Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

MQTT topic content for nuki/lock/log is cut-off #270

Closed
micronax opened this issue Jan 14, 2024 · 21 comments · Fixed by #368
Closed

MQTT topic content for nuki/lock/log is cut-off #270

micronax opened this issue Jan 14, 2024 · 21 comments · Fixed by #368
Assignees
Labels
bug Something isn't working
Milestone

Comments

@micronax
Copy link

micronax commented Jan 14, 2024

Hi,
thanks for building this super nice piece of code. The integration works like a charm.

I just encountered a problem with the log supplied within the MQTT topic nuki/lock/log:

Screenshot 2024-01-14 at 22 51 46

The JSON is somewhere just cut-off with some strange byte characters which makes it impossible to parse.

Also, the Keypad Status and Last action authorization are unknown in HA.

Is this kind of an overlow?

@technyon
Copy link
Owner

It's not exactly an overflow. There's a buffer allocated of 4096 bytes. The JSON serializer checks against this maximum size, and in your case has hit the limit. There's a flag in the serializer to check for that, in that case the last log entry should be removed ... or the easy fix maybe is to increase the buffer size. I'd need to to some math what the maximum size could be, considering you're using the maximum length for the keypad entry names.

@micronax
Copy link
Author

Thank you 🙏

considering you're using the maximum length for the keypad entry names

Is there anything I can change on my side to make it work out-of-the-box?

I only have one keypad permission right now and it's just called "Zutrittscode".

@technyon
Copy link
Owner

You'll find other things than keypad entries in the log. Any time you a lock action is executed, it appears in the log. Did you assign any long names (Android/IOS App, Fobs)? Also could you copy/paste the payload into a text editor and see if it really is longer than 4095 characterrs (4096 minus one for the termination character).

@micronax
Copy link
Author

Nope, my setup is pretty new. Just this one access code, no fobs, no other users etc.

@technyon
Copy link
Owner

OK

Counting the characters would help nevertheless :)

@micronax
Copy link
Author

I did a factory reset of the Nuki lock which led to the log field not being cut-off anymore.

But another thing I just noticed is that the indices are assigned multiple times, don't know whether that's by design or not:

[{"index":3,"authorizationId":190533920,"authorizationName":"","timeYear":2024,"timeMonth":1,"timeDay":16,"timeHour":22,"timeMinute":24,"timeSecond":48,"type":"InitializationRun"},{"index":4,"authorizationId":168375,"authorizationName":"<redacted>","timeYear":2024,"timeMonth":1,"timeDay":16,"timeHour":22,"timeMinute":35,"timeSecond":14,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":5,"authorizationId":168375,"authorizationName":"Nuki Keypad","timeYear":2024,"timeMonth":1,"timeDay":16,"timeHour":23,"timeMinute":34,"timeSecond":15,"type":"KeypadAction","action":"Unlatch","completionStatus":"invalidCode"},{"index":6,"authorizationId":168375,"authorizationName":"<redacted>","timeYear":2024,"timeMonth":1,"timeDay":17,"timeHour":11,"timeMinute":9,"timeSecond":54,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":7,"authorizationId":168375,"authorizationName":"<redacted>","timeYear":2024,"timeMonth":1,"timeDay":17,"timeHour":11,"timeMinute":10,"timeSecond":2,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":7,"authorizationId":168375,"authorizationName":"<redacted>","timeYear":2024,"timeMonth":1,"timeDay":17,"timeHour":11,"timeMinute":10,"timeSecond":2,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":6,"authorizationId":168375,"authorizationName":"<redacted>","timeYear":2024,"timeMonth":1,"timeDay":17,"timeHour":11,"timeMinute":9,"timeSecond":54,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":5,"authorizationId":168375,"authorizationName":"Nuki Keypad","timeYear":2024,"timeMonth":1,"timeDay":16,"timeHour":23,"timeMinute":34,"timeSecond":15,"type":"KeypadAction","action":"Unlatch","completionStatus":"invalidCode"},{"index":4,"authorizationId":168375,"authorizationName":"<redacted>","timeYear":2024,"timeMonth":1,"timeDay":16,"timeHour":22,"timeMinute":35,"timeSecond":14,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":3,"authorizationId":190533920,"authorizationName":"","timeYear":2024,"timeMonth":1,"timeDay":16,"timeHour":22,"timeMinute":24,"timeSecond":48,"type":"InitializationRun"}]

The unredacted version of the payload is in total 2198 characters long.

@technyon
Copy link
Owner

I'd say something strange is going on there. You don't just have duplicated indices, but duplicated log entries. Also, there should be no more than five log entries. NUKI Hub requests the last five log entries from the log, how those duplicates appear in your log I can only guess. It would also explain why you had the cut off json before.

Which MQTT broker are you using?

@micronax
Copy link
Author

I use the Mosquitto addon for Home Assistant. I also encountered that some lock-related topics are not updating for hours while eg. presence is updated every few seconds, also after changing eg. the lock state interval to 300 seconds etc.

Do you need some config insights?

@technyon
Copy link
Owner

technyon commented Jan 18, 2024

Let's check first what's going on on ESP side. Can you get serial logs? This firmware prints the log entry count when publishing, it should be no more than 5. Speed for serial logs is 115200.

nuki_hub-8.29-dbg-1.zip

@micronax
Copy link
Author

Somehow I wasn't able to flash that binary to my esp32 yet. I will try again tonight.

More insights:

  • I had to exchange my Nuki lock with a new one after I had issues with the lock mechanism. So now I have another and brand-new Nuki 4 (non-pro) and the same problem persists with the cut-off logs
  • I re-installed the esp32-nukihub like 3 times with the default binary from the installer, same problem persists

Maybe its a general problem with the Nuki 4 locks?

@technyon
Copy link
Owner

Very strange. Getting those serial logs would be helpful. If it's a Nuki 4 issue, it's a bug in the Nuki 4 firmware.

@micronax
Copy link
Author

Here comes the serial logs:

ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:1344
load:0x40078000,len:13516
load:0x40080400,len:3604
entry 0x400805f0
E (528) esp_core_dump_flaKr��core dump partition found!
E (528) esp_core_dump_flash: No core dump partition found!
NUKI Hub version 8.29-dbg-1
IP address empty, falling back to DHCP.
IP configuration: DHCP
Hardware detect     : 1
Network device: Wifi only
MQTT without TLS.
*wm:AutoConnect
*wm:Connecting to SAVED AP: <redacted>
*wm:connectTimeout not set, ESP waitForConnectResult...
*wm:AutoConnect: SUCCESS
*wm:STA IP Address: <redacted>
WiFi connected: <redacted>
Host name: nukihub
MQTT Broker: <redacted>
NUKI Lock enabled
Device id lock: <redacted>
Lock state interval: 300 | Battery interval: 1800 | Publish auth data: yes
NUKI Opener disabled
Presence detection timeout (ms): 60000
Attempting MQTT connection
MQTT: Connecting with user: <redacted>
MQTT connected
Nuki lock start pairing
Nuki paired
Querying lock state: unlocked
Log entry count: 22
Querying lock battery state: success
Reading config. Result: success
Reading advanced config. Result: success
HASS setup for lock completed.
HASS setup for lock completed.

@mallorca2288
Copy link

mallorca2288 commented Jan 25, 2024

I'm having the same issue with my Nuki4 Pro lock.

NUKI Hub info:

NUKI Hub version: 8.29
run: true
deviceId: <REDACTED>
deviceIdOp: <REDACTED>
mqttbroker: 192.168.8.10
mqttport: 1883
mqttuser: ***
mqttpass: ***
mqttlog: false
lockena: true
mqttpath: nuki
openerena: false
mqttoppath: 
maxkpad: 6
opmaxkpad: 
mqttca: 
mqttcrt: 
mqttkey: 
hassdiscovery: homeassistant
dhcpena: false
ipaddr: 192.168.8.56
ipsub: 255.255.255.0
ipgtw: 192.168.8.1
dnssrv: 1.0.0.1
nwhw: 1
rssipb: 60
hostname: nukihub
nettmout: -1
restdisc: false
rstbcn: -1
lockStInterval: 1800
configInterval: 3600
batInterval: 1800
kpInterval: 1800
kpEnabled: true
accLvl: 0
regAsApp: false
nrRetry: 3
rtryDelay: 100
crdusr: ***
crdpass: ***
pubauth: true
pubdbg: false
prdtimeout: 60
hasmac: false
macb0: 
macb1: 
macb2: 
MQTT connected: Yes
Lock firmware version: 4.0.37
Lock hardware version: 7.0
Lock paired: Yes
Lock PIN set: Yes
Lock has door sensor: Yes
Lock has keypad: Yes
Network device: Built-in Wifi
Uptime: 913 minutes
Heap: 65824
Stack watermarks: nw: 6104, nuki: 600, pd: 232
Restart reason FW: NotApplicable
Restart reason ESP: ESP_RST_INT_WDT: Reset (software or hardware) due to interrupt watchdog

