Can someone tell me from this log file if openejb is starting before or after my webapp

Question

I am running an enterprise Java app, using openEJB's TomEE++. The app is being started from within Eclipse Helios. I have changed the 'server Locations' in Eclipse, to allow Eclipse to take charge of Tomcat.

When I start the application from within Eclipse, I get some strange JPA errors, which I am thinking might come from the fact that the openejb webapp is being loaded after my webapp, called 'slides'

I have changed the load-on-startup value of my webapp in web.xml to 20, while openejb has a value of 0.

From the console's output, I am not able to figure out if openejb is starting before or after my application. The logs seem to be a bit contradictory.

Right at the begining, I can see

ERROR: OpenEJB webapp was not found

which seems to suggest that openejb did not start. But soon after that I see lines such as

INFO: OpenWebBeans Container is starting...

Which in my limited knowledge would come from openejb.

After that a bunch of things happen, including the startup of several apps, including mine.

TomcatWebAppBuilder.start /slides

After that, I spot a line which suggests that openejb has started

TomcatWebAppBuilder.start /openejb

So, what exactly is happening ? Is openejb starting before or after my application ?

Posting the logs below:

Apr 18, 2012 1:04:46 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/lib/jvm/java-6-sun-1.6.0.26/jre/lib/amd64/server:/usr/lib/jvm/java-6-sun-1.6.0.26/jre/lib/amd64:/usr/lib/jvm/java-6-sun-1.6.0.26/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
Apr 18, 2012 1:04:47 PM org.apache.tomcat.util.digester.SetPropertiesRule begin
WARNING: [SetPropertiesRule]{Server/Service/Engine/Host/Context} Setting property 'source' to 'org.eclipse.jst.j2ee.server:slides' did not find a matching property.
ERROR: OpenEJB webapp was not found
Apr 18, 2012 1:04:47 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8080"]
Apr 18, 2012 1:04:47 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8009"]
Apr 18, 2012 1:04:48 PM org.apache.openejb.cdi.CdiBuilder initializeOWB
INFO: Created new singletonService org.apache.openejb.cdi.ThreadSingletonServiceImpl@34b23d12
Apr 18, 2012 1:04:48 PM org.apache.openejb.cdi.CdiBuilder initializeOWB
INFO: succeeded in installing singleton service
Apache OpenEJB 4.0.0-beta-2    build: 20120115-08:26
http://openejb.apache.org/
Apr 18, 2012 1:04:52 PM org.apache.openejb.cdi.CdiBuilder build
INFO: existing thread singleton service in SystemInstance() org.apache.openejb.cdi.ThreadSingletonServiceImpl@34b23d12
Apr 18, 2012 1:04:53 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container is starting...
Apr 18, 2012 1:04:53 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [CdiPlugin]
Apr 18, 2012 1:04:53 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [OpenWebBeansJsfPlugin]
Apr 18, 2012 1:04:53 PM org.apache.openejb.cdi.BeansDeployer validateInjectionPoints
INFO: All injection points were validated successfully.
Apr 18, 2012 1:04:53 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container has started, it took [142] ms.
Apr 18, 2012 1:04:53 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 7751 ms
Apr 18, 2012 1:04:53 PM org.apache.catalina.core.StandardService startInternal
INFO: Starting service Catalina
Apr 18, 2012 1:04:53 PM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.21
TomcatWebAppBuilder.start /slides
[severity=ERROR,message=unexpected element (uri:"", local:"global"). Expected elements are <{http://jboss.org/xml/ns/javax/validation/configuration}constraint-validator-factory>,<{http://jboss.org/xml/ns/javax/validation/configuration}property>,<{http://jboss.org/xml/ns/javax/validation/configuration}traversable-resolver>,<{http://jboss.org/xml/ns/javax/validation/configuration}constraint-mapping>,<{http://jboss.org/xml/ns/javax/validation/configuration}message-interpolator>,<{http://jboss.org/xml/ns/javax/validation/configuration}default-provider>,locator=[node=null,object=null,url=null,line=13,col=13,offset=-1]]
[severity=ERROR,message=unexpected element (uri:"", local:"global"). Expected elements are <{http://jboss.org/xml/ns/javax/validation/configuration}constraint-validator-factory>,<{http://jboss.org/xml/ns/javax/validation/configuration}property>,<{http://jboss.org/xml/ns/javax/validation/configuration}traversable-resolver>,<{http://jboss.org/xml/ns/javax/validation/configuration}constraint-mapping>,<{http://jboss.org/xml/ns/javax/validation/configuration}message-interpolator>,<{http://jboss.org/xml/ns/javax/validation/configuration}default-provider>,locator=[node=null,object=null,url=null,line=13,col=13,offset=-1]]
Apr 18, 2012 1:05:02 PM org.apache.openejb.cdi.CdiBuilder build
INFO: existing thread singleton service in SystemInstance() org.apache.openejb.cdi.ThreadSingletonServiceImpl@34b23d12
Apr 18, 2012 1:05:02 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container is starting...
Apr 18, 2012 1:05:02 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [CdiPlugin]
Apr 18, 2012 1:05:02 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [OpenWebBeansJsfPlugin]
Apr 18, 2012 1:05:02 PM org.apache.openejb.cdi.BeansDeployer validateInjectionPoints
INFO: All injection points were validated successfully.
Apr 18, 2012 1:05:02 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container has started, it took [13] ms.
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/core_rt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/core is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/fmt_rt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/fmt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://jakarta.apache.org/taglibs/standard/permittedTaglibs is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://jakarta.apache.org/taglibs/standard/scriptfree is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/sql_rt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/sql is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/xml_rt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/xml is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/fmt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/fmt_rt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jsp/jstl/core is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jsp/jstl/fmt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/core_rt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/xml is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/xml_rt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://jakarta.apache.org/taglibs/standard/permittedTaglibs is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/sql is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jsp/jstl/functions is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/sql_rt is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jstl/core is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jsp/jstl/xml is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://java.sun.com/jsp/jstl/sql is already defined
Apr 18, 2012 1:05:03 PM org.apache.catalina.startup.TaglibUriRule body
INFO: TLD skipped. URI: http://jakarta.apache.org/taglibs/standard/scriptfree is already defined
Apr 18, 2012 1:05:05 PM org.apache.myfaces.shared.config.MyfacesConfig createAndInitializeMyFacesConfig
INFO: Tomahawk jar not available. Autoscrolling, DetectJavascript, AddResourceClass and CheckExtensionsFilter are disabled now.
Apr 18, 2012 1:05:05 PM org.apache.myfaces.webapp.AbstractFacesInitializer initFaces
WARNING: No mappings of FacesServlet found. Abort initializing MyFaces.
Apr 18, 2012 1:05:06 PM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory manager
TomcatWebAppBuilder.start /manager
Apr 18, 2012 1:05:07 PM org.apache.openejb.cdi.CdiBuilder build
INFO: existing thread singleton service in SystemInstance() org.apache.openejb.cdi.ThreadSingletonServiceImpl@34b23d12
Apr 18, 2012 1:05:07 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container is starting...
Apr 18, 2012 1:05:07 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [CdiPlugin]
Apr 18, 2012 1:05:07 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [OpenWebBeansJsfPlugin]
Apr 18, 2012 1:05:07 PM org.apache.openejb.cdi.BeansDeployer validateInjectionPoints
INFO: All injection points were validated successfully.
Apr 18, 2012 1:05:07 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container has started, it took [9] ms.
using context file /home/user/bin/tomcat/SlidesServer/apache-tomee-webprofile-1.0.0-beta-2/webapps/manager/META-INF/context.xml
Apr 18, 2012 1:05:07 PM org.apache.myfaces.shared.config.MyfacesConfig createAndInitializeMyFacesConfig
INFO: Tomahawk jar not available. Autoscrolling, DetectJavascript, AddResourceClass and CheckExtensionsFilter are disabled now.
Apr 18, 2012 1:05:07 PM org.apache.myfaces.webapp.AbstractFacesInitializer initFaces
WARNING: No mappings of FacesServlet found. Abort initializing MyFaces.
Apr 18, 2012 1:05:07 PM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory docs
TomcatWebAppBuilder.start /docs
Apr 18, 2012 1:05:08 PM org.apache.openejb.cdi.CdiBuilder build
INFO: existing thread singleton service in SystemInstance() org.apache.openejb.cdi.ThreadSingletonServiceImpl@34b23d12
Apr 18, 2012 1:05:08 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container is starting...
Apr 18, 2012 1:05:08 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [CdiPlugin]
Apr 18, 2012 1:05:08 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [OpenWebBeansJsfPlugin]
Apr 18, 2012 1:05:08 PM org.apache.openejb.cdi.BeansDeployer validateInjectionPoints
INFO: All injection points were validated successfully.
Apr 18, 2012 1:05:08 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container has started, it took [14] ms.
Apr 18, 2012 1:05:08 PM org.apache.myfaces.shared.config.MyfacesConfig createAndInitializeMyFacesConfig
INFO: Tomahawk jar not available. Autoscrolling, DetectJavascript, AddResourceClass and CheckExtensionsFilter are disabled now.
Apr 18, 2012 1:05:08 PM org.apache.myfaces.webapp.AbstractFacesInitializer initFaces
WARNING: No mappings of FacesServlet found. Abort initializing MyFaces.
Apr 18, 2012 1:05:08 PM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory ROOT
TomcatWebAppBuilder.start 
Apr 18, 2012 1:05:08 PM org.apache.openejb.cdi.CdiBuilder build
INFO: existing thread singleton service in SystemInstance() org.apache.openejb.cdi.ThreadSingletonServiceImpl@34b23d12
Apr 18, 2012 1:05:08 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container is starting...
Apr 18, 2012 1:05:08 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [CdiPlugin]
Apr 18, 2012 1:05:08 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [OpenWebBeansJsfPlugin]
Apr 18, 2012 1:05:08 PM org.apache.openejb.cdi.BeansDeployer validateInjectionPoints
INFO: All injection points were validated successfully.
Apr 18, 2012 1:05:08 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container has started, it took [6] ms.
Apr 18, 2012 1:05:08 PM org.apache.myfaces.shared.config.MyfacesConfig createAndInitializeMyFacesConfig
INFO: Tomahawk jar not available. Autoscrolling, DetectJavascript, AddResourceClass and CheckExtensionsFilter are disabled now.
Apr 18, 2012 1:05:08 PM org.apache.myfaces.webapp.AbstractFacesInitializer initFaces
WARNING: No mappings of FacesServlet found. Abort initializing MyFaces.
Apr 18, 2012 1:05:08 PM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory host-manager
TomcatWebAppBuilder.start /host-manager
Apr 18, 2012 1:05:09 PM org.apache.openejb.cdi.CdiBuilder build
INFO: existing thread singleton service in SystemInstance() org.apache.openejb.cdi.ThreadSingletonServiceImpl@34b23d12
Apr 18, 2012 1:05:09 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container is starting...
Apr 18, 2012 1:05:09 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [CdiPlugin]
Apr 18, 2012 1:05:09 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [OpenWebBeansJsfPlugin]
Apr 18, 2012 1:05:09 PM org.apache.openejb.cdi.BeansDeployer validateInjectionPoints
INFO: All injection points were validated successfully.
Apr 18, 2012 1:05:09 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container has started, it took [8] ms.
using context file /home/user/bin/tomcat/SlidesServer/apache-tomee-webprofile-1.0.0-beta-2/webapps/host-manager/META-INF/context.xml
Apr 18, 2012 1:05:09 PM org.apache.myfaces.shared.config.MyfacesConfig createAndInitializeMyFacesConfig
INFO: Tomahawk jar not available. Autoscrolling, DetectJavascript, AddResourceClass and CheckExtensionsFilter are disabled now.
Apr 18, 2012 1:05:09 PM org.apache.myfaces.webapp.AbstractFacesInitializer initFaces
WARNING: No mappings of FacesServlet found. Abort initializing MyFaces.
Apr 18, 2012 1:05:09 PM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory openejb
TomcatWebAppBuilder.start /openejb
Apr 18, 2012 1:05:09 PM org.apache.openejb.cdi.CdiBuilder build
INFO: existing thread singleton service in SystemInstance() org.apache.openejb.cdi.ThreadSingletonServiceImpl@34b23d12
Apr 18, 2012 1:05:09 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container is starting...
Apr 18, 2012 1:05:09 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [CdiPlugin]
Apr 18, 2012 1:05:09 PM org.apache.webbeans.plugins.PluginLoader startUp
INFO: Adding OpenWebBeansPlugin : [OpenWebBeansJsfPlugin]
Apr 18, 2012 1:05:09 PM org.apache.openejb.cdi.BeansDeployer validateInjectionPoints
INFO: All injection points were validated successfully.
Apr 18, 2012 1:05:09 PM org.apache.openejb.cdi.OpenEJBLifecycle startApplication
INFO: OpenWebBeans Container has started, it took [9] ms.
using context file /home/user/bin/tomcat/SlidesServer/apache-tomee-webprofile-1.0.0-beta-2/webapps/openejb/META-INF/context.xml
Apr 18, 2012 1:05:09 PM org.apache.myfaces.shared.config.MyfacesConfig createAndInitializeMyFacesConfig
INFO: Tomahawk jar not available. Autoscrolling, DetectJavascript, AddResourceClass and CheckExtensionsFilter are disabled now.
Apr 18, 2012 1:05:09 PM org.apache.myfaces.webapp.AbstractFacesInitializer initFaces
WARNING: No mappings of FacesServlet found. Abort initializing MyFaces.
OpenEJB Loader init-params:
    There are no initialization parameters.
Apr 18, 2012 1:05:10 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Apr 18, 2012 1:05:10 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Apr 18, 2012 1:05:10 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 16795 ms
Apr 18, 2012 1:05:11 PM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet [action] in context with path [/slides] threw exception [javax.ejb.EJBException: The bean encountered a non-application exception; nested exception is: 
    <openjpa-2.1.1-r422266:1148538 nonfatal general error> org.apache.openjpa.persistence.PersistenceException: null
FailedObject: Select s from SlideShow s [java.lang.String]] with root cause

Answer 1

Sounds more like the JavaAgent isn't used when Tomcat/TomEE is started from Eclipse. There's an openejb-javaagent jar file that need to specified on the command line via the -javaagent vm parameter.

This turns on the OpenJPA bytecode enhancer and makes all the JPA functionality work properly. It will work somewhat without the -javaagent vm flag as OpenJPA has limited support for the subclass-based approach to implementing JPA (only two ways to implement JPA: subclassing entity classes or bytecode enhancing entity classes). Hibernate uses only subclassing, for example, and doesn't need a javaagent.

A vanilla Tomcat startup command will have these arguments:

/System/Library/Frameworks/JavaVM.framework/Versions/CurrentJDK/Home/bin/java
-Djava.util.logging.config.file=<tomcat-home>/conf/logging.properties
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.endorsed.dirs=<tomcat-home>/endorsed
-classpath <tomcat-home>/bin/bootstrap.jar:<tomcat-home>/bin/tomcat-juli.jar
-Dcatalina.base=<tomcat-home>
-Dcatalina.home=<tomcat-home>
-Djava.io.tmpdir=<tomcat-home>/temp
org.apache.catalina.startup.Bootstrap
start

A TomEE install will have one extra -javaagent as OpenJPA requires it (can be omitted if using Hibernate instead).

/System/Library/Frameworks/JavaVM.framework/Versions/CurrentJDK/Home/bin/java
-Djava.util.logging.config.file=<tomcat-home>/conf/logging.properties
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.endorsed.dirs=<tomcat-home>/endorsed
-classpath <tomcat-home>/bin/bootstrap.jar:<tomcat-home>/bin/tomcat-juli.jar
-Dcatalina.base=<tomcat-home>
-Dcatalina.home=<tomcat-home>
-Djava.io.tmpdir=<tomcat-home>/temp
-javaagent:<tomcat-home>/lib/openejb-javaagent.jar
org.apache.catalina.startup.Bootstrap
start