Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Intermittent failure of test_rx_rate_limiting test #1809

Closed
raduiliescu opened this issue Apr 21, 2020 · 6 comments · Fixed by #1898
Closed

Intermittent failure of test_rx_rate_limiting test #1809

raduiliescu opened this issue Apr 21, 2020 · 6 comments · Fixed by #1898
Assignees
@acatangiu
Labels
Priority: High Indicates than an issue or pull request should be resolved ahead of issues or pull requests labelled

Comments

@raduiliescu
Copy link
Contributor

raduiliescu commented Apr 21, 2020 •
edited by aghecenco
Loading

test_rx_rate_limiting is failing intermittently.
Example of output:

=================================== FAILURES ===================================
____________________ test_rx_rate_limiting[ubuntu_with_ssh] ____________________
integration_tests/functional/test_rate_limiter.py:147: in test_rx_rate_limiting
    _check_rx_rate_limiting(test_microvm, guest_ips)
integration_tests/functional/test_rate_limiter.py:283: in _check_rx_rate_limiting
    assert (
E   assert 11.539077758789062 < 10
E    +  where 11.539077758789062 = _get_difference(92758000.0, 104857600.0)
------------------------------ Captured log setup ------------------------------
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8375] Command:
cd /firecracker && TARGET_CC=musl-gcc cargo build --release --target x86_64-unknown-linux-musl
[8375] stderr:
    Finished release [optimized] target(s) in 0.03s
------------------------------ Captured log call -------------------------------
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8378] Command:
ip netns add 7f369f93-a01c-4183-b4ec-00dd48078101
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8380] Command:
ln -f /tmp/fctest-efdxs5su/7f369f93-a01c-4183-b4ec-00dd48078101/log_fifo /srv/jailer/firecracker/7f369f93-a01c-4183-b4ec-00dd48078101/root/log_fifo
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8382] Command:
chown 1234:1234 /srv/jailer/firecracker/7f369f93-a01c-4183-b4ec-00dd48078101/root/log_fifo
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8385] Command:
['/tmp/fctest-efdxs5su/newpid_cloner', '/firecracker/build/cargo_target/x86_64-unknown-linux-musl/release/jailer', '--id', '7f369f93-a01c-4183-b4ec-00dd48078101', '--exec-file', '/firecracker/build/cargo_target/x86_64-unknown-linux-musl/release/firecracker', '--node', '0', '--uid', '1234', '--gid', '1234', '--chroot-base-dir', '/srv/jailer', '--netns', '/var/run/netns/7f369f93-a01c-4183-b4ec-00dd48078101', '--daemonize', '--', '--log-path', 'log_fifo', '--level', 'Info']
[8385] stdout:
8386
09:51:19 retry.api: WARNING , retrying in 0.1 seconds...
09:51:19 urllib3.connectionpool: DEBUG http://localhost:None "PUT /machine-config HTTP/1.1" 204 0
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8389] Command:
pmap -xq 8386
[8389] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1024    1024 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000      28      28      28 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bd6d000     132       8       8 rw---   [ stack ]
00007ffc3bd6d000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:19 commands: DEBUG 
[8392] Command:
ln -f /tmp/fctest-efdxs5su/7f369f93-a01c-4183-b4ec-00dd48078101/kernel/vmlinux.bin /srv/jailer/firecracker/7f369f93-a01c-4183-b4ec-00dd48078101/root/vmlinux.bin
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8394] Command:
chown 1234:1234 /srv/jailer/firecracker/7f369f93-a01c-4183-b4ec-00dd48078101/root/vmlinux.bin
09:51:19 urllib3.connectionpool: DEBUG http://localhost:None "PUT /boot-source HTTP/1.1" 204 0
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8396] Command:
ln -f /tmp/fctest-efdxs5su/7f369f93-a01c-4183-b4ec-00dd48078101/fsfiles/xenial.rootfs.ext4 /srv/jailer/firecracker/7f369f93-a01c-4183-b4ec-00dd48078101/root/xenial.rootfs.ext4
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8398] Command:
chown 1234:1234 /srv/jailer/firecracker/7f369f93-a01c-4183-b4ec-00dd48078101/root/xenial.rootfs.ext4
09:51:19 urllib3.connectionpool: DEBUG http://localhost:None "PUT /drives/rootfs HTTP/1.1" 204 0
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8400] Command:
ip tuntap add mode tap name 7f369f93tap1
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8402] Command:
ip link set 7f369f93tap1 netns 7f369f93-a01c-4183-b4ec-00dd48078101
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8404] Command:
ip netns exec 7f369f93-a01c-4183-b4ec-00dd48078101 ifconfig 7f369f93tap1 192.168.0.21/30 up
09:51:19 urllib3.connectionpool: DEBUG http://localhost:None "PUT /network-interfaces/1 HTTP/1.1" 204 0
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:19 commands: DEBUG 
[8406] Command:
ip tuntap add mode tap name 7f369f93tap2
09:51:19 asyncio: DEBUG Using selector: EpollSelector
09:51:20 commands: DEBUG 
[8408] Command:
ip link set 7f369f93tap2 netns 7f369f93-a01c-4183-b4ec-00dd48078101
09:51:20 asyncio: DEBUG Using selector: EpollSelector
09:51:20 commands: DEBUG 
[8410] Command:
ip netns exec 7f369f93-a01c-4183-b4ec-00dd48078101 ifconfig 7f369f93tap2 192.168.0.25/30 up
09:51:20 urllib3.connectionpool: DEBUG http://localhost:None "PUT /network-interfaces/2 HTTP/1.1" 204 0
09:51:20 asyncio: DEBUG Using selector: EpollSelector
09:51:20 commands: DEBUG 
[8412] Command:
ip tuntap add mode tap name 7f369f93tap3
09:51:20 asyncio: DEBUG Using selector: EpollSelector
09:51:20 commands: DEBUG 
[8414] Command:
ip link set 7f369f93tap3 netns 7f369f93-a01c-4183-b4ec-00dd48078101
09:51:20 asyncio: DEBUG Using selector: EpollSelector
09:51:20 commands: DEBUG 
[8416] Command:
ip netns exec 7f369f93-a01c-4183-b4ec-00dd48078101 ifconfig 7f369f93tap3 192.168.0.29/30 up
09:51:20 urllib3.connectionpool: DEBUG http://localhost:None "PUT /network-interfaces/3 HTTP/1.1" 204 0
09:51:20 urllib3.connectionpool: DEBUG http://localhost:None "PUT /actions HTTP/1.1" 204 0
09:51:20 nsenter: DEBUG Entering net namespace /var/run/netns/7f369f93-a01c-4183-b4ec-00dd48078101
09:51:20 asyncio: DEBUG Using selector: EpollSelector
09:51:20 asyncio: DEBUG Using selector: EpollSelector
09:51:20 commands: DEBUG 
[8421] Command:
pmap -xq 8386
[8421] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1216    1216 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000     540     480     480 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda86d6f000      16       0       0 rw---   [ anon ]
00007fda86d6f000       0       0       0 rw---   [ anon ]
00007fda86d73000       8       0       0 -----   [ anon ]
00007fda86d73000       0       0       0 -----   [ anon ]
00007fda86d75000    2052       8       8 rw---   [ anon ]
00007fda86d75000       0       0       0 rw---   [ anon ]
00007fda86f76000       8       0       0 -----   [ anon ]
00007fda86f76000       0       0       0 -----   [ anon ]
00007fda86f78000    2052       8       8 rw---   [ anon ]
00007fda86f78000       0       0       0 rw---   [ anon ]
00007fda87179000      12       4       4 rw-s-   [ anon ]
00007fda87179000       0       0       0 rw-s-   [ anon ]
00007fda8717c000      12       4       4 rw-s-   [ anon ]
00007fda8717c000       0       0       0 rw-s-   [ anon ]
00007fda8717f000       4       4       4 rw-s- zero (deleted)
00007fda8717f000       0       0       0 rw-s- zero (deleted)
00007fda87180000       4       4       4 rw-s- zero (deleted)
00007fda87180000       0       0       0 rw-s- zero (deleted)
00007fda87181000      12      12      12 rw-s- zero (deleted)
00007fda87181000       0       0       0 rw-s- zero (deleted)
00007fda87184000  262144   73020   73020 rw---   [ anon ]
00007fda87184000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bccb000     780     780     780 rw---   [ stack ]
00007ffc3bccb000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:20 commands: DEBUG 
[8420] Command:
['ssh', '-q', '-o', 'ConnectTimeout=1', '-o', 'StrictHostKeyChecking=no', '-o', 'UserKnownHostsFile=/dev/null', '-i', '/tmp/fctest-efdxs5su/7f369f93-a01c-4183-b4ec-00dd48078101/fsfiles/xenial.rootfs.id_rsa', 'root@192.168.0.22', 'true']
09:51:20 nsenter: DEBUG Leaving net namespace /var/run/netns/7f369f93-a01c-4183-b4ec-00dd48078101
09:51:20 nsenter: DEBUG Entering net namespace /var/run/netns/7f369f93-a01c-4183-b4ec-00dd48078101
09:51:20 asyncio: DEBUG Using selector: EpollSelector
09:51:21 commands: DEBUG 
[8423] Command:
['ssh', '-q', '-o', 'ConnectTimeout=1', '-o', 'StrictHostKeyChecking=no', '-o', 'UserKnownHostsFile=/dev/null', '-i', '/tmp/fctest-efdxs5su/7f369f93-a01c-4183-b4ec-00dd48078101/fsfiles/xenial.rootfs.id_rsa', 'root@192.168.0.22', 'iperf3 -sD -f KBytes\n']
09:51:21 nsenter: DEBUG Leaving net namespace /var/run/netns/7f369f93-a01c-4183-b4ec-00dd48078101
09:51:21 asyncio: DEBUG Using selector: EpollSelector
09:51:23 asyncio: DEBUG Using selector: EpollSelector
09:51:23 commands: DEBUG 
[8424] Command:
pmap -xq 8386
[8424] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1216    1216 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000     540     480     480 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda86d6f000      16       0       0 rw---   [ anon ]
00007fda86d6f000       0       0       0 rw---   [ anon ]
00007fda86d73000       8       0       0 -----   [ anon ]
00007fda86d73000       0       0       0 -----   [ anon ]
00007fda86d75000    2052       8       8 rw---   [ anon ]
00007fda86d75000       0       0       0 rw---   [ anon ]
00007fda86f76000       8       0       0 -----   [ anon ]
00007fda86f76000       0       0       0 -----   [ anon ]
00007fda86f78000    2052       8       8 rw---   [ anon ]
00007fda86f78000       0       0       0 rw---   [ anon ]
00007fda87179000      12       4       4 rw-s-   [ anon ]
00007fda87179000       0       0       0 rw-s-   [ anon ]
00007fda8717c000      12       4       4 rw-s-   [ anon ]
00007fda8717c000       0       0       0 rw-s-   [ anon ]
00007fda8717f000       4       4       4 rw-s- zero (deleted)
00007fda8717f000       0       0       0 rw-s- zero (deleted)
00007fda87180000       4       4       4 rw-s- zero (deleted)
00007fda87180000       0       0       0 rw-s- zero (deleted)
00007fda87181000      12      12      12 rw-s- zero (deleted)
00007fda87181000       0       0       0 rw-s- zero (deleted)
00007fda87184000  262144   73104   73104 rw---   [ anon ]
00007fda87184000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bccb000     780     780     780 rw---   [ stack ]
00007ffc3bccb000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:24 asyncio: DEBUG Using selector: EpollSelector
09:51:24 commands: DEBUG 
[8428] Command:
pmap -xq 8386
[8428] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1216    1216 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000     540     480     480 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda86d6f000      16       0       0 rw---   [ anon ]
00007fda86d6f000       0       0       0 rw---   [ anon ]
00007fda86d73000       8       0       0 -----   [ anon ]
00007fda86d73000       0       0       0 -----   [ anon ]
00007fda86d75000    2052       8       8 rw---   [ anon ]
00007fda86d75000       0       0       0 rw---   [ anon ]
00007fda86f76000       8       0       0 -----   [ anon ]
00007fda86f76000       0       0       0 -----   [ anon ]
00007fda86f78000    2052       8       8 rw---   [ anon ]
00007fda86f78000       0       0       0 rw---   [ anon ]
00007fda87179000      12       4       4 rw-s-   [ anon ]
00007fda87179000       0       0       0 rw-s-   [ anon ]
00007fda8717c000      12       4       4 rw-s-   [ anon ]
00007fda8717c000       0       0       0 rw-s-   [ anon ]
00007fda8717f000       4       4       4 rw-s- zero (deleted)
00007fda8717f000       0       0       0 rw-s- zero (deleted)
00007fda87180000       4       4       4 rw-s- zero (deleted)
00007fda87180000       0       0       0 rw-s- zero (deleted)
00007fda87181000      12      12      12 rw-s- zero (deleted)
00007fda87181000       0       0       0 rw-s- zero (deleted)
00007fda87184000  262144   73508   73508 rw---   [ anon ]
00007fda87184000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bccb000     780     780     780 rw---   [ stack ]
00007ffc3bccb000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:25 asyncio: DEBUG Using selector: EpollSelector
09:51:25 commands: DEBUG 
[8430] Command:
pmap -xq 8386
[8430] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1216    1216 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000     540     480     480 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda86d6f000      16       0       0 rw---   [ anon ]
00007fda86d6f000       0       0       0 rw---   [ anon ]
00007fda86d73000       8       0       0 -----   [ anon ]
00007fda86d73000       0       0       0 -----   [ anon ]
00007fda86d75000    2052       8       8 rw---   [ anon ]
00007fda86d75000       0       0       0 rw---   [ anon ]
00007fda86f76000       8       0       0 -----   [ anon ]
00007fda86f76000       0       0       0 -----   [ anon ]
00007fda86f78000    2052       8       8 rw---   [ anon ]
00007fda86f78000       0       0       0 rw---   [ anon ]
00007fda87179000      12       4       4 rw-s-   [ anon ]
00007fda87179000       0       0       0 rw-s-   [ anon ]
00007fda8717c000      12       4       4 rw-s-   [ anon ]
00007fda8717c000       0       0       0 rw-s-   [ anon ]
00007fda8717f000       4       4       4 rw-s- zero (deleted)
00007fda8717f000       0       0       0 rw-s- zero (deleted)
00007fda87180000       4       4       4 rw-s- zero (deleted)
00007fda87180000       0       0       0 rw-s- zero (deleted)
00007fda87181000      12      12      12 rw-s- zero (deleted)
00007fda87181000       0       0       0 rw-s- zero (deleted)
00007fda87184000  262144   73508   73508 rw---   [ anon ]
00007fda87184000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bccb000     780     780     780 rw---   [ stack ]
00007ffc3bccb000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:26 asyncio: DEBUG Using selector: EpollSelector
09:51:26 commands: DEBUG 
[8432] Command:
pmap -xq 8386
[8432] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1216    1216 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000     540     480     480 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda86d6f000      16       0       0 rw---   [ anon ]
00007fda86d6f000       0       0       0 rw---   [ anon ]
00007fda86d73000       8       0       0 -----   [ anon ]
00007fda86d73000       0       0       0 -----   [ anon ]
00007fda86d75000    2052       8       8 rw---   [ anon ]
00007fda86d75000       0       0       0 rw---   [ anon ]
00007fda86f76000       8       0       0 -----   [ anon ]
00007fda86f76000       0       0       0 -----   [ anon ]
00007fda86f78000    2052       8       8 rw---   [ anon ]
00007fda86f78000       0       0       0 rw---   [ anon ]
00007fda87179000      12       4       4 rw-s-   [ anon ]
00007fda87179000       0       0       0 rw-s-   [ anon ]
00007fda8717c000      12       4       4 rw-s-   [ anon ]
00007fda8717c000       0       0       0 rw-s-   [ anon ]
00007fda8717f000       4       4       4 rw-s- zero (deleted)
00007fda8717f000       0       0       0 rw-s- zero (deleted)
00007fda87180000       4       4       4 rw-s- zero (deleted)
00007fda87180000       0       0       0 rw-s- zero (deleted)
00007fda87181000      12      12      12 rw-s- zero (deleted)
00007fda87181000       0       0       0 rw-s- zero (deleted)
00007fda87184000  262144   73516   73516 rw---   [ anon ]
00007fda87184000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bccb000     780     780     780 rw---   [ stack ]
00007ffc3bccb000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:26 commands: DEBUG 
[8426] Command:
ip netns exec 7f369f93-a01c-4183-b4ec-00dd48078101  iperf3 -c 192.168.0.22 -t3 -f KBytes
[8426] stdout:
Connecting to host 192.168.0.22, port 5201
[  4] local 192.168.0.21 port 43634 connected to 192.168.0.22 port 5201
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  3.24 GBytes  3397961 KBytes/sec    4    935 KBytes       
[  4]   1.00-2.00   sec  3.27 GBytes  3424657 KBytes/sec    0    935 KBytes       
[  4]   2.00-3.00   sec  3.30 GBytes  3462204 KBytes/sec    0    936 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
[  4]   0.00-3.00   sec  9.81 GBytes  3428274 KBytes/sec    4             sender
[  4]   0.00-3.00   sec  9.81 GBytes  3427357 KBytes/sec                  receiver

iperf Done.

09:51:26 asyncio: DEBUG Using selector: EpollSelector
09:51:27 asyncio: DEBUG Using selector: EpollSelector
09:51:27 commands: DEBUG 
[8436] Command:
pmap -xq 8386
[8436] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1216    1216 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000     540     480     480 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda86d6f000      16       0       0 rw---   [ anon ]
00007fda86d6f000       0       0       0 rw---   [ anon ]
00007fda86d73000       8       0       0 -----   [ anon ]
00007fda86d73000       0       0       0 -----   [ anon ]
00007fda86d75000    2052       8       8 rw---   [ anon ]
00007fda86d75000       0       0       0 rw---   [ anon ]
00007fda86f76000       8       0       0 -----   [ anon ]
00007fda86f76000       0       0       0 -----   [ anon ]
00007fda86f78000    2052       8       8 rw---   [ anon ]
00007fda86f78000       0       0       0 rw---   [ anon ]
00007fda87179000      12       4       4 rw-s-   [ anon ]
00007fda87179000       0       0       0 rw-s-   [ anon ]
00007fda8717c000      12       4       4 rw-s-   [ anon ]
00007fda8717c000       0       0       0 rw-s-   [ anon ]
00007fda8717f000       4       4       4 rw-s- zero (deleted)
00007fda8717f000       0       0       0 rw-s- zero (deleted)
00007fda87180000       4       4       4 rw-s- zero (deleted)
00007fda87180000       0       0       0 rw-s- zero (deleted)
00007fda87181000      12      12      12 rw-s- zero (deleted)
00007fda87181000       0       0       0 rw-s- zero (deleted)
00007fda87184000  262144   74452   74452 rw---   [ anon ]
00007fda87184000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bccb000     780     780     780 rw---   [ stack ]
00007ffc3bccb000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:28 asyncio: DEBUG Using selector: EpollSelector
09:51:28 commands: DEBUG 
[8438] Command:
pmap -xq 8386
[8438] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1216    1216 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000     540     480     480 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda86d6f000      16       0       0 rw---   [ anon ]
00007fda86d6f000       0       0       0 rw---   [ anon ]
00007fda86d73000       8       0       0 -----   [ anon ]
00007fda86d73000       0       0       0 -----   [ anon ]
00007fda86d75000    2052       8       8 rw---   [ anon ]
00007fda86d75000       0       0       0 rw---   [ anon ]
00007fda86f76000       8       0       0 -----   [ anon ]
00007fda86f76000       0       0       0 -----   [ anon ]
00007fda86f78000    2052       8       8 rw---   [ anon ]
00007fda86f78000       0       0       0 rw---   [ anon ]
00007fda87179000      12       4       4 rw-s-   [ anon ]
00007fda87179000       0       0       0 rw-s-   [ anon ]
00007fda8717c000      12       4       4 rw-s-   [ anon ]
00007fda8717c000       0       0       0 rw-s-   [ anon ]
00007fda8717f000       4       4       4 rw-s- zero (deleted)
00007fda8717f000       0       0       0 rw-s- zero (deleted)
00007fda87180000       4       4       4 rw-s- zero (deleted)
00007fda87180000       0       0       0 rw-s- zero (deleted)
00007fda87181000      12      12      12 rw-s- zero (deleted)
00007fda87181000       0       0       0 rw-s- zero (deleted)
00007fda87184000  262144   74464   74464 rw---   [ anon ]
00007fda87184000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bccb000     780     780     780 rw---   [ stack ]
00007ffc3bccb000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:29 asyncio: DEBUG Using selector: EpollSelector
09:51:29 commands: DEBUG 
[8440] Command:
pmap -xq 8386
[8440] stdout:
8386:   /firecracker --id 7f369f93-a01c-4183-b4ec-00dd48078101 --start-time-us 6947503201 --start-time-cpu-us 207 --log-path log_fifo --level Info
0000000000400000    1360    1216    1216 r-x-- firecracker
0000000000400000       0       0       0 r-x-- firecracker
0000000000753000      56      56      56 rw--- firecracker
0000000000753000       0       0       0 rw--- firecracker
0000000000761000       8       8       8 rw---   [ anon ]
0000000000761000       0       0       0 rw---   [ anon ]
000000000185d000     540     480     480 rw---   [ anon ]
000000000185d000       0       0       0 rw---   [ anon ]
00007fda86d6f000      16       0       0 rw---   [ anon ]
00007fda86d6f000       0       0       0 rw---   [ anon ]
00007fda86d73000       8       0       0 -----   [ anon ]
00007fda86d73000       0       0       0 -----   [ anon ]
00007fda86d75000    2052       8       8 rw---   [ anon ]
00007fda86d75000       0       0       0 rw---   [ anon ]
00007fda86f76000       8       0       0 -----   [ anon ]
00007fda86f76000       0       0       0 -----   [ anon ]
00007fda86f78000    2052       8       8 rw---   [ anon ]
00007fda86f78000       0       0       0 rw---   [ anon ]
00007fda87179000      12       4       4 rw-s-   [ anon ]
00007fda87179000       0       0       0 rw-s-   [ anon ]
00007fda8717c000      12       4       4 rw-s-   [ anon ]
00007fda8717c000       0       0       0 rw-s-   [ anon ]
00007fda8717f000       4       4       4 rw-s- zero (deleted)
00007fda8717f000       0       0       0 rw-s- zero (deleted)
00007fda87180000       4       4       4 rw-s- zero (deleted)
00007fda87180000       0       0       0 rw-s- zero (deleted)
00007fda87181000      12      12      12 rw-s- zero (deleted)
00007fda87181000       0       0       0 rw-s- zero (deleted)
00007fda87184000  262144   74464   74464 rw---   [ anon ]
00007fda87184000       0       0       0 rw---   [ anon ]
00007fda97184000       8       0       0 rw---   [ anon ]
00007fda97184000       0       0       0 rw---   [ anon ]
00007fda97186000       8       0       0 -----   [ anon ]
00007fda97186000       0       0       0 -----   [ anon ]
00007fda97188000    2064      12      12 rw---   [ anon ]
00007fda97188000       0       0       0 rw---   [ anon ]
00007ffc3bccb000     780     780     780 rw---   [ stack ]
00007ffc3bccb000       0       0       0 rw---   [ stack ]
00007ffc3bdb0000      12       0       0 r----   [ anon ]
00007ffc3bdb0000       0       0       0 r----   [ anon ]
00007ffc3bdb3000       8       4       0 r-x--   [ anon ]
00007ffc3bdb3000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]

09:51:29 commands: DEBUG 
[8434] Command:
ip netns exec 7f369f93-a01c-4183-b4ec-00dd48078101  iperf3 -c 192.168.0.26 -t3 -f KBytes
[8434] stdout:
Connecting to host 192.168.0.26, port 5201
[  4] local 192.168.0.25 port 54290 connected to 192.168.0.26 port 5201
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  76.3 MBytes  78088 KBytes/sec  101    182 KBytes       
[  4]   1.00-2.00   sec   103 MBytes  105437 KBytes/sec    2    954 KBytes       
[  4]   2.00-3.00   sec  92.5 MBytes  94750 KBytes/sec    2    954 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
[  4]   0.00-3.00   sec   272 MBytes  92758 KBytes/sec  105             sender
[  4]   0.00-3.00   sec   270 MBytes  91994 KBytes/sec                  receiver

iperf Done.
---------------------------- Captured log teardown -----------------------------
09:51:29 asyncio: DEBUG Using selector: EpollSelector
09:51:29 commands: DEBUG 
[8442] Command:
kill -9 8386
============= 1 failed, 71 passed, 1 skipped in 418.53s (0:06:58) ==============
@aghecenco aghecenco self-assigned this Apr 22, 2020
@aghecenco
Copy link
Contributor

This test seemingly started failing some time in late October to mid November (hard to tell without timestamped logs) but the error has been getting more frequent lately. Neither the test runner AMI nor the docker image, nor the guest images changed, and there haven't been any suspicious changes in the rate limiter code. Since the CI improvements went in, we have more verbose logs that show iperf output; the first 2 seconds of traffic sometimes have a larger number of TCP retransmissions, which impacts the bandwidth measurement. @raduiliescu suggested to omit the first second(s) of iperf traffic so as to get TCP over the slowstart (iperf -O). If that doesn't work out, we could also try tweaking the TCP congestion algorithm.

Detailed investigation 
# Get all the CI logs
docker run --rm -it             \
    -v $PWD/.aws:/root/.aws     \
    -v $PWD:/aws                \
    amazon/aws-cli              \
    s3 sync s3://firecracker-pr/pr-logs/x86_64/ logs/

# Find PRs that failed the test_rx_rate_limiting test
grep -nr "test_rx_rate_limiting" logs/  \
    | grep -v PASSED                    \
    | grep -v setup | grep -v teardown  \
    | grep -v call                      \
    | cut -d: -f1 | sort | uniq >failed_prs

# Isolate the log snippets with test_rx_rate_limiting
for pr in `cat failed_prs`; do
    cat $pr                                                         \
        | grep -q "__\ test_rx_rate_limiting\[ubuntu_with_ssh\]"    \
         && printf "\n$pr\n"                                        \
         >>rx_errors
    cat $pr                                                         \
        | grep -A 6 "__\ test_rx_rate_limiting\[ubuntu_with_ssh\]"  \
        >>rx_errors
done

# Manual inspection of rx_errors shows intensifying bandwidth issues...

# Find iperf retransmission logs
for pr in `grep logs rx_errors`; do
    cat $pr | grep -q "Retr " && printf "\n$pr\n"
    cat $pr | grep "Retr " -A 3
done
logs/01756/raduiliescu-firecracker-86c1bc2.log.html
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  3.24 GBytes  3397961 KBytes/sec    4    935 KBytes       
[  4]   1.00-2.00   sec  3.27 GBytes  3424657 KBytes/sec    0    935 KBytes       
[  4]   2.00-3.00   sec  3.30 GBytes  3462204 KBytes/sec    0    936 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  76.3 MBytes  78088 KBytes/sec  101    182 KBytes       
[  4]   1.00-2.00   sec   103 MBytes  105437 KBytes/sec    2    954 KBytes       
[  4]   2.00-3.00   sec  92.5 MBytes  94750 KBytes/sec    2    954 KBytes       

logs/01772/iulianbarbu-firecracker-d0610da.log.html
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  3.31 GBytes  3473313 KBytes/sec    0    954 KBytes       
[  4]   1.00-2.00   sec  3.42 GBytes  3583774 KBytes/sec    0    954 KBytes       
[  4]   2.00-3.00   sec  3.46 GBytes  3629465 KBytes/sec    0    954 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec   108 MBytes  110438 KBytes/sec   10    556 KBytes       
[  4]   1.00-2.00   sec  95.0 MBytes  97291 KBytes/sec    6    646 KBytes       
[  4]   2.00-3.00   sec   103 MBytes  105818 KBytes/sec    5    764 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.35   sec  1001 MBytes  2937718 KBytes/sec    0    694 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.95   sec   100 MBytes  108433 KBytes/sec    4    950 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  53.0 MBytes  54298 KBytes/sec    8    700 KBytes       
[  4]   1.00-2.00   sec  50.5 MBytes  51741 KBytes/sec  320    451 KBytes       
[  4]   2.00-3.00   sec  50.6 MBytes  51790 KBytes/sec  255    281 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  30.0 MBytes  30700 KBytes/sec  348    416 KBytes       
[  4]   1.00-2.00   sec  41.5 MBytes  42518 KBytes/sec  423    294 KBytes       
[  4]   2.00-3.00   sec  50.6 MBytes  51861 KBytes/sec    4    574 KBytes       

logs/01784/serban300-firecracker-e52c46c.log.html
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  3.42 GBytes  3588923 KBytes/sec    0    950 KBytes       
[  4]   1.00-2.00   sec  3.37 GBytes  3531073 KBytes/sec    0    950 KBytes       
[  4]   2.00-3.00   sec  2.69 GBytes  2822642 KBytes/sec    0    950 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec   108 MBytes  110315 KBytes/sec   32    714 KBytes       
[  4]   1.00-2.00   sec  94.6 MBytes  96857 KBytes/sec    7    788 KBytes       
[  4]   2.00-3.00   sec   105 MBytes  107169 KBytes/sec    0    854 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.29   sec  1001 MBytes  3497590 KBytes/sec    0    971 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.94   sec   100 MBytes  109730 KBytes/sec   18    865 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  52.8 MBytes  54061 KBytes/sec   11    546 KBytes       
[  4]   1.00-2.00   sec  51.2 MBytes  52429 KBytes/sec    4    590 KBytes       
[  4]   2.00-3.00   sec  51.1 MBytes  52375 KBytes/sec    7    629 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  46.7 MBytes  47854 KBytes/sec    9    913 KBytes       
[  4]   1.00-2.00   sec  50.5 MBytes  51737 KBytes/sec    5    919 KBytes       
[  4]   2.00-3.00   sec  35.9 MBytes  36779 KBytes/sec   73    505 KBytes       

logs/01790/iulianbarbu-firecracker-6c00e6a.log.html
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  3.33 GBytes  3488284 KBytes/sec    2   1008 KBytes       
[  4]   1.00-2.00   sec  3.53 GBytes  3703655 KBytes/sec    1   1008 KBytes       
[  4]   2.00-3.00   sec  3.57 GBytes  3739831 KBytes/sec    0   1008 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  88.4 MBytes  90467 KBytes/sec   18    447 KBytes       
[  4]   1.00-2.00   sec   104 MBytes  106908 KBytes/sec   47    676 KBytes       
[  4]   2.00-3.00   sec   103 MBytes  105893 KBytes/sec    3    788 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.36   sec  1001 MBytes  2844073 KBytes/sec    3    693 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.94   sec   100 MBytes  109205 KBytes/sec   58    682 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  29.5 MBytes  30184 KBytes/sec   30    284 KBytes       
[  4]   1.00-2.00   sec  51.1 MBytes  52333 KBytes/sec  185    392 KBytes       
[  4]   2.00-3.00   sec  46.7 MBytes  47787 KBytes/sec    4    595 KBytes       

logs/01790/iulianbarbu-firecracker-8c80094.log.html
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  3.61 GBytes  3787847 KBytes/sec    1    950 KBytes       
[  4]   1.00-2.00   sec  3.65 GBytes  3821898 KBytes/sec    0    950 KBytes       
[  4]   2.00-3.00   sec  3.54 GBytes  3710287 KBytes/sec    0    950 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec   107 MBytes  109795 KBytes/sec   10    527 KBytes       
[  4]   1.00-2.00   sec  96.3 MBytes  98627 KBytes/sec    1    634 KBytes       
[  4]   2.00-3.00   sec   106 MBytes  108300 KBytes/sec    5    690 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.29   sec  1001 MBytes  3481979 KBytes/sec    0    967 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  62.8 MBytes  64254 KBytes/sec   11    939 KBytes       
[  4]   1.00-1.36   sec  37.4 MBytes  105836 KBytes/sec    8    946 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -

logs/01800/iulianbarbu-firecracker-41bb0a5.log.html
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  3.40 GBytes  3561895 KBytes/sec    1   1.04 MBytes       
[  4]   1.00-2.00   sec  3.43 GBytes  3600858 KBytes/sec    0   1.04 MBytes       
[  4]   2.00-3.00   sec  3.43 GBytes  3600682 KBytes/sec    0   1.04 MBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec   107 MBytes  109860 KBytes/sec    8    677 KBytes       
[  4]   1.00-2.00   sec  87.4 MBytes  89467 KBytes/sec    8    969 KBytes       
[  4]   2.00-3.00   sec  92.6 MBytes  94810 KBytes/sec    4    969 KBytes       
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.31   sec  1000 MBytes  3285652 KBytes/sec    4    969 KBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-0.93   sec   100 MBytes  110349 KBytes/sec    4   2.06 MBytes       
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
--
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  43.3 MBytes  44355 KBytes/sec  168    440 KBytes       
[  4]   1.00-2.00   sec  45.8 MBytes  46894 KBytes/sec    9    495 KBytes       
[  4]   2.00-3.00   sec  45.4 MBytes  46518 KBytes/sec    6    831 KBytes

aghecenco added a commit to aghecenco/firecracker that referenced this issue Apr 23, 2020
@aghecenco
tests: rate limiting: omit first 2s of traffic
18b7014 
TCP slow start might cause the initial bandwidth measurements
from the rate limiter integ tests to be false, skewing the
comparison between non-rate-limited traffic (slowed by the
TCP congestion algo) and the rate-limited one (slowed by
Firecracker). Letting traffic flow for 2 extra seconds to skip
over TCP slow start.

Fixes firecracker-microvm#1809

Signed-off-by: Alexandra Iordache <aghecen@amazon.com>
@aghecenco aghecenco mentioned this issue Apr 23, 2020
Merged
8 tasks
@aghecenco
Copy link
Contributor

Looks like the test is still failing sometimes even with #1815 😞

@aghecenco aghecenco reopened this Apr 29, 2020
@aghecenco aghecenco removed their assignment Apr 29, 2020
@lauralt lauralt mentioned this issue Apr 29, 2020
Merged
8 tasks
@lauralt lauralt mentioned this issue May 8, 2020
Merged
8 tasks
bbros-dev pushed a commit to BegleyBrothers/firecracker that referenced this issue May 10, 2020
@aghecenco @bbros-dev
tests: rate limiting: omit first 2s of traffic
4c0dab5 
TCP slow start might cause the initial bandwidth measurements
from the rate limiter integ tests to be false, skewing the
comparison between non-rate-limited traffic (slowed by the
TCP congestion algo) and the rate-limited one (slowed by
Firecracker). Letting traffic flow for 2 extra seconds to skip
over TCP slow start.

Fixes firecracker-microvm#1809

Signed-off-by: Alexandra Iordache <aghecen@amazon.com>
bbros-dev pushed a commit to bbros-dev/firecracker that referenced this issue May 10, 2020
@aghecenco @bbros-dev
tests: rate limiting: omit first 2s of traffic
0caa767 
TCP slow start might cause the initial bandwidth measurements
from the rate limiter integ tests to be false, skewing the
comparison between non-rate-limited traffic (slowed by the
TCP congestion algo) and the rate-limited one (slowed by
Firecracker). Letting traffic flow for 2 extra seconds to skip
over TCP slow start.

Fixes firecracker-microvm#1809

Signed-off-by: Alexandra Iordache <aghecen@amazon.com>
@andreeaflorescu andreeaflorescu mentioned this issue May 13, 2020
Merged
8 tasks
@raduiliescu raduiliescu added the Priority: High Indicates than an issue or pull request should be resolved ahead of issues or pull requests labelled label May 13, 2020
@acatangiu acatangiu self-assigned this May 13, 2020
@tnotw
Copy link
Contributor

tnotw commented May 13, 2020

Is this issue possibly kernel based? I think I got rid of it locally by building the latest linux kernel.... regressing to 4.14 also seemed to work better for me.

@acatangiu
Copy link
Contributor

It only occurs intermittently, are you confident that building another kernel alleviates the issue?

@tnotw
Copy link
Contributor

tnotw commented May 14, 2020

I could reproduce it pretty consistently on my old, slow, non-supported (from a firecracker perspective) kit. Perhaps my kit is so old that this test would always have failed, or it was something else that was wrong in my environment that was resolved by switching kernel versions. So on reflection, maybe it fixed a problem, but maybe not this problem.

@tnotw
Copy link
Contributor

tnotw commented May 14, 2020 •
edited
Loading

But, if it helps at all, failure rates for me are:

4.9 - 60%
5.7 - 10%
4.14 - 10%

So maybe it's fairer to say that 4.9 seems particularly bad, for me at least, rather than 5.7 fixes it.....

strings vmlinux.bin | grep '^Linux version'
Linux version 4.9.0+ (seriorga@u636c053592cf59.ant.amazon.com) (gcc version 7.4.0 (Ubuntu 7.4.0-1ubuntu1~18.04.1) ) #96 SMP Tue Mar 3 08:56:10 EET 2020


for x in {1..10}; do ./tools/devtool test -- integration_tests/functional/test_rate_limiter.py::test_rx_rate_limiting |grep ===; done
============================= test session starts ==============================
============================== 1 passed in 31.70s ==============================
============================= test session starts ==============================
=================================== FAILURES ===================================
============================== 1 failed in 16.47s ==============================
============================= test session starts ==============================
=================================== FAILURES ===================================
============================== 1 failed in 16.21s ==============================
============================= test session starts ==============================
============================== 1 passed in 31.71s ==============================
============================= test session starts ==============================
=================================== FAILURES ===================================
============================== 1 failed in 22.00s ==============================
============================= test session starts ==============================
=================================== FAILURES ===================================
============================== 1 failed in 16.25s ==============================
============================= test session starts ==============================
=================================== FAILURES ===================================
============================== 1 failed in 16.31s ==============================
============================= test session starts ==============================
============================== 1 passed in 32.39s ==============================
============================= test session starts ==============================
============================== 1 passed in 33.42s ==============================
============================= test session starts ==============================
=================================== FAILURES ===================================
============================== 1 failed in 16.69s ==============================

strings vmlinux.bin | grep '^Linux version'
Linux version 5.7.0-rc4 (xxxx@xxxxxx) (gcc version 9.3.1 20200408 (Red Hat 9.3.1-2) (GCC), GNU ld version 2.32-31.fc31) #2 SMP Fri May 8 14:49:02 BST 2020

for x in {1..10}; do ./tools/devtool test -- integration_tests/functional/test_rate_limiter.py::test_rx_rate_limiting |grep ===; done
============================= test session starts ==============================
============================== 1 passed in 30.23s ==============================
============================= test session starts ==============================
============================== 1 passed in 30.00s ==============================
============================= test session starts ==============================
============================== 1 passed in 29.92s ==============================
============================= test session starts ==============================
============================== 1 passed in 30.14s ==============================
============================= test session starts ==============================
============================== 1 passed in 31.22s ==============================
============================= test session starts ==============================
============================== 1 passed in 31.39s ==============================
============================= test session starts ==============================
============================== 1 passed in 32.58s ==============================
============================= test session starts ==============================
============================== 1 passed in 33.53s ==============================
============================= test session starts ==============================
=================================== FAILURES ===================================
============================== 1 failed in 15.90s ==============================
============================= test session starts ==============================
============================== 1 passed in 29.90s ==============================

strings vmlinux.bin | grep '^Linux version'
Linux version 4.14.55-84.37.amzn2.x86_64 (mockbuild@ip-10-0-1-79) (gcc version 7.3.1 20180303 (Red Hat 7.3.1-5) (GCC)) #1 SMP Wed Jul 25 18:47:15 UTC 2018

for x in {1..10}; do ./tools/devtool test -- integration_tests/functional/test_rate_limiter.py::test_rx_rate_limiting |grep ===; done
============================= test session starts ==============================
============================== 1 passed in 29.99s ==============================
============================= test session starts ==============================
============================== 1 passed in 31.55s ==============================
============================= test session starts ==============================
============================== 1 passed in 30.43s ==============================
============================= test session starts ==============================
============================== 1 passed in 30.85s ==============================
============================= test session starts ==============================
=================================== FAILURES ===================================
============================== 1 failed in 15.03s ==============================
============================= test session starts ==============================
============================== 1 passed in 30.67s ==============================
============================= test session starts ==============================
============================== 1 passed in 30.47s ==============================
============================= test session starts ==============================
============================== 1 passed in 31.70s ==============================
============================= test session starts ==============================
============================== 1 passed in 31.84s ==============================
============================= test session starts ==============================
============================== 1 passed in 29.98s ==============================

@acatangiu acatangiu mentioned this issue May 14, 2020
Merged
7 tasks
@lauralt lauralt mentioned this issue May 15, 2020
Merged
8 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@acatangiu acatangiu

Labels
Priority: High Indicates than an issue or pull request should be resolved ahead of issues or pull requests labelled
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

tests: fix net rate limiters test acatangiu/firecracker
4 participants
@aghecenco @tnotw @raduiliescu @acatangiu