Skip to content

Conversation

@mike-jumper
Copy link
Contributor

@mike-jumper mike-jumper commented Dec 12, 2025

This change performs significant automatic cleanup of our logging style. Previously, all log messages simply included an abbreviated class name for context:

02:24:20.729 [http-nio-8181-exec-10] INFO  o.a.d.a.l.e.ExtrasCodecFactoryUtil - MSG_06001_REGISTERED_EXTENDED_OP_FACTORY (1.3.6.1.4.1.4203.1.11.3)
02:24:20.729 [http-nio-8181-exec-10] INFO  o.a.d.a.l.e.ExtrasCodecFactoryUtil - MSG_06002_REGISTERED_INTERMEDIATE_FACTORY (1.3.6.1.4.1.4203.1.9.1.4)
02:24:20.771 [http-nio-8181-exec-10] INFO  o.a.g.a.l.AuthenticationProviderService - Unable to determine DN of user "guacadmin" using LDAP server "localhost". Proceeding with next server...
02:24:20.771 [http-nio-8181-exec-10] INFO  o.a.g.a.l.AuthenticationProviderService - User "guacadmin" did not successfully authenticate against any LDAP server.
02:24:20.771 [http-nio-8181-exec-10] WARN  o.a.g.event.EventLoggingListener - Authentication attempt from 127.0.0.1 for user "guacadmin" failed: Invalid login (rejected by "postgresql")
02:24:30.977 [http-nio-8181-exec-1] INFO  o.a.g.event.EventLoggingListener - User "guacadmin" (authenticated by "postgresql") successfully authenticated from 127.0.0.1
02:24:49.354 [http-nio-8181-exec-3] WARN  o.a.i.d.pooled.PooledDataSource - Execution of ping query 'SELECT 1' failed: FATAL: terminating connection due to administrator command
02:24:49.355 [http-nio-8181-exec-3] WARN  o.a.i.d.pooled.PooledDataSource - Execution of ping query 'SELECT 1' failed: FATAL: terminating connection due to administrator command
02:24:49.358 [http-nio-8181-exec-3] ERROR o.a.g.rest.RESTExceptionMapper - Unexpected internal error: 
### Error querying database.  Cause: org.postgresql.util.PSQLException: Connection to localhost:5432 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
### The error may exist in org/apache/guacamole/auth/jdbc/user/UserMapper.xml
### The error may involve org.apache.guacamole.auth.jdbc.user.UserMapper.selectOne
### The error occurred while executing a query
### Cause: org.postgresql.util.PSQLException: Connection to localhost:5432 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.

The class name is a detail that's mainly helpful to developers, and there are other issues with readability:

  • Messages that have been explicitly split into multiple lines are not clearly part of the same message vs. unexpected output from part of Tomcat.
  • Messages from third-party components are difficult to tie to their relevant Guacamole extension.
  • The timestamps are ambiguous and include only the time (no date or time zone).

To target messages more at administrators, these changes use an automatically determined "module" name for context (derived from context information on the call stack):

2025-12-11 11:26:39.355 -08:00 guacamole [ext:ldap] INFO: MSG_06001_REGISTERED_EXTENDED_OP_FACTORY (1.3.6.1.4.1.4203.1.11.3)
2025-12-11 11:26:39.356 -08:00 guacamole [ext:ldap] INFO: MSG_06002_REGISTERED_INTERMEDIATE_FACTORY (1.3.6.1.4.1.4203.1.9.1.4)
2025-12-11 11:26:39.396 -08:00 guacamole [ext:ldap] INFO: Unable to determine DN of user "guacadmin" using LDAP server "localhost". Proceeding with next server...
2025-12-11 11:26:39.396 -08:00 guacamole [ext:ldap] INFO: User "guacadmin" did not successfully authenticate against any LDAP server.
2025-12-11 11:26:39.396 -08:00 guacamole [app] WARN: Authentication attempt from 127.0.0.1 for user "guacadmin" failed: Invalid login (rejected by "postgresql")
2025-12-11 11:35:03.255 -08:00 guacamole [app] INFO: User "guacadmin" (authenticated by "postgresql") successfully authenticated from 127.0.0.1
2025-12-11 11:35:15.112 -08:00 guacamole [ext:postgresql] WARN: Execution of ping query 'SELECT 1' failed: FATAL: terminating connection due to administrator command
2025-12-11 11:35:15.113 -08:00 guacamole [ext:postgresql] WARN: Execution of ping query 'SELECT 1' failed: FATAL: terminating connection due to administrator command
2025-12-11 11:35:15.116 -08:00 guacamole [app] ERROR: Unexpected internal error: 
+ ### Error querying database.  Cause: org.postgresql.util.PSQLException: Connection to localhost:5432 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
+ ### The error may exist in org/apache/guacamole/auth/jdbc/user/UserMapper.xml
+ ### The error may involve org.apache.guacamole.auth.jdbc.user.UserMapper.selectOne
+ ### The error occurred while executing a query
+ ### Cause: org.postgresql.util.PSQLException: Connection to localhost:5432 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.

