OpenLiberty / ci.docker

Eclipse Public License 1.0
42 stars 59 forks source link

NPE in CacheConfigUtil.java when perform checkpoint app with infinispan client-server mode #547

Open tam512 opened 1 month ago

tam512 commented 1 month ago

Perform InstantOn checkpoint on QuickSec app with <feature>sessionCache-1.0</feature>and I got the following errors:

podman build -t qs10:wl-full-java17-x86 --cap-add=CHECKPOINT_RESTORE --cap-add=SYS_PTRACE --cap-add=SETPCAP --security-opt seccomp=unconfined -f Containerfile --no-cache --volume /opt/liberty-mavenartf:/opt/libertyrepo .
............
......................
[2/2] STEP 25/25: RUN checkpoint.sh afterAppStart
Performing checkpoint --at=afterAppStart
.............
...................
[WARNING ] CWLJC0011W: Error encountered while retrieving the AuthCache JCache. Will attempt to create it instead. The error was: java.lang.IllegalArgumentException: CWLJC0007E: Invalid syntax in cacheManager URI.  Cause is java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null.
        at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:216)
        at [internal classes]
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null
        at io.openliberty.jcache.utils.CacheConfigUtil.preConfigureCacheManager(CacheConfigUtil.java:112)
        ... 1 more
.
[WARNING ] CWLJC0011W: Error encountered while retrieving the AuthCache JCache. Will attempt to create it instead. The error was: java.lang.IllegalArgumentException: CWLJC0007E: Invalid syntax in cacheManager URI.  Cause is java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null.
        at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:216)
        at [internal classes]
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null
        at io.openliberty.jcache.utils.CacheConfigUtil.preConfigureCacheManager(CacheConfigUtil.java:112)
        ... 1 more
.
[WARNING ] CWLJC0011W: Error encountered while retrieving the AuthCache JCache. Will attempt to create it instead. The error was: java.lang.IllegalArgumentException: CWLJC0007E: Invalid syntax in cacheManager URI.  Cause is java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null.
        at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:216)
        at [internal classes]
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null
        at io.openliberty.jcache.utils.CacheConfigUtil.preConfigureCacheManager(CacheConfigUtil.java:112)
        ... 1 more
.
[WARNING ] CWLJC0011W: Error encountered while retrieving the AuthCache JCache. Will attempt to create it instead. The error was: java.lang.IllegalArgumentException: CWLJC0007E: Invalid syntax in cacheManager URI.  Cause is java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null.
        at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:216)
        at [internal classes]
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null
        at io.openliberty.jcache.utils.CacheConfigUtil.preConfigureCacheManager(CacheConfigUtil.java:112)
        ... 1 more
.
[AUDIT   ] CWWKZ0001I: Application QuickSec started in 32.790 seconds.
[ERROR   ] CWWKC0453E: The server checkpoint request failed with the following message: CWWKC0456E: A checkpoint cannot be taken because the following features configured in the server.xml file are not supported for checkpoint: [appClientSupport-2.0, batch-2.0, jakartaee-9.1, connectorsInboundSecurity-2.0, messagingSecurity-3.0, appAuthorization-2.0]
tam512 commented 1 month ago

This is being discussed in InstantOn slack channel https://ibm-cloud.slack.com/archives/C03MR7EC3NG/p1717187662402679?thread_ts=1717187652.885869&cid=C03MR7EC3NG

dazavala commented 4 weeks ago

Thank you @tam512 for acquiring the server logs. Here's what @anjumfatima90 and I have determined thus far. Fyi @tjwatson.

The causal NPE occurs because field CachingProviderService.cachingProvider is null when method CacheManagerServiceImpl.getCacheManager() executes. The field is null during checkpoint because CacheProviderService.activate() moves the set behavior to restore and does not otherwise initialize the field to a value.

The failing code path executes because the appSecurity feature is enabled and the Authentication Cache is configured for distributed Auth Caching using a JCache provider. Before invoking servlet.init() the web security collaborator attempts to add an authenticated subject to the auth cache and fails due to the NPE that occurs when accessing the yet-to-be-initialized caching provider.

AFAICT InstantOn support is not verified for Authentication Caching. Checkpoint at afterAppStart is now a known failure point when distributed Auth Caching is enabled and the server deploys applications having eager startup behaviors. It's not known whether a break will otherwise occur when in-memory Auth Caching is enabled. The appAuthorization feature does not appear to be involved.

Moving forward, try checkpoint at beforeAppStart to avoid the app startup behavior. Remove any features that are unnecessary. And use the system property to enable any required that feature does yet support InstantOn. My team will look into planning the Auth Caching support and a possible fix for the NPE.


Here's the NPE call stack that failed the server checkpoint, followed by the configuration snippet that configures app security and auth caching.

[6/3/24, 20:47:13:723 UTC] 00000038 io.openliberty.jcache.internal.CacheServiceImpl              W CWLJC0011W: Error encountered while retrieving the AuthCache JCache. Will attempt to create it instead. The error was: java.lang.IllegalArgumentException: CWLJC0007E: Invalid syntax in cacheManager URI.  Cause is java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null.
    at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:216)
    at io.openliberty.jcache.internal.CacheServiceImpl.lambda$getCache$1(CacheServiceImpl.java:200)
    at java.base/java.security.AccessController.doPrivileged(AccessController.java:692)
    at io.openliberty.jcache.internal.CacheServiceImpl.getCache(CacheServiceImpl.java:177)
    at com.ibm.ws.security.authentication.internal.cache.JCacheAuthCache.getJCache(JCacheAuthCache.java:272)
    at com.ibm.ws.security.authentication.internal.cache.JCacheAuthCache.insert(JCacheAuthCache.java:195)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.addCacheObject(AuthCacheServiceImpl.java:131)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.commonInsert(AuthCacheServiceImpl.java:121)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.insert(AuthCacheServiceImpl.java:108)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.insertSubjectInAuthCache(AuthenticationServiceImpl.java:587)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:224)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:207)
    at com.ibm.ws.security.authentication.internal.UnauthenticatedSubjectServiceImpl.getUnauthenticatedSubject(UnauthenticatedSubjectServiceImpl.java:164)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.setUnauthenticatedSubjectIfNeeded(WebAppSecurityCollaboratorImpl.java:1224)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.preInvoke(WebAppSecurityCollaboratorImpl.java:609)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.preInvoke(WebAppSecurityCollaboratorImpl.java:1062)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.init(ServletWrapper.java:245)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.loadOnStartupCheck(ServletWrapper.java:1409)
    at com.ibm.ws.webcontainer.webapp.WebApp.doLoadOnStartupActions(WebApp.java:1228)
    at com.ibm.ws.webcontainer.webapp.WebApp.commonInitializationFinally(WebApp.java:1196)
    at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:1081)
    at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:6722)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApp(DynamicVirtualHost.java:484)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApplication(DynamicVirtualHost.java:479)
    at com.ibm.ws.webcontainer.osgi.WebContainer.startWebApplication(WebContainer.java:1208)
    at com.ibm.ws.webcontainer.osgi.WebContainer.startModule(WebContainer.java:988)
    at com.ibm.ws.app.manager.module.internal.ModuleHandlerBase.deployModule(ModuleHandlerBase.java:101)
    at com.ibm.ws.app.manager.module.internal.DeployedModuleInfoImpl.installModule(DeployedModuleInfoImpl.java:51)
    at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.deployModules(SimpleDeployedAppInfoBase.java:600)
    at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:514)
    at com.ibm.ws.app.manager.wab.internal.WABInstaller$WABDeployedAppInfo.installApp(WABInstaller.java:1570)
    at com.ibm.ws.app.manager.wab.internal.WABInstaller.installIntoWebContainer(WABInstaller.java:522)
    at com.ibm.ws.app.manager.wab.internal.WAB.addToWebContainer(WAB.java:437)
    at com.ibm.ws.app.manager.wab.internal.WAB.addingBundle(WAB.java:551)
    at com.ibm.ws.app.manager.wab.internal.WAB.addingBundle(WAB.java:62)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:477)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:1)
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:258)
    at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:185)
    at org.osgi.util.tracker.BundleTracker.open(BundleTracker.java:161)
    at com.ibm.ws.app.manager.wab.internal.WAB$1.run(WAB.java:147)
    at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:280)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:857)
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null
    at io.openliberty.jcache.utils.CacheConfigUtil.preConfigureCacheManager(CacheConfigUtil.java:112)
    at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:186)
    ... 46 more
<server>
    <featureManager>
        <feature>appSecurity-4.0</feature>
        <feature>sessionCache-1.0</feature> 
    </featureManager>

    <!--<logging traceSpecification="com.ibm.ws.webcontainer.security.internal.JCacheLoggedOutCookieCache=all:jcache=all"/>-->

    <!--  
        Library to use when running Infinispan or Datagrid remotely.
     -->
    <library id="DatagridLib">
        <fileset dir="${server.config.dir}/datagrid" includes="*.jar"/>
    </library>

    <!--  
        Configure the CachingProvider and CacheManager.
     -->
    <cacheManager id="CacheManager" uri="file:///${server.config.dir}/datagrid/infinispan_hotrod.props">
        <!--  
            The system property can't be read from the Hotrod properties file, so define it here.
         -->
        <properties infinispan.client.hotrod.uri="hotrod://${INFINISPAN_USER}:${INFINISPAN_PASS}@${INFINISPAN_HOST}:${INFINISPAN_PORT}"/>
        <cachingProvider providerClass="org.infinispan.jcache.remote.JCachingProvider" jCacheLibraryRef="DatagridLib" />
    </cacheManager>

    <!-- 
        Configure the JCache instances.
     -->
    <cache id="AuthCache" name="AuthCache" cacheManagerRef="CacheManager"/>
    <cache id="LoggedOutCookieCache" name="LoggedOutCookieCache" cacheManagerRef="CacheManager"/>
    <httpSessionCache cacheManagerRef="CacheManager" cacheSeparator="_"/>
    <!-- 
        Configure the authentication cache and the logged out cookie cache to use
        the JCache instances.
     -->
    <authCache cacheRef="AuthCache"/>
    <webAppSecurity loggedOutCookieCacheRef="LoggedOutCookieCache"/>
</server>
dazavala commented 4 weeks ago

The NPE also occurs when configuring checkpoint at beforeAppStart. Moreover, the NPE occurs before the first application or resource class is loaded and used, which triggers the checkpoint when using option beforeAppStart. The server is configured for distributed auth caching w/ a JCache provider. The NPE occurs when accessing the JCache provider at checkpoint. Since in-memory Auth Caching does not use the JCache provider, we might avoid the problem by configuring the server to use in-memory caching or remove auth caching for now. I'm about to attempt a checkpoint over an in-memory caching config. And then I will investigate the feasibility of moving the offending behavior -- inserting the authenticated subject into the auth cache -- from checkpoint to restore.

Also, here's the minimized feature set:

     <feature>enterpriseBeans-4.0</feature>
     <feature>servlet-5.0</feature>
     <feature>appSecurity-4.0</feature>
     <feature>transportSecurity-1.0</feature>
     <feature>persistence-3.0</feature>
     <feature>microProfile-5.0</feature>
     <feature>ldapRegistry-3.0</feature>
     <feature>appSecurity-4.0</feature>
     <feature>sessionCache-1.0</feature>

bootstrap.properties: io.openliberty.checkpoint.allowed.features=enterpriseBeansRemote-4.0,enterpriseBeansPersistentTimer-4.0,enterpriseBeansHome-4.0,enterpriseBeans-4.0

anjumfatima90 commented 3 weeks ago

I think there is a problem here. I believe beforeAppStart is not working as expected. I see the message A CWWKZ0001I: Application QuickSec started in 31.804 seconds. in the checkpoint logs. The application should not have run the initialization code. Below are the logs for beforeAppStart. I would not expect CWWKZ0001I message in the logs but it appears in the logs. Probably com.ibm.ws.app.manager.wab.internal.WAB$1.run(WAB.java:147) should not have run in beforeAppStart.

product = WebSphere Application Server 24.0.0.6 (wlp-1.0.90.cl240620240530-1200)
wlp.install.dir = /opt/ibm/wlp/
server.output.dir = /opt/ibm/wlp/output/defaultServer/
java.home = /opt/java/openjdk
java.version = 17.0.11
java.runtime = IBM Semeru Runtime Open Edition (17.0.11+9)
os = Linux (5.15.0-97-generic; amd64) (en_US)
process = 1026@bcdc38d3af10
Classpath = /opt/ibm/wlp/bin/tools/ws-server.jar
Java Library path = /opt/java/openjdk/lib/default:/opt/java/openjdk/lib:/usr/lib64:/usr/lib
********************************************************************************
[6/4/24, 16:10:23:642 UTC] 00000001 com.ibm.ws.kernel.launch.internal.FrameworkManager           A CWWKE0001I: The server defaultServer has been launched.
[6/4/24, 16:10:23:652 UTC] 00000001 com.ibm.ws.kernel.launch.internal.FrameworkManager           A CWWKE0100I: This product is licensed for development, and limited production use. The full license terms can be viewed here: https://public.dhe.ibm.com/ibmdl/export/pub/software/websphere/wasdev/license/base_ilan/ilan/24.0.0.6/lafiles/en.html
[6/4/24, 16:10:24:014 UTC] 0000002c com.ibm.ws.config.xml.internal.ServerXMLConfiguration        A CWWKG0093A: Processing configuration drop-ins resource: /opt/ibm/wlp/usr/servers/defaultServer/configDropins/defaults/keystore.xml
[6/4/24, 16:10:24:037 UTC] 0000002c com.ibm.ws.config.xml.internal.XMLConfigParser               A CWWKG0028A: Processing included configuration resource: /opt/ibm/wlp/usr/servers/defaultServer/datagrid.xml
[6/4/24, 16:10:24:038 UTC] 0000002c com.ibm.ws.config.xml.internal.XMLConfigParser               A CWWKG0028A: Processing included configuration resource: /opt/ibm/wlp/usr/servers/defaultServer/ldap-config.xml
[6/4/24, 16:10:24:040 UTC] 0000002c com.ibm.ws.config.xml.internal.ServerXMLConfiguration        A CWWKG0093A: Processing configuration drop-ins resource: /opt/ibm/wlp/usr/servers/defaultServer/configDropins/overrides/infinispan-client-sessioncache-config.xml
[6/4/24, 16:10:24:040 UTC] 0000002c com.ibm.ws.config.xml.internal.ServerXMLConfiguration        A CWWKG0093A: Processing configuration drop-ins resource: /opt/ibm/wlp/usr/servers/defaultServer/configDropins/overrides/sessioncache-features.xml
[6/4/24, 16:10:24:174 UTC] 00000001 com.ibm.ws.kernel.launch.internal.FrameworkManager           I CWWKE0002I: The kernel started after 0.826 seconds
[6/4/24, 16:10:24:219 UTC] 00000037 com.ibm.ws.kernel.feature.internal.FeatureManager            I CWWKF0007I: Feature update started.
[6/4/24, 16:10:24:416 UTC] 00000037 com.ibm.ws.logging.internal.impl.IncidentImpl                I FFDC1015I: An FFDC Incident has been created: "com.ibm.ws.config.xml.internal.AttributeValidationException: Value "${env.ldapPort}" is not a number. com.ibm.ws.config.xml.internal.VariableEvaluator 169" at ffdc_24.06.04_16.10.24.0.log
[6/4/24, 16:10:24:418 UTC] 00000037 com.ibm.ws.config.xml.internal.ConfigEvaluator               E CWWKG0075E: The value ${env.ldapPort} is not valid for attribute port of configuration element ldapRegistry. The validation message was: Value "${env.ldapPort}" is not a number..
[6/4/24, 16:10:24:424 UTC] 00000037 com.ibm.ws.config.xml.internal.ConfigEvaluator               W CWWKG0011W: The configuration validation did not succeed. Value "${env.DBPort}" is not a number.
[6/4/24, 16:10:24:424 UTC] 00000037 com.ibm.ws.config.xml.internal.ConfigEvaluator               W CWWKG0083W: A validation failure occurred while processing the [portNumber] property, value = [${env.DBPort}]. Default value in use: [50000]. 
[6/4/24, 16:10:24:548 UTC] 0000002a com.ibm.ws.security.ready.internal.SecurityReadyServiceImpl  I CWWKS0007I: The security service is starting...
[6/4/24, 16:10:24:611 UTC] 0000002e com.ibm.ws.app.manager.internal.monitor.DropinMonitor        A CWWKZ0058I: Monitoring dropins for applications.
[6/4/24, 16:10:24:916 UTC] 0000002d com.ibm.ws.cache.ServerCache                                 I DYNA1001I: WebSphere Dynamic Cache instance named baseCache initialized successfully.
[6/4/24, 16:10:24:918 UTC] 0000002d com.ibm.ws.cache.ServerCache                                 I DYNA1071I: The cache provider default is being used.
[6/4/24, 16:10:24:920 UTC] 0000002d com.ibm.ws.cache.CacheServiceImpl                            I DYNA1056I: Dynamic Cache (object cache) initialized successfully.
[6/4/24, 16:10:24:925 UTC] 0000002e rty.security.mp.jwt.v12.config.impl.MpConfigProxyServiceImpl I CWWKS5780I: The MicroProfile JWT version 1.2 mpConfigProxy processed successfully.
[6/4/24, 16:10:25:125 UTC] 0000002a ibm.ws.security.authentication.internal.jaas.JAASServiceImpl I CWWKS1123I: The collective authentication plugin with class name NullCollectiveAuthenticationPlugin has been activated. 
[6/4/24, 16:10:25:265 UTC] 0000002a com.ibm.ws.security.jaspi.AuthConfigFactoryWrapper           I CWWKS1655I: The default Java Authentication SPI for Containers (JASPIC) AuthConfigFactory class com.ibm.ws.security.jaspi.ProviderRegistry is being used because the Java security property authconfigprovider.factory is not set. 
[6/4/24, 16:10:25:299 UTC] 0000002a com.ibm.ws.security.jwt.internal.ConsumerImpl                I CWWKS6012I: The JSON Web Token (JWT) consumer service is available.
[6/4/24, 16:10:25:310 UTC] 0000002a com.ibm.ws.security.jwt.web.JwtEndpointServices              I CWWKS6002I: The JSON Web Token (JWT) endpoint service is available.
[6/4/24, 16:10:25:591 UTC] 0000002a com.ibm.ws.session.WASSessionCore                            I SESN8502I: The session manager found a persistent storage location; it will use session persistence mode=JCACHE
[6/4/24, 16:10:25:643 UTC] 0000002a com.ibm.ws.security.wim.VMMService                           I CWIMK0009I: The user registry federation service is ready.
[6/4/24, 16:10:25:718 UTC] 0000002a .microprofile.metrics.internal.monitor.MonitorMetricsHandler I CWPMI2003I: Monitoring metrics can be retrieved through mpMetrics.
[6/4/24, 16:10:26:194 UTC] 00000038 com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: io.openliberty.security.jwt.internal.
[6/4/24, 16:10:26:194 UTC] 00000044 com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: health.
[6/4/24, 16:10:26:194 UTC] 00000043 com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: OpenAPIUI.
[6/4/24, 16:10:26:195 UTC] 00000040 com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: ibm/api.
[6/4/24, 16:10:26:196 UTC] 00000043 com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module OpenAPIUI has been bound to default_host.
[6/4/24, 16:10:26:196 UTC] 00000038 com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module io.openliberty.security.jwt.internal has been bound to default_host.
[6/4/24, 16:10:26:196 UTC] 00000044 com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module health has been bound to default_host.
[6/4/24, 16:10:26:194 UTC] 00000042 com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: PublicMicroProfileMetrics.
[6/4/24, 16:10:26:196 UTC] 00000042 com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module PublicMicroProfileMetrics has been bound to default_host.
[6/4/24, 16:10:26:194 UTC] 0000003e com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: MicroProfileOpenAPI.
[6/4/24, 16:10:26:196 UTC] 0000003e com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module MicroProfileOpenAPI has been bound to default_host.
[6/4/24, 16:10:26:196 UTC] 00000040 com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module ibm/api has been bound to default_host.
[6/4/24, 16:10:26:234 UTC] 00000043 com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for application key default_host/openapi/ui
[6/4/24, 16:10:26:234 UTC] 00000044 com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for application key default_host/health
[6/4/24, 16:10:26:234 UTC] 00000042 com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for application key default_host/metrics
[6/4/24, 16:10:26:235 UTC] 0000003e com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for application key default_host/openapi
[6/4/24, 16:10:26:234 UTC] 00000038 com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for application key default_host/jwt
[6/4/24, 16:10:26:299 UTC] 00000043 com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[6/4/24, 16:10:26:313 UTC] 00000044 com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[6/4/24, 16:10:26:313 UTC] 00000042 com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[6/4/24, 16:10:26:314 UTC] 00000038 com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[6/4/24, 16:10:26:314 UTC] 0000003e com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[6/4/24, 16:10:26:315 UTC] 00000040 com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for application key default_host/ibm/api
[6/4/24, 16:10:26:315 UTC] 00000040 com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[6/4/24, 16:10:26:318 UTC] 00000043 com.ibm.ws.cache.CacheServiceImpl                            I DYNA1056I: Dynamic Cache (object cache) initialized successfully.
[6/4/24, 16:10:26:553 UTC] 00000038 com.ibm.ws.app.manager.AppMessageHelper                      I CWWKZ0018I: Starting application QuickSec.
[6/4/24, 16:10:26:554 UTC] 00000038 bm.ws.app.manager.ear.internal.EARDeployedAppInfoFactoryImpl I CWWKZ0136I: The QuickSec application is using the archive file at the /opt/ibm/wlp/usr/servers/defaultServer/apps/QuickSec.ear location.
[6/4/24, 16:10:26:581 UTC] 00000044 com.ibm.ws.logging.internal.impl.IncidentImpl                I FFDC1015I: An FFDC Incident has been created: "java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null io.openliberty.jcache.internal.CacheManagerServiceImpl 212" at ffdc_24.06.04_16.10.26.0.log
[6/4/24, 16:10:26:599 UTC] 00000038 com.ibm.ws.app.manager.ear.internal.EARDeployedAppInfo       W CWWKZ0126W:  The QuickSec context root value that is specified on the QuickSec application has no effect.
[6/4/24, 16:10:26:582 UTC] 00000044 io.openliberty.jcache.internal.CacheServiceImpl              W CWLJC0011W: Error encountered while retrieving the AuthCache JCache. Will attempt to create it instead. The error was: java.lang.IllegalArgumentException: CWLJC0007E: Invalid syntax in cacheManager URI.  Cause is java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null.
    at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:216)
    at io.openliberty.jcache.internal.CacheServiceImpl.lambda$getCache$1(CacheServiceImpl.java:200)
    at java.base/java.security.AccessController.doPrivileged(AccessController.java:692)
    at io.openliberty.jcache.internal.CacheServiceImpl.getCache(CacheServiceImpl.java:177)
    at com.ibm.ws.security.authentication.internal.cache.JCacheAuthCache.getJCache(JCacheAuthCache.java:272)
    at com.ibm.ws.security.authentication.internal.cache.JCacheAuthCache.insert(JCacheAuthCache.java:195)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.addCacheObject(AuthCacheServiceImpl.java:131)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.commonInsert(AuthCacheServiceImpl.java:121)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.insert(AuthCacheServiceImpl.java:108)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.insertSubjectInAuthCache(AuthenticationServiceImpl.java:587)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:224)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:207)
    at com.ibm.ws.security.authentication.internal.UnauthenticatedSubjectServiceImpl.getUnauthenticatedSubject(UnauthenticatedSubjectServiceImpl.java:164)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.setUnauthenticatedSubjectIfNeeded(WebAppSecurityCollaboratorImpl.java:1224)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.preInvoke(WebAppSecurityCollaboratorImpl.java:609)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.preInvoke(WebAppSecurityCollaboratorImpl.java:1062)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.init(ServletWrapper.java:245)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.loadOnStartupCheck(ServletWrapper.java:1409)
    at com.ibm.ws.webcontainer.webapp.WebApp.doLoadOnStartupActions(WebApp.java:1228)
    at com.ibm.ws.webcontainer.webapp.WebApp.commonInitializationFinally(WebApp.java:1196)
    at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:1094)
    at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:6722)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApp(DynamicVirtualHost.java:484)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApplication(DynamicVirtualHost.java:479)
    at com.ibm.ws.webcontainer.osgi.WebContainer.startWebApplication(WebContainer.java:1208)
    at com.ibm.ws.webcontainer.osgi.WebContainer.startModule(WebContainer.java:988)
    at com.ibm.ws.app.manager.module.internal.ModuleHandlerBase.deployModule(ModuleHandlerBase.java:101)
    at com.ibm.ws.app.manager.module.internal.DeployedModuleInfoImpl.installModule(DeployedModuleInfoImpl.java:51)
    at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.deployModules(SimpleDeployedAppInfoBase.java:600)
    at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:514)
    at com.ibm.ws.app.manager.wab.internal.WABInstaller$WABDeployedAppInfo.installApp(WABInstaller.java:1570)
    at com.ibm.ws.app.manager.wab.internal.WABInstaller.installIntoWebContainer(WABInstaller.java:522)
    at com.ibm.ws.app.manager.wab.internal.WAB.addToWebContainer(WAB.java:437)
    at com.ibm.ws.app.manager.wab.internal.WAB.addingBundle(WAB.java:551)
    at com.ibm.ws.app.manager.wab.internal.WAB.addingBundle(WAB.java:62)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:477)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:1)
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:258)
    at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:185)
    at org.osgi.util.tracker.BundleTracker.open(BundleTracker.java:161)
    at com.ibm.ws.app.manager.wab.internal.WAB$1.run(WAB.java:147)
    at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:280)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:857)
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null
    at io.openliberty.jcache.utils.CacheConfigUtil.preConfigureCacheManager(CacheConfigUtil.java:112)
    at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:186)
    ... 46 more
.
[6/4/24, 16:10:26:607 UTC] 00000044 com.ibm.ws.webcontainer.servlet                              I SRVE0242I: [io.openliberty.microprofile.health.3.1.internal.jakarta] [/health] [HealthCheckReadinessServlet]: Initialization successful.
[6/4/24, 16:10:26:609 UTC] 00000044 com.ibm.ws.webcontainer.servlet                              I SRVE0242I: [io.openliberty.microprofile.health.3.1.internal.jakarta] [/health] [HealthCheckServlet]: Initialization successful.
[6/4/24, 16:10:26:609 UTC] 00000044 com.ibm.ws.webcontainer.servlet                              I SRVE0242I: [io.openliberty.microprofile.health.3.1.internal.jakarta] [/health] [HealthCheckStartupServlet]: Initialization successful.
[6/4/24, 16:10:26:610 UTC] 00000044 com.ibm.ws.webcontainer.servlet                              I SRVE0242I: [io.openliberty.microprofile.health.3.1.internal.jakarta] [/health] [HealthCheckLivenessServlet]: Initialization successful.
[6/4/24, 16:10:26:609 UTC] 00000042 io.openliberty.jcache.internal.CacheServiceImpl              W CWLJC0011W: Error encountered while retrieving the AuthCache JCache. Will attempt to create it instead. The error was: java.lang.IllegalArgumentException: CWLJC0007E: Invalid syntax in cacheManager URI.  Cause is java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null.
    at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:216)
    at io.openliberty.jcache.internal.CacheServiceImpl.lambda$getCache$1(CacheServiceImpl.java:200)
    at java.base/java.security.AccessController.doPrivileged(AccessController.java:692)
    at io.openliberty.jcache.internal.CacheServiceImpl.getCache(CacheServiceImpl.java:177)
    at com.ibm.ws.security.authentication.internal.cache.JCacheAuthCache.getJCache(JCacheAuthCache.java:272)
    at com.ibm.ws.security.authentication.internal.cache.JCacheAuthCache.insert(JCacheAuthCache.java:195)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.addCacheObject(AuthCacheServiceImpl.java:131)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.commonInsert(AuthCacheServiceImpl.java:121)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.insert(AuthCacheServiceImpl.java:108)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.insertSubjectInAuthCache(AuthenticationServiceImpl.java:587)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:224)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:207)
    at com.ibm.ws.security.authentication.internal.UnauthenticatedSubjectServiceImpl.getUnauthenticatedSubject(UnauthenticatedSubjectServiceImpl.java:164)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.setUnauthenticatedSubjectIfNeeded(WebAppSecurityCollaboratorImpl.java:1224)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.preInvoke(WebAppSecurityCollaboratorImpl.java:609)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.preInvoke(WebAppSecurityCollaboratorImpl.java:1062)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.init(ServletWrapper.java:245)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.loadOnStartupCheck(ServletWrapper.java:1409)
    at com.ibm.ws.webcontainer.webapp.WebApp.doLoadOnStartupActions(WebApp.java:1228)
    at com.ibm.ws.webcontainer.webapp.WebApp.commonInitializationFinally(WebApp.java:1196)
    at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:1094)
    at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:6722)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApp(DynamicVirtualHost.java:484)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApplication(DynamicVirtualHost.java:479)
    at com.ibm.ws.webcontainer.osgi.WebContainer.startWebApplication(WebContainer.java:1208)
    at com.ibm.ws.webcontainer.osgi.WebContainer.startModule(WebContainer.java:988)
    at com.ibm.ws.app.manager.module.internal.ModuleHandlerBase.deployModule(ModuleHandlerBase.java:101)
    at com.ibm.ws.app.manager.module.internal.DeployedModuleInfoImpl.installModule(DeployedModuleInfoImpl.java:51)
    at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.deployModules(SimpleDeployedAppInfoBase.java:600)
    at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:514)
    at com.ibm.ws.app.manager.wab.internal.WABInstaller$WABDeployedAppInfo.installApp(WABInstaller.java:1570)
    at com.ibm.ws.app.manager.wab.internal.WABInstaller.installIntoWebContainer(WABInstaller.java:522)
    at com.ibm.ws.app.manager.wab.internal.WAB.addToWebContainer(WAB.java:437)
    at com.ibm.ws.app.manager.wab.internal.WAB.addingBundle(WAB.java:551)
    at com.ibm.ws.app.manager.wab.internal.WAB.addingBundle(WAB.java:62)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:477)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:1)
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:258)
    at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:185)
    at org.osgi.util.tracker.BundleTracker.open(BundleTracker.java:161)
    at com.ibm.ws.app.manager.wab.internal.WAB$1.run(WAB.java:147)
    at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:280)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:857)
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null
    at io.openliberty.jcache.utils.CacheConfigUtil.preConfigureCacheManager(CacheConfigUtil.java:112)
    at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:186)
    ... 46 more
