Intermittent "Address already in use" error

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.

John,

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

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.

John

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

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.

John,

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

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

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.

[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.