[systemd-devel] job_type_lookup_merge assertion failure in systemd

[Steven Noonan]

Hi all,

I've been seeing this happen every now and then on a couple machines.
When I wake up in the morning and go to log in, I find X11 stopped,
and when I try to log in to the VT it hangs when trying to create a
session. I am forced to reset the box and then dig through logs on the
next boot. This is the cause:

Nov 12 08:01:01 dispater crond[12331]: pam_unix(crond:session):
session opened for user root by (uid=0)
Nov 12 08:01:01 dispater CROND[12332]: (root) CMD (run-parts /etc/cron.hourly)
Nov 12 08:01:01 dispater CROND[12331]: pam_unix(crond:session):
session closed for user root
Nov 12 08:03:37 dispater dhcpcd[1075]: br0: fe80::2472:37ff:fea0:49d2
is unreachable, expiring it
Nov 12 08:05:03 dispater dhcpcd[1075]: br0: Router Advertisement from
fe80::9844:a4ff:fe69:acd5
Nov 12 08:05:03 dispater dhcpcd[1075]: br0: adding address
2002:6898:6b85:beef:6a05:caff:fe0a:6ec2/64
Nov 12 08:05:03 dispater systemd[1]: Cannot add dependency job for
unit cups.socket, ignoring: Unit cups.socket failed to load: No such
file or directory.
Nov 12 08:05:03 dispater systemd[1]: Stopping Name Service Cache Daemon...
Nov 12 08:05:03 dispater systemd[1]: Assertion 'a >= 0 && a <
_JOB_TYPE_MAX_MERGING' failed at src/core/job.c:314, function
job_type_lookup_merge(). Aborting.
Nov 12 08:05:03 dispater systemd[1]: Caught <ABRT>, dumped core as pid 12419.
Nov 12 08:05:03 dispater systemd[1]: Freezing execution.
Nov 12 08:05:03 dispater systemd-coredump[12420]: Process 12419
(systemd) of user 0 dumped core.
Nov 12 08:05:08 dispater acpid[554]: client 608[0:0] has disconnected
Nov 12 08:05:08 dispater acpid[554]: client connected from 653[82:82]
Nov 12 08:05:08 dispater acpid[554]: 1 client rule loaded

I get an IPv6 router advertisement, then dhcpcd (which is spawned by
Arch's netctl for the connection) appears to trigger an nscd restart
somehow, although I can't find a hook responsible for doing that. When
the nscd restart is attempted, an assertion failure is hit in systemd.

systemd-coredump did pick up on it, but I'm not certain how useful the
dump actually is. Most of the variable contents are optimized out, the
best we can get cleanly seems to just be the stack trace, which is
this:

(gdb) bt
#0  0x00007f1fa89260c9 in raise () from /usr/lib/libpthread.so.0
#1  0x00007f1fa9a5b3c8 in crash.lto_priv.222 (sig=6) at src/core/main.c:168
#2  <signal handler called>
#3  0x00007f1fa85a6967 in raise () from /usr/lib/libc.so.6
#4  0x00007f1fa85a7d3a in abort () from /usr/lib/libc.so.6
#5  0x00007f1fa9a90012 in log_assert_failed
(text=text at entry=0x7f1fa9aa78b8 "a >= 0 && a < _JOB_TYPE_MAX_MERGING",
file=file at entry=0x7f1fa9a9a212 "src/core/job.c", line=line at entry=314,
func=func at entry=0x7f1fa9ab8370 <__PRETTY_FUNCTION__.15000>
"job_type_lookup_merge") at src/shared/log.c:718
#6  0x00007f1fa99e943f in job_type_lookup_merge (a=<optimized out>,
b=<optimized out>) at src/core/job.c:314
#7  0x00007f1fa9a330a5 in job_type_is_superset () at src/core/job.h:198
#8  transaction_is_destructive (e=<optimized out>, mode=<optimized
out>, tr=<optimized out>) at src/core/transaction.c:516
#9  transaction_activate (e=<optimized out>, mode=<optimized out>,
m=<optimized out>, tr=<optimized out>) at src/core/transaction.c:722
#10 manager_add_job (m=0x7f1fab518380, type=_JOB_TYPE_MAX_MERGING,
unit=0x6, mode=_JOB_MODE_INVALID, override=false, e=0x7f1fa9b07180
<buffer>, _ret=0x7fff46a422b0) at src/core/manager.c:1224
#11 0x00007f1fa9a1bbc5 in bus_unit_queue_job (bus=0x7f1fab5f9090,
message=0x7f1fab66dd20, u=0x7f1fab5b5820,
type=_JOB_TYPE_MAX_IN_TRANSACTION, mode=JOB_FAIL,
reload_if_possible=128, error=0x7fff46a42440) at
src/core/dbus-unit.c:777
#12 0x00007f1fa9a1bfe6 in bus_unit_method_start_generic
(bus=0x7f1fab5f9090, message=0x7f1fab66dd20, u=0x7f1fab5b5820,
job_type=_JOB_TYPE_MAX_IN_TRANSACTION,
reload_if_possible=reload_if_possible at entry=false,
error=0x7fff46a42440) at src/core/dbus-unit.c:383
#13 0x00007f1fa9a756c6 in method_start_unit_generic
(bus=0x7f1fab5f9090, message=0x7f1fab66dd20, m=0x7f1fab518380,
job_type=_JOB_TYPE_MAX_IN_TRANSACTION, reload_if_possible=<optimized
out>, error=0x7fff46a42440) at src/core/dbus-manager.c:478
#14 0x00007f1fa9a6b3ee in method_callbacks_run
(found_object=<optimized out>, require_fallback=<optimized out>,
c=<optimized out>, m=<optimized out>, bus=<optimized out>) at
src/libsystemd/sd-bus/bus-objects.c:400
#15 object_find_and_run.lto_priv.239 (bus=0x7f1fab5f9090,
m=0x7f1fab66dd20, p=0x6 <error: Cannot access memory at address 0x6>,
require_fallback=false, found_object=0x7fff46a425b0) at
src/libsystemd/sd-bus/bus-objects.c:1224
#16 0x00007f1fa9a85ace in bus_process_object (m=<optimized out>,
bus=0x7f1fab5f9090) at src/libsystemd/sd-bus/bus-objects.c:1340
#17 process_message (m=<optimized out>, bus=0x7f1fab5f9090) at
src/libsystemd/sd-bus/sd-bus.c:2409
#18 process_running (priority=0, ret=0x0, hint_priority=false,
bus=0x7f1fab5f9090) at src/libsystemd/sd-bus/sd-bus.c:2451
#19 bus_process_internal.constprop.164 (bus=0x7f1fab5f9090, ret=0x0,
priority=0, hint_priority=false) at
src/libsystemd/sd-bus/sd-bus.c:2640
#20 0x00007f1fa9a23b11 in sd_bus_process (ret=0x0, bus=<optimized
out>) at src/libsystemd/sd-bus/sd-bus.c:2659
#21 io_callback (s=<optimized out>, fd=<optimized out>,
revents=<optimized out>, userdata=<optimized out>) at
src/libsystemd/sd-bus/sd-bus.c:2918
#22 0x00007f1fa9a4e680 in source_dispatch (s=0x7f1fab607ee0) at
src/libsystemd/sd-event/sd-event.c:2103
#23 0x00007f1fa9a53bde in sd_event_dispatch (e=0x7f1fab5187b0) at
src/libsystemd/sd-event/sd-event.c:2460
#24 0x00007f1fa9a66590 in sd_event_run (timeout=<optimized out>,
e=<optimized out>) at src/libsystemd/sd-event/sd-event.c:2489
#25 manager_loop (m=0x7f1fab518380) at src/core/manager.c:2010
#26 0x00007f1fa99e6859 in main (argc=1, argv=0x7fff46a43098) at
src/core/main.c:1731

What's the best way to approach debugging this issue? Should I do a
debug build to get a better core dump and wait for this to happen
again?

- Steven