ArchのアップデートでGUIが起動しなくなった話

WindowsやUbuntuやDebianなどを使っていると「アプデ＝大切なのですぐやれ」みたいな気持ちになるが、Archはそうでもないらしい……。

GUIが起動しないというかグラボが正しく動かなくなったのかもしれなくて、結局カーネルとGPUドライバが合わないからカーネル戻そうねって話になった。

症状

ログインマネージャを使っていないのでTTY画面でいつもログインしてからstartxさせている。

amdgpuが載っているのでstartxするとGPUファンが回り出してモニタをHDMI入力に変えるとデスクトップに移行できる。

……はずなのだが、startxしても「..」を何行も出力させて5分くらい待たされてからXサーバーは死んだと言われ、ついでにGPUのファンも回っていない。

その上TTYでexitするかCtrl+Alt+F2等で別TTYに移行した後のログインで、ユーザ名入力までは通るもののパスワードを求めてこなくなった。

そのため一度ログアウトしたらCtrl+Alt+Del（何となく押したらシャットダウンに入るキーだったらしい）でシャットダウンするしか……と思いきや、ログイン系のジョブを待機して一向にシャットダウンもしない。ログイン中にシャットダウンさせても結局ジョブ待機で終わらない。文字通り寝て待ってみたら待機すらあきらめたようで起動したままだった。

昨日（2月24日）にpacman -Syyu をかけ、シャットダウンして翌日25日にこの有様なので、どう見ても24日のアプデにかかったパッケージが悪い。

調査：カーネルログを見る

実際使ったのは dmesg -H だけど、この記事を書く頃には治ってエラーログが出なくなったので、journalからの切り取り。

Feb 25 21:08:04 cookpod kernel: ------------[ cut here ]------------

Feb 25 21:08:04 cookpod kernel: WARNING: CPU: 0 PID: 98 at drivers/gpu/drm/amd/amdgpu/../display/amdgpu_dm/amdgpu_dm.c:1792 dm_suspend+0x1a7/0x1c0 [amdgpu]

Feb 25 21:08:04 cookpod kernel: Modules linked in: ccm btusb btrtl btbcm btintel bluetooth uas usb_storage ecdh_generic ecc hid_uclogic(OE) joydev mousedev snd_hda_codec_realtek snd_hda_codec_generic ledtrig_audio amdgpu 8021q iwlmvm gar>

Feb 25 21:08:04 cookpod kernel:  mei sysimgblt fb_sys_fops wmi mac_hid video acpi_pad drm fuse agpgart bpf_preload ip_tables x_tables ext4 crc32c_generic crc16 mbcache jbd2 usbhid xhci_pci sr_mod crc32c_intel cdrom xhci_pci_renesas

Feb 25 21:08:04 cookpod kernel: CPU: 0 PID: 98 Comm: kworker/0:2 Tainted: G           OE     5.11.1-arch1-1 #1

Feb 25 21:08:04 cookpod kernel: Hardware name: System manufacturer System Product Name/H110M-K, BIOS 4210 06/25/2019

Feb 25 21:08:04 cookpod kernel: Workqueue: pm pm_runtime_work

Feb 25 21:08:04 cookpod kernel: RIP: 0010:dm_suspend+0x1a7/0x1c0 [amdgpu]

Feb 25 21:08:04 cookpod kernel: Code: ff 31 d2 4c 89 e6 4c 89 ff e8 35 8e 13 00 83 f8 01 74 1e 89 c2 48 c7 c6 a0 44 40 c1 48 c7 c7 60 db 4a c1 e8 0b d8 20 ff eb c2 <0f> 0b e9 8e fe ff ff 4c 89 e6 4c 89 ff e8 47 cc 12 00 eb ae e8 80

Feb 25 21:08:04 cookpod kernel: RSP: 0018:ffffb5fa802f7c48 EFLAGS: 00010286

Feb 25 21:08:04 cookpod kernel: RAX: 0000000000000000 RBX: ffff88850b476920 RCX: 0000000000000000

Feb 25 21:08:04 cookpod kernel: RDX: 0000000000000009 RSI: ffff88863ec18be0 RDI: ffff88850b460000

Feb 25 21:08:04 cookpod kernel: RBP: ffff88850b460000 R08: 0000000000000000 R09: ffffb5fa802f7a38

Feb 25 21:08:04 cookpod kernel: R10: ffffb5fa802f7a30 R11: ffffffffaf0cba08 R12: ffff88850b460000

Feb 25 21:08:04 cookpod kernel: R13: 0000000000000001 R14: ffff888500df11ac R15: 0000000000000000

Feb 25 21:08:04 cookpod kernel: FS:  0000000000000000(0000) GS:ffff88863ec00000(0000) knlGS:0000000000000000

Feb 25 21:08:04 cookpod kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

Feb 25 21:08:04 cookpod kernel: CR2: 00007f72a3a54c18 CR3: 0000000110986005 CR4: 00000000003706f0

Feb 25 21:08:04 cookpod kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

Feb 25 21:08:04 cookpod kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

Feb 25 21:08:04 cookpod kernel: Call Trace:

Feb 25 21:08:04 cookpod kernel:  ? pp_set_clockgating_by_smu+0x35/0x60 [amdgpu]

Feb 25 21:08:04 cookpod kernel:  ? vi_common_set_clockgating_state+0x227/0x2f0 [amdgpu]

Feb 25 21:08:04 cookpod kernel:  amdgpu_device_ip_suspend_phase1+0x8e/0x100 [amdgpu]

Feb 25 21:08:04 cookpod kernel:  amdgpu_device_suspend+0x91/0x2e0 [amdgpu]

Feb 25 21:08:04 cookpod kernel:  amdgpu_pmops_runtime_suspend+0x9d/0x130 [amdgpu]

Feb 25 21:08:04 cookpod kernel:  pci_pm_runtime_suspend+0x5e/0x170

Feb 25 21:08:04 cookpod kernel:  ? pci_dev_put+0x20/0x20

Feb 25 21:08:04 cookpod kernel:  __rpm_callback+0xc5/0x170

Feb 25 21:08:04 cookpod kernel:  ? pci_dev_put+0x20/0x20

Feb 25 21:08:04 cookpod kernel:  rpm_callback+0x1f/0x70

Feb 25 21:08:04 cookpod kernel:  ? pci_dev_put+0x20/0x20

Feb 25 21:08:04 cookpod kernel:  rpm_suspend+0x176/0x6c0

Feb 25 21:08:04 cookpod kernel:  pm_runtime_work+0x94/0xa0

Feb 25 21:08:04 cookpod kernel:  process_one_work+0x214/0x3e0

Feb 25 21:08:04 cookpod kernel:  worker_thread+0x4d/0x3d0

Feb 25 21:08:04 cookpod kernel:  ? rescuer_thread+0x3c0/0x3c0

Feb 25 21:08:04 cookpod kernel:  kthread+0x133/0x150

Feb 25 21:08:04 cookpod kernel:  ? __kthread_bind_mask+0x60/0x60

Feb 25 21:08:04 cookpod kernel:  ret_from_fork+0x22/0x30

Feb 25 21:08:04 cookpod kernel: ---[ end trace 68eb043a9d56687c ]---

Feb 25 21:08:04 cookpod kernel: kernel tried to execute NX-protected page - exploit attempt? (uid: 0)

Feb 25 21:08:04 cookpod kernel: BUG: unable to handle page fault for address: ffff8885043a8d60

Feb 25 21:08:04 cookpod kernel: #PF: supervisor instruction fetch in kernel mode

Feb 25 21:08:04 cookpod kernel: #PF: error_code(0x0011) - permissions violation

Debian（カーネル4）でWifi6カードを使わせようとした時にも同じようなコアダンプ？が出ていたのを見たことあったし、startxができないあたりからも分かるけど、amdgpuとあるのでGPUまわりになんかある。

後になって分かったけど、このログが出る時は大体カーネルとカードの食い合わせが悪い時な気がする。

調査：pacmanのログ

特に設定をいじったわけでもない場合はアプデのせいであるとして、

そもそもpacmanで何をアプデしてしまったのかを見る。

$ egrep  "02-24.*upgraded" /var/log/pacman.log

[2021-02-24T22:20:22+0000] [ALPM] upgraded libunwind (1.4.0-1 -> 1.5.0-1)

[2021-02-24T22:20:22+0000] [ALPM] upgraded mesa (20.3.4-2 -> 20.3.4-3)

[2021-02-24T22:20:23+0000] [ALPM] upgraded js78 (78.7.1-1 -> 78.8.0-1)

[2021-02-24T22:20:23+0000] [ALPM] upgraded gtk3 (1:3.24.25-2 -> 1:3.24.26-1)

[2021-02-24T22:20:23+0000] [ALPM] upgraded gtkmm3 (3.24.3-1 -> 3.24.4-1)

[2021-02-24T22:20:23+0000] [ALPM] upgraded hdparm (9.58-3 -> 9.60-1)

[2021-02-24T22:20:23+0000] [ALPM] upgraded libgphoto2 (2.5.26-1 -> 2.5.27-1)

[2021-02-24T22:20:23+0000] [ALPM] upgraded libinput (1.16.4-1 -> 1.17.0-1)

[2021-02-24T22:20:23+0000] [ALPM] upgraded libva-mesa-driver (20.3.4-2 -> 20.3.4-3)

[2021-02-24T22:20:24+0000] [ALPM] upgraded linux (5.10.16.arch1-1 -> 5.11.1.arch1-1)

[2021-02-24T22:20:24+0000] [ALPM] upgraded python (3.9.1-2 -> 3.9.2-1)

[2021-02-24T22:20:26+0000] [ALPM] upgraded linux-headers (5.10.16.arch1-1 -> 5.11.1.arch1-1)

[2021-02-24T22:20:26+0000] [ALPM] upgraded mesa-vdpau (20.3.4-2 -> 20.3.4-3)

[2021-02-24T22:20:26+0000] [ALPM] upgraded openal (1.21.0-1 -> 1.21.1-1)

[2021-02-24T22:20:26+0000] [ALPM] upgraded opencl-mesa (20.3.4-2 -> 20.3.4-3)

[2021-02-24T22:20:26+0000] [ALPM] upgraded python-cryptography (3.3.1-1 -> 3.4.6-1)

[2021-02-24T22:20:26+0000] [ALPM] upgraded python-numpy (1.20.0-1 -> 1.20.1-1)

[2021-02-24T22:20:26+0000] [ALPM] upgraded r8168 (8.048.03-67 -> 8.048.03-70)

最初mesa系がドライバが原因だと思っていたのでここにあるmesaのつくものを全てダウングレードしたんだけど、実際悪かったのはカーネルだったらしい。

調査：lspciをする

GPUが認識されていないならlspciも出力が欠けるのでは…と思ってかけてみたら、案の定GPUファンも回らないし長々と待たされて^Cでキャンセルしてしまった。

Archインスコ初期の、amdgpuドライバを入れていない時にlspciをしたら短時間だけファンが回って無事出力に出たことがあったので、今はそれ以前の問題ということになる。

Feb 26 10:45:15 cookpod kernel: amdgpu: SMU load firmware failed

Feb 26 10:45:15 cookpod kernel: amdgpu: fw load failed

Feb 26 10:45:15 cookpod kernel: amdgpu: smu firmware loading failed

Feb 26 10:45:15 cookpod kernel: amdgpu 0000:01:00.0: amdgpu: amdgpu_device_ip_resume failed (-22).

