Hide Forgot
Description of problem: 'tcpstates' delta calculation is wrong for state change from LISTEN->SYN_RECV when a socket address is reused Version-Release number of selected component (if applicable): bcc-tools-0.16.0-2.el8.x86_64 How reproducible: Always Steps to Reproduce: 1. start ./tcpstates 2. initiate a connection from client. Close it and initiate again multiple times Actual results: ./tcpstates [...] 1 warning generated. SKADDR C-PID C-COMM LADDR LPORT RADDR RPORT OLDSTATE -> NEWSTATE MS [...] ffff97b2130b4e00 0 swapper/1 0.0.0.0 22 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 <--- First connection from client. MS delta is '0'. ffff97b2130b4e00 0 swapper/1 192.168.122.205 22 192.168.122.150 57532 SYN_RECV -> ESTABLISHED 0.012 ffff97b2130b4e00 7767 sshd 192.168.122.205 22 192.168.122.150 57532 ESTABLISHED -> FIN_WAIT1 120007.268 ffff97b2130b4e00 0 swapper/1 192.168.122.205 22 192.168.122.150 57532 FIN_WAIT2 -> CLOSE 0.003 ffff97b20dce57c0 0 swapper/0 0.0.0.0 22 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 <---- Got new sock addr. MS delta is '0' ffff97b20dce57c0 0 swapper/0 192.168.122.205 22 192.168.122.150 57534 SYN_RECV -> ESTABLISHED 0.010 ffff97b20dce57c0 0 swapper/1 192.168.122.205 22 192.168.122.150 57534 ESTABLISHED -> CLOSE_WAIT 17291.345 ffff97b20dce57c0 1 systemd 192.168.122.205 22 192.168.122.150 57534 LAST_ACK -> CLOSE 0.183 ffff97b20dce57c0 8645 sshd 192.168.122.205 22 192.168.122.150 57534 CLOSE_WAIT -> LAST_ACK 2.400 ffff97b2130b4e00 0 swapper/1 0.0.0.0 22 0.0.0.0 0 LISTEN -> SYN_RECV 907373.930 <--- Reusing sockaddr ffff97b2130b4e00. MS delta is "90"s. <<<< [...] ffff97b2130b30c0 8679 sshd 192.168.122.205 22 192.168.122.150 57544 CLOSE_WAIT -> LAST_ACK 1.785 ffff97b2130b30c0 983 auditd 192.168.122.205 22 192.168.122.150 57544 LAST_ACK -> CLOSE 0.159 ffff97b2130b30c0 0 swapper/1 0.0.0.0 22 0.0.0.0 0 LISTEN -> SYN_RECV 4818.211 <<< ffff97b2130b30c0 0 swapper/1 192.168.122.205 22 192.168.122.150 57546 SYN_RECV -> ESTABLISHED 0.006 ffff97b2130b30c0 0 swapper/1 192.168.122.205 22 192.168.122.150 57546 ESTABLISHED -> CLOSE_WAIT 1604.045 ffff97b2130b30c0 8682 sshd 192.168.122.205 22 192.168.122.150 57546 CLOSE_WAIT -> LAST_ACK 1.971 ffff97b2130b30c0 1157 sshd 192.168.122.205 22 192.168.122.150 57546 LAST_ACK -> CLOSE 0.121 ffff97b2130b30c0 0 swapper/1 0.0.0.0 22 0.0.0.0 0 LISTEN -> SYN_RECV 8609.057 <<< ffff97b2130b30c0 0 swapper/1 192.168.122.205 22 192.168.122.150 57548 SYN_RECV -> ESTABLISHED 0.007 ffff97b2130b30c0 8686 sshd 192.168.122.205 22 192.168.122.150 57548 ESTABLISHED -> FIN_WAIT1 120006.009 ffff97b2130b30c0 0 swapper/1 192.168.122.205 22 192.168.122.150 57548 FIN_WAIT1 -> FIN_WAIT2 40.539 ffff97b2130b30c0 0 swapper/1 192.168.122.205 22 192.168.122.150 57548 FIN_WAIT2 -> CLOSE 0.003 Expected results: Delta time not calculated from old socket. Additional info: The LISTEN -> SYN_RECV state change delta time normally starts with 0. But when the socket address is reused, the delta time is calculated from old socket hash value. The kernel can reuse the socket address. We see that from below kmem output: +++ crash> kmem ffff97b2130b30c0 CACHE OBJSIZE ALLOCATED TOTAL SLABS SSIZE NAME ffff97b21fdec8c0 2440 5 26 2 32k TCP SLAB MEMORY NODE TOTAL ALLOCATED FREE ffffd08c414c2c00 ffff97b2130b0000 0 13 3 10 FREE / [ALLOCATED] [ffff97b2130b30c0] <----------- Address allocated crash> kmem ffff97b2130b30c0 CACHE OBJSIZE ALLOCATED TOTAL SLABS SSIZE NAME ffff97b21fdec8c0 2440 4 26 2 32k TCP SLAB MEMORY NODE TOTAL ALLOCATED FREE ffffd08c414c2c00 ffff97b2130b0000 0 13 2 11 FREE / [ALLOCATED] ffff97b2130b30c0 (cpu 1 cache) <---------------------------------- Address free now. crash> kmem ffff97b2130b30c0 CACHE OBJSIZE ALLOCATED TOTAL SLABS SSIZE NAME ffff97b21fdec8c0 2440 5 26 2 32k TCP SLAB MEMORY NODE TOTAL ALLOCATED FREE ffffd08c414c2c00 ffff97b2130b0000 0 13 3 10 FREE / [ALLOCATED] [ffff97b2130b30c0] <------------------------------------------ Address allocated for new connection. +++ Problem may be due to socket hashing used by bcc. BPF_HASH(last, struct sock *, u64); <----------- In this hash, it updates the timestamp like: last.update(&sk, &ts); And delta calculation: u64 *tsp, delta_us; tsp = last.lookup(&sk); if (tsp == 0) delta_us = 0; else delta_us = (bpf_ktime_get_ns() - *tsp) / 1000; So its likely that old socket hash is still existing in hash table and last.lookup will be a success for new connection.
Created attachment 1760955 [details] Possible fix
Looks like we should forget the socket when the connection is closed. Can you try the attached tcpstates script?
(In reply to Jerome Marchand from comment #2) > Looks like we should forget the socket when the connection is closed. Can > you try the attached tcpstates script? it works perfectly now: 1 warning generated. SKADDR C-PID C-COMM LADDR LPORT RADDR RPORT OLDSTATE -> NEWSTATE MS ffff94e8dcafc440 0 swapper/0 0.0.0.0 22 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 ffff94e8dcafc440 0 swapper/0 192.168.122.205 22 192.168.122.1 36600 SYN_RECV -> ESTABLISHED 0.007 ffff94e8dcafc440 0 swapper/0 192.168.122.205 22 192.168.122.1 36600 ESTABLISHED -> CLOSE_WAIT 1699.773 ffff94e8dcafc440 6148 sshd 192.168.122.205 22 192.168.122.1 36600 CLOSE_WAIT -> LAST_ACK 1.724 ffff94e8dcafc440 1 systemd 192.168.122.205 22 192.168.122.1 36600 LAST_ACK -> CLOSE 0.116 ffff94e8dcafc440 0 swapper/0 0.0.0.0 22 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 <<<< ffff94e8dcafc440 0 swapper/0 192.168.122.205 22 192.168.122.1 36606 SYN_RECV -> ESTABLISHED 0.007 ffff94e8dcafc440 0 swapper/0 192.168.122.205 22 192.168.122.1 36606 ESTABLISHED -> CLOSE_WAIT 1495.353 ffff94e8dcafc440 6150 sshd 192.168.122.205 22 192.168.122.1 36606 CLOSE_WAIT -> LAST_ACK 1.723 ffff94e8dcafc440 6138 python3 192.168.122.205 22 192.168.122.1 36606 LAST_ACK -> CLOSE 0.109
Pre-verify by using ncat to build connection multiple times, the result looks good [root@netqe3 tools]# uname -r 4.18.0-305.1.el8.x86_64 [root@netqe3 tools]# rpm -q bcc bcc-0.19.0-2.el8.x86_64 [root@netqe3 tools]# [root@netqe3 tools]# ./tcpstates SKADDR C-PID C-COMM LADDR LPORT RADDR RPORT OLDSTATE -> NEWSTATE MS [Other connection output...] ffff8f95050f1380 39262 ncat 192.168.1.2 12530 192.168.1.1 43596 CLOSE_WAIT -> LAST_ACK 0.074 ffff8f95050f1380 0 swapper/46 192.168.1.2 12530 192.168.1.1 43596 LAST_ACK -> CLOSE 0.143 ffff8f9573f26b40 0 swapper/16 0.0.0.0 12530 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 ffff8f9573f26b40 0 swapper/16 192.168.1.2 12530 192.168.1.1 43598 SYN_RECV -> ESTABLISHED 0.004 ffff8f9573f26b40 0 swapper/16 192.168.1.2 12530 192.168.1.1 43598 ESTABLISHED -> CLOSE_WAIT 301.268 ffff8f9573f26b40 39262 ncat 192.168.1.2 12530 192.168.1.1 43598 CLOSE_WAIT -> LAST_ACK 0.075 ffff8f9573f26b40 0 swapper/10 192.168.1.2 12530 192.168.1.1 43598 LAST_ACK -> CLOSE 0.091 ffff8f9574bf3a80 0 swapper/14 0.0.0.0 12530 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 <<<<<<<<<<<<<< MS is from 0 ffff8f9574bf3a80 0 swapper/14 192.168.1.2 12530 192.168.1.1 43600 SYN_RECV -> ESTABLISHED 0.009 ffff8f9574bf3a80 0 swapper/14 192.168.1.2 12530 192.168.1.1 43600 ESTABLISHED -> CLOSE_WAIT 277.749 ffff8f9574bf3a80 0 swapper/14 192.168.1.2 12530 192.168.1.1 43600 LAST_ACK -> CLOSE 0.095 ffff8f9574bf3a80 39262 ncat 192.168.1.2 12530 192.168.1.1 43600 CLOSE_WAIT -> LAST_ACK 0.075 ffff8f9574b94440 0 swapper/6 0.0.0.0 12530 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 ffff8f9574b94440 0 swapper/6 192.168.1.2 12530 192.168.1.1 43602 SYN_RECV -> ESTABLISHED 0.010 ffff8f9574b94440 0 swapper/6 192.168.1.2 12530 192.168.1.1 43602 ESTABLISHED -> CLOSE_WAIT 289.831 ffff8f9574b94440 0 swapper/30 192.168.1.2 12530 192.168.1.1 43602 LAST_ACK -> CLOSE 0.046 [Other connection output...] ffff8f95050f57c0 0 swapper/28 192.168.1.2 12530 192.168.1.1 43618 ESTABLISHED -> CLOSE_WAIT 272.541 ffff8f95050f57c0 39262 ncat 192.168.1.2 12530 192.168.1.1 43618 CLOSE_WAIT -> LAST_ACK 0.074 ffff8f95050f57c0 0 swapper/44 192.168.1.2 12530 192.168.1.1 43618 LAST_ACK -> CLOSE 0.143 ffff8f9574bf3a80 0 swapper/14 0.0.0.0 12530 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 <<<<<<<<<<<<<< Reuse SKADDR ffff8f9574bf3a80, MS still count from 0 ffff8f9574bf3a80 0 swapper/14 192.168.1.2 12530 192.168.1.1 43620 SYN_RECV -> ESTABLISHED 0.009 ffff8f9574bf3a80 0 swapper/14 192.168.1.2 12530 192.168.1.1 43620 ESTABLISHED -> CLOSE_WAIT 287.069 ffff8f9574bf3a80 0 swapper/14 192.168.1.2 12530 192.168.1.1 43620 LAST_ACK -> CLOSE 0.036 ffff8f9574bf3a80 39262 ncat 192.168.1.2 12530 192.168.1.1 43620 CLOSE_WAIT -> LAST_ACK 0.076 ffff8f9574bf1380 0 swapper/14 0.0.0.0 12530 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 ffff8f9574bf1380 0 swapper/14 192.168.1.2 12530 192.168.1.1 43622 SYN_RECV -> ESTABLISHED 0.009 ffff8f9574bf1380 0 swapper/14 192.168.1.2 12530 192.168.1.1 43622 ESTABLISHED -> CLOSE_WAIT 260.303 [...]
[root@netqe3 tools]# ./tcpstates SKADDR C-PID C-COMM LADDR LPORT RADDR RPORT OLDSTATE -> NEWSTATE MS ffff8c6797977500 0 swapper/8 0.0.0.0 9904 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 ffff8c6797977500 0 swapper/8 192.168.1.2 9904 192.168.1.1 43296 SYN_RECV -> ESTABLISHED 0.010 ffff8c6797977500 0 swapper/8 192.168.1.2 9904 192.168.1.1 43296 ESTABLISHED -> CLOSE_WAIT 0.031 ffff8c6797977500 0 swapper/40 192.168.1.2 9904 192.168.1.1 43296 LAST_ACK -> CLOSE 0.049 ffff8c6797977500 44175 ncat 192.168.1.2 9904 192.168.1.1 43296 CLOSE_WAIT -> LAST_ACK 0.082 ffff8c67b58c4e00 44175 ncat 192.168.1.2 9904 192.168.1.1 43298 ESTABLISHED -> CLOSE_WAIT 0.040 ffff8c67b58c4e00 44175 ncat 192.168.1.2 9904 192.168.1.1 43298 CLOSE_WAIT -> LAST_ACK 0.015 ffff8c67b58c4e00 0 swapper/46 0.0.0.0 9904 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 <<<<<<< MS from 0 ffff8c67b58c4e00 0 swapper/46 192.168.1.2 9904 192.168.1.1 43298 SYN_RECV -> ESTABLISHED 0.011 ffff8c67b58c4e00 0 swapper/42 192.168.1.2 9904 192.168.1.1 43298 LAST_ACK -> CLOSE 0.032 [other connection...] ffff8c6797b5b0c0 0 swapper/28 0.0.0.0 9904 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 ffff8c6797b5b0c0 0 swapper/28 192.168.1.2 9904 192.168.1.1 43338 SYN_RECV -> ESTABLISHED 0.011 ffff8c6797b5b0c0 0 swapper/28 192.168.1.2 9904 192.168.1.1 43338 ESTABLISHED -> CLOSE_WAIT 0.031 ffff8c6797b5b0c0 0 swapper/22 192.168.1.2 9904 192.168.1.1 43338 LAST_ACK -> CLOSE 0.032 ffff8c6797b5b0c0 44175 ncat 192.168.1.2 9904 192.168.1.1 43338 CLOSE_WAIT -> LAST_ACK 0.019 ffff8c67b58c4e00 0 swapper/46 0.0.0.0 9904 0.0.0.0 0 LISTEN -> SYN_RECV 0.000 <<<<<< MS still from 0 for the same SKADDR ffff8c67b58c4e00 0 swapper/46 192.168.1.2 9904 192.168.1.1 43340 SYN_RECV -> ESTABLISHED 0.011 ffff8c67b58c4e00 0 swapper/46 192.168.1.2 9904 192.168.1.1 43340 ESTABLISHED -> CLOSE_WAIT 0.039 ffff8c67b58c4e00 44175 ncat 192.168.1.2 9904 192.168.1.1 43340 CLOSE_WAIT -> LAST_ACK 0.013 ffff8c67b58c4e00 0 swapper/42 192.168.1.2 9904 192.168.1.1 43340 LAST_ACK -> CLOSE 0.036 ^C[root@netqe3 tools]# uname -r 4.18.0-305.6.el8.x86_64 [root@netqe3 tools]# rpm -q bcc bcc-0.19.0-2.el8.x86_64 [root@netqe3 tools]#
Base on comment11, set this to VERIFIED
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory (bcc bug fix and enhancement update), and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2021:4205