unexpected SMP command

[corgan2222]

I'm using keyble mqtt for some time now and get every few minutes/hours some Bluetooth kernel errors.

raspizero2 kernel: [ 1277.916823] Bluetooth: hci0: unexpected SMP command 0x02 from 00:1a:xxxx

In this time, the look is offline in Home Assistant. In 5 from 10 attempts this happens if we need it.
I'm running it on a raspi zero. There are no other running processes, the zero is only for keyble.
Is there anything I can do about this?

[oyooyo]

I'm afraid I've never heard of this kind of error message before and currently have no clue what you could do about it.
In fact, I've never even heard of something Bluetooth-related called "SMP" until reading your posting. According to Wikipedia, it means "Low Energy Security Manager Protocol" and "is used by Bluetooth Low Energy implementations for pairing and transport specific key distribution". I guess it's something that is usually automatically handled by the lower BLE layers and one usually doesn't have to deal with it...

I found some other GitHub issue mentioning the "unexpected SMP command" error on the Raspberry Pi. Interestingly, the person reporting it also mentions something about the error being triggered by a Node.js program. He doesn't mention what kind of Node.js program it is (and it can't be keyble, because he posted it years before keyble was published), but that Node.js program was almost certainly using the "noble" library as well. So I currently assume the bug to be somewhere in the noble library.
I've also found this GitHub issue from the noble library which sound extremely similar, but no solution.

What exactly is device 00:1a:xxxx? Is it the Bluetooth adapter or the smart door lock, do you know?
Looking at the logs, I realized that this error seems to appear exactly every 10 minutes. Is there a keyble parameter that is set to exactly 10 minutes in your setup?
And which version of keyble are you using?

[markusweibofner]

Is there any update on this? I experience the same error, with the mac address being the smart lock itself. Unfortunately, i can do some locking and unlocking (usually for less than a minute or two) but then keyble seems to not reach the lock anymore. This happens regardless of having -adt 0 or not.
Is there a way to manually (re-)connect to the lock, so the mqtt-service can run as expected?

[corgan2222]

sorry for the late reply. No sadly the problem still exists. But i gave up to wonder about the strange BT stuff on the pi.
I have Problems with it every time.
If the error appears, the look is offline, but comes back after some time.

@oyooyo yes, the mac is from keyble. I dont have any timeout configured.

hci0 dev_found: 00:1A:22:13:6F:D2 type LE Public rssi -67 flags 0x0000
AD flags 0x05
name KEY-BLE

[corgan2222]

i found a new error message in the logs.

did this helps in any way?

`

[corgan2222]

Today keyble stopped working completely and i found some memory leak log entries.
I had to restart the BT and keyble service.

I orderd a usb bt dongle today, maybe this can fix these problems.

8:55:01 rngd[274]: stats: FIPS 140-2 successes: 698 │
18:55:01 rngd[274]: stats: FIPS 140-2 failures: 0 │
18:55:01 rngd[274]: stats: FIPS 140-2(2001-10-10) Monobit: 0 │
18:55:01 rngd[274]: stats: FIPS 140-2(2001-10-10) Poker: 0 │
18:55:01 rngd[274]: stats: FIPS 140-2(2001-10-10) Runs: 0 │
18:55:01 rngd[274]: stats: FIPS 140-2(2001-10-10) Long run: 0 │
18:55:01 rngd[274]: stats: FIPS 140-2(2001-10-10) Continuous run: 0 │
18:55:01 rngd[274]: stats: HRNG source speed: (min=58.194; avg=783.156; max=1005.056)Kibits/s │
18:55:01 rngd[274]: stats: FIPS tests speed: (min=371.302; avg=6784.684; max=9139.565)Kibits/s │
18:55:01 rngd[274]: stats: Lowest ready-buffers level: 2 │
18:55:01 rngd[274]: stats: Entropy starvations: 0 │
18:55:01 rngd[274]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us │
18:55:13 kernel: [1670453.435655] Bluetooth: hci0: unexpected SMP command 0x02 from 00:1a:22:13:6f:d2 │
18:55:13 kernel: [1670453.510736] Bluetooth: hci0: unexpected SMP command 0x03 from 00:1a:22:13:6f:d2 │
18:55:13 kernel: [1670453.555744] Bluetooth: hci0: unexpected SMP command 0x04 from 00:1a:22:13:6f:d2 │
18:55:13 kernel: [1670453.690717] Bluetooth: hci0: unexpected SMP command 0x06 from 00:1a:22:13:6f:d2 │
18:55:13 kernel: [1670453.691845] Bluetooth: hci0: unexpected SMP command 0x07 from 00:1a:22:13:6f:d2 │
19:05:17 kernel: [1671057.231033] Bluetooth: hci0: unexpected SMP command 0x02 from 00:1a:22:13:6f:d2 │
19:05:17 kernel: [1671057.306087] Bluetooth: hci0: unexpected SMP command 0x03 from 00:1a:22:13:6f:d2 │
19:05:17 kernel: [1671057.336058] Bluetooth: hci0: unexpected SMP command 0x04 from 00:1a:22:13:6f:d2 │
19:05:17 kernel: [1671057.470995] Bluetooth: hci0: unexpected SMP command 0x06 from 00:1a:22:13:6f:d2 │
19:05:17 kernel: [1671057.472131] Bluetooth: hci0: unexpected SMP command 0x07 from 00:1a:22:13:6f:d2 │
19:15:20 kernel: [1671660.211186] Bluetooth: hci0: unexpected SMP command 0x02 from 00:1a:22:13:6f:d2 │
19:15:20 kernel: [1671660.286310] Bluetooth: hci0: unexpected SMP command 0x03 from 00:1a:22:13:6f:d2 │
19:15:20 kernel: [1671660.316958] Bluetooth: hci0: unexpected SMP command 0x04 from 00:1a:22:13:6f:d2 │
19:15:20 kernel: [1671660.436252] Bluetooth: hci0: unexpected SMP command 0x06 from 00:1a:22:13:6f:d2 │
19:15:20 kernel: [1671660.437404] Bluetooth: hci0: unexpected SMP command 0x07 from 00:1a:22:13:6f:d2 │
19:17:01 CRON[16788]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly) │
19:23:26 keyble-mqtt.sh[4227]: /opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/keyble/keyble.js:544 │
19:23:26 keyble-mqtt.sh[4227]: #11#011#011receive_characteristic.off('data', on_data_received); │
19:23:26 keyble-mqtt.sh[4227]: #11#011#011^ │
19:23:26 keyble-mqtt.sh[4227]: ReferenceError: Cannot access 'receive_characteristic' before initialization │
19:23:26 keyble-mqtt.sh[4227]: at Peripheral. (/opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/keyble/keyble.js:544:4) │
19:23:26 keyble-mqtt.sh[4227]: at Object.onceWrapper (events.js:421:28) │
19:23:26 keyble-mqtt.sh[4227]: at Peripheral.emit (events.js:327:22) │
19:23:26 keyble-mqtt.sh[4227]: at Noble.onDisconnect (/opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/@abandonware/noble/lib/noble.js:241:16) │
19:23:26 keyble-mqtt.sh[4227]: at NobleBindings.emit (events.js:315:20) │
19:23:26 keyble-mqtt.sh[4227]: at NobleBindings.onDisconnComplete (/opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/@abandonware/noble/lib/hci-socket/bindings.js:274:10) │
19:23:26 keyble-mqtt.sh[4227]: at Hci.emit (events.js:315:20) │
19:23:26 keyble-mqtt.sh[4227]: at Hci.onSocketData (/opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/@abandonware/noble/lib/hci-socket/hci.js:557:12) │
19:23:26 keyble-mqtt.sh[4227]: at BluetoothHciSocket.emit (events.js:315:20) │
19:23:26 systemd[1]: keyble-mqtt.service: Main process exited, code=exited, status=1/FAILURE │
19:23:26 systemd[1]: keyble-mqtt.service: Failed with result 'exit-code'. │
19:23:28 bluetoothd[379]: No agent available for request type 2 │
19:23:28 bluetoothd[379]: device_confirm_passkey: Operation not permitted │
19:23:36 systemd[1]: keyble-mqtt.service: Service RestartSec=10s expired, scheduling restart. │
19:23:36 systemd[1]: keyble-mqtt.service: Scheduled restart job, restart counter is at 364. │
19:23:36 systemd[1]: Stopped keyble-mqtt service. │
19:23:36 systemd[1]: Started keyble-mqtt service. │
19:24:48 systemd[1]: Started Session 497 of user pi. │
19:24:50 systemd[1]: Started Session 498 of user pi. │
19:27:27 keyble-mqtt.sh[18398]: noble warning: unknown handle 65 disconnected! │
19:27:28 keyble-mqtt.sh[18398]: (node:18399) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 connect listeners added to [Peripheral]. Use emitter.setMaxListeners() to increase limit │
19:27:28 keyble-mqtt.sh[18398]: (Use node --trace-warnings ... to show where the warning was created) │
19:27:30 keyble-mqtt.sh[18398]: /opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/keyble/keyble.js:544 │
19:27:30 keyble-mqtt.sh[18398]: #11#011#011receive_characteristic.off('data', on_data_received); │
19:27:30 keyble-mqtt.sh[18398]: #11#011#011^ │
19:27:30 keyble-mqtt.sh[18398]: ReferenceError: Cannot access 'receive_characteristic' before initialization │
19:27:30 keyble-mqtt.sh[18398]: at Peripheral. (/opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/keyble/keyble.js:544:4) │
19:27:30 keyble-mqtt.sh[18398]: at Object.onceWrapper (events.js:421:28) │
19:27:30 keyble-mqtt.sh[18398]: at Peripheral.emit (events.js:327:22) │
19:27:30 keyble-mqtt.sh[18398]: at Noble.onDisconnect (/opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/@abandonware/noble/lib/noble.js:241:16) │
19:27:30 keyble-mqtt.sh[18398]: at NobleBindings.emit (events.js:315:20) │
19:27:30 keyble-mqtt.sh[18398]: at NobleBindings.onDisconnComplete (/opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/@abandonware/noble/lib/hci-socket/bindings.js:274:10) │
19:27:30 keyble-mqtt.sh[18398]: at Hci.emit (events.js:315:20) │
19:27:30 keyble-mqtt.sh[18398]: at Hci.onSocketData (/opt/nodejs/lib/node_modules/keyble-mqtt/node_modules/@abandonware/noble/lib/hci-socket/hci.js:557:12) │
19:27:30 keyble-mqtt.sh[18398]: at BluetoothHciSocket.emit (events.js:315:20) │
19:27:30 systemd[1]: keyble-mqtt.service: Main process exited, code=exited, status=1/FAILURE │
19:27:30 systemd[1]: keyble-mqtt.service: Failed with result 'exit-code'. │
19:27:30 bluetoothd[379]: No agent available for request type 2 │
19:27:30 bluetoothd[379]: device_confirm_passkey: Operation not permitted │
19:27:40 systemd[1]: keyble-mqtt.service: Service RestartSec=10s expired, scheduling restart. │
19:27:40 systemd[1]: keyble-mqtt.service: Scheduled restart job, restart counter is at 365. │
19:27:40 systemd[1]: Stopped keyble-mqtt service. │
19:27:40 systemd[1]: Started keyble-mqtt service.

[oyooyo]

i found a new error message in the logs.

did this helps in any way?

The error message about receive_characteristic was indeed indication of a small bug in the keyble code. Thanks for reporting it!
This bug should be fixed in version 0.3.2 that I published a few days ago. I don't know if this has anything to do with this strange "unexpected SMP command" error, I kind of doubt it, but who knows, might be worth trying.

[corgan2222]

Did you implement this fix also in keyble-mqtt?
I did a "npm install --update --global --unsafe-perm keyble-mqtt" and now i only getting errors?

[corgan2222]

Hmm never mind, after an nmp update it runs again.
For the moment i got the nmp "unexpected SMP command" errors on the first mqtt command, but for now, i can open/close without any errors. So the "receive_characteristic" bug seems to be fixed.

I keep monitoring the status in HA so i can give you later feedback if this is stable, or starts to struggle after some time after timeout.

[corgan2222]

after one day, i can report, that the SMP problem seems to be fixed, but its still not working. On every mqtt message i get this errors:

@oyooyo my BT usb dongle arrived today. But i could not find how to configure keyble to use the usb dongle. Is this even possible?

[oyooyo]

after one day, i can report, that the SMP problem seems to be fixed, but its still not working. On every mqtt message i get this errors:

Thanks for reporting. I need to try to reproduce this bug.

@oyooyo my BT usb dongle arrived today. But i could not find how to configure keyble to use the usb dongle. Is this even possible?

I haven't tried it myself, but it should be possible, see here.

[corgan2222]

Thanks! Please let me know, if I can help to debug this bug.

[nilsbraden]

Did you ever resolve this issue? My RP4 does this as well.