linux-nfs.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* It's back! (Re: [REGRESSION] NFS is creating a hidden port (left over from xs_bind() ))
@ 2016-06-30 12:59 Steven Rostedt
  2016-06-30 13:17 ` Trond Myklebust
  0 siblings, 1 reply; 12+ messages in thread
From: Steven Rostedt @ 2016-06-30 12:59 UTC (permalink / raw)
  To: Trond Myklebust
  Cc: Jeff Layton, Eric Dumazet, Anna Schumaker, Linux NFS Mailing List,
	Linux Network Devel Mailing List, LKML, Andrew Morton,
	Bruce James Fields

[-- Attachment #1: Type: text/plain, Size: 4137 bytes --]

[ resending as a new email, as I'm assuming people do not sort their
  INBOX via last email on thread, thus my last email is sitting in the
  bottom of everyone's INBOX ]

I've hit this again. Not sure when it started, but I applied my old
debug trace_printk() patch (attached) and rebooted (4.5.7). I just
tested the latest kernel from Linus's tree (from last nights pull), and
it still gives me the problem.

Here's the trace I have:

    kworker/3:1H-134   [003] ..s.    61.036129: inet_csk_get_port: snum 805
    kworker/3:1H-134   [003] ..s.    61.036135: <stack trace>
 => sched_clock
 => inet_addr_type_table
 => security_capable
 => inet_bind
 => xs_bind
 => release_sock
 => sock_setsockopt
 => __sock_create
 => xs_create_sock.isra.19
 => xs_tcp_setup_socket
 => process_one_work
 => worker_thread
 => worker_thread
 => kthread
 => ret_from_fork
 => kthread  
    kworker/3:1H-134   [003] ..s.    61.036136: inet_bind_hash: add 805
    kworker/3:1H-134   [003] ..s.    61.036138: <stack trace>
 => inet_csk_get_port
 => sched_clock
 => inet_addr_type_table
 => security_capable
 => inet_bind
 => xs_bind
 => release_sock
 => sock_setsockopt
 => __sock_create
 => xs_create_sock.isra.19
 => xs_tcp_setup_socket
 => process_one_work
 => worker_thread
 => worker_thread
 => kthread
 => ret_from_fork
 => kthread  
    kworker/3:1H-134   [003] ....    61.036139: xs_bind: RPC:       xs_bind 4.136.255.255:805: ok (0)
    kworker/3:1H-134   [003] ....    61.036140: xs_tcp_setup_socket: RPC:       worker connecting xprt ffff880407eca800 via tcp to 192.168.23.22 (port 43651)
    kworker/3:1H-134   [003] ....    61.036162: xs_tcp_setup_socket: RPC:       ffff880407eca800 connect status 115 connected 0 sock state 2
          <idle>-0     [001] ..s.    61.036450: xs_tcp_state_change: RPC:       xs_tcp_state_change client ffff880407eca800...
          <idle>-0     [001] ..s.    61.036452: xs_tcp_state_change: RPC:       state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
    kworker/1:1H-136   [001] ....    61.036476: xprt_connect_status: RPC:    43 xprt_connect_status: retrying
    kworker/1:1H-136   [001] ....    61.036478: xprt_prepare_transmit: RPC:    43 xprt_prepare_transmit
    kworker/1:1H-136   [001] ....    61.036479: xprt_transmit: RPC:    43 xprt_transmit(72)
    kworker/1:1H-136   [001] ....    61.036486: xs_tcp_send_request: RPC:       xs_tcp_send_request(72) = 0
    kworker/1:1H-136   [001] ....    61.036487: xprt_transmit: RPC:    43 xmit complete
          <idle>-0     [001] ..s.    61.036789: xs_tcp_data_ready: RPC:       xs_tcp_data_ready...
    kworker/1:1H-136   [001] ....    61.036798: xs_tcp_data_recv: RPC:       xs_tcp_data_recv started
    kworker/1:1H-136   [001] ....    61.036799: xs_tcp_data_recv: RPC:       reading TCP record fragment of length 24
    kworker/1:1H-136   [001] ....    61.036799: xs_tcp_data_recv: RPC:       reading XID (4 bytes)
    kworker/1:1H-136   [001] ....    61.036800: xs_tcp_data_recv: RPC:       reading request with XID 2f4c3f88
    kworker/1:1H-136   [001] ....    61.036800: xs_tcp_data_recv: RPC:       reading CALL/REPLY flag (4 bytes)
    kworker/1:1H-136   [001] ....    61.036801: xs_tcp_data_recv: RPC:       read reply XID 2f4c3f88
    kworker/1:1H-136   [001] ..s.    61.036801: xs_tcp_data_recv: RPC:       XID 2f4c3f88 read 16 bytes
    kworker/1:1H-136   [001] ..s.    61.036802: xs_tcp_data_recv: RPC:       xprt = ffff880407eca800, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24
    kworker/1:1H-136   [001] ..s.    61.036802: xprt_complete_rqst: RPC:    43 xid 2f4c3f88 complete (24 bytes received)
    kworker/1:1H-136   [001] ....    61.036803: xs_tcp_data_recv: RPC:       xs_tcp_data_recv done
    kworker/1:1H-136   [001] ....    61.036812: xprt_release: RPC:    43 release request ffff88040b270800


# unhide-tcp 
Unhide-tcp 20130526
Copyright © 2013 Yago Jesus & Patrick Gouin
License GPLv3+ : GNU GPL version 3 or later
http://www.unhide-forensics.info
Used options: 
[*]Starting TCP checking

Found Hidden port that not appears in ss: 805

-- Steve

[-- Attachment #2: debug-hidden-port-4.7.patch --]
[-- Type: text/x-patch, Size: 2378 bytes --]

---
 net/ipv4/inet_connection_sock.c |    4 ++++
 net/ipv4/inet_hashtables.c      |    5 +++++
 net/sunrpc/xprt.c               |    5 +++++
 net/sunrpc/xprtsock.c           |    5 +++++
 5 files changed, 22 insertions(+)

Index: linux-build.git/net/ipv4/inet_connection_sock.c
===================================================================
--- linux-build.git.orig/net/ipv4/inet_connection_sock.c	2016-06-22 11:55:05.952267493 -0400
+++ linux-build.git/net/ipv4/inet_connection_sock.c	2016-06-22 11:56:20.002662092 -0400
@@ -232,6 +232,10 @@ tb_found:
 		}
 	}
 success:
+	if (!current->mm) {
+		trace_printk("snum %d\n", snum);
+		trace_dump_stack(1);
+	}
 	if (!inet_csk(sk)->icsk_bind_hash)
 		inet_bind_hash(sk, tb, port);
 	WARN_ON(inet_csk(sk)->icsk_bind_hash != tb);
Index: linux-build.git/net/ipv4/inet_hashtables.c
===================================================================
--- linux-build.git.orig/net/ipv4/inet_hashtables.c	2016-06-22 11:55:05.952267493 -0400
+++ linux-build.git/net/ipv4/inet_hashtables.c	2016-06-22 11:55:05.948267360 -0400
@@ -93,6 +93,11 @@ void inet_bind_bucket_destroy(struct kme
 void inet_bind_hash(struct sock *sk, struct inet_bind_bucket *tb,
 		    const unsigned short snum)
 {
+	if (!current->mm) {
+		trace_printk("add %d\n", snum);
+		trace_dump_stack(1);
+	}
+
 	inet_sk(sk)->inet_num = snum;
 	sk_add_bind_node(sk, &tb->owners);
 	tb->num_owners++;
Index: linux-build.git/net/sunrpc/xprt.c
===================================================================
--- linux-build.git.orig/net/sunrpc/xprt.c	2016-06-22 11:55:05.952267493 -0400
+++ linux-build.git/net/sunrpc/xprt.c	2016-06-22 11:55:05.948267360 -0400
@@ -54,6 +54,11 @@
 
 #include "sunrpc.h"
 
+#undef dprintk
+#undef dprintk_rcu
+#define dprintk(args...)	trace_printk(args)
+#define dprintk_rcu(args...)	trace_printk(args)
+
 /*
  * Local variables
  */
Index: linux-build.git/net/sunrpc/xprtsock.c
===================================================================
--- linux-build.git.orig/net/sunrpc/xprtsock.c	2016-06-22 11:55:05.952267493 -0400
+++ linux-build.git/net/sunrpc/xprtsock.c	2016-06-22 11:55:05.948267360 -0400
@@ -51,6 +51,11 @@
 
 #include "sunrpc.h"
 
+#undef dprintk
+#undef dprintk_rcu
+#define dprintk(args...)	trace_printk(args)
+#define dprintk_rcu(args...)	trace_printk(args)
+
 static void xs_close(struct rpc_xprt *xprt);
 
 /*

^ permalink raw reply	[flat|nested] 12+ messages in thread
* Re: It's back! (Re: [REGRESSION] NFS is creating a hidden port (left over from xs_bind() ))
@ 2018-02-02 21:31 Daniel Reichelt
  2018-02-06  0:24 ` Trond Myklebust
  0 siblings, 1 reply; 12+ messages in thread
From: Daniel Reichelt @ 2018-02-02 21:31 UTC (permalink / raw)
  To: Trond Myklebust, Steven Rostedt; +Cc: Linux NFS Mailing List, LKML


[-- Attachment #1.1: Type: text/plain, Size: 672 bytes --]

Hi Trond, Steven,

eversince I switched from Debian Jessie to Stretch last summer, I've
been seeing the very same hidden ports on an NFS server as described in
[1], which is a follow-up to [2].

Your patch ([3], [4]) solved the issue back then. Later on, you changed
that fix again in [5], which lead to the situation we're seeing today.

Reverting 0b0ab51 fixes the issue for me.

Let me know if you need more info.



Thanks
Daniel


[1] https://lkml.org/lkml/2016/6/30/341
[2] https://lkml.org/lkml/2015/6/11/803
[3] https://lkml.org/lkml/2015/6/19/759
[4] 4876cc779ff525b9c2376d8076edf47815e71f2c
[5] 4b0ab51db32eba0f48b7618254742f143364a28d


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 866 bytes --]

^ permalink raw reply	[flat|nested] 12+ messages in thread
* [REGRESSION] NFS is creating a hidden port (left over from xs_bind() )
@ 2015-06-12  3:49 Steven Rostedt
  2015-06-12 14:10 ` Trond Myklebust
  0 siblings, 1 reply; 12+ messages in thread
From: Steven Rostedt @ 2015-06-12  3:49 UTC (permalink / raw)
  To: Trond Myklebust; +Cc: Anna Schumaker, linux-nfs, netdev, LKML, Andrew Morton


I recently upgraded my main server to 4.0.4 from 3.19.5 and rkhunter
started reporting a hidden port on my box.

Running unhide-tcp I see this:

# unhide-tcp 
Unhide-tcp 20121229
Copyright © 2012 Yago Jesus & Patrick Gouin
License GPLv3+ : GNU GPL version 3 or later
http://www.unhide-forensics.info
Used options: 
[*]Starting TCP checking

Found Hidden port that not appears in ss: 946
[*]Starting UDP checking

This scared the hell out of me as I'm thinking that I have got some kind
of NSA backdoor hooked into my server and it is monitoring my plans to
smuggle Kinder Überraschung into the USA from Germany. I panicked!

Well, I wasted the day writing modules to first look at all the sockets
opened by all processes (via their file descriptors) and posted their
port numbers.

  http://rostedt.homelinux.com/private/tasklist.c

But this port wasn't there either.

Then I decided to look at the ports in tcp_hashinfo.

  http://rostedt.homelinux.com/private/portlist.c

This found the port but no file was connected to it, and worse yet,
when I first ran it without using probe_kernel_read(), it crashed my
kernel, because sk->sk_socket pointed to a freed socket!

Note, each boot, the hidden port is different.

Finally, I decided to bring in the big guns, and inserted a
trace_printk() into the bind logic, to see if I could find the culprit.
After fiddling with it a few times, I found a suspect:

   kworker/3:1H-123   [003] ..s.    96.696213: inet_bind_hash: add 946

Bah, it's a kernel thread doing it, via a work queue. I then added a
trace_dump_stack() to find what was calling this, and here it is:

    kworker/3:1H-123   [003] ..s.    96.696222: <stack trace>
 => inet_csk_get_port
 => inet_addr_type
 => inet_bind
 => xs_bind
 => sock_setsockopt
 => __sock_create
 => xs_create_sock.isra.18
 => xs_tcp_setup_socket
 => process_one_work
 => worker_thread
 => worker_thread
 => kthread
 => kthread
 => ret_from_fork
 => kthread

I rebooted, and examined what happens. I see the kworker binding that
port, and all seems well:

# netstat -tapn |grep 946
tcp        0      0 192.168.23.9:946        192.168.23.22:55201     ESTABLISHED -               

But waiting for a bit, the connection goes into a TIME_WAIT, and then
it just disappears. But the bind to the port does not get released, and
that port is from then on, taken.

This never happened with my 3.19 kernels. I would bisect it but this is
happening on my main server box which I usually only reboot every other
month doing upgrades. It causes too much disturbance for myself (and my
family) as when this box is offline, basically the rest of my machines
are too.

I figured this may be enough information to see if you can fix it.
Otherwise I can try to do the bisect, but that's not going to happen
any time soon. I may just go back to 3.19 for now, such that rkhunter
stops complaining about the hidden port.

If you need anymore information, let me know.

-- Steve

^ permalink raw reply	[flat|nested] 12+ messages in thread
end of thread, other threads:[~2018-02-06 19:26 UTC | newest]

Thread overview: 12+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2016-06-30 12:59 It's back! (Re: [REGRESSION] NFS is creating a hidden port (left over from xs_bind() )) Steven Rostedt
2016-06-30 13:17 ` Trond Myklebust
2016-06-30 15:23   ` Steven Rostedt
2016-06-30 16:24     ` Steven Rostedt
2016-06-30 18:30     ` Trond Myklebust
2016-06-30 20:07       ` Steven Rostedt
2016-06-30 21:56         ` Steven Rostedt
  -- strict thread matches above, loose matches on Subject: below --
2018-02-02 21:31 Daniel Reichelt
2018-02-06  0:24 ` Trond Myklebust
2018-02-06  9:20   ` Daniel Reichelt
2018-02-06 19:26     ` Trond Myklebust
2015-06-12  3:49 [REGRESSION] NFS is creating a hidden port (left over from xs_bind() ) Steven Rostedt
2015-06-12 14:10 ` Trond Myklebust
2015-06-12 14:40   ` Eric Dumazet
2015-06-12 15:34     ` Steven Rostedt
2015-06-12 15:50       ` Steven Rostedt
2015-06-18  3:08         ` Steven Rostedt
2015-06-18 19:24           ` Trond Myklebust
2015-06-18 19:49             ` Steven Rostedt
2015-06-18 22:50               ` Jeff Layton
2015-06-19  1:08                 ` Steven Rostedt
2015-06-19  1:37                   ` Jeff Layton
     [not found]                     ` <20150619122553.43d2d86c@gandalf.local.home>
2015-06-19 17:17                       ` Steven Rostedt
2015-06-19 17:39                         ` Trond Myklebust
2015-06-19 19:52                           ` Jeff Layton
2015-06-19 20:30                             ` Trond Myklebust
2015-06-19 22:14                               ` Steven Rostedt
2015-06-19 23:25                                 ` Trond Myklebust
2015-06-20  1:27                                   ` Steven Rostedt
2016-06-22 16:41                                     ` It's back! (Re: [REGRESSION] NFS is creating a hidden port (left over from xs_bind() )) Steven Rostedt

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).