Skip to content

fix: correct log timestamps, thread attribution and config discovery - #7705

Merged
Vest merged 8 commits into
PCGen:masterfrom
Vest:fix/logging-formatter
Aug 18, 2026
Merged

fix: correct log timestamps, thread attribution and config discovery#7705
Vest merged 8 commits into
PCGen:masterfrom
Vest:fix/logging-formatter

Conversation

@Vest

@Vest Vest commented Aug 17, 2026

Copy link
Copy Markdown
Contributor

Summary

  • logging.properties was only searched in the working directory; a packaged launch leaves user.dir as / so the file was never found and PCGen silently fell back to the JDK default, losing SourceLogFormatter, the LoggingRecorder (Debug dialog), and pcgen.log. The fix also tries the install directory derived from java.home, mirroring how bundled data is located.
  • SourceLogFormatter stamped log records with LocalDateTime.now() at format time rather than record.getInstant(), so the reported time was wrong and two handlers formatting the same record disagreed. Timestamps now use the record's instant, rendered as local wall-clock time (no zone offset).
  • Thread name was taken from Thread.currentThread().getName() — the formatting thread, not the originating one. The fix reports the originating thread as name#id using LogRecord.getLongThreadID(), which matches thread dumps and debuggers. Unnamed/virtual threads and records formatted off-thread print as #id.
  • Replaces the per-record new Throwable().getStackTrace() caller-finder with a lazy StackWalker that stops at the first frame outside logging plumbing.
  • Converts the remaining Logging.log(Logging.ERROR/Level.SEVERE, ...) call sites to Logging.errorPrint(...), consistent with the other ~794 call sites.
  • Migrates the config-discovery helpers from legacy java.io.File to java.nio.file.Path, and tidies the (Source: <uri>) log suffix (SonarLint S1192/S3457).

Test Plan

  • ./gradlew :test --tests "pcgen.util.LoggingConfigTest" — verifies config-file discovery fallback logic
  • ./gradlew :test --tests "pcgen.util.SourceLogFormatterTest" — verifies timestamp, thread attribution, and caller functionality
  • Confirm pcgen.log is written — verified on Linux (SUSE VM) and via the macOS user.dir=/ java.home fallback
  • Log timestamps match wall clock (local time, no offset)
  • Debug dialog (Tools → Log Window / F10) populates from the recorder — verified on macOS with the log lines rendered

@Vest Vest self-assigned this Aug 17, 2026
@Vest Vest added the bug label Aug 17, 2026
@Vest
Vest force-pushed the fix/logging-formatter branch from 34237ef to cb1c0be Compare August 17, 2026 15:58
Vest and others added 3 commits August 17, 2026 18:00
logging.properties is what wires up SourceLogFormatter and the
LoggingRecorder behind the Debug dialog, but it was only ever looked for
in the working directory. A packaged launch leaves user.dir as "/", so
the file was never found and PCGen silently fell back to the JDK default
logging configuration, losing the formatter, the pcgen.log recorder and
the contents of the Debug dialog. The working directory is still tried
first, then the install directory derived from java.home, mirroring how
the bundled data directories are located.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
SourceLogFormatter took its timestamp from LocalDateTime.now() at the
moment of formatting rather than from the record, so the time reported
was not the time the event occurred, and two handlers formatting the same
record disagreed. It also printed bare UTC with no offset, which silently
differs from the wall clock and from surrounding system log lines. It now
uses record.getInstant(), rendered as local time with an explicit offset
and a fixed width.

The thread was reported as Thread.currentThread().getName(), which names
whichever thread happened to format the record rather than the one that
logged it. The originating thread is now reported as name#id: the id
comes from LogRecord.getLongThreadID(), which is the real Thread.threadId
captured when the record was created and matches thread dumps and
debuggers, while the name is only added when this is still the logging
thread, since LogRecord does not carry it. Unnamed virtual threads and
records formatted elsewhere print as #id rather than being misattributed.

Replaces the per-record new Throwable().getStackTrace() used to find the
caller with a lazy StackWalker that stops at the first frame outside the
logging plumbing.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Converts the nine remaining Logging.log(Logging.ERROR/Level.SEVERE, ...)
call sites to Logging.errorPrint(...), which is the same code path and
level and the idiom used by the other ~794 call sites.

Also documents the logging conventions (errorPrint idiom, logging.properties
wiring, SourceLogFormatter behavior) in AGENTS.md.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@Vest
Vest force-pushed the fix/logging-formatter branch from cb1c0be to dd4ab60 Compare August 17, 2026 16:02
Vest and others added 3 commits August 18, 2026 10:18
The formatter rendered the record's instant as local time with an
explicit offset (name#id timestamps like 2026-08-18T10:03:04.872+02:00).
For a single-user desktop app the offset is noise at best, and it leaks
the user's approximate location into logs that get pasted into public
bug reports. Drop the offset and print bare local wall-clock time, which
is what the user sees on their own clock.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
findLoggingConfig and candidateConfigDirs walked the filesystem with
java.io.File. Switch them to java.nio.file.Path/Files, the modern API:
Path.resolve for child paths, Path.getParent for the upward walk, and
Files.isRegularFile for the existence check. Behavior is unchanged; the
String inputs from SystemUtils are kept at the call boundary.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The " (Source: <uri>)" suffix was built by string concatenation and
duplicated across five log call sites (SonarLint S1192, and S3457 for
concatenating into a format-aware Logger.log message). Extract the
literal into a single SOURCE_FORMAT constant and build the message with
MessageFormat.format, passing the message and URI as arguments.

MessageFormat does not recursively parse argument values, so error
messages containing braces or quotes are unaffected. This also drops the
stray space before the closing paren that four of the sites had, so all
of them now render "(Source: <uri>)" consistently.

These warnings are pre-existing, not introduced by this branch; fixing
them here while the file is already being changed.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@Vest
Vest force-pushed the fix/logging-formatter branch from 8bc5d6e to e9fd0c3 Compare August 18, 2026 08:28
Vest and others added 2 commits August 18, 2026 10:52
Rewrite the formatter tests to guard functional guarantees rather than
the exact layout: the timestamp derives from the record's own instant
(same instant -> same stamp, different -> different, compared as a field
not a pattern), the logging thread is attributed by name and id, a record
formatted on another thread keeps its origin id without claiming the
formatting thread, and a thrown stack trace is rendered. The exact
timestamp pattern and thread rendering can now change without touching
these tests.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Trim the findLoggingConfig javadoc to a one-line what-and-why, and
reword the java.home walk comment to make clear it is layout-agnostic
(macOS is only cited as the deepest nesting that sets MAX_ANCESTORS)
rather than reading as a macOS special case.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@Vest
Vest force-pushed the fix/logging-formatter branch from a4d8cf8 to 75ae1ad Compare August 18, 2026 08:53
@Vest
Vest merged commit c747bc6 into PCGen:master Aug 18, 2026
4 checks passed
@Vest
Vest deleted the fix/logging-formatter branch August 18, 2026 09:14
@github-actions

Copy link
Copy Markdown
Contributor

🚧 PCGen Code Coverage

Overall Project 25.89% -0.03%
Files changed 61.58%

File Coverage
SourceLogFormatter.java 92.72% -7.28% 🍏
Logging.java 44.2% -8.51%
KitLevelAbility.java 12.94% -3.53%
VariableProcessor.java 2.27% -2.77%
ConsoleUIDelegate.java 0% -8%
Main.java 0% -0.7%
MaxCommand.java 0% -3.39%
OrCommand.java 0% -2.47%
IfCommand.java 0% -3.33%
MinCommand.java 0% -3.39%
FopTask.java 0% -0.78%
MinverToken.java 0% -13.33%
DestToken.java 0% -8.33%
MindevverToken.java 0% -13.33%

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant