fix(logs): enable millisecond-precision timestamps in heimdall logs#570
fix(logs): enable millisecond-precision timestamps in heimdall logs#570
Conversation
zerolog.TimeFieldFormat defaults to time.RFC3339 (second-level precision). This global controls how timestamps are stored in the zerolog event before the ConsoleWriter ever formats them. Even though TimeFormatOption(time.RFC3339Nano) was already set for the ConsoleWriter display layer, the stored value only carried second granularity, so the displayed timestamp was always truncated to the second. Setting zerolog.TimeFieldFormat = time.RFC3339Nano before logger construction makes all log lines emit sub-second timestamps (e.g. 2026-03-25T21:07:40.594Z instead of 2026-03-25T21:07:40Z), which is necessary for accurate block-finality timing analysis where Datadog ingestion delays make the Datadog timestamp unreliable as a high-resolution event marker.
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
There was a problem hiding this comment.
Claude Code Review
This repository is configured for manual code reviews. Comment @claude review to trigger a review.
Tip: disable this comment in your organization's Code Review settings.
Code reviewNo issues found. Checked for bugs and CLAUDE.md compliance. |
Codecov Report❌ Patch coverage is
❌ Your patch check has failed because the patch coverage (0.0%) is below the target coverage (90.0%). You can increase the patch coverage or adjust the target coverage. Additional details and impacted files@@ Coverage Diff @@
## develop #570 +/- ##
=========================================
- Coverage 41.7% 41.6% -0.1%
=========================================
Files 172 172
Lines 17434 17500 +66
=========================================
+ Hits 7280 7291 +11
- Misses 9074 9128 +54
- Partials 1080 1081 +1
... and 8 files with indirect coverage changes
🚀 New features to boost your workflow:
|
Switch from time.RFC3339Nano (nanoseconds) to a fixed 3-decimal-place
format ("2006-01-02T15:04:05.000Z07:00") so heimdall timestamps are
consistent with bor's millisecond-precision log format.
|
marcello33
left a comment
marcello33
left a comment
There was a problem hiding this comment.
Small nit, LGTM else
| logOpts = append(logOpts, | ||
| log.LevelOption(logLevel), | ||
| log.TimeFormatOption(time.RFC3339Nano), | ||
| log.TimeFormatOption("2006-01-02T15:04:05.000Z07:00"), |
There was a problem hiding this comment.
maybe we can use a constant here, since it's duplicated from line 144
| logOpts = append(logOpts, | ||
| logger.LevelOption(logLevel), | ||
| logger.TimeFormatOption(time.RFC3339Nano), | ||
| logger.TimeFormatOption("2006-01-02T15:04:05.000Z07:00"), |
2 participants
Problem
Heimdall log lines carry only second-precision timestamps, e.g.:
This makes it impossible to accurately measure sub-second timing between milestone events without relying on the Datadog ingestion timestamp — which carries a variable delay and is not a reliable high-resolution event marker.
Root cause
zerolog.TimeFieldFormat(a zerolog global) defaults totime.RFC3339, which has second-level precision. This global controls how the timestamp is stored in the zerolog event before theConsoleWriterever formats it.TimeFormatOption(time.RFC3339Nano)was already set for the ConsoleWriter display layer, but the stored value only carried second granularity — so the displayed timestamp was always truncated to the second regardless of display format.Fix
Set
zerolog.TimeFieldFormatto a fixed 3-decimal-place millisecond format ("2006-01-02T15:04:05.000Z07:00") before logger construction, and apply the same format toTimeFormatOption. This makes all log lines emit millisecond-precision timestamps that are consistent with bor's log format:Motivation
The change is driven by block-finality latency analysis. The key heimdall events being timed are:
Generated a new milestone proposition— proposal phase (T2)2/3rd majority reached on milestone proposition— consensus achieved (T3)Milestone stored successfully— finality committed (T4)With second precision, derived latencies have ±500ms noise per step. With millisecond precision, inter-event timing becomes accurate enough to identify the dominant bottleneck in the finality pipeline (CometBFT consensus round duration, validator nil-vote behavior) without relying on Datadog ingestion timestamps.
Milliseconds (3 decimal places) were chosen over nanoseconds to match bor's existing log timestamp format, keeping both services consistent for cross-service log analysis.
Validation
Tested on a local kurtosis devnet — confirmed all three milestone log events carry millisecond-precision timestamps after the fix.