You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Michael <ef...@gmail.com> on 2025/01/17 10:05:52 UTC
Sporadic NPEs from CoyoteOutputStream and their surprising effect
I have two applications, A and B, running in Tomcat 10.1.28 on RHEL
8.10 with Java 21 (OpenJDK Runtime Environment Red_Hat-21.0.5.0.10-1).
Application uses an AsyncContext and SSE to send messages back to an
application running in a Chrome browser. Sometimes I get an NPE with
the following stacktrace from app A:
04-Jan-2025 21:58:12.447 SEVERE [http-nio-8080-exec-11]
org.apache.catalina.core.Async
ContextImpl$RunnableWrapper.run Error
during processing of asynchronous Runnable via AsyncContext.start()
java.lang.NullPointerException: Cannot invoke
"org.apache.catalina.connector.OutputBuffer.setErrorException(java.lang.Exception)"
because "this.ob" is null
at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:138)
at com.a.b.c.A$2.run(A.java:123)
at org.apache.catalina.core.AsyncContextImpl$RunnableWrapper.run(AsyncContextImpl.java:562)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
at java.base/java.lang.Thread.run(Thread.java:1583)
In a development environment, I can reproduce an IOE in
CoyoteOutputStream.flush() if I in the browser switch to another tab
while my application A is trying to send a message to it. But I cannot
reproduce the following NPE shown above.
I've also tried to figure out why ob is set to null while in
CoyoteOutputStream.flush(), but that hasn't helped me much. Anyway,
I'm surprised to get an NPE from the platform.
In various logs from nightly(?) Tomcat test runs, I've been able to
find a similar problem. See this, for instance:
https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
.
Now, the next thing that happens is even more surprising to me.
Sometimes the uncaught NPE triggers an HTTP 500 response on a request
to a servlet in application B! This I've been able to reproduce in my
development environment, if I simply throw an NPE in application A
from withing the AsyncContext as shown in the stacktrace above while I
simultaneously keep requests coming in to application B. Then it
sometimes happens. I haven't been able to see what's going on in
application B when this happens, but my trace logs don't show anything
suspicious. The client making requests to application B just get's
back this:
<!doctype html><html lang="en"><head><title>HTTP Status 500 – Internal
Server Error</title><style type="text/css">body
{font-family:Tahoma,Arial,sans-serif;} h1, h2, h3, b
{color:white;background-color:#525D76;} h1 {font-size:22px;} h2
{font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a
{color:black;} .line
{height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP
Status 500 – Internal Server Error</h1><hr class="line"
/><p><b>Type</b> Exception Report</p><p><b>Description</b> The server
encountered an unexpected condition that prevented it from fulfilling
the request.</p><p><b>Exception</b></p><pre>java.lang.NullPointerException
</pre><p><b>Note</b> The full stack trace of the root cause is
available in the server logs.</p><hr class="line" /><h3>Apache
Tomcat/10.1.28</h3></body></html>
I don't know much about all this, but isn't both the NPE and it's
effect on another application's requests surprising?
For now, I've worked around the problem by explicitly catching NPEs in
this async code in application A.
Kind regards,
Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Michael <ef...@gmail.com>.
On Thu, Jan 23, 2025 at 5:30 PM Mark Thomas <ma...@apache.org> wrote:
>
> In the case of the unit test, it was a client disconnect during async
> processing that triggered the issue.
That sounds a lot like the situation we have seen.
> It would be worth testing with a 10.1.x build if you can. You can either
> build Tomcat from source or get a snapshot build from the CI system in a
> couple of hours once it has build the latest 10.1.x
>
> If this Tomcat bug was the cause of all the issues then great. That
> said, it is usually the case that more than one thing is going wrong.
> Fixing one thing just makes the next one easier to see. Do let us know
> how you get on once the NPE issue is out of the picture.
Thanks a lot for the fix!
As far as I can tell, it is somehow equivalent to the way I've handle
the NPE in the application code (we now catch the NPE and handle it as
we handle IOExceptions), so I'm quite confident that it will also
solve the problem we've seen.
I think there may be something with our implementation of part of the
AsyncListener interface when for instance the onError timing is bad
for us (which was also noted earlier in this thread). I'll try to get
some time to look into that, but as we don't see the problem anymore,
I've had some more urgent this to work on and it might take a while.
Thanks for all your comments and work on this issue to everyone that
took the time to write in this thread!
/Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Mark Thomas <ma...@apache.org>.
On 23/01/2025 14:34, Mark Thomas wrote:
<snip/>
> All of that suggests that something detects an issue with this request
> (or it just times out) which triggers the async error handling which
> eventually leads to the async request being completed/dispatched.
In the case of the unit test, it was a client disconnect during async
processing that triggered the issue.
> I suspect the NPE occurs more often on the CI system because it is
> relatively heavily loaded. We often see that with rare errors that are
> timing dependent.
As soon as I put my dev machine under load, I was able to recreate the
issue in my IDE.
The NPE is a Tomcat bug which will be fixed shortly and the fix included
in the next round of releases.
>> Now, the next thing that happens is even more surprising to me.
>> Sometimes the uncaught NPE triggers an HTTP 500 response on a request
>> to a servlet in application B! This I've been able to reproduce in my
>> development environment, if I simply throw an NPE in application A
>> from withing the AsyncContext as shown in the stacktrace above while I
>> simultaneously keep requests coming in to application B. Then it
>> sometimes happens. I haven't been able to see what's going on in
>> application B when this happens, but my trace logs don't show anything
>> suspicious. The client making requests to application B just get's
>> back this:
>> <!doctype html><html lang="en"><head><title>HTTP Status 500 – Internal
>> Server Error</title><style type="text/css">body
>> {font-family:Tahoma,Arial,sans-serif;} h1, h2, h3, b
>> {color:white;background-color:#525D76;} h1 {font-size:22px;} h2
>> {font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a
>> {color:black;} .line
>> {height:1px;background-color:#525D76;border:none;}</style></
>> head><body><h1>HTTP
>> Status 500 – Internal Server Error</h1><hr class="line"
>> /><p><b>Type</b> Exception Report</p><p><b>Description</b> The server
>> encountered an unexpected condition that prevented it from fulfilling
>> the request.</p><p><b>Exception</b></
>> p><pre>java.lang.NullPointerException
>> </pre><p><b>Note</b> The full stack trace of the root cause is
>> available in the server logs.</p><hr class="line" /><h3>Apache
>> Tomcat/10.1.28</h3></body></html>
>
> Most likely because the application A thread has continued to use a
> request/response that should have been recycled and reused for
> application B. That said, I wouldn't rule out a Tomcat bug so it is
> worth continuing to look at this.
It would be worth testing with a 10.1.x build if you can. You can either
build Tomcat from source or get a snapshot build from the CI system in a
couple of hours once it has build the latest 10.1.x
If this Tomcat bug was the cause of all the issues then great. That
said, it is usually the case that more than one thing is going wrong.
Fixing one thing just makes the next one easier to see. Do let us know
how you get on once the NPE issue is out of the picture.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Mark Thomas <ma...@apache.org>.
On 17/01/2025 10:05, Michael wrote:
> I have two applications, A and B, running in Tomcat 10.1.28 on RHEL
> 8.10 with Java 21 (OpenJDK Runtime Environment Red_Hat-21.0.5.0.10-1).
> Application uses an AsyncContext and SSE to send messages back to an
> application running in a Chrome browser. Sometimes I get an NPE with
> the following stacktrace from app A:
>
> 04-Jan-2025 21:58:12.447 SEVERE [http-nio-8080-exec-11]
> org.apache.catalina.core.Async
> ContextImpl$RunnableWrapper.run Error
> during processing of asynchronous Runnable via AsyncContext.start()
> java.lang.NullPointerException: Cannot invoke
> "org.apache.catalina.connector.OutputBuffer.setErrorException(java.lang.Exception)"
> because "this.ob" is null
> at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:138)
> at com.a.b.c.A$2.run(A.java:123)
> at org.apache.catalina.core.AsyncContextImpl$RunnableWrapper.run(AsyncContextImpl.java:562)
> at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
> at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
> at java.base/java.lang.Thread.run(Thread.java:1583)
ob.flush() has thrown an IOE at line 136 but then
ob.setErrorException() has thrown an NPE.
ob must have been set to null between those calls.
That means there must have been call to OutputBuffer.clear()
That only gets called from o.a.catalina.connector.Response.recycle()
That gets called once an async request has been completed/dispatched
All of that suggests that something detects an issue with this request
(or it just times out) which triggers the async error handling which
eventually leads to the async request being completed/dispatched.
Meanwhile, an application thread is writing to the response. If that
thread doesn't see the error until after the request has been
completed/dispatched (or doesn't check for the error or ignores it) then
things are going to start going wrong.
Because Tomcat recycles and re-uses the request and response objects
(and quite a few others), if an application retains a reference to one
those objects and continues to use it after it has been recycled pretty
much anything can go wrong.
If the application uses non-blocking IO it gets even more complicated.
Generally, applications should (even must) always implement
AsyncListener. In particular, that means preventing further reads and/or
writes after onError() or onTimeout() fire. Where non-blocking IO is
used similar requirements exist for ReadListener and WriteListener.
> In a development environment, I can reproduce an IOE in
> CoyoteOutputStream.flush() if I in the browser switch to another tab
> while my application A is trying to send a message to it. But I cannot
> reproduce the following NPE shown above.
> I've also tried to figure out why ob is set to null while in
> CoyoteOutputStream.flush(), but that hasn't helped me much. Anyway,
> I'm surprised to get an NPE from the platform.
> In various logs from nightly(?) Tomcat test runs, I've been able to
> find a similar problem. See this, for instance:
> https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
I suspect the NPE occurs more often on the CI system because it is
relatively heavily loaded. We often see that with rare errors that are
timing dependent.
> Now, the next thing that happens is even more surprising to me.
> Sometimes the uncaught NPE triggers an HTTP 500 response on a request
> to a servlet in application B! This I've been able to reproduce in my
> development environment, if I simply throw an NPE in application A
> from withing the AsyncContext as shown in the stacktrace above while I
> simultaneously keep requests coming in to application B. Then it
> sometimes happens. I haven't been able to see what's going on in
> application B when this happens, but my trace logs don't show anything
> suspicious. The client making requests to application B just get's
> back this:
> <!doctype html><html lang="en"><head><title>HTTP Status 500 – Internal
> Server Error</title><style type="text/css">body
> {font-family:Tahoma,Arial,sans-serif;} h1, h2, h3, b
> {color:white;background-color:#525D76;} h1 {font-size:22px;} h2
> {font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a
> {color:black;} .line
> {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP
> Status 500 – Internal Server Error</h1><hr class="line"
> /><p><b>Type</b> Exception Report</p><p><b>Description</b> The server
> encountered an unexpected condition that prevented it from fulfilling
> the request.</p><p><b>Exception</b></p><pre>java.lang.NullPointerException
> </pre><p><b>Note</b> The full stack trace of the root cause is
> available in the server logs.</p><hr class="line" /><h3>Apache
> Tomcat/10.1.28</h3></body></html>
Most likely because the application A thread has continued to use a
request/response that should have been recycled and reused for
application B. That said, I wouldn't rule out a Tomcat bug so it is
worth continuing to look at this.
Mark
>
> I don't know much about all this, but isn't both the NPE and it's
> effect on another application's requests surprising?
> For now, I've worked around the problem by explicitly catching NPEs in
> this async code in application A.
>
> Kind regards,
> Michael
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Mark Thomas <ma...@apache.org>.
On 20/01/2025 20:44, Michael wrote:
> On Fri, Jan 17, 2025 at 7:45 PM Michael <ef...@gmail.com> wrote:
>>
>> On Fri, Jan 17, 2025 at 3:51 PM Chuck Caldarale <n8...@gmail.com> wrote:
>>>
>>>> In various logs from nightly(?) Tomcat test runs, I've been able to
>>>> find a similar problem. See this, for instance:
>>>> https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
>>>
>>>
>>> I believe that the test referred to above intentionally causes the error.
>>
>> Okay, that sounds plausible.
>> It surprises me, though, that it's okay to provoke a NPE from the
>> application code, but again, I'm no expert in this :-)
>> Also, it seems that the error is sporadic in this log and logs from other tests.
>
> I looked up some of the other tests where this happens. A recent
> example (from a 10.1.35-dev version) is this one:
> 07-Jan-2025 12:30:28.836 INFO [testBug54928]
> org.apache.catalina.connector.TestCoyoteAdapter$AsyncServlet$1.run
> Exception caught java.lang.NullPointerException: Cannot invoke
> "org.apache.catalina.connector.OutputBuffer.setErrorException(java.lang.Exception)"
> because "this.ob" is null
> from https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1564/TEST-org.apache.catalina.connector.TestCoyoteAdapter.NIO.txt
> That test seems to run into the problem quite often.
> Would it be helpful if I tried to find out how to run those tests so I
> could start investigating how this.ob becomes null when inside
> this.ob.flush()? Or should I just be prepared for NPEs?
I've modified the logging for that test so we get a little more detail
about why there is an NPE at that point.
>>> This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled.
>
> If so, I can only imagine that this is in that of our applications
> that does async processing. Can I turn on some debugging to see if
> this is the case?
I wish it were that easy.
Getting Servlet async right is hard. Both from an implementers point of
view and for the developer.
I wouldn't be surprised if there is Tomcat bug in here somewhere. The
hard part is narrowing down a test to the point where only one thing
goes wrong and it happens often enough you can debug it. Often with
async issues, there are multiple things going wrong in both application
code and Tomcat code.
If it is a viable choice I would strongly recommend switching back to
non-async and use virtual threads. It is a lot easier to reason about
what is happening, what is going wrong and why when you only have a
single, container managed thread to worry about per request.
I am working my way through this thread and if I see something that
looks like a Tomcat bug I'll try and dig deeper.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Chuck Caldarale <n8...@gmail.com>.
> On Jan 20, 2025, at 14:44, Michael <ef...@gmail.com> wrote:
>
> On Fri, Jan 17, 2025 at 7:45 PM Michael <ef...@gmail.com> wrote:
>>
>> On Fri, Jan 17, 2025 at 3:51 PM Chuck Caldarale <n8...@gmail.com> wrote:
>>>
>>>> In various logs from nightly(?) Tomcat test runs, I've been able to
>>>> find a similar problem. See this, for instance:
>>>> https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
>>>
>>>
>>> I believe that the test referred to above intentionally causes the error.
>>
>> Okay, that sounds plausible.
>> It surprises me, though, that it's okay to provoke a NPE from the
>> application code, but again, I'm no expert in this :-)
Exceptions are frequently used when an application violates the behavior that the spec requires.
>> Also, it seems that the error is sporadic in this log and logs from other tests.
>
> I looked up some of the other tests where this happens. A recent
> example (from a 10.1.35-dev version) is this one:
> 07-Jan-2025 12:30:28.836 INFO [testBug54928]
> org.apache.catalina.connector.TestCoyoteAdapter$AsyncServlet$1.run
> Exception caught java.lang.NullPointerException: Cannot invoke
> "org.apache.catalina.connector.OutputBuffer.setErrorException(java.lang.Exception)"
> because "this.ob" is null
> from https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1564/TEST-org.apache.catalina.connector.TestCoyoteAdapter.NIO.txt
> That test seems to run into the problem quite often.
> Would it be helpful if I tried to find out how to run those tests so I
> could start investigating how this.ob becomes null when inside
> this.ob.flush()? Or should I just be prepared for NPEs?
I believe that the output buffer is set to null at some point during response completion processing, not during the flush() call. You might want to look through the BZ report that prompted creation of this particular test:
https://bz.apache.org/bugzilla/show_bug.cgi?id=54928
>>> This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled.
>
> If so, I can only imagine that this is in that of our applications
> that does async processing.
Yes - look for your application’s usage of the AsyncContext.complete() API, since I think somewhere inside that call is where the output buffer will get cleared out. Note that complete() will be called implicitly if the response times out (eg, the client disconnects).
If your application is trying to use the response object after that, you’ve got a problem.
A common problem is putting a reference to the request, response, or AsyncContext in a class (static) variable, or in a thread local where it can only cause confusion.
> Can I turn on some debugging to see if this is the case?
Sorry, I can’t help with the additional debugging, but possibly others on the list can.
- Chuck
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Christopher Schultz <ch...@christopherschultz.net>.
Michael,
On 1/20/25 3:44 PM, Michael wrote:
> On Fri, Jan 17, 2025 at 7:45 PM Michael <ef...@gmail.com> wrote:
>>
>> On Fri, Jan 17, 2025 at 3:51 PM Chuck Caldarale <n8...@gmail.com> wrote:
>>>
>>>> In various logs from nightly(?) Tomcat test runs, I've been able to
>>>> find a similar problem. See this, for instance:
>>>> https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
>>>
>>>
>>> I believe that the test referred to above intentionally causes the error.
>>
>> Okay, that sounds plausible.
>> It surprises me, though, that it's okay to provoke a NPE from the
>> application code, but again, I'm no expert in this :-)
>> Also, it seems that the error is sporadic in this log and logs from other tests.
>
> I looked up some of the other tests where this happens. A recent
> example (from a 10.1.35-dev version) is this one:
> 07-Jan-2025 12:30:28.836 INFO [testBug54928]
> org.apache.catalina.connector.TestCoyoteAdapter$AsyncServlet$1.run
> Exception caught java.lang.NullPointerException: Cannot invoke
> "org.apache.catalina.connector.OutputBuffer.setErrorException(java.lang.Exception)"
> because "this.ob" is null
> from https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1564/TEST-org.apache.catalina.connector.TestCoyoteAdapter.NIO.txt
> That test seems to run into the problem quite often.
> Would it be helpful if I tried to find out how to run those tests so I
> could start investigating how this.ob becomes null when inside
> this.ob.flush()? Or should I just be prepared for NPEs?
Running the unit tests is fairly easy.
Download the source package. You will need Apache ant available but
everything else will be downloaded on-demand by the build script.
$ ant deploy
Gets you a working local Tomcat build based upon that source.
$ ant test
Runs the entire set of test suites. If you wan to run only a single test:
$ ant -Dtest.entry=org.apache.whatever.Test test
>>> This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled.
>
> If so, I can only imagine that this is in that of our applications
> that does async processing. Can I turn on some debugging to see if
> this is the case?
Yes, but you are likely to get a huge amount of output. I wouldn't
recommend this in production.
https://tomcat.apache.org/tomcat-10.1-doc/logging.html
It's a relatively short read but will help you configure your loggers to
get information out of Tomcat. The hard part is knowing which loggers to
enable... but I suspect you can see which loggers would be interesting
given the code/classes you've already been looking at.
-chris
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Michael <ef...@gmail.com>.
On Fri, Jan 17, 2025 at 7:45 PM Michael <ef...@gmail.com> wrote:
>
> On Fri, Jan 17, 2025 at 3:51 PM Chuck Caldarale <n8...@gmail.com> wrote:
> >
> > > In various logs from nightly(?) Tomcat test runs, I've been able to
> > > find a similar problem. See this, for instance:
> > > https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
> >
> >
> > I believe that the test referred to above intentionally causes the error.
>
> Okay, that sounds plausible.
> It surprises me, though, that it's okay to provoke a NPE from the
> application code, but again, I'm no expert in this :-)
> Also, it seems that the error is sporadic in this log and logs from other tests.
I looked up some of the other tests where this happens. A recent
example (from a 10.1.35-dev version) is this one:
07-Jan-2025 12:30:28.836 INFO [testBug54928]
org.apache.catalina.connector.TestCoyoteAdapter$AsyncServlet$1.run
Exception caught java.lang.NullPointerException: Cannot invoke
"org.apache.catalina.connector.OutputBuffer.setErrorException(java.lang.Exception)"
because "this.ob" is null
from https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1564/TEST-org.apache.catalina.connector.TestCoyoteAdapter.NIO.txt
That test seems to run into the problem quite often.
Would it be helpful if I tried to find out how to run those tests so I
could start investigating how this.ob becomes null when inside
this.ob.flush()? Or should I just be prepared for NPEs?
> > This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled.
If so, I can only imagine that this is in that of our applications
that does async processing. Can I turn on some debugging to see if
this is the case?
/Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Christopher Schultz <ch...@christopherschultz.net>.
Michael,
On 1/18/25 2:22 AM, Michael wrote:
> Hi Chris,
>
>>> Yes, there's only the HTTP connector on port 8080. There's a load
>>> balancer in front of this that handles HTTPS.
>>
>> If you connect the client directly to Tomcat, are you still able to
>> reproduce the errors?
>
> I have only seen the NPE thrown from CoyoteOutputStream.flush() in
> production environments that use a load balancer.
> But when connecting directly to Tomcat in my devel environment, I was
> able to reproduce the behavior with the exception causing errors in
> requests handled by another application.
Try adding this to your <Connector> configuration in development and
pounding on it again:
discardFacades="true"
This ought to be the default, but ... just in case.
Are you able to reduce the test case to something you could share with
the Tomcat dev team? I know that's a big ask, but the other option is to
enable tons of logging and have what is likely to be a very long and
draw-out conversation with you via email.
-chris
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Michael <ef...@gmail.com>.
Hi Chris,
> > Yes, there's only the HTTP connector on port 8080. There's a load
> > balancer in front of this that handles HTTPS.
>
> If you connect the client directly to Tomcat, are you still able to
> reproduce the errors?
I have only seen the NPE thrown from CoyoteOutputStream.flush() in
production environments that use a load balancer.
But when connecting directly to Tomcat in my devel environment, I was
able to reproduce the behavior with the exception causing errors in
requests handled by another application.
/Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Christopher Schultz <ch...@christopherschultz.net>.
Michael,
On 1/17/25 4:21 PM, Michael wrote:
>>>> This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled. Can you post your <Connector> configuration? In particular, what are the settings for the discardFacades and discardRequestsAndResponses attributes?
>>>>
>>>
>>> The setup has defaults for those attributes, I guess. This is the
>>> connector config:
>>> <Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol"
>>> connectionTimeout="190000"
>>> maxConnections="10000"
>>> maxThreads="2000"
>>> acceptCount="1000"
>>> URIEncoding="UTF-8"
>>> compression="1024"
>>> compressibleMimeType="text/html,text/xml,text/plain,text/tcl,text/css,application/javascript,application/json,application/xml"
>>> redirectPort="8443"
>>> maxParameterCount="1000"/>
>>
>>
>> Is that the only <Connector> element? I would expect another one for the https port (8443).
>
> Yes, there's only the HTTP connector on port 8080. There's a load
> balancer in front of this that handles HTTPS.
If you connect the client directly to Tomcat, are you still able to
reproduce the errors?
-chris
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Michael <ef...@gmail.com>.
> >> This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled. Can you post your <Connector> configuration? In particular, what are the settings for the discardFacades and discardRequestsAndResponses attributes?
> >>
> >
> > The setup has defaults for those attributes, I guess. This is the
> > connector config:
> > <Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol"
> > connectionTimeout="190000"
> > maxConnections="10000"
> > maxThreads="2000"
> > acceptCount="1000"
> > URIEncoding="UTF-8"
> > compression="1024"
> > compressibleMimeType="text/html,text/xml,text/plain,text/tcl,text/css,application/javascript,application/json,application/xml"
> > redirectPort="8443"
> > maxParameterCount="1000"/>
>
>
> Is that the only <Connector> element? I would expect another one for the https port (8443).
Yes, there's only the HTTP connector on port 8080. There's a load
balancer in front of this that handles HTTPS.
/Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Chuck Caldarale <n8...@gmail.com>.
> On Jan 17, 2025, at 12:45, Michael <ef...@gmail.com> wrote:
>
> Thanks a lot for your comments, Chuck!
>
> On Fri, Jan 17, 2025 at 3:51 PM Chuck Caldarale <n8...@gmail.com> wrote:
>>
>>
>>> On Jan 17, 2025, at 04:05, Michael <ef...@gmail.com> wrote:
>>>
>>> I have two applications, A and B, running in Tomcat 10.1.28 on RHEL
>>> 8.10 with Java 21 (OpenJDK Runtime Environment Red_Hat-21.0.5.0.10-1).
>>
>>
>> You may want to try a newer version of 10.1; there have been several changes to the Catalina and Coyote components in the nearly six months since 10.1.28 was released.
>
> We will definitely try that soon.
> I should perhaps have mentioned that the problem with the NPE in app A
> affecting requests to app B, that problem can be reproduced in
> 10.1.34.
>
>
>>> In various logs from nightly(?) Tomcat test runs, I've been able to
>>> find a similar problem. See this, for instance:
>>> https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
>>
>>
>> I believe that the test referred to above intentionally causes the error.
>
> Okay, that sounds plausible.
> It surprises me, though, that it's okay to provoke a NPE from the
> application code, but again, I'm no expert in this :-)
> Also, it seems that the error is sporadic in this log and logs from other tests.
>
>
>>> Now, the next thing that happens is even more surprising to me.
>>> Sometimes the uncaught NPE triggers an HTTP 500 response on a request
>>> to a servlet in application B! This I've been able to reproduce in my
>>> development environment, if I simply throw an NPE in application A
>>> from withing the AsyncContext as shown in the stacktrace above while I
>>> simultaneously keep requests coming in to application B.
>>
>>
>> This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled. Can you post your <Connector> configuration? In particular, what are the settings for the discardFacades and discardRequestsAndResponses attributes?
>>
>
> The setup has defaults for those attributes, I guess. This is the
> connector config:
> <Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol"
> connectionTimeout="190000"
> maxConnections="10000"
> maxThreads="2000"
> acceptCount="1000"
> URIEncoding="UTF-8"
> compression="1024"
> compressibleMimeType="text/html,text/xml,text/plain,text/tcl,text/css,application/javascript,application/json,application/xml"
> redirectPort="8443"
> maxParameterCount="1000"/>
Is that the only <Connector> element? I would expect another one for the https port (8443).
- Chuck
> I haven't looked at why the various attributes are set like this. The
> connectionTimeout looks much too high to me, but I wouldn't expect
> that to have anything to do with the problem.
>
> /Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Michael <ef...@gmail.com>.
Thanks a lot for your comments, Chuck!
On Fri, Jan 17, 2025 at 3:51 PM Chuck Caldarale <n8...@gmail.com> wrote:
>
>
> > On Jan 17, 2025, at 04:05, Michael <ef...@gmail.com> wrote:
> >
> > I have two applications, A and B, running in Tomcat 10.1.28 on RHEL
> > 8.10 with Java 21 (OpenJDK Runtime Environment Red_Hat-21.0.5.0.10-1).
>
>
> You may want to try a newer version of 10.1; there have been several changes to the Catalina and Coyote components in the nearly six months since 10.1.28 was released.
We will definitely try that soon.
I should perhaps have mentioned that the problem with the NPE in app A
affecting requests to app B, that problem can be reproduced in
10.1.34.
> > In various logs from nightly(?) Tomcat test runs, I've been able to
> > find a similar problem. See this, for instance:
> > https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
>
>
> I believe that the test referred to above intentionally causes the error.
Okay, that sounds plausible.
It surprises me, though, that it's okay to provoke a NPE from the
application code, but again, I'm no expert in this :-)
Also, it seems that the error is sporadic in this log and logs from other tests.
> > Now, the next thing that happens is even more surprising to me.
> > Sometimes the uncaught NPE triggers an HTTP 500 response on a request
> > to a servlet in application B! This I've been able to reproduce in my
> > development environment, if I simply throw an NPE in application A
> > from withing the AsyncContext as shown in the stacktrace above while I
> > simultaneously keep requests coming in to application B.
>
>
> This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled. Can you post your <Connector> configuration? In particular, what are the settings for the discardFacades and discardRequestsAndResponses attributes?
>
The setup has defaults for those attributes, I guess. This is the
connector config:
<Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol"
connectionTimeout="190000"
maxConnections="10000"
maxThreads="2000"
acceptCount="1000"
URIEncoding="UTF-8"
compression="1024"
compressibleMimeType="text/html,text/xml,text/plain,text/tcl,text/css,application/javascript,application/json,application/xml"
redirectPort="8443"
maxParameterCount="1000"/>
I haven't looked at why the various attributes are set like this. The
connectionTimeout looks much too high to me, but I wouldn't expect
that to have anything to do with the problem.
/Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Sporadic NPEs from CoyoteOutputStream and their surprising effect
Posted by Chuck Caldarale <n8...@gmail.com>.
> On Jan 17, 2025, at 04:05, Michael <ef...@gmail.com> wrote:
>
> I have two applications, A and B, running in Tomcat 10.1.28 on RHEL
> 8.10 with Java 21 (OpenJDK Runtime Environment Red_Hat-21.0.5.0.10-1).
You may want to try a newer version of 10.1; there have been several changes to the Catalina and Coyote components in the nearly six months since 10.1.28 was released.
> Application uses an AsyncContext and SSE to send messages back to an
> application running in a Chrome browser. Sometimes I get an NPE with
> the following stacktrace from app A:
>
> 04-Jan-2025 21:58:12.447 SEVERE [http-nio-8080-exec-11]
> org.apache.catalina.core.Async
> ContextImpl$RunnableWrapper.run Error
> during processing of asynchronous Runnable via AsyncContext.start()
> java.lang.NullPointerException: Cannot invoke
> "org.apache.catalina.connector.OutputBuffer.setErrorException(java.lang.Exception)"
> because "this.ob" is null
> at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:138)
> at com.a.b.c.A$2.run(A.java:123)
> at org.apache.catalina.core.AsyncContextImpl$RunnableWrapper.run(AsyncContextImpl.java:562)
> at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
> at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
> at java.base/java.lang.Thread.run(Thread.java:1583)
>
> In a development environment, I can reproduce an IOE in
> CoyoteOutputStream.flush() if I in the browser switch to another tab
> while my application A is trying to send a message to it. But I cannot
> reproduce the following NPE shown above.
> I've also tried to figure out why ob is set to null while in
> CoyoteOutputStream.flush(), but that hasn't helped me much. Anyway,
> I'm surprised to get an NPE from the platform.
> In various logs from nightly(?) Tomcat test runs, I've been able to
> find a similar problem. See this, for instance:
> https://nightlies.apache.org/tomcat/tomcat-10.1.x/logs/1309/TEST-org.apache.coyote.http2.TestAsyncError.NIO.txt
I believe that the test referred to above intentionally causes the error.
> Now, the next thing that happens is even more surprising to me.
> Sometimes the uncaught NPE triggers an HTTP 500 response on a request
> to a servlet in application B! This I've been able to reproduce in my
> development environment, if I simply throw an NPE in application A
> from withing the AsyncContext as shown in the stacktrace above while I
> simultaneously keep requests coming in to application B.
This sounds suspiciously like the application is keeping references to requests or responses that have already been committed and recycled. Can you post your <Connector> configuration? In particular, what are the settings for the discardFacades and discardRequestsAndResponses attributes?
- Chuck
> Then it sometimes happens. I haven't been able to see what's going on in
> application B when this happens, but my trace logs don't show anything
> suspicious. The client making requests to application B just get's
> back this:
> <!doctype html><html lang="en"><head><title>HTTP Status 500 – Internal
> Server Error</title><style type="text/css">body
> {font-family:Tahoma,Arial,sans-serif;} h1, h2, h3, b
> {color:white;background-color:#525D76;} h1 {font-size:22px;} h2
> {font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a
> {color:black;} .line
> {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP
> Status 500 – Internal Server Error</h1><hr class="line"
> /><p><b>Type</b> Exception Report</p><p><b>Description</b> The server
> encountered an unexpected condition that prevented it from fulfilling
> the request.</p><p><b>Exception</b></p><pre>java.lang.NullPointerException
> </pre><p><b>Note</b> The full stack trace of the root cause is
> available in the server logs.</p><hr class="line" /><h3>Apache
> Tomcat/10.1.28</h3></body></html>
>
> I don't know much about all this, but isn't both the NPE and it's
> effect on another application's requests surprising?
> For now, I've worked around the problem by explicitly catching NPEs in
> this async code in application A.
>
> Kind regards,
> Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org