Unexpected FORMAT_FAILURE error when using cache-config-file with feature-disabled=persistent-user-sessions #44229
Description
Before reporting an issue
- I have read and understood the above terms for submitting issues, and I understand that my issue may be closed without action if I do not follow them.
Area
infinispan
Describe the bug
I am encountering an unexpected error when disabling persistent-user-sessions with a pre-existing cache-ispn.xml:
LogManager error of type FORMAT_FAILURE: Formatting error java.util.IllegalFormatConversionException: d != java.lang.String
Version
26.4
Regression
- The issue is a regression
Expected behavior
Keycloak logs what it's doing:
Offline sessions should have a max count set to avoid excessive memory usage. Setting a default cache limit of 10000 for cache offlineSessions.
Then it either bails out or works without the cache.
Actual behavior
Keycloak throws the following exception that seems to stem from the logger.infof call:
LogManager error of type FORMAT_FAILURE: Formatting error
java.util.IllegalFormatConversionException: d != java.lang.String
at org.jboss.logmanager.formatters.Printf.checkType(Printf.java:1091)
at org.jboss.logmanager.formatters.Printf.formatDirect(Printf.java:522)
at org.jboss.logmanager.formatters.ColorPrintf.formatDirect(ColorPrintf.java:43)
at org.jboss.logmanager.formatters.Printf.format(Printf.java:95)
at org.jboss.logmanager.formatters.ColorPatternFormatter.formatMessage(ColorPatternFormatter.java:131)
at org.jboss.logmanager.formatters.Formatters$16.renderRaw(Formatters.java:832)
at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:227)
at org.jboss.logmanager.formatters.ColorPatternFormatter$ColorStep.render(ColorPatternFormatter.java:152)
at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:90)
at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:58)
at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:54)
at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:88)
at org.jboss.logmanager.ExtHandler.publishToNestedHandlers(ExtHandler.java:125)
at io.quarkus.bootstrap.logging.QuarkusDelayedHandler.doPublish(QuarkusDelayedHandler.java:81)
at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:88)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:437)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:479)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:479)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:479)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:479)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:479)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:479)
at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:479)
at org.jboss.logmanager.Logger.logRaw(Logger.java:921)
at org.jboss.logmanager.Logger.log(Logger.java:884)
at org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:56)
at org.jboss.logging.Logger.infof(Logger.java:1151)
at org.keycloak.spi.infinispan.impl.embedded.CacheConfigurator.configureSessionsCachesForVolatileSessions(CacheConfigurator.java:289)
at org.keycloak.spi.infinispan.impl.embedded.DefaultCacheEmbeddedConfigProviderFactory.configureSingleSiteWithVolatileSessions(DefaultCacheEmbeddedConfigProviderFactory.java:175)
at org.keycloak.spi.infinispan.impl.embedded.DefaultCacheEmbeddedConfigProviderFactory.createConfiguration(DefaultCacheEmbeddedConfigProviderFactory.java:170)
at org.keycloak.spi.infinispan.impl.embedded.DefaultCacheEmbeddedConfigProviderFactory.lazyInit(DefaultCacheEmbeddedConfigProviderFactory.java:155)
at org.keycloak.spi.infinispan.impl.embedded.DefaultCacheEmbeddedConfigProviderFactory.create(DefaultCacheEmbeddedConfigProviderFactory.java:93)
at org.keycloak.spi.infinispan.impl.embedded.DefaultCacheEmbeddedConfigProviderFactory.create(DefaultCacheEmbeddedConfigProviderFactory.java:71)
at org.keycloak.services.DefaultKeycloakSession.getOrCreateProvider(DefaultKeycloakSession.java:183)
at org.keycloak.services.DefaultKeycloakSession.getProvider(DefaultKeycloakSession.java:172)
at org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory.createEmbeddedCacheManager(DefaultInfinispanConnectionProviderFactory.java:185)
at org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory.lazyInit(DefaultInfinispanConnectionProviderFactory.java:169)
at org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory.create(DefaultInfinispanConnectionProviderFactory.java:101)
at org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory.create(DefaultInfinispanConnectionProviderFactory.java:87)
at org.keycloak.services.DefaultKeycloakSession.getOrCreateProvider(DefaultKeycloakSession.java:183)
at org.keycloak.services.DefaultKeycloakSession.getProvider(DefaultKeycloakSession.java:172)
at org.keycloak.models.cache.infinispan.InfinispanCacheRealmProviderFactory.lazyInit(InfinispanCacheRealmProviderFactory.java:55)
at org.keycloak.models.cache.infinispan.InfinispanCacheRealmProviderFactory.create(InfinispanCacheRealmProviderFactory.java:47)
at org.keycloak.models.cache.infinispan.InfinispanCacheRealmProviderFactory.create(InfinispanCacheRealmProviderFactory.java:37)
at org.keycloak.services.DefaultKeycloakSession.getOrCreateProvider(DefaultKeycloakSession.java:183)
at org.keycloak.services.DefaultKeycloakSession.getProvider(DefaultKeycloakSession.java:172)
at org.keycloak.storage.datastore.DefaultDatastoreProvider.getRealmProvider(DefaultDatastoreProvider.java:156)
at org.keycloak.storage.datastore.DefaultDatastoreProvider.realms(DefaultDatastoreProvider.java:234)
at org.keycloak.services.DefaultKeycloakSession.realms(DefaultKeycloakSession.java:257)
at org.keycloak.migration.migrators.MigrateTo1_2_0.migrate(MigrateTo1_2_0.java:69)
at org.keycloak.storage.datastore.DefaultMigrationManager.migrate(DefaultMigrationManager.java:165)
at org.keycloak.migration.MigrationModelManager.migrate(MigrationModelManager.java:33)
at org.keycloak.quarkus.runtime.storage.database.jpa.QuarkusJpaConnectionProviderFactory.migrateModel(QuarkusJpaConnectionProviderFactory.java:205)
at org.keycloak.quarkus.runtime.storage.database.jpa.QuarkusJpaConnectionProviderFactory.initSchema(QuarkusJpaConnectionProviderFactory.java:196)
at org.keycloak.models.utils.KeycloakModelUtils.lambda$runJobInTransaction$1(KeycloakModelUtils.java:347)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithResult(KeycloakModelUtils.java:461)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:346)
at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:336)
at org.keycloak.quarkus.runtime.storage.database.jpa.QuarkusJpaConnectionProviderFactory.postInit(QuarkusJpaConnectionProviderFactory.java:129)
at org.keycloak.services.DefaultKeycloakSessionFactory.initializeProviders(DefaultKeycloakSessionFactory.java:167)
at org.keycloak.services.DefaultKeycloakSessionFactory.initProviderFactories(DefaultKeycloakSessionFactory.java:141)
at org.keycloak.services.DefaultKeycloakSessionFactory.initProviderFactories(DefaultKeycloakSessionFactory.java:125)
at org.keycloak.quarkus.runtime.integration.QuarkusKeycloakSessionFactory.init(QuarkusKeycloakSessionFactory.java:87)
at org.keycloak.quarkus.runtime.integration.jaxrs.QuarkusKeycloakApplication.createSessionFactory(QuarkusKeycloakApplication.java:60)
at org.keycloak.services.resources.KeycloakApplication.startup(KeycloakApplication.java:75)
at org.keycloak.quarkus.runtime.integration.jaxrs.QuarkusKeycloakApplication.onStartupEvent(QuarkusKeycloakApplication.java:50)
at org.keycloak.quarkus.runtime.integration.jaxrs.QuarkusKeycloakApplication_Observer_onStartupEvent_VUhusbW4xizn9A5dimKJUcfvjHs.notify(Unknown Source)
at io.quarkus.arc.impl.EventImpl$Notifier.notifyObservers(EventImpl.java:365)
at io.quarkus.arc.impl.EventImpl$Notifier.notify(EventImpl.java:347)
at io.quarkus.arc.impl.EventImpl.fire(EventImpl.java:81)
at io.quarkus.arc.runtime.ArcRecorder.fireLifecycleEvent(ArcRecorder.java:163)
at io.quarkus.arc.runtime.ArcRecorder.handleLifecycleEvents(ArcRecorder.java:114)
at io.quarkus.runner.recorded.LifecycleEventsBuildStep$startupEvent1144526294.deploy_0(Unknown Source)
at io.quarkus.runner.recorded.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:119)
at io.quarkus.runtime.Quarkus.run(Quarkus.java:80)
at org.keycloak.quarkus.runtime.KeycloakMain.start(KeycloakMain.java:129)
at org.keycloak.quarkus.runtime.cli.Picocli.start(Picocli.java:931)
at org.keycloak.quarkus.runtime.cli.command.AbstractAutoBuildCommand.runCommand(AbstractAutoBuildCommand.java:142)
at org.keycloak.quarkus.runtime.cli.command.AbstractCommand.lambda$call$1(AbstractCommand.java:69)
at java.base/java.util.Optional.orElseGet(Optional.java:364)
at org.keycloak.quarkus.runtime.cli.command.AbstractCommand.call(AbstractCommand.java:68)
at org.keycloak.quarkus.runtime.cli.command.AbstractCommand.call(AbstractCommand.java:37)
at picocli.CommandLine.executeUserObject(CommandLine.java:2031)
at picocli.CommandLine.access$1500(CommandLine.java:148)
at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2469)
at picocli.CommandLine$RunLast.handle(CommandLine.java:2461)
at picocli.CommandLine$RunLast.handle(CommandLine.java:2423)
at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2277)
at picocli.CommandLine$RunLast.execute(CommandLine.java:2425)
at picocli.CommandLine.execute(CommandLine.java:2174)
at org.keycloak.quarkus.runtime.cli.Picocli.parseAndRun(Picocli.java:180)
at org.keycloak.quarkus.runtime.KeycloakMain.main(KeycloakMain.java:104)
at org.keycloak.quarkus.runtime.KeycloakMain.main(KeycloakMain.java:81)
at io.quarkus.bootstrap.runner.QuarkusEntryPoint.doRun(QuarkusEntryPoint.java:69)
at io.quarkus.bootstrap.runner.QuarkusEntryPoint.main(QuarkusEntryPoint.java:37)
How to Reproduce?
I am using the following command to run the latest nightly:
podman run --rm -ti \
-v ./cache-ispn.xml:/opt/keycloak/conf/cache-ispn.xml:Z \
-e 'KC_FEATURES_DISABLED=persistent-user-sessions' \
-e 'KC_CACHE_CONFIG_FILE=cache-ispn.xml' \
keycloak/keycloak:nightly@sha256:7668e5b6bc3e90ea134980ef698b77e62033d4b0e535f10d8dc3562dbfafe5c2 \
start-devA simplified version of cache-ispn.xml look like so:
<?xml version="1.0" encoding="UTF-8"?>
<infinispan
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="urn:infinispan:config:15.0 http://www.infinispan.org/schemas/infinispan-config-15.0.xsd"
xmlns="urn:infinispan:config:15.0">
<cache-container name="keycloak">
<transport lock-timeout="60000" stack="udp"/>
<distributed-cache name="sessions" owners="2">
<expiration lifespan="-1"/>
</distributed-cache>
<distributed-cache name="offlineSessions" owners="2">
<expiration lifespan="-1"/>
</distributed-cache>
</cache-container>
</infinispan>Anything else?
The logging statement that throws the error from my logs is here:
I'm aware that my configuration is most likely very invalid and needs fixing, this issue is to report that Keycloak should log this properly instead of dumping a stack trace when it tries to write a log entry.
The error seems to have been introduced with 168d9cc.