[Bug 1710601] [NEW] bluetoothctl fails to connect

[doru001]

Public bug reported:

bluetooth stopped working after some update, probably to bluez5
before it was working flawlessly following https://wiki.archlinux.org/index.php/Bluetooth#Configuration_via_the_CLI
now $ bluetoothctl shows no typed characters, $ sudo bluetoothctl works well until I try to connect the device:
[bluetooth]# connect A8:7E:33:FC:6D:15
Attempting to connect to A8:7E:33:FC:6D:15
[CHG] Device A8:7E:33:FC:6D:15 Connected: yes
Failed to connect: org.bluez.Error.NotAvailable
[CHG] Device A8:7E:33:FC:6D:15 Connected: no
[CHG] Device A8:7E:33:FC:6D:15 RSSI: -81
[CHG] Device A8:7E:33:FC:6D:15 RSSI: -63
[CHG] Device A8:7E:33:FC:6D:15 RSSI: -73
[CHG] Device A8:7E:33:FC:6D:15 RSSI: -65
[CHG] Device A8:7E:33:FC:6D:15 RSSI: -79
[CHG] Device A8:7E:33:FC:6D:15 RSSI: -61
[CHG] Device A8:7E:33:FC:6D:15 RSSI: -75
[CHG] Device A8:7E:33:FC:6D:15 RSSI: -63

I am using bluez 5.37-0ubuntu5 under Ubuntu 16.04.3 LTS, updated to the
day.

I found errors in logs:
aug 13 17:34:25 george bluetoothd[752]: Starting SDP server
aug 13 17:34:26 george ModemManager[738]: <info>  ModemManager (version 1.4.12) starting in system bus...
aug 13 17:34:26 george kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3
aug 13 17:34:26 george kernel: Bluetooth: BNEP filters: protocol multicast
aug 13 17:34:26 george kernel: Bluetooth: BNEP socket layer initialized
aug 13 17:34:26 george bluetoothd[752]: Bluetooth management interface 1.10 initialized
aug 13 17:34:26 george dbus[702]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.fre
aug 13 17:34:26 george bluetoothd[752]: Failed to obtain handles for "Service Changed" characteristic
aug 13 17:34:26 george bluetoothd[752]: Not enough free handles to register service
aug 13 17:34:26 george bluetoothd[752]: Error adding Link Loss service
aug 13 17:34:26 george bluetoothd[752]: Not enough free handles to register service
aug 13 17:34:26 george bluetoothd[752]: Not enough free handles to register service
aug 13 17:34:26 george bluetoothd[752]: Not enough free handles to register service
aug 13 17:34:26 george bluetoothd[752]: Current Time Service could not be registered
aug 13 17:34:26 george bluetoothd[752]: gatt-time-server: Input/output error (5)
aug 13 17:34:26 george bluetoothd[752]: Not enough free handles to register service
aug 13 17:34:26 george bluetoothd[752]: Not enough free handles to register service
aug 13 17:34:26 george bluetoothd[752]: Sap driver initialization failed.
aug 13 17:34:26 george bluetoothd[752]: sap-server: Operation not permitted (1)

