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_dominique.m…
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
at_mitsuhiro.yoshida
2022年11月25日 8時24分
吉田です。
はい、基本的には電波状況が悪い為に再接続が発生いたします。
それ以外では、
料金プランによっては、一定時間経過すると一度切断するなどの仕様がある場合もあります。
通信の混み具合、通信事業者の工事などの要因で一定時間連続で繋がらないことはあり得ます。
よろしくお願いします。