Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

EJB Timer not available when restarting /CUSTCOM-65 #1596

Closed
ctabin opened this issue May 12, 2017 · 9 comments
Closed

EJB Timer not available when restarting /CUSTCOM-65 #1596

ctabin opened this issue May 12, 2017 · 9 comments
Assignees
@MattGill98
Labels
Status: Accepted Confirmed defect or accepted improvement to implement, issue has been escalated to Platform Dev Type: Bug Label issue as a bug defect

Comments

@ctabin
Copy link
Contributor

ctabin commented May 12, 2017 •
edited
Loading

Description

In an embedded payara server, the second time it is deployed, an Exception "EJB Timer Service is not available" is thrown.

Context

We want to use the payara server (or GlassFish embedded) for testing our application. Since there are complex workflows, this involves to start/stop GlassFish multiple times with different configurations (domain.xml).

In order to do so, here is the piece of code we are using to start/stop an instance:

//first pass
GlassFishProperties gfprops = new GlassFishProperties();
gfprops.setConfigFileURI(domainFile.toURI().toString());

ClassLoader contentCL = new URLClassLoader(new URL[]{}, Thread.currentThread().getContextClassLoader());
BootstrapProperties bsprops = new BootstrapProperties();
GlassFishRuntime runtime = GlassFishRuntime.bootstrap(bsprops, contentCL);
GlassFish glassfish = runtime.newGlassFish(gfprops);
glassfish.start();

String depName = glassfish.getDeployer().deploy(earFile);
if(depName==null || depName.trim().isEmpty()) { throw new RuntimeException("Unable to deploy"); }

// do some tests

glassfish.getDeployer().undeploy(depName);
glassfish.stop();
glassfish.dispose();
runtime.shutdown(); //all works fine

At this point, all works perfectly fine. After the shutdown(), I expect that the whole GlassFish container is stopped and all its resources have been released. However, once the domain.xml file has been updated and the server restarts:

//second pass
ClassLoader contentCL = new URLClassLoader(new URL[]{}, Thread.currentThread().getContextClassLoader());
BootstrapProperties bsprops = new BootstrapProperties();
GlassFishRuntime runtime = GlassFishRuntime.bootstrap(bsprops, contentCL);
GlassFish glassfish = runtime.newGlassFish(gfprops);
glassfish.start(); //Exception: EJB Timer Service is not available
java.lang.RuntimeException: EJB Timer Service is not available
        at com.sun.ejb.containers.BaseContainer.startApplication(BaseContainer.java:4009)
        at org.glassfish.ejb.startup.EjbApplication.start(EjbApplication.java:163)
        at org.glassfish.internal.data.EngineRef.start(EngineRef.java:122)
        at org.glassfish.internal.data.ModuleInfo.start(ModuleInfo.java:291)
        at org.glassfish.internal.data.ApplicationInfo.start(ApplicationInfo.java:352)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:500)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:219)
        at org.glassfish.deployment.admin.DeployCommand.execute(DeployCommand.java:491)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:539)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:535)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.execute(CommandRunnerImpl.java:534)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:565)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:557)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:556)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:1464)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.access$1300(CommandRunnerImpl.java:109)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1846)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1722)
        at com.sun.enterprise.admin.cli.embeddable.DeployerImpl.deploy(DeployerImpl.java:134)
        at ch.astorm.MyCustomServer.start(SAINetServer.java:311)

After some research, it seems there was a bug like this in Glassfish 3 (see here).

What I tried

  • Playing with the ClassLoader passed to GlassFishRuntime.bootstrap(), but the only effect was to lose the runtime discovery, or dit nothing
  • Using a different pool for the jdbc/__TimerPool (ie mapping to a custom jdbc pool, as mentionned here, but the error is still present.
  • Completely cleaning the domain.xml of the __TimerPool references. Then during the first pass I get a message in the log that the pool is not found (all works fine), and the second pass still crashes at the same place with the same error.
  • Switched from glassfish-embedded-all to payara-embedded-all hoping the issue would be resolved.

Some more logs

Here are the messages I have during the first pass before my EAR is deployed:

Found populator: org.glassfish.kernel.embedded.EmbeddedDomainXml
May 12, 2017 3:43:18 PM org.glassfish.grizzly.config.Utils newInstance
WARNING: Instance could not be initialized. Class=interface org.glassfish.grizzly.http.server.AddOn, name=http-listener-1, realClassName=org.glassfish.grizzly.http2.Http2AddOn
May 12, 2017 3:43:18 PM com.sun.enterprise.v3.services.impl.GrizzlyProxy start0
INFO: Grizzly Framework 2.3.21 started in: 21ms - bound to [/0.0.0.0:8080]
May 12, 2017 3:43:18 PM org.glassfish.grizzly.config.Utils newInstance
WARNING: Instance could not be initialized. Class=interface org.glassfish.grizzly.http.server.AddOn, name=http-listener-2, realClassName=org.glassfish.grizzly.http2.Http2AddOn
May 12, 2017 3:43:18 PM com.sun.enterprise.v3.services.impl.GrizzlyProxy start0
INFO: Grizzly Framework 2.3.21 started in: 1ms - bound to [/0.0.0.0:8181]
May 12, 2017 3:43:18 PM org.glassfish.grizzly.config.Utils newInstance
WARNING: Instance could not be initialized. Class=interface org.glassfish.grizzly.http.server.AddOn, name=admin-listener, realClassName=org.glassfish.grizzly.http2.Http2AddOn
May 12, 2017 3:43:18 PM com.sun.enterprise.v3.services.impl.GrizzlyProxy start0
INFO: Grizzly Framework 2.3.21 started in: 1ms - bound to [/0.0.0.0:4848]
May 12, 2017 3:43:19 PM com.sun.enterprise.connectors.jms.util.JmsRaUtil getInstalledMqVersion
WARNING: jmsra.upgrade_check_failed
ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console. Set system property 'org.apache.logging.log4j.simplelog.StatusLogger.level' to TRACE to show Log4j2 internal initialization logging.
May 12, 2017 3:43:22 PM org.glassfish.security.services.impl.authorization.AuthorizationServiceImpl initialize
INFO: Authorization Service has successfully initialized.
May 12, 2017 3:43:22 PM com.sun.enterprise.security.auth.realm.Realm doInstantiate
INFO: Realm [sairealm] of classtype [com.sun.enterprise.security.auth.realm.jdbc.JDBCRealm] successfully created.
May 12, 2017 3:43:22 PM com.sun.enterprise.v3.services.impl.GrizzlyProxy start0
INFO: Grizzly Framework 2.3.21 started in: 2ms - bound to [/0.0.0.0:3700]
May 12, 2017 3:43:22 PM com.sun.enterprise.v3.server.AppServerStartup postStartupJob
INFO: Undefined Product Name - define product and version info in config/branding  0.0.0.0.0  (0) startup time : Embedded (523ms), startup services(4,217ms), total(4,740ms)
May 12, 2017 3:43:22 PM com.sun.enterprise.v3.services.impl.GrizzlyProxy start0
INFO: Grizzly Framework 2.3.21 started in: 13ms - bound to [/0.0.0.0:7676]
May 12, 2017 3:43:22 PM org.glassfish.admin.mbeanserver.JMXStartupService$JMXConnectorsStarterThread startConnector
INFO: JMXStartupService has started JMXConnector on JMXService URL service:jmx:rmi://sagittarius:8686/jndi/rmi://sagittarius:8686/jmxrmi
May 12, 2017 3:43:25 PM com.sun.enterprise.deployment.util.DOLUtils readRuntimeDeploymentDescriptor
WARNING: AS-DEPLOYMENT-00001
May 12, 2017 3:43:26 PM com.sun.enterprise.deployment.node.DeploymentDescriptorNode setElementValue
WARNING: AS-DEPLOYMENT-00015
May 12, 2017 3:43:26 PM com.sun.enterprise.deployment.node.DeploymentDescriptorNode setElementValue
WARNING: AS-DEPLOYMENT-00015
May 12, 2017 3:43:26 PM com.sun.enterprise.deployment.node.DeploymentDescriptorNode setElementValue
WARNING: AS-DEPLOYMENT-00015
May 12, 2017 3:43:26 PM com.sun.enterprise.deployment.node.DeploymentDescriptorNode setElementValue
WARNING: AS-DEPLOYMENT-00015
May 12, 2017 3:43:26 PM com.sun.enterprise.deployment.node.DeploymentDescriptorNode setElementValue
WARNING: AS-DEPLOYMENT-00015
May 12, 2017 3:43:26 PM com.sun.enterprise.deployment.node.DeploymentDescriptorNode setElementValue
WARNING: AS-DEPLOYMENT-00015
May 12, 2017 3:43:26 PM com.sun.enterprise.security.SecurityLifecycle <init>
INFO: Java security manager is disabled.
May 12, 2017 3:43:26 PM com.sun.enterprise.security.SecurityLifecycle onInitialization
INFO: Entering Security Startup Service.
May 12, 2017 3:43:26 PM com.sun.enterprise.security.PolicyLoader loadPolicy
INFO: Loading policy provider com.sun.enterprise.security.provider.PolicyWrapper.
May 12, 2017 3:43:26 PM com.sun.enterprise.security.SecurityLifecycle onInitialization
INFO: Security Service(s) started successfully.
May 12, 2017 3:43:26 PM com.sun.enterprise.security.web.integration.MapValue handleUncoveredMethods
WARNING: JACC: For the URL pattern /*:/HealthCheck, all but the following methods were uncovered: TRACE,HEAD,DELETE,POST,GET,OPTIONS,PUT
May 12, 2017 3:43:26 PM com.sun.enterprise.security.web.integration.MapValue handleUncoveredMethods
WARNING: JACC: For the URL pattern /HealthCheck, all but the following methods were uncovered: TRACE,HEAD,DELETE,POST,GET,OPTIONS,PUT
May 12, 2017 3:43:27 PM com.sun.gjc.spi.jdbc40.ConnectionHolder40 close
INFO: jdbc.unable_to_set_client_info
May 12, 2017 3:43:31 PM com.sun.enterprise.web.WebContainer createHttpListener
INFO: Created HTTP listener http-listener-1 on host/port 0.0.0.0:8080
May 12, 2017 3:43:31 PM com.sun.enterprise.web.WebContainer createHttpListener
INFO: Created HTTP listener http-listener-2 on host/port 0.0.0.0:8181
May 12, 2017 3:43:31 PM com.sun.enterprise.web.WebContainer createHttpListener
INFO: Created HTTP listener admin-listener on host/port 0.0.0.0:4848
May 12, 2017 3:43:31 PM com.sun.enterprise.web.WebContainer createHosts
INFO: Created virtual server server
May 12, 2017 3:43:31 PM com.sun.enterprise.web.WebContainer createHosts
INFO: Created virtual server __asadmin
May 12, 2017 3:43:31 PM org.apache.catalina.realm.JAASRealm setContainer
INFO: Setting JAAS app name glassfish-web
May 12, 2017 3:43:31 PM com.sun.enterprise.web.WebContainer loadSystemDefaultWebModules
INFO: Virtual server server loaded default web module
May 12, 2017 3:43:31 PM com.sun.ejb.containers.BaseContainer initializeHome
INFO: Portable JNDI names for EJB InitializerBean: [...]
May 12, 2017 3:43:33 PM com.sun.jts.CosTransactions.DefaultTransactionService setServerName
INFO: JTS5014: Recoverable JTS instance, serverId = [3700]
May 12, 2017 3:43:33 PM com.sun.ejb.containers.BaseContainer initializeHome
INFO: Portable JNDI names for EJB EntryPointBean: [...]
May 12, 2017 3:43:33 PM com.sun.ejb.containers.BaseContainer initializeHome
INFO: Glassfish-specific (Non-portable) JNDI names for EJB EntryPointBean: [...]
May 12, 2017 3:43:33 PM com.sun.ejb.containers.BaseContainer initializeHome
INFO: Portable JNDI names for EJB HealthCheckBean: [...]
May 12, 2017 3:43:33 PM com.sun.ejb.containers.BaseContainer initializeHome
INFO: Portable JNDI names for EJB AsyncWorkerBean: [...]
May 12, 2017 3:43:33 PM org.glassfish.ejb.persistent.timer.PersistentEJBTimerService deployEJBTimerService
INFO: Loading EJBTimerService. Please wait.
May 12, 2017 3:43:34 PM org.eclipse.persistence.session./file:/tmp/gfembed7051493699681016510tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App
INFO: EclipseLink, version: Eclipse Persistence Services - 2.6.0.payara-p1
May 12, 2017 3:43:35 PM org.eclipse.persistence.session./file:/tmp/gfembed7051493699681016510tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App.connection
INFO: /file:/tmp/gfembed7051493699681016510tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App login successful
May 12, 2017 3:43:35 PM com.sun.ejb.containers.BaseContainer initializeHome
INFO: Portable JNDI names for EJB TimerBean: [java:global/ejb-timer-service-app/TimerBean, java:global/ejb-timer-service-app/TimerBean!org.glassfish.ejb.persistent.timer.TimerLocal]
May 12, 2017 3:43:35 PM com.sun.enterprise.web.WebApplication start
INFO: Loading application [ejb-timer-service-app] at [/ejb-timer-service-app]
May 12, 2017 3:43:35 PM org.glassfish.ejb.persistent.timer.PersistentEJBTimerService initEJBTimerService
INFO: EJB5109:EJB Timer Service started successfully for data source [jdbc/__TimerPool]
May 12, 2017 3:43:35 PM org.glassfish.ejb.persistent.timer.PersistentEJBTimerService resetEJBTimers
INFO: ==> Restoring Timers ... 
May 12, 2017 3:43:35 PM org.glassfish.ejb.persistent.timer.PersistentEJBTimerService restoreEJBTimers
INFO: There are no EJB Timers owned by this server
May 12, 2017 3:43:35 PM org.glassfish.ejb.persistent.timer.PersistentEJBTimerService resetEJBTimers
INFO: <== ... Timers Restored.
May 12, 2017 3:43:35 PM com.sun.ejb.containers.BaseContainer initializeHome
INFO: Portable JNDI names for EJB TimerFactoryBean: [...]
...
May 12, 2017 3:44:07 PM org.eclipse.persistence.session./file:/tmp/gfembed7051493699681016510tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App.connection
INFO: /file:/tmp/gfembed7051493699681016510tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App logout successful
May 12, 2017 3:44:07 PM org.eclipse.persistence.default
WARNING: session_manager_no_partition
JdbcRuntimeExtension,  getAllSystemRAResourcesAndPools = [GlassFishConfigBean.org.glassfish.jdbc.config.JdbcResource, GlassFishConfigBean.org.glassfish.jdbc.config.JdbcConnectionPool, GlassFishConfigBean.org.glassfish.jdbc.config.JdbcConnectionPool, GlassFishConfigBean.org.glassfish.jdbc.config.JdbcResource]

And then, during the second pass, up to the Exception:

Found populator: org.glassfish.kernel.embedded.EmbeddedDomainXml
May 12, 2017 3:44:13 PM com.sun.enterprise.web.WebContainer createHttpListener
INFO: Created HTTP listener http-listener-1 on host/port 0.0.0.0:8080
May 12, 2017 3:44:13 PM com.sun.enterprise.web.WebContainer createHttpListener
INFO: Created HTTP listener http-listener-2 on host/port 0.0.0.0:8181
May 12, 2017 3:44:13 PM com.sun.enterprise.web.WebContainer createHttpListener
INFO: Created HTTP listener admin-listener on host/port 0.0.0.0:4848
May 12, 2017 3:44:13 PM com.sun.enterprise.web.WebContainer createHosts
INFO: Created virtual server server
May 12, 2017 3:44:13 PM com.sun.enterprise.web.WebContainer createHosts
INFO: Created virtual server __asadmin
May 12, 2017 3:44:13 PM org.apache.catalina.realm.JAASRealm setContainer
INFO: Setting JAAS app name glassfish-web
May 12, 2017 3:44:13 PM com.sun.enterprise.web.WebContainer loadSystemDefaultWebModules
INFO: Virtual server server loaded default web module 
May 12, 2017 3:44:13 PM org.eclipse.persistence.session./file:/tmp/gfembed7044424746449664509tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App
INFO: EclipseLink, version: Eclipse Persistence Services - 2.6.0.payara-p1
May 12, 2017 3:44:13 PM org.eclipse.persistence.session./file:/tmp/gfembed7044424746449664509tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App.connection
INFO: /file:/tmp/gfembed7044424746449664509tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App login successful
May 12, 2017 3:44:13 PM org.eclipse.persistence.session./file:/tmp/gfembed7044424746449664509tmp/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App.server
WARNING: Failed to find MBean Server: null or empty List returned from MBeanServerFactory.findMBeanServer(null)
May 12, 2017 3:44:13 PM com.sun.enterprise.web.WebApplication start
INFO: Loading application [ejb-timer-service-app] at [/ejb-timer-service-app]
May 12, 2017 3:44:13 PM org.glassfish.internal.data.ModuleInfo start
SEVERE: Exception while invoking class org.glassfish.ejb.startup.EjbApplication start method
java.lang.RuntimeException: EJB Timer Service is not available
        at com.sun.ejb.containers.BaseContainer.startApplication(BaseContainer.java:4009)
        at org.glassfish.ejb.startup.EjbApplication.start(EjbApplication.java:163)
        at org.glassfish.internal.data.EngineRef.start(EngineRef.java:122)
        at org.glassfish.internal.data.ModuleInfo.start(ModuleInfo.java:291)
        at org.glassfish.internal.data.ApplicationInfo.start(ApplicationInfo.java:352)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:500)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:219)
        at org.glassfish.deployment.admin.DeployCommand.execute(DeployCommand.java:491)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:539)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:535)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.execute(CommandRunnerImpl.java:534)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:565)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:557)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:556)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:1464)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.access$1300(CommandRunnerImpl.java:109)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1846)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1722)
        at com.sun.enterprise.admin.cli.embeddable.DeployerImpl.deploy(DeployerImpl.java:134)
        at ch.saierp.sainet.testing.server.SAINetServer.start(SAINetServer.java:311)
        at ch.saierp.sainet.testing.server.SAINetServerTest.testBasicDeployment(SAINetServerTest.java:49)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at org.junit.runners.Suite.runChild(Suite.java:128)
        at org.junit.runners.Suite.runChild(Suite.java:27)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
        at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:157)
        at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:386)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:323)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:143)

May 12, 2017 3:44:13 PM com.sun.enterprise.v3.server.ApplicationLifecycle deploy
SEVERE: Exception during lifecycle processing
java.lang.RuntimeException: EJB Timer Service is not available
        at com.sun.ejb.containers.BaseContainer.startApplication(BaseContainer.java:4009)
        at org.glassfish.ejb.startup.EjbApplication.start(EjbApplication.java:163)
        at org.glassfish.internal.data.EngineRef.start(EngineRef.java:122)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
        at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:157)
        at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:386)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:323)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:143)

May 12, 2017 3:44:13 PM com.sun.enterprise.v3.server.ApplicationLifecycle deploy
SEVERE: Exception during lifecycle processing
java.lang.RuntimeException: EJB Timer Service is not available
        at com.sun.ejb.containers.BaseContainer.startApplication(BaseContainer.java:4009)
        at org.glassfish.ejb.startup.EjbApplication.start(EjbApplication.java:163)
        at org.glassfish.internal.data.EngineRef.start(EngineRef.java:122)
        at org.glassfish.internal.data.ModuleInfo.start(ModuleInfo.java:291)
        at org.glassfish.internal.data.ApplicationInfo.start(ApplicationInfo.java:352)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:500)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:219)
        at org.glassfish.deployment.admin.DeployCommand.execute(DeployCommand.java:491)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:539)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:535)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.execute(CommandRunnerImpl.java:534)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:565)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:557)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:556)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:1464)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.access$1300(CommandRunnerImpl.java:109)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1846)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1722)
        at com.sun.enterprise.admin.cli.embeddable.DeployerImpl.deploy(DeployerImpl.java:134)
        at ch.saierp.sainet.testing.server.SAINetServer.start(SAINetServer.java:311)
        at ch.saierp.sainet.testing.server.SAINetServerTest.testBasicDeployment(SAINetServerTest.java:49)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at org.junit.runners.Suite.runChild(Suite.java:128)
        at org.junit.runners.Suite.runChild(Suite.java:27)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
        at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
        at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:157)
        at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:386)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:323)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:143)

May 12, 2017 3:44:13 PM org.glassfish.api.ActionReport failure
SEVERE: Exception while loading the app
May 12, 2017 3:44:13 PM com.sun.enterprise.web.WebContainer unloadWebModule

Maven configuration

<dependency>
  <groupId>fish.payara.extras</groupId>
  <artifactId>payara-embedded-all</artifactId>
  <version>4.1.1.171.1</version>
</dependency>

Environment

  • Payara Version: 4.1.1.171.1
  • Edition: payara-embedded-all
  • JDK Version: Oracle JDK 1.8
  • Operating System: Linux Debian
  • Database: H2
@MattGill98
Copy link
Contributor

MattGill98 commented May 12, 2017 •
edited by mikecroft
Loading

Hi @ctabin,
Thank you for the detailed issue! I've managed to reproduce the problem, it seems to be an issue with the security manager being overwritten on the second instance. I've created this as internal issue PAYARA-1651. As a temporary fix I managed to prevent the errors by finding the <security-service> block in the server-config and changing it to <security-service activate-default-principal-to-role-mapping="true" jacc="simple">. Let me know if that solves it for you!

@ctabin
Copy link
Contributor Author

ctabin commented May 12, 2017

Hello @MattGill98
I just tried it now and it seems that is solves the EJB Timer problem.
Thanks you very much for your quick solution !

Can you provide me some further explanation about your fix ? I don't get how you it solves the problem.
How did you come to this solution ? I was digging in the source code (EJBTimerService), but it doesn't seem to be related at all with it.

I don't know if you have some code fix to do, so I let the issue open.
Since the fix worked for me, it's fine to close it.

Best regards,
Cédric

@mikecroft mikecroft added Status: Accepted Confirmed defect or accepted improvement to implement, issue has been escalated to Platform Dev Type: Bug Label issue as a bug defect labels May 14, 2017
@MattGill98
Copy link
Contributor

Hi @ctabin,
I'm glad that fixes it for you! The problem comes from the timer service (amongst other things) requiring a specific MBean permission which seems to be getting replaced for the second startup of the application. If you want to find the error in the log it's just before the bit you posted (sods law!):
INFO: JACC Policy Provider: Failed Permission Check, context(ejb-timer-service-app/ejb-timer-service-app_internal)- permission(("javax.security.jacc.EJBMethodPermission" "TimerBean" "findActiveTimersOwnedByThisServer,Local,"))
Just before that you'll see where the permissions file is being replaced. The temporary fix switches the jacc provider to another working provider (simple) with sensible defaults.

I'll leave this issue open until a permanent fix is available.

Kind regards,
Matt

@ctabin ctabin mentioned this issue May 18, 2017
Closed
@smillidge
Copy link
Contributor

Please try Payara 5 and see if it is still a problem there.

@ctabin
Copy link
Contributor Author

ctabin commented Sep 4, 2019

Hello @smillidge,

I'm sorry to come back so late. So we've update to the latest version of Payara (5.193) and the error is still present without the configuration mentioned by @MattGill98:

SEVERE: Exception while invoking class org.glassfish.ejb.startup.EjbApplication start method
java.lang.RuntimeException: EJB Timer Service is not available
        at com.sun.ejb.containers.BaseContainer.startApplication(BaseContainer.java:4120)
        at org.glassfish.ejb.startup.EjbApplication.start(EjbApplication.java:166)
        at org.glassfish.internal.data.EngineRef.start(EngineRef.java:123)
        at org.glassfish.internal.data.ModuleInfo.start(ModuleInfo.java:280)
        at org.glassfish.internal.data.ApplicationInfo.start(ApplicationInfo.java:344)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.initialize(ApplicationLifecycle.java:574)
        at org.glassfish.deployment.admin.DeployCommand.execute(DeployCommand.java:542)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:558)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:554)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.execute(CommandRunnerImpl.java:553)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:584)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:576)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:575)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:1495)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl.access$1300(CommandRunnerImpl.java:120)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1877)
        at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1753)
        at com.sun.enterprise.admin.cli.embeddable.DeployerImpl.deploy(DeployerImpl.java:136)

By adding the activate-default-principal-to-role-mapping="true" jacc="simple" attributes, then all is fine.

@ctabin
Copy link
Contributor Author

ctabin commented Nov 30, 2019

@smillidge FYI the problem is still present in 5.194 (JDK 8). Even worse, without changing any configuration (the attributes activate-default-principal-to-role-mapping="true" jacc="simple" are set), the realm seems to be ignored when Payara is restarted in the same VM, hence it is not possible to log in anymore (using JDBCRealm) 😞 That's probably worse another issue ?

@ctabin
Copy link
Contributor Author

ctabin commented Nov 30, 2019

I could get an interesting stack trace by activating the logging with SecurityLoggerInfo.getLogger().setLevel(Level.FINEST);:

SEVERE: jdbcrealm.invaliduser
FINE: Cannot validate user
javax.security.auth.login.LoginException: Unable to connect to datasource jndidb for database user myuser.                                                                                                                                      
        at com.sun.enterprise.security.auth.realm.jdbc.JDBCRealm.getConnection(JDBCRealm.java:547)
        at com.sun.enterprise.security.auth.realm.jdbc.JDBCRealm.isUserValid(JDBCRealm.java:380)
        at com.sun.enterprise.security.auth.realm.jdbc.JDBCRealm.authenticate(JDBCRealm.java:295)
        at com.sun.enterprise.security.ee.auth.login.JDBCLoginModule.authenticateUser(JDBCLoginModule.java:77)
        at com.sun.enterprise.security.BasePasswordLoginModule.login(BasePasswordLoginModule.java:143)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at javax.security.auth.login.LoginContext.invoke(LoginContext.java:755)
        at javax.security.auth.login.LoginContext.access$000(LoginContext.java:195)
        at javax.security.auth.login.LoginContext$4.run(LoginContext.java:682)
        at javax.security.auth.login.LoginContext$4.run(LoginContext.java:680)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
        at javax.security.auth.login.LoginContext.login(LoginContext.java:587)
        at com.sun.enterprise.security.auth.login.LoginContextDriver.tryJaasLogin(LoginContextDriver.java:194)
        at com.sun.enterprise.security.auth.WebAndEjbToJaasBridge.doPasswordLogin(WebAndEjbToJaasBridge.java:387)
        at com.sun.enterprise.security.auth.WebAndEjbToJaasBridge.login(WebAndEjbToJaasBridge.java:183)
        at com.sun.enterprise.security.auth.WebAndEjbToJaasBridge.login(WebAndEjbToJaasBridge.java:143)
        at com.sun.web.security.RealmAdapter.authenticate(RealmAdapter.java:912)
        at com.sun.web.security.RealmAdapter.authenticate(RealmAdapter.java:550)
        at org.apache.catalina.authenticator.AuthenticatorBase.doLogin(AuthenticatorBase.java:799)
        at org.apache.catalina.authenticator.AuthenticatorBase.login(AuthenticatorBase.java:783)
        at org.apache.catalina.connector.Request.login(Request.java:1983)
        at org.apache.catalina.connector.Request.login(Request.java:1962)
        at org.apache.catalina.connector.RequestFacade.login(RequestFacade.java:1088)
        ...
Caused by: java.lang.IllegalArgumentException: The descriptor passed to getServiceHandle is not associated with this ServiceLocator (id=4).  It is associated ServiceLocator id=0                                                                 
        at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:598)
        at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:627)
        at com.sun.enterprise.security.auth.realm.jdbc.JDBCRealm.getConnection(JDBCRealm.java:536)

Hopefully it can help ! Also, it could be more related to #1606 🤔

@rdebusscher
Copy link

Tracked now by CUSTCOM-65

@OndroMih OndroMih changed the title EJB Timer not available when restarting EJB Timer not available when restarting /CUSTCOM-65 Feb 4, 2020
@AlanRoth
Copy link

Hi, due to how long ago this issue was raised we have decided to close the issue immediately, and not consider the implementation of the fix/improvement that was requested. Please understand that this decision was taken into consideration with the resources that we have available at the moment. In case of having reported a bug, if the issue is still pressing to you, feel free to verify if it’s applicable in the current release of Payara Community edition, and proceed to raise a new issue with details of the test reproducer. Many thanks for your understanding.

@ctabin ctabin mentioned this issue Dec 19, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@MattGill98 MattGill98

Labels
Status: Accepted Confirmed defect or accepted improvement to implement, issue has been escalated to Platform Dev Type: Bug Label issue as a bug defect
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@smillidge @rdebusscher @mikecroft @ctabin @MattGill98 @AlanRoth