sco connection issue for BlueZ 4.x on kernel 2.6.29

sco connection issue for BlueZ 4.x on kernel 2.6.29

[Lan Zhu]

Can not accept incoming SCO connection. Kernel version 2.6.29. Kernel
log is as below. Is this a kernel bug? Is there any fix already for
this?

<6>[  158.339691] sco_connect_ind: hdev hci0, bdaddr CA:D3:10:55:0C:00
    -------// receive incoming sco
<6>[  158.518554] sco_connect_cfm: hcon cf18ee00 bdaddr CA:D3:10:55:0C:00 status
<6>[  158.721160] sco_connect_cfm: hcon cf149c00 bdaddr CA:D3:10:55:0C:00 status
<6>[  158.728851] sco_conn_add: hcon cf149c00 conn cc772640
<6>[  158.734313] sco_conn_ready: conn cc772640
-----------// handle sco connection complete
<6>[  158.738800] sco_sock_init: sk cf18c400
-----------// start handle sco socket
<6>[  158.742858] __sco_chan_add: conn cc772640
<6>[  159.693023] sco_sock_accept: sk ccfdf400 timeo 0
<6>[  159.708038] sco_sock_accept: new socket cf18c400
<6>[  159.713073] sco_sock_getsockopt: sk cf18c400
<6>[  159.717834] sco_sock_getsockopt_old: sk cf18c400
<6>[  159.722839] sco_sock_getsockopt_old: mtu 180
<6>[  159.727661] sco_sock_getname: sock ce9d80a0, sk cf18c400
<6>[  159.733398] sco_sock_getname: sock ce9d80a0, sk cf18c400
<6>[  159.739166] sco_sock_release: sock ce9d80a0, sk cf18c400
-----------// don't know why it call sco_sock_release
<6>[  159.745025] sco_sock_clear_timer: sock cf18c400 state 1
<6>[  159.750671] sco_sock_close: sk cf18c400 state 1 conn cc772640 socket ce9d8
<6>[  159.758453] sco_chan_del: sk cf18c400, conn cc772640, err 104
<6>[  159.764770] sco_sock_kill: sk cf18c400 state 9
<6>[  159.769592] sco_sock_destruct: sk cf18c400
------------// destruct sco socket, and disconnect SCO connection
<6>[  159.782745] l2cap_disconn_ind: hcon cf149c00
<6>[  159.787384] hci_acl_disconn: cf149c00
<6>[  159.950805] hci_disconn_complete_evt: hci0 status 0
<6>[  159.956207] l2cap_disconn_cfm: hcon cf149c00 reason 22
<6>[  159.961730] sco_disconn_cfm: hcon cf149c00 reason 22
-------------// sco disconnected
<6>[  159.967102] sco_conn_del: hcon cf149c00 conn cc772640, err 103
<6>[  162.130523] hci_disconn_complete_evt: hci0 status 0
<6>[  162.136291] l2cap_disconn_cfm: hcon cf18ee00 reason 19
<6>[  162.149871] sco_disconn_cfm: hcon cf18ee00 reason 19
<4>[  165.382141] done EDISCO CTRL ENABLE
<7>[  165.386077] sholes-panel:  edisco_ctrl_enable_te

Thanks,
Zhu Lan

Re: sco connection issue for BlueZ 4.x on kernel 2.6.29

[Marcel Holtmann]

Hi,

> Can not accept incoming SCO connection. Kernel version 2.6.29. Kernel
> log is as below. Is this a kernel bug? Is there any fix already for
> this?
> 
> <6>[  158.339691] sco_connect_ind: hdev hci0, bdaddr CA:D3:10:55:0C:00
>     -------// receive incoming sco
> <6>[  158.518554] sco_connect_cfm: hcon cf18ee00 bdaddr CA:D3:10:55:0C:00 status
> <6>[  158.721160] sco_connect_cfm: hcon cf149c00 bdaddr CA:D3:10:55:0C:00 status
> <6>[  158.728851] sco_conn_add: hcon cf149c00 conn cc772640
> <6>[  158.734313] sco_conn_ready: conn cc772640
> -----------// handle sco connection complete
> <6>[  158.738800] sco_sock_init: sk cf18c400
> -----------// start handle sco socket
> <6>[  158.742858] __sco_chan_add: conn cc772640
> <6>[  159.693023] sco_sock_accept: sk ccfdf400 timeo 0
> <6>[  159.708038] sco_sock_accept: new socket cf18c400
> <6>[  159.713073] sco_sock_getsockopt: sk cf18c400
> <6>[  159.717834] sco_sock_getsockopt_old: sk cf18c400
> <6>[  159.722839] sco_sock_getsockopt_old: mtu 180
> <6>[  159.727661] sco_sock_getname: sock ce9d80a0, sk cf18c400
> <6>[  159.733398] sco_sock_getname: sock ce9d80a0, sk cf18c400
> <6>[  159.739166] sco_sock_release: sock ce9d80a0, sk cf18c400
> -----------// don't know why it call sco_sock_release
> <6>[  159.745025] sco_sock_clear_timer: sock cf18c400 state 1
> <6>[  159.750671] sco_sock_close: sk cf18c400 state 1 conn cc772640 socket ce9d8
> <6>[  159.758453] sco_chan_del: sk cf18c400, conn cc772640, err 104
> <6>[  159.764770] sco_sock_kill: sk cf18c400 state 9
> <6>[  159.769592] sco_sock_destruct: sk cf18c400
> ------------// destruct sco socket, and disconnect SCO connection
> <6>[  159.782745] l2cap_disconn_ind: hcon cf149c00
> <6>[  159.787384] hci_acl_disconn: cf149c00
> <6>[  159.950805] hci_disconn_complete_evt: hci0 status 0
> <6>[  159.956207] l2cap_disconn_cfm: hcon cf149c00 reason 22
> <6>[  159.961730] sco_disconn_cfm: hcon cf149c00 reason 22
> -------------// sco disconnected
> <6>[  159.967102] sco_conn_del: hcon cf149c00 conn cc772640, err 103
> <6>[  162.130523] hci_disconn_complete_evt: hci0 status 0
> <6>[  162.136291] l2cap_disconn_cfm: hcon cf18ee00 reason 19
> <6>[  162.149871] sco_disconn_cfm: hcon cf18ee00 reason 19
> <4>[  165.382141] done EDISCO CTRL ENABLE
> <7>[  165.386077] sholes-panel:  edisco_ctrl_enable_te

what kind of program are you using?

Regards

Marcel

Re: sco connection issue for BlueZ 4.x on kernel 2.6.29

[Lan Zhu]

Hi Marcel,

2009/8/8 Marcel Holtmann <marcel@holtmann.org>:
> Hi,
>
>> Can not accept incoming SCO connection. Kernel version 2.6.29. Kernel
>> log is as below. Is this a kernel bug? Is there any fix already for
>> this?
>>
>> <6>[  158.339691] sco_connect_ind: hdev hci0, bdaddr CA:D3:10:55:0C:00
>>     -------// receive incoming sco
>> <6>[  158.518554] sco_connect_cfm: hcon cf18ee00 bdaddr CA:D3:10:55:0C:0=
0 status
>> <6>[  158.721160] sco_connect_cfm: hcon cf149c00 bdaddr CA:D3:10:55:0C:0=
0 status
>> <6>[  158.728851] sco_conn_add: hcon cf149c00 conn cc772640
>> <6>[  158.734313] sco_conn_ready: conn cc772640
>> -----------// handle sco connection complete
>> <6>[  158.738800] sco_sock_init: sk cf18c400
>> -----------// start handle sco socket
>> <6>[  158.742858] __sco_chan_add: conn cc772640
>> <6>[  159.693023] sco_sock_accept: sk ccfdf400 timeo 0
>> <6>[  159.708038] sco_sock_accept: new socket cf18c400
>> <6>[  159.713073] sco_sock_getsockopt: sk cf18c400
>> <6>[  159.717834] sco_sock_getsockopt_old: sk cf18c400
>> <6>[  159.722839] sco_sock_getsockopt_old: mtu 180
>> <6>[  159.727661] sco_sock_getname: sock ce9d80a0, sk cf18c400
>> <6>[  159.733398] sco_sock_getname: sock ce9d80a0, sk cf18c400
>> <6>[  159.739166] sco_sock_release: sock ce9d80a0, sk cf18c400
>> -----------// don't know why it call sco_sock_release
>> <6>[  159.745025] sco_sock_clear_timer: sock cf18c400 state 1
>> <6>[  159.750671] sco_sock_close: sk cf18c400 state 1 conn cc772640 sock=
et ce9d8
>> <6>[  159.758453] sco_chan_del: sk cf18c400, conn cc772640, err 104
>> <6>[  159.764770] sco_sock_kill: sk cf18c400 state 9
>> <6>[  159.769592] sco_sock_destruct: sk cf18c400
>> ------------// destruct sco socket, and disconnect SCO connection
>> <6>[  159.782745] l2cap_disconn_ind: hcon cf149c00
>> <6>[  159.787384] hci_acl_disconn: cf149c00
>> <6>[  159.950805] hci_disconn_complete_evt: hci0 status 0
>> <6>[  159.956207] l2cap_disconn_cfm: hcon cf149c00 reason 22
>> <6>[  159.961730] sco_disconn_cfm: hcon cf149c00 reason 22
>> -------------// sco disconnected
>> <6>[  159.967102] sco_conn_del: hcon cf149c00 conn cc772640, err 103
>> <6>[  162.130523] hci_disconn_complete_evt: hci0 status 0
>> <6>[  162.136291] l2cap_disconn_cfm: hcon cf18ee00 reason 19
>> <6>[  162.149871] sco_disconn_cfm: hcon cf18ee00 reason 19
>> <4>[  165.382141] done EDISCO CTRL ENABLE
>> <7>[  165.386077] sholes-panel:  edisco_ctrl_enable_te
>
> what kind of program are you using?
>
> Regards
>
> Marcel
>
>
>

