From 034e9719ac1ba88a36b05da38c7aa98761d42c77 Mon Sep 17 00:00:00 2001 From: Benjamin Robin Date: Sun, 3 May 2020 18:37:21 +0200 Subject: [PATCH 1/8] journald: Increase stdout buffer size sooner, when almost full If the previous received buffer length is almost equal to the allocated buffer size, before this change the next read can only receive a couple of bytes (in the worst case only 1 byte), which is not efficient. --- src/journal/journald-stream.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/journal/journald-stream.c b/src/journal/journald-stream.c index 4dadbd62be..6c10bfc259 100644 --- a/src/journal/journald-stream.c +++ b/src/journal/journald-stream.c @@ -511,8 +511,8 @@ static int stdout_stream_process(sd_event_source *es, int fd, uint32_t revents, goto terminate; } - /* If the buffer is full already (discounting the extra NUL we need), add room for another 1K */ - if (s->length + 1 >= s->allocated) { + /* If the buffer is almost full, add room for another 1K */ + if (s->length + 512 >= s->allocated) { if (!GREEDY_REALLOC(s->buffer, s->allocated, s->length + 1 + 1024)) { log_oom(); goto terminate; From 5fe7fb0bf604b7652091ffacd5679b310b18a70f Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 12 May 2020 18:52:33 +0200 Subject: [PATCH 2/8] journald: use log_warning_errno() where appropriate --- src/journal/journald-stream.c | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/src/journal/journald-stream.c b/src/journal/journald-stream.c index 6c10bfc259..e4f0ee36f4 100644 --- a/src/journal/journald-stream.c +++ b/src/journal/journald-stream.c @@ -322,8 +322,8 @@ static int stdout_stream_log(StdoutStream *s, const char *p, LineBreak line_brea } static int stdout_stream_line(StdoutStream *s, char *p, LineBreak line_break) { - int r; char *orig; + int r; assert(s); assert(p); @@ -332,10 +332,9 @@ static int stdout_stream_line(StdoutStream *s, char *p, LineBreak line_break) { p = strstrip(p); /* line breaks by NUL, line max length or EOF are not permissible during the negotiation part of the protocol */ - if (line_break != LINE_BREAK_NEWLINE && s->state != STDOUT_STREAM_RUNNING) { - log_warning("Control protocol line not properly terminated."); - return -EINVAL; - } + if (line_break != LINE_BREAK_NEWLINE && s->state != STDOUT_STREAM_RUNNING) + return log_warning_errno(SYNTHETIC_ERRNO(EINVAL), + "Control protocol line not properly terminated."); switch (s->state) { From 549b7379ba404c33fd448d2bca46a57f6529b00b Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 12 May 2020 18:53:35 +0200 Subject: [PATCH 3/8] journald: rework end of line marker handling to use a field table --- src/journal/journald-stream.c | 29 ++++++++++++++++++++--------- 1 file changed, 20 insertions(+), 9 deletions(-) diff --git a/src/journal/journald-stream.c b/src/journal/journald-stream.c index e4f0ee36f4..593bbc1476 100644 --- a/src/journal/journald-stream.c +++ b/src/journal/journald-stream.c @@ -58,6 +58,8 @@ typedef enum LineBreak { LINE_BREAK_NUL, LINE_BREAK_LINE_MAX, LINE_BREAK_EOF, + _LINE_BREAK_MAX, + _LINE_BREAK_INVALID = -1, } LineBreak; struct StdoutStream { @@ -238,7 +240,11 @@ fail: return log_error_errno(r, "Failed to save stream data %s: %m", s->state_file); } -static int stdout_stream_log(StdoutStream *s, const char *p, LineBreak line_break) { +static int stdout_stream_log( + StdoutStream *s, + const char *p, + LineBreak line_break) { + struct iovec *iovec; int priority; char syslog_priority[] = "PRIORITY=\0"; @@ -250,6 +256,9 @@ static int stdout_stream_log(StdoutStream *s, const char *p, LineBreak line_brea assert(s); assert(p); + assert(line_break >= 0); + assert(line_break < _LINE_BREAK_MAX); + if (s->context) (void) client_context_maybe_refresh(s->server, s->context, NULL, NULL, 0, NULL, USEC_INFINITY); else if (pid_is_valid(s->ucred.pid)) { @@ -301,17 +310,19 @@ static int stdout_stream_log(StdoutStream *s, const char *p, LineBreak line_brea iovec[n++] = IOVEC_MAKE_STRING(syslog_identifier); } - if (line_break != LINE_BREAK_NEWLINE) { - const char *c; + static const char * const line_break_field_table[_LINE_BREAK_MAX] = { + [LINE_BREAK_NEWLINE] = NULL, /* Do not add field if traditional newline */ + [LINE_BREAK_NUL] = "_LINE_BREAK=nul", + [LINE_BREAK_LINE_MAX] = "_LINE_BREAK=line-max", + [LINE_BREAK_EOF] = "_LINE_BREAK=eof", + }; - /* If this log message was generated due to an uncommon line break then mention this in the log - * entry */ + const char *c = line_break_field_table[line_break]; - c = line_break == LINE_BREAK_NUL ? "_LINE_BREAK=nul" : - line_break == LINE_BREAK_LINE_MAX ? "_LINE_BREAK=line-max" : - "_LINE_BREAK=eof"; + /* If this log message was generated due to an uncommon line break then mention this in the log + * entry */ + if (c) iovec[n++] = IOVEC_MAKE_STRING(c); - } message = strjoin("MESSAGE=", p); if (message) From 020b4a023c2c6dda83afb9a82a62e640569c40c1 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 12 May 2020 19:15:38 +0200 Subject: [PATCH 4/8] journald: use the fact that client_context_release() returns NULL --- src/journal/journald-stream.c | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/journal/journald-stream.c b/src/journal/journald-stream.c index 593bbc1476..4f8b5ce301 100644 --- a/src/journal/journald-stream.c +++ b/src/journal/journald-stream.c @@ -563,8 +563,7 @@ static int stdout_stream_process(sd_event_source *es, int fd, uint32_t revents, goto terminate; s->ucred = *ucred; - client_context_release(s->server, s->context); - s->context = NULL; + s->context = client_context_release(s->server, s->context); } s->length += l; From 45ba1ea5e9264d385fa565328fe957ef1d78caa1 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 12 May 2020 18:56:34 +0200 Subject: [PATCH 5/8] journald: rework pid change handling Let's introduce an explicit line ending marker for line endings due to pid change. Let's also make sure we don't get confused with buffer management. Fixes: #15654 --- src/journal/journald-stream.c | 103 ++++++++++++++++++++++------------ 1 file changed, 68 insertions(+), 35 deletions(-) diff --git a/src/journal/journald-stream.c b/src/journal/journald-stream.c index 4f8b5ce301..241e2572e6 100644 --- a/src/journal/journald-stream.c +++ b/src/journal/journald-stream.c @@ -58,6 +58,7 @@ typedef enum LineBreak { LINE_BREAK_NUL, LINE_BREAK_LINE_MAX, LINE_BREAK_EOF, + LINE_BREAK_PID_CHANGE, _LINE_BREAK_MAX, _LINE_BREAK_INVALID = -1, } LineBreak; @@ -315,6 +316,7 @@ static int stdout_stream_log( [LINE_BREAK_NUL] = "_LINE_BREAK=nul", [LINE_BREAK_LINE_MAX] = "_LINE_BREAK=line-max", [LINE_BREAK_EOF] = "_LINE_BREAK=eof", + [LINE_BREAK_PID_CHANGE] = "_LINE_BREAK=pid-change", }; const char *c = line_break_field_table[line_break]; @@ -435,21 +437,43 @@ static int stdout_stream_line(StdoutStream *s, char *p, LineBreak line_break) { assert_not_reached("Unknown stream state"); } -static int stdout_stream_scan(StdoutStream *s, bool force_flush) { - char *p; - size_t remaining; +static int stdout_stream_found( + StdoutStream *s, + char *p, + size_t l, + LineBreak line_break) { + + char saved; int r; assert(s); + assert(p); - p = s->buffer; - remaining = s->length; + /* Let's NUL terminate the specified buffer for this call, and revert back afterwards */ + saved = p[l]; + p[l] = 0; + r = stdout_stream_line(s, p, line_break); + p[l] = saved; - /* XXX: This function does nothing if (s->length == 0) */ + return r; +} + +static int stdout_stream_scan( + StdoutStream *s, + char *p, + size_t remaining, + LineBreak force_flush, + size_t *ret_consumed) { + + size_t consumed = 0; + int r; + + assert(s); + assert(p); for (;;) { LineBreak line_break; - size_t skip; + size_t skip, found; char *end1, *end2; end1 = memchr(p, '\n', remaining); @@ -457,43 +481,40 @@ static int stdout_stream_scan(StdoutStream *s, bool force_flush) { if (end2) { /* We found a NUL terminator */ - skip = end2 - p + 1; + found = end2 - p; + skip = found + 1; line_break = LINE_BREAK_NUL; } else if (end1) { /* We found a \n terminator */ - *end1 = 0; - skip = end1 - p + 1; + found = end1 - p; + skip = found + 1; line_break = LINE_BREAK_NEWLINE; } else if (remaining >= s->server->line_max) { /* Force a line break after the maximum line length */ - *(p + s->server->line_max) = 0; - skip = remaining; + found = skip = s->server->line_max; line_break = LINE_BREAK_LINE_MAX; } else break; - r = stdout_stream_line(s, p, line_break); + r = stdout_stream_found(s, p, found, line_break); if (r < 0) return r; - remaining -= skip; p += skip; + consumed += skip; + remaining -= skip; } - if (force_flush && remaining > 0) { - p[remaining] = 0; - r = stdout_stream_line(s, p, LINE_BREAK_EOF); + if (force_flush >= 0 && remaining > 0) { + r = stdout_stream_found(s, p, remaining, force_flush); if (r < 0) return r; - p += remaining; - remaining = 0; + consumed += remaining; } - if (p > s->buffer) { - memmove(s->buffer, p, remaining); - s->length = remaining; - } + if (ret_consumed) + *ret_consumed = consumed; return 0; } @@ -501,10 +522,11 @@ static int stdout_stream_scan(StdoutStream *s, bool force_flush) { static int stdout_stream_process(sd_event_source *es, int fd, uint32_t revents, void *userdata) { CMSG_BUFFER_TYPE(CMSG_SPACE(sizeof(struct ucred))) control; StdoutStream *s = userdata; + size_t limit, consumed; struct ucred *ucred; struct iovec iovec; - size_t limit; ssize_t l; + char *p; int r; struct msghdr msghdr = { @@ -532,7 +554,7 @@ static int stdout_stream_process(sd_event_source *es, int fd, uint32_t revents, /* Try to make use of the allocated buffer in full, but never read more than the configured line size. Also, * always leave room for a terminating NUL we might need to add. */ limit = MIN(s->allocated - 1, s->server->line_max); - + assert(s->length <= limit); iovec = IOVEC_MAKE(s->buffer + s->length, limit - s->length); l = recvmsg(s->fd, &msghdr, MSG_DONTWAIT|MSG_CMSG_CLOEXEC); @@ -546,31 +568,42 @@ static int stdout_stream_process(sd_event_source *es, int fd, uint32_t revents, cmsg_close_all(&msghdr); if (l == 0) { - stdout_stream_scan(s, true); + (void) stdout_stream_scan(s, s->buffer, s->length, /* force_flush = */ LINE_BREAK_EOF, NULL); goto terminate; } - /* Invalidate the context if the pid of the sender changed. This happens when a forked process - * inherits stdout / stderr from a parent. In this case getpeercred returns the ucred of the parent, - * which can be invalid if the parent has exited in the meantime. - */ + /* Invalidate the context if the PID of the sender changed. This happens when a forked process + * inherits stdout/stderr from a parent. In this case getpeercred() returns the ucred of the parent, + * which can be invalid if the parent has exited in the meantime. */ ucred = CMSG_FIND_DATA(&msghdr, SOL_SOCKET, SCM_CREDENTIALS, struct ucred); if (ucred && ucred->pid != s->ucred.pid) { - /* force out any previously half-written lines from a different process, before we switch to + /* Force out any previously half-written lines from a different process, before we switch to * the new ucred structure for everything we just added */ - r = stdout_stream_scan(s, true); + r = stdout_stream_scan(s, s->buffer, s->length, /* force_flush = */ LINE_BREAK_PID_CHANGE, NULL); if (r < 0) goto terminate; - s->ucred = *ucred; s->context = client_context_release(s->server, s->context); + + p = s->buffer + s->length; + } else { + p = s->buffer; + l += s->length; } - s->length += l; - r = stdout_stream_scan(s, false); + /* Always copy in the new credentials */ + if (ucred) + s->ucred = *ucred; + + r = stdout_stream_scan(s, p, l, _LINE_BREAK_INVALID, &consumed); if (r < 0) goto terminate; + /* Move what wasn't consumed to the front of the buffer */ + assert(consumed <= (size_t) l); + s->length = l - consumed; + memmove(s->buffer, p + consumed, s->length); + return 1; terminate: From c11d8fd1dab3bc3f0abbc861ba5eb34518cec1da Mon Sep 17 00:00:00 2001 From: Benjamin Robin Date: Wed, 6 May 2020 23:28:02 +0200 Subject: [PATCH 6/8] test: Add a test case for #15654 --- test/units/testsuite-04.sh | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/test/units/testsuite-04.sh b/test/units/testsuite-04.sh index 6e7627313c..df216a06a3 100755 --- a/test/units/testsuite-04.sh +++ b/test/units/testsuite-04.sh @@ -87,6 +87,14 @@ journalctl -b -o export -t "$ID" --output-fields=_PID | grep '^_PID=' >/output grep -q "^_PID=$PID" /output grep -vq "^_PID=$PID" /output +# https://github.com/systemd/systemd/issues/15654 +ID=$(journalctl --new-id128 | sed -n 2p) +printf "This will\nusually fail\nand be truncated\n">/expected +systemd-cat -t "$ID" /bin/sh -c 'env echo -n "This will";echo;env echo -n "usually fail";echo;env echo -n "and be truncated";echo;' +journalctl --sync +journalctl -b -o cat -t "$ID" >/output +cmp /expected /output + # Add new tests before here, the journald restarts below # may make tests flappy. From d38b3b74dbde2d65b23e5963354c3db96acd3420 Mon Sep 17 00:00:00 2001 From: Benjamin Robin Date: Sat, 9 May 2020 12:01:07 +0200 Subject: [PATCH 7/8] test: Stricter test case for #15654 (Add more checks) Check: - There is only 3 messages logged with type stdout - Check all messages logged does not have new line: LINE_BREAK=eof - Check that the 3 messages are logged from a different PID - Check the 3 MESSAGE= content --- test/units/testsuite-04.sh | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/test/units/testsuite-04.sh b/test/units/testsuite-04.sh index df216a06a3..3dce73b778 100755 --- a/test/units/testsuite-04.sh +++ b/test/units/testsuite-04.sh @@ -94,6 +94,10 @@ systemd-cat -t "$ID" /bin/sh -c 'env echo -n "This will";echo;env echo -n "usual journalctl --sync journalctl -b -o cat -t "$ID" >/output cmp /expected /output +[[ $(journalctl -b -o cat -t "$ID" --output-fields=_TRANSPORT | grep -Pc "^stdout$") -eq 3 ]] +[[ $(journalctl -b -o cat -t "$ID" --output-fields=_LINE_BREAK | grep -Pc "^pid-change$") -eq 3 ]] +[[ $(journalctl -b -o cat -t "$ID" --output-fields=_PID | sort -u | grep -c "^.*$") -eq 3 ]] +[[ $(journalctl -b -o cat -t "$ID" --output-fields=MESSAGE | grep -Pc "^(This will|usually fail|and be truncated)$") -eq 3 ]] # Add new tests before here, the journald restarts below # may make tests flappy. From a3d9aee14fa2f7df429dc401582877176206b7fd Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Wed, 13 May 2020 00:09:43 +0200 Subject: [PATCH 8/8] man: document the new _LINE_BREAK= type --- man/systemd.journal-fields.xml | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/man/systemd.journal-fields.xml b/man/systemd.journal-fields.xml index a0771f3c13..4d35cfb6dc 100644 --- a/man/systemd.journal-fields.xml +++ b/man/systemd.journal-fields.xml @@ -347,15 +347,16 @@ _LINE_BREAK= - Only applies to _TRANSPORT=stdout records: indicates that the log message in the - standard output/error stream was not terminated with a normal newline character (\n, - i.e. ASCII 10). Specifically, when set this field is one of (in case the line was - terminated by a NUL byte), (in case the maximum log line length was reached, as - configured with LineMax= in - journald.conf5) or - (if this was the last log record of a stream and the stream ended without a final - newline character). Note that this record is not generated when a normal newline character was used for - marking the log line end. + Only applies to _TRANSPORT=stdout records: indicates that the log message + in the standard output/error stream was not terminated with a normal newline character + (\n, i.e. ASCII 10). Specifically, when set this field is one of + (in case the line was terminated by a NUL byte), (in + case the maximum log line length was reached, as configured with LineMax= in + journald.conf5), + (if this was the last log record of a stream and the stream ended without a + final newline character), or (if the process which generated the log + output changed in the middle of a line). Note that this record is not generated when a normal + newline character was used for marking the log line end.