내 질문
비정상적인 종료에 대한 재시작/종료 로그는 어디에서 찾을 수 있나요?
내 상황
redhat 7.9 (3.10.0-1160.62.1.el7.x86_64)
업그레이드된 버전 에서는 redhat 6
간단한 sudo reboot
원인으로 인해 VM이 충돌했습니다. 아래 로그에서 이는 두 개의 연속된 SYSTEM_BOOT로 인한 비정상적인 종료로 인해 발생했음을 확인할 수 있습니다.
[root@rsvsiesigmprd02 wasadmin]# ausearch -i -m system_boot,system_shutdown | tail -7
type=SYSTEM_BOOT msg=audit(11/07/2022 06:18:15.281:6) : pid=765 uid=root auid=unset ses=unset subj=system_u:system_r:init_t:s0 msg=' comm=systemd-update-utmp exe=/usr/lib/systemd/systemd-update-utmp hostname=? addr=? terminal=? res=success'
----
type=SYSTEM_SHUTDOWN msg=audit(15/07/2022 03:12:06.064:5192) : pid=10697 uid=root auid=unset ses=unset subj=system_u:system_r:init_t:s0 msg=' comm=systemd-update-utmp exe=/usr/lib/systemd/systemd-update-utmp hostname=? addr=? terminal=? res=success'
----
type=SYSTEM_BOOT msg=audit(15/07/2022 08:38:48.151:6) : pid=767 uid=root auid=unset ses=unset subj=system_u:system_r:init_t:s0 msg=' comm=systemd-update-utmp exe=/usr/lib/systemd/systemd-update-utmp hostname=? addr=? terminal=? res=success'
----
type=SYSTEM_BOOT msg=audit(18/07/2022 06:17:40.034:6) : pid=767 uid=root auid=unset ses=unset subj=system_u:system_r:init_t:s0 msg=' comm=systemd-update-utmp exe=/usr/lib/systemd/systemd-update-utmp hostname=? addr=? terminal=? res=success'
또한 SSH를 통해 VM에 액세스할 수 없었고 최후의 수단은 VMWare를 통해 재부팅하고 하드 종료를 수행하는 것이었습니다.
로그에서 이 문제를 일으키는 내용을 찾을 수 없습니다. 나는 다음을 확인했다:
-
- /var/log/메시지
-
- 로그 제어
1. /var/log/messages
Jul 15 03:01:31 xxxxxxxxxx systemd: Started Session 722 of user ansible.
Jul 15 03:01:34 xxxxxxxxxx python: ansible-ansible.legacy.setup Invoked with filter=[] gather_subset=['all'] fact_path=/etc/ansible/facts.d gather_timeout=10
Jul 15 03:01:43 xxxxxxxxxx python: ansible-ansible.legacy.command Invoked with creates=None executable=None _uses_shell=False strip_empty_ends=True _raw_params=/usr/bin/package-cleanup -y --oldkernels --count=2 removes=None argv=None warn=False chdir=None stdin_add_newline=True stdin=None
Jul 15 03:01:53 xxxxxxxxxx python: ansible-ansible.legacy.yum Invoked with lock_timeout=30 update_cache=False conf_file=None exclude=[] allow_downgrade=False disable_gpg_check=False disable_excludes=None use_backend=auto state=latest disablerepo=[] skip_broken=False releasever=None autoremove=False download_dir=None enable_plugin=[] installroot=/ install_weak_deps=True name=['*'] download_only=False bugfix=False list=None install_repoquery=True update_only=False disable_plugin=[] enablerepo=[] security=True validate_certs=True
Jul 15 03:05:03 xxxxxxxxxx systemd-logind: New session 723 of user wasadmin.
Jul 15 03:05:03 xxxxxxxxxx systemd: Started Session 723 of user wasadmin.
Jul 15 03:05:04 xxxxxxxxxx systemd-logind: Removed session 723.
Jul 15 03:07:54 xxxxxxxxxx python: ansible-ansible.legacy.setup Invoked with filter=[] gather_subset=['all'] fact_path=/etc/ansible/facts.d gather_timeout=10
Jul 15 03:08:04 xxxxxxxxxx python: ansible-ansible.legacy.command Invoked with creates=None executable=None _uses_shell=False strip_empty_ends=True _raw_params=/sbin/shutdown -r +1 removes=None argv=None warn=False chdir=None stdin_add_newline=True stdin=None
Jul 15 03:08:04 xxxxxxxxxx systemd: Started Delayed Shutdown Service.
Jul 15 03:08:04 xxxxxxxxxx systemd-shutdownd: Shutting down at Fri 2022-07-15 03:09:04 CEST (reboot)...
Jul 15 03:08:04 xxxxxxxxxx systemd-shutdownd: Creating /run/nologin, blocking further logins...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping Session 721 of user root.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping NFS status monitor for NFSv2/3 locking....
Jul 15 03:09:04 xxxxxxxxxx systemd: Unmounting /opt/maximo/data...
Jul 15 03:09:04 xxxxxxxxxx systemd: Removed slice system-selinux\x2dpolicy\x2dmigrate\x2dlocal\x2dchanges.slice.
Jul 15 03:09:04 xxxxxxxxxx systemd: Unmounting /opt/maximo/sedif...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped Dump dmesg to /var/log/dmesg.
Jul 15 03:09:04 xxxxxxxxxx systemd: Unmounting /opt/maximo/agora...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping RPC bind service...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped target RPC Port Mapper.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping Session c2 of user wasadmin.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped target rpc_pipefs.target.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping Session 722 of user ansible.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped target Timers.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped Daily Cleanup of Temporary Directories.
Jul 15 03:09:04 xxxxxxxxxx systemd: Closed LVM2 poll daemon socket.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping Session 2 of user wasadmin.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped target Multi-User System.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping LSB: Starts and stops WebSphere Application Server instances...
Jul 15 03:09:04 xxxxxxxxxx umount: umount.nfs: /opt/maximo/data: device is busy
Jul 15 03:09:04 xxxxxxxxxx journal: IBM Java[2311]: JVMDUMP039I Traitement de l'événement de vidage "user", détails "" à 2022/07/15 03:09:04 - Veuillez patienter.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping LSB: Starts the Spacewalk Daemon...
Jul 15 03:09:04 xxxxxxxxxx journal: IBM Java[2311]: JVMDUMP032I La machine virtuelle Java a demandé un vidage Java en utilisant '/opt/dump/javacore.20220715.030904.2311.0001.txt' en réponse à un événement
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping Command Scheduler...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped target Login Prompts.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping Getty on tty1...
Jul 15 03:09:04 xxxxxxxxxx journal: IBM Java[3796]: JVMDUMP039I Traitement de l'événement de vidage "user", détails "" à 2022/07/15 03:09:04 - Veuillez patienter.
Jul 15 03:09:04 xxxxxxxxxx journal: IBM Java[2310]: JVMDUMP039I Traitement de l'événement de vidage "user", détails "" à 2022/07/15 03:09:04 - Veuillez patienter.
Jul 15 03:09:04 xxxxxxxxxx journal: IBM Java[3220]: JVMDUMP039I Traitement de l'événement de vidage "user", détails "" à 2022/07/15 03:09:04 - Veuillez patienter.
Jul 15 03:09:04 xxxxxxxxxx RSVSIESIGMPRD01ManagerNode_was.init: Stopping WebSphere Application Server - dmgr ...
Jul 15 03:09:04 xxxxxxxxxx journal: IBM Java[3796]: JVMDUMP032I La machine virtuelle Java a demandé un vidage Java en utilisant '/opt/IBM/WebSphere/AppServer/profiles/AppSrvUI01/javacore.20220715.030904.3796.0001.txt' en réponse à un événement
Jul 15 03:09:04 xxxxxxxxxx journal: IBM Java[3220]: JVMDUMP032I La machine virtuelle Java a demandé un vidage Java en utilisant '/opt/IBM/WebSphere/AppServer/profiles/dmgr/javacore.20220715.030904.3220.0001.txt' en réponse à un événement
Jul 15 03:09:04 xxxxxxxxxx journal: IBM Java[2310]: JVMDUMP032I La machine virtuelle Java a demandé un vidage Java en utilisant '/opt/dump/javacore.20220715.030904.2310.0001.txt' en réponse à un événement
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping LSB: Starts and stops IHS...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping ACPI Event Daemon...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped Resets System Activity Logs.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping Zabbix Agent...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping System Logging Service...
Jul 15 08:38:30 xxxxxxxxxx kernel: Initializing cgroup subsys cpuset
Jul 15 08:38:30 xxxxxxxxxx kernel: Initializing cgroup subsys cpu
Jul 15 08:38:30 xxxxxxxxxx kernel: Initializing cgroup subsys cpuacct
Jul 15 08:38:30 xxxxxxxxxx kernel: Linux version 3.10.0-1160.62.1.el7.x86_64 ([email protected]) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-44) (GCC) ) #1 SMP Wed Mar 23 09:04:02 UTC 2022
Jul 15 08:38:30 xxxxxxxxxx kernel: Command line: root=/dev/mapper/vg_main-lv_root ro rd.luks=0 rd.lvm.lv=vg_main/lv_swap rd.md=0 rd.locale.LANG=fr_FR.UTF-8 vconsole.font=latarcyrheb-sun16 KEYBOARDTYPE=pc vconsole.keymap=fr-latin9 crashkernel=auto rd.lvm.lv=vg_main/lv_root rd.dm=0 rhgb quiet LANG=fr_FR.UTF-8
Jul 15 08:38:30 xxxxxxxxxx kernel: Disabled fast string operations
Jul 15 08:38:30 xxxxxxxxxx kernel: e820: BIOS-provided physical RAM map:
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009f7ff] usable
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x000000000009f800-0x000000000009ffff] reserved
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x00000000000dc000-0x00000000000fffff] reserved
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x0000000000100000-0x00000000bfedffff] usable
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x00000000bfee0000-0x00000000bfefefff] ACPI data
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x00000000bfeff000-0x00000000bfefffff] ACPI NVS
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x00000000bff00000-0x00000000bfffffff] usable
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x00000000f0000000-0x00000000f7ffffff] reserved
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x00000000fec00000-0x00000000fec0ffff] reserved
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x00000000fffe0000-0x00000000ffffffff] reserved
Jul 15 08:38:30 xxxxxxxxxx kernel: BIOS-e820: [mem 0x0000000100000000-0x000000063fffffff] usable
Jul 15 08:38:30 xxxxxxxxxx kernel: NX (Execute Disable) protection: active
Jul 15 08:38:30 xxxxxxxxxx kernel: SMBIOS 2.4 present.
Jul 15 08:38:30 xxxxxxxxxx kernel: DMI: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 12/12/2018
Jul 15 08:38:30 xxxxxxxxxx kernel: Hypervisor detected: VMware
Jul 15 08:38:30 xxxxxxxxxx kernel: vmware: TSC freq read from hypervisor : 2893.203 MHz
Jul 15 08:38:30 xxxxxxxxxx kernel: vmware: Host bus clock speed read from hypervisor : 66000000 Hz
Jul 15 08:38:30 xxxxxxxxxx kernel: vmware: using sched offset of 7222055233 ns
Jul 15 08:38:30 xxxxxxxxxx kernel: e820: last_pfn = 0x640000 max_arch_pfn = 0x400000000
Jul 15 08:38:30 xxxxxxxxxx kernel: PAT configuration [0-7]: WB WC UC- UC WB WP UC- UC
Jul 15 08:38:30 xxxxxxxxxx kernel: total RAM covered: 31744M
==> 보시다시피 시스템이 3시부터 8시까지 다운되었습니다.
참고: 이 작업을 수행하면 sudo reboot -f
재부팅이 성공했습니다.
감사해요.
답변1
가독성을 높이기 위해 로그 줄이 래핑됩니다.
Jul 15 03:08:04 xxxxxxxxxx python: ansible-ansible.legacy.command Invoked with creates=None \
executable=None _uses_shell=False strip_empty_ends=True _raw_params=/sbin/shutdown -r +1 \
removes=None argv=None warn=False chdir=None stdin_add_newline=True stdin=None
shutdown -r +1
누군가 또는 무언가가 Ansible을 사용하여 전화를 걸고 있는 것 같습니다 .
닫기 전 마지막 메시지는 다음과 같습니다.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping LSB: Starts and stops IHS...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping ACPI Event Daemon...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopped Resets System Activity Logs.
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping Zabbix Agent...
Jul 15 03:09:04 xxxxxxxxxx systemd: Stopping System Logging Service...
...이는 통제된 폐쇄로 인해 많은 진전이 이루어졌음을 의미합니다. syslog 서비스가 중지된 후에는 다시 시작될 때까지 더 이상 로그 항목이 없습니다 /var/log/messages
. 영구 시스템 로깅을 활성화하면(디렉토리를 생성하여 /var/log/journal
) 를 사용하여 종료하기 전에 더 많은 항목을 볼 수 있습니다 journalctl
.
작업을 종료하기 전에 Ansible 작업이 실행 중인 것 같습니다 yum
.
Jul 15 03:01:53 xxxxxxxxxx python: ansible-ansible.legacy.yum Invoked with lock_timeout=30 \
update_cache=False conf_file=None exclude=[] allow_downgrade=False disable_gpg_check=False \
disable_excludes=None use_backend=auto state=latest disablerepo=[] skip_broken=False \
releasever=None autoremove=False download_dir=None enable_plugin=[] installroot=/ \
install_weak_deps=True name=['*'] download_only=False bugfix=False list=None \
install_repoquery=True update_only=False disable_plugin=[] enablerepo=[] security=True \
validate_certs=True
yum
이것이 커널 업데이트를 가져왔는지 확인하고, 그렇다면 initramfs 생성이 성공했는지 확인하는 것이 좋습니다 . 나는 이전에 RHEL 7.x에서 initramfs 생성이 실패한 상황을 본 적이 있다고 생각합니다. 예를 들어 yum
패키지 캐시로 인해 파일 시스템이 꽉 차서 새 커널로 부팅하지 못하기 때문입니다. 때로는 파일 시스템을 루트로 마운트하기 전에도 실패합니다. 읽기/쓰기 모드에 있었습니다. 이는 분명히 이 부팅 시도에 대해 로그가 기록되지 않음을 의미합니다.
이는 VMware 가상 머신이므로 하이퍼바이저(및/또는 가능한 경우 vSphere 관리) 로그는 시스템 충돌 후 발생한 상황을 자세히 설명할 수 있습니다. 아마도 예정된 하이퍼바이저 서비스 중단이 있었고 VMware 관리자는 중단 부분까지 VM 시작을 방지했습니다. 완료됐나요?
또한 시스템이 온라인 상태가 되고 NTP 시간 동기화가 활성화될 때까지 재부팅 직후 기록된 시간 값을 맹목적으로 신뢰하지 않습니다. 혼합된 Windows/Linux VMware 환경에서는 VMware 시간 동기화를 비활성화하는 것을 잊을 수 있습니다. 환경이 Windows 가상 머신에 의해 지배되는 경우 VMware 호스트는 현지 시간으로 시스템 시계를 실행할 수 있으며 가상 머신 가상 시계는 부팅 시 기본적으로 해당 시간으로 설정됩니다.
이 경우 NTP 동기화 서비스가 시작되면 사이트의 현재 UTC/DST 오프셋과 대략 동일할 수 있는 시작 시 시간 점프가 표시됩니다. 나중에 부팅 후 타임스탬프가 7월 15일 08:3x:xx에서 대략 7월 15일 03:xx:xx로 점프하는 경우 VM은 가상 하드웨어 시계가 UTC이고 Windows A를 실행하고 있다고 (잘못) 가정하도록 구성된 것입니다. UTC+4(+DST, 북반구) 또는 UTC+5(DST 없음) 시간대에 위치한 VMware 중심 환경입니다.
2022년 7월 15일 08:38:48.151:6의 시스템 시작과 2022년 7월 18일 06:17:40.034:6의 다음 시작 사이에 비정상적인 종료가 발생했습니다. 귀하의 /var/log/messages
발췌 내용은 해당 시간 간격을 다루지 않습니다.
비정상적인 종료로 인해 발생한 상황을 파악하려면 다음을 찾아야 합니다.2022년 7월 18일 06:17:40 이전의 마지막 로그 항목.
만약 있다면/var/log/messages
7월 15일 08:38:30 이후에는 더 이상 로그인이 불가능합니다., 그런 다음 가상 머신이 해킹되어 (서숙하지 않게) 루트킷되었을 가능성을 고려합니다. 이것이 사실로 밝혀지면 종료 시 충돌이 발생하는 것은 가상 머신의 루트킷 및/또는 기타 맬웨어의 부작용일 수 있지만 현재로서는 걱정할 필요가 가장 적을 것입니다.