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 |
高橋様
お世話になっております。
下記の件を確認いたしました。回答が遅くなり、大変申し訳ございませんでした。
> ひとまず、node-eyeで使用しているlibarmsをv5.41からv6.40にアップデートしたものを添付いたしますので、
> そちらで症状が解決するかどうか試していただけると幸いです。
>
> dpkg -i libarms_6.40-atmark1+deb10u1_armhf.deb
結果として、node-eyeのハートビートが停止する現象は発生いたしました。
現象は改善しないため、こちらの対応としては、ご提案いただいた「heart beatが停止している場合、サービスを再起動する」
を一旦対応する予定です。
2点ご質問がございます。
・libarmsをさらに詳細に調査する方法はあるでしょうか？
・libarms v6.40で運用する場合は、node-eyeのシステムに何か影響はありますでしょうか？
■バージョン
apt list --installed | grep arms
WARNING: apt does not have a stable CLI interface. Use with caution in scripts.
libarms/now 6.40-atmark1+deb10u1 armhf [インストール済み、ローカル]
■ログ
node-eye.service - node-eye client
Loaded: loaded (/lib/systemd/system/node-eye.service; enabled; vendor preset:
Active: active (running) since Wed 2025-01-15 09:55:08 JST; 5 days ago
Docs: https://node-eye.com
Process: 2011 ExecStart=/usr/sbin/exec-armsd (code=exited, status=0/SUCCESS)
Main PID: 2127 (armsd)
Memory: 2.3M
CGroup: /system.slice/node-eye.service
mq2127 /usr/sbin/armsd -v
1月 17 10:25:20 armadillo armsd[2127]: heartbeat traffic_rate: ifidx=0, in_octe
1月 17 10:25:20 armadillo armsd[2127]: log callback: 200 - Sent heartbeat to 20
1月 17 10:25:20 armadillo armsd[2127]: log callback: 200 - Sent heartbeat to 20
1月 17 10:30:20 armadillo armsd[2127]: heartbeat cpu_detail_usage: idx=0, idle=
1月 17 10:30:20 armadillo armsd[2127]: heartbeat mem_usage: idx=0, used=8952217
1月 17 10:30:20 armadillo armsd[2127]: heartbeat disk_usage: idx=0, path=/, use
1月 17 10:30:20 armadillo armsd[2127]: heartbeat traffic_rate: ifidx=0, in_octe
1月 17 10:30:20 armadillo armsd[2127]: log callback: 200 - Sent heartbeat to 20
1月 17 10:30:20 armadillo armsd[2127]: log callback: 200 - Sent heartbeat to 20
1月 17 10:32:07 armadillo armsd[2127]: log callback: 109 - SSL Connection reset
at_shinya.koga
アットマークテクノの古賀です。
h_iさん（2025年1月20日 16時38分）：
>下記の件を確認いたしました。回答が遅くなり、大変申し訳ございませんでした。
ご確認有り難うございます。
>>ひとまず、node-eyeで使用しているlibarmsをv5.41からv6.40にアップデートしたものを添付いたしますので、
>>そちらで症状が解決するかどうか試していただけると幸いです。
>>
dpkg -i libarms_6.40-atmark1+deb10u1_armhf.deb
>
>結果として、node-eyeのハートビートが停止する現象は発生いたしました。
>現象は改善しないため、こちらの対応としては、ご提案いただいた「heart beatが停止している場合、サービスを再起動する」
>を一旦対応する予定です。
了解しました。お手数をかけまして恐縮です。
>2点ご質問がございます。
以下、順に回答します。
>・libarmsをさらに詳細に調査する方法はあるでしょうか？
ビルド済みのものを使うだけですと、これ以上の調査は、難しそうです。
libarms のソースを見たのですが、引用して頂いた v6.40 でのログを見ると、最後（ハートビート送信が停止する直前？）に
>1月 17 10:32:07 armadillo armsd[2127]: log callback: 109 - SSL Connection reset
というログが出ています。
このログは途中で切れていますが、おそらく、"SSL Connection reset by peer." というメッセージが出ていたものと思われます。
このログの前の、ハートビート送信ログの日時が 1月 17 10:30:20 ですから、ハートビート送信間隔5分が経過する前に、サーバーとの接続が切られたような感じですね。
ソースを見た感じ、サーバー側から何かリクエストを受信した際に、リクエストの内容を読み出す時かまたはレスポンスを送信する時にエラーが起き、SSL 接続が切られたと判定して動作停止しているような雰囲気です。
>・libarms v6.40で運用する場合は、node-eyeのシステムに何か影響はありますでしょうか？
v5.41 から v6.40 への変更履歴を見てみたところ、バージョンアップにより armsd が動作不具合を起こすような仕様変更は、なさそうです：
https://dev.smf.jp/libarms/version/version_top.html
仕様変更のうち、v6.31 -> v6.32 での
・OpenSSL 1.1.0 系に対応した
というのが少々気になりましたので、この二つのバージョンのソースの diff をとって見てみましたが、後方互換性を保つ変更になっているようです。
以上、あまりお役に立てず恐縮ですが、どうぞ宜しくお願いします。
h_i
at_shinya.koga
アットマークテクノの古賀です。
h_iさん：
>１点ご確認ですが、armsdはネットワークが切断した場合、再接続は行わないのでしょうか？
ごめんなさい。分からないです。
armsd のソースを見ると、main() において、初期化時処理を終えた後に libarms の arms_event_loop() を呼び出しており、 arms_event_loop() でハートビート送信をスケジュールようです。
そして、ハートビート送信のスケジュール時刻に達すると、ハートビート送信動作を行い、送信動作の完了時に次のハートビート送信をスケジュールすることで、ハートビート送信動作を繰り返すようになっているように思われます。
そして、ハートビート送信動作の中で "SSL Connection reset by peer." のエラーが起きた場合、次のスケジュールを行わないように見えますが（※もしそうなら、そこでハートビート送信の繰り返しが停止してしまうでしょう）、実際そうなのかどうかは、ソースを見ただけでは判断がつきません。
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 を確認し、サービスが動作しているかご確認いただけますでしょうか。
以上です。