perfSONAR User Q&A and Other Discussion

[Ben Nelson <>]

Hey Aaron,

Ah, it looks like I grabbed the wrong logs, but I think you are correct
that two tests weren't actually binding on the port in question.  It
must have been something else.  Here are the recent logs I meant to attach:

Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]: BEGIN
IGNORED: empty AL3S-BW4_KANS_SALT file =
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU at
/opt/perfsonar_ps/perfsonarbuoy_ma/bin/bwcollector.pl line 891, <SESS>
line 17.#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
start_endpoint: 3611456686.375400#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
run_endpoint: receiver: 198.71.46.52#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
run_endpoint: sender: 198.71.46.48#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
exec_line: iperf -B em-2.400.pas-tst.kans.net.internet2.edu -s -f b -l
44872 -m -p 5004 -u -w 100663296 -t 20 -i 1.000000#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
run_tool: tester: iperf#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
run_tool: receiver: 198.71.46.52#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
run_tool: sender: 198.71.46.48#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
start_tool: 3611456737.008985#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bind
failed: Address already in use#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU:
------------------------------------------------------------#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: Server
listening on UDP port 5004#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: Binding to
local address em-2.400.pas-tst.kans.net.internet2.edu#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: Receiving
44872 byte datagrams#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: UDP buffer
size: 201326592 Byte (WARNING: requested 100663296 Byte)#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU:
------------------------------------------------------------#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
stop_tool: 3611456765.429594#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]:
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU: bwctl:
stop_endpoint: 3611456765.430053#012#012
Jun 11 06:26:05 pas.bldc.grnoc.iu.edu bwcollector.pl[11361]: END
IGNORED: empty AL3S-BW4_KANS_SALT file =
/var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/ewY_Up0NYU at
/opt/perfsonar_ps/perfsonarbuoy_ma/bin/bwcollector.pl line 896, <SESS>
line 34.#012

It doesn't look like we had any other iperf tests running on that port,
but the bind still failed. My guess is something else was using 5004
during that period, as we had tests run fine a few hours later. 

Thanks,
Ben

On 6/11/14, 4:14 PM, Aaron Brown wrote:
> Hey Ben,
>
> Unless something is going wonky with bwctl, it should cycle through ports 
> in order. Do you see it for ports other than 5001? I’m wondering if an old 
> iperf may be lying around or something.
>
> Cheers,
> Aaron
>
> On Jun 11, 2014, at 3:53 PM, Ben Nelson 
> <>
>  wrote:
>
>> Hey Aaron,
>>
>> We're running bwctl-1.5.1-20 and using iperf ports 5001-5100.
>>
>> Thanks,
>> Ben
>>
>> On 6/11/14, 3:41 PM, Aaron Brown wrote:
>>> Hey Ben,
>>>
>>> What are the iperf port settings in bwctld.conf? Also, what version of 
>>> bwctld is it running?
>>>
>>> Cheers,
>>> Aaron
>>>
>>> On Jun 11, 2014, at 3:30 PM, Ben Nelson 
>>> <>
>>>  wrote:
>>>
>>>> Hi All,
>>>>
>>>> We've seen an issue pop up a few times where consecutive bwctl tests on
>>>> the same host manage to use the same port or iperf testing.  If the
>>>> tests are close enough, it seems like the port doesn't get freed up
>>>> quickly enough for the second test to run, and ends up failing.  Here
>>>> are some log snippets of what we see:
>>>>
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]: BEGIN
>>>> IGNORED: empty AL3S-BW4_CHIC_LOSA file =
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S at
>>>> /opt/perfsonar_ps/perfsonarbuoy_m
>>>> a/bin/bwcollector.pl line 891, <SESS> line 17.#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> start_endpoint: 3609939653.158082#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> run_endpoint: receiver: 198.71.46.56#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> run_endpoint: sender: 198.71.46.50#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> exec_line: iperf -B em-2.400.pas-tst.chic.net.internet2.edu -s -f b -l 
>>>> 4487
>>>> 2 -m -p 5001 -u -w 100663296 -t 20 -i 1.000000#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> run_tool: tester: iperf#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> run_tool: receiver: 198.71.46.56#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> run_tool: sender: 198.71.46.50#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> start_tool: 3609939684.650671#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bind
>>>> failed: Address already in use#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S:
>>>> ------------------------------------------------------------#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: Server
>>>> listening on UDP port 5001#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: Binding to
>>>> local address em-2.400.pas-tst.chic.net.internet2.edu#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: Receiving
>>>> 44872 byte datagrams#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: UDP buffer
>>>> size: 201326592 Byte (WARNING: requested 100663296 Byte)#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S:
>>>> ------------------------------------------------------------#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> stop_tool: 3609939713.725873#012#012
>>>> May 24 17:01:53 pas.bldc.grnoc.iu.edu bwcollector.pl[45056]:
>>>> /var/lib/perfsonar/perfsonarbuoy_ma/bwctl/upload/K5pQCMJl0S: bwctl:
>>>> stop_endpoint: 3609939713.726364#012#012
>>>>
>>>> Can anything be done to unbind the port quicker, so the second test is
>>>> able to finish?  Or possible a change in bwctl testing to choose a port
>>>> that hasn't been used recently?
>>>>
>>>> Thanks,
>>>> Ben
>>>>
>>>>
>>>> -- 
>>>> Ben Nelson, Systems Engineer
>>>> Indiana University GlobalNOC
>>>> <>
>>>>
>> -- 
>> Ben Nelson, Systems Engineer
>> Indiana University GlobalNOC
>> <>
>>

-- 
Ben Nelson, Systems Engineer
Indiana University GlobalNOC
<>