Skip to content

[oxlog] include files whose creation time predates the range end - #11124

Open
smklein wants to merge 4 commits into
mainfrom
oxlog-crtime-date-range
Open

[oxlog] include files whose creation time predates the range end#11124
smklein wants to merge 4 commits into
mainfrom
oxlog-crtime-date-range

Conversation

@smklein

@smklein smklein commented Aug 20, 2026

Copy link
Copy Markdown
Collaborator

oxlog's date_range filter previously tested only a file's mtime against the range. Since mtime is the timestamp of a file's newest line, the end bound was lossy: a file whose content spans the end of the range was dropped whole, even though it might have entries from within the requested bounds. This is often the case for current log files, whose mtime is always recent.

As a concrete example of the old behavior:

  • If a caller asks for logs from "4 days ago" to "2 days ago", for a service that has not rotated, but has continued to write to its logs every hour...
  • ... then the most recent non-rotated log -- which includes all entries in that requested range! -- would be excluded, because "from an mtime point-of-view, it is more recent than that range".

To mitigate this, the oxlog filter now chooses to include a file when its [created, modified] content span intersects the range. Creation time (crtime) is trusted only when it is no later than the mtime: a copied file's crtime is the time of the copy, not a content bound, so files copied into archive locations with their mtime preserved keep the old mtime-only behavior, as do files where crtime is unavailable.

Once #11113 lands, support bundle zone-log collection inherits this fix through the shared filter.

Commits

[oxlog] Include files whose content span overlaps the date range

Adds the created field to LogFile and rewrites in_date_range to the span-intersection rule. Nothing populates the field yet, so this commit carries no behavior change on its own. Also fixes the DateRange field doc comments, which described the bounds as exclusive while the code has always been inclusive.

Test coverage: a new unit test covers the regression shape directly (created 1:00, mtime 2:00, range ending 1:59 is now included; the same mtime without a creation time stays excluded), the copied-file inversion in both directions, spans entirely outside the range, and inclusive boundary touches. The pre-existing test_daterange_filter continues to pass unchanged, pinning mtime-only behavior.

[oxlog] Populate LogFile creation times

On illumos, crtime is a system attribute (fsattr(7)) rather than part of stat(2), and std::fs::Metadata::created() returns Unsupported. A new crtime module retrieves it with getattrat(3C) from the read-write attribute view and parses the resulting nvlist via illumos-nvpair. On other platforms std::fs::Metadata::created() is used. A missing or unreadable creation time leaves the field None and the file is filtered by mtime alone.

Test coverage: an illumos-gated test creates a file on the ZFS-backed workspace, checks its crtime is readable, recent, and no later than its mtime, and that a missing file yields None rather than an error; run on an illumos workstation along with the rest of the oxlog suite.

[oxlog] Skip the crtime test on filesystems that record no crtime

Makes the illumos-gated test portable to dev environments where the workspace checkout is not on ZFS: it now checks the tempdir's filesystem via statvfs f_basetype and skips with a message rather than failing. Probing pathconf(_PC_SATTR_ENABLED) instead would not work: tmpfs reports system attribute support yet answers getattrat(3C) with an empty attribute list.

Test coverage: both branches of the guard were exercised on an illumos workstation; the ZFS path runs the crtime assertions, and a tempdir on /tmp (tmpfs) takes the skip path.

in_date_range previously tested only a file's mtime against the range,
which is lossy at the range's end: mtime is the timestamp of a file's
newest line, so a file whose content spans the end bound was dropped
whole, in-window lines included. This is systematic for current log
files, whose mtime is always recent: any end bound in the past excluded
every live current log along with all of its in-window history.

LogFile gains a created (crtime) field, and in_date_range now includes
a file when its [created, modified] content span intersects the range.
The creation time is trusted only when it is no later than the mtime:
a copied file's crtime is the time of the copy, not a content bound, so
such files (e.g. logs archived into crypt/debug with their mtime
preserved) keep the mtime-only behavior, as do files where crtime is
unavailable.

Nothing populates the new field yet, so this commit carries no behavior
change on its own.
On illumos, crtime is a system attribute (fsattr(7)) rather than part
of stat(2): a new crtime module retrieves it with getattrat(3C) and
parses the resulting nvlist's [seconds, nanoseconds] crtime entry via
illumos-nvpair. On other platforms, read_metadata uses
std::fs::Metadata::created(). Either way a missing or unreadable
creation time leaves the field None, and the file is filtered by mtime
alone.
@smklein smklein changed the title [oxlog] Filter by content span: include files whose creation time predates the range end [oxlog] include files whose creation time predates the range end Aug 20, 2026
};

