mike-jumper opened a new pull request, #1136:
URL: https://github.com/apache/guacamole-client/pull/1136
This change performs significant automatic cleanup of our logging style.
Currently, 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.
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:
```java
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:
```java
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:
```java
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.)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
