[systemd-devel] Restart sequence: "systemctl restart rsyslog.service syslog.socket" often/sometimes fails

[Peter Valdemar Mørch]

First: Please let me know if this is an inappropriate place to ask this

# systemctl restart syslog.socket rsyslog.service

seems to always work. But

# systemctl restart rsyslog.service syslog.socket

, the opposite sequence, seems to sometimes fail (details below). I'm
wondering: Why is that?

And if I have a list of 20 PATTERNs, how do I devise the magical
pattern that ALWAYS works?

man systemctl[1] seems not to mention anything about sequence of PATTERN...s.

Depending on what hardware I try it occurs always, often, sometimes or
rarely. But trying it e.g. 1000 times seems to always trigger it at
sometimes. (A little scary that it doesn't always produce the same
result!!!)

BACKGROUND
============
I'm not quite certain that there is a need to restart syslog.socket
too. Let me know if that is the case.

But the question is still broader: How is the sequence of PATTERN...s
relevant for restart and how do I create a "good" sequence (even if we
omit syslog.socket).

Our app uses a number of system services (apache2, syslog-ng, mysql,
rabbitmq-server and some more). We have a randomly ordered list of
them. (Note we're actually using syslog-ng but the same ordering issue
also applies for rsyslog as shown above)

When we restore from a backup, we stop these services, put restored
data in place and start them again. Because of debian issue #751744:
"dh-systemd: postinst snippets should stop foo.socket during upgrades
too", syslog.socket is also in our list or it sometimes starts up
before we're done.

When we change configuration files, we restart that same list of
"names". So also syslog.socket.

DETAILS
=======
***@capmon:~# journalctl -xn --show-cursor -l --no-pager | tail -n 1
-- cursor: s=7cdc228fff4d49ada9fbebdfaf72e357;i=7a3;b=916402c8a5c747938b040a03c16b0e60;m=9e7556e8;t=50e404b5811ad;x=59fdfb3b30d4bdfa

***@capmon:~# systemctl restart rsyslog.service syslog.socket
Job for syslog.socket failed. See 'systemctl status syslog.socket' and
'journalctl -xn' for details.
A dependency job for rsyslog.service failed. See 'journalctl -xn' for details.

***@capmon:~# journalctl -xn
--after-cursor='s=7cdc228fff4d49ada9fbebdfaf72e357;i=7a3;b=916402c8a5c747938b040a03c16b0e60;m=9e7556e8;t=50e404b5811ad;x=59fdfb3b30d4bdfa'
-l --no-pager
-- Logs begin at Wed 2015-02-04 10:18:51 CET, end at Wed 2015-02-04
11:06:42 CET. --
Feb 04 11:06:42 capmon systemd[1]: Stopping System Logging Service...
-- Subject: Unit rsyslog.service has begun shutting down
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit rsyslog.service has begun shutting down.
Feb 04 11:06:42 capmon systemd[1]: Starting Syslog Socket.
-- Subject: Unit syslog.socket has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit syslog.socket has begun starting up.
Feb 04 11:06:42 capmon systemd[1]: Listening on Syslog Socket.
-- Subject: Unit syslog.socket has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit syslog.socket has finished starting up.
--
-- The start-up result is done.
Feb 04 11:06:42 capmon systemd[1]: Starting System Logging Service...
-- Subject: Unit rsyslog.service has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit rsyslog.service has begun starting up.
Feb 04 11:06:42 capmon systemd[1]: Stopping Syslog Socket.
-- Subject: Unit syslog.socket has begun shutting down
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit syslog.socket has begun shutting down.
Feb 04 11:06:42 capmon systemd[1]: Starting Syslog Socket.
-- Subject: Unit syslog.socket has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit syslog.socket has begun starting up.
Feb 04 11:06:42 capmon systemd[1]: Socket service rsyslog.service
already active, refusing.
Feb 04 11:06:42 capmon systemd[1]: Failed to listen on Syslog Socket.
-- Subject: Unit syslog.socket has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit syslog.socket has failed.
--
-- The result is failed.
Feb 04 11:06:42 capmon systemd[1]: Dependency failed for System Logging Service.
-- Subject: Unit rsyslog.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit rsyslog.service has failed.
--
-- The result is dependency.

