Pete Zaitcev (zaitcev) wrote,
Pete Zaitcev

The killer colon of Lennart

It appears that we have a little problem in OpenStack Swift on Fedora 21: evey log entry has "journal:" inserted into it, so analysis scripts blow up. Before, it loooked like so:

Oct 10 23:54:20 rhev-a24c-01 proxy-server 11/Oct/2013/03/54/20 GET /v1/AUTH_test%3Fformat%3Djson HTTP/1.0 200 [....]

Now, it looks like so:

Oct 10 23:57:49 kvm-rei journal: proxy-server 11/Oct/2013/03/57/49 GET /v1/AUTH_t1%3Fformat%3Djson HTTP/1.0 200 [....]

The word "journal" points to the likely culprit, and indeed the problem is that Systemd Journal v.208 intercepts all system logging, parses it, and attempts to find something it calls "identifier". See src/journal/journald-syslog.c: server_process_syslog_message, syslog_parse_identifier. An acceptable identifier is a word that ends in a colon, and Swift does not end identifiers with colons.

If no identifier was identified, Journal adds its own process name, hence "journal:". It then packs the parsed message back into a syslog message and forwards it to rsyslog using an excessively tricky backchannel that involves temporary per-user files and inotify (le sigh).

For added bizzaredness, Systemd involves a provisioning to forward syslog messages as-is to a system logger, using a normal socket, only renamed, but for some reason rsyslog does not listen where $SystemLogSocketName instructs it. So, Systemd dutifuly forwards, the message is dropped by kernel, then the above farce proceeds ahead. The rsyslog listened on /run/systemd/journal/syslog in Fedora 19, but not in 21.

A simple cure would be kneel before Lennart and add the colon to Swift logging. I filed a Gerrit review to do just that, but I am not too optimistic. Although it keeps the word count, it adds the colon to the server name:

Oct 10 23:57:49 kvm-rei proxy-server: 11/Oct/2013/03/57/49 GET /v1/AUTH_t1%3Fformat%3Djson HTTP/1.0 200 [....]

From there, the colon leaks into whatever webpage or report the operators' scripts generate, so they need fix-ups to strip colons, however trivial.

IMHO, the best alternative would be to make Swift log directly into files, like Keystone and other OpenStack services do. This way we also avoid the unpleasant problem of double-logging due to stock rsyslog sending everyting above *.debug into /var/log/messages. But for that we have to implement HUP rotation, while SIGHUP is already used for graceful shutdowns... Seems suboptimal.

UPDATE: A week later, Lennart commented:

It's rsyslog which adds the "journal:" string in there, not systemd or the journal itself. We actually are very careful to forward the exact same syslog datagram we recieved on to any other running syslog daemon. Except that rsyslog doesn't make use of this forwarding scheme, and goes directly to the journal files and recreates the original message on its own way from that, apparently in a broken way. I mean, actually we tried very hard to not people piss of people like this, because we don't really like reading bullshit stories like yours. Alas, it didn't help, ignorants successfully blame us for everything anyway.

Summary: don't bitch at us. Bitch at the rsyslog people. Or even better: don't bitch at all, do your homework, and then file a bug against rsyslog.

I don't appreciate all your hateful rethoric btw. But I guess that's the point of it.

  • Post a new comment


    Anonymous comments are disabled in this journal

    default userpic

    Your reply will be screened

    Your IP address will be recorded