Bug 1072494 - systemctl status fails with "Assertion 'p > 0' failed at src/journal/journal-file.c:2306, function test_object_offset(). Aborting."
systemctl status fails with "Assertion 'p > 0' failed at src/journal/journal-...
Status: RESOLVED WORKSFORME
Classification: openSUSE
Product: openSUSE Tumbleweed
Classification: openSUSE
Component: Basesystem
Current
Other Other
: P5 - None : Normal (vote)
: ---
Assigned To: systemd maintainers
E-mail List
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2017-12-12 21:20 UTC by Michael Albert
Modified: 2017-12-14 16:01 UTC (History)
1 user (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments
journalctl --verify fail (3.73 MB, application/gzip)
2017-12-14 14:41 UTC, Michael Albert
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Albert 2017-12-12 21:20:55 UTC
I am not sure how long this has been going on, and I really don't know how to debug it, but for, at least, all of kernel 4.14, anytime I try to check the status on a service using "sudo systemctl status ..." I get the error message "Assertion 'p > 0' failed at src/journal/journal-file.c:2306, function test_object_offset(). Aborting."

Otherwise, as far as I can tell, systemd seems to be working correctly, I just can't check the status on any service. I'm happy to provide any information that is helpful in diagnosing and fixing the problem.

Thanks!
Comment 1 Franck Bui 2017-12-13 14:34:29 UTC
Hi,

Can you run the failing command with gdb ?

You can try "gdb --args systemctl status ..." and type 'r'.

It should reach the assertion failure. At that point please show the output of 'bt' command.

Thanks.
Comment 2 Michael Albert 2017-12-13 15:16:19 UTC
Ok, so I tried to do that (I had to first install 'gdb"'...), then I got a bunch of errors that were all something like:

Missing separate debuginfo for /lib64/libm.so.6
Try: zypper install -C "debuginfo(build-id)=4438f52aca53cf30228d97c1be876fa7bf309f08"

I don't really know what running that zypper install -C command would do, so I didn't run them.

Eventually I got:

Assertion 'p > 0' failed at src/journal/journal-file.c:2306, function test_object_offset(). Aborting.

Program received signal SIGABRT, Aborted.
0x00007ffff74040d0 in raise () from /lib64/libc.so.6

I then entered 'bt' at the gdb prompt, and I got this:

#0  0x00007ffff74040d0 in raise () from /lib64/libc.so.6
#1  0x00007ffff74056b1 in abort () from /lib64/libc.so.6
#2  0x00007ffff7a123a4 in log_assert_failed_realm () from /usr/lib/systemd/libsystemd-shared-234.so
#3  0x00007ffff7ad0c01 in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#4  0x00007ffff7ad3585 in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#5  0x00007ffff7ad3b93 in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#6  0x00007ffff7ad54ee in journal_file_move_to_entry_by_offset_for_data () from /usr/lib/systemd/libsystemd-shared-234.so
#7  0x00007ffff7ac8fba in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#8  0x00007ffff7ac901e in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#9  0x00007ffff7ac91f5 in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#10 0x00007ffff7ac9379 in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#11 0x00007ffff7ac94d2 in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#12 0x00007ffff7ac932c in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#13 0x00007ffff7aca519 in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#14 0x00007ffff7acacf6 in ?? () from /usr/lib/systemd/libsystemd-shared-234.so
#15 0x00007ffff7a5d772 in show_journal_by_unit () from /usr/lib/systemd/libsystemd-shared-234.so
#16 0x00005555555673e1 in ?? ()
#17 0x00005555555720c5 in ?? ()
#18 0x0000555555573333 in ?? ()
#19 0x00007ffff7a2e97e in dispatch_verb () from /usr/lib/systemd/libsystemd-shared-234.so
#20 0x000055555555c994 in ?? ()
#21 0x00007ffff73eef4a in __libc_start_main () from /lib64/libc.so.6
#22 0x000055555555e46a in ?? ()

Let me know if this helps. Thanks!
Comment 3 Franck Bui 2017-12-13 15:51:24 UTC
(In reply to Michael Albert from comment #2)
> Ok, so I tried to do that (I had to first install 'gdb"'...), then I got a
> bunch of errors that were all something like:
> 
> Missing separate debuginfo for /lib64/libm.so.6
> Try: zypper install -C
> "debuginfo(build-id)=4438f52aca53cf30228d97c1be876fa7bf309f08"
> 
> I don't really know what running that zypper install -C command would do, so
> I didn't run them.

It was suggesting you to install the debuginfo package.

Please do so by running "zypper in systemd-debuginfo"

You may need to enable the debug repo: "zypper mr --enable repo-debug" or something like this.

> #22 0x000055555555e46a in ?? ()
> 
> Let me know if this helps. Thanks!

Unfortunately it's pretty unusable if you do not install the debug info package.
Comment 4 Michael Albert 2017-12-13 15:55:47 UTC
Ok, I installed systemd-debuginfo, and then I ran the same exercise. Here is the output of the bt command within gdb:

#0  0x00007ffff74040d0 in raise () from /lib64/libc.so.6
#1  0x00007ffff74056b1 in abort () from /lib64/libc.so.6
#2  0x00007ffff7a123a4 in log_assert_failed_realm (realm=realm@entry=LOG_REALM_SYSTEMD, text=text@entry=0x7ffff7b14aae "p > 0", 
    file=file@entry=0x7ffff7b15b45 "src/journal/journal-file.c", line=line@entry=2306, 
    func=func@entry=0x7ffff7b16ff0 <__PRETTY_FUNCTION__.14068> "test_object_offset") at src/basic/log.c:809
#3  0x00007ffff7ad0c01 in test_object_offset (f=f@entry=0x5555557b14f0, p=<optimized out>, needle=needle@entry=4123496)
    at src/journal/journal-file.c:2306
#4  0x00007ffff7ad3585 in generic_array_bisect (f=f@entry=0x5555557b14f0, first=<optimized out>, first@entry=3764136, n=n@entry=239, 
    needle=needle@entry=4123496, test_object=0x7ffff7ad0b90 <test_object_offset>, direction=direction@entry=DIRECTION_UP, ret=0x0, 
    offset=0x7fffffffd1b0, idx=0x0) at src/journal/journal-file.c:2045
#5  0x00007ffff7ad3b93 in generic_array_bisect_plus_one (f=f@entry=0x5555557b14f0, extra=3758416, first=3764136, n=240, 
    needle=needle@entry=4123496, test_object=test_object@entry=0x7ffff7ad0b90 <test_object_offset>, direction=DIRECTION_UP, ret=0x0, 
    offset=0x7fffffffd1b0, idx=0x0) at src/journal/journal-file.c:2277
#6  0x00007ffff7ad54ee in journal_file_move_to_entry_by_offset_for_data (f=f@entry=0x5555557b14f0, data_offset=<optimized out>, 
    p=p@entry=4123496, direction=direction@entry=DIRECTION_UP, ret=ret@entry=0x0, offset=offset@entry=0x7fffffffd1b0)
    at src/journal/journal-file.c:2714
#7  0x00007ffff7ac8fba in next_for_match (j=j@entry=0x55555578e8a0, m=m@entry=0x55555578fff0, f=f@entry=0x5555557b14f0, 
    after_offset=after_offset@entry=4123496, direction=direction@entry=DIRECTION_UP, ret=ret@entry=0x0, offset=0x7fffffffd1b0)
    at src/journal/sd-journal.c:524
#8  0x00007ffff7ac901e in next_for_match (j=j@entry=0x55555578e8a0, m=m@entry=0x55555578ffa0, f=f@entry=0x5555557b14f0, 
    after_offset=4123496, direction=direction@entry=DIRECTION_UP, ret=ret@entry=0x0, offset=0x7fffffffd240)
    at src/journal/sd-journal.c:534
#9  0x00007ffff7ac91f5 in next_for_match (j=j@entry=0x55555578e8a0, m=m@entry=0x55555578ff50, f=f@entry=0x5555557b14f0, 
    after_offset=after_offset@entry=4123496, direction=direction@entry=DIRECTION_UP, ret=ret@entry=0x0, offset=0x7fffffffd368)
    at src/journal/sd-journal.c:566