MQTT value of /nuki/lock/log (4.106 characters long):

[{"index":565,"authorizationId":209924,"authorizationName":"NukiHub","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":0,"timeMinute":40,"timeSecond":55,"type":"LockAction","action":"Lock","trigger":"system","completionStatus":"success"},{"index":566,"authorizationId":18551808,"authorizationName":"","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":10,"timeMinute":47,"timeSecond":58,"type":"LockAction","action":"LockNgo","trigger":"button","completionStatus":"success"},{"index":567,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":10,"timeMinute":47,"timeSecond":59,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":568,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":10,"timeMinute":48,"timeSecond":6,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":569,"authorizationId":133518,"authorizationName":"Nuki Keypad","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":41,"timeSecond":9,"type":"KeypadAction","action":"Unknown","completionStatus":"undefined"},{"index":570,"authorizationId":133518,"authorizationName":"Nuki Keypad","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":41,"timeSecond":15,"type":"KeypadAction","action":"Unknown","completionStatus":"undefined"},{"index":571,"authorizationId":133518,"authorizationName":"Joaco","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":41,"timeSecond":39,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":572,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":41,"timeSecond":39,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":573,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":42,"timeSecond":2,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":574,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":31,"timeSecond":3,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":575,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":31,"timeSecond":5,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":576,"authorizationId":133518,"authorizationName":"Joaco","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":42,"timeSecond":30,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":577,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":42,"timeSecond":30,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":578,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":42,"timeSecond":30,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":579,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":57,"timeSecond":52,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":580,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":58,"timeSecond":1,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":581,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":17,"timeMinute":37,"timeSecond":17,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":582,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":17,"timeMinutxV�� �

Error seen in home-assistant logs:

2024-01-25 18:52:44.635 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'[{"index":565,"authorizationId":209924,"authorizationName":"NukiHub","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":0,"timeMinute":40,"timeSecond":55,"type":"LockAction","action":"Lock","trigger":"system","completionStatus":"success"},{"index":566,"authorizationId":18551808,"authorizationName":"","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":10,"timeMinute":47,"timeSecond":58,"type":"LockAction","action":"LockNgo","trigger":"button","completionStatus":"success"},{"index":567,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":10,"timeMinute":47,"timeSecond":59,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":568,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":10,"timeMinute":48,"timeSecond":6,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":569,"authorizationId":133518,"authorizationName":"Nuki Keypad","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":41,"timeSecond":9,"type":"KeypadAction","action":"Unknown","completionStatus":"undefined"},{"index":570,"authorizationId":133518,"authorizationName":"Nuki Keypad","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":41,"timeSecond":15,"type":"KeypadAction","action":"Unknown","completionStatus":"undefined"},{"index":571,"authorizationId":133518,"authorizationName":"Joaco","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":41,"timeSecond":39,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":572,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":41,"timeSecond":39,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":573,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":14,"timeMinute":42,"timeSecond":2,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":574,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":31,"timeSecond":3,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":575,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":31,"timeSecond":5,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":576,"authorizationId":133518,"authorizationName":"Joaco","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":42,"timeSecond":30,"type":"KeypadAction","action":"Unlatch","completionStatus":"success"},{"index":577,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":42,"timeSecond":30,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":578,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":42,"timeSecond":30,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":579,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":57,"timeSecond":52,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":580,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":15,"timeMinute":58,"timeSecond":1,"type":"DoorSensor","action":"DoorClosed","completionStatus":"undefined"},{"index":581,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":17,"timeMinute":37,"timeSecond":17,"type":"DoorSensor","action":"DoorOpened","completionStatus":"undefined"},{"index":582,"authorizationId":86077,"authorizationName":"2131887821","timeYear":2024,"timeMonth":1,"timeDay":13,"timeHour":17,"timeMinutxV\xad\xba \x18' on nuki/lock/log with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function MqttSensor._prepare_subscribe_topics.<locals>.message_received at 0x7ff9cc20f9c0>, <function async_subscribe.<locals>.<lambda> at 0x7ff9cc20f880>)>)

