SAML issue

[Reneftec]

Evening,

I'm trying to connect to Azure AD using SAML. I've set everything up but am getting the following error

20:13:58.532 [http-nio-8080-exec-5] WARN  o.a.g.e.AuthenticationProviderFacade - The "saml" 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: saml" within your guacamole.properties.
20:13:58.542 [http-nio-8080-exec-5] ERROR o.a.g.rest.RESTExceptionMapper - An internal error occurred, but did not contain an error message. Enable debug-level logging for details.

I'm not sure where to find further logs or if I'm missing something obvious. A copy of my compose file is below

version: "3"
services:
  guacamole:
    image: abesnier/guacamole
    container_name: guacamole
    volumes:
      - postgres:/config
    ports:
      - 8080:8080
    environment:
      - TZ=Europe/London
      - EXTENSIONS=auth-sso-saml
      - EXTENSION_PRIORITY=*, saml
      - SAML_IDP_METADATA_URL=https://login.microsoftonline.com/xxxxxxxxxxxxxxxxxxx/federationmetadata/2007-06/federationmetadata.xml?appid=xxxxxxxxxxxxxxxxxxxx
      - SAML_IDP_URL=https://login.microsoftonline.com/xxxxxxxxxxxxxxxxxxxxx/saml2
      - SAML_ENTITY_ID=https://you.me.them
      - SAML_CALLBACK_URL=https://you.me.them

      - GUACD_LOG_LEVEL=debug
      - SAML_STRICT=false
      - SAML_DEBUG=true
volumes:
  postgres:
    driver: local

[abesnier]

Hi,

Sorry, I am not very familiar with SAML, but I'll try to assist as much as possible.

My first instinct would be that there are two versions of the saml extension in the extensions directory. If you pulled the image I uploaded a few days ago, make sure to delete all references to version 1.5.3 in the directories extensions and extensions-available.
The container is supposed to clean itself at startup, but I may have missed something.

Can you also post the full version of the log?

I'll also look at the mailing list to see if a similar issue has been reported already.

Cheers

Antoine

[Reneftec]

As requested

`s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service s6rc-fdholder successfully started
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
cont-init: info: running /etc/cont-init.d/30-defaults.sh
cont-init: info: /etc/cont-init.d/30-defaults.sh exited 0
cont-init: info: running /etc/cont-init.d/40-postgres.sh
Database already configured
cont-init: info: /etc/cont-init.d/40-postgres.sh exited 0
cont-init: info: running /etc/cont-init.d/50-extensions.sh
Cleaning Extensions from previous Guacamole versions
Cleaning Extensions
Enabling selected extensions
cont-init: info: /etc/cont-init.d/50-extensions.sh exited 0
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service syslogd-prepare: starting
s6-rc: info: service syslogd-prepare successfully started
s6-rc: info: service syslogd-log: starting
s6-rc: info: service syslogd-log successfully started
s6-rc: info: service syslogd: starting
s6-rc: info: service syslogd successfully started
s6-rc: info: service legacy-services: starting
services-up: info: copying legacy longrun guacamole (no readiness notification)
services-up: info: copying legacy longrun guacd (no readiness notification)
services-up: info: copying legacy longrun postgres (no readiness notification)
s6-rc: info: service legacy-services successfully started
Starting guacamole guacd...
Starting postgres...
/var/run/postgresql:5432 - no response
Waiting for postgres to come up...
guacd[165]: INFO: Guacamole proxy daemon (guacd) version 1.5.4 started
guacd[165]: DEBUG: Successfully bound AF_INET socket to host 0.0.0.0, port 4822
guacd[165]: INFO: Listening on host 0.0.0.0, port 4822
2023-12-12 13:41:04.041 UTC [166] LOG: starting PostgreSQL 13.13 (Ubuntu 13.13-1.pgdg22.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit
2023-12-12 13:41:04.042 UTC [166] LOG: listening on IPv4 address "127.0.0.1", port 5432
2023-12-12 13:41:04.042 UTC [166] LOG: could not bind IPv6 address "::1": Cannot assign requested address
2023-12-12 13:41:04.042 UTC [166] HINT: Is another postmaster already running on port 5432? If not, wait a few seconds and retry.
2023-12-12 13:41:04.045 UTC [166] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-12-12 13:41:04.056 UTC [168] LOG: database system was shut down at 2023-12-12 13:40:59 UTC
2023-12-12 13:41:04.075 UTC [166] LOG: database system is ready to accept connections
2023-12-12 13:41:04.984 UTC [176] FATAL: role "root" does not exist
/var/run/postgresql:5432 - accepting connections
Starting guacamole client...
NOTE: Picked up JDK_JAVA_OPTIONS: --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
12-Dec-2023 13:41:05.728 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name: Apache Tomcat/9.0.83
12-Dec-2023 13:41:05.740 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Nov 9 2023 20:57:42 UTC
12-Dec-2023 13:41:05.741 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.83.0
12-Dec-2023 13:41:05.742 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: Linux
12-Dec-2023 13:41:05.742 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 5.15.0-89-generic
12-Dec-2023 13:41:05.743 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64
12-Dec-2023 13:41:05.744 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: /opt/java/openjdk
12-Dec-2023 13:41:05.744 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 11.0.21+9
12-Dec-2023 13:41:05.745 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: Eclipse Adoptium
12-Dec-2023 13:41:05.745 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: /usr/local/tomcat
12-Dec-2023 13:41:05.746 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: /usr/local/tomcat
12-Dec-2023 13:41:05.776 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
12-Dec-2023 13:41:05.776 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
12-Dec-2023 13:41:05.777 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util=ALL-UNNAMED
12-Dec-2023 13:41:05.778 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util.concurrent=ALL-UNNAMED
12-Dec-2023 13:41:05.779 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
12-Dec-2023 13:41:05.779 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties
12-Dec-2023 13:41:05.780 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
12-Dec-2023 13:41:05.781 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
12-Dec-2023 13:41:05.781 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
12-Dec-2023 13:41:05.782 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
12-Dec-2023 13:41:05.783 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
12-Dec-2023 13:41:05.783 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
12-Dec-2023 13:41:05.784 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
12-Dec-2023 13:41:05.784 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
12-Dec-2023 13:41:05.795 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.39] using APR version [1.7.0].
12-Dec-2023 13:41:05.795 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true], UDS [true].
12-Dec-2023 13:41:05.796 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
12-Dec-2023 13:41:05.807 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 3.0.2 15 Mar 2022]
12-Dec-2023 13:41:06.333 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
12-Dec-2023 13:41:06.366 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [924] milliseconds
12-Dec-2023 13:41:06.438 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
12-Dec-2023 13:41:06.438 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.83]
12-Dec-2023 13:41:06.460 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/usr/local/tomcat/webapps/ROOT.war]
12-Dec-2023 13:41:08.952 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
13:41:09.662 [main] INFO o.a.g.environment.LocalEnvironment - GUACAMOLE_HOME is "/config/guacamole".
13:41:09.812 [main] INFO o.a.g.GuacamoleServletContextListener - Read configuration parameters from "/config/guacamole/guacamole.properties".
13:41:09.814 [main] INFO o.a.g.rest.auth.HashTokenSessionMap - Sessions will expire after 60 minutes of inactivity.
13:41:10.374 [main] INFO o.a.g.extension.ExtensionModule - Multiple extensions are installed and will be loaded in order of decreasing priority:
13:41:10.374 [main] INFO o.a.g.extension.ExtensionModule - - [postgresql] "PostgreSQL Authentication" (/config/guacamole/extensions/guacamole-auth-jdbc-postgresql-1.5.4.jar)
13:41:10.375 [main] INFO o.a.g.extension.ExtensionModule - - [saml] "SAML Authentication Extension" (/config/guacamole/extensions/guacamole-auth-sso-saml-1.5.4.jar)
13:41:10.375 [main] INFO o.a.g.extension.ExtensionModule - To change this order, set the "extension-priority" property or rename the extension files. The default priority of extensions is dictated by the sort order of their filenames.
13:41:11.370 [main] INFO o.a.g.extension.ExtensionModule - Extension "PostgreSQL Authentication" (postgresql) loaded.
13:41:11.571 [main] INFO o.a.g.extension.ExtensionModule - Extension "SAML Authentication Extension" (saml) loaded.
13:41:11.728 [main] INFO o.a.g.t.w.WebSocketTunnelModule - Loading JSR-356 WebSocket support...
13:41:12.625 [main] WARN o.g.jersey.server.wadl.WadlFeature - JAXBContext implementation could not be found. WADL feature is disabled.
12-Dec-2023 13:41:13.011 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/usr/local/tomcat/webapps/ROOT.war] has finished in [6,551] ms
12-Dec-2023 13:41:13.014 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
12-Dec-2023 13:41:13.044 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [6677] milliseconds
13:41:13.593 [http-nio-8080-exec-2] WARN o.a.g.e.AuthenticationProviderFacade - The "saml" 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: saml" within your guacamole.properties.
13:41:13.593 [http-nio-8080-exec-1] WARN o.a.g.e.AuthenticationProviderFacade - The "saml" 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: saml" within your guacamole.properties.
13:41:13.599 [http-nio-8080-exec-1] ERROR o.a.g.rest.RESTExceptionMapper - An internal error occurred, but did not contain an error message. Enable debug-level logging for details.
13:41:13.599 [http-nio-8080-exec-2] ERROR o.a.g.rest.RESTExceptionMapper - An internal error occurred, but did not contain an error message. Enable debug-level logging for details.
13:41:14.685 [http-nio-8080-exec-8] WARN o.a.g.e.AuthenticationProviderFacade - The "saml" 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: saml" within your guacamole.properties.
13:41:14.686 [http-nio-8080-exec-8] ERROR o.a.g.rest.RESTExceptionMapper - An internal error occurred, but did not contain an error message. Enable debug-level logging for details.

`

[abesnier]

So it's not an issue of duplicate extensions... On one side, it's good, it means my cleanup routine works, on the other hand, that does not solve your issue...

You could try to move the saml configuration into your guacamole.properties. Passing parameters as environment variables is not trivial, and needs to be coded variable by variable.

EDIT: I confirm that moving the SAML configuration to guacamole.properties makes progress. The exception is not raised anymore, but I cannot go further as I cannot use your URLs. But I confirm this is a way to try.

For info, it takes more than 1200 lines of code for the official Guacamole image to deal with environment variable. I know this is something I should do, but I don't know when I would find the time to do this...