Skip to content

Optional microsecond timestamp in the log (debug.extra) - #3005

Draft
DL6ER wants to merge 1 commit into
developmentfrom
tweak/log-microseconds
Draft

Optional microsecond timestamp in the log (debug.extra)#3005
DL6ER wants to merge 1 commit into
developmentfrom
tweak/log-microseconds

Conversation

@DL6ER

@DL6ER DL6ER commented Aug 6, 2026

Copy link
Copy Markdown
Member

What does this implement/fix?

Our log timestamps carry millisecond resolution. That is fine for everyday use, but too coarse whenever one is actually chasing a timing problem - a burst of related log lines regularly ends up sharing the very same millisecond, so the log no longer tells us in which order things happened.

Rather than adding yet another config option for this, we reuse debug.extra, the flag that already exists for exactly this kind of temporary investigation ("Temporary flag that may print additional information [...] meant to be used whenever needed for temporary investigations"). When it is enabled, get_timestr() prints six instead of three fractional digits:

2026-08-06 08:01:40.086 CEST [12345M] INFO: ...     (default)
2026-08-06 08:01:40.086300 CEST [12345M] INFO: ...  (debug.extra = true)

As every timestamped log line goes through get_timestr(), this covers FTL.log, webserver.log and the foreground/stdout output alike. The default output is bit-for-bit unchanged, so nothing that reads our logs today is affected unless the flag is deliberately turned on.

The debug.extra help text mentions the added resolution so the behavior is discoverable from pihole-FTL --config debug.extra instead of only from the source.

Note that the handful of lines emitted before the config has been read still use millisecond resolution - the flag simply is not known yet at that point.

How to test the change during review

  1. Build FTL and start it as usual. The timestamps in /var/log/pihole/FTL.log have three fractional digits, as before:
    2026-08-06 08:01:28.828 CEST [12345M] INFO: ########## FTL started on host! ##########
    
  2. Enable the flag and restart:
    sudo pihole-FTL --config debug.extra true
    sudo service pihole-FTL restart
    
    From the point where the config has been read, all timestamps carry six fractional digits:
    2026-08-06 08:01:40.086300 CEST [12345M] DEBUG_ANY: * EXTRA:          YES  *
    
    The same can be done without touching the config file by starting FTL with FTLCONF_debug_extra=true.
  3. Check /var/log/pihole/webserver.log while the flag is set - it uses the same time string and switches along.
  4. Turn the flag off again and confirm the log is back to milliseconds.

Automated coverage: the existing test/ suite runs with debug.extra unset, so the log format it sees is unchanged; test_final.bats continues to scan FTL.log for unexpected WARNING/ERROR/CRIT lines as before.


Related issue or feature (if applicable): N/A

Pull request in docs with documentation (if applicable): N/A


By submitting this pull request, I confirm the following:

  1. I have read and understood the contributors guide, as well as this entire template. I understand which branch to base my commits and Pull Requests against.
  2. I have commented my proposed changes within the code.
  3. I am willing to help maintain this change if there are issues with it later.
  4. It is compatible with the EUPL 1.2 license
  5. I have squashed any insignificant commits. (git rebase)

Checklist:

  • The code change is tested and works locally.
  • I based my code and PRs against the repositories development branch.
  • I signed off all commits. Pi-hole enforces the DCO for all contributions
  • I signed all my commits. Pi-hole requires signatures to verify authorship
  • I have read the above and my PR is ready for review.

The millisecond resolution of our log timestamps is too coarse to order
events that happen inside the same millisecond, which is exactly what one
needs when chasing down a timing problem. Instead of adding yet another
config option for this, we reuse `debug.extra`, the flag that already
exists for temporary investigations: when it is enabled, `get_timestr()`
prints six instead of three fractional digits.

```
2026-08-06 08:01:40.086 CEST [12345M] INFO: ...     (default)
2026-08-06 08:01:40.086300 CEST [12345M] INFO: ...  (debug.extra = true)
```

This covers every timestamped log line (FTL.log, webserver.log and stdout)
as they all go through `get_timestr()`. The default output is unchanged.

Signed-off-by: DL6ER <dl6er@dl6er.de>
Copilot AI lite review requested due to automatic review settings August 6, 2026 06:03
@DL6ER
DL6ER requested a review from a team as a code owner August 6, 2026 06:03

Copilot AI 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.

Pull request overview

This PR enhances Pi-hole FTL’s log timestamp precision for debugging scenarios by switching fractional timestamp output from milliseconds to microseconds when debug.extra is enabled, while keeping the default log format unchanged.

Changes:

  • Update get_timestr() to emit 6 fractional digits (microseconds) when config.debug.extra is set, otherwise preserve the existing 3-digit millisecond format.
  • Extend the debug.extra config help text to document the timestamp-resolution change.

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 1 comment.

File Description
src/log.c Adds conditional microsecond vs millisecond fractional timestamp formatting based on debug.extra.
src/config/config.c Updates debug.extra help text to mention the increased log timestamp resolution.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread src/log.c
Comment on lines +110 to +113
// debug.extra bumps the resolution to microseconds so events
// happening within the same millisecond can still be ordered
const bool micros = config.debug.extra.v.b;
const int subsec = micros ? (int)tv.tv_usec : (int)(tv.tv_usec/1000);

@yubiuser yubiuser left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

test/pihole.toml needs adjustment

@DL6ER
DL6ER marked this pull request as draft August 6, 2026 13:20
@DL6ER

DL6ER commented Aug 6, 2026

Copy link
Copy Markdown
Member Author

Parked as a draft for now: the open chain of logging PRs (#2958, #2960, #2968, #2969) introduces get_timestr_iso8601() for the JSON/journald output, which still formats milliseconds. Once that series has landed, this should be revisited so both timestamp paths gain the higher resolution together.

@DL6ER DL6ER changed the title Use microsecond timestamp resolution in the log when debug.extra is set Optional microsecond timestamp in the log (debug.extra) Aug 6, 2026
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.

3 participants