Re: sk->sk_socket seems to disappear before connection termination

[Eric Dumazet <eric.dumazet@gmail.com>]

Le mercredi 10 novembre 2010 à 11:53 +0100, Jan Engelhardt a écrit :
> On Wednesday 2010-11-10 06:47, Eric Dumazet wrote:
> >Le mercredi 10 novembre 2010 à 02:09 +0100, Jan Engelhardt a écrit :
> >> Hi,
> >> 
> >> Rafał reported this to us on IRC, paraphrasing what has been observed:
> >> 
> >> Using a simple rule like `iptables -A OUTPUT -p tcp --dport 80 -j LOG 
> >> --log-uid`, one can observe on creating a connection and terminating
> >> it that the trailing packets have skb->sk->sk_socket == NULL.
> >> Is this intended? Is the socket not retained until after TCP has
> >> sent out the closing exchange?
> >> 
> >> As I can reproduce:
> >> 
> >> $ telnet 134.76.13.21 80
> >> Trying 134.76.13.21...
> >> Connected to 134.76.13.21.
> >> Escape character is '^]'.
> >> ^]
> >> telnet> ^D
> >> Connection closed.
> >> 
> >> [491419.500978] IN= OUT=tun0 SRC=134.76.2.163 DST=134.76.13.21 LEN=60 TOS=0x10 PREC=0x00 TTL=64 ID=35420 DF PROTO=TCP SPT=58613 DPT=80 WINDOW=5488 RES=0x00 SYN URGP=0 UID=25121 GID=100 
> >> [491419.511533] IN= OUT=tun0 SRC=134.76.2.163 DST=134.76.13.21 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=35421 DF PROTO=TCP SPT=58613 DPT=80 WINDOW=86 RES=0x00 ACK URGP=0 UID=25121 GID=100 
> >> [491420.052182] IN= OUT=tun0 SRC=134.76.2.163 DST=134.76.13.21 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=35422 DF PROTO=TCP SPT=58613 DPT=80 WINDOW=86 RES=0x00 ACK FIN URGP=0 UID=25121 GID=100 
> >> [491420.063619] IN= OUT=tun0 SRC=134.76.2.163 DST=134.76.13.21 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=35423 DF PROTO=TCP SPT=58613 DPT=80 WINDOW=86 RES=0x00 ACK URGP=0 
> >
> >Hmmm... skb->sk->sk_socket is really NULL ?
> >Are you sure its not skb->sk->sk_socket->file which is NULL ?
> 
> I am certain of it, having augmented ipt_LOG/xt_LOGMARK temporarily by 
> appropriate printks.
> 
> >In this case, you might need to use sock_i_uid() / sock_i_ino() as a
> >fallback ? (expensive because they take a rwlock)
> 
> No, sock_i_uid also uses sk->sk_socket. What is interesting though is 
> that sock_i_uid uses SOCK_INODE(sk->sk_socket)->i_uid, but xt_owner uses 
> sk->sk_socket->file->f_cred->fsuid. Would you have an idea as to why 
> that is?
> Dave Howells (cced) did the last change on it.
> 

Hmm, this is not what I get here. Could you please recheck ?

diff --git a/net/ipv4/netfilter/ipt_LOG.c b/net/ipv4/netfilter/ipt_LOG.c
index 72ffc8f..b0933b7 100644
--- a/net/ipv4/netfilter/ipt_LOG.c
+++ b/net/ipv4/netfilter/ipt_LOG.c
@@ -337,6 +337,8 @@ static void dump_packet(struct sbuff *m,
        /* Max length: 15 "UID=4294967295 " */
        if ((logflags & IPT_LOG_UID) && !iphoff && skb->sk) {
                read_lock_bh(&skb->sk->sk_callback_lock);
+               pr_err("sk=%p sk->sk_socket=%p file=%p\n",
+                       skb->sk, skb->sk->sk_socket, skb->sk->sk_socket ? skb->sk->sk_socket->file : NULL);
                if (skb->sk->sk_socket && skb->sk->sk_socket->file)
                        sb_add(m, "UID=%u GID=%u ",
                                skb->sk->sk_socket->file->f_cred->fsuid,


[ 9917.808796] ipt_LOG: sk=ffff880118bd32c0 sk->sk_socket=ffff88011d0d8c00 file=ffff88011cd4e100
[ 9917.808851] IN= OUT=eth1 SRC=192.168.20.108 DST=192.168.20.110 LEN=60 TOS=0x10 PREC=0x00 TTL=64 ID=63701 DF PROTO=TCP SPT=60088 DPT=22 WINDOW=4380 RES=0x00 SYN URGP=0 UID=0 GID=0 
[ 9917.809091] ipt_LOG: sk=ffff880118bd32c0 sk->sk_socket=ffff88011d0d8c00 file=ffff88011cd4e100
[ 9917.809142] IN= OUT=eth1 SRC=192.168.20.108 DST=192.168.20.110 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=63702 DF PROTO=TCP SPT=60088 DPT=22 WINDOW=35 RES=0x00 ACK URGP=0 UID=0 GID=0 
[ 9917.814199] ipt_LOG: sk=ffff880118bd32c0 sk->sk_socket=ffff88011d0d8c00 file=ffff88011cd4e100
[ 9917.814251] IN= OUT=eth1 SRC=192.168.20.108 DST=192.168.20.110 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=63703 DF PROTO=TCP SPT=60088 DPT=22 WINDOW=35 RES=0x00 ACK URGP=0 UID=0 GID=0 
[ 9920.234680] ipt_LOG: sk=ffff880118bd32c0 sk->sk_socket=ffff88011d0d8c00 file=ffff88011cd4e100
[ 9920.234731] IN= OUT=eth1 SRC=192.168.20.108 DST=192.168.20.110 LEN=52 TOS=0x10 PREC=0x00 TTL=64 ID=63704 DF PROTO=TCP SPT=60088 DPT=22 WINDOW=35 RES=0x00 ACK FIN URGP=0 UID=0 GID=0 
[ 9920.235221] ipt_LOG: sk=ffff880078998000 sk->sk_socket=ffff880078c58300 file=          (null)
[ 9920.235271] IN= OUT=eth1 SRC=192.168.20.108 DST=192.168.20.110 LEN=52 TOS=0x00 PREC=0x00 TTL=64 ID=0 DF PROTO=TCP SPT=60088 DPT=22 WINDOW=35 RES=0x00 ACK URGP=0 


You can see in my log, that the last packet seems to be from a different socket !
(sk pointer changed to ffff880078998000 !)

Well well well, thats an ACK, in answer to FIN packet received from remote side.