Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

vm exited for unknown reason #41

Open
BlackHole1 opened this issue Mar 30, 2024 · 2 comments
Open

vm exited for unknown reason #41

BlackHole1 opened this issue Mar 30, 2024 · 2 comments
Assignees
Labels
bug Something isn't working

Comments

@BlackHole1
Copy link
Member

BlackHole1 commented Mar 30, 2024

Description:

  • After launching ovm, it shuts down itself after about 2 seconds.
  • In the ovm.log file, there is an error message: read ready failed: EOF
  • In the vm.log file, it is observed that the shutdown process occurs after executing ready.service.

Additional:

  • ready.service executes the command in the /opt/ready.command file.
  • The issue has only occurred once. CPU: M1 Pro, System Version: Sonoma 14.3.1. Reported by @Moskize91.

Suppose:

  • It is suspected that the modification of system time using date -s in the command is causing the issue. However, there is no evidence, and it is only a simple inference based on the logs. 🤷‍♂️
@BlackHole1 BlackHole1 added the bug Something isn't working label Mar 30, 2024
@BlackHole1 BlackHole1 self-assigned this Mar 30, 2024
@BlackHole1
Copy link
Member Author

BlackHole1 commented Mar 30, 2024

The problem may not be with date -s, because based on the returned EOF error, the socket connection has already been established. So the issue may lie with socat.

BlackHole1 added a commit to BlackHole1/ovm that referenced this issue Mar 30, 2024
BlackHole1 added a commit that referenced this issue Mar 30, 2024
@BlackHole1
Copy link
Member Author

BlackHole1 commented Apr 30, 2024

Recently, @l1shen also reported the same issue. Below are two vm logs.

vm.0.log

 [  OK  ] Started gvisor-tap-vsock Network Traffic Forwarder.
          Starting OpenSSH server daemon...
 [  OK  ] Started vsock-guest-exec.service.
          Starting Podman Start All Container…th Restart Policy Set To Always...
 [    2.838630] gvforwarder[410]: time="2023-09-27T17:31:39+08:00" level=info msg="waiting for packets..."
 [    2.840516] gvforwarder[437]: udhcpc: started, v1.36.1
 [  OK  ] Found device /sys/devices/virtual/net/tap0.
 [    2.865212] gvforwarder[437]: udhcpc: broadcasting discover
 [    2.876176] gvforwarder[437]: udhcpc: broadcasting select for 192.168.127.2, server 192.168.127.1
 [    2.893079] gvforwarder[437]: udhcpc: lease of 192.168.127.2 obtained from 192.168.127.1, lease time 3600
 [    2.894812] ssh-keygen[413]: ssh-keygen: generating new host keys: RSA ECDSA ED25519
 [    2.899140] gvforwarder[450]: deleting routers
 [  OK  ] Started OpenSSH server daemon.
          Starting ssh-auth.service...
 [  OK  ] Started ssh-auth.service.
          Starting ready.service...
 [    2.910634] gvforwarder[450]: adding dns 192.168.127.1
 [    2.916211] podman[394]: time="2023-09-27T17:31:39+08:00" level=info msg="/usr/bin/podman filtering at log level info"
 [    2.917599] podman[417]: time="2023-09-27T17:31:39+08:00" level=info msg="/usr/bin/podman filtering at log level info"
+[    2.920701] sh[467]: Tue Apr 16 17:49:16 CST 2024
 [  OK  ] Removed slice Slice /system/modprobe.
 [  OK  ] Stopped target Login Prompts.
 [  OK  ] Stopped target Remote File Systems.
 [  OK  ] Stopped target Timer Units.
 [  OK  ] Stopped Discard unused filesystem blocks once a week.
 [  OK  ] Stopped Daily Cleanup of Temporary Directories.
 [  OK  ] Stopped Periodic XFS Online Metadata Check for All Filesystems.
 [  OK  ] Stopped target System Time Set.
          Stopping ACPI event daemon...
          Stopping Availability of block devices...
          Stopping D-Bus System Message Bus...
          Stopping Podman API Service...
          Stopping Serial Getty on hvc0...
          Stopping User Login Management...
          Stopping Load/Save OS Random Seed...
 [  OK  ] Stopped ACPI event daemon.
 [  OK  ] Stopped D-Bus System Message Bus.
 [  OK  ] Stopped Clean up podman transient data.
 [  OK  ] Stopped Podman API Service.
 [  OK  ] Stopped Serial Getty on hvc0.
 [  OK  ] Stopped Podman Start All Containers With Restart Policy Set To Always.
 [  OK  ] Stopped ready.service.
+[    2.987659] sh[470]: 2024/04/16 17:49:16 socat[470] N reading from and writing to stdio
+[    2.989378] sh[470]: 2024/04/16 17:49:16 socat[470] N opening connection to AF=40 cid:2 port:1026
+[    2.989664] sh[470]: 2024/04/16 17:49:16 socat[470] N socat_signal(): handling signal 15
 [  OK  ] Stopped Availability of block devices.
+[    2.990035] sh[470]: 2024/04/16 17:49:16 socat[470] W exiting on signal 15
 [  OK  ] Stopped User Login Management.
+[    2.994905] sh[470]: 2024/04/16 17:49:16 socat[470] N socat_signal(): finishing signal 15
+[    2.995066] sh[470]: 2024/04/16 17:49:16 socat[470] N exit(143)
 [  OK  ] Removed slice Slice /system/serial-getty.
 [    2.998806] sshd[453]: Server listening on :: port 22.
 [  OK  ] Stopped target Boot Completion Check.
 [    3.003453] sshd[453]: Server listening on 0.0.0.0 port 22.
 [    3.003615] podman[394]: time="2024-04-16T17:49:16+08:00" level=info msg="Received shutdown signal \"terminated\", terminating!" PID=394
 [    3.004248] podman[394]: time="2024-04-16T17:49:16+08:00" level=info msg="Invoking shutdown handler \"libpod\"" PID=394
 [  OK  ] Stopped target Network is Online.
 [    3.006877] acpid[388]: exiting
 [    3.007014] podman[417]: time="2024-04-16T17:49:16+08:00" level=info msg="Received shutdown signal \"terminated\", terminating!" PID=417
 [    3.007130] podman[417]: time="2024-04-16T17:49:16+08:00" level=info msg="Invoking shutdown handler \"libpod\"" PID=417
 [    3.007335] blkdeactivate[474]: Deactivating block devices:
          Stopping gvisor-tap-vsock Network Traffic Forwarder...
          Stopping ssh-auth.service...
          Stopping vsock-guest-exec.service...
 [  OK  ] Stopped vsock-guest-exec.service.
 [  OK  ] Stopped ssh-auth.service.
 [  OK  ] Stopped Load/Save OS Random Seed.
          Stopping Chrony Network Time Daemon...
 [    3.022844] sshd[453]: Received signal 15; terminating.
 [    3.157474] systemd-shutdown[1]: Syncing filesystems and block devices.
 [    3.171359] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
 [    3.174491] systemd-journald[274]: Received SIGTERM from PID 1 (systemd-shutdow).
 [    3.198771] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
 [    3.199799] systemd-shutdown[1]: Unmounting file systems.
 [    3.200425] (sd-remount)[532]: Remounting '/' read-only with options 'lowerdir=/mnt/rootfs,upperdir=/mnt/tmpfs/upperdir,workdir=/mnt/tmpfs/workdir'.
 [    3.209362] systemd-shutdown[1]: All filesystems unmounted.
 [    3.209480] systemd-shutdown[1]: Deactivating swaps.
 [    3.209934] systemd-shutdown[1]: All swaps deactivated.
 [    3.210001] systemd-shutdown[1]: Detaching loop devices.
 [    3.210336] systemd-shutdown[1]: All loop devices detached.
 [    3.210386] systemd-shutdown[1]: Stopping MD devices.
 [    3.210463] systemd-shutdown[1]: All MD devices stopped.
 [    3.210507] systemd-shutdown[1]: Detaching DM devices.
 [    3.210573] systemd-shutdown[1]: All DM devices detached.
 [    3.210611] systemd-shutdown[1]: All filesystems, swaps, loop devices, MD devices and DM devices detached.
 [    3.210795] systemd-shutdown[1]: Syncing filesystems and block devices.
 [    3.211348] systemd-shutdown[1]: Powering off.
 [    3.211624] reboot: Power down

