m.yoshida
2024年4月4日 12時58分
”user.err swupdate: FAILURE ERROR : Terminated”がアップデート中にでますが、影響ありますでしょうか？
原因と対策があればご教示ねがいます。
【詳細内容】
デフォルトでインストールされているコンテナ削除するためにdescファイル以下追加した影響
かもしれませんが
swdesc_option CONTAINER_CLEAR
”Waiting for btrfs to flush deleted subvolumes”から、30分後に”user.err swupdate: FAILURE ERROR : Terminated”がでます。
以下armadilloのlogになります。
tail -f /var/log/messages Jan 1 09:08:15 armadillo authpriv.notice login[1550]: pam_unix(login:account): expired passw ord for user root (root enforced) Jan 1 09:08:20 armadillo authpriv.err login[1550]: Failed preliminary check by password serv ice Jan 1 09:08:20 armadillo daemon.info init: process '/sbin/getty -L 115200 ttymxc2 vt102' (pi d 1550) exited. Scheduling for restart. Jan 1 09:08:21 armadillo daemon.info init: starting pid 1551, tty '': '/sbin/getty -L 115200 ttymxc2 vt102' Jan 1 09:08:28 armadillo authpriv.debug login[1551]: pam_unix(login:auth): user [root] has b lank password; authenticated without it Jan 1 09:08:28 armadillo authpriv.debug login[1551]: pam_unix(login:auth): user [root] has b lank password; authenticated without it Jan 1 09:08:28 armadillo authpriv.notice login[1551]: pam_unix(login:account): expired passw ord for user root (root enforced) Jan 1 09:08:35 armadillo authpriv.notice login[1551]: pam_unix(login:chauthtok): password ch anged for root Jan 1 09:08:35 armadillo authpriv.info login[1551]: pam_unix(login:session): session opened for user root(uid=0) by (uid=0) Jan 1 09:09:55 armadillo kern.info kernel: [ 595.944776] usb 1-1: new high-speed USB device number 2 using ci_hdrc Jan 1 09:09:56 armadillo kern.info kernel: [ 596.155855] usb-storage 1-1:1.0: USB Mass Storage device detected Jan 1 09:09:56 armadillo kern.info kernel: [ 596.165649] scsi host0: usb-storage 1-1:1.0 Jan 1 09:09:56 armadillo kern.info kernel: [ 596.195142] usbcore: registered new interface driver uas Jan 1 09:09:57 armadillo kern.notice kernel: [ 597.207219] scsi 0:0:0:0: Direct-Access Generic Flash Disk 8.07 PQ: 0 ANSI: 4 Jan 1 09:09:57 armadillo kern.notice kernel: [ 597.212426] sd 0:0:0:0: [sda] 15728640 512-byte logical blocks: (8.05 GB/7.50 GiB) Jan 1 09:09:57 armadillo kern.notice kernel: [ 597.213673] sd 0:0:0:0: [sda] Write Protect is off Jan 1 09:09:57 armadillo kern.debug kernel: [ 597.213706] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00 Jan 1 09:09:57 armadillo kern.notice kernel: [ 597.216216] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA Jan 1 09:09:57 armadillo kern.info kernel: [ 597.248164] sda: sda1 sda2 Jan 1 09:09:57 armadillo kern.notice kernel: [ 597.252920] sd 0:0:0:0: [sda] Attached SCSI removable disk Jan 1 09:09:57 armadillo user.notice swupdate-auto-update: Mounting sda2 on /mnt in private namespace Jan 1 09:09:57 armadillo user.notice swupdate-auto-update: Trying update /mnt/my_swu.swu Jan 1 09:09:58 armadillo user.info swupdate: START Software Update started ! Jan 1 09:09:58 armadillo user.info swupdate: RUN [install_single_image] : Installing pre_script Jan 1 09:10:00 armadillo kern.info kernel: [ 600.386225] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null) Jan 1 09:10:00 armadillo user.info swupdate: RUN [read_lines_notify] : No base os update: copying current os over Jan 1 09:10:14 armadillo user.warn swupdate: RUN [read_lines_notify] : ---------------------------------------------- Jan 1 09:10:14 armadillo user.warn swupdate: RUN [read_lines_notify] : WARNING: CONTAINER_CLEAR requested: stopping and destroying all container data first Jan 1 09:10:14 armadillo user.warn swupdate: RUN [read_lines_notify] : ---------------------------------------------- Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Interface veth0.IPv6 no longer relevant for mDNS. Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Leaving mDNS multicast group on interface veth0.IPv6 with address fe80::2ca6:a1ff:fec6:14e6. Jan 1 09:10:15 armadillo kern.info kernel: [ 615.432589] podman0: port 1(veth0) entered disabled state Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Withdrawing address record for fe80::2ca6:a1ff:fec6:14e6 on veth0. Jan 1 09:10:15 armadillo kern.info kernel: [ 615.442553] device veth0 left promiscuous mode Jan 1 09:10:15 armadillo kern.info kernel: [ 615.442606] podman0: port 1(veth0) entered disabled state Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Interface podman0.IPv6 no longer relevant for mDNS. Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Leaving mDNS multicast group on interface podman0.IPv6 with address fe80::68d6:2fff:fe84:423d. Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Interface podman0.IPv4 no longer relevant for mDNS. Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Leaving mDNS multicast group on interface podman0.IPv4 with address 10.88.0.1. Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Withdrawing address record for fe80::68d6:2fff:fe84:423d on podman0. Jan 1 09:10:15 armadillo daemon.info avahi-daemon[1246]: Withdrawing address record for 10.88.0.1 on podman0. Jan 1 09:10:15 armadillo daemon.info NetworkManager[990]: <info> [615.5936] device (veth0): state change: activated -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed') Jan 1 09:10:15 armadillo daemon.info NetworkManager[990]: <info> [615.6309] device (veth0): released from master device podman0 Jan 1 09:10:15 armadillo daemon.info dbus-daemon[931]: [system] Activating service name='org.freedesktop.nm_dispatcher' requested by ':1.0' (uid=0 pid=990 comm="/usr/sbin/NetworkManager -n") (using servicehelper) Jan 1 09:10:15 armadillo daemon.info NetworkManager[990]: <info> [615.9827] device (podman0): state change: activated -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed') Jan 1 09:10:16 armadillo daemon.info NetworkManager[990]: <info> [616.0357] manager: NetworkManager state is now DISCONNECTED Jan 1 09:10:16 armadillo daemon.info dbus-daemon[931]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Jan 1 09:10:16 armadillo user.info swupdate: RUN [read_lines_notify] : Command 'command podman stop -a' output: Jan 1 09:10:16 armadillo user.info swupdate: RUN [read_lines_notify] : time="1970-01-01T09:10:16+09:00" level=error msg="Unable to clean up network for container 42fb69d14571eb15671636b49c6f9631391268d533db496d7ed169d986276c62: \"unmounting network namespace for container 42fb69d14571eb15671636b49c6f9631391268d533db496d7ed16 Jan 1 09:10:16 armadillo user.info swupdate: RUN [read_lines_notify] : 9d986276c62: failed to remove ns path /run/netns/netns-dab364e4-544e-8731-3609-9d94036e2e2e: remove /run/netns/netns-dab364e4-544e-8731-3609-9d94036e2e2e: device or resource busy\"" Jan 1 09:10:16 armadillo user.info swupdate: RUN [read_lines_notify] : 42fb69d14571eb15671636b49c6f9631391268d533db496d7ed169d986276c62 Jan 1 09:10:19 armadillo user.info swupdate: RUN [read_lines_notify] : Command 'command podman rm -a -f' output: Jan 1 09:10:19 armadillo user.info swupdate: RUN [read_lines_notify] : 42fb69d14571eb15671636b49c6f9631391268d533db496d7ed169d986276c62 Jan 1 09:10:21 armadillo user.info swupdate: RUN [read_lines_notify] : Waiting for btrfs to flush deleted subvolumes Jan 1 09:14:04 armadillo daemon.info NetworkManager[990]: <info> [844.6403] device (wlan0): set-hw-addr: set MAC address to A2:F2:48:C3:F8:A3 (scanning) Jan 1 09:14:04 armadillo daemon.info NetworkManager[990]: <info> [844.6705] device (wlan0): supplicant interface state: inactive -> interface_disabled Jan 1 09:14:04 armadillo daemon.info NetworkManager[990]: <info> [844.6711] device (p2p-dev-wlan0): supplicant management interface state: inactive -> interface_disabled Jan 1 09:14:04 armadillo daemon.info NetworkManager[990]: <info> [844.6721] device (wlan0): supplicant interface state: interface_disabled -> inactive Jan 1 09:14:04 armadillo daemon.info NetworkManager[990]: <info> [844.6726] device (p2p-dev-wlan0): supplicant management interface state: interface_disabled -> inactive Jan 1 09:20:56 armadillo daemon.info NetworkManager[990]: <info> [1256.6416] device (wlan0): set-hw-addr: set MAC address to A2:A7:EA:2B:EF:CF (scanning) Jan 1 09:20:56 armadillo daemon.info NetworkManager[990]: <info> [1256.6671] device (wlan0): supplicant interface state: inactive -> interface_disabled Jan 1 09:20:56 armadillo daemon.info NetworkManager[990]: <info> [1256.6731] device (p2p-dev-wlan0): supplicant management interface state: inactive -> interface_disabled Jan 1 09:20:56 armadillo daemon.info NetworkManager[990]: <info> [1256.6745] device (wlan0): supplicant interface state: interface_disabled -> inactive Jan 1 09:20:56 armadillo daemon.info NetworkManager[990]: <info> [1256.6750] device (p2p-dev-wlan0): supplicant management interface state: interface_disabled -> inactive Jan 1 09:27:48 armadillo daemon.info NetworkManager[990]: <info> [1668.6415] device (wlan0): set-hw-addr: set MAC address to 96:FF:4F:0F:CF:29 (scanning) Jan 1 09:27:48 armadillo daemon.info NetworkManager[990]: <info> [1668.6705] device (wlan0): supplicant interface state: inactive -> interface_disabled Jan 1 09:27:48 armadillo daemon.info NetworkManager[990]: <info> [1668.6711] device (p2p-dev-wlan0): supplicant management interface state: inactive -> interface_disabled Jan 1 09:27:48 armadillo daemon.info NetworkManager[990]: <info> [1668.6721] device (wlan0): supplicant interface state: interface_disabled -> inactive Jan 1 09:27:48 armadillo daemon.info NetworkManager[990]: <info> [1668.6726] device (p2p-dev-wlan0): supplicant management interface state: interface_disabled -> inactive Jan 1 09:34:41 armadillo daemon.info NetworkManager[990]: <info> [2081.6416] device (wlan0): set-hw-addr: set MAC address to BE:F3:5F:8A:C6:3C (scanning) Jan 1 09:34:41 armadillo daemon.info NetworkManager[990]: <info> [2081.6632] device (wlan0): supplicant interface state: inactive -> interface_disabled Jan 1 09:34:41 armadillo daemon.info NetworkManager[990]: <info> [2081.6724] device (p2p-dev-wlan0): supplicant management interface state: inactive -> interface_disabled Jan 1 09:34:41 armadillo daemon.info NetworkManager[990]: <info> [2081.6740] device (wlan0): supplicant interface state: interface_disabled -> inactive Jan 1 09:34:41 armadillo daemon.info NetworkManager[990]: <info> [2081.6745] device (p2p-dev-wlan0): supplicant management interface state: interface_disabled -> inactive Jan 1 09:40:21 armadillo user.err swupdate: FAILURE ERROR : Terminated Jan 1 09:40:22 armadillo user.info swupdate: RUN [install_single_image] : Installing setting passwords
コメント
m.yoshida
2024年4月4日 14時11分
マルティネさん
返信ありがとうございます。
>問題なければアップデートが終了されて再起動で確認できなくなったと思いますが、またインストールすることになって10分以上遅かったら「findmnt -t btrfs」の出力をいただければ助かります（今後のアップデートで、30分で停止されない場合に自動的に表示するようにします）
こちら動作確認しました。
Jan 1 09:35:09 armadillo user.err swupdate: FAILURE ERROR : Terminated
Jan 1 09:35:10 armadillo user.info swupdate: RUN [install_single_image] : Installing setting passwords
Jan 1 09:35:13 armadillo user.info swupdate: RUN [install_single_image] : Installing swdesc_embed_container my_debian_tar.tar
^C
armadillo:~# findmnt -t btrfs
TARGET SOURCE FSTYPE OPTIONS
/var/lib/containers/storage_readonly
/dev/mmcblk0p5[/boot_0/containers_storage//deleted]
btrfs rw,noat
/var/app/rollback/volumes
/dev/mmcblk0p5[/boot_0/volumes//deleted] btrfs rw,noat
/var/app/volumes /dev/mmcblk0p5[/volumes//deleted] btrfs rw,noat
/var/tmp /dev/mmcblk0p5[/tmp] btrfs rw,noat
armadillo:~# タイミングちがいましたら、もう一度確認してみます。
30分かかるのはできれば改善したいとおもってます。
at_dominique.m…
2024年4月4日 14時39分
マルティネです。
> 30分かかるのはできれば改善したいとおもってます。
了解しました。
> こちら動作確認しました。
> /var/lib/containers/storage_readonly > /dev/mmcblk0p5[/boot_0/containers_storage//deleted]
「/deleted」の文字列が記載されていますので、2/ の「削除されたサブボリュームがまだ使用中」の方の問題ですね。
すみません、ログをもう一度読み直しておそらく分かりました。
USB 経由でアップデートを起動させる場合には Armadillo Base OS に影響を与えないために別の「mount namespace」で実行していますが、その場合に CONTAINER_CLEAR の umount 処理は無効になってしまって30分待つことになりますね… 再現できました。
対応には時間が必要になりますので、ひとまず「待たない」というワークアラウンドで進みましょう。
desc ファイルに「swdesc_option SKIP_APP_SUBVOL_SYNC」を追加してから再び mkswu で swu を生成しなおしていただければ、その待つ時間がなくなります。
デメリットとしては、appfs の容量はすぐに戻らないので、コンテナの書込みにほぼ appfs の全てを消費する場合に書込みが失敗するかもしれません。
その場合は、swdesc_image の前に sleep 60 でも追加していただければある容量が戻る時間を少し与えることができます。
解決になってない気持ち悪い方法で申し訳ございませんが、修正まで少々お待ちください。
よろしくお願いします。
m.yoshida
2024年4月4日 15時55分
マルティネさん
下記対応でいけました。ありがとうございます。
>desc ファイルに「swdesc_option SKIP_APP_SUBVOL_SYNC」を追加してから再び mkswu で swu を生成しなおしていただければ、その待つ時間がなくなります。
また、知識不足なので教えてくださいほしいのですが、appfs というのは、なんでしょうか？
参考になる資料、サイトでもかもしれませんので、教えてください
>デメリットとしては、appfs の容量はすぐに戻らないので、コンテナの書込みにほぼ appfs の全てを消費する場合に書込みが失敗するかもしれません。
at_dominique.m…
2024年4月4日 16時22分
マルティネです。
> 下記対応でいけました。ありがとうございます。
よかったです。修正方法を確認できましたので、今月末のリリースで修正されます。
> また、知識不足なので教えてくださいほしいのですが、appfs というのは、なんでしょうか？
すみません、eMMC のパーティションリストの「app」の事でした：
https://manual.atmark-techno.com/armadillo-iot-a6e/armadillo-iotg-a6e_p…
一言で言うと、アプリケーションの領域でコンテナのイメージとボリュームのことです。
Armadillo A6E では 2.5GB がありますので、例えばアップデートのコンテナイメージに 1GB が必要とします。
続いて、書込み前のデーターで 2GB がすでに消費されている状態で CONTAINER_CLEAR を使用して、 btrfs の削除を待たない場合にその 2GB がまだ使用中の状態で書込みを行うと、アップデートが失敗するかもしれません。
今回は成功したようですので、再起動した後に btrfs が容量を取り戻して問題なさそうですが、場合によっては待つ必要があります。
よろしくお願いします。
at_dominique.m…
2024年4月4日 13時46分
m.yoshidaさん
連絡ありがとうございます、
マルティネです。
> ”user.err swupdate: FAILURE ERROR : Terminated”がアップデート中にでますが、影響ありますでしょうか？
このメッセージ自体に「アップデートが必要以上に遅かった」以外に問題がありませんが、他の問題があれば確認が必要です。
> descファイル以下追加した影響かもしれませんが
> ”Waiting for btrfs to flush deleted subvolumes”から、30分後に”user.err swupdate: FAILURE ERROR : Terminated”がでます。
そのとおりだと思います。
出力された Terminated が分かりにくいですが、その「btrfs のサブボリュームの削除を待ちます」コマンドが30分で終了されない場合に強制的に停止させている現象です。
その30分で停止されてない問題ですが、二つの可能性を考えています：
1/ データーがものすごく細かくに記載されていてデーターの削除に30分以上かかってしまった可能性は低いと思いますが、その場合はバックグラウンドで削除されます（再起動後でも）ので、書込みができた場合に問題がありません。
2/ 何かの理由で削除された btrfs サブボリュームがまだマウントされている場合に、その待つコマンドの仕様としてはいくら待っても完了されないようにできているので、無駄に30分を待った≪だけ≫です。
ただいま動作確認してみましたが 2/ の問題を再現できませんでしたので、何かの理由で違う動作になっているかもしれません。
これからもう少し確認を続きます。
問題なければアップデートが終了されて再起動で確認できなくなったと思いますが、またインストールすることになって10分以上遅かったら「findmnt -t btrfs」の出力をいただければ助かります（今後のアップデートで、30分で停止されない場合に自動的に表示するようにします）
アップデートが最終的に失敗したか、別の問題があればまた聞いてください。
よろしくお願いします。