Repository navigation
Expand file tree
/
Copy pathlogsource.py
More file actions
1612 lines (1449 loc) · 69.7 KB
/
Copy pathlogsource.py
File metadata and controls
1612 lines (1449 loc) · 69.7 KB
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
#! /usr/bin/env python3
# -*- coding: utf-8; py-indent-offset: 4 -*-
#
# Author: Linuxfabrik GmbH, Zurich, Switzerland
# Contact: info (at) linuxfabrik (dot) ch
# https://www.linuxfabrik.ch/
# License: The Unlicense, see LICENSE file.
# https://github.com/Linuxfabrik/lib/blob/main/CONTRIBUTING.md
"""Reads a log incrementally, wherever it is kept: a file on disk, a systemd unit in the
journal, or the log of a container.
Anything that watches a log answers the same three questions on every run, and each storage
answers them differently: where the lines come from, where the previous run stopped, and
whether that stored position still means anything after the log was rotated, truncated or
rewritten. This module answers all three behind one call and hands back an opaque position to
store until the next run.
How exactly a position can be expressed differs per storage, and that difference is reported
rather than hidden. A file is resumed at a byte offset and a unit at a journal cursor, so
neither repeats nor loses a line. A container log only offers a timestamp, and the engines
treat it inclusively, so an entry written in the very same instant as the last one read can
come back twice. A consumer that cannot afford a repeated line reads `fidelity` and
deduplicates where it says so.
"""
__author__ = 'Linuxfabrik GmbH, Zurich/Switzerland'
__version__ = '2026101203'
import collections
import datetime
import os
import re
import stat
from . import disk, human, shell, txt
from . import time as lftime
# A position either names the exact spot the previous run stopped at, or only
# approximates it. See the module docstring.
FIDELITY_APPROXIMATE = 'approximate'
FIDELITY_EXACT = 'exact'
KIND_CONTAINER = 'container'
KIND_FILE = 'file'
KIND_JOURNALD = 'journald'
DEFAULT_TIMEOUT = 8
# Prefixes that name where a log is kept. Anything else is a path, which is why
# a Windows drive letter (`C:\log\app.log`) is read as one.
_SOURCE_PREFIXES = {
'docker': KIND_CONTAINER,
'kubectl': KIND_CONTAINER,
'podman': KIND_CONTAINER,
'systemd': KIND_JOURNALD,
}
# What a syslog daemon or journald puts in front of the message an application
# wrote: a time, the host, and the identifier with the process id. Both spellings
# of the time, because a file written by rsyslog carries the traditional one and
# `journalctl --output=short-iso` carries ISO 8601.
_SYSLOG_PREFIX_REGEX = re.compile(
r"""^(?:
[A-Z][a-z]{2}\s+\d{1,2}\s+\d{2}:\d{2}:\d{2} # Aug 29 11:15:53
|\d{4}-\d{2}-\d{2}[T\ ]\d{2}:\d{2}:\d{2}\S* # 2026-08-29T11:15:53+0200
)
\s+\S+ # the host
\s+(?P<identifier>[^\s:\[]+)(?:\[\d+\])?:\s # sshd-session[1234]:
""",
re.VERBOSE,
)
def count_within(lines, since, parse_line=None, key=None):
"""
Count the lines written at or after a moment, optionally per source.
What a log holds and what happened lately are two different numbers, and a consumer that
alerts on how often something arrives needs the second one. A window over the whole log
would keep reporting a burst that ended hours ago.
Where the lines name who caused them, the total is not the number to judge by either.
Six failures from one address within ten minutes is somebody working on this host; six
failures from six addresses is the background of an open network going past, and only the
first is worth reporting. `key` turns the count into the largest a single source reached,
which is also the quantity an intrusion prevention system counts before it blocks one, so
thresholds derived from such a system compare against the same thing.
Parameters
----------
lines : iterable of str
The log lines to count.
since : datetime.datetime
The start of the window, naive and in local time.
parse_line : callable, optional
Handed to `timestamp()`.
key : callable, optional
Takes a line and returns what caused it - an address, an account, whatever the format
offers - or None where the line names nothing. Lines returning None are counted
together as one source, so a burst of unattributable lines still shows up. Without it
the lines are not grouped and `count` is the plain total.
Returns
-------
dict
- `busiest` (`str | None`): The source that reached `count`. None without `key`, and
None where the lines that reached it name no source.
- `count` (**int**): The number to judge by: the total, or with `key` the largest any
single source reached.
- `sources` (**int**): How many distinct sources were seen. 0 without `key`.
- `total` (**int**): Every line within the window, whatever its source.
- `undated` (**int**): Lines carrying no timestamp either reader could find.
Notes
-----
- The undated ones are reported separately rather than counted in or silently dropped,
because a source whose format leaves the timestamp out would otherwise read as a quiet
one and never raise anything.
Examples
--------
>>> count_within(lines, datetime.now() - timedelta(minutes=10))
{'busiest': None, 'count': 37, 'sources': 0, 'total': 37, 'undated': 1}
>>> count_within(lines, datetime.now() - timedelta(minutes=10), key=peer_of)
{'busiest': '198.51.100.7', 'count': 12, 'sources': 9, 'total': 37, 'undated': 1}
"""
buckets = collections.Counter()
total = 0
undated = 0
for line in lines:
logged_at = timestamp(line, parse_line)
if logged_at is None:
undated += 1
elif logged_at >= since:
total += 1
if key:
buckets[key(line)] += 1
busiest = None
count = total
if key and buckets:
busiest, count = buckets.most_common(1)[0]
return {
'busiest': busiest,
'count': count,
'sources': len([name for name in buckets if name is not None]),
'total': total,
'undated': undated,
}
def covered_window(line_groups, parse_line=None):
"""
Return the earliest and the latest moment a set of logs was written in.
A consumer reporting on a window of a log has to say which stretch of time that window
covers, because the line count alone does not: on a busy host the same 30000 lines reach
back hours, on a quiet one months.
Each group is one log, and only its ends are read rather than every line, which keeps the
cost at two parses per log however long it is. Taking the ends of the whole set instead
would be wrong as soon as there is more than one: the logs arrive one after the other, so
the newest line of the first one sits in the middle rather than at the end.
Parameters
----------
line_groups : iterable of iterable of str
One iterable of lines per log, each
in the order the log holds them.
parse_line : callable, optional
Handed to `timestamp()` for a format it cannot
read on its own.
Returns
-------
tuple
- tuple[0] (**datetime.datetime | None**): The earliest moment found, or None where no
line carries a time.
- tuple[1] (**datetime.datetime | None**): The latest moment found, or None.
Examples
--------
>>> covered_window(
... [['Aug 29 11:15:53 host sshd[1]: Accepted publickey for alice']]
... )[0].hour
11
"""
moments = []
for lines in line_groups:
lines = list(lines)
for candidate in (lines, reversed(lines)):
for line in candidate:
moment = timestamp(line, parse_line)
if moment is not None:
moments.append(moment)
break
if not moments:
return None, None
# Compared as they are only where they agree on being aware or naive: a log
# written with a UTC offset next to one written without cannot be ordered,
# and guessing an offset would move a line by hours.
if len({moment.tzinfo is None for moment in moments}) > 1:
moments = [moment.replace(tzinfo=None) for moment in moments]
return min(moments), max(moments)
def describe(source, size=None, size_threshold=None):
"""
Name one source the way a report names it, together with what was read along.
A source read from a file is named by its path in full, because that is where
somebody copies the path from, and the rotated predecessors that were read with
it are listed behind it. Their size is looked up here rather than passed in: a
predecessor is not a source the caller named, the reader found it, and it stays
out of the size a caller trends.
Parameters
----------
source : dict
One entry of the `sources` a `read_many()` result carries,
holding at least a `label` and a `rotated` list.
size : int, optional
The size of the live source in bytes, where the
caller has it and wants it named. Defaults to `None`, which names no size.
size_threshold : int, optional
A size to compare against, so the fact
arrives with the verdict a caller reaches on it. Defaults to `None`, which
states the size on its own.
Returns
-------
str
The description, with every path in backticks.
Examples
--------
>>> describe({'label': '/var/log/secure', 'rotated': []})
'`/var/log/secure`'
>>> describe({'label': '/var/log/secure', 'rotated': []}, size=2048)
'`/var/log/secure` (size: 2.0KiB)'
"""
described = f'`{source["label"]}`'
if size is not None:
if size_threshold is None:
described += f' (size: {human.bytes2human(size)})'
else:
comparison = '>' if size >= size_threshold else '<'
described += (
f' (size: {human.bytes2human(size)} {comparison}'
f' {human.bytes2human(size_threshold)})'
)
for predecessor in source.get('rotated') or []:
described += f' + `{predecessor}`'
predecessor_stat = disk.stat(predecessor)
if predecessor_stat is not None:
described += f' (size: {human.bytes2human(predecessor_stat.st_size)})'
return described
def parse(source):
"""
Split a log source specification into the storage it names and the target within it.
Parameters
----------
source : str
Either a path to a file, or a prefixed target: `systemd:UNITNAME` for a unit in the
journal, and `docker:NAME`, `kubectl:NAME` or `podman:NAME` for the log of a container.
Returns
-------
tuple
- tuple[0] (**bool**): True if the source could be read, otherwise False.
- tuple[1] (**tuple | str**):
- If successful, a `(kind, engine, target)` tuple. `kind` is one of `KIND_CONTAINER`,
`KIND_FILE` or `KIND_JOURNALD`. `engine` names the container engine and is None for
everything else. `target` is the path, the unit name or the container name.
- If unsuccessful, an error message string.
Examples
--------
>>> parse('/var/log/messages')
(True, ('file', None, '/var/log/messages'))
>>> parse('systemd:sshd')
(True, ('journald', None, 'sshd'))
>>> parse('podman:database')
(True, ('container', 'podman', 'database'))
"""
if not source or not isinstance(source, str):
return False, 'No log source given.'
prefix, separator, target = source.partition(':')
kind = _SOURCE_PREFIXES.get(prefix) if separator else None
if kind is None:
return True, (KIND_FILE, None, source)
target = target.strip()
if not target:
return False, f'Log source "{source}" names no target.'
return True, (kind, prefix if kind == KIND_CONTAINER else None, target)
def systemd_booted(root=''):
"""
Tell whether systemd is the service manager this host runs, the way `sd_booted()` does.
A unit file says only that a package shipped one: Devuan, Alpine and other hosts with
another init system still carry the `.service` files of the packages they install, and
there is no journal to read for those units. systemd creates its runtime unit directory
very early at boot, so its presence answers the question, and nothing else does.
The path is fixed and read without following a symlink at its end, and only root can
create it below `/run`, so no caller of a privileged consumer steers the answer.
Verified against `sd_booted()` in systemd's `src/libsystemd/sd-daemon/sd-daemon.c`,
which tests `access_nofollow("/run/systemd/system/", F_OK)`.
Parameters
----------
root : str, optional
Prefix for the path, for the unit tests of a consumer that stand in a directory tree
for the host. Defaults to the host itself.
Returns
-------
bool
True if systemd runs the host, otherwise False, also on Windows.
Examples
--------
>>> systemd_booted() # doctest: +SKIP
True
"""
return os.path.lexists(f'{root}/run/systemd/system')
# Enough of the head of a file to tell two lines of text apart, which is all the
# fingerprint has to do here.
_FINGERPRINT_LENGTH = 256
# What one run takes from a log. Anybody who can create a file in a log directory
# decides what a rotated file holds, and a root consumer reads it: a line without a line
# end, or a compressed file that is a megabyte on disk and a terabyte as text, must cost a
# bounded amount of memory and time.
#
# A line over `MAX_LINE_BYTES` is no log line any more. Its first `MAX_LINE_BYTES` bytes are
# reported, the rest of it up to the line end is skipped, and the offset moves past all of
# it. A last line without a line end that is shorter than that is held back for the next run
# as before; one that has reached the bound is cut off the same way, because waiting for a
# line end that never comes would read the same bytes on every run. The bytes that arrive
# after the cut are then read as a line of their own.
#
# `MAX_ROTATED_BYTES` is the most a run reads out of rotated files and of a compressed
# source, counted uncompressed. Every line is counted with `_LINE_OVERHEAD` on top, the
# memory of the string that holds it, so that a file of empty lines is bounded too. 512 MiB
# is more than a day of access log of a busy web server, which the consumers read one
# rotated file of; where the bound is reached the reading stops and the notice says so. The live file of a plain source
# is not capped: it is read from where the previous run stopped, and everything in it is
# what the consumer asked for.
MAX_LINE_BYTES = 1024 * 1024
MAX_ROTATED_BYTES = 512 * 1024 * 1024
_LINE_OVERHEAD = 64
# What a journald unit or a container may print in one read, per stream: a resumed read
# hands over everything logged since the cursor or the timestamp, and `--lines` or `--tail`
# do not cap it. A runaway unit would otherwise be held in memory whole, up to what it prints
# within the timeout. Past the cap the command is killed and the read fails with a message
# that says so. A capture costs about three times its size in memory (the chunks, the joined
# bytes, the decoded text and the split lines), which is why it is a quarter of what is
# read out of rotated files. `journalctl` says little on standard error, hints only, so
# its cap is small; a container client passes what the application wrote to standard error,
# which is log content, and gets the same cap as standard output.
MAX_COMMAND_OUTPUT_BYTES = 128 * 1024 * 1024
MAX_JOURNALCTL_STDERR_BYTES = 1024 * 1024
class _BudgetExhausted(Exception):
"""A run has read as much out of rotated files as it may."""
class _ReadState:
"""What one run has used up of its bounds, and what it has to report about them.
`budget` is the number of bytes a run may still take, or None where there is no cap.
"""
def __init__(self, budget=None):
self.budget = budget
self.shortened = 0
self.stopped = None
def charge(self, size):
"""Count `size` more bytes, and raise `_BudgetExhausted` once the budget is gone."""
if self.budget is None:
return
self.budget -= size + _LINE_OVERHEAD
if self.budget < 0:
raise _BudgetExhausted
def _bounded_lines(handle, state):
"""Yield `(line, consumed, final)` for every line of `handle`, each `line` at most
`MAX_LINE_BYTES` long.
`consumed` is how many bytes of the file the line took, its line end and the part of a
too long line that was skipped included, so the caller's offset stays exact. `final`
says the line is complete: it has its line end, or it has reached the bound, which is as
long as a line may get. A last line that is not final is for the caller to hold back. A
line that really lost bytes to the bound is counted in `state.shortened`; one that is
exactly as long as the bound, with or without its line end, is returned whole. The bytes
are charged to `state` as they are read, which raises `_BudgetExhausted` when it runs out.
"""
while True:
line = handle.readline(MAX_LINE_BYTES)
if not line:
return
consumed = len(line)
state.charge(consumed)
if len(line) >= MAX_LINE_BYTES and not line.endswith(b'\n'):
# Skip the rest of the line in pieces, so none of it is held. Nothing was lost
# if all that follows is the line end.
lost = False
while True:
rest = handle.readline(MAX_LINE_BYTES)
consumed += len(rest)
state.charge(len(rest))
if rest not in (b'', b'\n', b'\r\n'):
lost = True
if not rest or rest.endswith(b'\n'):
break
if lost:
state.shortened += 1
yield line, consumed, line.endswith(b'\n') or len(line) >= MAX_LINE_BYTES
def _is_rewritten(raw, fingerprint, length):
"""Tell whether the head of an open file still matches the fingerprint of the previous run.
The head is the part that appending does not touch, so it identifies the file: it changes
only once the file has become a different one. Hashes exactly as many bytes as were hashed
back then, so appending to a file whose head was shorter than the fingerprint does not look
like a rewrite.
"""
if not length:
# The file was empty on the previous run, so there is nothing to compare
# against, and nothing to miss either: an offset of 0 stays valid no
# matter what was written since.
return True, False
success, result = disk.get_fingerprint(raw, length=length)
if not success:
return False, result
current, hashed = result
if hashed < length:
# the file no longer holds the bytes that were hashed last time, so it
# must have been truncated
return True, True
return True, current != fingerprint
# What a log rotator appends to the name of the file it moved aside. Everything
# it can produce is made of digits and separators, whether it counts generations
# (`.1`) or stamps a date (`-20260828`, `-2026-08-28`), so a name carrying a
# letter is somebody's backup copy and not a rotation.
_ROTATED_SUFFIX_REGEX = re.compile(r'^[-.][-_.0-9]*[0-9][-_.0-9]*$')
# Compression a rotator applies to what it moved aside, and the module that
# reads it back. A rotator can be told to use something else (zstd, for
# example); such a file simply does not look like a rotation here and is left
# alone rather than read as binary noise.
_COMPRESSION_MODULES = {
'.bz2': 'bz2',
'.gz': 'gzip',
'.xz': 'lzma',
}
def _open_log_file(path, allowed_roots=None):
"""Open a log file for reading in binary, decompressing it where its name says so.
The file is opened once, through `disk.open_file()`, so with `allowed_roots` it is
the very file that was checked, and everything the caller needs from it (its
inode, its size, its fingerprint, its lines) comes from that one handle rather
than from a second look at the path.
Returns `(True, (handle, raw))`, where `handle` yields the uncompressed lines and
`raw` is the file underneath it; the caller closes both. For an uncompressed file
the two are the same object.
The module that reads a compression is imported here rather than at the top, because a
Python can be built without one, and that must not keep this module from being imported at
all.
"""
module = None
for suffix, module_name in _COMPRESSION_MODULES.items():
if not path.endswith(suffix):
continue
try:
module = __import__(module_name)
except ImportError:
return False, (
f'Cannot read "{path}": this Python has no `{module_name}` module.'
)
break
success, raw = disk.open_file(
path, binary=True, allowed_roots=allowed_roots, nofollow=bool(allowed_roots)
)
if not success:
return False, raw
if module is None:
return True, (raw, raw)
try:
return True, (module.open(raw, mode='rb'), raw)
except OSError as e:
raw.close()
return False, f'I/O error "{e.strerror}" while reading {path}'
def _rotated_files(path, count=None):
"""Return the files a rotator moved aside from `path`, the oldest of them first.
`count` limits them to the most recent ones; None returns all of them.
Ordering is by modification time rather than by name, because the two naming schemes a
rotator uses disagree about which name is the newest: a counted generation is renamed
upwards on every rotation while a dated one never moves. Compressing a rotated file keeps
its modification time, so the order holds either way.
Only a regular file is considered, and a symlink is not followed, so nothing that was
dropped into the log directory can widen what the caller reads.
"""
directory = os.path.dirname(path) or '.'
base = os.path.basename(path)
candidates = []
try:
entries = os.listdir(directory)
except OSError:
# A directory that cannot be listed simply yields no predecessor. The
# file itself is read on its own and reports its own trouble.
return []
for name in entries:
if not name.startswith(base) or name == base:
continue
suffix = name[len(base) :]
for compression in _COMPRESSION_MODULES:
if suffix.endswith(compression):
suffix = suffix[: -len(compression)]
break
if not _ROTATED_SUFFIX_REGEX.match(suffix):
continue
candidate = os.path.join(directory, name)
try:
candidate_stat = os.lstat(candidate)
except OSError:
continue
if not stat.S_ISREG(candidate_stat.st_mode):
continue
candidates.append((candidate_stat.st_mtime, candidate))
# newest first to pick the `count` most recent, then reversed so their lines
# arrive in the order they were written
candidates.sort(reverse=True)
return [candidate for _, candidate in reversed(candidates[:count])]
def _is_truncated(size, position, compressed):
"""Return whether a file of `size` bytes is shorter than where `position` stopped.
The offset counts the bytes of the lines read, which for a compressed file are the
uncompressed ones; its compressed size is nearly always smaller, so holding the two
against each other took every compressed file for truncated and read it again from
the start, run after run. A compressed file is therefore compared with its own size
at the time the position was taken. A position from before that size was stored
leaves the decision to the fingerprint.
"""
if compressed:
return size < position.get('size', 0)
return size < position.get('offset', 0)
def _resume_rotated(path, position, allowed_roots, lines, state):
"""Read what the file held after `position` before a rotator moved it aside.
The stored inode names the file the previous run stopped in. If a predecessor still
carries it, the rest of that file is read from the stored offset, followed by every
predecessor that was rotated after it, so the lines written between the last run and the
rotation are not lost. A rotator that compressed the file wrote a new one with a new
inode, and one that deleted it left nothing to find; then nothing is read and the caller
restarts at the beginning of the live file.
The candidate is checked on the handle that reads it, not on the path: it has to be the
same inode, at least as long as the stored offset, and start with the bytes the stored
fingerprint was taken from.
Returns `(resumed, files, read, notices)`: whether the file was found, the files that
were read in order, how many lines they had, and why a newer predecessor was skipped.
The lines are appended to `lines`. What is read is charged to `state`; where its budget
is gone, the reading stops with `state.stopped` set.
"""
stored_inode = str(position.get('inode'))
offset = position.get('offset', 0)
predecessors = _rotated_files(path)
index = None
for number, candidate in enumerate(predecessors):
try:
candidate_inode = str(os.lstat(candidate).st_ino)
except OSError:
continue
if candidate_inode == stored_inode:
index = number
break
if index is None:
return False, [], 0, []
files = []
read = 0
notices = []
for number, predecessor in enumerate(predecessors[index:]):
success, opened = _open_log_file(predecessor, allowed_roots)
if not success:
if number == 0:
return False, [], 0, []
notices.append(opened)
continue
predecessor_handle, predecessor_raw = opened
try:
with predecessor_raw, predecessor_handle:
start = 0
if number == 0:
candidate_stat = os.fstat(predecessor_raw.fileno())
if str(candidate_stat.st_ino) != stored_inode or _is_truncated(
candidate_stat.st_size,
position,
compressed=predecessor_handle is not predecessor_raw,
):
return False, [], 0, []
if position.get('fingerprint'):
success, rewritten = _is_rewritten(
predecessor_raw,
position.get('fingerprint'),
position.get('length', 0),
)
if not success or rewritten:
return False, [], 0, []
start = offset
predecessor_handle.seek(start)
# A rotated file is complete, so a last line without a line end is
# read as it is rather than held back for a run that never comes.
for line, _, _ in _bounded_lines(predecessor_handle, state):
read += 1
lines.append(
txt.to_text(line, errors='strict_or_latin1').rstrip('\r\n')
)
except _BudgetExhausted:
state.stopped = predecessor
files.append(predecessor)
break
except OSError as e:
if number == 0:
return False, [], 0, []
notices.append(f'I/O error "{e.strerror}" while reading {predecessor}')
continue
files.append(predecessor)
return True, files, read, notices
def _read_open_file(path, handle, raw, position, allowed_roots, max_lines, rotated):
"""The part of `_read_file()` that works on the already opened file."""
try:
file_stat = os.fstat(raw.fileno())
except OSError as e:
return False, f'I/O error "{e.strerror}" while reading {path}'
inode = str(file_stat.st_ino)
# Fingerprint before reading rather than after: should the file be rewritten
# in between, the stored fingerprint is the older one, so the next run
# rescans the file instead of missing what was written in the meantime.
success, result = disk.get_fingerprint(raw, length=_FINGERPRINT_LENGTH)
if not success:
return False, result
fingerprint, fingerprint_length = result
stored_offset = position.get('offset', 0) if position else 0
offset = stored_offset
restarted = False
moved_aside = False
if position:
# A state written before the position carried a kind may hold the inode
# with INTEGER affinity and read back as int, so compare as strings.
if str(position.get('inode')) != inode:
# rotated or replaced; what the old file held after the stored offset is
# looked for among the predecessors below
moved_aside = True
offset = 0
elif _is_truncated(file_stat.st_size, position, compressed=handle is not raw):
# truncated below where we stopped
offset = 0
elif position.get('fingerprint'):
success, rewritten = _is_rewritten(
raw,
position.get('fingerprint'),
position.get('length', 0),
)
if not success:
return False, rewritten
if rewritten:
# An application that rewrites its log from the beginning
# (`> logfile` instead of `>> logfile`) keeps the inode, and if
# the new content is at least as long as what was read last
# time, the size does not shrink either. Only the head tells us
# that everything after our offset is gone.
offset = 0
# Resetting a position that was 0 anyway loses nothing, so it is not a
# restart the consumer has to hear about.
restarted = offset == 0 and stored_offset != 0
# The fingerprint moved the file position. A decompressor reads on from wherever
# the file underneath stands, so put it back to where the stream starts.
try:
raw.seek(0)
except OSError as e:
return False, f'I/O error "{e.strerror}" while reading {path}'
# A cap is applied to the lines that are kept, not to the lines that are
# read: the offset still advances to the end, so a run that hits the cap
# drops the oldest of the new lines instead of re-reading them forever.
# Rotated predecessors share the same deque, so the cap keeps the most
# recent lines across all of them rather than per file.
lines = collections.deque(maxlen=max_lines) if max_lines else []
read = 0
notices = []
rotated_read = []
state = _ReadState(MAX_ROTATED_BYTES)
for predecessor in _rotated_files(path, rotated) if rotated else []:
success, opened = _open_log_file(predecessor, allowed_roots)
if not success:
notices.append(opened)
continue
predecessor_handle, predecessor_raw = opened
try:
with predecessor_raw, predecessor_handle:
for line, _, _ in _bounded_lines(predecessor_handle, state):
read += 1
lines.append(
txt.to_text(line, errors='strict_or_latin1').rstrip('\r\n')
)
except _BudgetExhausted:
state.stopped = predecessor
rotated_read.append(predecessor)
break
except OSError as e:
notices.append(f'I/O error "{e.strerror}" while reading {predecessor}')
continue
rotated_read.append(predecessor)
if moved_aside and state.stopped is None:
resumed, files, resumed_read, resumed_notices = _resume_rotated(
path, position, allowed_roots, lines, state
)
if resumed:
# nothing between the stored offset and the live file is missing
restarted = False
read += resumed_read
rotated_read += files
notices += resumed_notices
if handle is raw:
# the live file of a plain source is read from where the previous run stopped,
# and all of it is what the consumer asked for
state.budget = None
try:
handle.seek(offset)
for line, consumed, final in _bounded_lines(handle, state):
if not final:
# The writer is in the middle of this line. Reporting it now would
# hand out half a line and the rest of it on the next run, so it
# is left for the next run to read whole.
break
read += 1
lines.append(txt.to_text(line, errors='strict_or_latin1').rstrip('\r\n'))
offset += consumed
except _BudgetExhausted:
# only a compressed source gets here, which is read from its start every time
state.stopped = path
except OSError as e:
return False, f'I/O error "{e.strerror}" while reading {path}'
notice = []
if notices:
notice.append('Skipped a rotated file: ' + '; '.join(notices) + '.')
if state.stopped:
notice.append(
f'Stopped reading {state.stopped}: more than '
f'{MAX_ROTATED_BYTES // 1024 // 1024} MiB uncompressed.'
)
if state.shortened:
notice.append(
f'Shortened {state.shortened} line(s) longer than '
f'{MAX_LINE_BYTES // 1024 // 1024} MiB.'
)
return True, {
'fidelity': FIDELITY_EXACT,
'kind': KIND_FILE,
'label': path,
'lines': list(lines),
# What the consumer hears about the file: a rotated predecessor that could not be
# read, a read that was stopped by its budget, and lines that were cut.
'notice': ' '.join(notice),
'position': {
'fingerprint': fingerprint,
'inode': inode,
'kind': KIND_FILE,
'length': fingerprint_length,
'offset': offset,
# the size of the file itself, for a compressed one, whose offset counts
# the uncompressed bytes and cannot be held against it
**({'size': file_stat.st_size} if handle is not raw else {}),
},
'restarted': restarted,
'rotated': rotated_read,
'truncated': read > len(lines) or bool(state.shortened or state.stopped),
}
def _read_file(path, position, allowed_roots, max_lines, rotated):
"""Read the lines a file grew by since `position`, detecting rotation and rewrites."""
# Through the decompressor where the name says the file is compressed, the
# way a rotated predecessor is read: a caller that names a rotated file
# directly would otherwise be handed the compressed bytes as text and told
# that the application never wrote a line. `seek()` and `tell()` on such a
# handle count uncompressed bytes, so the position keeps its meaning.
success, result = _open_log_file(path, allowed_roots)
if not success:
if result.startswith('I/O error') and any(
character in path for character in '*?['
):
# A shell that found nothing to expand hands the pattern on
# unchanged, and a caller who meant a set of files then sees a
# missing file with an odd name. Saying that a source is one file
# beats letting them hunt for a typo that is not there.
result += (
' - a wildcard is not expanded here, every file is its own source.'
)
return False, result
handle, raw = result
with raw, handle:
return _read_open_file(
path, handle, raw, position, allowed_roots, max_lines, rotated
)
# journalctl prints the cursor of the last entry on a line of its own when asked
# for it with --show-cursor.
_JOURNALD_CURSOR_PREFIX = '-- cursor: '
def _read_journald(unit, position, max_lines, since, timeout):
"""Read the entries a unit logged since `position`, resuming at a journal cursor."""
cursor = position.get('cursor') if position else None
# `cursor` moves on to the one journalctl prints below; whether the caller
# passed one in decides how --lines= behaves and how a cut is detected
resumed = bool(cursor)
cmd = [
'journalctl',
'--no-pager',
'--output=short-iso',
'--show-cursor',
# Every value is bound to its option with `=`, so a unit name starting
# with `-` cannot be picked up as an option of journalctl itself.
f'--unit={unit}',
]
if resumed:
cmd.append(f'--after-cursor={cursor}')
elif since:
cmd.append(f'--since={since}')
else:
# Without a stored position and without a window the caller named, the
# current boot is the one bounded answer that needs no clock arithmetic.
cmd.append('--boot')
if max_lines and not resumed:
# Without a cursor journalctl jumps back from the end, so --lines= keeps the
# most recent entries. After a cursor it reads forward from there and stops
# after N, which are the oldest ones, and the cursor it prints then follows
# them: a busy unit would fall further behind on every run. The cap is applied
# below instead. Verified against systemd 259, src/journal/journalctl-show.c,
# seek_journal().
cmd.append(f'--lines={max_lines}')
success, result = shell.shell_exec(
cmd,
timeout=timeout,
max_bytes=(MAX_COMMAND_OUTPUT_BYTES, MAX_JOURNALCTL_STDERR_BYTES),
)
if not success:
return False, result
stdout, stderr, retc = result
if 'insufficient permissions' in stderr:
# journalctl ends with this, and with an exit code of 1, when the caller may
# not open a single journal file (src/shared/journal-util.c). Passing the raw
# text on would bury the one thing to do under three lines of hint.
# Verified against systemd 252 on Rocky 9.
return False, (
f'Not allowed to read `systemd:{unit}`. Run with elevated privileges, '
f'or add the account to the `adm` or `systemd-journal` group.'
)
if retc != 0 and stderr.strip():
return False, (
f'`{" ".join(cmd)}` exited with error ({retc}, {stderr.strip()}).'
)
# An exit code with nothing said about it means the journal holds nothing for
# this unit rather than that the read went wrong: `--show-cursor` exits 1 on a
# unit that logged nothing since the boot, because there is no cursor to
# print, and journalctl says so on standard output only ("-- No entries --").
# Failing here would put a permanent WARNING on every host with a quiet unit.
# Measured against systemd 239 on Rocky 8.
lines = collections.deque(maxlen=max_lines) if max_lines else []
read = 0
for line in stdout.splitlines():
if line.startswith(_JOURNALD_CURSOR_PREFIX):
# Keep the previous cursor when journalctl prints none, which is what
# it does when the unit logged nothing at all since last time.
cursor = line[len(_JOURNALD_CURSOR_PREFIX) :].strip() or cursor
continue
if line.startswith('-- '):
# journalctl frames its output with informational lines such as
# `-- No entries --` and `-- Boot ... --`. With --output=short-iso
# every real entry starts with its timestamp, so a line starting
# with `-- ` is never one of them.
continue
read += 1
lines.append(line)
notice = stderr.strip()
if notice and not lines:
# journalctl says on stderr, and with an exit code of 0, that it is only
# showing what the caller is allowed to see. Where that leaves nothing at
# all, returning an empty result would report a quiet log on a host whose
# log simply cannot be read, which is the worst answer a check can give.
# Verified against systemd 257 on Debian 13, where an account outside the
# `adm` and `systemd-journal` groups sees no system entries at all.
return False, (
f'Read no entries of `systemd:{unit}`, and journalctl reported: {notice} '
f'Run with elevated privileges, or add the account to the `adm` or '
f'`systemd-journal` group.'
)
return True, {
'fidelity': FIDELITY_EXACT,
'kind': KIND_JOURNALD,
'label': f'systemd:{unit}',
'lines': list(lines),
# What journalctl said next to the entries it did return, so a consumer
# can pass on a partial read instead of presenting it as a whole one.
'notice': notice,
'position': {'cursor': cursor, 'kind': KIND_JOURNALD},
# A cursor whose entry has rotated out of the journal makes journalctl
# resume at the closest one it still holds, without saying so, so there
# is nothing here that could be reported as a restart.
'restarted': False,
# Neither storage has a rotation of its own a caller could ask for.
'rotated': [],
# After a cursor every entry was read and the cap dropped the oldest; without
# one journalctl applied the cap itself, and a full result may have been cut.
'truncated': read > len(lines)
if resumed
else bool(max_lines) and len(lines) >= max_lines,
}
# `<engine> logs --timestamps` prefixes every line with an RFC 3339 timestamp.
# Verified against podman 5 on Fedora 44, which renders it in local time with an
# explicit offset (`2026-08-28T15:30:26.241557000+02:00`) rather than in UTC.
_CONTAINER_TIMESTAMP_REGEX = re.compile(
r'^(\d{4}-\d{2}-\d{2}T[\d:.]+(?:Z|[+-][\d:]+)) ?'
)
# What an unstamped entry, or a stored timestamp that cannot be read, sorts as.
_CONTAINER_TIME_UNKNOWN = (
datetime.datetime.min.replace(tzinfo=datetime.timezone.utc),
0,
)
# The fractional seconds of a container timestamp, taken apart from the rest
# because a datetime holds microseconds only.
_CONTAINER_FRACTION_REGEX = re.compile(r'\.(\d+)')
def _container_time(stamp):
"""The moment a container timestamp names, comparable across UTC offsets.
Podman writes local time with its offset, so the same wall clock hour comes twice when
daylight saving time ends (`02:59+02:00`, then `02:10+01:00`) and the strings no longer
sort in the order they were written. It also writes nine fractional digits (libpod
`LogTimeFormat`), more than a datetime holds, and a burst can put two entries into the
same microsecond. Returns the second as an aware datetime together with the
nanoseconds, so both the offset and the full precision count.
"""
if not stamp:
return _CONTAINER_TIME_UNKNOWN
match = _CONTAINER_FRACTION_REGEX.search(stamp)
nanoseconds = int(match.group(1)[:9].ljust(9, '0')) if match else 0
whole = _CONTAINER_FRACTION_REGEX.sub('', stamp, count=1)
try:
return lftime.timestr2datetime(whole, pattern='iso8601'), nanoseconds
except ValueError:
return _CONTAINER_TIME_UNKNOWN
def _read_container(engine, target, position, max_lines, since, timeout):