LinuxLists.cc - Revert: SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose

2016-07-01 21:26:14

Subject: Revert: SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose

A while back, rkhunter reported a "hidden port" on my main server,
making me nervous that I had been hacked. Doing lots of debugging, I
found that it was happening from xprt code in NFS. I found a way to
trigger the bug, which happened because my wife's machine was NFS
mounting a directory of my main server. She does this to upload her
photos quickly to gallery2.

"Warning: Hidden ports found:
Port number: TCP:871"

A hidden port is one that has no socket connected to it. That is, it's
a dead resource. Nothing can ever use that port. It's not something
that is "reserved", it's just a leaked bit of info. rkhunter treats
this as a possible root kit attack.

I did a bisect and found the culprit and worked with the NFS folks who
came up with a fix that made rkhunter happy again.

Link: http://lkml.kernel.org/r/[email protected]

The previous fix was 4876cc779ff5 ("SUNRPC: Ensure we release the TCP
socket once it has been closed")

Recently, after traveling with my wife, she decided to upload pictures
again and mounted the directory, and lo and behold the hidden port
re-appeared. I noticed that the mounting of the NFS directory caused
this to happen again. I did lots of debugging to see why and asked for
help from the NFS folks again. But this time I didn't receive much help.

Link: http://lkml.kernel.org/r/[email protected]

Frustrated, I spent all day bisecting this, and found that this bug was
created in the next release. And I even found the commit that causes
this bug: 4b0ab51db32e ("SUNRPC: xs_sock_mark_closed() does not need to
trigger socket autoclose"). This commit states:

"Under all conditions, it should be quite sufficient just to mark
the socket as disconnected. It will then be closed by the
transport shutdown or reconnect code."

Well, this isn't quite correct. And doing a little git blaming, the
line that it removed was added by the first commit above that
previously fixed my issue.

Reverting this commit makes rkhunter and myself quite happy again.

I consider this userland breakage, as rkhunter is a userland tool and
this commit causes it to report a problem that does not exist.

Fixes: 4b0ab51db32e ("SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose")
Cc: [email protected] # v4.3+
Signed-off-by: Steven Rostedt <[email protected]>
---
diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
index 7e2b2fa189c3..5579d13e253f 100644
--- a/net/sunrpc/xprtsock.c
+++ b/net/sunrpc/xprtsock.c
@@ -768,6 +768,7 @@ static void xs_sock_mark_closed(struct rpc_xprt *xprt)
xs_sock_reset_connection_flags(xprt);
/* Mark transport as closed and wake up all pending tasks */
xprt_disconnect_done(xprt);
+ xprt_force_disconnect(xprt);
}

/**

2016-07-01 22:34:09

by Trond Myklebust

[permalink] [raw]

Subject: Re: Revert: SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose

> On Jul 1, 2016, at 17:24, Steven Rostedt <[email protected]> wrote:
>
> A while back, rkhunter reported a "hidden port" on my main server,
> making me nervous that I had been hacked. Doing lots of debugging, I
> found that it was happening from xprt code in NFS. I found a way to
> trigger the bug, which happened because my wife's machine was NFS
> mounting a directory of my main server. She does this to upload her
> photos quickly to gallery2.
>
> "Warning: Hidden ports found:
> Port number: TCP:871"
>
> A hidden port is one that has no socket connected to it. That is, it's
> a dead resource. Nothing can ever use that port. It's not something
> that is "reserved", it's just a leaked bit of info. rkhunter treats
> this as a possible root kit attack.

No, it?s not leaked at all; it is still being tracked by the RPC layer.

Furthermore, you haven?t unmounted the NFS partition, so it is a port that can and SHOULD, according to the NFSv3 rules be reused by the same NFS client when it reconnects. The server attaches a duplicate reply cache to the source IP address and port number and expects RPC calls that were lost by the server to be replayed through the same IP address and port number.

>
> I did a bisect and found the culprit and worked with the NFS folks who
> came up with a fix that made rkhunter happy again.
>
> Link: http://lkml.kernel.org/r/[email protected]
>
> The previous fix was 4876cc779ff5 ("SUNRPC: Ensure we release the TCP
> socket once it has been closed")
>
> Recently, after traveling with my wife, she decided to upload pictures
> again and mounted the directory, and lo and behold the hidden port
> re-appeared. I noticed that the mounting of the NFS directory caused
> this to happen again. I did lots of debugging to see why and asked for
> help from the NFS folks again. But this time I didn't receive much help.
>
> Link: http://lkml.kernel.org/r/[email protected]
>
> Frustrated, I spent all day bisecting this, and found that this bug was
> created in the next release. And I even found the commit that causes
> this bug: 4b0ab51db32e ("SUNRPC: xs_sock_mark_closed() does not need to
> trigger socket autoclose"). This commit states:
>
> "Under all conditions, it should be quite sufficient just to mark
> the socket as disconnected. It will then be closed by the
> transport shutdown or reconnect code."
>
> Well, this isn't quite correct. And doing a little git blaming, the
> line that it removed was added by the first commit above that
> previously fixed my issue.
>
> Reverting this commit makes rkhunter and myself quite happy again.
>
> I consider this userland breakage, as rkhunter is a userland tool and
> this commit causes it to report a problem that does not exist.
>
> Fixes: 4b0ab51db32e ("SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose")
> Cc: [email protected] # v4.3+
> Signed-off-by: Steven Rostedt <[email protected]>
> ---
> diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
> index 7e2b2fa189c3..5579d13e253f 100644
> --- a/net/sunrpc/xprtsock.c
> +++ b/net/sunrpc/xprtsock.c
> @@ -768,6 +768,7 @@ static void xs_sock_mark_closed(struct rpc_xprt *xprt)
> xs_sock_reset_connection_flags(xprt);
> /* Mark transport as closed and wake up all pending tasks */
> xprt_disconnect_done(xprt);
> + xprt_force_disconnect(xprt);
> }

NACK. This ocde was removed on purpose because it is dangerous to have the TCP state change callbacks queue up a new close(). The connect code sometimes has to close sockets that are misbehaving, and so we?ve seen races whereby the old socket closes and triggers an autoclose for the new socket while it is connecting.

Trond

2016-07-01 22:39:16

by Steven Rostedt

[permalink] [raw]

Subject: Re: Revert: SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose

On Fri, 1 Jul 2016 22:34:02 +0000
Trond Myklebust <[email protected]> wrote:

> NACK. This ocde was removed on purpose because it is dangerous to
> have the TCP state change callbacks queue up a new close(). The
> connect code sometimes has to close sockets that are misbehaving, and
> so we’ve seen races whereby the old socket closes and triggers an
> autoclose for the new socket while it is connecting.

OK fine. But can we please come up with a solution to get rid of the
hidden port issue. It's very annoying that I get a message from
rkhunter ever morning telling me "Please inspect this machine, because
it may be infected."

-- Steve

2016-07-01 23:02:31

by Trond Myklebust

[permalink] [raw]

Subject: Re: Revert: SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose

DQo+IE9uIEp1bCAxLCAyMDE2LCBhdCAxODozOSwgU3RldmVuIFJvc3RlZHQgPHJvc3RlZHRAZ29v
ZG1pcy5vcmc+IHdyb3RlOg0KPiANCj4gT24gRnJpLCAxIEp1bCAyMDE2IDIyOjM0OjAyICswMDAw
DQo+IFRyb25kIE15a2xlYnVzdCA8dHJvbmRteUBwcmltYXJ5ZGF0YS5jb20+IHdyb3RlOg0KPiAN
Cj4gDQo+PiBOQUNLLiBUaGlzIG9jZGUgd2FzIHJlbW92ZWQgb24gcHVycG9zZSBiZWNhdXNlIGl0
IGlzIGRhbmdlcm91cyB0bw0KPj4gaGF2ZSB0aGUgVENQIHN0YXRlIGNoYW5nZSBjYWxsYmFja3Mg
cXVldWUgdXAgYSBuZXcgY2xvc2UoKS4gVGhlDQo+PiBjb25uZWN0IGNvZGUgc29tZXRpbWVzIGhh
cyB0byBjbG9zZSBzb2NrZXRzIHRoYXQgYXJlIG1pc2JlaGF2aW5nLCBhbmQNCj4+IHNvIHdl4oCZ
dmUgc2VlbiByYWNlcyB3aGVyZWJ5IHRoZSBvbGQgc29ja2V0IGNsb3NlcyBhbmQgdHJpZ2dlcnMg
YW4NCj4+IGF1dG9jbG9zZSBmb3IgdGhlIG5ldyBzb2NrZXQgd2hpbGUgaXQgaXMgY29ubmVjdGlu
Zy4NCj4gDQo+IE9LIGZpbmUuIEJ1dCBjYW4gd2UgcGxlYXNlIGNvbWUgdXAgd2l0aCBhIHNvbHV0
aW9uIHRvIGdldCByaWQgb2YgdGhlDQo+IGhpZGRlbiBwb3J0IGlzc3VlLiBJdCdzIHZlcnkgYW5u
b3lpbmcgdGhhdCBJIGdldCBhIG1lc3NhZ2UgZnJvbQ0KPiBya2h1bnRlciBldmVyIG1vcm5pbmcg
dGVsbGluZyBtZSAiUGxlYXNlIGluc3BlY3QgdGhpcyBtYWNoaW5lLCBiZWNhdXNlDQo+IGl0IG1h
eSBiZSBpbmZlY3RlZC7igJ0NCj4gDQoNCkNhbiB3ZSBsb29rIGludG8gd2h5IHRoZSBzb2NrZXQg
ZGlzY29ubmVjdCBpcyBoYXBwZW5pbmcgaW4gdGhlIGZpcnN0IHBsYWNlPyBJdOKAmXMgcHJlc3Vt
YWJseSBub3QgdGhlIHNlcnZlciwgc2luY2UgdGhhdCBfd291bGRfIHRyaWdnZXIgYW4gYXV0b2Ns
b3NlIHdoZW4gdGhlIHNvY2tldCBoaXRzIFRDUF9DTE9TRV9XQUlULiBUaGF0IHB1dHMgdGhlIHR3
byB0b3Agc3VzcGVjdHMgYmVpbmcgdGhlIFRDUCBrZWVwYWxpdmUgYW5kIHRoZSBUQ1BfVVNFUl9U
SU1FT1VULiBBcmUgdGhlcmUgYW55IHRyYWNlcG9pbnRzIHdlIGNvdWxkIHVzZSB0byBsb29rIGF0
IHdoZXRoZXIgb3Igbm90IHRoZXkgYXJlIHRyaWdnZXJpbmcgYSBjbG9zZT8NCg0KVGhhbmtzDQog
IFRyb25kDQoNCg0K

2016-07-01 23:14:38

by Steven Rostedt

[permalink] [raw]

Subject: Re: Revert: SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose

On Fri, 1 Jul 2016 22:34:02 +0000
Trond Myklebust <[email protected]> wrote:

> > On Jul 1, 2016, at 17:24, Steven Rostedt <[email protected]> wrote:
> >
> > A while back, rkhunter reported a "hidden port" on my main server,
> > making me nervous that I had been hacked. Doing lots of debugging, I
> > found that it was happening from xprt code in NFS. I found a way to
> > trigger the bug, which happened because my wife's machine was NFS
> > mounting a directory of my main server. She does this to upload her
> > photos quickly to gallery2.
> >
> > "Warning: Hidden ports found:
> > Port number: TCP:871"
> >
> > A hidden port is one that has no socket connected to it. That is, it's
> > a dead resource. Nothing can ever use that port. It's not something
> > that is "reserved", it's just a leaked bit of info. rkhunter treats
> > this as a possible root kit attack.

[ missed this part when replying last time ]
>
> No, it’s not leaked at all; it is still being tracked by the RPC layer.

How so? I watched on wireshark and the port is closed (FIN/ACK are
sent, and I watch it go in "netstat -tapn" from ESTABLISHED to
TIME_WAIT to nothing at all), and then it is never reused. I kicked off
lots of copies to and from that mounted directory, and that port never
shows up.

>
> Furthermore, you haven’t unmounted the NFS partition, so it is a port
> that can and SHOULD, according to the NFSv3 rules be reused by the
> same NFS client when it reconnects.

It uses another port. Maybe I missed saying that. But there's two ports
that show up.

Not to mention, when I unmount that port still exists as unhidden. It's
not till I remount it that the port goes away until it goes into it
times out again.

> The server attaches a duplicate
> reply cache to the source IP address and port number and expects RPC
> calls that were lost by the server to be replayed through the same IP
> address and port number.
>

Is this what is expected?

[ from Wife's machine ]

# mount /upload

[ from my server ]

# netstat -tapn | grep '192.168.23.22'
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:2049 192.168.23.22:879 ESTABLISHED -

# while :; do if ! netstat -tapn |grep :931; then break; fi; sleep 1; done; netstat -tapn | grep '192.168.23.22'
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
[...]
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 ESTABLISHED -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 TIME_WAIT -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 TIME_WAIT -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 TIME_WAIT -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 TIME_WAIT -
[...]
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 TIME_WAIT -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 TIME_WAIT -
tcp 0 0 192.168.23.9:931 192.168.23.22:42546 TIME_WAIT -
# netstat -tapn | grep '192.168.23.22'
tcp 0 0 192.168.23.9:2049 192.168.23.22:879 ESTABLISHED -

At this point port 931 is hidden and never shows up again. All
connection (according to wireshark) goes through port 2049 from this
point on.

I unmount, and the port is still hidden, but if I remount, the port
goes away and another two ports are connect (2049 along with another
one)

[ form Wife's machine ]

# umount /upload
# mount /upload

[ from my server ]

# netstat -tapn | grep '192.168.23.22'
tcp 0 0 192.168.23.9:2049 192.168.23.22:859 ESTABLISHED -
tcp 0 0 192.168.23.9:975 192.168.23.22:39281 ESTABLISHED -

Is this expected?

-- Steve

2016-07-01 23:17:48

by Steven Rostedt

[permalink] [raw]

Subject: Re: Revert: SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose

On Fri, 1 Jul 2016 23:02:23 +0000
Trond Myklebust <[email protected]> wrote:

> Can we look into why the socket disconnect is happening in the first
> place? It’s presumably not the server, since that _would_ trigger an
> autoclose when the socket hits TCP_CLOSE_WAIT. That puts the two top
> suspects being the TCP keepalive and the TCP_USER_TIMEOUT. Are there
> any tracepoints we could use to look at whether or not they are
> triggering a close?

There's not many tracepoints, but from my previous emails I added some
trace_printk()s and converted some of your debug prints into
trace_printk():

+#undef dprintk
+#undef dprintk_rcu
+#define dprintk(args...) trace_printk(args)
+#define dprintk_rcu(args...) trace_printk(args)

See my previous email that describes all this (I removed the debugging
from my kernel, and I need to spend time with the family so I can't get
to this again till Tuesday)

http://lkml.kernel.org/r/[email protected]

-- Steve

2016-07-01 23:19:33

by Steven Rostedt

[permalink] [raw]

Subject: Re: Revert: SUNRPC: xs_sock_mark_closed() does not need to trigger socket autoclose

On Fri, 1 Jul 2016 19:17:45 -0400
Steven Rostedt Ug, that link is ugly.

Here's a cut and paste of that email:

On Thu, 30 Jun 2016 16:07:26 -0400
Steven Rostedt <[email protected]> wrote:
the debugging
so I can't get
f.local.home">http://lkml.kernel.org/r/[email protected]
dfdecefaddd5d5ded7d3c994d5c8dd9cddce81"><[email protected]> wrote:
the
the hidden
it
is
TIME_WAIT -
ESTABLISHED -
ESTABLISHED -
the
set up xprt to 192.168.23.22 (port 44672) via tcp
created transport ffff8803b1c38000 with 65536 slots
47 reserved req ffff88040b27ca00 xid c50ccaff
47 xprt_connect xprt ffff8803b1c38000 is not connected
xs_connect scheduled xprt ffff8803b1c38000
snum 892
/> add 892 ffff8803bb9b5cc0
/> xs_bind 4.136.255.255:892: ok (0)
worker connecting xprt ffff8803b1c38000 via tcp to 192.168.23.22 (port 44672)
ffff8803b1c38000 connect status 115 connected 0 sock state 2
xs_tcp_state_change client ffff8803b1c38000...
state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
47 xprt_connect_status: retrying
47 xprt_prepare_transmit
47 xprt_transmit(72)
xs_tcp_send_request(72) = 0
47 xmit complete
xs_tcp_data_ready...
xs_tcp_data_recv started
reading TCP record fragment of length 24
reading XID (4 bytes)
reading request with XID c50ccaff
reading CALL/REPLY flag (4 bytes)
read reply XID c50ccaff
XID c50ccaff read 16 bytes
xprt = ffff8803b1c38000, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24
47 xid c50ccaff complete (24 bytes received)
xs_tcp_data_recv done
47 release request ffff88040b27ca00
destroying transport ffff8803b1c38000
xs_destroy xprt ffff8803b1c38000
xs_close xprt ffff8803b1c38000
xs_tcp_state_change client ffff8803b1c38000...
state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
disconnected transport ffff8803b1c38000
disconnect transport!
/> turn into the hidden port:
set up xprt to 192.168.23.22 (port 44672) via tcp
created transport ffff8803b8c22000 with 65536 slots
48 reserved req ffff8803bfe89c00 xid 10c028fe
48 xprt_connect xprt ffff8803b8c22000 is not connected
xs_connect scheduled xprt ffff8803b8c22000
snum 754
/> add 754 ffff8803afc20e40
/> xs_bind 4.136.255.255:754: ok (0)
worker connecting xprt ffff8803b8c22000 via tcp to 192.168.23.22 (port 44672)
ffff8803b8c22000 connect status 115 connected 0 sock state 2
xs_tcp_state_change client ffff8803b8c22000...
state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
48 xprt_connect_status: retrying
48 xprt_prepare_transmit
48 xprt_transmit(72)
xs_tcp_send_request(72) = 0
48 xmit complete
xs_tcp_data_ready...
xs_tcp_data_recv started
reading TCP record fragment of length 24
reading XID (4 bytes)
reading request with XID 10c028fe
reading CALL/REPLY flag (4 bytes)
read reply XID 10c028fe
XID 10c028fe read 16 bytes
xprt = ffff8803b8c22000, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24
48 xid 10c028fe complete (24 bytes received)
xs_tcp_data_recv done
48 release request ffff8803bfe89c00
of data.
(no more connections
there's still an owner
Even if the client
/> xs_tcp_state_change client ffff8803b8c22000...
state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
xs_tcp_state_change client ffff8803b8c22000...
state 5 conn 0 dead 0 zapped 1 sk_shutdown 3
moving xs_bind sock to time wait
trace>
shows it.
destroy 754 empty=0 ffff8803afc20e40
trace>
port is not empty, and the
code finally cleans
destroying transport ffff8803b8c22000
xs_destroy xprt ffff8803b8c22000
xs_close xprt ffff8803b8c22000
xs_tcp_state_change client ffff8803b8c22000...
state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
disconnected transport ffff8803b8c22000
disconnect transport!
destroy 754 empty=1 ffff8803afc20e40
/> disconnected transport ffff8803b8c22000
xs_bind 4.136.255.255:973: ok (0)
worker connecting xprt ffff8803d7fd3800 via tcp to 192.168.23.22 (port 45075)
ffff8803d7fd3800 connect status 115 connected 0 sock state 2
xs_tcp_state_change client ffff8803d7fd3800...
state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
49 xprt_connect_status: retrying
49 xprt_prepare_transmit
49 xprt_transmit(72)
xs_tcp_send_request(72) = 0
49 xmit complete
xs_tcp_data_ready...
xs_tcp_data_recv started
reading TCP record fragment of length 24
reading XID (4 bytes)
reading request with XID e2e1dc21
reading CALL/REPLY flag (4 bytes)
read reply XID e2e1dc21
XID e2e1dc21 read 16 bytes
xprt = ffff8803d7fd3800, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24
49 xid e2e1dc21 complete (24 bytes received)
xs_tcp_data_recv done
49 release request ffff8800dba14800
destroying transport ffff8803d7fd3800
xs_destroy xprt ffff8803d7fd3800
xs_close xprt ffff8803d7fd3800
xs_tcp_state_change client ffff8803d7fd3800...
state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
disconnected transport ffff8803d7fd3800
disconnect transport!
away (and freed)
xs_bind 4.136.255.255:688: ok (0)
worker connecting xprt ffff8803bb889000 via tcp to 192.168.23.22 (port 45075)
ffff8803bb889000 connect status 115 connected 0 sock state 2
xs_tcp_state_change client ffff8803bb889000...
state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
50 xprt_connect_status: retrying
50 xprt_prepare_transmit
50 xprt_transmit(72)
xs_tcp_send_request(72) = 0
50 xmit complete
xs_tcp_data_ready...
xs_tcp_data_recv started
reading TCP record fragment of length 24
reading XID (4 bytes)
reading request with XID a4418f34
reading CALL/REPLY flag (4 bytes)
read reply XID a4418f34
XID a4418f34 read 16 bytes
xprt = ffff8803bb889000, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24
50 xid a4418f34 complete (24 bytes received)
xs_tcp_data_recv done
50 release request ffff8800db28d800
ports properly. There's
is it wasting a port
because it's one of