Sougen Blog

Cube J1 から Grafana に送った電力グラフの途切れを減らす

cube-j1echonet-litewi-sunmqttgrafana

前編では、Cube J1 と cube-j1-mqtt でスマートメーターの瞬時電力を取り出し、Grafana に送る構成を書きました。
その最後に、グラフが数十分単位で途切れる問題を予告していました。

手元でブリッジを改造して調べ、取得率は改造前の約 2 割から、いまは約 86% になりました。
改造前は 60 秒間隔で理想が 60 回/h、いまは 30 秒間隔で理想が 120 回/h です。
数字はすべて我が家の 1 台で測ったもので、対策の前後は、別の日の同じ時刻帯をそれぞれ 3 時間ずつ比べています。

この記事では、グラフが途切れる原因の見分け方と本家のブリッジの弱点を説明したあと、本家のコードに当てられる最小の修正と、手元の改造版だけで試した対策を分けて書きます。

途切れる原因の見分け方

グラフが途切れる原因には、MQTT の接続が切れて値が届かない場合と、スマートメーターから値を取れていない場合の 2 つがあります。

1 つ目は Mosquitto のログで分かります。
Cube J1 の接続が exceeded timeout で切られていれば、こちらです。

Client cubej1_cubej1 [<Cube J1 の IP アドレス>:<ポート>] disconnected: exceeded timeout.

2 つ目はブリッジのログで分かります。
本家のブリッジは /data/local/mqtt_bridge.log に時刻付きでログを書いており、メーターの応答を待ちきれなかったときは No ERXUDP response (timeout) という行が出ます。
件数ではなく、ログの時刻をグラフが途切れた時刻と突き合わせます。

adb connect <Cube J1 の IP アドレス>:5555
adb shell grep "No ERXUDP response" /data/local/mqtt_bridge.log | tail -20

我が家では、改造を始めたころは両方が起きていました。
1 つ目は前編で書いたとおり、約 12 分おきに起きていました。

本家のブリッジの弱点

本家の mqtt_bridge.py（commit 3bbb6bf、2026 年 5 月）を読むと、グラフが途切れる原因になる作りが 3 つあります。

3 つ目が、我が家で最も多くの値を失っていた原因でした。

本家のコードに当てられる最小の修正

この節の修正は、本家の commit 3bbb6bf に当てるパッチ mqtt-bridge-reduce-gaps.patch にまとめました。
リポジトリの直下で git apply mqtt-bridge-reduce-gaps.patch を実行すれば当たります。
同じ処理は、改造版で 2026 年 7 月から動かしています。
本文には、応答を読む read_erxudp の断片だけを載せます。
この断片は、実機の Python 2.7.13 で、INF、TID が一致しない応答、Get_SNA、Get_Res の 4 種類の ERXUDP 行を流し、意図どおりに動くことを確かめました。

応答の種類と TID を確かめる

改造版では、応答の TID が一致しないフレームを受け取ると、それを捨てて、その回の応答待ちも終えていました。
取りこぼしの内訳を知るために、この捨てていたフレームを種類（ESV）、TID、届くまでの遅れの 3 つで分類しました。
6 時間に捨てた 66 件のうち、59% は ESV が 0x73（INF）のフレームでした。
INF は、問い合わせへの応答ではなく、メーターが自分から送ってくるプロパティの通知です。
Wi-SUN をつなぎ直すたびに届いており、1 時間あたりの件数は再接続の回数とほぼ同じでした。

本家のブリッジは INF も今回の応答として受け取ります。
本家の parse_el_response は Get_Res（0x72）と Get_SNA（0x52）以外を空として扱うので、INF を受け取ったその回は値を送らずに終わり、本来の応答は読まれません。
改造版で INF を読み飛ばして本来の応答を待ち続けるようにしたところ、変更前の 12.5/h に対して、変更後の 6 時間は 26.2/h（続く夜間の 10 時間は 25.5/h）でした。
タイムアウトは 1 時間あたり約 30 件のまま変わっていません。

下の断片では、TID が送った問い合わせと一致し、ESV が Get_Res か Get_SNA のフレームだけを応答として受け取ります。
TID の照合は、別の fork の nanamitm/cube-j1-mqtt が入れていたものを参考にしました。

ESV_GET_RES = 0x72  # Get への正常な応答
ESV_GET_SNA = 0x52  # Get への応答（要求されたプロパティの一部またはすべてを返せなかった）


def read_erxudp(fd, expected_tid, timeout=15):
    """expected_tid への応答だけを返す。通知 (INF) や遅れた応答は読み飛ばして待ち続ける。"""
    deadline = time.time() + timeout
    while time.time() < deadline:
        line = serial_readline(fd, timeout=max(0.5, deadline - time.time()))
        if line is None or not line.startswith("ERXUDP"):
            continue
        parts = line.split()
        if len(parts) < 9 or not parts[-1].startswith("1081"):
            continue
        try:
            # Python 2.7 の str は添字で 1 文字の str を返すので、bytearray にして整数で比べる
            data = bytearray(binascii.unhexlify(parts[-1].strip()))
        except Exception as e:
            log("ERXUDP hex decode error: {}".format(e))
            continue
        if len(data) < 12:
            continue
        if ((data[2] << 8) | data[3]) != expected_tid:
            continue
        if data[10] not in (ESV_GET_RES, ESV_GET_SNA):
            continue
        return data
    return None

呼び出し側には、TID を進める前の値を渡します。
本家は send_el_get の直後で tid を進めているので、パッチではその行を read_erxudp(fd, tid, timeout=15) のあとに移しています。

いくつか補足します。

タイムアウトしたらつなぎ直す

応答がタイムアウトしたら、Wi-SUN をつなぎ直すようにしました。
連続で何回タイムアウトしたらつなぎ直すかを、2 段階で減らしています。

比較 取得数 長い途切れ
6 回 → 2 回（2026-07-03、同じ日の別の時刻帯の各 3 時間） 17.8/h → 23.3/h 300 秒超の停止 16 回 → 2 回
2 回 → 1 回（2026-07-05 と 07-06 の同じ時刻帯、各 3 時間） 41.3/h → 51.2/h 90 秒超の途切れ 40 件 → 5 件

あわせて、つなぎ直す前の待ちを 30 秒から 5 秒に縮めました。
同じ時刻帯で比べると、取得数は 23.3/h から 28.1/h になりました。
この期間の再接続は 1 時間に約 11 回で、待ちを 25 秒ずつ縮めると、停止時間は 1 時間に約 275 秒減ります。
これを当時の 60 秒間隔で単純に割ると、約 4.6 回分の問い合わせにあたります。
実測の増加（4.8 回/h）はこれと同じくらいでした。

パッチでは、main でタイムアウトが続いた回数を数え、2 回続いたら例外を投げます。
つなぎ直しは、本家にもともとある外側の except Exception に任せます。
回数は、応答が取れたときと外側の except に入ったときに 0 に戻し、つなぎ直す前の待ちは 30 秒から 5 秒にしています。

つなぎ直すまでの回数は、まず 2 回にするのが安全です。
本家の wisun_connect はつなぎ直すたびにすべてのチャネルをスキャンするので、1 回に 30〜40 秒かかります。
また、1 回のタイムアウトでつなぎ直すと、雑音の多い時間帯につなぎ直しが連続することがあります。
我が家で最終的に 1 回まで減らせたのは、後で書く改造版の対策（スキャンを省くつなぎ直しと、雑音の多いときのタイムアウトを数えない仕組み）を先に入れていたからです。
2 回で動かしながら再接続の回数を見て、1 回に減らすかどうかを決めます。

keepalive を延ばす

前編で書いた exceeded timeout の切断は、まず keepalive を 60 秒から 300 秒に延ばして減らしました。
手元では、切断の頻度が約 5 分の 1 になりました。
本家のブリッジでは、MQTTClient.connect が組み立てる CONNECT パケットの可変ヘッダーの末尾に、keepalive の秒数が 2 バイトのビッグエンディアンで書かれています。
パッチでは、ここの b"\x00\x3C"（60 秒）を b"\x01\x2C"（300 秒）に変えています。

本家は、前回の ping から 50 秒を超えていれば問い合わせのあとに ping を送るので、keepalive を 300 秒にしても ping の間隔はそのままです。
延ばしても、つなぎ直しが長引けば 300 秒を超えることはあります。

問い合わせの間隔を 30 秒にする

config.json の poll_interval を 60 から 30 にしました。
取得数は 51.2/h から 98.7/h に増えました。
理想の回数も 60/h から 120/h に倍になるので、取得できた割合で見ると 85% から 82% へわずかに下がっています。

問い合わせを倍にすると、PANA セッションの切断やタイムアウトが増えるかを心配しました。
この比較では、1 時間あたりの再接続は 1.27 倍になり、問い合わせ 1 回あたりのタイムアウトの割合は 24% から 16% になりました。
別の日の測定なので、30 秒にしたことで割合が下がったとまでは言えません。

