From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932126AbcF3M75 (ORCPT ); Thu, 30 Jun 2016 08:59:57 -0400 Received: from smtprelay0193.hostedemail.com ([216.40.44.193]:57940 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1752035AbcF3M7z (ORCPT ); Thu, 30 Jun 2016 08:59:55 -0400 X-Session-Marker: 726F737465647440676F6F646D69732E6F7267 X-Spam-Summary: 50,0,0,,d41d8cd98f00b204,rostedt@goodmis.org,:::::::::::::::::,RULES_HIT:41:152:196:355:379:541:871:960:967:973:988:989:1260:1263:1313:1314:1345:1437:1516:1518:1535:1544:1575:1594:1622:1711:1730:1747:1764:1777:1792:2198:2199:2393:2525:2538:2560:2563:2682:2685:2859:2933:2937:2939:2942:2945:2947:2951:2954:3022:3138:3139:3140:3141:3142:3355:3865:3866:3867:3868:3870:3871:3872:3874:3934:3936:3938:3941:3944:3947:3950:3953:3956:3959:4119:4250:4321:4605:5007:6117:6119:6120:6248:6261:6748:6996:6997:7281:7875:7901:7903:8660:8985:9025:10004:10394:10848:11026:11232:11473:11604:11658:11852:11914:12043:12438:12517:12519:12555:12663:12681:12740:13148:13230:13255:14181:14659:14721:21063:21080:21088:21433:30022:30045:30046:30054:30060:30062:30064:30067:30070,0,RBL:none,CacheIP:none,Bayesian:0.5,0.5,0.5,Netcheck:none,DomainCache:0,MSF:not bulk,SPF:fn,MSBL:0,DNSBL:none,Custom_rules:0:0:0,LFtime:2,LUA_SUMMARY:none X-HE-Tag: flock71_562d505068d4d X-Filterd-Recvd-Size: 8141 Date: Thu, 30 Jun 2016 08:59:50 -0400 From: Steven Rostedt 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 Subject: It's back! (Re: [REGRESSION] NFS is creating a hidden port (left over from xs_bind() )) Message-ID: <20160630085950.61e5c7e0@gandalf.local.home> X-Mailer: Claws Mail 3.13.2 (GTK+ 2.24.30; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="MP_/cuRJNwtlXYuEP0MTlFBq6e1" Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org --MP_/cuRJNwtlXYuEP0MTlFBq6e1 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Content-Disposition: inline [ 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: =3D> sched_clock =3D> inet_addr_type_table =3D> security_capable =3D> inet_bind =3D> xs_bind =3D> release_sock =3D> sock_setsockopt =3D> __sock_create =3D> xs_create_sock.isra.19 =3D> xs_tcp_setup_socket =3D> process_one_work =3D> worker_thread =3D> worker_thread =3D> kthread =3D> ret_from_fork =3D> kthread =20 kworker/3:1H-134 [003] ..s. 61.036136: inet_bind_hash: add 805 kworker/3:1H-134 [003] ..s. 61.036138: =3D> inet_csk_get_port =3D> sched_clock =3D> inet_addr_type_table =3D> security_capable =3D> inet_bind =3D> xs_bind =3D> release_sock =3D> sock_setsockopt =3D> __sock_create =3D> xs_create_sock.isra.19 =3D> xs_tcp_setup_socket =3D> process_one_work =3D> worker_thread =3D> worker_thread =3D> kthread =3D> ret_from_fork =3D> kthread =20 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 -0 [001] ..s. 61.036450: xs_tcp_state_change: RPC: = xs_tcp_state_change client ffff880407eca800... -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 x= prt_transmit(72) kworker/1:1H-136 [001] .... 61.036486: xs_tcp_send_request: RPC: = xs_tcp_send_request(72) =3D 0 kworker/1:1H-136 [001] .... 61.036487: xprt_transmit: RPC: 43 x= mit complete -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 =3D ffff880407eca800, tcp_copied =3D 24, tcp_offset =3D 24, tcp_recl= en =3D 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 re= lease request ffff88040b270800 # unhide-tcp=20 Unhide-tcp 20130526 Copyright =C2=A9 2013 Yago Jesus & Patrick Gouin License GPLv3+ : GNU GPL version 3 or later http://www.unhide-forensics.info Used options:=20 [*]Starting TCP checking Found Hidden port that not appears in ss: 805 -- Steve --MP_/cuRJNwtlXYuEP0MTlFBq6e1 Content-Type: text/x-patch Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename=debug-hidden-port-4.7.patch --- 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); /* --MP_/cuRJNwtlXYuEP0MTlFBq6e1-- From mboxrd@z Thu Jan 1 00:00:00 1970 From: Steven Rostedt Subject: It's back! (Re: [REGRESSION] NFS is creating a hidden port (left over from xs_bind() )) Date: Thu, 30 Jun 2016 08:59:50 -0400 Message-ID: <20160630085950.61e5c7e0@gandalf.local.home> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="MP_/cuRJNwtlXYuEP0MTlFBq6e1" Cc: Jeff Layton , Eric Dumazet , Anna Schumaker , Linux NFS Mailing List , Linux Network Devel Mailing List , LKML , Andrew Morton , Bruce James Fields To: Trond Myklebust Return-path: Sender: linux-nfs-owner-u79uwXL29TY76Z2rM5mHXA@public.gmane.org List-Id: netdev.vger.kernel.org --MP_/cuRJNwtlXYuEP0MTlFBq6e1 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Content-Disposition: inline [ 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: =3D> sched_clock =3D> inet_addr_type_table =3D> security_capable =3D> inet_bind =3D> xs_bind =3D> release_sock =3D> sock_setsockopt =3D> __sock_create =3D> xs_create_sock.isra.19 =3D> xs_tcp_setup_socket =3D> process_one_work =3D> worker_thread =3D> worker_thread =3D> kthread =3D> ret_from_fork =3D> kthread =20 kworker/3:1H-134 [003] ..s. 61.036136: inet_bind_hash: add 805 kworker/3:1H-134 [003] ..s. 61.036138: =3D> inet_csk_get_port =3D> sched_clock =3D> inet_addr_type_table =3D> security_capable =3D> inet_bind =3D> xs_bind =3D> release_sock =3D> sock_setsockopt =3D> __sock_create =3D> xs_create_sock.isra.19 =3D> xs_tcp_setup_socket =3D> process_one_work =3D> worker_thread =3D> worker_thread =3D> kthread =3D> ret_from_fork =3D> kthread =20 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 -0 [001] ..s. 61.036450: xs_tcp_state_change: RPC: = xs_tcp_state_change client ffff880407eca800... -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 x= prt_transmit(72) kworker/1:1H-136 [001] .... 61.036486: xs_tcp_send_request: RPC: = xs_tcp_send_request(72) =3D 0 kworker/1:1H-136 [001] .... 61.036487: xprt_transmit: RPC: 43 x= mit complete -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 =3D ffff880407eca800, tcp_copied =3D 24, tcp_offset =3D 24, tcp_recl= en =3D 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 re= lease request ffff88040b270800 # unhide-tcp=20 Unhide-tcp 20130526 Copyright =C2=A9 2013 Yago Jesus & Patrick Gouin License GPLv3+ : GNU GPL version 3 or later http://www.unhide-forensics.info Used options:=20 [*]Starting TCP checking Found Hidden port that not appears in ss: 805 -- Steve --MP_/cuRJNwtlXYuEP0MTlFBq6e1 Content-Type: text/x-patch Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename=debug-hidden-port-4.7.patch --- 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); /* --MP_/cuRJNwtlXYuEP0MTlFBq6e1-- -- To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org More majordomo info at http://vger.kernel.org/majordomo-info.html