search

Bluetooth-Devices / bthome-ble

Parser for BTHome BLE devices
https://bthome.io/
MIT License
64 stars 11 forks source link

BTHome incidentally fails decryption #107

Closed rrooggiieerr closed 4 months ago

rrooggiieerr commented 5 months ago

Describe the bug Since HA Core beta 2024.2b1 BTHome incidentally fails decryption and I can only get rid of the reconfigure message by re-applying the bind key, even though the device was successfully decrypting on newer messages. Problem is also in 2024.2b2 and 2024.2b3

To Reproduce Install the latest HA Beta and over time you will get notices that the BTHome needs re-authentication.

Additional context

The notice on re-authentication:

Screenshot 2024-02-02 at 19 48 12

The reconfigure message:

Screenshot 2024-02-02 at 19 45 21

The device is just successfully receiving valid data

Screenshot 2024-02-02 at 19 45 33

Relevant messages from home-assistant.log

2024-02-02 16:28:37.792 WARNING (MainThread) [bthome_ble.parser] Decryption failed:    
2024-02-02 17:22:00.324 WARNING (MainThread) [bthome_ble.parser] Decryption failed:
2024-02-02 19:29:47.136 WARNING (MainThread) [bthome_ble.parser] Decryption failed:

Notice there is no additional info in the logs even though the : makes you think more info should follow.

The re-authentication notice and reconfigure message disappear after a HA restart but then appear again after some time

Ernst79 commented 5 months ago

Didn’t you had this issue with the previous version of HA 2024.1.x? I didn’t change this part of the code, so I don’t understand (yet) why you see this error in the beta, and not earlier.

The log should normally show the error after the : but apparently it is empty. Very strange.

rrooggiieerr commented 5 months ago

No, under 2024.1.x everything worked fine, except for the encryption counter is lower than or equal to the previous value which is solved in the beta of 2024.2

Ernst79 commented 5 months ago

Can you enable debug logging at debug level for the BTHome integration? This would give me the message that fails. Please also post the encryption key, you can change that afterwards.

rrooggiieerr commented 5 months ago

Enabling the debug logging overflows my log with lots of Parsing BTHome BLE advertisement data: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f7a9c3ec0> messages, but also with some valuable data:

2024-02-08 13:10:43.467 DEBUG (MainThread) [bthome_ble.parser] Parsing BTHome BLE advertisement data: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f929eeec0>
2024-02-08 13:10:43.515 WARNING (MainThread) [bthome_ble.parser] Decryption failed:
2024-02-08 13:10:43.524 DEBUG (MainThread) [bthome_ble.parser] mic: cd860400                         
2024-02-08 13:10:43.525 DEBUG (MainThread) [bthome_ble.parser] nonce: a4c1380e56acd2fc4139120600
2024-02-08 13:10:43.525 DEBUG (MainThread) [bthome_ble.parser] encrypted_payload: d0717c3fcb2cecd4
2024-02-08 14:03:02.055 DEBUG (MainThread) [bthome_ble.parser] Parsing BTHome BLE advertisement data: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f7aa34ac0>
2024-02-08 14:03:02.060 WARNING (MainThread) [bthome_ble.parser] Decryption failed:
2024-02-08 14:03:02.061 DEBUG (MainThread) [bthome_ble.parser] mic: 4ee11caa                         
2024-02-08 14:03:02.062 DEBUG (MainThread) [bthome_ble.parser] nonce: a4c1388f19e9d2fc41c600009a
2024-02-08 14:03:02.062 DEBUG (MainThread) [bthome_ble.parser] encrypted_payload: 6b7f4e1b0e      
2024-02-08 14:13:23.375 DEBUG (MainThread) [bthome_ble.parser] Parsing BTHome BLE advertisement data: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f7aa7bbc0>
2024-02-08 14:13:23.379 WARNING (MainThread) [bthome_ble.parser] Decryption failed:
2024-02-08 14:13:23.380 DEBUG (MainThread) [bthome_ble.parser] mic: c9090400                         
2024-02-08 14:13:23.380 DEBUG (MainThread) [bthome_ble.parser] nonce: a4c1380e56acd2fc41d8140600
2024-02-08 14:13:23.381 DEBUG (MainThread) [bthome_ble.parser] encrypted_payload: 0f6e6277e64b61e6
Ernst79 commented 5 months ago

Can you send me the MAC address and encryption key of the sensor? Otherwise, I can't check what is going on.

My first guess is that the message are actually wrongly encrypted. Main question will than be, why is the encryption not correct? A bug in the sensor firmware? What kind of sensor is it? a DIY project? or a shelly, or a Xiaomi temperature sensor with pvvx firmware?

slashrsm commented 5 months ago

