search

OpenLiberty / open-liberty

Open Liberty is a highly composable, fast to start, dynamic application server runtime environment
https://openliberty.io
Eclipse Public License 2.0
1.16k stars 597 forks source link

SVT: Warning CWWJP9991W when using EE11 features (not for EE10) #29521

Open mtamboli opened 2 months ago

mtamboli commented 2 months ago

Describe the bug
A clear and concise description of what the bug is.

If there is a stack trace, please include the FULL stack trace (without any [internal classes] lines in it). To find the full stack trace, you may need to check in $WLP_OUTPUT_DIR/messages.log

I am testing EE11 features and noticed below exception when I use EE11 features as opposed to EE10 after I access database in my test application. [8/27/24, 12:15:40:794 PDT] 0000002b eclipselink.server W CWWJP9991W: [eclipselink.server] Failed to find MBean Server: null or empty List returned from MBeanServerFactory.findMBeanServer(null).

[8/27/24, 12:15:38:756 PDT] 0000002b eclipselink                                                  I CWWJP9990I: [eclipselink] EclipseLink, version: Eclipse Persistence Services - 5.0.0-B02.v202404111748
[8/27/24, 12:15:40:593 PDT] 0000002b com.ibm.ws.rsadapter.impl.DatabaseHelper                     I DSRA8203I: Database product name : DB2/LINUXX8664
[8/27/24, 12:15:40:596 PDT] 0000002b com.ibm.ws.rsadapter.impl.DatabaseHelper                     I DSRA8204I: Database product version : SQL110590
[8/27/24, 12:15:40:596 PDT] 0000002b com.ibm.ws.rsadapter.impl.DatabaseHelper                     I DSRA8205I: JDBC driver name  : IBM Data Server Driver for JDBC and SQLJ
[8/27/24, 12:15:40:596 PDT] 0000002b com.ibm.ws.rsadapter.impl.DatabaseHelper                     I DSRA8206I: JDBC driver version  : 4.33.31
[8/27/24, 12:15:40:794 PDT] 0000002b eclipselink.server                                           W CWWJP9991W: [eclipselink.server] Failed to find MBean Server: null or empty List returned from MBeanServerFactory.findMBeanServer(null)

Steps to Reproduce
Steps to reproduce the bug

Expected behavior
A clear and concise description of what you expected to happen.

This exception is not expected as the Database is configured correctly. This exception does not occur for EE10 features.

Diagnostic information: 

product = Open Liberty 24.0.0.9-beta (wlp-1.0.92.cl240920240801-1104)
wlp.install.dir = /root/liberty/ee11/wlp/
java.home = /root/liberty/jdk-17.0.8.1+1
java.version = 17.0.8.1
java.runtime = IBM Semeru Runtime Open Edition (17.0.8.1+1)
os = Linux (5.14.0-427.31.1.el9_4.x86_64; amd64) (en_US)
process = 86122@lib-rhel1.fyre.ibm.com
Classpath = /root/liberty/ee11/wlp/bin/tools/ws-server.jar
Java Library path = /root/liberty/jdk-17.0.8.1+1/lib/default:/root/liberty/jdk-17.0.8.1+1/lib:/usr/lib64:/usr/lib

[8/7/24, 13:15:59:391 PDT] 00000001 com.ibm.ws.kernel.launch.internal.FrameworkManager           A CWWKE0001I: The server defaultServer has been launched.
[8/7/24, 13:16:00:302 PDT] 00000020 com.ibm.ws.config.xml.internal.XMLConfigParser               A CWWKG0028A: Processing included configuration resource: /ro
ot/liberty/ee11/wlp/usr/servers/defaultServer/ldap-config.xml
[8/7/24, 13:16:00:560 PDT] 00000001 com.ibm.ws.kernel.launch.internal.FrameworkManager           I CWWKE0002I: The kernel started after 1.537 seconds
[8/7/24, 13:16:00:940 PDT] 0000002a com.ibm.ws.kernel.feature.internal.FeatureManager            I CWWKF0007I: Feature update started.
[8/7/24, 13:16:03:034 PDT] 0000001f com.ibm.ws.security.ready.internal.SecurityReadyServiceImpl  I CWWKS0007I: The security service is starting...
[8/7/24, 13:16:03:556 PDT] 00000020 com.ibm.ws.app.manager.internal.monitor.DropinMonitor        A CWWKZ0058I: Monitoring dropins for applications.
[8/7/24, 13:16:04:016 PDT] 00000020 com.ibm.ws.cache.ServerCache                                 I DYNA1001I: WebSphere Dynamic Cache instance named baseCache
 initialized successfully.
[8/7/24, 13:16:04:018 PDT] 00000020 com.ibm.ws.cache.ServerCache                                 I DYNA1071I: The cache provider default is being used.
[8/7/24, 13:16:04:019 PDT] 00000020 com.ibm.ws.cache.CacheServiceImpl                            I DYNA1056I: Dynamic Cache (object cache) initialized success
fully.
[8/7/24, 13:16:04:220 PDT] 0000002b com.ibm.ws.security.token.ltpa.internal.LTPAKeyCreateTask    I CWWKS4105I: LTPA configuration is ready after 0.021 seconds
.
[8/7/24, 13:16:04:235 PDT] 0000001f ibm.ws.security.authentication.internal.jaas.JAASServiceImpl I CWWKS1123I: The collective authentication plugin with class
 name NullCollectiveAuthenticationPlugin has been activated. 
[8/7/24, 13:16:04:571 PDT] 0000001f com.ibm.ws.security.jaspi.AuthConfigFactoryWrapper           I CWWKS1655I: The default Java Authentication SPI for Contain
ers (JASPIC) AuthConfigFactory class com.ibm.ws.security.jaspi.ProviderRegistry is being used because the Java security property authconfigprovider.factory is
 not set. 
[8/7/24, 13:16:04:617 PDT] 00000026 com.ibm.ws.ssl.config.WSKeyStore                             A CWPKI0820A: The default keystore has been created using the
 'keystore_password' environment variable.
[8/7/24, 13:16:04:686 PDT] 00000026 com.ibm.ws.ssl.config.WSKeyStore                             I Successfully loaded default keystore: /root/liberty/ee11/wl
p/usr/servers/defaultServer/resources/security/key.p12 of type: PKCS12
[8/7/24, 13:16:04:963 PDT] 0000001f com.ibm.ws.security.wim.VMMService                           I CWIMK0009I: The user registry federation service is ready.
[8/7/24, 13:16:04:968 PDT] 0000001f com.ibm.ws.security.ready.internal.SecurityReadyServiceImpl  I CWWKS0008I: The security service is ready.
[8/7/24, 13:16:05:239 PDT] 00000021 com.ibm.ws.transport.iiop.internal.ORBWrapperInternal        A CWWKI0001I: The CORBA name server is now available at corba
loc:iiop:localhost:2809/NameService.
[8/7/24, 13:16:05:381 PDT] 0000002c com.ibm.ws.app.manager.AppMessageHelper                      I CWWKZ0018I: Starting application QuickSec.
[8/7/24, 13:16:05:381 PDT] 0000002c bm.ws.app.manager.ear.internal.EARDeployedAppInfoFactoryImpl I CWWKZ0136I: The QuickSec application is using the archive f
ile at the /root/liberty/ee11/wlp/usr/servers/defaultServer/apps/QuickSec.ear location.
[8/7/24, 13:16:05:472 PDT] 0000002c com.ibm.ws.app.manager.ear.internal.EARDeployedAppInfo       W CWWKZ0126W:  The QuickSec context root value that is specif
ied on the QuickSec application has no effect.
[8/7/24, 13:16:06:516 PDT] 0000002c org.jboss.weld.Version                                       I WELD-000900: 6.0.0 (Beta1)
[8/7/24, 13:16:08:264 PDT] 0000002c com.ibm.ws.session.WASSessionCore                            I SESN8501I: The session manager did not find a persistent st
orage location; HttpSession objects will be stored in the local application server's memory.
[8/7/24, 13:16:08:270 PDT] 0000002c com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl         I CNTR4000I: The messengerEJB.jar EJB module in the QuickSec 
application is starting.
[8/7/24, 13:16:08:316 PDT] 0000002c com.ibm.ws.ejbcontainer.osgi.internal.NameSpaceBinderImpl    I CNTR0167I: The server is binding the com.ibm.ws.svt.quickse
c.EJB.Messenger interface of the MessengerBean enterprise bean in the messengerEJB.jar module of the QuickSec application.  The binding location is: ejb/Quick
Sec/messengerEJB.jar/MessengerBean#com.ibm.ws.svt.quicksec.EJB.Messenger
[8/7/24, 13:16:08:320 PDT] 0000002c com.ibm.ws.ejbcontainer.osgi.internal.NameSpaceBinderImpl    I CNTR0167I: The server is binding the com.ibm.ws.svt.quickse
c.EJB.Messenger interface of the MessengerBean enterprise bean in the messengerEJB.jar module of the QuickSec application.  The binding location is: com.ibm.w
s.svt.quicksec.EJB.Messenger
[8/7/24, 13:16:08:321 PDT] 0000002c com.ibm.ws.ejbcontainer.runtime.AbstractEJBRuntime           I CNTR0167I: The server is binding the com.ibm.ws.svt.quickse
c.EJB.Messenger interface of the MessengerBean enterprise bean in the messengerEJB.jar module of the QuickSec application.  The binding location is: java:glob
al/QuickSec/messengerEJB/MessengerBean!com.ibm.ws.svt.quicksec.EJB.Messenger
[8/7/24, 13:16:08:321 PDT] 0000002c com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl         I CNTR4001I: The messengerEJB.jar EJB module in the QuickSec 
application has started successfully.
[8/7/24, 13:16:08:321 PDT] 0000002c com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl         I CNTR4000I: The delegateEJB.jar EJB module in the QuickSec a
pplication is starting.
[8/7/24, 13:16:08:323 PDT] 0000002c com.ibm.ws.ejbcontainer.osgi.internal.NameSpaceBinderImpl    I CNTR0167I: The server is binding the com.ibm.ws.svt.quickse
c.EJB.Delegate interface of the DelegateBean enterprise bean in the delegateEJB.jar module of the QuickSec application.  The binding location is: ejb/QuickSec
/delegateEJB.jar/DelegateBean#com.ibm.ws.svt.quicksec.EJB.Delegate
[8/7/24, 13:16:08:324 PDT] 0000002c com.ibm.ws.ejbcontainer.osgi.internal.NameSpaceBinderImpl    I CNTR0167I: The server is binding the com.ibm.ws.svt.quickse
c.EJB.Delegate interface of the DelegateBean enterprise bean in the delegateEJB.jar module of the QuickSec application.  The binding location is: com.ibm.ws.s
vt.quicksec.EJB.Delegate
[8/7/24, 13:16:08:324 PDT] 0000002c com.ibm.ws.ejbcontainer.runtime.AbstractEJBRuntime           I CNTR0167I: The server is binding the com.ibm.ws.svt.quickse
c.EJB.Delegate interface of the DelegateBean enterprise bean in the delegateEJB.jar module of the QuickSec application.  The binding location is: java:global/
QuickSec/delegateEJB/DelegateBean!com.ibm.ws.svt.quicksec.EJB.Delegate
[8/7/24, 13:16:08:324 PDT] 0000002c com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl         I CNTR4001I: The delegateEJB.jar EJB module in the QuickSec a
pplication has started successfully.
[8/7/24, 13:16:08:335 PDT] 0000002c com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: quickSecForm.
[8/7/24, 13:16:08:337 PDT] 0000002c com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module quickSecForm has been bound to defaul
t_host.
[8/7/24, 13:16:08:338 PDT] 0000002c com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0016I: Web application available (default_host): http:
//10.88.0.1:9080/QuickSecForm/
[8/7/24, 13:16:08:353 PDT] 0000002c com.ibm.ws.webcontainer.osgi.webapp.WebGroup                 I SRVE0169I: Loading Web Module: QuickSecBasic.
[8/7/24, 13:16:08:353 PDT] 0000002c com.ibm.ws.webcontainer                                      I SRVE0250I: Web Module QuickSecBasic has been bound to defau
lt_host.
[8/7/24, 13:16:08:353 PDT] 0000002c com.ibm.ws.http.internal.VirtualHostImpl                     A CWWKT0016I: Web application available (default_host): http:
//10.88.0.1:9080/QuickSecBasic/
[8/7/24, 13:16:08:360 PDT] 00000041 com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for applic
ation key default_host/QuickSecBasic
[8/7/24, 13:16:08:364 PDT] 0000002d com.ibm.ws.session.WASSessionCore                            I SESN0176I: A new session context will be created for applic
ation key default_host/QuickSecForm
[8/7/24, 13:16:08:369 PDT] 00000041 com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default Se
cureRandom implementation for session ID generation.
[8/7/24, 13:16:08:376 PDT] 0000002d com.ibm.ws.util                                              I SESN0172I: The session manager is using the Java default Se
cureRandom implementation for session ID generation.
[8/7/24, 13:16:08:388 PDT] 00000041 com.ibm.ws.webcontainer.webapp                               W SRVE0272W: JSP Processor not defined. Skipping : /BasicLogi
nController.jsp
[8/7/24, 13:16:08:391 PDT] 0000002d com.ibm.ws.cache.CacheServiceImpl                            I DYNA1056I: Dynamic Cache (object cache) initialized success
fully.
[8/7/24, 13:16:08:430 PDT] 00000041 com.ibm.ws.app.manager.AppMessageHelper                      A CWWKZ0001I: Application QuickSec started in 3.048 seconds.
[8/7/24, 13:16:08:460 PDT] 00000041 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 
[8/7/24, 13:16:08:467 PDT] 0000002a com.ibm.ws.tcpchannel.internal.TCPPort                       I CWWKO0219I: TCP Channel defaultHttpEndpoint has been starte
d and is now listening for requests on host *  (IPv4) port 9080.
[8/7/24, 13:16:08:477 PDT] 0000002a com.ibm.ws.tcpchannel.internal.TCPPort                       I CWWKO0219I: TCP Channel defaultHttpEndpoint-ssl has been st
arted and is now listening for requests on host *  (IPv4) port 9443.
[8/7/24, 13:16:08:610 PDT] 0000002a com.ibm.ws.kernel.feature.internal.FeatureManager            A CWWKF0012I: The server installed the following features: [a
ppSecurity-6.0, cdi-4.1, connectors-2.1, distributedMap-1.0, enterpriseBeans-4.0, enterpriseBeansHome-4.0, enterpriseBeansLite-4.0, enterpriseBeansPersistentT
imer-4.0, enterpriseBeansRemote-4.0, expressionLanguage-6.0, federatedRegistry-1.0, jdbc-4.2, jndi-1.0, jsonp-2.1, ldapRegistry-3.0, mdb-4.0, persistence-3.2,
 persistenceContainer-3.2, servlet-6.1, ssl-1.0, transportSecurity-1.0].
[8/7/24, 13:16:08:611 PDT] 0000002a com.ibm.ws.kernel.feature.internal.FeatureManager            I CWWKF0008I: Feature update completed in 8.053 seconds.
[8/7/24, 13:16:08:611 PDT] 0000002a com.ibm.ws.kernel.feature.internal.FeatureManager            A CWWKF0011I: The defaultServer server is ready to run a smar
ter planet. The defaultServer server started in 9.589 seconds.
[8/7/24, 13:16:08:694 PDT] 00000040 com.ibm.ws.webcontainer.osgi.mbeans.PluginGenerator          I SRVE9103I: A configuration file for a web server plugin was
 automatically generated for this server at /root/liberty/ee11/wlp/usr/servers/defaultServer/logs/state/plugin-cfg.xml.
[8/7/24, 13:16:39:073 PDT] 0000002d com.ibm.ws.webcontainer.servlet                              I SRVE0242I: [QuickSec] [/QuickSecForm] [QuickSecForm]: Initi
alization successful.
[8/7/24, 13:16:41:156 PDT] 0000002c com.ibm.ws.recoverylog.spi.RecoveryDirectorImpl              I CWRLS0010I: Performing recovery processing for local WebSph
ere server (defaultServer).
[8/7/24, 13:16:41:279 PDT] 0000002c com.ibm.ws.recoverylog.spi.RecoveryDirectorImpl              I CWRLS0012I: All persistent services have been directed to p
erform recovery processing for this WebSphere server (defaultServer).
[8/7/24, 13:16:41:287 PDT] 00000046 com.ibm.tx.jta.impl.RecoveryManager                          I WTRN0135I: Transaction service recovering no transactions.
[8/7/24, 13:16:41:622 PDT] 0000002b com.ibm.ws.jca.cm.ConnectorService                           I J2CA8050I: An authentication alias should be used instead o
f defining a user name and password on dataSource[Messenger].
[8/7/24, 13:16:43:167 PDT] 0000002b eclipselink                                                  I CWWJP9990I: [eclipselink] EclipseLink, version: Eclipse Per
sistence Services - 5.0.0-B02.v202404111748
[8/7/24, 13:16:44:583 PDT] 0000002b com.ibm.ws.rsadapter.impl.DatabaseHelper                     I DSRA8203I: Database product name : DB2/LINUXX8664
[8/7/24, 13:16:44:585 PDT] 0000002b com.ibm.ws.rsadapter.impl.DatabaseHelper                     I DSRA8204I: Database product version : SQL110590
[8/7/24, 13:16:44:585 PDT] 0000002b com.ibm.ws.rsadapter.impl.DatabaseHelper                     I DSRA8205I: JDBC driver name  : IBM Data Server Driver for J
DBC and SQLJ
[8/7/24, 13:16:44:586 PDT] 0000002b com.ibm.ws.rsadapter.impl.DatabaseHelper                     I DSRA8206I: JDBC driver version  : 4.33.31
[8/7/24, 13:16:44:792 PDT] 0000002b eclipselink.server                                           W CWWJP9991W: [eclipselink.server] Failed to find MBean Serve
r: null or empty List returned from MBeanServerFactory.findMBeanServer(null)

server.xml

<featureManager>

    <!-- <feature>jakartaee-11.0</feature> -->
     <feature>servlet-6.1</feature>
     <!--  <feature>microProfile-6.1</feature> --> 
     <feature>ldapRegistry-3.0</feature>
     <feature>appSecurity-6.0</feature>
     <feature>persistence-3.2</feature>
     <feature>enterpriseBeans-4.0</feature>

   </featureManager>

  <httpEndpoint host="*" httpPort="9080" httpsPort="9443" id="defaultHttpEndpoint"> 
    <tcpOptions soReuseAddr="true"/> 
    <httpOptions maxKeepAliveRequests="-1"/>
  </httpEndpoint>

  <mpMetrics authentication="false" />

  <include optional="false" location="./ldap-config.xml"/>

<!-- This is new property for 4Q to make JAPSIC application works like non-JAPIC -->
<webAppSecurity useLtpaSSOForJaspic="true" />

<!-- This property was set to set custom cookie name to avoid conflict when using SSO -->
<!--<webAppSecurity useOnlyCustomCookieName="true" ssoCookieName="mstCookie"/> -->  

<!-- Replace DB server information below to connect to your own DB server -->
        <authData id="DBAuth" password="xxxx" user="db2inst1"/>

    <dataSource containerAuthDataRef="DBAuth" id="Messenger" jdbcDriverRef="JDBCDriver" jndiName="jdbc/Messenger" type="javax.sql.XADataSource">
         <properties.db2.jcc databaseName="MSGRDB" driverType="4" password="xxxx" portNumber="50000" serverName="localhost"  />
    </dataSource>

    <jdbcDriver id="JDBCDriver">
     <library>
      <fileset dir="/root/liberty/ee11/db2jars" id="db2jcc4" includes="db2jcc4.jar, db2jcc_license_cu.jar"/>
     </library>
    </jdbcDriver>

<!-- This allows certificate client to use basic authentication if certificate authentication does not succeed -->
<!--    <webAppSecurity allowFailOverToBasicAuth="true" useAuthenticationDataForUnprotectedResource="false"/> -->

<!-- Binding for QuickSec application -->
    <application context-root="QuickSec" id="QuickSec" location="${server.config.dir}/apps/QuickSec.ear" name="QuickSec" type="ear">
    <application-bnd> 
....

Additional context
Add any other context about the problem here.

There is disucsson on slack channel on this. It was possible to recreate this problem on FVT tests as well.

tkburroughs commented 2 months ago

This can be re-created by running the following FAT bucket:

gradlew com.ibm.ws.jpa.tests.jpa_32_fat:buildAndRun -Dfat.bucket.db.type=SQLServer

Using the default Derby database passes.

I enable -verbose:class in jvm.options and can see that the Derby driver accesses MBeanServerFactory, initializing the MBeanServer instance; whereas SQLServer and DB2 do not... so then EclipseLink becomes the first code to access MBeanServerFactory and finds the MBeanServer instance has not be created yet.

EclipseLink does handle this scenario, and ends up initializing the MBeanServer instance, but has logged the warning.

For EE 10, I'm guessing that some other feature is initializing the MBeanServer instance earlier, but that has changed for EE 11.

If we can identify the code that is initializing the MBeanServer instance

tkburroughs commented 2 months ago

The component that is creating the MBeanServer can be determined by adding the following in a jvm.options file:

-Xtrace:print=mt,methods={javax/management/MBeanServerFactory.*},trigger=method{javax/management/MBeanServerFactory.<clinit>,jstacktrace}

For EE 11; this shows that Derby creates the MBeanServer; thus no warning; SQLServer & DB2 do not, so EclipseLink warns

For EE 10; I see the same behavior.... the same warning occurs. Does not appear to be a new problem, just an exiting warning from EclipseLink that does not cause any failures; EclipseLink recovers fine and goes on.

tkburroughs commented 2 months ago

Improved jvm.options setting:

-Xtrace:print=mt,methods={javax/management/MBeanServerFactory.*},trigger=method{javax/management/MBeanServerFactory.<clinit>,jstacktrace},trigger=method{javax/management/MBeanServerFactory.createMBeanServer,jstacktrace}
tkburroughs commented 2 months ago

Added some extra debug in EclipseLink JMXServerPlatformBase.getMBeanServer() and found that in the "failing" scenarios, this code receives an empty list when calling MBeanServerFactory.findMBeanServer(null), which results in the warning and then goes on to call ManagementFactory.getPlatformMBeanServer() which works. I think this may just be a normal scenario for Liberty, and the warning can just be ignored... or even removed for Liberty.

My recommendation is: