Hello everyone,
I have discovered a strange problem with Bluez. I have two Sony PS3 clone devices, which I tried to connect to LEGO EV3 (slow ARM device) powered by EV3DEV (ev3dev.org), which is a Debian-based OS. I used a Debian-buster version (oss.jfrog.org/list/oss-snapshot-local/org/ev3dev/brickstrap/2019-09-08/snapshot-ev3dev-buster-ev3-generic-2019-09-08.img.xz) that includes Bluez 5.50
It became possible to connect Sony PS3 clone devices after the following change was added:
git.kernel.org/pub/scm/bluetooth/bluez.git/commit/?h=5.48&id=1629c39ededef07988a5403b27331e0e317f1e08
When I attempted to connect a single PS3 device, it didn't connect. However, when I tried to connect both devices at the same time one of them was connected, while another one didn't. The problem occurs each time when I attempted to connect these PS3 devices. It is shown in the attached "ev3-bluetoothd-log.txt" file. Here device 05:F3:77:B5:63:25 unsuccessfully attempted to connects until a second device 06:2A:94:A0:63:25 attempted to connect at the same time (line 35). Then device 05:F3:77:B5:63:25 successfully connected (line 41), while device 06:2A:94:A0:63:25 kept trying to connect without any luck.
I tried to connect these devices to a laptop with Ubuntu and the same version of Bluez 5.50. They connect without any problem. See attached "ubuntu-bluetoothd-log.txt".
I would probably add more debug messages to see what exactly is going on, but I don't have much experience of compiling such projects in Linux. A Bluez package that I built and installed myself on LEGO EV3 device using these instructions: git.kernel.org/pub/scm/bluetooth/bluez.git/about/ doesn't work.
I am wondering whether anyone can take a look and help with this problem? I can definitely assist with testing or recording more logs if needed. Solving this problem will allow many kids around the world to connect inexpensive Sony PS3 clone controllers to LEGO EV3 robots.
Many thanks,
Eugene
Dec 17 21:58:17 usb bluetoothd[3594]: src/adapter.c:connected_callback() hci0 device 05:F3:77:B5:63:25 connected eir_len 5
Dec 17 21:58:21 usb bluetoothd[3594]: profiles/input/server.c:connect_event_cb() Incoming connection from 05:F3:77:B5:63:25 on PSM 17
Dec 17 21:58:21 usb bluetoothd[3594]: profiles/input/device.c:input_device_set_channel() idev 0x563461452780 psm 17
Dec 17 21:58:21 usb bluetoothd[3594]: profiles/input/server.c:confirm_event_cb()
Dec 17 21:58:21 usb bluetoothd[3594]: profiles/input/server.c:connect_event_cb() Incoming connection from 05:F3:77:B5:63:25 on PSM 19
Dec 17 21:58:21 usb bluetoothd[3594]: profiles/input/device.c:input_device_set_channel() idev 0x563461452780 psm 19
Dec 17 21:58:21 usb bluetoothd[3594]: src/service.c:change_state() 0x563461456af0: device 05:F3:77:B5:63:25 profile input-hid state changed: disconnected -> connected (0)
Dec 17 21:58:21 usb bluetoothd[3594]: src/service.c:btd_service_ref() 0x563461456af0: ref=3
Dec 17 21:58:21 usb bluetoothd[3594]: plugins/policy.c:service_cb() Added input-hid reconnect 0
Dec 17 21:58:26 usb bluetoothd[3594]: src/adapter.c:connected_callback() hci0 device 06:2A:94:A0:63:25 connected eir_len 5
Dec 17 21:58:30 usb bluetoothd[3594]: profiles/input/server.c:connect_event_cb() Incoming connection from 06:2A:94:A0:63:25 on PSM 17
Dec 17 21:58:30 usb bluetoothd[3594]: profiles/input/device.c:input_device_set_channel() idev 0x563461451030 psm 17
Dec 17 21:58:30 usb bluetoothd[3594]: profiles/input/server.c:confirm_event_cb()
Dec 17 21:58:30 usb bluetoothd[3594]: profiles/input/server.c:connect_event_cb() Incoming connection from 06:2A:94:A0:63:25 on PSM 19
Dec 17 21:58:30 usb bluetoothd[3594]: profiles/input/device.c:input_device_set_channel() idev 0x563461451030 psm 19
Dec 17 21:58:30 usb bluetoothd[3594]: src/service.c:change_state() 0x56346144e920: device 06:2A:94:A0:63:25 profile input-hid state changed: disconnected -> connected (0)
Dec 17 21:58:30 usb bluetoothd[3594]: src/service.c:btd_service_ref() 0x56346144e920: ref=3
Dec 17 21:58:30 usb bluetoothd[3594]: plugins/policy.c:service_cb() Added input-hid reconnect 0
Dec 18 02:24:09 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 05:F3:77:B5:63:25 connected eir_len 5
Dec 18 02:24:13 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 05:F3:77:B5:63:25 on PSM 17
Dec 18 02:24:13 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ed9b0 psm 17
Dec 18 02:24:14 ev3dev bluetoothd[334]: src/adapter.c:dev_disconnected() Device 05:F3:77:B5:63:25 disconnected, reason 1
Dec 18 02:24:14 ev3dev bluetoothd[334]: src/adapter.c:adapter_remove_connection()
Dec 18 02:24:14 ev3dev bluetoothd[334]: plugins/policy.c:disconnect_cb() reason 1
Dec 18 02:24:14 ev3dev bluetoothd[334]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 05:F3:77:B5:63:25 type 0 status 0xe
Dec 18 02:24:14 ev3dev bluetoothd[334]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Dec 18 02:24:14 ev3dev bluetoothd[334]: src/device.c:device_bonding_failed() status 14
Dec 18 02:24:14 ev3dev bluetoothd[334]: src/adapter.c:resume_discovery()
Dec 18 02:24:14 ev3dev bluetoothd[334]: profiles/input/device.c:ctrl_watch_cb() Device 05:F3:77:B5:63:25 disconnected
Dec 18 02:24:15 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 05:F3:77:B5:63:25 connected eir_len 5
Dec 18 02:24:19 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 05:F3:77:B5:63:25 on PSM 17
Dec 18 02:24:19 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ed9b0 psm 17
Dec 18 02:24:22 ev3dev bluetoothd[334]: src/adapter.c:dev_disconnected() Device 05:F3:77:B5:63:25 disconnected, reason 1
Dec 18 02:24:22 ev3dev bluetoothd[334]: src/adapter.c:adapter_remove_connection()
Dec 18 02:24:22 ev3dev bluetoothd[334]: plugins/policy.c:disconnect_cb() reason 1
Dec 18 02:24:22 ev3dev bluetoothd[334]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 05:F3:77:B5:63:25 type 0 status 0xe
Dec 18 02:24:22 ev3dev bluetoothd[334]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Dec 18 02:24:22 ev3dev bluetoothd[334]: src/device.c:device_bonding_failed() status 14
Dec 18 02:24:22 ev3dev bluetoothd[334]: src/adapter.c:resume_discovery()
Dec 18 02:24:22 ev3dev bluetoothd[334]: profiles/input/device.c:ctrl_watch_cb() Device 05:F3:77:B5:63:25 disconnected
Dec 18 02:24:22 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 05:F3:77:B5:63:25 connected eir_len 5
Dec 18 02:24:26 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 05:F3:77:B5:63:25 on PSM 17
Dec 18 02:24:26 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ed9b0 psm 17
Dec 18 02:24:31 ev3dev bluetoothd[334]: src/adapter.c:dev_disconnected() Device 05:F3:77:B5:63:25 disconnected, reason 1
Dec 18 02:24:31 ev3dev bluetoothd[334]: src/adapter.c:adapter_remove_connection()
Dec 18 02:24:31 ev3dev bluetoothd[334]: plugins/policy.c:disconnect_cb() reason 1
Dec 18 02:24:31 ev3dev bluetoothd[334]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 05:F3:77:B5:63:25 type 0 status 0xe
Dec 18 02:24:31 ev3dev bluetoothd[334]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Dec 18 02:24:31 ev3dev bluetoothd[334]: src/device.c:device_bonding_failed() status 14
Dec 18 02:24:31 ev3dev bluetoothd[334]: src/adapter.c:resume_discovery()
Dec 18 02:24:31 ev3dev bluetoothd[334]: profiles/input/device.c:ctrl_watch_cb() Device 05:F3:77:B5:63:25 disconnected
Dec 18 02:24:31 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 05:F3:77:B5:63:25 connected eir_len 5
Dec 18 02:24:35 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 06:2A:94:A0:63:25 connected eir_len 5
Dec 18 02:24:35 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 05:F3:77:B5:63:25 on PSM 17
Dec 18 02:24:35 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ed9b0 psm 17
Dec 18 02:24:35 ev3dev bluetoothd[334]: profiles/input/server.c:confirm_event_cb()
Dec 18 02:24:35 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 05:F3:77:B5:63:25 on PSM 19
Dec 18 02:24:35 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ed9b0 psm 19
Dec 18 02:24:36 ev3dev bluetoothd[334]: src/service.c:change_state() 0x5eabe0: device 05:F3:77:B5:63:25 profile input-hid state changed: disconnected -> connected (0)
Dec 18 02:24:36 ev3dev bluetoothd[334]: src/service.c:btd_service_ref() 0x5eabe0: ref=3
Dec 18 02:24:36 ev3dev bluetoothd[334]: plugins/policy.c:service_cb() Added input-hid reconnect 0
Dec 18 02:24:39 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 06:2A:94:A0:63:25 on PSM 17
Dec 18 02:24:39 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ee470 psm 17
Dec 18 02:24:59 ev3dev bluetoothd[334]: src/adapter.c:dev_disconnected() Device 06:2A:94:A0:63:25 disconnected, reason 1
Dec 18 02:24:59 ev3dev bluetoothd[334]: src/adapter.c:adapter_remove_connection()
Dec 18 02:24:59 ev3dev bluetoothd[334]: plugins/policy.c:disconnect_cb() reason 1
Dec 18 02:24:59 ev3dev bluetoothd[334]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 06:2A:94:A0:63:25 type 0 status 0xe
Dec 18 02:24:59 ev3dev bluetoothd[334]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Dec 18 02:24:59 ev3dev bluetoothd[334]: src/device.c:device_bonding_failed() status 14
Dec 18 02:24:59 ev3dev bluetoothd[334]: src/adapter.c:resume_discovery()
Dec 18 02:24:59 ev3dev bluetoothd[334]: profiles/input/device.c:ctrl_watch_cb() Device 06:2A:94:A0:63:25 disconnected
Dec 18 02:25:01 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 06:2A:94:A0:63:25 connected eir_len 5
Dec 18 02:25:05 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 06:2A:94:A0:63:25 on PSM 17
Dec 18 02:25:05 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ee470 psm 17
Dec 18 02:25:25 ev3dev bluetoothd[334]: src/adapter.c:dev_disconnected() Device 06:2A:94:A0:63:25 disconnected, reason 1
Dec 18 02:25:25 ev3dev bluetoothd[334]: src/adapter.c:adapter_remove_connection()
Dec 18 02:25:25 ev3dev bluetoothd[334]: plugins/policy.c:disconnect_cb() reason 1
Dec 18 02:25:25 ev3dev bluetoothd[334]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 06:2A:94:A0:63:25 type 0 status 0xe
Dec 18 02:25:25 ev3dev bluetoothd[334]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Dec 18 02:25:25 ev3dev bluetoothd[334]: src/device.c:device_bonding_failed() status 14
Dec 18 02:25:25 ev3dev bluetoothd[334]: src/adapter.c:resume_discovery()
Dec 18 02:25:25 ev3dev bluetoothd[334]: profiles/input/device.c:ctrl_watch_cb() Device 06:2A:94:A0:63:25 disconnected
Dec 18 02:25:29 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 06:2A:94:A0:63:25 connected eir_len 5
Dec 18 02:25:33 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 06:2A:94:A0:63:25 on PSM 17
Dec 18 02:25:33 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ee470 psm 17
Dec 18 02:25:53 ev3dev bluetoothd[334]: src/adapter.c:dev_disconnected() Device 06:2A:94:A0:63:25 disconnected, reason 1
Dec 18 02:25:53 ev3dev bluetoothd[334]: src/adapter.c:adapter_remove_connection()
Dec 18 02:25:53 ev3dev bluetoothd[334]: plugins/policy.c:disconnect_cb() reason 1
Dec 18 02:25:53 ev3dev bluetoothd[334]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 06:2A:94:A0:63:25 type 0 status 0xe
Dec 18 02:25:53 ev3dev bluetoothd[334]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Dec 18 02:25:53 ev3dev bluetoothd[334]: src/device.c:device_bonding_failed() status 14
Dec 18 02:25:53 ev3dev bluetoothd[334]: src/adapter.c:resume_discovery()
Dec 18 02:25:53 ev3dev bluetoothd[334]: profiles/input/device.c:ctrl_watch_cb() Device 06:2A:94:A0:63:25 disconnected
Dec 18 02:25:55 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 06:2A:94:A0:63:25 connected eir_len 5
Dec 18 02:25:59 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 06:2A:94:A0:63:25 on PSM 17
Dec 18 02:25:59 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ee470 psm 17
Dec 18 02:26:19 ev3dev bluetoothd[334]: src/adapter.c:dev_disconnected() Device 06:2A:94:A0:63:25 disconnected, reason 1
Dec 18 02:26:19 ev3dev bluetoothd[334]: src/adapter.c:adapter_remove_connection()
Dec 18 02:26:19 ev3dev bluetoothd[334]: plugins/policy.c:disconnect_cb() reason 1
Dec 18 02:26:19 ev3dev bluetoothd[334]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 06:2A:94:A0:63:25 type 0 status 0xe
Dec 18 02:26:19 ev3dev bluetoothd[334]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Dec 18 02:26:19 ev3dev bluetoothd[334]: src/device.c:device_bonding_failed() status 14
Dec 18 02:26:19 ev3dev bluetoothd[334]: src/adapter.c:resume_discovery()
Dec 18 02:26:19 ev3dev bluetoothd[334]: profiles/input/device.c:ctrl_watch_cb() Device 06:2A:94:A0:63:25 disconnected
Dec 18 02:26:21 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 06:2A:94:A0:63:25 connected eir_len 5
Dec 18 02:26:25 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 06:2A:94:A0:63:25 on PSM 17
Dec 18 02:26:25 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ee470 psm 17
Dec 18 02:26:45 ev3dev bluetoothd[334]: src/adapter.c:dev_disconnected() Device 06:2A:94:A0:63:25 disconnected, reason 1
Dec 18 02:26:45 ev3dev bluetoothd[334]: src/adapter.c:adapter_remove_connection()
Dec 18 02:26:45 ev3dev bluetoothd[334]: plugins/policy.c:disconnect_cb() reason 1
Dec 18 02:26:45 ev3dev bluetoothd[334]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 06:2A:94:A0:63:25 type 0 status 0xe
Dec 18 02:26:45 ev3dev bluetoothd[334]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Dec 18 02:26:45 ev3dev bluetoothd[334]: src/device.c:device_bonding_failed() status 14
Dec 18 02:26:45 ev3dev bluetoothd[334]: src/adapter.c:resume_discovery()
Dec 18 02:26:45 ev3dev bluetoothd[334]: profiles/input/device.c:ctrl_watch_cb() Device 06:2A:94:A0:63:25 disconnected
Dec 18 02:26:50 ev3dev bluetoothd[334]: src/adapter.c:connected_callback() hci0 device 06:2A:94:A0:63:25 connected eir_len 5
Dec 18 02:26:54 ev3dev bluetoothd[334]: profiles/input/server.c:connect_event_cb() Incoming connection from 06:2A:94:A0:63:25 on PSM 17
Dec 18 02:26:54 ev3dev bluetoothd[334]: profiles/input/device.c:input_device_set_channel() idev 0x5ee470 psm 17