I have a similar problem, except that it is a new device that I am trying to add. Until it is unencrypted it appears and works fine in HA. When I encrypt it HA asks me to reconfigure it with the key and it fails with

The provided bindkey did not work, sensor data could not be decrypted. Please check it and try again.

I did check the key multiple times and I am sure that it is correct. I also tried to decrypt and encrypt again, removed and re-added the device and restarting HA. Nothing helped.

I already have a bunch of other BLE encrypted devices and they all work fine. The device in question is Shelly Door/Window sensor.

I tried enabling debug logging on BT Home and I got only this:

2024-02-09 20:21:21.075 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:21:40.768 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:21:46.255 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:21:47.301 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:21:48.259 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:21:49.486 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:22:21.312 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:22:57.794 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:22:59.668 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:23:00.735 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:23:01.810 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:23:14.239 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:23:39.958 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:24:43.890 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-02-09 20:30:14.022 WARNING (MainThread) [bthome_ble.parser] Decryption failed:

I am on HA 2024.1.2

rrooggiieerr commented 5 months ago

I'm using 5 Xiaomi temperature sensors with the pvvx firmware. I'll mail you the MAC addresses and encryption keys

Ernst79 commented 5 months ago

There is (most likely) a bug in the most recent firmware versions of the Shelly door/window sensor, see https://github.com/home-assistant/core/issues/109529

I have send Shelly a message on discord, but haven’t got a response yet. Please send a message to Shelly.

Ernst79 commented 5 months ago

@rrooggiieerr I found your mail in the spambox. Unfortunately, I won’t have access to a computer this week. I’ll look into it after next week.

rrooggiieerr commented 4 months ago

@Ernst79, did you happen to find some time to look into the issue?

Ernst79 commented 4 months ago

Sorry, totally forgot it. I looked at one of the messages, but the encrypted payload seems to fail on an InvalidTag error. Could you make a debug log for BLE monitor for one of the sensors, by enabling debug logging in HA and enable the option to log unknown BLE advertisements for the MAC address of the sensor (select the sensor's mac from the devices list in the BLE monitor options, submit, enable the option te report unknown BLE advertisements. Please send me the full log, either by mail or post it here. Thanks

rrooggiieerr commented 4 months ago

Sorry, I didn't get how I should enable logging for unknown BLE advertisements. What should I add to the configuration.yaml?

Ernst79 commented 4 months ago

Ah, sorry, I'm was giving instructions for BLE monitor, but we are talking about the bthome integration.

You can add the following to configuration.yaml

logger:
  default: info
  logs:
    homeassistant.components.bluetooth: debug
    homeassistant.components.bthome: debug
rrooggiieerr commented 4 months ago

Ok, there's a lot of logging going on now. I now have to wait for a Decryption failed: message

thecode commented 4 months ago

Just a note, to see the debug for bthome-ble, you probably also need to add it:

logger:
  default: info
  logs:
    homeassistant.components.bluetooth: debug
    homeassistant.components.bthome: debug
    homeassistant.components.bthome_ble: debug
rrooggiieerr commented 4 months ago

I've got 3 decryption failed since yesterday, this is the logging that goes with it

2024-03-05 01:25:29.518 DEBUG (MainThread) [homeassistant.components.bluetooth.manager] hci0 (B8:27:EB:B0:2C:A1) [connectable]: A4:C1:38:8F:19:E9 AdvertisementData(local_name='Kitchen', service_data={'0000fcd2-0000-1000-8000-00805f9b34fb': b'A<}\xba\xf1|\xe1\x18\x00\x8f*\x0c\x00\x1e\xf5\x13\xfd'}, service_uuids=['0000fcd2-0000-1000-8000-00805f9b34fb'], rssi=-79) match: set()
2024-03-05 01:25:29.519 DEBUG (MainThread) [bthome_ble.parser] Parsing BTHome BLE advertisement data: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f58ba5140>
2024-03-05 01:25:29.575 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-03-05 01:25:29.582 DEBUG (MainThread) [bthome_ble.parser] mic: 1ef513fd
2024-03-05 01:25:29.583 DEBUG (MainThread) [bthome_ble.parser] nonce: a4c1388f19e9d2fc418f2a0c00
2024-03-05 01:25:29.583 DEBUG (MainThread) [bthome_ble.parser] encrypted_payload: 3c7dbaf17ce11800
2024-03-05 06:15:51.869 DEBUG (MainThread) [homeassistant.components.bluetooth.manager] hci0 (B8:27:EB:B0:2C:A1) [connectable]: A4:C1:38:8F:19:E9 AdvertisementData(local_name='Kitchen', service_data={'0000fcd2-0000-1000-8000-00805f9b34fb': b'A\x173\xa4\x17l}\xc1-\xae\xa7\x00\xdb\x07i\xb3\x04'}, service_uuids=['0000fcd2-0000-1000-8000-00805f9b34fb'], rssi=62) match: set()
2024-03-05 06:15:51.870 DEBUG (MainThread) [bthome_ble.parser] Parsing BTHome BLE advertisement data: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f518b2640>
2024-03-05 06:15:51.877 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-03-05 06:15:51.878 DEBUG (MainThread) [bthome_ble.parser] mic: 0769b304
2024-03-05 06:15:51.878 DEBUG (MainThread) [bthome_ble.parser] nonce: a4c1388f19e9d2fc41aea700db
2024-03-05 06:15:51.879 DEBUG (MainThread) [bthome_ble.parser] encrypted_payload: 1733a4176c7dc12d
2024-03-05 09:36:50.536 DEBUG (MainThread) [homeassistant.components.bluetooth.manager] hci0 (B8:27:EB:B0:2C:A1) [connectable]: A4:C1:38:8F:19:E9 AdvertisementData(local_name='Kitchen', service_data={'0000fcd2-0000-1000-8000-00805f9b34fb': b'A$\xf6\xc4\x8c\xa3\xfe\xedv\x14?\x0c\x00\x8d\x04\x04\x00'}, service_uuids=['0000fcd2-0000-1000-8000-00805f9b34fb'], rssi=62) match: set()
2024-03-05 09:36:50.537 DEBUG (MainThread) [bthome_ble.parser] Parsing BTHome BLE advertisement data: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7f5fd254c0>
2024-03-05 09:36:50.541 WARNING (MainThread) [bthome_ble.parser] Decryption failed: 
2024-03-05 09:36:50.542 DEBUG (MainThread) [bthome_ble.parser] mic: 8d040400
2024-03-05 09:36:50.543 DEBUG (MainThread) [bthome_ble.parser] nonce: a4c1388f19e9d2fc41143f0c00
2024-03-05 09:36:50.543 DEBUG (MainThread) [bthome_ble.parser] encrypted_payload: 24f6c48ca3feed76
Ernst79 commented 4 months ago

I tried to decrypt the first message with a manual script, but it does indeed fail to decrypt.

One option could be be to ask on the pvvx repo if pvvx knows why some of the messages seem to be encrypted not correct.

Another option could be to adjust the bthome parser to allow one failed message. If it is followed by a subsequent correct decrypted message, we don't ask for reauthentication. But when the next message also fails, we do assume the key has changed and reauthentication is needed.

rrooggiieerr commented 4 months ago

For me the asking for reauthentication is the main problem because since HA 2024.2 this triggers a notification and repair issue which can only be resolved by restarting HA or reauthenticating even if messages since the authentication failure authenticate successfully.

https://www.home-assistant.io/blog/2024/02/07/release-20242/#integrations-with-authentication-issues-are-now-shown-in-the-repairs-dashboards

Ernst79 commented 4 months ago

Yes, I understand. But it would be good to understand why some of the messages are encrypted incorrectly.

I will look into creating a workaround in the bthome parser, to avoid reauthentication.

pvvx commented 4 months ago

@Ernst79 - The BT adapter in Raspberry 3 often makes errors when transmitting via UART. Consequently, the topikaster advertisement data may be damaged. This can't be fixed. Problems with UART in BT adapters on rPi have been known for a long time.

Similar errors occur with ESPHome. ESP crashes, stack overflows and other errors are common there.

rrooggiieerr commented 4 months ago

Ok, so that probably explains it then. Would it be possible to detect when data is corrupted vs incorrectly encrypted?

Ernst79 commented 4 months ago

@Ernst79 - The BT adapter in Raspberry 3 often makes errors when transmitting via UART. Consequently, the topikaster advertisement data may be damaged. This can't be fixed. Problems with UART in BT adapters on rPi have been known for a long time.

Similar errors occur with BTHome. ESP crashes, stack overflows and other errors are common there.

Ah, ok. I'll create a fix in the parser then. Thanks for the explanation.

pvvx commented 4 months ago

Ok, so that probably explains it then. Would it be possible to detect when data is corrupted vs incorrectly encrypted?

It was recommended to use encrypted advertising to filter out bad packets.

Error messages in working with rPI BT via UART have been encountered for a long time and were frequent. Someone even caught data substitution in the BT log... What the search found

https://github.com/pvvx/ATC_MiThermometer/issues/317#issue-1626034177 https://github.com/pvvx/ATC_MiThermometer/issues/246#issuecomment-1323280418 ...

Ernst79 commented 4 months ago

The issue should be closed in the next point release of HA (2024.3.1), see https://github.com/home-assistant/core/pull/113008

This issue can be closed therefore. Thanks all for your help