search

zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.51k stars 6.44k forks source link

settings: Bluetooth: Failed parse/lookup #13572

Closed Qbicz closed 5 years ago

Qbicz commented 5 years ago

Describe the bug Bluetooth host cannot load the values it previously stored in settings. After wake up or reset, it asserts with set-value operation failure. In settings_set_value_priv(), settings_parse_and_lookup() fails and -EINVAL is returned (-22).

Similar problem has been previously fixed in https://github.com/zephyrproject-rtos/zephyr/pull/11576, but now it happens again. 

[01004699] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0026 offset 66 length 13
[01005435] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x002b offset 0 length 4
[01006173] <dbg> bt_gatt.bt_gatt_attr_write_ccc: handle 0x0020 value 1
[01006173] <dbg> bt_gatt.gatt_ccc_changed: ccc 0x20001d34 value 0x0001
[01006190] <dbg> bt_gatt.gatt_notify: conn 0x2000258c handle 0x001f
[01006197] <dbg> bt_gatt.gatt_notify: conn 0x2000258c handle 0x001f
[01006911] <dbg> bt_gatt.bt_gatt_attr_write_ccc: handle 0x0029 value 1
[01006912] <dbg> bt_gatt.gatt_ccc_changed: ccc 0x20001d44 value 0x0001
[01007809] <dbg> bt_gatt.ccc_save: Storing CCCs handle 0x0004 value 0x0002
[01007810] <dbg> bt_gatt.ccc_save: Storing CCCs handle 0x0020 value 0x0001
[01007810] <dbg> bt_gatt.ccc_save: Storing CCCs handle 0x0029 value 0x0001
[01007813] <dbg> bt_settings.bt_settings_encode_key: Encoded path bt/ccc/8883223e9a6b0
[01007933] <dbg> bt_gatt.bt_gatt_store_ccc: Stored CCCs for 88:83:22:3e:9a:6b (public) (bt/ccc/8883223e9a6b0)
[01007933] <dbg> bt_gatt.bt_gatt_store_ccc:   CCC: handle 0x0004 value 0x0002
[01007933] <dbg> bt_gatt.bt_gatt_store_ccc:   CCC: handle 0x0020 value 0x0001
[01007934] <dbg> bt_gatt.bt_gatt_store_ccc:   CCC: handle 0x0029 value 0x0001

[DISCONNECTION]

02454260] <dbg> bt_gatt.bt_gatt_disconnected: conn 0x2000258c
[02454260] <dbg> bt_gatt.sc_ccc_cfg_changed: value 0x0000
[02454260] <dbg> bt_gatt.disconnected_cb: ccc 0x20009390 reseted
[02454261] <inf> hids:
[02454262] <inf> hids: Notifications disabled
[02454263] <dbg> bt_gatt.disconnected_cb: ccc 0x20001d34 reseted
[02454263] <inf> hids:
[02454263] <dbg> bt_gatt.disconnected_cb: ccc 0x20001d44 reseted
[02454264] <dbg> bt_gatt.ccc_save: Storing CCCs handle 0x0004 value 0x0002
[02454265] <dbg> bt_gatt.ccc_save: Storing CCCs handle 0x0020 value 0x0001
[02454266] <dbg> bt_gatt.ccc_save: Storing CCCs handle 0x0029 value 0x0001
[02454268] <dbg> bt_settings.bt_settings_encode_key: Encoded path �m
[02454290] <dbg> bt_gatt.bt_gatt_store_ccc: Stored CCCs for 88:83:22:3e:9a:6b (public) (�m)
[02454290] <dbg> bt_gatt.bt_gatt_store_ccc:   CCC: handle 0x0004 value 0x0002
[02454290] <dbg> bt_gatt.bt_gatt_store_ccc:   CCC: handle 0x0020 value 0x0001
[02454290] <dbg> bt_gatt.bt_gatt_store_ccc:   CCC: handle 0x0029 value 0x0001
[02454316] <inf> event_manager: e: hid_report_subscription_event MOUSE report notification disabled by 0x2000258c
[02454317] <inf> hid_state: Clear report data (0)
[02454450] <dbg> bt_gatt.bt_gatt_store_cf: Stored CF for 88:83:22:3e:9a:6b (public) (|-)
[02454453] <inf> ble_state: Disconnected from 88:83:22:3e:9a:6b (public) (reason 19)
[02454460] <inf> event_manager: e: ble_peer_event id=0x2000258c DISCONNECTED

[REBOOT]

[00000004] <dbg> bt_gatt.gatt_register: attr 0x20009484 handle 0x0001 uuid 2a4c perm 0x01
[00000005] <dbg> bt_gatt.gatt_register: attr 0x20009498 handle 0x0002 uuid 2a4c perm 0x01
[00000005] <dbg> bt_gatt.gatt_register: attr 0x200094ac handle 0x0003 uuid 2a4c perm 0x00
[00000006] <dbg> bt_gatt.gatt_register: attr 0x200094c0 handle 0x0004 uuid 2a4c perm 0x03
[00000007] <dbg> bt_gatt.gatt_register: attr 0x200094d4 handle 0x0005 uuid 2a4c perm 0x01
[00000008] <dbg> bt_gatt.gatt_register: attr 0x200094e8 handle 0x0006 uuid 2a4c perm 0x03
[00000008] <dbg> bt_gatt.gatt_register: attr 0x200094fc handle 0x0007 uuid 2a4c perm 0x01
[00000009] <dbg> bt_gatt.gatt_register: attr 0x20009510 handle 0x0008 uuid 2a4c perm 0x01
[00000010] <dbg> bt_gatt.gatt_register: attr 0x200093ec handle 0x0009 uuid 2a4c perm 0x01
[00000011] <dbg> bt_gatt.gatt_register: attr 0x20009400 handle 0x000a uuid 2a4c perm 0x01
[00000011] <dbg> bt_gatt.gatt_register: attr 0x20009414 handle 0x000b uuid 2a4c perm 0x01
[00000012] <dbg> bt_gatt.gatt_register: attr 0x20009428 handle 0x000c uuid 2a4c perm 0x01
[00000013] <dbg> bt_gatt.gatt_register: attr 0x2000943c handle 0x000d uuid 2a4c perm 0x01
[00000014] <dbg> bt_gatt.gatt_register: attr 0x20009450 handle 0x000e uuid 2a4c perm 0x01
[00000014] <dbg> bt_gatt.gatt_register: attr 0x20009464 handle 0x000f uuid 2a4c perm 0x01
[00000021] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0001 offset 0 length 2
[00000022] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0002 offset 0 length 5
[00000028] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0005 offset 0 length 5
[00000034] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0007 offset 0 length 5
[00000035] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0009 offset 0 length 2
[00000036] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x000a offset 0 length 5
[00000042] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x000c offset 0 length 5
[00000048] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x000e offset 0 length 5
[00000054] <dbg> bt_gatt: Hash:
                          af 57 cf 1e 32 c0 c6 45 |.W..2..E
                          4d 4b 8a 82 2d e2 77 fb |MK..-.w.
[00000055] <dbg> bt_gatt.gatt_register: attr 0x20009080 handle 0x0010 uuid 2a4c perm 0x01
[00000056] <dbg> bt_gatt.gatt_register: attr 0x20009094 handle 0x0011 uuid 2a4c perm 0x01
[00000056] <dbg> bt_gatt.gatt_register: attr 0x200090a8 handle 0x0012 uuid 2a4c perm 0x01
[00000057] <dbg> bt_gatt.gatt_register: attr 0x200090bc handle 0x0013 uuid 2a4c perm 0x01
[00000058] <dbg> bt_gatt.gatt_register: attr 0x200090d0 handle 0x0014 uuid 2a4c perm 0x01
[00000059] <dbg> bt_gatt.gatt_register: attr 0x200090e4 handle 0x0015 uuid 2a4c perm 0x01
[00000059] <dbg> bt_gatt.gatt_register: attr 0x200090f8 handle 0x0016 uuid 2a4c perm 0x01
[00000064] <inf> event_manager: e: module_state_event module:main state:READY
[00000083] <dbg> bt_settings.bt_settings_init:
[00000197] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00000197] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00000197] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 1.14 Build 0
[00000212] <wrn> bt_hci_core: No ID address. Expecting one to come from storage.
[00011457] <dbg> bt_settings.set: ID Addr 0 da:cc:c2:8d:fa:d9 (random)
[00011457] <err> settings_store: rc=0
[00011464] <inf> bt_settings: checking ccc...
[00011464] <inf> bt_settings: checking cf...
[00011464] <inf> bt_settings: checking keys...
[00011465] <inf> bt_settings: call set: keys
[00011470] <dbg> bt_settings.bt_settings_decode_key: Decoded  as 88:83:22:3e:9a:6b (public)
[00011471] <err> settings_store: rc=0
[00011478] <inf> bt_settings: checking ccc...
[00011478] <inf> bt_settings: call set: ccc
[00011481] <dbg> bt_settings.bt_settings_decode_key: Decoded   as 88:83:22:3e:9a:6b (public)
[00011482] <dbg> bt_gatt.ccc_set: Read CCC: handle 0x0004 value 0x0002
[00011482] <dbg> bt_gatt.ccc_set: Read CCC: handle 0x0020 value 0x0001
[00011482] <dbg> bt_gatt.ccc_set: Read CCC: handle 0x0029 value 0x0001
[00011482] <dbg> bt_gatt.ccc_load: Restoring CCC: handle 0x0004 value 0x0002
[00011483] <dbg> bt_gatt.ccc_load: Restoring CCC: handle 0x0020 value 0x0001
[00011484] <dbg> bt_gatt.ccc_load: Restoring CCC: handle 0x0029 value 0x0001
[00011487] <dbg> bt_gatt.ccc_set: Restored CCC for 88:83:22:3e:9a:6b (public)
[00011487] <err> settings_store: rc=0
[00011491] <err> settings: F: failed parse and lookup
[00011491] <err> settings_store: rc=-22
ASSERTION FAIL [rc == 0] @ /home/fi/ncs/zephyr/subsys/settings/src/settings_store.c:52
        set-value operation failure

To Reproduce

Environment (please complete the following information):

jhedberg commented 5 years ago

I wonder what's going on here. Bluetooth writes to flash only through the settings API, so the corruption would have to happen on some lower level. Is it really a good policy to have settings assert, instead of throwing an error, when encountering corrupted flash content?

Qbicz commented 5 years ago

Can be reproduced every time.

Qbicz commented 5 years ago

@jhedberg I agree asserting here is unfortunate. If we ignore such error, the previous record will be used, if any was valid before (am I correct?).

It may also be an effect of Bluetooth host writing something incorrect.

Laczen commented 5 years ago

@jhedberg, @Qbicz: It is unfortunate that an assert is triggered, this is triggered if there is a record in flash that has no set handler. As a result it is not possible to store data on the flash that is not related to settings. However, in this case it is an advantage because there definitely is something wrong with what is written to settings by the bluetooth module:

[02454268] <dbg> bt_settings.bt_settings_encode_key: Encoded path �m

This is written after the disconnect and is clearly wrong.

jhedberg commented 5 years ago

[02454268] <dbg> bt_settings.bt_settings_encode_key: Encoded path �m

This is written after the disconnect and is clearly wrong.

@Laczen are you sure that's not just a missing log_strdup() call? Ever since we moved to deferred logging trying to log any on-stack strings will give you garbage like that, since by the time the logger thread processes the message the string is already out of scope.

jhedberg commented 5 years ago

@Laczen I just looked at the code and bt_settings_encode_key() is indeed missing a log_strdup(). So this corrupted string is a red herring, I think, i.e. probably safe to ignore (someone should submit a PR to add the log_strdup though).

jhedberg commented 5 years ago

@Laczen I created #13612 which should fix the corrupted string in the logs.

Laczen commented 5 years ago

@jhedberg, OK, I really dislike this deferred logging. So it seems that it is failing on restoring "cf", this was the last thing stored but is not restored.

Laczen commented 5 years ago

@jhedberg, in gatt.c: bt_gatt_store_cf() &conn->le.dst is used to store the key, is it guaranteed that this is a string that does not contain the separation \ ?

Laczen commented 5 years ago

@jhedberg, it might be something else: in bt_gatt_store_cf key is not given a value if (!cfg), so what is stored? Should key be set to "bt/cf" ?

Qbicz commented 5 years ago

@Laczen thanks for finding that! This is indeed caused by cf which was introduced as a new Bluetooth 5.1 feature in aecf7c7076. I confirm that initializing key with "bt/cf/address" or "bt/cf" solves this particular problem.

jhedberg commented 5 years ago

FYI @Vudentz