search

tohojo / flent

The FLExible Network Tester.
https://flent.org
Other
431 stars 77 forks source link

Getting Traceback while issuing a command with "-v" option #251

Closed kanrenibm closed 2 years ago

kanrenibm commented 2 years ago

Was trying to execute tcp_bidirectional test, initially without -v option went well, but with "-v"was getting an error message as below(just a snipper, attaching full logs in a file).

command: flent tcp_bidirectional -l 10 -H 10.51.24.147 --send-size 64 -v

-- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/__init__.py", line 996, in emit
    stream.write(msg)
ValueError: I/O operation on closed file.
Call stack:
  File "/usr/lib/python3.6/threading.py", line 884, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.6/dist-packages/flent/runners.py", line 219, in run
    self._run()
  File "/usr/local/lib/python3.6/dist-packages/flent/runners.py", line 334, in _run
    self.name, extra={'runner': self})
Message: '%s %s: timer expired'

log file:

issue_tracebackerror_with_v_option.log

tohojo commented 2 years ago

Hmm, I think there's a race where the watchdog timer threads can exit after the main thread. The errors are harmless, but obviously annoying. Could you please test the pull request I just opened with what should hopefully be a fix for this?

kanrenibm commented 2 years ago

Hmm, I think there's a race where the watchdog timer threads can exit after the main thread. The errors are harmless, but obviously annoying. Could you please test the pull request I just opened with what should hopefully be a fix for this?

Thanks for the quick update, I shall test and update you asap. Thanks !

kanrenibm commented 2 years ago

Hi Apologize for my delay, I have verified from the master branch, looks good. Thanks