aug 13 17:35:00 george dbus[702]: [system] Rejected send message, 2 matched rules; type="method_call", sender=":1.22" (uid=100
aug 13 17:35:14 george sudo[1199]:     user : TTY=pts/0 ; PWD=/home/user ; USER=root ; COMMAND=/usr/bin/bluetoothctl
aug 13 17:35:14 george sudo[1199]: pam_unix(sudo:session): session opened for user root by user(uid=0)
aug 13 17:35:23 george systemd[1]: Starting Stop ureadahead data collection...
aug 13 17:35:23 george systemd[1]: Started Stop ureadahead data collection.
aug 13 17:35:23 george systemd[1]: Stopped Read required files in advance.
aug 13 17:43:26 george sudo[1199]: pam_unix(sudo:session): session closed for user root
aug 13 17:47:44 george sshd[1389]: Accepted publickey for user from 192.168.69.200 port 57812 ssh2: RSA SHA256:MQ3JEM2k/Yw2jzz
aug 13 17:47:44 george sshd[1389]: pam_unix(sshd:session): session opened for user user by (uid=0)
aug 13 17:47:44 george systemd-logind[742]: New session 2 of user user.
aug 13 17:47:44 george systemd[1]: Started Session 2 of user user.
aug 13 17:47:52 george sudo[1431]:     user : TTY=pts/1 ; PWD=/home/user ; USER=root ; COMMAND=/usr/bin/bluetoothctl
aug 13 17:47:52 george sudo[1431]: pam_unix(sudo:session): session opened for user root by user(uid=0)
aug 13 17:49:30 george /usr/lib/snapd/snapd[685]: snapmgr.go:422: No snaps to auto-refresh found
aug 13 17:49:30 george systemd[1]: Starting Cleanup of Temporary Directories...
aug 13 17:49:30 george snapd[685]: 2017/08/13 17:49:30.803962 snapmgr.go:422: No snaps to auto-refresh found
aug 13 17:49:30 george systemd-tmpfiles[1459]: [/usr/lib/tmpfiles.d/var.conf:14] Duplicate line for path "/var/log", ignoring.
aug 13 17:49:31 george systemd[1]: Started Cleanup of Temporary Directories.
aug 13 17:53:16 george sudo[1520]:     user : TTY=pts/0 ; PWD=/var/log ; USER=root ; COMMAND=/usr/bin/vim -R dmesg
aug 13 17:53:16 george sudo[1520]: pam_unix(sudo:session): session opened for user root by user(uid=0)
aug 13 17:53:18 george sudo[1520]: pam_unix(sudo:session): session closed for user root

these errors are common, as you can see in comments to this bug report:
https://bugs.launchpad.net/ubuntu/+source/bluez/+bug/1490349

user at george:~$ lsmod | grep bt\\\|blue
btusb                  40960  0
btrtl                  16384  1 btusb
btbcm                  16384  1 btusb
btintel                16384  1 btusb
bluetooth             479232  24 bnep,btbcm,btrtl,btusb,btintel
toshiba_bluetooth      16384  0

strangely enough, I succeded to connect from the xfce4 GUI, using the
applet next to the clock, probably using blueman-manager and associated
GUI only commands.

hardware used is the same and of good quality, a Toshiba laptop and a
Nokia phone. I can use the GUI connection without problems, and
bluetoothctl also works correctly in user space as long as the GUI keeps
the device connected.

it looks like a permissions issue

user at george:/dev$ ls -tl | head # after boot in text mode, wireless card on
total 0
crw-rw-rw- 1 root tty       5,   2 aug 14 11:59 ptmx
crw------- 1 root root      5,   1 aug 14 11:57 console
crw--w---- 1 root tty       4,   1 aug 14 11:57 tty1
crw--w---- 1 root tty       4,   6 aug 14 11:57 tty6
crw--w---- 1 root tty       4,   5 aug 14 11:57 tty5
crw--w---- 1 root tty       4,   4 aug 14 11:57 tty4
crw--w---- 1 root tty       4,   3 aug 14 11:57 tty3
crw--w---- 1 root tty       4,   2 aug 14 11:57 tty2
brw-rw---- 1 root disk      8,   3 aug 14 11:57 sda3
user at george:/dev$ ls -tl | head # after startx
total 0
drwxrwxrwt  2 root root          80 aug 14 12:01 shm
crw-rw-rw-  1 root tty       5,   2 aug 14 12:01 ptmx
crw-------  1 user tty       4,   1 aug 14 12:01 tty1
crw-rw-rw-  1 root tty       5,   0 aug 14 12:00 tty
crw-------  1 root root      5,   1 aug 14 11:57 console
crw--w----  1 root tty       4,   6 aug 14 11:57 tty6
crw--w----  1 root tty       4,   5 aug 14 11:57 tty5
crw--w----  1 root tty       4,   4 aug 14 11:57 tty4
crw--w----  1 root tty       4,   3 aug 14 11:57 tty3
user at george:/dev$ ls -tl | head # connected
total 0
crw-rw-rw-  1 root tty       5,   2 aug 14 12:06 ptmx
crw-rw----  1 root dialout 216,   0 aug 14 12:04 rfcomm0
drwxr-xr-x  2 root root        3760 aug 14 12:04 char
drwxrwxrwt  2 root root         120 aug 14 12:04 shm
crw-------  1 user tty       4,   1 aug 14 12:01 tty1
crw-rw-rw-  1 root tty       5,   0 aug 14 12:00 tty
crw-------  1 root root      5,   1 aug 14 11:57 console
crw--w----  1 root tty       4,   6 aug 14 11:57 tty6
crw--w----  1 root tty       4,   5 aug 14 11:57 tty5

** Affects: bluez (Ubuntu)
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of
Bluetooth, which is subscribed to bluez in Ubuntu.
https://bugs.launchpad.net/bugs/1710601

Title:
  bluetoothctl fails to connect

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/bluez/+bug/1710601/+subscriptions