From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
	id S1752488AbcF3PXv (ORCPT <rfc822;w@1wt.eu>);
	Thu, 30 Jun 2016 11:23:51 -0400
Received: from smtprelay0193.hostedemail.com ([216.40.44.193]:54938 "EHLO
	smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL)
	by vger.kernel.org with ESMTP id S1752000AbcF3PXt convert rfc822-to-8bit
	(ORCPT <rfc822;linux-kernel@vger.kernel.org>);
	Thu, 30 Jun 2016 11:23:49 -0400
X-Session-Marker: 726F737465647440676F6F646D69732E6F7267
X-Spam-Summary: 50,0,0,,d41d8cd98f00b204,rostedt@goodmis.org,:::::::::::::::::,RULES_HIT:2:41:152:196:355:379:541:599:800:960:967:973:988:989:1260:1263:1277:1311:1313:1314:1345:1359:1434:1437:1513:1515:1516:1518:1521:1535:1593:1594:1605:1622:1730:1747:1777:1792:2198:2199:2393:2525:2538:2553:2560:2563:2682:2685:2691:2859:2933:2937:2939:2942:2945:2947:2951:2954:3022:3138:3139:3140:3141:3142:3622:3865:3866:3867:3868:3870:3871:3872:3874:3934:3936:3938:3941:3944:3947:3950:3953:3956:3959:4049:4119:4250:4321:4605:5007:6117:6119:6120:6248:6261:6996:6997:7875:7901:7903:7974:8660:9025:10004:10394:10848:10967:11026:11232:11473:11658:11914:12043:12438:12517:12519:12555:12663:12681:12740:13148:13230:13255:14659:21063:21080:21088:21325:21433:30022:30045:30046:30054:30060:30062:30064:30067:30070:30079:30090:30091,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:3,LUA_SUMMARY:none
X-HE-Tag: hour47_2083682654903
X-Filterd-Recvd-Size: 8319
Date: Thu, 30 Jun 2016 11:23:41 -0400
From: Steven Rostedt <rostedt@goodmis.org>
To: Trond Myklebust <trondmy@primarydata.com>
Cc: Jeff Layton <jlayton@poochiereds.net>,
        Eric Dumazet <eric.dumazet@gmail.com>,
        Schumaker Anna <anna.schumaker@netapp.com>,
        "Linux NFS Mailing List" <linux-nfs@vger.kernel.org>,
        "Linux Network Devel Mailing List" <netdev@vger.kernel.org>,
        LKML <linux-kernel@vger.kernel.org>,
        "Andrew Morton" <akpm@linux-foundation.org>,
        Fields Bruce <bfields@fieldses.org>
Subject: Re: It's back! (Re: [REGRESSION] NFS is creating a hidden port
 (left over from xs_bind() ))
Message-ID: <20160630112341.5ab5a821@gandalf.local.home>
In-Reply-To: <C44AFFBB-EF40-4B22-8B45-7817EB7276E3@primarydata.com>
References: <20160630085950.61e5c7e0@gandalf.local.home>
 <C44AFFBB-EF40-4B22-8B45-7817EB7276E3@primarydata.com>
X-Mailer: Claws Mail 3.13.2 (GTK+ 2.24.30; x86_64-pc-linux-gnu)
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8BIT
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On Thu, 30 Jun 2016 13:17:47 +0000
Trond Myklebust <trondmy@primarydata.com> wrote:

> > On Jun 30, 2016, at 08:59, Steven Rostedt <rostedt@goodmis.org> 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: <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)

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
> >          <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
> >   
> 
> 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
          <idle>-0     [001] ..s.   364.762715: xs_tcp_state_change: RPC:       xs_tcp_state_change client ffff88040ad68800...
          <idle>-0     [001] ..s.   364.762716: xs_tcp_state_change: RPC:       state 5 conn 0 dead 0 zapped 1 sk_shutdown 3
          <idle>-0     [001] ..s.   364.762728: xs_tcp_state_change: RPC:       xs_tcp_state_change client ffff88040ad68800...
          <idle>-0     [001] ..s.   364.762728: xs_tcp_state_change: RPC:       state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
          <idle>-0     [001] ..s.   364.762729: xprt_disconnect_done: RPC:       disconnected transport ffff88040ad68800
          <idle>-0     [001] ..s.   364.762730: xs_tcp_state_change: RPC:       xs_tcp_state_change client ffff88040ad68800...
          <idle>-0     [001] ..s.   364.762730: xs_tcp_state_change: RPC:       state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
          <idle>-0     [001] ..s.   364.762730: xprt_disconnect_done: RPC:       disconnected transport ffff88040ad68800

I can add more trace_printk()s if it would help.

-- Steve