vm.1.log

 [  OK  ] Started gvisor-tap-vsock Network Traffic Forwarder.
          Starting OpenSSH server daemon...
 [  OK  ] Started vsock-guest-exec.service.
          Starting Podman Start All Container…th Restart Policy Set To Always...
 [  OK  ] Started User Login Management.
 [    2.601788] gvforwarder[410]: time="2023-09-27T17:31:39+08:00" level=info msg="waiting for packets..."
 [  OK  ] Found device /sys/devices/virtual/net/tap0.
 [    2.608979] gvforwarder[438]: udhcpc: started, v1.36.1
 [    2.641215] gvforwarder[438]: udhcpc: broadcasting discover
 [    2.653341] gvforwarder[438]: udhcpc: broadcasting select for 192.168.127.2, server 192.168.127.1
 [    2.683277] gvforwarder[438]: udhcpc: lease of 192.168.127.2 obtained from 192.168.127.1, lease time 3600
 [    2.686819] gvforwarder[447]: deleting routers
 [    2.701361] gvforwarder[447]: adding dns 192.168.127.1
 [    2.739307] podman[394]: time="2023-09-27T17:31:39+08:00" level=info msg="/usr/bin/podman filtering at log level info"
 [    2.753576] podman[413]: time="2023-09-27T17:31:39+08:00" level=info msg="/usr/bin/podman filtering at log level info"
 [    2.789815] ssh-keygen[411]: ssh-keygen: generating new host keys: RSA ECDSA ED25519
 [  OK  ] Started OpenSSH server daemon.
          Starting ssh-auth.service...
 [    2.834524] sshd[460]: Server listening on :: port 22.
 [    2.835924] sshd[460]: Server listening on 0.0.0.0 port 22.
 [    2.878483] podman[413]: time="2023-09-27T17:31:39+08:00" level=info msg="Not using native diff for overlay, this may cause degraded  performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled"
 [    2.878718] podman[413]: time="2023-09-27T17:31:39+08:00" level=info msg="[graphdriver] using prior storage driver: overlay"
 [    2.878825] podman[394]: time="2023-09-27T17:31:39+08:00" level=info msg="Not using native diff for overlay, this may cause degraded  performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled"
 [    2.878876] podman[394]: time="2023-09-27T17:31:39+08:00" level=info msg="[graphdriver] using prior storage driver: overlay"
 [    2.924208] podman[413]: time="2023-09-27T17:31:39+08:00" level=info msg="Setting parallel job count to 13"
 [    2.924812] podman[394]: time="2023-09-27T17:31:39+08:00" level=info msg="Setting parallel job count to 13"
 [    2.925843] podman[394]: time="2023-09-27T17:31:39+08:00" level=info msg="Using systemd socket activation to determine API endpoint"
 [    2.925933] podman[394]: time="2023-09-27T17:31:39+08:00" level=info msg="API service listening on \"/run/podman/podman.sock\". URI: \"/ run/podman/podman.sock\""
 [  OK  ] Finished Podman Start All Container…With Restart Policy Set To Always.
 [  OK  ] Finished Clean up podman transient data.
 [  OK  ] Started ssh-auth.service.
          Starting ready.service...
+[    2.952467] sh[479]: Fri Apr 26 17:26:27 CST 2024
+[FAILED] Failed to start ready.service.
+See 'systemctl status ready.service' for details.
 [  OK  ] Stopped target Boot Completion Check.
 [  OK  ] Stopped target Login Prompts.
 [  OK  ] Stopped target Remote File Systems.
 [  OK  ] Stopped target Timer Units.
 [  OK  ] Stopped Discard unused filesystem blocks once a week.
 [  OK  ] Stopped Daily Cleanup of Temporary Directories.
 [  OK  ] Stopped Periodic XFS Online Metadata Check for All Filesystems.
 [  OK  ] Stopped target System Time Set.
          Stopping ACPI event daemon...
          Stopping Availability of block devices...
          Stopping D-Bus System Message Bus...
          Stopping gvisor-tap-vsock Network Traffic Forwarder...
          Stopping Podman Start All Container…th Restart Policy Set To Always...
          Stopping Podman API Service...
          Stopping Serial Getty on hvc0...
          Stopping ssh-auth.service...
          Stopping User Login Management...
          Stopping Load/Save OS Random Seed...
+[    2.984633] sh[481]: 2024/04/26 17:26:27 socat[481] N reading from and writing to stdio
+[    2.984854] sh[481]: 2024/04/26 17:26:27 socat[481] N opening connection to AF=40 cid:2 port:1026
+[    2.984952] sh[481]: 2024/04/26 17:26:27 socat[481] N successfully connected from local address AF=40 cid:4294967295 port:406156747
+[    2.985120] sh[481]: 2024/04/26 17:26:27 socat[481] N starting data transfer loop with FDs [0,1] and [5,5]
+[    2.985208] sh[481]: > 2024/04/26 17:26:27.000002921  length=6 from=0 to=5
+[    2.985304] sh[481]: Ready
+[    2.985375] sh[481]: 2024/04/26 17:26:27 socat[481] E write(5, 0xaaaae6514000, 6): Broken pipe
+[    2.985454] sh[481]: 2024/04/26 17:26:27 socat[481] N exit(1)
 [  OK  ] Stopped ACPI event daemon.
 [    2.987142] acpid[388]: exiting
 [    2.989587] blkdeactivate[483]: Deactivating block devices:
 [    2.993146] podman[394]: time="2024-04-26T17:26:27+08:00" level=info msg="Received shutdown signal \"terminated\", terminating!" PID=394
 [  OK  ] Stopped D-Bus System Message Bus.
 [    2.993575] podman[394]: time="2024-04-26T17:26:27+08:00" level=info msg="Invoking shutdown handler \"service\"" PID=394
 [    2.993735] podman[394]: time="2024-04-26T17:26:27+08:00" level=info msg="Invoking shutdown handler \"libpod\"" PID=394
 [  OK  ] Stopped Serial Getty on hvc0.
 [  OK  ] Stopped Podman API Service.
 [  OK  ] Stopped ssh-auth.service.
 [  OK  ] Stopped gvisor-tap-vsock Network Traffic Forwarder.
          Stopping OpenSSH server daemon...
 [    3.002954] sshd[460]: Received signal 15; terminating.
+You are in emergency mode. After logging in, type "journalctl -xb" to view
 system logs, "systemctl reboot" to reboot, or "exit"
 to continue bootup.
 Give root password for maintenance
 (or type Ctrl-D to continue): 

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

1 participant