settings: Bluetooth: Failed parse/lookup #13572

Qbicz · 2019-02-20T13:59:29Z

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 #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

flash a peripheral with HID service
connect from any central (Android, Windows or Zephyr central)
pair and send HID notifications
disconnect
Zephyr peripheral reset
on booting the device is bricked with ASSERTION FAIL [rc == 0]

Environment (please complete the following information):

nrf52840
Zephyr SDK 0.9.5, ninja 1.5.1
Commit SHA: ec424b7

The text was updated successfully, but these errors were encountered:

jhedberg · 2019-02-20T14:07:32Z

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 · 2019-02-20T14:42:11Z

Can be reproduced every time.

Qbicz · 2019-02-20T14:50:15Z

@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 · 2019-02-21T07:21:27Z

@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 · 2019-02-21T07:41:38Z

[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 · 2019-02-21T07:43:21Z

@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 · 2019-02-21T07:48:26Z

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

Laczen · 2019-02-21T08:08:40Z

@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 · 2019-02-21T08:34:12Z

@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 · 2019-02-21T09:00:53Z

@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 · 2019-02-21T10:32:51Z

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

jhedberg · 2019-02-21T10:42:05Z

FYI @Vudentz

Fixes zephyrproject-rtos#13572. Initialize key used to store Client Features even when config was not found. Signed-off-by: Filip Kubicz <[email protected]>

Fixes #13572. Initialize key used to store Client Features even when config was not found. Signed-off-by: Filip Kubicz <[email protected]>

Qbicz added bug The issue is a bug, or the PR is fixing a bug area: Bluetooth area: Storage Storage subsystem labels Feb 20, 2019

jhedberg assigned jhedberg and nvlsianpu Feb 20, 2019

Qbicz mentioned this issue Feb 21, 2019

Bluetooth: settings: Always initialize key when storing Client Features #13620

Merged

nashif closed this as completed in #13620 Feb 21, 2019

nashif pushed a commit that referenced this issue Feb 21, 2019

Bluetooth: settings: Always initialize key when storing Client Features

f1a2295

Fixes #13572. Initialize key used to store Client Features even when config was not found. Signed-off-by: Filip Kubicz <[email protected]>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

settings: Bluetooth: Failed parse/lookup #13572

settings: Bluetooth: Failed parse/lookup #13572

Qbicz commented Feb 20, 2019 •

edited

Loading

jhedberg commented Feb 20, 2019

Uh oh!

Qbicz commented Feb 20, 2019

Uh oh!

Qbicz commented Feb 20, 2019

Uh oh!

Laczen commented Feb 21, 2019 •

edited

Loading

Uh oh!

jhedberg commented Feb 21, 2019

Uh oh!

jhedberg commented Feb 21, 2019

Uh oh!

jhedberg commented Feb 21, 2019

Uh oh!

Laczen commented Feb 21, 2019

Uh oh!

Laczen commented Feb 21, 2019

Uh oh!

Laczen commented Feb 21, 2019 •

edited

Loading

Uh oh!

Qbicz commented Feb 21, 2019

Uh oh!

jhedberg commented Feb 21, 2019

Uh oh!

settings: Bluetooth: Failed parse/lookup #13572

settings: Bluetooth: Failed parse/lookup #13572

Comments

Qbicz commented Feb 20, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

jhedberg commented Feb 20, 2019

Uh oh!

Qbicz commented Feb 20, 2019

Uh oh!

Qbicz commented Feb 20, 2019

Uh oh!

Laczen commented Feb 21, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jhedberg commented Feb 21, 2019

Uh oh!

jhedberg commented Feb 21, 2019

Uh oh!

jhedberg commented Feb 21, 2019

Uh oh!

Laczen commented Feb 21, 2019

Uh oh!

Laczen commented Feb 21, 2019

Uh oh!

Laczen commented Feb 21, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Qbicz commented Feb 21, 2019

Uh oh!

jhedberg commented Feb 21, 2019

Uh oh!

Qbicz commented Feb 20, 2019 •

edited

Loading

Laczen commented Feb 21, 2019 •

edited

Loading

Laczen commented Feb 21, 2019 •

edited

Loading