Armadilloフォーラム

node-eyeのHeartbeat が途切れる原因の調査

製品
Armadillo-IoT G3

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が途切れた原因を調査したいのですが、どのような方法がありますでしょうか。

コメント

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 を確認し、サービスが動作しているかご確認いただけますでしょうか。

以上です。

h_i

2024年8月20日 9時27分

> 原因切り分けのため、お手数ですが
> 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

h_i

2024年8月23日 15時32分

> > 原因切り分けのため、お手数ですが
> > 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

2024年8月26日 13時24分

大塩です。

返答が遅くなり申し訳ございません。

頂いた情報から、eth と wwan の2つのコネクションが存在しておりますがnode-eye の config 設定でどちらを使用しているでしょうか。
両方使用する設定の場合は、外部ネットワークに接続しているのはどちらになるでしょうか。

以上です。

h_i

2024年8月27日 13時33分

大塩様

> 頂いた情報から、eth と wwan の2つのコネクションが存在しておりますがnode-eye の config 設定でどちらを使用しているでしょうか。
> 両方使用する設定の場合は、外部ネットワークに接続しているのはどちらになるでしょうか。

　現在、双方のコネクションとも利用しております。
　eth：ローカルネットワーク
　wwan：node-eye、外部通信用

at_syunya.ohshio

2024年8月27日 14時44分

大塩です。

> 　現在、双方のコネクションとも利用しております。
> 　eth：ローカルネットワーク
> 　wwan：node-eye、外部通信用

上記情報ありがとうございます。
現状での情報にて、ご確認頂きたい内容が2点あります。
1. wwan のみを使用した状態で、node-eyeのハートビートが切断される現象が発生するか
2. eth wwan 両方使用している状態でハートビートが送られない状態が発生した場合、systemctl restart node-eye.service を行うことで再びハートビートが送られるようになるか

以上です。

h_i

2024年9月19日 9時34分

大塩様

> 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

2024年9月24日 15時23分

大塩です。

ご確認ありがとうございます。

> 　結果としては、wwanのみを利用した状態で、ハートビートによる切断が発生しました。

これまで頂いた情報から、wwan が切断状態になりハートビート送信失敗が連続して続いた場合に発生しているように見えます。
wwan が長時間切断状態となっているかどうかはこれまでの情報からは不明ですが、少なくともハートビート送信失敗のログから20分以上は切断状態になっていると思います。

現象発生時、"nmcli device" で wwan の通信状態をご確認いただけますでしょうか。
おそらく armsd_connection_wwan の接続状態が切断になっていると思います。

これにより、原因が wwan 側か node-eye service 側かを切り分けることが出来ると思っています。

以上です。

h_i

2024年9月30日 16時35分

大塩様

> 現象発生時、"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

2024年9月30日 17時38分

大塩です。

> 　現状のコマンド結果を記載いたします。
> 　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

2024年10月1日 9時57分

大塩様

> ログの送付ありがとうございます。
> 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

2024年10月1日 11時07分

大塩です。

> 　リスタート後にはハートビートが再開され、node-eyeのサイトが接続状態となりました。
>
> 　ちなみに他のarmadilloで同様の現象が発生しているなど、情報はございますでしょうか。

今のところ、本現象での node-eye が接続されていない問題は把握できておりません。
何かしらのアプリケーションとの兼ね合いでwwan からハートビート送信が出来なくなっている可能性はありますが、現状の対策としては該当のログが出た場合にサービスを再起動する処理を組み込むのが良いかと思います。

以上です。