Open BlackHole1 opened 5 months ago
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.
Recently, @l1shen also reported the same issue. Below are two vm logs.
[ 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
[ 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):
Description:
ovm
, it shuts down itself after about 2 seconds.read ready failed: EOF
Additional:
/opt/ready.command
file.M1 Pro
, System Version:Sonoma 14.3.1
. Reported by @Moskize91.Suppose:
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. 🤷‍♂️