Bluetooth not working anymore

koenr · 2021-06-09T19:36:05.135Z

My bluetooth connection with SMA-converter stopped working. First it got unreliable (working for minutes hours or days), now not anymore.
I read Emonhub: Bluetooth not available
I updated everything, including an apt-get dist-upgrade of the emonPI - not sure if that was a good idea.

So, what I have is this error message:

2021-06-09 20:15:19,046 ERROR    SMASolar   [Errno 110] Connection timed out
2021-06-09 20:15:19,047 ERROR    SMASolar   Bluetooth error while connecting to 00:80:25:21:55:8D
2021-06-09 20:15:19,047 ERROR    SMASolar   'BluetoothError' object is not subscriptable
2021-06-09 20:15:19,049 ERROR    SMASolar   ['Traceback (most recent call last):
  File "<string>", line 3, in connect
_bluetooth.error: (110, 'Connection timed out')

During handling of the above exception, another exception occurred:

'Traceback (most recent call last):
  File "/opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py", line 132, in _open_bluetooth
    btSocket.connect((inverteraddress, port))
  File "<string>", line 5, in connect
bluetooth.btcommon.BluetoothError: [Errno 110] Connection timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py", line 223, in read
    self._login_inverter()
  File "/opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py", line 64, in _login_inverter
    self._btSocket = self._open_bluetooth(self._inverteraddress, self._port)
  File "/opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py", line 140, in _open_bluetooth
    errCode = eval(err[0])[0]
TypeError: 'BluetoothError' object is not subscriptable]

If I look on the pi at the connection, i see

pi@emonpi:~ $ hcitool con
Connections:
	< ACL 00:80:25:21:55:8D handle 0 state 5 lm MASTER 

pi@emonpi:~ $ hciconfig dev
hci0:	Type: Primary  Bus: USB
	BD Address: 00:16:38:3A:3A:8D  ACL MTU: 1017:8  SCO MTU: 64:0
	UP RUNNING 
	RX bytes:201087 acl:4136 sco:0 events:5670 errors:0
	TX bytes:87773 acl:3986 sco:0 commands:2060 errors:0

I doesn’t want to give me any information:

pi@emonpi:~ $ hcitool info 00:16:38:3A:3A:8D
Requesting information ...
Can't create connection: Operation not permitted
pi@emonpi:~ $

So to me it looks like there is some form of connection.
I don’t know enough python to see what is causing the error.

Server info:

Server Information

Services

emonhub :- Active Running
emoncms_mqtt :- Active Running
feedwriter :- Active Running - sleep 300s 272 feed points pending write
service-runner :- Active Running
emonPiLCD :- Active Running
redis-server :- Active Running
mosquitto :- Active Running
demandshaper :- Active Running

Emoncms

Version :- low-write 10.4
Modules :- Administration | App v2.2.7 | Backup v2.2.7 | EmonHub Config v2.0.6 | Dashboard v2.0.10 | DemandShaper v2.1.3 | Device v2.0.10 | EventProcesses | Feed | Graph v2.0.11 | Input | Postprocess v2.1.5 | CoreProcess | Schedule | Network Setup v1.0.2 | sync | Time | User | Visualisation | WiFi v2.0.4
Git :-
- URL :- GitHub - emoncms/emoncms: Web-app for processing, logging and visualising energy, temperature and other environmental data
- Branch :- * stable
- Describe :- 10.4

Server

OS :- Linux 5.10.17-v7+
Host :- emonpi | emonpi | (192.168.2.163)
Date :- 2021-06-09 20:36:31 BST
Uptime :- 20:36:31 up 3:20, 1 user, load average: 0.62, 0.50, 0.55

Memory

RAM :- Used: 19.79%
- Total :- 924.21 MB
- Used :- 182.89 MB
- Free :- 741.32 MB
Swap :- Used: 0.00%
- Total :- 100 MB
- Used :- 0 B
- Free :- 100 MB
  Write Load Period

Disk

/ :- Used: 50.08%
- Total :- 4.06 GB
- Used :- 2.03 GB
- Free :- 1.83 GB
- Write Load :- 26.11 KB/s (3 hours 12 mins)
/var/opt/emoncms :- Used: 0.39%
- Total :- 9.84 GB
- Used :- 38.83 MB
- Free :- 9.3 GB
- Write Load :- 57.88 B/s (3 hours 12 mins)
/boot :- Used: 18.90%
- Total :- 252.05 MB
- Used :- 47.64 MB
- Free :- 204.4 MB
- Write Load :- 1.86 B/s (3 hours 12 mins)
/var/log :- Used: 15.11%
- Total :- 50 MB
- Used :- 7.55 MB
- Free :- 42.45 MB
- Write Load :- n/a

HTTP

Server :- Apache/2.4.38 (Raspbian) HTTP/1.1 CGI/1.1 80

MySQL

Version :- 5.5.5-10.3.27-MariaDB-0+deb10u1
Host :- 127.0.0.1 (127.0.0.1)
Date :- 2021-06-09 20:36:31 (UTC 01:00‌)
Stats :- Uptime: 12021 Threads: 13 Questions: 69228 Slow queries: 0 Opens: 46 Flush tables: 1 Open tables: 40 Queries per second avg: 5.758

Redis

Version :-
- Redis Server :- 5.0.3
- PHP Redis :- 5.3.1
Host :- localhost:6379
Size :- 310 keys (838.02K)
Uptime :- 0 days

MQTT Server

Version :- Mosquitto 1.5.7
Host :- localhost:1883 (127.0.0.1)

PHP

Version :- 7.3.27-1~deb10u1 (Zend Version 3.3.27)
Modules :- apache2handlercalendar Core ctype curl date dom v20031129exif fileinfo filter ftp gd gettext hash iconv json v1.7.0libxml mbstring mosquitto v0.4.0mysqli mysqlnd vmysqlnd 5.0.12-dev - 20150407 - $Id: 7cc7cc96e675f6d72e5cf0f267f48e167c2abb23 $openssl pcre PDO pdo_mysql Phar posix readline redis v5.3.1Reflection session shmop SimpleXML sockets sodium SPL standard sysvmsg sysvsem sysvshm tokenizer wddx xml xmlreader xmlwriter xsl Zend OPcache zlib

Pi

Model :- Raspberry Pi 3 Model B Rev 1.2 - 1GB (Sony UK)
Serial num. :- 698A595
CPU Temperature :- 55.84°C
GPU Temperature :- 56.4°C
emonpiRelease :- emonSD-24Jul20
File-system :- read-write

Client Information

HTTP

Browser :- Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.77 Safari/537.36
Language :- nl-NL,nl;q=0.9,en-US;q=0.8,en;q=0.7

Window

Size :- 1905 x 912

Screen

Resolution :- 1920 x 1080

Anyone else experiencing this problem? Idea how to start debugging?

Robert.Wall · 2021-06-09T19:48:20.979Z

Welcome, Koen, to the OEM forum.

I’m afraid I can’t help with the Bluetooth problem, but I’ve formatted your post so that it’s hopefully a bit more readable.

I wouldn’t expect you to know this, but for future reference, when posting code or output, please put 3 ‘backticks’ (normally found at the top left of the keyboard) on a line of their own before the code, and 3 more backticks also on a line of their own after the code:

```
code
```

If it is something like php you can add a language identifier after the first 3 backticks: ```php or even ```text if you don’t want any language markup applied.

koenr · 2021-06-12T10:03:48.749Z

Some extra information gathered with hcidump:

hcidump -i hci0 hci
HCI sniffer - Bluetooth packet analyzer ver 5.50
device: hci0 snap_len: 1500 filter: 0x2
> HCI Event: Command Status (0x0f) plen 4
    Disconnect (0x01|0x0006) status 0x00 ncmd 1
> HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 11 reason 0x16
    Reason: Connection Terminated by Local Host
> HCI Event: Command Status (0x0f) plen 4
    Create Connection (0x01|0x0005) status 0x00 ncmd 1
> HCI Event: Connect Complete (0x03) plen 11
    status 0x00 handle 11 bdaddr 00:80:25:21:55:8D type ACL encrypt 0x00
> HCI Event: Command Status (0x0f) plen 4
    Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1
> HCI Event: Read Remote Supported Features (0x0b) plen 11
    status 0x00 handle 11
    Features: 0xff 0xff 0x8f 0xfe 0x9b 0xf9 0x00 0x80
> HCI Event: Command Status (0x0f) plen 4
    Read Remote Extended Features (0x01|0x001c) status 0x00 ncmd 1
> HCI Event: Read Remote Extended Features (0x23) plen 13
    status 0x00 handle 11 page 1 max 0
    Features: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
> HCI Event: Command Status (0x0f) plen 4
    Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
> HCI Event: Remote Name Req Complete (0x07) plen 255
    status 0x00 bdaddr 00:80:25:21:55:8D name 'SMA001d SN: 2110244663 SN2110244663'
> HCI Event: Command Status (0x0f) plen 4
    Disconnect (0x01|0x0006) status 0x00 ncmd 1
> HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 11 reason 0x16
    Reason: Connection Terminated by Local Host

After this, the loop starts over again with

> HCI Event: Command Status (0x0f) plen 4
    Create Connection (0x01|0x0005) status 0x00 ncmd 1

For some reason, localhost decides to terminate the connection.

koenr · 2021-06-16T18:03:07.270Z

I tried 2 things in the last few days:
First, I found that the 2A power supply doesn’t give enough power since lots of

Under-voltage detected! (0x00050005)

in dmesg. I replaced it with a 3A version and that doesn’t happen anymore.

Second, I replaced the bluetooth adapter with a new one. It didn’t help at first. I got 104 messages with

[Wed Jun 16 11:12:07 2021] Bluetooth: hci0: link tx timeout
[Wed Jun 16 11:12:07 2021] Bluetooth: hci0: killing stalled connection 00:80:25:21:55:8d

but after 27 hours uptime, suddenly I got readings form my inverter again after being broken for 16 days. The log message I posted is the last error I have seen.
I have no idea what has suddenly changed at 11:12 UTC (actually 12:12 my time), just as I don’t have any idea why it stopped working.
I’m going to use a USB extension lead to bring the USB-dongle a bit further away from wiring and hopefully make the connection more reliable. I can only think of a signal strength or signal/noise ratio issue.
So I’m marking this as solved.