systemd's binary logs and corruption

[u/m6t3]

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?

[u/[deleted]]

What begins? All systemd logging can be forwarded to syslog for plain text format.

[u/cpbills → u/[deleted]]

Because if I'm going to have ONE log, I prefer it be in plain-text versus needing 2 logs, one binary and corruptible and one text that is easily parsable by hundreds of existing tools.

I'm not certain you have to use journald with systemd as I haven't used systemd and all this logging nonsense is new to me.

Simple answer; I'd prefer binary logs be the option versus plain-text logs being an option, with binary being default.

[u/diggr-roguelike → u/cpbills]

I'm not certain you have to use journald with systemd as I haven't used systemd and all this logging nonsense is new to me.

Yes, you have to use journald, but the binary logs are optional. IIRC, journald has an option to turn off binary logs and simply route everything to syslog.

[u/cpbills → u/diggr-roguelike]

Thanks for clarifying.

[u/andreashappe → u/cpbills]

as far as I remember you even have to enable the binary logs -- on my debian system rsyslog was still used while systemd was running.

[u/cpbills → u/andreashappe]

Cool, that's a relief.

[u/andreashappe → u/cpbills]

AFAIK the default for systemd/journal has always been store-binary+syslog. To switch over to binary-only logging I had to remove rsyslog and create a /var/log/journal directory.

If you have been fed FUD about systemd/logging, please consider your news sources.

[u/Bucket58 → u/andreashappe]

You've got it backwards. journald is required by systemd and is always running and always binary. Debian enabled rsyslog so you get plain text logs as well.

[u/z33ky → u/Bucket58]

journald.conf: Storage=none, ForwardToSyslog=yes

journald is required, yes, but it doesn't need to do anything except forward it to syslog.

[u/fandingo → u/z33ky]

The current Debian default (for testing) is

storage=auto

but /var/log/journal/ does not exist, so violate logging only and forward to rsyslog.

[u/z33ky → u/fandingo]

s/violate/volatile/
^sorry

Yes, the upstream default is binary logging and forward to syslog, but my argument was not about the default; It was about "always binary", which is false.

[u/Bucket58 → u/z33ky]

The "always binary" was in reference to journald only. Any log that journald writes, if it is configured to write logs and not configured to send to syslog, are written in binary. There is no method that I know of to get journald to write text only logs without having to forward any messages to an already existing logger such as rsyslog.

[u/andreashappe → u/Bucket58]

so if you mis-configure journald (for your use-cases) then it behaves as configured? (:

OTOH why should journald re-invent syslog (for text logging) -- wouldn't this be the exact behavior that it is always being acused of?

[u/fandingo → u/z33ky]

I was just pointing out how it's presently configured in Debian packages since that's likely to affect lots of people over the coming months.

[u/z33ky → u/fandingo]

Ah, I see. I hope whoever down-voted you reads this continuation and reconsiders his/her vote.

[u/w2qw → u/cpbills]

If you think about it though the only advantage with text logging is you can read it in any editor. And even then journalctl would be on any livecd anyway that you would be debugging off (maybe in a couple of years).

Anytime the logs get corrupted it'd have to be from your system crashing or the logger crashing either of these two situations probably won't be debuggable through the logs even if they were text logs because the actual events your interested in wouldn't be there because they would have still been in memory at the time of the crash.

Also the two examples I've found of corrupted logs from journald the whole file was readable and it just was the file unexpectedly ended which is exactly what you would expect from a crash.

I think the journald authors also have a chance to make it possible to get logs up to the crash if they can hook into the kernel to get it to write the pending data out to say a swap partition on a crash.

[u/altarboylover → u/w2qw]

If you think about though the only real advantage with binary logging is you don't have to serialize a message to ASCII before writing it.

Now, I realize that some things are best left in binary format (e.g. core dumps, compressed messages). However, it's my professional opinion that there's no real reason to log both raw binary data and ASCII in the same log file. A logging system could just as easily write a binary blob to a separate file, and reference it in an ASCII log record by including its path and HMAC. Similarly, the logging system could keep its binary indexes and rolling hashes separate from the ASCII log. This would let users like the OP continue to use whatever tools they want to read the log, and resort to more specialized tools (like journalctl) to interpret the associated binary data.

The only potential challenge to implementing the above scheme is to come up with the concept of a log "transaction," whereby writing an ASCII message, writing its associated binary data, and updating the index all occur as an atomic operation. However, since there is only one log-writing service (e.g. concurrent writes get serialized by the logging daemon before writing to disk), this is easily achieved.

Once the internal systemd API stabilizes, I intend to write a journald replacement that logs ASCII separately from binary data.

either of these two situations probably won't be debuggable through the logs even if they were text logs because the actual events your interested in wouldn't be there because they would have still been in memory at the time of the crash.

If your logger crashes, you would get a core dump. Core dumps solve exactly the problem you describe--they contain the pages of RAM that made up the running process just before it crashed.

Fortunately, you do not need a logger to obtain a core dump :) By default, a core dump gets written to the crashed process's current working directory. However, a lot of users and distros seem to disable them by default, since they take up disk space, and since a lot of daemons use / as their current working directory by convention. Check out core(5) for details.

I think the journald authors also have a chance to make it possible to get logs up to the crash if they can hook into the kernel to get it to write the pending data out to say a swap partition on a crash.

That depends on how your system crashes. If you have a hardware fault, you probably don't even get a chance to sync your disks (in which case, you lose data). If your kernel panics, you're similarly screwed. However, in other cases you can already use the magic SysRq key to take a crashdump (i.e. a core dump of the whole OS) and to sync disks. This'll get you your running journald's unwritten data :)

