History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: IDEADEV-11540
Type: Bug Bug
Status: Open Open
Priority: Normal Normal
Assignee: Nikolay Chashnikov
Reporter: Dean Thompson
Votes: 1
Watchers: 2
Operations

If you were logged in you would be able to see more operations.
IDEA: Development

non-deterministic failures starting Tomcat in debugger

Created: 01 Sep 06 18:45   Updated: 31 Jul 08 19:12
Component/s: J2EE.Deployment and Run.Tomcat
Fix Version/s: None

Original Estimate: Unknown Remaining Estimate: Unknown Time Spent: Unknown
File Attachments: 1. Zip Archive idea_tomcat_startup_race.zip (5 kb)

Environment:
Windows XP.
Tomcat 5.5.16.

Build: 5,581
Severity: High


 Description  « Hide
When I try to start a Tomcat project in the debugger, it fails about 20% to 50% of the time. (I go through good periods where it is about 20%, and bad periods where it is more like 50%.) I suspect a race condition, for several reasons:
  • There are a variety of failure modes, from missing jar files (which will not be missing next time) to mysterious unloading or reloading of the context. I will attach a zip file containing the log output from 4 different failure modes.
  • If I have a client attempting HTTP requests of Tomcat while I am starting Tomcat, the startup attempt is much more likely to fail – it sometimes seems 80% likely to fail.
  • I get the impression that if I wait longer after stopping Tomcat before restarting it, the startup is less likely to fail. It is hard to be sure of this, though.

I should also mention that startup very rarely fails on the first attempt in a newly started Idea.



 All   Comments   Work Log   Change History      Sort Order:
Dean Thompson - 15 Sep 06 01:45
Now this is happening to make on perhaps 90% of startup attempts. It makes it very difficult to use Tomcat within IDEA at all. I have to try over and over again until eventually it starts successfully. If there is anything I can do to help debug this, please let me know.

Dean Thompson - 16 Sep 06 01:12
I just experienced a new failure mode:

cmd /c C:\apache-tomcat-5.5.16\bin\catalina.bat run
Connected to the target VM, address: '127.0.0.1:3242', transport: 'socket'
Using CATALINA_BASE: C:\Documents and Settings\Dean Thompson\.IntelliJIdea60\system\tomcat_Tomcat_CME_2ca89961
Using CATALINA_HOME: C:\apache-tomcat-5.5.16
Using CATALINA_TMPDIR: C:\apache-tomcat-5.5.16\temp
Using JRE_HOME: C:\Program Files\Java\jdk1.5.0_06
Sep 15, 2006 5:10:35 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFO: The Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: C:\Program Files\Java\jdk1.5.0_06\bin;.;C:\WINDOWS\system32;C:\WINDOWS;c:\cygwin\home\Dean Thompson\bin;c:\Program Files\Java\jdk1.5.0_06\bin;c:\ruby\bin;c:\cygwin\usr\bin;c:\Program Files\apache-ant-1.6.5\bin;c:\java\anteater-0.9.16\bin;C:\Program Files\MySQL\MySQL Server 5.0\bin;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\Microsoft Office\OFFICE11\Business Contact Manager\IM;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;C:\Program Files\Microsoft Office\OFFICE11\Business Contact Manager\
Sep 15, 2006 5:10:36 PM org.apache.coyote.http11.Http11BaseProtocol init
INFO: Initializing Coyote HTTP/1.1 on http-8080
Sep 15, 2006 5:10:36 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 984 ms
Sep 15, 2006 5:10:36 PM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Sep 15, 2006 5:10:36 PM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/5.5.16
Sep 15, 2006 5:10:36 PM org.apache.catalina.core.StandardHost start
INFO: XML validation disabled
Sep 15, 2006 5:10:37 PM org.apache.catalina.core.StandardContext resourcesStart
SEVERE: Error starting static Resources
java.lang.IllegalArgumentException: Document base C:\apache-tomcat-5.5.16\webapps\cme does not exist or is not a readable directory
at org.apache.naming.resources.FileDirContext.setDocBase(FileDirContext.java:140)
at org.apache.catalina.core.StandardContext.resourcesStart(StandardContext.java:3814)
at org.apache.catalina.core.StandardContext.start(StandardContext.java:3985)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:759)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:739)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:524)
at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:904)
at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:867)
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:474)
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1112)
at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:310)
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1021)
at org.apache.catalina.core.StandardHost.start(StandardHost.java:718)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013)
at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442)
at org.apache.catalina.core.StandardService.start(StandardService.java:450)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:709)
at org.apache.catalina.startup.Catalina.start(Catalina.java:551)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:275)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)
Sep 15, 2006 5:10:37 PM org.apache.catalina.core.StandardContext start
SEVERE: Error in resourceStart()
Sep 15, 2006 5:10:37 PM org.apache.catalina.core.StandardContext start
SEVERE: Error getConfigured
Sep 15, 2006 5:10:37 PM org.apache.catalina.core.StandardContext start
SEVERE: Context [/cme] startup failed due to previous errors
Sep 15, 2006 5:10:37 PM org.apache.catalina.core.StandardContext stop
INFO: Container org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/cme] has not been started
Sep 15, 2006 5:10:38 PM org.apache.coyote.http11.Http11BaseProtocol start
INFO: Starting Coyote HTTP/1.1 on http-8080
Sep 15, 2006 5:10:38 PM org.apache.jk.common.ChannelSocket init
INFO: JK: ajp13 listening on /0.0.0.0:8009
Sep 15, 2006 5:10:38 PM org.apache.jk.server.JkMain start
INFO: Jk running ID=0 time=0/78 config=null
Sep 15, 2006 5:10:38 PM org.apache.catalina.storeconfig.StoreLoader load
INFO: Find registry server-registry.xml at classpath resource
Sep 15, 2006 5:10:39 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 2891 ms
Connected to server


Dean Thompson - 03 Nov 06 18:18
I have discovered a work-around that sheds light on the underlying problem. It turns out that every time I run Tomcat within IDEA, it creates a deployment directory within $CATALINA_HOME/webapps. (I don't know why it creates it there – seems to me that it should only create the deployment directory within $CATALINA_BASE/webapps.) If I delete the deployment directory from $CATALINA_HOME/webapps before starting Tomcat inside IDEA (every time I start Tomcat!), it reliably starts.

Vladimir - 31 Jul 08 19:12
Similar behaviour with IDEA 7.0.3 and Tomcat 6.0.16. Workaround was the same - ant task that removes deployment directory before every application launch. But it was real pain to work with Tomcat in IDEA before Dean's tip was found!