Stefan Bluhm created GUACAMOLE-1928:
---------------------------------------
Summary: Show better error description in logs on MySQL
authentication failure
Key: GUACAMOLE-1928
URL: https://issues.apache.org/jira/browse/GUACAMOLE-1928
Project: Guacamole
Issue Type: Improvement
Components: guacamole-auth-jdbc-mysql
Affects Versions: 1.5.4
Environment: AlmaLinux 9, Tomcat 9.0.62-37.el9_3.1, guacd 1.5.4-1.el9,
mariadb-java-client-3.3.3.jar, Extension: mysql, ldap
Reporter: Stefan Bluhm
The information logging of the MySQL/MariaDB extention is not sufficient and
should show more reasons of connection failures.
Example: When the DB server has an expired SSL certificate, Guacamole only logs:
```
Mar 04 19:29:52 server.example.com server[972]: 19:29:52.465
[http-nio-8080-exec-10] WARN o.a.g.e.AuthenticationProviderFacade - The
"mysql" authentication provider has encountered an internal error which will
halt the authentication process. If this is unexpected or you are the developer
of this authentication provider, you may wish to enable debug-level logging. If
this is expected and you wish to ignore such failures in the future, please set
"skip-if-unavailable: mysql" within your guacamole.properties.
Mar 04 19:29:52 server.example.com server[972]: 19:29:52.468
[http-nio-8080-exec-10] ERROR o.a.g.rest.RESTExceptionMapper - Unexpected
internal error:
Mar 04 19:29:52 server.example.com server[972]: ### Error querying database.
Cause: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications
link failure
Mar 04 19:29:52 server.example.com server[972]: The last packet sent
successfully to the server was 0 milliseconds ago. The driver has not received
any packets from the server.
Mar 04 19:29:52 server.example.com server[972]: ### The error may exist in
org/apache/guacamole/auth/jdbc/user/UserMapper.xml
Mar 04 19:29:52 server.example.com server[972]: ### The error may involve
org.apache.guacamole.auth.jdbc.user.UserMapper.selectOne
Mar 04 19:29:52 server.example.com server[972]: ### The error occurred while
executing a query
Mar 04 19:29:52 server.example.com server[972]: ### Cause:
com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link
failure
Mar 04 19:29:52 server.example.com server[972]: The last packet sent
successfully to the server was 0 milliseconds ago. The driver has not received
any packets from the server.
```
The DB Server only phrases that that the connection has been closed by the
client.
Debug mode gave more information:
```
Mar 5 12:06:45 server.example.com server[62724]: Caused by:
javax.net.ssl.SSLHandshakeException: NotAfter: Sat Jan 13 17:21:58 CET 2024
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.Alert.createSSLException(Alert.java:131)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:360)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:303)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:298)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.CertificateMessage$T13CertificateConsumer.checkServerCerts(CertificateMessage.java:1357)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.CertificateMessage$T13CertificateConsumer.onConsumeCertificate(CertificateMessage.java:1232)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.CertificateMessage$T13CertificateConsumer.consume(CertificateMessage.java:1175)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.SSLHandshake.consume(SSLHandshake.java:392)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:443)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:421)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:183)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:172)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1511)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(SSLSocketImpl.java:1421)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:456)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:427)
Mar 5 12:06:45 server.example.com server[62724]: #011at
com.mysql.cj.protocol.ExportControlled.performTlsHandshake(ExportControlled.java:214)
Mar 5 12:06:45 server.example.com server[62724]: #011at
com.mysql.cj.protocol.StandardSocketFactory.performTlsHandshake(StandardSocketFactory.java:191)
Mar 5 12:06:45 server.example.com server[62724]: #011at
com.mysql.cj.protocol.a.NativeSocketConnection.performTlsHandshake(NativeSocketConnection.java:101)
Mar 5 12:06:45 server.example.com server[62724]: #011at
com.mysql.cj.protocol.a.NativeProtocol.negotiateSSLConnection(NativeProtocol.java:370)
Mar 5 12:06:45 server.example.com server[62724]: #011... 100 common frames
omitted
Mar 5 12:06:45 server.example.com server[62724]: Caused by:
java.security.cert.CertificateExpiredException: NotAfter: Sat Jan 13 17:21:58
CET 2024
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.x509.CertificateValidity.valid(CertificateValidity.java:277)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.x509.X509CertImpl.checkValidity(X509CertImpl.java:669)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.x509.X509CertImpl.checkValidity(X509CertImpl.java:642)
Mar 5 12:06:45 server.example.com server[62724]: #011at
com.mysql.cj.protocol.ExportControlled$X509TrustManagerWrapper.checkServerTrusted(ExportControlled.java:680)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.AbstractTrustManagerWrapper.checkServerTrusted(SSLContextImpl.java:1533)
Mar 5 12:06:45 server.example.com server[62724]: #011at
java.base/sun.security.ssl.CertificateMessage$T13CertificateConsumer.checkServerCerts(CertificateMessage.java:1341)
Mar 5 12:06:45 server.example.com server[62724]: #011... 115 common frames
omitted
```
This information should have been passed on to the logs as ERROR.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
