世の中には、一見関係なさそうな物理現象がITシステムに不可思議な影響を及ぼすことがあります
例えば,500マイル以上離れた場所にメールが送れないという話だったり
中国人のAさんがお茶を入れると会社のネットが繋がらなくなる
という話があります。
私の場合は、祖母が就寝するとDBインサートが失敗する、という状況でした
実家の見守りシステム
問題が起きているのは、離れた実家にいる一人暮らしの祖母の状態を見守るために作成した自作のシステムです。
気温や湿度、CO2濃度、明るさ、部屋のドアの開閉、冷蔵庫の開閉の状況をモニタリングできるようにしています。
Raspberry Piに各種センサが接続され、定期的にInfluxDBに送信し、Grafanaという可視化ツールでいつでも見られるようにしています。
これらの情報を見ることで、祖母の家の部屋の温度が適切か、活動しているか、部屋にいるかなどが分かります。
データが来てない時間がある
見守りシステムを構築して、たまにモニタリングをしていたのですが、データが存在しない時間帯があることに気づきました。
この画像だと、赤色に示した時間帯はデータが欠損しており、夜の11時から翌日の6時ごろまでデータがありません。
この現象は毎日起きており、データが欠損の開始時刻は夜10~11時ごろから、終了時刻は朝5~6時ごろで
多少の時差はあるものの、ほぼ祖母が就寝している時間と一致していました。
このことから、祖母が寝ている時間だけInfluxDBのインサートに失敗していると捉えました。
原因を考える
前提として、すぐにラズパイなどのログは見ることができません。
実家に構築されており、外部からsshを許可していないので、調査ができませんでした。
最初は、祖母が寝る前にRaspberry Piの電源を落としているのでは？と疑いました。コンピュータの知識がない祖母なら、使ってないのに電源が入っているのは違和感を感じて、電源タップのスイッチを切っているのではないかと思いました。もしくは、Wifiルーターの電源が落ちているのではないかと考えました
しかしその時間帯に全てのセンサーのデータが欠損しているわけではなく、祖母が夜中に起きてトイレに行った時のドアの開閉のデータは送信されていました。
DBにインサートするプログラムは2つあり、
室温、湿度、CO２濃度、照度を送るプログラムAと
ドアの開閉回数を送るプログラムBです。
プログラムBの動作には問題がないようなので、Raspberry PiやWifiルーターの動作には問題はなさそうです。
さらにプログラムAは、各種データをInfluxDBだけではなく、Ambientという無料で使えるIoTデータ可視化サービスにも送信しています。
このデータを見ると、データの欠損する時間はなく、きちんとデータ取得ができていることが分かりました。
センサの不具合という可能性は消えてしましました。
このデータから、祖母が照明を消して寝る時間がはっきりと分かります。
照度が関係してる？
Ambientのデータから、祖母が照明を消して就寝する時間がはっきりと分かります。
照明を消すとほぼ真っ暗になり、照度センサの値は0として観測されていることが分かります。そしてその時間からInfluxDBのインサートができなくなります。
そしてInfluxDBの照度のデータには、照度が0のデータが全く見られません。
すると、この現象が起きるのは、「祖母が就寝したら」ではなく、「照度センサの計測値が0になったら」である可能性があります。
その可能性が出てきたので、他にデータが欠損している時間はないか確認したところ
日没後に祖母が部屋におらず、照明を消しているであろう時間帯があり、その時間はデータが欠損していました。
このことから、「照度センサの計測値が0になった」時にInfluxDBにデータがインサートされないことが分かりました。
ここまで分かりましたが、真相はログを見て確認するしかありません。
実家に帰って答え合わせ
というわけで、年末年始の休みに実家に帰りまして、ラズパイのログを確認しました。
案の定、下記のエラーが出ていました
Reason: Unprocessable Entity
HTTP response headers: HTTPHeaderDict({'Content-Type': 'application/json; charset=utf-8', 'X-Influxdb-Build': 'OSS', 'X-Influxdb-Version': 'v2.7.3', 'X-Platform-Error-Code': 'unprocessable entity', 'Date': 'Sat, 30 Dec 2023 15:20:11 GMT', 'Content-Length': '227'})
HTTP response body: {"code":"unprocessable entity","message":"failure writing points to database: partial write: field type conflict: input field \"lux\" on measurement \"home_environment\" is type integer, already exists as type float dropped=1"}
大事なのはこの部分ですね
field type conflict: input field \"lux\" on measurement \"home_environment\" is type integer, already exists as type float
送られたluxのデータはint型だが、luxとして既にあるデータはfloat型だと言われていますね。
多分普段の照度はfloat型ですが、照度が0の時だけ0というint型になってしまっていることが原因のようです。
照度センサーは、秋月で売られていたtsl2572というセンサーを使っており(今はもう販売終了)
python用のサンプルプログラムが提供されていました。
そのプログラムでは、一定時間ごとに照度をprintするものでしたが、それを改良してモジュール化し
下記のように使って、InfluxDBにwriteしていました
from tsl2572 import Tsl2572
lx = tsl.getLx()
...
...
write_api = write_client.write_api(write_options=SYNCHRONOUS)
data = [
{
"measurement": "home_environment",
"tags": {
"room": "toyama"
},
"fields": {
"temperature": temperature,
"humidity": int(humidity) ,
"pressure": pressure,
"co2":co2,
"lux": lx
}
}
]
write_api.write(bucket=bucket, org="bohemia", record=data)
lx = tsl.getLx()
で取得した照度はおそらくstring型で、jsonに入れるとほとんどの場合float型の形式になりますが、値が0になった場合のみ0.0ではなく0としてint型として認識されてしまい、型の不一致が起きたようです。
解決策として、floatで型変換をしてあげると、照度が0の場合でもインサートできるようになりました
data = [
{
"measurement": "home_environment",
"tags": {
"room": "toyama"
},
"fields": {
"temperature": temperature,
"humidity": int(humidity) ,
"pressure": pressure,
"co2":co2,
"lux": float(lx)
}
}
まとめ
結論としては、
「祖母が寝たらDBインサートできなくなる」
ではなくて、
「夜になり照明が付いていない時間帯に照度センサーの計測値が0になる場合、計測プログラムの出力がINT型になってしまい、FLOAT型で定義されたDBのインサートに失敗する」
というのが真相でした。
祖母は関係ありませんでした。疑ってごめんなさい。
ログが見られればすぐ解決したのでしょうが、セキュリティ上すぐにログを見られなかったので状況から考察したことでこのような一見おかしな状況が観測されたようです。
冒頭の例もそうですが、一見関係なさそうな物理的な現象がITシステムの不具合を引き起こしているように見える現象を表す言葉が欲しいなぁと思いました。誰か考えてください。
類似例
バニラのアイスを買ったときだけ車のエンジンがかからなくなる不思議な現象、その原因は？
「朝7時にインターネットが突然つながらなくなる」という怪奇現象が1年半も続いた村、その原因とは？
余談
近くのレストランに行ってクレジットカードで決済しようとしたら予約の電話がかかってきて
別の店員が子機で電話を始めたのですが、電話してる間はWifiが繋がらなくなって決済ができないので
電話が終わるまで待ってくださいと言われ5分も待たされたのですが、なぜこんなことが起きているのか気になっています