Skip to content

fix: print the -T detection frequency timeline in the selected timezone - #1914

Open
kotru21 wants to merge 3 commits into
Yamato-Security:mainfrom
kotru21:fix/visualize-timeline-timezone
Open

fix: print the -T detection frequency timeline in the selected timezone#1914
kotru21 wants to merge 3 commits into
Yamato-Security:mainfrom
kotru21:fix/visualize-timeline-timezone

Conversation

@kotru21

@kotru21 kotru21 commented Jul 30, 2026

Copy link
Copy Markdown

The bug

-T, --visualize-timeline draws its axis markers in UTC and always has, while
every other timestamp in the same output honours the selected time format. The
two sit about ten lines apart on screen, so the same detection is printed twice
with different times:

  2026-05-06 12:49:03            <- histogram axis
First timestamp: 2026-05-06 15:49:03.364 +03:00

(host in UTC+3, so the axis is three hours behind; the gap is whatever the local
UTC offset happens to be.)

The markers carry no timezone of their own, so nothing on screen says which of
the two readings is UTC. On a host far from UTC this is easy to read as a real
gap in the data rather than a formatting difference.

Reproducing it

Any evtx and any host that is not on UTC:

hayabusa dfir-timeline -d <evtx-dir> -s -T

Compare the leftmost axis marker with the First timestamp: line below the
histogram. They differ by the host's UTC offset. Running the same scan with -U
makes them agree again, which is the tell: the axis never moved, the rest of the
output did.

Cause

calc_statistic_info collects detect_info.detected_time.timestamp() — raw UTC
epoch seconds. krapslog renders each marker with DateTime::from_timestamp,
which is always UTC, and strips the trailing " UTC", so the markers come out as
unlabelled UTC regardless of the output format.

There used to be a helper that compensated for exactly this, _get_timestamp,
which added the local offset before the value reached krapslog. It lost its last
caller in 9f8e737 (Feb 2024) and has been dead code since, kept alive only by
the underscore that silences the dead-code warning. The raw-epoch collection
that replaced it arrived in d202638. Every release since has had the mismatch.

The fix

The collection goes through that helper again, revived as
get_histogram_timestamp. Two things changed while reviving it:

  • The offset is taken at the instant being converted, not at the Unix epoch. The
    old code read Local.timestamp_opt(0, 0), which is the offset that was in
    effect in 1970 — wrong for any zone whose rules have changed since, and wrong
    for half the year in any zone with DST. On my UTC+3 host chrono reports +02:00
    for 1970, so the old helper would have been an hour off even here.
  • The display timezone is a parameter instead of a hard-coded Local. Callers
    pass &Local; tests pass an explicit FixedOffset so the assertions still
    mean something on a CI runner, which is UTC.

format_time and the histogram both need to decide whether the output is in
UTC, and each spelled the condition out separately. They now share
TimeFormatOptions::is_utc_output, so adding another always-UTC format later
cannot leave one of them converting to local time while the other does not —
which is the shape of the original bug.

Finally, since the markers carry no offset, the title now names the zone:
Detection Frequency Timeline (local time) or (UTC) under -U/--iso-8601.
It says "local time" rather than a concrete offset because a set of logs can
span a DST transition and so have no single offset.

After

Detection Frequency Timeline (local time)      Detection Frequency Timeline (UTC)
  2026-05-06 15:49:03                            2026-05-06 12:49:03
First timestamp: ...15:49:03.364 +03:00        First timestamp: ...12:49:03.364 +00:00

Checked against all seven time formats — default, --utc, --iso-8601,
--rfc-2822, --rfc-3339, --us-time, --us-military-time, --european-time
— on a 137-file evtx set; the axis agrees with the CSV in each. The collection
point is shared by every output type, so CSV, JSON and JSONL are all covered.

Tests

Three unit tests on the helper (offset applied against explicit +09:00/0/
-07:00; offset taken at the event rather than a fixed reference point;
pass-through under --utc/--iso-8601) and one on calc_statistic_info itself,
which is where the bug actually lived. Verified they fail without the fix: with
the old collection restored, the calc_statistic_info test reports
left: 2021-12-23T00:00:00, right: 2021-12-23T03:00:00, and with the offset
dropped from the helper the FixedOffset test fails independently of the
machine's zone.

508 unit tests pass, cargo fmt --check is clean, and cargo clippy --all-targets reports nothing new.

Unrelated, noticed while testing

_print_timeline_hist panics with an out-of-range slice index on terminals
between roughly 28 and 44 columns: the guard checks the title length, but the
real constraint is that the inner width has to fit krapslog's 19-character
markers. This is present on main today (28–44 columns) and unaffected in kind
by this PR, which only shifts the window (41–44). Happy to send it separately
rather than mix it in here.

kotru21 added 2 commits July 30, 2026 22:29
The axis markers of the `-T, --visualize-timeline` histogram were always
rendered in UTC, while every other timestamp in the same output honoured
the selected time format. On a UTC+3 host the axis read 12:49:03 directly
above a summary line reading 12:49:03.364 +03:00 for the same detection.

calc_statistic_info collected `detected_time.timestamp()`, i.e. raw UTC
epoch seconds. krapslog renders each marker with `DateTime::from_timestamp`
(always UTC) and strips the " UTC" suffix, so the markers came out as
unlabelled UTC no matter what. The helper that used to compensate for this,
`_get_timestamp`, lost its last caller in 9f8e737 and has been dead code
since.

Collect the value through it again, restored as `get_histogram_timestamp`.
Two things changed while reviving it:

- the offset is taken at the instant being converted instead of at the Unix
  epoch, so events on either side of a DST transition get the offset that
  was actually in effect;
- the display timezone is a parameter rather than a hard-coded `Local`, so
  the conversion can be tested against a known offset instead of whatever
  zone the test machine happens to be in.

`format_time` and the histogram both need to know whether the output is in
UTC, and had that condition spelled out separately; both now call
`TimeFormatOptions::is_utc_output`, so a future always-UTC format cannot
leave them disagreeing again.

The markers carry no offset of their own, so the histogram title now names
the zone: "Detection Frequency Timeline (local time)" or "(UTC)".
@Shirofune-Security

Copy link
Copy Markdown
Collaborator

The fix itself looks right to me, and I checked the part that worried me most: result_state.timestamps has exactly two touch points in the whole codebase — the push in calc_statistic_info and the read in _print_timeline_hist — so shifting the stored value can't leak into any other output. The _get_timestamp dead-code history checks out too.

One thing I'd ask for before merge.

calc_statistic_info_shifts_histogram_timestamps_into_the_output_timezone can't fail on CI

It's the only test covering the production wiring this PR changes, and on a UTC runner both of its assertions are tautologies:

  • the local half asserts marker.naive_utc() == detected_time.with_timezone(&Local).naive_local() — when Local is UTC the right-hand side collapses to detected_time.naive_utc(), which is exactly what the pre-fix code pushed;
  • the -U half asserts utc_state.timestamps == vec![detected_time.timestamp()], which is precisely the pre-fix value, in any timezone.

.github/workflows/rust.yml builds only windows-latest and no TZ is set anywhere under .github/, so CI runs in UTC.

I verified this by mutation rather than by reading. Forcing the histogram back to UTC at the call site — the exact bug this PR fixes — while keeping everything else intact:

result_state.timestamps.push(get_histogram_timestamp(
    &TimeFormatOptions { utc: true, ..output_option.time_format_options.clone() },
    &detect_info.detected_time,
    &Local,
));

results in:

cargo clippy --all-targets -- -D warnings   clean
TZ=UTC        cargo test --lib get_histogram              3 passed
TZ=UTC        cargo test --lib calc_statistic_info_shifts 1 passed   <-- bug not caught
TZ=Asia/Tokyo cargo test --lib calc_statistic_info_shifts FAILED
                left: 2021-12-23T00:00:00  right: 2021-12-23T09:00:00

So the regression this PR fixes could be reintroduced and CI would stay green. The test only bites on a non-UTC developer machine, which is presumably where it was written.

To be clear about scope: the three get_histogram_timestamp tests do use explicit FixedOffset and do bite on a UTC runner — the arithmetic is properly covered, and the comment saying so ("Explicit offsets rather than Local, so the assertion still bites on a UTC CI runner") is accurate. What isn't covered is the wiring: that calc_statistic_info calls the helper at all, with the right timezone and the right TimeFormatOptions.

Simplest fix is to make the assertion timezone-independent the same way the mod.rs tests already are — assert against get_histogram_timestamp(&TimeFormatOptions::default(), &detected_time, &tz) for an explicit FixedOffset, so what's being pinned is the wiring rather than chrono's own conversion. Setting TZ on the test step in rust.yml would also work, but that's a repo-wide change and probably a separate discussion.

Minor

  • -T is requires = "sort_events", and detections are sorted by UTC instant, so shifting each timestamp by its own offset makes the vector non-monotonic across a DST fall-back — two markers in the ambiguous hour can appear out of order. Inherent to displaying local time on a UTC-sorted vector, cosmetic, and not a reason to hold the PR; just noting it's a known edge rather than an oversight.
  • First timestamp: in the example is the first scanned event, not a detection, so "for the same detection" is slightly off. The mismatch it illustrates is real either way.
  • On the width window: the default title is 41 bytes but the -U title is 34, so the panic window is 41–44 in the default case and 34–44 under -U/--iso-8601 — whether the histogram draws at all now depends on a time-format flag. Not a regression: I measured main panicking across 28–44 columns, so this PR strictly shrinks the window in both modes.

Thanks for splitting out the narrow-terminal panic rather than mixing it in — I filed it as #1915 with the root cause. It's krapslog 0.6.1 time_marker.rs:57 (self.horizontal_offset - time.len() + 1 underflowing for any top-row marker inside the first 18 columns), and the window turns out to depend on marker_num, so it moves with the detection count: 28–44 columns with ~2,500 detections, 28–33 with 6. Same code and dependency in hayabusa-pro, filed there too.

calc_statistic_info_shifts_histogram_timestamps_into_the_output_timezone
asserted against Local, so on a UTC runner both halves collapsed to the
unshifted UTC epoch and the test passed against the pre-fix behaviour.
CI builds windows-latest with no TZ set anywhere under .github/, so the
regression this PR fixes could have been reintroduced with CI green.

calc_statistic_info now takes the display timezone as a parameter, for
the same reason get_histogram_timestamp already does; both production
callers pass &Local and the test passes an explicit +09:00 FixedOffset.
Verified by mutation: forcing the histogram back to UTC at the call site
now fails the test on a UTC+03:00 machine (left 00:00, right 09:00),
driven only by the fixed offset in the test rather than by the host zone.

Also correct the CHANGELOG example: "First timestamp:" prints
timeline.stats.start_time, the first scanned event rather than a
detection. And document the DST fall-back ordering edge on
get_histogram_timestamp.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@kotru21

kotru21 commented Aug 4, 2026

Copy link
Copy Markdown
Author

Thanks — you're right, and the mutation was the convincing part. Fixed in 64f7caa.

Why it couldn't bite. The cause was structural rather than a merely weak assertion: calc_statistic_info hardcoded &Local, so no assertion had any way to name a timezone. On a UTC runner detected_time.with_timezone(&Local).naive_local() collapses to detected_time.naive_utc() — exactly the pre-fix value — and the -U half compared against detected_time.timestamp(), which is the pre-fix value in every zone.

Fix. calc_statistic_info now takes the display timezone as a parameter, for the same reason get_histogram_timestamp already does. Both production callers pass &Local; the test passes an explicit FixedOffset::east_opt(9 * 3600). Neither half references Local any more, so the assertion depends only on that explicit offset.

Verified the same way you did. Re-applying your mutation at the call site:

left: 2021-12-23T00:00:00  right: 2021-12-23T09:00:00

That run was on a UTC+03:00 machine, and the failure is driven entirely by the +09:00 offset in the test rather than by the host zone — so a UTC runner produces the identical failure.

One trade-off, stated plainly. What is pinned now is "the shift is applied, with the display timezone and the caller's TimeFormatOptions". It no longer pins that production passes Local specifically — that is a one-line fact visible at each call site. The -U half is genuine rather than tautological now, since a non-UTC display zone is handed in and ignored.

Minor points.

  • First timestamp: — correct, it is timeline.stats.start_time, the first scanned event rather than a detection. Reworded to "in the same summary" in both CHANGELOGs.
  • DST fall-back ordering — documented as a known edge on get_histogram_timestamp rather than changed, per your read that it is inherent and cosmetic.
  • Width window — agreed, no action. Thanks for measuring main across 28–44 columns and confirming this strictly shrinks the window in both modes.

On setting TZ in rust.yml: agreed it is a separate discussion, but worth having — it would catch this class of tautology in tests nobody thought to make offset-explicit. Happy to open it separately.

Thanks also for filing the narrow-terminal panic as #1915 with the krapslog root cause and the marker_num dependency — that saved me the bisect.

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