From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752017AbcF3Sav (ORCPT ); Thu, 30 Jun 2016 14:30:51 -0400 Received: from us-smtp-delivery-194.mimecast.com ([63.128.21.194]:22709 "EHLO us-smtp-delivery-194.mimecast.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751424AbcF3Sat (ORCPT ); Thu, 30 Jun 2016 14:30:49 -0400 From: Trond Myklebust To: Rostedt Steven CC: Jeff Layton , Eric Dumazet , Schumaker Anna , "Linux NFS Mailing List" , "Linux Network Devel Mailing List" , LKML , "Andrew Morton" , Fields Bruce Subject: Re: It's back! (Re: [REGRESSION] NFS is creating a hidden port (left over from xs_bind() )) Thread-Topic: It's back! (Re: [REGRESSION] NFS is creating a hidden port (left over from xs_bind() )) Thread-Index: AQHR0s9O30c/297HZUWMQOY0eOqNe6AB/fWAgAAjL4CAADRAgA== Date: Thu, 30 Jun 2016 18:30:42 +0000 Message-ID: <72EF2259-3A78-4FE3-8E0E-B3090FDFF14F@primarydata.com> References: <20160630085950.61e5c7e0@gandalf.local.home> <20160630112341.5ab5a821@gandalf.local.home> In-Reply-To: <20160630112341.5ab5a821@gandalf.local.home> Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: x-ms-exchange-messagesentrepresentingtype: 1 x-originating-ip: [68.49.162.121] x-ms-office365-filtering-correlation-id: de843e47-5799-4ab3-d03b-08d3a114a4db x-microsoft-exchange-diagnostics: 1;BN3PR11MB0306;20:5EZNkjIe/c29syFC2At8u11IaLJRLIdDBg3Q8GbpMbKcSO2znET2guCUvnN8VXzAPLYj9j1iNHZp9KGfihOicSJbzTU55GzIf6pWcaSvF+l/C3ENjiVjDRcIgFC/RFAtqc9iNLDatEr/JcAjs1vOMnqtEsiuiNzneMx6Eph3z5E= x-microsoft-antispam: UriScan:;BCL:0;PCL:0;RULEID:;SRVR:BN3PR11MB0306; x-microsoft-antispam-prvs: x-exchange-antispam-report-test: UriScan:(158342451672863)(192374486261705)(21532816269658); x-exchange-antispam-report-cfa-test: BCL:0;PCL:0;RULEID:(6040130)(601004)(2401047)(8121501046)(5005006)(3002001)(10201501046)(6041072)(6043046);SRVR:BN3PR11MB0306;BCL:0;PCL:0;RULEID:;SRVR:BN3PR11MB0306; x-forefront-prvs: 0989A7979C x-forefront-antispam-report: SFV:NSPM;SFS:(10019020)(6009001)(7916002)(209900001)(24454002)(189002)(199003)(305945005)(8936002)(102836003)(3846002)(6116002)(3280700002)(77096005)(7846002)(586003)(7736002)(83716003)(99286002)(36756003)(68736007)(16601075003)(5890100001)(4326007)(2950100001)(2900100001)(97736004)(2906002)(15975445007)(66066001)(110136002)(81156014)(92566002)(106356001)(106116001)(101416001)(81166006)(76176999)(105586002)(54356999)(86362001)(50986999)(8676002)(87936001)(10400500002)(82746002)(122556002)(19580395003)(33656002)(11100500001)(3660700001)(189998001)(19580405001)(5002640100001)(104396002)(6606295002);DIR:OUT;SFP:1102;SCL:1;SRVR:BN3PR11MB0306;H:BN3PR11MB0305.namprd11.prod.outlook.com;FPR:;SPF:None;PTR:InfoNoRecords;MX:1;A:1;LANG:en; spamdiagnosticoutput: 1:99 spamdiagnosticmetadata: NSPM Content-ID: MIME-Version: 1.0 X-OriginatorOrg: primarydata.com X-MS-Exchange-CrossTenant-originalarrivaltime: 30 Jun 2016 18:30:42.3266 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Hosted X-MS-Exchange-CrossTenant-id: 03193ed6-8726-4bb3-a832-18ab0d28adb7 X-MS-Exchange-Transport-CrossTenantHeadersStamped: BN3PR11MB0306 X-MC-Unique: wgBU1iI9MZmTiIBpVCIWsA-1 Content-Type: text/plain; charset=UTF-8 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Transfer-Encoding: 8bit X-MIME-Autoconverted: from base64 to 8bit by mail.home.local id u5UIVENj029523 > On Jun 30, 2016, at 11:23, Steven Rostedt wrote: > > On Thu, 30 Jun 2016 13:17:47 +0000 > Trond Myklebust wrote: > >>> On Jun 30, 2016, at 08:59, Steven Rostedt wrote: >>> >>> [ 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 > > Here's were the port is taken > >>> kworker/3:1H-134 [003] ..s. 61.036135: >>> => 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: >>> => 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) > > Here's where it is bounded. > >>> 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 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 >>> -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 >>> >> >> What is a “Hidden port that not appears in ss: 805”, and what does this report mean? Are we failing to close a socket? > > I believe hidden ports are ports that are bound to no socket. > Basically, a "port leak". Where they are in limbo and can never be > reused. > > I looked at my past report, and everthing is exactly like the issue > before. When I first boot my box, the port is there, I have the above > trace. I run netstat -tapn and grep for the port. And it shows that it > is an established socket between my box and my wife's box (I have a nfs > mounted file system for her to copy her pictures to my server). After a > couple of minutes, the port turns from ESTABLISHED to TIME_WAIT, and > after another minute it disappears. At that moment, the unhide-tcp > shows the port as hidden. > > When the socket goes away (without releasing the port) I see this in my > trace: > > kworker/1:1H-131 [001] ..s. 364.762537: xs_tcp_state_change: RPC: xs_tcp_state_change client ffff88040ad68800... > kworker/1:1H-131 [001] ..s. 364.762539: xs_tcp_state_change: RPC: state 4 conn 1 dead 0 zapped 1 sk_shutdown 3 > -0 [001] ..s. 364.762715: xs_tcp_state_change: RPC: xs_tcp_state_change client ffff88040ad68800... > -0 [001] ..s. 364.762716: xs_tcp_state_change: RPC: state 5 conn 0 dead 0 zapped 1 sk_shutdown 3 > -0 [001] ..s. 364.762728: xs_tcp_state_change: RPC: xs_tcp_state_change client ffff88040ad68800... > -0 [001] ..s. 364.762728: xs_tcp_state_change: RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3 > -0 [001] ..s. 364.762729: xprt_disconnect_done: RPC: disconnected transport ffff88040ad68800 > -0 [001] ..s. 364.762730: xs_tcp_state_change: RPC: xs_tcp_state_change client ffff88040ad68800... > -0 [001] ..s. 364.762730: xs_tcp_state_change: RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3 > -0 [001] ..s. 364.762730: xprt_disconnect_done: RPC: disconnected transport ffff88040ad68800 > > I can add more trace_printk()s if it would help. Wait. So the NFS mount is still active, it’s just that the socket disconnected due to no traffic? That should be OK. Granted that the port can’t be reused by another process, but you really don’t want that: what if there are no other ports available and you start writing to a file on the NFS partition? Cheers Trond