-----Original Message----- From: Christopher Schultz [mailto:ch...@christopherschultz.net] Sent: Friday, March 09, 2012 10:56 AM To: Tomcat Users List Subject: Re: Web service not starting up as expected
-----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'm pretty sure that's accurate in this case, however. I had 7.0.23 installed as of last week and then this week did the upgrade to 7.0.26. I'm wondering about your question regarding timing though. It's possible that Tomcat is doing more cleanup than it has in the past and it's taking longer to shut down? Maybe I do just need some kind of pause in between stopping and restarting. > 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? I either directly run the .bat command or launch the scheduled task that normally runs the same .bat command. The contents of the .bat file is as follows: sc \\bidev2 stop Tomcat7 taskkill /F /FI "IMAGENAME eq java.exe" /FI "USERNAME eq NT AUTHORITY\SYSTEM" REM delay batch job to wait for services to stop for /F "tokens=1-4 delims=/- " %%A in ('date/T') do set DATE=%%B%%C%%D for /F "tokens=1-4 delims=:., " %%a in ('time/T') do set TIME=%%a%%b%%c cd c:\"Program Files"\"Apache Software Foundation"\"Tomcat 7.0"\webapps\sree\WEB-INF\classes rename sree.log %DATE%_%TIME%_sree.log rename schedule.log %DATE%_%TIME%_schedule.log cd c:\"Program Files"\"Apache Software Foundation"\"Tomcat 7.0"\webapps\sree\WEB-INF\classes compact %DATE%_%TIME%_sree.log /c compact %DATE%_%TIME%_schedule.log /c sc \\bidev2 start Tomcat7 cd c:\"Scheduled Jobs" >>> 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. I have actually mentioned the memory leaks to them before. They said not to be concerned, but maybe others will report this as well. >>> 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? Yes, this was my manual restart. 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. Yes, this is the user help for the users accessing the web app (also built by InetSoft). There are actually 3. The main web app, the user help and developer help. > 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. Yes, this was the automated scheduled task kicking off. > 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? This was the end of the file, yes. I thought it looked odd too. I don't move any of the Tomcat logs. I only compress and rename the old InetSoft logs. Again, how do you actually tell the service to restart? I have a scheduled task that kicks off the .bat file I copied above. If you use Windows' "service restart", does it give you any errors in the system error log? Yes, all it says is: Event ID: 7036 The Apache Tomcat 7.0 Tomcat7 service entered the stopped state. For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp. > 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. This second scheduled task started up fine. So maybe it is just a timing issue. 7.0.26 takes longer to shut down than 7.0.23 maybe? > 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. I'm going to test out a delay in the restart after I shut down, but just wanted to throw out there that after my stop service command, which happens at exactly 11:30, the restart failure in the event viewer has a timestamp of 11:30:06. That's not much of a delay between the stop and restart, so maybe it's still technically shutting down at this point. 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. Yes, it is pretty common in the windows world to restart servers and services due to various memory issues. I'm doing this because the application is a reporting tool and if the users run any enormous reports that cause it to run out of java heap or something, this provides for an automated way of maintaining the application so that it doesn't require manual intervention to fix it and I know that even if no one calls me, it will be reset at some point. I also use it as an opportunity to save off a daily copy of the InetSoft logs if I need to go back and review errors later. Personally, I'm a Mac fan at heart. :-) - -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