Entities on home assistant are unknown:
imagen

I'm not sure if it's related to this problem (Sorry if it's not, maybe I can create a new issue for this), but I'm also seeing multiple lock autodiscovery topics with weird names created in /homeassistant/lock
imagen

And this are some examples of multiple warnings that I can see in my home-assistant logs:

2024-01-25 18:52:40.193 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON battery_level: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"battery level","unique_id":"38354535_battery_level","dev_cla":"battery","stat_t":"~/battery/level","stat_cla":"measurement","ent_cat":"diagnostic","unit_of_meas":"%"}'
2024-01-25 18:52:40.193 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON wifi_signal_strength: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"wifi signal strength","unique_id":"38354535_wifi_signal_strength","dev_cla":"signal_strength","stat_t":"~/maintenance/wifiRssi","stat_cla":"measurement","ent_cat":"diagnostic","unit_of_meas":"dBm"}'
2024-01-25 18:52:40.194 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON bluetooth_signal_strength: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"bluetooth signal strength","unique_id":"38354535_bluetooth_signal_strength","dev_cla":"signal_strength","stat_t":"~/lock/rssi","stat_cla":"measurement","ent_cat":"diagnostic","unit_of_meas":"dBm"}'
2024-01-25 18:52:40.194 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON last_action_authorization: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"Last action authorization","unique_id":"38354535_last_action_authorization","stat_t":"~/lock/log","ent_cat":"diagnostic","ic":"mdi:format-list-bulleted","value_template":"{{ (value_json|selectattr('type', 'eq', 'LockAction')|selectattr('action', 'in', ['Lock', 'Unlock', 'Unlatch'])|first|default).authorizationName|default }}"}'
2024-01-25 18:52:40.195 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON keypad_status: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"Keypad status","unique_id":"38354535_keypad_stats","stat_t":"~/lock/log","ent_cat":"diagnostic","ic":"mdi:drag-vertical","value_template":"{{ (value_json|selectattr('type', 'eq', 'KeypadAction')|first|default).completionStatus|default }}"}'
2024-01-25 18:52:40.202 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":"LED brightness","unique_id":"a5a5a5a5_led_brightness","stat_t":"~/configuration/ledBrightness","ent_cat":"config","cmd_t":"~/configuration/ledBrightness","ic":"mdi:brightness-6","min":"0","max":"5"}' on homeassistant/number/a5a5a5a5/led_brightness/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.203 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON led_brightness: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"LED brightness","unique_id":"38354535_led_brightness","stat_t":"~/configuration/ledBrightness","ent_cat":"config","cmd_t":"~/configuration/ledBrightness","ic":"mdi:brightness-6","min":"0","max":"5"}'
2024-01-25 18:52:40.207 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":"battery low","unique_id":"a5a5a5a5_battery_low","dev_cla":"battery","stat_t":"~/battery/critical","ent_cat":"diagnostic","pl_on":"1","pl_off":"0"}' on homeassistant/binary_sensor/a5a5a5a5/battery_low/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.207 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":"keypad battery low","unique_id":"a5a5a5a5_keypad_battery_low","dev_cla":"battery","stat_t":"~/battery/keypadCritical","ent_cat":"diagnostic","pl_on":"1","pl_off":"0"}' on homeassistant/binary_sensor/a5a5a5a5/keypad_battery_low/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.208 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":"MQTT connected","unique_id":"a5a5a5a5_mqtt_connected","stat_t":"~/maintenance/mqttConnectionState","ent_cat":"diagnostic","pl_on":"online","pl_off":"offline","ic":"mdi:lan-connect"}' on homeassistant/binary_sensor/a5a5a5a5/mqtt_connected/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.208 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":"door sensor","unique_id":"a5a5a5a5_door_sensor","dev_cla":"door","stat_t":"~/lock/doorSensorState","pl_on":"doorOpened","pl_off":"doorClosed","pl_not_avail":"unavailable"}' on homeassistant/binary_sensor/a5a5a5a5/door_sensor/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.209 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON battery_low: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"battery low","unique_id":"38354535_battery_low","dev_cla":"battery","stat_t":"~/battery/critical","ent_cat":"diagnostic","pl_on":"1","pl_off":"0"}'
2024-01-25 18:52:40.210 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON keypad_battery_low: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"keypad battery low","unique_id":"38354535_keypad_battery_low","dev_cla":"battery","stat_t":"~/battery/keypadCritical","ent_cat":"diagnostic","pl_on":"1","pl_off":"0"}'
2024-01-25 18:52:40.210 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON mqtt_connected: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"MQTT connected","unique_id":"38354535_mqtt_connected","stat_t":"~/maintenance/mqttConnectionState","ent_cat":"diagnostic","pl_on":"online","pl_off":"offline","ic":"mdi:lan-connect"}'
2024-01-25 18:52:40.210 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON door_sensor: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"door sensor","unique_id":"38354535_door_sensor","dev_cla":"door","stat_t":"~/lock/doorSensorState","pl_on":"doorOpened","pl_off":"doorClosed","pl_not_avail":"unavailable"}'
2024-01-25 18:52:40.212 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":"Restart NUKI Hub","unique_id":"a5a5a5a5_reset","stat_t":"~/maintenance/reset","ent_cat":"diagnostic","cmd_t":"~/maintenance/reset","ic":"mdi:restart","pl_on":"1","pl_off":"0","state_on":"1","state_off":"0"}' on homeassistant/switch/a5a5a5a5/reset/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.213 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":"LED enabled","unique_id":"a5a5a5a5_led_enabled","stat_t":"~/configuration/ledEnabled","ent_cat":"config","cmd_t":"~/configuration/ledEnabled","ic":"mdi:led-variant-on","pl_on":"1","pl_off":"0","state_on":"1","state_off":"0"}' on homeassistant/switch/a5a5a5a5/led_enabled/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.215 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":"Button enabled","unique_id":"a5a5a5a5_button_enabled","stat_t":"~/configuration/buttonEnabled","ent_cat":"config","cmd_t":"~/configuration/buttonEnabled","ic":"mdi:radiobox-marked","pl_on":"1","pl_off":"0","state_on":"1","state_off":"0"}' on homeassistant/switch/a5a5a5a5/button_enabled/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.215 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON reset: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"Restart NUKI Hub","unique_id":"38354535_reset","stat_t":"~/maintenance/reset","ent_cat":"diagnostic","cmd_t":"~/maintenance/reset","ic":"mdi:restart","pl_on":"1","pl_off":"0","state_on":"1","state_off":"0"}'
2024-01-25 18:52:40.216 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON led_enabled: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"LED enabled","unique_id":"38354535_led_enabled","stat_t":"~/configuration/ledEnabled","ent_cat":"config","cmd_t":"~/configuration/ledEnabled","ic":"mdi:led-variant-on","pl_on":"1","pl_off":"0","state_on":"1","state_off":"0"}'
2024-01-25 18:52:40.216 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON button_enabled: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":"Button enabled","unique_id":"38354535_button_enabled","stat_t":"~/configuration/buttonEnabled","ent_cat":"config","cmd_t":"~/configuration/buttonEnabled","ic":"mdi:radiobox-marked","pl_on":"1","pl_off":"0","state_on":"1","state_off":"0"}'
2024-01-25 18:52:40.217 WARNING (MainThread) [homeassistant.components.mqtt.client] Can't decode payload b'{"dev":{"ids":["nuki_a5a5a5a5"],"mf":"Nuki","mdl":"SmartLock","name":"\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5\xa5"},"~":"nuki","name":null,"unique_id":"a5a5a5a5_lock","cmd_t":"~/lock/action","avty":{"t":"~/maintenance/mqttConnectionState"},"pl_lock":"lock","pl_unlk":"unlock","pl_open":"unlatch","stat_t":"~/lock/binaryState","stat_locked":"locked","stat_unlocked":"unlocked","opt":"false"}' on homeassistant/lock/a5a5a5a5/smartlock/config with encoding utf-8 (for <Job None HassJobType.Callback functools.partial(<function _callback_wrapper at 0x7ff9fe12f600>, <function async_start.<locals>.async_discovery_message_received at 0x7ff9d8d7cf40>, <function async_subscribe.<locals>.<lambda> at 0x7ff9d52b4220>)>)
2024-01-25 18:52:40.218 WARNING (MainThread) [homeassistant.components.mqtt.discovery] Unable to parse JSON smartlock: '{"dev":{"ids":["nuki_38354535"],"mf":"Nuki","mdl":"SmartLock","name":"E50�local"},"~":"nuki","name":null,"unique_id":"38354535_lock","cmd_t":"~/lock/action","avty":{"t":"~/maintenance/mqttConnectionState"},"pl_lock":"lock","pl_unlk":"unlock","pl_open":"unlatch","stat_t":"~/lock/binaryState","stat_locked":"locked","stat_unlocked":"unlocked","opt":"false"}'

If I delete the autodiscovery topics on the MQTT broker, the warnings on home-assistant go away for a few hours, but then reappear after some time.

I only have one NUKI Lock and one NUKI Hub.

@technyon
Copy link
Owner

This is your problem:

Log entry count: 22

Only 5 entries are requested from the lock, so there should be a maximum of 5 entries. I suspect a bug in the firmware, especially if it 's only reported for 4.0 locks.

Let me get in touch with the devs of the library that controls the lock. Problem is though we could ask in the NUKI developer forum, but lately there seems to be noone answering there.

@micronax
Copy link
Author

micronax commented Jan 26, 2024

So the JSON is already delivered cut-off from that other library?

Is that your fork here: https://github.com/technyon/nuki_ble ?

@technyon
Copy link
Owner

Yes that's my fork, altough there should be no difference to the main project at this time, except maybe for a few missing commits.

That library doesn't provide JSON, but enables communication to the lock. If 5 log entries are requested, it should return 5 objects with log information. In your case it returns 22, which are then serialized to JSON. Since the library worked fine until now, I suspect firmware bug in the 4.0 locks.

@micronax
Copy link
Author

But since the JSON itself is prematurely terminated and therefore no valid JSON, it could also be a memory / buffer problem in your JSON serialization, can't it?

Am I thinking to primitive or might it be just possible to discard any entries you receive from that lib after the fifth one and then just serialize those 5 ones?

@technyon
Copy link
Owner

Well, on a microcontroller resources are limited. You can't just happily create strings like on a x86 architecture, since memory is limited. For serialization a static buffer is allocated, and the number of log entries was chosen accordingly so they fit into this buffer. NUKI Hub relies on a the library to only send it 5 entries, which in turn relies on the lock to send only 5 entries. The lock has a bug, sends more entries, the serializer stops when it reaches the buffer limit and your string is truncated.

Long story short, one should check external input, and yes maybe adding a check to only serialize the first five entries is a idea. Check the binary below.

nuki_hub-8.30-pre-3.zip

@micronax
Copy link
Author

Yes, I must admit that I don't have much experience with embedded and microcontroller coding.

But whatever you did now, worked. At least the JSON in that log field is not truncated anymore. Thank you 🙏

But: It also doesn't show the most recent logs. I think the logs are being red in reverse order.

Currently the JSON contains the indices 2-6 which represents the oldest entries 2-6 shown in the app. So the first one is skipped, then the 5 next entries are shown. But since there the log recorded like ~25 more log entries.

@technyon
Copy link
Owner

technyon commented Jan 27, 2024

Ultimately NUKI has to fix this. The order to send this is also specified when sending the request to the lock, and the lock should return entries in the correct order.

P.S.: Included in release 8.30

@iranl
Copy link
Collaborator

iranl commented May 19, 2024

Fixed in #368

@iranl iranl added the bug Something isn't working label May 19, 2024
@iranl iranl self-assigned this May 19, 2024
@iranl iranl added this to the 8.35 milestone May 19, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants