Hi all,
Just wondering what is the status of "bluetooth disabled with current
2.6.38-rc4"
from Justin (http://www.spinics.net/lists/linux-bluetooth/msg10745.html) and
"[BUG] usb problems in .38-rc3+"" (http://marc.info/?t=129693396800003&r=1&w=2)
from Ed? (apologies for not being able to reply to those threads)
The first one because I think I see the same problem and the second one because
for me also "hciconfig -a" makes the bluetooth adapter work. Maybe they have
a common cause.
For me, reverting 23bb57633df ("Bluetooth: Fix __hci_request synchronization
for hci_open_dev"; suggested by Justin) on top of
2.6.38-rc6-166-g493f335 makes everything work as before.
bluez version and bluetooth adapter model:
[root@koni ~]# pacman -Qo /usr/sbin/bluetoothd
/usr/sbin/bluetoothd is owned by bluez 4.89-1
[root@koni ~]# lsusb | grep i.Tech
Bus 003 Device 002: ID 13dd:0001 i.Tech Dynamic Limited
Part of bluetoothd -d dump below. The printout only really got started when
I run "hciconfig -a" after 22:01:42 (hciconfig hci0 down and hciconfig hci0 up
can also be used to make it work):
[root@koni ~]# hciconfig
hci0: Type: BR/EDR Bus: USB
BD Address: 00:0D:3C:38:xx:yy ACL MTU: 384:8 SCO MTU: 64:8
UP RUNNING
RX bytes:356 acl:0 sco:0 events:13 errors:0
TX bytes:53 acl:0 sco:0 commands:13 errors:0
[root@koni ~]# date
Mon Feb 28 22:01:42 EET 2011
[root@koni ~]# hciconfig -a
hci0: Type: BR/EDR Bus: USB
BD Address: 00:0D:3C:38:xx:yy ACL MTU: 384:8 SCO MTU: 64:8
UP RUNNING
RX bytes:356 acl:0 sco:0 events:13 errors:0
TX bytes:53 acl:0 sco:0 commands:13 errors:0
Features: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
Packet type: DM1 DH1 HV1
Link policy:
Link mode: SLAVE ACCEPT
Name: 'CSR - bc4'
Class: 0x000000
Service Classes: Unspecified
Device Class: Miscellaneous,
HCI Version: 2.0 (0x3) Revision: 0x7a6
LMP Version: 2.0 (0x3) Subversion: 0x7a6
Manufacturer: Cambridge Silicon Radio (10)
Feb 28 21:55:39 koni bluetoothd[3256]: src/rfkill.c:rfkill_event() RFKILL event
idx 0 type 1 op 0 soft 1 hard 0
Feb 28 21:55:39 koni bluetoothd[3256]: plugins/hciops.c:init_known_adapters()
Feb 28 21:56:14 koni blueman-mechanism: Starting blueman-mechanism
Feb 28 21:56:14 koni kernel: fuse init (API version 7.16)
Feb 28 21:56:14 koni blueman-mechanism: reload 0 0
Feb 28 21:56:15 koni kernel: Bluetooth: RFCOMM TTY layer initialized
Feb 28 21:56:15 koni kernel: Bluetooth: RFCOMM socket layer initialized
Feb 28 21:56:15 koni kernel: Bluetooth: RFCOMM ver 1.11
Feb 28 21:56:28 koni kernel: usb 6-1: new full speed USB device using ohci_hcd
and address 2
Feb 28 21:56:29 koni kernel: usb 6-1: New USB device found, idVendor=13dd,
idProduct=0001
Feb 28 21:56:29 koni kernel: usb 6-1: New USB device strings: Mfr=1, Product=2,
SerialNumber=0
Feb 28 21:56:29 koni kernel: usb 6-1: Product: BlueCON U2
Feb 28 21:56:29 koni kernel: usb 6-1: Manufacturer: i.Tech Dynamic
Feb 28 21:56:29 koni kernel: Bluetooth: Generic Bluetooth USB driver ver 0.6
Feb 28 21:56:29 koni bluetoothd[3256]: src/rfkill.c:rfkill_event() RFKILL event
idx 1 type 2 op 0 soft 0 hard 0
Feb 28 21:56:29 koni bluetoothd[3256]: HCI dev 0 registered
Feb 28 21:56:29 koni bluetoothd[3256]: plugins/hciops.c:init_device() hci0
Feb 28 21:56:29 koni bluetoothd[3256]: Listening for HCI events on hci0
Feb 28 21:56:29 koni bluetoothd[3256]: plugins/hciops.c:init_device() child 3317
forked
Feb 28 21:56:29 koni bluetoothd[3256]: src/rfkill.c:rfkill_event() RFKILL event
idx 1 type 2 op 2 soft 0 hard 0
Feb 28 21:56:29 koni kernel: usbcore: registered new interface driver btusb
Feb 28 21:56:29 koni bluetoothd[3256]:
plugins/hciops.c:read_local_version_complete() Got version for hci0
Feb 28 21:56:29 koni bluetoothd[3256]: plugins/hciops.c:read_bd_addr_complete()
hci0 status 0
Feb 28 21:56:29 koni bluetoothd[3256]: plugins/hciops.c:read_bd_addr_complete()
Got bdaddr for hci0
Feb 28 21:56:29 koni bluetoothd[3256]:
plugins/hciops.c:read_local_name_complete() hci0 status 0
Feb 28 21:56:29 koni bluetoothd[3256]:
plugins/hciops.c:read_local_name_complete() Got name for hci0
Feb 28 21:56:29 koni bluetoothd[3256]: plugins/hciops.c:child_exit() child 3317
exited
Feb 28 21:56:29 koni bluetoothd[3256]: HCI dev 0 up
Feb 28 21:56:29 koni bluetoothd[3256]: plugins/hciops.c:device_devup_setup()
hci0
Feb 28 21:56:44 koni blueman-mechanism: Exiting
Feb 28 22:01:45 koni bluetoothd[3256]:
plugins/hciops.c:read_local_name_complete() hci0 status 0
Feb 28 22:01:45 koni bluetoothd[3256]:
plugins/hciops.c:read_local_name_complete() Got name for hci0
Feb 28 22:01:45 koni bluetoothd[3256]:
plugins/hciops.c:read_local_features_complete() Got features for hci0
Feb 28 22:01:45 koni bluetoothd[3256]: src/adapter.c:btd_adapter_ref()
0x7f2d7b862e10: ref=1
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:hciops_read_bdaddr()
hci0
Feb 28 22:01:45 koni bluetoothd[3256]:
plugins/hciops.c:hciops_read_local_version() hci0
Feb 28 22:01:45 koni bluetoothd[3256]:
plugins/hciops.c:hciops_read_local_features() hci0
Feb 28 22:01:45 koni bluetoothd[3256]:
src/sdpd-database.c:sdp_init_services_list()
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:hciops_add_uuid() hci0
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:update_service_classes()
hci0 value 0
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:hciops_add_uuid() hci0
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:update_service_classes()
hci0 value 0
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:hciops_add_uuid() hci0
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:update_service_classes()
hci0 value 16
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:hciops_add_uuid() hci0
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/hciops.c:update_service_classes()
hci0 value 16
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/service.c:register_interface()
path /org/bluez/3256/hci0
Feb 28 22:01:45 koni bluetoothd[3256]: plugins/service.c:register_interface()
Registered interface org.bluez.Service on path /org/bluez/3256/hci0
Feb 28 22:01:45 koni bluetoothd[3256]: network/manager.c:network_server_probe()
path /org/bluez/3256/hci0
Feb 28 22:01:45 koni bluetoothd[3256]: src/adapter.c:btd_adapter_ref()
0x7f2d7b862e10: ref=2
Feb 28 22:01:45 koni bluetoothd[3256]: network/server.c:server_register()
Registered interface org.bluez.NetworkServer on path /org/bluez/3256/hci0
Feb 28 22:01:45 koni bluetoothd[3256]: serial/manager.c:proxy_probe() path
/org/bluez/3256/hci0
Feb 28 22:01:45 koni bluetoothd[3256]: src/adapter.c:btd_adapter_ref()
0x7f2d7b862e10: ref=3
Feb 28 22:01:45 koni bluetoothd[3256]: serial/proxy.c:proxy_register()
Registered interface org.bluez.SerialProxyManager on path /org/bluez/3256/hci0
Feb 28 22:01:45 koni bluetoothd[3256]: src/adapter.c:btd_adapter_ref()
0x7f2d7b862e10: ref=4
...
Mikko
On Feb 28, 2011, at 2:29 PM, Mikko Vinni wrote:
> Hi all,
>
> Just wondering what is the status of "bluetooth disabled with current
> 2.6.38-rc4"
> from Justin (http://www.spinics.net/lists/linux-bluetooth/msg10745.html
> ) and
> "[BUG] usb problems in .38-rc3+"" (http://marc.info/?t=129693396800003&r=1&w=2
> )
> from Ed? (apologies for not being able to reply to those threads)
>
good im not going crazy!!!(thought I was the only one)
> The first one because I think I see the same problem and the second
> one because
> for me also "hciconfig -a" makes the bluetooth adapter work. Maybe
> they have
> a common cause.
>
> For me, reverting 23bb57633df ("Bluetooth: Fix __hci_request
> synchronization
> for hci_open_dev"; suggested by Justin) on top of
> 2.6.38-rc6-166-g493f335 makes everything work as before.
>
thankfully the revert is not that big.. if/when I get time(in the
process of relocating)
I would not mind going through that commit and plucking things to find
exactly what's causing
the problem then go from there(if somebody gets to that before, Ill
gladly supply info and/or test anything
for them!!)
> bluez version and bluetooth adapter model:
>
> [root@koni ~]# pacman -Qo /usr/sbin/bluetoothd
> /usr/sbin/bluetoothd is owned by bluez 4.89-1
> [root@koni ~]# lsusb | grep i.Tech
> Bus 003 Device 002: ID 13dd:0001 i.Tech Dynamic Limited
>
> Part of bluetoothd -d dump below. The printout only really got
> started when
> I run "hciconfig -a" after 22:01:42 (hciconfig hci0 down and
> hciconfig hci0 up
> can also be used to make it work):
>
> [root@koni ~]# hciconfig
> hci0: Type: BR/EDR Bus: USB
> BD Address: 00:0D:3C:38:xx:yy ACL MTU: 384:8 SCO MTU: 64:8
> UP RUNNING
> RX bytes:356 acl:0 sco:0 events:13 errors:0
> TX bytes:53 acl:0 sco:0 commands:13 errors:0
>
> [root@koni ~]# date
> Mon Feb 28 22:01:42 EET 2011
> [root@koni ~]# hciconfig -a
> hci0: Type: BR/EDR Bus: USB
> BD Address: 00:0D:3C:38:xx:yy ACL MTU: 384:8 SCO MTU: 64:8
> UP RUNNING
> RX bytes:356 acl:0 sco:0 events:13 errors:0
> TX bytes:53 acl:0 sco:0 commands:13 errors:0
> Features: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
> Packet type: DM1 DH1 HV1
> Link policy:
> Link mode: SLAVE ACCEPT
> Name: 'CSR - bc4'
> Class: 0x000000
> Service Classes: Unspecified
> Device Class: Miscellaneous,
> HCI Version: 2.0 (0x3) Revision: 0x7a6
> LMP Version: 2.0 (0x3) Subversion: 0x7a6
> Manufacturer: Cambridge Silicon Radio (10)
>
>
> Feb 28 21:55:39 koni bluetoothd[3256]: src/rfkill.c:rfkill_event()
> RFKILL event
> idx 0 type 1 op 0 soft 1 hard 0
> Feb 28 21:55:39 koni bluetoothd[3256]: plugins/
> hciops.c:init_known_adapters()
> Feb 28 21:56:14 koni blueman-mechanism: Starting blueman-mechanism
> Feb 28 21:56:14 koni kernel: fuse init (API version 7.16)
> Feb 28 21:56:14 koni blueman-mechanism: reload 0 0
> Feb 28 21:56:15 koni kernel: Bluetooth: RFCOMM TTY layer initialized
> Feb 28 21:56:15 koni kernel: Bluetooth: RFCOMM socket layer
> initialized
> Feb 28 21:56:15 koni kernel: Bluetooth: RFCOMM ver 1.11
> Feb 28 21:56:28 koni kernel: usb 6-1: new full speed USB device
> using ohci_hcd
> and address 2
> Feb 28 21:56:29 koni kernel: usb 6-1: New USB device found,
> idVendor=13dd,
> idProduct=0001
> Feb 28 21:56:29 koni kernel: usb 6-1: New USB device strings: Mfr=1,
> Product=2,
> SerialNumber=0
> Feb 28 21:56:29 koni kernel: usb 6-1: Product: BlueCON U2
> Feb 28 21:56:29 koni kernel: usb 6-1: Manufacturer: i.Tech Dynamic
> Feb 28 21:56:29 koni kernel: Bluetooth: Generic Bluetooth USB driver
> ver 0.6
> Feb 28 21:56:29 koni bluetoothd[3256]: src/rfkill.c:rfkill_event()
> RFKILL event
> idx 1 type 2 op 0 soft 0 hard 0
> Feb 28 21:56:29 koni bluetoothd[3256]: HCI dev 0 registered
> Feb 28 21:56:29 koni bluetoothd[3256]: plugins/
> hciops.c:init_device() hci0
> Feb 28 21:56:29 koni bluetoothd[3256]: Listening for HCI events on
> hci0
> Feb 28 21:56:29 koni bluetoothd[3256]: plugins/
> hciops.c:init_device() child 3317
> forked
> Feb 28 21:56:29 koni bluetoothd[3256]: src/rfkill.c:rfkill_event()
> RFKILL event
> idx 1 type 2 op 2 soft 0 hard 0
> Feb 28 21:56:29 koni kernel: usbcore: registered new interface
> driver btusb
> Feb 28 21:56:29 koni bluetoothd[3256]:
> plugins/hciops.c:read_local_version_complete() Got version for hci0
> Feb 28 21:56:29 koni bluetoothd[3256]: plugins/
> hciops.c:read_bd_addr_complete()
> hci0 status 0
> Feb 28 21:56:29 koni bluetoothd[3256]: plugins/
> hciops.c:read_bd_addr_complete()
> Got bdaddr for hci0
> Feb 28 21:56:29 koni bluetoothd[3256]:
> plugins/hciops.c:read_local_name_complete() hci0 status 0
> Feb 28 21:56:29 koni bluetoothd[3256]:
> plugins/hciops.c:read_local_name_complete() Got name for hci0
> Feb 28 21:56:29 koni bluetoothd[3256]: plugins/hciops.c:child_exit()
> child 3317
> exited
> Feb 28 21:56:29 koni bluetoothd[3256]: HCI dev 0 up
> Feb 28 21:56:29 koni bluetoothd[3256]: plugins/
> hciops.c:device_devup_setup()
> hci0
> Feb 28 21:56:44 koni blueman-mechanism: Exiting
> Feb 28 22:01:45 koni bluetoothd[3256]:
> plugins/hciops.c:read_local_name_complete() hci0 status 0
> Feb 28 22:01:45 koni bluetoothd[3256]:
> plugins/hciops.c:read_local_name_complete() Got name for hci0
> Feb 28 22:01:45 koni bluetoothd[3256]:
> plugins/hciops.c:read_local_features_complete() Got features for hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: src/adapter.c:btd_adapter_ref()
> 0x7f2d7b862e10: ref=1
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:hciops_read_bdaddr()
> hci0
> Feb 28 22:01:45 koni bluetoothd[3256]:
> plugins/hciops.c:hciops_read_local_version() hci0
> Feb 28 22:01:45 koni bluetoothd[3256]:
> plugins/hciops.c:hciops_read_local_features() hci0
> Feb 28 22:01:45 koni bluetoothd[3256]:
> src/sdpd-database.c:sdp_init_services_list()
>
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:hciops_add_uuid() hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:update_service_classes()
> hci0 value 0
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:hciops_add_uuid() hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:update_service_classes()
> hci0 value 0
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:hciops_add_uuid() hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:update_service_classes()
> hci0 value 16
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:hciops_add_uuid() hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> hciops.c:update_service_classes()
> hci0 value 16
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> service.c:register_interface()
> path /org/bluez/3256/hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: plugins/
> service.c:register_interface()
> Registered interface org.bluez.Service on path /org/bluez/3256/hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: network/
> manager.c:network_server_probe()
> path /org/bluez/3256/hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: src/adapter.c:btd_adapter_ref()
> 0x7f2d7b862e10: ref=2
> Feb 28 22:01:45 koni bluetoothd[3256]: network/
> server.c:server_register()
> Registered interface org.bluez.NetworkServer on path /org/bluez/3256/
> hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: serial/
> manager.c:proxy_probe() path
> /org/bluez/3256/hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: src/adapter.c:btd_adapter_ref()
> 0x7f2d7b862e10: ref=3
> Feb 28 22:01:45 koni bluetoothd[3256]: serial/proxy.c:proxy_register()
> Registered interface org.bluez.SerialProxyManager on path /org/bluez/
> 3256/hci0
> Feb 28 22:01:45 koni bluetoothd[3256]: src/adapter.c:btd_adapter_ref()
> 0x7f2d7b862e10: ref=4
> ...
>
> Mikko
>
>
>
Hi Szymon,
* Szymon Janc <[email protected]> [2011-03-17 11:35:20 +0100]:
> > We can't send new commands before a cmd_complete for the HCI_RESET commnnd
>
> Typo: comm*a*nd
>
> > shows up.
> >
> > Reported-by: Mikko Vinni <[email protected]>
> > Reported-by: Justin P. Mattock <[email protected]>
> > Reported-by: Ed Tomlinson <[email protected]>
> > Signed-off-by: Gustavo F. Padovan <[email protected]>
> > ---
> > include/net/bluetooth/hci.h | 2 ++
> > net/bluetooth/hci_core.c | 3 +++
> > net/bluetooth/hci_event.c | 4 +++-
> > 3 files changed, 8 insertions(+), 1 deletions(-)
> >
> > diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
> > index ec6acf2..2c0d309 100644
> > --- a/include/net/bluetooth/hci.h
> > +++ b/include/net/bluetooth/hci.h
> > @@ -84,6 +84,8 @@ enum {
> > HCI_SERVICE_CACHE,
> > HCI_LINK_KEYS,
> > HCI_DEBUG_KEYS,
> > +
> > + HCI_RESET,
> > };
> >
> > /* HCI ioctl defines */
> > diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> > index b372fb8..32b82e2 100644
> > --- a/net/bluetooth/hci_core.c
> > +++ b/net/bluetooth/hci_core.c
> > @@ -534,6 +534,8 @@ int hci_dev_open(__u16 dev)
> > set_bit(HCI_INIT, &hdev->flags);
> > hdev->init_last_cmd = 0;
> >
> > + set_bit(HCI_RESET, &hdev->flags);
>
> Does this work with HCI_QUIRK_NO_RESET enabled?
> Shouldn't this bit be set only right before sending HCI_OP_RESET
> (in hci_init_req and hci_reset_req) for doing what commit msg says?
>
> Now it looks more like a workaround for initialization issue..
Ah yes, I fixed this as well now.
>
> > +
> > ret = __hci_request(hdev, hci_init_req, 0,
> > msecs_to_jiffies(HCI_INIT_TIMEOUT));
> >
> > @@ -1074,6 +1076,7 @@ static void hci_cmd_timer(unsigned long arg)
> >
> > BT_ERR("%s command tx timeout", hdev->name);
> > atomic_set(&hdev->cmd_cnt, 1);
> > + clear_bit(HCI_RESET, &hdev->flags);
> > tasklet_schedule(&hdev->cmd_task);
> > }
> >
> > diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
> > index 3fbfa50..cebe7588 100644
> > --- a/net/bluetooth/hci_event.c
> > +++ b/net/bluetooth/hci_event.c
> > @@ -183,6 +183,8 @@ static void hci_cc_reset(struct hci_dev *hdev, struct sk_buff *skb)
> >
> > BT_DBG("%s status 0x%x", hdev->name, status);
> >
> > + clear_bit(HCI_RESET, &hdev->flags);
> > +
> > hci_req_complete(hdev, HCI_OP_RESET, status);
> > }
> >
> > @@ -1847,7 +1849,7 @@ static inline void hci_cmd_status_evt(struct hci_dev *hdev, struct sk_buff *skb)
> > if (ev->opcode != HCI_OP_NOP)
> > del_timer(&hdev->cmd_timer);
> >
> > - if (ev->ncmd) {
> > + if (ev->ncmd && !test_bit(HCI_RESET, &hdev->flags)) {
> > atomic_set(&hdev->cmd_cnt, 1);
> > if (!skb_queue_empty(&hdev->cmd_q))
> > tasklet_schedule(&hdev->cmd_task);
>
> Maybe use unlikely() here?
We don't use this in Bluetooth.
--
Gustavo F. Padovan
http://profusion.mobi
> We can't send new commands before a cmd_complete for the HCI_RESET commnnd
Typo: comm*a*nd
> shows up.
>
> Reported-by: Mikko Vinni <[email protected]>
> Reported-by: Justin P. Mattock <[email protected]>
> Reported-by: Ed Tomlinson <[email protected]>
> Signed-off-by: Gustavo F. Padovan <[email protected]>
> ---
> include/net/bluetooth/hci.h | 2 ++
> net/bluetooth/hci_core.c | 3 +++
> net/bluetooth/hci_event.c | 4 +++-
> 3 files changed, 8 insertions(+), 1 deletions(-)
>
> diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
> index ec6acf2..2c0d309 100644
> --- a/include/net/bluetooth/hci.h
> +++ b/include/net/bluetooth/hci.h
> @@ -84,6 +84,8 @@ enum {
> HCI_SERVICE_CACHE,
> HCI_LINK_KEYS,
> HCI_DEBUG_KEYS,
> +
> + HCI_RESET,
> };
>
> /* HCI ioctl defines */
> diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> index b372fb8..32b82e2 100644
> --- a/net/bluetooth/hci_core.c
> +++ b/net/bluetooth/hci_core.c
> @@ -534,6 +534,8 @@ int hci_dev_open(__u16 dev)
> set_bit(HCI_INIT, &hdev->flags);
> hdev->init_last_cmd = 0;
>
> + set_bit(HCI_RESET, &hdev->flags);
Does this work with HCI_QUIRK_NO_RESET enabled?
Shouldn't this bit be set only right before sending HCI_OP_RESET
(in hci_init_req and hci_reset_req) for doing what commit msg says?
Now it looks more like a workaround for initialization issue..
> +
> ret = __hci_request(hdev, hci_init_req, 0,
> msecs_to_jiffies(HCI_INIT_TIMEOUT));
>
> @@ -1074,6 +1076,7 @@ static void hci_cmd_timer(unsigned long arg)
>
> BT_ERR("%s command tx timeout", hdev->name);
> atomic_set(&hdev->cmd_cnt, 1);
> + clear_bit(HCI_RESET, &hdev->flags);
> tasklet_schedule(&hdev->cmd_task);
> }
>
> diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
> index 3fbfa50..cebe7588 100644
> --- a/net/bluetooth/hci_event.c
> +++ b/net/bluetooth/hci_event.c
> @@ -183,6 +183,8 @@ static void hci_cc_reset(struct hci_dev *hdev, struct sk_buff *skb)
>
> BT_DBG("%s status 0x%x", hdev->name, status);
>
> + clear_bit(HCI_RESET, &hdev->flags);
> +
> hci_req_complete(hdev, HCI_OP_RESET, status);
> }
>
> @@ -1847,7 +1849,7 @@ static inline void hci_cmd_status_evt(struct hci_dev *hdev, struct sk_buff *skb)
> if (ev->opcode != HCI_OP_NOP)
> del_timer(&hdev->cmd_timer);
>
> - if (ev->ncmd) {
> + if (ev->ncmd && !test_bit(HCI_RESET, &hdev->flags)) {
> atomic_set(&hdev->cmd_cnt, 1);
> if (!skb_queue_empty(&hdev->cmd_q))
> tasklet_schedule(&hdev->cmd_task);
Maybe use unlikely() here?
--
BR
Szymon Janc
On Wednesday 16 March 2011 16:02:17 Justin Mattock wrote:
> > No, it's based on bluetooth-next (2.6.39). But you can drop the hci_cmd_timer
> > part while testing it. It's not needed unless you have and hci_reset cmd
> > timeout.
> >
> > --
> > Gustavo F. Padovan
> > http://profusion.mobi
> >
>
> o.k. works over here..
> Tested-by: Justin P. Mattock <[email protected]>
Works here too (Justin's varient on top of .38)
Tested-by: Ed Tomlinson <[email protected]>
Thanks
Ed
> here is an updated patch for the current Mainline if anybody needs it:
>
> ---
> include/net/bluetooth/hci.h | 1 +
> net/bluetooth/hci_core.c | 1 +
> net/bluetooth/hci_event.c | 4 +++-
> 3 files changed, 5 insertions(+), 1 deletions(-)
>
> diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
> index 29a7a8c..c4f4c42 100644
> --- a/include/net/bluetooth/hci.h
> +++ b/include/net/bluetooth/hci.h
> @@ -76,6 +76,7 @@ enum {
> HCI_INQUIRY,
>
> HCI_RAW,
> + HCI_RESET,
> };
>
> /* HCI ioctl defines */
> diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> index 9c4541b..07a1a4c 100644
> --- a/net/bluetooth/hci_core.c
> +++ b/net/bluetooth/hci_core.c
> @@ -522,6 +522,7 @@ int hci_dev_open(__u16 dev)
> atomic_set(&hdev->cmd_cnt, 1);
> set_bit(HCI_INIT, &hdev->flags);
>
> + set_bit(HCI_RESET, &hdev->flags);
> //__hci_request(hdev, hci_reset_req, 0, HZ);
> ret = __hci_request(hdev, hci_init_req, 0,
> msecs_to_jiffies(HCI_INIT_TIMEOUT));
> diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
> index a290854..a63bcf0 100644
> --- a/net/bluetooth/hci_event.c
> +++ b/net/bluetooth/hci_event.c
> @@ -183,6 +183,8 @@ static void hci_cc_reset(struct hci_dev *hdev,
> struct sk_buff *skb)
>
> BT_DBG("%s status 0x%x", hdev->name, status);
>
> + clear_bit(HCI_RESET, &hdev->flags);
> +
> hci_req_complete(hdev, HCI_OP_RESET, status);
> }
>
> @@ -1464,7 +1466,7 @@ static inline void hci_cmd_status_evt(struct
> hci_dev *hdev, struct sk_buff *skb)
> break;
> }
>
> - if (ev->ncmd) {
> + if (ev->ncmd && !test_bit(HCI_RESET, &hdev->flags)) {
> atomic_set(&hdev->cmd_cnt, 1);
> if (!skb_queue_empty(&hdev->cmd_q))
> tasklet_schedule(&hdev->cmd_task);
>
Justin Mattock wrote:
> o.k. works over here..
> Tested-by: Justin P. Mattock <[email protected]>
Works for me too (tested with the (original) patch applied on top of
bluetooth-next
merged on 2.6.38).
Tested-by: Mikko Vinni <[email protected]>
Thanks for solving the problem!
Mikko
>
> here is an updated patch for the current Mainline if anybody needs it:
>
...
> No, it's based on bluetooth-next (2.6.39). But you can drop the hci_cmd_timer
> part while testing it. It's not needed unless you have and hci_reset cmd
> timeout.
>
> --
> Gustavo F. Padovan
> http://profusion.mobi
>
o.k. works over here..
Tested-by: Justin P. Mattock <[email protected]>
here is an updated patch for the current Mainline if anybody needs it:
---
include/net/bluetooth/hci.h | 1 +
net/bluetooth/hci_core.c | 1 +
net/bluetooth/hci_event.c | 4 +++-
3 files changed, 5 insertions(+), 1 deletions(-)
diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
index 29a7a8c..c4f4c42 100644
--- a/include/net/bluetooth/hci.h
+++ b/include/net/bluetooth/hci.h
@@ -76,6 +76,7 @@ enum {
HCI_INQUIRY,
HCI_RAW,
+ HCI_RESET,
};
/* HCI ioctl defines */
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index 9c4541b..07a1a4c 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -522,6 +522,7 @@ int hci_dev_open(__u16 dev)
atomic_set(&hdev->cmd_cnt, 1);
set_bit(HCI_INIT, &hdev->flags);
+ set_bit(HCI_RESET, &hdev->flags);
//__hci_request(hdev, hci_reset_req, 0, HZ);
ret = __hci_request(hdev, hci_init_req, 0,
msecs_to_jiffies(HCI_INIT_TIMEOUT));
diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index a290854..a63bcf0 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -183,6 +183,8 @@ static void hci_cc_reset(struct hci_dev *hdev,
struct sk_buff *skb)
BT_DBG("%s status 0x%x", hdev->name, status);
+ clear_bit(HCI_RESET, &hdev->flags);
+
hci_req_complete(hdev, HCI_OP_RESET, status);
}
@@ -1464,7 +1466,7 @@ static inline void hci_cmd_status_evt(struct
hci_dev *hdev, struct sk_buff *skb)
break;
}
- if (ev->ncmd) {
+ if (ev->ncmd && !test_bit(HCI_RESET, &hdev->flags)) {
atomic_set(&hdev->cmd_cnt, 1);
if (!skb_queue_empty(&hdev->cmd_q))
tasklet_schedule(&hdev->cmd_task);
--
1.7.4.1
--
Justin P. Mattock
Hi Justin,
* Justin P. Mattock <[email protected]> [2011-03-16 12:11:10 -0700]:
> On 03/16/2011 12:01 PM, Gustavo F. Padovan wrote:
> > Hi Anderson,
> >
> > * Anderson Lizardo<[email protected]> [2011-03-16 14:48:31 -0400]:
> >
> >> Hi Gustavo,
> >>
> >> On Wed, Mar 16, 2011 at 2:46 PM, Gustavo F. Padovan
> >> <[email protected]> wrote:
> >>>
> >>> * Gustavo F. Padovan<[email protected]> [2011-03-16 15:44:46 -0300]:
> >>>
> >>>> We can't send new commands before a cmd_complete for the HCI_RESET commnnd
> >>>> shows up.
> >>>>
> >>>> Reported-by: Mikko Vinni<[email protected]>
> >>>> Reported-by: Justin P. Mattock<[email protected]>
> >>>> Reported-by: Ed Tomlinson<[email protected]>
> >>>> Signed-off-by: Gustavo F. Padovan<[email protected]>
> >>>> ---
> >>>> include/net/bluetooth/hci.h | 2 ++
> >>>> net/bluetooth/hci_core.c | 3 +++
> >>>> net/bluetooth/hci_event.c | 4 +++-
> >>>> 3 files changed, 8 insertions(+), 1 deletions(-)
> >>>
> >>> It works for me, but can someone test this and then add a Tested-by line.
> >>> Thanks.
> >>
> >> Which hardware is needed to test this?
> >
> > I don't know, I have a dongle that can cause this issue. It's CSR 1.1.
> > I don't know which other dongles have a similar issue.
> >
>
> I started to test this out, but crapped out at hci_cmd_timer with the
> current Mainline do you have this for the current?
No, it's based on bluetooth-next (2.6.39). But you can drop the hci_cmd_timer
part while testing it. It's not needed unless you have and hci_reset cmd
timeout.
--
Gustavo F. Padovan
http://profusion.mobi
On 03/16/2011 12:01 PM, Gustavo F. Padovan wrote:
> Hi Anderson,
>
> * Anderson Lizardo<[email protected]> [2011-03-16 14:48:31 -0400]:
>
>> Hi Gustavo,
>>
>> On Wed, Mar 16, 2011 at 2:46 PM, Gustavo F. Padovan
>> <[email protected]> wrote:
>>>
>>> * Gustavo F. Padovan<[email protected]> [2011-03-16 15:44:46 -0300]:
>>>
>>>> We can't send new commands before a cmd_complete for the HCI_RESET commnnd
>>>> shows up.
>>>>
>>>> Reported-by: Mikko Vinni<[email protected]>
>>>> Reported-by: Justin P. Mattock<[email protected]>
>>>> Reported-by: Ed Tomlinson<[email protected]>
>>>> Signed-off-by: Gustavo F. Padovan<[email protected]>
>>>> ---
>>>> include/net/bluetooth/hci.h | 2 ++
>>>> net/bluetooth/hci_core.c | 3 +++
>>>> net/bluetooth/hci_event.c | 4 +++-
>>>> 3 files changed, 8 insertions(+), 1 deletions(-)
>>>
>>> It works for me, but can someone test this and then add a Tested-by line.
>>> Thanks.
>>
>> Which hardware is needed to test this?
>
> I don't know, I have a dongle that can cause this issue. It's CSR 1.1.
> I don't know which other dongles have a similar issue.
>
I started to test this out, but crapped out at hci_cmd_timer with the
current Mainline do you have this for the current?
Hi Anderson,
* Anderson Lizardo <[email protected]> [2011-03-16 14:48:31 -0400]:
> Hi Gustavo,
>
> On Wed, Mar 16, 2011 at 2:46 PM, Gustavo F. Padovan
> <[email protected]> wrote:
> >
> > * Gustavo F. Padovan <[email protected]> [2011-03-16 15:44:46 -0300]:
> >
> >> We can't send new commands before a cmd_complete for the HCI_RESET commnnd
> >> shows up.
> >>
> >> Reported-by: Mikko Vinni <[email protected]>
> >> Reported-by: Justin P. Mattock <[email protected]>
> >> Reported-by: Ed Tomlinson <[email protected]>
> >> Signed-off-by: Gustavo F. Padovan <[email protected]>
> >> ---
> >> ?include/net/bluetooth/hci.h | ? ?2 ++
> >> ?net/bluetooth/hci_core.c ? ?| ? ?3 +++
> >> ?net/bluetooth/hci_event.c ? | ? ?4 +++-
> >> ?3 files changed, 8 insertions(+), 1 deletions(-)
> >
> > It works for me, but can someone test this and then add a Tested-by line.
> > Thanks.
>
> Which hardware is needed to test this?
I don't know, I have a dongle that can cause this issue. It's CSR 1.1.
I don't know which other dongles have a similar issue.
--
Gustavo F. Padovan
http://profusion.mobi
Hi Gustavo,
On Wed, Mar 16, 2011 at 2:46 PM, Gustavo F. Padovan
<[email protected]> wrote:
>
> * Gustavo F. Padovan <[email protected]> [2011-03-16 15:44:46 -0300]:
>
>> We can't send new commands before a cmd_complete for the HCI_RESET commnnd
>> shows up.
>>
>> Reported-by: Mikko Vinni <[email protected]>
>> Reported-by: Justin P. Mattock <[email protected]>
>> Reported-by: Ed Tomlinson <[email protected]>
>> Signed-off-by: Gustavo F. Padovan <[email protected]>
>> ---
>> ?include/net/bluetooth/hci.h | ? ?2 ++
>> ?net/bluetooth/hci_core.c ? ?| ? ?3 +++
>> ?net/bluetooth/hci_event.c ? | ? ?4 +++-
>> ?3 files changed, 8 insertions(+), 1 deletions(-)
>
> It works for me, but can someone test this and then add a Tested-by line.
> Thanks.
Which hardware is needed to test this?
I have a 1.1 dongle which doesn't work on current mainline tree, but
I'm not sure it is this same issue. I "fixed" it by upgrading the
firmware to support 1.2, but I can downgrade it to test if this is
related to 1.1 dongles.
Regards,
--
Anderson Lizardo
Instituto Nokia de Tecnologia - INdT
Manaus - Brazil
* Gustavo F. Padovan <[email protected]> [2011-03-16 15:44:46 -0300]:
> We can't send new commands before a cmd_complete for the HCI_RESET commnnd
> shows up.
>
> Reported-by: Mikko Vinni <[email protected]>
> Reported-by: Justin P. Mattock <[email protected]>
> Reported-by: Ed Tomlinson <[email protected]>
> Signed-off-by: Gustavo F. Padovan <[email protected]>
> ---
> include/net/bluetooth/hci.h | 2 ++
> net/bluetooth/hci_core.c | 3 +++
> net/bluetooth/hci_event.c | 4 +++-
> 3 files changed, 8 insertions(+), 1 deletions(-)
It works for me, but can someone test this and then add a Tested-by line.
Thanks.
--
Gustavo F. Padovan
http://profusion.mobi
We can't send new commands before a cmd_complete for the HCI_RESET commnnd
shows up.
Reported-by: Mikko Vinni <[email protected]>
Reported-by: Justin P. Mattock <[email protected]>
Reported-by: Ed Tomlinson <[email protected]>
Signed-off-by: Gustavo F. Padovan <[email protected]>
---
include/net/bluetooth/hci.h | 2 ++
net/bluetooth/hci_core.c | 3 +++
net/bluetooth/hci_event.c | 4 +++-
3 files changed, 8 insertions(+), 1 deletions(-)
diff --git a/include/net/bluetooth/hci.h b/include/net/bluetooth/hci.h
index ec6acf2..2c0d309 100644
--- a/include/net/bluetooth/hci.h
+++ b/include/net/bluetooth/hci.h
@@ -84,6 +84,8 @@ enum {
HCI_SERVICE_CACHE,
HCI_LINK_KEYS,
HCI_DEBUG_KEYS,
+
+ HCI_RESET,
};
/* HCI ioctl defines */
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index b372fb8..32b82e2 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -534,6 +534,8 @@ int hci_dev_open(__u16 dev)
set_bit(HCI_INIT, &hdev->flags);
hdev->init_last_cmd = 0;
+ set_bit(HCI_RESET, &hdev->flags);
+
ret = __hci_request(hdev, hci_init_req, 0,
msecs_to_jiffies(HCI_INIT_TIMEOUT));
@@ -1074,6 +1076,7 @@ static void hci_cmd_timer(unsigned long arg)
BT_ERR("%s command tx timeout", hdev->name);
atomic_set(&hdev->cmd_cnt, 1);
+ clear_bit(HCI_RESET, &hdev->flags);
tasklet_schedule(&hdev->cmd_task);
}
diff --git a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
index 3fbfa50..cebe7588 100644
--- a/net/bluetooth/hci_event.c
+++ b/net/bluetooth/hci_event.c
@@ -183,6 +183,8 @@ static void hci_cc_reset(struct hci_dev *hdev, struct sk_buff *skb)
BT_DBG("%s status 0x%x", hdev->name, status);
+ clear_bit(HCI_RESET, &hdev->flags);
+
hci_req_complete(hdev, HCI_OP_RESET, status);
}
@@ -1847,7 +1849,7 @@ static inline void hci_cmd_status_evt(struct hci_dev *hdev, struct sk_buff *skb)
if (ev->opcode != HCI_OP_NOP)
del_timer(&hdev->cmd_timer);
- if (ev->ncmd) {
+ if (ev->ncmd && !test_bit(HCI_RESET, &hdev->flags)) {
atomic_set(&hdev->cmd_cnt, 1);
if (!skb_queue_empty(&hdev->cmd_q))
tasklet_schedule(&hdev->cmd_task);
--
1.7.4.1
On 03/11/2011 05:33 PM, Gustavo F. Padovan wrote:
> * Johan Hedberg<[email protected]> [2011-03-10 09:32:06 +0200]:
>
>> Hi,
>>
>> On Wed, Mar 09, 2011, Ed Tomlinson wrote:
>>>> diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
>>>> index 9c4541b..f690eb5 100644
>>>> --- a/net/bluetooth/hci_core.c
>>>> +++ b/net/bluetooth/hci_core.c
>>>> @@ -95,18 +95,17 @@ void hci_req_complete(struct hci_dev *hdev, __u16
>>>> cmd, int result)
>>>> {
>>>> BT_DBG("%s command 0x%04x result 0x%2.2x", hdev->name, cmd, result);
>>>>
>>>> + if (hdev->req_status == HCI_REQ_PEND) {
>>>> + hdev->req_result = result;
>>>> + hdev->req_status = HCI_REQ_DONE;
>>>> + wake_up_interruptible(&hdev->req_wait_q);
>>>> + }
>>>> /* If the request has set req_last_cmd (typical for multi-HCI
>>>> * command requests) check if the completed command matches
>>>> * this, and if not just return. Single HCI command requests
>>>> * typically leave req_last_cmd as 0 */
>>>> if (hdev->req_last_cmd&& cmd != hdev->req_last_cmd)
>>>> return;
>>>> -
>>>> - if (hdev->req_status == HCI_REQ_PEND) {
>>>> - hdev->req_result = result;
>>>> - hdev->req_status = HCI_REQ_DONE;
>>>> - wake_up_interruptible(&hdev->req_wait_q);
>>>> - }
>>>> }
>>>>
>>>> static void hci_req_cancel(struct hci_dev *hdev, int err)
>>>>
>>>
>>> Works here too - bluetooth comes up enabled. On to Linus?
>>
>> All the patch does is it re-breaks the __hci_request function by
>> removing proper synchronization from it (again) and thereby hides the
>> real bug which is the kernel sending commands to the controller before
>> the HCI_Reset command has completed.
>
> I got an 1.1 Bluetooth dongle that can cause this issue, now I can test this
> by myself. I'll work to fix this next week.
>
cool... I am not going insane!!! let me know if you want me to test any
patches out.
Justin P. Mattock
* Johan Hedberg <[email protected]> [2011-03-10 09:32:06 +0200]:
> Hi,
>
> On Wed, Mar 09, 2011, Ed Tomlinson wrote:
> > > diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> > > index 9c4541b..f690eb5 100644
> > > --- a/net/bluetooth/hci_core.c
> > > +++ b/net/bluetooth/hci_core.c
> > > @@ -95,18 +95,17 @@ void hci_req_complete(struct hci_dev *hdev, __u16
> > > cmd, int result)
> > > {
> > > BT_DBG("%s command 0x%04x result 0x%2.2x", hdev->name, cmd, result);
> > >
> > > + if (hdev->req_status == HCI_REQ_PEND) {
> > > + hdev->req_result = result;
> > > + hdev->req_status = HCI_REQ_DONE;
> > > + wake_up_interruptible(&hdev->req_wait_q);
> > > + }
> > > /* If the request has set req_last_cmd (typical for multi-HCI
> > > * command requests) check if the completed command matches
> > > * this, and if not just return. Single HCI command requests
> > > * typically leave req_last_cmd as 0 */
> > > if (hdev->req_last_cmd && cmd != hdev->req_last_cmd)
> > > return;
> > > -
> > > - if (hdev->req_status == HCI_REQ_PEND) {
> > > - hdev->req_result = result;
> > > - hdev->req_status = HCI_REQ_DONE;
> > > - wake_up_interruptible(&hdev->req_wait_q);
> > > - }
> > > }
> > >
> > > static void hci_req_cancel(struct hci_dev *hdev, int err)
> > >
> >
> > Works here too - bluetooth comes up enabled. On to Linus?
>
> All the patch does is it re-breaks the __hci_request function by
> removing proper synchronization from it (again) and thereby hides the
> real bug which is the kernel sending commands to the controller before
> the HCI_Reset command has completed.
I got an 1.1 Bluetooth dongle that can cause this issue, now I can test this
by myself. I'll work to fix this next week.
--
Gustavo F. Padovan
http://profusion.mobi
On 03/09/2011 11:32 PM, Johan Hedberg wrote:
> Hi,
>
> On Wed, Mar 09, 2011, Ed Tomlinson wrote:
>>> diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
>>> index 9c4541b..f690eb5 100644
>>> --- a/net/bluetooth/hci_core.c
>>> +++ b/net/bluetooth/hci_core.c
>>> @@ -95,18 +95,17 @@ void hci_req_complete(struct hci_dev *hdev, __u16
>>> cmd, int result)
>>> {
>>> BT_DBG("%s command 0x%04x result 0x%2.2x", hdev->name, cmd, result);
>>>
>>> + if (hdev->req_status == HCI_REQ_PEND) {
>>> + hdev->req_result = result;
>>> + hdev->req_status = HCI_REQ_DONE;
>>> + wake_up_interruptible(&hdev->req_wait_q);
>>> + }
>>> /* If the request has set req_last_cmd (typical for multi-HCI
>>> * command requests) check if the completed command matches
>>> * this, and if not just return. Single HCI command requests
>>> * typically leave req_last_cmd as 0 */
>>> if (hdev->req_last_cmd&& cmd != hdev->req_last_cmd)
>>> return;
>>> -
>>> - if (hdev->req_status == HCI_REQ_PEND) {
>>> - hdev->req_result = result;
>>> - hdev->req_status = HCI_REQ_DONE;
>>> - wake_up_interruptible(&hdev->req_wait_q);
>>> - }
>>> }
>>>
>>> static void hci_req_cancel(struct hci_dev *hdev, int err)
>>>
>>
>> Works here too - bluetooth comes up enabled. On to Linus?
>
> All the patch does is it re-breaks the __hci_request function by
> removing proper synchronization from it (again) and thereby hides the
> real bug which is the kernel sending commands to the controller before
> the HCI_Reset command has completed.
>
> Johan
>
well, please send a patch my way and I will test it out!
Justin P. Mattock
Hi,
On Wed, Mar 09, 2011, Ed Tomlinson wrote:
> > diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> > index 9c4541b..f690eb5 100644
> > --- a/net/bluetooth/hci_core.c
> > +++ b/net/bluetooth/hci_core.c
> > @@ -95,18 +95,17 @@ void hci_req_complete(struct hci_dev *hdev, __u16
> > cmd, int result)
> > {
> > BT_DBG("%s command 0x%04x result 0x%2.2x", hdev->name, cmd, result);
> >
> > + if (hdev->req_status == HCI_REQ_PEND) {
> > + hdev->req_result = result;
> > + hdev->req_status = HCI_REQ_DONE;
> > + wake_up_interruptible(&hdev->req_wait_q);
> > + }
> > /* If the request has set req_last_cmd (typical for multi-HCI
> > * command requests) check if the completed command matches
> > * this, and if not just return. Single HCI command requests
> > * typically leave req_last_cmd as 0 */
> > if (hdev->req_last_cmd && cmd != hdev->req_last_cmd)
> > return;
> > -
> > - if (hdev->req_status == HCI_REQ_PEND) {
> > - hdev->req_result = result;
> > - hdev->req_status = HCI_REQ_DONE;
> > - wake_up_interruptible(&hdev->req_wait_q);
> > - }
> > }
> >
> > static void hci_req_cancel(struct hci_dev *hdev, int err)
> >
>
> Works here too - bluetooth comes up enabled. On to Linus?
All the patch does is it re-breaks the __hci_request function by
removing proper synchronization from it (again) and thereby hides the
real bug which is the kernel sending commands to the controller before
the HCI_Reset command has completed.
Johan
On Wednesday 09 March 2011 16:23:55 Justin P. Mattock wrote:
>
> looking more into this issue I am noticing that it seems this might be a
> timing issue. I have tried adding msleep to the function but endedup
> having a system freeze(only because I am not sure how msleep
> works)udelay I have not played around with just yet.
>
> the below patch gets everything working for me:
>
>
> From 8065e37b546cdf6e42a5de4277e08ebba0a18637 Mon Sep 17 00:00:00 2001
> From: Justin P. Mattock <[email protected]>
> Date: Tue, 8 Mar 2011 22:01:19 -0800
> Subject: [PATCH] bluetooth_bug_fix_test_1
> Signed-off-by: Justin P. Mattock <[email protected]>
>
> ---
> net/bluetooth/hci_core.c | 11 +++++------
> 1 files changed, 5 insertions(+), 6 deletions(-)
>
> diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
> index 9c4541b..f690eb5 100644
> --- a/net/bluetooth/hci_core.c
> +++ b/net/bluetooth/hci_core.c
> @@ -95,18 +95,17 @@ void hci_req_complete(struct hci_dev *hdev, __u16
> cmd, int result)
> {
> BT_DBG("%s command 0x%04x result 0x%2.2x", hdev->name, cmd, result);
>
> + if (hdev->req_status == HCI_REQ_PEND) {
> + hdev->req_result = result;
> + hdev->req_status = HCI_REQ_DONE;
> + wake_up_interruptible(&hdev->req_wait_q);
> + }
> /* If the request has set req_last_cmd (typical for multi-HCI
> * command requests) check if the completed command matches
> * this, and if not just return. Single HCI command requests
> * typically leave req_last_cmd as 0 */
> if (hdev->req_last_cmd && cmd != hdev->req_last_cmd)
> return;
> -
> - if (hdev->req_status == HCI_REQ_PEND) {
> - hdev->req_result = result;
> - hdev->req_status = HCI_REQ_DONE;
> - wake_up_interruptible(&hdev->req_wait_q);
> - }
> }
>
> static void hci_req_cancel(struct hci_dev *hdev, int err)
>
Works here too - bluetooth comes up enabled. On to Linus?
Thanks
Ed
looking more into this issue I am noticing that it seems this might be a
timing issue. I have tried adding msleep to the function but endedup
having a system freeze(only because I am not sure how msleep
works)udelay I have not played around with just yet.
the below patch gets everything working for me:
From 8065e37b546cdf6e42a5de4277e08ebba0a18637 Mon Sep 17 00:00:00 2001
From: Justin P. Mattock <[email protected]>
Date: Tue, 8 Mar 2011 22:01:19 -0800
Subject: [PATCH] bluetooth_bug_fix_test_1
Signed-off-by: Justin P. Mattock <[email protected]>
---
net/bluetooth/hci_core.c | 11 +++++------
1 files changed, 5 insertions(+), 6 deletions(-)
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index 9c4541b..f690eb5 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -95,18 +95,17 @@ void hci_req_complete(struct hci_dev *hdev, __u16
cmd, int result)
{
BT_DBG("%s command 0x%04x result 0x%2.2x", hdev->name, cmd, result);
+ if (hdev->req_status == HCI_REQ_PEND) {
+ hdev->req_result = result;
+ hdev->req_status = HCI_REQ_DONE;
+ wake_up_interruptible(&hdev->req_wait_q);
+ }
/* If the request has set req_last_cmd (typical for multi-HCI
* command requests) check if the completed command matches
* this, and if not just return. Single HCI command requests
* typically leave req_last_cmd as 0 */
if (hdev->req_last_cmd && cmd != hdev->req_last_cmd)
return;
-
- if (hdev->req_status == HCI_REQ_PEND) {
- hdev->req_result = result;
- hdev->req_status = HCI_REQ_DONE;
- wake_up_interruptible(&hdev->req_wait_q);
- }
}
static void hci_req_cancel(struct hci_dev *hdev, int err)
--
1.7.4.1
I have done multiple reboots warm/cold and the bluetooth connects
everytime with the above. If this seems to be a good solution let me
know, if its not then maybe udelay/msleep is better(or not!)
Justin P. Mattock
alright..
<------clip --------->
finally had time to get online and look at this issue. from playing
around(hopefully)I found the trouble spot in of which this is
hitting(but could be wrong).
By doing the below:
From ff80f03c351018b53a630de8f256137a7af8f00c Mon Sep 17 00:00:00 2001
From: Justin P. Mattock <[email protected]>
Date: Tue, 8 Mar 2011 13:28:22 -0800
Subject: [PATCH] test
Signe-off-by: Justin P. Mattock <[email protected]>
---
net/bluetooth/hci_core.c | 4 ++--
1 files changed, 2 insertions(+), 2 deletions(-)
diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c
index 9c4541b..9b8f425 100644
--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -99,8 +99,8 @@ void hci_req_complete(struct hci_dev *hdev, __u16 cmd,
int result)
* command requests) check if the completed command matches
* this, and if not just return. Single HCI command requests
* typically leave req_last_cmd as 0 */
- if (hdev->req_last_cmd && cmd != hdev->req_last_cmd)
- return;
+ /*if (hdev->req_last_cmd && cmd != hdev->req_last_cmd)
+ return; */
if (hdev->req_status == HCI_REQ_PEND) {
hdev->req_result = result;
--
1.7.4.1
I am able to have a clean connect every reboot and hard shutdown/start.
strange thing with this, is I was able to have a clean connect on the
current with nothing added or removed(but only one time out of 6
restarts) with the above every time.
if you guys need any info let me know and/or if you want me to test
anything out(keep in mind I am limited to intranet so I might take some
time to respond)
Justin P. Mattock
Hi,
Johan Hedberg wrote:
> In any case what's happening is that there's never a command complete
> for the local features. This is one of those commands that user space
> tracks to determine that the adapter is initialized so if it never comes
> the adapter remains uninitialized from a bluetoothd perspective. There
> is supposed to be some work-around code in bluetoothd for this kind of
> situations, but due to the patch you found in the kernel the code
> doesn't get triggered since the "up" flag is not set when the situation
> happens. The patch I've attached removed this check for the flag. Could
> you try and see if it helps?
I compiled bluez 4.89-71-gdc920af from git, which seems to contain the
patch that was as an attachment (9bae9813abf29344cc3d84af2ee59efd9e9e78fc).
It sometimes helps, but not always. Maybe there are some alternative code
paths, races, or something. Below some logs for a case when it doesn't
help. Also, it doesn't seem to work when bluetoothd is started before
plugging in the adapter or if the adapter is unplugged and replugged.
adapter in; start hcidump; start self-compiled bluetoothd
hcidump log ("hcidump -a" ran around 21.27.30):
HCI sniffer - Bluetooth packet analyzer ver 2.0
btsnoop version: 1 datalink type: 1002
2011-03-07 21:27:08.891188 < HCI Command: Reset (0x03|0x0003) plen 0
2011-03-07 21:27:08.891722 > HCI Event: Command Status (0x0f) plen 4
Unknown (0x00|0x0000) status 0x00 ncmd 1
2011-03-07 21:27:08.891747 < HCI Command: Read Local Supported Features
(0x04|0x0003) plen 0
2011-03-07 21:27:09.029713 > HCI Event: Command Complete (0x0e) plen 4
Reset (0x03|0x0003) ncmd 1
status 0x00
2011-03-07 21:27:09.029785 < HCI Command: Read Local Version Information
(0x04|0x0001) plen 0
2011-03-07 21:27:09.033720 > HCI Event: Command Complete (0x0e) plen 12
Read Local Version Information (0x04|0x0001) ncmd 1
status 0x00
HCI Version: 2.0 (0x3) HCI Revision: 0x7a6
LMP Version: 2.0 (0x3) LMP Subversion: 0x7a6
Manufacturer: Cambridge Silicon Radio (10)
2011-03-07 21:27:09.033767 < HCI Command: Read Buffer Size (0x04|0x0005) plen 0
2011-03-07 21:27:09.037700 > HCI Event: Command Complete (0x0e) plen 11
Read Buffer Size (0x04|0x0005) ncmd 1
status 0x00
ACL MTU 384:8 SCO MTU 64:8
2011-03-07 21:27:09.037726 < HCI Command: Read BD ADDR (0x04|0x0009) plen 0
2011-03-07 21:27:09.040717 > HCI Event: Command Complete (0x0e) plen 10
Read BD ADDR (0x04|0x0009) ncmd 1
status 0x00 bdaddr 00:0D:3C:38:FA:B5
2011-03-07 21:27:09.040756 < HCI Command: Read Class of Device (0x03|0x0023)
plen 0
2011-03-07 21:27:09.043704 > HCI Event: Command Complete (0x0e) plen 7
Read Class of Device (0x03|0x0023) ncmd 1
status 0x00 class 0x000000
2011-03-07 21:27:09.043741 < HCI Command: Read Local Name (0x03|0x0014) plen 0
2011-03-07 21:27:09.078711 > HCI Event: Command Complete (0x0e) plen 252
Read Local Name (0x03|0x0014) ncmd 1
status 0x00 name 'CSR - bc4'
2011-03-07 21:27:09.078749 < HCI Command: Read Voice Setting (0x03|0x0025) plen
0
2011-03-07 21:27:09.081733 > HCI Event: Command Complete (0x0e) plen 6
Read Voice Setting (0x03|0x0025) ncmd 1
status 0x00 voice setting 0x0060
2011-03-07 21:27:09.081764 < HCI Command: Set Event Filter (0x03|0x0005) plen 1
type 0 condition 0
Clear all filters
2011-03-07 21:27:09.084712 > HCI Event: Command Complete (0x0e) plen 4
Set Event Filter (0x03|0x0005) ncmd 1
status 0x00
2011-03-07 21:27:09.084738 < HCI Command: Write Page Timeout (0x03|0x0018) plen
2
timeout 32768
2011-03-07 21:27:09.087703 > HCI Event: Command Complete (0x0e) plen 4
Write Page Timeout (0x03|0x0018) ncmd 1
status 0x00
2011-03-07 21:27:09.087726 < HCI Command: Write Connection Accept Timeout
(0x03|0x0016) plen 2
timeout 32000
2011-03-07 21:27:09.090699 > HCI Event: Command Complete (0x0e) plen 4
Write Connection Accept Timeout (0x03|0x0016) ncmd 1
status 0x00
2011-03-07 21:27:09.091818 < HCI Command: Write Page Timeout (0x03|0x0018) plen
2
timeout 8192
2011-03-07 21:27:09.094704 > HCI Event: Command Complete (0x0e) plen 4
Write Page Timeout (0x03|0x0018) ncmd 1
status 0x00
2011-03-07 21:27:09.094758 < HCI Command: Read Stored Link Key (0x03|0x000d)
plen 7
bdaddr 00:00:00:00:00:00 all 1
2011-03-07 21:27:09.098714 > HCI Event: Command Complete (0x0e) plen 8
Read Stored Link Key (0x03|0x000d) ncmd 1
status 0x00 max 16 num 0
2011-03-07 21:27:33.036962 < HCI Command: Read Local Name (0x03|0x0014) plen 0
2011-03-07 21:27:33.088144 > HCI Event: Command Complete (0x0e) plen 252
Read Local Name (0x03|0x0014) ncmd 1
status 0x00 name 'CSR - bc4'
2011-03-07 21:27:33.088386 < HCI Command: Read Class of Device (0x03|0x0023)
plen 0
2011-03-07 21:27:33.091152 > HCI Event: Command Complete (0x0e) plen 7
Read Class of Device (0x03|0x0023) ncmd 1
status 0x00 class 0x000000
2011-03-07 21:27:33.091181 < HCI Command: Read Local Supported Features
(0x04|0x0003) plen 0
2011-03-07 21:27:33.094151 > HCI Event: Command Complete (0x0e) plen 12
Read Local Supported Features (0x04|0x0003) ncmd 1
status 0x00
Features: 0xff 0xff 0x8f 0xfe 0x9b 0xf9 0x00 0x80
2011-03-07 21:27:33.094175 < HCI Command: Read Local Version Information
(0x04|0x0001) plen 0
2011-03-07 21:27:33.098150 > HCI Event: Command Complete (0x0e) plen 12
Read Local Version Information (0x04|0x0001) ncmd 1
status 0x00
HCI Version: 2.0 (0x3) HCI Revision: 0x7a6
LMP Version: 2.0 (0x3) LMP Subversion: 0x7a6
Manufacturer: Cambridge Silicon Radio (10)
2011-03-07 21:27:33.150368 < HCI Command: Set Event Mask (0x03|0x0001) plen 8
Mask: 0xfffffbff07180000
2011-03-07 21:27:33.153142 > HCI Event: Command Complete (0x0e) plen 4
Set Event Mask (0x03|0x0001) ncmd 1
status 0x00
2011-03-07 21:27:33.153176 < HCI Command: Write Inquiry Mode (0x03|0x0045) plen
1
mode 1
2011-03-07 21:27:33.156136 > HCI Event: Command Complete (0x0e) plen 4
Write Inquiry Mode (0x03|0x0045) ncmd 1
status 0x00
2011-03-07 21:27:33.156168 < HCI Command: Write Default Link Policy Settings
(0x02|0x000f) plen 2
policy 0x0f
Link policy: RSWITCH HOLD SNIFF PARK
2011-03-07 21:27:33.159136 > HCI Event: Command Complete (0x0e) plen 4
Write Default Link Policy Settings (0x02|0x000f) ncmd 1
status 0x00
2011-03-07 21:27:33.159163 < HCI Command: Write Local Name (0x03|0x0013) plen
248
name 'koni-0'
2011-03-07 21:27:33.162140 > HCI Event: Command Complete (0x0e) plen 4
Write Local Name (0x03|0x0013) ncmd 1
status 0x00
2011-03-07 21:27:33.162167 < HCI Command: Write Class of Device (0x03|0x0024)
plen 3
class 0x480100
2011-03-07 21:27:33.165143 > HCI Event: Command Complete (0x0e) plen 4
Write Class of Device (0x03|0x0024) ncmd 1
status 0x00
2011-03-07 21:27:33.165180 < HCI Command: Write Scan Enable (0x03|0x001a) plen 1
enable 3
2011-03-07 21:27:33.169143 > HCI Event: Command Complete (0x0e) plen 4
Write Scan Enable (0x03|0x001a) ncmd 1
status 0x00
2011-03-07 21:27:33.169175 < HCI Command: Read Local Name (0x03|0x0014) plen 0
2011-03-07 21:27:33.190186 > HCI Event: Command Complete (0x0e) plen 252
Read Local Name (0x03|0x0014) ncmd 1
status 0x00 name 'koni-0'
2011-03-07 21:27:33.190246 < HCI Command: Read Scan Enable (0x03|0x0019) plen 0
2011-03-07 21:27:33.193155 > HCI Event: Command Complete (0x0e) plen 5
Read Scan Enable (0x03|0x0019) ncmd 1
status 0x00 enable 3
2011-03-07 21:27:50.114574 < HCI Command: Reset (0x03|0x0003) plen 0
syslog:
Mar 7 21:26:47 koni kernel: usb 5-3: New USB device found, idVendor=13dd,
idProduct=0001
Mar 7 21:26:47 koni kernel: usb 5-3: New USB device strings: Mfr=1, Product=2,
SerialNumber=0
Mar 7 21:26:47 koni kernel: usb 5-3: Product: BlueCON U2
Mar 7 21:26:47 koni kernel: usb 5-3: Manufacturer: i.Tech Dynamic
Mar 7 21:27:08 koni bluetoothd[18369]: Bluetooth deamon 4.89
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:parse_config() parsing
main.conf
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:parse_config() discovto=0
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:parse_config() pairto=0
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:parse_config() pageto=8192
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:parse_config() name=%h-%d
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:parse_config() class=0x000100
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:parse_config()
discov_interval=0
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:parse_config() Key file does
not have key 'DeviceID'
Mar 7 21:27:08 koni bluetoothd[18369]: Starting SDP server
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:plugin_init() Loading
builtin plugins
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading audio
plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading input
plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading serial
plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading
network plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading
service plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading attrib
plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading health
plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading hciops
plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading
mgmtops plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading
formfactor plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:add_plugin() Loading
storage plugin
Mar 7 21:27:08 koni bluetoothd[18369]: src/plugin.c:plugin_init() Loading
plugins /usr/lib/bluetooth/plugins
Mar 7 21:27:08 koni bluetoothd[18369]: plugins/service.c:register_interface()
path /org/bluez/18369/any
Mar 7 21:27:08 koni bluetoothd[18369]: plugins/service.c:register_interface()
Registered interface org.bluez.Service on path /org/bluez/18369/any
Mar 7 21:27:08 koni bluetoothd[18369]: health/hdp.c:hdp_manager_start()
Starting Health manager
Mar 7 21:27:08 koni bluetoothd[18369]: network/manager.c:read_config()
/etc/bluetooth/network.conf: Key file does not have key 'DisableSecurity'
Mar 7 21:27:08 koni bluetoothd[18369]: network/manager.c:read_config() Config
options: Security=true
Mar 7 21:27:08 koni bluetoothd[18369]: input/manager.c:input_manager_init()
input.conf: Key file does not have key 'IdleTimeout'
Mar 7 21:27:08 koni bluetoothd[18369]: audio/manager.c:audio_manager_init()
audio.conf: Key file does not have key 'AutoConnect'
Mar 7 21:27:08 koni bluetoothd[18369]: audio/unix.c:unix_init() Unix socket
created: 8
Mar 7 21:27:08 koni bluetoothd[18369]: plugins/hciops.c:hciops_init()
Mar 7 21:27:08 koni bluetoothd[18369]: plugins/hciops.c:hciops_setup()
Mar 7 21:27:08 koni bluetoothd[18369]: src/main.c:main() Entering main loop
Mar 7 21:27:08 koni kernel: Bluetooth: SCO (Voice Link) ver 0.6
Mar 7 21:27:08 koni kernel: Bluetooth: SCO socket layer initialized
Mar 7 21:27:08 koni bluetoothd[18369]: src/rfkill.c:rfkill_event() RFKILL event
idx 0 type 1 op 0 soft 0 hard 0
Mar 7 21:27:08 koni bluetoothd[18369]: src/rfkill.c:rfkill_event() RFKILL event
idx 16 type 2 op 0 soft 0 hard 0
Mar 7 21:27:08 koni bluetoothd[18369]: plugins/hciops.c:init_known_adapters()
Mar 7 21:27:08 koni bluetoothd[18369]: plugins/hciops.c:init_device() hci0
Mar 7 21:27:08 koni bluetoothd[18369]: Listening for HCI events on hci0
Mar 7 21:27:08 koni bluetoothd[18369]: plugins/hciops.c:init_device() child
18372 forked
Mar 7 21:27:09 koni bluetoothd[18369]:
plugins/hciops.c:read_local_version_complete() Got version for hci0
Mar 7 21:27:09 koni bluetoothd[18369]: plugins/hciops.c:read_bd_addr_complete()
hci0 status 0
Mar 7 21:27:09 koni bluetoothd[18369]: plugins/hciops.c:read_bd_addr_complete()
Got bdaddr for hci0
Mar 7 21:27:09 koni bluetoothd[18369]:
plugins/hciops.c:read_local_name_complete() hci0 status 0
Mar 7 21:27:09 koni bluetoothd[18369]:
plugins/hciops.c:read_local_name_complete() Got name for hci0
Mar 7 21:27:09 koni bluetoothd[18369]: plugins/hciops.c:child_exit() child
18372 exited
Mar 7 21:27:09 koni bluetoothd[18369]: HCI dev 0 up
Mar 7 21:27:09 koni bluetoothd[18369]: plugins/hciops.c:device_devup_setup()
hci0
Mar 7 21:27:33 koni bluetoothd[18369]:
plugins/hciops.c:read_local_name_complete() hci0 status 0
Mar 7 21:27:33 koni bluetoothd[18369]:
plugins/hciops.c:read_local_name_complete() Got name for hci0
Mar 7 21:27:33 koni bluetoothd[18369]:
plugins/hciops.c:read_local_features_complete() Got features for hci0
Mar 7 21:27:33 koni bluetoothd[18369]: src/adapter.c:btd_adapter_ref()
0x7f28f49b3800: ref=1
Mar 7 21:27:33 koni bluetoothd[18369]: plugins/hciops.c:hciops_read_bdaddr()
hci0
...
Mikko
Hi,
On Thu, Mar 03, 2011 at 11:31:54AM -0300, ext Johan Hedberg wrote:
> Hi Mikko,
>
> On Thu, Mar 03, 2011, Mikko Vinni wrote:
> > > I can't reproduce this issue with any of my Bluetooth adapters (I tested
> > > with 6 different ones). Could you get us the hcidump of what happens
> > > when bluetoothd tries to switch on the adapter for the very first time?
> > > Probably you'll need to disable starting of bluetoothd when your system
> > > boots so that you have the chance to run hcidump first. Additionally, if
> > > possible, could you enable dynamic debug in your kernel and get the logs
> > > from hci_core.c and hci_event.c? Typically you'd enable this with
> > > something like:
> > >
> > > echo 'file hci_event.c +p' > /sys/kernel/debug/dynamic_debug/control
> > > echo 'file hci_core.c +p' > /sys/kernel/debug/dynamic_debug/control
> > >
> > > Hopefully those logs will give some better idea of what's going on since
> > > the logs provided so far aren't really helpful.
> > >
> >
> > - Compiled the kernel (2.6.38-rc7 now) with dynamic debug
> > - Commented out the lines to start bluetoothd from /lib/udev/rules.d/
> > - Killed bluetoothd
> > - rmmod'ed all bluetooth modules and then modprobe'd rfcomm (which pulls
> > in all the others) (this resets the situation so that the bug appears -
> > when unplugging and plugging the adapter in the working state it keeps
> > on working)
> > - enabled dynamic debug for hci_core.c, hci_event.c, and rfcomm/core.c
> > - plugged in the bluetooth adapter
> > - hcidump -w hcidump_ddebug (parsed version below)
> > - bluetoothd -d
> > - run hciconfig (without parameters) a couple of times
> > - waited some minutes
> > - run hciconfig -a (around 08:18:37 in the logs)
> > - adapter led starts blinking (and e.g. blueman-applet sees it)
> > - messages from syslog further below
> >
> > Do these help?
>
> They do indeed. However, the simplest short-term fix I can come up for
> this is in user space and not the kernel.
>
> > HCI sniffer - Bluetooth packet analyzer ver 2.0
> > btsnoop version: 1 datalink type: 1002
> > 2011-03-03 08:14:38.386728 < HCI Command: Reset (0x03|0x0003) plen 0
> > 2011-03-03 08:14:38.386759 > HCI Event: Command Status (0x0f) plen 4
> > Unknown (0x00|0x0000) status 0x00 ncmd 1
> > 2011-03-03 08:14:38.386810 < HCI Command: Read Local Supported Features
> > (0x04|0x0003) plen 0
> > 2011-03-03 08:14:38.524768 > HCI Event: Command Complete (0x0e) plen 4
> > Reset (0x03|0x0003) ncmd 1
> > status 0x00
>
> I'm not sure if this is correct. The command status for opcode 0 means
> that we can start sending commands to the controller, however since
> there's a pending reset command maybe we should be waiting for its
> command complete event before sending the features command. Or should we
> be sending the Reset command at all so early and instead wait for the
> command status before sending it?
No need to wait for NOP event. And after reset no other commands should be sent
before cmd complete.
At least according the spec. So reset should be handled in a special way.
>
> In any case what's happening is that there's never a command complete
> for the local features. This is one of those commands that user space
> tracks to determine that the adapter is initialized so if it never comes
> the adapter remains uninitialized from a bluetoothd perspective. There
> is supposed to be some work-around code in bluetoothd for this kind of
> situations, but due to the patch you found in the kernel the code
> doesn't get triggered since the "up" flag is not set when the situation
> happens. The patch I've attached removed this check for the flag. Could
> you try and see if it helps?
>
> Meanwhile, it'd be nice to get some input from more knowledgeable
> persons on whether the kernel is doing the right thing in not waiting
> for the command status for opcode 0 before sending the HCI_Reset.
It's doing wrong currently.
--
Ville
Hi Mikko,
On Thu, Mar 03, 2011, Mikko Vinni wrote:
> > I can't reproduce this issue with any of my Bluetooth adapters (I tested
> > with 6 different ones). Could you get us the hcidump of what happens
> > when bluetoothd tries to switch on the adapter for the very first time?
> > Probably you'll need to disable starting of bluetoothd when your system
> > boots so that you have the chance to run hcidump first. Additionally, if
> > possible, could you enable dynamic debug in your kernel and get the logs
> > from hci_core.c and hci_event.c? Typically you'd enable this with
> > something like:
> >
> > echo 'file hci_event.c +p' > /sys/kernel/debug/dynamic_debug/control
> > echo 'file hci_core.c +p' > /sys/kernel/debug/dynamic_debug/control
> >
> > Hopefully those logs will give some better idea of what's going on since
> > the logs provided so far aren't really helpful.
> >
>
> - Compiled the kernel (2.6.38-rc7 now) with dynamic debug
> - Commented out the lines to start bluetoothd from /lib/udev/rules.d/
> - Killed bluetoothd
> - rmmod'ed all bluetooth modules and then modprobe'd rfcomm (which pulls
> in all the others) (this resets the situation so that the bug appears -
> when unplugging and plugging the adapter in the working state it keeps
> on working)
> - enabled dynamic debug for hci_core.c, hci_event.c, and rfcomm/core.c
> - plugged in the bluetooth adapter
> - hcidump -w hcidump_ddebug (parsed version below)
> - bluetoothd -d
> - run hciconfig (without parameters) a couple of times
> - waited some minutes
> - run hciconfig -a (around 08:18:37 in the logs)
> - adapter led starts blinking (and e.g. blueman-applet sees it)
> - messages from syslog further below
>
> Do these help?
They do indeed. However, the simplest short-term fix I can come up for
this is in user space and not the kernel.
> HCI sniffer - Bluetooth packet analyzer ver 2.0
> btsnoop version: 1 datalink type: 1002
> 2011-03-03 08:14:38.386728 < HCI Command: Reset (0x03|0x0003) plen 0
> 2011-03-03 08:14:38.386759 > HCI Event: Command Status (0x0f) plen 4
> Unknown (0x00|0x0000) status 0x00 ncmd 1
> 2011-03-03 08:14:38.386810 < HCI Command: Read Local Supported Features
> (0x04|0x0003) plen 0
> 2011-03-03 08:14:38.524768 > HCI Event: Command Complete (0x0e) plen 4
> Reset (0x03|0x0003) ncmd 1
> status 0x00
I'm not sure if this is correct. The command status for opcode 0 means
that we can start sending commands to the controller, however since
there's a pending reset command maybe we should be waiting for its
command complete event before sending the features command. Or should we
be sending the Reset command at all so early and instead wait for the
command status before sending it?
In any case what's happening is that there's never a command complete
for the local features. This is one of those commands that user space
tracks to determine that the adapter is initialized so if it never comes
the adapter remains uninitialized from a bluetoothd perspective. There
is supposed to be some work-around code in bluetoothd for this kind of
situations, but due to the patch you found in the kernel the code
doesn't get triggered since the "up" flag is not set when the situation
happens. The patch I've attached removed this check for the flag. Could
you try and see if it helps?
Meanwhile, it'd be nice to get some input from more knowledgeable
persons on whether the kernel is doing the right thing in not waiting
for the command status for opcode 0 before sending the HCI_Reset.
Johan
From: Johan Hedberg:
>
> I can't reproduce this issue with any of my Bluetooth adapters (I tested
> with 6 different ones). Could you get us the hcidump of what happens
> when bluetoothd tries to switch on the adapter for the very first time?
> Probably you'll need to disable starting of bluetoothd when your system
> boots so that you have the chance to run hcidump first. Additionally, if
> possible, could you enable dynamic debug in your kernel and get the logs
> from hci_core.c and hci_event.c? Typically you'd enable this with
> something like:
>
> echo 'file hci_event.c +p' > /sys/kernel/debug/dynamic_debug/control
> echo 'file hci_core.c +p' > /sys/kernel/debug/dynamic_debug/control
>
> Hopefully those logs will give some better idea of what's going on since
> the logs provided so far aren't really helpful.
>
- Compiled the kernel (2.6.38-rc7 now) with dynamic debug
- Commented out the lines to start bluetoothd from /lib/udev/rules.d/
- Killed bluetoothd
- rmmod'ed all bluetooth modules and then modprobe'd rfcomm (which pulls
in all the others) (this resets the situation so that the bug appears -
when unplugging and plugging the adapter in the working state it keeps
on working)
- enabled dynamic debug for hci_core.c, hci_event.c, and rfcomm/core.c
- plugged in the bluetooth adapter
- hcidump -w hcidump_ddebug (parsed version below)
- bluetoothd -d
- run hciconfig (without parameters) a couple of times
- waited some minutes
- run hciconfig -a (around 08:18:37 in the logs)
- adapter led starts blinking (and e.g. blueman-applet sees it)
- messages from syslog further below
Do these help?
The commit we tried to revert (23bb57633df) changes when processes
are woken up. Is there any command which would show if some process
is waiting for a wake up?
Mikko
HCI sniffer - Bluetooth packet analyzer ver 2.0
btsnoop version: 1 datalink type: 1002
2011-03-03 08:14:38.386728 < HCI Command: Reset (0x03|0x0003) plen 0
2011-03-03 08:14:38.386759 > HCI Event: Command Status (0x0f) plen 4
Unknown (0x00|0x0000) status 0x00 ncmd 1
2011-03-03 08:14:38.386810 < HCI Command: Read Local Supported Features
(0x04|0x0003) plen 0
2011-03-03 08:14:38.524768 > HCI Event: Command Complete (0x0e) plen 4
Reset (0x03|0x0003) ncmd 1
status 0x00
2011-03-03 08:14:38.524819 < HCI Command: Read Local Version Information
(0x04|0x0001) plen 0
2011-03-03 08:14:38.528758 > HCI Event: Command Complete (0x0e) plen 12
Read Local Version Information (0x04|0x0001) ncmd 1
status 0x00
HCI Version: 2.0 (0x3) HCI Revision: 0x7a6
LMP Version: 2.0 (0x3) LMP Subversion: 0x7a6
Manufacturer: Cambridge Silicon Radio (10)
2011-03-03 08:14:38.528806 < HCI Command: Read Buffer Size (0x04|0x0005) plen 0
2011-03-03 08:14:38.532764 > HCI Event: Command Complete (0x0e) plen 11
Read Buffer Size (0x04|0x0005) ncmd 1
status 0x00
ACL MTU 384:8 SCO MTU 64:8
2011-03-03 08:14:38.532822 < HCI Command: Read BD ADDR (0x04|0x0009) plen 0
2011-03-03 08:14:38.535758 > HCI Event: Command Complete (0x0e) plen 10
Read BD ADDR (0x04|0x0009) ncmd 1
status 0x00 bdaddr 00:0D:3C:38:FA:B5
2011-03-03 08:14:38.535820 < HCI Command: Read Class of Device (0x03|0x0023)
plen 0
2011-03-03 08:14:38.538765 > HCI Event: Command Complete (0x0e) plen 7
Read Class of Device (0x03|0x0023) ncmd 1
status 0x00 class 0x000000
2011-03-03 08:14:38.538818 < HCI Command: Read Local Name (0x03|0x0014) plen 0
2011-03-03 08:14:38.573755 > HCI Event: Command Complete (0x0e) plen 252
Read Local Name (0x03|0x0014) ncmd 1
status 0x00 name 'CSR - bc4'
2011-03-03 08:14:38.573808 < HCI Command: Read Voice Setting (0x03|0x0025) plen
0
2011-03-03 08:14:38.576766 > HCI Event: Command Complete (0x0e) plen 6
Read Voice Setting (0x03|0x0025) ncmd 1
status 0x00 voice setting 0x0060
2011-03-03 08:14:38.576828 < HCI Command: Set Event Filter (0x03|0x0005) plen 1
type 0 condition 0
Clear all filters
2011-03-03 08:14:38.579757 > HCI Event: Command Complete (0x0e) plen 4
Set Event Filter (0x03|0x0005) ncmd 1
status 0x00
2011-03-03 08:14:38.579802 < HCI Command: Write Page Timeout (0x03|0x0018) plen
2
timeout 32768
2011-03-03 08:14:38.582766 > HCI Event: Command Complete (0x0e) plen 4
Write Page Timeout (0x03|0x0018) ncmd 1
status 0x00
2011-03-03 08:14:38.582829 < HCI Command: Write Connection Accept Timeout
(0x03|0x0016) plen 2
timeout 32000
2011-03-03 08:14:38.585770 > HCI Event: Command Complete (0x0e) plen 4
Write Connection Accept Timeout (0x03|0x0016) ncmd 1
status 0x00
2011-03-03 08:14:38.586767 < HCI Command: Write Page Timeout (0x03|0x0018) plen
2
timeout 8192
2011-03-03 08:14:38.589774 > HCI Event: Command Complete (0x0e) plen 4
Write Page Timeout (0x03|0x0018) ncmd 1
status 0x00
2011-03-03 08:14:38.589820 < HCI Command: Read Stored Link Key (0x03|0x000d)
plen 7
bdaddr 00:00:00:00:00:00 all 1
2011-03-03 08:14:38.593763 > HCI Event: Command Complete (0x0e) plen 8
Read Stored Link Key (0x03|0x000d) ncmd 1
status 0x00 max 16 num 0
2011-03-03 08:18:37.515128 < HCI Command: Read Local Name (0x03|0x0014) plen 0
2011-03-03 08:18:37.566070 > HCI Event: Command Complete (0x0e) plen 252
Read Local Name (0x03|0x0014) ncmd 1
status 0x00 name 'CSR - bc4'
2011-03-03 08:18:37.566326 < HCI Command: Read Local Supported Features
(0x04|0x0003) plen 0
2011-03-03 08:18:37.569055 > HCI Event: Command Complete (0x0e) plen 12
Read Local Supported Features (0x04|0x0003) ncmd 1
status 0x00
Features: 0xff 0xff 0x8f 0xfe 0x9b 0xf9 0x00 0x80
2011-03-03 08:18:37.569121 < HCI Command: Read Class of Device (0x03|0x0023)
plen 0
2011-03-03 08:18:37.572061 > HCI Event: Command Complete (0x0e) plen 7
Read Class of Device (0x03|0x0023) ncmd 1
status 0x00 class 0x000000
2011-03-03 08:18:37.572532 < HCI Command: Read Local Version Information
(0x04|0x0001) plen 0
2011-03-03 08:18:37.576057 > HCI Event: Command Complete (0x0e) plen 12
Read Local Version Information (0x04|0x0001) ncmd 1
status 0x00
HCI Version: 2.0 (0x3) HCI Revision: 0x7a6
LMP Version: 2.0 (0x3) LMP Subversion: 0x7a6
Manufacturer: Cambridge Silicon Radio (10)
2011-03-03 08:18:37.618553 < HCI Command: Set Event Mask (0x03|0x0001) plen 8
Mask: 0xfffffbff07180000
2011-03-03 08:18:37.621056 > HCI Event: Command Complete (0x0e) plen 4
Set Event Mask (0x03|0x0001) ncmd 1
status 0x00
...
syslog:
...
Mar 3 08:13:17 koni kernel: usb 6-1: new full speed USB device using ohci_hcd
and address 2
Mar 3 08:13:17 koni kernel: usb 6-1: New USB device found, idVendor=13dd,
idProduct=0001
Mar 3 08:13:17 koni kernel: usb 6-1: New USB device strings: Mfr=1, Product=2,
SerialNumber=0
Mar 3 08:13:17 koni kernel: usb 6-1: Product: BlueCON U2
Mar 3 08:13:17 koni kernel: usb 6-1: Manufacturer: i.Tech Dynamic
Mar 3 08:13:17 koni kernel: Bluetooth: Generic Bluetooth USB driver ver 0.6
Mar 3 08:13:17 koni kernel: hci_register_dev: ffff88013c6b1000 name bus 1
owner ffffffffa038b7c0
Mar 3 08:13:17 koni kernel: hci_rfkill_set_block: ffff88013c6b1000 name hci0
blocked 0
Mar 3 08:13:17 koni kernel: usbcore: registered new interface driver btusb
Mar 3 08:13:31 koni kernel: hci_dev_get: 0
Mar 3 08:13:37 koni kernel: hci_dev_get: 0
Mar 3 08:13:39 koni -- MARK --
Mar 3 08:14:04 koni kernel: hci_dev_get: 0
Mar 3 08:14:04 koni kernel: hci_dev_get: 0
Mar 3 08:14:04 koni kernel: hci_dev_get: 0
Mar 3 08:14:26 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni bluetoothd[3270]: Bluetooth deamon 4.89
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:parse_config() parsing
main.conf
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:parse_config() discovto=0
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:parse_config() pairto=0
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:parse_config() pageto=8192
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:parse_config() name=%h-%d
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:parse_config() class=0x000100
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:parse_config()
discov_interval=0
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:parse_config() Key file does
not have key 'DeviceID'
Mar 3 08:14:38 koni bluetoothd[3270]: Starting SDP server
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:plugin_init() Loading
builtin plugins
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading audio
plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading input
plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading serial
plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading network
plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading service
plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading hciops
plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading mgmtops
plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading
formfactor plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:add_plugin() Loading storage
plugin
Mar 3 08:14:38 koni bluetoothd[3270]: src/plugin.c:plugin_init() Loading
plugins /usr/lib/bluetooth/plugins
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/service.c:register_interface()
path /org/bluez/3270/any
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/service.c:register_interface()
Registered interface org.bluez.Service on path /org/bluez/3270/any
Mar 3 08:14:38 koni bluetoothd[3270]: network/manager.c:read_config()
/etc/bluetooth/network.conf: Key file does not have key 'DisableSecurity'
Mar 3 08:14:38 koni bluetoothd[3270]: network/manager.c:read_config() Config
options: Security=true
Mar 3 08:14:38 koni bluetoothd[3270]: input/manager.c:input_manager_init()
input.conf: Key file does not have key 'IdleTimeout'
Mar 3 08:14:38 koni kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3
Mar 3 08:14:38 koni bluetoothd[3270]: audio/manager.c:audio_manager_init()
audio.conf: Key file does not have key 'AutoConnect'
Mar 3 08:14:38 koni bluetoothd[3270]: audio/unix.c:unix_init() Unix socket
created: 8
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:hciops_init()
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:hciops_setup()
Mar 3 08:14:38 koni bluetoothd[3270]: src/main.c:main() Entering main loop
Mar 3 08:14:38 koni bluetoothd[3270]: src/rfkill.c:rfkill_event() RFKILL event
idx 0 type 1 op 0 soft 0 hard 0
Mar 3 08:14:38 koni bluetoothd[3270]: src/rfkill.c:rfkill_event() RFKILL event
idx 5 type 2 op 0 soft 0 hard 0
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:init_known_adapters()
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:init_device() hci0
Mar 3 08:14:38 koni bluetoothd[3270]: Listening for HCI events on hci0
Mar 3 08:14:38 koni kernel: hci_register_proto: ffffffffa057b000 name SCO id 1
Mar 3 08:14:38 koni kernel: Bluetooth: SCO (Voice Link) ver 0.6
Mar 3 08:14:38 koni kernel: Bluetooth: SCO socket layer initialized
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:init_device() child 3275
forked
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_dev_open: hci0 ffff88013c6b1000
Mar 3 08:14:38 koni kernel: __hci_request: hci0 start
Mar 3 08:14:38 koni kernel: hci_init_req: hci0 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0xc03 plen 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 3
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0x1003 plen 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 3
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0x1001 plen 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 3
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0x1005 plen 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 3
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0x1009 plen 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 3
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0xc23 plen 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 3
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0xc14 plen 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 3
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0xc25 plen 0
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 3
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0xc05 plen 1
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 4
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0xc18 plen 2
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 5
Mar 3 08:14:38 koni kernel: hci_send_cmd: hci0 opcode 0xc16 plen 2
Mar 3 08:14:38 koni kernel: hci_send_cmd: skb len 5
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cmd_status_evt: hci0 opcode 0x0
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cc_reset: hci0 status 0x0
Mar 3 08:14:38 koni kernel: hci_req_complete: hci0 command 0x0c03 result 0x00
(last cmd 0x0c16)
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cc_read_local_version: hci0 status 0x0
Mar 3 08:14:38 koni kernel: hci_cc_read_local_version: hci0 manufacturer 10 hci
ver 3:1958
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni bluetoothd[3270]:
plugins/hciops.c:read_local_version_complete() Got version for hci0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cc_read_buffer_size: hci0 status 0x0
Mar 3 08:14:38 koni kernel: hci_cc_read_buffer_size: hci0 acl mtu 384:8 sco mtu
64:8
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:read_bd_addr_complete()
hci0 status 0
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:read_bd_addr_complete()
Got bdaddr for hci0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cc_read_bd_addr: hci0 status 0x0
Mar 3 08:14:38 koni kernel: hci_req_complete: hci0 command 0x1009 result 0x00
(last cmd 0x0c16)
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cc_read_class_of_dev: hci0 status 0x0
Mar 3 08:14:38 koni kernel: hci_cc_read_class_of_dev: hci0 class 0x000000
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni bluetoothd[3270]:
plugins/hciops.c:read_local_name_complete() hci0 status 0
Mar 3 08:14:38 koni bluetoothd[3270]:
plugins/hciops.c:read_local_name_complete() Got name for hci0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cc_read_local_name: hci0 status 0x0
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cc_read_voice_setting: hci0 status 0x0
Mar 3 08:14:38 koni kernel: hci_cc_read_voice_setting: hci0 voice setting
0x0060
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 4
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cmd_complete_evt: hci0 opcode 0xc05
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 5
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cmd_complete_evt: hci0 opcode 0xc18
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 5
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cc_write_ca_timeout: hci0 status 0x0
Mar 3 08:14:38 koni kernel: hci_req_complete: hci0 command 0x0c16 result 0x00
(last cmd 0x0c16)
Mar 3 08:14:38 koni kernel: __hci_request: hci0 end: err 0
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:child_exit() child 3275
exited
Mar 3 08:14:38 koni bluetoothd[3270]: HCI dev 0 up
Mar 3 08:14:38 koni bluetoothd[3270]: plugins/hciops.c:device_devup_setup()
hci0
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 5
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 0
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cmd_complete_evt: hci0 opcode 0xc18
Mar 3 08:14:38 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:14:38 koni kernel: hci_send_frame: hci0 type 1 len 10
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:14:38 koni kernel: hci_rx_task: hci0
Mar 3 08:14:38 koni kernel: hci_cmd_complete_evt: hci0 opcode 0xc0d
Mar 3 08:14:38 koni kernel: hci_dev_get: 0
Mar 3 08:18:31 koni kernel: hci_dev_get: 0
Mar 3 08:18:37 koni kernel: hci_dev_get: 0
Mar 3 08:18:37 koni kernel: hci_dev_get: 0
Mar 3 08:18:37 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:18:37 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:18:37 koni bluetoothd[3270]:
plugins/hciops.c:read_local_name_complete() hci0 status 0
Mar 3 08:18:37 koni bluetoothd[3270]:
plugins/hciops.c:read_local_name_complete() Got name for hci0
Mar 3 08:18:37 koni kernel: hci_rx_task: hci0
Mar 3 08:18:37 koni kernel: hci_cc_read_local_name: hci0 status 0x0
Mar 3 08:18:37 koni kernel: hci_dev_get: 0
Mar 3 08:18:37 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:18:37 koni kernel: hci_dev_get: 0
Mar 3 08:18:37 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:18:37 koni kernel: hci_cmd_task: hci0 cmd 0
Mar 3 08:18:37 koni bluetoothd[3270]:
plugins/hciops.c:read_local_features_complete() Got features for hci0
Mar 3 08:18:37 koni bluetoothd[3270]: src/adapter.c:btd_adapter_ref()
0x7f84c3257950: ref=1
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_read_bdaddr()
hci0
Mar 3 08:18:37 koni bluetoothd[3270]:
plugins/hciops.c:hciops_read_local_version() hci0
Mar 3 08:18:37 koni bluetoothd[3270]:
plugins/hciops.c:hciops_read_local_features() hci0
Mar 3 08:18:37 koni bluetoothd[3270]:
src/sdpd-database.c:sdp_init_services_list()
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_add_uuid() hci0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:update_service_classes()
hci0 value 0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_add_uuid() hci0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:update_service_classes()
hci0 value 0
Mar 3 08:18:37 koni kernel: hci_rx_task: hci0
Mar 3 08:18:37 koni kernel: hci_cc_read_local_features: hci0 status 0x0
Mar 3 08:18:37 koni kernel: hci_cc_read_local_features: hci0 features
0xffff8ffe9bf90080
Mar 3 08:18:37 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:18:37 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:18:37 koni kernel: hci_dev_get: 0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/service.c:register_interface()
path /org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/service.c:register_interface()
Registered interface org.bluez.Service on path /org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: network/manager.c:network_server_probe()
path /org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: src/adapter.c:btd_adapter_ref()
0x7f84c3257950: ref=2
Mar 3 08:18:37 koni bluetoothd[3270]: network/server.c:server_register()
Registered interface org.bluez.NetworkServer on path /org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: serial/manager.c:proxy_probe() path
/org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: src/adapter.c:btd_adapter_ref()
0x7f84c3257950: ref=3
Mar 3 08:18:37 koni bluetoothd[3270]: serial/proxy.c:proxy_register()
Registered interface org.bluez.SerialProxyManager on path /org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: src/adapter.c:btd_adapter_ref()
0x7f84c3257950: ref=4
Mar 3 08:18:37 koni bluetoothd[3270]: audio/manager.c:headset_server_probe()
path /org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: src/adapter.c:btd_adapter_ref()
0x7f84c3257950: ref=5
Mar 3 08:18:37 koni bluetoothd[3270]: audio/manager.c:audio_adapter_ref()
0x7f84c3258000: ref=1
Mar 3 08:18:37 koni bluetoothd[3270]: audio/manager.c:headset_server_init()
audio.conf: Key file does not have key 'Master'
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Adding record with handle 0x10000
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_add_uuid() hci0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:update_service_classes()
hci0 value 0
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000003-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000100-0000-1000-8000-00805f9
Mar 3 08:18:37 koni kernel: rfcomm_dlc_clear_state: ffff88013ad69100
Mar 3 08:18:37 koni kernel: rfcomm_dlc_alloc: ffff88013ad69100
Mar 3 08:18:37 koni kernel: hci_rx_task: hci0
Mar 3 08:18:37 koni kernel: hci_cc_read_class_of_dev: hci0 status 0x0
Mar 3 08:18:37 koni kernel: hci_cc_read_class_of_dev: hci0 class 0x000000
Mar 3 08:18:37 koni kernel: hci_dev_get: 0
Mar 3 08:18:37 koni kernel: hci_cmd_task: hci0 cmd 1
Mar 3 08:18:37 koni kernel: hci_send_frame: hci0 type 1 len 3
Mar 3 08:18:37 koni kernel: rfcomm_dlc_clear_state: ffff88013c50c200
Mar 3 08:18:37 koni kernel: rfcomm_dlc_alloc: ffff88013c50c200
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001002-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001108-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001112-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001203-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: audio/headset.c:headset_config_init()
audio.conf: Key file does not have key 'SCORouting'
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Adding record with handle 0x10001
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_add_uuid() hci0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:update_service_classes()
hci0 value 64
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000003-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000100-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001002-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 0000111e-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 0000111f-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001203-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: audio/manager.c:state_changed()
/org/bluez/3270/hci0 powered on
Mar 3 08:18:37 koni bluetoothd[3270]: audio/telephony.c:telephony_init()
Mar 3 08:18:37 koni bluetoothd[3270]: audio/headset.c:telephony_ready_ind()
Telephony plugin initialized
Mar 3 08:18:37 koni bluetoothd[3270]: audio/headset.c:print_ag_features() HFP
AG features: "Ability to reject a call" "Enhanced call status" "Extended Error
Result Codes"
Mar 3 08:18:37 koni bluetoothd[3270]: audio/manager.c:a2dp_server_probe() path
/org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: audio/manager.c:audio_adapter_ref()
0x7f84c3258000: ref=2
Mar 3 08:18:37 koni bluetoothd[3270]: audio/a2dp.c:a2dp_register() audio.conf:
Key file does not have key 'Enable'
Mar 3 08:18:37 koni bluetoothd[3270]: audio/a2dp.c:a2dp_register() audio.conf:
Key file does not have key 'Disable'
Mar 3 08:18:37 koni bluetoothd[3270]: audio/a2dp.c:a2dp_register() audio.conf:
Key file does not have group 'A2DP'
Mar 3 08:18:37 koni bluetoothd[3270]: audio/a2dp.c:a2dp_register() audio.conf:
Key file does not have group 'A2DP'
Mar 3 08:18:37 koni bluetoothd[3270]: audio/a2dp.c:a2dp_register() audio.conf:
Key file does not have group 'A2DP'
Mar 3 08:18:37 koni bluetoothd[3270]: audio/a2dp.c:a2dp_register() audio.conf:
Key file does not have group 'A2DP'
Mar 3 08:18:37 koni bluetoothd[3270]: audio/avdtp.c:avdtp_init() audio.conf:
Key file does not have key 'Master'
Mar 3 08:18:37 koni bluetoothd[3270]: audio/avdtp.c:avdtp_register_sep() SEP
0x7f84c3259ad0 registered: type:0 codec:0 seid:1
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Adding record with handle 0x10002
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_add_uuid() hci0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:update_service_classes()
hci0 value 72
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000019-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000100-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001002-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 0000110a-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 0000110d-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: audio/manager.c:avrcp_server_probe() path
/org/bluez/3270/hci0
Mar 3 08:18:37 koni bluetoothd[3270]: audio/manager.c:audio_adapter_ref()
0x7f84c3258000: ref=3
Mar 3 08:18:37 koni bluetoothd[3270]: audio/control.c:avrcp_register()
audio.conf: Key file does not have key 'Master'
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Adding record with handle 0x10003
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_add_uuid() hci0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:update_service_classes()
hci0 value 72
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000017-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000100-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001002-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 0000110c-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 0000110e-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Adding record with handle 0x10004
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_add_uuid() hci0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:update_service_classes()
hci0 value 72
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000017-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00000100-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 00001002-0000-1000-8000-00805f9
Mar 3 08:18:37 koni bluetoothd[3270]: src/sdpd-service.c:add_record_to_server()
Record pattern UUID 0000110e-0000-1000-8000-00805f9
Mar 3 08:18:37 koni kernel: hci_rx_task: hci0
Mar 3 08:18:37 koni kernel: hci_cc_read_local_version: hci0 status 0x0
Mar 3 08:18:37 koni kernel: hci_cc_read_local_version: hci0 manufacturer 10 hci
ver 3:1958
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/formfactor.c:formfactor_probe()
Setting 0x000100 for major/minor device class
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_set_dev_class()
hci0 major 1 minor 0
Mar 3 08:18:37 koni bluetoothd[3270]: plugins/hciops.c:hciops_unblock_device()
hci0 dba 00:00:00:00:00:00
Mar 3 08:18:37 koni bluetoothd[3270]: src/device.c:device_create() Creating
device /org/bluez/3270/hci0/dev_00_11_24_68_xx_yy
Mar 3 08:18:37 koni bluetoothd[3270]: src/device.c:btd_device_ref()
0x7f84c3280fc0: ref=1
Mar 3 08:18:37 koni bluetoothd[3270]: src/device.c:device_set_temporary()
temporary 0
Mar 3 08:18:37 koni bluetoothd[3270]: src/device.c:device_probe_drivers()
Probing drivers for 00:11:24:68:xx:yy
... (a lot of bluetooth stuff, all only after hciconfig -a)
Hi,
On Mon, Feb 28, 2011, Mikko Vinni wrote:
> Just wondering what is the status of "bluetooth disabled with current
> 2.6.38-rc4"
> from Justin (http://www.spinics.net/lists/linux-bluetooth/msg10745.html) and
> "[BUG] usb problems in .38-rc3+"" (http://marc.info/?t=129693396800003&r=1&w=2)
> from Ed? (apologies for not being able to reply to those threads)
>
> The first one because I think I see the same problem and the second one because
> for me also "hciconfig -a" makes the bluetooth adapter work. Maybe they have
> a common cause.
I can't reproduce this issue with any of my Bluetooth adapters (I tested
with 6 different ones). Could you get us the hcidump of what happens
when bluetoothd tries to switch on the adapter for the very first time?
Probably you'll need to disable starting of bluetoothd when your system
boots so that you have the chance to run hcidump first. Additionally, if
possible, could you enable dynamic debug in your kernel and get the logs
from hci_core.c and hci_event.c? Typically you'd enable this with
something like:
echo 'file hci_event.c +p' > /sys/kernel/debug/dynamic_debug/control
echo 'file hci_core.c +p' > /sys/kernel/debug/dynamic_debug/control
Hopefully those logs will give some better idea of what's going on since
the logs provided so far aren't really helpful.
Johan