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

getOutputStream() has already been called for this response - still not completely fixed #155

Closed
davidjirovec opened this issue May 11, 2017 · 16 comments
Assignees
Labels

Comments

@davidjirovec
Copy link

Same problem as #146. Although #146 was fixed, problem is back when I turn on logbook request response logging by adding

logging.level.org.zalando.logbook=trace

to application.properties.

Minimal example to reproduce is still prepared here. Revision d46137b contains updated logbook version and the mentioned logging configuration.

@whiskeysierra
Copy link
Collaborator

I cloned your repo and tried to reproduce it, but if I start it with

mvn clean spring-boot:run

and in a second terminal I perform requests (in this example using httpie):

http :8080/foo

I see no exception but the following output:

2017-05-11 23:56:27.106 TRACE 24746 --- [nio-8080-exec-9] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"27c0e8f2-adc6-43f2-ad77-6e98defafe1b","protocol":"HTTP/1.1","remote":"127.0.0.1","method":"GET","uri":"http://localhost:8080/foo","headers":{"accept":["*/*"],"accept-encoding":["gzip, deflate"],"connection":["keep-alive"],"host":["localhost:8080"],"user-agent":["HTTPie/0.9.6"]},"body":"<skipped>"}
2017-05-11 23:56:27.106 TRACE 24746 --- [nio-8080-exec-9] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"27c0e8f2-adc6-43f2-ad77-6e98defafe1b","protocol":"HTTP/1.1","status":401,"headers":{"Cache-Control":["no-cache, no-store, max-age=0, must-revalidate"],"Expires":["0"],"Pragma":["no-cache"],"Strict-Transport-Security":["max-age=31536000 ; includeSubDomains"],"WWW-Authenticate":["Basic realm=\"Spring\""],"X-Content-Type-Options":["nosniff"],"X-Frame-Options":["DENY"],"X-XSS-Protection":["1; mode=block"]}}
2017-05-11 23:56:27.107 TRACE 24746 --- [nio-8080-exec-9] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"e1fe8726-668c-49e3-a35d-9ac79bb318e3","protocol":"HTTP/1.1","remote":"127.0.0.1","method":"GET","uri":"http://localhost:8080/error","headers":{"accept":["*/*"],"accept-encoding":["gzip, deflate"],"connection":["keep-alive"],"host":["localhost:8080"],"user-agent":["HTTPie/0.9.6"]}}
2017-05-11 23:56:27.109 TRACE 24746 --- [nio-8080-exec-9] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"e1fe8726-668c-49e3-a35d-9ac79bb318e3","protocol":"HTTP/1.1","status":401,"headers":{"Cache-Control":["no-cache, no-store, max-age=0, must-revalidate"],"Content-Type":["application/json;charset=UTF-8"],"Date":["Thu, 11 May 2017 21:56:27 GMT"],"Expires":["0"],"Pragma":["no-cache"],"Strict-Transport-Security":["max-age=31536000 ; includeSubDomains"],"Transfer-Encoding":["chunked"],"WWW-Authenticate":["Basic realm=\"Spring\""],"X-Content-Type-Options":["nosniff"],"X-Frame-Options":["DENY"],"X-XSS-Protection":["1; mode=block"]},"body":{"timestamp":1494539787108,"status":401,"error":"Unauthorized","message":"Full authentication is required to access this resource","path":"/foo"}}
2017-05-11 23:56:27.110 TRACE 24746 --- [nio-8080-exec-9] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"25a8fce5-dad6-407c-88d2-b088fc6c3e9e","protocol":"HTTP/1.1","remote":"127.0.0.1","method":"GET","uri":"http://localhost:8080/error","headers":{"accept":["*/*"],"accept-encoding":["gzip, deflate"],"connection":["keep-alive"],"host":["localhost:8080"],"user-agent":["HTTPie/0.9.6"]},"body":"<skipped>"}
2017-05-11 23:56:27.111 TRACE 24746 --- [nio-8080-exec-9] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"25a8fce5-dad6-407c-88d2-b088fc6c3e9e","protocol":"HTTP/1.1","status":401,"headers":{"Cache-Control":["no-cache, no-store, max-age=0, must-revalidate"],"Content-Type":["application/json;charset=UTF-8"],"Date":["Thu, 11 May 2017 21:56:27 GMT"],"Expires":["0"],"Pragma":["no-cache"],"Strict-Transport-Security":["max-age=31536000 ; includeSubDomains"],"Transfer-Encoding":["chunked"],"WWW-Authenticate":["Basic realm=\"Spring\""],"X-Content-Type-Options":["nosniff"],"X-Frame-Options":["DENY"],"X-XSS-Protection":["1; mode=block"]},"body":{"timestamp":1494539787108,"status":401,"error":"Unauthorized","message":"Full authentication is required to access this resource","path":"/foo"}}

I can definitely see that we don't handle the error dispatch correctly, since there are 6 log messages but I'd have expected 2.

@davidjirovec
Copy link
Author

Sorry I forgot to mention that same as in #146, the sample needs to be deployed to Tomcat.

Anyway I think what you mentioned about incorrect error handling when running as Spring Boot app might have same cause.

@AlexanderYastrebov
Copy link
Member

From what I can see the problem is in ErrorPageFilter which tries to forward to error page but since we logged response body it can not use getOutputStream or getWriter for a second time.

ErrorPageFilter itself has a workaround which checks whether response was commited (i.e. flushed)
https://github.com/spring-projects/spring-boot/blob/v1.5.2.RELEASE/spring-boot/src/main/java/org/springframework/boot/web/support/ErrorPageFilter.java#L138 but then it will just log a error and show blank page.

This could be reproduced by flushing response:

diff --git a/logbook-servlet/src/main/java/org/zalando/logbook/servlet/SecurityStrategy.java b/logbook-servlet/src/main/java/org/zalando/logbook/servlet/SecurityStrategy.java
index f901357..a725a84 100644
--- a/logbook-servlet/src/main/java/org/zalando/logbook/servlet/SecurityStrategy.java
+++ b/logbook-servlet/src/main/java/org/zalando/logbook/servlet/SecurityStrategy.java
@@ -41,6 +41,7 @@ final class SecurityStrategy implements Strategy {
             }
 
             if (correlator.isPresent()) {
+                response.getWriter().flush();
                 correlator.get().write(response);
             }
         }

As far as I understand design, Logbook should be an most outer filter (@whiskeysierra is it correct?) but ErrorPageFilter has a highest priority itself https://github.com/spring-projects/spring-boot/blob/v1.5.2.RELEASE/spring-boot/src/main/java/org/springframework/boot/web/support/ErrorPageFilter.java#L58

@AlexanderYastrebov
Copy link
Member

but since we logged response body it can not use getOutputStream

This happens because we apply filters to body while logging thus effectively using body's getOutputStream

@AlexanderYastrebov
Copy link
Member

Looks like we have to collect nested chain output in LocalResponse buffer (what we already do), filter and log it, and only then copy this buffer to real http response output stream.

@AlexanderYastrebov
Copy link
Member

In such case we can see whether buffer is empty, i.e. nested chain did not produce anything and can avoid calling real http response's getOutputStream so ErrorPageHandler can take care of it. Downside is that error page itself will not be logged by logbook

@whiskeysierra
Copy link
Collaborator

@davidjirovec How do you quickly deploy your sample project in a standalone tomcat?

I tried

mvn clean package tomcat:run-war

But that didn't seem to deploy the Spring Application correctly.

@whiskeysierra
Copy link
Collaborator

I configured the tomcat7-maven-plugin and that did the trick. But the output looks ok.

@whiskeysierra
Copy link
Collaborator

http :8080/demo/foo returns:

HTTP/1.1 401 Unauthorized
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Content-Type: application/json;charset=UTF-8
Date: Wed, 22 Nov 2017 14:00:39 GMT
Expires: 0
Pragma: no-cache
Server: Apache-Coyote/1.1
Strict-Transport-Security: max-age=31536000 ; includeSubDomains
Transfer-Encoding: chunked
WWW-Authenticate: Basic realm="Spring"
X-Content-Type-Options: nosniff
X-Frame-Options: DENY
X-XSS-Protection: 1; mode=block

