Comment 12 for bug 1572577

Revision history for this message
Konrad ZapaƂowicz (kzapalowicz) wrote :

What I have found in the syslog:

15:21:25 here the car is connecting to the phone, the bluez correctly handles the device:

src/adapter.c:connected_callback() hci0 device 00:1A:77:F6:D5:2B connected eir_len 5
src/device.c:device_create() dst 00:1A:77:F6:D5:2B
src/device.c:device_new() address 00:1A:77:F6:D5:2B
src/device.c:device_new() Creating device /org/bluez/hci0/dev_00_1A_77_F6_D5_2B
src/device.c:device_set_class() /org/bluez/hci0/dev_00_1A_77_F6_D5_2B 0x300408

15:21:26 next the car is disconnecting. The reason 3 means Remote Disconnected and status 0xe means Status Disconnected.

src/adapter.c:dev_disconnected() Device 00:1A:77:F6:D5:2B disconnected, reason 3
src/adapter.c:adapter_remove_connection()
src/adapter.c:adapter_remove_connection() Removing temporary device /org/bluez/hci0/dev_00_1A_77_F6_D5_2B
src/device.c:device_remove() Removing device /org/bluez/hci0/dev_00_1A_77_F6_D5_2B
src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_00_1A_77_F6_D5_2B
src/device.c:device_free() 0xb7837780
plugins/policy.c:disconnect_cb() reason 3
src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:1A:77:F6:D5:2B type 0 status 0xe

15:21:32 8 seconds later we see that the pin code request callback has kicked in

Apr 20 15:21:32 src/adapter.c:pin_code_request_callback() hci0 00:1A:77:F6:D5:2B
Apr 20 15:21:32 src/device.c:device_create() dst 00:1A:77:F6:D5:2B
Apr 20 15:21:32 src/device.c:device_new() address 00:1A:77:F6:D5:2B
Apr 20 15:21:32 src/device.c:device_new() Creating device /org/bluez/hci0/dev_00_1A_77_F6_D5_2B
Apr 20 15:21:32 src/device.c:new_auth() Requesting agent authentication for 00:1A:77:F6:D5:2B
Apr 20 15:21:32 src/agent.c:agent_ref() 0xb782a140: ref=2
The pairing request is send to the registered agent however it is denied:

Agent /com/canonical/SettingsBluetoothAgent/adapteragent replied with an error: org.bluez.Error.Rejected, The request was rejected: RequestPinCode

As a result the bonding obviously fails:

src/adapter.c:btd_adapter_pincode_reply() hci0 addr 00:1A:77:F6:D5:2B pinlen 0
src/agent.c:agent_unref() 0xb782a140: ref=2
src/agent.c:agent_unref() 0xb782a140: ref=1
src/adapter.c:connect_failed_callback() hci0 00:1A:77:F6:D5:2B status 11
plugins/policy.c:conn_fail_cb() status 11
src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:1A:77:F6:D5:2B type 0 status 0xb
src/device.c:device_bonding_complete() bonding (nil) status 0x0b
src/device.c:device_cancel_authentication() Canceling authentication request for 00:1A:77:F6:D5:2B
src/device.c:device_bonding_failed() status 11
src/adapter.c:resume_discovery()
src/device.c:device_remove() Removing device /org/bluez/hci0/dev_00_1A_77_F6_D5_2B
src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_00_1A_77_F6_D5_2B
src/device.c:device_free() 0xb7837780

15:21:40 8 seconds later the pin request callback is called again and the whole thing repeats with the same result.