FWD » Core Development » Runtime Infrastructure

I’ve attached a patch that adds structured logging for key GUI events, specifically when windows are opened/closed and when buttons are clicked.

Hynek, please take a look.

The idea behind these logs is to make it easier to trace the sequence of user actions leading up to a crash or unexpected behavior. For example:

• Window opened/closed logs help reconstruct the navigation flow (which screen the user was on, and in what order). This is especially useful if issues appear only after entering or leaving certain dialogs.

• Button click logs capture the specific actions the user performed. When combined with the window context, they show why the application transitioned into a particular state.

With this information, we can replay the user’s journey and reproduce the bug much more reliably. It also helps to distinguish whether a failure was triggered by a particular user action, or whether it occurred 'spontaneously' in the background.

Here’s a sample of how the logs look:

25/08/20 16:16:32.920+0300 |    INFO | com.goldencode.p2j.ui.client.widget.TitledWindow | PID:81199, ThreadName:main, Session:00000017, ThreadId:00000001, User:bogus | Window opened: Display customer details
25/08/20 16:16:40.896+0300 |    INFO | com.goldencode.p2j.ui.client.gui.ButtonGuiImpl | PID:81199, ThreadName:main, Session:00000017, ThreadId:00000001, User:bogus | User clicked: Next button.
25/08/20 16:16:42.037+0300 |    INFO | com.goldencode.p2j.ui.client.gui.ButtonGuiImpl | PID:81199, ThreadName:main, Session:00000017, ThreadId:00000001, User:bogus | User clicked: Previous button.
25/08/20 16:16:43.024+0300 |    INFO | com.goldencode.p2j.ui.client.gui.ButtonGuiImpl | PID:81199, ThreadName:main, Session:00000017, ThreadId:00000001, User:bogus | User clicked: Next button.

By default, these logs are suppressed. In directory.xml, the config for the relevant classes will be set to WARNING:

            <node class="string" name="com.goldencode.p2j.ui.client.gui.ButtonGuiImpl">
              <node-attribute name="value" value="WARNING"/>
            </node>
            <node class="string" name="com.goldencode.p2j.ui.client.widget.TitledWindow">
              <node-attribute name="value" value="WARNING"/>
            </node>

If we want these events to be logged, we simply change the level to INFO for the same entries.

Committed finest level logging for window open/close and mouse click events as rev 16135 / 10451a.

Next, I’ll review which additional events might be useful to log. Not all events will be included, since we want to avoid unnecessary overhead even in a testing system. I’ll focus on those that provide the most value.

• window open / close
• widget clicks
• TAB / ENTER key input events

This should be sufficient for now, since navigation typically occurs through TAB, ENTER, or mouse clicks. I’ve attached an example log output for reference.

Hynek, please review.

Code review 10451a.

The "window closed" log output is a bit misleading. It is logged in the remove method of WindowManage. Close operation simetime means a window is closed/hidden rather than destroyed. Also remove is not very meaningful for the navigation, the method is called when a window widget gets out of scope. This could have different timing than just closing a window.

For the key events logging I think it would make it more useful if more information is included in the output, like widget id/name/type/etc. And rather than posting the event it is better to log the event when it is dispatched as dispatch closer to the related UI actions.

Please make the added toString output more in line with the existing formats of the other widgets.

Some UI navigation actions are triggered on mouse release, for these cases, click doesn't even need to come.

When creating logger with Class resolution (name) it is better to pass the Class and let the logger facility to come up with the name. This ensures consistency.

I attached the patch. (reverted window manager, event manager, logs for show / hide are now handled by TitledWindow and ModalWindow. In TC I've added logs for tab / return / choose key).

What I wanted to highlight in my prev note can be seen in the attached logs.

Committed changes as rev 16137.

Hynek, please review.

Hynek Cihlar wrote:

If the log output should function as a tool for tracing UI flow then it is better to have a dedicated logger for all of these outputs. Enabling the logger will only bring in the needed set of outputs not spoiling the log with other entries.

Hynek, are you suggesting that instead of using the CentralLogger, we should use a custom logger that can be enabled through directory.xml..?

Addressed review as rev 16138.

Hynek, please review.

Code review 10451a revisions 16134..16138

• [MAJOR] functional ButtonListGuiImpl.Item.toString: textWidget can be null when toString() is called. Add a null guard.
• [MAJOR] functional MouseHandler.applyMouseEvent: Mouse release events (MOUSE_RELEASED) are not logged. The issue spec explicitly requires mouse release logging, but only MOUSE_CLICKED has the UI_LOGGER.finest(...) call added.
• [MAJOR] performance MouseHandler.applyMouseEvent: UI_LOGGER.finest(mouseSource + " was clicked.") performs unconditional mouseSource.toString() and string concatenation on every mouse-click event, regardless of whether FINEST is enabled. Use UI_LOGGER.log(Level.FINEST, () -> ...) or guard with isLoggable.
• [MINOR] performance TitledWindow.dispatchEvent: The key-dispatch logging block unconditionally calls Keyboard.eventName(action) and builds the concatenated log string even when FINEST is disabled. The isLoggableKey guard filters by event kind but not by log level. Wrap the entire block in a UI_LOGGER.isLoggable(Level.FINEST) guard.
• [MINOR] performance TitledWindow.show: UI_LOGGER.finest("Window " + this + " was shown.") performs unconditional string concatenation and toString() on every invocation regardless of log level. Same applies to TitledWindow.hide and ModalWindow.show. Use UI_LOGGER.log(Level.FINEST, () -> ...) or guard with isLoggable.
• [MINOR] style UITracker: The license block uses a leading space before ** on every line ( ** text) instead of the standard ** text format used in the module header.
• [MINOR] style TitledWindow: Two explicit class imports (CentralLogger and UITracker) from the same package com.goldencode.p2j.util.logging instead of a single wildcard import.

Addressed review as rev 16139.

Next, I'll rebase the branch to retest the behavior.

Code review 10451a revisions 16515..16521

• [MAJOR] performance TitledWindow.processEvent: In the new KeyInput branch, keyEvent.actionCode(), Keyboard.eventName(action) (string allocation/lookup), and keyEvent.isRealKey() are all invoked on every dispatched key event BEFORE UI_LOGGER.isLoggable(Level.FINEST) is checked. Key dispatch is a hot path; this imposes per-keystroke overhead even when FINEST is disabled. The history entry advertises "Guarded finest logging in ... key dispatch processing", but the guard is placed after the expensive computation. Move the isLoggable check outer-most so the eventName computation is only performed when logging is enabled.
• [MAJOR] functional TitledWindow.show/hide: The diff adds import com.goldencode.p2j.ui.client.gui.OverlayWindow; and two instanceof OverlayWindow guards into TitledWindow (package com.goldencode.p2j.ui.client.widget), which had no GUI-package dependencies and is the base of CHUI widgets such as OuterFrame. Leaking a concrete GUI subtype reference into a driver-agnostic base inverts the dependency direction. Since TopLevelWindow already declares an abstract getRelativeTo(), either (a) introduce a protected boolean isTransientCursorRelative() hook on TitledWindow (default false, overridden by OverlayWindow to return true when getRelativeTo() == RELATIVE_TO_CURSOR), or (b) move the logging into TopLevelWindow.show/hide where getRelativeTo() is already in scope without a cast.
• [MINOR] functional ModalWindow.show: The "Window ... was shown." log is emitted before any of the actual show work - realize(), forceVisibility(true), gd.setWindowVisible(true), WindowManager.modalizeWindow(this), WindowManager.forceActivateWindow(this, true). Any of these can throw, leaving the trace claiming success when the window was never actually shown. Move the log to after those steps, or change wording to "is being shown.".
• [MINOR] functional Item.toString: Hardcodes the class name as the literal "ButtonListGuiImpl.Item" instead of using getClass().getSimpleName() or delegating to super.toString(). AbstractWidget.toString() already emits getClass().getSimpleName() + " [id=" + Utils.nonNull(getId(), "<null>") + "]", and MenuItemGuiImpl.toString() correctly follows the super.toString() + " title=" + ... pattern. Item is non-final so hardcoding defeats the existing pattern and breaks on subclass/rename.
• [MINOR] functional Item.toString: textWidget.getText() may itself return null (the underlying TextCell.getText() returns the text field unguarded, and setText() permits null), yielding title=null in the output. Use Utils.nonNull(textWidget.getText(), "") for consistency with TitledWindow.toString().
• [MINOR] performance TitledWindow.hide: The instanceof OverlayWindow test, cast, and getRelativeTo() call are evaluated on every hide() before the isLoggable guard. Reorder so UI_LOGGER.isLoggable(Level.FINEST) is checked first to short-circuit when FINEST is off.
• [MINOR] performance TitledWindow.show: Same pattern as hide(); put isLoggable first in the outer check so the instanceof/getRelativeTo() work is skipped when logging is disabled.
• [MINOR] style TitledWindow: New import java.util.logging.Level; uses an explicit class import where the project convention is .* unless a conflict requires an explicit import.
• [MINOR] style MouseHandler: New import java.util.logging.Level; uses an explicit class import where the project convention is .*.
• [MINOR] style TitledWindow: New import com.goldencode.p2j.ui.client.gui.OverlayWindow; is an explicit single-class import; the convention is com.goldencode.p2j.ui.client.gui.* unless a naming conflict exists. (Note: introducing this import at all is flagged separately as an architectural concern.)

Addressed code review as rev 16522. I also added the one time warning.

Hynek, please review. Thanks!

Code review 10451a revisions 16515..16522

• [MAJOR] security UITracker.<clinit>: The keylogger warning is emitted only at Level.FINEST and only inside the class's static initializer. (1) It is logged at the same level as the keystrokes themselves, so an operator who has turned on FINEST for UITracker but routes only INFO+ to operator-visible sinks will never see the warning. The Redmine summary explicitly states the warning should be at WARNING level. (2) The warning fires at most once - at class-load time; if FINEST is enabled later via CentralLogger.setLevels() the warning never fires while keystroke logging starts working. (3) Conversely, if the class loads before FINEST is enabled, the static init guard if (LOG.isLoggable(Level.FINEST)) evaluates false and the warning is never emitted.

• [MAJOR] functional Item.toString: textWidget itself can be null. The field is initialized lazily in createOrUpdateComponents()/recomputeSize(), which has an early-return path when window() null, leaving textWidget uninitialized. The expression textWidget.getText() will throw NPE before Utils.nonNull ever sees the value. The history comment says "Added NPE protection," but Utils.nonNull(...) only protects against a null return from getText(), not against textWidget itself being null. With the new MouseHandler logging using mouseSource + " was clicked.", an Item whose layout has not yet completed (or after a window destroy that nulls children) will throw NPE inside applyMouseEvent, propagating through handleMouseEvent and corrupting the UI event chain. Add a null guard, e.g. textWidget null ? "" : Utils.nonNull(textWidget.getText(), "").

• [MINOR] performance TitledWindow.processEvent: Keyboard.eventName(action) is computed before the isLoggableKey check. For non-loggable keys (the vast majority of keystrokes - any modifier, function key, etc., that is not TAB/RETURN/CHOOSE/real-key), this produces a wasted String allocation per key event whenever FINEST is enabled. Move the eventName computation inside the if (isLoggableKey) block so it only runs when actually needed.

• [MINOR] functional TitledWindow.show: The FINEST log fires near the end of TitledWindow.show() but BEFORE subclass code in OverlayWindow.show() and WindowGuiImpl.show() completes (e.g., gd.setWindowVisible(true)). The log records that the window "was shown" before the driver-level visibility is actually set. By contrast, ModalWindow.show() logs at the end after forceActivateWindow() (correct timing). For consistency, consider moving the log to occur after the full subclass-specific show sequence.

• [MINOR] functional ModalWindow.show: Logging is duplicated logic instead of leveraging super.show(). The rest of the subclass hierarchy (OverlayWindow, WindowGuiImpl, FrameOverlay, DialogBoxWindow, AlertBoxGuiImpl) calls super.show() to inherit logging, but ModalWindow.show() does not call super.show() (it has its own divergent implementation). The added log message string is hand-copied from TitledWindow.show(). If the format diverges, the two paths drift. Suggested fix: extract a small helper such as logShown() on TitledWindow that both paths invoke.

• [MINOR] functional ModalWindow.show: The show log lacks the !isTransientCursorRelative() guard used in TitledWindow.show()/hide(). Since ModalWindow is never cursor-relative this is currently harmless, but if a future modal subtype needs to suppress its show log there is no hook. Suggested fix: gate the log with the same guard for design consistency.

• [MINOR] functional Item.toString: Formatting deviates from the established convention. Other GuiImpl toString() methods (e.g. AbstractWidget, BrowseGuiImpl, TitledWindow) use getClass().getSimpleName() + " [id=..." with a leading space before the bracket; the new code emits getClass().getSimpleName() + "[id=..." with no space, producing output like Item[id=...] instead of Item [id=...]. Add the leading space for visual consistency in logs.

• [MINOR] functional Item.toString: The override returns getClass().getSimpleName() + "[id=...]" and entirely drops the parent's super.toString() info. The convention in sibling classes (MenuItemGuiImpl, SubMenuGuiImpl) is to extend it via super.toString() + " title=" + .... Not a defect but consider chaining to super.toString() to keep any future parent-added fields visible and avoid duplicating the id/class header.

• [MINOR] functional MouseHandler.applyMouseEvent: The new FINEST log is placed AFTER the call to mouseSource.mouseClicked(evt) / mouseSource.mouseReleased(evt). If the widget's handler throws (or terminates the dispatch via an exception path), the FINEST entry will not be emitted, so the log will not reflect that the event was actually delivered. Additionally, if a click handler causes the widget to be destroyed before the log statement executes, toString() could touch null/disposed state (especially relevant given the new ButtonListGuiImpl.Item.toString() override that dereferences textWidget). Suggested fix: move the log line above the dispatch, or wrap it in try/finally.

• [MINOR] functional MouseHandler.applyMouseEvent: The chosen pair MOUSE_CLICKED + MOUSE_RELEASED (without MOUSE_PRESSED) is asymmetric and likely accidental. The natural mouse interaction sequence is PRESSED -> RELEASED -> CLICKED; logging RELEASED and CLICKED but not PRESSED makes the trace harder to interpret (e.g. drag-then-release-outside scenarios produce a RELEASED log with no preceding PRESSED context). Suggested fix: either also add a FINEST log in the MOUSE_PRESSED branch, or document why MOUSE_PRESSED is intentionally suppressed.

• [MINOR] functional MouseHandler.applyMouseEvent: The log message mouseSource + " was clicked." discards the actual MouseEvent payload (button, click count, modifiers, coordinates). MOUSE_CLICKED can fire with click counts > 1 (double-click) and with different buttons (BUTTON1/2/3); the log entry as written cannot distinguish a left-click from a right-click or a single from a double-click on the same widget. Suggested fix: include evt.getButton(), evt.getClickCount(), and possibly evt.getX()/evt.getY() in the log message.

• [MINOR] functional TitledWindow.processEvent: When the inner source.processEvent(event) triggers a focus change or destroys the widget, the subsequent UI_LOGGER.finest("'" + eventName + "' key dispatched for source = " + source) calls toString() on a potentially-disposed widget, which can in turn call user code (configured toString overrides like the new ButtonListGuiImpl.Item.toString which can NPE). Move the log line above source.processEvent(event) (with wording adjusted to "dispatching") to keep diagnostics safe and to also capture cases where the dispatch throws. Even if the widget destroy is currently impossible I think it makes sense to harden the code for potential future changes.

• [MINOR] style ModalWindow: Copyright year in the file header is 2015-2025 but new history entries are dated 20260415. Update the copyright to 2015-2026.

• [MINOR] style TitledWindow: Copyright year is updated only to 2010-2025, but new history entries are dated up to 20260423. Update copyright to 2010-2026.

Addressed code review as rev 16523.

Code review 10451a revisions 16515..16523

The changes look good, please address the following style issue and go ahead with regression testing. Also please update the wiki unless you already did.

• [MAJOR] style MouseHandler.logMouseEvent: Line 942 is 134 characters, exceeding the 110-character limit. The UI_LOGGER.finest(mouseSource + " was clicked. Button = " + evt.getButton() + ", click count = " + evt.getClickCount()) call must be wrapped across multiple lines.

Please merge 10451a to trunk.

Branch 10451a was merged into trunk as rev. 16583 and archived.