journald: make maximum size of stream log lines configurable and bump… #6838

poettering · 2017-09-15T11:06:02Z

… it to 48K

This adds a new setting LineMax= to journald.conf, and sets it by
default to 48K. When we convert stream-based stdout/stderr logging into
record-based log entries, read up to the specified amount of bytes
before forcing a line-break.

This also makes three related changes:

When a NUL byte is read we'll now recognize this as alternative line
break, instead of silently dropping everything after it. (see systemd-journald drops all bytes after '\0' #4863)
The reason for a line-break is now encoded in the log record, if it
wasn't a plain newline. Specifically, we distuingish "nul",
"max-reached" and "eof", for line breaks due to NUL byte, due to the
maximum line length as configured with LineMax= or due to end of
stream. This data is stored in the new implicit _LINE_BREAK= field.
It's not synthesized for plain \n line breaks.
A randomized 128bit ID is assigned to each log stream.

With these three changes in place it's (mostly) possible to reconstruct
the original byte streams from log data, as (most) of the context of
the conversion from the byte stream to log records is saved now. (So,
the only bits we still drop are empty lines. Which might be something to
look into in a future change, and which is outside of the scope of this
work)

Fixes: https://bugs.freedesktop.org/show_bug.cgi?id=86465
See: #4863
Replaces: #4875

evverx · 2017-09-15T15:03:49Z

When a NUL byte is read we'll now recognize this as alternative line
break, instead of silently dropping everything after it. (see #4863)

I would expect NUL to be a part of a line. In my opinion, sending ab\0cd should result in MESSAGE=ab\0cd, not MESSAGE=ab and MESSAGE=cd.

poettering · 2017-09-15T15:17:19Z

I would expect NUL to be a part of a line. In my opinion, sending ab\0cd should result in MESSAGE=ab\0cd, not MESSAGE=ab and MESSAGE=cd.

I strongly disagree. Stream logging is textual logging, and NUL bytes have no place in text strings really. At least not in a C/UNIX world. I mean, if you pick your random system hacker off the street and ask him, what's the best way to end a string, about half of them will say newline! and the other half nul-byte!, and as such we should handle both, as both are typically used to delimit text lines or strings.

I mean, this is not about being binary transparent, we aren't that anyway really, and if you really want to drop binary blobs in the journal you better should use the native API, but not stream log lines.

I am also pretty sure we should avoid needlessly generating non-printable MESSAGE= fields. Not only we can't display them easily in journalctl ourselves, but also lots of other software and protocols might end up using them, and embedded NUL bytes are generally a source of problems, hence I think we should avoid leaving them in...

evverx · 2017-09-15T15:38:31Z

I'm not talking about stream logging only.

Given that journald might be used to read data from /dev/log and the syslog protocol allows sending nulls, I would expect journald not to drop them, especially when journald forwards data to syslog.

Also, I'm not sure why, but the following command still results in losing the part after '\0':

printf '<13>Sep 15 15:07:58 HOST: null\0here' | nc -w1 -u -U /run/systemd/journal/dev-log

poettering · 2017-09-15T15:45:10Z

I'm not talking about stream logging only.

but that's a different story really, this PR is about stream logging only...

poettering · 2017-09-15T15:46:14Z

Also, I'm not sure why, but the following command still results in losing the part after '\0':

That's using the AF_UNIX/SOCK_DGRAM protocol, but this PR is exclusively about stdou/stderr stream logging, i.e. AF_UNIX/SOCK_STREAM...

evverx · 2017-09-15T15:52:45Z

but this PR is exclusively about stdou/stderr stream logging, i.e. AF_UNIX/SOCK_STREAM...

I see. Could "fixes #4863" be removed from the commit message then?

I'll update the description of #4863 to be more specific about what I really mean there.

poettering · 2017-09-15T15:55:17Z

I see. Could "fixes #4863" be removed from the commit message then?

Ah right! will do. Sorry for the confusion!

poettering · 2017-09-15T15:57:11Z

for pushed a new version, downgrading "Fixes" to "See" for #4863.

evverx · 2017-09-15T16:11:53Z

man/journald.conf.xml

+        the value is suffixed with K, M, G or T, the specified size is parsed as Kilobytes, Megabytes, Gigabytes, or
+        Terabytes (with the base 1024), respectively. Defaults to 48K, which is relatively large but still small enough
+        so that log records likely fit into network datagrams along with extra room for metadata.</para></listitem>
+      </varlistentry>


I think that 0 should be documented. It would probably make sense to mention that journald sets LineMax to 79 if LineMax < 79. I'm not sure about UINT64_MAX and SSIZE_MAX though.

keszybz · 2017-09-17T06:41:43Z

src/journal/journald-server.c

+                if (v == 0 || v == UINT64_MAX)
+                        /* 0 or maximum means default */
+                        *sz = DEFAULT_LINE_MAX;
+                else if (v < 79) {


I agree with @evverx about dropping the check for 0 and -1. It's easy to enough to say "An empty assignment resets to the the default value". We don't really need a way to specify the same thing in three ways.

keszybz · 2017-09-17T06:48:15Z

src/journal/journald-stream.c

+                end1 = memchr(p, '\n', remaining);
+                end2 = memchr(p, 0, end1 ? (size_t) (end1 - p) : remaining);
+
+                if (end1 && (!end2 || end1 < end2)) {


Line 453 only searches until end1, so end1 >= end2, so the condition could be written as end1 && !end2.

keszybz · 2017-09-17T06:51:36Z

src/journal/journald-stream.c

+                        assert(s->server->line_max > s->length);
+                        new_size = s->server->line_max + 1;
+                } else
+                        new_size = s->length + 1 + 1024;


I don't think the overflow could ever happen. length is size_t, and line_max is limited to SSIZE_T_MAX.

keszybz · 2017-09-17T07:04:43Z

src/journal/journald-stream.c

+                 * entry */
+
+                c =     line_break == LINE_BREAK_NUL ?         "_LINE_BREAK=nul" :
+                        line_break == LINE_BREAK_MAX_REACHED ? "_LINE_BREAK=max-reached" :


I'm not convinced about "max-reached", it doesn't say the maximum of what was reached. Wouldn't "max-line" or "line-max" or "line-limit" or "max-length" be better?

… it to 48K This adds a new setting LineMax= to journald.conf, and sets it by default to 48K. When we convert stream-based stdout/stderr logging into record-based log entries, read up to the specified amount of bytes before forcing a line-break. This also makes three related changes: - When a NUL byte is read we'll not recognize this as alternative line break, instead of silently dropping everything after it. (see systemd#4863) - The reason for a line-break is now encoded in the log record, if it wasn't a plain newline. Specifically, we distuingish "nul", "line-max" and "eof", for line breaks due to NUL byte, due to the maximum line length as configured with LineMax= or due to end of stream. This data is stored in the new implicit _LINE_BREAK= field. It's not synthesized for plain \n line breaks. - A randomized 128bit ID is assigned to each log stream. With these three changes in place it's (mostly) possible to reconstruct the original byte streams from log data, as (most) of the context of the conversion from the byte stream to log records is saved now. (So, the only bits we still drop are empty lines. Which might be something to look into in a future change, and which is outside of the scope of this work) Fixes: https://bugs.freedesktop.org/show_bug.cgi?id=86465 See: systemd#4863 Replaces: systemd#4875

poettering · 2017-09-21T19:20:06Z

force pushed a new version now, addressing all issues pointed out

… it to 48K (systemd#6838) This adds a new setting LineMax= to journald.conf, and sets it by default to 48K. When we convert stream-based stdout/stderr logging into record-based log entries, read up to the specified amount of bytes before forcing a line-break. This also makes three related changes: - When a NUL byte is read we'll not recognize this as alternative line break, instead of silently dropping everything after it. (see systemd#4863) - The reason for a line-break is now encoded in the log record, if it wasn't a plain newline. Specifically, we distuingish "nul", "line-max" and "eof", for line breaks due to NUL byte, due to the maximum line length as configured with LineMax= or due to end of stream. This data is stored in the new implicit _LINE_BREAK= field. It's not synthesized for plain \n line breaks. - A randomized 128bit ID is assigned to each log stream. With these three changes in place it's (mostly) possible to reconstruct the original byte streams from log data, as (most) of the context of the conversion from the byte stream to log records is saved now. (So, the only bits we still drop are empty lines. Which might be something to look into in a future change, and which is outside of the scope of this work) Fixes: https://bugs.freedesktop.org/show_bug.cgi?id=86465 See: systemd#4863 Replaces: systemd#4875 (cherry picked from commit ec20fe5) Resolves: #1442262 [msekleta: I had to manually rewrite upstream commit, because git did very poor job merging old and new code and identified a lot of merge conflicts in a code that was totally unrelated.]

poettering added the journal label Sep 15, 2017

This was referenced Sep 15, 2017

journald: bump log message buffer size to 64K #4875

Closed

systemd-journald drops all bytes after '\0' #4863

Closed

poettering force-pushed the line-max branch from 487ccc1 to f8cd512 Compare September 15, 2017 15:56

evverx reviewed Sep 15, 2017

View reviewed changes

keszybz reviewed Sep 17, 2017

View reviewed changes

poettering force-pushed the line-max branch from f8cd512 to 25c9651 Compare September 21, 2017 19:19

keszybz approved these changes Sep 22, 2017

View reviewed changes

keszybz merged commit ec20fe5 into systemd:master Sep 22, 2017

Uh oh!

journald: make maximum size of stream log lines configurable and bump… #6838

journald: make maximum size of stream log lines configurable and bump… #6838

Uh oh!

Conversation

poettering commented Sep 15, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

evverx commented Sep 15, 2017

Uh oh!

poettering commented Sep 15, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

evverx commented Sep 15, 2017

Uh oh!

poettering commented Sep 15, 2017

Uh oh!

poettering commented Sep 15, 2017

Uh oh!

evverx commented Sep 15, 2017

Uh oh!

poettering commented Sep 15, 2017

Uh oh!

poettering commented Sep 15, 2017

Uh oh!

evverx Sep 15, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

keszybz Sep 17, 2017

Choose a reason for hiding this comment

Uh oh!

keszybz Sep 17, 2017

Choose a reason for hiding this comment

Uh oh!

keszybz Sep 17, 2017

Choose a reason for hiding this comment

Uh oh!

keszybz Sep 17, 2017

Choose a reason for hiding this comment

Uh oh!

poettering commented Sep 21, 2017

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

3 participants

poettering commented Sep 15, 2017 •

edited

Loading

poettering commented Sep 15, 2017 •

edited

Loading

evverx Sep 15, 2017 •

edited

Loading