Armadilloフォーラム

コンテナトリガでのスリープへ移行する場合、稀に失敗する

akihito

2024年8月16日 13時53分

発生環境:
 Armadillo-IoT ゲートウェイ A6E +Di8+Ai4
 ソフトウェアバージョン:
  base_os 3.19.2-at.5
  boot 2020.4-at24
  extra_os.a6e-gw-container 2.5.2
 アプリケーション:
  CUI アプリケーション
 コンテナ:
  privileged権限付与、rootユーザで実行
 コンテナbaseOS:
  alpine

上記環境でコンテナトリガで間欠動作を実現しています。
コンテナ終了時に稀に スリープ(SMSあり) に移行しないことがあります。
またこの現象が発生すると、コンテナは既に終了しているため以降スリープしなくなります。(ユーザ目線ではだんまり状態)

コンテナのログ(掲載不可)と /var/log/message を比較すると、コンテナ終了の0.5秒後に★のログが出ておりました。
本件含めて2件しか発生しておらず、諸事情によりログの解析が出来る状況となったのが今回が初めてとなります。
★のログはスリープしなかったことと関係があると野ではと考えておりますが、いかがでしょうか?
本件以外で同様の現象は発生しておりますでしょうか?
ご教示のほどよろしくお願いします。

-ログ(/var/log/message)-
 Aug 16 13:22:34 armadillo daemon.notice [1997]: [modem0] simple connect started...
 Aug 16 13:22:34 armadillo daemon.notice [1997]: [modem0] simple connect state (6/10): register
 Aug 16 13:22:34 armadillo daemon.notice [1997]: [modem0] simple connect state (7/10): wait to get packet service state attached
 Aug 16 13:22:34 armadillo daemon.notice [1997]: [modem0] simple connect state (8/10): bearer
 Aug 16 13:22:34 armadillo daemon.notice [1997]: [modem0] simple connect state (9/10): connect
 Aug 16 13:22:34 armadillo daemon.notice [1997]: [modem0] state changed (registered -> connecting)
★Aug 16 13:22:50 armadillo kern.info kernel: [ 134.974087] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
 Aug 16 13:22:54 armadillo daemon.warn [1997]: [modem0/bearer0] connection attempt #4 failed: Couldn't match response
 Aug 16 13:22:54 armadillo daemon.notice [1997]: [modem0] state changed (connecting -> registered)
 Aug 16 13:22:54 armadillo daemon.notice [1997]: [modem0/bearer0] connection #4 finished: duration 0s
 Aug 16 13:22:54 armadillo daemon.warn [1997]: [modem0] couldn't connect bearer: Couldn't match response
 Aug 16 13:22:54 armadillo daemon.warn NetworkManager[1048]: [1723782174.7664] modem-broadband[ttyCommModem]: failed to connect modem: Couldn't match response
 Aug 16 13:22:54 armadillo daemon.info NetworkManager[1048]: [1723782174.7669] device (ttyCommModem): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
 Aug 16 13:22:54 armadillo daemon.info NetworkManager[1048]: [1723782174.7944] manager: NetworkManager state is now CONNECTED_LOCAL
 Aug 16 13:22:54 armadillo daemon.warn NetworkManager[1048]: [1723782174.7987] device (ttyCommModem): Activation: failed for connection 'gsm-ttyCommModem'
 Aug 16 13:22:54 armadillo daemon.info NetworkManager[1048]: [1723782174.8206] device (ttyCommModem): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
--

コメント

at_dominique.m…

2024年8月16日 14時44分

akihitoさん

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

> ★Aug 16 13:22:50 armadillo kern.info kernel: [ 134.974087] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)

このログは rootfs (Armadillo Base OS の / ファイルシステム)がリマウントされたとのことですので、おそらく何かが persist_file で何かのファイルを永続化しましたと思います。
これでスリープしないことはないと思いますが、意図的に何かを保存してないと思いますので気になるログですね…

お手数ですが、間欠動作の設定を教えていただけますでしょうか?

具体的に
- Armadillo Base OS とカーネルのバージョン「cat /etc/atmark-release」「uname -r
- コンテナコンフィグファイルの内容(少なくとも間欠動作に関わる hook まわり、a6e-gw-container.conf を元にした場合は念のため hooks-dir の中身も確認したいです)
- /etc/atmark/power-utils.conf の内容(バージョンが古かった場合は /etc/conf.d/power-utils.conf )

普段は間欠動作をできてますのでこれで大きい問題を見つからないと思いますが、ひとまず内容を確認してこちらで再現できるかを試したいと思います。

よろしくお願いします。

koga

2024年8月16日 15時05分

アットマークテクノの古賀(休日モード)です。

