Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"IllegalStateException: STREAM" when using Spring MVC Callable return value on Jetty 9 failures [SPR-10790] #15416

Closed
spring-projects-issues opened this issue Jul 29, 2013 · 19 comments
Assignees
Labels
in: web status: declined

Comments

@spring-projects-issues
Copy link
Collaborator

spring-projects-issues commented Jul 29, 2013

David Harrigan opened SPR-10790 and commented

Hi,

I've come across a problem with Spring MVC and Jetty 9 that does not happen on Jetty 8.1.12. It appears that after a while (reproduced by using Siege), Spring MVC (with an Async Callable Controller) fails to find a View.

The View can be loaded via a web browser, so it's not that it doesn't exist - it just appears that under a bit of stress, Spring with Jetty can't find it.

As always, it's difficult to determine if this a problem with Spring or a problem with Jetty 9. My only evidence so far is that under Jetty 8.1.12 I am unable to reproduce the problem.

I've raised the bug in the Jetty Bugzilla as well (https://bugs.eclipse.org/bugs/show_bug.cgi?id=413901) since it may be a Jetty issue.

I've uploaded my test project here:

https://github.com/dharrigan/bizarro

Please feel free to clone and try out and see if I'm not going crazy :-)

Thank you.


Affects: 3.2.3

Attachments:

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

Rossen Stoyanchev commented

The View can be loaded via a web browser, so it's not that it doesn't exist - it just appears that under a bit of stress, Spring with Jetty can't find it.

What actually happens? Exception or something else? What is the view name in the failed request?

I haven't run the project but if you can do a little more debugging that would help move the issue forward. Another suggestion is enable debug logging for 'org.springframework.web', and then separate out + examine the logs for the failing request.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

David Harrigan commented

Hi Rossen,

Thank you for your comment. What actually happens is a stack trace. I'll dig one up. I apologise for not being clearer :-)

-=david=-

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

David Harrigan commented

Hi Rossen,

Here is the stack. Notice how the "aroomwithaview" cannot be found, yet obviously this view does exist...I've included a snippet of the siege output as well (that generates this error):

HTTP/1.1 200   0.11 secs:     279 bytes ==> /client/aroomwithaview
HTTP/1.1 200   0.08 secs:     279 bytes ==> /client/aroomwithaview
HTTP/1.1 200   0.09 secs:     279 bytes ==> /client/aroomwithaview
HTTP/1.1 200   0.08 secs:     279 bytes ==> /client/aroomwithaview
HTTP/1.1 500   0.01 secs:    3467 bytes ==> /client/aroomwithaview <--------- THIS FAILURE PRODUCES THE STACK BELOW
HTTP/1.1 200   0.12 secs:     279 bytes ==> /client/aroomwithaview
[15:20:39.702] [WARN ] [o.apache.tiles.impl.BasicTilesContainer ] [623 ] - Unable to find the definition 'client/aroomwithaview'
2013-07-29 15:20:39.707:WARN:oejs.ServletHandler:qtp1669420564-28: 
org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.apache.tiles.definition.NoSuchDefinitionException: client/aroomwithaview
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:948)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:827)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:735)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1477)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:138)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:564)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:213)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1094)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:432)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:175)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1028)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:258)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:445)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:267)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:224)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:601)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:532)
	at java.lang.Thread.run(Thread.java:724)
Caused by: 
org.apache.tiles.definition.NoSuchDefinitionException: client/aroomwithaview
	at org.apache.tiles.impl.BasicTilesContainer.render(BasicTilesContainer.java:625)
	at org.apache.tiles.impl.BasicTilesContainer.render(BasicTilesContainer.java:321)
	at org.thymeleaf.extras.tiles2.spring.web.view.ThymeleafTilesView.render(ThymeleafTilesView.java:91)
	at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1208)
	at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:992)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:939)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:936)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:827)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:735)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:812)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:698)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1506)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1477)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:138)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:564)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:213)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1094)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:432)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:175)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1028)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:258)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:445)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:267)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:224)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:601)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:532)
	at java.lang.Thread.run(Thread.java:724)
2013-07-29 15:20:39.710:WARN:oejs.ServletHandler:qtp1669420564-28: 
org.springframework.web.util.NestedServletException: Request processing failed; nested exception is java.lang.IllegalStateException: STREAM
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:948)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:827)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:735)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:812)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:698)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1506)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1477)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:138)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:564)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:213)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1094)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:432)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:175)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1028)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:196)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handleAsync(Server.java:502)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:281)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:224)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:601)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:532)
	at java.lang.Thread.run(Thread.java:724)
Caused by: 
java.lang.IllegalStateException: STREAM
	at org.eclipse.jetty.server.Response.getWriter(Response.java:715)
	at org.thymeleaf.extras.tiles2.spring.web.view.ThymeleafTilesView.render(ThymeleafTilesView.java:91)
	at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1208)
	at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:992)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:939)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:936)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:827)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:735)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:812)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:698)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1506)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1477)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:503)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:138)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:564)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:213)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1094)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:432)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:175)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1028)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:196)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handleAsync(Server.java:502)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:281)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:224)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:601)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:532)
	at java.lang.Thread.run(Thread.java:724)

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

Rossen Stoyanchev commented

Perhaps the Jetty guys could clarify the meaning of that exception. Also it would still be helpful to see additional logging from that thread.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

David Harrigan commented

Hi Rossen,

I'll turn on some debug and produce the same result. I'll also tarball up the debug as it could be quite big! :-) I'll attach to this JIRA.

-=david=-

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

David Harrigan commented

Hi,

Log file attached as gzip. Spring logging was set to DEBUG.

-=david=-

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

David Harrigan commented

Notice that in the instances that Spring MVC can't find the view, the leading "/" is stripped.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

Rossen Stoyanchev commented

The root cause for the exception is the "IllegalStateException: STREAM" in Jetty, which is raised if the code calls servletResponse.getOutputStream first and then servletResponse.getWriter. Clearly Thymeleaf calls getWriter, however it's not clear what (if anything) calls getOutputStream.

To confirm that, wrap the ServletResponse and override getOutputStream to raise an exception. That will reveal if anything is doing that or not. To do that you can extend HttpServletResponseWrapper, wrap the response from a Filter and pass the wrapped response to the next filter. Let me know if this is unclear.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

Rossen Stoyanchev commented

BTW the reason for this exercise is that I don't expect that anything should be calling getOutputStream. So either we need to confirm what is doing that or if not, that brings the question back to Jetty.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 29, 2013

David Harrigan commented

Hi Rossen,

I've git pushed the new project updates with a Filter as you suggested. I'm also attaching a log file from the run after the application of the filter. I hope this helps. Please do check my project to ensure I'm doing it okay - the log file does seem to suggest that the filter is being correctly applied. As expected, still getting a stack when I run with Seige and put Jetty 9 + Spring MVC (3.2.3) under a bit of stress.

https://github.com/dharrigan/bizarro

-=david=-

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 30, 2013

Rossen Stoyanchev commented

I'm sure you've seen my response on Jetty mailing list but adding a similar comment here for completeness.

The only other option I can think of is that something else is
calling getOutputStream() directly on the original response. 
Perhaps some code internal to Jetty?

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 31, 2013

Rossen Stoyanchev commented

Since the Jetty list has been silent, one thing you could try is put a breakpoint in Jetty's Response.getOutputStream() and run in debug mode. In your sample I would expect getWriter() is always called, it should be as simple as waiting for the first break in getOutputStream. To make the source available for debugging, you could include "org.eclipse.jetty:jetty-server" as a Maven dependency.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 31, 2013

David Harrigan commented

Hi Rossen,

Thank you for the update. I will follow and apply your instructions and get back to you with my findings :-)

-=david=-

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Jul 31, 2013

David Harrigan commented

Hi Rossen,

Okay, some info.

It appears that at random intervals, the Thymeleaf view cannot be found by Spring, and falls back to the DefaultRequestToViewNameTranslator, which strips the leading slash from the start of the URL (i.e., /client/aroomwithaview -> client/aroomwithaview) and thus fails to find the resource. I'm attaching a screenshot of where I am up to on this. Could this actually be a Spring problem that with Callable, and under a bit of load, it can't find views, and thus falls back to the default? Putting a breakpoint on the Jetty Server/Servlet code didn't reveal anything, just to highlight that Spring was not finding the view, thus causing Jetty to raise a 500 Internal Error exception.

-=david=-

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Aug 1, 2013

Rossen Stoyanchev commented

I ran the project myself and got the errors. I think I know what the issue is.

What happens usually when a controller method returns Callable is we invoke it in a separate thread and let the request processing thread exit. Then when the Callable is done we call dispatch and the Servlet container is called a second time to finish processing.

Here the Callable executes immediately and the dispatch is made before the request processing thread has exited. Jetty is supposed hold up the dispatch until the request processing thread has exited, and it looks like it does, but request.isAsyncStarted no longer returns true. This is why you see the DefaultRequestToViewNameTranslator invoked when it shouldn't be.

This can be seen in a couple of ways. First if you add a one second delay to the Callable (e.g. Thread.sleep()) all works fine because the request processing thread is allowed to finish. Also if you put a break in RequestMappingHandlerAdapter line 747 (i.e. immediately after the controller method is invoked) that will force the issue and you'll see the failure even from a single call.

I will respond on the Jetty list, pretty sure this is a Jetty bug though, which is consistent with the fact you can't reproduce it on Jetty 8.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Aug 1, 2013

David Harrigan commented

Hi Rossen,

Thank you tremendously for the update and for clarifying it. I look forward to a resolution for all concerned in the near future :-) I'm sure others will hit this bug as well :-)

-=david=-

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Aug 1, 2013

Rossen Stoyanchev commented

Thanks for the useful bug report and project!

I'm resolving this for now since I'm fairly certain it's not an issue on our end but feel free to re-open if necessary.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Aug 13, 2013

David Harrigan commented

Hi,

This has now been resolved from the commit by Greg on the Jetty 9.0.5 master branch.

80b422c0e45d1fefdab130f4da2fd175ce568e5d

I've tested a snapshot of 9.0.5 against the bizarro project that is failing on 9.0.4 and this commit seems to have fixed the problem!

Thank you Rossen for your help on this issue.

-=david=-

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Aug 13, 2013

Rossen Stoyanchev commented

Excellent, thanks for reporting it.

@spring-projects-issues spring-projects-issues added type: bug status: declined in: web labels Jan 11, 2019
@spring-projects-issues spring-projects-issues removed the type: bug label Jan 12, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
in: web status: declined
Projects
None yet
Development

No branches or pull requests

2 participants