search

Frozen-Burrito / hydrate-extension-inteligente

Repositorio para el software de aplicación para la extensión inteligente de botellas de agua Hydrate.
2 stars 0 forks source link

[BUG] Intentar obtener los registros desde NVS para sincronizarlos resulta en `ESP_ERR_NVS_NOT_FOUND` #4

Closed Frozen-Burrito closed 2 years ago

Frozen-Burrito commented 2 years ago

Descripción del Error Cuando la extensión de la botella entra en modo de sincronización e intenta obtener los registros de hidratación almacenados en NVS, puede obtener un solo registro y luego produce un error ESP_ERR_NVS_NOT_FOUND para los cuatro registros restantes (la extensión puede almacenar hasta 5 registros de hidratación en NVS).

Cómo Reproducir Pasos para reproducir el error:

  1. Inicializar la extensión de botella, con la versión 1.0.0+2 actual programada en el ESP32.
  2. Esperar un momento a que varios registros de hidratación sean producidos y almacenados en NVS.
  3. Hacer que la extensión entre en modo de sincronización (emparejándola con un dispositivo periférico por BLE).
  4. Observar los errores de NVS resultantes.

Comportamiento Esperado Al entrar en modo de sincronización, la extensión para botellas debería sincronizar todos los registros encontrados en xSyncQueue, los registros previamente enviados a xStorageQueue, y los registros almacenados en NVS (hasta 5 de los últimos).

Entorno

Contexto Adicional Es muy probable que el problema esté relacionado con los índices de acceso a entradas de NVS (el parámetro index, recibido por la función get_hydration_record() en storage.h. También es posible que el problema esté en la forma que se obtienen las keys para NVS (obtenerlas según el índice, como water_amount_1 y water_amount_2 corresponden a los registros con índice 1 y 2, respectivamente).

Los logs producidos antes, durante y después de uno de los varios eventos de error producidos por la extensión de botellas:

(...)
I (33762) MAIN: Nuevo registro de hidratacion generado: { water: 410, temp: 13, bat: 0, time: 33}
I (33762) MAIN: Nuevo registro de hidratacion enviado para almacenamiento, total 7
I (33832) BLE: Estado de BLE: Advertising
I (34352) BLE: Estado de BLE: Advertising
I (34852) BLE: Estado de BLE: Advertising
I (35262) BLE: Estado de BLE: Advertising
I (35262) MAIN: Estado de conexion BLE: sin emparejar
I (35352) BLE: Estado de BLE: Advertising
I (35852) BLE: Estado de BLE: Advertising
I (36352) BLE: Estado de BLE: Advertising
I (36852) BLE: Estado de BLE: Advertising
I (37352) BLE: Estado de BLE: Advertising
I (37852) BLE: Estado de BLE: Advertising
I (38352) BLE: Estado de BLE: Advertising
I (38772) BLE: Estado de BLE: Advertising
I (38772) MAIN: Nuevo registro de hidratacion generado: { water: 981, temp: 18, bat: 38, time: 38}
I (38772) MAIN: Nuevo registro de hidratacion enviado para almacenamiento, total 8
I (38852) BLE: Estado de BLE: Advertising
I (39372) BLE: Estado de BLE: Advertising
I (39872) BLE: Estado de BLE: Advertising
I (40372) BLE: Estado de BLE: Advertising
I (40512) BLE: Estado de BLE: Advertising
I (40512) MAIN: Estado de conexion BLE: sin emparejar
I (40872) BLE: Estado de BLE: Advertising
I (41372) BLE: Estado de BLE: Advertising
I (41872) BLE: Estado de BLE: Advertising
I (42372) BLE: Estado de BLE: Advertising
I (42872) BLE: Estado de BLE: Advertising
I (43372) BLE: Estado de BLE: Advertising
I (43782) BLE: Estado de BLE: Advertising
I (43782) MAIN: Nuevo registro de hidratacion generado: { water: 929, temp: 16, bat: 15, time: 43}
I (43782) MAIN: Nuevo registro de hidratacion enviado para almacenamiento, total 9
I (43872) BLE: Estado de BLE: Advertising
I (44392) BLE: Estado de BLE: Advertising
I (44432) BLE: ESP_GATTS_CONNECT_EVT, conn_id = 0
I (44432) BLE: 56 21 25 a3 99 43
I (44432) BLE: Estado de BLE: Paired
I (44692) BLE: Estado de BLE: Paired
I (44832) BLE: Parámetros de conexión actualizados:
status = 0
min_int = 16
max_int = 32
conn_int = 24
latency = 0
timeout = 400
I (44892) BLE: Estado de BLE: Paired
I (44892) MAIN: Numero de registros almacenados: 5
I (44902) MAIN: Registro obtenido de NVS: (indice 0) { water: 929, temp: 16, bat: 15, time: 43}
W (44902) STORAGE: Error de lectura de NVS (1/4): ESP_ERR_NVS_NOT_FOUND
E (44912) MAIN: Error al recuperar registro desde NVS (ESP_ERR_NVS_NOT_FOUND)
W (44922) STORAGE: Error de lectura de NVS (1/4): ESP_ERR_NVS_NOT_FOUND
E (44922) MAIN: Error al recuperar registro desde NVS (ESP_ERR_NVS_NOT_FOUND)
W (44932) STORAGE: Error de lectura de NVS (1/4): ESP_ERR_NVS_NOT_FOUND
E (44942) MAIN: Error al recuperar registro desde NVS (ESP_ERR_NVS_NOT_FOUND)
I (44942) BLE: Estado de BLE: Paired
I (44952) BLE: Registro convertido a buffers para ser sincronizado: { water: [0XA1,0X3], temp: [0X10,0], bat: 15, time: [0X2B,0,0,0]}
W (44962) STORAGE: Error de lectura de NVS (1/4): ESP_ERR_NVS_NOT_FOUND
E (44972) MAIN: Error al recuperar registro desde NVS (ESP_ERR_NVS_NOT_FOUND)
I (45122) BLE: Parámetros de conexión actualizados:
status = 0
min_int = 0
max_int = 0
conn_int = 6
latency = 0
timeout = 500
W (45212) MAIN: Registro sincronizado, pero no obtenido por cliente, restantes = 1
I (45212) BLE: Registro convertido a buffers para ser sincronizado: { water: [0XA1,0X3], temp: [0X10,0], bat: 15, time: [0X2B,0,0,0]}
I (45262) BLE: Parámetros de conexión actualizados:
status = 0
min_int = 0
max_int = 0
conn_int = 24
latency = 0
timeout = 400
W (45472) MAIN: Registro sincronizado, pero no obtenido por cliente, restantes = 1
I (45472) BLE: Registro convertido a buffers para ser sincronizado: { water: [0XA1,0X3], temp: [0X10,0], bat: 15, time: [0X2B,0,0,0]}
I (45482) BLE: Estado de BLE: Paired
(...)
Frozen-Burrito commented 2 years ago

Otro problema sucede cuando se ha repetido este bug varias veces, donde storage_task recupera el registro de hidratación desde NVS con éxito, pero no puede enviado a xSyncQueue porque la queue está llena. Esto resulta en que errQUEUE_FULL sea retornado por la función xQueueSendToBack.

Frozen-Burrito commented 2 years ago

El problema del comentario anterior también evita que generator_task pueda enviar registros de hidratación para sincronización.

Frozen-Burrito commented 2 years ago

Después de más pruebas y análisis, parece que la causa del problema sí era la forma en que se generan y usan los índices para almacenar/recuperar registros de NVS. Aparentemente, storage_task generaba índices irregularmente, causando que cuando registros con cierto índice fueran leídos de NVS, hubiera la posibilidad de las keys de NVS para el índice dado no hubieran sido escritas.

El problema fue solucionado al cambiar ligeramente la obtención del índice para almacenar:

- lastReceivedRecordIdx = (i + lastReceivedRecordIdx) % MAX_STORED_RECORD_COUNT;
int16_t recordIndex = (i + indexOfLastStoredRecord + 1) % MAX_STORED_RECORD_COUNT;

En vez de modificar la misma variable que es usada para mantener el índice del último registro almacenado, se asigna el resultado a una nueva variable que es usada como índice.

p.d. también arreglé el orden en que son recuperados los registros de NVS. Antes era un orden por índice (con un índice simple de 0 - 5), ahora se recuperan primero los registro con más antigüedad en NVS, con el último siendo el registro más recientemente almacenado.

Frozen-Burrito commented 2 years ago

El problema del comentario anterior también evita que generator_task pueda enviar registros de hidratación para sincronización.

Identifiqué que los problemas que resultan en errQUEUE_FULL son dados por la forma en que pruebo la extensión para botellas: xSyncQueue siempre está llena porque por el momento todavía no se sincronizan los registros por BLE y no son removidos de la queue.

Frozen-Burrito commented 2 years ago

Ya hice más pruebas y me parece que este problema ha quedado solucionado, los índices para los registros de hidratación están implementados correctamente.