Bug 1018042 - All log entries have "journal" prepended
Summary: All log entries have "journal" prepended
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: Fedora
Classification: Fedora
Component: openstack-swift
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Silas Sewell
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-10-11 04:31 UTC by Pete Zaitcev
Modified: 2013-11-05 14:51 UTC (History)
11 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-11-05 14:51:22 UTC
Type: Bug


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
OpenStack gerrit 53252 0 None None None Never

Description Pete Zaitcev 2013-10-11 04:31:54 UTC
Description of problem:

Log entries look like this:

Oct 10 23:57:49 kvm-rei journal: proxy-server 192.168.128.11 192.168.128.11 11/Oct/2013/03/57/49 GET /v1/AUTH_t1%3Fformat%3Djson HTTP/1.0 200 - - MIIF.........i8w%3D%3D - 786 - tx22d63c0146ca40c7bff2e-005257773d - 0.0455 - -

They used to be like this on RHEL 6:

Oct 10 23:54:20 rhev-a24c-01 proxy-server 10.10.55.128 127.0.0.1 11/Oct/2013/03/54/20 GET /v1/AUTH_test%3Fformat%3Djson HTTP/1.0 200 - - AUTH_tka.........6a7 - 907 - tx6018d95b1cec45c8aa5ed-005257766c - 0.0392 - -

Version-Release number of selected component (if applicable):

openstack-swift-1.9.1-2.fc21.noarch
rsyslog-7.4.2-2.fc20.x86_64

How reproducible:

Seems stable

Steps to Reproduce:
1. Install openstack-swift-proxy

Actual results:

Different log format

Expected results:

Traditional log format

Additional info:

We thought it was systemd journal thing, but then realized
that /var/log/messages still has normal looking entries
from every other service.

[zaitcev@kvm-rei ~]$ cat /etc/rsyslog.d/swift.conf 
local0.*	/var/log/swift/swift.log

But actually same thing happens if we let logs go into
/var/log/messages too.

Comment 1 Pete Zaitcev 2013-10-21 21:47:17 UTC
Oh, brother, it's just as I suspected.

The /dev/log is served by the systemd-journal, which parses the messages,
optionally stores them, then reassembles them back and forwards to rsyslog.
At the parsing time, something called "identifier" is searched by
looking for a word surrounded by whitespace and ending with a colon.
It's in src/journal/journal-syslog.c,
 server_process_syslog_message => syslog_parse_identifier
If the indentifier is not set, something in the depths of systemd adds it.

There's an option of forwarding to syslog raw, and in fact it is enabled
by default in systemd. Rsyslog is configured to listen on
/run/systemd/journal/syslog as well (with $SystemLogSocketName
in /etc/rsyslog.d/listen.conf), but it does not actually listen there.

The way journal forwards logging to rsyslogd is fairly strange
and difficult to pick up with strace - apparently it goes through
shared mmap-ed file, watched with inotify in
/var/log/journal/xxxxxxxxx/user-531.journal

Comment 2 Pete Zaitcev 2013-11-05 14:51:22 UTC
merged upstream (tentatively at least), will track in Icehouse


Note You need to log in before you can comment on or make changes to this bug.