Skip to content

fix: startup-time numbers printed as literal SLF4J specifiers (1.1.1) - #44

Merged
ddsha441981 merged 3 commits into
mainfrom
fix/startup-time-log-format
Aug 24, 2026
Merged

fix: startup-time numbers printed as literal SLF4J specifiers (1.1.1)#44
ddsha441981 merged 3 commits into
mainfrom
fix/startup-time-log-format

Conversation

@ddsha441981

Copy link
Copy Markdown
Owner

Correctness pass found by running the published 1.1.0 artifact unmodified
against spring-petclinic (Spring Boot 4.1.0, Framework 7.0.8, Java 25.0.2,
470 beans). No API, schema, or configuration changes.

The bug

Three log templates used {:+d} / {:.1f}. SLF4J interpolates only {}, so
the specifier was printed verbatim and every following argument shifted by one
slot
:

⏱ Startup Time: 6687ms -> ms ({:+d}ms, {:.1f}% 7178)   # before
⏱ Startup Time: 6687ms -> 7418ms (+731ms, 10.9% slower) # after

It hit the diff summary, its no-regression variant, and the startup-time
gate's log.error — the last being the line a CI reader lands on first. Numbers
are now pre-formatted through signed(long) / oneDecimal(double) and passed as
plain {} arguments. The WireDoctorRegressionException message was already
correct and is unchanged.

Also: startupTimePercentChange in wiredoctor-gate.status was written with a
default-locale String.format("%.1f", …), so a comma-decimal build machine
emitted 4,3 into a file that is meant to be machine-read. It now goes through
oneDecimal(…), which pins Locale.ROOT.

The docs bug, which is the more damaging one

ci-gating.md told you to record the baseline with ./mvnw spring-boot:run
while Step 3 gates on java -jar. devtools is on the classpath for the former
and excluded from the repackaged jar for the latter — on spring-petclinic that
single difference is 12 removed beans and a 31% startup-time delta, enough to
trip the startup-time gate on a build where nobody changed a line of code. The
quickstart prescribed the exact mismatch that produces a false failure.

Step 1 now records from the jar, with a callout on keeping profiles and
spring.main.web-application-type identical across both runs. Step 3 gains a
warning that a Maven-goal gate cannot fail a build at all: with devtools
present, spring-boot:run runs main on its own restart thread, so the gate
trips, BUILD SUCCESS prints, and the job exits 0.

configuration.md documents output-path for projects whose build lints the
source tree (nohttp rejects the http:// license headers vendored in the
self-contained report, failing the next build), and that scan-packages also
keeps WireDoctor's own beans out of the smell rankings. _config.yml declares
the warning callout the docs reference.

Verification

End-to-end against the petclinic jar with a locally built WireDoctor — both the
summary line and the armed gate:

WireDoctor regression gate 'startup-time' tripped: startup time increased by
290ms (4.3%) vs baseline jar-baseline.json (6687ms -> 6977ms).
Thresholds: >=100ms AND >=2%

Gate run exits 1; wiredoctor-gate.status carries startupTimePercentChange=4.3.

257 tests green — 246 autoconfigure + 11 actuator, +4 new. Among them a guard
that scans every log.* template in the module for a non-{} specifier, so the
whole defect class stays closed. Verified it actually fails by re-injecting
{:+d} before restoring.

Note on publishing

1.1.1 is a source tag only — nothing is published to Maven Central by this
PR, so install snippets in README.md, docs/index.md and
docs/why-wiredoctor.md deliberately stay on 1.1.0. The valuable half of this
change is the docs, and that ships via GitHub Pages the moment this merges.

Three log templates used {:+d} / {:.1f}. SLF4J only interpolates {}, so the
specifier was printed literally and every following argument shifted by one:

  ⏱ Startup Time: 6687ms -> ms ({:+d}ms, {:.1f}% 7178)

The worst one was the startup-time gate's log.error, which is exactly the line
a CI reader lands on. Numbers are now pre-formatted through signed()/oneDecimal()
and passed as plain {} arguments:

  ⏱ Startup Time: 6687ms -> 7418ms (+731ms, 10.9% slower)

Also routes the percent change written into wiredoctor-gate.status through
oneDecimal(), which pins Locale.ROOT — that file is machine-read, so the
decimal separator must not follow the build machine's default locale.

Docs, found while reproducing on spring-petclinic:

- ci-gating.md prescribed recording the baseline with `spring-boot:run` while
  gating on `java -jar`. devtools is on the classpath for one and excluded from
  the repackaged jar for the other, which on petclinic is 12 removed beans and a
  31% startup delta — a startup-time failure on a build where nobody changed a
  line. Step 1 now records from the jar, with a callout on keeping profiles and
  web-application-type identical across both runs.
- ci-gating.md now warns that gating through `spring-boot:run` cannot fail a
  build: devtools runs main on its own restart thread, so the gate trips,
  BUILD SUCCESS prints, and the job exits 0. Falls back to grepping
  wiredoctor-gate.status for anyone stuck on a Maven goal.
- configuration.md documents output-path for projects whose build lints the
  source tree (nohttp rejects the vendored http:// license headers in the
  report), and that scan-packages also keeps WireDoctor's own beans out of the
  smell rankings.
- _config.yml declares the warning callout the docs reference; Just the Docs
  renders it unstyled otherwise.

Adds WireDoctorLogFormattingTest, including a guard that greps every log
template in the module for a non-{} specifier so the whole defect class stays
fixed.
Filed under [Unreleased] — the fix sits on main and the docs corrections go
live via Pages, but there is no reason to cut a patch release to Central for
console formatting alone. It rides along in the next release that has its own
reason to exist.
Parent version bumped in all three child poms, not just the root — a partial
bump is what broke CI on the v0.7.0 release.

Install snippets in README.md, docs/index.md and docs/why-wiredoctor.md stay on
1.1.0 deliberately: 1.1.1 is a source tag, and the docs must only ever point at
a coordinate that actually resolves from Maven Central.
@ddsha441981
ddsha441981 merged commit f8acb57 into main Aug 24, 2026
14 checks passed
@ddsha441981
ddsha441981 deleted the fix/startup-time-log-format branch August 24, 2026 08:03
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