sys-kernel-debug 및 로그인 서비스 오류로 인해 상당한 로그인 지연이 발생함

배경/배경

저는 LVC 컨테이너(proxmox 항목)에서 Debian GNU/Linux 11(bullseye) x86_64(5.4.174-2-pve) 가상화 서버를 실행하고 있습니다. 저는 데비안을 처음 사용합니다(보통 아치 리눅스를 사용합니다. 롤과 릴리스입니다). Proxmox는 거의 건드리지 않았습니다(기본적으로 가족 구성원이 제 웹사이트를 개발할 수 있는 컨테이너와 제가 원하는 모든 것을 제공했습니다).

나는 내 작업을 시작했고 모든 것이 잘 진행되고 있지만 버전에 대한 미러링을 설정하는 방법을 배우는 데 시간이 좀 걸렸고 몇 달 후에 웹 사이트와 일반적인 시스템 해킹을 구축했습니다.

나는 광고를 차단하기 위해 일종의 pyhole을 다운로드하여 나에게 서버를 제공하는 가족 구성원을 돕기로 결정했습니다. 문제는 혼란을 일으킬지 모르기 때문에 docker를 통해 수행하고 싶다는 것입니다.

내 생각엔 docker와 docker-compose를 다운로드했을 때 모든 것이 내리막길을 걷고 있었던 것 같아요. 그 기간 동안 했던 업데이트와 업그레이드 때문이었죠.

눈에 보이는 문제

나는 ssh가 로그인 작업을 완료하는 데 더 많은 시간이 걸린다는 것을 알아차리기 시작했습니다(약 5초 정도). 이것만은 충분히 강조한다아니요SSH 자체, 명령을 누르면 일반적인 motd가 즉시 나타납니다.

내가 주목한 또 다른 점은 다음과 같습니다.