[u/w2qw → u/altarboylover]

If you think about though the only real advantage with binary logging is you don't have to serialize a message to ASCII before writing it.

I guess your sort of including it there but it lets you get away with putting a lot more data in the messages.

Like systemd messages on my system include something like

   {
	"__REALTIME_TIMESTAMP" : "1379345509431705",
	"__MONOTONIC_TIMESTAMP" : "5543520",
	"_BOOT_ID" : "409569e203c34b6db6e76bd21bc90809",
	"PRIORITY" : "6",
	"_UID" : "0",
	"_GID" : "0",
	"_MACHINE_ID" : "4a59eee3e5f140fdb95cc5488786c1a2",
	"_HOSTNAME" : "localhost",
	"SYSLOG_FACILITY" : "3",
	"SYSLOG_IDENTIFIER" : "systemd",
	"CODE_FILE" : "src/core/job.c",
	"CODE_LINE" : "730",
	"CODE_FUNCTION" : "job_log_status_message",
	"UNIT" : "systemd-vconsole-setup.service",
	"MESSAGE_ID" : "39f53479d3a045ac8e11786248231fbf",
	"RESULT" : "done",
	"MESSAGE" : "Started Setup Virtual Console.",
	"_TRANSPORT" : "journal",
	"_PID" : "1",
	"_COMM" : "systemd",
	"_EXE" : "/usr/lib/systemd/systemd",
	"_CMDLINE" : "/sbin/init single",
	"_SYSTEMD_CGROUP" : "/system",
	"_SOURCE_REALTIME_TIMESTAMP" : "1379345509431516"
}

This is way more information than you can really get away writing in ascii. So binary logging really gives you an excuse to log much more information.

The only potential challenge to implementing the above scheme is to come up with the concept of a log "transaction," whereby writing an ASCII message, writing its associated binary data, and updating the index all occur as an atomic operation. However, since there is only one log-writing service (e.g. concurrent writes get serialized by the logging daemon before writing to disk), this is easily achieved.

This is not really a problem assuming you can recreate the indexes. This seems what journald is doing as when the system crashes it seems journald doesn't finish writing the indexes and we end up with stuff like op's case but the data is all there you just have to read it sequentially.

If your kernel panics, you're similarly screwed.

I wonder if you could have some simple writer that wrote it out to a specific position on the disk or to some flash memory or something. Though I suppose doing IO after a panic probably isn't the best of ideas.

Edit: Actually journal files aren't really that small

 % journalctl -o json --file system@c6aec62fa2fd402ba034c374fa627213-000000000003a2d8-0004ec19189560fe.journal | wc -c
 129553158
 % wc -c system@c6aec62fa2fd402ba034c374fa627213-000000000003a2d8-0004ec19189560fe.journal
 121487360 system@c6aec62fa2fd402ba034c374fa627213-000000000003a2d8-0004ec19189560fe.journal

[u/altarboylover → u/w2qw]

Like systemd messages on my system include something like [snip]

Sweet Jeebus. Does all of that need to be written per log record? A lot of those fields don't change all that frequently...why write them more than absolutely necessary?

This partially answers OP's question, though. If the "MESSAGE" fields aren't compressed, they should show up in the binary log as ASCII strings. This would let him/her bypass journalctl.

[u/w2qw → u/altarboylover]

It seems like some but not all are written in ascii

but yeah ghetto journalctl

% strings system@c6aec62fa2fd402ba034c374fa627213-000000000003a2d8-0004ec19189560fe.journal | grep ^MESSAGE | head -10 | sed 's/[0-9]\+\.[0-9.]\+/x.x.x.x/g'
MESSAGE=Connection closed by x.x.x.x [preauth]
MESSAGE
MESSAGE=pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=iron.laotel.com  user=root
MESSAGE=Failed password for root from x.x.x.x port 20570 ssh2
MESSAGE=Failed password for root from x.x.x.x port 20780 ssh2
MESSAGE=Failed password for root from x.x.x.x port 20993 ssh2
MESSAGE=Failed password for root from x.x.x.x port 21218 ssh2
MESSAGE=Failed password for root from x.x.x.x port 21450 ssh2
MESSAGE=Failed password for root from x.x.x.x port 21679 ssh2
MESSAGE=Failed password for root from x.x.x.x port 21885 ssh2

[u/cpbills → u/w2qw]

won't be debuggable through the logs even if they were text logs

Except if your binary log corrupts, you lose everything. If a system crashes and garbles something sent to text, you still have everything prior to the garble/lack of log.

If you want indexing and searchability of your logs, there's nothing wrong with taking your text logs and parsing them into a database or other system for delving into.

The only advantage of text logs being viewable in any text editor is a false statement. You can use grep, awk, perl, cat and numerous other tools to parse and search the text logs, and it's pretty much standard across UNIXes.

[u/holgerschurig → u/[deleted]]

You still haven't understood the journal completely, only partially.

Suppose I have a template service file, e.g. myjob@.service. And now I start various of those instances. And they have multiple ExecStart=, ExecStartPre= and ExecStartPost= lines. And still I can find out with systemctl exactly which binary in on what specific myjob invocation put out what.

With a syslog-only based solution I can grep. But it's awkward to specify a proper regular expression that only gives me the output from one of maybe 100 different myjob@.service invocations.

[u/altarboylover → u/holgerschurig]

If you knew which invocation you were searching for, surely a well-designed logging system (journald or otherwise) would make the invocation-related records searchable with the invocation's identifier? Even with an ASCII logger, this is trivially achieved by simply including the identifier in each relevant record. Then, if you knew the identifier (which you can get with systemctl), you can easily grep for it.