Armadilloフォーラム

connection-recoverでのLTE再接続処理について

r_kawai

2022年11月24日 19時06分

いつもお世話になっております。

LTE環境で動作試験を行った後、/var/log/messagesを確認したところconnection-recoverによる再接続のログ(以下■ログ参照)が頻繁に残っていました。
弊社とは他の環境で別担当者が実施していたため不明点が多いのですが、把握している範囲では以下のような状況とのことです。
・当初はLTE接続した状態でインターネットにアクセスはできていた
・途中でネットワークが切断されることがあった
・現象発生場所での電波強度は不明
・使用したSIMは「BIGLOBEモバイル タイプD」

つきましては、ログについて何点か確認させてください。

・NetworkManagerやpppdの切断ログが出ていますが、connection-recoverで再接続することにより発生している認識でよろしいでしょうか
・電波状況が悪いこと以外で「ttyCommModem ping fail」が発生する要因がありましたらご教示頂けませんでしょうか

情報不足のため分かることは少ないかもしれませんが、再接続が発生する要因について何か思い当たる点などがありましたらご教示頂けますとありがたいです。

■ログ

Nov 11 08:23:54 armadillo user.notice connection-recover: ttyCommModem ping fail
Nov 11 08:23:54 armadillo user.notice connection-recover: ttyCommModem reconnect start... 
Nov 11 08:24:00 armadillo daemon.info NetworkManager[1318]: <info>  [1668122640.0500] agent-manager: agent[0dd92fa9ad237e8d,:1.79/nmcli-connect/0]: agent registered
Nov 11 08:24:00 armadillo daemon.info NetworkManager[1318]: <info>  [1668122640.0547] device (ttyCommModem): disconnecting for new activation request.
Nov 11 08:24:00 armadillo daemon.info NetworkManager[1318]: <info>  [1668122640.0549] device (ttyCommModem): state change: activated -> deactivating (reason 'new-activation', sys-iface-state: 'managed')
Nov 11 08:24:00 armadillo daemon.info NetworkManager[1318]: <info>  [1668122640.0560] manager: NetworkManager state is now DISCONNECTING
Nov 11 08:24:00 armadillo daemon.info dbus-daemon[1256]: [system] Activating service name='org.freedesktop.nm_dispatcher' requested by ':1.0' (uid=0 pid=1318 comm="/usr/sbin/NetworkManager -n") (using servicehelper)
Nov 11 08:24:00 armadillo daemon.info NetworkManager[1318]: <info>  [1668122640.0605] audit: op="connection-activate" uuid="80146e1e-a5c8-45df-b8b4-ccd5ed0d6b67" name="gsm-ttyCommModem" pid=3334 uid=0 result="success"
Nov 11 08:24:00 armadillo daemon.info dbus-daemon[1256]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 11 08:24:01 armadillo daemon.info pppd[1961]: Terminating on signal 15
Nov 11 08:24:01 armadillo daemon.info pppd[1961]: Connect time 68.3 minutes.
Nov 11 08:24:01 armadillo daemon.info pppd[1961]: Sent 894489 bytes, received 5944835 bytes.
Nov 11 08:24:01 armadillo daemon.info [1850]: <info>  [modem0] state changed (connected -> disconnecting)
Nov 11 08:24:01 armadillo auth.notice dbus-daemon[1256]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.0" (uid=0 pid=1318 comm="/usr/sbin/NetworkManager -n") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.8" (uid=0 pid=1961 comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,")
Nov 11 08:24:01 armadillo auth.notice dbus-daemon[1256]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.0" (uid=0 pid=1318 comm="/usr/sbin/NetworkManager -n") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.8" (uid=0 pid=1961 comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,")
Nov 11 08:24:01 armadillo auth.notice dbus-daemon[1256]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.0" (uid=0 pid=1318 comm="/usr/sbin/NetworkManager -n") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.8" (uid=0 pid=1961 comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,")
Nov 11 08:24:01 armadillo daemon.notice pppd[1961]: Connection terminated.
Nov 11 08:24:01 armadillo auth.notice dbus-daemon[1256]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.0" (uid=0 pid=1318 comm="/usr/sbin/NetworkManager -n") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.8" (uid=0 pid=1961 comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,")
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] state changed (disconnecting -> registered)
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0/bearer4] connection #1 finished: duration 4094s, tx: 0 bytes, rx: 0 bytes
Nov 11 08:24:02 armadillo daemon.info pppd[1961]: Exit.
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2090] device (ttyCommModem): state change: deactivating -> disconnected (reason 'new-activation', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.warn dnsmasq[1348]: no servers found in /run/NetworkManager/no-stub-resolv.conf, will retry
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2155] manager: NetworkManager state is now DISCONNECTED
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2166] device (ttyCommModem): Activation: starting connection 'gsm-ttyCommModem' (80146e1e-a5c8-45df-b8b4-ccd5ed0d6b67)
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2189] device (ttyCommModem): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2198] manager: NetworkManager state is now CONNECTING
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2208] device (ttyCommModem): state change: prepare -> need-auth (reason 'none', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info chronyd[1589]: Source 162.159.200.1 offline
Nov 11 08:24:02 armadillo daemon.info chronyd[1589]: Source 129.250.35.250 offline
Nov 11 08:24:02 armadillo daemon.info chronyd[1589]: Source 162.159.200.123 offline
Nov 11 08:24:02 armadillo daemon.info chronyd[1589]: Can't synchronise: no selectable sources
Nov 11 08:24:02 armadillo daemon.info chronyd[1589]: Source 133.243.238.163 offline
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2260] device (ttyCommModem): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] simple connect started...
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (4/8): wait to get fully enabled
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (5/8): register
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (6/8): bearer
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (7/8): connect
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] state changed (registered -> connecting)
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] state changed (connecting -> connected)
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (8/8): all done
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2972] device (ttyCommModem): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2981] modem["ttyCommModem"]: using modem-specified IP timeout: 20 seconds
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.2987] ppp-manager: starting PPP connection
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.3017] ppp-manager: pppd started with pid 3349
Nov 11 08:24:02 armadillo daemon.info pppd[3349]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Nov 11 08:24:02 armadillo daemon.notice pppd[3349]: pppd 2.4.9 started by root, uid 0
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.3200] manager: (ppp0): new Ppp device (/org/freedesktop/NetworkManager/Devices/12)
Nov 11 08:24:02 armadillo daemon.info pppd[3349]: Using interface ppp0
Nov 11 08:24:02 armadillo daemon.notice pppd[3349]: Connect: ppp0 <--> /dev/ttyUSB3
Nov 11 08:24:02 armadillo daemon.info pppd[3349]: CHAP authentication succeeded
Nov 11 08:24:02 armadillo daemon.notice pppd[3349]: CHAP authentication succeeded
Nov 11 08:24:02 armadillo daemon.notice pppd[3349]: Modem hangup
Nov 11 08:24:02 armadillo daemon.notice pppd[3349]: Connection terminated.
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4709] device (ttyCommModem): state change: config -> failed (reason 'ppp-disconnect', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4724] manager: NetworkManager state is now DISCONNECTED
Nov 11 08:24:02 armadillo daemon.warn NetworkManager[1318]: <warn>  [1668122642.4746] device (ttyCommModem): Activation: failed for connection 'gsm-ttyCommModem'
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] state changed (connected -> disconnecting)
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4806] device (ttyCommModem): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4831] policy: auto-activating connection 'gsm-ttyCommModem-1' (c7b2783f-d924-40a8-9288-5c89eed71279)
Nov 11 08:24:02 armadillo user.notice connection-recover: ttyCommModem reconnect fail: 4
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4853] device (ttyCommModem): Activation: starting connection 'gsm-ttyCommModem-1' (c7b2783f-d924-40a8-9288-5c89eed71279)
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4856] device (ttyCommModem): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4866] manager: NetworkManager state is now CONNECTING
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4874] device (ttyCommModem): state change: prepare -> need-auth (reason 'none', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info NetworkManager[1318]: <info>  [1668122642.4905] device (ttyCommModem): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] simple connect started...
Nov 11 08:24:02 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (4/8): wait to get fully enabled
Nov 11 08:24:03 armadillo daemon.info pppd[3349]: Exit.
Nov 11 08:24:03 armadillo auth.notice dbus-daemon[1256]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.0" (uid=0 pid=1318 comm="/usr/sbin/NetworkManager -n") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.81" (uid=0 pid=3349 comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,")
Nov 11 08:24:03 armadillo daemon.info [1850]: <info>  [modem0] state changed (disconnecting -> registered)
Nov 11 08:24:03 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (5/8): register
Nov 11 08:24:03 armadillo daemon.info [1850]: <info>  [modem0/bearer5] connection #1 finished: duration 1s, tx: 0 bytes, rx: 0 bytes
Nov 11 08:24:03 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (6/8): bearer
Nov 11 08:24:03 armadillo daemon.info [1850]: <info>  [modem0] simple connect state (7/8): connect
ファイル ファイルの説明
message0.log
コメント

at_mitsuhiro.yoshida

2022年11月25日 8時24分

吉田です。

はい、基本的には電波状況が悪い為に再接続が発生いたします。

それ以外では、
料金プランによっては、一定時間経過すると一度切断するなどの仕様がある場合もあります。
通信の混み具合、通信事業者の工事などの要因で一定時間連続で繋がらないことはあり得ます。

よろしくお願いします。

at_dominique.m…

2022年11月25日 8時26分

r_kawaiさん

お世話になっています、マルティネです。

> ・NetworkManagerやpppdの切断ログが出ていますが、connection-recoverで再接続することにより発生している認識でよろしいでしょうか

はい、これであっています。
ログファイルを確認したところ、ping が通らない状態になった時には再接続も何回か失敗しています(「connection-recover: ttyCommModem reconnect fail」のエラー)。恐らくその時に電波の状態が悪かったと思います。
最終的にはエラーせずに再び接続できたので、無事に動作しているようにみえます。

設定可能なパラメターもいくつかありますので、G4の製品マニュアルの「7.1.5.9. 3G/LTE再接続サービス」を参考にしてください:
https://manual.atmark-techno.com/armadillo-iot-g4/armadillo-iotg-g4_pro…

> ・電波状況が悪いこと以外で「ttyCommModem ping fail」が発生する要因がありましたらご教示頂けませんでしょうか

デフォルトでは 120秒毎に 8.8.8.8 に 1秒を挟んだ 10つの ping を送っています。そのすべてが通らなかった場合は「ping fail」のメッセージとともにネットワークを再接続させます。
8.8.8.8 が失敗する可能性がとても低いので、10秒続いて接続できないのは電波状態以外はあまりないと思います。

よろしくお願いします。

r_kawai

2022年11月25日 10時33分

吉田様、マルティネ様

本件の現象はG4起因ではなく、電波状態や通信事業者等の外部要因の可能性が高い旨承知いたしました。
お忙しいところご回答いただきありがとうございました。