search

tohojo / flent

The FLExible Network Tester.
https://flent.org
Other
428 stars 79 forks source link

Problem with current flent on macosc monterey #268

Closed moeller0 closed 2 years ago

moeller0 commented 2 years ago

Macos monterey, Python 3.9.13:

bash-3.2$ ./run-flent --version
Starting Flent 2.0.1-git-7b14d50 using Python 3.9.13.
Flent v2.0.1-git-7b14d50.
Running on Python 3.9.13 (main, May 24 2022, 21:28:44)  [Clang 13.0.0 (clang-1300.0.29.30)].
Using matplotlib version 3.4.2 on numpy 1.20.3.
Using Qt: pyqt5 v5.15.5.
bash-3.2$ date ; ping -c 10 singapore.starlink.taht.net ; ./run-flent --ipv4 -l 60 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Sat Jul  2 11:27:32 CEST 2022
PING singapore.starlink.taht.net (172.105.113.30): 56 data bytes
64 bytes from 172.105.113.30: icmp_seq=0 ttl=46 time=292.928 ms
64 bytes from 172.105.113.30: icmp_seq=1 ttl=46 time=284.487 ms
64 bytes from 172.105.113.30: icmp_seq=2 ttl=46 time=284.738 ms
64 bytes from 172.105.113.30: icmp_seq=3 ttl=46 time=284.281 ms
64 bytes from 172.105.113.30: icmp_seq=4 ttl=46 time=291.311 ms
64 bytes from 172.105.113.30: icmp_seq=5 ttl=46 time=283.758 ms
64 bytes from 172.105.113.30: icmp_seq=6 ttl=46 time=284.761 ms
64 bytes from 172.105.113.30: icmp_seq=7 ttl=46 time=284.233 ms
64 bytes from 172.105.113.30: icmp_seq=8 ttl=46 time=284.337 ms
64 bytes from 172.105.113.30: icmp_seq=9 ttl=46 time=284.429 ms

--- singapore.starlink.taht.net ping statistics ---
10 packets transmitted, 10 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 283.758/285.926/292.928/3.129 ms
Starting Flent 2.0.1-git-7b14d50 using Python 3.9.13.
Starting rrul_var test. Expected run time: 70 seconds.
Exception ignored in: <function RunnerBase.__del__ at 0x108639790>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 205, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 282, in close
    if self.stdout is not None:
AttributeError: 'IrttRunner' object has no attribute 'stdout'
Exception ignored in: <function RunnerBase.__del__ at 0x10a35d790>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 205, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 282, in close
    if self.stdout is not None:
AttributeError: 'NetperfDemoRunner' object has no attribute 'stdout'
Exception ignored in: <function RunnerBase.__del__ at 0x10882b790>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 205, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 282, in close
    if self.stdout is not None:
AttributeError: 'NetperfDemoRunner' object has no attribute 'stdout'
Exception ignored in: <function RunnerBase.__del__ at 0x111581790>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 205, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 282, in close
    if self.stdout is not None:
AttributeError: 'NetperfDemoRunner' object has no attribute 'stdout'
^CProcess SpawnPoolWorker-10:

/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/resource_tracker.py:216: UserWarning: resource_tracker: There appear to be 6 leaked semaphore objects to clean up at shutdown
  warnings.warn('resource_tracker: There appear to be %d '

Output from Ubuntu 22LTS, Python 3.10.4

user@ubuntu:~/CODE/flent$ ./run-flent --version
Starting Flent 2.0.1-git-7b14d50 using Python 3.10.4.
Flent v2.0.1-git-7b14d50.
Running on Python 3.10.4 (main, Apr  2 2022, 09:04:19) [GCC 11.2.0].
Using matplotlib version 3.5.1 on numpy 1.21.5.
Using Qt: pyqt5 v5.15.3.
user@ubuntu:~/CODE/flent$ date ; ping4 -c 10 singapore.starlink.taht.net ; ./run-flent --ipv4 -l 60 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Sa 2. Jul 11:42:13 CEST 2022
PING  (172.105.113.30) 56(84) bytes of data.
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=1 ttl=46 time=284 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=2 ttl=46 time=284 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=3 ttl=46 time=284 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=4 ttl=46 time=284 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=5 ttl=46 time=286 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=6 ttl=46 time=284 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=7 ttl=46 time=290 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=8 ttl=46 time=284 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=9 ttl=46 time=292 ms
64 bytes from li2006-30.members.linode.com (172.105.113.30): icmp_seq=10 ttl=46 time=285 ms

---  ping statistics ---
10 packets transmitted, 10 received, 0% packet loss, time 9001ms
rtt min/avg/max/mdev = 283.667/285.541/291.908/2.743 ms
Starting Flent 2.0.1-git-7b14d50 using Python 3.10.4.
Starting rrul_var test. Expected run time: 70 seconds.
Data file written to ./rrul_var-2022-07-02T114223.563655.IPv4_work_mbpro_thunderbolt_ethernet_2_singapore_starlink_taht_net.flent.gz

Summary of rrul_var test run from 2022-07-02 09:42:23.563655
  Title: 'IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net'

                                           avg       median       99th %          # data pts
 Ping (ms) ICMP 1.1.1.1 (extra) :        14.40        12.40        35.50 ms             1398
 Ping (ms) avg                  :       207.47          N/A          N/A ms             1407
 Ping (ms)::ICMP                :       179.25       177.00       198.03 ms             1398
 Ping (ms)::UDP 0 (0)           :       210.90       209.60       232.56 ms             1407
 Ping (ms)::UDP 1 (0)           :       202.74       200.91       224.70 ms             1407
 Ping (ms)::UDP 2 (0)           :       210.36       209.01       231.98 ms             1407
 Ping (ms)::UDP 3 (0)           :       208.52       207.01       229.46 ms             1407
 Ping (ms)::UDP 4 (0)           :       204.10       202.48       225.52 ms             1407
 Ping (ms)::UDP 5 (0)           :       211.02       209.59       232.30 ms             1407
 Ping (ms)::UDP 6 (0)           :       209.79       208.45       229.83 ms             1407
 Ping (ms)::UDP 7 (0)           :       202.33       200.63       224.05 ms             1407
 TCP download avg               :         9.76          N/A          N/A Mbits/s        1407
 TCP download sum               :        78.06          N/A          N/A Mbits/s        1407
 TCP download::0 (0)            :        18.82        18.80        45.80 Mbits/s        1407
 TCP download::1 (0)            :        13.35        14.63        41.05 Mbits/s        1407
 TCP download::2 (0)            :         4.99         2.47        39.28 Mbits/s        1407
 TCP download::3 (0)            :        11.67        12.95        29.73 Mbits/s        1407
 TCP download::4 (0)            :        17.34        17.52        39.90 Mbits/s        1407
 TCP download::5 (0)            :         4.26         2.06        29.45 Mbits/s        1407
 TCP download::6 (0)            :         2.61         1.74        12.98 Mbits/s        1407
 TCP download::7 (0)            :         5.02         2.75        25.88 Mbits/s        1407
 TCP totals                     :       105.54          N/A          N/A Mbits/s        1407
 TCP upload avg                 :         3.44          N/A          N/A Mbits/s        1407
 TCP upload sum                 :        27.48          N/A          N/A Mbits/s        1407
 TCP upload::0 (0)              :         3.31         3.70        24.10 Mbits/s        1407
 TCP upload::1 (0)              :         3.46         3.51        19.43 Mbits/s        1407
 TCP upload::2 (0)              :         3.53         3.74        26.43 Mbits/s        1407
 TCP upload::3 (0)              :         3.51         3.65        27.98 Mbits/s        1407
 TCP upload::4 (0)              :         3.12         3.49         8.38 Mbits/s        1407
 TCP upload::5 (0)              :         3.51         3.64         8.69 Mbits/s        1407
 TCP upload::6 (0)              :         3.54         3.76        23.90 Mbits/s        1407
 TCP upload::7 (0)              :         3.50         3.58        16.36 Mbits/s        1407

Under ubuntu I get the expected data and log files, under macos I only get the attached log but no data file... rrul_var-2022-07-02T112742.819661.IPv4_work_mbpro_thunderbolt_ethernet_2_singapore_starlink_taht_net.log

tohojo commented 2 years ago

269 should at least fix the crash you're seeing. Not sure if it'll restore full functionality, could you please test?

moeller0 commented 2 years ago 
bash-3.2$ git pull
remote: Enumerating objects: 4, done.
remote: Counting objects: 100% (4/4), done.
remote: Total 4 (delta 3), reused 4 (delta 3), pack-reused 0
Unpacking objects: 100% (4/4), 975 bytes | 108.00 KiB/s, done.
From https://github.com/tohojo/flent
 * [new branch]      pickle-fix -> origin/pickle-fix
Already up to date.
Press any key to continue...

bash-3.2$ git switch pickle-fix
branch 'pickle-fix' set up to track 'origin/pickle-fix'.
Switched to a new branch 'pickle-fix'

bash-3.2$ date ; ping -c 10 singapore.starlink.taht.net ; ./run-flent --ipv4 -l 60 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Sun Jul  3 14:11:45 CEST 2022
PING singapore.starlink.taht.net (172.105.113.30): 56 data bytes
64 bytes from 172.105.113.30: icmp_seq=0 ttl=46 time=289.610 ms
64 bytes from 172.105.113.30: icmp_seq=1 ttl=46 time=293.091 ms
64 bytes from 172.105.113.30: icmp_seq=2 ttl=46 time=289.509 ms
64 bytes from 172.105.113.30: icmp_seq=3 ttl=46 time=291.866 ms
64 bytes from 172.105.113.30: icmp_seq=4 ttl=46 time=294.221 ms
64 bytes from 172.105.113.30: icmp_seq=5 ttl=46 time=288.983 ms
64 bytes from 172.105.113.30: icmp_seq=6 ttl=46 time=289.526 ms
64 bytes from 172.105.113.30: icmp_seq=7 ttl=46 time=289.427 ms
64 bytes from 172.105.113.30: icmp_seq=8 ttl=46 time=289.733 ms
64 bytes from 172.105.113.30: icmp_seq=9 ttl=46 time=291.713 ms

--- singapore.starlink.taht.net ping statistics ---
10 packets transmitted, 10 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 288.983/290.768/294.221/1.730 ms
Starting Flent 2.0.1-git-0577a5a using Python 3.9.13.
Starting rrul_var test. Expected run time: 70 seconds.
Exception ignored in: <function RunnerBase.__del__ at 0x108b41700>
Exception ignored in: <function RunnerBase.__del__ at 0x10f75f700>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 209, in __del__
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 209, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 286, in close
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 286, in close
    if self.stdout is not None:
AttributeError: 'NetperfDemoRunner' object has no attribute 'stdout'
    if self.stdout is not None:
AttributeError: 'PingRunner' object has no attribute 'stdout'
Exception ignored in: <function RunnerBase.__del__ at 0x10f3d8700>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 209, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 286, in close
    if self.stdout is not None:
AttributeError: 'NetperfDemoRunner' object has no attribute 'stdout'
Exception ignored in: <function RunnerBase.__del__ at 0x1172ae700>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 209, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 286, in close
    if self.stdout is not None:
AttributeError: 'IrttRunner' object has no attribute 'stdout'
Exception ignored in: <function RunnerBase.__del__ at 0x10e8ec700>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 209, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 286, in close
    if self.stdout is not None:
AttributeError: 'NetperfDemoRunner' object has no attribute 'stdout'
Exception ignored in: <function RunnerBase.__del__ at 0x10c77b700>
Traceback (most recent call last):
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 209, in __del__
    self.close()
  File "/Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py", line 286, in close
    if self.stdout is not None:
AttributeError: 'NetperfDemoRunner' object has no attribute 'stdout'
^CProcess SpawnPoolWorker-15:
/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/resource_tracker.py:216: UserWarning: resource_tracker: There appear to be 6 leaked semaphore objects to clean up at shutdown
  warnings.warn('resource_tracker: There appear to be %d '

bash-3.2$ 
bash-3.2$ ./run-flent --version
Starting Flent 2.0.1-git-0577a5a using Python 3.9.13.
Flent v2.0.1-git-0577a5a.
Running on Python 3.9.13 (main, May 24 2022, 21:28:44)  [Clang 13.0.0 (clang-1300.0.29.30)].
Using matplotlib version 3.4.2 on numpy 1.20.3.
Using Qt: pyqt5 v5.15.5.
bash-3.2$

Mmmh, looks slightly different, but not fixed? Anything I can do to help diagnosing/fixing the issue?

tohojo commented 2 years ago

Hmm, force-pushed a different fix to #269 - does that help?

moeller0 commented 2 years ago

Sorry for the delay, was out with the family for a short hike (though cherry plantations full of ripe cherrys, over here cherry season will last for ~two more weeks):

bash-3.2date ; ping -c 10 singapore.starlink.taht.net ; ./run-flent --ipv4 -l 60 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Sun Jul  3 21:42:32 CEST 2022
PING singapore.starlink.taht.net (172.105.113.30): 56 data bytes
64 bytes from 172.105.113.30: icmp_seq=0 ttl=46 time=290.593 ms
64 bytes from 172.105.113.30: icmp_seq=1 ttl=46 time=289.596 ms
64 bytes from 172.105.113.30: icmp_seq=2 ttl=46 time=289.670 ms
64 bytes from 172.105.113.30: icmp_seq=3 ttl=46 time=289.521 ms
64 bytes from 172.105.113.30: icmp_seq=4 ttl=46 time=289.220 ms
64 bytes from 172.105.113.30: icmp_seq=5 ttl=46 time=291.315 ms
64 bytes from 172.105.113.30: icmp_seq=6 ttl=46 time=289.470 ms
64 bytes from 172.105.113.30: icmp_seq=7 ttl=46 time=289.594 ms
64 bytes from 172.105.113.30: icmp_seq=8 ttl=46 time=289.393 ms
64 bytes from 172.105.113.30: icmp_seq=9 ttl=46 time=289.117 ms

--- singapore.starlink.taht.net ping statistics ---
10 packets transmitted, 10 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 289.117/289.749/291.315/0.645 ms
Starting Flent 2.0.1-git-97de5ef using Python 3.9.13.
Starting rrul_var test. Expected run time: 70 seconds.
^CProcess SpawnPoolWorker-14:
Process SpawnPoolWorker-12:
Process SpawnPoolWorker-15:

bash-3.2$ /usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/resource_tracker.py:216: UserWarning: resource_tracker: There appear to be 6 leaked semaphore objects to clean up at shutdown
  warnings.warn('resource_tracker: There appear to be %d '

does not throw errors, but also does not seem to work, I CTRL-C'd to end this after ~6 minutes, which for a 60 second tests should be ample.

moeller0 commented 2 years ago

But looking at iftop -i pppoe-wan on the router indicates that it really does transfer data in both directions, however it does not seem to end and does not write a json output file (the log is still written out).

moeller0 commented 2 years ago

Update, I left a test hanging after the Starting rrul_var test. Expected run time: 70 seconds. output for a full hour and no progress.

tohojo commented 2 years ago

Hmm, could you try printing the output of this (using the 'python' binary that you're running Flent through)?

python -c "from multiprocessing.reduction import DupFd; print(DupFd)"

moeller0 commented 2 years ago 
bash-3.2$ python3 -c "from multiprocessing.reduction import DupFd; print(DupFd)"
<function DupFd at 0x1019b4d30>
bash-3.2$ python3 --version
Python 3.9.13
tohojo commented 2 years ago

Okay, think this may be an OOM thing? Please try with the latest commit added to the pickle-fix branch (force-pushed so you'll need to reset)

moeller0 commented 2 years ago 
bash-3.2$ git pull
remote: Enumerating objects: 5, done.
remote: Counting objects: 100% (5/5), done.
remote: Compressing objects: 100% (2/2), done.
remote: Total 5 (delta 3), reused 5 (delta 3), pack-reused 0
Unpacking objects: 100% (5/5), 1.99 KiB | 290.00 KiB/s, done.
From https://github.com/tohojo/flent
 + 97de5ef...ec5809f pickle-fix -> origin/pickle-fix  (forced update)
Successfully rebased and updated refs/heads/pickle-fix.
bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Mon Jul  4 13:27:45 CEST 2022
Starting Flent 2.0.1-git-ec5809f using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
^C
bash-3.2$ /usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/resource_tracker.py:216: UserWarning: resource_tracker: There appear to be 6 leaked semaphore objects to clean up at shutdown
  warnings.warn('resource_tracker: There appear to be %d '

bash-3.2$

still the same behavior, it starts, it actually transfers data (as monitored with iftop on the mac itself) it just never finishes (I CTRL_C'd it ~4 minutes after calling it). OOM might be an issue, albeit not a system-wide issue, there is still plenty of paging space available on disk...

tohojo commented 2 years ago

Hmm, okay, pushed another commit with some debug prints - please try that and post the output... need to figure out where exactly it's hanging...

moeller0 commented 2 years ago 
bash-3.2$ git pull
remote: Enumerating objects: 5, done.
remote: Counting objects: 100% (5/5), done.
remote: Total 5 (delta 4), reused 5 (delta 4), pack-reused 0
Unpacking objects: 100% (5/5), 729 bytes | 81.00 KiB/s, done.
From https://github.com/tohojo/flent
   ec5809f..2930a77  pickle-fix -> origin/pickle-fix
Updating ec5809f..2930a77
Fast-forward
 flent/aggregators.py | 6 ++++++
 flent/runners.py     | 2 ++
 2 files changed, 8 insertions(+)
bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Mon Jul  4 14:13:30 CEST 2022
Starting Flent 2.0.1-git-2930a77 using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
33.730011164: starting log reader thread
33.737054163: starting parser threads
do_parse() in <flent.runners.PingRunner object at 0x10854d670> (64550)
do_parse() in <flent.runners.IrttRunner object at 0x10854dee0> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x10854d880> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x10854da00> (64550)
do_parse() in <flent.runners.IrttRunner object at 0x1085632b0> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x108563400> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x108563580> (64550)
do_parse() in <flent.runners.IrttRunner object at 0x108563850> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x1085639a0> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x108563b20> (64550)
do_parse() in <flent.runners.IrttRunner object at 0x108563df0> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x108563f40> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x108571100> (64550)
do_parse() in <flent.runners.IrttRunner object at 0x1085713d0> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x108571520> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x1085716a0> (64550)
do_parse() in <flent.runners.IrttRunner object at 0x108571970> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x108571ac0> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x108571c40> (64550)
do_parse() in <flent.runners.IrttRunner object at 0x108571f10> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x10855f0a0> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x10855f220> (64550)
do_parse() in <flent.runners.IrttRunner object at 0x10855f4f0> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x10855f640> (64550)
do_parse() in <flent.runners.NetperfDemoRunner object at 0x10855f7c0> (64550)
do_parse() in <flent.runners.PingRunner object at 0x10855f940> (64550)
33.738303924: closing pool
33.738547923: joining pool

There it hangs now....

tohojo commented 2 years ago

Hmm, okay, added some more debug prints, try again? :D

moeller0 commented 2 years ago 
bash-3.2$ git pull
remote: Enumerating objects: 5, done.
remote: Counting objects: 100% (5/5), done.
remote: Total 5 (delta 4), reused 5 (delta 4), pack-reused 0
Unpacking objects: 100% (5/5), 855 bytes | 85.00 KiB/s, done.
From https://github.com/tohojo/flent
 + 2930a77...24ff633 pickle-fix -> origin/pickle-fix  (forced update)
Successfully rebased and updated refs/heads/pickle-fix.
bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Mon Jul  4 15:38:00 CEST 2022
Starting Flent 2.0.1-git-24ff633 using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
33.718177967: starting log reader thread
33.720147593: running log reader
33.721222545: getting log msg
33.724558459: starting parser threads
33.72485109: do_parse() in <flent.runners.PingRunner object at 0x10c25fd90> (65289)
33.725061178: do_parse() in <flent.runners.IrttRunner object at 0x10c25f4f0> (65289)
33.725166758: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c25fb80> (65289)
33.725225037: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c25fa60> (65289)
33.72526483: do_parse() in <flent.runners.IrttRunner object at 0x10c285280> (65289)
33.725292074: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c2853d0> (65289)
33.725317534: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c285550> (65289)
33.725343454: do_parse() in <flent.runners.IrttRunner object at 0x10c285820> (65289)
33.72536826: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c285970> (65289)
33.725390418: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c285af0> (65289)
33.725420647: do_parse() in <flent.runners.IrttRunner object at 0x10c285dc0> (65289)
33.725456098: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c285f10> (65289)
33.729917805: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c2700d0> (65289)
33.730014905: do_parse() in <flent.runners.IrttRunner object at 0x10c2703a0> (65289)
33.730069902: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c2704f0> (65289)
33.730097822: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c270670> (65289)
33.730139423: do_parse() in <flent.runners.IrttRunner object at 0x10c270940> (65289)
33.730164753: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c270a90> (65289)
33.730185272: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c270c10> (65289)
33.730280801: do_parse() in <flent.runners.IrttRunner object at 0x10c270ee0> (65289)
33.730316501: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c282070> (65289)
33.730344565: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c2821f0> (65289)
33.730376405: do_parse() in <flent.runners.IrttRunner object at 0x10c2824c0> (65289)
33.740738263: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c282610> (65289)
33.740787568: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10c282790> (65289)
33.74082428: do_parse() in <flent.runners.PingRunner object at 0x10c282910> (65289)
33.74086195: closing pool
33.740993245: joining pool
1.021076665: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x11019db80> (65370) 11/12
1.026733947: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x11019db50> (65370) 11/12
1.031159875: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x11019db80> (65370) 11/12
1.036714285: print: Running in parse_output in <flent.runners.IrttRunner object at 0x11019db50> (65370) 11/12
1.093690151: print: Running in parse_output in <flent.runners.PingRunner object at 0x10cde2b80> (65364) 11/12
1.106548687: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10cde2b50> (65364) 11/12
1.102319378: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10193fb80> (65365) 11/12
1.112534372: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10cde2b80> (65364) 11/12
1.06657285: print: Running in parse_output in <flent.runners.IrttRunner object at 0x11019db80> (65370) 11/12
1.118212271: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10cde2b50> (65364) 11/12
1.129753149: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10cde2b80> (65364) 11/12
1.119975293: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x109c5cb80> (65367) 11/12
1.135866296: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10193fb50> (65365) 11/12
1.144597454: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10193fb80> (65365) 11/12
1.13252166: print: Running in parse_output in <flent.runners.IrttRunner object at 0x109c5cb50> (65367) 11/12
1.151667241: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10193fb50> (65365) 11/12
1.113276558: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x11019db50> (65370) 11/12
1.157750396: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10193fb80> (65365) 11/12
1.120986629: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x11019db80> (65370) 11/12
1.157789953: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x109c5cb80> (65367) 11/12
1.144290803: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bdf5b80> (65369) 11/12
1.156037658: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10302ab80> (65371) 11/12

Thanks!

tohojo commented 2 years ago

Alright, there's some issue with the use of the multiprocess module on OSX. Which, from a bit of googling, doesn't seem to be too unusual... Added some more debug prints and a mode change, please try again? :)

moeller0 commented 2 years ago 
bash-3.2$ git pull
remote: Enumerating objects: 10, done.
remote: Counting objects: 100% (10/10), done.
remote: Compressing objects: 100% (2/2), done.
remote: Total 10 (delta 8), reused 10 (delta 8), pack-reused 0
Unpacking objects: 100% (10/10), 1.44 KiB | 87.00 KiB/s, done.
From https://github.com/tohojo/flent
 + 24ff633...dd20032 pickle-fix -> origin/pickle-fix  (forced update)
Successfully rebased and updated refs/heads/pickle-fix.
bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Mon Jul  4 16:34:25 CEST 2022
Starting Flent 2.0.1-git-dd20032 using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
33.709370443: starting log reader thread
33.716009804: running log reader
33.71603502: getting log msg
33.716961636: starting parser threads
33.71720007: do_parse() in <flent.runners.PingRunner object at 0x107d1ac70> (65772)
33.717534925: do_parse() in <flent.runners.IrttRunner object at 0x107d1a340> (65772)
33.717631053: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d1a100> (65772)
33.717689316: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d1a850> (65772)
33.717728029: do_parse() in <flent.runners.IrttRunner object at 0x107d2f1c0> (65772)
33.7177752: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d2f310> (65772)
33.717801044: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d2f490> (65772)
33.717837428: do_parse() in <flent.runners.IrttRunner object at 0x107d2f760> (65772)
33.717863041: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d2f8b0> (65772)
33.717922728: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d2fa30> (65772)
33.717954975: do_parse() in <flent.runners.IrttRunner object at 0x107d2fd00> (65772)
33.717982035: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d2fe50> (65772)
33.720187406: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d2ffd0> (65772)
33.720451335: do_parse() in <flent.runners.IrttRunner object at 0x107d212e0> (65772)
33.72049346: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d21430> (65772)
33.720522495: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d215b0> (65772)
33.720553854: do_parse() in <flent.runners.IrttRunner object at 0x107d21880> (65772)
33.720580602: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d219d0> (65772)
33.72060745: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d21b50> (65772)
33.720636236: do_parse() in <flent.runners.IrttRunner object at 0x107d21e20> (65772)
33.720661132: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d21f70> (65772)
33.720683296: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d38130> (65772)
33.720716131: do_parse() in <flent.runners.IrttRunner object at 0x107d38400> (65772)
33.727717959: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d38550> (65772)
33.727761737: do_parse() in <flent.runners.NetperfDemoRunner object at 0x107d386d0> (65772)
33.727788972: do_parse() in <flent.runners.PingRunner object at 0x107d38850> (65772)
33.727810897: closing pool
33.727913769: joining pool
0.161604761: Set queue handler in 65831
0.171417014: Set queue handler in 65832
0.170704101: Set queue handler in 65833
0.188416046: Set queue handler in 65830
0.161573786: Set queue handler in 65835
0.16789941: Set queue handler in 65834
0.17679888: Set queue handler in 65836
0.178900695: Set queue handler in 65837
0.950753618: 65833 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.920448256: 65836 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.922088254: 65837 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.973371129: 65830 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.974677372: 65831 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.967649035: 65832 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.947097031: 65835 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.952631059: 65834 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.665517348: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.666139816: getting log msg
34.6664031: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.666865464: getting log msg
34.66728414: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.667499639: getting log msg
34.667673519: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.667872917: getting log msg
34.668023251: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.668220199: getting log msg
34.66913725: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.669353084: getting log msg
34.669527655: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.669734829: getting log msg
34.670260891: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.670482479: getting log msg
1.007639306: 65831 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.97863915: 65835 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.958159614: 65837 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.694438898: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.694743083: getting log msg
34.694921515: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.695135546: getting log msg
34.695297459: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.985080084: 65834 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.695596736: getting log msg
34.695888322: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.994615233: 65833 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.696113714: getting log msg
34.696343554: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.696552068: getting log msg
1.011663944: 65830 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.697407897: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.961585796: 65836 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.697652849: getting log msg
34.697892294: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.698101709: getting log msg
1.012875471: 65831 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.699465068: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.699711887: getting log msg
0.963918431: 65837 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.700578162: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.700814162: getting log msg
0.985203143: 65835 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
1.014675927: 65831 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.701137233: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
0.96501394: 65837 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.99103869: 65834 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.701352536: getting log msg
1.015263023: 65831 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.701616526: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.986084391: 65835 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
1.000398183: 65833 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.70186243: getting log msg
0.965674601: 65837 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
1.015770904: 65831 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.702123337: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.991901028: 65834 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.986712283: 65835 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.702353148: getting log msg
0.99222155: 65834 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
0.966326939: 65837 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
1.001380683: 65833 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.703009492: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
0.987466662: 65835 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.703238095: getting log msg
0.992965924: 65834 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.703683515: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
1.002337804: 65833 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.703912722: getting log msg
34.70417756: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.704435822: getting log msg
34.70460739: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.704828866: getting log msg
34.705002487: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.705211787: getting log msg
34.705399831: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
1.020192112: 65830 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.705674157: getting log msg
1.004624101: 65833 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.706315858: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
0.97055965: 65836 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
1.021794287: 65830 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.971275938: 65836 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.707452201: getting log msg
34.707918085: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
1.022699372: 65830 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.708367975: getting log msg
34.708660557: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
0.973001716: 65836 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.709049303: getting log msg
34.709290736: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.709596889: getting log msg
34.710161594: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
0.974609465: 65836 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.710645869: getting log msg
34.710884139: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.711171437: getting log msg
1.026090199: 65830 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.711643613: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.712077354: getting log msg
34.712627745: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.713029764: getting log msg
34.713225152: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.713464263: getting log msg
34.713634027: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.713845359: getting log msg
34.714202643: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.714534928: getting log msg
34.714700027: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.714889501: getting log msg
34.715060541: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.715278635: getting log msg
34.715445654: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.715666299: getting log msg
34.715838172: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.716067164: getting log msg
34.716511864: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.716941366: getting log msg
34.717318668: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.717698329: getting log msg
0.987333283: print: Running in parse_output in <flent.runners.IrttRunner object at 0x108cc1b80> (65837) 12/13
0.98773418: 65837 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.987391097: log: Running in parse_output in <flent.runners.IrttRunner object at 0x108cc1b80> (65837) 12/13">
1.031002571: 65832 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.724597941: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.987391097: log: Running in parse_output in <flent.runners.IrttRunner object at 0x108cc1b80> (65837) 12/13">
0.987391097: log: Running in parse_output in <flent.runners.IrttRunner object at 0x108cc1b80> (65837) 12/13
34.724907081: getting log msg
34.725106433: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.725334293: getting log msg
1.039847064: print: Running in parse_output in <flent.runners.PingRunner object at 0x1015a9b80> (65831) 12/13
1.040134045: 65831 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.03990616: log: Running in parse_output in <flent.runners.PingRunner object at 0x1015a9b80> (65831) 12/13">
34.726975722: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.03990616: log: Running in parse_output in <flent.runners.PingRunner object at 0x1015a9b80> (65831) 12/13">
1.03990616: log: Running in parse_output in <flent.runners.PingRunner object at 0x1015a9b80> (65831) 12/13
34.727256537: getting log msg
1.035568098: 65832 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.729089254: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
1.036034461: 65832 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.729365814: getting log msg
1.036441857: 65832 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.729642277: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.729859005: getting log msg
1.036804429: 65832 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.730039506: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.730271595: getting log msg
34.730790985: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.731161427: getting log msg
1.056575787: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1015a9b50> (65831) 12/13
1.056826227: 65831 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.056730821: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1015a9b50> (65831) 12/13">
34.743518555: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.056730821: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1015a9b50> (65831) 12/13">
1.056730821: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1015a9b50> (65831) 12/13
34.74388033: getting log msg
1.055230645: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10f3c6b80> (65832) 12/13
1.05536397: 65832 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.055267081: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10f3c6b80> (65832) 12/13">
34.748929569: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.055267081: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10f3c6b80> (65832) 12/13">
1.055267081: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10f3c6b80> (65832) 12/13
34.749306368: getting log msg
1.063298163: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1015a9b80> (65831) 12/13
1.063403564: 65831 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.063326866: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1015a9b80> (65831) 12/13">
34.749996846: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.063326866: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1015a9b80> (65831) 12/13">
1.063326866: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1015a9b80> (65831) 12/13
34.750324791: getting log msg
1.069780062: print: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b50> (65831) 12/13
1.069879556: 65831 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.069813497: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b50> (65831) 12/13">
34.756499391: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.069813497: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b50> (65831) 12/13">
1.069813497: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b50> (65831) 12/13
34.756794364: getting log msg
1.027477691: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13
1.027598241: 65837 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.027515643: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13">
34.764256981: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.027515643: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13">
1.027515643: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13
34.764594407: getting log msg
1.034830471: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b80> (65837) 12/13
1.034942287: 65837 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.034864927: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b80> (65837) 12/13">
1.078561011: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10f3c6b50> (65832) 12/13
34.771774123: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.034864927: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b80> (65837) 12/13">
1.078676706: 65832 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.07859485: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10f3c6b50> (65832) 12/13">
1.034864927: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b80> (65837) 12/13
34.772292394: getting log msg
34.772742806: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.07859485: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10f3c6b50> (65832) 12/13">
1.07859485: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10f3c6b50> (65832) 12/13
34.773583594: getting log msg
1.04302296: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13
1.043164264: 65837 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.043072892: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13">
34.780035302: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.043072892: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13">
1.043072892: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13
34.780379691: getting log msg
1.051511489: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b80> (65837) 12/13
1.051701095: 65837 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.051579365: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b80> (65837) 12/13">
34.78866309: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.051579365: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b80> (65837) 12/13">
1.051579365: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b80> (65837) 12/13
34.789194339: getting log msg
1.108709931: print: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b80> (65831) 12/13
1.108883053: 65831 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.108771742: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b80> (65831) 12/13">
34.797125109: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.108771742: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b80> (65831) 12/13">
1.108771742: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b80> (65831) 12/13
34.797515573: getting log msg
1.062300571: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13
1.062441617: 65837 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.062359414: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13">
34.799127493: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.062359414: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13">
1.062359414: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13
34.799423576: getting log msg
1.110293477: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b80> (65832) 12/13
1.110422932: 65832 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.110334785: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b80> (65832) 12/13">
34.80400477: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.110334785: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b80> (65832) 12/13">
1.110334785: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b80> (65832) 12/13
34.804467777: getting log msg
1.069075558: print: Running in parse_output in <flent.runners.IrttRunner object at 0x108cc1b80> (65837) 12/13
1.069177003: 65837 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.069108576: log: Running in parse_output in <flent.runners.IrttRunner object at 0x108cc1b80> (65837) 12/13">
34.805827165: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.069108576: log: Running in parse_output in <flent.runners.IrttRunner object at 0x108cc1b80> (65837) 12/13">
1.069108576: log: Running in parse_output in <flent.runners.IrttRunner object at 0x108cc1b80> (65837) 12/13
34.806143151: getting log msg
1.116980082: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b50> (65832) 12/13
1.117088996: 65832 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.117018063: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b50> (65832) 12/13">
34.810609448: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.117018063: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b50> (65832) 12/13">
1.117018063: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b50> (65832) 12/13
34.810932098: getting log msg
1.12286192: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b80> (65832) 12/13
1.12295964: 65832 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.122896423: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b80> (65832) 12/13">
34.816513555: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.122896423: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b80> (65832) 12/13">
1.122896423: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b80> (65832) 12/13
34.816830068: getting log msg
1.131562387: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b50> (65832) 12/13
1.131752037: 65832 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.13163482: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b50> (65832) 12/13">
34.827179254: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.13163482: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b50> (65832) 12/13">
1.13163482: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f3c6b50> (65832) 12/13
34.827837269: getting log msg
1.141901614: print: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b50> (65831) 12/13
1.142083109: 65831 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.141949345: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b50> (65831) 12/13">
34.828876165: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.141949345: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b50> (65831) 12/13">
1.141949345: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1015a9b50> (65831) 12/13
34.830044651: getting log msg
1.137797891: print: Running in parse_output in <flent.runners.PingRunner object at 0x10f3c6b80> (65832) 12/13
1.137904276: 65832 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.13784016: log: Running in parse_output in <flent.runners.PingRunner object at 0x10f3c6b80> (65832) 12/13">
34.831455418: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.13784016: log: Running in parse_output in <flent.runners.PingRunner object at 0x10f3c6b80> (65832) 12/13">
1.13784016: log: Running in parse_output in <flent.runners.PingRunner object at 0x10f3c6b80> (65832) 12/13
34.831828926: getting log msg
1.095834748: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13
1.095966391: 65837 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.09586851: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13">
34.83264601: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.09586851: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13">
1.09586851: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x108cc1b50> (65837) 12/13
34.832925835: getting log msg
0.106474769: Set queue handler in 65846
0.102807589: Set queue handler in 65847
0.110144355: Set queue handler in 65848
0.10358819: Set queue handler in 65850
0.109640378: Set queue handler in 65849

Still hangs...

tohojo commented 2 years ago

Right, we'll just keep at this until we figure out where it's hanging :) another bit of debug output now...

moeller0 commented 2 years ago 
bash-3.2$ git pull
remote: Enumerating objects: 4, done.
remote: Counting objects: 100% (4/4), done.
remote: Total 4 (delta 3), reused 4 (delta 3), pack-reused 0
Unpacking objects: 100% (4/4), 692 bytes | 98.00 KiB/s, done.
From https://github.com/tohojo/flent
 + dd20032...a9d91ca pickle-fix -> origin/pickle-fix  (forced update)
Successfully rebased and updated refs/heads/pickle-fix.
bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Mon Jul  4 16:54:23 CEST 2022
Starting Flent 2.0.1-git-a9d91ca using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
33.857897988: starting log reader thread
33.861161987: running log reader
33.861248332: getting log msg
33.86831317: starting parser threads
33.869024987: do_parse() in <flent.runners.PingRunner object at 0x11057f9d0> (65950)
33.870023485: do_parse() in <flent.runners.IrttRunner object at 0x11057fd30> (65950)
33.870217833: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11057ffd0> (65950)
33.870342071: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11057feb0> (65950)
33.870404643: do_parse() in <flent.runners.IrttRunner object at 0x110596250> (65950)
33.870436152: do_parse() in <flent.runners.NetperfDemoRunner object at 0x1105963a0> (65950)
33.870465756: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110596520> (65950)
33.870494187: do_parse() in <flent.runners.IrttRunner object at 0x1105967f0> (65950)
33.870518563: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110596940> (65950)
33.87054004: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110596ac0> (65950)
33.870568755: do_parse() in <flent.runners.IrttRunner object at 0x110596d90> (65950)
33.873335677: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110596ee0> (65950)
33.873374924: do_parse() in <flent.runners.NetperfDemoRunner object at 0x1105850a0> (65950)
33.873403168: do_parse() in <flent.runners.IrttRunner object at 0x110585370> (65950)
33.873430091: do_parse() in <flent.runners.NetperfDemoRunner object at 0x1105854c0> (65950)
33.873453218: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110585640> (65950)
33.873480407: do_parse() in <flent.runners.IrttRunner object at 0x110585910> (65950)
33.873501788: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110585a60> (65950)
33.873521625: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110585be0> (65950)
33.873545675: do_parse() in <flent.runners.IrttRunner object at 0x110585eb0> (65950)
33.873568169: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110594040> (65950)
33.873590622: do_parse() in <flent.runners.NetperfDemoRunner object at 0x1105941c0> (65950)
33.873619535: do_parse() in <flent.runners.IrttRunner object at 0x110594490> (65950)
33.882041479: do_parse() in <flent.runners.NetperfDemoRunner object at 0x1105945e0> (65950)
33.882079746: do_parse() in <flent.runners.NetperfDemoRunner object at 0x110594760> (65950)
33.882103284: do_parse() in <flent.runners.PingRunner object at 0x1105948e0> (65950)
33.882124432: closing pool
33.882575157: joining pool
0.135443743: Set queue handler in 66009
0.146472438: Set queue handler in 66008
0.149596032: Set queue handler in 66007
0.137971895: Set queue handler in 66010
0.14829252: Set queue handler in 66011
0.142158433: Set queue handler in 66012
0.146998014: Set queue handler in 66013
0.157457775: Set queue handler in 66014
0.822293133: 66008 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.814752529: 66010 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.661216009: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.821891901: 66009 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.662550487: getting log msg
34.665943754: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.670339933: getting log msg
34.671339457: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.673998679: getting log msg
0.846499785: 66008 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.681511378: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.842570896: 66009 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.836470053: 66010 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.683127551: getting log msg
0.852166666: 66007 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.850765941: 66008 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.684205897: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.684747474: getting log msg
0.8518199: 66008 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.685266617: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.852499041: 66008 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.685806435: getting log msg
0.852979392: 66008 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.686409808: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.687125736: getting log msg
0.834519341: 66011 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.8410743: 66010 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
0.847275892: 66009 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.687636208: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.848032867: 66009 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.842059502: 66010 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.688335426: getting log msg
0.848546875: 66009 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.688770668: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
0.842620654: 66010 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.689155252: getting log msg
0.84919581: 66009 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.689402355: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.843438935: 66010 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.689984103: getting log msg
34.696722587: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
0.818093734: 66013 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.700095234: getting log msg
34.702081106: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.702882388: getting log msg
34.703868113: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.707008932: getting log msg
34.707625099: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.708424763: getting log msg
0.855826959: 66011 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.708782779: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.877451787: 66007 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.709595908: getting log msg
34.709973654: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.71053629: getting log msg
0.870580982: print: Running in parse_output in <flent.runners.PingRunner object at 0x1047c4b80> (66009) 12/13
0.870690202: 66009 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.870612477: log: Running in parse_output in <flent.runners.PingRunner object at 0x1047c4b80> (66009) 12/13">
0.850994999: 66012 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.711444552: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.712327754: getting log msg
0.860056361: 66011 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.71278535: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.713229018: getting log msg
0.860644099: 66011 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.861264378: 66011 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
0.882381531: 66007 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.714223088: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
0.862061394: 66011 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.714822495: getting log msg
0.883217487: 66007 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.883852757: 66007 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.716032438: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.71694045: getting log msg
34.717360543: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.877542555: Finished parse_output() in <flent.runners.PingRunner object at 0x1047c4b80> (66009)
34.718364565: getting log msg
0.889706582: 66007 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
0.835561542: 66014 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.848215083: 66013 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.728698899: recv_result() in <flent.runners.PingRunner object at 0x11057f9d0> (65950)
34.728811973: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.729447775: getting log msg
34.72981043: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.730251141: getting log msg
34.730645022: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.870612477: log: Running in parse_output in <flent.runners.PingRunner object at 0x1047c4b80> (66009) 12/13">
0.870612477: log: Running in parse_output in <flent.runners.PingRunner object at 0x1047c4b80> (66009) 12/13
0.891025864: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b50> (66009) 12/13
34.731253458: getting log msg
0.891205368: 66009 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.891074178: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b50> (66009) 12/13">
34.731577289: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.732549096: getting log msg
0.87999749: print: Running in parse_output in <flent.runners.IrttRunner object at 0x100e7db80> (66011) 12/13
0.88012649: 66011 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.880030697: log: Running in parse_output in <flent.runners.IrttRunner object at 0x100e7db80> (66011) 12/13">
34.733578561: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
34.734163848: getting log msg
0.894186727: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1047c4b50> (66009)
34.734736395: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.735742027: recv_result() in <flent.runners.NetperfDemoRunner object at 0x110596940> (65950)
0.876227444: 66012 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.736715496: getting log msg
34.737134943: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
0.857213293: 66013 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.737621917: getting log msg
34.737951985: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
0.858051716: 66013 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.738588204: getting log msg
34.738995457: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
0.898919153: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13
0.899019652: 66009 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.898948932: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13">
0.859430424: 66013 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.739613763: getting log msg
34.740400126: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.741388177: getting log msg
0.881234126: 66012 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.742103661: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
0.862487681: 66013 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.742851158: getting log msg
0.903501791: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009)
0.913275933: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f544b80> (66007) 12/13
34.744990923: recv_result() in <flent.runners.NetperfDemoRunner object at 0x110596ac0> (65950)
0.913397133: 66007 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.913309715: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f544b80> (66007) 12/13">
34.745441017: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.746740271: getting log msg
34.747122767: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "matplotlib data path: %s">
0.887209902: 66012 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.748146375: getting log msg
34.748483271: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.891074178: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b50> (66009) 12/13">
0.891074178: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b50> (66009) 12/13
0.9198435: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10f544b80> (66007)
0.864776905: 66014 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.899554931: Finished parse_output() in <flent.runners.IrttRunner object at 0x100e7db80> (66011)
34.752880209: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11057ffd0> (65950)
34.753229859: getting log msg
0.913279859: print: Running in parse_output in <flent.runners.IrttRunner object at 0x1047c4b50> (66009) 12/13
0.913395449: 66009 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.91331291: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1047c4b50> (66009) 12/13">
0.893695576: 66012 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.75556958: recv_result() in <flent.runners.IrttRunner object at 0x110596250> (65950)
34.758753309: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.759793114: getting log msg
34.760070113: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.880030697: log: Running in parse_output in <flent.runners.IrttRunner object at 0x100e7db80> (66011) 12/13">
0.880030697: log: Running in parse_output in <flent.runners.IrttRunner object at 0x100e7db80> (66011) 12/13
34.760516057: getting log msg
34.760840358: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
0.88141451: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bbd3b80> (66013) 12/13
34.761475478: getting log msg
0.881536428: 66013 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.881450184: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bbd3b80> (66013) 12/13">
34.761828107: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
0.901898376: 66012 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.762280754: getting log msg
34.762676898: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.763325634: getting log msg
34.763768004: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.898948932: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13">
0.898948932: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13
0.876986601: 66014 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.764851708: getting log msg
0.886429125: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10bbd3b80> (66013)
34.766868415: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.767735125: recv_result() in <flent.runners.NetperfDemoRunner object at 0x110596520> (65950)
0.880989297: 66014 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.770144715: getting log msg
0.884033674: 66014 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.771408876: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.772431966: getting log msg
34.773107416: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
0.886344383: 66014 - emit log record <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.774170052: getting log msg
34.7746558: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.913309715: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f544b80> (66007) 12/13">
0.913309715: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f544b80> (66007) 12/13
0.894693585: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10bbd3b50> (66013) 12/13
0.894851685: 66013 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.894735645: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10bbd3b50> (66013) 12/13">
34.775668385: getting log msg
34.776104767: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.777042653: getting log msg
34.777703563: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 224, "CONFIGDIR=%s">
34.778301409: getting log msg
34.778876447: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.91331291: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1047c4b50> (66009) 12/13">
0.91331291: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1047c4b50> (66009) 12/13
34.779694284: getting log msg
34.780208084: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
0.920691476: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13
34.781107564: getting log msg
0.920845945: 66012 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.920739328: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13">
0.941374221: Finished parse_output() in <flent.runners.IrttRunner object at 0x1047c4b50> (66009)
34.782005002: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.881450184: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bbd3b80> (66013) 12/13">
0.881450184: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bbd3b80> (66013) 12/13
34.784580105: recv_result() in <flent.runners.IrttRunner object at 0x110596d90> (65950)
0.924344686: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012)
34.784641916: getting log msg
34.786056208: recv_result() in <flent.runners.NetperfDemoRunner object at 0x1105963a0> (65950)
34.786612867: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
34.787112284: getting log msg
34.787397971: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1394, "matplotlib version %s">
34.787752923: getting log msg
34.788049266: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1395, "interactive is %s">
34.788401399: getting log msg
34.788634217: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1396, "platform is %s">
34.788944498: getting log msg
0.949239992: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13
34.789467612: got log msg <LogRecord: matplotlib, 10, /Users/smoeller/Library/Python/3.9/lib/python/site-packages/matplotlib/__init__.py, 1397, "loaded modules: %s">
0.949509293: 66009 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.949271738: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13">
34.789991858: getting log msg
0.929650415: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13
0.929753971: 66012 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.929677838: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13">
34.790173059: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.894735645: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10bbd3b50> (66013) 12/13">
0.894735645: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10bbd3b50> (66013) 12/13
34.790405576: getting log msg
34.790571953: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.920739328: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13">
0.920739328: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13
34.790782236: getting log msg
34.790944998: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.949271738: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13">
0.949271738: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13
34.791145461: getting log msg
34.791295986: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.929677838: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13">
0.929677838: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13
34.791507343: getting log msg
0.95176683: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009)
34.792398278: recv_result() in <flent.runners.NetperfDemoRunner object at 0x1105854c0> (65950)
0.933362176: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012)
34.794417204: recv_result() in <flent.runners.NetperfDemoRunner object at 0x110585640> (65950)
0.917324354: Finished parse_output() in <flent.runners.IrttRunner object at 0x10bbd3b50> (66013)
0.93714566: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13
0.937268984: 66012 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.937194749: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13">
34.798007546: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.937194749: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13">
0.937194749: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13
34.798304696: getting log msg
0.960298308: print: Running in parse_output in <flent.runners.IrttRunner object at 0x1047c4b50> (66009) 12/13
0.940130463: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012)
0.960406423: 66009 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.960332758: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1047c4b50> (66009) 12/13">
34.801860011: recv_result() in <flent.runners.IrttRunner object at 0x110585370> (65950)
34.803156874: recv_result() in <flent.runners.NetperfDemoRunner object at 0x110585a60> (65950)
34.803353086: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.960332758: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1047c4b50> (66009) 12/13">
0.960332758: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1047c4b50> (66009) 12/13
34.804117732: getting log msg
0.944213656: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13
0.944306106: 66012 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.944242768: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13">
34.8049536: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.944242768: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13">
0.944242768: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13
34.805205335: getting log msg
0.947764222: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012)
34.809078356: recv_result() in <flent.runners.NetperfDemoRunner object at 0x110585be0> (65950)
0.952011489: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13
0.952118079: 66012 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.952047513: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13">
34.812852108: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.952047513: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13">
0.952047513: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012) 12/13
34.813173543: getting log msg
0.934088298: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10bbd3b80> (66013) 12/13
0.934471029: 66013 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.934371565: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10bbd3b80> (66013) 12/13">
0.954215746: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1013b7b80> (66012)
34.814956583: recv_result() in <flent.runners.NetperfDemoRunner object at 0x110594040> (65950)
34.815147601: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.934371565: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10bbd3b80> (66013) 12/13">
0.934371565: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10bbd3b80> (66013) 12/13
34.8158344: getting log msg
0.956459726: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13
0.956610729: 66012 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.956517489: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13">
34.817357973: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.956517489: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13">
0.956517489: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012) 12/13
34.817672484: getting log msg
0.960984956: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1013b7b50> (66012)
34.824708627: recv_result() in <flent.runners.NetperfDemoRunner object at 0x1105941c0> (65950)
0.966667929: print: Running in parse_output in <flent.runners.IrttRunner object at 0x1013b7b80> (66012) 12/13
0.966808609: 66012 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.966709184: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1013b7b80> (66012) 12/13">
34.827700113: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.966709184: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1013b7b80> (66012) 12/13">
0.966709184: log: Running in parse_output in <flent.runners.IrttRunner object at 0x1013b7b80> (66012) 12/13
34.828109602: getting log msg
0.990807733: Finished parse_output() in <flent.runners.IrttRunner object at 0x1047c4b50> (66009)
34.833329385: recv_result() in <flent.runners.IrttRunner object at 0x110585910> (65950)
0.995312016: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13
0.995455382: 66009 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.995358073: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13">
34.836120555: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.995358073: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13">
0.956083862: Finished parse_output() in <flent.runners.IrttRunner object at 0x10bbd3b80> (66013)
0.995358073: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009) 12/13
34.83644803: getting log msg
0.998323025: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1047c4b80> (66009)
34.838480358: recv_result() in <flent.runners.IrttRunner object at 0x110585eb0> (65950)
34.839252052: recv_result() in <flent.runners.NetperfDemoRunner object at 0x1105945e0> (65950)
0.961234837: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bbd3b50> (66013) 12/13
0.961395882: 66013 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.961273711: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bbd3b50> (66013) 12/13">
1.001683428: print: Running in parse_output in <flent.runners.PingRunner object at 0x1047c4b50> (66009) 12/13
34.841842716: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "0.961273711: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bbd3b50> (66013) 12/13">
0.961273711: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10bbd3b50> (66013) 12/13
1.001874267: 66009 - emit log record <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.001713428: log: Running in parse_output in <flent.runners.PingRunner object at 0x1047c4b50> (66009) 12/13">
34.842136605: getting log msg
34.842419022: got log msg <LogRecord: flent.runners, 20, /Users/Shared/space/data_local/moeller/PRIVATE/samba/privat/MOEWE/techno_kram/CODE/flent/flent/runners.py, 595, "1.001713428: log: Running in parse_output in <flent.runners.PingRunner object at 0x1047c4b50> (66009) 12/13">
1.001713428: log: Running in parse_output in <flent.runners.PingRunner object at 0x1047c4b50> (66009) 12/13
34.842655221: getting log msg
0.966838141: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10bbd3b50> (66013)
1.007510226: Finished parse_output() in <flent.runners.PingRunner object at 0x1047c4b50> (66009)
34.847670867: recv_result() in <flent.runners.NetperfDemoRunner object at 0x110594760> (65950)
34.848897808: recv_result() in <flent.runners.PingRunner object at 0x1105948e0> (65950)
0.990717627: Finished parse_output() in <flent.runners.IrttRunner object at 0x1013b7b80> (66012)
34.855499911: recv_result() in <flent.runners.IrttRunner object at 0x110594490> (65950)
0.102586912: Set queue handler in 66023
0.100834132: Set queue handler in 66024
0.088739652: Set queue handler in 66025
0.082697771: Set queue handler in 66027
0.090864675: Set queue handler in 66026
tohojo commented 2 years ago

And another :)

moeller0 commented 2 years ago 
bash-3.2$ git pull
remote: Enumerating objects: 6, done.
remote: Counting objects: 100% (6/6), done.
remote: Total 6 (delta 5), reused 6 (delta 5), pack-reused 0
Unpacking objects: 100% (6/6), 1.09 KiB | 93.00 KiB/s, done.
From https://github.com/tohojo/flent
 + a9d91ca...e71efa4 pickle-fix -> origin/pickle-fix  (forced update)
Successfully rebased and updated refs/heads/pickle-fix.
bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Mon Jul  4 17:29:52 CEST 2022
Starting Flent 2.0.1-git-e71efa4 using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
33.570699546: starting log reader thread
33.572452978: running log reader
33.572475613: getting log msg
33.574711949: starting parser threads
33.574878392: do_parse() in <flent.runners.PingRunner object at 0x11b375790> (66319)
33.575093309: do_parse() in <flent.runners.IrttRunner object at 0x11b375b80> (66319)
33.575163188: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b375dc0> (66319)
33.575209672: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b375ee0> (66319)
33.575247797: do_parse() in <flent.runners.IrttRunner object at 0x11b395220> (66319)
33.575274681: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b395370> (66319)
33.575297857: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b3954f0> (66319)
33.57532709: do_parse() in <flent.runners.IrttRunner object at 0x11b3957c0> (66319)
33.575352237: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b395910> (66319)
33.575373727: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b395a90> (66319)
33.575399791: do_parse() in <flent.runners.IrttRunner object at 0x11b395d60> (66319)
33.575428811: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b395eb0> (66319)
33.575462018: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b384070> (66319)
33.575492073: do_parse() in <flent.runners.IrttRunner object at 0x11b384340> (66319)
33.57620759: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b384490> (66319)
33.576243525: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b384610> (66319)
33.576275103: do_parse() in <flent.runners.IrttRunner object at 0x11b3848e0> (66319)
33.57630428: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b384a30> (66319)
33.5763282: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b384bb0> (66319)
33.575811732: 66319: Pickling <flent.runners.PingRunner object at 0x11b375790>
33.57668702: do_parse() in <flent.runners.IrttRunner object at 0x11b384e80> (66319)
33.578566446: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b384fd0> (66319)
33.578604895: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b392190> (66319)
33.578645366: do_parse() in <flent.runners.IrttRunner object at 0x11b392460> (66319)
33.578674631: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b3925b0> (66319)
33.578704765: do_parse() in <flent.runners.NetperfDemoRunner object at 0x11b392730> (66319)
33.578735611: do_parse() in <flent.runners.PingRunner object at 0x11b3928b0> (66319)
33.578757703: closing pool
33.578870691: joining pool
33.58340809: 66319: Pickling <flent.runners.IrttRunner object at 0x11b375b80>
33.587146775: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b375dc0>
33.587563155: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b375ee0>
33.587943052: 66319: Pickling <flent.runners.IrttRunner object at 0x11b395220>
33.588349494: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b395370>
0.122772515: 66380: Set queue handler
33.67658124: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b3954f0>
0.119865461: 66381: Set queue handler
33.677312042: 66319: Pickling <flent.runners.IrttRunner object at 0x11b3957c0>
0.122095644: 66382: Set queue handler
33.684257742: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b395910>
0.121474258: 66384: Set queue handler
33.69406858: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b395a90>
0.128572571: 66383: Set queue handler
33.696418424: 66319: Pickling <flent.runners.IrttRunner object at 0x11b395d60>
0.12896929: 66385: Set queue handler
33.707788595: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b395eb0>
0.12577863: 66386: Set queue handler
33.713148099: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b384070>
0.126808817: 66387: Set queue handler
33.716333104: 66319: Pickling <flent.runners.IrttRunner object at 0x11b384340>
34.319190552: getting log msg
34.319596522: getting log msg
34.320092583: getting log msg
34.320472323: getting log msg
34.321032536: getting log msg
34.332954232: getting log msg
34.333779592: getting log msg
34.337979456: getting log msg
34.338504685: getting log msg
34.338873465: getting log msg
34.339247719: getting log msg
34.339634849: getting log msg
34.340689233: getting log msg
34.341884338: getting log msg
34.342752918: getting log msg
34.343608019: getting log msg
34.343989257: getting log msg
34.344428296: getting log msg
34.344973663: getting log msg
34.345389424: getting log msg
34.345960879: getting log msg
34.34673682: getting log msg
34.347494463: getting log msg
34.347885832: getting log msg
34.348259083: getting log msg
34.348627761: getting log msg
34.349016253: getting log msg
34.349380631: getting log msg
34.349750693: getting log msg
34.350496602: getting log msg
34.350877879: getting log msg
0.794076314: 66381: Unpickling <flent.runners.IrttRunner object at 0x10aee8b80>
34.351654379: getting log msg
0.784757986: 66383: Unpickling <flent.runners.IrttRunner object at 0x104b9bb80>
34.352550987: getting log msg
34.353297044: getting log msg
0.791600286: 66382: Unpickling <flent.runners.NetperfDemoRunner object at 0x10da8bb80>
0.796660495: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10aee8b80> (66381) 12/13
0.786766935: print: Running in parse_output in <flent.runners.IrttRunner object at 0x104b9bb80> (66383) 12/13
0.79668751: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10aee8b80> (66381) 12/13
34.354882651: getting log msg
0.786798635: log: Running in parse_output in <flent.runners.IrttRunner object at 0x104b9bb80> (66383) 12/13
34.355476209: getting log msg
0.802712353: 66380: Unpickling <flent.runners.PingRunner object at 0x1084acb80>
0.804144913: print: Running in parse_output in <flent.runners.PingRunner object at 0x1084acb80> (66380) 12/13
0.80417673: log: Running in parse_output in <flent.runners.PingRunner object at 0x1084acb80> (66380) 12/13
34.358488214: getting log msg
34.359143541: getting log msg
34.359475252: getting log msg
34.360011384: getting log msg
34.361249213: getting log msg
0.810162687: Finished parse_output() in <flent.runners.PingRunner object at 0x1084acb80> (66380)
0.811653325: 66380: Unpickling <flent.runners.NetperfDemoRunner object at 0x1084acb50>
0.785146415: 66384: Unpickling <flent.runners.NetperfDemoRunner object at 0x1095e4b80>
34.36793695: recv_result() in <flent.runners.PingRunner object at 0x11b375790> (66319)
34.368068956: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b384490>
34.369079133: getting log msg
0.791446026: 66385: Unpickling <flent.runners.NetperfDemoRunner object at 0x10fe7eb80>
34.370353271: getting log msg
0.816764753: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1084acb50> (66380) 12/13
0.816856037: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1084acb50> (66380) 12/13
34.371170538: getting log msg
0.799054915: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1095e4b80> (66384) 12/13
0.799245073: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1095e4b80> (66384) 12/13
34.37233686: getting log msg
34.372673976: getting log msg
34.373063318: getting log msg
0.805441692: Finished parse_output() in <flent.runners.IrttRunner object at 0x104b9bb80> (66383)
0.819747658: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1084acb50> (66380)
34.373461504: getting log msg
34.373895841: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b395910> (66319)
0.820481559: 66380: Unpickling <flent.runners.NetperfDemoRunner object at 0x1084acb80>
0.81702921: Finished parse_output() in <flent.runners.IrttRunner object at 0x10aee8b80> (66381)
34.373985561: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b384610>
0.807552913: 66383: Unpickling <flent.runners.IrttRunner object at 0x104b9bb50>
34.37627859: recv_result() in <flent.runners.IrttRunner object at 0x11b395220> (66319)
0.820003913: 66381: Unpickling <flent.runners.NetperfDemoRunner object at 0x10aee8b50>
0.805155477: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1095e4b80> (66384)
34.377670505: recv_result() in <flent.runners.IrttRunner object at 0x11b375b80> (66319)
34.377893659: 66319: Pickling <flent.runners.IrttRunner object at 0x11b3848e0>
34.378559987: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b384a30>
34.37861435: getting log msg
0.806419675: 66384: Unpickling <flent.runners.NetperfDemoRunner object at 0x1095e4b50>
34.379346902: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b384bb0>
34.380253509: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b375ee0> (66319)
34.380980672: getting log msg
34.381492158: getting log msg
34.382240949: getting log msg
0.793276211: 66387: Unpickling <flent.runners.IrttRunner object at 0x10ecf5b80>
34.384125664: getting log msg
0.799139521: 66386: Unpickling <flent.runners.NetperfDemoRunner object at 0x10330eb80>
0.797177643: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387) 12/13
0.797297474: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387) 12/13
34.388135109: getting log msg
0.801422905: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10330eb80> (66386) 12/13
0.801476627: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10330eb80> (66386) 12/13
34.389932007: getting log msg
0.805512208: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10330eb80> (66386)
0.806255444: 66386: Unpickling <flent.runners.IrttRunner object at 0x10330eb50>
34.393484858: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b3954f0> (66319)
34.393574163: 66319: Pickling <flent.runners.IrttRunner object at 0x11b384e80>
0.808270454: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10330eb50> (66386) 12/13
0.808320861: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10330eb50> (66386) 12/13
34.396416779: getting log msg
0.818403543: Finished parse_output() in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387)
0.820153292: 66387: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ecf5b50>
34.409877804: recv_result() in <flent.runners.IrttRunner object at 0x11b3957c0> (66319)
34.410044789: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b384fd0>
0.824528518: Finished parse_output() in <flent.runners.IrttRunner object at 0x10330eb50> (66386)
0.822932949: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387) 12/13
0.826355793: 66386: Unpickling <flent.runners.NetperfDemoRunner object at 0x10330eb80>
34.414014428: recv_result() in <flent.runners.IrttRunner object at 0x11b384340> (66319)
0.822994417: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387) 12/13
34.414366328: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b392190>
0.825587735: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387)
34.415602934: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b384490> (66319)
0.826391367: 66387: Unpickling <flent.runners.IrttRunner object at 0x10ecf5b80>
34.415791425: 66319: Pickling <flent.runners.IrttRunner object at 0x11b392460>
34.416444313: getting log msg
0.828579707: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387) 12/13
0.828612814: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387) 12/13
34.418786712: getting log msg
0.843502555: Finished parse_output() in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387)
0.848247144: 66387: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ecf5b50>
34.437753705: recv_result() in <flent.runners.IrttRunner object at 0x11b3848e0> (66319)
34.438022352: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b3925b0>
0.851391966: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387) 12/13
0.8514343: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387) 12/13
34.44182389: getting log msg
0.853665472: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387)
34.444096088: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b384a30> (66319)
34.444309212: 66319: Pickling <flent.runners.NetperfDemoRunner object at 0x11b392730>
0.855333121: 66387: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ecf5b80>
0.856892564: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387) 12/13
0.856935731: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387) 12/13
34.447320901: getting log msg
0.86025918: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387)
0.861031369: 66387: Unpickling <flent.runners.IrttRunner object at 0x10ecf5b50>
34.450494005: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b384bb0> (66319)
34.450757347: 66319: Pickling <flent.runners.PingRunner object at 0x11b3928b0>
0.863247497: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10ecf5b50> (66387) 12/13
0.863326875: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10ecf5b50> (66387) 12/13
34.454533838: getting log msg
0.887265208: Finished parse_output() in <flent.runners.IrttRunner object at 0x10ecf5b50> (66387)
0.889092019: 66387: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ecf5b80>
34.478933548: recv_result() in <flent.runners.IrttRunner object at 0x11b384e80> (66319)
0.891090791: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387) 12/13
0.891124504: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387) 12/13
0.894523583: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387)
34.484885725: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b384fd0> (66319)
0.895802654: 66387: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ecf5b50>
34.487354045: getting log msg
0.898364885: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387) 12/13
0.898409: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387) 12/13
34.488846983: getting log msg
0.901872021: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387)
34.492064893: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b392190> (66319)
0.902839676: 66387: Unpickling <flent.runners.IrttRunner object at 0x10ecf5b80>
0.903995868: print: Running in parse_output in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387) 12/13
0.904029345: log: Running in parse_output in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387) 12/13
34.49412575: getting log msg
0.919961744: Finished parse_output() in <flent.runners.IrttRunner object at 0x10ecf5b80> (66387)
0.931168958: 66387: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ecf5b50>
34.520602582: recv_result() in <flent.runners.IrttRunner object at 0x11b392460> (66319)
0.933129159: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387) 12/13
0.933184174: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387) 12/13
34.523363729: getting log msg
0.936367318: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ecf5b50> (66387)
0.937137484: 66387: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ecf5b80>
34.526553518: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b3925b0> (66319)
0.938307767: print: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387) 12/13
0.938336471: log: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387) 12/13
34.528360409: getting log msg
0.941525787: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ecf5b80> (66387)
0.942374074: 66387: Unpickling <flent.runners.PingRunner object at 0x10ecf5b50>
34.531862685: recv_result() in <flent.runners.NetperfDemoRunner object at 0x11b392730> (66319)
0.945454531: print: Running in parse_output in <flent.runners.PingRunner object at 0x10ecf5b50> (66387) 12/13
0.945534772: log: Running in parse_output in <flent.runners.PingRunner object at 0x10ecf5b50> (66387) 12/13
34.536396273: getting log msg
0.951334095: Finished parse_output() in <flent.runners.PingRunner object at 0x10ecf5b50> (66387)
34.542763893: recv_result() in <flent.runners.PingRunner object at 0x11b3928b0> (66319)
0.115585459: 66396: Set queue handler
0.108763832: 66397: Set queue handler
0.105953605: 66398: Set queue handler
0.099126861: 66400: Set queue handler
0.10645776: 66399: Set queue handler
0.092179971: 66402: Set queue handler
0.102266606: 66401: Set queue handler
tohojo commented 2 years ago

Ah, seems you can also make the multiprocessing module output some debug logging; try again?

moeller0 commented 2 years ago 
bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Mon Jul  4 17:52:39 CEST 2022
Starting Flent 2.0.1-git-ab96c18 using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
[INFO/SyncManager-1] child process calling self.run()
[INFO/SyncManager-1] created temp directory /var/folders/gw/g72dl4fn4sdgx5xwctkv82zjzjww9p/T/pymp-upelmhb4
[INFO/SyncManager-1] manager serving at '/var/folders/gw/g72dl4fn4sdgx5xwctkv82zjzjww9p/T/pymp-upelmhb4/listener-icirzfqd'
[DEBUG/MainProcess] requesting creation of a shared 'Queue' object
[DEBUG/SyncManager-1] 'Queue' callable returned object with id '109826fd0'
[DEBUG/MainProcess] INCREF '109826fd0'
[DEBUG/MainProcess] created semlock with handle 64
[DEBUG/MainProcess] created semlock with handle 65
[DEBUG/MainProcess] created semlock with handle 69
[DEBUG/MainProcess] created semlock with handle 70
[DEBUG/MainProcess] created semlock with handle 73
[DEBUG/MainProcess] created semlock with handle 74
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
33.602625403: starting log reader thread
33.602950318: running log reader
33.603014191: getting log msg
[DEBUG/MainProcess] thread 'Thread-30' does not own a connection
[DEBUG/MainProcess] making connection to manager
33.602994036: starting parser threads
33.603582855: 66608: do_parse() in <flent.runners.PingRunner object at 0x109188d30>
33.603731279: 66608: do_parse() in <flent.runners.IrttRunner object at 0x109188940>
33.604255074: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x109188700>
33.60436679: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x1091885e0>
33.604409282: 66608: do_parse() in <flent.runners.IrttRunner object at 0x109188490>
33.604438929: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10917a160>
33.60446217: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10917a2e0>
33.604485812: 66608: do_parse() in <flent.runners.IrttRunner object at 0x10917a5b0>
33.604506347: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10917a700>
33.604527814: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10917a880>
33.604550113: 66608: do_parse() in <flent.runners.IrttRunner object at 0x10917ab50>
33.604575832: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10917aca0>
33.604605111: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10917ae20>
33.604747492: 66608: do_parse() in [DEBUG/SyncManager-1] starting server thread to service 'MainProcess|Thread-30'
<flent.runners.IrttRunner object at 0x10918a130>
33.604005342: 66608: Pickling <flent.runners.PingRunner object at 0x109188d30>
33.641245718: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10918a280>
33.641777699: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10918a400>
33.641827097: 66608: do_parse() in <flent.runners.IrttRunner object at 0x10918a6d0>
33.641859007: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10918a820>
33.641894267: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10918a9a0>
33.641924141: 66608: do_parse() in <flent.runners.IrttRunner object at 0x10918ac70>
33.641950171: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10918adc0>
33.64197696: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x10918af40>
33.642021719: 66608: do_parse() in <flent.runners.IrttRunner object at 0x109195250>
33.642053514: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x1091953a0>
33.642085772: 66608: do_parse() in <flent.runners.NetperfDemoRunner object at 0x109195520>
33.642122464: 66608: do_parse() in <flent.runners.PingRunner object at 0x1091956a0>
33.642165881: closing pool
[DEBUG/MainProcess] closing pool
33.642451855: joining pool
[DEBUG/MainProcess] joining pool
[DEBUG/MainProcess] starting listener and thread for sending handles
[INFO/MainProcess] created temp directory /var/folders/gw/g72dl4fn4sdgx5xwctkv82zjzjww9p/T/pymp-ct5h_gtv
33.646874481: 66608: Pickling <flent.runners.IrttRunner object at 0x109188940>
33.647505862: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x109188700>
33.647967829: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x1091885e0>
33.648361548: 66608: Pickling <flent.runners.IrttRunner object at 0x109188490>
33.648759258: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10917a160>
[DEBUG/SpawnPoolWorker-3] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-3] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-3] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-3] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-3] INCREF '109826fd0'
[INFO/SpawnPoolWorker-3] child process calling self.run()
0.201833234: 66664: Set queue handler
33.774296651: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10917a2e0>
[DEBUG/SpawnPoolWorker-2] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-2] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-2] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-2] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-4] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-4] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-4] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-4] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-4] INCREF '109826fd0'
[INFO/SpawnPoolWorker-4] child process calling self.run()
0.232765873: 66665: Set queue handler
33.81789327: 66608: Pickling <flent.runners.IrttRunner object at 0x10917a5b0>
[DEBUG/SpawnPoolWorker-5] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-5] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-5] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-5] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-2] INCREF '109826fd0'
[INFO/SpawnPoolWorker-2] child process calling self.run()
0.25698579: 66663: Set queue handler
33.824642925: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10917a700>
[DEBUG/SpawnPoolWorker-9] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-9] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-9] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-9] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-6] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-6] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-6] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-6] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-7] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-7] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-7] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-7] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-8] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-8] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-9] INCREF '109826fd0'
[INFO/SpawnPoolWorker-9] child process calling self.run()
[DEBUG/SpawnPoolWorker-8] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-8] recreated blocker with handle 70
0.24710228: 66670: Set queue handler
33.870167306: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10917a880>
[DEBUG/SpawnPoolWorker-5] INCREF '109826fd0'
[INFO/SpawnPoolWorker-5] child process calling self.run()
0.276767477: 66666: Set queue handler
33.877021495: 66608: Pickling <flent.runners.IrttRunner object at 0x10917ab50>
[DEBUG/SpawnPoolWorker-7] INCREF '109826fd0'
[INFO/SpawnPoolWorker-7] child process calling self.run()
0.280102926: 66668: Set queue handler
33.889966571: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10917aca0>
[DEBUG/SpawnPoolWorker-6] INCREF '109826fd0'
[INFO/SpawnPoolWorker-6] child process calling self.run()
0.282472676: 66667: Set queue handler
33.892073048: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10917ae20>
[DEBUG/SpawnPoolWorker-8] INCREF '109826fd0'
[INFO/SpawnPoolWorker-8] child process calling self.run()
0.275822604: 66669: Set queue handler
33.894847607: 66608: Pickling <flent.runners.IrttRunner object at 0x10918a130>
[DEBUG/SpawnPoolWorker-3] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-3] making connection to manager
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-3'
34.971675848: getting log msg
[DEBUG/SpawnPoolWorker-4] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-4] making connection to manager
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-4'
34.975911516: getting log msg
[DEBUG/SpawnPoolWorker-2] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-2] making connection to manager
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-2'
34.991102018: getting log msg
34.999617374: getting log msg
35.003090253: getting log msg
[DEBUG/SpawnPoolWorker-5] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-5] making connection to manager
35.004416228: getting log msg
35.005208471: getting log msg
35.005879808: getting log msg
35.006782034: getting log msg
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-5'
35.007746798: getting log msg
35.008257426: getting log msg
35.008778523: getting log msg
35.009214086: getting log msg
35.010100976: getting log msg
[DEBUG/SpawnPoolWorker-9] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-9] making connection to manager
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-9'
35.017781433: getting log msg
35.018393763: getting log msg
1.447077417: 66664: Unpickling <flent.runners.PingRunner object at 0x10545eee0>
1.451333237: 66664: Running in parse_output in <flent.runners.PingRunner object at 0x10545eee0> 12/13
35.024830523: getting log msg
35.025760456: getting log msg
1.433733652: 66665: Unpickling <flent.runners.IrttRunner object at 0x10a382ee0>
35.030811103: getting log msg
1.458696836: 66664: Finished parse_output() in <flent.runners.PingRunner object at 0x10545eee0>
35.032062941: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10918a280>
1.460184151: 66664: Unpickling <flent.runners.NetperfDemoRunner object at 0x10545e310>
35.032747124: getting log msg
35.033868462: 66608: recv_result() in <flent.runners.PingRunner object at 0x109188d30>
1.463396243: 66664: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10545e310> 12/13
[DEBUG/SpawnPoolWorker-8] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-8] making connection to manager
1.467286679: 66664: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10545e310>
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-8'
1.468259943: 66664: Unpickling <flent.runners.NetperfDemoRunner object at 0x10545eee0>
35.043629399: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10917a700>
35.044250348: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10918a400>
35.045272883: getting log msg
35.045965168: getting log msg
35.046428742: getting log msg
35.04740397: getting log msg
35.047960576: getting log msg
35.048385525: getting log msg
35.049394621: getting log msg
[DEBUG/SpawnPoolWorker-7] thread 'MainThread' does not own a connection
35.049973142: getting log msg
[DEBUG/SpawnPoolWorker-7] making connection to manager
35.050498938: getting log msg
1.466957423: 66665: Running in parse_output in <flent.runners.IrttRunner object at 0x10a382ee0> 12/13
35.051083107: getting log msg
1.479273304: 66664: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10545eee0> 12/13
35.052042631: getting log msg
1.483794663: 66664: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10545eee0>
35.056639796: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10917a880>
35.056774429: 66608: Pickling <flent.runners.IrttRunner object at 0x10918a6d0>
1.484736759: 66664: Unpickling <flent.runners.IrttRunner object at 0x10545e310>
1.458899023: 66666: Unpickling <flent.runners.IrttRunner object at 0x10efceee0>
1.486636565: 66664: Running in parse_output in <flent.runners.IrttRunner object at 0x10545e310> 12/13
1.46051427: 66666: Running in parse_output in <flent.runners.IrttRunner object at 0x10efceee0> 12/13
1.437850033: 66670: Unpickling <flent.runners.NetperfDemoRunner object at 0x10f6f6ee0>
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-7'
35.062234781: getting log msg
1.439785585: 66670: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f6f6ee0> 12/13
1.496677311: 66663: Unpickling <flent.runners.NetperfDemoRunner object at 0x105ea6ee0>
1.444023831: 66670: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10f6f6ee0>
35.067315411: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x1091885e0>
35.067411825: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10918a820>
1.445245435: 66670: Unpickling <flent.runners.NetperfDemoRunner object at 0x10f6f6310>
35.069305693: getting log msg
[DEBUG/SpawnPoolWorker-6] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-6] making connection to manager
1.509220136: 66663: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x105ea6ee0> 12/13
35.077184145: getting log msg
1.454929722: 66670: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f6f6310> 12/13
35.077836952: getting log msg
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-6'
35.07870997: getting log msg
1.456962363: 66670: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10f6f6310>
35.079867157: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10917aca0>
35.079979296: getting log msg
35.080146684: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10918a9a0>
1.457905144: 66670: Unpickling <flent.runners.NetperfDemoRunner object at 0x10f6f6ee0>
35.08164413: getting log msg
1.517193254: 66663: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x105ea6ee0>
1.485228988: 66666: Finished parse_output() in <flent.runners.IrttRunner object at 0x10efceee0>
35.085208349: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x109188700>
1.518089787: 66663: Unpickling <flent.runners.IrttRunner object at 0x105ea6310>
35.085359793: 66608: Pickling <flent.runners.IrttRunner object at 0x10918ac70>
1.522644867: 66663: Running in parse_output in <flent.runners.IrttRunner object at 0x105ea6310> 12/13
1.510163842: 66665: Finished parse_output() in <flent.runners.IrttRunner object at 0x10a382ee0>
35.101553199: 66608: recv_result() in <flent.runners.IrttRunner object at 0x109188940>
1.517757368: 66665: Unpickling <flent.runners.NetperfDemoRunner object at 0x10a382310>
35.101710024: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10918adc0>
1.484729273: 66669: Unpickling <flent.runners.IrttRunner object at 0x10663fee0>
1.482306457: 66670: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10f6f6ee0> 12/13
1.521086618: 66665: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10a382310> 12/13
1.524167028: 66665: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10a382310>
35.10865677: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10918a280>
35.108798845: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x10918af40>
1.525368187: 66665: Unpickling <flent.runners.NetperfDemoRunner object at 0x10a382ee0>
1.490933147: 66669: Running in parse_output in <flent.runners.IrttRunner object at 0x10663fee0> 12/13
1.527037039: 66665: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10a382ee0> 12/13
1.530999084: 66665: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10a382ee0>
35.115782055: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10918a400>
1.548867405: 66663: Finished parse_output() in <flent.runners.IrttRunner object at 0x105ea6310>
35.116499173: 66608: Pickling <flent.runners.IrttRunner object at 0x109195250>
1.533544612: 66665: Unpickling <flent.runners.IrttRunner object at 0x10a382310>
35.119573308: getting log msg
35.121970246: 66608: recv_result() in <flent.runners.IrttRunner object at 0x10918a130>
35.122315955: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x1091953a0>
1.55628876: 66663: Unpickling <flent.runners.NetperfDemoRunner object at 0x105ea6ee0>
1.542665591: 66665: Running in parse_output in <flent.runners.IrttRunner object at 0x10a382310> 12/13
35.127153978: getting log msg
1.560074224: 66663: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x105ea6ee0> 12/13
35.127648027: getting log msg
35.128168811: getting log msg
35.12858477: getting log msg
35.129765159: getting log msg
1.563679978: 66663: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x105ea6ee0>
1.510348943: 66670: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10f6f6ee0>
1.566423215: 66663: Unpickling <flent.runners.NetperfDemoRunner object at 0x105ea6310>
1.511831518: 66670: Unpickling <flent.runners.IrttRunner object at 0x10f6f6310>
35.134340375: 66608: recv_result() in <flent.runners.IrttRunner object at 0x109188490>
35.134698291: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10918a820>
35.135194316: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10917ae20>
1.535693821: 66666: Unpickling <flent.runners.NetperfDemoRunner object at 0x10efce310>
35.135672769: 66608: Pickling <flent.runners.NetperfDemoRunner object at 0x109195520>
35.136259654: 66608: Pickling <flent.runners.PingRunner object at 0x1091956a0>
35.138206915: getting log msg
1.566450379: 66664: Finished parse_output() in <flent.runners.IrttRunner object at 0x10545e310>
35.138923457: getting log msg
35.139445578: getting log msg
1.521309242: 66669: Finished parse_output() in <flent.runners.IrttRunner object at 0x10663fee0>
35.14079735: getting log msg
35.146663176: 66608: recv_result() in <flent.runners.IrttRunner object at 0x10917a5b0>
1.580858981: 66663: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x105ea6310> 12/13
1.529574569: 66669: Unpickling <flent.runners.NetperfDemoRunner object at 0x10663f310>
[DEBUG/SpawnPoolWorker-5] worker got EOFError or OSError -- exiting
[DEBUG/SpawnPoolWorker-5] worker exiting after 1 tasks
[INFO/SpawnPoolWorker-5] process shutting down
1.52670071: 66670: Running in parse_output in <flent.runners.IrttRunner object at 0x10f6f6310> 12/13
[DEBUG/SpawnPoolWorker-5] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-5] DECREF '109826fd0'
1.578700212: 66664: Unpickling <flent.runners.IrttRunner object at 0x10545eee0>
[DEBUG/SpawnPoolWorker-5] thread 'MainThread' has no more proxies so closing conn
35.151731855: 66608: recv_result() in <flent.runners.IrttRunner object at 0x10917ab50>
[DEBUG/SpawnPoolWorker-5] running the remaining "atexit" finalizers
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-5'
1.584834445: 66663: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x105ea6310>
[INFO/SpawnPoolWorker-5] process exiting with exitcode 0
1.533856493: 66669: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10663f310> 12/13
35.153148879: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10918a9a0>
1.585966341: 66663: Unpickling <flent.runners.NetperfDemoRunner object at 0x105ea6ee0>
[DEBUG/SpawnPoolWorker-2] worker got EOFError or OSError -- exiting
[DEBUG/SpawnPoolWorker-2] worker exiting after 4 tasks
[INFO/SpawnPoolWorker-2] process shutting down
[DEBUG/SpawnPoolWorker-2] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-2] DECREF '109826fd0'
[DEBUG/SpawnPoolWorker-2] thread 'MainThread' has no more proxies so closing conn
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-2'
[DEBUG/SpawnPoolWorker-2] running the remaining "atexit" finalizers
[INFO/SpawnPoolWorker-2] process exiting with exitcode 0
1.583676278: 66664: Running in parse_output in <flent.runners.IrttRunner object at 0x10545eee0> 12/13
1.537944485: 66669: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10663f310>
35.157570007: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10918af40>
1.538898245: 66669: Unpickling <flent.runners.NetperfDemoRunner object at 0x10663fee0>
1.549224364: 66668: Unpickling <flent.runners.NetperfDemoRunner object at 0x10b838ee0>
1.540442246: 66669: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10663fee0> 12/13
1.547265159: 66669: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10663fee0>
1.582532258: 66665: Finished parse_output() in <flent.runners.IrttRunner object at 0x10a382310>
35.166957026: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x109195520>
1.548388176: 66669: Unpickling <flent.runners.PingRunner object at 0x10663f310>
1.555139647: 66669: Running in parse_output in <flent.runners.PingRunner object at 0x10663f310> 12/13
1.566739341: 66668: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10b838ee0> 12/13
1.567175148: 66667: Unpickling <flent.runners.NetperfDemoRunner object at 0x1058b1ee0>
1.571318058: 66667: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x1058b1ee0> 12/13
1.561992694: 66669: Finished parse_output() in <flent.runners.PingRunner object at 0x10663f310>
1.571686174: 66668: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10b838ee0>
35.182978882: 66608: recv_result() in <flent.runners.IrttRunner object at 0x10918a6d0>
1.611022904: 66664: Finished parse_output() in <flent.runners.IrttRunner object at 0x10545eee0>
35.184146453: 66608: recv_result() in <flent.runners.PingRunner object at 0x1091956a0>
35.184575351: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10917a160>
1.575366708: 66667: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x1058b1ee0>
1.56326474: 66670: Finished parse_output() in <flent.runners.IrttRunner object at 0x10f6f6310>
35.186335587: 66608: recv_result() in <flent.runners.IrttRunner object at 0x109195250>
35.186955179: 66608: recv_result() in <flent.runners.NetperfDemoRunner object at 0x10917a2e0>
35.190080624: 66608: recv_result() in <flent.runners.IrttRunner object at 0x10918ac70>
[DEBUG/MainProcess] cleaning up worker 0
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] cleaning up worker 2
[DEBUG/MainProcess] added worker
[DEBUG/SpawnPoolWorker-10] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-10] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-10] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-10] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-11] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-11] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-11] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-11] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-10] INCREF '109826fd0'
[INFO/SpawnPoolWorker-10] child process calling self.run()
0.086725664: 66679: Set queue handler
[DEBUG/SpawnPoolWorker-11] INCREF '109826fd0'
[INFO/SpawnPoolWorker-11] child process calling self.run()
0.085486012: 66680: Set queue handler
^C[INFO/SpawnPoolWorker-8] process shutting down
[INFO/SpawnPoolWorker-9] process shutting down
[INFO/SpawnPoolWorker-10] process shutting down
[INFO/SpawnPoolWorker-11] process shutting down
[DEBUG/SpawnPoolWorker-9] running all "atexit" finalizers with priority >= 0
[DEBUG/MainProcess] terminating pool
[DEBUG/SpawnPoolWorker-10] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-11] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-9] DECREF '109826fd0'
[DEBUG/MainProcess] finalizing pool
[INFO/SpawnPoolWorker-7] process shutting down
[INFO/SpawnPoolWorker-6] process shutting down
[DEBUG/SpawnPoolWorker-10] DECREF '109826fd0'
[INFO/SpawnPoolWorker-4] process shutting down
[DEBUG/SpawnPoolWorker-11] DECREF '109826fd0'
[DEBUG/SpawnPoolWorker-7] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-6] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-4] running all "atexit" finalizers with priority >= 0
[[DEBUG/SpawnPoolWorker-4] DECREF '109826fd0'
[DEBUG/SpawnPoolWorker-8] running all "atexit" finalizers with priority >= 0
DEBUG/SpawnPoolWorker-7] DECREF '109826fd0'
[DEBUG/SpawnPoolWorker-6] DECREF '109826fd0'
[INFO/SpawnPoolWorker-3] process shutting down
[DEBUG/SpawnPoolWorker-8] DECREF '109826fd0'
[DEBUG/SpawnPoolWorker-3] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-3] DECREF '109826fd0'
[DEBUG/MainProcess] helping task handler/workers to finish
[DEBUG/MainProcess] removing tasks from inqueue until task handler finished
[DEBUG/SpawnPoolWorker-9] thread 'MainThread' has no more proxies so closing conn
[DEBUG/SpawnPoolWorker-11] running the remaining "atexit" finalizers
[DEBUG/MainProcess] worker handler exiting
[DEBUG/SpawnPoolWorker-9] running the remaining "atexit" finalizers
Process SpawnPoolWorker-11:
Process SpawnPoolWorker-9:
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-9'
[DEBUG/MainProcess] task handler got sentinel
[DEBUG/MainProcess] joining worker handler
[DEBUG/MainProcess] task handler sending sentinel to result handler
[DEBUG/SpawnPoolWorker-10] running the remaining "atexit" finalizers
Process SpawnPoolWorker-10:
[DEBUG/MainProcess] result handler found thread._state=TERMINATE
[DEBUG/MainProcess] terminating workers
[DEBUG/MainProcess] task handler sending sentinel to workers
[DEBUG/MainProcess] task handler exiting
[DEBUG/MainProcess] ensuring that outqueue is not full
[DEBUG/MainProcess] joining task handler
[DEBUG/MainProcess] joining result handler
[DEBUG/MainProcess] result handler exiting: len(cache)=2, thread._state=TERMINATE
[DEBUG/MainProcess] joining pool workers
[DEBUG/MainProcess] cleaning up worker 66664
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-4'
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-7'
[DEBUG/MainProcess] cleaning up worker 66667
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-3'
[DEBUG/MainProcess] cleaning up worker 66669
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-6'
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 202, in handle_request\n    connection.deliver_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 745, in deliver_challenge\n    response = connection.recv_bytes(256)        # reject large message\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes\n    buf = self._recv_bytes(maxlength)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes\n    buf = self._recv(4)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 388, in _recv\n    raise EOFError\nEOFError\n')
[INFO/SyncManager-1]  ... request was None
[INFO/MainProcess] sending shutdown message to manager
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-8'
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 202, in handle_request\n    connection.deliver_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 745, in deliver_challenge\n    response = connection.recv_bytes(256)        # reject large message\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes\n    buf = self._recv_bytes(maxlength)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes\n    buf = self._recv(4)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 388, in _recv\n    raise EOFError\nEOFError\n')
[INFO/SyncManager-1]  ... request was None
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 203, in handle_request\n    connection.answer_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 757, in answer_challenge\n    message = connection.recv_bytes(256)         # reject large message\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes\n    buf = self._recv_bytes(maxlength)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes\n    buf = self._recv(4)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 388, in _recv\n    raise EOFError\nEOFError\n')
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 202, in handle_request\n    connection.deliver_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 745, in deliver_challenge\n    response = connection.recv_bytes(256)        # reject large message\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes\n    buf = self._recv_bytes(maxlength)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes\n    buf = self._recv(4)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 388, in _recv\n    raise EOFError\nEOFError\n')
[INFO/SyncManager-1]  ... request was None
[INFO/SyncManager-1]  ... request was None
[DEBUG/SyncManager-1] manager received shutdown message
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[INFO/SyncManager-1] process shutting down
[DEBUG/SyncManager-1] running all "atexit" finalizers with priority >= 0
[DEBUG/SyncManager-1] running the remaining "atexit" finalizers
[INFO/SyncManager-1] process exiting with exitcode 0
48.737354403: EOF on reading log queue, exiting
/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/resource_tracker.py:216: UserWarning: resource_tracker: There appear to be 6 leaked semaphore objects to clean up at shutdown
  warnings.warn('resource_tracker: There appear to be %d '

This spewed more information after CTRL-C, hence I deleted the first stuck result an replaced with a new run including the post-CRTL-C output

tohojo commented 2 years ago

Right, ran out of time earlier; pushed some more changes + debugging, see how that goes?

moeller0 commented 2 years ago 
bash-3.2$ git pull
remote: Enumerating objects: 9, done.
remote: Counting objects: 100% (9/9), done.
remote: Compressing objects: 100% (2/2), done.
remote: Total 9 (delta 7), reused 9 (delta 7), pack-reused 0
Unpacking objects: 100% (9/9), 1.12 KiB | 67.00 KiB/s, done.
From https://github.com/tohojo/flent
   ab96c18..800a4a5  pickle-fix -> origin/pickle-fix
Updating ab96c18..800a4a5
Fast-forward
 flent/aggregators.py | 10 +++++++---
 flent/runners.py     | 16 ++++++++++------
 2 files changed, 17 insertions(+), 9 deletions(-)
bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Tue Jul  5 09:50:41 CEST 2022
Starting Flent 2.0.1-git-800a4a5 using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
[INFO/SyncManager-1] child process calling self.run()
[INFO/SyncManager-1] created temp directory /var/folders/gw/g72dl4fn4sdgx5xwctkv82zjzjww9p/T/pymp-ndg87x6k
[INFO/SyncManager-1] manager serving at '/var/folders/gw/g72dl4fn4sdgx5xwctkv82zjzjww9p/T/pymp-ndg87x6k/listener-l7u852ai'
[DEBUG/MainProcess] requesting creation of a shared 'Queue' object
[DEBUG/SyncManager-1] 'Queue' callable returned object with id '10b938fd0'
[DEBUG/MainProcess] INCREF '10b938fd0'
[DEBUG/MainProcess] created semlock with handle 64
[DEBUG/MainProcess] created semlock with handle 65
[DEBUG/MainProcess] created semlock with handle 69
[DEBUG/MainProcess] created semlock with handle 70
[DEBUG/MainProcess] created semlock with handle 73
[DEBUG/MainProcess] created semlock with handle 74
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
33.953464548: starting log reader thread
33.955797507: running log reader
33.955819802: getting log msg
[DEBUG/MainProcess] thread 'Thread-30' does not own a connection
[DEBUG/MainProcess] making connection to manager
33.957199576: starting parser threads
33.957369645: 72103: do_parse() in <flent.runners.PingRunner object at 0x114b45d60>
33.957609253: 72103: do_parse() in <flent.runners.IrttRunner object at 0x114b45670>
33.957648847: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b45280>
33.957679561: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b45160>
33.957703614: 72103: do_parse() in <flent.runners.IrttRunner object at 0x114b581f0>
33.957723455: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b58340>
33.957741836: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b584c0>
33.957762042: 72103: do_parse() in <flent.runners.IrttRunner object at 0x114b58790>
33.95778069: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b588e0>
33.957798408: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b58a60>
33.957821282: 72103: do_parse() in <flent.runners.IrttRunner object at 0x114b58d30>
33.957863902: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b58e80>
33.95788537: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b48040>
33.960059514: 72103: Pickling <flent.runners.PingRunner object at 0x114b45d60>
33.961400864: 72103: do_parse() in <flent.runners.IrttRunner object at 0x114b48310>
33.962685718: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b48460>
33.96272507: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b485e0>
33.962759454: 72103: do_parse() in <flent.runners.IrttRunner object at 0x114b488b0>
33.962790894: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b48a00>
33.962812787: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b48b80>
33.962835663: 72103: do_parse() in <flent.runners.IrttRunner object at 0x114b48e50>
33.962856552: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b48fa0>
33.962994763: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b64160>
33.963045248: 72103: do_parse() in <flent.runners.IrttRunner object at 0x114b64430>
33.963074716: 72103: do_parse() in <flent.runners.NetperfDemoRunner object at 0x114b64580>
33.963102086: 72103: do_parse() in <flent[DEBUG/MainProcess] starting listener and thread for sending handles
.runners.NetperfDemoRunner object at 0x114b64700>
33.965992741: 72103: do_parse() in <flent.runners.PingRunner object at 0x114b64880>
33.966031404: waiting for parsing result 1 of 26
[INFO/MainProcess] created temp directory /var/folders/gw/g72dl4fn4sdgx5xwctkv82zjzjww9p/T/pymp-13ovmtxc
[DEBUG/SyncManager-1] starting server thread to service 'MainProcess|Thread-30'
33.968190386: 72103: Pickling <flent.runners.IrttRunner object at 0x114b45670>
33.968603542: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b45280>
33.968956877: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b45160>
33.969302388: 72103: Pickling <flent.runners.IrttRunner object at 0x114b581f0>
33.969649678: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b58340>
[DEBUG/SpawnPoolWorker-2] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-2] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-2] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-2] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-3] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-3] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-3] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-3] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-4] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-4] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-4] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-4] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-2] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-2] child process calling self.run()
0.130781492: 72177: Set queue handler
34.050608776: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b584c0>
[DEBUG/SpawnPoolWorker-5] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-5] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-5] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-5] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-6] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-6] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-6] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-6] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-3] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-3] child process calling self.run()
[DEBUG/SpawnPoolWorker-4] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-4] child process calling self.run()
0.126549184: 72179: Set queue handler
0.131279651: 72178: Set queue handler
34.058739736: 72103: Pickling <flent.runners.IrttRunner object at 0x114b58790>
34.059290121: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b588e0>
[DEBUG/SpawnPoolWorker-7] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-7] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-7] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-7] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-5] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-5] child process calling self.run()
0.138190638: 72180: Set queue handler
34.078250262: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b58a60>
[DEBUG/SpawnPoolWorker-8] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-8] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-8] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-8] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-6] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-6] child process calling self.run()
0.13373826: 72181: Set queue handler
34.080635542: 72103: Pickling <flent.runners.IrttRunner object at 0x114b58d30>
[DEBUG/SpawnPoolWorker-9] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-9] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-9] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-9] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-8] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-8] child process calling self.run()
0.133440204: 72183: Set queue handler
34.098906873: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b58e80>
[DEBUG/SpawnPoolWorker-7] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-7] child process calling self.run()
0.143239665: 72182: Set queue handler
34.100293992: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b48040>
[DEBUG/SpawnPoolWorker-9] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-9] child process calling self.run()
0.135001659: 72184: Set queue handler
34.109454005: 72103: Pickling <flent.runners.IrttRunner object at 0x114b48310>
[DEBUG/SpawnPoolWorker-3] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-3] making connection to manager
[DEBUG/SpawnPoolWorker-6] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-6] making connection to manager
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-6'
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-3'
34.829417258: getting log msg
34.830174216: getting log msg
[DEBUG/SpawnPoolWorker-5] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-5] making connection to manager
[DEBUG/SpawnPoolWorker-4] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-4] making connection to manager
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-4'
34.838529447: getting log msg
[DEBUG/SpawnPoolWorker-2] thread 'MainThread' does not own a connection
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-5'
[DEBUG/SpawnPoolWorker-2] making connection to manager
34.839799414: getting log msg
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-2'
34.843681051: getting log msg
34.855311816: getting log msg
34.857131436: getting log msg
[DEBUG/SpawnPoolWorker-7] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-7] making connection to manager
34.85951896: getting log msg
34.859996677: getting log msg
34.860636212: getting log msg
34.861498817: getting log msg
34.862021023: getting log msg
34.862522014: getting log msg
34.863070527: getting log msg
34.86349617: getting log msg
34.864783227: getting log msg
34.866444041: getting log msg
34.866835008: getting log msg
34.867401296: getting log msg
34.868202973: getting log msg
34.869270854: getting log msg
0.92343193: 72181: Unpickling <flent.runners.IrttRunner object at 0x10ae43ee0>
34.873438707: getting log msg
[DEBUG/SpawnPoolWorker-8] thread 'MainThread' does not own a connection
0.927081914: 72181: Running in parse_output in <flent.runners.IrttRunner object at 0x10ae43ee0> 12/13
[DEBUG/SpawnPoolWorker-8] making connection to manager
34.874693767: getting log msg
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-8'
0.936083261: 72180: Unpickling <flent.runners.NetperfDemoRunner object at 0x109f14ee0>
34.87604514: getting log msg
34.87656881: getting log msg
34.877671419: getting log msg
34.87815253: getting log msg
0.938442679: 72180: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x109f14ee0> 12/13
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-7'
0.952517946: 72178: Unpickling <flent.runners.IrttRunner object at 0x10432bee0>
34.879915998: getting log msg
0.941387325: 72180: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x109f14ee0>
0.942125569: 72180: Unpickling <flent.runners.NetperfDemoRunner object at 0x109f14310>
34.882452316: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b45160>
34.882678573: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b48460>
34.883769569: getting log msg
34.884176366: getting log msg
34.884591502: getting log msg
34.885517201: getting log msg
0.959207747: 72178: Running in parse_output in <flent.runners.IrttRunner object at 0x10432bee0> 12/13
0.946945182: 72180: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x109f14310> 12/13
0.955259347: 72179: Unpickling <flent.runners.NetperfDemoRunner object at 0x100da4ee0>
0.956917458: 72179: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x100da4ee0> 12/13
0.949175065: 72180: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x109f14310>
34.889585199: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b588e0>
34.889711865: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b485e0>
0.949869139: 72180: Unpickling <flent.runners.NetperfDemoRunner object at 0x109f14ee0>
0.959007149: 72179: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x100da4ee0>
[DEBUG/SpawnPoolWorker-9] thread 'MainThread' does not own a connection
[DEBUG/SpawnPoolWorker-9] making connection to manager
0.959815541: 72179: Unpickling <flent.runners.IrttRunner object at 0x100da4310>
0.973851396: 72177: Unpickling <flent.runners.PingRunner object at 0x10ac56ee0>
[DEBUG/SpawnPoolWorker-2] worker got EOFError or OSError -- exiting
[DEBUG/SpawnPoolWorker-2] worker exiting after 0 tasks
[INFO/SpawnPoolWorker-2] process shutting down
[DEBUG/SpawnPoolWorker-2] running all "atexit" finalizers with priority >= 0
[DEBUG/SyncManager-1] starting server thread to service 'SpawnPoolWorker-9'
34.894623615: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b45280>
34.894966863: 72103: Pickling <flent.runners.IrttRunner object at 0x114b488b0>
0.955154082: 72180: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x109f14ee0> 12/13
[DEBUG/SpawnPoolWorker-2] DECREF '10b938fd0'
34.895833464: getting log msg
0.965406686: 72179: Running in parse_output in <flent.runners.IrttRunner object at 0x100da4310> 12/13
0.958313125: 72180: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x109f14ee0>
34.898921197: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b58a60>
34.899041355: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b48a00>
0.959195014: 72180: Unpickling <flent.runners.NetperfDemoRunner object at 0x109f14310>
34.900718607: getting log msg
0.961254593: 72180: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x109f14310> 12/13
[DEBUG/SpawnPoolWorker-2] thread 'MainThread' has no more proxies so closing conn
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-2'
[DEBUG/SpawnPoolWorker-2] running the remaining "atexit" finalizers
[INFO/SpawnPoolWorker-2] process exiting with exitcode 0
0.963455541: 72180: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x109f14310>
34.903882614: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b58e80>
0.964137531: 72180: Unpickling <flent.runners.NetperfDemoRunner object at 0x109f14ee0>
34.904026174: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b48b80>
34.90510457: getting log msg
34.905693263: getting log msg
0.959343186: 72181: Finished parse_output() in <flent.runners.IrttRunner object at 0x10ae43ee0>
34.906246609: getting log msg
0.966647688: 72180: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x109f14ee0> 12/13
34.906842811: getting log msg
34.907628621: getting log msg
0.981027212: 72178: Finished parse_output() in <flent.runners.IrttRunner object at 0x10432bee0>
0.969836635: 72180: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x109f14ee0>
34.909991881: 72103: recv_result() in <flent.runners.IrttRunner object at 0x114b581f0>
34.91019478: 72103: Pickling <flent.runners.IrttRunner object at 0x114b48e50>
0.963747454: 72181: Unpickling <flent.runners.IrttRunner object at 0x10ae43310>
34.912279841: 72103: recv_result() in <flent.runners.IrttRunner object at 0x114b45670>
34.912594795: getting log msg
34.912760922: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b48fa0>
0.973176057: 72180: Unpickling <flent.runners.NetperfDemoRunner object at 0x109f14310>
34.913296484: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b48040>
34.913958703: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b64160>
0.987292757: 72178: Unpickling <flent.runners.NetperfDemoRunner object at 0x10432b310>
34.914643348: getting log msg
[DEBUG/SpawnPoolWorker-3] worker got EOFError or OSError -- exiting
34.915072959: getting log msg
34.915854613: getting log msg
[DEBUG/SpawnPoolWorker-3] worker exiting after 1 tasks
[INFO/SpawnPoolWorker-3] process shutting down
[DEBUG/SpawnPoolWorker-3] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-3] DECREF '10b938fd0'
0.95128179: 72183: Unpickling <flent.runners.NetperfDemoRunner object at 0x10d02bee0>
[DEBUG/SpawnPoolWorker-8] worker got EOFError or OSError -- exiting
[DEBUG/SpawnPoolWorker-8] worker exiting after 0 tasks
[INFO/SpawnPoolWorker-8] process shutting down
[DEBUG/SpawnPoolWorker-3] thread 'MainThread' has no more proxies so closing conn
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-3'
[DEBUG/SpawnPoolWorker-3] running the remaining "atexit" finalizers
[INFO/SpawnPoolWorker-3] process exiting with exitcode 0
34.918535453: getting log msg
0.979409026: 72180: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x109f14310> 12/13
0.981323763: 72180: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x109f14310>
0.964638774: 72182: Unpickling <flent.runners.NetperfDemoRunner object at 0x10fae7ee0>
34.921731325: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b48460>
0.975201376: 72181: Running in parse_output in <flent.runners.IrttRunner object at 0x10ae43310> 12/13
34.921929324: 72103: Pickling <flent.runners.IrttRunner object at 0x114b64430>
0.982384627: 72180: Unpickling <flent.runners.IrttRunner object at 0x109f14ee0>
[DEBUG/SpawnPoolWorker-5] worker got EOFError or OSError -- exiting
[DEBUG/SpawnPoolWorker-5] worker exiting after 6 tasks
[INFO/SpawnPoolWorker-5] process shutting down
[DEBUG/SpawnPoolWorker-5] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-5] DECREF '10b938fd0'
34.923790429: getting log msg
34.924367784: getting log msg
[DEBUG/SpawnPoolWorker-5] thread 'MainThread' has no more proxies so closing conn
0.96753756: 72182: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10fae7ee0> 12/13
[DEBUG/SpawnPoolWorker-5] running the remaining "atexit" finalizers
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-5'
[INFO/SpawnPoolWorker-5] process exiting with exitcode 0
34.92488969: getting log msg
34.925845252: getting log msg
0.971007262: 72182: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10fae7ee0>
34.928684496: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b584c0>
0.97182455: 72182: Unpickling <flent.runners.NetperfDemoRunner object at 0x10fae7310>
34.928814011: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b64580>
[DEBUG/SpawnPoolWorker-8] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-8] DECREF '10b938fd0'
0.973485415: 72182: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10fae7310> 12/13
[DEBUG/SpawnPoolWorker-8] thread 'MainThread' has no more proxies so closing conn
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-8'
[DEBUG/SpawnPoolWorker-8] running the remaining "atexit" finalizers
[INFO/SpawnPoolWorker-8] process exiting with exitcode 0
0.976139767: 72182: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10fae7310>
34.933601452: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b48a00>
0.976786799: 72182: Unpickling <flent.runners.NetperfDemoRunner object at 0x10fae7ee0>
34.933747812: 72103: Pickling <flent.runners.NetperfDemoRunner object at 0x114b64700>
0.96011563: 72184: Unpickling <flent.runners.IrttRunner object at 0x106f6aee0>
1.00288947: 72179: Finished parse_output() in <flent.runners.IrttRunner object at 0x100da4310>
1.004716283: 72179: Unpickling <flent.runners.IrttRunner object at 0x100da4ee0>
[DEBUG/SpawnPoolWorker-4] worker got EOFError or OSError -- exiting
34.937037201: 72103: recv_result() in <flent.runners.IrttRunner object at 0x114b58d30>
[DEBUG/SpawnPoolWorker-4] worker exiting after 2 tasks
[INFO/SpawnPoolWorker-4] process shutting down
[DEBUG/SpawnPoolWorker-4] running all "atexit" finalizers with priority >= 0
34.937233963: 72103: Pickling <flent.runners.PingRunner object at 0x114b64880>
[DEBUG/SpawnPoolWorker-4] DECREF '10b938fd0'
0.980996126: 72182: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10fae7ee0> 12/13
0.964421571: 72184: Running in parse_output in <flent.runners.IrttRunner object at 0x106f6aee0> 12/13
[DEBUG/SpawnPoolWorker-4] thread 'MainThread' has no more proxies so closing conn
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-4'
[DEBUG/SpawnPoolWorker-4] running the remaining "atexit" finalizers
[INFO/SpawnPoolWorker-4] process exiting with exitcode 0
0.993628004: 72181: Finished parse_output() in <flent.runners.IrttRunner object at 0x10ae43310>
0.98437268: 72182: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10fae7ee0>
0.985245568: 72182: Unpickling <flent.runners.NetperfDemoRunner object at 0x10fae7310>
34.942774305: 72103: recv_result() in <flent.runners.IrttRunner object at 0x114b48310>
34.943156368: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b48b80>
0.996590531: 72181: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ae43ee0>
0.987915314: 72182: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10fae7310> 12/13
0.998663792: 72181: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ae43ee0> 12/13
0.990096032: 72182: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10fae7310>
34.947520393: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b48fa0>
0.990754885: 72182: Unpickling <flent.runners.IrttRunner object at 0x10fae7ee0>
0.991951981: 72182: Running in parse_output in <flent.runners.IrttRunner object at 0x10fae7ee0> 12/13
1.002679695: 72181: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ae43ee0>
34.950983797: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b64160>
1.00498441: 72181: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ae43310>
1.006306398: 72181: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ae43310> 12/13
1.008362837: 72181: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ae43310>
34.955598566: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b64580>
0.981423299: 72184: Finished parse_output() in <flent.runners.IrttRunner object at 0x106f6aee0>
1.00928084: 72181: Unpickling <flent.runners.NetperfDemoRunner object at 0x10ae43ee0>
0.983640345: 72184: Unpickling <flent.runners.PingRunner object at 0x106f6a310>
34.958241339: 72103: recv_result() in <flent.runners.IrttRunner object at 0x114b58790>
1.012301471: 72181: Running in parse_output in <flent.runners.NetperfDemoRunner object at 0x10ae43ee0> 12/13
1.016366482: 72181: Finished parse_output() in <flent.runners.NetperfDemoRunner object at 0x10ae43ee0>
34.963774599: 72103: recv_result() in <flent.runners.NetperfDemoRunner object at 0x114b64700>
1.011969075: 72182: Finished parse_output() in <flent.runners.IrttRunner object at 0x10fae7ee0>
0.995715104: 72184: Running in parse_output in <flent.runners.PingRunner object at 0x106f6a310> 12/13
34.975253667: 72103: recv_result() in <flent.runners.IrttRunner object at 0x114b64430>
1.001063277: 72184: Finished parse_output() in <flent.runners.PingRunner object at 0x106f6a310>
34.97683445: 72103: recv_result() in <flent.runners.PingRunner object at 0x114b64880>
[DEBUG/MainProcess] cleaning up worker 0
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] cleaning up worker 0
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] cleaning up worker 1
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] cleaning up worker 3
[DEBUG/MainProcess] cleaning up worker 0
[DEBUG/MainProcess] added worker
[DEBUG/MainProcess] added worker
[DEBUG/SpawnPoolWorker-10] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-10] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-10] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-10] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-11] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-11] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-11] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-11] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-12] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-12] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-12] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-12] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-10] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-10] child process calling self.run()
0.105829741: 72193: Set queue handler
[DEBUG/SpawnPoolWorker-13] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-13] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-13] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-13] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-11] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-11] child process calling self.run()
0.110459369: 72194: Set queue handler
[DEBUG/SpawnPoolWorker-12] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-12] child process calling self.run()
0.103332675: 72195: Set queue handler
[DEBUG/SpawnPoolWorker-14] recreated blocker with handle 64
[DEBUG/SpawnPoolWorker-14] recreated blocker with handle 65
[DEBUG/SpawnPoolWorker-14] recreated blocker with handle 69
[DEBUG/SpawnPoolWorker-14] recreated blocker with handle 70
[DEBUG/SpawnPoolWorker-13] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-13] child process calling self.run()
0.10664452: 72196: Set queue handler
[DEBUG/SpawnPoolWorker-14] INCREF '10b938fd0'
[INFO/SpawnPoolWorker-14] child process calling self.run()
0.106076084: 72197: Set queue handler
^C[INFO/SpawnPoolWorker-9] process shutting down
[INFO/SpawnPoolWorker-7] process shutting down
[DEBUG/SpawnPoolWorker-7] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-7] DECREF '10b938fd0'
[DEBUG/MainProcess] terminating pool
[INFO/SpawnPoolWorker-10] process shutting down
[DEBUG/MainProcess] finalizing pool
[DEBUG/SpawnPoolWorker-9] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-10] running all "atexit" finalizers with priority >= 0
[INFO/SpawnPoolWorker-13] process shutting down
[INFO/SpawnPoolWorker-11] process shutting down
[DEBUG/SpawnPoolWorker-13] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-9] DECREF '10b938fd0'
[INFO/SpawnPoolWorker-14] process shutting down
[DEBUG/SpawnPoolWorker-11] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-14] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-10] DECREF '10b938fd0'
[DEBUG/MainProcess] helping task handler/workers to finish
[DEBUG/MainProcess] removing tasks from inqueue until task handler finished
[INFO/SpawnPoolWorker-6] process shutting down
[INFO/SpawnPoolWorker-12] process shutting down
[DEBUG/SpawnPoolWorker-6] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-13] DECREF '10b938fd0'
[DEBUG/SpawnPoolWorker-12] running all "atexit" finalizers with priority >= 0
[DEBUG/SpawnPoolWorker-14] DECREF '10b938fd0'
[DEBUG/SpawnPoolWorker-11] DECREF '10b938fd0'
[DEBUG/SpawnPoolWorker-6] DECREF '10b938fd0'
[DEBUG/MainProcess] joining worker handler
[DEBUG/MainProcess] result handler found thread._state=TERMINATE
[DEBUG/SpawnPoolWorker-12] DECREF '10b938fd0'
[DEBUG/MainProcess] worker handler exiting
[DEBUG/SpawnPoolWorker-9] thread 'MainThread' has no more proxies so closing conn
[DEBUG/MainProcess] ensuring that outqueue is not full
[DEBUG/SpawnPoolWorker-9] running the remaining "atexit" finalizers
Process SpawnPoolWorker-9:
[DEBUG/SpawnPoolWorker-7] thread 'MainThread' has no more proxies so closing conn
[DEBUG/MainProcess] terminating workers
[DEBUG/SpawnPoolWorker-7] running the remaining "atexit" finalizers
Process SpawnPoolWorker-7:
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-7'
[DEBUG/MainProcess] task handler got sentinel
[DEBUG/MainProcess] task handler sending sentinel to result handler
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-9'
[DEBUG/MainProcess] task handler sending sentinel to workers
[DEBUG/MainProcess] joining task handler
[DEBUG/MainProcess] result handler exiting: len(cache)=5, thread._state=TERMINATE
[DEBUG/MainProcess] task handler exiting
[DEBUG/MainProcess] joining result handler
[DEBUG/MainProcess] joining pool workers
[DEBUG/MainProcess] cleaning up worker 72181
[DEBUG/MainProcess] cleaning up worker 72182
[DEBUG/SyncManager-1] got EOF -- exiting thread serving 'SpawnPoolWorker-6'
[INFO/MainProcess] sending shutdown message to manager
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 202, in handle_request\n    connection.deliver_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 743, in deliver_challenge\n    connection.send_bytes(CHALLENGE + message)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 205, in send_bytes\n    self._send_bytes(m[offset:offset + size])\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 416, in _send_bytes\n    self._send(header + buf)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 373, in _send\n    n = write(self._handle, buf)\nBrokenPipeError: [Errno 32] Broken pipe\n')
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 202, in handle_request\n    connection.deliver_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 743, in deliver_challenge\n    connection.send_bytes(CHALLENGE + message)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 205, in send_bytes\n    self._send_bytes(m[offset:offset + size])\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 416, in _send_bytes\n    self._send(header + buf)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 373, in _send\n    n = write(self._handle, buf)\nBrokenPipeError: [Errno 32] Broken pipe\n')
[INFO/SyncManager-1]  ... request was None
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 202, in handle_request\n    connection.deliver_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 745, in deliver_challenge\n    response = connection.recv_bytes(256)        # reject large message\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes\n    buf = self._recv_bytes(maxlength)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes\n    buf = self._recv(4)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 388, in _recv\n    raise EOFError\nEOFError\n')
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 203, in handle_request\n    connection.answer_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 757, in answer_challenge\n    message = connection.recv_bytes(256)         # reject large message\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes\n    buf = self._recv_bytes(maxlength)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes\n    buf = self._recv(4)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 388, in _recv\n    raise EOFError\nEOFError\n')
[DEBUG/SyncManager-1] manager received shutdown message
[INFO/SyncManager-1] Failure to send message: ('#TRACEBACK', 'Traceback (most recent call last):\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/managers.py", line 202, in handle_request\n    connection.deliver_challenge(c, self.authkey)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 745, in deliver_challenge\n    response = connection.recv_bytes(256)        # reject large message\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes\n    buf = self._recv_bytes(maxlength)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes\n    buf = self._recv(4)\n  File "/usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/connection.py", line 388, in _recv\n    raise EOFError\nEOFError\n')
[INFO/SyncManager-1]  ... request was None
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[INFO/SyncManager-1]  ... request was None
[INFO/SyncManager-1]  ... request was None
[INFO/SyncManager-1] process shutting down
[INFO/SyncManager-1]  ... request was None
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[DEBUG/SyncManager-1] running all "atexit" finalizers with priority >= 0
[INFO/SyncManager-1]  ... exception was BrokenPipeError(32, 'Broken pipe')
[DEBUG/SyncManager-1] running the remaining "atexit" finalizers
[INFO/SyncManager-1] process exiting with exitcode 0
864.433094902: EOF on reading log queue, exiting

bash-3.2$ /usr/local/Cellar/python@3.9/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/resource_tracker.py:216: UserWarning: resource_tracker: There appear to be 6 leaked semaphore objects to clean up at shutdown
  warnings.warn('resource_tracker: There appear to be %d '

bash-3.2$
tohojo commented 2 years ago

Hmm, okay, so at this point I'm ready to conclude that this is simply a bug in the internals of the multiprocessing library, which it seems non-trivial to work around. So I'll restructure things so we can just avoid using in on OSX instead...

moeller0 commented 2 years ago

Fair enough. Do you think that might be python 3.9 related? I could try the non-default python 3.10 on homebrew... will do and report results later tonight.

tohojo commented 2 years ago

Fair enough. Do you think that might be python 3.9 related? I could try the non-default python 3.10 on homebrew... will do and report results later tonight.

No idea; but sure, might be worth trying!

Please also try #270 and see if that works without hanging :)

moeller0 commented 2 years ago

Yes, the no-multiproc branch works as expected:

bash-3.2$ git pull
remote: Enumerating objects: 10, done.
remote: Counting objects: 100% (10/10), done.
remote: Compressing objects: 100% (2/2), done.
remote: Total 10 (delta 8), reused 10 (delta 8), pack-reused 0
Unpacking objects: 100% (10/10), 2.78 KiB | 167.00 KiB/s, done.
From https://github.com/tohojo/flent
 * [new branch]      no-multiproc -> origin/no-multiproc
Already up to date.
bash-3.2$ git switch no-multiproc
branch 'no-multiproc' set up to track 'origin/no-multiproc'.
Switched to a new branch 'no-multiproc'

bash-3.2$ date ; ./run-flent --ipv4 -l 20 -H singapore.starlink.taht.net rrul_var  --step-size=.05 --test-parameter bidir_streams=8 --test-parameter markings=0,0,0,0,0,0,0,0 --test-parameter ping_hosts=1.1.1.1 -D . -t IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net --log-file
Tue Jul  5 12:25:57 CEST 2022
Starting Flent 2.0.1-git-1afb43e using Python 3.9.13.
Starting rrul_var test. Expected run time: 30 seconds.
Data file written to ./rrul_var-2022-07-05T122558.255029.IPv4_work_mbpro_thunderbolt_ethernet_2_singapore_starlink_taht_net.flent.gz

Summary of rrul_var test run from 2022-07-05 10:25:58.255029
  Title: 'IPv4_work_mbpro_thunderbolt_ethernet_2_singapore.starlink.taht.net'

                                           avg       median       99th %          # data pts
 Ping (ms) ICMP 1.1.1.1 (extra) :         8.52         8.14        11.71 ms              599
 Ping (ms) avg                  :       250.45          N/A          N/A ms              610
 Ping (ms)::ICMP                :       245.46       244.00       258.03 ms              598
 Ping (ms)::UDP 0 (0)           :       242.74       241.22       255.11 ms              610
 Ping (ms)::UDP 1 (0)           :       243.85       242.13       263.28 ms              610
 Ping (ms)::UDP 2 (0)           :       269.36       267.59       283.41 ms              610
 Ping (ms)::UDP 3 (0)           :       242.81       240.96       258.96 ms              610
 Ping (ms)::UDP 4 (0)           :       248.32       246.60       264.99 ms              610
 Ping (ms)::UDP 5 (0)           :       244.11       242.30       257.60 ms              610
 Ping (ms)::UDP 6 (0)           :       246.36       244.37       261.88 ms              610
 Ping (ms)::UDP 7 (0)           :       266.07       264.15       279.37 ms              610
 TCP download avg               :        32.23          N/A          N/A Mbits/s         610
 TCP download sum               :       257.80          N/A          N/A Mbits/s         610
 TCP download::0 (0)            :        23.47        23.73       133.21 Mbits/s         610
 TCP download::1 (0)            :        67.21        68.06       488.20 Mbits/s         610
 TCP download::2 (0)            :        21.22        21.39        94.47 Mbits/s         610
 TCP download::3 (0)            :        34.68        35.62       163.42 Mbits/s         610
 TCP download::4 (0)            :        18.58        17.87        83.47 Mbits/s         610
 TCP download::5 (0)            :        29.99        27.62       114.17 Mbits/s         610
 TCP download::6 (0)            :        36.94        38.92       117.25 Mbits/s         610
 TCP download::7 (0)            :        25.71        25.93       112.32 Mbits/s         610
 TCP totals                     :       759.10          N/A          N/A Mbits/s         610
 TCP upload avg                 :        62.66          N/A          N/A Mbits/s         610
 TCP upload sum                 :       501.30          N/A          N/A Mbits/s         610
 TCP upload::0 (0)              :        55.02        83.28       220.49 Mbits/s         610
 TCP upload::1 (0)              :        56.83        76.00       270.56 Mbits/s         610
 TCP upload::2 (0)              :        48.28        56.25       253.71 Mbits/s         610
 TCP upload::3 (0)              :        53.14        80.93       245.71 Mbits/s         610
 TCP upload::4 (0)              :        58.79        77.85       244.80 Mbits/s         610
 TCP upload::5 (0)              :        75.83        91.84       214.56 Mbits/s         610
 TCP upload::6 (0)              :        77.16        88.48       228.08 Mbits/s         610
 TCP upload::7 (0)              :        76.25        89.56       206.14 Mbits/s         610
tohojo commented 2 years ago

Alright, merging that in the interest of unbreaking stuff, then :)