tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Christopher Schultz <ch...@christopherschultz.net>
Subject Re: Apache Tomcat service has been shutting down/stopping randomly.
Date Thu, 06 Jun 2013 15:55:45 GMT
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

James,

On 6/6/13 10:47 AM, James Snider wrote:
> Here's what we have completed since the last post:

Notably missing: the answers to any of the questions I asked. :(

> 1. We have enabled AWTThreadProtection in the server.xml file by
> setting the attribute to true.

This will not have any effect on the problem you are having. It may
help prevent resource leaks, but depending upon your use of AWT
classes, it may do nothing at all. This is currently a red herring for
this conversation.

> 2.  We have added a flush/close to the ImageIO code in our web
> application.

How did you do that? Be specific.

I can see that you are still having ImageIO try to write to the socket
(probably) long after the socket has been recycled.

> We are still receiving the java.lang.IllegalStateException error.

The IllegalStateException shown below is probably something different.
The problem is that you are having multiple problems, confusing them
all, and trying to solve them all at once.

If I were you, I'd focus on stopping the JVM crashes first. I'm going
to ignore everything else in this thread except for the JVM crashes
from here on out. If you want to start another thread for something
else, feel free to do so. But, if you present 5 different problems all
at once, nobody will be able to help you because it's just too confusing.

> Can you go into more detail on the wrapper we need for the output 
> stream?

Yes. Here is the problem, laid-out as a series of events, in
chronological order:

1. Tomcat receives a request, assigns a thread to handle the request,
and hands the request and response objects over to the webapp
(Servlet.service method)

2. Your code takes over and performs an operation using ImageIO, which
is a Java service (e.g. you didn't write it). You use it to produce an
image which is written to the response's output stream.

2a. When you call ImageIO, it retains a reference to the OutputStream
you passed to it. This is important, later.

3. Your code completes. You flush the buffer. You close the buffer.
You close the output stream. You do whatever you want. You'll see
later that it doesn't matter what you do.

4. Some random amount of time passes, and the finalizer thread sees
that the ImageIO objects that are no longer in use can be "finalized".
The finalizers on those objects are written. You can see the stack
trace here in the crash report:

> j  org.apache.tomcat.jni.Socket.sendbb(JII)I+0 j
> org.apache.coyote.http11.InternalAprOutputBuffer.flushBuffer()V+22 
> j  org.apache.coyote.http11.InternalAprOutputBuffer.flush()V+5 j
org.apache.coyote.http11.AbstractHttp11Processor.action(Lorg/apache/coyote/ActionCode;Ljava/lang/Object;)V+130
> j
org.apache.coyote.Response.action(Lorg/apache/coyote/ActionCode;Ljava/lang/Object;)V+31
> j  org.apache.catalina.connector.OutputBuffer.doFlush(Z)V+97 j
> org.apache.catalina.connector.OutputBuffer.flush()V+2 j
> org.apache.catalina.connector.CoyoteOutputStream.flush()V+4 j
> javax.imageio.stream.FileCacheImageOutputStream.close()V+60 j
> javax.imageio.stream.ImageInputStreamImpl.finalize()V+8 v
> ~StubRoutines::call_stub j
> java.lang.ref.Finalizer.invokeFinalizeMethod(Ljava/lang/Object;)V+0
>
> 
j  java.lang.ref.Finalizer.runFinalizer()V+45
> j
> java.lang.ref.Finalizer.access$100(Ljava/lang/ref/Finalizer;)V+1 j
> java.lang.ref.Finalizer$FinalizerThread.run()V+11 v
> ~StubRoutines::call_stub

At the bottom of that is the FinalizerThread.run method (that's the
finalizer thread running). If you look up the stack, you can see that
ImageIO is attempting to close and flush the OutputStream that you
used waaaaay back in step 2. You can tell because it's a
o.a.c.c.CoyoteOutputStream, which could only have come from Tomcat. I
guarantee you that ImageIO isn't creating those objects itself... it's
retaining references to them and then attempting to close them later.
This is (IMO) a bug in ImageIO.

5. The response's socket has been recycled, waiting for another
request to need its services. It's basically in a limbo-state which is
usually okay because Tomcat is managing it, and no other code should
be doing anything with it. Because of this bug in ImageIO, there is a
reference out there that shouldn't exist.

5b. Calling flush() on the socket that isn't actually attached to
anything calls into tcnative's sendbb() function where there is
another bug: a missing sanity-check that leads to a segmentation fault
(NULL pointer de-reference, access violation, other names, etc.). When
this happens in native code, the whole JVM goes down:

> # # A fatal error has been detected by the Java Runtime
> Environment: # #  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at
> pc=0x00000001800057b2, pid=5768, tid=5708 # # JRE version:
> 6.0_21-b07 # Java VM: Java HotSpot(TM) 64-Bit Server VM (17.0-b17
> mixed mode windows-amd64 ) # Problematic frame: # C
> [tcnative-1.dll+0x57b2] # # If you would like to submit a bug
> report, please visit: #
> http://java.sun.com/webapps/bugreport/crash.jsp # The crash
> happened outside the Java Virtual Machine in native code. # See
> problematic frame for where to report the bug. #
> 
> ---------------  T H R E A D  ---------------
> 
> Current thread (0x0000000004f32800):  JavaThread "Finalizer" daemon
> [_thread_in_native, id=5708,
> stack(0x0000000005b50000,0x0000000005c50000)]
> 
> siginfo: ExceptionCode=0xc0000005, reading address
> 0x0000000000000040
> 
> Registers: EAX=0x0000000000000000, EBX=0x0000000000000000,
> ECX=0x0000000007d560f0, EDX=0x0000000006468000 
> ESP=0x0000000005c4ee30, EBP=0x0000000000000000,
> ESI=0x0000000006b11240, EDI=0x000000000000006f 
> EIP=0x00000001800057b2, EFLAGS=0x0000000000010206
> 
> Top of Stack: (sp=0x0000000005c4ee30) 0x0000000005c4ee30:
> 000000000000006f 0000000000000000 0x0000000005c4ee40:
> 0000000000000087 0000000000000000 0x0000000005c4ee50:
> 00000000013959ce 00000000013a1260 0x0000000005c4ee60:
> 0000000005c4eee0 000000000000006f 0x0000000005c4ee70:
> 0000000080d8bd40 0000000000000054 0x0000000005c4ee80:
> 000000000000006f 000000000000006f 0x0000000005c4ee90:
> 0000000085ad21d0 0000000005c4ee98 0x0000000005c4eea0:
> 0000000005c4eea0 0000000000000000 0x0000000005c4eeb0:
> 0000000005c4ef18 0000000080d8d358 0x0000000005c4eec0:
> 0000000000000000 0000000080d8bd40 0x0000000005c4eed0:
> 0000000000000000 0000000005c4ef00 0x0000000005c4eee0:
> 0000000005c4ef60 00000000013959ce 0x0000000005c4eef0:
> 0000000080d8d2a0 000000000139e316 0x0000000005c4ef00:
> 000000000000006f 0000000000000000 0x0000000005c4ef10:
> 0000000006b11240 0000000085ad21d0 0x0000000005c4ef20:
> 0000000005c4ef20 0000000081107f9e
> 
> Instructions: (pc=0x00000001800057b2) 0x00000001800057a2:   8d 44
> 24 38 48 89 44 24 38 48 8b 46 30 48 03 d3 0x00000001800057b2:   ff
> 50 40 85 c0 75 29 48 8b 44 24 38 48 85 c0 74
> 
> 
> Stack: [0x0000000005b50000,0x0000000005c50000],
> sp=0x0000000005c4ee30,  free space=3fb0000000000000000k Native
> frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native
> code) C  [tcnative-1.dll+0x57b2]
> 
> [error occurred during error reporting (printing native stack), id
> 0xc0000005]
> 
> Java frames: (J=compiled Java code, j=interpreted, Vv=VM code) j
> org.apache.tomcat.jni.Socket.sendbb(JII)I+0

You can find this bug in ASF's Bugzilla here:
https://issues.apache.org/bugzilla/show_bug.cgi?id=51813

So, if we modify step #2 above so that we wrap the OutputStream in
another object that tracks whether the stream has been closed, etc.
and ignores all operations, you can actually avoid both bugs at once:
first, ImageIO will not attempt to close the "real" output stream
(because you gave it a wrapper that knows better) and therefore the
real socket won't get a flush() call and you won't trigger the
tcnative bug.

- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG/MacGPG2 v2.0.17 (Darwin)
Comment: GPGTools - http://gpgtools.org
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQIcBAEBCAAGBQJRsLEBAAoJEBzwKT+lPKRYTE0P/03TJdNuX0Ow7I7elSOzYp7s
BFv5IXznHdbgUgCA0nlwJj+qUKgBgbS9G2RR/enGSCz04vHfKSL2XHDMp8uGVhRQ
SfZemEnla/CsgsWEG0tl+e+EJveZEPG2Th/C4zKW/AiABRFe27LnxF5XdR3kEENH
qx9RhmpRcrHzX1OvUcxAN00f+uMXAKvPNpZplL1sub8NtraeKhSQtm0KI7jccI83
PnYhPHBaS0cPdIdh0OgAx2uE4SIvEQmoM2+ccU5ZktIca6nOSmmWSjmnCbxsk30P
akMjBVrZmk4XJ1LNVrDnSM4TIr6DkVtYpvOexbnJlEmRady3j6VKsTrX9shLmmK2
O+vUfhQ+0YVIWr5+MiIKhLPQh2yUwsi8PuthI/edzq+HJKEByM0pObuI1IKTvmLC
3LAPjMdWs+u+/rAZhVvO8+MvhsV8X3uUGWzfhgXOxCD9sKeyumXmOVkHec+dBXyG
EnrlpCSR9LOPUFEAAZX3pCTriCSLnBHYDZ3r9wgUUfXuCSsDrm0kiX4uO7o+Xb8h
ruD++I4Mg85vXTnQbJo2PsKatm0lK1tD4DFIkBXv7znOZEFAcjGLdxXkng+VrU3z
AHM3HJ1hoD5GvtdIKJZau97EQahadpnJOI491R/ae8qMHBzYhk25uIkggKuy8f44
7Oi/1srTVRi7vaUFfNoq
=+ZKg
-----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