spring-cloud-sleuth: Zuul: Spans are removed from MDC "too early" when SendErrorFilter forwards to /error

Suppose a servlet filter logging incoming requests configured with a priority such that it appears just after Sleuth’s TraceFilter. The filter would log a pre and post message just like Spring’s CommonRequestLoggingFilter. Thanks to Sleuth integration, both lines will have the spanid attached to them as shown in below sample log output:

2017-04-12 19:07:09.090  INFO [-,b1fe361d6c1d8c35,b1fe361d6c1d8c35,false] 73856 --- [nio-8080-exec-1] c.e.ZuulsleuthApplication$MyFilter       : BEFORE
2017-04-12 19:07:09.098  INFO [-,b1fe361d6c1d8c35,b1fe361d6c1d8c35,false] 73856 --- [nio-8080-exec-1] o.s.c.n.zuul.web.ZuulHandlerMapping      : Mapped URL path [/test/**] onto handler of type [class org.springframework.cloud.netflix.zuul.web.ZuulController]
...
2017-04-12 19:07:09.120  INFO [-,b1fe361d6c1d8c35,b1fe361d6c1d8c35,false] 73856 --- [nio-8080-exec-1] c.e.ZuulsleuthApplication$MyFilter       : AFTER

The SendErrorFilter is triggered whenever Zuul encounters a problem during the routing of the request (either via SimpleRouting or RibbonRouting). The filter forwards the request to the /error endpoint for handling. In this case it appears the span information is NOT present in the MDC when the execution flow returns to the logging ServletFilter - hence the AFTER message doesn’t have the spanid attached to it. Example:

2017-04-12 19:44:21.307  INFO [-,87ac57c7bbda596d,87ac57c7bbda596d,false] 74041 --- [nio-8080-exec-1] c.e.ZuulsleuthApplication$MyFilter       : BEFORE
2017-04-12 19:44:21.315  INFO [-,87ac57c7bbda596d,87ac57c7bbda596d,false] 74041 --- [nio-8080-exec-1] o.s.c.n.zuul.web.ZuulHandlerMapping      : Mapped URL path [/test/**] onto handler of type [class org.springframework.cloud.netflix.zuul.web.ZuulController]
2017-04-12 19:44:21.395  WARN [-,87ac57c7bbda596d,c80a4aef1716bc74,false] 74041 --- [nio-8080-exec-1] o.s.c.n.z.filters.post.SendErrorFilter   : Error during filtering

com.netflix.zuul.exception.ZuulException: Connect to localhost:1 [localhost/127.0.0.1, localhost/0:0:0:0:0:0:0:1] failed: Connection refused
	at org.springframework.cloud.netflix.zuul.util.ZuulRuntimeException.<init>(ZuulRuntimeException.java:33) ~[spring-cloud-netflix-core-1.3.0.RC1.jar:1.3.0.RC1]
	at org.springframework.cloud.netflix.zuul.filters.route.SimpleHostRoutingFilter.run(SimpleHostRoutingFilter.java:200) ~[spring-cloud-netflix-core-1.3.0.RC1.jar:1.3.0.RC1]
...

2017-04-12 19:44:21.464  INFO [-,,87ac57c7bbda596d,false] 74041 --- [nio-8080-exec-1] c.e.ZuulsleuthApplication$MyFilter       : AFTER

Look at the last line: the traceid is still present, but the spanid is gone (or is it the opposite?).

Although we discovered that behaviour with Brixton.SR7, it can be reproduced with Dalston.RC1 as well.