.
[6/4/24, 16:10:26:618 UTC] 00000042 com.ibm.ws.webcontainer.servlet                              I SRVE0242I: [io.openliberty.microprofile.metrics.internal.public] [/metrics] [PublicMetricsRESTProxyServlet]: Initialization successful.
[6/4/24, 16:10:26:621 UTC] 0000003e io.openliberty.jcache.internal.CacheServiceImpl              W CWLJC0011W: Error encountered while retrieving the AuthCache JCache. Will attempt to create it instead. The error was: java.lang.IllegalArgumentException: CWLJC0007E: Invalid syntax in cacheManager URI.  Cause is java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null.
    at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:216)
    at io.openliberty.jcache.internal.CacheServiceImpl.lambda$getCache$1(CacheServiceImpl.java:200)
    at java.base/java.security.AccessController.doPrivileged(AccessController.java:692)
    at io.openliberty.jcache.internal.CacheServiceImpl.getCache(CacheServiceImpl.java:177)
    at com.ibm.ws.security.authentication.internal.cache.JCacheAuthCache.getJCache(JCacheAuthCache.java:272)
    at com.ibm.ws.security.authentication.internal.cache.JCacheAuthCache.insert(JCacheAuthCache.java:195)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.addCacheObject(AuthCacheServiceImpl.java:131)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.commonInsert(AuthCacheServiceImpl.java:121)
    at com.ibm.ws.security.authentication.internal.cache.AuthCacheServiceImpl.insert(AuthCacheServiceImpl.java:108)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.insertSubjectInAuthCache(AuthenticationServiceImpl.java:587)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:224)
    at com.ibm.ws.security.authentication.internal.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:207)
    at com.ibm.ws.security.authentication.internal.UnauthenticatedSubjectServiceImpl.getUnauthenticatedSubject(UnauthenticatedSubjectServiceImpl.java:164)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.setUnauthenticatedSubjectIfNeeded(WebAppSecurityCollaboratorImpl.java:1224)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.preInvoke(WebAppSecurityCollaboratorImpl.java:609)
    at com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.preInvoke(WebAppSecurityCollaboratorImpl.java:1062)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.init(ServletWrapper.java:245)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.loadOnStartupCheck(ServletWrapper.java:1409)
    at com.ibm.ws.webcontainer.webapp.WebApp.doLoadOnStartupActions(WebApp.java:1228)
    at com.ibm.ws.webcontainer.webapp.WebApp.commonInitializationFinally(WebApp.java:1196)
    at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:1094)
    at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:6722)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApp(DynamicVirtualHost.java:484)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApplication(DynamicVirtualHost.java:479)
    at com.ibm.ws.webcontainer.osgi.WebContainer.startWebApplication(WebContainer.java:1208)
    at com.ibm.ws.webcontainer.osgi.WebContainer.startModule(WebContainer.java:988)
    at com.ibm.ws.app.manager.module.internal.ModuleHandlerBase.deployModule(ModuleHandlerBase.java:101)
    at com.ibm.ws.app.manager.module.internal.DeployedModuleInfoImpl.installModule(DeployedModuleInfoImpl.java:51)
    at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.deployModules(SimpleDeployedAppInfoBase.java:600)
    at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:514)
    at com.ibm.ws.app.manager.wab.internal.WABInstaller$WABDeployedAppInfo.installApp(WABInstaller.java:1570)
    at com.ibm.ws.app.manager.wab.internal.WABInstaller.installIntoWebContainer(WABInstaller.java:522)
    at com.ibm.ws.app.manager.wab.internal.WAB.addToWebContainer(WAB.java:437)
    at com.ibm.ws.app.manager.wab.internal.WAB.addingBundle(WAB.java:551)
    at com.ibm.ws.app.manager.wab.internal.WAB.addingBundle(WAB.java:62)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:477)
    at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:1)
    at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:258)
    at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:185)
    at org.osgi.util.tracker.BundleTracker.open(BundleTracker.java:161)
    at com.ibm.ws.app.manager.wab.internal.WAB$1.run(WAB.java:147)
    at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:280)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:857)
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.Object.getClass()" because "cachingProvider" is null
    at io.openliberty.jcache.utils.CacheConfigUtil.preConfigureCacheManager(CacheConfigUtil.java:112)
    at io.openliberty.jcache.internal.CacheManagerServiceImpl.getCacheManager(CacheManagerServiceImpl.java:186)
    ... 46 more
.
[6/4/24, 16:10:26:627 UTC] 0000003e com.ibm.ws.webcontainer.servlet                              I SRVE0242I: [io.openliberty.microprofile.openapi.2.0.internal.servlet.jakarta] [/openapi] [ApplicationServlet]: Initialization successful.
[6/4/24, 16:10:27:037 UTC] 00000038 org.jboss.weld.Version                                       I WELD-000900: 4.0.3 (Final)
[6/4/24, 16:10:28:226 UTC] 00000038 com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl         I CNTR4000I: The messengerEJB.jar EJB module in the QuickSec application is starting.
[6/4/24, 16:10:58:297 UTC] 00000038 com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl         I CNTR4001I: The messengerEJB.jar EJB module in the QuickSec application has started successfully.
[6/4/24, 16:10:58:298 UTC] 00000038 com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl         I CNTR4000I: The delegateEJB.jar EJB module in the QuickSec application is starting.
[6/4/24, 16:10:58:307 UTC] 00000038 com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl         I CNTR4001I: The delegateEJB.jar EJB module in the QuickSec application has started successfully.
[6/4/24, 16:10:58:313 UTC] 00000038 com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: quickSecForm.
[6/4/24, 16:10:58:313 UTC] 00000038 com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module quickSecForm has been bound to default_host.
[6/4/24, 16:10:58:316 UTC] 00000038 com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for application key default_host/QuickSecForm
[6/4/24, 16:10:58:316 UTC] 00000038 com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[6/4/24, 16:10:58:346 UTC] 00000038 com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: QuickSecBasic.
[6/4/24, 16:10:58:346 UTC] 00000038 com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module QuickSecBasic has been bound to default_host.
[6/4/24, 16:10:58:346 UTC] 00000038 com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for application key default_host/QuickSecBasic
[6/4/24, 16:10:58:347 UTC] 00000038 com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default SecureRandom implementation for session ID generation.
[6/4/24, 16:10:58:349 UTC] 00000038 com.ibm.ws.webcontainer.webapp                               W SRVE0272W: JSP Processor not defined. Skipping : /BasicLoginController.jsp
[6/4/24, 16:10:58:354 UTC] 00000038 com.ibm.ws.webcontainer.security.ServletStartedListener      I CWWKS9122I:  For URL /unsecSession in application QuickSec, the following HTTP methods are uncovered, and accessible: GET POST PUT DELETE HEAD OPTIONS TRACE 
[6/4/24, 16:10:58:358 UTC] 00000038 com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0001I: Application QuickSec started in 31.804 seconds.
[6/4/24, 16:10:58:382 UTC] 00000037 io.openliberty.checkpoint.internal.CheckpointImpl            A CWWKC0451I: A server checkpoint "beforeAppStart" was requested. When the checkpoint completes, the server stops.
dazavala commented 3 weeks ago

Anjum's post shows the NPE occurs on threads running WAB install, which I hadn't noticed earlier. We determined that only the system WABs (PrivateMetricsRESTProxyServlet, ApplicationServlet, HealthCheckReadinessServlet, HealthCheckServlet, HealthCheckStartupServlet and HealthCheckLivenessServlet) suffer the problem. The QuickSec EAR has no early startup behaviors, so the checkpoint at beforeAppStart launches after the application has started. This is expected behavior, but because only WABs are problematic, the advice to use beforeAppStart was inappropriate.

To unblock test progress, we will attempt to remove auth caching while we fix it, or use different cache type. FYI @tjwatson

tjwatson commented 3 weeks ago

Are we sure this is only happening with WABs? Seems the classes you reference ((PrivateMetricsRESTProxyServlet, ApplicationServlet, HealthCheckReadinessServlet, HealthCheckServlet, HealthCheckStartupServlet and HealthCheckLivenessServlet) are loadOnStartup servlets in the WABs. I suspect this could be an issue with any application with a loadOnStartup servlet.

tjwatson commented 3 weeks ago

I wonder if com.ibm.ws.webcontainer.security.WebAppSecurityCollaboratorImpl.setUnauthenticatedSubjectIfNeeded(Subject, Subject) should be delayed to restore.

anjumfatima90 commented 3 weeks ago

@tjwatson Do you think the loadOnStartup initialization code should have run on restore for the beforeAppStart. In my understanding, the applications with loadOnStartup servlet runs the initialization code on restore. But since this WABs, I feel they are not working the same way?

tjwatson commented 3 weeks ago

See https://github.com/OpenLiberty/open-liberty/blob/integration/dev/io.openliberty.microprofile.health.3.0.internal/resources/WEB-INF/web.xml and https://github.com/OpenLiberty/open-liberty/blob/integration/dev//io.openliberty.microprofile.health.3.1.internal/resources/WEB-INF/web.xml all the health servlets have <load-on-startup>1</load-on-startup>

PrivateMetricsRESTProxyServlet and ApplicationServlet are also load-on-startup servlets. I believe an application that has a load-on-startup servlet would also see this codepath run.

dazavala commented 3 weeks ago

The failure will certainly occur for deployed web applications with loadOnStartup=1. The caching behavior is driven from the WebAppSecurityCollaborator.preInvoke() method that executes before the container invokes servlet.init() or servlet.destroy()

dazavala commented 3 weeks ago

Here are my initial considerations regarding the solution.