root@kantest-worker:~/flent/git_flent/flent# flent tcp_bidirectional -l 1000 -H 10.51.24.147 --send-size 64 -v
Starting Flent 2.0.1-git using Python 3.6.9.
Executing test environment file /usr/local/lib/python3.6/dist-packages/flent/tests/tcp_bidirectional.conf
Looking up hostname '10.51.24.147'.
Executing test environment file /usr/local/lib/python3.6/dist-packages/flent/tests/tcp_bidirectional.conf
Gathering local metadata
Executing 'uname -s' on localhost
Executing 'uname -r' on localhost
Executing 'find /sys/module -name .note.gnu.build-id' on localhost
Executing 'sysctl -e net.core.rmem_max net.core.wmem_max net.ipv4.tcp_autocorking net.ipv4.tcp_early_retrans net.ipv4.tcp_ecn net.ipv4.tcp_pacing_ca_ratio net.ipv4.tcp_pacing_ss_ratio net.ipv4.tcp_dsack net.ipv4.tcp_fack net.ipv4.tcp_sack net.ipv4.tcp_fastopen net.ipv4.tcp_syncookies net.ipv4.tcp_window_scaling net.ipv4.tcp_notsent_lowat net.ipv4.tcp_limit_output_bytes net.ipv4.tcp_timestamps net.ipv4.tcp_congestion_control net.ipv4.tcp_allowed_congestion_control net.ipv4.tcp_available_congestion_control net.ipv4.tcp_mem net.ipv4.tcp_rmem net.ipv4.tcp_wmem net.ipv4.tcp_moderate_rcvbuf net.ipv4.tcp_no_metrics_save' on localhost
Looking up hostname '10.51.24.147'.
Executing 'ip route get 10.51.24.147' on localhost
Executing 'tc qdisc show dev eth0' on localhost
Executing 'tc -s qdisc show dev eth0' on localhost
Executing 'tc class show dev eth0' on localhost
Executing 'ethtool -k eth0' on localhost
Executing 'for i in /sys/class/net/eth0/queues/tx-*; do [ -d $i/byte_queue_limits ] && echo -n "$(basename $i) " && cat $i/byte_queue_limits/limit_max; done' on localhost
Executing 'basename $(readlink /sys/class/net/eth0/device/driver)' on localhost
Executing 'ip link show dev eth0' on localhost
Executing 'ethtool eth0' on localhost
Starting tcp_bidirectional test. Expected run time: 1010 seconds.
which: /usr/local/sbin/netperf is not an executable file
which: Found netperf executable at /usr/local/bin/netperf
which: /usr/local/sbin/netperf is not an executable file
which: Found netperf executable at /usr/local/bin/netperf
which: /usr/local/sbin/fping is not an executable file
which: /usr/local/bin/fping is not an executable file
which: /usr/sbin/fping is not an executable file
which: /usr/bin/fping is not an executable file
which: /sbin/fping is not an executable file
which: /bin/fping is not an executable file
which: /usr/games/fping is not an executable file
which: /usr/local/games/fping is not an executable file
which: /snap/bin/fping is not an executable file
which: /root/.local/bin/fping is not an executable file
which: /root/.local/bin/fping is not an executable file
which: /usr/local/sbin/fping is not an executable file
which: /usr/local/bin/fping is not an executable file
which: /usr/sbin/fping is not an executable file
which: /usr/bin/fping is not an executable file
which: /sbin/fping is not an executable file
which: /bin/fping is not an executable file
which: /usr/games/fping is not an executable file
which: /usr/local/games/fping is not an executable file
which: /snap/bin/fping is not an executable file
which: /root/.local/bin/fping is not an executable file
which: /root/.local/bin/fping is not an executable file
which: /usr/local/sbin/ping is not an executable file
which: /usr/local/bin/ping is not an executable file
which: /usr/sbin/ping is not an executable file
which: /usr/bin/ping is not an executable file
which: /sbin/ping is not an executable file
which: Found ping executable at /bin/ping
Forking to run command /usr/local/bin/netperf -P 0 -v 0 -D -0.20 -4  -H 10.51.24.147 -p 12865 -t TCP_MAERTS -l 1000 -F /dev/urandom -f m   --  -m 64 -M 64  -H 10.51.24.147 -k THROUGHPUT,LOCAL_CONG_CONTROL,REMOTE_CONG_CONTROL,TRANSPORT_MSS,LOCAL_TRANSPORT_RETRANS,REMOTE_TRANSPORT_RETRANS,LOCAL_SOCKET_TOS,REMOTE_SOCKET_TOS,DIRECTION,ELAPSED_TIME,PROTOCOL,LOCAL_SEND_SIZE,LOCAL_RECV_SIZE,REMOTE_SEND_SIZE,REMOTE_RECV_SIZE,LOCAL_BYTES_SENT,LOCAL_BYTES_RECVD,REMOTE_BYTES_SENT,REMOTE_BYTES_RECVD
Forked /usr/local/bin/netperf as pid 3896
TCP download: Starting watchdog with timeout 1015
Started TimerRunner idx 0 ('Watchdog [TCP download]')
Started NetperfDemoRunner idx 0 ('TCP download')
Forking to run command /usr/local/bin/netperf -P 0 -v 0 -D -0.20 -4  -H 10.51.24.147 -p 12865 -t TCP_STREAM -l 1000 -F /dev/urandom -f m   --  -m 64 -M 64  -H 10.51.24.147 -k THROUGHPUT,LOCAL_CONG_CONTROL,REMOTE_CONG_CONTROL,TRANSPORT_MSS,LOCAL_TRANSPORT_RETRANS,REMOTE_TRANSPORT_RETRANS,LOCAL_SOCKET_TOS,REMOTE_SOCKET_TOS,DIRECTION,ELAPSED_TIME,PROTOCOL,LOCAL_SEND_SIZE,LOCAL_RECV_SIZE,REMOTE_SEND_SIZE,REMOTE_RECV_SIZE,LOCAL_BYTES_SENT,LOCAL_BYTES_RECVD,REMOTE_BYTES_SENT,REMOTE_BYTES_RECVD
Forked /usr/local/bin/netperf as pid 3899
TCP upload: Starting watchdog with timeout 1015
Started TimerRunner idx 1 ('Watchdog [TCP upload]')
Started NetperfDemoRunner idx 1 ('TCP upload')
Forking to run command /bin/ping -n -D -i 0.20 -w 1010    10.51.24.147
Forked /bin/ping as pid 3902
Started PingRunner idx 2 ('Ping (ms) ICMP')
^CReceived SIGINT
NetperfDemoRunner TCP download killed by kill event
Sending SIGINT to pid 3896
Sending signal 15 to pid 3896.
NetperfDemoRunner TCP upload killed by kill event
Sending SIGINT to pid 3899
Sending signal 15 to pid 3899.
PingRunner Ping (ms) ICMP killed by kill event
Sending SIGINT to pid 3902
Sending signal 15 to pid 3902.
Killing child processes
Sending signal 15 to pid 3896.
Sending signal 15 to pid 3899.
Sending signal 15 to pid 3902.

root@kantest-worker:~/flent/git_flent/flent# flent tcp_bidirectional -l 100 -H 10.51.24.147 --send-size 64 -v
Starting Flent 2.0.1-git using Python 3.6.9.
Executing test environment file /usr/local/lib/python3.6/dist-packages/flent/tests/tcp_bidirectional.conf
Looking up hostname '10.51.24.147'.
Executing test environment file /usr/local/lib/python3.6/dist-packages/flent/tests/tcp_bidirectional.conf
Gathering local metadata
Executing 'uname -s' on localhost
Executing 'uname -r' on localhost
Executing 'find /sys/module -name .note.gnu.build-id' on localhost
Executing 'sysctl -e net.core.rmem_max net.core.wmem_max net.ipv4.tcp_autocorking net.ipv4.tcp_early_retrans net.ipv4.tcp_ecn net.ipv4.tcp_pacing_ca_ratio net.ipv4.tcp_pacing_ss_ratio net.ipv4.tcp_dsack net.ipv4.tcp_fack net.ipv4.tcp_sack net.ipv4.tcp_fastopen net.ipv4.tcp_syncookies net.ipv4.tcp_window_scaling net.ipv4.tcp_notsent_lowat net.ipv4.tcp_limit_output_bytes net.ipv4.tcp_timestamps net.ipv4.tcp_congestion_control net.ipv4.tcp_allowed_congestion_control net.ipv4.tcp_available_congestion_control net.ipv4.tcp_mem net.ipv4.tcp_rmem net.ipv4.tcp_wmem net.ipv4.tcp_moderate_rcvbuf net.ipv4.tcp_no_metrics_save' on localhost
Looking up hostname '10.51.24.147'.
Executing 'ip route get 10.51.24.147' on localhost
Executing 'tc qdisc show dev eth0' on localhost
Executing 'tc -s qdisc show dev eth0' on localhost
Executing 'tc class show dev eth0' on localhost
Executing 'ethtool -k eth0' on localhost
Executing 'for i in /sys/class/net/eth0/queues/tx-*; do [ -d $i/byte_queue_limits ] && echo -n "$(basename $i) " && cat $i/byte_queue_limits/limit_max; done' on localhost
Executing 'basename $(readlink /sys/class/net/eth0/device/driver)' on localhost
Executing 'ip link show dev eth0' on localhost
Executing 'ethtool eth0' on localhost
Starting tcp_bidirectional test. Expected run time: 110 seconds.
which: /usr/local/sbin/netperf is not an executable file
which: Found netperf executable at /usr/local/bin/netperf
which: /usr/local/sbin/netperf is not an executable file
which: Found netperf executable at /usr/local/bin/netperf
which: /usr/local/sbin/fping is not an executable file
which: /usr/local/bin/fping is not an executable file
which: /usr/sbin/fping is not an executable file
which: /usr/bin/fping is not an executable file
which: /sbin/fping is not an executable file
which: /bin/fping is not an executable file
which: /usr/games/fping is not an executable file
which: /usr/local/games/fping is not an executable file
which: /snap/bin/fping is not an executable file
which: /root/.local/bin/fping is not an executable file
which: /root/.local/bin/fping is not an executable file
which: /usr/local/sbin/fping is not an executable file
which: /usr/local/bin/fping is not an executable file
which: /usr/sbin/fping is not an executable file
which: /usr/bin/fping is not an executable file
which: /sbin/fping is not an executable file
which: /bin/fping is not an executable file
which: /usr/games/fping is not an executable file
which: /usr/local/games/fping is not an executable file
which: /snap/bin/fping is not an executable file
which: /root/.local/bin/fping is not an executable file
which: /root/.local/bin/fping is not an executable file
which: /usr/local/sbin/ping is not an executable file
which: /usr/local/bin/ping is not an executable file
which: /usr/sbin/ping is not an executable file
which: /usr/bin/ping is not an executable file
which: /sbin/ping is not an executable file
which: Found ping executable at /bin/ping
Forking to run command /usr/local/bin/netperf -P 0 -v 0 -D -0.20 -4  -H 10.51.24.147 -p 12865 -t TCP_MAERTS -l 100 -F /dev/urandom -f m   --  -m 64 -M 64  -H 10.51.24.147 -k THROUGHPUT,LOCAL_CONG_CONTROL,REMOTE_CONG_CONTROL,TRANSPORT_MSS,LOCAL_TRANSPORT_RETRANS,REMOTE_TRANSPORT_RETRANS,LOCAL_SOCKET_TOS,REMOTE_SOCKET_TOS,DIRECTION,ELAPSED_TIME,PROTOCOL,LOCAL_SEND_SIZE,LOCAL_RECV_SIZE,REMOTE_SEND_SIZE,REMOTE_RECV_SIZE,LOCAL_BYTES_SENT,LOCAL_BYTES_RECVD,REMOTE_BYTES_SENT,REMOTE_BYTES_RECVD
Forked /usr/local/bin/netperf as pid 3946
TCP download: Starting watchdog with timeout 115
Started TimerRunner idx 0 ('Watchdog [TCP download]')
Started NetperfDemoRunner idx 0 ('TCP download')
Forking to run command /usr/local/bin/netperf -P 0 -v 0 -D -0.20 -4  -H 10.51.24.147 -p 12865 -t TCP_STREAM -l 100 -F /dev/urandom -f m   --  -m 64 -M 64  -H 10.51.24.147 -k THROUGHPUT,LOCAL_CONG_CONTROL,REMOTE_CONG_CONTROL,TRANSPORT_MSS,LOCAL_TRANSPORT_RETRANS,REMOTE_TRANSPORT_RETRANS,LOCAL_SOCKET_TOS,REMOTE_SOCKET_TOS,DIRECTION,ELAPSED_TIME,PROTOCOL,LOCAL_SEND_SIZE,LOCAL_RECV_SIZE,REMOTE_SEND_SIZE,REMOTE_RECV_SIZE,LOCAL_BYTES_SENT,LOCAL_BYTES_RECVD,REMOTE_BYTES_SENT,REMOTE_BYTES_RECVD
Forked /usr/local/bin/netperf as pid 3949
TCP upload: Starting watchdog with timeout 115
Started TimerRunner idx 1 ('Watchdog [TCP upload]')
Started NetperfDemoRunner idx 1 ('TCP upload')
Forking to run command /bin/ping -n -D -i 0.20 -w 110    10.51.24.147
Forked /bin/ping as pid 3952
Started PingRunner idx 2 ('Ping (ms) ICMP')
TimerRunner Watchdog [TCP download] finished
NetperfDemoRunner TCP download finished
TimerRunner Watchdog [TCP upload] finished
NetperfDemoRunner TCP upload finished
PingRunner Ping (ms) ICMP finished
Runner aggregation finished
Postprocessing data using 0 postprocessors
Recording postrun metadata
Executing 'tc -s qdisc show dev eth0' on localhost
Writing data file to './tcp_bidirectional-2022-01-26T010401.452006.flent.gz'
Data file written to ./tcp_bidirectional-2022-01-26T010401.452006.flent.gz
Creating new DefaultFormatter

Summary of tcp_bidirectional test run from 2022-01-26 09:04:01.452006

                           avg       median       99th %          # data pts
 Ping (ms) ICMP :         2.82         2.78         4.95 ms              550
 TCP download   :      5449.31      5414.11      6720.29 Mbits/s         550
 TCP upload     :       488.21       489.45       589.09 Mbits/s         550
tohojo commented 2 years ago

Awesome! Thanks for testing! :)