[
https://issues.apache.org/jira/browse/GUACAMOLE-1928?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stefan Bluhm updated GUACAMOLE-1928:
------------------------------------
Description:
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:
{quote}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.
{quote}
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.
was:
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.
> 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
> Priority: Major
>
> 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:
>
> {quote}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.
> {quote}
>
> 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)
