fix: print the -T detection frequency timeline in the selected timezone - #1914
fix: print the -T detection frequency timeline in the selected timezone#1914kotru21 wants to merge 3 commits into
Conversation
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)".
|
The fix itself looks right to me, and I checked the part that worried me most: One thing I'd ask for before merge.
|
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>
|
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: Fix. Verified the same way you did. Re-applying your mutation at the call site: 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 Minor points.
On setting Thanks also for filing the narrow-terminal panic as #1915 with the krapslog root cause and the |
The bug
-T, --visualize-timelinedraws its axis markers in UTC and always has, whileevery 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:
(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:
Compare the leftmost axis marker with the
First timestamp:line below thehistogram. They differ by the host's UTC offset. Running the same scan with
-Umakes them agree again, which is the tell: the axis never moved, the rest of the
output did.
Cause
calc_statistic_infocollectsdetect_info.detected_time.timestamp()— raw UTCepoch seconds. krapslog renders each marker with
DateTime::from_timestamp,which is always UTC, and strips the trailing
" UTC", so the markers come out asunlabelled 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:old code read
Local.timestamp_opt(0, 0), which is the offset that was ineffect 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.
Local. Callerspass
&Local; tests pass an explicitFixedOffsetso the assertions stillmean something on a CI runner, which is UTC.
format_timeand the histogram both need to decide whether the output is inUTC, and each spelled the condition out separately. They now share
TimeFormatOptions::is_utc_output, so adding another always-UTC format latercannot 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
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 oncalc_statistic_infoitself,which is where the bug actually lived. Verified they fail without the fix: with
the old collection restored, the
calc_statistic_infotest reportsleft: 2021-12-23T00:00:00, right: 2021-12-23T03:00:00, and with the offsetdropped from the helper the
FixedOffsettest fails independently of themachine's zone.
508 unit tests pass,
cargo fmt --checkis clean, andcargo clippy --all-targetsreports nothing new.Unrelated, noticed while testing
_print_timeline_histpanics with an out-of-range slice index on terminalsbetween 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
maintoday (28–44 columns) and unaffected in kindby this PR, which only shifts the window (41–44). Happy to send it separately
rather than mix it in here.