昨日の修正でBME680が使えるようになったので、温度と湿度と気圧を測って電圧と一緒にWebサーバーにPOSTするプログラムを書いて放置してみたところ、突然データが送信されないバグに遭遇した。
調査してみたところ、BME680のライブラリがバグってた。
症状
突然プログラムが一切のログも吐かずに動かなくなった。カーネルパニックとかのログもなく。一切動かなくなる。
原因調査
デバッグするための機器をもってないので、昔ながらのprintfデバッグ。片っ端からログ仕込んで、どこまで動いてるのか、どこで止まってるのかを確認。
最終的にたどり着いたのが
static void bme680_delay_ms(uint32_t period)
{
uint32_t start_time = sdk_system_get_time () / 1000;
vTaskDelay((period + portTICK_PERIOD_MS-1) / portTICK_PERIOD_MS);
while (sdk_system_get_time()/1000 - start_time < period)
vTaskDelay (1);
}bmc680.cにあったこの関数。指定時間より若干短めにdelayしたあと、時刻確認しながらdelayを微調整してるっぽい。
ここのwhileにログ仕込んでstart_timeとsdk_system_get_time()/1000の値を出してみたところ
sdk_system_get_time()/1000の値が4294967で固まったまま動かず、ここで無限ループになってた。(Exception云々は、idf.py monitorを止めたときのもの)
続いてsdk_system_get_time()を確認
uint32_t sdk_system_get_time ()
{
struct timeval time;
gettimeofday(&time,0);
return time.tv_sec*1e6 + time.tv_usec;
}これはesp8266_wrapper.cにあった。gettimeofdayで秒とマイクロ秒を取得し、秒を106倍してそれとマイクロ秒を足し算したuint32_tを返してる。
で、それを1000で割ってミリ秒に変換して待ち時間比較に使っている。
ここでちょっと気になってuint32_tの最大値を見てみたら「4294967295」。1000で割ったら「4294967」で固まったときの値と一致する。
「多分これ、オーバーフローして計算できなくなったんかな?」と思い、修正
修正
マイクロ秒を足した値を使おうにも使い物にならないので、方針変更。
gettimeofday()で取得できるtimeval構造体にはそれを計算をする関数があるので、「timeval同士で計算して経過時間を取得してから変換して比較」する方針で修正。
static void bme680_delay_ms(uint32_t period)
{
struct timeval start_timeval, now_timeval, difference_timeval;
gettimeofday(&start_timeval, NULL);
vTaskDelay((period + portTICK_PERIOD_MS-1) / portTICK_PERIOD_MS);
gettimeofday(&now_timeval, NULL);
timersub(&now_timeval, &start_timeval, &difference_timeval);
uint32_t difference_time = (difference_timeval.tv_sec * 1e6 + difference_timeval.tv_usec) / 1000;
while (difference_time < period)
{
vTaskDelay (1);
gettimeofday(&now_timeval, NULL);
timersub(&now_timeval, &start_timeval, &difference_timeval);
difference_time = (difference_timeval.tv_sec * 1e6 + difference_timeval.tv_usec) / 1000;
}
}いまのところこれで2時間は動いた。
余談
秒を106倍してuint32_tの最大値に届くってことは、最大で4294秒までで約1時間11分ちょっと。最初に友人に愚痴ったときは「1時間ちょっとで止まる」だったので、ちゃんと測ってたわけでもないのに意外とあってた。
gettimeofday()は途中で時計が変わると影響を受けたり、そもそもPOSIXで非推奨になったらしい。つまりこれ、NTP実装するとかして動作中にESP32の時計を修正すると、タイミングによってはまたバグる可能性がある。gettimeofdayが非推奨の件は、clock_gettime()で取得するのが推奨されてるらしい。
「オーバーフローして計算できなくなった」と思っているけど、本当にそうかはわからない。アセンブラ読めないし、CPUの仕様も知らないし。ただ、値が進まなくて無限ループしてるのは確かなようだ。
Diff
diff -cr a/bme680/bme680.c b/bme680/bme680.c
*** a/bme680/bme680.c 2023-09-10 17:24:28.864249600 +0900
--- b/bme680/bme680.c 2023-09-11 19:04:30.342671456 +0900
***************
*** 50,55 ****
--- 50,56 ----
#include <string.h>
#include <stdlib.h>
+ #include <sys/time.h>
#include "bme680_platform.h"
#include "bme680.h"
***************
*** 1214,1225 ****
static void bme680_delay_ms(uint32_t period)
{
! uint32_t start_time = sdk_system_get_time () / 1000;
vTaskDelay((period + portTICK_PERIOD_MS-1) / portTICK_PERIOD_MS);
! while (sdk_system_get_time()/1000 - start_time < period)
vTaskDelay (1);
}
--- 1215,1236 ----
static void bme680_delay_ms(uint32_t period)
{
! struct timeval start_timeval, now_timeval, difference_timeval;
! gettimeofday(&start_timeval, NULL);
vTaskDelay((period + portTICK_PERIOD_MS-1) / portTICK_PERIOD_MS);
! gettimeofday(&now_timeval, NULL);
! timersub(&now_timeval, &start_timeval, &difference_timeval);
! uint32_t difference_time = (difference_timeval.tv_sec * 1e6 + difference_timeval.tv_usec) / 1000;
! while (difference_time < period)
! {
vTaskDelay (1);
+
+ gettimeofday(&now_timeval, NULL);
+ timersub(&now_timeval, &start_timeval, &difference_timeval);
+ difference_time = (difference_timeval.tv_sec * 1e6 + difference_timeval.tv_usec) / 1000;
+ }
}