This issue was found when testing HFP on android platform with a
Bluetooth carkit which is not support eSCO. At first android tries to
establish eSCO with carkit, carkit response with error that eSCO is
not supported. Then carkit send SCO connect request to android
automatically, android accepted this connection but disconnect it
immediately.

I also use scotest command to test it. Run "scotest -r" on one device
to accept sco connection, run "scotest -s xx:xx:xx:xx" on another
device to send sco connection. This problem is reproduceable
everytime.

This is the hcidump log on the acceptor device,

1970-01-01 00:02:38.138427 > HCI Event: Connect Request (0x04) plen 10
    bdaddr 00:0C:55:10:D3:CA class 0x480100 type ACL
1970-01-01 00:02:38.202423 < HCI Command: Accept Connection Request (0x01|0=
x0009
) plen 7
    bdaddr 00:0C:55:10:D3:CA role 0x00
    Role: Master
1970-01-01 00:02:38.323730 > HCI Event: Command Status (0x0f) plen 4
    Accept Connection Request (0x01|0x0009) status 0x00 ncmd 1
1970-01-01 00:02:38.510467 > HCI Event: Role Change (0x12) plen 8
    status 0x00 bdaddr 00:0C:55:10:D3:CA role 0x00
    Role: Master
1970-01-01 00:02:38.534637 > HCI Event: Connect Complete (0x03) plen 11
    status 0x00 handle 1 bdaddr 00:0C:55:10:D3:CA type ACL encrypt 0x00
1970-01-01 00:02:38.552123 > HCI Event: Page Scan Repetition Mode Change (0=
x20)
plen 7
    bdaddr 00:0C:55:10:D3:CA mode 0
1970-01-01 00:02:38.579528 > HCI Event: Max Slots Change (0x1b) plen 3
    handle 1 slots 5
1970-01-01 00:02:38.603668 > HCI Event: Connect Request (0x04) plen 10
    bdaddr 00:0C:55:10:D3:CA class 0x480100 type SCO
1970-01-01 00:02:38.746490 < HCI Command: Read Remote Supported Features (0=
x01|0
x001b) plen 2
    handle 1
1970-01-01 00:02:38.827789 > HCI Event: Command Status (0x0f) plen 4
    Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1
1970-01-01 00:02:38.845550 > HCI Event: Read Remote Supported Features (0x0=
b) pl
en 11
    status 0x00 handle 1
    Features: 0xff 0xfe 0x0d 0x38 0x08 0x08 0x00 0x00
1970-01-01 00:02:38.929840 < HCI Command: Accept Synchronous Connection (0x=
01|0x
0029) plen 21
    bdaddr 00:0C:55:10:D3:CA
    0000: 40 1f 00 00 40 1f 00 00  ff ff 60 00 ff c7 03     @...@...=FF=FF`=
.=FF?
1970-01-01 00:02:39.012329 > HCI Event: Command Status (0x0f) plen 4
    Accept Synchronous Connection (0x01|0x0029) status 0x00 ncmd 1
1970-01-01 00:02:39.044982 > HCI Event: Synchronous Connect Complete (0x2c)=
 plen
 17
    status 0x00 handle 257 bdaddr 00:0C:55:10:D3:CA type SCO
    Air mode: CVSD
1970-01-01 00:02:39.062438 > HCI Event: Max Slots Change (0x1b) plen 3
    handle 1 slots 3
1970-01-01 00:02:39.371032 < HCI Command: Remote Name Request (0x01|0x0019)=
 plen
 10
    bdaddr 00:0C:55:10:D3:CA mode 2 clkoffset 0x0000
1970-01-01 00:02:39.452514 > HCI Event: Command Status (0x0f) plen 4
    Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
1970-01-01 00:02:39.509918 > HCI Event: Remote Name Req Complete (0x07) ple=
n 255

    status 0x00 bdaddr 00:0C:55:10:D3:CA name '"generic"'
1970-01-01 00:02:40.178985 < HCI Command: Disconnect (0x01|0x0006) plen 3
    handle 257 reason 0x13
    Reason: Remote User Terminated Connection
1970-01-01 00:02:40.260284 > HCI Event: Command Status (0x0f) plen 4
    Disconnect (0x01|0x0006) status 0x00 ncmd 1
1970-01-01 00:02:40.284271 > HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 257 reason 0x16
    Reason: Connection Terminated by Local Host
1970-01-01 00:02:40.301849 > HCI Event: Max Slots Change (0x1b) plen 3
    handle 1 slots 5
1970-01-01 00:02:42.486175 > HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 1 reason 0x13
    Reason: Remote User Terminated Connection


Thanks,
Zhu Lan

Re: sco connection issue for BlueZ 4.x on kernel 2.6.29

[Marcel Holtmann]

Hi,

> >> Can not accept incoming SCO connection. Kernel version 2.6.29. Kernel
> >> log is as below. Is this a kernel bug? Is there any fix already for
> >> this?
> >>
> >> <6>[  158.339691] sco_connect_ind: hdev hci0, bdaddr CA:D3:10:55:0C:00
> >>     -------// receive incoming sco
> >> <6>[  158.518554] sco_connect_cfm: hcon cf18ee00 bdaddr CA:D3:10:55:0C:00 status
> >> <6>[  158.721160] sco_connect_cfm: hcon cf149c00 bdaddr CA:D3:10:55:0C:00 status
> >> <6>[  158.728851] sco_conn_add: hcon cf149c00 conn cc772640
> >> <6>[  158.734313] sco_conn_ready: conn cc772640
> >> -----------// handle sco connection complete
> >> <6>[  158.738800] sco_sock_init: sk cf18c400
> >> -----------// start handle sco socket
> >> <6>[  158.742858] __sco_chan_add: conn cc772640
> >> <6>[  159.693023] sco_sock_accept: sk ccfdf400 timeo 0
> >> <6>[  159.708038] sco_sock_accept: new socket cf18c400
> >> <6>[  159.713073] sco_sock_getsockopt: sk cf18c400
> >> <6>[  159.717834] sco_sock_getsockopt_old: sk cf18c400
> >> <6>[  159.722839] sco_sock_getsockopt_old: mtu 180
> >> <6>[  159.727661] sco_sock_getname: sock ce9d80a0, sk cf18c400
> >> <6>[  159.733398] sco_sock_getname: sock ce9d80a0, sk cf18c400
> >> <6>[  159.739166] sco_sock_release: sock ce9d80a0, sk cf18c400
> >> -----------// don't know why it call sco_sock_release
> >> <6>[  159.745025] sco_sock_clear_timer: sock cf18c400 state 1
> >> <6>[  159.750671] sco_sock_close: sk cf18c400 state 1 conn cc772640 socket ce9d8
> >> <6>[  159.758453] sco_chan_del: sk cf18c400, conn cc772640, err 104
> >> <6>[  159.764770] sco_sock_kill: sk cf18c400 state 9
> >> <6>[  159.769592] sco_sock_destruct: sk cf18c400
> >> ------------// destruct sco socket, and disconnect SCO connection
> >> <6>[  159.782745] l2cap_disconn_ind: hcon cf149c00
> >> <6>[  159.787384] hci_acl_disconn: cf149c00
> >> <6>[  159.950805] hci_disconn_complete_evt: hci0 status 0
> >> <6>[  159.956207] l2cap_disconn_cfm: hcon cf149c00 reason 22
> >> <6>[  159.961730] sco_disconn_cfm: hcon cf149c00 reason 22
> >> -------------// sco disconnected
> >> <6>[  159.967102] sco_conn_del: hcon cf149c00 conn cc772640, err 103
> >> <6>[  162.130523] hci_disconn_complete_evt: hci0 status 0
> >> <6>[  162.136291] l2cap_disconn_cfm: hcon cf18ee00 reason 19
> >> <6>[  162.149871] sco_disconn_cfm: hcon cf18ee00 reason 19
> >> <4>[  165.382141] done EDISCO CTRL ENABLE
> >> <7>[  165.386077] sholes-panel:  edisco_ctrl_enable_te
> >
> > what kind of program are you using?
> >
> 
> This issue was found when testing HFP on android platform with a
> Bluetooth carkit which is not support eSCO. At first android tries to
> establish eSCO with carkit, carkit response with error that eSCO is
> not supported. Then carkit send SCO connect request to android
> automatically, android accepted this connection but disconnect it
> immediately.

I think we fixed all of these. Try a 2.6.31-rc5 kernel. Also you would
need to include the output of hcidump -X -V.

Regards

Marcel

Re: sco connection issue for BlueZ 4.x on kernel 2.6.29

[Lan Zhu]

Hi Marcel,

2009/8/8 Marcel Holtmann <marcel@holtmann.org>:
> Hi,
>
>> >> Can not accept incoming SCO connection. Kernel version 2.6.29. Kernel
>> >> log is as below. Is this a kernel bug? Is there any fix already for
>> >> this?
>> >>
>> >> <6>[ =A0158.339691] sco_connect_ind: hdev hci0, bdaddr CA:D3:10:55:0C=
:00
>> >> =A0 =A0 -------// receive incoming sco
>> >> <6>[ =A0158.518554] sco_connect_cfm: hcon cf18ee00 bdaddr CA:D3:10:55=
:0C:00 status
>> >> <6>[ =A0158.721160] sco_connect_cfm: hcon cf149c00 bdaddr CA:D3:10:55=
:0C:00 status
>> >> <6>[ =A0158.728851] sco_conn_add: hcon cf149c00 conn cc772640
>> >> <6>[ =A0158.734313] sco_conn_ready: conn cc772640
>> >> -----------// handle sco connection complete
>> >> <6>[ =A0158.738800] sco_sock_init: sk cf18c400
>> >> -----------// start handle sco socket
>> >> <6>[ =A0158.742858] __sco_chan_add: conn cc772640
>> >> <6>[ =A0159.693023] sco_sock_accept: sk ccfdf400 timeo 0
>> >> <6>[ =A0159.708038] sco_sock_accept: new socket cf18c400
>> >> <6>[ =A0159.713073] sco_sock_getsockopt: sk cf18c400
>> >> <6>[ =A0159.717834] sco_sock_getsockopt_old: sk cf18c400
>> >> <6>[ =A0159.722839] sco_sock_getsockopt_old: mtu 180
>> >> <6>[ =A0159.727661] sco_sock_getname: sock ce9d80a0, sk cf18c400
>> >> <6>[ =A0159.733398] sco_sock_getname: sock ce9d80a0, sk cf18c400
>> >> <6>[ =A0159.739166] sco_sock_release: sock ce9d80a0, sk cf18c400
>> >> -----------// don't know why it call sco_sock_release
>> >> <6>[ =A0159.745025] sco_sock_clear_timer: sock cf18c400 state 1
>> >> <6>[ =A0159.750671] sco_sock_close: sk cf18c400 state 1 conn cc772640=
 socket ce9d8
>> >> <6>[ =A0159.758453] sco_chan_del: sk cf18c400, conn cc772640, err 104
>> >> <6>[ =A0159.764770] sco_sock_kill: sk cf18c400 state 9
>> >> <6>[ =A0159.769592] sco_sock_destruct: sk cf18c400
>> >> ------------// destruct sco socket, and disconnect SCO connection
>> >> <6>[ =A0159.782745] l2cap_disconn_ind: hcon cf149c00
>> >> <6>[ =A0159.787384] hci_acl_disconn: cf149c00
>> >> <6>[ =A0159.950805] hci_disconn_complete_evt: hci0 status 0
>> >> <6>[ =A0159.956207] l2cap_disconn_cfm: hcon cf149c00 reason 22
>> >> <6>[ =A0159.961730] sco_disconn_cfm: hcon cf149c00 reason 22
>> >> -------------// sco disconnected
>> >> <6>[ =A0159.967102] sco_conn_del: hcon cf149c00 conn cc772640, err 10=
3
>> >> <6>[ =A0162.130523] hci_disconn_complete_evt: hci0 status 0
>> >> <6>[ =A0162.136291] l2cap_disconn_cfm: hcon cf18ee00 reason 19
>> >> <6>[ =A0162.149871] sco_disconn_cfm: hcon cf18ee00 reason 19
>> >> <4>[ =A0165.382141] done EDISCO CTRL ENABLE
>> >> <7>[ =A0165.386077] sholes-panel: =A0edisco_ctrl_enable_te
>> >
>> > what kind of program are you using?
>> >
>>
>> This issue was found when testing HFP on android platform with a
>> Bluetooth carkit which is not support eSCO. At first android tries to
>> establish eSCO with carkit, carkit response with error that eSCO is
>> not supported. Then carkit send SCO connect request to android
>> automatically, android accepted this connection but disconnect it
>> immediately.
>
> I think we fixed all of these. Try a 2.6.31-rc5 kernel. Also you would
> need to include the output of hcidump -X -V.
>
> Regards
>
> Marcel
>
>
>

I think there is a bug in the function sco_sock_getsockopt_old() in sco.c.

I changed the code like below and then test sco again, incoming sco
connection can be created successfully now.

@@ -719,7 +715,10 @@ static int sco_sock_getsockopt_old(struct socket *sock=
, int
                break;
        }

-       release_sock(sk);
+    if (err !=3D 0) {
+           release_sock(sk);
+    }
        return err;


Thanks,
Zhu Lan

Re: sco connection issue for BlueZ 4.x on kernel 2.6.29

[Marcel Holtmann]

Hi,

> >> >> Can not accept incoming SCO connection. Kernel version 2.6.29. Kernel
> >> >> log is as below. Is this a kernel bug? Is there any fix already for
> >> >> this?
> >> >>
> >> >> <6>[  158.339691] sco_connect_ind: hdev hci0, bdaddr CA:D3:10:55:0C:00
> >> >>     -------// receive incoming sco
> >> >> <6>[  158.518554] sco_connect_cfm: hcon cf18ee00 bdaddr CA:D3:10:55:0C:00 status
> >> >> <6>[  158.721160] sco_connect_cfm: hcon cf149c00 bdaddr CA:D3:10:55:0C:00 status
> >> >> <6>[  158.728851] sco_conn_add: hcon cf149c00 conn cc772640
> >> >> <6>[  158.734313] sco_conn_ready: conn cc772640
> >> >> -----------// handle sco connection complete
> >> >> <6>[  158.738800] sco_sock_init: sk cf18c400
> >> >> -----------// start handle sco socket
> >> >> <6>[  158.742858] __sco_chan_add: conn cc772640
> >> >> <6>[  159.693023] sco_sock_accept: sk ccfdf400 timeo 0
> >> >> <6>[  159.708038] sco_sock_accept: new socket cf18c400
> >> >> <6>[  159.713073] sco_sock_getsockopt: sk cf18c400
> >> >> <6>[  159.717834] sco_sock_getsockopt_old: sk cf18c400
> >> >> <6>[  159.722839] sco_sock_getsockopt_old: mtu 180
> >> >> <6>[  159.727661] sco_sock_getname: sock ce9d80a0, sk cf18c400
> >> >> <6>[  159.733398] sco_sock_getname: sock ce9d80a0, sk cf18c400
> >> >> <6>[  159.739166] sco_sock_release: sock ce9d80a0, sk cf18c400
> >> >> -----------// don't know why it call sco_sock_release
> >> >> <6>[  159.745025] sco_sock_clear_timer: sock cf18c400 state 1
> >> >> <6>[  159.750671] sco_sock_close: sk cf18c400 state 1 conn cc772640 socket ce9d8
> >> >> <6>[  159.758453] sco_chan_del: sk cf18c400, conn cc772640, err 104
> >> >> <6>[  159.764770] sco_sock_kill: sk cf18c400 state 9
> >> >> <6>[  159.769592] sco_sock_destruct: sk cf18c400
> >> >> ------------// destruct sco socket, and disconnect SCO connection
> >> >> <6>[  159.782745] l2cap_disconn_ind: hcon cf149c00
> >> >> <6>[  159.787384] hci_acl_disconn: cf149c00
> >> >> <6>[  159.950805] hci_disconn_complete_evt: hci0 status 0
> >> >> <6>[  159.956207] l2cap_disconn_cfm: hcon cf149c00 reason 22
> >> >> <6>[  159.961730] sco_disconn_cfm: hcon cf149c00 reason 22
> >> >> -------------// sco disconnected
> >> >> <6>[  159.967102] sco_conn_del: hcon cf149c00 conn cc772640, err 103
> >> >> <6>[  162.130523] hci_disconn_complete_evt: hci0 status 0
> >> >> <6>[  162.136291] l2cap_disconn_cfm: hcon cf18ee00 reason 19
> >> >> <6>[  162.149871] sco_disconn_cfm: hcon cf18ee00 reason 19
> >> >> <4>[  165.382141] done EDISCO CTRL ENABLE
> >> >> <7>[  165.386077] sholes-panel:  edisco_ctrl_enable_te
> >> >
> >> > what kind of program are you using?
> >> >
> >>
> >> This issue was found when testing HFP on android platform with a
> >> Bluetooth carkit which is not support eSCO. At first android tries to
> >> establish eSCO with carkit, carkit response with error that eSCO is
> >> not supported. Then carkit send SCO connect request to android
> >> automatically, android accepted this connection but disconnect it
> >> immediately.
> >
> > I think we fixed all of these. Try a 2.6.31-rc5 kernel. Also you would
> > need to include the output of hcidump -X -V.
>
> I think there is a bug in the function sco_sock_getsockopt_old() in sco.c.
> 
> I changed the code like below and then test sco again, incoming sco
> connection can be created successfully now.
> 
> @@ -719,7 +715,10 @@ static int sco_sock_getsockopt_old(struct socket *sock, int
>                 break;
>         }
> 
> -       release_sock(sk);
> +    if (err != 0) {
> +           release_sock(sk);
> +    }
>         return err;

that is not it for sure. The release_sock() is the unlock function and
your patch create a locking imbalance.

Regards

Marcel

Re: sco connection issue for BlueZ 4.x on kernel 2.6.29

[Lan Zhu]

Hi Marcel,

2009/8/12 Marcel Holtmann <marcel@holtmann.org>:
> Hi,
>
>> >> >> Can not accept incoming SCO connection. Kernel version 2.6.29. Ker=
nel
>> >> >> log is as below. Is this a kernel bug? Is there any fix already fo=
r
>> >> >> this?
>> >> >>
>> >> >> <6>[ =A0158.339691] sco_connect_ind: hdev hci0, bdaddr CA:D3:10:55=
:0C:00
>> >> >> =A0 =A0 -------// receive incoming sco
>> >> >> <6>[ =A0158.518554] sco_connect_cfm: hcon cf18ee00 bdaddr CA:D3:10=
:55:0C:00 status
>> >> >> <6>[ =A0158.721160] sco_connect_cfm: hcon cf149c00 bdaddr CA:D3:10=
:55:0C:00 status
>> >> >> <6>[ =A0158.728851] sco_conn_add: hcon cf149c00 conn cc772640
>> >> >> <6>[ =A0158.734313] sco_conn_ready: conn cc772640
>> >> >> -----------// handle sco connection complete
>> >> >> <6>[ =A0158.738800] sco_sock_init: sk cf18c400
>> >> >> -----------// start handle sco socket
>> >> >> <6>[ =A0158.742858] __sco_chan_add: conn cc772640
>> >> >> <6>[ =A0159.693023] sco_sock_accept: sk ccfdf400 timeo 0
>> >> >> <6>[ =A0159.708038] sco_sock_accept: new socket cf18c400
>> >> >> <6>[ =A0159.713073] sco_sock_getsockopt: sk cf18c400
>> >> >> <6>[ =A0159.717834] sco_sock_getsockopt_old: sk cf18c400
>> >> >> <6>[ =A0159.722839] sco_sock_getsockopt_old: mtu 180
>> >> >> <6>[ =A0159.727661] sco_sock_getname: sock ce9d80a0, sk cf18c400
>> >> >> <6>[ =A0159.733398] sco_sock_getname: sock ce9d80a0, sk cf18c400
>> >> >> <6>[ =A0159.739166] sco_sock_release: sock ce9d80a0, sk cf18c400
>> >> >> -----------// don't know why it call sco_sock_release
>> >> >> <6>[ =A0159.745025] sco_sock_clear_timer: sock cf18c400 state 1
>> >> >> <6>[ =A0159.750671] sco_sock_close: sk cf18c400 state 1 conn cc772=
640 socket ce9d8
>> >> >> <6>[ =A0159.758453] sco_chan_del: sk cf18c400, conn cc772640, err =
104
>> >> >> <6>[ =A0159.764770] sco_sock_kill: sk cf18c400 state 9
>> >> >> <6>[ =A0159.769592] sco_sock_destruct: sk cf18c400
>> >> >> ------------// destruct sco socket, and disconnect SCO connection
>> >> >> <6>[ =A0159.782745] l2cap_disconn_ind: hcon cf149c00
>> >> >> <6>[ =A0159.787384] hci_acl_disconn: cf149c00
>> >> >> <6>[ =A0159.950805] hci_disconn_complete_evt: hci0 status 0
>> >> >> <6>[ =A0159.956207] l2cap_disconn_cfm: hcon cf149c00 reason 22
>> >> >> <6>[ =A0159.961730] sco_disconn_cfm: hcon cf149c00 reason 22
>> >> >> -------------// sco disconnected
>> >> >> <6>[ =A0159.967102] sco_conn_del: hcon cf149c00 conn cc772640, err=
 103
>> >> >> <6>[ =A0162.130523] hci_disconn_complete_evt: hci0 status 0
>> >> >> <6>[ =A0162.136291] l2cap_disconn_cfm: hcon cf18ee00 reason 19
>> >> >> <6>[ =A0162.149871] sco_disconn_cfm: hcon cf18ee00 reason 19
>> >> >> <4>[ =A0165.382141] done EDISCO CTRL ENABLE
>> >> >> <7>[ =A0165.386077] sholes-panel: =A0edisco_ctrl_enable_te
>> >> >
>> >> > what kind of program are you using?
>> >> >
>> >>
>> >> This issue was found when testing HFP on android platform with a
>> >> Bluetooth carkit which is not support eSCO. At first android tries to
>> >> establish eSCO with carkit, carkit response with error that eSCO is
>> >> not supported. Then carkit send SCO connect request to android
>> >> automatically, android accepted this connection but disconnect it
>> >> immediately.
>> >
>> > I think we fixed all of these. Try a 2.6.31-rc5 kernel. Also you would
>> > need to include the output of hcidump -X -V.
>>
>> I think there is a bug in the function sco_sock_getsockopt_old() in sco.=
c.
>>
>> I changed the code like below and then test sco again, incoming sco
>> connection can be created successfully now.
>>
>> @@ -719,7 +715,10 @@ static int sco_sock_getsockopt_old(struct socket *s=
ock, int
>> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 break;
>> =A0 =A0 =A0 =A0 }
>>
>> - =A0 =A0 =A0 release_sock(sk);
>> + =A0 =A0if (err !=3D 0) {
>> + =A0 =A0 =A0 =A0 =A0 release_sock(sk);
>> + =A0 =A0}
>> =A0 =A0 =A0 =A0 return err;
>
> that is not it for sure. The release_sock() is the unlock function and
> your patch create a locking imbalance.
>
> Regards
>
> Marcel
>
>
>

This issue is fixed by Johan's commit of "Don't enable the SCO server
socket when not necessary"
(http://git.kernel.org/?p=3Dbluetooth/bluez.git;a=3Dcommit;h=3Dcd6678404659=
a1bf6449b5b1d48b17883d895aef)

Thanks,
Zhu Lan

Re: sco connection issue for BlueZ 4.x on kernel 2.6.29

[Marcel Holtmann]

Hi,

> >> >> >> Can not accept incoming SCO connection. Kernel version 2.6.29. Kernel
> >> >> >> log is as below. Is this a kernel bug? Is there any fix already for
> >> >> >> this?
> >> >> >>
> >> >> >> <6>[  158.339691] sco_connect_ind: hdev hci0, bdaddr CA:D3:10:55:0C:00
> >> >> >>     -------// receive incoming sco
> >> >> >> <6>[  158.518554] sco_connect_cfm: hcon cf18ee00 bdaddr CA:D3:10:55:0C:00 status
> >> >> >> <6>[  158.721160] sco_connect_cfm: hcon cf149c00 bdaddr CA:D3:10:55:0C:00 status
> >> >> >> <6>[  158.728851] sco_conn_add: hcon cf149c00 conn cc772640
> >> >> >> <6>[  158.734313] sco_conn_ready: conn cc772640
> >> >> >> -----------// handle sco connection complete
> >> >> >> <6>[  158.738800] sco_sock_init: sk cf18c400
> >> >> >> -----------// start handle sco socket
> >> >> >> <6>[  158.742858] __sco_chan_add: conn cc772640
> >> >> >> <6>[  159.693023] sco_sock_accept: sk ccfdf400 timeo 0
> >> >> >> <6>[  159.708038] sco_sock_accept: new socket cf18c400
> >> >> >> <6>[  159.713073] sco_sock_getsockopt: sk cf18c400
> >> >> >> <6>[  159.717834] sco_sock_getsockopt_old: sk cf18c400
> >> >> >> <6>[  159.722839] sco_sock_getsockopt_old: mtu 180
> >> >> >> <6>[  159.727661] sco_sock_getname: sock ce9d80a0, sk cf18c400
> >> >> >> <6>[  159.733398] sco_sock_getname: sock ce9d80a0, sk cf18c400
> >> >> >> <6>[  159.739166] sco_sock_release: sock ce9d80a0, sk cf18c400
> >> >> >> -----------// don't know why it call sco_sock_release
> >> >> >> <6>[  159.745025] sco_sock_clear_timer: sock cf18c400 state 1
> >> >> >> <6>[  159.750671] sco_sock_close: sk cf18c400 state 1 conn cc772640 socket ce9d8
> >> >> >> <6>[  159.758453] sco_chan_del: sk cf18c400, conn cc772640, err 104
> >> >> >> <6>[  159.764770] sco_sock_kill: sk cf18c400 state 9
> >> >> >> <6>[  159.769592] sco_sock_destruct: sk cf18c400
> >> >> >> ------------// destruct sco socket, and disconnect SCO connection
> >> >> >> <6>[  159.782745] l2cap_disconn_ind: hcon cf149c00
> >> >> >> <6>[  159.787384] hci_acl_disconn: cf149c00
> >> >> >> <6>[  159.950805] hci_disconn_complete_evt: hci0 status 0
> >> >> >> <6>[  159.956207] l2cap_disconn_cfm: hcon cf149c00 reason 22
> >> >> >> <6>[  159.961730] sco_disconn_cfm: hcon cf149c00 reason 22
> >> >> >> -------------// sco disconnected
> >> >> >> <6>[  159.967102] sco_conn_del: hcon cf149c00 conn cc772640, err 103
> >> >> >> <6>[  162.130523] hci_disconn_complete_evt: hci0 status 0
> >> >> >> <6>[  162.136291] l2cap_disconn_cfm: hcon cf18ee00 reason 19
> >> >> >> <6>[  162.149871] sco_disconn_cfm: hcon cf18ee00 reason 19
> >> >> >> <4>[  165.382141] done EDISCO CTRL ENABLE
> >> >> >> <7>[  165.386077] sholes-panel:  edisco_ctrl_enable_te
> >> >> >
> >> >> > what kind of program are you using?
> >> >> >
> >> >>
> >> >> This issue was found when testing HFP on android platform with a
> >> >> Bluetooth carkit which is not support eSCO. At first android tries to
> >> >> establish eSCO with carkit, carkit response with error that eSCO is
> >> >> not supported. Then carkit send SCO connect request to android
> >> >> automatically, android accepted this connection but disconnect it
> >> >> immediately.
> >> >
> >> > I think we fixed all of these. Try a 2.6.31-rc5 kernel. Also you would
> >> > need to include the output of hcidump -X -V.
> >>
> >> I think there is a bug in the function sco_sock_getsockopt_old() in sco.c.
> >>
> >> I changed the code like below and then test sco again, incoming sco
> >> connection can be created successfully now.
> >>
> >> @@ -719,7 +715,10 @@ static int sco_sock_getsockopt_old(struct socket *sock, int
> >>                 break;
> >>         }
> >>
> >> -       release_sock(sk);
> >> +    if (err != 0) {
> >> +           release_sock(sk);
> >> +    }
> >>         return err;
> >
> > that is not it for sure. The release_sock() is the unlock function and
> > your patch create a locking imbalance.
>
> This issue is fixed by Johan's commit of "Don't enable the SCO server
> socket when not necessary"
> (http://git.kernel.org/?p=bluetooth/bluez.git;a=commit;h=cd6678404659a1bf6449b5b1d48b17883d895aef)

so if Android would finally start using upstream BlueZ and not ship
their own stuff, we could have avoided this non-sense.

Regards

Marcel