Re: pvget -m timeout after first value

[Michael Davidsaver <mdavidsaver@gmail.com>]

On 10/29/18 10:46 AM, Kasemir, Kay wrote:
> .. As you can see from the -d output, I have EPICS_PVA_ADDR_LIST set to 10.0.2.15, the IP of the VM, which is fine for pvget.
> .. Pvinfo never shows anything for the other IP or broadcast addresses:
> 
> $ EPICS_PVA_ADDR_LIST=192.168.122.255 pvinfo training:ai1
> training:ai1 Error: channel destroyed
> $ EPICS_PVA_ADDR_LIST=192.168.122.1 pvinfo training:ai1
> training:ai1 Error: channel destroyed
> $ EPICS_PVA_ADDR_LIST=10.0.2.15 pvinfo training:ai1
> training:ai1 Error: channel destroyed
> $ EPICS_PVA_ADDR_LIST=10.0.2.255 pvinfo training:ai1
> training:ai1 Error: channel destroyed

Yes, something funny is happening.  Below is what 'pvinfo -d' on a machine
with two NICs should look like.  Note the "Broadcast address #1" which is
missing in your case.

From the ordering in your log it looks like somehow at attempt is being
made to send the GetField message before the TCP connection is created.
This smells like a race condition.

> 2018-10-29T13:32:21.451 UDP Rx (53) 0.0.0.0:50068 <- 10.0.2.15:43452
> training:ai1 Error: channel destroyed
> 2018-10-29T13:32:21.451 UDP socket 0.0.0.0:0 closed.
> 2018-10-29T13:32:21.451 Connecting to PVA server: 10.0.2.15:48086.





successful 'pvinfo -d' on a machine with two NICs.

> 2018-10-29T10:53:28.158 Broadcast address #0: 198.129.223.255:5076. (not unicast)
> 2018-10-29T10:53:28.158 Broadcast address #1: 192.168.210.255:5076. (not unicast)
> 2018-10-29T10:53:28.158 Setting up UDP for interface 198.129.219.251/255.255.248.0, broadcast 198.129.223.255, dest <none>.
> 2018-10-29T10:53:28.158 Creating datagram socket from: 198.129.219.251:5076.
> 2018-10-29T10:53:28.158 Creating datagram socket from: 198.129.223.255:5076.
> 2018-10-29T10:53:28.158 Setting up UDP for interface 192.168.210.1/255.255.255.0, broadcast 192.168.210.255, dest <none>.
> 2018-10-29T10:53:28.158 Creating datagram socket from: 192.168.210.1:5076.
> 2018-10-29T10:53:28.158 Creating datagram socket from: 192.168.210.255:5076.
> 2018-10-29T10:53:28.158 Creating datagram socket from: 224.0.0.128:5076.
> 2018-10-29T10:53:28.158 Local multicast enabled on 127.0.0.1/224.0.0.128:5076.
> 2018-10-29T10:53:28.158 Sending 52 bytes 0.0.0.0:48789 -> 198.129.223.255:5076.
> 2018-10-29T10:53:28.158 Sending 52 bytes 0.0.0.0:48789 -> 192.168.210.255:5076.
> 2018-10-29T10:53:28.158 UDP Rx (52) 192.168.210.255:5076 <- 192.168.210.1:48789
> 2018-10-29T10:53:28.158 UDP Rx (53) 0.0.0.0:48789 <- 192.168.210.1:57632
> 2018-10-29T10:53:28.158 Connecting to PVA server: 192.168.210.1:5075.
> 2018-10-29T10:53:28.158 Opening socket to PVA server 192.168.210.1:5075, attempt 1.
> 2018-10-29T10:53:28.158 Socket connected to PVA server: 192.168.210.1:5075.
> 2018-10-29T10:53:28.159 Acquiring transport to 192.168.210.1:5075.
> 2018-10-29T10:53:28.159 Connected to PVA server: 192.168.210.1:5075.
> TST:iq structure
> .......
> 2018-10-29T10:53:28.160 Releasing TCP transport to 192.168.210.1:5075.
> 2018-10-29T10:53:28.160 TCP socket to 192.168.210.1:5075 is to be closed.
> 2018-10-29T10:53:28.160 UDP socket 0.0.0.0:0 closed.
> 2018-10-29T10:53:28.160 UDP Rx (0) 0.0.0.0:48789 <- 192.168.210.1:57632
> 2018-10-29T10:53:28.160 UDP socket 198.129.219.251:5076 closed.
> 2018-10-29T10:53:28.160 UDP Rx (0) 198.129.219.251:5076 <- <Ukn Addr Type>
> 2018-10-29T10:53:28.160 UDP socket 198.129.223.255:5076 closed.
> 2018-10-29T10:53:28.160 UDP Rx (0) 198.129.223.255:5076 <- <Ukn Addr Type>
> 2018-10-29T10:53:28.160 UDP socket 192.168.210.1:5076 closed.
> 2018-10-29T10:53:28.160 UDP Rx (0) 192.168.210.1:5076 <- <Ukn Addr Type>
> 2018-10-29T10:53:28.160 UDP socket 192.168.210.255:5076 closed.
> 2018-10-29T10:53:28.160 UDP Rx (0) 192.168.210.255:5076 <- 192.168.210.1:48789
> 2018-10-29T10:53:28.160 UDP socket 224.0.0.128:5076 closed.
> 2018-10-29T10:53:28.160 UDP Rx (0) 224.0.0.128:5076 <- <Ukn Addr Type>