Skip to content

Demote granular internal logs from Debug to Trace level#5116

Merged
thomhurst merged 1 commit intomainfrom
demote-debug-logs-to-trace
Mar 10, 2026
Merged

Demote granular internal logs from Debug to Trace level#5116
thomhurst merged 1 commit intomainfrom
demote-debug-logs-to-trace

Conversation

@thomhurst
Copy link
Owner

Summary

  • Moves per-item scheduling, hook building, test grouping, and assembly loading logs from Debug to Trace level, reducing noise at Debug verbosity
  • Keeps high-level flow logs (test count, max parallelism config, hook init start/complete, infrastructure bookends) at Debug
  • Adds IsTraceEnabled property to TUnitFrameworkLogger for guard checks

Files changed

  • ConstraintKeyScheduler — all 5 per-test constraint key logs → Trace
  • TestScheduler — 7 per-group/per-batch start logs → Trace; kept 2 flow + 5 config logs as Debug
  • HookDelegateBuilder — 2 per-hook detail logs → Trace; kept 2 top-level summary logs as Debug
  • TestGroupingService — 7 summary detail lines → Trace
  • InfrastructureGenerator — 4 per-assembly generated log patterns → Trace; kept init start/complete as Debug
  • TUnitFrameworkLogger — added IsTraceEnabled property
  • 4 snapshot .verified.txt files updated to match

Test plan

  • TUnit.Engine builds with 0 warnings
  • TUnit.Core.SourceGenerator builds with 0 warnings
  • Snapshot verified files updated to match generator output
  • CI passes

Per-item scheduling, hook building, and assembly loading logs are too
verbose for Debug and better suited to Trace. High-level flow and
configuration logs remain at Debug.
Copy link
Contributor

@claude claude bot left a comment

Choose a reason for hiding this comment

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

Code Review

Overall this is a clean, well-scoped PR that improves the signal-to-noise ratio at Debug level. The separation between Debug (flow-level) and Trace (per-item detail) is a meaningful improvement for users who run with --log-level debug.


Concern: Assembly load failures demoted to Trace

The four Failed to load ... messages in InfrastructureGenerator.cs (and the generated snapshot files) have been moved to Trace:

// Before
LogDebug("[ModuleInitializer:...] Failed to load ...: " + ex.Message);
// After  
LogTrace("[ModuleInitializer:...] Failed to load ...: " + ex.Message);

I'd argue these should stay at Debug. The success path (Assembly initialized) is absolutely right to move to Trace — it's noise. But a failure deserves more visibility. A user who runs --log-level debug to investigate a test discovery problem would no longer see these. They'd need to know to enable Trace first, which is a significant discoverability hurdle.

The PR description itself notes this pattern: "Keeps high-level flow logs... at Debug". An assembly load failure is effectively a flow event (it affects what tests are discovered), not a per-item detail.

Suggested approach: Keep Failed to load at Debug, move only Loading assembly containing and Assembly initialized to Trace.


Inconsistency: Missing IsTraceEnabled guards in HookDelegateBuilder

ConstraintKeyScheduler and TestScheduler correctly guard their trace calls:

if (_logger.IsTraceEnabled)
    await _logger.LogTraceAsync($"Starting test {test.TestId} with constraint keys: {string.Join(...)}");

But HookDelegateBuilder.cs does not:

// No guard — string interpolation always runs
await _logger.LogTraceAsync($"Creating delegate for {hookTypeName} hook: {hook.Name}");
await _logger.LogTraceAsync($"Built {hooks.Count} {hookTypeName} hook delegate(s)");

The existing LogAsync base method short-circuits on IsEnabled, so correctness is fine — but the string interpolation always allocates even when Trace is off. The guards in the other files exist specifically to avoid this. The PR adds IsTraceEnabled precisely to enable this pattern; it should be applied consistently.


Minor: TestGroupingService summary block has no guard

The 7-call summary block:

await _logger.LogTraceAsync("═══ Test Grouping Summary ═══").ConfigureAwait(false);
await _logger.LogTraceAsync($"  Parallel (no constraints): {parallelTests.Count} tests").ConfigureAwait(false);
// ... 5 more calls

Could be wrapped in a single guard to avoid 7 async overhead calls when Trace is disabled:

if (_logger.IsTraceEnabled)
{
    await _logger.LogTraceAsync("═══ Test Grouping Summary ═══").ConfigureAwait(false);
    // ...
}

The individual string interpolations here are cheap (just integer property accesses), so this is low priority — but it would be consistent with the guard pattern used elsewhere and GroupTestsByConstraintsAsync is on the hot path.


What's good

  • The two-tier Debug/Trace separation is clearly reasoned and the PR description maps it well.
  • Adding to is the right way to enable efficient guard checks — it mirrors the existing pattern symmetrically.
  • Snapshot files correctly updated across all 4 target frameworks.
  • The per-test constraint key and scheduling logs are absolutely right to move to Trace — they'd produce O(N) lines per test run at Debug level.

Copy link
Contributor

@claude claude bot left a comment

Choose a reason for hiding this comment

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

Code Review

Overall this is a clean, well-scoped PR that improves the signal-to-noise ratio at Debug level. The separation between Debug (flow-level) and Trace (per-item detail) is a meaningful improvement for users who run with --log-level debug.


Concern: Assembly load failures demoted to Trace

The four Failed to load ... messages in InfrastructureGenerator.cs (and the generated snapshot files) have been moved to Trace:

// Before
LogDebug("[ModuleInitializer:...] Failed to load ...: " + ex.Message);
// After  
LogTrace("[ModuleInitializer:...] Failed to load ...: " + ex.Message);

I'd argue these should stay at Debug. The success path (Assembly initialized) is absolutely right to move to Trace — it's noise. But a failure deserves more visibility. A user who runs --log-level debug to investigate a test discovery problem would no longer see these. They'd need to know to enable Trace first, which is a significant discoverability hurdle.

The PR description itself notes this pattern: "Keeps high-level flow logs... at Debug". An assembly load failure is effectively a flow event (it affects what tests are discovered), not a per-item detail.

Suggested approach: Keep Failed to load at Debug, move only Loading assembly containing and Assembly initialized to Trace.


Inconsistency: Missing IsTraceEnabled guards in HookDelegateBuilder

ConstraintKeyScheduler and TestScheduler correctly guard their trace calls:

if (_logger.IsTraceEnabled)
    await _logger.LogTraceAsync($"Starting test {test.TestId} with constraint keys: {string.Join(...)}");

But HookDelegateBuilder.cs does not:

// No guard — string interpolation always runs
await _logger.LogTraceAsync($"Creating delegate for {hookTypeName} hook: {hook.Name}");
await _logger.LogTraceAsync($"Built {hooks.Count} {hookTypeName} hook delegate(s)");

The existing LogAsync base method short-circuits on IsEnabled, so correctness is fine — but the string interpolation always allocates even when Trace is off. The guards in the other files exist specifically to avoid this. The PR adds IsTraceEnabled precisely to enable this pattern; it should be applied consistently.


Minor: TestGroupingService summary block has no guard

The 7-call summary block:

await _logger.LogTraceAsync("=== Test Grouping Summary ===").ConfigureAwait(false);
await _logger.LogTraceAsync($"  Parallel (no constraints): {parallelTests.Count} tests").ConfigureAwait(false);
// ... 5 more calls

Could be wrapped in a single guard to avoid 7 async overhead calls when Trace is disabled:

if (_logger.IsTraceEnabled)
{
    await _logger.LogTraceAsync("=== Test Grouping Summary ===").ConfigureAwait(false);
    // ...
}

The individual string interpolations here are cheap (just integer property accesses), so this is low priority — but it would be consistent with the guard pattern used elsewhere, and GroupTestsByConstraintsAsync is on the hot path.


What's good

  • The two-tier Debug/Trace separation is clearly reasoned and the PR description maps it well.
  • Adding IsTraceEnabled to TUnitFrameworkLogger is the right way to enable efficient guard checks — it mirrors the existing IsDebugEnabled pattern symmetrically.
  • Snapshot files correctly updated across all 4 target frameworks.
  • The per-test constraint key and scheduling logs are absolutely right to move to Trace — they would produce O(N) lines per test run at Debug level, which was the real noise problem.

@thomhurst thomhurst enabled auto-merge (squash) March 10, 2026 11:42
@thomhurst thomhurst merged commit 393e26c into main Mar 10, 2026
15 of 16 checks passed
@thomhurst thomhurst deleted the demote-debug-logs-to-trace branch March 10, 2026 12:04
@claude claude bot mentioned this pull request Mar 10, 2026
1 task
intellitect-bot pushed a commit to IntelliTect/EssentialCSharp.Web that referenced this pull request Mar 12, 2026
Updated [TUnit](https://github.com/thomhurst/TUnit) from 1.19.16 to
1.19.22.

<details>
<summary>Release notes</summary>

_Sourced from [TUnit's
releases](https://github.com/thomhurst/TUnit/releases)._

## 1.19.22

<!-- Release notes generated using configuration in .github/release.yml
at v1.19.22 -->

## What's Changed
### Other Changes
* Remove redundant prefixes from tracing timeline spans by @​thomhurst
in thomhurst/TUnit#5111
* Render span tags and events on separate lines by @​thomhurst in
thomhurst/TUnit#5113
* Demote granular internal logs from Debug to Trace level by @​thomhurst
in thomhurst/TUnit#5116
### Dependencies
* chore(deps): update tunit to 1.19.16 by @​thomhurst in
thomhurst/TUnit#5109


**Full Changelog**:
thomhurst/TUnit@v1.19.16...v1.19.22

Commits viewable in [compare
view](thomhurst/TUnit@v1.19.16...v1.19.22).
</details>

[![Dependabot compatibility
score](https://dependabot-badges.githubapp.com/badges/compatibility_score?dependency-name=TUnit&package-manager=nuget&previous-version=1.19.16&new-version=1.19.22)](https://docs.github.com/en/github/managing-security-vulnerabilities/about-dependabot-security-updates#about-compatibility-scores)

Dependabot will resolve any conflicts with this PR as long as you don't
alter it yourself. You can also trigger a rebase manually by commenting
`@dependabot rebase`.

[//]: # (dependabot-automerge-start)
[//]: # (dependabot-automerge-end)

---

<details>
<summary>Dependabot commands and options</summary>
<br />

You can trigger Dependabot actions by commenting on this PR:
- `@dependabot rebase` will rebase this PR
- `@dependabot recreate` will recreate this PR, overwriting any edits
that have been made to it
- `@dependabot show <dependency name> ignore conditions` will show all
of the ignore conditions of the specified dependency
- `@dependabot ignore this major version` will close this PR and stop
Dependabot creating any more for this major version (unless you reopen
the PR or upgrade to it yourself)
- `@dependabot ignore this minor version` will close this PR and stop
Dependabot creating any more for this minor version (unless you reopen
the PR or upgrade to it yourself)
- `@dependabot ignore this dependency` will close this PR and stop
Dependabot creating any more for this dependency (unless you reopen the
PR or upgrade to it yourself)


</details>

Signed-off-by: dependabot[bot] <support@github.com>
Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>
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.

1 participant