Reattempt failed flash operations

[todd-herbert]

In collaboration with @esev

Submitted for your consideration. Seems to be working, but definitely needs careful review.

(Hopefully) resolves the issues with NRF52 flash corruption which are occasionally caused when a connected BLE device moves out of range.

Flash operations are asynchronous when softdevice is enabled. If a BLE connection terminates non-gracefully (BLE_HCI_CONNECTION_TIMEOUT etc), it will cause an in-progress write/erase operation to fail.

---

Currently: failure of an async flash operation is not detected. No attempt to repeat is made if the operation failed.

Log (old)

INFO  | 20:29:31 2159141 [Router] Save /prefs/db.proto
lfs debug:617: Bad block at 126
lfs debug:617: Bad block at 180
INFO  | 20:29:36 2159146 [Router] BLE Disconnected, reason = 0x8
DEBUG | 20:29:36 2159146 [Router] PhoneAPI::close()
lfs debug:640: Relocating 126 160 to 181 160

---

This PR: detects failed flash operations using info available in the flash event callback, and makes several additional attempts to repeat a failed operation (before eventually giving up, if necessary).

Log

DEBUG | 16:17:19 43 [Button] Opening /prefs/config.proto, fullAtomic=1
INFO  | 16:17:19 43 [Button] Save /prefs/config.proto
DEBUG | 16:17:20 44 [Button] Opening /prefs/module.proto, fullAtomic=1
INFO  | 16:17:20 44 [Button] Save /prefs/module.proto
DEBUG | 16:17:20 44 [Button] Opening /prefs/channels.proto, fullAtomic=1
INFO  | 16:17:20 44 [Button] Save /prefs/channels.proto
INFO  | 16:17:25 49 [Button] BLE Disconnected, reason = 0x8
DEBUG | 16:17:25 49 [Button] PhoneAPI::close()
DEBUG | 16:17:25 49 [Button] Opening /prefs/db.proto, fullAtomic=0
INFO  | 16:17:25 49 [Button] Save /prefs/db.proto
DEBUG | 16:17:25 49 [Button] State: ON
DEBUG | 16:17:25 49 [Power] Battery: usbPower=0, isCharging=0, batMv=4172, batPct=98
INFO  | 16:17:25 49 [DeviceTelemetry] Send: air_util_tx=0.002611, channel_utilization=0.156667, battery_level=98, voltage=4.172000, uptime=49

Log (verbose)

Note: Write 1 and Write 2 are a result of a pre-existing workaround:

// Somehow S140 v6.1.1 assert an error when writing a whole page
// https://devzone.nordicsemi.com/f/nordic-q-a/40088/sd_flash_write-cause-nrf_fault_id_sd_assert
// Workaround: write half page at a time.

DEBUG | 09:11:25 503 [Button] Opening /prefs/config.proto, fullAtomic=1
INFO  | 09:11:25 503 [Button] Save /prefs/config.proto
[SOC   ] NRF_EVT_FLASH_OPERATION_ERROR#
[IFLASH] Erase: retry#
[SOC   ] NRF_EVT_FLASH_OPERATION_ERROR#
[IFLASH] Erase: retry#
[SOC   ] NRF_EVT_FLASH_OPERATION_ERROR#
[IFLASH] Erase: retry#
INFO  | 09:11:27 505 [Button] BLE Disconnected, reason = 0x8
DEBUG | 09:11:27 505 [Button] PhoneAPI::close()
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Erase: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 1: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 2: success#
DEBUG | 09:11:27 505 [Button] Opening /prefs/module.proto, fullAtomic=1
INFO  | 09:11:27 505 [Button] Save /prefs/module.proto
INFO  | 09:11:27 505 [Button] BLE Connected to TH-Phone
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Erase: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 1: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 2: success#
DEBUG | 09:11:27 506 [Button] Opening /prefs/channels.proto, fullAtomic=1
INFO  | 09:11:27 506 [Button] Save /prefs/channels.proto
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Erase: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 1: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 2: success#
[GAP   ] Conn Interval= 7.50 ms, Latency = 0, Supervisor Timeout = 5000 ms#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Erase: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 1: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 2: success#
[BOND  ] Loaded keys from file /adafruit/bond_prph/C921C7F59F80#
DEBUG | 09:11:28 506 [Button] Opening /prefs/db.proto, fullAtomic=0
INFO  | 09:11:28 506 [Button] Save /prefs/db.proto
[BOND  ] Loaded CCCD from file /adafruit/bond_prph/C921C7F59F80 ( offset = 91, len = 32 bytes )#
INFO  | 09:11:28 506 [Button] BLE connection secured
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Erase: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 1: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 2: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Erase: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 1: success#
[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS#
[IFLASH] Write 2: success#
DEBUG | 09:11:29 507 [Button] State: ON
bool BLEAdvertising::_start(uint16_t, uint16_t): 379: verify failed, error = NRF_ERROR_CONN_COUNT#
[GAP   ] ATT MTU is changed to 247#
DEBUG | 09:11:29 507 [Power] Battery: usbPower=0, isCharging=0, batMv=4198, batPct=100
[GAP   ] Conn Interval= 48.75 ms, Latency = 0, Supervisor Timeout = 5000 ms#
INFO  | 09:11:30 508 toRadioWriteCb data 0x2001f66a, len 2
DEBUG | 09:11:30 508 New ToRadio packet
INFO  | 09:11:30 508 Client wants config, nonce=65
DEBUG | 09:11:30 508 Got 4 files in manifest
INFO  | 09:11:30 508 Start API client config
[GATTS ] attr's cccd = 0x0001#
INFO  | 09:11:30 508 CCCD Updated: 1
INFO  | 09:11:30 508 Notify/Indicate enabled
[BOND  ] CCCD matches file /adafruit/bond_prph/C921C7F59F80 contents, no need to write#
DEBUG | 09:11:30 508 FromRadio=STATE_SEND_MY_INFO
INFO  | 09:11:30 508 getFromRadio=STATE_SEND_UIDATA
DEBUG | 09:11:30 508 Send My NodeInfo
DEBUG | 09:11:30 508 Send device metadata
DEBUG | 09:11:31 509 Send channels 8
DEBUG | 09:11:31 509 Send config: device

[thebentern]

Looks like a great approach to me

[todd-herbert]

Just an update that, as was suggested in the Discord discussion, I've opened an upstream PR at adafruit#838 first

[esev]

Initially I thought it would be better to not assert when one of the erase/program operations fails. But given meshtastic/firmware#4447 I think maybe calling assert is the right thing. It'll make it easier to find the cause for subsequent LittleFS failures.

[todd-herbert]

Initially I thought it would be better to not assert when one of the erase/program operations fails. But given meshtastic/firmware#4447 I think maybe calling assert is the right thing. It'll make it easier to find the cause for subsequent LittleFS failures.

I can imagine this would certainly make it easier to track down other sources of corruption. Do you think there's any reason to consider only asserting when debugging, or do you think this should be the general behavior? Would you suggest this in the upstream PR too? I imagine Adafruit may be less enthusiastic about the idea.