[systemd-devel] I/O error on "systemctl kill -s HUP rsyslog.service"

[Harald Dunkel]

On 8/11/20 2:27 PM, Lennart Poettering wrote:
> 
> Can you run systemctl with SYSTEMD_LOG_LEVEL debug? Anything
> interesting in the debug output it generates then? I wonder where the
> I/O error comes from...
> 

Sure:

# export SYSTEMD_LOG_LEVEL=debug
# systemctl kill -s HUP rsyslog.service
Bus n/a: changing state UNSET → OPENING
Bus n/a: changing state OPENING → AUTHENTICATING
Bus n/a: changing state AUTHENTICATING → RUNNING
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=KillUnit cookie=1 reply_cookie=0 signature=ssi error-name=n/a error-message=n/a
Got message type=error sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=org.freedesktop.DBus.Error.IOError error-message=Input/output error
Failed to kill unit rsyslog.service: Input/output error
Bus n/a: changing state RUNNING → CLOSED

> i.e. question is if the error is client side. If it's coming from the
> server side, then the next thing to try would be to turn on debug
> logging with "systemd-analyze log-level debug" and reproduce the
> issue, then check if there's anything interesting in the logs.
> 
> Please provide the relevant log excerpts here then.
> 

/var/log/debug:

Aug 12 08:30:40 srvvm01 systemd[1]: Sent message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=n/a error-name=n/a error-message=n/a
Aug 12 08:30:40 srvvm01 systemd[1]: Bus private-bus-connection: changing state RUNNING → CLOSING
Aug 12 08:30:40 srvvm01 systemd[1]: Bus private-bus-connection: changing state CLOSING → CLOSED
Aug 12 08:30:40 srvvm01 systemd[1]: Got disconnect on private connection.
Aug 12 08:30:42 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:30:44 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:30:47 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:30:49 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:30:52 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:30:54 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:30:57 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:30:59 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:02 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:04 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:05 srvvm01 systemd[1]: Bus private-bus-connection: changing state UNSET → OPENING
Aug 12 08:31:05 srvvm01 systemd[1]: Bus private-bus-connection: changing state OPENING → AUTHENTICATING
Aug 12 08:31:05 srvvm01 systemd[1]: Accepted new private connection.
Aug 12 08:31:05 srvvm01 systemd[1]: Bus private-bus-connection: changing state AUTHENTICATING → RUNNING
Aug 12 08:31:05 srvvm01 systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=KillUnit cookie=1 reply_cookie=0 signature=ssi error-name=n/a error-message=n/a
Aug 12 08:31:05 srvvm01 systemd[1]: Sent message type=error sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=org.freedesktop.DBus.Error.IOError error-message=Input/output error
Aug 12 08:31:05 srvvm01 systemd[1]: Failed to process message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=KillUnit cookie=1 reply_cookie=0 signature=ssi error-name=n/a error-message=n/a: Input/output error
Aug 12 08:31:05 srvvm01 systemd[1]: Bus private-bus-connection: changing state RUNNING → CLOSING
Aug 12 08:31:05 srvvm01 systemd[1]: Bus private-bus-connection: changing state CLOSING → CLOSED
Aug 12 08:31:05 srvvm01 systemd[1]: Got disconnect on private connection.
Aug 12 08:31:07 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:09 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:12 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:14 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:17 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:19 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:22 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:24 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:27 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:29 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:32 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:34 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:37 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:39 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)
Aug 12 08:31:42 srvvm01 systemd[1]: inetd.service: Got notification message from PID 292 (WATCHDOG=1)


Hope this helps
Harri