Armadilloフォーラム

アプリケーションで通信エラーが発生する。また、復帰にかかる時間が長い。

tsukasa.arita.ye

2023年9月29日 12時16分

LTEモデムを通して、HTTP通信を定周期(10秒に1回程度)で行うアプリケーションを作成しました。(Podmanコンテナ)

そのアプリケーションで通信エラー(HTTPSConnectionPool  Read timed out.)が発生してる時間が20分以上あり、原因を探っています。
添付のログファイル(230913_NetworkManager_State.txt)のNetworkManager stateが[CONNECTED_LOCAL、CONNECTING]の間に通信エラーが出ており原因の一つかと思っております。

①CONNECTED_LOCAL、CONNECTINGのときに端末はどういう状態なのか分かるでしょうか?
②復帰に20分以上かかるものでしょうか?

ファイル ファイルの説明
20230913_messages.txt 端末ログ(var/log/messages)
20230913_NetworkManager_State.txt 端末ログ(var/log/messages)からNetworkManagerのStateだけ抜き出したもの
コメント

at_mitsuhiro.yoshida

2023年10月6日 16時33分

吉田です。

ご迷惑をおかけしております。

> ①CONNECTED_LOCAL、CONNECTINGのときに端末はどういう状態なのか分かるでしょうか?

NetworkManager のソースコードより以下のとおりです。

 * @NM_STATE_CONNECTING: A network connection is being started
 *    The graphical shell should indicate the network is being connected while
 *    the applications should still make no attempts to connect the network.
 * @NM_STATE_CONNECTED_LOCAL: There is only local IPv4 and/or IPv6 connectivity,
 *    but no default route to access the Internet. The graphical shell should
 *    indicate no network connectivity.

> ②復帰に20分以上かかるものでしょうか?

ログを確認したところ LTE の再接続を行おうとして切断処理を実施している際に pppd が終了しきれてない状態で、
再度接続を行おうとして再接続に失敗しております。
現在原因解析しておりますが、現象の再現に難航しております。

tsukasa.arita.ye

2023年11月13日 19時53分

> 吉田です。
>
> ご迷惑をおかけしております。
>
> > ①CONNECTED_LOCAL、CONNECTINGのときに端末はどういう状態なのか分かるでしょうか?
>
> NetworkManager のソースコードより以下のとおりです。
>

>  * @NM_STATE_CONNECTING: A network connection is being started
>  *    The graphical shell should indicate the network is being connected while
>  *    the applications should still make no attempts to connect the network.
>  * @NM_STATE_CONNECTED_LOCAL: There is only local IPv4 and/or IPv6 connectivity,
>  *    but no default route to access the Internet. The graphical shell should
>  *    indicate no network connectivity.
> 

>
> > ②復帰に20分以上かかるものでしょうか?
>
> ログを確認したところ LTE の再接続を行おうとして切断処理を実施している際に pppd が終了しきれてない状態で、
> 再度接続を行おうとして再接続に失敗しております。
> 現在原因解析しておりますが、現象の再現に難航しております。

/etc/ppp/optionsにdebugを追加してログ出力をおこなっているのですが、現状20分以上の通信不通の状態が再現できない状況です。
2分程度、通信ができない状態のログですが念のため、添付いたします。

podman上のプログラムでは
Nov 10 13:31:24  ~ Nov 10 13:33:22 の期間に通信エラーが発生していたようです。

引き続き、20分以上通信ができない状況のログが取得できないか動作させてみます。

ファイル ファイルの説明
20231110_messages.txt 端末ログ(var/log/messages) debug設定
20231110_NetworkManager_State.txt 端末ログ(var/log/messages)からNetworkManagerのStateだけ抜き出したもの

tsukasa.arita.ye

2023年11月14日 10時02分

> > 吉田です。
> >
> > ご迷惑をおかけしております。
> >
> > > ①CONNECTED_LOCAL、CONNECTINGのときに端末はどういう状態なのか分かるでしょうか?
> >
> > NetworkManager のソースコードより以下のとおりです。
> >

> >  * @NM_STATE_CONNECTING: A network connection is being started
> >  *    The graphical shell should indicate the network is being connected while
> >  *    the applications should still make no attempts to connect the network.
> >  * @NM_STATE_CONNECTED_LOCAL: There is only local IPv4 and/or IPv6 connectivity,
> >  *    but no default route to access the Internet. The graphical shell should
> >  *    indicate no network connectivity.
> > 

> >
> > > ②復帰に20分以上かかるものでしょうか?
> >
> > ログを確認したところ LTE の再接続を行おうとして切断処理を実施している際に pppd が終了しきれてない状態で、
> > 再度接続を行おうとして再接続に失敗しております。
> > 現在原因解析しておりますが、現象の再現に難航しております。
>
> /etc/ppp/optionsにdebugを追加してログ出力をおこなっているのですが、現状20分以上の通信不通の状態が再現できない状況です。
> 2分程度、通信ができない状態のログですが念のため、添付いたします。
>
> podman上のプログラムでは
> Nov 10 13:31:24  ~ Nov 10 13:33:22 の期間に通信エラーが発生していたようです。
>
> 引き続き、20分以上通信ができない状況のログが取得できないか動作させてみます。

40分以上通信ができなかったときのログが取得できたので添付しました。

podman上のプログラムでは
Nov 13 22:30:00 ~ Nov 13 23:11:06 の期間に通信エラーが発生していました。

ファイル ファイルの説明
20231113_messages.txt 端末ログ(var/log/messages) debug設定
20231113_NetworkManager_State.txt 端末ログ(var/log/messages)からNetworkManagerのStateだけ抜き出したもの

at_mitsuhiro.yoshida

2023年11月17日 9時28分

吉田です。

ログのご提供ありがとうございます、再現が難しいので助かります。

原因としては ppp 終了時に対向からの応答が無く pppd が終了しきれずに再接続を開始して
上手く接続出来ない様な状況となっていると思われますので、
そこに対して対処を追加する方向で実装・動作確認を実施しています。

対応に時間がかかっており申し訳ありませんが、よろしくお願いします。

tsukasa.arita.ye

2023年11月20日 9時36分

> 吉田です。
>
> ログのご提供ありがとうございます、再現が難しいので助かります。
>
> 原因としては ppp 終了時に対向からの応答が無く pppd が終了しきれずに再接続を開始して
> 上手く接続出来ない様な状況となっていると思われますので、
> そこに対して対処を追加する方向で実装・動作確認を実施しています。
>
> 対応に時間がかかっており申し訳ありませんが、よろしくお願いします。

返信ありがとうございます。
大体で良いのですが、どれぐらいの時期に対応完了(OSアップデート)となるでしょうか?

at_mitsuhiro.yoshida

2023年11月28日 16時49分

吉田です。

> 返信ありがとうございます。
> 大体で良いのですが、どれぐらいの時期に対応完了(OSアップデート)となるでしょうか?

現在テスト版を作成し、動作検証中です。
問題がなければ 12 月のアップデートでリリースいたします。

よろしくお願いします。

at_mitsuhiro.yoshida

2023年12月27日 11時27分

吉田です。

12 月の製品アップデートにてワークアラウンドを追加したものをリリースしました。
よろしくお願いします。

tsukasa.arita.ye

2024年1月4日 17時36分

> 吉田です。
>
> 12 月の製品アップデートにてワークアラウンドを追加したものをリリースしました。
> よろしくお願いします。

ご対応まことにありがとうございます。本年もよろしくお願いいたします。

早速、Armadillo Base OSのアップデートを行いたいのですが、アップデート元(3.16.2-at.5)から(3.18.5-at.8)にアップデートする際に簡単な手順等ありますでしょうか?
(できれば、すでにコンテナ起動中のPythonアプリはそのままでアップデート出来ると良いのですが)

at_mitsuhiro.yoshida

2024年1月5日 9時58分

吉田です。

> 早速、Armadillo Base OSのアップデートを行いたいのですが、アップデート元(3.16.2-at.5)から(3.18.5-at.8)に
> アップデートする際に簡単な手順等ありますでしょうか?
> (できれば、すでにコンテナ起動中のPythonアプリはそのままでアップデート出来ると良いのですが)

簡単なのは USB メモリのルートディレクトリに最新の Armadillo Base OS の SWU をコピーして Armadillo に挿す手順です。
設定内容などは残ったまま、Armadillo Base OS のみがアップデートされます。

最新の Armadillo Base OS の SWU は以下に存在します。
https://armadillo.atmark-techno.com/resources/software/armadillo-iot-a6…

アップデート手順は、
製品マニュアル「SWU イメージのインストール」に説明があります。
https://manual.atmark-techno.com/armadillo-iot-a6e/armadillo-iotg-a6e_p…

tsukasa.arita.ye

2024年1月9日 16時12分

返信ありがとうございます。

アップデートが完了して、動作確認しているところですが
通信できていない時間帯(※1分程度ですが)があり、念のため動作ログを確認いただけないでしょうか?
該当する時間帯は「2024/1/8 9:09:55 ~ 9:11:03」です。

ファイル ファイルの説明
20240109_messages.txt 端末ログ(var/log/messages)
20240109_NetworkManager_State.txt 端末ログ(var/log/messages)からNetworkManagerのStateだけ抜き出したもの

at_mitsuhiro.yoshida

2024年1月11日 17時11分

吉田です。

ログを確認しました。
一旦切断されていますが、その後再接続しておりますので問題はないです。

tsukasa.arita.ye

2024年1月11日 18時55分

2024/1/10 に1分以上データが送信できていない期間を以下にまとめました。

別途アプリケーション内で出しているログでは、回線品質(SignalQuality)も80~87だったため、
頻繁にデータが送信できなくなっている原因を知りたいです。

(A):データの送信ができていなかった期間
(B):データの送信ができていた直近の時刻
-------------
(A) (B)
0:01:43 2024/1/10 14:26:03
0:01:21 2024/1/10 14:24:42
0:03:42 2024/1/10 14:20:59
0:01:03 2024/1/10 14:18:37
0:02:26 2024/1/10 13:40:21
0:01:44 2024/1/10 13:05:43
0:02:02 2024/1/10 12:56:02
0:01:23 2024/1/10 12:54:39
0:02:12 2024/1/10 12:52:10
0:02:24 2024/1/10 12:49:28
0:02:04 2024/1/10 12:46:09
0:01:02 2024/1/10 12:45:07
0:01:36 2024/1/10 9:54:09
0:01:21 2024/1/10 9:25:28
0:02:04 2024/1/10 9:17:04
0:01:32 2024/1/10 9:08:30
0:04:46 2024/1/10 9:01:16
0:01:22 2024/1/10 8:59:50
0:03:06 2024/1/10 8:45:38 ※次にデータを送信できていたのが 2024/1/10 8:48:43 という意味です。
-----------------------

ファイル ファイルの説明
20240111_messages.txt 端末ログ(var/log/messages)

at_mitsuhiro.yoshida

2024年1月16日 16時55分

吉田です。

添付いただいたログを確認したところ、再接続サービスにて ping 導通の NG を検出して再接続を行っており、その期間通信ができなくなっています。
再接続サービスでは、ping にて確認を実施してるため、電波品質以外にも通信経路上の問題によっても LTE の再接続を実施いたします。

Armadillo 側で出来る対策としては、
製品マニュアル 「LTE モデム EMS31-J 省電力などの設定 (Cat.M1 モデル)」に記載しております、
https://manual.atmark-techno.com/armadillo-iot-a6e/armadillo-iotg-a6e_p…
サスペンドの有効無効、Power Save Mode の設定、eDRX の設定を全て disable にし、
出来るだけ LTE モジュールが稼働している状態を継続するようにします。

tsukasa.arita.ye

2024年1月18日 12時13分

回答ありがとうございます。

>再接続サービスでは、ping にて確認を実施してるため、電波品質以外にも通信経路上の問題によっても LTE の再接続を実施いたします。
通信経路上の問題とは具体的にどういった内容でしょうか?

また、いったんArmadilloの省電力設定をdisableにしてみて動作をみているところですが、他に要因、設定変更で改善できそうであれば教えていただきたいです。

(A):データの送信ができていなかった期間
(B):データの送信ができていた直近の時刻
-------------
(A) (B)
0:01:14 2024/1/17 21:09:54
0:02:35 2024/1/17 17:24:23
0:01:01 2024/1/17 17:22:40
0:01:41 2024/1/17 17:20:39
0:01:16 2024/1/17 9:11:03
-------------

ファイル ファイルの説明
20240118_messages.txt 端末ログ(var/log/messages)

at_mitsuhiro.yoshida

2024年1月26日 15時51分

吉田です。

ping にて導通確認を実施しておりますが、多機種含めて通信に問題が無い場合、
3 日以上再接続が発生せず通信を継続しているのを確認しておりますので、
ping での導通確認を採用しております。

ems31-boot 以外で、省電力モードへ移行する要因として AT コマンドで
"AT^SPOW: Set UART Mode and SLEEP Mode on UART"
がありますので、これも無効となる様に設定していただけますでしょうか。
以下のコマンドになります。

armadillo:~# send-at /dev/ttyMux2 AT^SPOW? echo ems31

at_mitsuhiro.yoshida

2024年1月26日 15時58分

吉田です。

失礼しました、以下のコマンドとなります。

armadillo:~# send-at /dev/ttyMux2 AT^SPOW=1,0 echo ems31

tsukasa.arita.ye

2024年1月30日 11時49分

返信ありがとうございます。

頂いたコマンドを実行(2024/01/29 11:50ごろ)して「OK」の応答を確認したのですが、LTE接続に関しては、あまり変化は見られないです。
端末の再起動等必要でしょうか?

(A):データの送信ができていなかった期間
(B):データの送信ができていた直近の時刻
-------------
(A) (B)
0:01:14 2024/1/29 18:54:49
0:02:02 2024/1/29 18:33:22
0:03:21 2024/1/29 18:26:48
0:01:04 2024/1/29 12:37:22
0:01:06 2024/1/29 12:14:39
※コマンド実行
0:03:56 2024/1/29 10:52:32
0:01:07 2024/1/29 10:49:16
0:07:06 2024/1/29 10:38:38
0:03:09 2024/1/29 9:42:14
0:01:08 2024/1/29 9:41:07
0:01:13 2024/1/29 8:49:47
0:01:24 2024/1/29 8:42:25
-------------

ファイル ファイルの説明
20240130_messages.txt 端末ログ(var/log/messages)

at_mitsuhiro.yoshida

2024年1月30日 12時39分

吉田です。

LTE モジュールの再起動などは不要です。

12 時台と 18 時台に周辺環境に変化ありますでしょうか。
人通りが増えるなど。

tsukasa.arita.ye

2024年1月31日 17時26分

返信ありがとうございます。

>12 時台と 18 時台に周辺環境に変化ありますでしょうか。
機器自体は、弊社オフィス内に設置しておりまして、大きな変化はないと考えております。
他の日の通信不可の期間を調査してみても時間帯による傾向はないように思います。

 
また以前回答いただいた「再接続サービスでは、ping にて確認を実施してるため、電波品質以外にも通信経路上の問題によっても LTE の再接続を実施いたします。」
とのことですが、スマホで言うところの「パケットロス」みたいな状況の可能性があるということでしょうか?
それともping先に問題があるイメージでしょうか?

at_mitsuhiro.yoshida

2024年2月2日 17時23分

吉田です。

> >12 時台と 18 時台に周辺環境に変化ありますでしょうか。
> 機器自体は、弊社オフィス内に設置しておりまして、大きな変化はないと考えております。
> 他の日の通信不可の期間を調査してみても時間帯による傾向はないように思います。

ご連絡ありがとうございます。
私がテストしていると、外の人通りが多い 9 時台と 17 時台に
再接続が発生していることが多いので確認いたしました。

> また以前回答いただいた「再接続サービスでは、ping にて確認を実施してるため、電波品質以外にも通信経路上の問題によっても LTE の再接続を実施いたします。」
> とのことですが、スマホで言うところの「パケットロス」みたいな状況の可能性があるということでしょうか?
> それともping先に問題があるイメージでしょうか?

物理レイヤから IP レイヤまでの通信確認として ping を利用しております。
ModemManager としては connected 状態でも、
経路上の問題で通信ができないケースもあります。

また、再度 LTE モジュールメーカーに常時通信を行う上での設定を確認をしております。
何か有益な情報がございましたら、情報展開や標準ソフトウェアへの実装をいたします。