Uploaded image for project: 'Guacamole'
  1. Guacamole
  2. GUACAMOLE-1928

Log hints/notes for suspected causes of third-party library failures

    XMLWordPrintableJSON

Details

    • Wish
    • Status: Reopened
    • Minor
    • Resolution: Unresolved
    • None
    • None
    • guacamole
    • None
    • 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

    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:

       

      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.

      Attachments

        Activity

          People

            Unassigned Unassigned
            bluhm Stefan Bluhm
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated: