sk->sk_socket seems to disappear before connection termination

sk->sk_socket seems to disappear before connection termination

[Jan Engelhardt]

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 
--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Eric Dumazet]

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 ?

In this case, you might need to use sock_i_uid() / sock_i_ino() as a
fallback ? (expensive because they take a rwlock)




--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Jan Engelhardt]

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.

--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Eric Dumazet]

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.

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

[Jan Engelhardt]

On Wednesday 2010-11-10 17:44, Eric Dumazet wrote:
>
>[ 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 !)

Yes, that's it.

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

But why is it not handled by sk ffff880118bd32c0 anymore?
It does have, after all, the same (addr,port) tuple.
And it is sort of a hiccup for xt_owner users.

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

[Eric Dumazet]

Le mercredi 10 novembre 2010 à 18:17 +0100, Jan Engelhardt a écrit :
> On Wednesday 2010-11-10 17:44, Eric Dumazet wrote:
> >
> >[ 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 !)
> 
> Yes, that's it.
> 
> >Well well well, thats an ACK, in answer to FIN packet received from remote
> >side.
> 
> But why is it not handled by sk ffff880118bd32c0 anymore?
> It does have, after all, the same (addr,port) tuple.
> And it is sort of a hiccup for xt_owner users.

Its because of TIMEWAIT state : no more socket

We use a special tcp socket (net->ipv4.tcp_sock) in tcp_v4_send_ack()

Its yet another contention point on SMP machines :(

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

[Patrick McHardy]

On 10.11.2010 18:37, Eric Dumazet wrote:
> Le mercredi 10 novembre 2010 à 18:17 +0100, Jan Engelhardt a écrit :
>> On Wednesday 2010-11-10 17:44, Eric Dumazet wrote:
>>>
>>> [ 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 !)
>>
>> Yes, that's it.
>>
>>> Well well well, thats an ACK, in answer to FIN packet received from remote
>>> side.
>>
>> But why is it not handled by sk ffff880118bd32c0 anymore?
>> It does have, after all, the same (addr,port) tuple.
>> And it is sort of a hiccup for xt_owner users.
> 
> Its because of TIMEWAIT state : no more socket
> 
> We use a special tcp socket (net->ipv4.tcp_sock) in tcp_v4_send_ack()

Yeah, this has always been a problem with the owner match.
I don't think this fixable, it should probably only be used
in a stateful manner.