tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Debbie Shapiro <DShap...@cardiacscience.com>
Subject RE: Web service not starting up as expected
Date Fri, 09 Mar 2012 21:41:50 GMT
I was able to add a sleep command (I had to do it for at least 30 seconds, any less and starting
up was still overlapping with the previous stop command). After adding this in, it seems to
be starting up without a problem. Glad it was something simple. Unfortunately, it forces me
to install an additional Microsoft windows resource kit app on the server, but no biggie.



Please create a HelpStar ticket for any requests for assistance. This will help us better
track your request.
http://helpstar


Debbie Shapiro
Data Warehouse Manager
Cardiac Science
Office: 425.402.2233

Visit us at www.cardiacscience.com
Suppliers of Cardiac Science, Criticare, Unetixs, Powerheart, Burdick, and Quinton products
Part of the Opto Circuits Family


-----Original Message-----
From: Debbie Shapiro
Sent: Friday, March 09, 2012 12:58 PM
To: Tomcat Users List
Subject: RE: Web service not starting up as expected



-----Original Message-----
From: Christopher Schultz [mailto:chris@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:chris@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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message