akihitoさん:
>上記環境でコンテナトリガで間欠動作を実現しています。
>コンテナ終了時に稀に スリープ(SMSあり) に移行しないことがあります。
>またこの現象が発生すると、コンテナは既に終了しているため以降スリープしなくなります。(ユーザ目線ではだんまり状態)
>コンテナのログ(掲載不可)と /var/log/message を比較すると、コンテナ終了の0.5秒後に★のログが出ておりました。
>本件含めて2件しか発生しておらず、諸事情によりログの解析が出来る状況となったのが今回が初めてとなります。
>★のログはスリープしなかったことと関係があると野ではと考えておりますが、いかがでしょうか?

マルティネ:
>>★Aug 16 13:22:50 armadillo kern.info kernel: [ 134.974087] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
>
>このログは rootfs (Armadillo Base OS の / ファイルシステム)がリマウントされたとのことですので、おそらく何かが persist_file で何かのファイルを永続化しましたと思います。
>これでスリープしないことはないと思いますが、意図的に何かを保存してないと思いますので気になるログですね…
>
>お手数ですが、間欠動作の設定を教えていただけますでしょうか?
>
>具体的に
> - Armadillo Base OS とカーネルのバージョン「cat /etc/atmark-release」「uname -r
>- コンテナコンフィグファイルの内容(少なくとも間欠動作に関わる hook まわり、a6e-gw-container.conf を元にした場合は念のため hooks-dir の中身も確認したいです)
>- /etc/atmark/power-utils.conf の内容(バージョンが古かった場合は /etc/conf.d/power-utils.conf )
>
>普段は間欠動作をできてますのでこれで大きい問題を見つからないと思いますが、ひとまず内容を確認してこちらで再現できるかを試したいと思います。

追加でお願いですが、もし、症状が発生した際に /var/run/power-utils.log を採取可能であれば、採取して頂けると助かります。
状況からすると、コンテナ終了をトリガとして atmark-power-utils サービスが電源状態を遷移すべきところ、状態遷移できていないようです。
コンテナ終了通知を受けて電源状態を遷移しようとした際に、atmark-power-utils サービス内でエラーが起きていれば、/var/run/power-utils.log にエラーログが出ていると思います。その内容を見ることで、手がかりを得られるかも知れません。

akihito

2024年8月16日 17時06分

アットマークテクノ 古賀さん

お世話になっております。
返信ありがとうございます。

> 追加でお願いですが、もし、症状が発生した際に /var/run/power-utils.log を採取可能であれば、採取して頂けると助かります。
> 状況からすると、コンテナ終了をトリガとして atmark-power-utils サービスが電源状態を遷移すべきところ、状態遷移できていないようです。
→ /var/run/power-utils.log の内容を確認しましたが、空(から)でした。
  同じ現象が発生した場合は 直ぐに/var/run/power-utils.log を確認するようにいたします。

akihito

2024年8月16日 16時58分

マルティネさん

お世話になっております。
早速の返信ありがとうございます。

> このログは rootfs (Armadillo Base OS の / ファイルシステム)がリマウントされたとのことですので、おそらく何かが persist_file で何かのファイルを永続化しましたと思います。
→ 承知しました。
  たしかに コンテナ終了時に/etc/atmark/power-utils.confを更新して persist_file で永続化しておりますので、そのログになりそうです。
  該当ログが関係ないことが分かり、安心しました。

さて間欠動作の設定について共有します。

> - Armadillo Base OS とカーネルのバージョン「cat /etc/atmark-release」「uname -r
■armadillo:~# cat /etc/atmark-release
3.19.2-at.5

■armadillo:~# uname -r
5.10.220-1-at

> - コンテナコンフィグファイルの内容(少なくとも間欠動作に関わる hook まわり、a6e-gw-container.conf を元にした場合は念のため hooks-dir の中身も確認したいです)

■app.conf (抜粋)
add_args --hooks-dir=/etc/containers/aiot_gw_container_hooks.d

■armadillo:~# cat /etc/containers/aiot_gw_container_hooks.d/hook.sh
#!/bin/sh

/usr/bin/pwu_notify container_stop

■armadillo:~# cat /etc/containers/aiot_gw_container_hooks.d/setting.json
{
"version": "1.0.0",
"when": { "always": true },
"hook": { "path": "/etc/containers/aiot_gw_container_hooks.d/hook.sh" },
"stages": ["poststop"]
}

> - /etc/atmark/power-utils.conf の内容(バージョンが古かった場合は /etc/conf.d/power-utils.conf )
TARGETの名称は適当なものに変更しております。

TARGET='test'
MODE='SLEEP'
WAKEUP='RTC:240','SMS'

よろしくお願いします。

at_dominique.m…

2024年8月16日 17時48分

マルティネです。

> さて間欠動作の設定について共有します。

情報ありがとうございます。

コードを確認したところいくつかの可能性があります:
* SMS で wake up して、再び sleep する時にまだ前回の RTC タイマーが切れてない場合は、再び RTC のタイマーを設定できないことでエラーします
* /run が full になった際(コンテナも起動できなくなりますし、そうならないのは動作の条件になりますが、power-utils.log のサイズに制限がないところは引っかかりました。full になるまではもの凄く時間かかりそうですが、一応制限を追加した方がいいと感じました)

他に問題があるかもしれませんので、再び発生した際にログを確認していただければ幸いです。

とりあえず一つ目のが怪しいと思いますので、それでしたらログではっきり分かります:

sh: write error: Resource busy
aiot-set-wake-trigger failed for rtc.

修正の納期は約束できませんが、とりあえずのワークアラウンドとしてはリトライを足せばこの問題を回避できると思いますので、
/usr/bin/aiot-set-wake-trigger にこういう変更を加えたら再現しなくなるはずです:

--- a/aiot-set-wake-trigger
+++ b/aiot-set-wake-trigger
@@ -83,7 +83,9 @@ alarm_timer () {
     *) usage;;
     esac
 
-    echo "$1" > /sys/class/rtc/rtc0/wakealarm
+    while ! echo "$1" > /sys/class/rtc/rtc0/wakealarm; do
+        sleep 10;
+    done
 }
 
 alarm_timer_off () {

(最終の修正は違う形になると思いますが、この問題だと確認できたら使ってみてください)

よろしくお願いします。

at_dominique.m…

2024年8月16日 17時54分

連続で失礼しました。

先ほどの rtc の問題はこちらの手順ミスでした。
(手動で色々同時に試しすぎていて、本来発生しない問題でした。通常の動作では rtc のアラームを無効化してからセットしますので、そこはちゃんと成功します)

間欠動作で何かを再現できたらまた連絡します。

引き続きよろしくお願いします

akihito

2024年8月16日 18時51分

マルティネさん

検証までして頂き、ありがとうございます。
再現しましたらログを収集し、共有させて頂けたらと思います。

power-utils.log の サイズフルの件はローテイトを行っていないので、処置を入れた方が良いというお話だと理解しました。
その辺りも今後はケアする必要がありそうです。
ご指摘ありがとうございます。

akihito

2024年8月19日 12時45分

アットマークテクノ 古賀さん、マルティネさん

概ね再現手順が判明しました。
コンテナ終了によるスリープの直前で例えば、シリアルコンソールにてEnterキーを連続入力するとスリープしませんでした。

この際に /var/run/power-utils.log を取得しましたが空(から)となっておりました。

-ログ-
armadillo:~# cat /var/run/power-utils.log
armadillo:~# cat /etc/atmark/power-utils.conf

TARGET='test'
MODE='SLEEP'
WAKEUP='RTC:420', 'SMS'
armadillo:~#

ひとまず上記再現手順であれば、運用で起こることはないのですが、他のトリガ(何らかの割込み)でも発生しそうな気がしております。
何か分かりますでしょうか?
必要なログ等がありましたら、取得しますので返信頂けると助かります。

at_shinya.koga

2024年8月19日 17時55分

アットマークテクノの古賀です。

akihitoさん:
>概ね再現手順が判明しました。
>コンテナ終了によるスリープの直前で例えば、シリアルコンソールにてEnterキーを連続入力するとスリープしませんでした。
>
>この際に /var/run/power-utils.log を取得しましたが空(から)となっておりました。
>
>-ログ-
>armadillo:~# cat /var/run/power-utils.log
>armadillo:~# cat /etc/atmark/power-utils.conf
>
> TARGET='test'
> MODE='SLEEP'
> WAKEUP='RTC:420', 'SMS'
> armadillo:~#

こちらで同様の手順を試してみているのですが、再現できません。

>ひとまず上記再現手順であれば、運用で起こることはないのですが、他のトリガ(何らかの割込み)でも発生しそうな気がしております。
>何か分かりますでしょうか?
>必要なログ等がありましたら、取得しますので返信頂けると助かります。

要因切り分けのため、次の二点を試してみて頂けると助かります:

1.) power-utils.conf の起床要因設定(WAKEUP)から 'SMS' を除外した場合、上記再現手順でスリープしない症状は変わりなく起きるでしょうか?

2.) 上記再現手順を行わずにコンテナが終了してスリープした場合も、起床後に /var/run/power-utils.log は空のままでしょうか?

(2) については、SMS を起床要因にしてスリープした場合、/var/run/power-utils.log には次のようなログが出力されるはずなのです:

AT^SIND="message",0
^SIND: message,0,0
OK
AT^SIND="message",1
^SIND: message,1,0
OK

以上、ひとまずのコメントです。お手数をかけますが、どうぞ宜しくお願いします。