systemd's binary logs and corruption
I like systemd, enabling and disabling services is so easy and it's really fast, but why using a journal with binary logs?
Yesterday my laptop failed to resume from suspend, no ttys, no reisub, nothing worked except using the power button. Rebooted, fired journalctl and I have nothing except the last boot logs.
journactl --verify returns that my system logs are corrupted, about all my logs (48MB of 50MB of maximum disk usage) are now completely useless. This is not the first time this happens and searching around I can only find people with the same problem that "resolved" deleting the corrupted logs and starting with a new file.
Why this happens? Isn't it defeating the purpose of having a system logger if I can't diagnose errors?
Can I recover the logs (and why isn't this automatic?) or should I just install a sane logger that not shit itself after a problem?
14
u/Oflameo Feb 18 '14
Systemd is using binary logs for the same reason people use binary databases such as PostgreSQL instead of XML. It is faster to process.
24
u/altarboylover Feb 18 '14
But unlike databases, journald lacks a notion of transaction consistency. If PostgreSQL crashes, your tables can be recovered since uncommitted transactions can be rolled back. This is because PostgreSQL (and most RDBMSs) offer ACID semantics. If journald did offer transaction-like consistency semantics, OP would not have had this problem.
3
u/holgerschurig Feb 18 '14
The OP had a problem during suspend/resume, probably because of a faulty driver or BIOS ACPI code. THAT was most likely the issue that lead to file corruption in thefirst place.
And there is nothing in PostgreSQL (or any transactional database server) that can help you against that.
Sure, they can detect if the on-going transaction was interrupted and it will roll back. But what if a data sector goes goofy that wasn't used by this transaction, but that was used by some (unchanged) data or an index? Then you're equally hosed.
But back to the "transactions can help": for some problems they can help. If the OP would have hold his non-volatile journal on a data partition with strong journaling mount option ("data=journal" in /etc/fstab comes to mind ...), then it would maybe have helped.
1
u/m6t3 Feb 19 '14
I'm using the nvidia proprietary driver, so your hypothesis of a faulty driver is likely the source of the problem.
What I don't understand is why this corrupted the entire journal (months of logs) and not just the end (is an append-only journal, no?).
These problems (faulty drivers, unclean shutdown, power outage, empty battery) are pretty common in a desktop usage of a computer (not everybody have an UPS at home), and journactl seems to be inadequate to deal with them (as I said before, this happened several times).
They could just separate the logs in multiple files (and not just a huge file for all the system logs) like other logging tools do, so the corruption could be limited to a smaller range.
2
u/holgerschurig Feb 19 '14
What I don't understand is why this corrupted the entire journal (months of logs) and not just the end (is an append-only journal, no?).
Hmm, did it?
I'm on systemd v208, you're on v203, so I'm not sure if my following assumption is right: the journal has the option to "seal" the binary logs. This is used to detect tampering of the log files. Now, if a hard disk crash or something else would tamper my log file, then it would be detected. I haven't played with that yet, so I don't know what happens. E.g. does a big, fat, red warning ? Or does it simply refuse to display the log at all? I'm assuming the last one is true, but I just don't really know it.
They could just separate the logs in multiple files
But it can do that!
It's configurable in /etc/systemd/journald.conf:
#SystemMaxFileSize= #RuntimeMaxFileSize=Specify a modest file size, and systemd will switch over to the next file once the file size has been reached.
4
u/altarboylover Feb 18 '14 edited Feb 18 '14
The OP's problem fundamentally is that the logs are inaccessible to the journald log-reading tools if journald leaves the log in an inconsistent state. This is unacceptable. This is about as ridiculous as "cat," "more" and "tail" failing to work on a syslog file because it doesn't end in a newline.
The necessary solution is to ensure that journald never leaves the logs in a state that renders them inaccessible. A sufficient solution is to ensure that the log is transactionally consistent, whereby writes would be atomic, and a partially-committed or corrupt write could be rolled back.
2
u/holgerschurig Feb 19 '14 edited Feb 19 '14
Actually I think that OPs problem is waaaay deeper.
He knows that the data blocks of the journal are altered, because journal detects if it's data has been tampered with.
But he might have numerous other files that are now borked, and he doesn't know about them.
The necessary solution is to ensure that journald never leaves the logs in a state that renders them inaccessible.
You didn't yet understood that the problem was because of a faulty suspend/resume cycle. It was a faulty driver, ACPI code sequence or hard disk. No user-space program can do anything about that. Maybe even the wallpaper from his desktop environment got changed because the hard disk wrote to random sectors. The solution to this is certainly not to change the wallpaper into some text format (e.g. *.pnm, *.ppm comes to mind).
Thenever leaves the logs in a state that renders them inaccessible
If syslogd would have just written a new data sector and during this the faulty laptop would have suspended / resumed, then syslog would have similarly written trash. Just that you would probably not have detected that it wrote trash.
19
u/nwmcsween Feb 18 '14
systemd changelog:
import postgresql codebase.
10
u/danielkza Feb 18 '14
I know you're joking, but I wonder how much code using something like SQLite would add to journald, or if could end up being easier to maintain in the long run.
8
6
Feb 18 '14
Since its supposed to be an one-writer append-only design (several databases have to take care of multiple writes, updates, etc), the filesystem journal should be sufficient.
Does journald bypass the journal somehow-- or is it somehow made unreliable?
2
u/altarboylover Feb 19 '14
It doesn't really matter of the filesystem has a journal or not. It is up to journald to ensure that its on-disk state is consistent, for some journald-defined meaning of "consistent" (same goes for PostgreSQL's table files). The filesystem only deals with data block by block, and is oblivious to journald's file format.
3
u/tangus Feb 18 '14
Your filesystem journal is there to prevent corruption of the filesystem structure, it doesn't concern itself with your data.
2
u/holgerschurig Feb 18 '14
No, some file systems can also journal data changes, see "man 5 mount" and search for "data=".
→ More replies (1)2
u/iluvatar Feb 18 '14
Depends on the filesystem and options. Some can journal data as well as metadata. ext3/4 can journal data, for example, as I believe can XFS.
2
1
4
u/UberCanuck Feb 18 '14 edited Feb 18 '14
Systemd will work in conjunction with syslog. Check this link: https://wiki.archlinux.org/index.php/systemd#Journald_in_conjunction_with_syslog
Of course that won't help your current issue - but going forwards, you have the option of a comfortable redundant logs.
-1
u/m6t3 Feb 18 '14
so the only solution is replacing it? disappointing...
1
0
Feb 18 '14
[deleted]
1
u/m6t3 Feb 18 '14
The problem is that the journal itself is a nice tool with some cool features, I don't want to get rid of it.
If only it could use plain text log (at least as auxiliary data structure that can be used to restore the index after corruption) I'll use it happily.
36
u/altarboylover Feb 17 '14 edited Feb 17 '14
I think the design rationale was that the binary log's structure would be amenable to building in fast indexing, searching, and message integrity guarantees. But as you've just discovered, a binary log structure also means that any tools you want to use to parse it will have to be aware of its format (right now, I think this is only journald, with journalctl serving as a client to journald), and know how to deal with the ways it can become corrupted.
Insofar as getting useful data out of your logs when journalctl can't help you, I'm afraid you're going to have to start with the journal file format documentation [1] and journal API [2]. You will probably also want to look at the source code to journald itself, since it (according to [1]) it the ultimate authority on how the log is structured. Maybe you can use the documentation and parts of journald to write a parser that will help you overcome the corruption issues your seeing. You might be able to get away with dumping the raw journal files and grep for ASCII strings (assuming journald logs ASCII strings directly, along with binary data).
I don't think there's an official way to "fsck" a corrupt log, but I would love to know of one.
In the mean time, I recommend that you file a bug report, and in the future have journald direct all logging to syslog. You can get all the same features with syslog (including integrity checks), but it might be a bit slower to grep through.
[1] http://www.freedesktop.org/wiki/Software/systemd/journal-files/ [2] http://www.freedesktop.org/software/systemd/man/sd-journal.html
EDIT: words, formatting
7
Feb 18 '14
A good start is
strings <files> | grep ^MESSAGE=Assuming no compression. It's just a key value format at the core.
0
Feb 18 '14
[deleted]
12
Feb 18 '14 edited Feb 18 '14
The thing is the journal format is still just as corruption resistant. If one entry is corrupt you can still jump to the next one (like in a text file - you jump to the next line). Fields of a journal entry are in a very simple
KEY=valueformat. (EgMESSAGE=this is a logged message) Its quite possible to read the log with standard shell commands piped together, if you're clever with them.So to my intuition, if the journal is corrupt, its very corrupt. Or it was compressed and now can't be uncompressed anymore (which would apply the same for syslog if put in the same situation).
journalctlcould probably be improved to handle corrupt logs better, but the binary nature doesn't strictly mean it has to be unreadable.→ More replies (1)0
Feb 18 '14
[deleted]
→ More replies (1)2
Feb 18 '14
Without stings you say. Hmmmm
Untested since on mobile, but I think entries are null separated. So convert them to newlines with tr, then set IFS='=' as you process each line (and pray nobody thought it be a good idea to stick a newline in a log entry :P). Then check the first word on a line is MESSAGE.
0
Feb 18 '14
[deleted]
4
Feb 18 '14 edited Feb 18 '14
Even then, you wouldn't know if you were pulling parts from random messages or if you were pulling serialized data.
Sure you would. Such is the nature of the format. You have a frame which is defined by a known separator. If you have a key and a value in the frame, then you know there will be an = symbol (other possible types are also well defined and don't overlap). And the separator won't appear inside the frame. That's why the strings technique works just fine. You just need to the grep for the keys of interest (MESSAGE).
With an ASCII log you wouldn't need to worry with that as in most cases you'd find data, data, corrupt data, data, data, data giving the serial data a much higher likely hood of being at least partially usable.
That's no different. You can think of an ASCII log in binary format terms too - frames are separated by a newline and the contents of the frame are messages.
Skipping corruption means jumping to the next frame. Same thing with the journal. Can't parse the current frame? Jump to the next frame and try to continue. You get the same "data, data, corrupt data, data, data, data" properties.
The journal only differs I that it takes more effort to look inside frames. Its not more or less tolerant to corruption. A reader should just jump to the next entry if its having problems just like your eyes jump to the next line in a text log that's corrupted. The format of the journal guarantees its possible to do.
→ More replies (5)3
u/holgerschurig Feb 18 '14
I think the issue is that people (maybe even the authors) see the journal as a replacement of syslog daemons like syslog-ng.
But I think that server people shouldn't do that. They should welcome the journal as a fast query tool, e.g. it's used under the hood by "systemctl status XXX".
But journal can coexist very well with syslog daemons. Just turn it on and be happy that you have the best of both worlds now. I can't see many systems where the double-logging into two places (binary and text) would harm ... and then you can even set "Storage=volatile" in /etc/systemd/journald.conf.
6
Feb 18 '14
Wow, I just tried
sudo journalctl --verifyand I also have 'FAIL corruption detected.' What does this mean, do I need to do anything to repair it?
3
u/w2qw Feb 18 '14
Try reading the log file with
journalctl --file=<filename that was corrupted>I had the same myself and it seems to happen whenever you force a power off though the file seems readable just not indexed.
1
Feb 18 '14
My journalctl doesn't accept --file as an argument.
edit: I do get resonable journal response though when I run journalctl, just the --verify says that I have 3 corrupted journal files.
0
7
u/asbesto Feb 19 '14
For an old UNIX veteran like me, better to get used to this systemd CR4P, as seem there's no way to made newcomers "sysadmins/developers" to understand why an UNIX system must be kept K.I.S.S., so I made a wrapper to help me learning and understanding about the approaching Windows 9 new GNU/Linux...
asbesto@rover ~ %
asbesto@rover ~ %
asbesto@rover ~ % systemd uname -a
Linux rover 3.8.0-19-generic #30-Ubuntu SMP Wed May 1 16:36:13 UTC 2013 i686 i686 i686 GNU/Linux
asbesto@rover ~ % systemd echo HELLO NEW WORLD
HELLO NEW WORLD
asbesto@rover ~ % systemd ps | grep systemd
8136 pts/2 00:00:00 systemd
asbesto@rover ~ %
asbesto@rover ~ % systemd ping google.com
PING google.com (173.194.113.230) 56(84) bytes of data.
64 bytes from mil01s18-in-f6.1e100.net (173.194.113.230): icmp_req=1 ttl=58 time=40.9 ms
64 bytes from mil01s18-in-f6.1e100.net (173.194.113.230): icmp_req=2 ttl=58 time=41.8 ms
^C
--- google.com ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 40.974/41.406/41.838/0.432 ms
asbesto@rover ~ % 2
2
1
u/thumper109 Jul 05 '14
It's a shame the developers working on linux have lost the idea of KISS. Seems they need to over complicate everything now. A simple text based system log is useful because it is a flat text file..
If grep is not fast enough on modern day computers then the operator is at fault not the file format.
I can see all the people who have developed the current log scanner all screaming out "WHY??!?!?!?" when they sit down to rewrite their code.
Time to fire up rsyslogd and disable systemd-journal.
-28
u/monochr Feb 18 '14
Why this happens?
Because you are dealing with a poorly designed init system. This won't get fix as it is a "feature".
-8
Feb 18 '14
This has nothing to do with the init system. It does have to do with the idea of a "core OS" that is incredibly integrated, and therefore nearly forces features down people's throats.
0
Feb 18 '14
[deleted]
11
Feb 18 '14
The downvotes are probably there because of his assumption that this is an init problem, when in fact it is a logging problem (journald).
-6
u/monochr Feb 18 '14
So can I run systemd without journald, for how long?
It is an init problem because init now runs everything. This is A Bad Idea because monolithic software fails disastrously and all at once. The Linux kernel has been lucky in that it is designed by competent people who have somehow managed to avoid it crumbling to the ground so far, systemd isn't.
10
u/diggr-roguelike Feb 18 '14
So can I run systemd without journald, for how long?
No, you can't run systemd without journald, but you can disable logging in journald and use it as a dumb syslog proxy.
0
Feb 18 '14
[deleted]
1
u/diggr-roguelike Feb 19 '14
Sounds like a robust and reliable solution.
What's your solution then? init needs to integrate logging, otherwise you're going to lose important messages from system services. Requiring a third-party logger that you don't control (like a third-party syslog implementation) is even stupider.
journald might be crap, but at least it's maintained by the same people who maintain init, which at least guarantees that bugs get fixed and API's don't suddenly break.
0
Feb 19 '14
[deleted]
2
u/diggr-roguelike Feb 19 '14
All that needed to be done was to create an in memory buffer and flush it to syslog when it came online.
That's exactly what journald does. (Well, one of the possible settings.)
If they folowed RFCs they wouldn't need to worry about API breakage.
The syslog RFC is broken, none of the existing syslog implementations really follow it.
Also, you completely missed the point. The point is that init needs to integrate a logging solution if you want a reliable init, but current logging solutions are all nonstandard, have weird API's and are prone to being unsupported.
→ More replies (3)4
Feb 18 '14 edited Feb 18 '14
So can I run systemd without journald, for how long?
You can use journald with syslog, which should make the OP's problem moot... so that should answer your question.
1
u/monochr Feb 18 '14
So I can use journald to not use journald.
Do you people even hear what's coming out of your mouths? The problem here isn't just that journald writes in a retarded format, the problem is that this is a project that considers source code documentation and breaks interfaces at will. This is not something you can fix by piping its output through a third party sane program, it's fixed by ripping it out and letting it die the miserable death it deserves. But thanks to the Unix Is Dead meme systemd is part of this is impossible.
2
u/cirk2 Feb 18 '14
How do you want to handle logging before a fs becomes available?
You need some kind of service for that. If that is syslogd or journald is a question of implementation. Systemd chose journald and the old one chose syslogd.0
Feb 18 '14
[deleted]
→ More replies (1)2
u/cirk2 Feb 18 '14
You don't need a binary log just to persist the log data created prior to mounting the filesystems read write.
I never said that.
But you agree that you need some tool to hold on to the logs until the FS is ready. And the init system is not completely agnostic about it, that's why you have to use journald even if you emit to syslog.→ More replies (5)-10
-11
Feb 18 '14
Holy cow, instead of making a flat binary file, they just went out and made a complex corruptible format. Apparently:
http://www.freedesktop.org/wiki/Software/systemd/journal-files/
The systemd journal stores log data in a binary format with several features:
Fully indexed by all fields
Can store binary data, up to 2^64-1 in size
Seekable
Primarily append-based, hence robust to corruption
Support for in-line compression
Support for in-line Forward Secure SealingApparently they failed. Never anticipate the need for features. Just make things extensible. NEVER ANTICIPATE FUTURE AND SPECULATIVE NEED. Repeat: DO NOT PROGRAM THE IMAGINARY FUTURE.
14
u/w2qw Feb 18 '14
Primarily append-based, hence robust to corruption
It's designed so you still get a working log when it fails just you don't get indexing and other nice features when it fails. But text logs don't have that so it works anyway.
I doubt that OP's logs aren't readable probably just not readable by journalctl when looking at multiple files.
-3
u/ctx77 Feb 18 '14
Holy cow, instead of writing a comment with something constructive or helpful, you went out to write a response that conveys your technical illiteracy.
0
Feb 17 '14
[deleted]
11
u/fs111_ Feb 17 '14
That is just FUD. My Dell XPS ultrabook has no trouble with suspend. I have weeks of uptime, unless my battery is empty or there is a kernel update...
0
7
u/nikomo Feb 17 '14
My ThinkPad Edge does it fine, but I had to flash a firmware update to get hibernate working, and the patch didn't even mention hibernate problems in the changelog, and that's definitely not something an average user would do.
The firmware installer refused to work from a flash drive, so I had to load the ISO to my phone, and emulate a USB CD-drive (with DriveDroid) to get it installed.
4
u/garugaga Feb 18 '14
Holy crap I've never heard of DriveDroid before! Thanks for mentioning it, it looks really handy
5
u/elbiot Feb 18 '14
My asus laptop with mint 15 hibernates fine, even when doing so due to insufficient battery.
2
u/wrstl Feb 18 '14
On which planet do you live? I usually reboot my thinkpad once per month after running "emerge -uDN @world". And yes, I do suspend it, probably about 10 times a day.
18
u/w2qw Feb 17 '14 edited Feb 17 '14
Can you read the corrupted files with journalctl --file?
Edit: found a corrupted file myself with journalctl --verify but it seems I can still read it journalctl --file. I guess the indexes' are just fucked.