Return-Path: MIME-Version: 1.0 In-Reply-To: <20170406125150.GF12069@annapurna> References: <20170406125150.GF12069@annapurna> From: Luiz Augusto von Dentz Date: Thu, 6 Apr 2017 23:46:11 +0300 Message-ID: Subject: Re: Regression in bluez 5.44, bluetoothd crashes To: Konrad Zapalowicz Cc: "linux-bluetooth@vger.kernel.org" Content-Type: text/plain; charset=UTF-8 Sender: linux-bluetooth-owner@vger.kernel.org List-ID: Hi Konrad, On Thu, Apr 6, 2017 at 3:51 PM, Konrad Zapalowicz wrote: > Hey, > > I see a regression in 5.44 when testing Sony SBH52 headset. It fails to > connect profiles but the worst thing is that the bluetoothd crashes > (logs below). > > I have git bisect'ed it down to the commit f2483bbfd. It works fine if > I remove it. That is because the very next patch fix it: commit 4a8c33b1f76edf2dfe33b9956014cc2746ae71d8 Author: Luiz Augusto von Dentz Date: Mon Nov 14 13:30:09 2016 +0200 core/adapter: Fix using wrong address type to listen ATT bdaddr_type shall only matter for controllers supporting LE otherwise it may cause BDADDR_BREDR to be used for things like LE ATT socket listen breaking reconnections. > Stacktrace: > > (gdb) c > Continuing. > > Program received signal SIGSEGV, Segmentation fault. > strlen () at ../sysdeps/x86_64/strlen.S:106 > 106 ../sysdeps/x86_64/strlen.S: No such file or directory. > (gdb) bt > #0 strlen () at ../sysdeps/x86_64/strlen.S:106 > #1 0x00007f92806179a1 in _IO_vfprintf_internal (s=s@entry=0x557f37ad5520, format=, format@entry=0x557f36cd515c "%s:%s() %s err %d", ap=0x7ffc0b7a86d0) > at vfprintf.c:1637 > #2 0x00007f92806dffc6 in ___vfprintf_chk (fp=fp@entry=0x557f37ad5520, flag=flag@entry=1, format=format@entry=0x557f36cd515c "%s:%s() %s err %d", > ap=ap@entry=0x7ffc0b7a86d0) at vfprintf_chk.c:33 > #3 0x00007f92806c9028 in __GI___vsyslog_chk (pri=, pri@entry=7, flag=flag@entry=1, fmt=fmt@entry=0x557f36cd515c "%s:%s() %s err %d", > ap=ap@entry=0x7ffc0b7a86d0) at ../misc/syslog.c:222 > #4 0x0000557f36c6735b in vsyslog (__ap=0x7ffc0b7a86d0, __fmt=0x557f36cd515c "%s:%s() %s err %d", __pri=7) at /usr/include/x86_64-linux-gnu/bits/syslog.h:47 > #5 btd_debug (index=index@entry=65535, format=format@entry=0x557f36cd515c "%s:%s() %s err %d") at src/log.c:252 > #6 0x0000557f36c94d88 in device_svc_resolved (dev=0x557f36c90e60 , bdaddr_type=0 '\000', err=-111) at src/device.c:2214 > #7 0x0000557f36c97adb in search_cb (user_data=, err=-111, recs=) at src/device.c:4516 > #8 browse_cb (recs=, err=-111, user_data=) at src/device.c:4549 > #9 0x0000557f36c73551 in connect_watch (chan=0x557f37ae0350, cond=, user_data=0x557f37ae0060) at src/sdp-client.c:286 > #10 0x00007f928124f6ea in g_main_context_dispatch () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0 > #11 0x00007f928124faa0 in ?? () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0 > #12 0x00007f928124fdc2 in g_main_loop_run () from target:/lib/x86_64-linux-gnu/libglib-2.0.so.0 > #13 0x0000557f36c353cc in main (argc=, argv=) at src/main.c:708 > (gdb) Ok, so this seem to be SDP causing and error, 111 connection refused. > Syslog: > > bluetoothd: src/device.c:bonding_request_new() Requesting bonding for 68:76:4F:6C:31:E9 > bluetoothd: src/agent.c:agent_ref() 0x557f37ae5120: ref=3 > bluetoothd: src/agent.c:agent_unref() 0x557f37ae5120: ref=2 > bluetoothd: src/adapter.c:suspend_discovery() > bluetoothd: src/adapter.c:adapter_bonding_attempt() hci0 bdaddr 68:76:4F:6C:31:E9 type 0 io_cap 0x01 > bluetoothd: src/adapter.c:add_whitelist_complete() 68:76:4F:6C:31:E9 added to kernel whitelist > bluetoothd: src/adapter.c:connected_callback() hci0 device 68:76:4F:6C:31:E9 connected eir_len 12 > bluetoothd: src/adapter.c:new_link_key_callback() hci0 new key for 68:76:4F:6C:31:E9 type 4 pin_len 0 store_hint 1 > bluetoothd: src/device.c:device_set_bonded() > bluetoothd: src/device.c:device_bonding_complete() bonding 0x557f37acc860 status 0x00 > bluetoothd: src/device.c:device_bonding_complete() Proceeding with service discovery > bluetoothd: src/agent.c:agent_unref() 0x557f37ae5120: ref=1 > bluetoothd: src/adapter.c:resume_discovery() > bluetoothd: src/adapter.c:pair_device_complete() Success (0x00) > bluetoothd: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 68:76:4F:6C:31:E9 type 0 status 0x0 > bluetoothd: src/device.c:device_bonding_complete() bonding (nil) status 0x00 > bluetoothd: src/adapter.c:resume_discovery() > bluetoothd: src/gatt-database.c:connect_cb() New incoming BR/EDR ATT connection > bluetoothd: attrib/gattrib.c:g_attrib_ref() 0x557f37ae4b40: g_attrib_ref=1 > bluetoothd: src/device.c:load_gatt_db() Restoring 68:76:4F:6C:31:E9 gatt database from file > bluetoothd: No cache for 68:76:4F:6C:31:E9 > bluetoothd: src/gatt-client.c:btd_gatt_client_connected() Device connected. > bluetoothd: src/adapter.c:dev_disconnected() Device 68:76:4F:6C:31:E9 disconnected, reason 3 > bluetoothd: src/adapter.c:adapter_remove_connection() > bluetoothd: plugins/policy.c:disconnect_cb() reason 3 > bluetoothd: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 68:76:4F:6C:31:E9 type 0 status 0xe > bluetoothd: src/device.c:device_bonding_complete() bonding (nil) status 0x0e > bluetoothd: src/device.c:device_bonding_failed() status 14 > bluetoothd: src/adapter.c:resume_discovery() > bluetoothd: src/device.c:gatt_debug() Primary service discovery failed. ATT ECODE: 0x00 > bluetoothd: src/device.c:gatt_debug() Failed to initialize gatt-client > bluetoothd: src/device.c:gatt_client_ready_cb() status: failed, error: 0 > bluetoothd: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_68_76_4F_6C_31_E9 err -5 > bluetoothd: src/device.c:att_disconnected_cb() > bluetoothd: src/device.c:att_disconnected_cb() Connection reset by peer (104) > bluetoothd: src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. Cleaning up. > bluetoothd: src/device.c:att_disconnected_cb() Automatic connection disabled > bluetoothd: attrib/gattrib.c:g_attrib_unref() 0x557f37ae4b40: g_attrib_unref=0 > bluetoothd: src/device.c:btd_device_set_trusted() trusted 1 > bluetoothd: src/device.c:connect_profiles() /org/bluez/hci0/dev_68_76_4F_6C_31_E9 (all), client :1.256 > bluetoothd: src/device.c:connect_profiles() Resolving services for /org/bluez/hci0/dev_68_76_4F_6C_31_E9 > bluetoothd: src/gatt-database.c:connect_cb() New incoming BR/EDR ATT connection > bluetoothd: attrib/gattrib.c:g_attrib_ref() 0x557f37ae4b40: g_attrib_ref=1 > bluetoothd: src/device.c:load_gatt_db() Restoring 68:76:4F:6C:31:E9 gatt database from file > bluetoothd: No cache for 68:76:4F:6C:31:E9 > bluetoothd: src/gatt-client.c:btd_gatt_client_connected() Device connected. > bluetoothd: 89:48:53:01:00:27: error updating services: Connection refused (111) Interesting, the device is connecting ATT over BR/EDR which is weird if that is a headset, and we can see the 111, though the address printed seems wrong, I wonder if that is why it crashes. > There is one interestig thing that I have noticed examining the the > btmon output. The bluez is repeatedly (literally till the end) sending > the Information Request (Extended Feature Mask) and the headset is > answering Not Supported. For the same headset bluez 5.43 sends this > request only once. The bluez 5.44 works fine with a Phillips headset > that answers Success to this knd of Information Response. Well this is the information request is sent by the kernel, so if you haven't change it between versions that should not change between daemon versions, but ATT is not a fixed channel on BR/EDR so I wonder if the information request is actually sent because ATT is being connected. > Additionaly to Information Request (Ext Feature Mask) bluez 5.44 keeps > repeating ATT Read By Group Type Request, GATT Primary Service > Declaration which in case of Phillips device happens only once. Bluez > 5.43 does not send it whatsoever. I suspect it doesn't even connect over ATT in 5.43, anyway that should only happen once but I can see from the logs that it fails and disconnects and then connects again. > Let me know if I can in any way help debugging this issue further. > > Thanks, > Konrad > -- > To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html -- Luiz Augusto von Dentz