SymbX/systemd
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge pull request #27519 from yuwata/journalctl-fixes

Browse Source 
journalctl: several fixes and cleanups for --follow
This commit is contained in:
Luca Boccassi
2023-05-31 11:05:54 +01:00
committed by GitHub
parent 23f315dc08 80ec3db5c7
commit 29084afd91
7 changed files with 362 additions and 216 deletions
Download Patch File Download Diff File Expand all files Collapse all files
man/rules/meson.build
+2 -1
View File
@@ -742,7 +742,8 @@ manpages = [
'SD_JOURNAL_FOREACH_BACKWARDS',
'sd_journal_next_skip',
'sd_journal_previous',
'sd_journal_previous_skip'],
'sd_journal_previous_skip',
'sd_journal_step_one'],
''],
['sd_journal_open',
'3',
man/sd_journal_next.xml
+17
View File
@@ -18,6 +18,7 @@
<refnamediv>
<refname>sd_journal_next</refname>
<refname>sd_journal_previous</refname>
<refname>sd_journal_step_one</refname>
<refname>sd_journal_next_skip</refname>
<refname>sd_journal_previous_skip</refname>
<refname>SD_JOURNAL_FOREACH</refname>
@@ -39,6 +40,12 @@
<paramdef>sd_journal *<parameter>j</parameter></paramdef>
</funcprototype>
<funcprototype>
<funcdef>int <function>sd_journal_step_one</function></funcdef>
<paramdef>sd_journal *<parameter>j</parameter></paramdef>
<paramdef>int <parameter>advanced</parameter></paramdef>
</funcprototype>
<funcprototype>
<funcdef>int <function>sd_journal_next_skip</function></funcdef>
<paramdef>sd_journal *<parameter>j</parameter></paramdef>
@@ -77,6 +84,16 @@
<para>Similarly, <function>sd_journal_previous()</function> sets
the read pointer back one entry.</para>
<para><function>sd_journal_step_one()</function> also moves the read pointer. If the current location
is the head of the journal, e.g. when this is called following
<function>sd_journal_seek_head()</function>, then this is equivalent to
<function>sd_journal_next()</function>, and the argument <varname>advanced</varname> will be ignored.
Similary, if the current location is the tail of the journal, e.g. when this is called following
<function>sd_journal_seek_tail()</function>, then this is equivalent to
<function>sd_journal_previous()</function>, and <varname>advanced</varname> will be ignored. Otherwise,
this is equivalent to <function>sd_journal_next()</function> when <varname>advanced</varname> is
non-zero, and <function>sd_journal_previous()</function> when <varname>advanced</varname> is zero.</para>
<para><function>sd_journal_next_skip()</function> and
<function>sd_journal_previous_skip()</function> advance/set back the read pointer by multiple
entries at once, as specified in the <varname>skip</varname> parameter. The <varname>skip</varname>
src/journal/journalctl.c
+318 -215
View File
@@ -65,6 +65,7 @@
#include "rlimit-util.h"
#include "set.h"
#include "sigbus.h"
#include "signal-util.h"
#include "static-destruct.h"
#include "stdio-util.h"
#include "string-table.h"
@@ -115,7 +116,7 @@ static char *arg_verify_key = NULL;
static usec_t arg_interval = DEFAULT_FSS_INTERVAL_USEC;
static bool arg_force = false;
#endif
static usec_t arg_since, arg_until;
static usec_t arg_since = 0, arg_until = 0;
static bool arg_since_set = false, arg_until_set = false;
static char **arg_syslog_identifier = NULL;
static char **arg_system_units = NULL;
@@ -1047,7 +1048,10 @@ static int parse_argv(int argc, char *argv[]) {
assert_not_reached();
}
if (arg_follow && !arg_no_tail && !arg_since && arg_lines == ARG_LINES_DEFAULT)
if (arg_no_tail)
arg_lines = ARG_LINES_ALL;
if (arg_follow && !arg_since_set && arg_lines == ARG_LINES_DEFAULT)
arg_lines = 10;
if (arg_follow && !arg_merge && !arg_boot) {
@@ -2058,51 +2062,295 @@ static int sync_journal(void) {
return simple_varlink_call("--sync", "io.systemd.Journal.Synchronize");
}
static int wait_for_change(sd_journal *j, int poll_fd) {
struct pollfd pollfds[] = {
{ .fd = poll_fd, .events = POLLIN },
{ .fd = STDOUT_FILENO },
};
usec_t timeout;
int r;
static int action_list_fields(sd_journal *j) {
const void *data;
size_t size;
int r, n_shown = 0;
assert(j);
assert(poll_fd >= 0);
assert(arg_field);
/* Much like sd_journal_wait() but also keeps an eye on STDOUT, and exits as soon as we see a POLLHUP on that,
* i.e. when it is closed. */
r = sd_journal_get_timeout(j, &timeout);
r = sd_journal_set_data_threshold(j, 0);
if (r < 0)
return log_error_errno(r, "Failed to determine journal waiting time: %m");
return log_error_errno(r, "Failed to unset data size threshold: %m");
r = ppoll_usec(pollfds, ELEMENTSOF(pollfds), timeout);
if (r == -EINTR)
return 0;
r = sd_journal_query_unique(j, arg_field);
if (r < 0)
return log_error_errno(r, "Couldn't wait for journal event: %m");
return log_error_errno(r, "Failed to query unique data objects: %m");
if (pollfds[1].revents & (POLLHUP|POLLERR)) /* STDOUT has been closed? */
return log_debug_errno(SYNTHETIC_ERRNO(ECANCELED),
"Standard output has been closed.");
SD_JOURNAL_FOREACH_UNIQUE(j, data, size) {
const void *eq;
r = sd_journal_process(j);
if (r < 0)
return log_error_errno(r, "Failed to process journal events: %m");
if (arg_lines >= 0 && n_shown >= arg_lines)
break;
eq = memchr(data, '=', size);
if (eq)
printf("%.*s\n", (int) (size - ((const uint8_t*) eq - (const uint8_t*) data + 1)), (const char*) eq + 1);
else
printf("%.*s\n", (int) size, (const char*) data);
n_shown++;
}
return 0;
}
static int update_cursor(sd_journal *j) {
_cleanup_free_ char *cursor = NULL;
int r;
assert(j);
if (!arg_show_cursor && !arg_cursor_file)
return 0;
r = sd_journal_get_cursor(j, &cursor);
if (r == -EADDRNOTAVAIL)
return 0;
if (r < 0)
return log_error_errno(r, "Failed to get cursor: %m");
if (arg_show_cursor)
printf("-- cursor: %s\n", cursor);
if (arg_cursor_file) {
r = write_string_file(arg_cursor_file, cursor, WRITE_STRING_FILE_CREATE | WRITE_STRING_FILE_ATOMIC);
if (r < 0)
return log_error_errno(r, "Failed to write new cursor to %s: %m", arg_cursor_file);
}
return 0;
}
typedef struct Context {
sd_journal *journal;
bool need_seek;
bool since_seeked;
bool ellipsized;
bool previous_boot_id_valid;
sd_id128_t previous_boot_id;
sd_id128_t previous_boot_id_output;
dual_timestamp previous_ts_output;
} Context;
static int show(Context *c) {
sd_journal *j;
int r, n_shown = 0;
assert(c);
j = ASSERT_PTR(c->journal);
while (arg_lines < 0 || n_shown < arg_lines || arg_follow) {
int flags;
size_t highlight[2] = {};
if (c->need_seek) {
r = sd_journal_step_one(j, !arg_reverse);
if (r < 0)
return log_error_errno(r, "Failed to iterate through journal: %m");
if (r == 0)
break;
}
if (arg_until_set && !arg_reverse && (arg_lines < 0 || arg_since_set)) {
/* If --lines= is set, we usually rely on the n_shown to tell us
* when to stop. However, if --since= is set too, we may end up
* having less than --lines= to output. In this case let's also
* check if the entry is in range. */
usec_t usec;
r = sd_journal_get_realtime_usec(j, &usec);
if (r < 0)
return log_error_errno(r, "Failed to determine timestamp: %m");
if (usec > arg_until)
break;
}
if (arg_since_set && (arg_reverse || !c->since_seeked)) {
usec_t usec;
r = sd_journal_get_realtime_usec(j, &usec);
if (r < 0)
return log_error_errno(r, "Failed to determine timestamp: %m");
if (usec < arg_since) {
if (arg_reverse)
break; /* Reached the earliest entry */
/* arg_lines >= 0 (!since_seeked):
* We jumped arg_lines back and it seems to be too much */
r = sd_journal_seek_realtime_usec(j, arg_since);
if (r < 0)
return log_error_errno(r, "Failed to seek to date: %m");
c->since_seeked = true;
c->need_seek = true;
continue;
}
c->since_seeked = true; /* We're surely within the range of --since now */
}
if (!arg_merge && !arg_quiet) {
sd_id128_t boot_id;
r = sd_journal_get_monotonic_usec(j, NULL, &boot_id);
if (r >= 0) {
if (c->previous_boot_id_valid &&
!sd_id128_equal(boot_id, c->previous_boot_id))
printf("%s-- Boot "SD_ID128_FORMAT_STR" --%s\n",
ansi_highlight(), SD_ID128_FORMAT_VAL(boot_id), ansi_normal());
c->previous_boot_id = boot_id;
c->previous_boot_id_valid = true;
}
}
if (arg_compiled_pattern) {
const void *message;
size_t len;
r = sd_journal_get_data(j, "MESSAGE", &message, &len);
if (r < 0) {
if (r == -ENOENT) {
c->need_seek = true;
continue;
}
return log_error_errno(r, "Failed to get MESSAGE field: %m");
}
assert_se(message = startswith(message, "MESSAGE="));
r = pattern_matches_and_log(arg_compiled_pattern, message,
len - strlen("MESSAGE="), highlight);
if (r < 0)
return r;
if (r == 0) {
c->need_seek = true;
continue;
}
}
flags =
arg_all * OUTPUT_SHOW_ALL |
arg_full * OUTPUT_FULL_WIDTH |
colors_enabled() * OUTPUT_COLOR |
arg_catalog * OUTPUT_CATALOG |
arg_utc * OUTPUT_UTC |
arg_no_hostname * OUTPUT_NO_HOSTNAME;
r = show_journal_entry(stdout, j, arg_output, 0, flags,
arg_output_fields, highlight, &c->ellipsized,
&c->previous_ts_output, &c->previous_boot_id_output);
c->need_seek = true;
if (r == -EADDRNOTAVAIL)
break;
if (r < 0)
return r;
n_shown++;
/* If journalctl take a long time to process messages, and during that time journal file
* rotation occurs, a journalctl client will keep those rotated files open until it calls
* sd_journal_process(), which typically happens as a result of calling sd_journal_wait() below
* in the "following" case. By periodically calling sd_journal_process() during the processing
* loop we shrink the window of time a client instance has open file descriptors for rotated
* (deleted) journal files. */
if ((n_shown % PROCESS_INOTIFY_INTERVAL) == 0) {
r = sd_journal_process(j);
if (r < 0)
return log_error_errno(r, "Failed to process inotify events: %m");
}
}
return n_shown;
}
static int show_and_fflush(Context *c, sd_event_source *s) {
int r;
assert(c);
assert(s);
r = show(c);
if (r < 0)
return sd_event_exit(sd_event_source_get_event(s), r);
fflush(stdout);
return 0;
}
static int on_journal_event(sd_event_source *s, int fd, uint32_t revents, void *userdata) {
Context *c = ASSERT_PTR(userdata);
int r;
assert(s);
r = sd_journal_process(c->journal);
if (r < 0) {
log_error_errno(r, "Failed to process journal events: %m");
return sd_event_exit(sd_event_source_get_event(s), r);
}
return show_and_fflush(c, s);
}
static int on_first_event(sd_event_source *s, void *userdata) {
return show_and_fflush(userdata, s);
}
static int on_signal(sd_event_source *s, const struct signalfd_siginfo *si, void *userdata) {
assert(s);
assert(si);
assert(IN_SET(si->ssi_signo, SIGTERM, SIGINT));
return sd_event_exit(sd_event_source_get_event(s), si->ssi_signo);
}
static int setup_event(Context *c, int fd, sd_event **ret) {
_cleanup_(sd_event_unrefp) sd_event *e = NULL;
int r;
assert(arg_follow);
assert(c);
assert(fd >= 0);
assert(ret);
r = sd_event_default(&e);
if (r < 0)
return log_error_errno(r, "Failed to allocate sd_event object: %m");
(void) sd_event_add_signal(e, NULL, SIGTERM | SD_EVENT_SIGNAL_PROCMASK, on_signal, NULL);
(void) sd_event_add_signal(e, NULL, SIGINT | SD_EVENT_SIGNAL_PROCMASK, on_signal, NULL);
r = sd_event_add_io(e, NULL, fd, EPOLLIN, &on_journal_event, c);
if (r < 0)
return log_error_errno(r, "Failed to add io event source for journal: %m");
/* Also keeps an eye on STDOUT, and exits as soon as we see a POLLHUP on that, i.e. when it is closed. */
r = sd_event_add_io(e, NULL, STDOUT_FILENO, EPOLLHUP|EPOLLERR, NULL, INT_TO_PTR(-ECANCELED));
if (r < 0)
return log_error_errno(r, "Failed to add io event source for stdout: %m");
if (arg_lines != 0 || arg_since_set) {
r = sd_event_add_defer(e, NULL, on_first_event, c);
if (r < 0)
return log_error_errno(r, "Failed to add defer event source: %m");
}
*ret = TAKE_PTR(e);
return 0;
}
static int run(int argc, char *argv[]) {
bool need_seek = false, since_seeked = false, use_cursor = false, after_cursor = false;
_cleanup_(loop_device_unrefp) LoopDevice *loop_device = NULL;
_cleanup_(umount_and_freep) char *mounted_dir = NULL;
bool previous_boot_id_valid = false, first_line = true, ellipsized = false, need_seek = false, since_seeked = false;
bool use_cursor = false, after_cursor = false;
_cleanup_(sd_journal_closep) sd_journal *j = NULL;
sd_id128_t previous_boot_id = SD_ID128_NULL, previous_boot_id_output = SD_ID128_NULL;
dual_timestamp previous_ts_output = DUAL_TIMESTAMP_NULL;
_cleanup_close_ int machine_fd = -EBADF;
int n_shown = 0, r, poll_fd = -EBADF;
int n_shown, r, poll_fd = -EBADF;
setlocale(LC_ALL, "");
log_setup();
@@ -2381,37 +2629,8 @@ static int run(int argc, char *argv[]) {
log_debug("Journal filter: %s", filter);
}
if (arg_action == ACTION_LIST_FIELDS) {
const void *data;
size_t size;
assert(arg_field);
r = sd_journal_set_data_threshold(j, 0);
if (r < 0)
return log_error_errno(r, "Failed to unset data size threshold: %m");
r = sd_journal_query_unique(j, arg_field);
if (r < 0)
return log_error_errno(r, "Failed to query unique data objects: %m");
SD_JOURNAL_FOREACH_UNIQUE(j, data, size) {
const void *eq;
if (arg_lines >= 0 && n_shown >= arg_lines)
break;
eq = memchr(data, '=', size);
if (eq)
printf("%.*s\n", (int) (size - ((const uint8_t*) eq - (const uint8_t*) data + 1)), (const char*) eq + 1);
else
printf("%.*s\n", (int) size, (const char*) data);
n_shown++;
}
return 0;
}
if (arg_action == ACTION_LIST_FIELDS)
return action_list_fields(j);
/* Opening the fd now means the first sd_journal_wait() will actually wait */
if (arg_follow) {
@@ -2540,169 +2759,53 @@ static int run(int argc, char *argv[]) {
}
}
for (;;) {
while (arg_lines < 0 || n_shown < arg_lines || (arg_follow && !first_line)) {
int flags;
size_t highlight[2] = {};
Context c = {
.journal = j,
.need_seek = need_seek,
.since_seeked = since_seeked,
};
if (need_seek) {
if (!arg_reverse)
r = sd_journal_next(j);
else
r = sd_journal_previous(j);
if (r < 0)
return log_error_errno(r, "Failed to iterate through journal: %m");
if (r == 0)
break;
}
if (arg_follow) {
_cleanup_(sd_event_unrefp) sd_event *e = NULL;
int sig;
if (arg_until_set && !arg_reverse && (arg_lines < 0 || arg_since_set)) {
/* If --lines= is set, we usually rely on the n_shown to tell us
* when to stop. However, if --since= is set too, we may end up
* having less than --lines= to output. In this case let's also
* check if the entry is in range. */
assert(poll_fd >= 0);
usec_t usec;
r = sd_journal_get_realtime_usec(j, &usec);
if (r < 0)
return log_error_errno(r, "Failed to determine timestamp: %m");
if (usec > arg_until)
break;
}
if (arg_since_set && (arg_reverse || !since_seeked)) {
usec_t usec;
r = sd_journal_get_realtime_usec(j, &usec);
if (r < 0)
return log_error_errno(r, "Failed to determine timestamp: %m");
if (usec < arg_since) {
if (arg_reverse)
break; /* Reached the earliest entry */
/* arg_lines >= 0 (!since_seeked):
* We jumped arg_lines back and it seems to be too much */
r = sd_journal_seek_realtime_usec(j, arg_since);
if (r < 0)
return log_error_errno(r, "Failed to seek to date: %m");
since_seeked = true;
need_seek = true;
continue;
}
since_seeked = true; /* We're surely within the range of --since now */
}
if (!arg_merge && !arg_quiet) {
sd_id128_t boot_id;
r = sd_journal_get_monotonic_usec(j, NULL, &boot_id);
if (r >= 0) {
if (previous_boot_id_valid &&
!sd_id128_equal(boot_id, previous_boot_id))
printf("%s-- Boot "SD_ID128_FORMAT_STR" --%s\n",
ansi_highlight(), SD_ID128_FORMAT_VAL(boot_id), ansi_normal());
previous_boot_id = boot_id;
previous_boot_id_valid = true;
}
}
if (arg_compiled_pattern) {
const void *message;
size_t len;
r = sd_journal_get_data(j, "MESSAGE", &message, &len);
if (r < 0) {
if (r == -ENOENT) {
need_seek = true;
continue;
}
return log_error_errno(r, "Failed to get MESSAGE field: %m");
}
assert_se(message = startswith(message, "MESSAGE="));
r = pattern_matches_and_log(arg_compiled_pattern, message,
len - strlen("MESSAGE="), highlight);
if (r < 0)
return r;
if (r == 0) {
need_seek = true;
continue;
}
}
flags =
arg_all * OUTPUT_SHOW_ALL |
arg_full * OUTPUT_FULL_WIDTH |
colors_enabled() * OUTPUT_COLOR |
arg_catalog * OUTPUT_CATALOG |
arg_utc * OUTPUT_UTC |
arg_no_hostname * OUTPUT_NO_HOSTNAME;
r = show_journal_entry(stdout, j, arg_output, 0, flags,
arg_output_fields, highlight, &ellipsized,
&previous_ts_output, &previous_boot_id_output);
need_seek = true;
if (r == -EADDRNOTAVAIL)
break;
if (r < 0)
return r;
n_shown++;
/* If journalctl take a long time to process messages, and during that time journal file
* rotation occurs, a journalctl client will keep those rotated files open until it calls
* sd_journal_process(), which typically happens as a result of calling sd_journal_wait() below
* in the "following" case. By periodically calling sd_journal_process() during the processing
* loop we shrink the window of time a client instance has open file descriptors for rotated
* (deleted) journal files. */
if ((n_shown % PROCESS_INOTIFY_INTERVAL) == 0) {
r = sd_journal_process(j);
if (r < 0)
return log_error_errno(r, "Failed to process inotify events: %m");
}
}
if (!arg_follow) {
if (n_shown == 0 && !arg_quiet)
printf("-- No entries --\n");
break;
}
fflush(stdout);
r = wait_for_change(j, poll_fd);
r = setup_event(&c, poll_fd, &e);
if (r < 0)
return r;
first_line = false;
r = sd_event_loop(e);
if (r < 0)
return r;
sig = r;
/* unref signal event sources. */
e = sd_event_unref(e);
r = update_cursor(j);
if (r < 0)
return r;
/* re-send the original signal. */
assert(SIGNAL_VALID(sig));
if (raise(sig) < 0)
log_error("Failed to raise the original signal SIG%s, ignoring: %m", signal_to_string(sig));
return 0;
}
if (arg_show_cursor || arg_cursor_file) {
_cleanup_free_ char *cursor = NULL;
r = show(&c);
if (r < 0)
return r;
n_shown = r;
r = sd_journal_get_cursor(j, &cursor);
if (r < 0 && r != -EADDRNOTAVAIL)
return log_error_errno(r, "Failed to get cursor: %m");
if (r >= 0) {
if (arg_show_cursor)
printf("-- cursor: %s\n", cursor);
if (n_shown == 0 && !arg_quiet)
printf("-- No entries --\n");
if (arg_cursor_file) {
r = write_string_file(arg_cursor_file, cursor,
WRITE_STRING_FILE_CREATE |
WRITE_STRING_FILE_ATOMIC);
if (r < 0)
return log_error_errno(r, "Failed to write new cursor to %s: %m",
arg_cursor_file);
}
}
}
r = update_cursor(j);
if (r < 0)
return r;
if (arg_compiled_pattern && n_shown == 0)
/* --grep was used, no error was thrown, but the pattern didn't
src/libsystemd/libsystemd.sym
+1
View File
@@ -825,4 +825,5 @@ global:
sd_event_trim_memory;
sd_pid_notify_barrier;
sd_event_source_leave_ratelimit;
sd_journal_step_one;
} LIBSYSTEMD_253;
src/libsystemd/sd-journal/sd-journal.c
+10
View File
@@ -979,6 +979,16 @@ _public_ int sd_journal_previous(sd_journal *j) {
return real_journal_next(j, DIRECTION_UP);
}
_public_ int sd_journal_step_one(sd_journal *j, int advanced) {
assert_return(j, -EINVAL);
if (j->current_location.type == LOCATION_HEAD)
return sd_journal_next(j);
if (j->current_location.type == LOCATION_TAIL)
return sd_journal_previous(j);
return real_journal_next(j, advanced ? DIRECTION_DOWN : DIRECTION_UP);
}
static int real_journal_next_skip(sd_journal *j, direction_t direction, uint64_t skip) {
int c = 0, r;
src/systemd/sd-journal.h
+1
View File
@@ -93,6 +93,7 @@ void sd_journal_close(sd_journal *j);
int sd_journal_previous(sd_journal *j);
int sd_journal_next(sd_journal *j);
int sd_journal_step_one(sd_journal *j, int advanced);
int sd_journal_previous_skip(sd_journal *j, uint64_t skip);
int sd_journal_next_skip(sd_journal *j, uint64_t skip);
test/units/testsuite-04.sh
+13
View File
@@ -161,6 +161,19 @@ journalctl --follow --file=/var/log/journal/*/* | head -n1 | grep .
journalctl --follow --merge | head -n1 | grep .
set -o pipefail
# https://github.com/systemd/systemd/issues/26746
rm -f /tmp/issue-26746-log /tmp/issue-26746-cursor
ID=$(systemd-id128 new)
journalctl -t "$ID" --follow --cursor-file=/tmp/issue-26746-cursor | tee /tmp/issue-26746-log &
systemd-cat -t "$ID" /bin/sh -c 'echo hogehoge'
# shellcheck disable=SC2016
timeout 10 bash -c 'while ! [[ -f /tmp/issue-26746-log && "$(cat /tmp/issue-26746-log)" =~ hogehoge ]]; do sleep .5; done'
pkill -TERM journalctl
test -f /tmp/issue-26746-cursor
CURSOR_FROM_FILE=$(cat /tmp/issue-26746-cursor)
CURSOR_FROM_JOURNAL=$(journalctl -t "$ID" --output export MESSAGE=hogehoge | sed -n -e '/__CURSOR=/ { s/__CURSOR=//; p }')
test "$CURSOR_FROM_FILE" = "$CURSOR_FROM_JOURNAL"
add_logs_filtering_override() {
local unit="${1:?}"
local override_name="${2:?}"