true
content_start <= date_range.before && modified >= date_range.after

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

from a 10,000 ft view, this is the entire change

/// Returns the creation time of the file at `path`, or `None` if it
/// cannot be determined (missing file, a filesystem without system
/// attribute support, or an unexpected attribute shape).
pub(crate) fn crtime(path: &Utf8Path) -> Option<Timestamp> {

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the lack of support for "created_time" on illumos means we need to do these gymnastics to get the same benefit

The test previously assumed the workspace checkout is on ZFS and
failed its crtime expectation anywhere else. Guard it with statvfs
f_basetype and skip, with a message, when the tempdir's filesystem is
not ZFS.

Probing pathconf(_PC_SATTR_ENABLED) instead would not work: tmpfs
reports system attribute support yet answers getattrat(3C) with an
empty attribute list. Both branches of the guard were exercised on an
illumos workstation (ZFS runs the assertions; a /tmp tempdir skips).
}

#[test]
fn test_crtime_of_new_file() {

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This whole test is:

  • if we make a file
  • can we observe the crtime with the function we just wrote

Should be easy, right? well, we don't totally know the filesystem of the development environment we're operating on. So... we have to check that, to see if it supports the created-time attribute, before continuing.

@wfchandler wfchandler left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is a good change, but archived logs will still be a problem. Those have their crtime set to the time of migration by sled-agent, not the original file's creation time. Something we can fix in a follow-on PR.

On colo:

# F=system-illumos-propolis-server:default.log.1778804100
# head -1 $F | jq -r .time; tail -1 $F | jq -r .time; ls -l -%all $F
2026-05-14T20:15:10.122754809Z
2026-05-15T00:15:00.944443313Z
-rw-r--r--   1 root     root      904142 May 15 00:18 system-illumos-propolis-server:default.log.1778804100
         timestamp: atime         Aug 21 13:31:08 2026 
         timestamp: ctime         May 15 00:18:29 2026 
         timestamp: mtime         May 15 00:18:29 2026 
         timestamp: crtime         May 15 00:18:29 2026 

@wfchandler

Copy link
Copy Markdown
Contributor

I will note that this change makes oxlog noticeably slower, but I think the tradeoff is worthwhile.

root@BRM42220051:# time oxlog logs oxz_switch dendrite --current --archived > /dev/null  

real    0m1.048s
user    0m0.357s
sys     0m0.677s

root@BRM42220051:# time ./oxlog-crtime logs oxz_switch dendrite --current --archived > /dev/null

real    0m2.651s
user    0m0.834s
sys     0m1.801s

wfchandler measured "oxlog logs oxz_switch dendrite --current
--archived" going from ~1.0s to ~2.65s on a dogfood sled: the per-file
getattrat(3C) call ran for every statted file, including runs with no
date range at all, where the result is never consulted.

The lookup now happens only when it can change the outcome of
in_date_range: a date range must be present, and the file mtime must
postdate the end of the range. An mtime within the range proves overlap
by itself, and an mtime before the range is excluded through the start
bound, which the creation time never weakens. In practice this limits
the lookup to the handful of current logs still written past the range
end; rotated and archived logs are filtered on mtime alone.

Measured on BRM42220051 against the same 20,892-file log set: the
unfiltered command returns to baseline (~0.95s vs ~2.6s unfixed), and a
date-filtered run does too (~0.9s vs ~2.5s). Output is byte-identical
to the ungated build in both shapes.

Test coverage: a new unit test pins the gate at its boundaries (mtime
after, at, within, and before the range, and absent) and asserts that
wherever the gate skips the lookup, in_date_range answers the same with
and without a creation time.
@smklein

smklein commented Aug 21, 2026

Copy link
Copy Markdown
Collaborator Author

I really only need this crtime for scenarios where the "modified" time is greater than the end of the requested date range. I did some lazy loading of crtime to speed this up.

I re-ran the benchmarks on dogfood (same machine as you).

For oxlog logs oxz_switch dendrite --current --archived:

binary real times (3 runs)
oxlog (installed baseline) 1.028s / 0.892s / 0.876s
oxlog-crtime (PR head, unfixed) 2.545s / 2.687s / 2.576s
oxlog-gated (PR + lazy loading) 0.969s / 0.971s / 0.904s

And If I add some explicit date-filtering with -A '4 days ago' -B '2 days ago':

binary real times (3 runs)
oxlog (installed baseline) 0.774s / 0.852s / 0.889s
oxlog-crtime (PR head, unfixed) 2.500s / 2.570s / 2.519s
oxlog-gated (PR + lazy loading) 0.905s / 0.883s / 0.909s

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants