[systemd-devel] Failed to get journal fields: Bad message

[Lennart Poettering]

On Mon, 27.02.17 08:29, Krzysztof Błaszkowski (kb at sysmikro.com.pl) wrote:

> > The journal file format is primarily an append-based format (though
> > some fields at the front are updated, to link the new additions
> > up). This makes it not too bad when it comes to disk corruptions, and
> > data up to the point of corruption should be readable pretty nicely
> > still.
> 
> well, the most interesting information is located beyond that point
> very often. 

Well, note that journald will stop writing to journal files as soon as
it notices a corruption of any kind, and will start new journal files,
leaving the old ones the way they are (thus not making them worse). We
also start new journal files in regular intervals, after a fixed time
interval or after a certain number of bytes wirtten, for whatever
comes first.

With that in place I am pretty sure our behaviour when it comes to
real-life corruptions these days isn't that bad: when something bad
happens, then we'll conserve in time what has been written already,
and if you destroy one file entirely what you loose will be bounded
both in time and in size.

But anyway, I get the impression that you don't like the journal out
of principle, and I am not sure I want to try to convince you
otherwise. My recommendation would be: if you don't like it don't use
it, set Storage=no in journald.conf and use whatever you like
better. You'll still benefit from journald and systemd collecting
all service stdout/stderr and early boot stuff for you, over plain
sysvinit/syslog, but it won't store anything on disk for you anymore.

> > Anyway, if you have a corrupted journal file and current journalctl
> > can't read it, then please file a bug, attach the journal file, and
> > we'll look into improving journalctl.
> > 
> 
> journalctl --verify
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-
> 1105.journal                         
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005495e
> 2bb26863-aa72c6a8a7437123.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005455b
> e5e6181f-8616123458bd2b50.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 00054956
> b0c61ef7-6f0ef8bfd59ad5e8.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 00054
> 95e2c558675-4af46c2d79464765.journal~
> 549f50: Invalid entry item (7/9 offset:
> 000000                                                    
> 549f50: Invalid object contents: Bad
> message                                                      
> File corruption detected at /var/log/journal/52f04da61fa8108cd5f48bca58
> 6164a2/system at 0005495abfa1c9d8-cf2deeeef0a23044.journal~:549f50 (of
> 8388608 bytes, 66%).
> FAIL: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005495a
> bfa1c9d8-cf2deeeef0a23044.journal~ (Bad message)
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 00054
> 55bfdbeb23d-1ff3046498e945ad.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005495e
> 3d56c587-44f1967167aac5a3.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 65bee6e3
> 4f3c4b77b265431a1dd2a6df-0000000000000001-0005459b8fd2a11e.journal
> c84f48: Invalid entry item (8/24 offset:
> 000000                                                   
> c84f48: Invalid object contents: Bad
> message                                                      
> File corruption detected at /var/log/journal/52f04da61fa8108cd5f48bca58
> 6164a2/system at 0005459b8ff5e32b-620437abf7009d7d.journal~:c84f48 (of
> 16777216 bytes, 78%).
> FAIL: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005459b
> 8ff5e32b-620437abf7009d7d.journal~ (Bad message)
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-
> 1000.journal                         
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 00054
> 95e3de63208-bbc6d86046b94014.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1105 at 2a1f1
> b3f5241431483971743eded852c-000000000000d6d6-000547f91700222b.journal
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 00054
> 59b907b630d-a25c081908a032be.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005495e
> 8db292fb-cb1d4cbe87b5093f.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1001 at 1dd4c
> 9dcd66446b483e91ea564f6f1b6-00000000000043c6-0005478f1ea62cb4.journal
> PASS:
> /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system.journal       
>                      
> 3a86e0: Invalid
> object                                                                 
>            
> File corruption detected at /var/log/journal/52f04da61fa8108cd5f48bca58
> 6164a2/user-1000 at 0005495ac03d6f02-bc5bf9a6b1d16fec.journal~:3a86e0 (of
> 8388608 bytes, 45%).
> FAIL: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 00054
> 95ac03d6f02-bc5bf9a6b1d16fec.journal~ (Bad message)
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005455b
> eea9f506-e4b5738d99c3f3ab.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-
> 1020.journal                         
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-
> 1005.journal                         
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 8d932
> e8a67a74b8483761b6d509bd81f-00000000000005e0-0005459b907b791b.journal
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 00054
> 956b1a5b541-cf982e5a4667655f.journal~
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-
> 1001.journal                         
> 4bf850: Invalid
> object                                                                 
>            
> File corruption detected at /var/log/journal/52f04da61fa8108cd5f48bca58
> 6164a2/system at 0005495e4825d0e0-cb146f70781a7baa.journal~:4bf850 (of
> 8388608 bytes, 59%).
> FAIL: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005495e
> 4825d0e0-cb146f70781a7baa.journal~ (Bad message)
> PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 00054956
> aac67a38-5b59fccdc0bcf4fe.journal~

Well, these aren't necessarily problems, as it could just be that your
machine was turned off without all data written to disk in full, and
thus the most recent data is incompletely written. journalctl should
still be able to read as much as was written correctly though, even
though verify will show you detailed info where things aren't clean.

Please try with a current systemd journalctl (newer than 228 though),
as it should be pretty good at recovering from journal files what may
be recovered.

> so does it make any sense to design surplus journal log recovery
> facilities ? no it does not because if filesytem fails then nothing
> else will help.

Well, you are ignoring that the journal is structured and hence binary
for a reason.

But again, if you aren't interested in the structured nature of the
journal, in its indexing, in its trust model, in its implicit
metadata, in anything it provides, and prefer plain old log files,
then you are welcome to turn off the journal storage and just install
rsyslog/syslog-ng or whatever you like.

If you think the journal files don't provide you with any benefit and
you think indexing and trust and structure and implicit metadata is
useless, then that's OK, so use something else.

> Is *-journal recovery done right now ? of course it is not. if *-
> journal is stopped abruptly then logs can be corrupted - that's my
> case.

Yeah, but that's not really a problem, is it? As long as journalctl
can read data until the point where things went bad, and as long as
journald will not write to the corrupted journal files (and thus
possibly make things worse) then we should be fine.

> I would really like to have old syslogd + logrotate restored and
> working however systemd is required by too many things thus I can not
> get rid of whole systemd however I would like to listen to *-journal
> developers on how to replace systemd-journal preserving other systemd
> facilities.

Just install rsyslog or syslog-ng, it's not that hard. It works fine
with journald. No additional configuration necessary on most distros.

And turn off journald's own storage with Storage=no...

Of course, you can't use journalctl then anymore, and "systemctl
status" and friends won't show you the 10 most recent log lines
anymore, but I think that's kinda what you are asking for then, as you
are back at sysvinit's original feature level.

> Seems that I have to be an expert on *-journal while I don't want to be
> because there are other topics I'm more interested in and I wouldn't
> even find this if my Dell's M4800 battery approached end of its life
> thus many weird things used to happen after un/re-plugging mains.

I don't see why you would have to be an expert on journal files. use
them, or don't. use something else, it's your choice...

Lennart

-- 
Lennart Poettering, Red Hat