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

Wed Mar 1 06:58:51 UTC 2017

Lennart,

On Mon, 2017-02-27 at 19:42 +0100, Lennart Poettering wrote:
> 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). 

Is there a way to access the data collected beyond the point of
corruption ? Notice that I lost logs for a month time because of system
freeze however my ext4 recovered and is clean but *-journal.

> 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.

splendid. this is like making poor candies more sweet.

> 
> 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.

right, it will not convince me because we differ in very basic points
of views. You agree for log losses "to some degree" (undefined) while I
reckon this is not acceptable utterly. And because I think that I'm
absolutely right that log losses are not acceptable then here is
logical conclusion: a syslogd replacement must do exactly what syslogd
used to do because if there are only milisecs to kernel failure left
then there is no time for various funny "database doings" like hashing,
indexing rows, compression - all that is rubbish. Logs must be appended
only to current log file all the time as fast as syslogd or its
replacement can do. Let filesystem do these things.

and many don't need one "sweety tool for dumbs" because they are
familiar with cat and grep. These various http crap admin idiots better
educate themself.

>  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.
> 

ok. will give a try. Collected new battery yesterday and troubles gone.

> > 
> > > 
> > > 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 0005
> > 495e
> > 2bb26863-aa72c6a8a7437123.journal~
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005
> > 455b
> > e5e6181f-8616123458bd2b50.journal~
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005
> > 4956
> > b0c61ef7-6f0ef8bfd59ad5e8.journal~
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 0
> > 0054
> > 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 0005
> > 495a
> > bfa1c9d8-cf2deeeef0a23044.journal~ (Bad message)
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 0
> > 0054
> > 55bfdbeb23d-1ff3046498e945ad.journal~
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005
> > 495e
> > 3d56c587-44f1967167aac5a3.journal~
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 65be
> > e6e3
> > 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 0005
> > 459b
> > 8ff5e32b-620437abf7009d7d.journal~ (Bad message)
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-
> > 1000.journal                         
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 0
> > 0054
> > 95e3de63208-bbc6d86046b94014.journal~
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1105 at 2
> > a1f1
> > b3f5241431483971743eded852c-000000000000d6d6-
> > 000547f91700222b.journal
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 0
> > 0054
> > 59b907b630d-a25c081908a032be.journal~
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005
> > 495e
> > 8db292fb-cb1d4cbe87b5093f.journal~
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1001 at 1
> > dd4c
> > 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 0
> > 0054
> > 95ac03d6f02-bc5bf9a6b1d16fec.journal~ (Bad message)
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005
> > 455b
> > 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 8
> > d932
> > e8a67a74b8483761b6d509bd81f-00000000000005e0-
> > 0005459b907b791b.journal
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/user-1000 at 0
> > 0054
> > 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 0005
> > 495e
> > 4825d0e0-cb146f70781a7baa.journal~ (Bad message)
> > PASS: /var/log/journal/52f04da61fa8108cd5f48bca586164a2/system at 0005
> > 4956
> > 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
> 
-- 
Krzysztof Blaszkowski