The programs included with the Debian GNU/Linux system are free software;
the exact distribution terms for each program are described in the
individual files in /usr/share/doc/*/copyright.

proxmox 콘솔에서 두 번 인쇄하면 두 번 번갈아 인쇄된 전체 메시지가 표시되는 것 같습니다. 원본 메시지가 ABC인 경우 ABACB C가 인쇄됩니다.

진단

저는 몇 년 동안(약 4년) 아치 리눅스를 사용했지만 개인적인 용도로 사용하고... 컨테이너가 아닌 전체 설치입니다. 그래서 저는 커널이나 기타 OS 관련 내용을 너무 많이 건드릴 필요가 없었습니다.

어쨌든, 도움을 받을 수 있기를 바라며 공유하고 싶은 몇 가지 생각은 다음과 같습니다.

logctl -b

Sep 04 13:05:51 LinuxJD systemd-journald[59]: Journal started
Sep 04 13:05:51 LinuxJD systemd-journald[59]: Runtime Journal (/run/log/journal/c5b67cb2fb4c49678a4fd62f7e4a2b20) is 8.0M, max 116.3M, 108.3M free.
Sep 04 13:05:51 LinuxJD systemd[1]: Starting Flush Journal to Persistent Storage...
Sep 04 13:05:51 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
Sep 04 13:05:51 LinuxJD mount[65]: mount: /sys/kernel/config: cannot mount configfs read-only.
Sep 04 13:05:51 LinuxJD systemd-journald[59]: Time spent on flushing to /var/log/journal/c5b67cb2fb4c49678a4fd62f7e4a2b20 is 2.371449s for 5 entries.
Sep 04 13:05:51 LinuxJD systemd-journald[59]: System Journal (/var/log/journal/c5b67cb2fb4c49678a4fd62f7e4a2b20) is 80.0M, max 1.1G, 1.0G free.
Sep 04 13:05:51 LinuxJD systemd[1]: Finished Helper to synchronize boot up for ifupdown.
Sep 04 13:05:52 LinuxJD systemd[1]: Finished Apply Kernel Variables.
Sep 04 13:05:55 LinuxJD apparmor.systemd[94]: Not starting AppArmor in container
Sep 04 13:05:52 LinuxJD systemd[1]: Finished Create System Users.
Sep 04 13:05:52 LinuxJD systemd[1]: Starting Create Static Device Nodes in /dev...
Sep 04 13:05:52 LinuxJD systemd[1]: Finished Create Static Device Nodes in /dev.
Sep 04 13:05:52 LinuxJD systemd[1]: Reached target Local File Systems (Pre).
Sep 04 13:05:52 LinuxJD systemd[1]: Reached target Local File Systems.
Sep 04 13:05:52 LinuxJD systemd[1]: Starting Load AppArmor profiles...
Sep 04 13:05:55 LinuxJD systemd-journald[59]: Forwarding to syslog missed 1 messages.
Sep 04 13:05:52 LinuxJD systemd[1]: Condition check resulted in Store a System Token in an EFI Variable being skipped.
Sep 04 13:05:52 LinuxJD systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
Sep 04 13:05:52 LinuxJD systemd[1]: Condition check resulted in Rule-based Manager for Device Events and Files being skipped.
Sep 04 13:05:55 LinuxJD systemd[1]: Reached target Network is Online.
Sep 04 13:05:55 LinuxJD systemd[1]: Finished Create Volatile Files and Directories.
Sep 04 13:05:55 LinuxJD systemd[1]: Condition check resulted in Network Time Synchronization being skipped.
Sep 04 13:05:55 LinuxJD systemd[1]: Reached target System Time Set.
Sep 04 13:05:55 LinuxJD systemd[1]: Reached target System Time Synchronized.
Sep 04 13:05:55 LinuxJD systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Sep 04 13:05:55 LinuxJD systemd[1]: Finished Update UTMP about System Boot/Shutdown.
Sep 04 13:05:55 LinuxJD systemd[1]: Reached target System Initialization.
Sep 04 13:05:55 LinuxJD systemd[1]: Started Daily apt download activities.
Sep 04 13:05:55 LinuxJD systemd[1]: Started Daily apt upgrade and clean activities.
Sep 04 13:05:55 LinuxJD systemd[1]: Started Periodic ext4 Online Metadata Check for All Filesystems.
Sep 04 13:05:55 LinuxJD systemd[1]: Started Daily rotation of log files.
Sep 04 13:05:55 LinuxJD systemd[1]: Started Clean PHP session files every 30 mins.
Sep 04 13:05:55 LinuxJD systemd[1]: Listening on D-Bus System Message Bus Socket.
Sep 04 13:05:55 LinuxJD cron[162]: (CRON) INFO (pidfile fd = 3)
Sep 04 13:05:55 LinuxJD systemd[1]: Reached target Sockets.
Sep 04 13:05:56 LinuxJD cron[162]: (CRON) INFO (Running @reboot jobs)
Sep 04 13:05:55 LinuxJD systemd[1]: Reached target Basic System.
Sep 04 13:05:55 LinuxJD systemd[1]: Starting LSB: Set up cgroupfs mounts....
Sep 04 13:05:55 LinuxJD systemd[1]: Started Regular background program processing daemon.
Sep 04 13:05:55 LinuxJD systemd[1]: Started D-Bus System Message Bus.
Sep 04 13:05:55 LinuxJD systemd[1]: Starting Remove Stale Online ext4 Metadata Check Snapshots...
Sep 04 13:05:55 LinuxJD systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped.
Sep 04 13:05:55 LinuxJD systemd[1]: Starting A high performance web server and a reverse proxy server...
Sep 04 13:05:55 LinuxJD systemd[1]: Starting The PHP 7.4 FastCGI Process Manager...
Sep 04 13:05:55 LinuxJD systemd[1]: Starting Postfix Mail Transport Agent (instance -)...
Sep 04 13:05:55 LinuxJD systemd[1]: Starting System Logging Service...
Sep 04 13:05:56 LinuxJD systemd[173]: systemd-logind.service: Failed to set up mount namespacing: /run/systemd/unit-root/proc: Permission denied
Sep 04 13:05:56 LinuxJD systemd[173]: systemd-logind.service: Failed at step NAMESPACE spawning /lib/systemd/systemd-logind: Permission denied
Sep 04 13:05:56 LinuxJD systemd[1]: systemd-logind.service: Main process exited, code=exited, status=226/NAMESPACE
Sep 04 13:05:56 LinuxJD systemd[220]: systemd-logind.service: Failed to set up mount namespacing: /run/systemd/unit-root/proc: Permission denied
Sep 04 13:05:56 LinuxJD systemd[220]: systemd-logind.service: Failed at step NAMESPACE spawning /lib/systemd/systemd-logind: Permission denied
Sep 04 13:05:57 LinuxJD systemd[241]: systemd-logind.service: Failed to set up mount namespacing: /run/systemd/unit-root/proc: Permission denied
Sep 04 13:05:57 LinuxJD systemd[241]: systemd-logind.service: Failed at step NAMESPACE spawning /lib/systemd/systemd-logind: Permission denied
Sep 04 13:05:57 LinuxJD systemd[1]: systemd-logind.service: Main process exited, code=exited, status=226/NAMESPACE
Sep 04 13:05:57 LinuxJD systemd[1]: Finished Load Kernel Module drm.
Sep 04 13:05:57 LinuxJD systemd[245]: systemd-logind.service: Failed to set up mount namespacing: /run/systemd/unit-root/proc: Permission denied
Sep 04 13:05:57 LinuxJD systemd[245]: systemd-logind.service: Failed at step NAMESPACE spawning /lib/systemd/systemd-logind: Permission denied
Sep 04 13:05:57 LinuxJD systemd[1]: systemd-logind.service: Scheduled restart job, restart counter is at 4.
Sep 04 13:05:57 LinuxJD systemd[249]: systemd-logind.service: Failed to set up mount namespacing: /run/systemd/unit-root/proc: Permission denied
Sep 04 13:05:58 LinuxJD postfix[253]: Postfix is running with backwards-compatible default settings
Sep 04 13:05:57 LinuxJD systemd[249]: systemd-logind.service: Failed at step NAMESPACE spawning /lib/systemd/systemd-logind: Permission denied
Sep 04 13:05:58 LinuxJD postfix[253]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Sep 04 13:05:58 LinuxJD systemd[1]: [email protected]: Failed with result 'start-limit-hit'.
Sep 04 13:05:58 LinuxJD postfix[253]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
Sep 04 13:05:58 LinuxJD systemd[1]: systemd-logind.service: Failed with result 'exit-code'.
Sep 04 13:05:58 LinuxJD rsyslogd[168]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.2102.0]
Sep 04 13:05:58 LinuxJD systemd[1]: Failed to start User Login Management.
Sep 04 13:05:58 LinuxJD rsyslogd[168]: imklog: cannot open kernel log (/proc/kmsg): Permission denied.
Sep 04 13:05:58 LinuxJD systemd[1]: Started System Logging Service.
Sep 04 13:05:58 LinuxJD rsyslogd[168]: activation of module imklog failed [v8.2102.0 try https://www.rsyslog.com/e/2145 ]
...(im cutting due to retries) 
Sep 04 13:05:58 LinuxJD systemd[1]: Failed to start User Login Management.
Sep 04 13:05:58 LinuxJD rsyslogd[168]: imklog: cannot open kernel log (/proc/kmsg): Permission denied.
Sep 04 13:05:58 LinuxJD systemd[1]: Started System Logging Service.
Sep 04 13:05:58 LinuxJD rsyslogd[168]: activation of module imklog failed [v8.2102.0 try https://www.rsyslog.com/e/2145 ]
Sep 04 13:05:58 LinuxJD rsyslogd[168]: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="168" x-info="https://www.rsyslog.com"] start
Sep 04 13:05:59 LinuxJD sshd[299]: Server listening on 0.0.0.0 port 22.
Sep 04 13:05:59 LinuxJD sshd[299]: Server listening on :: port 22.
Sep 04 13:05:59 LinuxJD systemd[1]: Started OpenBSD Secure Shell server.
Sep 04 13:06:00 LinuxJD postmulti[301]: postsuper: fatal: scan_dir_push: open directory hold: Permission denied
Sep 04 13:06:00 LinuxJD postfix/postsuper[301]: fatal: scan_dir_push: open directory hold: Permission denied
Sep 04 13:06:01 LinuxJD postfix/postfix-script[302]: fatal: Postfix integrity check failed!
Sep 04 13:06:01 LinuxJD systemd[1]: nginx.service: Failed to parse PID from file /run/nginx.pid: Invalid argument
Sep 04 13:06:01 LinuxJD systemd[1]: Started A high performance web server and a reverse proxy server.
Sep 04 13:06:02 LinuxJD systemd[1]: [email protected]: Control process exited, code=exited, status=1/FAILURE
Sep 04 13:06:02 LinuxJD systemd[1]: [email protected]: Failed with result 'exit-code'.
Sep 04 13:06:02 LinuxJD systemd[1]: Failed to start Postfix Mail Transport Agent (instance -).
Sep 04 13:06:02 LinuxJD systemd[1]: Starting Postfix Mail Transport Agent...
Sep 04 13:06:02 LinuxJD systemd[1]: Finished Postfix Mail Transport Agent.

그래서 계속해서 일부 systemctl 작업이 무엇을 하고 있는지 관찰했고 이 모든 것에서 얻은 것은 sys-kernel-config.mount, sys-kernel-debug.mount 또는systemd-logind.service다른 여러 서비스의 장애를 야기할 가능성이 높아 인터넷을 뒤져보았지만 관련 없는 답변만 찾았습니다.

Journalctl -u 서비스에 로그인

이것은 망각 속으로 인쇄되는 유일한 관련 줄입니다.

Aug 23 13:04:14 LinuxJD systemd[132]: systemd-logind.service: **Failed to set up mount namespacing: /run/systemd/unit-root/proc: Permission denied**
Aug 23 13:04:14 LinuxJD systemd[132]: systemd-logind.service: Failed at step NAMESPACE spawning /lib/systemd/systemd-logind: Permission denied
Aug 23 13:04:14 LinuxJD systemd[1]: systemd-logind.service: Main process exited, code=exited, status=226/NAMESPACE
Aug 23 13:04:14 LinuxJD systemd[1]: systemd-logind.service: Failed with result 'exit-code'.
Aug 23 13:04:14 LinuxJD systemd[1]: Failed to start User Login Management.

보시다시피 날짜는 8월 23일 입니다. 농담으로 제가 얼마나 게으른지 아시겠지만 며칠 전에 고치기 시작했습니다. 이전에는 시작 시 오류가 표시되지 않았지만 서비스 섹션에 알 수 없는 lvalue에 대한 일부 경고가 인쇄되었으므로 무시하십시오. 변수 이름에는 ProtectProc, ProtectKernelLogs 등이 포함됩니다.

Journalctl -u sys-kernel-config.mount

-- Journal begins at Mon 2022-08-22 10:01:37 WEST, ends at Sun 2022-09-04 13:23:49 WEST. --
Aug 22 10:01:37 LinuxJD systemd[1]: Mounting Kernel Configuration File System...
Aug 22 10:01:37 LinuxJD mount[66]: mount: /sys/kernel/config: permission denied.
Aug 22 10:01:37 LinuxJD systemd[1]: sys-kernel-config.mount: Mount process exited, code=exited, status=32/n/a
Aug 22 10:01:37 LinuxJD systemd[1]: sys-kernel-config.mount: Failed with result 'exit-code'.
Aug 22 10:01:37 LinuxJD systemd[1]: Failed to mount Kernel Configuration File System.
-- Boot 5e947e1d71c347de842d58ff83346b46 --
Aug 23 13:04:12 LinuxJD mount[67]: mount: /sys/kernel/config: cannot mount configfs read-only.
-- Boot 7cb1cef78bec4260b9b08de48728723f --
Aug 29 23:07:53 LinuxJD mount[67]: mount: /sys/kernel/config: cannot mount configfs read-only.
-- Boot f52c4a767b8343808ac8b2ae0c459494 --
Aug 30 17:03:10 LinuxJD mount[66]: mount: /sys/kernel/config: cannot mount configfs read-only.
-- Boot 3533ad0f42464deda95142c7eea10fc8 --
Aug 30 17:16:20 LinuxJD systemd[1]: Mounting Kernel Configuration File System...
Aug 30 17:16:20 LinuxJD mount[69]: mount: /sys/kernel/config: cannot mount configfs read-only.
Aug 30 17:16:20 LinuxJD systemd[1]: sys-kernel-config.mount: Mount process exited, code=exited, status=32/n/a
Aug 30 17:16:20 LinuxJD systemd[1]: sys-kernel-config.mount: Failed with result 'exit-code'.
Aug 30 17:16:20 LinuxJD systemd[1]: Failed to mount Kernel Configuration File System.

여기서는 할 말이 많지 않습니다. sys/kernel/에 어떤 종류의 설치가 발생했는지조차 모릅니다.

Journalctl -u sys-kernel-debug.mount

-- Journal begins at Mon 2022-08-22 10:01:37 WEST, ends at Sun 2022-09-04 13:25:01 WEST. --
Aug 22 10:01:37 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot 5e947e1d71c347de842d58ff83346b46 --
Aug 23 13:04:12 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot 7cb1cef78bec4260b9b08de48728723f --
Aug 29 23:07:53 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot f52c4a767b8343808ac8b2ae0c459494 --
Aug 30 17:03:10 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot 3533ad0f42464deda95142c7eea10fc8 --
Aug 30 17:16:20 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot adf79f39689b4cad9b0c5f25601a1e16 --
Aug 30 17:36:16 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot 7670161016694d8cbebb490d8da76048 --
Aug 30 17:50:51 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot 33d84ff5be5845fa87731c4ea0042c99 --
Sep 04 00:38:07 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot e2851d364555457a873de23656622b8b --
Sep 04 00:49:40 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot a7fff694cd6d4585b911d0ee40275b3c --
Sep 04 00:54:00 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
-- Boot 4fefd1bd372d47218eed549cd0044aa9 --
Sep 04 01:00:18 LinuxJD mount[55]: mount: /sys/kernel/debug: permission denied.
Sep 04 01:00:18 LinuxJD systemd[1]: sys-kernel-debug.mount: Mount process exited, code=exited, status=32/n/a
Sep 04 01:00:18 LinuxJD systemd[1]: sys-kernel-debug.mount: Failed with result 'exit-code'.
Sep 04 01:00:18 LinuxJD systemd[1]: Failed to mount Kernel Debug File System.

나머지는 어떻습니까?

댓글에서 제안한다면 로그를 게시하겠습니다. 하지만 이 세 가지가 많은 문제를 일으킬 가능성이 있다고 생각합니다. 예를 들어 modprobe는 너무 여러 번 재실행을 시도하여 실패했다고 말합니다.

문제를 해결해 보세요.

콘텐츠를 업데이트하고 업그레이드해 보았습니다.

Hit:1 http://ftp.pt.debian.org/debian bullseye InRelease
Get:2 https://packages.microsoft.com/debian/11/prod bullseye InRelease [10.5 kB]
Get:3 https://packages.microsoft.com/debian/11/prod bullseye/main arm64 Packages [15.8 kB]
Get:4 https://packages.microsoft.com/debian/11/prod bullseye/main amd64 Packages [77.8 kB]
Get:5 https://packages.microsoft.com/debian/11/prod bullseye/main armhf Packages [17.7 kB]

거울의 영향이죠. 나는 컨테이너를 닫고 열어 보았습니다. 나는 pyhole 컨테이너를 삭제하려고 시도했고, sudo systemctl log-level debug답을 얻을 수 있는 더 많은 텍스트를 제공하기를 바라면서 몇 가지 systemctl 명령을 시도했습니다 . /proc 항목에도 몇 가지 문제가 있어 아무것도 시작할 수 없기 때문에 docker와 docker-compose를 제거했습니다. 여러 번 다시 시작을 시도했고 마침내 문제가 있는지 확인하기 위해 시작 시 nginx, php, posgresql 등과 관련된 일부 서비스를 종료했습니다.

진행 상황을 보여주는 유일한 것은... 로그인 서비스를 보호하는 것입니다. Enter 키를 눌렀을 때 해당 명령이 수행하는 작업이 무엇인지는 정확히 모르겠지만 일시적으로 아무데도 심볼릭 링크를 연결하지 않아 또 다른 문제가 발생하는 것 같습니다. 하지만 이제는 로그인할 때 눈에 띄는 지연이 없습니다.

그런 다음 계속해서 systemctl unmask systemd-logind를 실행했는데 문제가 다시 발생했습니다.

간단히 말해서:

서버에 로그인할 때 눈에 띄는 지연이 있고, systemd-logind, sys-kernel-config.mount, sys-kernel-debug.mount를 혼합하면 많은 서비스 오류가 발생하는 것 같습니다. /proc 폴더가 관련되어 마운트될 때 항상 많은 오류가 권한 부족을 나타냅니다.