***@capmon:~# systemctl status syslog.socket -l
syslog.socket - Syslog Socket
Loaded: loaded (/lib/systemd/system/syslog.socket; static)
Active: inactive (dead) since Wed 2015-02-04 11:06:42 CET; 2min 58s ago
Docs: man:systemd.special(7)
http://www.freedesktop.org/wiki/Software/systemd/syslog
Listen: /run/systemd/journal/syslog (Datagram)

Feb 04 11:06:42 capmon systemd[1]: Starting Syslog Socket.
Feb 04 11:06:42 capmon systemd[1]: Listening on Syslog Socket.
Feb 04 11:06:42 capmon systemd[1]: Stopping Syslog Socket.
Feb 04 11:06:42 capmon systemd[1]: Starting Syslog Socket.
Feb 04 11:06:42 capmon systemd[1]: Socket service rsyslog.service
already active, refusing.
Feb 04 11:06:42 capmon systemd[1]: Failed to listen on Syslog Socket.

# It looks to me like systemd should be able to establish the correct
restarts equence
***@capmon:~# systemctl list-dependencies rsyslog.service | head -n2
rsyslog.service
|-syslog.socket

ENVIRONMENT
============
We have a debian testing/jessie based system that is more complicated,
but the above seems very easy to reproduce:

Install a minimum fresh system with the Debian jessie Beta 2 installer[2]
Run the commands above (in a for loop with many iterations to ensure
that it occurs)

# dpkg-query -W | egrep 'systemd|syslog' | sort
libsystemd0:amd64 215-10
libsystemd-daemon0:amd64 208-8
libsystemd-journal0:amd64 208-8
libsystemd-login0:amd64 208-8
rsyslog 8.4.2-1
systemd 208-8
systemd-sysv 208-8

# lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description: Debian GNU/Linux testing/unstable
Release: testing/unstable
Codename: n/a

LINKS
=====
1: http://www.freedesktop.org/software/systemd/man/systemctl.html
2: http://cdimage.debian.org/cdimage/jessie_di_beta_2/amd64/iso-cd/debian-jessie-DI-b2-amd64-netinst.iso
3: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=751744

[Lennart Poettering]

Post by Peter Valdemar Mørch
First: Please let me know if this is an inappropriate place to ask this
# systemctl restart syslog.socket rsyslog.service
seems to always work. But
# systemctl restart rsyslog.service syslog.socket
, the opposite sequence, seems to sometimes fail (details below). I'm
wondering: Why is that?

Whats are the precise ordering and requirement deps between those two
services?

Note that the command will first enqueue the restart job for the first
mentioned service, then the restart job for the second service. It
will then wait for both jobs to complete. Depending on the deps it
might happen in the second case, that the service is first stopped,
and then the socket stopped, and then the service started again. Now,
when the socket is about to be started again too, the service will
already be up, but in non-socket-activation mode, at which point the
socket unit refuses to start up, in order to not corrupt the socket
the service created on its own without usage of socket activation.

This is something that can be fixed by adding stricter deps between
the service and the socket, so that the socket is always required to
be started before the service. Something for the respective package
maintainers upstream to fix.

Alternatively, only restart the service, don't bother with the socket...

Lennart

[Peter Valdemar Mørch]

Thank you Lennart for your explanation about the enqueuing. Sounds
reasonable. And helps me understand! :-)

Here I reply to you a little out of order:

On Wed, Feb 4, 2015 at 2:34 PM, Lennart Poettering

Post by Lennart Poettering
This is something that can be fixed by adding stricter deps between
the service and the socket, so that the socket is always required to
be started before the service. Something for the respective package
maintainers upstream to fix.

So have I understood this correctly: That the order matters *is* a
bug. Either in systemd (that provides
/lib/systemd/system/syslog.socket) or in syslog-ng and rsyslog that
provide e.g. /lib/systemd/system/syslog-ng.service ?

I'm worried that we manually have to figure out the correct ordering
of names to "systemctl restart PATTERN...." and would like to be able
to rely on systemctl to figure that out for us. Is that a reasonable
long-term expectation? (And the reason order/sequence isn't mentioned
in the man page?)

Post by Lennart Poettering
Alternatively, only restart the service, don't bother with the socket...

That in fact is what we might end up doing as it fixes this instance
of the problem short-term. I just want to understand what is going on
to determine if we're going to run into headaches long-term.

Post by Lennart Poettering
Whats are the precise ordering and requirement deps between those two
services?

I have no idea what they *should* be, but to show what they *are*,
here i show for syslog-ng. Seems to me that syslog-ng is clear about

Post by Lennart Poettering
cat /lib/systemd/system/syslog-ng.service

[Unit]
Description=System Logger Daemon
Documentation=man:syslog-ng(8)

[Service]
Type=notify
Sockets=syslog.socket
ExecStart=/usr/sbin/syslog-ng -F
ExecReload=/bin/kill -HUP $MAINPID
StandardOutput=null
Restart=on-failure

[Install]
WantedBy=multi-user.target
Alias=syslog.service

Post by Lennart Poettering
systemctl list-dependencies -l syslog-ng | cat

syslog-ng.service
● ├─syslog.socket
● ├─system.slice
● └─basic.target
● ├─paths.target
● │ └─acpid.path
● ├─slices.target
● │ ├─-.slice
● │ └─system.slice
● ├─sockets.target
● │ ├─acpid.socket
● │ ├─dbus.socket
● │ ├─systemd-initctl.socket
● │ ├─systemd-journald-dev-log.socket
● │ ├─systemd-journald.socket
● │ ├─systemd-shutdownd.socket
● │ ├─systemd-udevd-control.socket
● │ └─systemd-udevd-kernel.socket
● ├─sysinit.target
● │ ├─console-setup.service
● │ ├─debian-fixup.service
● │ ├─dev-hugepages.mount
● │ ├─dev-mqueue.mount
● │ ├─hdparm.service
● │ ├─kbd.service
● │ ├─keyboard-setup.service
● │ ├─kmod-static-nodes.service
● │ ├─networking.service
● │ ├─nfs-common.service
● │ ├─proc-sys-fs-binfmt_misc.automount
● │ ├─rpcbind.service
● │ ├─sys-fs-fuse-connections.mount
● │ ├─sys-kernel-config.mount
● │ ├─sys-kernel-debug.mount
● │ ├─systemd-ask-password-console.path
● │ ├─systemd-binfmt.service
● │ ├─systemd-journal-flush.service
● │ ├─systemd-journald.service
● │ ├─systemd-modules-load.service
● │ ├─systemd-random-seed.service
● │ ├─systemd-sysctl.service
● │ ├─systemd-tmpfiles-setup-dev.service
● │ ├─systemd-tmpfiles-setup.service
● │ ├─systemd-udev-trigger.service
● │ ├─systemd-udevd.service
● │ ├─systemd-update-utmp.service
● │ ├─udev-finish.service
● │ ├─vmware-tools.service
● │ ├─cryptsetup.target
● │ ├─local-fs.target
● │ │ ├─-.mount
● │ │ ├─jail-dev.mount
● │ │ ├─jail-proc.mount
● │ │ ├─jail-tftp-cliusers.mount
● │ │ ├─systemd-fsck-root.service
● │ │ └─systemd-remount-fs.service
● │ └─swap.target
● │ ├─dev-disk-by\x2duuid-37ac7cd8\x2d4a9c\x2d4118\x2d8192\x2d7ecaf6229d75.swap
● │ └─dev-disk-by\x2duuid-37ac7cd8\x2d4a9c\x2d4118\x2d8192\x2d7ecaf6229d75.swap
● └─timers.target
● └─systemd-tmpfiles-clean.timer

Thanks,

Peter

[Lennart Poettering]

Post by Peter Valdemar Mørch
On Wed, Feb 4, 2015 at 2:34 PM, Lennart Poettering

Post by Lennart Poettering
This is something that can be fixed by adding stricter deps between
the service and the socket, so that the socket is always required to
be started before the service. Something for the respective package
maintainers upstream to fix.

So have I understood this correctly: That the order matters *is* a
bug. Either in systemd (that provides
/lib/systemd/system/syslog.socket) or in syslog-ng and rsyslog that
provide e.g. /lib/systemd/system/syslog-ng.service ?

The latter.

Post by Peter Valdemar Mørch
I'm worried that we manually have to figure out the correct ordering
of names to "systemctl restart PATTERN...." and would like to be able
to rely on systemctl to figure that out for us. Is that a reasonable
long-term expectation? (And the reason order/sequence isn't mentioned
in the man page?)

systemd follows the relations expressed via the deps. If you don't
tell systemd the right deps, then things will be executed in any
order, and things might not work.

Post by Peter Valdemar Mørch
I have no idea what they *should* be, but to show what they *are*,
here i show for syslog-ng. Seems to me that syslog-ng is clear about

It would be a good idea to add Requires=syslog.socket here (or even
BindsTo=syslog.socket), as well as After=syslog.socket...

Post by Peter Valdemar Mørch

Post by Lennart Poettering
cat /lib/systemd/system/syslog-ng.service

[Unit]
Description=System Logger Daemon
Documentation=man:syslog-ng(8)
[Service]
Type=notify
Sockets=syslog.socket
ExecStart=/usr/sbin/syslog-ng -F
ExecReload=/bin/kill -HUP $MAINPID
StandardOutput=null
Restart=on-failure

Lennart

[Andrei Borzenkov]

В Wed, 4 Feb 2015 14:34:01 +0100

Post by Lennart Poettering

Post by Peter Valdemar Mørch
First: Please let me know if this is an inappropriate place to ask this
# systemctl restart syslog.socket rsyslog.service
seems to always work. But
# systemctl restart rsyslog.service syslog.socket
, the opposite sequence, seems to sometimes fail (details below). I'm
wondering: Why is that?

Whats are the precise ordering and requirement deps between those two
services?
Note that the command will first enqueue the restart job for the first
mentioned service, then the restart job for the second service. It
will then wait for both jobs to complete. Depending on the deps it
might happen in the second case, that the service is first stopped,
and then the socket stopped, and then the service started again. Now,
when the socket is about to be started again too, the service will
already be up, but in non-socket-activation mode, at which point the
socket unit refuses to start up, in order to not corrupt the socket
the service created on its own without usage of socket activation.

Is it possible to build transaction involving all units? Then it would
not depend on precise ordering, right?

[Lennart Poettering]

Post by Andrei Borzenkov
В Wed, 4 Feb 2015 14:34:01 +0100

Post by Lennart Poettering

Post by Peter Valdemar Mørch
First: Please let me know if this is an inappropriate place to ask this
# systemctl restart syslog.socket rsyslog.service
seems to always work. But
# systemctl restart rsyslog.service syslog.socket
, the opposite sequence, seems to sometimes fail (details below). I'm
wondering: Why is that?

Whats are the precise ordering and requirement deps between those two
services?
Note that the command will first enqueue the restart job for the first
mentioned service, then the restart job for the second service. It
will then wait for both jobs to complete. Depending on the deps it
might happen in the second case, that the service is first stopped,
and then the socket stopped, and then the service started again. Now,
when the socket is about to be started again too, the service will
already be up, but in non-socket-activation mode, at which point the
socket unit refuses to start up, in order to not corrupt the socket
the service created on its own without usage of socket activation.

Is it possible to build transaction involving all units? Then it would
not depend on precise ordering, right?

Michal Sekletar was working on a patch that made it possible to
enqueue multiple specified jobs within a single transaction, but this
has not been finished so far.

Lennart