-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Debbie,
On 3/9/12 1:09 PM, Debbie Shapiro wrote: > From: Christopher Schultz [mailto:ch...@christopherschultz.net] >> >> So, your load-on-startup servlet somehow restarts your services? >> When you say "services", do you mean it restarts Tomcat? How does >> it do that? > > No, it forces (or is supposed to) InetSoft's application to load > when the service starts up. Right: that's what's supposed to happen. I just wanted to make sure you understood the difference between starting the Windows service and starting your InetSoft servlet (which could be thought of as a "service"). >> My immediate guess would be that when you run it manually, you >> are logged-in as yourself, while the scheduled task runs as some >> other user. Any file permission issues that might be in play? > > Nothing has changed on this server between having Tomcat 7.0.23 > installed and upgrading to 7.0.26. Famous last words :) > I typically don't log out of these servers (though it might be > locked), so the same user is logged in regardless of whether it is > starting up automatically or a manual start up. Tomcat is using a > Local System account for login. How do you start Tomcat when you start it "manually"? How about when you schedule a restart? >>> The only difference I am seeing is that in the Catalina log, >>> the automated process ends with: >> >>> Mar 7, 2012 11:30:06 PM org.apache.coyote.AbstractProtocol >>> stop INFO: Stopping ProtocolHandler ["http-bio-8080"] Mar 7, >>> 2012 11:30:06 PM org.apache.coyote.AbstractProtocol stop INFO: >>> Stopping ProtocolHandler ["ajp-bio-8009"] >> >> That's Tomcat stopping. Is there more above that line? Perhaps >> some kind of exception and/or stack trace? > > There are errors shown here. This is everything logged from the > point of the automated restart. I mentioned the warnings about the > memory leaks to InetSoft and they indicated that these are only > warnings and that I shouldn't be concerned about them, but I see > there are other errors here now as well. > > Mar 7, 2012 11:30:01 PM org.apache.coyote.AbstractProtocol pause > INFO: Pausing ProtocolHandler ["http-bio-8080"] Mar 7, 2012 > 11:30:01 PM org.apache.coyote.AbstractProtocol pause INFO: Pausing > ProtocolHandler ["ajp-bio-8009"] Mar 7, 2012 11:30:01 PM > org.apache.catalina.core.StandardService stopInternal INFO: > Stopping service Catalina Mar 7, 2012 11:30:06 PM > com.sun.xml.ws.transport.http.servlet.WSServletDelegate destroy > INFO: WSSERVLET15: JAX-WS servlet destroyed Mar 7, 2012 11:30:06 PM > com.sun.xml.ws.transport.http.servlet.WSServletContextListener > contextDestroyed INFO: WSSERVLET13: JAX-WS context listener > destroyed Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader clearReferencesJdbc > SEVERE: The web application [/sree] registered the JDBC driver > [com.microsoft.sqlserver.jdbc.SQLServerDriver] but failed to > unregister it when the web application was stopped. To prevent a > memory leak, the JDBC Driver has been forcibly unregistered. Mar 7, > 2012 11:30:06 PM org.apache.catalina.loader.WebappClassLoader > clearReferencesThreads SEVERE: The web application [/sree] appears > to have started a thread named [AWT-Windows] but has failed to stop > it. This is very likely to create a memory leak. Mar 7, 2012 > 11:30:06 PM org.apache.catalina.loader.WebappClassLoader > clearReferencesThreads SEVERE: The web application [/sree] appears > to have started a thread named [Thread-3] but has failed to stop > it. This is very likely to create a memory leak. Mar 7, 2012 > 11:30:06 PM org.apache.catalina.loader.WebappClassLoader > clearReferencesThreads SEVERE: The web application [/sree] appears > to have started a thread named [Thread-8] but has failed to stop > it. This is very likely to create a memory leak. Mar 7, 2012 > 11:30:06 PM org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@5fe0095c]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@6d86a830]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@238c1f7d]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@446759c6]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@5d36f93f]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@4425c6e8]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@c25cc4c]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@58797cf]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@8ff99df]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@44cf0416]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. > Mar 7, 2012 11:30:06 PM > org.apache.catalina.loader.WebappClassLoader > checkThreadLocalMapForLeaks SEVERE: The web application [/sree] > created a ThreadLocal with key of type [java.lang.ThreadLocal] > (value [java.lang.ThreadLocal@400a3bdc]) and a value of type > [inetsoft.util.CurrentException.Infomation] (value > [inetsoft.util.CurrentException$Infomation@731563a4]) but failed to > remove it when the web application was stopped. Threads are going > to be renewed over time to try and avoid a probable memory leak. So, those are essentially warnings Tomcat logs when stopping your webapp. Basically, your webapp has a whole bunch of memory leaks (or, more likely, a single memory leak duplicated across all threads). You should contact the InetSoft folks and tell them to clean up after their ThreadLocals. You can safely ignore those log messages for now because they have nothing directly to do with your restart problems. >>> When I start it up manually, I see this: Mar 8, 2012 9:48:42 >>> AM org.apache.coyote.AbstractProtocol start INFO: Starting >>> ProtocolHandler ["http-bio-8080"] Mar 8, 2012 9:48:42 AM >>> org.apache.coyote.AbstractProtocol start INFO: Starting >>> ProtocolHandler ["ajp-bio-8009"] Mar 8, 2012 9:48:42 AM >>> org.apache.catalina.startup.Catalina start INFO: Server startup >>> in 20377 ms >> >> That's Tomcat starting. >> >>> So, for some reason, the load-on-startup doesn't seem to be >>> working properly. Any ideas why? Is this a bug in 7.0.26? >> >> I think load-on-startup isn't your problem, because Tomcat itself >> does not appear to even be attempting to start (or fails to >> start, and shuts down). > > What's concerning me is this all worked fine in 7.0.23 an prior > versions. I'm fairly confident that nothing terribly important changed. We'll figure it out. > I tried your test. 1. I shut down Tomcat manually and moved the > files from the log directory. 2. Start Tomcat manually, it started > up fine. 3. Schedule a restart 2 minutes into the future. 4. Wait 2 > minutes. I'm getting the same error here again. 5. Tomcat indeed is > not running. > > Here's the contents of the Catalina log with this test: > > > Mar 8, 2012 4:34:27 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: > C:\Program Files\Apache Software Foundation\Tomcat > 7.0\bin;C:\WINDOWS\Sun\Java\bin;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;. > > Mar 8, 2012 4:34:27 PM org.apache.coyote.AbstractProtocol init > INFO: Initializing ProtocolHandler ["http-bio-8080"] Mar 8, 2012 > 4:34:27 PM org.apache.coyote.AbstractProtocol init INFO: > Initializing ProtocolHandler ["ajp-bio-8009"] Mar 8, 2012 4:34:27 > PM org.apache.catalina.startup.Catalina load INFO: Initialization > processed in 1074 ms Mar 8, 2012 4:34:27 PM > org.apache.catalina.core.StandardService startInternal INFO: > Starting service Catalina Mar 8, 2012 4:34:27 PM > org.apache.catalina.core.StandardEngine startInternal INFO: > Starting Servlet Engine: Apache Tomcat/7.0.26 Tomcat is starting. This is the manual start, right? Now, Tomcat will deploy your webapps: > Mar 8, 2012 4:34:27 PM org.apache.catalina.startup.HostConfig > deployDirectory INFO: Deploying web application directory > C:\Program Files\Apache Software Foundation\Tomcat > 7.0\webapps\devhelp Mar 8, 2012 4:34:29 PM > org.apache.catalina.startup.HostConfig deployDirectory INFO: > Deploying web application directory C:\Program Files\Apache > Software Foundation\Tomcat 7.0\webapps\docs Mar 8, 2012 4:34:29 PM > org.apache.catalina.startup.HostConfig deployDirectory INFO: > Deploying web application directory C:\Program Files\Apache > Software Foundation\Tomcat 7.0\webapps\manager Mar 8, 2012 4:34:30 > PM org.apache.catalina.startup.HostConfig deployDirectory INFO: > Deploying web application directory C:\Program Files\Apache > Software Foundation\Tomcat 7.0\webapps\ROOT Mar 8, 2012 4:34:31 PM > org.apache.catalina.startup.HostConfig deployDirectory INFO: > Deploying web application directory C:\Program Files\Apache > Software Foundation\Tomcat 7.0\webapps\sree Now, all your initializers fire and dump a bunch of crap into the log. I'm removing these because they are not relevant (although they do make me thing twice: creating "request wrappers" before any requests have been made seems a little fishy). Oh, looks like one more webapp to be deployed: > Mar 8, 2012 4:34:43 PM org.apache.catalina.startup.HostConfig > deployDirectory INFO: Deploying web application directory > C:\Program Files\Apache Software Foundation\Tomcat > 7.0\webapps\userhelp Now, the connectors (things that actually bind to ports) are started: > Mar 8, 2012 4:34:43 PM org.apache.coyote.AbstractProtocol start > INFO: Starting ProtocolHandler ["http-bio-8080"] Mar 8, 2012 > 4:34:43 PM org.apache.coyote.AbstractProtocol start INFO: Starting > ProtocolHandler ["ajp-bio-8009"] Mar 8, 2012 4:34:43 PM > org.apache.catalina.startup.Catalina start INFO: Server startup in > 15762 ms Tomcat has officially started and all is well. Looks like 2 minutes later, Tomcat gets a shutdown request: > Mar 8, 2012 4:37:00 PM org.apache.coyote.AbstractProtocol pause > INFO: Pausing ProtocolHandler ["http-bio-8080"] Mar 8, 2012 4:37:00 > PM org.apache.coyote.AbstractProtocol pause INFO: Pausing > ProtocolHandler ["ajp-bio-8009"] Mar 8, 2012 4:37:00 PM > org.apache.catalina.core.StandardService stopInternal INFO: > Stopping service Catalina Mar 8, 2012 4:37:04 PM > com.sun.xml.ws.transport.http.servlet.WSServletDelegate destroy > INFO: WSSERVLET15: JAX-WS servlet destroyed Mar 8, 2012 4:37:04 PM > com.sun.xml.ws.transport.http.servlet.WSServletContextListener > contextDestroyed INFO: WSSERVLET13: JAX-WS context listener > destroyed I'll remove all the warnings about threadlocals. > Mar 8, 2012 4:37:04 PM org.apache.coyote.AbstractProtocol stop > INFO: Stopping ProtocolHandler ["http-bio-8080"] Mar 8, 2012 > 4:37:04 PM org.apache.coyote.AbstractProtocol stop INFO: Stopping > ProtocolHandler ["ajp-bio-8009"] Tomcat has stopped. If this is really the end of the log file, then it looks like Tomcat didn't even attempt to start itself again. When you perform a restart, do you move the log file out of the way or anything like that? If so, is there a "new" log file that might have some indication on an error? Again, how do you actually tell the service to restart? If you use Windows' "service restart", does it give you any errors in the system error log? > So, just for fun, I scheduled a second restart a couple of minutes > out. Then it said it was starting up fine. > > Mar 8, 2012 4:40:01 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: > C:\Program Files\Apache Software Foundation\Tomcat > 7.0\bin;C:\WINDOWS\Sun\Java\bin;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;. That > definitely looks like it's trying to start. > I guess I COULD do a workaround to just run the restart twice, but > I'd rather not. :-) I will for now so that my validation expert > isn't waiting for me to come in and start it. I wonder if this is a timing issue. I've never used Tomcat on Windows, but I used to use an old Java-based TiVo media server that came with a Windows Service. I seem to remember that clicking the "restart" widget in the service snap-in would seem to take *forever* and then it would finally say "sorry, this service isn't responding". For whatever reason, the service interface wasn't getting the feedback it needed to declare the service stopped. Perhaps the same thing is happening to you, here. Tomcat obviously stops (if after some delay) and will restart *later* if using the sam procedure. Perhaps all you need is some appropriate delay between the "stop" command and the "start" command? Silly question: why do you bother to restart this service in the first place? Is it in danger of running out of memory or something? Or is this just something that people in the Windows worls do as a matter of course because it seems like everything runs better with a restart every 24 hours? I'm honestly not trying to sound snide, but I have services that run (in *NIX systems) for months without needing any of this kind of foolishness. - -chris -----BEGIN PGP SIGNATURE----- Version: GnuPG/MacGPG2 v2.0.17 (Darwin) Comment: GPGTools - http://gpgtools.org Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iEYEARECAAYFAk9aUjgACgkQ9CaO5/Lv0PBBvACcDVX51NFHli0cdT0a6U5V2nvt xKIAn0OkYr9JfSPlUAAg7Y+zTLa89IbS =bNRt -----END PGP SIGNATURE----- --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
