Running a keycloak container (21.0 - 21.1.1) on a Debian 11 Bullseye recently stopped working after host restart (MariaDB didn't start up, leading to keycloak also exiting. When the issue was noticed we started mariadb with --restart=always):
Most relevant seems to be this except from the Stacktrace:
2023-06-30 11:51:12,749 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) Error details:: java.lang.IllegalArgumentException: Negative delay.
at java.base/java.util.Timer.schedule(Timer.java:257)
...
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at org.hibernate.query.spi.StreamDecorator.forEach(StreamDecorator.java:153)
at org.keycloak.utils.ClosingStream.forEach(ClosingStream.java:128)
at org.keycloak.storage.managers.UserStorageSyncManager$1.run(UserStorageSyncManager.java:64)
at org.keycloak.models.utils.KeycloakModelUtils.lambda$runJobInTransaction$1(KeycloakModelUtils.java:256)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithResult(KeycloakModelUtils.java:269)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:255)
at org.keycloak.storage.managers.UserStorageSyncManager.bootstrapPeriodic(UserStorageSyncManager.java:59)
at org.keycloak.storage.datastore.LegacyDatastoreProviderFactory.setupScheduledTasks(LegacyDatastoreProviderFactory.java:108)
at org.keycloak.storage.datastore.LegacyDatastoreProviderFactory.onEvent(LegacyDatastoreProviderFactory.java:88)
at org.keycloak.services.DefaultKeycloakSessionFactory.publish(DefaultKeycloakSessionFactory.java:91)
at org.keycloak.services.resources.KeycloakApplication.startup(KeycloakApplication.java:164)
at org.keycloak.quarkus.runtime.integration.QuarkusLifecycleObserver.onStartupEvent(QuarkusLifecycleObserver.java:37)
at org.keycloak.quarkus.runtime.integration.QuarkusLifecycleObserver_Observer_onStartupEvent_b0e82415b143738dc1f986a5fa4668e83d0a5dea.notify(Unknown Source)
Full Log:
user@VM-LIN:~$ sudo docker ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
b16748ab4688 quay.io/keycloak/keycloak "/opt/keycloak/bin/k…" 2 hours ago Exited (1) 2 hours ago keycloak
e18eab3e8ed0 LOCALPROXY/mariadb:latest "docker-entrypoint.s…" 3 hours ago Up 3 hours 3306/tcp rdb
user@VM-LIN:~$ sudo docker run --rm -it quay.io/keycloak/keycloak --version
Changes detected in configuration. Updating the server image.
Keycloak 21.1.1
JVM: 17.0.7 (Red Hat, Inc. OpenJDK 64-Bit Server VM 17.0.7+7-LTS)
OS: Linux 5.10.0-21-amd64 amd64
Next time you run the server, just run:
kc.sh start --optimized
Keycloak 21.1.1
JVM: 17.0.7 (Red Hat, Inc. OpenJDK 64-Bit Server VM 17.0.7+7-LTS)
OS: Linux 5.10.0-21-amd64 amd64
user@VM-LIN:~$ sudo docker run --name keycloak --net local -v keycloakCerts:/certs -p 8443:8443 -it quay.io/keycloak/keycloak --verbose start --hostname 10.49.72.187 --features=token-exchange --db=mariadb --db-url=jdbc:mariadb://rdb:3306/keycloak --db-username=keycloak --db-password=$(cat ./rdb-keycloak.secret) --https-certificate-file=/certs/KeyCloak.crt.pem --https-certificate-key-file=/certs/KeyCloak.rsa.key.pem
Changes detected in configuration. Updating the server image.
Updating the configuration and installing your custom providers, if any. Please wait.
2023-06-30 11:50:55,560 INFO [org.keycloak.common.Profile] (main) Preview features enabled: token-exchange
2023-06-30 11:51:03,379 INFO [io.quarkus.deployment.QuarkusAugmentor] (main) Quarkus augmentation completed in 8160ms
Server configuration updated and persisted. Run the following command to review the configuration:
kc.sh show-config
Next time you run the server, just run:
kc.sh start --optimized --hostname=10.49.72.187 --db-url=jdbc:mariadb://rdb:3306/keycloak --db-username=keycloak --db-password=******* --https-certificate-file=/certs/KeyCloak.crt.pem --https-certificate-key-file=/certs/KeyCloak.rsa.key.pem
2023-06-30 11:51:05,096 INFO [org.keycloak.common.Profile] (main) Preview features enabled: token-exchange
2023-06-30 11:51:05,669 INFO [org.keycloak.quarkus.runtime.hostname.DefaultHostnameProvider] (main) Hostname settings: Base URL: <unset>, Hostname: 10.49.72.187, Strict HTTPS: true, Path: <request>, Strict BackChannel: false, Admin URL: <unset>, Admin: <request>, Port: -1, Proxied: false
2023-06-30 11:51:07,152 WARN [io.quarkus.agroal.runtime.DataSources] (main) Datasource <default> enables XA but transaction recovery is not enabled. Please enable transaction recovery by setting quarkus.transaction-manager.enable-recovery=true, otherwise data may be lost if the application is terminated abruptly
2023-06-30 11:51:07,981 INFO [org.infinispan.SERVER] (keycloak-cache-init) ISPN005054: Native IOUring transport not available, using NIO instead: io.netty.incubator.channel.uring.IOUring
2023-06-30 11:51:08,065 WARN [org.infinispan.PERSISTENCE] (keycloak-cache-init) ISPN000554: jboss-marshalling is deprecated and planned for removal
2023-06-30 11:51:08,133 WARN [org.infinispan.CONFIG] (keycloak-cache-init) ISPN000569: Unable to persist Infinispan internal caches as no global state enabled
2023-06-30 11:51:08,176 INFO [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener
2023-06-30 11:51:08,185 INFO [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2023-06-30 11:51:08,548 INFO [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000088: Unable to use any JGroups configuration mechanisms provided in properties {}. Using default JGroups configuration!
2023-06-30 11:51:08,645 INFO [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000078: Starting JGroups channel `ISPN`
2023-06-30 11:51:08,650 INFO [org.jgroups.JChannel] (keycloak-cache-init) local_addr: 42fd7dfa-8223-464b-ac87-911f1a858dda, name: b16748ab4688-28782
2023-06-30 11:51:08,656 WARN [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the send buffer of socket MulticastSocket was set to 1MB, but the OS only allocated 212.99KB
2023-06-30 11:51:08,657 WARN [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the receive buffer of socket MulticastSocket was set to 20MB, but the OS only allocated 212.99KB
2023-06-30 11:51:08,657 WARN [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the send buffer of socket MulticastSocket was set to 1MB, but the OS only allocated 212.99KB
2023-06-30 11:51:08,657 WARN [org.jgroups.protocols.UDP] (keycloak-cache-init) JGRP000015: the receive buffer of socket MulticastSocket was set to 25MB, but the OS only allocated 212.99KB
2023-06-30 11:51:08,665 INFO [org.jgroups.protocols.FD_SOCK2] (keycloak-cache-init) server listening on *.33951
2023-06-30 11:51:10,670 INFO [org.jgroups.protocols.pbcast.GMS] (keycloak-cache-init) b16748ab4688-28782: no members discovered after 2002 ms: creating cluster as coordinator
2023-06-30 11:51:10,693 INFO [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000094: Received new cluster view for channel ISPN: [b16748ab4688-28782|0] (1) [b16748ab4688-28782]
2023-06-30 11:51:10,707 INFO [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000079: Channel `ISPN` local address is `b16748ab4688-28782`, physical addresses are `[172.18.0.3:49487]`
2023-06-30 11:51:11,837 INFO [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: b16748ab4688-28782, Site name: null
2023-06-30 11:51:12,529 INFO [org.keycloak.storage.ldap.LDAPIdentityStoreRegistry] (main) Creating new LDAP Store for the LDAP storage provider: 'ldap', LDAP Configuration: {fullSyncPeriod=[2419200], pagination=[false], startTls=[false], connectionPooling=[false], usersDn=[OU=USER,OU=DK_DG,OU=STANDORT,dc=behrww,dc=behringer,dc=net], cachePolicy=[DEFAULT], useKerberosForPasswordAuthentication=[false], importEnabled=[true], enabled=[true], usernameLDAPAttribute=[sAMAccountName], bindDn=[LDAP], changedSyncPeriod=[86400], vendor=[ad], uuidLDAPAttribute=[objectGUID], allowKerberosAuthentication=[false], connectionUrl=[ldap://10.49.74.21:389], syncRegistrations=[false], authType=[simple], connectionTimeout=[30000], debug=[false], searchScope=[2], useTruststoreSpi=[ldapsOnly], usePasswordModifyExtendedOp=[false], trustEmail=[true], userObjectClasses=[person, organizationalPerson, user], rdnLDAPAttribute=[cn], editMode=[READ_ONLY], readTimeout=[30000], validatePasswordPolicy=[false], batchSizeForSync=[50]}, binaryAttributes: []
2023-06-30 11:51:12,681 WARN [io.agroal.pool] (main) Datasource '<default>': JDBC resources leaked: 1 ResultSet(s) and 1 Statement(s)
2023-06-30 11:51:12,706 INFO [org.infinispan.CLUSTER] (main) ISPN000080: Disconnecting JGroups channel `ISPN`
2023-06-30 11:51:12,749 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) ERROR: Failed to start server in (production) mode
2023-06-30 11:51:12,749 ERROR [org.keycloak.quarkus.runtime.cli.ExecutionExceptionHandler] (main) Error details:: java.lang.IllegalArgumentException: Negative delay.
at java.base/java.util.Timer.schedule(Timer.java:257)
at org.keycloak.timer.basic.BasicTimerProvider.schedule(BasicTimerProvider.java:65)
at org.keycloak.storage.managers.UserStorageSyncManager.refreshPeriodicSyncForProvider(UserStorageSyncManager.java:207)
at org.keycloak.storage.managers.UserStorageSyncManager$1.lambda$run$0(UserStorageSyncManager.java:69)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.base/java.util.stream.SortedOps$SizedRefSortingSink.end(SortedOps.java:357)
at java.base/java.util.stream.Sink$ChainedReference.end(Sink.java:258)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:510)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEachOrdered(ReferencePipeline.java:601)
at org.keycloak.storage.managers.UserStorageSyncManager$1.lambda$run$1(UserStorageSyncManager.java:66)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
at java.base/java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1845)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at org.hibernate.query.spi.StreamDecorator.forEach(StreamDecorator.java:153)
at org.keycloak.utils.ClosingStream.forEach(ClosingStream.java:128)
at org.keycloak.storage.managers.UserStorageSyncManager$1.run(UserStorageSyncManager.java:64)
at org.keycloak.models.utils.KeycloakModelUtils.lambda$runJobInTransaction$1(KeycloakModelUtils.java:256)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithResult(KeycloakModelUtils.java:269)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:255)
at org.keycloak.storage.managers.UserStorageSyncManager.bootstrapPeriodic(UserStorageSyncManager.java:59)
at org.keycloak.storage.datastore.LegacyDatastoreProviderFactory.setupScheduledTasks(LegacyDatastoreProviderFactory.java:108)
at org.keycloak.storage.datastore.LegacyDatastoreProviderFactory.onEvent(LegacyDatastoreProviderFactory.java:88)
at org.keycloak.services.DefaultKeycloakSessionFactory.publish(DefaultKeycloakSessionFactory.java:91)
at org.keycloak.services.resources.KeycloakApplication.startup(KeycloakApplication.java:164)
at org.keycloak.quarkus.runtime.integration.QuarkusLifecycleObserver.onStartupEvent(QuarkusLifecycleObserver.java:37)
at org.keycloak.quarkus.runtime.integration.QuarkusLifecycleObserver_Observer_onStartupEvent_b0e82415b143738dc1f986a5fa4668e83d0a5dea.notify(Unknown Source)
at io.quarkus.arc.impl.EventImpl$Notifier.notifyObservers(EventImpl.java:326)
at io.quarkus.arc.impl.EventImpl$Notifier.notify(EventImpl.java:308)
at io.quarkus.arc.impl.EventImpl.fire(EventImpl.java:76)
at io.quarkus.arc.runtime.ArcRecorder.fireLifecycleEvent(ArcRecorder.java:131)
at io.quarkus.arc.runtime.ArcRecorder.handleLifecycleEvents(ArcRecorder.java:100)
at io.quarkus.deployment.steps.LifecycleEventsBuildStep$startupEvent1144526294.deploy_0(Unknown Source)
at io.quarkus.deployment.steps.LifecycleEventsBuildStep$startupEvent1144526294.deploy(Unknown Source)
at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
at io.quarkus.runtime.Application.start(Application.java:101)
at io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:110)
at io.quarkus.runtime.Quarkus.run(Quarkus.java:70)
at org.keycloak.quarkus.runtime.KeycloakMain.start(KeycloakMain.java:98)
at org.keycloak.quarkus.runtime.cli.command.AbstractStartCommand.run(AbstractStartCommand.java:37)
at picocli.CommandLine.executeUserObject(CommandLine.java:1939)
at picocli.CommandLine.access$1300(CommandLine.java:145)
at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2358)
at picocli.CommandLine$RunLast.handle(CommandLine.java:2352)
at picocli.CommandLine$RunLast.handle(CommandLine.java:2314)
at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2179)
at picocli.CommandLine$RunLast.execute(CommandLine.java:2316)
at picocli.CommandLine.execute(CommandLine.java:2078)
at org.keycloak.quarkus.runtime.cli.Picocli.parseAndRun(Picocli.java:94)
at org.keycloak.quarkus.runtime.KeycloakMain.main(KeycloakMain.java:88)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at io.quarkus.bootstrap.runner.QuarkusEntryPoint.doRun(QuarkusEntryPoint.java:61)
at io.quarkus.bootstrap.runner.QuarkusEntryPoint.main(QuarkusEntryPoint.java:32)
user@VM-LIN:~$ sudo docker logs rdb
2023-06-30 10:05:46+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.2+maria~ubu2204 started.
2023-06-30 10:05:46+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2023-06-30 10:05:46+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.2+maria~ubu2204 started.
2023-06-30 10:05:47+00:00 [Note] [Entrypoint]: MariaDB upgrade not required
2023-06-30 10:05:47 0 [Note] Starting MariaDB 10.11.2-MariaDB-1:10.11.2+maria~ubu2204 source revision cafba8761af55ae16cc69c9b53a341340a845b36 as process 1
2023-06-30 10:05:47 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-06-30 10:05:47 0 [Note] InnoDB: Number of transaction pools: 1
2023-06-30 10:05:47 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-06-30 10:05:47 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
2023-06-30 10:05:47 0 [Note] InnoDB: Using liburing
2023-06-30 10:05:47 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
2023-06-30 10:05:47 0 [Note] InnoDB: Completed initialization of buffer pool
2023-06-30 10:05:47 0 [Note] InnoDB: File system buffers for log disabled (block size=512 bytes)
2023-06-30 10:05:47 0 [Note] InnoDB: 128 rollback segments are active.
2023-06-30 10:05:47 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2023-06-30 10:05:47 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2023-06-30 10:05:47 0 [Note] InnoDB: log sequence number 27426101; transaction id 24773
2023-06-30 10:05:47 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2023-06-30 10:05:47 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-06-30 10:05:47 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
2023-06-30 10:05:47 0 [Note] Server socket created on IP: '0.0.0.0'.
2023-06-30 10:05:47 0 [Note] Server socket created on IP: '::'.
2023-06-30 10:05:47 0 [Note] mariadbd: ready for connections.
Version: '10.11.2-MariaDB-1:10.11.2+maria~ubu2204' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
2023-06-30 10:05:48 0 [Note] InnoDB: Buffer pool(s) load completed at 230630 10:05:48
Google didn't yield any results, Similar questions in the Network do not seem to be about this problem. Any Ideas where to start?
