h_i
2024年8月8日 16時39分
現在、node-eyeに複数台の接続を行っているのですが、node-eyeの画面上、すべて切断状態となりました。
そのうちの1台の/var/log/syslogを確認すると、下記のログを最後に"armsd"のログが出力されていませんでした。
heartbeatの送信が途切れたため、切断状態になっていると思われます。
Aug 7 03:11:23 armadillo armsd[2259]: log callback: 200 - Sent heartbeat to XXX.XXX.XXX.XXX
Aug 7 03:11:23 armadillo armsd[2259]: log callback: 200 - Sent heartbeat to XXX.XXX.XXX.XXX
psコマンドで確認すると、armsdは起動しております。
root@armadillo:/var/log# ps aux | grep armsd
root 2259 0.0 0.3 5064 3952 ? Ss 8月02 0:13 /usr/sbin/armsd
armsdのheartbeatが途切れた原因を調査したいのですが、どのような方法がありますでしょうか。
コメント
h_i
> 原因切り分けのため、お手数ですが
> node-eye に接続している Armadillo の nmcli connection を送付いただけますでしょうか。
> また、systemctl status node-eye.service を確認し、サービスが動作しているかご確認いただけますでしょうか。
>
> 以上です。
大塩様
ご回答ありがとうございます。
切断が再現しましたので、その状態のnmcli connectionおよび、systemctl status node-eye.serviceの状態を記載いたします。
■nmcli
nmcli connection
NAME UUID TYPE DEVICE
armsd_connection_eth0 3d554a21-4ba1-443d-9e24-d1e0c021f064 ethernet eth0
armsd_connection_wwan c182f306-f244-4764-ab9b-fe784ae2259b gsm ttyUSB2
gw-lan-config db0c773f-7d47-497a-8b44-6e0cef378523 ethernet --
gw-sim-config 62d77ed7-d81b-4dc6-9dfe-1a47dc043dbb gsm --
■systemctl
root@armadillo:/home/sems/log# systemctl status node-eye.service
● node-eye.service - node-eye client
Loaded: loaded (/lib/systemd/system/node-eye.service; enabled; vendor preset:
Active: active (running) since Thu 2019-02-14 19:12:20 JST; 5 years 6 months
Docs: https://node-eye.com
Process: 2047 ExecStart=/usr/sbin/exec-armsd (code=exited, status=0/SUCCESS)
Main PID: 2344 (armsd)
Memory: 2.2M
CGroup: /system.slice/node-eye.service
mq2344 /usr/sbin/armsd
8月 18 07:35:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:35:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:40:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:40:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:45:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:45:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:50:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:50:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:55:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
8月 18 07:55:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> > 原因切り分けのため、お手数ですが
> > node-eye に接続している Armadillo の nmcli connection を送付いただけますでしょうか。
> > また、systemctl status node-eye.service を確認し、サービスが動作しているかご確認いただけますでしょうか。
> >
> > 以上です。
大塩様
お世話になっております。
上記の件、ご確認の状況はいかがでしょうか。
>
> 大塩様
> ご回答ありがとうございます。
>
> 切断が再現しましたので、その状態のnmcli connectionおよび、systemctl status node-eye.serviceの状態を記載いたします。
>
> ■nmcli
> nmcli connection
> NAME UUID TYPE DEVICE
> armsd_connection_eth0 3d554a21-4ba1-443d-9e24-d1e0c021f064 ethernet eth0
> armsd_connection_wwan c182f306-f244-4764-ab9b-fe784ae2259b gsm ttyUSB2
> gw-lan-config db0c773f-7d47-497a-8b44-6e0cef378523 ethernet --
> gw-sim-config 62d77ed7-d81b-4dc6-9dfe-1a47dc043dbb gsm --
>
> ■systemctl
> root@armadillo:/home/sems/log# systemctl status node-eye.service
> ● node-eye.service - node-eye client
> Loaded: loaded (/lib/systemd/system/node-eye.service; enabled; vendor preset:
> Active: active (running) since Thu 2019-02-14 19:12:20 JST; 5 years 6 months
> Docs: https://node-eye.com
> Process: 2047 ExecStart=/usr/sbin/exec-armsd (code=exited, status=0/SUCCESS)
> Main PID: 2344 (armsd)
> Memory: 2.2M
> CGroup: /system.slice/node-eye.service
> mq2344 /usr/sbin/armsd
>
> 8月 18 07:35:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:35:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:40:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:40:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:45:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:45:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:50:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:50:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:55:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
> 8月 18 07:55:04 armadillo armsd[2344]: log callback: 200 - Sent heartbeat to 20
>
at_syunya.ohshio
at_syunya.ohshio
大塩です。
> 現在、双方のコネクションとも利用しております。
> eth：ローカルネットワーク
> wwan：node-eye、外部通信用
上記情報ありがとうございます。
現状での情報にて、ご確認頂きたい内容が2点あります。
1. wwan のみを使用した状態で、node-eyeのハートビートが切断される現象が発生するか
2. eth wwan 両方使用している状態でハートビートが送られない状態が発生した場合、systemctl restart node-eye.service を行うことで再びハートビートが送られるようになるか
以上です。
h_i
大塩様
> 1. wwan のみを使用した状態で、node-eyeのハートビートが切断される現象が発生するか
ご連絡が滞っており、申し訳ございません。
上記の内容を検証いたしました。
結果としては、wwanのみを利用した状態で、ハートビートによる切断が発生しました。
（eth：ローカルネットワーク はLANケーブルを抜いた状態としております。）
■node-eye
2024/09/06 03:00:06
Heartbeatによる切断通知
■systemctl status node-eye.service
9月 06 02:20:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:20:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:25:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:25:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:30:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:30:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:35:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:35:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:40:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
9月 06 02:40:47 armadillo armsd[2246]: log callback: 200 - Sent heartbeat to 20
at_syunya.ohshio
大塩です。
ご確認ありがとうございます。
> 結果としては、wwanのみを利用した状態で、ハートビートによる切断が発生しました。
これまで頂いた情報から、wwan が切断状態になりハートビート送信失敗が連続して続いた場合に発生しているように見えます。
wwan が長時間切断状態となっているかどうかはこれまでの情報からは不明ですが、少なくともハートビート送信失敗のログから20分以上は切断状態になっていると思います。
現象発生時、"nmcli device" で wwan の通信状態をご確認いただけますでしょうか。
おそらく armsd_connection_wwan の接続状態が切断になっていると思います。
これにより、原因が wwan 側か node-eye service 側かを切り分けることが出来ると思っています。
以上です。
大塩様
> 現象発生時、"nmcli device" で wwan の通信状態をご確認いただけますでしょうか。
> おそらく armsd_connection_wwan の接続状態が切断になっていると思います。
>
> これにより、原因が wwan 側か node-eye service 側かを切り分けることが出来ると思っています。
上記の件、ご連絡ありがとうございます。
現状のコマンド結果を記載いたします。
wwan側は接続しており、node-eye serviceのheartbeatログが出ていない状態と見受けられます。
■コマンド結果
root@armadillo:~# nmcli device
DEVICE TYPE STATE CONNECTION
ttyUSB2 gsm 接続済み armsd_connection_wwan
eth0 ethernet 接続済み armsd_connection_eth0
gre0 iptunnel 管理無し --
gretap0 iptunnel 管理無し --
ip6gre0 iptunnel 管理無し --
ip6tnl0 iptunnel 管理無し --
sit0 iptunnel 管理無し --
tunl0 iptunnel 管理無し --
lo loopback 管理無し --
ppp0 ppp 管理無し --
root@armadillo:~# systemctl status node-eye.service
● node-eye.service - node-eye client
Loaded: loaded (/lib/systemd/system/node-eye.service; enabled; vendor preset:
Active: active (running) since Thu 2019-02-14 19:12:20 JST; 5 years 7 months
Docs: https://node-eye.com
Process: 2128 ExecStart=/usr/sbin/exec-armsd (code=exited, status=0/SUCCESS)
Main PID: 2246 (armsd)
Memory: 1.7M
CGroup: /system.slice/node-eye.service
mq2246 /usr/sbin/armsd
Warning: Journal has been rotated since unit was
at_syunya.ohshio
大塩です。
> 現状のコマンド結果を記載いたします。
> wwan側は接続しており、node-eye serviceのheartbeatログが出ていない状態と見受けられます。
>
> ■コマンド結果
>
> root@armadillo:~# nmcli device
> DEVICE TYPE STATE CONNECTION
> ttyUSB2 gsm 接続済み armsd_connection_wwan
> eth0 ethernet 接続済み armsd_connection_eth0
> gre0 iptunnel 管理無し --
> gretap0 iptunnel 管理無し --
> ip6gre0 iptunnel 管理無し --
> ip6tnl0 iptunnel 管理無し --
> sit0 iptunnel 管理無し --
> tunl0 iptunnel 管理無し --
> lo loopback 管理無し --
> ppp0 ppp 管理無し --
> root@armadillo:~# systemctl status node-eye.service
> ● node-eye.service - node-eye client
> Loaded: loaded (/lib/systemd/system/node-eye.service; enabled; vendor preset:
> Active: active (running) since Thu 2019-02-14 19:12:20 JST; 5 years 7 months
> Docs: https://node-eye.com
> Process: 2128 ExecStart=/usr/sbin/exec-armsd (code=exited, status=0/SUCCESS)
> Main PID: 2246 (armsd)
> Memory: 1.7M
> CGroup: /system.slice/node-eye.service
> mq2246 /usr/sbin/armsd
>
> Warning: Journal has been rotated since unit was
ログの送付ありがとうございます。
wwan の接続が原因でない場合、node-eye サービスの再起動でハートビートは復活するでしょうか。
以下コマンドでサービスのリスタートが出来るので、現象発生時にコマンドを実行して現象が解消するかどうかご確認いただけますでしょうか。
systemctl restart node-eye.service
以上です。
h_i
大塩様
> ログの送付ありがとうございます。
> wwan の接続が原因でない場合、node-eye サービスの再起動でハートビートは復活するでしょうか。
> 以下コマンドでサービスのリスタートが出来るので、現象発生時にコマンドを実行して現象が解消するかどうかご確認いただけますでしょうか。
>
> systemctl restart node-eye.service >
上記の件、ご連絡ありがとうございます。
node-eye.service をリスタートしました。
リスタート後にはハートビートが再開され、node-eyeのサイトが接続状態となりました。
ちなみに他のarmadilloで同様の現象が発生しているなど、情報はございますでしょうか。
■リスタート後のログ
root@armadillo:~# systemctl status node-eye.service
● node-eye.service - node-eye client
Loaded: loaded (/lib/systemd/system/node-eye.service; enabled; vendor preset:
Active: active (running) since Tue 2024-10-01 09:50:55 JST; 1min 8s ago
Docs: https://node-eye.com
Process: 20036 ExecStart=/usr/sbin/exec-armsd (code=exited, status=0/SUCCESS)
Main PID: 20074 (armsd)
Memory: 3.2M
CGroup: /system.slice/node-eye.service
mq20074 /usr/sbin/armsd
10月 01 09:51:13 armadillo armsd[20074]: log callback: 80 - Start heartbeat (int
10月 01 09:51:13 armadillo armsd[20074]: log callback: 82 - heartbeat server: 2
10月 01 09:51:13 armadillo armsd[20074]: log callback: 82 - heartbeat server: 2
10月 01 09:51:13 armadillo armsd[20074]: log callback: 200 - [98323202] End push
10月 01 09:51:13 armadillo armsd[20074]: log callback: 200 - Sent confirmation r
10月 01 09:51:13 armadillo armsd[20074]: log callback: 200 - Sent heartbeat to 2
10月 01 09:51:13 armadillo armsd[20074]: log callback: 200 - Sent heartbeat to 2
10月 01 09:51:13 armadillo armsd[20074]: log callback: 200 - new SSL connection
10月 01 09:51:13 armadillo armsd[20074]: log callback: 200 - [-] Start push-conf
10月 01 09:51:13 armadillo armsd[20074]: log callback: 200 - [-] End push-confir
at_syunya.ohshio
at_koseki
古関です。
大塩に代わりまして私の方から対応いたします。
回答が遅くなっており申し訳ありません。
進め方として、ワークアラウンド等で、とりあえずheartbeatを途切れ無くしつつ、
原因特定や別の対策を進める形でよいでしょうか？
問題切り分け・原因特定のために、いくつか教えてください。
以下のログについて
> h_i 2024年9月30日 16時35分
> root@armadillo:~# systemctl status node-eye.service
> ● node-eye.service - node-eye client
> ・・・
> Warning: Journal has been rotated since unit was
Warningのログが途中で切れていますが、どのようなログが出ていたか分かるでしょうか？
「Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable」
もし、上記だとすると、一時的にストレージの空き容量が無くなった疑いがあります。
また、heartbeat が停止した際、
LTE経由でインターネット上の任意のサイト等と通信が可能だったか分かるでしょうか？
例えば、お客様アプリケーション内でawsやazureとの通信はできているけど、
node-eyeのheartbeatだけ途切れる、など。
よろしくお願いいたします。
古関様
お世話になります。
上記の件、ご回答ありがとうございます。
> 進め方として、ワークアラウンド等で、とりあえずheartbeatを途切れ無くしつつ、
> 原因特定や別の対策を進める形でよいでしょうか？
現在は、node-eye.serviceのログを確認し、heartbeatが途切れた場合に、
サービスを再起動する対応をしており、現場はそれで対応する予定をしております。
また、armsdの起動引数を与えて動作させてみましたが、再現時には有用なログは出力されませんでした。
（armsdの内部のスケジューラにheartbeatのイベントが登録されているようですが、
スケジューラが何らかの原因で動作しないのか、heartbeatの処理自体でエラーが発生して停止したのかも
ログとして出力されていませんでした。）
> > Warning: Journal has been rotated since unit was
> Warningのログが途中で切れていますが、どのようなログが出ていたか分かるでしょうか？
>
> 「Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable」
> もし、上記だとすると、一時的にストレージの空き容量が無くなった疑いがあります。
上記の件ですが、申し訳ございませんが当時のログは取得しておりませんでした。
ただ、再現した際に上記のログは出力されておりませんでした。
> また、heartbeat が停止した際、
> LTE経由でインターネット上の任意のサイト等と通信が可能だったか分かるでしょうか？
> 例えば、お客様アプリケーション内でawsやazureとの通信はできているけど、
> node-eyeのheartbeatだけ途切れる、など。
node-eyeのheartbeatが途切れた際、その他の通信は正常に行われておりました。
at_keitaro.takahashi
高橋です。
症状がこちらで再現できておらず、回答に時間がかかってしまい申し訳ありません。
引き続き調査してまいります。
ひとまず、node-eyeで使用しているlibarmsをv5.41からv6.40にアップデートしたものを添付いたしますので、
そちらで症状が解決するかどうか試していただけると幸いです。
dpkg -i libarms_6.40-atmark1+deb10u1_armhf.deb
v5.41からv6.40までの変更内容は以下に記載されております。
https://dev.smf.jp/libarms/version/version_top.html
| ファイル | ファイルの説明 |
|---|---|
| libarms_6.40-atmark1+deb10u1_armhf.deb |
at_syunya.ohshio
2024年8月8日 17時16分
大塩です。
> 現在、node-eyeに複数台の接続を行っているのですが、node-eyeの画面上、すべて切断状態となりました。
> そのうちの1台の/var/log/syslogを確認すると、下記のログを最後に"armsd"のログが出力されていませんでした。
> heartbeatの送信が途切れたため、切断状態になっていると思われます。
>
> Aug 7 03:11:23 armadillo armsd[2259]: log callback: 200 - Sent heartbeat to XXX.XXX.XXX.XXX
> Aug 7 03:11:23 armadillo armsd[2259]: log callback: 200 - Sent heartbeat to XXX.XXX.XXX.XXX
>
> psコマンドで確認すると、armsdは起動しております。
> root@armadillo:/var/log# ps aux | grep armsd
> root 2259 0.0 0.3 5064 3952 ? Ss 8月02 0:13 /usr/sbin/armsd
原因切り分けのため、お手数ですが
node-eye に接続している Armadillo の nmcli connection を送付いただけますでしょうか。
また、systemctl status node-eye.service を確認し、サービスが動作しているかご確認いただけますでしょうか。
以上です。