Re: A couple of questions related to a rfcomm server

Hi Peter,

Em Mon, 25 Jul 2011 23:05:17 +0100, Peter Hurley  
[off-list ref] escreveu:

Hi Sérgio,

On Sun, 2011-07-24 at 18:08 -0400, Sérgio Capela wrote:

quoted

Hi Peter,

....

quoted

quoted

If you have to have server-side discovery, you could only perform
inquiry with one controller at a time. That way, the other  

controller's

quoted

available for new rfcomm connections (assuming your client  

load-balances

quoted

like that...).

Yep, that is what I'm doing. I bind one adapter to the rfcomm server and
use the other one for discovery and content delivery. The main process
thread is the accept server and both the inquiry and the content  
delivery
are done in threads launched for the purpose. I also made more tests
recently and what is happening is that as soon as the inquiry starts the
server stops accepting connections and starts processing inquiry result
events, however, after a couple of minutes I can see the server both
accepting and processing new connections and new inquiry result events.
The end result is that launching an inquiry leads me to loose possible
connections during a few minutes which is excessive for this case where
inquiries would be launched regularly.

Inquiry in the host stack does serialize wrt. several other ioctl
functions; however, this is per device. Running a simple test here
produces expected results, ie. concurrent discovery and connections:
  1. Start inquiry on device hci1. eg.,
         hcitool -i hci1 inq --length=30
  2. Initiate connection on device hci0. In my case, turning on a
     bluetooth headset initiates a connection. Of course, the headset
     was previously paired.

You may need to confirm where/what your threads are blocked on (well, at
least your main process thread that should be blocked on the accept
syscall). Stack backtrace in gdb would clear that up.

I was able to test this today to make sure that a block was not the cause  
of the problem. The thread isn't blocked since it remains printing to  
stdout on the accept thread.

I'm calling the client from a separate machine using the following shell  
command:

while [ 1 ]; do ./rfcomm-client; sleep 5; done

where rfcomm-client is the simple example found in the web from the  
bluetooth introduction book.

The response from my server is:

waiting for connection
waiting for connection
waiting for connection
accepted connection from 00:15:83:15:A3:10
received [{"sala":"Sala  
tziranda","conteudos":[{"i":"qualquercoisa","t":"qualquercoisa2","d":"a"}]}]
thread created and detached
waiting for connection
thread end
waiting for connection
waiting for connection
waiting for connection
accepted connection from 00:15:83:15:A3:10
received [{"sala":"Sala  
tziranda","conteudos":[{"i":"qualquercoisa","t":"qualquercoisa2","d":"a"}]}]
thread created and detached
waiting for connection
thread end
waiting for connection
waiting for connection
waiting for connection
accepted connection from 00:15:83:15:A3:10
received [{"sala":"Sala  
tziranda","conteudos":[{"i":"qualquercoisa","t":"qualquercoisa2","d":"a"}]}]
thread created and detached
waiting for connection
thread end
waiting for connection
waiting for connection
waiting for connection
accepted connection from 00:15:83:15:A3:10
received [{"sala":"Sala  
tziranda","conteudos":[{"i":"qualquercoisa","t":"qualquercoisa2","d":"a"}]}]
thread created and detached
thread end
waiting for connection
waiting for connection
waiting for connection

where "waiting for connection" is written to stdout before the accept  
call. The timeout for the accept is of 1.5 seconds.

In attachment I send two logs with my results when I turn on the rssi  
inquiry. For testing purposes I initiate the inquiry when receiving a  
client connection if one isn't already running.

- ssh-output.txt is the log for the client where the error message I get  
is presented in one line followed by the time in seconds in another;

- shell-output.txt is the log for the server where both the accept server  
messages and the inquiry messages are present. The content of the file is  
similar to the one already presented except for the following:
	-- inquiry start logged with two lines: "Inquiry" and "Starting inquiry  
with RSSI..." which appears whenever I start a inquiry;
	-- inquiry results: "<TZ_OK> RSSI 188  Time 1312194878" which shows the  
result of a curl call from within the program followed by a "RSSI" value  
and time in seconds.

 From the server log it can be seen that I initiate a inquiry in response  
to a connection and start receiving inquiry responses at time 1312194729  
and at the same time I stop receiving connections despite the "waiting for  
connection" logged output. Inspecting the client log I see six failed  
connection attempts from Time 1312194740 to time 1312194791. Going to the  
sever log again I can see that I then receive 3 connection from the client  
with the inquiry still running as seen below.

<TZ_OK> RSSI 200  Time 1312194794
waiting for connection
accepted connection from 00:15:83:15:A3:10
received [{"sala":"Sala  
tziranda","conteudos":[{"i":"qualquercoisa","t":"qualquercoisa2","d":"a"}]}]
thread created and detached
waiting for connection
thread end
waiting for connection
waiting for connection
<TZ_OK> RSSI 190  Time 1312194799

<TZ_OK> RSSI 182  Time 1312194801
accepted connection from 00:15:83:15:A3:10
received [{"sala":"Sala  
tziranda","conteudos":[{"i":"qualquercoisa","t":"qualquercoisa2","d":"a"}]}]
thread created and detached
waiting for connection
thread end
<TZ_OK> RSSI 181  Time 1312194801

<TZ_OK> RSSI 186  Time 1312194804
waiting for connection
accepted connection from 00:15:83:15:A3:10
received [{"sala":"Sala  
tziranda","conteudos":[{"i":"qualquercoisa","t":"qualquercoisa2","d":"a"}]}]
thread created and detached
waiting for connection
thread end
waiting for connection
<TZ_OK> RSSI 189  Time 1312194809

I then start another inquiry:

<TZ_OK> RSSI 190  Time 1312194811
<TZ_OK>accepted connection from 00:15:83:15:A3:10
received [{"sala":"Sala  
tziranda","conteudos":[{"i":"qualquercoisa","t":"qualquercoisa2","d":"a"}]}]
thread created and detached
Inquiry
waiting for connection
Starting inquiry with RSSI...
thread end
  RSSI 189  Time 1312194812

And start loosing connections again:

uh oh: Invalid argument
Time 1312194823

quoted

quoted

quoted

Another question is related to a rfcomm client getting into D state  

and

quoted

quoted

thus not killable.

...

quoted

quoted

Although I'm not certain that they would fix the problem you're  

having,

quoted

I just posted a patch series that resolves some issues with lost  

wakeups

quoted

in rfcomm and l2cap. They need testing. You'd need patches 1~4 of 7.

Please feel free to reply direct regarding whether you can test these
and what that outcome was.

I suppose those patches would be available in the git sources right? At
the moment I can't test it but in a week or two I will try to compile  
the
sources and unless I encounter some problem I will reply in this topic.

Well, right now, those patches are on the mailing list. I was really
looking to get some more testing on them _prior_ to them making their
way into the kernel. They're mostly associated with missing wakeups --
although it's possible they could fix the D state client, I couldn't
hypothesize how the rfcomm socket could become uninterruptible from what
I fixed. They may be unrelated.

I thought the patches were on the user side of things and not on the  
kernel side. I can't really test this since I can't even afford the disk  
space needed for the kernel compilation because I'm making these tests in  
a resource limited machine. Also I can't make the machine unstable.

Regards,
Sérgio Capela

Regards,
Peter

-- 
Sérgio Pedro dos Santos Capela - Tziranda

Polo Tecnológico de Lisboa
Edifício Empresarial 3
1600-546 Lisboa

Telf:  21 314 09 83
Telml: 96 491 94 37
Email: ssc@tziranda.com