Example log:
Jul 22 15:55:21 fedora systemd[1]: a1.service: Found ordering cycle on a2.service/start
Jul 22 15:55:21 fedora systemd[1]: a1.service: Found dependency on a3.service/start
Jul 22 15:55:21 fedora systemd[1]: a1.service: Found dependency on a1.service/start
Jul 22 15:55:21 fedora systemd[1]: a1.service: Job a2.service/start deleted to break ordering cycle starting with a1.service/start
Jul 22 15:55:21 fedora systemd[1]: Starting a1.service...
Jul 22 15:55:21 fedora systemd[1]: Started a1.service.
Example log entry:
Sat 2017-07-22 15:55:21.372389 EDT [s=0004bb6302d94ac3aa69987fb6157338;i=9ae;b=a96eb6153d4f4f3686c7b4
_BOOT_ID=a96eb6153d4f4f3686c7b4db8a432908
_MACHINE_ID=ad18f69b80264b52bb3b766240742383
_HOSTNAME=fedora
PRIORITY=3
SYSLOG_FACILITY=3
SYSLOG_IDENTIFIER=systemd
_UID=0
_GID=0
_PID=1
_TRANSPORT=journal
_CAP_EFFECTIVE=3fffffffff
_COMM=systemd
_EXE=/usr/lib/systemd/systemd
_SYSTEMD_CGROUP=/init.scope
_SYSTEMD_UNIT=init.scope
_SYSTEMD_SLICE=-.slice
_SELINUX_CONTEXT=system_u:system_r:kernel_t:s0
CODE_FILE=../src/core/transaction.c
CODE_FUNC=transaction_verify_order_one
UNIT=a3.service
UNIT=a1.service
UNIT=a2.service
CODE_LINE=430
MESSAGE=a1.service: Job a2.service/start deleted to break ordering cycle starting with a1.service
_CMDLINE=/usr/lib/systemd/systemd --system --deserialize 28
_SOURCE_REALTIME_TIMESTAMP=1500753321372389
This should make it easier to see when any of the units are involved in an
ordering cycle.
Fixes#6336.
v2:
- also update the "Unable to break cycle" message.
Unit.JobTimeoutSec starts when a job is enqueued in a transaction. The
introduced distinct Unit.JobRunningTimeoutSec starts only when the job starts
running (e.g. it groups all Exec* commands of a service or spans waiting for a
device period.)
Unit.JobRunningTimeoutSec is intended to be used by default instead of
Unit.JobTimeoutSec for device units where such behavior causes less confusion
(consider a job for a _netdev mount device, with this change the timeout will
start ticking only after the network is ready).
This is important if a job was queued for a unit but not yet started.
Without this, the job will be canceled and is never executed even though
IgnoreOnIsolate it set to 'true'.
We currently generate log message about unit being started even when
unit was started already and job didn't do anything. This is because job
was requested explicitly and hence became anchor job of the transaction
thus we could not eliminate it. That is fine but, let's not pollute
journal with useless log messages.
$ systemctl start systemd-resolved
$ systemctl start systemd-resolved
$ systemctl start systemd-resolved
Current state:
$ journalctl -u systemd-resolved | grep Started
May 05 15:31:42 rawhide systemd[1]: Started Network Name Resolution.
May 05 15:31:59 rawhide systemd[1]: Started Network Name Resolution.
May 05 15:32:01 rawhide systemd[1]: Started Network Name Resolution.
After patch applied:
$ journalctl -u systemd-resolved | grep Started
May 05 16:42:12 rawhide systemd[1]: Started Network Name Resolution.
Fixes#1723
If the error code ever leaks (we print the strerror error instead of providing
our own), the message for ESHUTDOWN is "Cannot send after transport endpoint
shutdown", which can be misleading. In particular it suggest that some
mishandling of the dbus connection occured. Let's change that to ERFKILL which
has the advantage that a) it sounds implausible as actual error, b) has the
connotation of disabling something manually.
This replaces the old function call manager_is_reloading_or_reexecuting() which
was used only at very few places. Use the new macro wherever we check whether
we are reloading. This should hopefully make things a bit more readable, given
the nature of Manager:n_reloading being a counter.
This commit changes the mapping of the BUS_ERROR_UNIT_MASKED error to ESHUTDOWN. This error is used whenever the
transaction engine is asked to operate on a masked unit. ESHUTDOWN is what is used for the similar case when the unit
file enable/disable logic hits a masked unit file, hence is a natural candidate to be used here too.
Background: before this patch both "job type not applicable" and "unit masked" where mapped to EBADR, which
transaction_add_job_and_dependencies() then checked for. It actually wanted to check exclusively for the former error
condition, not the latter but due to the same mapping this failed to work.
This patch semi-undoes an accidental change made in caffa4ef70, however restores the
error number to ESHUTDOWN instead of the original ENOSYS (for the reasons indicated above).
To make this easier to grok for the future, I added comments to explaining which error conditions are checked for.
Fixes: #2315
If a unit was pulled by a Wants= dependency but its unit file was not
present then we logged this as an error.
However Wants= might be used to configure a soft/optional dependency
on another unit, ie. start an optional service only if it's installed
otherwise simply skip it. In this case emitting an error doesn't look
appropriate.
But it's still an error if the optional dependency exists but its
activation fails for any reasons.
When masking is used to prevent a unit from being loaded,
every transaction with dependent units would generate a warning.
Downgrade this warning to debug level.
transaction_add_job_and_dependencies only generated a few return
values found in the table in bus_common_errors.c, and EADDRNOTAVAIL
is not one of them, so do not try to suppress EADDRNOTAVAIL.
https://bugzilla.redhat.com/show_bug.cgi?id=1278264
Now that we don't have RequiresOverridable= and RequisiteOverridable=
dependencies anymore, we can get rid of tracking the "override" boolean
for jobs in the job engine, as it serves no purpose anymore.
While we are at it, fix some error messages we print when invoking
functions that take the override parameter.
As discussed at systemd.conf 2015 and on also raised on the ML:
http://lists.freedesktop.org/archives/systemd-devel/2015-November/034880.html
This removes the two XyzOverridable= unit dependencies, that were
basically never used, and do not enhance user experience in any way.
Most folks looking for the functionality this provides probably opt for
the "ignore-dependencies" job mode, and that's probably a good idea.
Hence, let's simplify systemd's dependency engine and remove these two
dependency types (and their inverses).
The unit file parser and the dbus property parser will now redirect
the settings/properties to result in an equivalent non-overridable
dependency. In the case of the unit file parser we generate a warning,
to inform the user.
The dbus properties for this unit type stay available on the unit
objects, but they are now hidden from usual introspection and will
always return the empty list when queried.
This should provide enough compatibility for the few unit files that
actually ever made use of this.
Let's underline the header line of the table shown by cgtop, how it is
customary for tables. In order to do this, let's introduce new ANSI
underline macros, and clean up the existing ones as side effect.
Previously, if a service A depended on a service B via Requires=, and A
was not running and B restarted this would trigger a start of A as well,
since the restart was propagated as restart independently of the state
of A.
This patch ensures that a restart of B would be propagated as a
try-restart to A, thus not changing its state if it isn't up.
http://lists.freedesktop.org/archives/systemd-devel/2015-May/032061.html
This reverts the primary effect of be7d9ff730.
After all Requisite= should be close to Requires=, without the one
exception that it doesn't pull in dependencies on start. However,
reverse deps on stop/restart should be treated the same way as for
Restart=, and this is already documented in the man page, hence stick to
it.
http://lists.freedesktop.org/archives/systemd-devel/2015-May/032049.html
This changes log_unit_info() (and friends) to take a real Unit* object
insted of just a unit name as parameter. The call will now prefix all
logged messages with the unit name, thus allowing the unit name to be
dropped from the various passed romat strings, simplifying invocations
drastically, and unifying log output across messages. Also, UNIT= vs.
USER_UNIT= is now derived from the Manager object attached to the Unit
object, instead of getpid(). This has the benefit of correcting the
field for --test runs.
Also contains a couple of other logging improvements:
- Drops a couple of strerror() invocations in favour of using %m.
- Not only .mount units now warn if a symlinks exist for the mount
point already, .automount units do that too, now.
- A few invocations of log_struct() that didn't actually pass any
additional structured data have been replaced by simpler invocations
of log_unit_info() and friends.
- For structured data a new LOG_UNIT_MESSAGE() macro has been added,
that works like LOG_MESSAGE() but prefixes the message with the unit
name. Similar, there's now LOG_LINK_MESSAGE() and
LOG_NETDEV_MESSAGE().
- For structured data new LOG_UNIT_ID(), LOG_LINK_INTERFACE(),
LOG_NETDEV_INTERFACE() macros have been added that generate the
necessary per object fields. The old log_unit_struct() call has been
removed in favour of these new macros used in raw log_struct()
invocations. In addition to removing one more function call this
allows generated structured log messages that contain two object
fields, as necessary for example for network interfaces that are
joined into another network interface, and whose messages shall be
indexed by both.
- The LOG_ERRNO() macro has been removed, in favour of
log_struct_errno(). The latter has the benefit of ensuring that %m in
format strings is properly resolved to the specified error number.
- A number of logging messages have been converted to use
log_unit_info() instead of log_info()
- The client code in sysv-generator no longer #includes core code from
src/core/.
- log_unit_full_errno() has been removed, log_unit_full() instead takes
an errno now, too.
- log_unit_info(), log_link_info(), log_netdev_info() and friends, now
avoid double evaluation of their parameters
This is yet another attempt to fix coldplugging order (more especially,
the problem which happens when one creates a job during coldplugging and
it references a not-yet-coldplugged unit).
Now we forcibly coldplug all units which participate in jobs. This
is a superset of previously implemented handling of the UNIT_TRIGGERS
dependencies, so that handling is removed.
http://lists.freedesktop.org/archives/systemd-devel/2015-April/031212.htmlhttps://bugs.freedesktop.org/show_bug.cgi?id=88401 (once again)
This patch removes includes that are not used. The removals were found with
include-what-you-use which checks if any of the symbols from a header is
in use.
As a followup to 086891e5c1 "log: add an "error" parameter to all
low-level logging calls and intrdouce log_error_errno() as log calls
that take error numbers", use sed to convert the simple cases to use
the new macros:
find . -name '*.[ch]' | xargs sed -r -i -e \
's/log_(debug|info|notice|warning|error|emergency)\("(.*)%s"(.*), strerror\(-([a-zA-Z_]+)\)\);/log_\1_errno(-\4, "\2%m"\3);/'
Multi-line log_*() invocations are not covered.
And we also should add log_unit_*_errno().
- Rename log_meta() → log_internal(), to follow naming scheme of most
other log functions that are usually invoked through macros, but never
directly.
- Rename log_info_object() to log_object_info(), simply because the
object should be before any other parameters, to follow OO-style
programming style.
The previous fix e0312f4db "core: fix check for transaction
destructiveness" broke test-engine (noticed by Zbyszek).
Apparently I had a wrong idea of the intended semantics of --fail.
The manpage says the operation should fail if it "conflicts with a
pending job (more specifically: causes an already pending start job to
be reversed into a stop job or vice versa)".
So let's check job_type_is_conflicting, instead of !is_superset.
This makes both test-engine and TEST-03-JOBS pass again.
When checking if the transaction is destructive, we need to check if the
previously installed job is a superset of the new job (and hence the new
job will fold into the installed one without changing it), not the other
way around.
This way they always show up together with 'Found ordering cycle...'.
Ordering cycles are a serious error and a major pain to debug. If
quiet is enabled, only the first and the last line of output are
shown:
systemd[1]: Found ordering cycle on basic.target/start
systemd[1]: Breaking ordering cycle by deleting job timers.target/start
systemd[1]: Job timers.target/start deleted to break ordering cycle starting with basic.target/start
which isn't particularly enlightening. So just show the whole message
at the same level.
https://bugzilla.redhat.com/show_bug.cgi?id=1158206
It is redundant to store 'hash' and 'compare' function pointers in
struct Hashmap separately. The functions always comprise a pair.
Store a single pointer to struct hash_ops instead.
systemd keeps hundreds of hashmaps, so this saves a little bit of
memory.
Patch fixes some incorrect-looking code in transaction.c.
It could fix cases where Debian users with bad package configurations
had systemd go into an infinite loop printing messages about breaking an
ordering cycle, though I have not reproduced that problem myself.
transaction_verify_order_one() considers jobs/units outside current
transaction when checking whether ordering dependencies cause cycles.
It would also incorrectly try to break cycles at these jobs; this
cannot work, as the break action is to remove the job from the
transaction, which is a no-op if the job isn't part of the transaction
to begin with. The unit_matters_to_anchor() test also looks like it
would not work correctly for non-transaction jobs. Add a check to
verify that the unit is part of the transaction before considering a
job a candidate for deletion.
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=752259
Jouke Witteveen