bluetoothctl fails to connect [USB 0930:0506 Toshiba Corp. Integrated Bluetooth]

[doru001]

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@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@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@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@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
---
ApportVersion: 2.20.1-0ubuntu2.10
Architecture: i386
CurrentDesktop: XFCE
DistroRelease: Ubuntu 16.04
InstallationDate: Installed on 2017-01-16 (210 days ago)
InstallationMedia: Ubuntu 16.04.1 LTS "Xenial Xerus" - Release i386 (20160719)
InterestingModules: rfcomm bnep btusb bluetooth
MachineType: TOSHIBA Satellite A80
Package: bluez 5.37-0ubuntu5
PackageArchitecture: i386
PccardctlIdent:
 Socket 0:
   no product info available
PccardctlStatus:
 Socket 0:
   no card
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.4.0-91-generic root=UUID=c661e78f-3377-4661-b1a4-35f168e682ed ro text consoleblank=300
ProcVersionSignature: Ubuntu 4.4.0-91.114-generic 4.4.76
Tags: xenial
Uname: Linux 4.4.0-91-generic i686
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: adm cdrom dip lpadmin netdev plugdev sambashare sudo
_MarkForUpload: True
dmi.bios.date: 10/25/2006
dmi.bios.vendor: TOSHIBA
dmi.bios.version: V2.80
dmi.board.name: EAT10/EAT20
dmi.board.vendor: TOSHIBA
dmi.board.version: Null
dmi.chassis.asset.tag: *
dmi.chassis.type: 10
dmi.chassis.vendor: TOSHIBA
dmi.chassis.version: N/A
dmi.modalias: dmi:bvnTOSHIBA:bvrV2.80:bd10/25/2006:svnTOSHIBA:pnSatelliteA80:pvrPSA80L-03U003:rvnTOSHIBA:rnEAT10/EAT20:rvrNull:cvnTOSHIBA:ct10:cvrN/A:
dmi.product.name: Satellite A80
dmi.product.version: PSA80L-03U003
dmi.sys.vendor: TOSHIBA
hciconfig:
 hci0: Type: BR/EDR Bus: USB
  BD Address: 00:03:7A:21:C0:53 ACL MTU: 192:8 SCO MTU: 64:8
  UP RUNNING PSCAN
  RX bytes:8854 acl:44 sco:0 events:105 errors:0
  TX bytes:1598 acl:36 sco:0 commands:44 errors:0

[Daniel van Vugt (vanvugt)]

Please check to see if the bluetoothd process has gone away (crashed?) after the problem occurs. You might also want to look in /var/crash/

Please also run this command to help us get more information about your system:
   apport-collect 1710601

[doru001 (headset001)]

bluetoothd is still running after the problem occurs.
there is a /var/crash/_usr_lib_blueman_blueman-rfcomm-watcher.0.crash which in my opinion refers to an unrelated incident involving blueman. if you want I can upload the file.

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

apport information

[doru001 (headset001)]

This is not a crash. Nothing crashes. It just disconnects immediately after connect and bluetoothctl is frozen without sudo.

After running apport-collect bluetooth started working without sudo, but it still failed to connect. This is weird, since I did not use the GUI applet to connect.

Thank you for your help.