Intermittent "Address already in use" error

Intermittent "Address already in use" error

[John Freeman]

I am developing an application that is similar to a Hands-free service
written in python.

 From time to time, I encounter an "Address already in use" error when
attempting to bind a socket to a particular local adapter.  The python
code looks like:

    Listener = BluetoothSocket(SCO)
    Listener.bind((addr1, ))
    Listener.listen(1)

strace shows this as:

    3328  socket(PF_BLUETOOTH, SOCK_SEQPACKET, 2)               = 5
    3328  bind(5, {sa_family=AF_BLUETOOTH, 
sa_data="\xa2\xc7\x07\x83\x15\x00\x13\xad\x76\x2d\xf4\xf2\x42\x09"...}, 8) = 0
    3328  listen(5, 1)                                          = 0

Subsequently, in a separate python thread (is this significant?), I issue:

    sock, whence = Listener.accept()

strace shows this as:

    3343  accept(5,  <unfinished ...>
    ...
    3343  accept(5,  <unfinished ...>
    ...
    3343  <... accept resumed> {sa_family=AF_BLUETOOTH, 
sa_data="\x4e\xe4\xec\xfd\x1d\x00\xb4\x3b\x82\x04\x20\x04\xbb\xb7"...}, [8]) = 10

After many send() and recv() calls on the socket, it is closed.

Sometimes, the accept-recv-send-close cycle is repeated a number of times.

At the conclusion of the program the Listener socket is always closed.
Because, initially, it looked like the problem was related to not
closing this socket, I added logging so that I could be absolutely
sure it had been closed.

Now that you understand what the program does, we can get down to
explaining the problem.

I can run the program muliple times with no error, but occasionally
the

    Listener.bind((addr1, ))

raises a Bluetooth error (98, 'Address already in use')

When this happens, I find that there is a file /sys/class/bluetooth/sco
that contains:

    A2:C7:07:83:15:00 00:00:00:00:00:00 4

When we don't experience this problem, this file doesn't exist or is empty.

The contents of the file correspond to the bind() call, but I would
expect this to be cleaned-up on a close() of the listener.  Usually it
is, but sometimes not.  There are no obvious correlations with external
events as far as I can tell.

The problem persists as long as /sys/class/bluetooth/sco is non-empty,
and I have not discovered any way to continue other than to reboot,
which causes the file to disappear.

Any pointers on where to look next would be greatly appreciated.

Re: Intermittent "Address already in use" error

[Brad Midgley]

John,

> From time to time, I encounter an "Address already in use" error when
> attempting to bind a socket to a particular local adapter.  The python
> code looks like:
>
>   Listener = BluetoothSocket(SCO)
>   Listener.bind((addr1, ))
>   Listener.listen(1)

Is the error appearing when you want to rebind a short time after it
was used? Maybe you need to setsockopt SO_REUSEADDR just like you
would if you wanted to quickly rebind a tcp serversocket.

-- 
Brad Midgley

Re: Intermittent "Address already in use" error

[John Freeman]

Brad Midgley wrote:
> John,
> 
>> From time to time, I encounter an "Address already in use" error when
>> attempting to bind a socket to a particular local adapter.  The python
>> code looks like:
>>
>>   Listener = BluetoothSocket(SCO)
>>   Listener.bind((addr1, ))
>>   Listener.listen(1)
> 
> Is the error appearing when you want to rebind a short time after it
> was used? Maybe you need to setsockopt SO_REUSEADDR just like you
> would if you wanted to quickly rebind a tcp serversocket.

Brad,

Thanks for the suggestion.  At first sight, that seemed like a possible cause. 
However, further testing shows that I can make another attempt a few seconds 
(limited by the speed of my fingers) after the socket has been closed, and that 
it is usually successful.

When it fails, /sys/class/bluetooth/sco contains:

    A2:C7:07:83:15:00 00:00:00:00:00:00 4

where "A2:C7:07:83:15:00" matches addr1 in the code above.  Normally, content 
appears in /sys/class/bluetooth/sco at the point of bind(), is modified slightly 
by listen(), then disappears on close of the Listener socket.

Once it gets into this state, all further attempts to bind fail with "Address 
already in use" ... until I reboot.

I haven't been able to pin down the exact circumstances that trigger the problem 
other than that it seems more likely to occur following a program run that fails 
with an unhandled exception.  That is, it seems like things aren't cleaned-up 
correctly sometimes. Unfortunately, I can't make it happen at will.

Any more ideas?

John.

Re: Intermittent "Address already in use" error

[Brad Midgley]

John

> Once it gets into this state, all further attempts to bind fail with
> "Address already in use" ... until I reboot.

if you're using kernel modules, you might be able to unload/reload a
bluetooth related kernel module to restore it. This would also help
narrowing down the cause.

-- 
Brad Midgley

Re: Intermittent "Address already in use" error

[John Freeman]

Brad Midgley wrote:
>> Once it gets into this state, all further attempts to bind fail with
>> "Address already in use" ... until I reboot.
> 
> if you're using kernel modules, you might be able to unload/reload a
> bluetooth related kernel module to restore it. This would also help
> narrowing down the cause.

The bad news is that I can't unload the sco or bluetooth modules when the 
problem occurs because they are allegedly "in use".

The good news is that I have found a combination of circumstances that makes the 
problem hard-on rather than intermittent.  As a result, I have discovered some 
additional symptoms.  In addition to the /sys/class/bluetooth/sco file that is 
not cleaned-up, there is also a /sys/class/bluetooth/rfcomm file with contents 
that correspond to a listen() on a RFCOMM socket.  There is also a leftover SDP 
entry arising from advertise_service() even after stop_advertising() has been 
called.

 From what I know of sysfs (learned during the past 24 hours), these entries are 
controlled by reference counts, so it looks like the counts are getting screwed 
somewhere.

Can anyone suggest where I should start looking?

John.

Re: Intermittent "Address already in use" error

[Brad Midgley]

John,

> Can anyone suggest where I should start looking?

Are you using a recent kernel and bluez? Do you have example code that
will cause the problem? Even better if it is in script like python.

-- 
Brad Midgley

Re: Intermittent "Address already in use" error

[John Freeman]

Brad Midgley wrote:
>> Can anyone suggest where I should start looking?
> 
> Are you using a recent kernel and bluez?

Very recent:
Kernel  2.6.29.5-84.fc10.i686
bluez-4.30-2.fc10.i386

 > Do you have example code that
 > will cause the problem? Even better if it is in script like python.

The code that causes the problem is 4000 lines of python, most of which I can't 
publish; you probably wouldn't want to look at it anyway.  I haven't been able 
to reduce it to a simple example because minor changes cause the problem to 
disappear.  Even running strace on the program makes the problem go away, so it 
looks like it's timing-related.

I was asking where in kernel/bluez code should I start looking.

Re: Intermittent "Address already in use" error

[John Freeman]

John Freeman wrote:
> Brad Midgley wrote:
>>> Can anyone suggest where I should start looking?
>> Are you using a recent kernel and bluez?
> 
> Very recent:
> Kernel  2.6.29.5-84.fc10.i686
> bluez-4.30-2.fc10.i386
> 
>  > Do you have example code that
>  > will cause the problem? Even better if it is in script like python.

[Red face mode]
Now I know the superficial cause of the problem.  The program ran hcidump:
subprocess.Popen(['hcidump', '-i', adapterId, '-w', fname])
in order to gather info on some other problems.  Under some circumstances it 
didn't clean up the process before terminating.

Killing the hcidump cleaned up the files in /sys/class/bluetooth and I no longer 
get the error.

If anyone can explain why, I'd be very interested.