RE: Qualification testing - rfcomm

RE: Qualification testing - rfcomm

[Max Krasnyansky]

At 11:13 PM 6/9/2003, Marcel Holtmann wrote:
>Hi Daryl,
>
>> > But the problem with
>> > 
>> >     Send failed. Resource temporarily unavailable(11)
>> > 
>> > is a problem in the rctest program, because we don't handle 
>> > correctly EAGAIN errors. We should go on and try sending data 
>> > and don't exit with an error message. Maybe it is a good idea 
>> > to put in a select and check for the time when it is safe to 
>> > send the first data packets.
>> 
>> Shouldn't send() block?
>
>yes it should block. I think this problem is introduced with the "wait
>for complete MSC exchange" patch and I am not quite sure where the
>problem is. But the EAGAIN comes from the function sock_alloc_send_skb()
>if I am right. Max, can you please look at it.

Yes, that error comes from sock_alloc_send_skb(). And yes you're right 
it probably has something to do with MSC stuff. However I don't think it's
our bug though. It looks like MSC exchange didn't complete within 30 secs
(ie default SO_SNDTIMEO).

Here is the relevant part of the trace 
> ACL data: handle 0x0001 flags 0x02 dlen 8
    L2CAP(d): cid 0x40 len 4 [psm 3]
      RFCOMM(s): SABM: cr 1 dlci 0 pf 1 ilen 0 fcs 0x1c 
< ACL data: handle 0x0001 flags 0x02 dlen 8
    L2CAP(d): cid 0x40 len 4 [psm 3]
      RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7 
> HCI Event: Number of Completed Packets(0x13) plen 5
  01 01 00 01 00 
> ACL data: handle 0x0001 flags 0x02 dlen 8
    L2CAP(d): cid 0x40 len 4 [psm 3]
      RFCOMM(s): SABM: cr 1 dlci 2 pf 1 ilen 0 fcs 0x59 
< ACL data: handle 0x0001 flags 0x02 dlen 8
    L2CAP(d): cid 0x40 len 4 [psm 3]
      RFCOMM(s): UA: cr 1 dlci 2 pf 1 ilen 0 fcs 0x92 
> HCI Event: Number of Completed Packets(0x13) plen 5
  01 01 00 01 00 

See, that's what I meant by incomplete in my prev email. We now always send MSC after UA, 
I mean it's unconditional in the code
                 /* DLC was previously opened by PN request */
                         rfcomm_send_ua(s, dlci);

                        rfcomm_dlc_lock(d);
                        d->state = BT_CONNECTED;
                        d->state_change(d, 0);
                        rfcomm_dlc_unlock(d);

                        rfcomm_send_msc(s, 1, dlci, d->v24_sig);        
But there is no MSC in the trace.

