Zephyr: when CONFIG_BT_SETTINGS is enabled, stack stores id in flash memory each power up of device (call to bt_enable)

[ppryga]

Describe the bug
BT settings commit procedure calls bt_settings_save_id each bt_enable at power up:

    if (!atomic_test_bit(bt_dev.flags, BT_DEV_PRESET_ID)) {
        BT_WARN("commit");
        bt_settings_save_id();
    }

As far as I found the commit proceudre is registered as static handler for settings and is triggered by settings driver after load finishes.
BT_DEV_PRESET_ID bit is set by bt_init() if CONFIG_BT_SETTINGS is enabled.

To Reproduce
Steps to reproduce the behavior:

1. Run a sample that uses CONFIG_BT_SETTINGS (e.g. nRF Desktop) that uses BLE and check if save_id is called by BT settings commit.

Expected behavior
BT init should not store id if ID were already stored.

Impact
May decrease lifetime of flash memory if device goest to power down mode very often.
Block execution system work queue for long time because of use of flash write operation.
Can't run very high frequecy task in a work queue when BT settings are loading.

[aescolar]

CC @nvlsianpu @jhedberg @Vudentz

[jhedberg]

If you look at the bt_settings_save_id() function in subsys/bluetooth/host/settings.c you'll see that the storing to flash is done through the system workqueue, meaning the ID creation functions should return immediately. This is intentionally designed this way so that you can call bt_id_create() multiple times in a loop, and only when a context switch occurs will the identities be stored into flash. So I'm not sure what the problem is - perhaps I'm misunderstanding your description.

[ppryga]

I apologize for wrong description. It've updated the comment - update section of Description

[ppryga]

The question here is: if store of that id - by bt_settings_save_id is required each time I call bt_enable on power up? Even the device has already stored some ids in settings?

[pdunaj]

Hi @dleach02 it does not look low as it will cause FLASH memory degradation. This will especially impact devices that reboot frequently (e.g. use off mode for power saving) and have small settings partition.

Hi @aescolar , even if the write operation occurs in workqueue it will cause system block for 10s of milliseconds during each reboot. Not at the ble initialization but at the first thing that will require system workqueue to be available.

Hi @nvlsianpu , would it be possible to create some async mechanism for writing to storage? Something that would not require blocking threads during it? Is there a way for HW to notify that operation is done (so we don't have actively wait for it)?

[nvlsianpu]

@ppryga - Are you sure that write to the flash really occurring? Normal settings check storage content and avoid write of duplicates (although it reads storage while searching for similar key-value).

@pdunaj - first we have to make settings multi-threading safe, other problem is that at the lowest level the flash driver is just blocking API now.

[jhedberg]

Expected behavior
BT init should not store id if ID were already stored.

@ppryga thanks for clarifying - it is indeed a bug if data that was just read from flash upon Bluetooth init gets written back to flash. That's something we actively detect and prevent for all other types of data we store in flash.

[ppryga]

@nvlsianpu Yes I'm sure.

This part of code from bt_init sets the flag BT_DEV_PRESET_ID

    if (IS_ENABLED(CONFIG_BT_SETTINGS)) {
        if (!bt_dev.id_count) {
            BT_WARN("No ID address. App must call settings_load()");
            return 0;
        }

        atomic_set_bit(bt_dev.flags, BT_DEV_PRESET_ID);
    }

This part of commit (settings.c) triggers save settings:

        if (!atomic_test_bit(bt_dev.flags, BT_DEV_PRESET_ID)) {
        BT_WARN("commit, bt_def.flags: %x", bt_dev.flags);
        bt_settings_save_id();
    }

And be_settings_save_id triggers work responsible for settings store:

void bt_settings_save_id(void)
{
    k_work_submit(&save_id_work);
}

And save_id does store operation unconditioanlly:

static void save_id(struct k_work *work)
{
    int err;
    BT_INFO("Saving ID");
    err = settings_save_one("bt/id", &bt_dev.id_addr,
                ID_DATA_LEN(bt_dev.id_addr));
    if (err) {
        BT_ERR("Failed to save ID (err %d)", err);
    }

#if defined(CONFIG_BT_PRIVACY)
    err = settings_save_one("bt/irk", bt_dev.irk, ID_DATA_LEN(bt_dev.irk));
    if (err) {
        BT_ERR("Failed to save IRK (err %d)", err);
    }
#endif
    BT_INFO("Saving ID Done");
}

[Laczen]

I can confirm the reported bug. I don't understand the reason that the commit calls a save, I think it should be bt_id_create() that calls the save.

[Laczen]

Or maybe the save should be called only when there was no bt_dev.id_count in the commit routine.

[nvlsianpu]

BT_DEV_PRESET_ID bit causes that 'bt/id` key is not loaded from the storage and bt_dev.id_count is never assign. so bt_dev.id_count keep 0 values, which causes generation of new ID and attempt to write it to the settings storage. somehow new ID must be always different than the old one...

What BT_DEV_PRESET_ID flag suppose to do?

[jhedberg]

What BT_DEV_PRESET_ID flag suppose to do?

It's supposed to track whether the application explicitly created identities before calling bt_enable() in which case those identities take precedence over anything that might be stored in flash.

The code in the commit() function looks buggy to me - it seems it was introduced by commit 2b84c726c8893eaaa1bf26dfddf2798b159cd47d so I hope @joerchan can provide some clarity on this. It seems to me like we should be tracking through the set() callback if any identities were stored in flash, and if so not try re-write them to flash through commit(). It looks like the existing code was put there for the use case bt_enable(); .. create identities; settings_load(); in which case we do want to store those in flash through commit(), however it doesn't consider the simpler (and probably more common) case of bt_enable(); settings_load(); when flash already contains identities.

[joerchan]

@jhedberg Thank you for the analysis. I will check if I can solve the problem.

The reason why I added it is for the simple scenario where the application does not create any identities at all. In this case the Host will read an identity address and generate an identity resolving key (IRK). And it is the generation of the IRK that is the problem since it is not stored in flash.
This resulted in the IRK being generated on every power-up and the privacy feature is then completely broken.

[nvlsianpu]

So, I investigated the issue - write to the storage is requested (nvs_write() ) but is not executed in fact as NVS discard duplicates writes (other settings back-end filter duplicates on higher level).
So increase of wear leveling is not an issue.

[nvlsianpu]

@ppryga >

Block execution system work queue for long time is in fact due to fact that storage is scanned for settings record duplicates.

Impact
May decrease lifetime of flash memory if device goes to power down mode very often.
Block execution system work queue for long time because of use of flash read operations for searching entire storage for a settings duplicate .
Can't run very high frequecy task in a work queue when BT settings are loading.

[nvlsianpu]

@joakimtoe From conversation above I see that if BT_DEV_PRESET_ID flag is set basically writing of bt/id and bt/irk settings records should be disabled.

[joakimtoe]

@joakimtoe From conversation above I see that if BT_DEV_PRESET_ID flag is set basically writing of bt/id and bt/irk settings records should be disabled.

Wrong Joakim, @joerchan maybe?

[joerchan]

So, I investigated the issue - write to the storage is requested (nvs_write() ) but is not executed in fact as NVS discard duplicates writes (other settings back-end filter duplicates on higher level).
So increase of wear leveling is not an issue.

Thank you @nvlsianpu that is good to hear that flash wear is not an issue. I`m working an fix that would prevent the attempted write when no new IDs has been generated. On nRF devices we shouldn't have to generate an IRK at all.

[mfiumara]

@nvlsianpu Is the conclusion correct that there is no flash wear? Maybe so for the bt/id and bt/irk flags, but bt/hash gets rewritten always (as mentioned in #20632). An excerpt from my storage memory of a device resetting multiple times:

0x0007B000: C0FFEEEE 0007FF01 2F746218 68736168   |.........bt/hash|
0x0007B010: 9243D53D 3B7FBAD2 2DD486F0 2AD9F5CC   |=.C....;...-...*|
0x0007B020: 6218905A 61682F74 003D6873 00000000   |Z..bt/hash=.....|
0x0007B030: 00000000 00000000 EF000000 2F746218   |.............bt/|
0x0007B040: 68736168 9243D53D 3B7FBAD2 2DD486F0   |hash=.C....;...-|
0x0007B050: 2AD9F5CC 6218905A 61682F74 003D6873   |...*Z..bt/hash=.|
0x0007B060: 00000000 00000000 00000000 EF000000   |................|
0x0007B070: 2F746218 68736168 9243D53D 3B7FBAD2   |.bt/hash=.C....;|
0x0007B080: 2DD486F0 2AD9F5CC 6218905A 61682F74   |...-...*Z..bt/ha|
0x0007B090: 003D6873 00000000 00000000 00000000   |sh=.............|
0x0007B0A0: EF000000 2F746218 68736168 9243D53D   |.....bt/hash=.C.|
0x0007B0B0: 3B7FBAD2 2DD486F0 2AD9F5CC 6218905A   |...;...-...*Z..b|
0x0007B0C0: 61682F74 003D6873 00000000 00000000   |t/hash=.........|
0x0007B0D0: 00000000 EF000000 2F746218 68736168   |.........bt/hash|
0x0007B0E0: 9243D53D 3B7FBAD2 2DD486F0 2AD9F5CC   |=.C....;...-...*|
0x0007B0F0: 6218905A 61682F74 003D6873 00000000   |Z..bt/hash=.....|
0x0007B100: 00000000 00000000 EF000000 2F746218   |.............bt/|
0x0007B110: 68736168 9243D53D 3B7FBAD2 2DD486F0   |hash=.C....;...-|
0x0007B120: 2AD9F5CC 6218905A 61682F74 003D6873   |...*Z..bt/hash=.|
0x0007B130: 00000000 00000000 00000000 EF000000   |................|
0x0007B140: 2F746218 68736168 9243D53D 3B7FBAD2   |.bt/hash=.C....;|
0x0007B150: 2DD486F0 2AD9F5CC 6218905A 61682F74   |...-...*Z..bt/ha|
0x0007B160: 003D6873 00000000 00000000 00000000   |sh=.............|
0x0007B170: EF000000 2F746218 68736168 9243D53D   |.....bt/hash=.C.|
0x0007B180: 3B7FBAD2 2DD486F0 2AD9F5CC 6218905A   |...;...-...*Z..b|
0x0007B190: 61682F74 003D6873 00000000 00000000   |t/hash=.........|
0x0007B1A0: 00000000 EF000000 2F746218 68736168   |.........bt/hash|
0x0007B1B0: 9243D53D 3B7FBAD2 2DD486F0 2AD9F5CC   |=.C....;...-...*|
0x0007B1C0: 6218905A 61682F74 003D6873 00000000   |Z..bt/hash=.....|
0x0007B1D0: 00000000 00000000 EF000000 2F746218   |.............bt/|
0x0007B1E0: 68736168 9243D53D 3B7FBAD2 2DD486F0   |hash=.C....;...-|
0x0007B1F0: 2AD9F5CC 6218905A 61682F74 003D6873   |...*Z..bt/hash=.|
0x0007B200: 00000000 00000000 00000000 EF000000   |................|
0x0007B210: 2F746218 68736168 9243D53D 3B7FBAD2   |.bt/hash=.C....;|

[joerchan]

@mfiumara It seems to alternate between the same value and zero. Is it deleted by the application at one point perhaps?

[mfiumara]

@joerchan I just checked again and can explain what is happening in my flash storage partition. I'm calling settings_load in my bt_ready callback, which results in a db_hash_store with hash=0x00000. After this, somewhere db_hash_gen is triggered, which generates the proper hash and stores it again to the flash. Whenever I reset the same happens, which causes the switching of hashes.
I'll create a separate issue for this.

[joerchan]

The original issue I believe has been fixed by #21217
If anybody disagrees please re-open the issue.

The issue about flash wear on the bt/hash setting has been moved to it's own issue: #22730