From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752109AbcF3NSN (ORCPT ); Thu, 30 Jun 2016 09:18:13 -0400 Received: from us-smtp-delivery-194.mimecast.com ([216.205.24.194]:42817 "EHLO us-smtp-delivery-194.mimecast.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751704AbcF3NSK convert rfc822-to-8bit (ORCPT ); Thu, 30 Jun 2016 09:18:10 -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/fWA Date: Thu, 30 Jun 2016 13:17:47 +0000 Message-ID: References: <20160630085950.61e5c7e0@gandalf.local.home> In-Reply-To: <20160630085950.61e5c7e0@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: 9cee15a6-edf5-4ab3-6529-08d3a0e8ee5a x-microsoft-exchange-diagnostics: 1;BN3PR11MB0307;20:Eh5oOdBNndhTa26DcCpV7s/VKUt+OFfcerBNwupT++XxbJrWG6r3W7jRRXFH0t1M/Gzigi2M0IwD5FGnJ5BhOvy1aLHG/J7CLjG9ktl0JPtDXdYjqXD0OPjZcMZIOwrLo3TvDj5ckmPc6MgVqv4fp1zHaOfOREidYv8OXlpaFh8= x-microsoft-antispam: UriScan:;BCL:0;PCL:0;RULEID:;SRVR:BN3PR11MB0307; x-microsoft-antispam-prvs: x-exchange-antispam-report-test: UriScan:(192374486261705)(21532816269658); x-exchange-antispam-report-cfa-test: BCL:0;PCL:0;RULEID:(6040130)(601004)(2401047)(8121501046)(5005006)(3002001)(10201501046)(6041072)(6043046);SRVR:BN3PR11MB0307;BCL:0;PCL:0;RULEID:;SRVR:BN3PR11MB0307; x-forefront-prvs: 0989A7979C x-forefront-antispam-report: SFV:NSPM;SFS:(10019020)(6009001)(7916002)(209900001)(189002)(199003)(24454002)(81166006)(81156014)(8676002)(68736007)(105586002)(2900100001)(99286002)(3280700002)(2950100001)(106356001)(15975445007)(122556002)(86362001)(106116001)(77096005)(2906002)(54356999)(586003)(11100500001)(7846002)(16601075003)(4326007)(87936001)(19580405001)(19580395003)(33656002)(66066001)(5002640100001)(50986999)(110136002)(82746002)(36756003)(8936002)(92566002)(7736002)(6116002)(83716003)(5890100001)(102836003)(3660700001)(3846002)(101416001)(97736004)(10400500002)(76176999)(189998001)(305945005)(104396002)(6606295002);DIR:OUT;SFP:1102;SCL:1;SRVR:BN3PR11MB0307;H:BN3PR11MB0305.namprd11.prod.outlook.com;FPR:;SPF:None;PTR:InfoNoRecords;MX:1;A:1;LANG:en; spamdiagnosticoutput: 1:99 spamdiagnosticmetadata: NSPM Content-ID: <5C4B0D82C3083343B79D3A034F3E0BEF@namprd11.prod.outlook.com> MIME-Version: 1.0 X-OriginatorOrg: primarydata.com X-MS-Exchange-CrossTenant-originalarrivaltime: 30 Jun 2016 13:17:47.9028 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Hosted X-MS-Exchange-CrossTenant-id: 03193ed6-8726-4bb3-a832-18ab0d28adb7 X-MS-Exchange-Transport-CrossTenantHeadersStamped: BN3PR11MB0307 X-MC-Unique: JB0Ryo2-PtCzAi2DCYPQ3Q-1 Content-Type: text/plain; charset=WINDOWS-1252 Content-Transfer-Encoding: 8BIT Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org > 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 > 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) > 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? Cheers Trond