Feb 26 10:45:15 cookpod kernel: snd_hda_intel 0000:01:00.1: CORB reset timeout#1, CORBRP = 0

Feb 26 10:47:46 cookpod kernel: BUG: kernel NULL pointer dereference, address: 0000000000000028

Feb 26 10:47:46 cookpod kernel: #PF: supervisor read access in kernel mode

Feb 26 10:47:46 cookpod kernel: #PF: error_code(0x0000) - not-present page

これもjournalからのウロ覚えの切り出しだから場所間違ってるかもしんないけど、lspciのタイムアウト？の時にやっぱり動かないログが出る。

ダウングレード

みんな大好きArchWikiのダウングレードのページ https://wiki.archlinux.jp/index.php/%E3%83%91%E3%83%83%E3%82%B1%E3%83%BC%E3%82%B8%E3%81%AE%E3%83%80%E3%82%A6%E3%83%B3%E3%82%B0%E3%83%AC%E3%83%BC%E3%83%89

まずダウングレードしたい過去版のパッケージ（ここではlinuxとlinux-headers）がキャッシュに残ってるかを探す。

$ ls /var/cache/pacman/pkg/linux* -al | grep Feb

-rw-r--r-- 1 root root  77367667 Feb  4 00:27 /var/cache/pacman/pkg/linux-5.10.13.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  77436359 Feb  6 11:51 /var/cache/pacman/pkg/linux-5.10.13.arch1-2-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  77446405 Feb  7 23:20 /var/cache/pacman/pkg/linux-5.10.14.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  77447565 Feb 10 19:10 /var/cache/pacman/pkg/linux-5.10.15.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  77458518 Feb 13 21:21 /var/cache/pacman/pkg/linux-5.10.16.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  97244155 Feb 23 14:49 /var/cache/pacman/pkg/linux-5.11.1.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root   1130768 Feb  4 04:36 /var/cache/pacman/pkg/linux-api-headers-5.10.13-1-any.pkg.tar.zst

-rw-r--r-- 1 root root 154264692 Feb  8 21:41 /var/cache/pacman/pkg/linux-firmware-20210208.b79d239-1-any.pkg.tar.zst

-rw-r--r-- 1 root root  24238611 Feb  4 00:27 /var/cache/pacman/pkg/linux-headers-5.10.13.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  24114094 Feb  6 11:51 /var/cache/pacman/pkg/linux-headers-5.10.13.arch1-2-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  24116904 Feb  7 23:20 /var/cache/pacman/pkg/linux-headers-5.10.14.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  24123929 Feb 10 19:10 /var/cache/pacman/pkg/linux-headers-5.10.15.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  24125444 Feb 13 21:21 /var/cache/pacman/pkg/linux-headers-5.10.16.arch1-1-x86_64.pkg.tar.zst

-rw-r--r-- 1 root root  24292855 Feb 23 14:49 /var/cache/pacman/pkg/linux-headers-5.11.1.arch1-1-x86_64.pkg.tar.zst

取得日時がpacmanのログと噛み合ってない気がするけど、事実これのダウングレードで治ったのでよしとします。
問題のものが5.11.1だったので、5.10.16にとりあえず戻す。

$ sudo pacman -U linux-5.10.16.arch1-1-x86_64.pkg.tar.zst linux-headers-5.10.16.arch1-1-x86_64.pkg.tar.zst

ArchWikiによればカーネルのダウングレードはまずUSBブートしてarch-chrootしろとあるけど、
あれはおそらくEmergencyモード等でニッチモサッチモいかない時だと思うので、普通に起動したままやる。普通にできたし「Good News!モジュールとカーネルのバージョンがマッチしたよ」みたいなことも言われた。

おわり

XがつかないのはGPUとカーネルの相性だったとしても、TTYログインで一向に終わらないのもはたしてカーネルのせいだったんだろうか……と疑問は残る。

Debianみたいに1つ前のバージョンのカーネルをGRUBで選べるようにできたら便利そう。