You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@guacamole.apache.org by "mike-jumper (via GitHub)" <gi...@apache.org> on 2025/12/12 10:34:16 UTC
[PR] GUACAMOLE-2181: Improve readability of logs. [guacamole-client]
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: dev-unsubscribe@guacamole.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] GUACAMOLE-2181: Improve readability of logs. [guacamole-client]
Posted by "mike-jumper (via GitHub)" <gi...@apache.org>.
mike-jumper commented on PR #1136:
URL: https://github.com/apache/guacamole-client/pull/1136#issuecomment-3647584392
> ... 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!
--
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: dev-unsubscribe@guacamole.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] GUACAMOLE-2181: Improve readability of logs. [guacamole-client]
Posted by "mike-jumper (via GitHub)" <gi...@apache.org>.
mike-jumper commented on PR #1136:
URL: https://github.com/apache/guacamole-client/pull/1136#issuecomment-3648386197
No longer part of these changes, but an earlier iteration involved creating [a `ForkableHashMap` class that supports copy-on-write](https://github.com/mike-jumper/guacamole-client/blob/be53376f280cd646d096c67a6feb930b2bf56f01/guacamole/src/main/java/org/apache/guacamole/log/ForkableHashMap.java):
```java
/**
* 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 be53376f280cd646d096c67a6feb930b2bf56f01 and might be handy in the future.
--
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: dev-unsubscribe@guacamole.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] GUACAMOLE-2181: Improve readability of logs. [guacamole-client]
Posted by "mike-jumper (via GitHub)" <gi...@apache.org>.
mike-jumper commented on code in PR #1136:
URL: https://github.com/apache/guacamole-client/pull/1136#discussion_r2615516392
##########
extensions/guacamole-auth-radius/src/main/java/org/apache/guacamole/auth/radius/AuthenticationProviderService.java:
##########
@@ -95,15 +95,13 @@ private GuacamoleRadiusChallenge getRadiusChallenge(RadiusPacket challengePacket
RadiusAttribute stateAttr = challengePacket.findAttribute(Attr_State.TYPE);
if (stateAttr == null) {
logger.error("Something went wrong, state attribute not present.");
- logger.debug("State Attribute turned up null, which shouldn't happen in AccessChallenge.");
Review Comment:
OK - I think I've clarified both these messages 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: dev-unsubscribe@guacamole.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] GUACAMOLE-2181: Improve readability of logs. [guacamole-client]
Posted by "necouchman (via GitHub)" <gi...@apache.org>.
necouchman commented on PR #1136:
URL: https://github.com/apache/guacamole-client/pull/1136#issuecomment-3646619063
@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.
--
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: dev-unsubscribe@guacamole.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] GUACAMOLE-2181: Improve readability of logs. [guacamole-client]
Posted by "necouchman (via GitHub)" <gi...@apache.org>.
necouchman merged PR #1136:
URL: https://github.com/apache/guacamole-client/pull/1136
--
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: dev-unsubscribe@guacamole.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] GUACAMOLE-2181: Improve readability of logs. [guacamole-client]
Posted by "mike-jumper (via GitHub)" <gi...@apache.org>.
mike-jumper commented on code in PR #1136:
URL: https://github.com/apache/guacamole-client/pull/1136#discussion_r2615516392
##########
extensions/guacamole-auth-radius/src/main/java/org/apache/guacamole/auth/radius/AuthenticationProviderService.java:
##########
@@ -95,15 +95,13 @@ private GuacamoleRadiusChallenge getRadiusChallenge(RadiusPacket challengePacket
RadiusAttribute stateAttr = challengePacket.findAttribute(Attr_State.TYPE);
if (stateAttr == null) {
logger.error("Something went wrong, state attribute not present.");
- logger.debug("State Attribute turned up null, which shouldn't happen in AccessChallenge.");
Review Comment:
OK - I think I've clarified both these messages a bit: 5ad5a46cfe539fc038c5c87a7fb1eebb0696abdd
--
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: dev-unsubscribe@guacamole.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] GUACAMOLE-2181: Improve readability of logs. [guacamole-client]
Posted by "necouchman (via GitHub)" <gi...@apache.org>.
necouchman commented on code in PR #1136:
URL: https://github.com/apache/guacamole-client/pull/1136#discussion_r2615184895
##########
extensions/guacamole-auth-radius/src/main/java/org/apache/guacamole/auth/radius/AuthenticationProviderService.java:
##########
@@ -95,15 +95,13 @@ private GuacamoleRadiusChallenge getRadiusChallenge(RadiusPacket challengePacket
RadiusAttribute stateAttr = challengePacket.findAttribute(Attr_State.TYPE);
if (stateAttr == null) {
logger.error("Something went wrong, state attribute not present.");
- logger.debug("State Attribute turned up null, which shouldn't happen in AccessChallenge.");
return null;
}
// We need to get the reply message so we know what to ask the user
RadiusAttribute replyAttr = challengePacket.findAttribute(Attr_ReplyMessage.TYPE);
if (replyAttr == null) {
logger.error("No reply message received from the server.");
- logger.debug("Expecting a Attr_ReplyMessage attribute on this packet, and did not get one.");
Review Comment:
Similar to the above change - the `logger.error()` version of this message might need to get some of the details from the `debug()` message that's being removed.
##########
extensions/guacamole-auth-radius/src/main/java/org/apache/guacamole/auth/radius/AuthenticationProviderService.java:
##########
@@ -95,15 +95,13 @@ private GuacamoleRadiusChallenge getRadiusChallenge(RadiusPacket challengePacket
RadiusAttribute stateAttr = challengePacket.findAttribute(Attr_State.TYPE);
if (stateAttr == null) {
logger.error("Something went wrong, state attribute not present.");
- logger.debug("State Attribute turned up null, which shouldn't happen in AccessChallenge.");
Review Comment:
I wonder if it's worth a tweak to the error message just above this to be a little more clear on when this error is occurring? Something like:
```
logger.error("Missing \"state\" attribute during the access challenge step.");
```
I clearly wrote the messages above (and just below this) in pairs, expecting that, if one happened and you turned on debugging, it'd be obvious what was going on. Since the debug-level messages are being removed, here, the error messages may need a little more verbosity?
--
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: dev-unsubscribe@guacamole.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org