本記事の背景、概要
使っていたラズパイ4が起動しなくなり、以下の記事でmicroSDを取り替えて運良く復旧できました。インストールしているOSはUbuntu 22.04 LTSです。
しかし、その後にDNSに接続出来なくなって名前解決できなくなったり、Dockerコンテナが立ち上がらなくなったり、たまにネットワーク接続が切断されてしまったり、広範囲に不具合が起きている状態でした。
調べていったところ、"org.freedesktop.systemd1"というD-Busを使ったサービスが起動していないことが根本原因だとわかりました。
その時のLinux（Ubuntu）の状況や対処法について本記事にまとめます。
TL;DR
起きている現象
journalctlコマンドでSystemdのジャーナルを見ると、以下のように org.freedesktop.systemd1 の起動に失敗したと表示される。
May 08 05:24:35 hostname dbus-daemon[838]:
[system] Failed to activate service 'org.freedesktop.systemd1':
timed out (service_start_timeout=25000ms)
対応策
systemdを再インストールする。
sudo apt install --reinstall systemd
対応後
org.freedesktop.systemd1やその他のコアなサービスが起動するようになり、発生していた不具合が全て解消する。
以後は筆者のメモも兼ねているので、ご興味あれば読んでいただく感じで大丈夫です。
具体的にどんな症状が起きていたか？
(1) 名前解決できず、apt等で外部接続できない
以下のコマンドを実行すると本来は自分のパブリックIPアドレスが返ってくるはずなのですが、名前解決できずにエラーになります。
$ curl httpbin.org/ip
curl: (6) Could not resolve host: httpbin.org
通常であればsystemd-resolvedというサービスを介してよしなに名前解決してくれるのですが、どうもそこに関連するサービスがうまく動いていないようです。この影響で、例えばaptで外からパッケージを取得更新することも出来なくなっています。
aptでの外部接続は問題解決のために必須になるので、暫定で /etc/systemd/resolved.confを次のように編集して名前解決できる状態にしておきます。（8.8.8.8はGoogleが提供するDNSのIPアドレスです）
# 変更前
#DNS=
↓
# 変更後
DNS=8.8.8.8
変更したら、systemd-resolvedを再起動します。
sudo systemctl restart systemd-resolved
httpbin.orgが名前解決されて、自身のIPアドレスが返ってくることを確認します。
$ curl httpbin.org/ip
{
"origin": "xxx.yyy.zzz.aaa"
}
また上記の対応で、aptでの外部接続もできるようになっています。
(2) Dockerコンテナが起動しない
試しにhello-worldのDockerコンテナを起動すると、Dockerイメージの取得後に数分何もレスポンスが返ってこない状態になり、最終的にエラー終了します。
docker run hello-world
Dockerイメージの取得までは、順調です。
Unable to find image 'hello-world:latest' locally
latest: Pulling from library/hello-world
478afc919002: Pull complete
Digest: sha256:a26bff933ddc26d5cdf7faa98b4ae1e3ec20c4985e6f87ac0973052224d24302
Status: Downloaded newer image for hello-world:latest
しかしこの後しばらくレスポンスがなく、以下のようにエラーが返ります。
コードブロック(```)だと1行出力で見にくいので、引用(>)で記載します。
docker: Error response from daemon: failed to create task for container: failed to create shim task: OCI runtime create failed: runc create failed: unable to start container process: unable to apply cgroup configuration: unable to start unit "docker-d0a3829e2732e79c7e00fb9f75359a295c4c650cd47f0e469979f35a599b8b76.scope" (properties [{Name:Description Value:"libcontainer container d0a3829e2732e79c7e00fb9f75359a295c4c650cd47f0e469979f35a599b8b76"} {Name:Slice Value:"system.slice"} {Name:Delegate Value:true} {Name:PIDs Value:@au [3839]} {Name:MemoryAccounting Value:true} {Name:CPUAccounting Value:true} {Name:IOAccounting Value:true} {Name:TasksAccounting Value:true} {Name:DefaultDependencies Value:false}]): Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms): unknown.
最初はDockerの裏側で動いているcontainerdとかrunCの状態がおかしいのかなあと疑い、Docker関連のパッケージを全部インストールし直したりしてたのですが、状況は一向に変わらず...
本記事の主題になっているように、問題の根本はコンテナタイムよりも奥のLinuxのシステム側で発生していることにこの時は気づいていませんでした。上のエラーをよく見ると、org.freedesktop.systemd1のアクティベートに失敗した旨のメッセージが出ていますが、systemd側の知識がほぼ無いのもあって完全にスルーしていました。原因調査の際に、自分に少しでも馴染みがある部分だけが気になるというバイアスが掛かりますね...
※調査の過程で、Dockerの背後の動作について以下の図のような構成になっていることがわかったので、それはそれで勉強になりました。下の図で言うと、問題が起きていたのは左下の赤枠で囲まれた「Linux Kernel」の部分でした。
(3) Login関連のサービスで謎のエラーが出る
今回問題が生じたラズパイにインストールしたUbuntuはGUI無しの状態で動かしており、そこにモニターをつなぐと黒の背景でコマンドのみを受け付ける状態になっています。そこに数分おきに以下のようなメッセージが一行ずつ出てきます。
[FAILED] Failed to start User Login Management.
[FAILED] Failed to start User Login Management.
[FAILED] Failed to start User Login Management.
...
どうやら、systemd-logindというサービスが正常に動いていないようです（だけとSSH等でログインができる状態）。
試しにsystemd-logindを再起動してみますが、うまく立ち上がりません。
$ sudo systemctl restart systemd-logind.service
Job for systemd-logind.service failed because a timeout was exceeded.
See "systemctl status systemd-logind.service" and "journalctl -xeu systemd-logind.service" for details.
journalを見ると、変わらず "Failed to start User Login Management." というメッセージが出ています。
$ sudo journalctl -xeu systemd-logind.service
（以下抜粋）
May 06 16:39:53 ubuntu systemd[1]: Failed to start User Login Management.
░░ Subject: A start job for unit systemd-logind.service has failed
░░ Defined-By: systemd
░░ Support: http://www.ubuntu.com/support
░░
░░ A start job for unit systemd-logind.service has finished with a failure.
░░
░░ The job identifier is 1650 and the job result is failed.
筆者の知識の無さもあるとは思いますが、そんなに役に立ちそうなログは出力されていないようです。
(4) ネットワークが突如繋がらなくなる
起動後に半日くらい放置してネットワーク越しにSSH等でアクセスしようとすると、高確率で繋がらなくなります。まずはNetworkManagerのjournalを以下のコマンドで確認してみます。
sudo journalctl -u NetworkManager --since "2024-05-06 21:42:40" --until "2024-05-06 21:43:10"
すると、ネットワークが繋がらなくなったと思われる時間帯に次のようなエラーを見つけました。
May 06 21:42:55 ubuntu systemd[1]: NetworkManager.service: Unexpected error response from GetNameOwner(): Connection terminated
さらにNetworkManagerと同様のエラーが、他のサービスでも出ていることを確認できました。
$ sudo journalctl --since "2024-05-06 21:40:30" --until "2024-05-06 21:44:45" | grep Unexpected
May 06 21:42:55 ubuntu systemd[1]: systemd-timesyncd.service: Unexpected error response from GetNameOwner(): Connection terminated
May 06 21:42:55 ubuntu systemd[1]: NetworkManager.service: Unexpected error response from GetNameOwner(): Connection terminated
May 06 21:42:55 ubuntu systemd[1]: systemd-networkd.service: Unexpected error response from GetNameOwner(): Connection terminated
May 06 21:42:55 ubuntu systemd[1]: wpa_supplicant.service: Unexpected error response from GetNameOwner(): Connection terminated
May 06 21:42:55 ubuntu systemd[1]: udisks2.service: Unexpected error response from GetNameOwner(): Connection terminated
May 06 21:42:55 ubuntu systemd[1]: systemd-resolved.service: Unexpected error response from GetNameOwner(): Connection terminated
May 06 21:42:55 ubuntu systemd[1]: systemd-logind.service: Unexpected error response from GetNameOwner(): Connection terminated
May 06 21:42:55 ubuntu systemd[1]: ModemManager.service: Unexpected error response from GetNameOwner(): Connection terminated
May 06 21:42:55 ubuntu systemd[1]: polkit.service: Unexpected error response from GetNameOwner(): Connection terminated
このエラーは、D-Busとの接続がうまくいかなくなると発生するようですが、とりあえずWi-Fi経由でネットワーク接続できない問題に関しては、以下のコマンドを実行して解消しました。
sudo systemctl restart wpa_supplicant
sudo systemctl restart NetworkManager
根本的な問題への対処
(1)から(4)で個別に起きている問題は確認できましたが、「これらの問題を引き起こしている共通の原因がありそうだ」と考え始めます。ログやjournalにD-Busとかsystemdとかが出ているから、この辺の状態がわかるコマンドがあればいいのかな、とひらめきます。
ChatGPTに聞いてみたら、busctl listというコマンドで起動しているD-Busのサービスの一覧を見れるようです。早速確認してみます。
$ busctl list
NAME PID PROCESS USER CONNECTION UNIT SESSION DESCRIPTION
(中略)
org.bluez - - - (activatable) - - -
org.freedesktop.DBus 1 systemd root - init.scope - -
org.freedesktop.ModemManager1 - - - (activatable) - - -
org.freedesktop.NetworkManager 46883 NetworkManager root :1.11615 NetworkManager.service - -
org.freedesktop.PackageKit - - - (activatable) - - -
org.freedesktop.PolicyKit1 - - - (activatable) - - -
org.freedesktop.UDisks2 - - - (activatable) - - -
org.freedesktop.bolt - - - (activatable) - - -
org.freedesktop.fwupd - - - (activatable) - - -
org.freedesktop.nm_dispatcher - - - (activatable) - - -
org.freedesktop.nm_priv_helper - - - (activatable) - - -
org.freedesktop.timesync1 752 systemd-timesyn systemd-timesync :1.2 systemd-timesyncd.service - -
org.freedesktop.xxxというサービスが沢山立ち上がっていますが、これが正常な状態なのかどうかがよくわかりません。
そこで試しに正常稼働しているUbuntuで同じbusctl listコマンドを実行してみると、org.freedesktop.systemd1 やorg.freedesktop.login1 等が出てくるのを確認できました。これ以外でも7,8個くらい立ち上がっていないorg.freedesktop系のサービスがあるようです。
なるほど、現状立ち上がっていない org.freedesktop系のサービスが立ち上がればいいのかな。しかしそれらはどうすれば立ち上がる？？
org.freedesktop.xxxはD-Busのサービスなので、systemctl startとかでは起動できなさそうです。また、busctl startみたいなコマンドも存在しないらしい。
暗中模索の状況で、ChatGPTから教えてもらった以下のコマンドを実行してみます。
sudo apt install --reinstall systemd
すると、org.freedesktop系で起動していなかった他のD-Busのサービス（org.freedesktop.systemd1 やorg.freedesktop.login1 等）も、以下のように立ち上がることを確認できました！
$ sudo busctl list
NAME PID PROCESS USER CONNECTION UNIT SESSION DESCRIPTION
(中略)
org.bluez - - - (activatable) - - -
org.freedesktop.DBus 1 systemd root - init.scope - -
org.freedesktop.ModemManager1 968 ModemManager root :1.19 ModemManager.service - -
org.freedesktop.NetworkManager 846 NetworkManager root :1.9 NetworkManager.service - -
org.freedesktop.PackageKit 2704 packagekitd root :1.170 packagekit.service - -
org.freedesktop.PolicyKit1 859 polkitd root :1.7 polkit.service - -
org.freedesktop.UDisks2 883 udisksd root :1.8 udisks2.service - -
org.freedesktop.bolt - - - (activatable) - - -
org.freedesktop.fwupd - - - (activatable) - - -
org.freedesktop.hostname1 - - - (activatable) - - -
org.freedesktop.locale1 - - - (activatable) - - -
org.freedesktop.login1 2719 systemd-logind root :1.173 systemd-logind.service - -
org.freedesktop.network1 2657 systemd-network systemd-network :1.165 systemd-networkd.service - -
org.freedesktop.nm_dispatcher - - - (activatable) - - -
org.freedesktop.nm_priv_helper - - - (activatable) - - -
org.freedesktop.resolve1 2663 systemd-resolve systemd-resolve :1.167 systemd-resolved.service - -
org.freedesktop.systemd1 1 systemd root :1.164 init.scope - -
org.freedesktop.timedate1 - - - (activatable) - - -
org.freedesktop.timesync1 2874 systemd-timesyn systemd-timesync :1.177 systemd-timesyncd.service - -
これにより、(1)~(4)の全ての問題も解決しました！
おわりに
かなり手こずりましたが、何とか解決できました。
ただD-BusやSystemd部分は正直未だにあまりわかっていないので、この辺を理解してもっと強くなりたいところです。