{
    "error": "Unauthorized",
    "message": "Full authentication is required to access this resource",
    "path": "/demo/foo",
    "status": 401,
    "timestamp": 1511359239651
}

Log output is:

2017-11-22 15:00:39.649 TRACE 21495 --- [bio-8080-exec-5] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"23620e63-38da-42f1-9770-ef55c48839e3","protocol":"HTTP/1.1","remote":"127.0.0.1","method":"GET","uri":"http://localhost:8080/demo/foo","headers":{"accept":["*/*"],"accept-encoding":["gzip, deflate"],"connection":["keep-alive"],"host":["localhost:8080"],"user-agent":["HTTPie/0.9.6"]},"body":"<skipped>"}
2017-11-22 15:00:39.650 TRACE 21495 --- [bio-8080-exec-5] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"23620e63-38da-42f1-9770-ef55c48839e3","protocol":"HTTP/1.1","status":401,"headers":{"Cache-Control":["no-cache, no-store, max-age=0, must-revalidate"],"Expires":["0"],"Pragma":["no-cache"],"Strict-Transport-Security":["max-age=31536000 ; includeSubDomains"],"WWW-Authenticate":["Basic realm=\"Spring\""],"X-Content-Type-Options":["nosniff"],"X-Frame-Options":["DENY"],"X-XSS-Protection":["1; mode=block"]}}

@whiskeysierra
Copy link
Collaborator

@davidjirovec I tried your project but I can't reproduce the issue. Can you help?

@davidjirovec
Copy link
Author

I hope I will find time to help you this week.

@davidjirovec
Copy link
Author

Ok, I see you are trying tomcat-maven-plugin. You should download Tomcat here. Start downloaded Tomcat, copy built war from my project (target/demo-0.0.1-SNAPSHOT.war) to Tomcat webapps directory.

Wait for deployment to finish, then try to access http://localhost:8080/demo-0.0.1-SNAPSHOT/

getOutputStream() has already been called for this response should appear.

@whiskeysierra
Copy link
Collaborator

22-Jan-2018 09:48:32.716 SEVERE [http-nio-8080-exec-8] org.apache.catalina.core.ApplicationDispatcher.invoke Servlet.service() for servlet [dispatcherServlet] threw exception
 java.lang.IllegalStateException: getOutputStream() has already been called for this response
	at org.apache.catalina.connector.Response.getWriter(Response.java:624)
	at org.apache.catalina.connector.ResponseFacade.getWriter(ResponseFacade.java:211)
	at javax.servlet.ServletResponseWrapper.getWriter(ServletResponseWrapper.java:109)
	at org.springframework.boot.autoconfigure.web.ErrorMvcAutoConfiguration$SpelView.render(ErrorMvcAutoConfiguration.java:227)
	at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1282)
	at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1037)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:980)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
	at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:108)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:728)
	at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:470)
	at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:395)
	at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:316)
	at org.springframework.boot.web.support.ErrorPageFilter.handleErrorStatus(ErrorPageFilter.java:149)
	at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:117)
	at org.springframework.boot.web.support.ErrorPageFilter.access$000(ErrorPageFilter.java:59)
	at org.springframework.boot.web.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:90)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:108)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)


==> catalina.out <==
2018-01-22 09:48:32.725 ERROR 15886 --- [nio-8080-exec-8] o.s.boot.web.support.ErrorPageFilter     : Forwarding to error page from request [/] due to exception [getOutputStream() has already been called for this response]

java.lang.IllegalStateException: getOutputStream() has already been called for this response
	at org.apache.catalina.connector.Response.getWriter(Response.java:624) ~[catalina.jar:8.5.24]
	at org.apache.catalina.connector.ResponseFacade.getWriter(ResponseFacade.java:211) ~[catalina.jar:8.5.24]
	at javax.servlet.ServletResponseWrapper.getWriter(ServletResponseWrapper.java:109) ~[servlet-api.jar:3.1.FR]
	at org.springframework.boot.autoconfigure.web.ErrorMvcAutoConfiguration$SpelView.render(ErrorMvcAutoConfiguration.java:227) ~[spring-boot-autoconfigure-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1282) ~[spring-webmvc-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1037) ~[spring-webmvc-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:980) ~[spring-webmvc-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) ~[spring-webmvc-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) ~[spring-webmvc-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861) ~[spring-webmvc-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) ~[servlet-api.jar:na]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) ~[spring-webmvc-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) ~[servlet-api.jar:na]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208) ~[spring-security-web-4.2.2.RELEASE.jar:4.2.2.RELEASE]
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177) ~[spring-security-web-4.2.2.RELEASE.jar:4.2.2.RELEASE]
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346) ~[spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262) ~[spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:108) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:728) ~[catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:470) ~[catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:395) ~[catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:316) ~[catalina.jar:8.5.24]
	at org.springframework.boot.web.support.ErrorPageFilter.handleErrorStatus(ErrorPageFilter.java:149) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:117) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.web.support.ErrorPageFilter.access$000(ErrorPageFilter.java:59) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.web.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:90) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:108) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.24]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.24]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) [catalina.jar:8.5.24]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [catalina.jar:8.5.24]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504) [catalina.jar:8.5.24]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [catalina.jar:8.5.24]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) [catalina.jar:8.5.24]
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650) [catalina.jar:8.5.24]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [catalina.jar:8.5.24]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [catalina.jar:8.5.24]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) [tomcat-coyote.jar:8.5.24]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-coyote.jar:8.5.24]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790) [tomcat-coyote.jar:8.5.24]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459) [tomcat-coyote.jar:8.5.24]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:8.5.24]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_151]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_151]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:8.5.24]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_151]
2018-01-22 09:48:32.703 TRACE 15886 --- [nio-8080-exec-8] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"86e373fe-d5b6-4a8c-b1db-db94a795d602","protocol":"HTTP/1.1","remote":"0:0:0:0:0:0:0:1","method":"GET","uri":"http://localhost:8080/demo-0.0.1-SNAPSHOT/","headers":{"accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8"],"accept-encoding":["gzip, deflate, br"],"accept-language":["en-US,en;q=0.9,de-DE;q=0.8,de;q=0.7"],"cache-control":["max-age=0"],"connection":["keep-alive"],"host":["localhost:8080"],"referer":["http://localhost:8080/manager/html/upload;jsessionid=B859CFD691B90BDF14851BE4DD01B4D7?org.apache.catalina.filters.CSRF_NONCE=1BAB0A3A21FEB7410CAE65DB8717B926"],"upgrade-insecure-requests":["1"],"user-agent":["Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36"]},"body":"<skipped>"}
2018-01-22 09:48:32.704 TRACE 15886 --- [nio-8080-exec-8] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"86e373fe-d5b6-4a8c-b1db-db94a795d602","protocol":"HTTP/1.1","status":401,"headers":{"Cache-Control":["no-cache, no-store, max-age=0, must-revalidate"],"Expires":["0"],"Pragma":["no-cache"],"Strict-Transport-Security":["max-age=31536000 ; includeSubDomains"],"WWW-Authenticate":["Basic realm=\"Spring\""],"X-Content-Type-Options":["nosniff"],"X-Frame-Options":["DENY"],"X-XSS-Protection":["1; mode=block"]}}

It's caused by (or originates from) the ErrorMvcAutoConfiguration which I'd recommend to disable. I don't believe the error dispatch to be useful for Spring/REST applications.

@whiskeysierra
Copy link
Collaborator

I don't remember why we register the filter for the error dispatch though. We might stop doing that. Should resolve the issue as well.

@whiskeysierra
Copy link
Collaborator

I'd consider this to be a bug in Spring. Current workaround is to:

@EnableAutoConfiguration(exclude = ErrorMvcAutoConfiguration.class)

Alternatively, you'd need to wait for Spring Boot 2, since they include a fix. See spring-projects/spring-boot#11580.

I'll close this for now. Feel free to re-open/challenge.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants