diff --git a/man/rules/meson.build b/man/rules/meson.build index d496ebc747..4658ef99f0 100644 --- a/man/rules/meson.build +++ b/man/rules/meson.build @@ -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', diff --git a/man/sd_journal_next.xml b/man/sd_journal_next.xml index 628abb296c..cc267fa1bd 100644 --- a/man/sd_journal_next.xml +++ b/man/sd_journal_next.xml @@ -18,6 +18,7 @@ sd_journal_next sd_journal_previous + sd_journal_step_one sd_journal_next_skip sd_journal_previous_skip SD_JOURNAL_FOREACH @@ -39,6 +40,12 @@ sd_journal *j + + int sd_journal_step_one + sd_journal *j + int advanced + + int sd_journal_next_skip sd_journal *j @@ -77,6 +84,16 @@ Similarly, sd_journal_previous() sets the read pointer back one entry. + sd_journal_step_one() also moves the read pointer. If the current location + is the head of the journal, e.g. when this is called following + sd_journal_seek_head(), then this is equivalent to + sd_journal_next(), and the argument advanced will be ignored. + Similary, if the current location is the tail of the journal, e.g. when this is called following + sd_journal_seek_tail(), then this is equivalent to + sd_journal_previous(), and advanced will be ignored. Otherwise, + this is equivalent to sd_journal_next() when advanced is + non-zero, and sd_journal_previous() when advanced is zero. + sd_journal_next_skip() and sd_journal_previous_skip() advance/set back the read pointer by multiple entries at once, as specified in the skip parameter. The skip diff --git a/src/journal/journalctl.c b/src/journal/journalctl.c index c53f2d5847..4f9c1f4780 100644 --- a/src/journal/journalctl.c +++ b/src/journal/journalctl.c @@ -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 diff --git a/src/libsystemd/libsystemd.sym b/src/libsystemd/libsystemd.sym index 35352dc832..936a3577f5 100644 --- a/src/libsystemd/libsystemd.sym +++ b/src/libsystemd/libsystemd.sym @@ -825,4 +825,5 @@ global: sd_event_trim_memory; sd_pid_notify_barrier; sd_event_source_leave_ratelimit; + sd_journal_step_one; } LIBSYSTEMD_253; diff --git a/src/libsystemd/sd-journal/sd-journal.c b/src/libsystemd/sd-journal/sd-journal.c index 47532e2cbc..957817bfab 100644 --- a/src/libsystemd/sd-journal/sd-journal.c +++ b/src/libsystemd/sd-journal/sd-journal.c @@ -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; diff --git a/src/systemd/sd-journal.h b/src/systemd/sd-journal.h index 24e67663b9..4af540400d 100644 --- a/src/systemd/sd-journal.h +++ b/src/systemd/sd-journal.h @@ -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); diff --git a/test/units/testsuite-04.sh b/test/units/testsuite-04.sh index 6ed41f24ea..4af619941b 100755 --- a/test/units/testsuite-04.sh +++ b/test/units/testsuite-04.sh @@ -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:?}"