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

Merge pull request #26355 from poettering/journal-no-rtc

Browse Source 
journald: support ordering journal entries by boot ID if no RTC is available
This commit is contained in:
Lennart Poettering
2023-03-03 13:13:13 +01:00
committed by GitHub
parent 11875a98e4 c48f13d8e1
commit 16a9ad557d
16 changed files with 331 additions and 18 deletions
Download Patch File Download Diff File Expand all files Collapse all files
TODO
+10
View File
@@ -164,6 +164,16 @@ Features:
* SIGRTMIN+18 and memory pressure handling should still be added to: hostnamed,
localed, oomd, timedated.
* journald: also collect CLOCK_BOOTTIME timestamps per log entry. Then, derive
"corrected" CLOCK_REALTIME information on display from that and the timestamp
info of the newest entry of the specificy boot (as identified by the boot
ID). This way, if a system comes up without a valid clock but acquires a
better clock later, we can "fix" older entry timestamps on display, by
calculating backwards. We cannot use CLOCK_MONOTONIC for this, since it does
not account for suspend phases. This would then also enable us to correct the
kmsg timestamping we consume (where we erroneously assume the clock was in
CLOCK_MONOTONIC, but it actually is CLOCK_BOOTTIME as per kernel).
* sd-journal puts a limit on parallel journal files to view at once. journald
should probably honour that same limit (JOURNAL_FILES_MAX) when vacuuming to
ensure we never generate more files than we can actually view.
docs/JOURNAL_FILE_FORMAT.md
+7 -2
View File
@@ -178,8 +178,10 @@ _packed_ struct Header {
le64_t data_hash_chain_depth;
le64_t field_hash_chain_depth;
/* Added in 252 */
le32_t tail_entry_array_offset; \
le32_t tail_entry_array_n_entries; \
le32_t tail_entry_array_offset;
le32_t tail_entry_array_n_entries;
/* Added in 254 */
le64_t tail_entry_offset;
};
```
@@ -252,6 +254,9 @@ field hash table, minus one.
**tail_entry_array_offset** and **tail_entry_array_n_entries** allow immediate
access to the last entry array in the global entry array chain.
**tail_entry_offset** allow immediate access to the last entry in the journal
file.
## Extensibility
The format is supposed to be extensible in order to enable future additions of
src/libsystemd/sd-journal/journal-def.h
+3 -1
View File
@@ -239,12 +239,14 @@ enum {
/* Added in 252 */ \
le32_t tail_entry_array_offset; \
le32_t tail_entry_array_n_entries; \
/* Added in 254 */ \
le64_t tail_entry_offset; \
}
struct Header struct_Header__contents;
struct Header__packed struct_Header__contents _packed_;
assert_cc(sizeof(struct Header) == sizeof(struct Header__packed));
assert_cc(sizeof(struct Header) == 264);
assert_cc(sizeof(struct Header) == 272);
#define FSS_HEADER_SIGNATURE \
((const char[]) { 'K', 'S', 'H', 'H', 'R', 'H', 'L', 'P' })
src/libsystemd/sd-journal/journal-file.c
+9
View File
@@ -28,6 +28,7 @@
#include "lookup3.h"
#include "memory-util.h"
#include "path-util.h"
#include "prioq.h"
#include "random-util.h"
#include "set.h"
#include "sort-util.h"
@@ -505,6 +506,11 @@ static int journal_file_verify_header(JournalFile *f) {
!VALID64(le64toh(f->header->entry_array_offset)))
return -ENODATA;
if (JOURNAL_HEADER_CONTAINS(f->header, tail_entry_offset) &&
le64toh(f->header->tail_entry_offset) != 0 &&
!VALID64(le64toh(f->header->tail_entry_offset)))
return -ENODATA;
if (journal_file_writable(f)) {
sd_id128_t machine_id;
uint8_t state;
@@ -2053,6 +2059,8 @@ static int journal_file_link_entry(
f->header->tail_entry_realtime = o->entry.realtime;
f->header->tail_entry_monotonic = o->entry.monotonic;
f->header->tail_entry_offset = offset;
f->newest_mtime = 0; /* we have a new tail entry now, explicitly invalidate newest boot id/timestamp info */
/* Link up the items */
for (uint64_t i = 0; i < n_items; i++) {
@@ -3781,6 +3789,7 @@ int journal_file_open(
DEFAULT_COMPRESS_THRESHOLD :
MAX(MIN_COMPRESS_THRESHOLD, compress_threshold_bytes),
.strict_order = FLAGS_SET(file_flags, JOURNAL_STRICT_ORDER),
.newest_boot_id_prioq_idx = PRIOQ_IDX_NULL,
};
if (fname) {
src/libsystemd/sd-journal/journal-file.h
+8
View File
@@ -121,6 +121,14 @@ typedef struct JournalFile {
void *fsprg_seed;
size_t fsprg_seed_size;
#endif
/* When we insert this file into the per-boot priority queue 'newest_by_boot_id' in sd_journal, then by these keys */
sd_id128_t newest_boot_id;
sd_id128_t newest_machine_id;
uint64_t newest_monotonic_usec;
uint64_t newest_realtime_usec;
unsigned newest_boot_id_prioq_idx;
usec_t newest_mtime;
} JournalFile;
typedef enum JournalFileFlags {
src/libsystemd/sd-journal/journal-internal.h
+1
View File
@@ -78,6 +78,7 @@ struct sd_journal {
OrderedHashmap *files;
IteratedCache *files_cache;
MMapCache *mmap;
Hashmap *newest_by_boot_id; /* key: boot_id, value: prioq, ordered by monotonic timestamp of last update */
Location current_location;
src/libsystemd/sd-journal/sd-journal.c
+269 -15
View File
@@ -34,6 +34,7 @@
#include "lookup3.h"
#include "nulstr-util.h"
#include "path-util.h"
#include "prioq.h"
#include "process-util.h"
#include "replace-var.h"
#include "stat-util.h"
@@ -51,6 +52,8 @@
#define DEFAULT_DATA_THRESHOLD (64*1024)
static void remove_file_real(sd_journal *j, JournalFile *f);
static int journal_file_read_tail_timestamp(sd_journal *j, JournalFile *f);
static void journal_file_unlink_newest_by_bood_id(sd_journal *j, JournalFile *f);
static bool journal_pid_changed(sd_journal *j) {
assert(j);
@@ -414,9 +417,76 @@ _public_ void sd_journal_flush_matches(sd_journal *j) {
detach_location(j);
}
_pure_ static int compare_with_location(const JournalFile *f, const Location *l, const JournalFile *current_file) {
static int journal_file_find_newest_for_boot_id(
sd_journal *j,
sd_id128_t id,
JournalFile **ret) {
JournalFile *prev = NULL;
int r;
assert(j);
assert(ret);
/* Before we use it, let's refresh the timestamp from the header, and reshuffle our prioq
* accordingly. We do this only a bunch of times, to not be caught in some update loop. */
for (unsigned n_tries = 0;; n_tries++) {
JournalFile *f;
Prioq *q;
q = hashmap_get(j->newest_by_boot_id, &id);
if (!q)
return log_debug_errno(SYNTHETIC_ERRNO(ENODATA),
"Requested delta for boot ID %s, but we have no information about that boot ID.", SD_ID128_TO_STRING(id));
assert_se(f = prioq_peek(q)); /* we delete hashmap entries once the prioq is empty, so this must hold */
if (f == prev || n_tries >= 5) {
/* This was already the best answer in the previous run, or we tried too often, use it */
*ret = f;
return 0;
}
prev = f;
/* Let's read the journal file's current timestamp once, before we return it, maybe it has changed. */
r = journal_file_read_tail_timestamp(j, f);
if (r < 0)
return log_debug_errno(r, "Failed to read tail timestamp while trying to find newest journal file for boot ID %s.", SD_ID128_TO_STRING(id));
/* Refreshing the timestamp we read might have reshuffled the prioq, hence let's check the
* prioq again and only use the the information once we reached an equilibrium or hit a
* limit */
}
}
static int compare_boot_ids(sd_journal *j, sd_id128_t a, sd_id128_t b) {
JournalFile *x, *y;
assert(j);
/* Try to find the newest open journal file for the two boot ids */
if (journal_file_find_newest_for_boot_id(j, a, &x) < 0 ||
journal_file_find_newest_for_boot_id(j, b, &y) < 0)
return 0;
/* Only compare the boot id timestamps if they originate from the same machine. If they are from
* different machines, then we timestamps of the boot ids might be as off as the timestamps on the
* entries and hence not useful for comparing. */
if (!sd_id128_equal(x->newest_machine_id, y->newest_machine_id))
return 0;
return CMP(x->newest_realtime_usec, y->newest_realtime_usec);
}
static int compare_with_location(
sd_journal *j,
const JournalFile *f,
const Location *l,
const JournalFile *current_file) {
int r;
assert(j);
assert(f);
assert(l);
assert(f->location_type == LOCATION_SEEK);
@@ -436,29 +506,30 @@ _pure_ static int compare_with_location(const JournalFile *f, const Location *l,
if (l->seqnum_set &&
sd_id128_equal(f->header->seqnum_id, l->seqnum_id)) {
r = CMP(f->current_seqnum, l->seqnum);
if (r != 0)
return r;
}
if (l->monotonic_set &&
sd_id128_equal(f->current_boot_id, l->boot_id)) {
r = CMP(f->current_monotonic, l->monotonic);
if (l->monotonic_set) {
/* If both arguments have the same boot ID, then we can compare the monotonic timestamps. If
* they are distinct, then we might able to lookup the timestamps of those boot IDs (if they
* are from the same machine) and order by that. */
if (sd_id128_equal(f->current_boot_id, l->boot_id))
r = CMP(f->current_monotonic, l->monotonic);
else
r = compare_boot_ids(j, f->current_boot_id, l->boot_id);
if (r != 0)
return r;
}
if (l->realtime_set) {
r = CMP(f->current_realtime, l->realtime);
if (r != 0)
return r;
}
if (l->xor_hash_set) {
r = CMP(f->current_xor_hash, l->xor_hash);
if (r != 0)
return r;
@@ -741,6 +812,8 @@ static int next_beyond_location(sd_journal *j, JournalFile *f, direction_t direc
assert(j);
assert(f);
(void) journal_file_read_tail_timestamp(j, f);
n_entries = le64toh(f->header->n_entries);
/* If we hit EOF before, we don't need to look into this file again
@@ -784,7 +857,7 @@ static int next_beyond_location(sd_journal *j, JournalFile *f, direction_t direc
if (j->current_location.type == LOCATION_DISCRETE) {
int k;
k = compare_with_location(f, &j->current_location, j->current_file);
k = compare_with_location(j, f, &j->current_location, j->current_file);
found = direction == DIRECTION_DOWN ? k > 0 : k < 0;
} else
@@ -801,9 +874,10 @@ static int next_beyond_location(sd_journal *j, JournalFile *f, direction_t direc
}
}
static int compare_locations(JournalFile *af, JournalFile *bf) {
static int compare_locations(sd_journal *j, JournalFile *af, JournalFile *bf) {
int r;
assert(j);
assert(af);
assert(af->header);
assert(bf);
@@ -830,12 +904,14 @@ static int compare_locations(JournalFile *af, JournalFile *bf) {
* make the best of it and compare by time. */
}
if (sd_id128_equal(af->current_boot_id, bf->current_boot_id)) {
if (sd_id128_equal(af->current_boot_id, bf->current_boot_id))
/* If the boot id matches, compare monotonic time */
r = CMP(af->current_monotonic, bf->current_monotonic);
if (r != 0)
return r;
}
else
/* If they don't match try to compare boot IDs */
r = compare_boot_ids(j, af->current_boot_id, bf->current_boot_id);
if (r != 0)
return r;
/* Otherwise, compare UTC time */
r = CMP(af->current_realtime, bf->current_realtime);
@@ -879,7 +955,7 @@ static int real_journal_next(sd_journal *j, direction_t direction) {
else {
int k;
k = compare_locations(f, new_file);
k = compare_locations(j, f, new_file);
found = direction == DIRECTION_DOWN ? k < 0 : k > 0;
}
@@ -1351,6 +1427,7 @@ static int add_any_file(
* which are gone. */
f->last_seen_generation = j->generation;
(void) journal_file_read_tail_timestamp(j, f);
return 0;
}
@@ -1391,6 +1468,7 @@ static int add_any_file(
track_file_disposition(j, f);
check_network(j, f->fd);
(void) journal_file_read_tail_timestamp(j, f);
j->current_invalidate_counter++;
@@ -1479,6 +1557,7 @@ static void remove_file_real(sd_journal *j, JournalFile *f) {
j->fields_file_lost = true;
}
journal_file_unlink_newest_by_bood_id(j, f);
(void) journal_file_close(f);
j->current_invalidate_counter++;
@@ -2173,10 +2252,15 @@ fail:
_public_ void sd_journal_close(sd_journal *j) {
Directory *d;
Prioq *p;
if (!j)
return;
while ((p = hashmap_first(j->newest_by_boot_id)))
journal_file_unlink_newest_by_bood_id(j, prioq_peek(p));
hashmap_free(j->newest_by_boot_id);
sd_journal_flush_matches(j);
ordered_hashmap_free_with_destructor(j->files, journal_file_close);
@@ -2208,6 +2292,176 @@ _public_ void sd_journal_close(sd_journal *j) {
free(j);
}
static void journal_file_unlink_newest_by_bood_id(sd_journal *j, JournalFile *f) {
JournalFile *nf;
Prioq *p;
assert(j);
assert(f);
if (f->newest_boot_id_prioq_idx == PRIOQ_IDX_NULL) /* not linked currently, hence this is a NOP */
return;
assert_se(p = hashmap_get(j->newest_by_boot_id, &f->newest_boot_id));
assert_se(prioq_remove(p, f, &f->newest_boot_id_prioq_idx) > 0);
nf = prioq_peek(p);
if (nf)
/* There's still a member in the prioq? Then make sure the hashmap key now points to its
* .newest_boot_id field (and not ours!). Not we only replace the memory of the key here, the
* value of the key (and the data associated with it) remain the same. */
assert_se(hashmap_update(j->newest_by_boot_id, &nf->newest_boot_id, p) >= 0);
else {
assert_se(hashmap_remove(j->newest_by_boot_id, &f->newest_boot_id) == p);
prioq_free(p);
}
f->newest_boot_id_prioq_idx = PRIOQ_IDX_NULL;
}
static int journal_file_newest_monotonic_compare(const void *a, const void *b) {
const JournalFile *x = a, *y = b;
return -CMP(x->newest_monotonic_usec, y->newest_monotonic_usec); /* Invert order, we want newest first! */
}
static int journal_file_reshuffle_newest_by_boot_id(sd_journal *j, JournalFile *f) {
Prioq *p;
int r;
assert(j);
assert(f);
p = hashmap_get(j->newest_by_boot_id, &f->newest_boot_id);
if (p) {
/* There's already a priority queue for this boot ID */
if (f->newest_boot_id_prioq_idx == PRIOQ_IDX_NULL) {
r = prioq_put(p, f, &f->newest_boot_id_prioq_idx); /* Insert if we aren't in there yet */
if (r < 0)
return r;
} else
prioq_reshuffle(p, f, &f->newest_boot_id_prioq_idx); /* Reshuffle otherwise */
} else {
_cleanup_(prioq_freep) Prioq *q = NULL;
/* No priority queue yet, then allocate one */
assert(f->newest_boot_id_prioq_idx == PRIOQ_IDX_NULL); /* we can't be a member either */
q = prioq_new(journal_file_newest_monotonic_compare);
if (!q)
return -ENOMEM;
r = prioq_put(q, f, &f->newest_boot_id_prioq_idx);
if (r < 0)
return r;
r = hashmap_ensure_put(&j->newest_by_boot_id, &id128_hash_ops, &f->newest_boot_id, q);
if (r < 0)
return r;
TAKE_PTR(q);
}
return 0;
}
static int journal_file_read_tail_timestamp(sd_journal *j, JournalFile *f) {
uint64_t offset, mo, rt;
sd_id128_t id;
ObjectType type;
Object *o;
int r;
assert(j);
assert(f);
assert(f->header);
/* Tries to read the timestamp of the most recently written entry. */
r = journal_file_fstat(f);
if (r < 0)
return r;
if (f->newest_mtime == timespec_load(&f->last_stat.st_mtim))
return 0; /* mtime didn't change since last time, don't bother */
if (JOURNAL_HEADER_CONTAINS(f->header, tail_entry_offset)) {
offset = le64toh(READ_NOW(f->header->tail_entry_offset));
type = OBJECT_ENTRY;
} else {
offset = le64toh(READ_NOW(f->header->tail_object_offset));
type = OBJECT_UNUSED;
}
if (offset == 0)
return -ENODATA; /* not a single object/entry, hence no tail timestamp */
/* Move to the last object in the journal file, in the hope it is an entry (which it usually will
* be). If we lack the "tail_entry_offset" field in the header, we specify the type as OBJECT_UNUSED
* here, since we cannot be sure what the last object will be, and want no noisy logging if it isn't
* an entry. We instead check after figuring out the pointer. */
r = journal_file_move_to_object(f, type, offset, &o);
if (r < 0) {
log_debug_errno(r, "Failed to move to last object in journal file, ignoring: %m");
o = NULL;
}
if (o && o->object.type == OBJECT_ENTRY) {
/* Yay, last object is an entry, let's use the data. */
id = o->entry.boot_id;
mo = le64toh(o->entry.monotonic);
rt = le64toh(o->entry.realtime);
} else {
/* So the object is not an entry or we couldn't access it? In that case, let's read the most
* recent entry timestamps from the header. It's equally good. Unfortunately though, in old
* versions of the journal the boot ID in the header doesn't have to match the monotonic
* timestamp of the header. Let's check the header flag that indicates whether this strictly
* matches first hence, before using the data. */
if (JOURNAL_HEADER_TAIL_ENTRY_BOOT_ID(f->header) && f->header->state == STATE_ARCHIVED) {
mo = le64toh(f->header->tail_entry_monotonic);
rt = le64toh(f->header->tail_entry_realtime);
id = f->header->tail_entry_boot_id;
/* Some superficial checking if what we read makes sense. Note that we only do this
* when reading the timestamps from the Header object, but not when reading them from
* the most recent entry object, because in that case journal_file_move_to_object()
* already validated them. */
if (!VALID_MONOTONIC(mo) || !VALID_REALTIME(rt))
return -ENODATA;
} else {
/* Otherwise let's find the last entry manually (this possibly means traversing the
* chain of entry arrays, till the end */
r = journal_file_next_entry(f, 0, DIRECTION_UP, &o, NULL);
if (r < 0)
return r;
id = o->entry.boot_id;
mo = le64toh(o->entry.monotonic);
rt = le64toh(o->entry.realtime);
}
}
if (mo > rt) /* monotonic clock is further ahead than realtime? that's weird, refuse to use the data */
return -ENODATA;
if (!sd_id128_equal(f->newest_boot_id, id))
journal_file_unlink_newest_by_bood_id(j, f);
f->newest_boot_id = id;
f->newest_monotonic_usec = mo;
f->newest_realtime_usec = rt;
f->newest_machine_id = f->header->machine_id;
f->newest_mtime = timespec_load(&f->last_stat.st_mtim);
r = journal_file_reshuffle_newest_by_boot_id(j, f);
if (r < 0)
return r;
return 0;
}
_public_ int sd_journal_get_realtime_usec(sd_journal *j, uint64_t *ret) {
JournalFile *f;
Object *o;
test/TEST-04-JOURNAL/test.sh
+9
View File
@@ -7,4 +7,13 @@ TEST_DESCRIPTION="Journal-related tests"
# shellcheck source=test/test-functions
. "${TEST_BASE_DIR:?}/test-functions"
test_append_files() {
local workspace="${1:?}"
mkdir -p "$workspace/test-journals/"
cp -av "${TEST_BASE_DIR:?}/test-journals/"* "$workspace/test-journals/"
inst_binary unzstd
}
do_test "$@"
test/test-journals/1/system.journal.zst
BIN
View File
Binary file not shown.
test/test-journals/1/system@0005ebbfd42fc981-39a8842ec948769a.journal~.zst
BIN
View File
Binary file not shown.
test/test-journals/1/system@0005ebbfd4346b9f-43185b46162d9fa5.journal~.zst
BIN
View File
Binary file not shown.
test/test-journals/1/system@0005ebbfd4385848-2e5dff5354ab9bcf.journal~.zst
BIN
View File
Binary file not shown.
test/test-journals/1/user-1000.journal.zst
BIN
View File
Binary file not shown.
test/test-journals/1/user-1000@0005ebbfd660bcbe-dbef2eee11f4b575.journal~.zst
BIN
View File
Binary file not shown.
test/test-journals/1/user-1000@0005ebbfe89faec4-a5e890e7b00bedd1.journal~.zst
BIN
View File
Binary file not shown.
test/units/testsuite-04.sh
+15
View File
@@ -275,4 +275,19 @@ journalctl --sync
SEQNUM2=$(journalctl -o export -n 1 | grep -Ea "^__SEQNUM=" | cut -d= -f2)
test "$SEQNUM2" -gt "$SEQNUM1"
JTMP="/var/tmp/jtmp-$RANDOM"
mkdir "$JTMP"
( cd /test-journals/1 && for f in *.zst ; do unzstd < "$f" > "$JTMP/${f%.zst}" ; done )
journalctl --directory="$JTMP" --list-boots --output=json > /tmp/lb1
diff -u /tmp/lb1 - <<'EOF'
[{"index":-3,"boot_id":"5ea5fc4f82a14186b5332a788ef9435e","first_entry":1666569600994371,"last_entry":1666584266223608},{"index":-2,"boot_id":"bea6864f21ad4c9594c04a99d89948b0","first_entry":1666584266731785,"last_entry":1666584347230411},{"index":-1,"boot_id":"4c708e1fd0744336be16f3931aa861fb","first_entry":1666584348378271,"last_entry":1666584354649355},{"index":0,"boot_id":"35e8501129134edd9df5267c49f744a4","first_entry":1666584356661527,"last_entry":1666584438086856}]
EOF
rm -rf "$JTMP"
rm /tmp/lb1
touch /testok