Stack traces are automatically omitted except when debug-level logging is enabled, in which case the abbreviated class name also returns:

2025-12-11 11:38:08.757 -08:00 guacamole [ext:ldap, thread:NioProcessor-1] DEBUG: o.a.d.l.c.api.LdapNetworkConnection - MSG_04119_GETTING (2,org.apache.directory.ldap.client.api.future.SearchFuture)
2025-12-11 11:38:08.757 -08:00 guacamole [ext:ldap, thread:NioProcessor-1] DEBUG: o.a.d.l.c.api.LdapNetworkConnection - MSG_04131_SEARCH_SUCCESSFUL (MessageType : SEARCH_RESULT_DONE
+ Message ID : 2
+     Search Result Done
+         Ldap Result
+             Result code : (SUCCESS) success
+             Matched Dn : ''
+             Diagnostic message : ''
+ )
2025-12-11 11:38:08.757 -08:00 guacamole [ext:ldap, thread:NioProcessor-1] DEBUG: o.a.d.l.c.api.LdapNetworkConnection - MSG_04126_REMOVING (2,org.apache.directory.ldap.client.api.future.SearchFuture)
2025-12-11 11:38:08.757 -08:00 guacamole [ext:ldap, thread:http-nio-8181-exec-4] DEBUG: org.apache.directory.CURSOR_LOG - MSG_04171_CLOSING_SEARCH_CURSOR (org.apache.directory.ldap.client.api.SearchCursorImpl@1c4e71b)
2025-12-11 11:38:08.757 -08:00 guacamole [ext:ldap, thread:http-nio-8181-exec-4] DEBUG: org.apache.directory.CURSOR_LOG - MSG_04171_CLOSING_SEARCH_CURSOR (org.apache.directory.ldap.client.api.SearchCursorImpl@1c4e71b)
2025-12-11 11:38:08.757 -08:00 guacamole [ext:ldap, thread:NioProcessor-1] DEBUG: o.a.d.l.c.api.LdapNetworkConnection - MSG_04137_NOD_RECEIVED ()
2025-12-11 11:38:08.758 -08:00 guacamole [ext:ldap, thread:http-nio-8181-exec-4] INFO: o.a.g.a.l.AuthenticationProviderService - Unable to determine DN of user "guacadmin" using LDAP server "localhost". Proceeding with next server...
2025-12-11 11:38:08.758 -08:00 guacamole [ext:ldap, thread:http-nio-8181-exec-4] INFO: o.a.g.a.l.AuthenticationProviderService - User "guacadmin" did not successfully authenticate against any LDAP server.
2025-12-11 11:38:08.758 -08:00 guacamole [app, thread:http-nio-8181-exec-4] DEBUG: o.a.g.a.f.FileAuthenticationProvider - User mapping file "/home/mjumper/.guacamole/user-mapping.xml" does not exist and will not be read.
2025-12-11 11:38:08.758 -08:00 guacamole [app, thread:http-nio-8181-exec-4] WARN: o.a.g.event.EventLoggingListener - Authentication attempt from 127.0.0.1 for user "guacadmin" failed: Invalid login (rejected by "postgresql")
+ org.apache.guacamole.net.auth.credentials.GuacamoleInvalidCredentialsException: Invalid login
+ 	at org.apache.guacamole.auth.jdbc.JDBCAuthenticationProviderService.authenticateUser(JDBCAuthenticationProviderService.java:88)
+ 	at org.apache.guacamole.auth.jdbc.InjectedAuthenticationProvider.authenticateUser(InjectedAuthenticationProvider.java:76)
+ 	at org.apache.guacamole.extension.AuthenticationProviderFacade.authenticateUser(AuthenticationProviderFacade.java:200)
+ 	at org.apache.guacamole.rest.auth.AuthenticationService.authenticateUser(AuthenticationService.java:132)
+ 	at org.apache.guacamole.rest.auth.AuthenticationService.getAuthenticatedUser(AuthenticationService.java:235)
+ 	at org.apache.guacamole.rest.auth.AuthenticationService.authenticate(AuthenticationService.java:391)
+ 	at org.apache.guacamole.rest.auth.TokenRESTService.createToken(TokenRESTService.java:174)

The fact that this is now automatic means that the old style of manually logging twice:

logger.warn("Something looks wrong: {}", e.getMessage());
logger.debug("Something failed while performing an action.", e);

can now be replaced with a single log statement:

logger.warn("Something looks wrong: {}", e.getMessage(), e);

and these changes update the rest of guacamole-client to do so.

These changes also silence the following confusing WebSocket error that can sometimes appear when a connection has closed:

Exception in thread "Thread-2" java.lang.IllegalStateException: Message will not be sent because the WebSocket session has been closed
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:454)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlockInternal(WsRemoteEndpointImplBase.java:312)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:265)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:249)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendString(WsRemoteEndpointImplBase.java:191)
	at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:36)
	at org.apache.guacamole.websocket.GuacamoleWebSocketTunnelEndpoint.sendInstruction(GuacamoleWebSocketTunnelEndpoint.java:152)
	at org.apache.guacamole.websocket.GuacamoleWebSocketTunnelEndpoint.access$200(GuacamoleWebSocketTunnelEndpoint.java:53)
	at org.apache.guacamole.websocket.GuacamoleWebSocketTunnelEndpoint$2.run(GuacamoleWebSocketTunnelEndpoint.java:253)

This will now only appear at the debug level, handled as part of the WebSocket tunnel's overall logging of I/O errors, rather than propagating all the way up to Tomcat.

(Opening as a draft while I self-review this a bit.)

@necouchman
Copy link
Contributor

@mike-jumper One question about these changes that I just want to confirm - when DEBUG-level logging is enabled, this will result in the abbreviated class names being included at all of the message levels (INFO, WARN, DEBUG, etc.), and not just for stack traces or DEBUG-level messages, correct? I think this is what I see in your output above, just want to verify, as I find that valuable as a developer.

@mike-jumper
Copy link
Contributor Author

... when DEBUG-level logging is enabled, this will result in the abbreviated class names being included at all of the message levels (INFO, WARN, DEBUG, etc.), and not just for stack traces or DEBUG-level messages, correct?

@necouchman Yep!

@mike-jumper mike-jumper marked this pull request as ready for review December 12, 2025 18:43
Copy link
Contributor

@necouchman necouchman left a comment

Choose a reason for hiding this comment

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

Just a couple of log message...that I wrote...that probably need some updating :-).

@mike-jumper
Copy link
Contributor Author

mike-jumper commented Dec 12, 2025

No longer part of these changes, but an earlier iteration involved creating a ForkableHashMap class that supports copy-on-write:

/**
 * HashMap implementation that uses copy-on-write to allow efficient cloning.
 * When an instance of ForkableHashMap has been copied using {@link #fork()},
 * the parent and child both continue to refer to the same copy of their
 * underlying data. If the parent (or child) is modified, only then does the
 * parent (or child) create an independent copy of that underlying data.
 * <p>
 * For simplicity, this implementation DOES NOT permit modification via the
 * collections/sets returned by {@link #values()}, {@link #keySet()}, or
 * {@link #entrySet()}.
 * <p>
 * As with the standard HashMap, this implementation IS NOT threadsafe.
 *
 * @param <K>
 *     The type of key used to store/retrieve values within this map.
 *
 * @param <V>
 *     The type of values stored by this map.
 */
public class ForkableHashMap<K, V> implements Map<K, V> {
   ...
}

It was a neat data structure that lives on in the git history as part of commit be53376 and might be handy in the future.

We don't use WADL support and it has historically been implicitly
disabled through the lack of a JAXB implementation. Jersey warns of this
every time Guacamole starts up:

    WARN: JAXBContext implementation could not be found. WADL feature is disabled.

This disables WADL explicitly.
The LDAP extension's guac-manifest.json refers to a German translation
in "de.json", but that translation file doesn't actually exist for LDAP,
hence the following warning at startup:

    WARN: Overlay language resource "de" does not exist.

This corrects that warning by removing the erroneous reference.
@necouchman necouchman merged commit 4aa841c into apache:staging/1.6.1 Dec 13, 2025
1 check passed
@mike-jumper mike-jumper deleted the improve-log-style branch December 13, 2025 01:34
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.

2 participants