Uploaded image for project: 'Red Hat build of Keycloak'
  1. Red Hat build of Keycloak
  2. RHBK-3921

Unexpected FORMAT_FAILURE error when using cache-config-file with feature-disabled=persistent-user-sessions [GHI#44229]

XMLWordPrintable

    • False
    • Hide

      None

      Show
      None
    • False

      Before reporting an issue

      [x] 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-dev
      

      A 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:

      https://github.com/keycloak/keycloak/blob/f96765c4b49fd6a6ae392054def7ccd61e59d6fa/model/infinispan/src/main/java/org/keycloak/spi/infinispan/impl/embedded/CacheConfigurator.java#L290

      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 168d9cc09053c1c974023a088752db6dca12438d.

              Unassigned Unassigned
              pvlha Pavel Vlha
              Keycloak SRE
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Created:
                Updated:
                Resolved: