search

spring-cloud / spring-cloud-sleuth

Distributed tracing for spring cloud
https://spring.io/projects/spring-cloud-sleuth
Apache License 2.0
1.78k stars 781 forks source link

Spans not exported to Zipkin with property 'spring.sleuth.sampler.probability' set to value 1 #1356

Closed pawcykca closed 5 years ago

pawcykca commented 5 years ago

I'm developing application using Spring Boot (2.1.4) running on Kubernetes. Spans from my application aren't exported to Zipkin while property 'spring.sleuth.sampler.probability' is set to value 1.

[2019-05-17T09:59:07.083Z][http-nio-8080-exec-9] TRACE; [service,71283846f6dd8fc3c096c1eae7e35142,8b3124a796b24061,false] ; org.springframework.cloud.sleuth.log.Slf4jScopeDecorator; Starting scope for span: 71283846f6dd8fc3c096c1eae7e35142/8b3124a796b24061
[2019-05-17T09:59:07.083Z][http-nio-8080-exec-9] TRACE; [service,71283846f6dd8fc3c096c1eae7e35142,8b3124a796b24061,false] ; org.springframework.cloud.sleuth.log.Slf4jScopeDecorator; With parent: -4569251557263847102
[2019-05-17T09:59:07.109Z][http-nio-8080-exec-9] TRACE; [service,71283846f6dd8fc3c096c1eae7e35142,8b3124a796b24061,false] ; org.springframework.cloud.sleuth.log.Slf4jScopeDecorator; Closing scope for span: 71283846f6dd8fc3c096c1eae7e35142/8b3124a796b24061

I set this property via Consul and verified via Actuator (endpoint actuator/configprops) that it is set properly:

                "spring.sleuth.sampler-org.springframework.cloud.sleuth.sampler.SamplerProperties": {
                    "prefix": "spring.sleuth.sampler",
                    "properties": {
                        "probability": 1
                    }
                },

Is there any additional property/header/configuration that could prevent sending spans by Sleuth to Zipkin?

marcingrzejszczak commented 5 years ago

I'm more than certain that you're trying to trace an endpoint that is ignored by default. Where do you send your request to?

pawcykca commented 5 years ago

Below are example requests (logs from Istio-proxy sidecar container):

[2019-05-17T12:19:49.949Z] "POST /api/admin/dictionaries/pages HTTP/1.1" 200 - "-" 78 1036 151 148 "192.168.109.64" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36" "e0b550fe-269c-467f-bd87-cec5fe7bba26" "test.env:31380" "127.0.0.1:8080" inbound|8080|http|service.services.svc.cluster.local - 192.168.140.112:8080 192.168.109.64:0 -
[2019-05-17T12:20:02.100Z] "GET /api/admin/dictionaries/1 HTTP/1.1" 200 - "-" 0 57 24 22 "192.168.109.64" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36" "5f037a6c-ceff-42e2-8e28-34afd2925a1a" "test.env:31380" "127.0.0.1:8080" inbound|8080|http|service.services.svc.cluster.local - 192.168.140.112:8080 192.168.109.64:0 -
[2019-05-17T12:20:02.105Z] "POST /api/admin/dictionaries/1/values/pages HTTP/1.1" 200 - "-" 79 1851 68 67 "192.168.109.64" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36" "08ac4ef6-96f0-460b-a052-e9ba01e89718" "test.env:31380" "127.0.0.1:8080" inbound|8080|http|service.services.svc.cluster.local - 192.168.140.112:8080 192.168.109.64:0 -
[2019-05-17T12:20:02.238Z] "POST /api/institutions/pages HTTP/1.1" 200 - "-" 99 459 42 42 "192.168.109.64" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36" "ff4bc751-a19e-458c-bf65-cbfa5e439254" "test.env:31380" "127.0.0.1:8080" inbound|8080|http|service.services.svc.cluster.local - 192.168.140.112:8080 192.168.109.64:0 -
marcingrzejszczak commented 5 years ago

Doesn't istio already set the tracing headers?

pawcykca commented 5 years ago

Yes, Istio already sets tracing headers as below:

2019-05-17 13:14:51.072 TRACE [microservice-example,3cec6bab7c68679f458d44c09de3286c,10f5ce0b6ca21bbb,false] 7 --- [nio-8080-exec-6] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: 3cec6bab7c68679f458d44c09de3286c/10f5ce0b6ca21bbb
2019-05-17 13:14:51.074 TRACE [microservice-example,3cec6bab7c68679f458d44c09de3286c,10f5ce0b6ca21bbb,false] 7 --- [nio-8080-exec-6] o.s.c.sleuth.log.Slf4jScopeDecorator     : With parent: 5011737554406549612
2019-05-17 13:14:51.077 DEBUG [microservice-example,3cec6bab7c68679f458d44c09de3286c,10f5ce0b6ca21bbb,false] 7 --- [nio-8080-exec-6] o.s.w.f.CommonsRequestLoggingFilter      : Before request [uri=/api/admin/dictionaries;headers=[host:"test.env", user-agent:"PostmanRuntime/7.13.0", accept:"*/*", cache-control:"no-cache", postman-token:"3d2efef2-44cf-4394-990b-d9b167af56bc", accept-encoding:"gzip, deflate", content-length:"20", x-forwarded-for:"1.2.3.4", x-forwarded-proto:"http", x-request-id:"3f8a319f-c6b2-4d70-8192-8f9cfb9db1cb", x-envoy-internal:"true", x-b3-traceid:"3cec6bab7c68679f458d44c09de3286c", x-b3-spanid:"10f5ce0b6ca21bbb", x-b3-parentspanid:"458d44c09de3286c", x-b3-sampled:"0", Content-Type:"application/json;charset=UTF-8"]]
2019-05-17 13:14:51.081  INFO [microservice-example,3cec6bab7c68679f458d44c09de3286c,10f5ce0b6ca21bbb,false] 7 --- [nio-8080-exec-6] p.c.b.e.c.c.TestHttpsContriller          : Received request for /api/admin/dictionaries endpoint
2019-05-17 13:14:51.083 DEBUG [microservice-example,3cec6bab7c68679f458d44c09de3286c,10f5ce0b6ca21bbb,false] 7 --- [nio-8080-exec-6] o.s.w.f.CommonsRequestLoggingFilter      : REQUEST DATA: uri=/api/admin/dictionaries;headers=[host:"test.env", user-agent:"PostmanRuntime/7.13.0", accept:"*/*", cache-control:"no-cache", postman-token:"3d2efef2-44cf-4394-990b-d9b167af56bc", accept-encoding:"gzip, deflate", content-length:"20", x-forwarded-for:"1.2.3.4", x-forwarded-proto:"http", x-request-id:"3f8a319f-c6b2-4d70-8192-8f9cfb9db1cb", x-envoy-internal:"true", x-b3-traceid:"3cec6bab7c68679f458d44c09de3286c", x-b3-spanid:"10f5ce0b6ca21bbb", x-b3-parentspanid:"458d44c09de3286c", x-b3-sampled:"0", Content-Type:"application/json;charset=UTF-8"]]
2019-05-17 13:14:51.085 TRACE [microservice-example,3cec6bab7c68679f458d44c09de3286c,10f5ce0b6ca21bbb,false] 7 --- [nio-8080-exec-6] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: 3cec6bab7c68679f458d44c09de3286c/10f5ce0b6ca21bbb

Does this mean that Istio should sends this span to Zipkin on behalf of microservice if it sets tracing headers?

devinsba commented 5 years ago

You need to set the sampling in istio, it is likely marking the traces as not sampled through the headers it generated

marcingrzejszczak commented 5 years ago

Yup @devinsba is right. The request comes in to a spring sleuth application already ubsampled .

pawcykca commented 5 years ago

You are right! Default value of PILOT_TRACE_SAMPLING environment variable was set to 1.0 (what means 1%)

Thanks!