Hold on! I think I found a bug here. We always send MSC when DLC was opened by PN
request but don't send it when DLC was opened by SABM. Ok that would explain it 
(trace doesn't have PN in it). They probably sit there and wait for MSC from us and 
in the mean time send() times out.
Should be fixed now, I'm pushing a one liner fix as we speak :)

Max

RE: Qualification testing - rfcomm

[Daryl Van Vorst]

Max,

Below is exactly why the tests were failing (well, incomplete) - the tester
was waiting for an MSC which we never sent. Thanks!

With a little luck there won't be more bugs found in those tests. :) I'll
let you know what the results are when we do another round of tests.

-Daryl.

> Here is the relevant part of the trace 
> > ACL data: handle 0x0001 flags 0x02 dlen 8
>     L2CAP(d): cid 0x40 len 4 [psm 3]
>       RFCOMM(s): SABM: cr 1 dlci 0 pf 1 ilen 0 fcs 0x1c 
> < ACL data: handle 0x0001 flags 0x02 dlen 8
>     L2CAP(d): cid 0x40 len 4 [psm 3]
>       RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7 
> > HCI Event: Number of Completed Packets(0x13) plen 5
>   01 01 00 01 00 
> > ACL data: handle 0x0001 flags 0x02 dlen 8
>     L2CAP(d): cid 0x40 len 4 [psm 3]
>       RFCOMM(s): SABM: cr 1 dlci 2 pf 1 ilen 0 fcs 0x59 
> < ACL data: handle 0x0001 flags 0x02 dlen 8
>     L2CAP(d): cid 0x40 len 4 [psm 3]
>       RFCOMM(s): UA: cr 1 dlci 2 pf 1 ilen 0 fcs 0x92 
> > HCI Event: Number of Completed Packets(0x13) plen 5
>   01 01 00 01 00 
> 
> See, that's what I meant by incomplete in my prev email. We 
> now always send MSC after UA, 
> I mean it's unconditional in the code
>                  /* DLC was previously opened by PN request */
>                          rfcomm_send_ua(s, dlci);
> 
>                         rfcomm_dlc_lock(d);
>                         d->state = BT_CONNECTED;
>                         d->state_change(d, 0);
>                         rfcomm_dlc_unlock(d);
> 
>                         rfcomm_send_msc(s, 1, dlci, 
> d->v24_sig);        
> But there is no MSC in the trace.
> 
> Hold on! I think I found a bug here. We always send MSC when 
> DLC was opened by PN request but don't send it when DLC was 
> opened by SABM. Ok that would explain it 
> (trace doesn't have PN in it). They probably sit there and 
> wait for MSC from us and 
> in the mean time send() times out.
> Should be fixed now, I'm pushing a one liner fix as we speak :)
> 
> Max
> 
> 

Qualification testing - rfcomm

[Daryl Van Vorst]

[-- Attachment #1: Type: text/plain, Size: 1605 bytes --]

Marcel,

Finally got some results on those latest rfcomm changes for qualification.
Looks like there are a few more problems. :(  But we're close. :)

TP/RFC/BV-09-C:
"Verify that the IUT handles flow control correctly when the Tester, acting
as a device conforming to Bluetooth version 1.0B, controls the data flow
using the Modem Status Command. The IUT's device role is of no importance."

The command and console output:

root@jack-00000000:~>./rctest -s -P 1 -b 20 00:A0:96:1F:83:71
rctest[351]: Connected
rctest[351]: Sending ...
rctest[351]: Send failed. Resource temporarily unavailable(11)

The IUT sends data in 5 frames, then stops for aboue 20s, then sends 5 more,
then stops, etc. Technically, this test passed because we did stop sending
data after the tester send MSC stop to the IUT. But something's clearly not
right.

There is an hcidump of the session attached.

TP/RFC/BV-12-C:
"Verify that the IUT handles aggregate flow control correctly when the
Tester, acting as a device conforming to Bleutooth version 1.0B, controls
the data flow using the Flow Control on/off commands FCon and FCoff. The
IUT's device role is of no importance."

The command and console output:

root@jack-00000000:~>./rctest -s -P 1 -b 20 00:A0:96:1F:83:71
rctest[362]: Connected
rctest[362]: Sending ...
rfcomm_recv_mcc: Unknown control type 0x18
rfcomm_recv_mcc: Unknown control type 0x28

The IUT does not respond to FCoff with FCoff, and continues sending data. It
also does not respond to FCon with FCon. 

There is an hcidump of the session attached.

-Daryl.

[-- Attachment #2: RFC_BV_09_IUT_sends_5_frames_every_20s_hcidump --]
[-- Type: application/octet-stream, Size: 1792 bytes --]

[-- Attachment #3: RFC_BV_12_IUT_does_not_reply_with_FCoff_FCon_hcidump --]
[-- Type: application/octet-stream, Size: 4864 bytes --]

[Bluez-devel] Re: Qualification testing - rfcomm

[Marcel Holtmann]

Hi Daryl,

> Finally got some results on those latest rfcomm changes for qualification.
> Looks like there are a few more problems. :(  But we're close. :)
> 
> TP/RFC/BV-09-C:
> "Verify that the IUT handles flow control correctly when the Tester, acting
> as a device conforming to Bluetooth version 1.0B, controls the data flow
> using the Modem Status Command. The IUT's device role is of no importance."
> 
> The command and console output:
> 
> root@jack-00000000:~>./rctest -s -P 1 -b 20 00:A0:96:1F:83:71
> rctest[351]: Connected
> rctest[351]: Sending ...
> rctest[351]: Send failed. Resource temporarily unavailable(11)
> 
> The IUT sends data in 5 frames, then stops for aboue 20s, then sends 5 more,
> then stops, etc. Technically, this test passed because we did stop sending
> data after the tester send MSC stop to the IUT. But something's clearly not
> right.

this looks quite right, but the rctest program don't check the error
code. If it receives EAGAIN it should try again, but it aborts.

Regards

Marcel




-------------------------------------------------------
This SF.Net email sponsored by: Parasoft
Error proof Web apps, automate testing & more.
Download & eval WebKing and get a free book.
www.parasoft.com/bulletproofapps1
_______________________________________________
Bluez-devel mailing list
Bluez-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bluez-devel

RE: Qualification testing - rfcomm

[Daryl Van Vorst]

Marcel,

You're right that it doesn't check the error code, it just exits. But that
doesn't explain why it sends 5 frames, waits for 20 seconds, and then sends
5 more.  Shouldn't send block?

I haven't yet tried to reproduce that behaviour.  So I'm not certain that
the sequence of send 5, wait 20, send 5 repeats indefinitely.  I'll take a
look at it shortly.

Thanks for the flow control patch...  I'll wait and see if anything comes
out of the above stuff before sending it out for testing.

-Daryl.

> -----Original Message-----
> From: Marcel Holtmann [mailto:marcel@rvs.uni-bielefeld.de] 
> Sent: July 11, 2003 1:55 AM
> To: Daryl Van Vorst
> Cc: BlueZ Mailing List
> Subject: Re: Qualification testing - rfcomm
> 
> 
> Hi Daryl,
> 
> > Finally got some results on those latest rfcomm changes for 
> > qualification. Looks like there are a few more problems. :( 
>  But we're 
> > close. :)
> > 
> > TP/RFC/BV-09-C:
> > "Verify that the IUT handles flow control correctly when 
> the Tester, 
> > acting as a device conforming to Bluetooth version 1.0B, 
> controls the 
> > data flow using the Modem Status Command. The IUT's device 
> role is of 
> > no importance."
> > 
> > The command and console output:
> > 
> > root@jack-00000000:~>./rctest -s -P 1 -b 20 00:A0:96:1F:83:71
> > rctest[351]: Connected
> > rctest[351]: Sending ...
> > rctest[351]: Send failed. Resource temporarily unavailable(11)
> > 
> > The IUT sends data in 5 frames, then stops for aboue 20s, 
> then sends 5 
> > more, then stops, etc. Technically, this test passed because we did 
> > stop sending data after the tester send MSC stop to the IUT. But 
> > something's clearly not right.
> 
> this looks quite right, but the rctest program don't check 
> the error code. If it receives EAGAIN it should try again, 
> but it aborts.
> 
> Regards
> 
> Marcel
> 
> 
>