chakokuのブログ(rev4)

テック・コミック・DTM・・・ごくまれにチャリ

MQTTにPublishするがセッションが維持されない問題

課題:なんとかセンサ情報も取れるようになり、MQTTでThingspeakに計測データを投稿しようとするが、ブチブチ切れる症状が発生
取り組み:エラー原因を調べて、セッションが維持されるようにする。また、これまで動かしていた古いバージョンのアプリでどういう症状だったかも確認
結論:ClientID/UserID/PWDを複数センサで共有していた。先行して接続していたMQTT-ClientがBroker側から切断された(MQTTの仕様に基づく動作)
詳細:
MQTT Clientのログは以下

I (367569) esp-x509-crt-bundle: Certificate validated
I (369769) mqtt_client2: [Que] Event: Connected(session: false)

E (388819) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (388819) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=119
I (388829) mqtt_client2: [Que] Event: Error(ESP_FAIL (error code -1))

E (388839) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
I (388849) mqtt_client2: [Que] Event: Disconnected

I (403849) mqtt_client2: [Que] Event: BeforeConnect

I (404429) esp-x509-crt-bundle: Certificate validated
I (405619) mqtt_client2: [Que] Event: Connected(session: false)
      *繰り返し*

上記ログ中、下記メッセージはMQTT Brokerからの応答を待っているのにブチ切りされているのが原因らしかった。
(ERR_TCP_TRANSPORT_CONNECTION_CLOSED_BY_FIN)

mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF

mqtt_client.rsのソースから抜粋

static int esp_mqtt_handle_transport_read_error(int err, esp_mqtt_client_handle_t client, bool mid_message)
{
    if (err == ERR_TCP_TRANSPORT_CONNECTION_TIMEOUT) {
        if (mid_message) {
            // No error message, because we could've read with timeout 0 (caller will decide)
            return -1;
        }
        // Not an error, continue
        ESP_LOGV(TAG, "%s: transport_read(): call timed out before data was ready!", __func__);
        return 0;
    }

    if (err == ERR_TCP_TRANSPORT_CONNECTION_CLOSED_BY_FIN) {
        ESP_LOGE(TAG, "%s: transport_read(): EOF", __func__);               <<<<<<<<<<<<<<<!!!!!!!
    }

    ESP_LOGE(TAG, "%s: transport_read() error: errno=%d", __func__, errno);
    esp_mqtt_client_dispatch_transport_error(client);
    return -2;
}

esp-mqtt/mqtt_client.c at master · espressif/esp-mqtt · GitHub
ブチきりされる理由は分からないが、session: falseと出ているのが何か関係するかも

I (369769) mqtt_client2: [Que] Event: Connected(session: false)

一つ前の行が、ブローカとTCP接続を確立したログになっているので、ブローカと接続はしたものの、Session維持はしないモードで接続しているということか。。

MqttClientConfiguration in esp_idf_svc::mqtt::client - Rust
MqttClientConfigurationのパラメータの中で、disable_clean_sessionというのがあって、これが何なのか
EMQXのQAより

Clean Session は、セッション状態のライフサイクルを制御するために使用されるフラグ ビットです

disable_clean_session .... クリーンセッションを無効化するフラグ。。。だから、Trueにすると無効になる(Clean Sessionされない)
defaultでTrueかもしれないが、これをTrueに変えてみる

&MqttClientConfiguration {
    disable_clean_session: true,
    crt_bundle_attach: Some(esp_idf_sys::esp_crt_bundle_attach),
    keep_alive_interval: Some(Duration::from_secs(5 * 60)),   // 5min
    client_id: Some(client_id),
    username: Some(client_id),
    password: Some(client_pwd),
    ..Default::default()
},

結果は変わらず。

MQTT Listening for messages
I (4139) mqtt_client2: [Que] Event: BeforeConnect

I (4149) wifi:<ba-add>idx:0 (ifx:0, f8:b7xxxxx), tid:0, ssn:4, winSize:64
Connected to MQTTwait for 10sec
I (4689) esp-x509-crt-bundle: Certificate validated
I (5849) mqtt_client2: [Que] Event: Connected(session: false)

topics: channels/1xxxxxx3/publish
payload: field1=1&field2=2&field3=3&field4=4
I (22639) wifi:<ba-add>idx:1 (ifx:0, f8:b7:xxxxxx), tid:6, ssn:0, winSize:64
E (23049) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (23049) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=119
I (23059) mqtt_client2: [Que] Event: Error(ESP_FAIL (error code -1))

E (23059) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
I (23069) mqtt_client2: [Que] Event: Disconnected

I (33079) mqtt_client2: [Que] Event: BeforeConnect

I (33639) esp-x509-crt-bundle: Certificate validated
I (34929) mqtt_client2: [Que] Event: Connected(session: false)

mqtt_clientのソースを調べて、どこでConnected(session: false)を出しているのか特定しないと何がfalseなのか分からず
他のmqtt client サンプルコードを動かしても、 Event: Connected(session: false) と表示されるが、その後、EOFで切れることがないので、このsession: falseは問題ないと判断。Brokerから切ってくるのが問題というより、何か送るべき情報が不足しているか、接続時のMQTTパラメータで「keep aliveしません」的なオプションを指定しているのが原因ではないかと推測。このレベルになるとパケットキャプチャしないと原因が分からない。
だったら、、ESP32でデバッグせずに、(センサ制御を除いた)MQTTだけをPC上で動かして、どんなパケットを送受信しているか見てみるか。。
根本原因の一つとして、RustによるThread実装が分かっていない。そもそも組み込みプログラミングではシングルスレッドしか作ったことがないので。。。
ThingspeakのFQAより

QoS が 0 に設定されていることを確認します。デバイスによっては、既定の QoS が 0 ではないものがあります。一部のクライアントでは、手動で設定を変更する必要があります。
CleanSession フラグは 0 に設定しないでください。MQTT クライアントで CleanSession フラグを 0 に設定した場合、ThingSpeak™ MQTT ブローカーへの接続要求はすべて拒否され、CONNACK のステータスが "0x05 Connection Refused, not authorized" になります。
ポートが正しいことを確認します。認められているポートのリストは、MQTT クライアントの構成を参照してください。
MQTT クライアントでWillフラグをゼロ以外の値に設定しないでください。ゼロ以外のThingSpeak Will MQTT ブローカーへの接続要求は、CONNACKステータス"0x05 Connection Refused, not authorized"で拒否されます。

MQTT パブリッシュのトラブルシューティング - MATLAB & Simulink - MathWorks 日本
■追記
PCをWiFiのAPとして設定して、ESP32とPC間をWiFiで接続する。ESP上のMQTT Clientを走らせて、PC内でパケットキャプチャする。キャプチャした内容を解析することでMQTT通信の何が悪いのか?が分かるはず。(何か正しくないbitを立ててしまっているか、Brokerからの問い合わせに返答できずにBrokerからFINが送られているか・・・そんなところではなかろうか)
■追記
今回の試作では、正常に動作しているセンサ+ESP32_C3のID/PWDを流用していた。MQTTの仕様としてClientIDが重複した場合、先行して接続している端末との通信は遮断するのが正しい動作らしく、今回の問題はClientIDの使いまわしが原因であった。また、ClientIDについては適当なIDは使えず、Thingspeakでデバイス登録して、ClinetID、UserName, Passwordを発行して、その1セットを指定して認証を通す必要があった(昔そういう操作をしたと思うけど、数年以上前の事なので忘れていた)。ご参考にデバイス登録画面は以下

これにより、セッションが途中で切られる問題は発生しなくなった。(パケットの内容まで調べる必要がなくなって助かった)