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

Strange "Uncaught exception thrown" when including Zipkin starter #966

Closed
nickcodefresh opened this issue May 1, 2018 · 3 comments
Closed

Comments

@nickcodefresh
Copy link

If I include this dependency in my Spring Boot 1.5.9.RELEASE / Spring Cloud Edgware.SR3 project:

    <dependency>
      <groupId>org.springframework.cloud</groupId>
      <artifactId>spring-cloud-starter-zipkin</artifactId>
    </dependency>

I get lots of Zipkin-related errors when calling my controllers, despite not having Zipkin enabled:

flex-fastobject-service_1      | 2018-05-01 14:24:52 ERROR [flex-fastobject-service,7f747335b9f97a1c,ad666e2b3698bc70,false] 1 ---[o-18128-exec-89]o.s.c.sleuth.instrument.web.TraceFilter  : Uncaught exception thrown
flex-fastobject-service_1      | org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe
flex-fastobject-service_1      | 	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:321)
flex-fastobject-service_1      | 	at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284)
flex-fastobject-service_1      | 	at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:118)
flex-fastobject-service_1      | 	at org.springframework.cloud.sleuth.instrument.web.TraceServletOutputStream.flush(TraceServletOutputStream.java:128)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.core.json.UTF8JsonGenerator.flush(UTF8JsonGenerator.java:1054)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ObjectMapper.writeValue(ObjectMapper.java:2511)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.core.base.GeneratorBase.writeObject(GeneratorBase.java:378)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.node.POJONode.serialize(POJONode.java:112)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.node.ObjectNode.serialize(ObjectNode.java:304)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.node.ObjectNode.serialize(ObjectNode.java:304)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ser.std.SerializableSerializer.serialize(SerializableSerializer.java:49)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ser.std.SerializableSerializer.serialize(SerializableSerializer.java:27)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:704)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:689)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:155)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:292)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ObjectWriter$Prefetch.serialize(ObjectWriter.java:1429)
flex-fastobject-service_1      | 	at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:951)
flex-fastobject-service_1      | 	at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.writeInternal(AbstractJackson2HttpMessageConverter.java:286)
flex-fastobject-service_1      | 	at org.springframework.http.converter.AbstractGenericHttpMessageConverter.write(AbstractGenericHttpMessageConverter.java:106)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:231)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.handleReturnValue(RequestResponseBodyMethodProcessor.java:174)
flex-fastobject-service_1      | 	at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:81)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:113)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
flex-fastobject-service_1      | 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
flex-fastobject-service_1      | 	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
flex-fastobject-service_1      | 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55)
flex-fastobject-service_1      | 	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:110)
flex-fastobject-service_1      | 	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208)
flex-fastobject-service_1      | 	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
flex-fastobject-service_1      | 	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
flex-fastobject-service_1      | 	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
flex-fastobject-service_1      | 	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108)
flex-fastobject-service_1      | 	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
flex-fastobject-service_1      | 	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.springframework.cloud.sleuth.instrument.web.TraceFilter.doFilter(TraceFilter.java:166)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
flex-fastobject-service_1      | 	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
flex-fastobject-service_1      | 	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
flex-fastobject-service_1      | 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)

I found this issue but I don't know if it's related (but it's supposed to be fixed in the version I'm running anyway).

@nickcodefresh nickcodefresh changed the title Strange "Uncaught exception thrown" when including Zipkin depdendency Strange "Uncaught exception thrown" when including Zipkin starter May 1, 2018
@marcingrzejszczak
Copy link
Contributor

You're not getting Zipkin related issues, you're getting Sleuth related issues. You'd have to disable Sleuth.

What's going on is that we're wrapping an output stream in a tracing representation. When flush is called, we delegate flush to the output stream. So it's the output stream CoyoteOutputStream that is throwing that exception. TraceFilter is just catching it and logging that exception.

The issue you mentioned has nothing to do with this problem.

Don't you get these exceptions thrown when you don't have Zipkin starter on the classpath? Can you share a sample?

@nickcodefresh
Copy link
Author

So I discovered this is related to change in Spring Cloud whereby the default Ribbon timeout has changed from 5s to 1s. Our service hits a laggy legacy API that can be slow, so numerous calls would timeout. When I added

ribbon:
    ReadTimeout: 5000

to application.yml, the timeouts went, as did these exceptions.

@codefromthecrypt
Copy link
Contributor

maybe we shouldn't log the exception as the usual thing is to do span.error() instead? possibly less confusion. wdyt?

codefromthecrypt pushed a commit that referenced this issue May 15, 2020
`ExceptionLoggingFilter` logs "Uncaught exception thrown" to error level
when there is a synchronous exception not otherwise swallowed. This is a
cure worse than the disease. This issue disables by default and the 3.x
should end the years of problems it caused.

Fixes #1347

This was done IIUC to help @jfuerth who had log messages with trace IDs,
except the uncaught one, in #714 (Sept 2017). They were formerly told to
use `ExceptionHandler` and noted that didn't work in practice as it
subverted their status code logic.

Concretely, 4203566 "solved" the issue
by having sleuth log all uncaught exceptions with the message
"Uncaught exception thrown". This code was initially embedded in
sleuth's and later pulled out to `ExceptionLoggingFilter` in 2.0.

A few months later @brenuart noticed this "solution" had problems. For
example, it caused the same exception to be logged twice. Bertrand also
mentioned some faults in the implementation including edge cases like
`ClientAbortException` not addressed by this. (In fact, there are even
more problems: the implementation assumes async isn't in use!)
Bertands concerns about this having surprising logging effects were
dismissed as a non-issue. Bertrand raised #859 about glitches this
caused, the status_code related ones being if statemented around, and
it went quiet a while.

A month later @oburgosm opened #902 (currently 5 thumbs up) asking to
remove the "Uncaught exception thrown" or at least set it to debug.
The response was if they don't like it, control their own tracing
filter and the issue was closed.

A month later, @nickcodefresh opened #966 confused about "Uncaught
exception thrown" messages raised by sleuth, incidentally the
`ClientAbortException` mentioned by @brenuart before. Because the
logging came from Sleuth, it appeared they were zipkin errors, and was
explained they weren't.

A year later, @T3rm1 opened #1347 to remove the filter, or at least
disable it by default. The response was first to set the Logger to OFF.
A few days later the issue was closed as the submitter was told they
were the first person to complain about this. 5 months later, another
user rallied for support.

In April 2020, #902 was re-touched by @kosciej who asked to please
reconsider, mentioning it was not typical even in Spring to do this,
for example 'org.springframework.web.filter' package. The impact of
needing to specifically change apps to OFF the sleuth logger seemed
harsh. The suggestion was instead of setting log config, to set a
property instead `spring.sleuth.web.exception-logging-filter-enabled`,
to `false` as that could also accomplish the goal of stopping
"Uncaught exception thrown".

A month later (yesterday) @MrHurniak commented again on #1347 with the
usual complaint that it is redundant and confusing.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants