ESP32 bug: user is forced to repair when they should not be

[geeksville]

It seems sometimes the device forgets its bluetooth pairing state. The bug is definitely on the device side and independent of the GATT services used. I suspect that the ESP32 bluetooth's persistent NVS data might be getting discarded/corrupted somehow? Next steps are to print the entire NVS contents just before we try to start bluetooth and see if it is changing.

[geeksville]

This issue has been mentioned on Meshtastic. There might be relevant details there:

https://meshtastic.discourse.group/t/bluetooth-connection/152/7

[geeksville]

This issue has been mentioned on Meshtastic. There might be relevant details there:

https://meshtastic.discourse.group/t/alpha-tester-thread-please-try-device-code-0-7-11/298/185

[geeksville]

possibly related: espressif/esp-idf#3968

[geeksville]

yeah - this portion of esp32-hal-misc.c seems bad:

    esp_err_t err = nvs_flash_init();
    if(err == ESP_ERR_NVS_NO_FREE_PAGES){
        const esp_partition_t* partition = esp_partition_find_first(ESP_PARTITION_TYPE_DATA, ESP_PARTITION_SUBTYPE_DATA_NVS, NULL);
        if (partition != NULL) {
            err = esp_partition_erase_range(partition, 0, partition->size);
            if(!err){
                err = nvs_flash_init();
            } else {
                log_e("Failed to format the broken NVS partition!");
            }
        }
    }

[geeksville]

misc notes to self:
node 0xb4 has 202 entries allocated.
node 0x38 has 188 entries allocated.
ble security overview: https://www.kynetics.com/docs/2018/BLE_Pairing_and_bonding/

ok - NVS is not filling up, but this looks plausible:
espressif/esp-idf#5530 (comment) (and related thread) https://www.esp32.com/viewtopic.php?t=13049

alas - not related (it was in nimble). though it did make me realize that the idf 3.3 in the arduino build is pretty old. Looking at commits.

[geeksville]

alas - just had a failure. will now try logging all NVS writes.

[geeksville]

misc notes to self:

after a failure node 0x38 has 178 used entries. Therefore it must have done a GC on the NVS.
esptool.py read_flash 0x9000 0x5000 node38-june19.bin

good description of how RPA addressing works https://www.electronicdesign.com/technologies/communications/article/21801870/ble-v42-creating-faster-more-secure-powerefficient-designspart-2 (which seems related to the problem)

Someone encountered the same problem but never followed up: espressif/esp-idf#3968

ooh super interesting! espressif/esp-idf#1811 (comment) MITM_BOND might be the fix! Alas no.

After failure when phone tries to connect it just looks like hte normal auth flow?

Setting RTC 1595275827 secs
Read RTC time as 1595275827 (cur millis 12233) valid=1
GPS fix type 0
[D][BLEDevice.cpp:102] gattServerEventHandler(): gattServerEventHandler [esp_gatt_if: 3] ... Unknown
[D][BLEServer.cpp:368] onConnect(): BLEServerCallbacks
[D][BLEServer.cpp:369] onConnect(): BLEServerCallbacks
[D][BLEServer.cpp:370] onConnect(): BLEServerCallbacks
[D][BLEDevice.cpp:571] getAdvertising(): get advertising
[D][BLEAdvertising.cpp:193] start(): - advertising service: 6ba1b218-15a8-461f-9fa8-5dcae273eafd
[D][BLEDevice.cpp:571] getAdvertising(): get advertising
[D][BLEAdvertising.cpp:495] handleGAPEvent(): handleGAPEvent [event no: 0]
[D][BLEDevice.cpp:571] getAdvertising(): get advertising
[D][BLEAdvertising.cpp:495] handleGAPEvent(): handleGAPEvent [event no: 1]
[D][BLEDevice.cpp:571] getAdvertising(): get advertising
[D][BLEAdvertising.cpp:495] handleGAPEvent(): handleGAPEvent [event no: 6]
[I][BLEDevice.cpp:237] gapEventHandler(): ESP_GAP_BLE_PASSKEY_NOTIF_EVT
[I][BLEDevice.cpp:239] gapEventHandler(): passKey = 369823
onPassKeyNotify 369823
Trigger powerFSM 7
Transition powerFSM transition=Bluetooth pairing, from=ON to=ON
[D][BLEDevice.cpp:571] getAdvertising(): get advertising
[D][BLEAdvertising.cpp:495] handleGAPEvent(): handleGAPEvent [event no: 11]
showing bluetooth screen
GPS fix type 0
GPS fix type 0
GPS fix type 0
[I][BLEDevice.cpp:253] gapEventHandler(): ESP_GAP_BLE_AUTH_CMPL_EVT
phone authenticate failed 99
[D][BLEDevice.cpp:571] getAdvertising(): get advertising
[D][BLEAdvertising.cpp:495] handleGAPEvent(): handleGAPEvent [event no: 8]
showing standard frames
[D][BLEDevice.cpp:102] gattServerEventHandler(): gattServerEventHandler [esp_gatt_if: 3] ... Unknown
processUBX: counter hit MAX_PAYLOAD_SIZE
GPS fix type 0
GPS fix type 0

[geeksville]

This issue has been mentioned on Meshtastic. There might be relevant details there:

https://meshtastic.discourse.group/t/im-away-from-forum-for-a-couple-of-days-fixing-esp32-re-pairing/776/3

[geeksville]

ooh - someone with the same problem: https://www.bountysource.com/issues/61707647-whitelisting-still-does-not-allow-connections-idfgh-322. The bluedroid support for RPA is broken on ESP32 and they don't seem to be fixing it. Instead people are moving to Nimble.

Which is a bummer - because I wouldn't want to make such a big change in the project that this point. But it seems unavoidable (because I'm not going to be fixing bluedroid ;-). So I'll need to switch to Nimble (like the commerical devs seem to be doing). It will provide a few benefits:

• This bug can be fixed. (Because both iOS and Android now require RPA)
• SUBSTANTIAL savings in IRAM usage (very useful for turning wifi back on at the same time)
• Can use the same bluetooth stack on NRF52 AND ESP32 (so testing coverage is improved and maintenance costs go down)
• Will save LOTS of flash space on NRF52 because no need for softdevice with this stack.
• Support BLE-Mesh if we want to use it someday

[geeksville]

This issue has been mentioned on Meshtastic. There might be relevant details there:

https://meshtastic.discourse.group/t/an-update-on-the-esp-32-loss-of-pairing-bug/776/4