30 秒より短くはしていません。
Wi-SUN モジュールのコマンドリファレンスには、ARIB STD-T108 に基づく送信時間の総和の制限があり、制限が発動すると EVENT 32 が出て、以後の送信要求がすべてキャンセルされると書かれています。
手元では問い合わせ以外の通信も考えて、経験的に 30 秒を下限にしました。

手元の改造版だけで試した対策

ここからは、改造版で入れた対策です。
コードが長くなるので、考え方と手順だけを書きます。

スキャンを省いてつなぎ直す

前回の接続で得たチャネル、PAN ID、MAC アドレス、メーターの IPv6 アドレスを覚えておきます。
つなぎ直すときは SKSCAN と SKLL64 を省き、次の順にコマンドを送ります。

SKRESET → SKSETPWD（B ルートのパスワード）→ SKSETRBID（認証 ID）
→ SKSREG S2 <チャネル> → SKSREG S3 <PAN ID> → SKJOIN <メーターの IPv6 アドレス>
→ EVENT 25（接続成功）を待つ。EVENT 24（接続失敗）なら失敗

2 回続けて失敗したら、覚えた値を捨ててすべてのチャネルのスキャンに戻します。
65 分の検証で、5 回のつなぎ直しはすべて覚えた値で成功し、1 回にかかる時間は 31〜46 秒から 14〜15 秒になりました。

雑音の多いときのタイムアウトを数えない

Wi-SUN モジュールのエネルギー検出スキャン（ED スキャン）で、2 分おきにメーターが使うチャネルの電波エネルギーを測ります。
値はチャネルごとに 0〜255 で返り、手元では 100 以上を「雑音が多い」とみなしています。
値が高い原因は雑音に限らず、ほかの機器の送信も含まれます。
雑音が多いときのタイムアウトは、つなぎ直すまでの連続回数に数えません。
「1 回のタイムアウトでつなぎ直す」を雑音の多い時間帯でも使えるようにするための仕組みです。

MQTT の送信を別のスレッドに分ける

keepalive を延ばしても、メーターとのやり取りが詰まれば ping は遅れます。
改造版では、MQTT の送信と ping をそれぞれ別のスレッドから行い、どちらもソケットに書き込む前に同じロックを取るようにしました。
ロックを取らずに 2 つのスレッドから書き込むと、パケットが混ざるおそれがあります。
その後は、91 日間で MQTT の再接続が 5 回だけになりました。

効果がなかった対策

試したものの、効果がなかったり取り消したりした対策もあります。

いまの取得率と分かっていないこと

10 月初めの直近 20 日間では、取得数は約 103/h で、理想の 120/h の約 86% です。
残りの欠損の多くは、応答タイムアウトのあとの Wi-SUN の再接続中に起きています。
ただし、タイムアウトの時点で PANA セッションが本当に切れていたかは確かめていません。
再接続は 1 時間に約 21 回起き、そのたびにグラフの値の間隔が普段より延びます。
延びる時間は、速い場合で約 21 秒で、これが 9 割を占めます。
残りの 1 割は 1 回目のつなぎ直しに失敗した場合で、約 92 秒延びます。
平均すると 1 回あたり約 28 秒です。
延びた時間の合計を問い合わせの間隔の 30 秒で割る概算では、1 時間に約 20 回分（21 × 28 ÷ 30 ≈ 19.6）を失います。
問い合わせの時刻とのずれを無視した粗い概算ですが、120 − 20 = 100 で、実測の約 103/h と近い値です。

48 日間、Wi-SUN モジュールの送信結果のイベント（EVENT 21）を約 14 万 7 千件記録し、すべてが送信成功（PARAM=0）でした。
コマンドリファレンスによると、ユニキャストでの PARAM=0 は、送信相手から無線の Ack（受信確認）を受け取ったことを表します。
つまり問い合わせは、少なくともメーターの無線モジュールまでは届いています。
メーターがその問い合わせを処理して応答を送ったかまでは分かりません。
応答が返らない原因が、メーターの中とメーターからの無線のどちらにあるかは、まだ切り分けられていません。
少なくとも、今回試した再送や再接続の工夫では、これ以上大きくは減らせませんでした。

本家のブリッジを使っているなら、まずパッチを当てるのが手軽です。
問い合わせの間隔を 30 秒にするかどうかは、そのあとで取得数を見て決めます。