#10 0x00007ffff7ac9379 in find_location_for_match (j=j@entry=0x55555578e8a0, m=m@entry=0x55555578ff50, f=f@entry=0x5555557b14f0, 
    direction=direction@entry=DIRECTION_UP, ret=ret@entry=0x0, offset=offset@entry=0x7fffffffd368) at src/journal/sd-journal.c:687
#11 0x00007ffff7ac94d2 in find_location_for_match (j=j@entry=0x55555578e8a0, m=m@entry=0x55555578fba0, f=f@entry=0x5555557b14f0, 
    direction=direction@entry=DIRECTION_UP, ret=ret@entry=0x0, offset=offset@entry=0x7fffffffd408) at src/journal/sd-journal.c:641
#12 0x00007ffff7ac932c in find_location_for_match (j=j@entry=0x55555578e8a0, m=0x55555578f9d0, f=f@entry=0x5555557b14f0, 
    direction=direction@entry=DIRECTION_UP, ret=ret@entry=0x7fffffffd4b0, offset=offset@entry=0x7fffffffd4b8)
    at src/journal/sd-journal.c:679
#13 0x00007ffff7aca519 in find_location_with_matches (offset=0x7fffffffd4b8, ret=0x7fffffffd4b0, direction=DIRECTION_UP, 
    f=0x5555557b14f0, j=0x55555578e8a0) at src/journal/sd-journal.c:724
#14 next_beyond_location (direction=DIRECTION_UP, f=0x5555557b14f0, j=0x55555578e8a0) at src/journal/sd-journal.c:784
#15 real_journal_next (j=j@entry=0x55555578e8a0, direction=direction@entry=DIRECTION_UP) at src/journal/sd-journal.c:832
#16 0x00007ffff7acacf6 in real_journal_next_skip (j=j@entry=0x55555578e8a0, direction=direction@entry=DIRECTION_UP, skip=skip@entry=10)
---Type <return> to continue, or q <return> to quit---
    at src/journal/sd-journal.c:895
#17 0x00007ffff7acc84a in sd_journal_previous_skip (j=j@entry=0x55555578e8a0, skip=skip@entry=10) at src/journal/sd-journal.c:914
#18 0x00007ffff7a5d772 in show_journal (ellipsized=0x7fffffffde63, flags=<optimized out>, how_many=10, not_before=140877101, n_columns=0, 
    mode=OUTPUT_SHORT, j=<optimized out>, f=0x7ffff7783720 <_IO_2_1_stdout_>) at src/shared/logs-show.c:1039
#19 show_journal_by_unit (f=0x7ffff7783720 <_IO_2_1_stdout_>, unit=<optimized out>, mode=OUTPUT_SHORT, n_columns=0, not_before=140877101, 
    how_many=10, uid=0, flags=(OUTPUT_WARN_CUTOFF | OUTPUT_FULL_WIDTH | OUTPUT_COLOR | OUTPUT_BEGIN_NEWLINE), journal_open_flags=1, 
    system_unit=true, ellipsized=0x7fffffffde63) at src/shared/logs-show.c:1365
#20 0x00005555555673e1 in print_status_info (bus=0x555555786b20, i=<optimized out>, ellipsized=0x7fffffffde63)
    at src/systemctl/systemctl.c:4250
#21 0x00005555555720c5 in show_one (verb=<optimized out>, bus=0x555555786b20, path=<optimized out>, unit=<optimized out>, 
    show_properties=<optimized out>, new_line=<optimized out>, ellipsized=0x7fffffffde63) at src/systemctl/systemctl.c:5078
#22 0x0000555555573333 in show (argc=<optimized out>, argv=0x7fffffffe260, userdata=<optimized out>) at src/systemctl/systemctl.c:5311
#23 0x00007ffff7a2e97e in dispatch_verb (argc=<optimized out>, argv=0x7fffffffe258, verbs=0x55555577e060 <verbs>, userdata=0x0)
    at src/basic/verbs.c:92
#24 0x000055555555c994 in systemctl_main (argv=0x7fffffffe258, argc=3) at src/systemctl/systemctl.c:8289
#25 main (argc=3, argv=0x7fffffffe258) at src/systemctl/systemctl.c:8592

Hope that helps! Thanks!
Comment 5 Franck Bui 2017-12-14 13:37:09 UTC
Could you try to run "journactl --verify" ?
Comment 6 Michael Albert 2017-12-14 14:05:45 UTC
Sure. I just ran it, and I got a bunch of errors like this:

40c650: Invalid object                                                                                       
File corruption detected at /var/log/journal/40fba7f32a8e9bde469a5b4157bb64ab/user-1000@fb0b61ce7623450585c7da8fd17fd1f5-0000000000001101-00055fee5c6ac3d6.journal:40c650 (of 8388608 bytes, 50%).

I suppose that is my problem. Any idea on what to do/what caused it?

Thanks!
Comment 7 Franck Bui 2017-12-14 14:12:26 UTC
No idea sorry, at least I'll need to check the content of the corrupted journal file first.

Could you attach it ?
Comment 8 Michael Albert 2017-12-14 14:41:23 UTC
Created attachment 753065 [details]
journalctl --verify fail

Filename is system@00055d41ccab0776-40efcca036d1f121.journal~ before packing.
Comment 9 Michael Albert 2017-12-14 14:42:28 UTC
For the above attachment, I just chose one file. There are probably around 30 errors. The error for that file was;

a11750: Entry array not sorted at 21972 of 22698                                                             
File corruption detected at /var/log/journal/40fba7f32a8e9bde469a5b4157bb64ab/system@00055d41ccab0776-40efcca036d1f121.journal~:12f3ee8 (of
 33554432 bytes, 59%).

Do you need more log files?
Comment 10 Michael Albert 2017-12-14 15:06:39 UTC
Also, I'm happy to just blow away everything under /var/log/journal/ if that will likely fix the problem. Is there any reason that I shouldn't try that?
Comment 11 Franck Bui 2017-12-14 15:16:31 UTC
(In reply to Michael Albert from comment #10)
> Also, I'm happy to just blow away everything under /var/log/journal/ if that
> will likely fix the problem. Is there any reason that I shouldn't try that?

You could do that indeed, not sure if it will fit the attachment size limit though.

Or maybe you can just upload them somewhere and paste the link here.

Also it might be interesting to attach the coredump of systemctl as well. You can do so by inspecting the output of "coredumpctl" which will list the saved coredumps. If you can find the relevant one, use "coredumpctl dump xxx" to extract the coredump.

That said I'm really not sure to find what went wrong, you'll be warned ;)

You might want to open a bug against upstream if you need a quicker resolution.

Thanks.
Comment 12 Michael Albert 2017-12-14 15:36:36 UTC
An update on this. I just deleted all of my old journal files (basically anything with an @ in the name). Now journalctl --verify doesn't return any errors, and running 'sudo systemctl status avahi-daemon.service' gives correct output (and a lot faster than it used to).

I did lose my old journal files, but I'm not personally worried about that. I consider my own issue fixed, but I do believe that journalctl should be able to gracefully deal with corrupted files, and I'm not sure why it was failing.

Unfortunately, I don't have the skills to pursue this bug, so I'm not going to worry about it, and I'm fine with this being closed.
Comment 13 Franck Bui 2017-12-14 15:48:20 UTC
Well without the journal files, it's becoming hard to debug this.

Since you're ok to close this issue, I'll do that.

Sorry to see your journal files lost.
Comment 14 Michael Albert 2017-12-14 15:49:55 UTC
I still have the journal files in snapshots and backups, so they're not entirely gone. However, I'm fine closing this.
Comment 15 Franck Bui 2017-12-14 15:51:35 UTC
Well if you can upload them somewhere I'm fine to look at them and let this bug closed as well ;)
Comment 16 Michael Albert 2017-12-14 15:56:24 UTC
Ah, I just realized that snapper doesn't take snapshots of /var/log... And my backup strategy was built around snapper (mirroring snapshots to an external drive periodically), so my journals are definitely gone. I'm fine with it, I don't expect that I will have had any need to review them, but I wish I had made a backup before getting rid of them so that I could help with the debugging.

Sorry that I can't provide more information to help debug this!
Comment 17 Franck Bui 2017-12-14 16:01:25 UTC
We'll do better next time :P