Unable to Use IAM Authentication (PostgreSQL)

thomascjohnson commented 2 years ago

Bug Description

I'm trying to connect a Keycloak instance in a container to a Cloud SQL instance via the Cloud SQL proxy running on the host on 5432. Things work when I provide the username and password for an account on the database, but not when I try to use IAM authentication. Hopefully you can spot an error I'm making! :)

Example code (or command)

Cloud SQL Proxy on Host

cloud_sql_proxy -instances=$CLOUD_SQL_INSTANCE_ID=tcp:5432

Dockerfile

(this is just a simplified test case to allow me to ensure I've got the JDBC connection setup correctly, so excuse the lack of proper certificates, inelegant Dockerfile, etc.)

FROM quay.io/keycloak/keycloak:latest as builder

ENV KC_METRICS_ENABLED=true
ENV KC_DB_KIND=other
ENV KC_DB_DIALECT=org.hibernate.dialect.PostgreSQL10Dialect
ENV KC_DB_DRIVER=org.postgresql.Driver
COPY postgres-socket-factory-1.5.0-jar-with-dependencies.jar /opt/keycloak/providers/

RUN /opt/keycloak/bin/kc.sh build --transaction-xa-enabled=false

FROM quay.io/keycloak/keycloak:latest

ENV KC_METRICS_ENABLED=true
ENV KC_DB_KIND=other
ENV KC_DB_DIALECT=org.hibernate.dialect.PostgreSQL10Dialect
ENV KC_DB_DRIVER=org.postgresql.Driver
COPY postgres-socket-factory-1.5.0-jar-with-dependencies.jar /opt/keycloak/providers/

COPY --from=builder /opt/keycloak/lib/quarkus/ /opt/keycloak/lib/quarkus/
WORKDIR /opt/keycloak
RUN keytool -genkeypair -storepass password -storetype PKCS12 -keyalg RSA -keysize 2048 -dname "CN=server" -alias server -ext "SAN:c=DNS:localhost,IP:127.0.0.1" -keystore conf/server.keystore

Docker build

docker build -t keycloak_jdbc_cloudsql_tcp .

Docker run

export JDBC_CLOUD_SQL_DB_URL="jdbc:postgresql://host.docker.internal/$CLOUD_SQL_DATABASE?enableIamAuth=true&user=$CLOUD_SQL_IAM_USER&cloudSqlInstance=$CLOUD_SQL_INSTANCE_ID&socketFactory=com.google.cloud.sql.postgres.SocketFactory"
docker run \
  --rm \                                                          
  --name keycloak \
  -p 8443:8443 \
  -e GOOGLE_APPLICATION_CREDENTIALS=/creds.json \
  -v $GOOGLE_APP_CREDS_JSON_PATH:/creds.json \
  -e KC_DB_URL=$JDBC_CLOUD_SQL_DB_URL \                                                          
  keycloak_jdbc_cloudsql_tcp \
  start \ 
  --https-key-store-file=/opt/keycloak/conf/server.keystore \
  --https-key-store-password=password \
  --hostname=localhost

As far as I can tell, adding the password property as password=password (as shown here) makes no difference

Stacktrace

➜ docker run \
  --rm \                                                          
  --name keycloak \
  -p 8443:8443 \
  -e GOOGLE_APPLICATION_CREDENTIALS=/creds.json \
  -v $GOOGLE_APP_CREDS_JSON_PATH:/creds.json \
  -e KC_DB_URL=$JDBC_CLOUD_SQL_DB_URL \                                                
  keycloak_jdbc_cloudsql_tcp \
  start \ 
  --https-key-store-file=/opt/keycloak/conf/server.keystore \
  --https-key-store-password=password \
  --hostname=localhost
2022-04-20 22:09:42,515 INFO  [org.keycloak.quarkus.runtime.hostname.DefaultHostnameProvider] (main) Hostname settings: FrontEnd: localhost, Strict HTTPS: true, Path: <request>, Strict BackChannel: false, Admin: <request>, Port: -1, Proxied: false
2022-04-20 22:09:43,198 INFO  [com.google.cloud.sql.core.CoreSocketFactory] (agroal-11) Connecting to Cloud SQL instance [$CLOUD_SQL_INSTANCE_ID] via SSL socket.
2022-04-20 22:09:43,199 INFO  [com.google.cloud.sql.core.CoreSocketFactory] (agroal-11) First Cloud SQL connection, generating RSA key pair.
2022-04-20 22:09:45,714 WARN  [org.infinispan.PERSISTENCE] (keycloak-cache-init) ISPN000554: jboss-marshalling is deprecated and planned for removal
2022-04-20 22:09:45,803 WARN  [org.infinispan.CONFIG] (keycloak-cache-init) ISPN000569: Unable to persist Infinispan internal caches as no global state enabled
2022-04-20 22:09:45,845 INFO  [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2022-04-20 22:09:46,379 INFO  [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000128: Infinispan version: Infinispan 'Triskaidekaphobia' 13.0.6.Final
2022-04-20 22:09:46,705 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000078: Starting JGroups channel `ISPN`
2022-04-20 22:09:46,707 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000088: Unable to use any JGroups configuration mechanisms provided in properties {}. Using default JGroups configuration!
2022-04-20 22:09:46,848 WARN  [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the send buffer of socket MulticastSocket was set to 1.00MB, but the OS only allocated 212.99KB
2022-04-20 22:09:46,856 WARN  [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the receive buffer of socket MulticastSocket was set to 20.00MB, but the OS only allocated 212.99KB
2022-04-20 22:09:46,857 WARN  [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the send buffer of socket MulticastSocket was set to 1.00MB, but the OS only allocated 212.99KB
2022-04-20 22:09:46,858 WARN  [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the receive buffer of socket MulticastSocket was set to 25.00MB, but the OS only allocated 212.99KB
2022-04-20 22:09:48,926 INFO  [org.jgroups.protocols.pbcast.GMS] (keycloak-cache-init) d4717e764d4a-4405: no members discovered after 2012 ms: creating cluster as coordinator
2022-04-20 22:09:48,953 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000094: Received new cluster view for channel ISPN: [d4717e764d4a-4405|0] (1) [d4717e764d4a-4405]
2022-04-20 22:09:48,966 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000079: Channel `ISPN` local address is `d4717e764d4a-4405`, physical addresses are `[172.17.0.2:38079]`
2022-04-20 22:09:51,792 INFO  [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: d4717e764d4a-4405, Site name: null
2022-04-20 22:09:52,309 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:09:56,155 INFO  [com.google.cloud.sql.core.CoreSocketFactory] (agroal-11) Connecting to Cloud SQL instance [$CLOUD_SQL_INSTANCE_ID] via SSL socket.
2022-04-20 22:09:57,376 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:09:58,777 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:09:59,142 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:00,290 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:00,405 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:01,753 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:01,867 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:03,441 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:03,567 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:05,148 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:05,263 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:06,725 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:06,842 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:07,725 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:08,000 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:08,979 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:09,095 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:11,165 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:11,305 WARN  [liquibase.database.DatabaseFactory] (main) Unknown database: PostgreSQL
2022-04-20 22:10:14,466 WARN  [org.keycloak.connections.jpa.updater.liquibase.lock.CustomLockService] (main) Failed to create lock table. Maybe other transaction created in the meantime. Retrying...
2022-04-20 22:10:14,686 INFO  [org.infinispan.CLUSTER] (main) ISPN000080: Disconnecting JGroups channel `ISPN`
2022-04-20 22:10:14,825 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: Failed to start server in (production) mode
2022-04-20 22:10:14,828 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: liquibase.exception.DatabaseException: ERROR: current transaction is aborted, commands ignored until end of transaction block [Failed SQL: (0) CREATE TABLE DATABASECHANGELOGLOCK (ID INT NOT NULL, "LOCKED" BOOLEAN NOT NULL, LOCKGRANTED datetime, LOCKEDBY VARCHAR(255), CONSTRAINT PK_DATABASECHANGELOGLOCK PRIMARY KEY (ID))]
2022-04-20 22:10:14,829 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: ERROR: current transaction is aborted, commands ignored until end of transaction block [Failed SQL: (0) CREATE TABLE DATABASECHANGELOGLOCK (ID INT NOT NULL, "LOCKED" BOOLEAN NOT NULL, LOCKGRANTED datetime, LOCKEDBY VARCHAR(255), CONSTRAINT PK_DATABASECHANGELOGLOCK PRIMARY KEY (ID))]
2022-04-20 22:10:14,829 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: ERROR: current transaction is aborted, commands ignored until end of transaction block
2022-04-20 22:10:14,832 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: ERROR: syntax error at end of input
  Position: 20
2022-04-20 22:10:14,832 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) For more details run the same command passing the '--verbose' option. Also you can use '--help' to see the details about the usage of the particular command.

While this is going on, there is no sign of an actual connection with the Cloud SQL Proxy. As I said above, the connection works when I specify a user and password for a non-IAM user on the instance, regardless of whether I have enableIamAuth set to true or false. I also see no change as a result of setting sslmode=disable.

I am also unsure of whether the unixSocketPath will work – I'm having trouble getting a database socket mapped as a volume to work at all with docker, even in simpler cases. Here's a question I wrote on stackoverflow regarding that.

How to reproduce

If the above details aren't enough to get this going, let me know and I can provide any other instructions.

Environment

OS type and version: Mac OS 10.15.4 on host, in container:


sh-4.4$ cat /etc/os-release 
NAME="Red Hat Enterprise Linux"
VERSION="8.5 (Ootpa)"
ID="rhel"
ID_LIKE="fedora"
VERSION_ID="8.5"
PLATFORM_ID="platform:el8"
PRETTY_NAME="Red Hat Enterprise Linux 8.5 (Ootpa)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:redhat:enterprise_linux:8::baseos"
HOME_URL="https://www.redhat.com/"
DOCUMENTATION_URL="https://access.redhat.com/documentation/red_hat_enterprise_linux/8/"
BUG_REPORT_URL="https://bugzilla.redhat.com/"

REDHAT_BUGZILLA_PRODUCT="Red Hat Enterprise Linux 8" REDHAT_BUGZILLA_PRODUCT_VERSION=8.5 REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux" REDHAT_SUPPORT_PRODUCT_VERSION="8.5"

3. Java SDK version: `java -version` (in container)

sh-4.4$ java -version openjdk version "11.0.14.1" 2022-02-08 LTS OpenJDK Runtime Environment 18.9 (build 11.0.14.1+1-LTS) OpenJDK 64-Bit Server VM 18.9 (build 11.0.14.1+1-LTS, mixed mode, sharing)


2. Socket Factory version: 1.5.0

thomascjohnson commented 2 years ago

As a follow up, I was able to successfully use the built-in postgres DB type (see here) with the service account as the name and an access token generated via

gcloud auth print-access-token --impersonate-service-account=$SERVICE_ACCOUNT

However, providing the same username and password via the Cloud SQL JDBC Socket Factory did not work. The error message is the same as above.

I've also tried using these instructions to no avail. Any ideas?

kurtisvg commented 2 years ago

So I can't speak for KeyCloak, but one issue with your setup is that you should use either the Cloud SQL Java connector or the Cloud SQL auth proxy - using both is redundant (which is why you aren't seeing any connections to the proxy).

If you use the Java connector, you don't need to run the proxy. I don't see anything wrong with your JDBC url, so my guess is that Keycloak isn't correctly picking up or using the socket factory (based on the logs not showing any initialization for it).

If you use the proxy, you don't need the java connector. But you will need to add the -enable-iam-login flag to enable it to use IAM DB AuthN. Then you can connect to the proxy just like it's a database without the java-connector.

thomascjohnson commented 2 years ago

Kurtis, thank you for your reply! I thought that might be the case, but I was led astray by this line in the root README:

It can not provide a network path to a Cloud SQL instance if one is not already present.

I realize that actually refers to the public Ip/private IP with VPC access, now 🤦‍♂️.

This helps me reduce my uncertainty, so thanks a lot!

GoogleCloudPlatform / cloud-sql-jdbc-socket-factory