search

mdavidsaver / pvxs

PVA protocol client/server library and utilities.
https://mdavidsaver.github.io/pvxs/
Other
19 stars 25 forks source link

Fix local mcast forwarding #33

Closed mdavidsaver closed 1 year ago

mdavidsaver commented 1 year ago

Attempts to address #31. Includes changes to:

mdavidsaver commented 1 year ago

@jbellister-slac Would you be able to test this change?

jbellister-slac commented 1 year ago

Absolutely! Will give it a spin later today and report back.

jbellister-slac commented 1 year ago

Functionality looks great to me! My simple test case of running the pvget on the same machine works just fine now. Moved it onto our network and tested communication between two different machines and that also works now too. Environments tested were Red Hat 6 and 7.

One minor note, the new unit tests did not pass on a fresh install to either location, I could look further if it would help

testudpfwd.t ... 2023-01-31T20:07:09.642649600 WARN pvxs.tcp.setup Server unable to bind port 45742, falling back to 45.33.109.184:42159
testudpfwd.t ... Failed 1/1 subtests
AppVeyorBot commented 1 year ago

:white_check_mark: Build pvxs 1.0.838 completed (commit https://github.com/mdavidsaver/pvxs/commit/b2e6cd958d by @mdavidsaver)

mdavidsaver commented 1 year ago

One minor note, the new unit tests did not pass on a fresh install to either location, I could look further if it would help

Could you send the output of running the equivalent of:

PVXS_LOG=*=DEBUG ./test/O.linux-x86_64/testudpfwd
jbellister-slac commented 1 year ago 
./test/O.linux-x86_64/testudpfwd 
1..1
# In testFwdIface
2023-02-01T09:46:56.123175528 DEBUG pvxs.iface refresh after 15535154.4 sec
2023-02-01T09:46:56.123469431 DEBUG pvxs.iface Ignoring interface 'lo' address family=17
2023-02-01T09:46:56.123495491 DEBUG pvxs.iface Ignoring interface 'eth0' address family=17
2023-02-01T09:46:56.123511521 DEBUG pvxs.iface Ignoring interface 'docker0' address family=17
2023-02-01T09:46:56.123526371 DEBUG pvxs.iface Ignoring interface 'br-67a3e997d373' address family=17
2023-02-01T09:46:56.123541441 DEBUG pvxs.iface Ignoring interface 'veth9ba2dc7' address family=17
2023-02-01T09:46:56.123630012 DEBUG pvxs.iface Found interface 1 "lo" w/ 2 127.0.0.1
2023-02-01T09:46:56.123817693 DEBUG pvxs.iface Found interface 2 "eth0" w/ 2 45.33.109.184
2023-02-01T09:46:56.123851524 DEBUG pvxs.iface Found interface 101480 "docker0" w/ 2 172.17.0.1
2023-02-01T09:46:56.123882104 DEBUG pvxs.iface Found interface 223161 "br-67a3e997d373" w/ 2 192.168.49.1
2023-02-01T09:46:56.123912594 DEBUG pvxs.iface Found interface 1 "lo" w/ 10 [::1]
2023-02-01T09:46:56.123944014 DEBUG pvxs.iface Found interface 2 "eth0" w/ 10 [2600:3c01::f03c:93ff:fe35:1c56]
2023-02-01T09:46:56.123977175 DEBUG pvxs.iface Found interface 2 "eth0" w/ 10 [fe80::f03c:93ff:fe35:1c56]%2
2023-02-01T09:46:56.124017365 DEBUG pvxs.iface Found interface 101480 "docker0" w/ 10 [fe80::42:3ff:fe99:c51d]%101480
2023-02-01T09:46:56.124048715 DEBUG pvxs.iface Found interface 223161 "br-67a3e997d373" w/ 10 [fe80::42:6dff:fe81:6b2a]%223161
2023-02-01T09:46:56.124078895 DEBUG pvxs.iface Found interface 223167 "veth9ba2dc7" w/ 10 [fe80::78f0:e3ff:fe41:b586]%223167

# In testFwdVia(45.33.109.184)
2023-02-01T09:46:56.124448238 INFO pvxs.loop Enter loop worker for 0x7f4cf4000900 using epoll
2023-02-01T09:46:56.124659920 INFO pvxs.loop Enter loop worker for 0x7f4cf8000900 using epoll
2023-02-01T09:46:56.124835791 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:46464 as lo
2023-02-01T09:46:56.124873372 DEBUG pvxs.udp.setup Listening for SEARCH on 45.33.109.184:46464
2023-02-01T09:46:56.125071013 DEBUG pvxs.udp.setup Listening for SEARCH on 45.33.109.255:46464
2023-02-01T09:46:56.125662018 INFO pvxs.loop Enter loop worker for 0x7f4cec000900 using epoll
2023-02-01T09:46:56.125834969 INFO pvxs.loop Enter loop worker for 0x7f4cf0000900 using epoll
2023-02-01T09:46:56.125942060 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:46464 as lo
2023-02-01T09:46:56.125969930 DEBUG pvxs.udp.setup Listening for SEARCH on 45.33.109.184:46464
2023-02-01T09:46:56.126150191 DEBUG pvxs.udp.setup Listening for SEARCH on 45.33.109.255:46464
2023-02-01T09:46:56.126422604 DEBUG pvxs.tcp.setup Address 45.33.109.184:38105 in use
2023-02-01T09:46:56.126464284 WARN pvxs.tcp.setup Server unable to bind port 38105, falling back to 45.33.109.184:44273
2023-02-01T09:46:56.126733736 INFO pvxs.loop Enter loop worker for 0x7f4ce4000900 using epoll
2023-02-01T09:46:56.126909307 INFO pvxs.loop Enter loop worker for 0x7f4ce8000900 using epoll
2023-02-01T09:46:56.127015268 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:46464 as lo
2023-02-01T09:46:56.127063989 DEBUG pvxs.udp.setup Listening for SEARCH on 0.0.0.0:46464
2023-02-01T09:46:56.127299681 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:46:56.127354651 DEBUG pvxs.server.setup Server starting
2023-02-01T09:46:56.127376611 DEBUG pvxs.server.setup Server enabled listener on 45.33.109.184:38105
2023-02-01T09:46:56.127417851 DEBUG pvxs.udp.setup Start listening for UDP 45.33.109.184:46464
2023-02-01T09:46:56.127478112 DEBUG pvxs.udp.setup Start listening for UDP 45.33.109.255:46464
2023-02-01T09:46:56.127557003 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:46:56.127591133 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:46:56.127672713 DEBUG pvxs.server.setup Server starting
2023-02-01T09:46:56.127692424 DEBUG pvxs.server.setup Server enabled listener on 45.33.109.184:44273
2023-02-01T09:46:56.127732304 DEBUG pvxs.udp.setup Start listening for UDP 45.33.109.184:46464
2023-02-01T09:46:56.127797094 DEBUG pvxs.udp.setup Start listening for UDP 45.33.109.255:46464
2023-02-01T09:46:56.127820525 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:46:56.127834995 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:46:56.127939536 DEBUG pvxs.server.setup Server starting
2023-02-01T09:46:56.127957006 DEBUG pvxs.server.setup Server enabled listener on [::]:40358
2023-02-01T09:46:56.127980576 DEBUG pvxs.udp.setup Start listening for UDP 0.0.0.0:46464
2023-02-01T09:46:56.128003736 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:46:56.128140837 INFO pvxs.loop Enter loop worker for 0x7f4cdc000900 using epoll
2023-02-01T09:46:56.128815952 INFO pvxs.loop Enter loop worker for 0x7f4ce0000900 using epoll
2023-02-01T09:46:56.129022134 DEBUG pvxs.client.setup Using UDP Rx port 40324
2023-02-01T09:46:56.129090525 INFO pvxs.client.io Searching to 45.33.109.184:46464 unicast
2023-02-01T09:46:56.129230376 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:46464 as lo
2023-02-01T09:46:56.129285446 INFO pvxs.client.io Listening for beacons on 45.33.109.184:46464
2023-02-01T09:46:56.129360727 DEBUG pvxs.udp.setup Start listening for UDP 45.33.109.184:46464
2023-02-01T09:46:56.129487898 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:46:56.129525658 DEBUG pvxs.client.io Search tick 0
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:46:56.129647029 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
2023-02-01T09:46:56.129702329 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:46:56.129785250 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:46:56.129824090 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:46:57.130259713 DEBUG pvxs.client.io Search tick 1
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:46:57.130358673 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
2023-02-01T09:46:57.130416504 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:46:57.130427464 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:46:57.130444584 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:46:58.131445010 DEBUG pvxs.client.io Search tick 2
2023-02-01T09:46:59.131773141 DEBUG pvxs.client.io Search tick 3
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:46:59.131867382 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
2023-02-01T09:46:59.131917102 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:46:59.131929902 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:46:59.131950213 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:47:00.132793858 DEBUG pvxs.client.io Search tick 4
2023-02-01T09:47:01.129687903 INFO pvxs.client.setup implied cancel of opa on channel 'testpv1'
# Timeout testpv1
2023-02-01T09:47:01.129831954 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:47:01.129848584 DEBUG pvxs.client.io Search tick 5
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 79077465
0030 : 73747076 32  
2023-02-01T09:47:01.129932724 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
2023-02-01T09:47:01.129901124 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 79077465
0030 : 73747076 32  
2023-02-01T09:47:01.129957195 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:47:01.130396218 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:47:02.131056932 DEBUG pvxs.client.io Search tick 6
2023-02-01T09:47:02.131198573 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 02123456 78077465
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:02.131152283 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 02123456 78077465
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:02.131216433 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:47:02.131241924 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:47:03.132285420 DEBUG pvxs.client.io Search tick 7
2023-02-01T09:47:04.133391688 DEBUG pvxs.client.io Search tick 8
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 79077465
0030 : 73747076 32  
2023-02-01T09:47:04.133486999 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
2023-02-01T09:47:04.133517719 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 79077465
0030 : 73747076 32  
2023-02-01T09:47:04.133536759 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:47:04.133847492 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:47:05.134052341 DEBUG pvxs.client.io Search tick 9
2023-02-01T09:47:06.129928948 DEBUG pvxs.client.setup Chan GC sweep 'testpv1':''
2023-02-01T09:47:06.130065709 INFO pvxs.client.setup implied cancel of opa on channel 'testpv2'
# Timeout testpv2
2023-02-01T09:47:06.130122779 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:47:06.130132979 DEBUG pvxs.client.io Search tick 10
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:06.130191170 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
2023-02-01T09:47:06.130208950 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:06.130225490 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:47:06.130255750 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:47:07.131262487 DEBUG pvxs.client.io Search tick 11
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 02123456 79077465
0030 : 73747076 32123456 7A077465 73747076
...
2023-02-01T09:47:07.131353358 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
2023-02-01T09:47:07.131374318 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 02123456 79077465
0030 : 73747076 32123456 7A077465 73747076
...
2023-02-01T09:47:07.131392028 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:47:07.131415218 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:47:08.132438665 DEBUG pvxs.client.io Search tick 12
2023-02-01T09:47:09.132957368 DEBUG pvxs.client.io Search tick 13
2023-02-01T09:47:09.133070169 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:09.133054549 DEBUG pvxs.client.io Search to 45.33.109.184:46464 ucast
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 9D840103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:09.133088339 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
2023-02-01T09:47:09.133113479 DEBUG pvxs.udp.io Ignore as originated for 45.33.109.184:46464
2023-02-01T09:47:10.133975965 DEBUG pvxs.client.io Search tick 14
# Timeout testpv3
2023-02-01T09:47:11.130264294 INFO pvxs.client.setup implied cancel of opa on channel 'testpv3'
2023-02-01T09:47:11.130337854 DEBUG pvxs.client.setup context 0x71a5d8 close
2023-02-01T09:47:11.130668727 DEBUG pvxs.udp.setup Stop listening for UDP 45.33.109.184:46464
2023-02-01T09:47:11.130890279 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce0000900
2023-02-01T09:47:11.131080490 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cdc000900
2023-02-01T09:47:11.131149601 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:11.131299432 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:11.131441303 DEBUG pvxs.udp.setup Stop listening for UDP 0.0.0.0:46464
2023-02-01T09:47:11.131496013 DEBUG pvxs.server.setup Server disabled listener on [::]:40358
2023-02-01T09:47:11.131599264 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:11.131681755 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:11.131860096 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce8000900
2023-02-01T09:47:11.131948747 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce4000900
2023-02-01T09:47:11.132065578 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:11.132146139 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:11.132219009 DEBUG pvxs.udp.setup Stop listening for UDP 45.33.109.184:46464
2023-02-01T09:47:11.132303360 DEBUG pvxs.udp.setup Stop listening for UDP 45.33.109.255:46464
2023-02-01T09:47:11.132354010 DEBUG pvxs.server.setup Server disabled listener on 45.33.109.184:44273
2023-02-01T09:47:11.132375570 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:11.132434551 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:11.132654113 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf0000900
2023-02-01T09:47:11.132715513 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cec000900
2023-02-01T09:47:11.132777603 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:11.132834324 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:11.132911935 DEBUG pvxs.udp.setup Stop listening for UDP 45.33.109.184:46464
2023-02-01T09:47:11.132951675 DEBUG pvxs.udp.setup Stop listening for UDP 45.33.109.255:46464
2023-02-01T09:47:11.133017295 DEBUG pvxs.server.setup Server disabled listener on 45.33.109.184:38105
2023-02-01T09:47:11.133043556 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:11.133116596 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:11.133255087 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf8000900
2023-02-01T09:47:11.133371558 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf4000900

# In testFwdVia(172.17.0.1)
2023-02-01T09:47:11.133718411 INFO pvxs.loop Enter loop worker for 0x7f4cf4001160 using epoll
2023-02-01T09:47:11.133923252 INFO pvxs.loop Enter loop worker for 0x7f4cf8000900 using epoll
2023-02-01T09:47:11.134036713 DEBUG pvxs.iface refresh forced after 15.0 sec
2023-02-01T09:47:11.134208555 DEBUG pvxs.iface Ignoring interface 'lo' address family=17
2023-02-01T09:47:11.134223655 DEBUG pvxs.iface Ignoring interface 'eth0' address family=17
2023-02-01T09:47:11.134226775 DEBUG pvxs.iface Ignoring interface 'docker0' address family=17
2023-02-01T09:47:11.134229485 DEBUG pvxs.iface Ignoring interface 'br-67a3e997d373' address family=17
2023-02-01T09:47:11.134231675 DEBUG pvxs.iface Ignoring interface 'veth9ba2dc7' address family=17
2023-02-01T09:47:11.134294805 DEBUG pvxs.iface Found interface 1 "lo" w/ 2 127.0.0.1
2023-02-01T09:47:11.134322316 DEBUG pvxs.iface Found interface 2 "eth0" w/ 2 45.33.109.184
2023-02-01T09:47:11.134342776 DEBUG pvxs.iface Found interface 101480 "docker0" w/ 2 172.17.0.1
2023-02-01T09:47:11.134361916 DEBUG pvxs.iface Found interface 223161 "br-67a3e997d373" w/ 2 192.168.49.1
2023-02-01T09:47:11.134380456 DEBUG pvxs.iface Found interface 1 "lo" w/ 10 [::1]
2023-02-01T09:47:11.134407236 DEBUG pvxs.iface Found interface 2 "eth0" w/ 10 [2600:3c01::f03c:93ff:fe35:1c56]
2023-02-01T09:47:11.134435766 DEBUG pvxs.iface Found interface 2 "eth0" w/ 10 [fe80::f03c:93ff:fe35:1c56]%2
2023-02-01T09:47:11.134455597 DEBUG pvxs.iface Found interface 101480 "docker0" w/ 10 [fe80::42:3ff:fe99:c51d]%101480
2023-02-01T09:47:11.134474857 DEBUG pvxs.iface Found interface 223161 "br-67a3e997d373" w/ 10 [fe80::42:6dff:fe81:6b2a]%223161
2023-02-01T09:47:11.134493837 DEBUG pvxs.iface Found interface 223167 "veth9ba2dc7" w/ 10 [fe80::78f0:e3ff:fe41:b586]%223167
2023-02-01T09:47:11.134516487 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:43587 as lo
2023-02-01T09:47:11.134550147 DEBUG pvxs.udp.setup Listening for SEARCH on 172.17.0.1:43587
2023-02-01T09:47:11.134790409 DEBUG pvxs.udp.setup Listening for SEARCH on 172.17.255.255:43587
2023-02-01T09:47:11.135162722 INFO pvxs.loop Enter loop worker for 0x7f4cec0008c0 using epoll
2023-02-01T09:47:11.135311813 INFO pvxs.loop Enter loop worker for 0x7f4cf0000900 using epoll
2023-02-01T09:47:11.135414204 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:43587 as lo
2023-02-01T09:47:11.135461904 DEBUG pvxs.udp.setup Listening for SEARCH on 172.17.0.1:43587
2023-02-01T09:47:11.135669806 DEBUG pvxs.udp.setup Listening for SEARCH on 172.17.255.255:43587
2023-02-01T09:47:11.135804477 DEBUG pvxs.tcp.setup Address 172.17.0.1:45643 in use
2023-02-01T09:47:11.135827467 WARN pvxs.tcp.setup Server unable to bind port 45643, falling back to 172.17.0.1:34525
2023-02-01T09:47:11.136054749 INFO pvxs.loop Enter loop worker for 0x7f4ce4000900 using epoll
2023-02-01T09:47:11.136139700 INFO pvxs.loop Enter loop worker for 0x7f4ce8000900 using epoll
2023-02-01T09:47:11.136238391 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:43587 as lo
2023-02-01T09:47:11.136279761 DEBUG pvxs.udp.setup Listening for SEARCH on 0.0.0.0:43587
2023-02-01T09:47:11.136527853 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:47:11.136569123 DEBUG pvxs.server.setup Server starting
2023-02-01T09:47:11.136582943 DEBUG pvxs.server.setup Server enabled listener on 172.17.0.1:45643
2023-02-01T09:47:11.136631104 DEBUG pvxs.udp.setup Start listening for UDP 172.17.0.1:43587
2023-02-01T09:47:11.136666084 DEBUG pvxs.udp.setup Start listening for UDP 172.17.255.255:43587
2023-02-01T09:47:11.136730434 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:11.136763475 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:47:11.136869416 DEBUG pvxs.server.setup Server starting
2023-02-01T09:47:11.136879056 DEBUG pvxs.server.setup Server enabled listener on 172.17.0.1:34525
2023-02-01T09:47:11.136911136 DEBUG pvxs.udp.setup Start listening for UDP 172.17.0.1:43587
2023-02-01T09:47:11.136973626 DEBUG pvxs.udp.setup Start listening for UDP 172.17.255.255:43587
2023-02-01T09:47:11.137027177 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:11.137054217 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:47:11.137134878 DEBUG pvxs.server.setup Server starting
2023-02-01T09:47:11.137145018 DEBUG pvxs.server.setup Server enabled listener on [::]:34861
2023-02-01T09:47:11.137205058 DEBUG pvxs.udp.setup Start listening for UDP 0.0.0.0:43587
2023-02-01T09:47:11.137269699 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:11.137382080 INFO pvxs.loop Enter loop worker for 0x7f4cdc000900 using epoll
2023-02-01T09:47:11.137522251 INFO pvxs.loop Enter loop worker for 0x7f4ce0000900 using epoll
2023-02-01T09:47:11.137632031 DEBUG pvxs.client.setup Using UDP Rx port 54700
2023-02-01T09:47:11.137730352 INFO pvxs.client.io Searching to 172.17.0.1:43587 unicast
2023-02-01T09:47:11.137998624 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:43587 as lo
2023-02-01T09:47:11.138028215 INFO pvxs.client.io Listening for beacons on 172.17.0.1:43587
2023-02-01T09:47:11.138119475 DEBUG pvxs.udp.setup Start listening for UDP 172.17.0.1:43587
2023-02-01T09:47:11.138178476 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:47:11.138190536 DEBUG pvxs.client.io Search tick 0
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:11.138277587 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:11.138303577 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:11.138376347 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:11.138421848 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:11.138431388 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:11.138451808 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:11.138464308 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:11.138467998 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 0000002D 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 01123456 78  
2023-02-01T09:47:11.138471858 DEBUG pvxs.udp.io Send 0.0.0.0:43587 -> 45.33.109.184:54700
2023-02-01T09:47:11.138520388 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 0000002D 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 01123456 78  
2023-02-01T09:47:11.138532429 DEBUG pvxs.client.io UDP search Rx 53 from 45.33.109.184:43587
2023-02-01T09:47:11.138563219 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:11.139088693 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:11.139115323 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:11.139137093 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:11.139153703 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:11.139161353 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:12.139218973 DEBUG pvxs.client.io Search tick 1
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 78077465 73747076
...
2023-02-01T09:47:12.139306533 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:12.139357104 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 78077465 73747076
...
2023-02-01T09:47:12.139367394 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:12.139390444 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:12.139398114 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:12.139407054 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:12.139410214 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:12.139413034 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:12.139415484 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:12.139418324 DEBUG pvxs.server.search Search claimed 'testpv1'
2023-02-01T09:47:12.139420564 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:12.139424294 DEBUG pvxs.udp.io Send 0.0.0.0:43587 -> 45.33.109.184:54700
2023-02-01T09:47:12.139461935 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:12.139470565 DEBUG pvxs.client.io UDP search Rx 57 from 45.33.109.184:43587
2023-02-01T09:47:12.139506885 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:12.139617216 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:12.139631826 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:12.139636296 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:12.139649026 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:12.139655686 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:12.139663306 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:13.140725033 DEBUG pvxs.client.io Search tick 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:13.140829474 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:13.140883775 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:13.140900055 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:13.140923115 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:13.140930095 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:13.140937355 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:13.140940925 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:13.140944475 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 0000002D 6BF84E92 A93C78A9
errlog: lost 4 messages
2023-02-01T09:47:13.141009046 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 0000002D 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 01123456 78  
2023-02-01T09:47:13.141025986 DEBUG pvxs.client.io UDP search Rx 53 from 45.33.109.184:43587
2023-02-01T09:47:13.141039796 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:13.141164337 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:13.141190477 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:13.141208177 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:13.141218447 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:13.141241317 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:14.142323205 DEBUG pvxs.client.io Search tick 3
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 78077465 73747076
...
2023-02-01T09:47:14.142413996 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:14.142463426 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 78077465 73747076
...
2023-02-01T09:47:14.142472836 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:14.142488136 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:14.142495536 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:14.142510126 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:14.142513166 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:14.142515616 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:14.142518166 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:14.142520746 DEBUG pvxs.server.search Search claimed 'testpv1'
2023-02-01T09:47:14.142522736 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:14.142526476 DEBUG pvxs.udp.io Send 0.0.0.0:43587 -> 45.33.109.184:54700
2023-02-01T09:47:14.142557267 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:14.142562767 DEBUG pvxs.client.io UDP search Rx 57 from 45.33.109.184:43587
2023-02-01T09:47:14.142578297 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:14.142689068 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:14.142704088 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:14.142708308 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:14.142720448 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:14.142726948 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:14.142729738 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:15.143502473 DEBUG pvxs.client.io Search tick 4
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 78077465 73747076
...
2023-02-01T09:47:15.143609664 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:15.143671114 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 78077465 73747076
...
2023-02-01T09:47:15.143681574 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:15.143705404 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:15.143713205 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:15.143724655 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:15.143727755 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:15.143730665 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:15.143732975 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:15.143763555 DEBUG pvxs.server.search Search claimed 'testpv1'
2023-02-01T09:47:15.143766485 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:15.143770615 DEBUG pvxs.udp.io Send 0.0.0.0:43587 -> 45.33.109.184:54700
2023-02-01T09:47:15.143821065 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:15.143837686 DEBUG pvxs.client.io UDP search Rx 57 from 45.33.109.184:43587
2023-02-01T09:47:15.143859096 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:15.143973787 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:15.143996597 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:15.144002277 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:15.144016587 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:15.144029467 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:15.144033227 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:16.138381092 INFO pvxs.client.setup implied cancel of opa on channel 'testpv1'
# Timeout testpv1
2023-02-01T09:47:16.138519763 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:47:16.138537143 DEBUG pvxs.client.io Search tick 5
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:16.138592163 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:16.138632944 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:16.138649424 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:16.138667454 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:16.138673784 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:16.138680864 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:16.138684094 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:16.138686434 DEBUG pvxs.server.io   disclaim testpv2
2023-02-01T09:47:16.138689174 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 0000002D 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 01123456 78  
2023-02-01T09:47:16.138692304 DEBUG pvxs.udp.io Send 0.0.0.0:43587 -> 45.33.109.184:54700
2023-02-01T09:47:16.138732254 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 0000002D 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 01123456 78  
2023-02-01T09:47:16.138769145 DEBUG pvxs.client.io UDP search Rx 53 from 45.33.109.184:43587
2023-02-01T09:47:16.138786445 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:16.138901746 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:16.138918716 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:16.138932126 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:16.138943156 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:16.138946206 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:17.140025852 DEBUG pvxs.client.io Search tick 6
2023-02-01T09:47:17.140153643 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 00000045 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 03123456 78077465
0000 : CA028003 00000045 66696E64 80000000
0030 : 73747076 31123456 79077465 73747076
0010 : 00000000 00000000 00000000 00000000
...
0020 : D5AC0103 74637000 03123456 78077465
2023-02-01T09:47:17.140129813 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:17.140176994 DEBUG pvxs.udp.io UDP Rx 77, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:17.140346305 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:17.140365905 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:17.140381635 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:17.140393105 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:17.140402805 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:17.140412175 DEBUG pvxs.server.io   disclaim testpv2
2023-02-01T09:47:17.140421025 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:17.140430266 DEBUG pvxs.server.search Search claimed 'testpv1'
2023-02-01T09:47:17.140438906 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:17.140449506 DEBUG pvxs.udp.io Send 0.0.0.0:43587 -> 45.33.109.184:54700
2023-02-01T09:47:17.140529446 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:17.140543616 DEBUG pvxs.client.io UDP search Rx 57 from 45.33.109.184:43587
2023-02-01T09:47:17.140560537 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:17.140677177 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:17.140694098 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:17.140699398 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:17.140718868 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:17.140730128 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:17.140733498 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:18.141840515 DEBUG pvxs.client.io Search tick 7
2023-02-01T09:47:18.141958736 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:18.141935636 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:18.141978596 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:18.142002047 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:18.142009577 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:18.142016937 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:18.142019977 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:18.142022887 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 0000002D 6BF84E92 A93C78A9
errlog: lost 4 messages
2023-02-01T09:47:18.142079777 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 0000002D 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 01123456 78  
2023-02-01T09:47:18.142088187 DEBUG pvxs.client.io UDP search Rx 53 from 45.33.109.184:43587
2023-02-01T09:47:18.142099427 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:18.142206338 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:18.142224788 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:18.142237778 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:18.142245228 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:18.142248518 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:19.143212745 DEBUG pvxs.client.io Search tick 8
0000 : CA028003 00000045 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 03123456 78077465
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:19.143302066 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:19.143358216 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 00000045 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 03123456 78077465
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:19.143368656 DEBUG pvxs.udp.io UDP Rx 77, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:19.143393047 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:19.143401557 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:19.143415727 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:19.143419877 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:19.143423037 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:19.143430497 DEBUG pvxs.server.io   disclaim testpv2
2023-02-01T09:47:19.143455957 DEBUG pvxs.server.io   claim testpv1
2023-02-01T09:47:19.143467787 DEBUG pvxs.server.search Search claimed 'testpv1'
2023-02-01T09:47:19.143477247 DEBUG pvxs.server.search Search claimed 'testpv1'
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:19.143489027 DEBUG pvxs.udp.io Send 0.0.0.0:43587 -> 45.33.109.184:54700
2023-02-01T09:47:19.143557638 DEBUG pvxs.client.io UDP search Rx event 2
0000 : CA02C004 00000031 6BF84E92 A93C78A9
0010 : A9656A98 66696E64 00000000 00000000
0020 : 0000FFFF 00000000 B24B0374 63700100
0030 : 02123456 78123456 78 
2023-02-01T09:47:19.143572788 DEBUG pvxs.client.io UDP search Rx 57 from 45.33.109.184:43587
2023-02-01T09:47:19.143617498 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:19.143728209 DEBUG pvxs.client.io Connecting to 45.33.109.184:45643, RX readahead 174760
2023-02-01T09:47:19.143787110 DEBUG pvxs.client.io Search reply for testpv1
2023-02-01T09:47:19.143799720 DEBUG pvxs.client.io UDP search processed 1/40
2023-02-01T09:47:19.143821210 ERR pvxs.tcp.io connection to Server 45.33.109.184:45643 closed with socket error 111 : Connection refused
2023-02-01T09:47:19.143835980 DEBUG pvxs.client.io Server 45.33.109.184:45643 detach channel 'testpv1' to re-search
2023-02-01T09:47:19.143847390 DEBUG pvxs.client.io Cleaning connection to 45.33.109.184:45643
2023-02-01T09:47:20.143191624 DEBUG pvxs.client.io Search tick 9
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 78077465 73747076
...
2023-02-01T09:47:20.143277785 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:20.143325875 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 78077465
0030 : 73747076 31123456 78077465 73747076
...
2023-02-01T09:47:20.143335375 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:20.143350705 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:20.143358015 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:20.143364915 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
2023-02-01T09:47:20.143367795 DEBUG pvxs.server.staticsource 0x6e4528 claim 'testpv1'
errlog: lost 22 messages
2023-02-01T09:47:21.138767288 DEBUG pvxs.client.setup Chan GC sweep 'testpv1':''
2023-02-01T09:47:21.138808328 INFO pvxs.client.setup implied cancel of opa on channel 'testpv2'
# Timeout testpv2
2023-02-01T09:47:21.138939579 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:47:21.138955600 DEBUG pvxs.client.io Search tick 10
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:21.139005590 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:21.139055820 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:21.139065050 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:21.139079280 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:21.139085161 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:21.139092111 DEBUG pvxs.server.io   disclaim testpv3
2023-02-01T09:47:22.139777955 DEBUG pvxs.client.io Search tick 11
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 79077465
0030 : 73747076 32123456 7A077465 73747076
...
2023-02-01T09:47:22.139875756 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:22.139916756 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 02123456 79077465
0030 : 73747076 32123456 7A077465 73747076
...
2023-02-01T09:47:22.139925226 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:22.139940856 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:22.139947736 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:22.139956086 DEBUG pvxs.server.io   disclaim testpv2
2023-02-01T09:47:22.139958406 DEBUG pvxs.server.io   disclaim testpv3
2023-02-01T09:47:23.140468688 DEBUG pvxs.client.io Search tick 12
2023-02-01T09:47:24.141577826 DEBUG pvxs.client.io Search tick 13
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:24.141664446 DEBUG pvxs.client.io Search to 172.17.0.1:43587 ucast
2023-02-01T09:47:24.141705397 DEBUG pvxs.udp.io UDP 0x7f4cf8001590 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : D5AC0103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:24.141714897 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:54700 -> 172.17.0.1:43587 @1 (0.0.0.0:43587)
2023-02-01T09:47:24.141731177 DEBUG pvxs.udp.io Ignore as originated for 172.17.0.1:43587
2023-02-01T09:47:24.141764727 DEBUG pvxs.server.io 45.33.109.184:54700 searching
2023-02-01T09:47:24.141773617 DEBUG pvxs.server.io   disclaim testpv3
2023-02-01T09:47:25.142473532 DEBUG pvxs.client.io Search tick 14
2023-02-01T09:47:26.139065094 INFO pvxs.client.setup implied cancel of opa on channel 'testpv3'
# Timeout testpv3
2023-02-01T09:47:26.139145894 DEBUG pvxs.client.setup context 0x6e3388 close
2023-02-01T09:47:26.139401196 DEBUG pvxs.udp.setup Stop listening for UDP 172.17.0.1:43587
2023-02-01T09:47:26.139554378 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce0000900
2023-02-01T09:47:26.139692159 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cdc000900
2023-02-01T09:47:26.139842340 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:26.139975091 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:26.140084492 DEBUG pvxs.udp.setup Stop listening for UDP 0.0.0.0:43587
2023-02-01T09:47:26.140179333 DEBUG pvxs.server.setup Server disabled listener on [::]:34861
2023-02-01T09:47:26.140209463 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:26.140288913 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:26.140406104 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce8000900
2023-02-01T09:47:26.140511155 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce4000900
2023-02-01T09:47:26.140578056 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:26.140674096 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:26.140776407 DEBUG pvxs.udp.setup Stop listening for UDP 172.17.0.1:43587
2023-02-01T09:47:26.140820138 DEBUG pvxs.udp.setup Stop listening for UDP 172.17.255.255:43587
2023-02-01T09:47:26.140866538 DEBUG pvxs.server.setup Server disabled listener on 172.17.0.1:34525
2023-02-01T09:47:26.140901548 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:26.140967509 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:26.141073900 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf0000900
2023-02-01T09:47:26.141155510 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cec0008c0
2023-02-01T09:47:26.141217301 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:26.141280431 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:26.141496793 DEBUG pvxs.udp.setup Stop listening for UDP 172.17.0.1:43587
2023-02-01T09:47:26.141650414 DEBUG pvxs.udp.setup Stop listening for UDP 172.17.255.255:43587
2023-02-01T09:47:26.141695634 DEBUG pvxs.server.setup Server disabled listener on 172.17.0.1:45643
2023-02-01T09:47:26.141718405 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:26.141754055 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:26.141914266 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf8000900
2023-02-01T09:47:26.141961026 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf4001160

# In testFwdVia(192.168.49.1)
2023-02-01T09:47:26.142177078 INFO pvxs.loop Enter loop worker for 0x7f4cf4001160 using epoll
2023-02-01T09:47:26.142341209 INFO pvxs.loop Enter loop worker for 0x7f4cf8000900 using epoll
2023-02-01T09:47:26.142454280 DEBUG pvxs.iface refresh forced after 15.0 sec
2023-02-01T09:47:26.142647542 DEBUG pvxs.iface Ignoring interface 'lo' address family=17
2023-02-01T09:47:26.142665132 DEBUG pvxs.iface Ignoring interface 'eth0' address family=17
2023-02-01T09:47:26.142669062 DEBUG pvxs.iface Ignoring interface 'docker0' address family=17
2023-02-01T09:47:26.142672022 DEBUG pvxs.iface Ignoring interface 'br-67a3e997d373' address family=17
2023-02-01T09:47:26.142674812 DEBUG pvxs.iface Ignoring interface 'veth9ba2dc7' address family=17
2023-02-01T09:47:26.142724292 DEBUG pvxs.iface Found interface 1 "lo" w/ 2 127.0.0.1
2023-02-01T09:47:26.142769123 DEBUG pvxs.iface Found interface 2 "eth0" w/ 2 45.33.109.184
2023-02-01T09:47:26.142794733 DEBUG pvxs.iface Found interface 101480 "docker0" w/ 2 172.17.0.1
2023-02-01T09:47:26.142816783 DEBUG pvxs.iface Found interface 223161 "br-67a3e997d373" w/ 2 192.168.49.1
2023-02-01T09:47:26.142842023 DEBUG pvxs.iface Found interface 1 "lo" w/ 10 [::1]
2023-02-01T09:47:26.142867054 DEBUG pvxs.iface Found interface 2 "eth0" w/ 10 [2600:3c01::f03c:93ff:fe35:1c56]
2023-02-01T09:47:26.142890714 DEBUG pvxs.iface Found interface 2 "eth0" w/ 10 [fe80::f03c:93ff:fe35:1c56]%2
2023-02-01T09:47:26.142910824 DEBUG pvxs.iface Found interface 101480 "docker0" w/ 10 [fe80::42:3ff:fe99:c51d]%101480
2023-02-01T09:47:26.142937734 DEBUG pvxs.iface Found interface 223161 "br-67a3e997d373" w/ 10 [fe80::42:6dff:fe81:6b2a]%223161
2023-02-01T09:47:26.142961724 DEBUG pvxs.iface Found interface 223167 "veth9ba2dc7" w/ 10 [fe80::78f0:e3ff:fe41:b586]%223167
2023-02-01T09:47:26.142988935 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:33072 as lo
2023-02-01T09:47:26.143005815 DEBUG pvxs.udp.setup Listening for SEARCH on 192.168.49.1:33072
2023-02-01T09:47:26.144922110 DEBUG pvxs.udp.setup Listening for SEARCH on 192.168.49.255:33072
2023-02-01T09:47:26.145381043 INFO pvxs.loop Enter loop worker for 0x7f4cec000900 using epoll
2023-02-01T09:47:26.145524414 INFO pvxs.loop Enter loop worker for 0x7f4cf0000900 using epoll
2023-02-01T09:47:26.145616165 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:33072 as lo
2023-02-01T09:47:26.145650605 DEBUG pvxs.udp.setup Listening for SEARCH on 192.168.49.1:33072
2023-02-01T09:47:26.145939258 DEBUG pvxs.udp.setup Listening for SEARCH on 192.168.49.255:33072
2023-02-01T09:47:26.146163469 DEBUG pvxs.tcp.setup Address 192.168.49.1:44884 in use
2023-02-01T09:47:26.146197270 WARN pvxs.tcp.setup Server unable to bind port 44884, falling back to 192.168.49.1:34857
2023-02-01T09:47:26.146456782 INFO pvxs.loop Enter loop worker for 0x7f4ce4000900 using epoll
2023-02-01T09:47:26.146624663 INFO pvxs.loop Enter loop worker for 0x7f4ce8000900 using epoll
2023-02-01T09:47:26.146806424 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:33072 as lo
2023-02-01T09:47:26.146864565 DEBUG pvxs.udp.setup Listening for SEARCH on 0.0.0.0:33072
2023-02-01T09:47:26.147111997 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:47:26.147237288 DEBUG pvxs.server.setup Server starting
2023-02-01T09:47:26.147253758 DEBUG pvxs.server.setup Server enabled listener on 192.168.49.1:44884
2023-02-01T09:47:26.147325808 DEBUG pvxs.udp.setup Start listening for UDP 192.168.49.1:33072
2023-02-01T09:47:26.147410049 DEBUG pvxs.udp.setup Start listening for UDP 192.168.49.255:33072
2023-02-01T09:47:26.147459710 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:26.147484900 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:47:26.147593711 DEBUG pvxs.server.setup Server starting
2023-02-01T09:47:26.147608191 DEBUG pvxs.server.setup Server enabled listener on 192.168.49.1:34857
2023-02-01T09:47:26.147635791 DEBUG pvxs.udp.setup Start listening for UDP 192.168.49.1:33072
2023-02-01T09:47:26.147677771 DEBUG pvxs.udp.setup Start listening for UDP 192.168.49.255:33072
2023-02-01T09:47:26.147780292 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:26.147785352 DEBUG pvxs.server.setup Server Starting
2023-02-01T09:47:26.147828882 DEBUG pvxs.server.setup Server starting
2023-02-01T09:47:26.147838252 DEBUG pvxs.server.setup Server enabled listener on [::]:46710
2023-02-01T09:47:26.147860683 DEBUG pvxs.udp.setup Start listening for UDP 0.0.0.0:33072
2023-02-01T09:47:26.147898073 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:26.147994664 INFO pvxs.loop Enter loop worker for 0x7f4cdc000900 using epoll
2023-02-01T09:47:26.148111505 INFO pvxs.loop Enter loop worker for 0x7f4ce0000900 using epoll
2023-02-01T09:47:26.148247086 DEBUG pvxs.client.setup Using UDP Rx port 35698
2023-02-01T09:47:26.148322436 INFO pvxs.client.io Searching to 192.168.49.1:33072 unicast
2023-02-01T09:47:26.148449887 INFO pvxs.udp.setup Bound to UDP 0.0.0.0:33072 as lo
2023-02-01T09:47:26.148477748 INFO pvxs.client.io Listening for beacons on 192.168.49.1:33072
2023-02-01T09:47:26.148588548 DEBUG pvxs.udp.setup Start listening for UDP 192.168.49.1:33072
2023-02-01T09:47:26.148649419 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:47:26.148661799 DEBUG pvxs.client.io Search tick 0
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:26.148780620 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:26.148808050 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:26.148831510 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:26.148858261 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:27.149782946 DEBUG pvxs.client.io Search tick 1
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:27.149868387 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:27.149917257 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:27.149926677 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:27.149943108 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:28.150777583 DEBUG pvxs.client.io Search tick 2
2023-02-01T09:47:29.153785445 DEBUG pvxs.client.io Search tick 3
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:29.153863835 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:29.153907366 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 78077465
0030 : 73747076 31  
2023-02-01T09:47:29.153917546 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:29.153934386 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:30.154942513 DEBUG pvxs.client.io Search tick 4
2023-02-01T09:47:31.148829144 INFO pvxs.client.setup implied cancel of opa on channel 'testpv1'
# Timeout testpv1
2023-02-01T09:47:31.149048005 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:47:31.149065785 DEBUG pvxs.client.io Search tick 5
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 79077465
0030 : 73747076 32  
2023-02-01T09:47:31.149115516 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:31.149160966 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 79077465
0030 : 73747076 32  
2023-02-01T09:47:31.149173936 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:31.149193446 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:32.149783920 DEBUG pvxs.client.io Search tick 6
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 02123456 78077465
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:32.149878851 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:32.149930521 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 02123456 78077465
0030 : 73747076 31123456 79077465 73747076
...
2023-02-01T09:47:32.149940861 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:32.149957511 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:33.150968858 DEBUG pvxs.client.io Search tick 7
2023-02-01T09:47:34.151783743 DEBUG pvxs.client.io Search tick 8
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 79077465
0030 : 73747076 32  
2023-02-01T09:47:34.151877544 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:34.151922094 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 79077465
0030 : 73747076 32  
2023-02-01T09:47:34.151940045 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:34.151968635 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:35.152984181 DEBUG pvxs.client.io Search tick 9
2023-02-01T09:47:36.148982128 DEBUG pvxs.client.setup Chan GC sweep 'testpv1':''
# Timeout testpv2
2023-02-01T09:47:36.149085549 INFO pvxs.client.setup implied cancel of opa on channel 'testpv2'
2023-02-01T09:47:36.149147509 DEBUG pvxs.client.setup hurryUp()
2023-02-01T09:47:36.149161890 DEBUG pvxs.client.io Search tick 10
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:36.149217570 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:36.149771124 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:36.149800025 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:36.149829615 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:37.150794441 DEBUG pvxs.client.io Search tick 11
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 02123456 79077465
0030 : 73747076 32123456 7A077465 73747076
...
2023-02-01T09:47:37.150943062 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:37.150985153 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 00000039 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 02123456 79077465
0030 : 73747076 32123456 7A077465 73747076
...
2023-02-01T09:47:37.151036193 DEBUG pvxs.udp.io UDP Rx 65, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:37.151078813 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:38.153779924 DEBUG pvxs.client.io Search tick 12
2023-02-01T09:47:39.154778200 DEBUG pvxs.client.io Search tick 13
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:39.154869631 DEBUG pvxs.client.io Search to 192.168.49.1:33072 ucast
2023-02-01T09:47:39.156773576 DEBUG pvxs.udp.io UDP 0x7f4ce0001690 event 2
0000 : CA028003 0000002D 66696E64 80000000
0010 : 00000000 00000000 00000000 00000000
0020 : 8B720103 74637000 01123456 7A077465
0030 : 73747076 33  
2023-02-01T09:47:39.156817906 DEBUG pvxs.udp.io UDP Rx 53, 45.33.109.184:35698 -> 192.168.49.1:33072 @1 (0.0.0.0:33072)
2023-02-01T09:47:39.156862606 DEBUG pvxs.udp.io Ignore as originated for 192.168.49.1:33072
2023-02-01T09:47:40.155943528 DEBUG pvxs.client.io Search tick 14
2023-02-01T09:47:41.149301265 INFO pvxs.client.setup implied cancel of opa on channel 'testpv3'
# Timeout testpv3
2023-02-01T09:47:41.149378236 DEBUG pvxs.client.setup context 0x6f5a48 close
2023-02-01T09:47:41.149719838 DEBUG pvxs.udp.setup Stop listening for UDP 192.168.49.1:33072
2023-02-01T09:47:41.149834259 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce0000900
2023-02-01T09:47:41.149959140 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cdc000900
2023-02-01T09:47:41.150007681 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:41.150196902 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:41.150225842 DEBUG pvxs.udp.setup Stop listening for UDP 0.0.0.0:33072
2023-02-01T09:47:41.150249312 DEBUG pvxs.server.setup Server disabled listener on [::]:46710
2023-02-01T09:47:41.150259253 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:41.150366663 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:41.150432284 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce8000900
2023-02-01T09:47:41.150487644 INFO pvxs.loop Exit loop worker: 0 for 0x7f4ce4000900
2023-02-01T09:47:41.150524355 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:41.150626655 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:41.150663986 DEBUG pvxs.udp.setup Stop listening for UDP 192.168.49.1:33072
2023-02-01T09:47:41.150695016 DEBUG pvxs.udp.setup Stop listening for UDP 192.168.49.255:33072
2023-02-01T09:47:41.150750666 DEBUG pvxs.server.setup Server disabled listener on 192.168.49.1:34857
2023-02-01T09:47:41.150776107 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:41.150867997 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:41.150955098 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf0000900
2023-02-01T09:47:41.151025369 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cec000900
2023-02-01T09:47:41.151079279 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:41.151149470 DEBUG pvxs.server.setup Server beacon timer expires
2023-02-01T09:47:41.151188320 DEBUG pvxs.udp.setup Stop listening for UDP 192.168.49.1:33072
2023-02-01T09:47:41.151236580 DEBUG pvxs.udp.setup Stop listening for UDP 192.168.49.255:33072
2023-02-01T09:47:41.151284001 DEBUG pvxs.server.setup Server disabled listener on 192.168.49.1:44884
2023-02-01T09:47:41.151294451 DEBUG pvxs.server.setup Server Stopping
2023-02-01T09:47:41.151336091 DEBUG pvxs.server.setup Server not running 0
2023-02-01T09:47:41.151498652 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf8000900
2023-02-01T09:47:41.151572843 INFO pvxs.loop Exit loop worker: 0 for 0x7f4cf4001160
not ok  1 - Succeeded via at least one interface

    Results
    =======
       Tests: 1  
      Passed:   0 =  0.00%
      Failed:   1 = 100.00%
mdavidsaver commented 1 year ago

One of the behaviors which is puzzling me is:

... pvxs.udp.io UDP Rx 53, 45.33.109.184:40324 -> 45.33.109.184:46464 @1 (0.0.0.0:46464)
... pvxs.udp.io Ignore as originated for 45.33.109.184:46464

Here unicast traffic to/from one local (but not localhost) interface address is being routed through the loopback interface (the @1).

... pvxs.udp.io UDP Rx 53, 192.168.1.249:46288 -> 192.168.1.249:54416 @3 (0.0.0.0:54416)
... pvxs.udp.io Forward as originated for 192.168.1.249:54416

When I run this test myself (Linux 5.10.0-21-amd64) these unicasts are routed through the corresponding non-loopback interface (@3).

I can't explain this difference. So I don't know whether this is a question of Linux kernel version or of system configuration.

jbellister-slac commented 1 year ago

Hmm.. so just for added context the output I pasted above is from Red Hat 7 on a cloud server where I can mess around with stuff (3.10.0-1160.71.1.el7.x86_64). It's also what I ran pvxinfo -D on in #31

I see the same problem with routing through @1and Ignore as originated on Red Hat 6 on the SLAC network with an even older kernel.

I tried the same build on a different cloud server (same provider) except using recent debian (5.10.0-18-amd64) and the test ran just fine.

mdavidsaver commented 1 year ago 
$ ip -4 route list table all
192.168.1.0/24 dev br0 proto kernel scope link src 192.168.1.1 
broadcast 127.0.0.0 dev lo table local proto kernel scope link src 127.0.0.1 
local 127.0.0.0/8 dev lo table local proto kernel scope host src 127.0.0.1 
local 127.0.0.1 dev lo table local proto kernel scope host src 127.0.0.1 
broadcast 127.255.255.255 dev lo table local proto kernel scope link src 127.0.0.1 
broadcast 192.168.1.0 dev br0 table local proto kernel scope link src 192.168.1.1 
local 192.168.1.1 dev br0 table local proto kernel scope host src 192.168.1.1 
broadcast 192.168.1.255 dev br0 table local proto kernel scope link src 192.168.1.1

Adding table all shows the automatic and normally hidden "local" and "broadcast" routing tables.

I'm wondering if there has been some change to the automatic entiries in the "local" table (aka. the proto kernel lines). Specifically the equivalents of this line:

local 192.168.1.1 dev br0 table local proto kernel scope host src 192.168.1.1
jbellister-slac commented 1 year ago 
$ ip -4 route list table all
default via 45.33.109.1 dev eth0 proto dhcp metric 100 
45.33.109.0/24 dev eth0 proto kernel scope link src 45.33.109.184 metric 100 
172.17.0.0/16 dev docker0 proto kernel scope link src 172.17.0.1 
192.168.49.0/24 dev br-67a3e997d373 proto kernel scope link src 192.168.49.1 
broadcast 45.33.109.0 dev eth0 table local proto kernel scope link src 45.33.109.184 
local 45.33.109.184 dev eth0 table local proto kernel scope host src 45.33.109.184 
broadcast 45.33.109.255 dev eth0 table local proto kernel scope link src 45.33.109.184 
broadcast 127.0.0.0 dev lo table local proto kernel scope link src 127.0.0.1 
local 127.0.0.0/8 dev lo table local proto kernel scope host src 127.0.0.1 
local 127.0.0.1 dev lo table local proto kernel scope host src 127.0.0.1 
broadcast 127.255.255.255 dev lo table local proto kernel scope link src 127.0.0.1 
broadcast 172.17.0.0 dev docker0 table local proto kernel scope link src 172.17.0.1 
local 172.17.0.1 dev docker0 table local proto kernel scope host src 172.17.0.1 
broadcast 172.17.255.255 dev docker0 table local proto kernel scope link src 172.17.0.1 
broadcast 192.168.49.0 dev br-67a3e997d373 table local proto kernel scope link src 192.168.49.1 
local 192.168.49.1 dev br-67a3e997d373 table local proto kernel scope host src 192.168.49.1 
broadcast 192.168.49.255 dev br-67a3e997d373 table local proto kernel scope link src 192.168.49.1
jbellister-slac commented 1 year ago

As an additional data point, this also isn't working on a linuxRT server with a newer 4.X kernel version. Not sure about the unit tests but just the functionality itself, with multiple IOCs started on the same server only one will respond.

uname -a
Linux cpu-b084-sp18 4.14.139-rt66 #1 SMP PREEMPT RT Mon Sep 30 14:33:17 PDT 2019 x86_64 GNU/Linux
cat /etc/os-release
NAME=Buildroot
VERSION=2019.08
ID=buildroot
VERSION_ID=2019.08
PRETTY_NAME="Buildroot 2019.08"
mdavidsaver commented 1 year ago

I've pushed another iteration, further relaxing the checks.

AppVeyorBot commented 1 year ago

:white_check_mark: Build pvxs 1.0.847 completed (commit https://github.com/mdavidsaver/pvxs/commit/2f5a9e328f by @mdavidsaver)

jbellister-slac commented 1 year ago

Thanks! This does get the unit test to pass now. I'm still waiting on the linuxRT case though, will report back when I know more.

jbellister-slac commented 1 year ago

Alright, this functionality looks good for our tested use cases now! We did notice an issue where when bringing up multiple pvxs servers on the same host pvlist will only return pv names from the first one started. But this also is the case with the pvAccessCPP module under epics-base, so something that could be looked at separately later.

AppVeyorBot commented 1 year ago

:white_check_mark: Build pvxs 1.0.863 completed (commit https://github.com/mdavidsaver/pvxs/commit/51c85c23ae by @mdavidsaver)

mdavidsaver commented 1 year ago

Ok, thank you for testing. I'll take this as good enough for now.