[systemd-devel] job_type_lookup_merge assertion failure in systemd

Wed Nov 12 11:00:28 PST 2014

Forgot to explain my setup a bit:

Arch Linux, x86_64, systemd 217

On Wed, Nov 12, 2014 at 9:57 AM, Steven Noonan <steven at uplinklabs.net> wrote:
> 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