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

Question: is ok to get the same x-b3-traceid for different request without a root context? #52

Closed
aledbf opened this issue Aug 8, 2018 · 32 comments

Comments

@aledbf
Copy link

aledbf commented Aug 8, 2018

while true;do kubectl exec -n ingress-nginx   nginx-ingress-controller-76bdfb5c64-2hvcc  -it -- curl localhost/echo -H 'Host: example.com'|grep traceid ;done
	x-b3-traceid=0a1ae1fabcda88f9
	x-b3-traceid=267495655b75771f
	x-b3-traceid=a1eebdbfedb047c5
	x-b3-traceid=0c98081b94f174ff
	x-b3-traceid=0a1ae1fabcda88f9
	x-b3-traceid=c025d275e340ad21
	x-b3-traceid=f11689ab9675606e
	x-b3-traceid=e9d46ae5f3e04de4
	x-b3-traceid=9c1a32235f7413c5
	x-b3-traceid=69d3e6753e1fd345
	x-b3-traceid=69d3e6753e1fd345
	x-b3-traceid=372835f40f77de4d
	x-b3-traceid=22ffc11d5144998c
	x-b3-traceid=c6557c10db6655ac
	x-b3-traceid=5b0e43a659640f57
	x-b3-traceid=267495655b75771f
	x-b3-traceid=372835f40f77de4d
	x-b3-traceid=75c571e2172456d1
	x-b3-traceid=97f89ce39d582611
	x-b3-traceid=13bf9e8b27046f49
	x-b3-traceid=a1eebdbfedb047c5
	x-b3-traceid=be05273935e4ee03
	x-b3-traceid=5b0e43a659640f57
	x-b3-traceid=e39b41505f07beb8
	x-b3-traceid=71593a170e6a243b
	x-b3-traceid=67650848024984b1
	x-b3-traceid=a46d7d742e048b69
	x-b3-traceid=ce79afd8d60822b1
	x-b3-traceid=71593a170e6a243b
	x-b3-traceid=75c571e2172456d1
	x-b3-traceid=ce79afd8d60822b1
	x-b3-traceid=97f89ce39d582611
	x-b3-traceid=b7f0956e451fac0b
	x-b3-traceid=0b1921b459b7c4c3
	x-b3-traceid=f11689ab9675606e
	x-b3-traceid=e9d46ae5f3e04de4
	x-b3-traceid=fe446a8a0acbde99
	x-b3-traceid=d7258f18771c66f6
	x-b3-traceid=be05273935e4ee03
	x-b3-traceid=e39b41505f07beb8
	x-b3-traceid=9c1a32235f7413c5
	x-b3-traceid=84c9234b81b3f238
	x-b3-traceid=5b0e43a659640f57
	x-b3-traceid=b7f0956e451fac0b
	x-b3-traceid=67650848024984b1
	x-b3-traceid=13bf9e8b27046f49
	x-b3-traceid=a46d7d742e048b69
	x-b3-traceid=e39b41505f07beb8
	x-b3-traceid=a3facea2962664f4
@aledbf aledbf changed the title Question: is ok to get the same x-b3-traceid for different request? Question: is ok to get the same x-b3-traceid for different request without a root context? Aug 8, 2018
@Stono
Copy link

Stono commented Aug 8, 2018

This manifests for me as multiple requests being logged under the same trace!

screen shot 2018-08-08 at 19 07 47

@rnburn
Copy link
Collaborator

rnburn commented Aug 8, 2018

I was looking through the zipkin tracer, and it looks like it's using a 32-bit random number to seed the 64-bit random number generator for IDs, which would probably explain why it clashes sometimes.

I'll put in a fix so that this problem will be much less likely.

@Stono
Copy link

Stono commented Aug 8, 2018

Brilliant, thank you @rnburn

@aledbf
Copy link
Author

aledbf commented Aug 10, 2018

@rnburn any update on this? (apologies to ask this but I was planning to release a new version of the ingress controller)

@rnburn
Copy link
Collaborator

rnburn commented Aug 10, 2018

@aledbf - I'll try to get a patch in today

@rnburn
Copy link
Collaborator

rnburn commented Aug 10, 2018

I released a version of the zipkin tracer with a fix: https://github.com/rnburn/zipkin-cpp-opentracing/releases/tag/v0.5.1

@rnburn rnburn closed this as completed Aug 10, 2018
@aledbf
Copy link
Author

aledbf commented Aug 10, 2018

building...

@rnburn thank you for the quick fix!

@aledbf
Copy link
Author

aledbf commented Aug 10, 2018

@rnburn I get this error

2018/08/10 21:15:53 [emerg] 336#336: dlopen() "/etc/nginx/modules/ngx_http_opentracing_module.so" failed (/etc/nginx/modules/ngx_http_opentracing_module.so: undefined symbol: _ZN11opentracing2v13ext17sampling_priorityE) in /tmp/nginx-cfg404726037:7

I just opened #53 because I had to update opentracing-cpp to 1.5 because with 1.4 zipkin-cpp doesn't compile.

Any idea?

@rnburn
Copy link
Collaborator

rnburn commented Aug 10, 2018

It looks like a mismatch between something built with 1.4 and something else built with 1.5.

Btw - for Jaeger, you have to use this commit. They haven't released a version for OT 1.5 yet.

@aledbf
Copy link
Author

aledbf commented Aug 10, 2018

@rnburn I still see the issue

	x-b3-traceid=f6494e0eaa30f630
	x-b3-traceid=f6494e0eaa30f630
	x-b3-traceid=f6494e0eaa30f630
	x-b3-traceid=f6494e0eaa30f630
	x-b3-traceid=4fcecfd34e979374
	x-b3-traceid=4fcecfd34e979374
	x-b3-traceid=f6494e0eaa30f630
	x-b3-traceid=58db37eb8eabf4b7
	x-b3-traceid=eec79022d1e737f9
	x-b3-traceid=58db37eb8eabf4b7
	x-b3-traceid=4fcecfd34e979374
	x-b3-traceid=f6494e0eaa30f630
	x-b3-traceid=eec79022d1e737f9
	x-b3-traceid=4fcecfd34e979374
	x-b3-traceid=f6494e0eaa30f630
	x-b3-traceid=4fcecfd34e979374
	x-b3-traceid=58db37eb8eabf4b7
	x-b3-traceid=87804d1e2051b727
	x-b3-traceid=4fcecfd34e979374
	x-b3-traceid=f6494e0eaa30f630
	x-b3-traceid=58db37eb8eabf4b7
	x-b3-traceid=49b0c18b63228642
	x-b3-traceid=eec79022d1e737f9
	x-b3-traceid=eec79022d1e737f9
	x-b3-traceid=4fcecfd34e979374
	x-b3-traceid=58db37eb8eabf4b7
	x-b3-traceid=58db37eb8eabf4b7
	x-b3-traceid=4fcecfd34e979374
	x-b3-traceid=87804d1e2051b727
	x-b3-traceid=87804d1e2051b727
	x-b3-traceid=eec79022d1e737f9
	x-b3-traceid=58db37eb8eabf4b7
	x-b3-traceid=49b0c18b63228642
	x-b3-traceid=32e5ffb028e390cd
	x-b3-traceid=87804d1e2051b727
	x-b3-traceid=87804d1e2051b727
	x-b3-traceid=eec79022d1e737f9
	x-b3-traceid=49b0c18b63228642
	x-b3-traceid=49b0c18b63228642
	x-b3-traceid=eec79022d1e737f9
	x-b3-traceid=b495c0c5d7577dca
	x-b3-traceid=87804d1e2051b727
	x-b3-traceid=9778c3a9db49157c
	x-b3-traceid=49b0c18b63228642
	x-b3-traceid=32e5ffb028e390cd
	x-b3-traceid=e482467013ea9504
	x-b3-traceid=b495c0c5d7577dca
	x-b3-traceid=32e5ffb028e390cd
	x-b3-traceid=58db37eb8eabf4b7
	x-b3-traceid=32e5ffb028e390cd
	x-b3-traceid=b495c0c5d7577dca
	x-b3-traceid=49b0c18b63228642
	x-b3-traceid=b495c0c5d7577dca
	x-b3-traceid=87804d1e2051b727
	x-b3-traceid=9778c3a9db49157c
	x-b3-traceid=eec79022d1e737f9
	x-b3-traceid=87804d1e2051b727
	x-b3-traceid=49b0c18b63228642
	x-b3-traceid=32e5ffb028e390cd
	x-b3-traceid=9778c3a9db49157c
	x-b3-traceid=b495c0c5d7577dca
	x-b3-traceid=49b0c18b63228642
	x-b3-traceid=e482467013ea9504
	x-b3-traceid=9778c3a9db49157c
	x-b3-traceid=32e5ffb028e390cd
	x-b3-traceid=b495c0c5d7577dca
	x-b3-traceid=2556a4f48caba3c1
	x-b3-traceid=9778c3a9db49157c
	x-b3-traceid=e482467013ea9504
	x-b3-traceid=32e5ffb028e390cd
	x-b3-traceid=9778c3a9db49157c
	x-b3-traceid=2556a4f48caba3c1
	x-b3-traceid=2556a4f48caba3c1
	x-b3-traceid=e482467013ea9504
	x-b3-traceid=01cf586d2e0e633d
	x-b3-traceid=e482467013ea9504
	x-b3-traceid=01cf586d2e0e633d
	x-b3-traceid=e482467013ea9504
	x-b3-traceid=9250c9b137f2e8b4
	x-b3-traceid=b495c0c5d7577dca
	x-b3-traceid=1ed93dbce6c2fd57
	x-b3-traceid=2556a4f48caba3c1
	x-b3-traceid=9250c9b137f2e8b4
	x-b3-traceid=01cf586d2e0e633d
	x-b3-traceid=9250c9b137f2e8b4
	x-b3-traceid=f1206d4736ca20ef
	x-b3-traceid=2556a4f48caba3c1
	x-b3-traceid=2556a4f48caba3c1
	x-b3-traceid=01cf586d2e0e633d
	x-b3-traceid=01cf586d2e0e633d
	x-b3-traceid=9778c3a9db49157c
	x-b3-traceid=32e5ffb028e390cd
	x-b3-traceid=e482467013ea9504
	x-b3-traceid=b495c0c5d7577dca
	x-b3-traceid=8e69d4bb6867f5d4
	x-b3-traceid=9250c9b137f2e8b4
	x-b3-traceid=1ed93dbce6c2fd57
	x-b3-traceid=cb6da4c7c4a8a1d0
	x-b3-traceid=0af1db0344256cc6
	x-b3-traceid=e6c14e4781e95a0b
	x-b3-traceid=9250c9b137f2e8b4
	x-b3-traceid=03533aee2116a084
	x-b3-traceid=2556a4f48caba3c1
	x-b3-traceid=1ed93dbce6c2fd57
	x-b3-traceid=01cf586d2e0e633d
	x-b3-traceid=f1206d4736ca20ef
	x-b3-traceid=9250c9b137f2e8b4
	x-b3-traceid=9778c3a9db49157c
	x-b3-traceid=06bb12a6aecfe782
	x-b3-traceid=8e69d4bb6867f5d4
	x-b3-traceid=1ed93dbce6c2fd57
	x-b3-traceid=f1206d4736ca20ef
	x-b3-traceid=1ed93dbce6c2fd57
	x-b3-traceid=f1206d4736ca20ef
	x-b3-traceid=cb6da4c7c4a8a1d0
	x-b3-traceid=01cf586d2e0e633d
	x-b3-traceid=1ed93dbce6c2fd57
	x-b3-traceid=f1206d4736ca20ef

NGINX_OPENTRACING_VERSION=0.6.0
OPENTRACING_CPP_VERSION=1.5.0
ZIPKIN_CPP_VERSION=0.5.1
JAEGER_VERSION=ba0fa3fa6dbb01995d996f988a897e272100bf95

@rnburn
Copy link
Collaborator

rnburn commented Aug 10, 2018

@aledbf - are you sure there's not any caching going on in that test?

I'm trying something similar. I generated over 5k IDs but I'm not seeing any collisions.

@aledbf
Copy link
Author

aledbf commented Aug 10, 2018

are you sure there's not any caching going on in that test?

I am creating a new k8s cluster and compiling a new image just to be sure.

@rnburn
Copy link
Collaborator

rnburn commented Aug 10, 2018

I mean caching so that the same response is delivered.

I took this example https://github.com/opentracing-contrib/nginx-opentracing/tree/master/example/trivial/zipkin. Then modified https://github.com/opentracing-contrib/nginx-opentracing/blob/master/example/trivial/zipkin/go/server.go with

@@ -30,6 +30,11 @@ func handler(w http.ResponseWriter, r *http.Request) {
                opentracing.ChildOf(wireContext))
        defer span.Finish()
        tm := time.Now().Format(time.RFC1123)
+  for name, headers := range r.Header {
+    for _, h := range headers {
+      w.Write([]byte(fmt.Sprintf("%v: %v\n", name, h)))
+    }
+  }
        w.Write([]byte("The time is " + tm))
 }

After starting with docker-compose and running

Ryans-MacBook-Pro:zipkin ryanburn$ while true; do curl -s localhost:8080 | grep Traceid; done
X-B3-Traceid: 64e3661f25f81ccb
X-B3-Traceid: aa4baa5e24363bf7
X-B3-Traceid: b37acf34afa426f7
X-B3-Traceid: 2c83c9c37a2e25e8
X-B3-Traceid: 7850cf11bd778eb5
X-B3-Traceid: 1b65ac45633a9156
X-B3-Traceid: 04c47049e0652ff9
X-B3-Traceid: 004bc0a32789723e
X-B3-Traceid: b56a74d0121a773a
X-B3-Traceid: 6e2a7c1f317d1531
X-B3-Traceid: 00df91c9f9cb12f3
X-B3-Traceid: dc45f9e7754ef15c
X-B3-Traceid: 2344124cd9e76d22
X-B3-Traceid: ca51bce0f217e4f8
X-B3-Traceid: 3f4c095c8a49efc2
X-B3-Traceid: d6c556c581824e8e
X-B3-Traceid: 8da5ffc8ff46b4d0
X-B3-Traceid: ff444b03c0c7fe55
X-B3-Traceid: 3f429491b0e321ce
X-B3-Traceid: b5acb0cf118c2a19
X-B3-Traceid: 827d40cc1c2fa3fb
X-B3-Traceid: 31064ab19bff7a12
X-B3-Traceid: 52e20279629457da
X-B3-Traceid: a68d434a3516fd74
X-B3-Traceid: a986efd671df451e
X-B3-Traceid: 015bbbbe1746ec91
X-B3-Traceid: bc12a5c742ab6aeb
X-B3-Traceid: 8b8bb8f363718168
X-B3-Traceid: 6d77305538c42099
X-B3-Traceid: 23d378c701f32212
X-B3-Traceid: 1b37ea3646ecb161
X-B3-Traceid: f4c6ff7d4a7d352f
X-B3-Traceid: e23a2f91e8d6b2fd
X-B3-Traceid: 5ef2a4ddf96439c8
X-B3-Traceid: 3fe7280b7ef2bf6a
X-B3-Traceid: 6a68670034b6dab9
X-B3-Traceid: bd511764c42274a0
X-B3-Traceid: 01be87728b5fd4dd
X-B3-Traceid: d5c675222fed115b
X-B3-Traceid: 2084e4deb802778d
X-B3-Traceid: be763933aa53500b
X-B3-Traceid: 7110bd2132595284
X-B3-Traceid: 41e26ad3d2f6d4ea
X-B3-Traceid: c1a8d8e81515a452
X-B3-Traceid: 2eab96b0ba0e0a28
X-B3-Traceid: ff8f8a81eff0bdb8
X-B3-Traceid: 352f4639ad628277
X-B3-Traceid: 65e85a193e2ca9c2
X-B3-Traceid: f22339e27d29fb3a
X-B3-Traceid: 8260fef856899ed2
X-B3-Traceid: 51249138db35959c
X-B3-Traceid: f410bcdee637c4ff
X-B3-Traceid: 5fd468a715039134
X-B3-Traceid: 3447ebf813917050
X-B3-Traceid: 821465ad07fcc2d1
X-B3-Traceid: a10e694359841850
X-B3-Traceid: 93baa222ecec4bad
X-B3-Traceid: c10a32d323e91175
X-B3-Traceid: afb479acc6a93d86
X-B3-Traceid: 43f3c51cf04733a5
X-B3-Traceid: 5610ba4477045ef7
X-B3-Traceid: 8b72b61e4bfb5840
X-B3-Traceid: 5581620621a046c9
X-B3-Traceid: 6925ae03c8efaa0f
X-B3-Traceid: e9a0189a6c8ac62c
X-B3-Traceid: 4fa503d04bf40d73
X-B3-Traceid: 8f38615b58d40f22
X-B3-Traceid: fb1247e4814a4f82
X-B3-Traceid: 9d693cbf055ce0a2
X-B3-Traceid: f37a4a5871f7acd6
X-B3-Traceid: 31915377fc2d79f0
X-B3-Traceid: b77b8a026fc93e0b
X-B3-Traceid: 5087f5932985e5d3
X-B3-Traceid: 403c7ae59dc159ac
X-B3-Traceid: d60a2296f93c26d3

I don't see any clashes.

@aledbf
Copy link
Author

aledbf commented Aug 10, 2018

@rnburn this is strange, I still see duplicates. This is the config file https://gist.github.com/aledbf/d65841c037e29725872c5b4e9dd2cae5#file-nginx-conf-L392
The test app just dumps the headers

@aledbf
Copy link
Author

aledbf commented Aug 11, 2018

Ok, this is an example of two requests where nginx returns different x-request-id headers. Why x-b3-parentspanid is not empty?

Hostname: http-svc-664d7bc4bc-hvj2s

Pod Information:
	node name:	kube-node-2
	pod name:	http-svc-664d7bc4bc-hvj2s
	pod namespace:	default
	pod IP:	10.244.3.10

Server values:
	server_version=nginx: 1.12.2 - lua: 10010

Request Information:
	client_address=10.244.3.9
	method=GET
	real path=/
	query=
	request_version=1.1
	request_scheme=http
	request_uri=http://echoheaders:8080/

Request Headers:
	accept=*/*
	connection=close
	host=echoheaders
	user-agent=curl/7.58.0
	x-b3-flags=0
	x-b3-parentspanid=b645ed6a787276a2
	x-b3-sampled=1
	x-b3-spanid=a1badc73a4d2b5fe
	x-b3-traceid=51036217f8abdc99
	x-forwarded-for=10.192.0.3
	x-forwarded-host=echoheaders
	x-forwarded-port=80
	x-forwarded-proto=http
	x-original-uri=/
	x-real-ip=10.192.0.3
	x-request-id=eeca23da25f7d8442f9e0c6e74653516
	x-scheme=http

Request Body:
	-no body in request-
Hostname: http-svc-664d7bc4bc-hvj2s

Pod Information:
	node name:	kube-node-2
	pod name:	http-svc-664d7bc4bc-hvj2s
	pod namespace:	default
	pod IP:	10.244.3.10

Server values:
	server_version=nginx: 1.12.2 - lua: 10010

Request Information:
	client_address=10.244.3.9
	method=GET
	real path=/
	query=
	request_version=1.1
	request_scheme=http
	request_uri=http://echoheaders:8080/

Request Headers:
	accept=*/*
	connection=close
	host=echoheaders
	user-agent=curl/7.58.0
	x-b3-flags=0
	x-b3-parentspanid=b645ed6a787276a2
	x-b3-sampled=1
	x-b3-spanid=a1badc73a4d2b5fe
	x-b3-traceid=51036217f8abdc99
	x-forwarded-for=10.192.0.3
	x-forwarded-host=echoheaders
	x-forwarded-port=80
	x-forwarded-proto=http
	x-original-uri=/
	x-real-ip=10.192.0.3
	x-request-id=bc4cfa3d02646d544f6975ac9114d4f3
	x-scheme=http

Request Body:
	-no body in request-
diff -u 1 2
--- 1	2018-08-10 22:34:55.061868000 -0400
+++ 2	2018-08-10 22:35:06.678443214 -0400
@@ -34,7 +34,7 @@
 	x-forwarded-proto=http
 	x-original-uri=/
 	x-real-ip=10.192.0.3
-	x-request-id=bc4cfa3d02646d544f6975ac9114d4f3
+	x-request-id=eeca23da25f7d8442f9e0c6e74653516
 	x-scheme=http

Edit: I cannot find the referenced x-b3-parentspanid in the log

@aledbf
Copy link
Author

aledbf commented Aug 11, 2018

This is a nginx trace (not sure if this is useful)

2018/08/11 03:14:24 [debug] 121#121: accept on 0.0.0.0:80, ready: 1
2018/08/11 03:14:24 [debug] 121#121: posix_memalign: 0000559B96494910:512 @16
2018/08/11 03:14:24 [debug] 121#121: *2 accept: 10.192.0.3:24608 fd:3
2018/08/11 03:14:24 [debug] 121#121: *2 event timer add: 3: 60000:483464395
2018/08/11 03:14:24 [debug] 121#121: *2 reusable connection: 1
2018/08/11 03:14:24 [debug] 121#121: *2 epoll add event: fd:3 op:1 ev:80002001
2018/08/11 03:14:24 [debug] 121#121: accept() not ready (11: Resource temporarily unavailable)
2018/08/11 03:14:24 [debug] 121#121: *2 http wait request handler
2018/08/11 03:14:24 [debug] 121#121: *2 malloc: 0000559B96527580:1024
2018/08/11 03:14:24 [debug] 121#121: *2 recv: eof:0, avail:1
2018/08/11 03:14:24 [debug] 121#121: *2 recv: fd:3 75 of 1024
2018/08/11 03:14:24 [debug] 121#121: *2 reusable connection: 0
2018/08/11 03:14:24 [debug] 121#121: *2 posix_memalign: 0000559B9647E7B0:4096 @16
2018/08/11 03:14:24 [debug] 121#121: *2 http process request line
2018/08/11 03:14:24 [debug] 121#121: *2 http request line: "GET / HTTP/1.1"
2018/08/11 03:14:24 [debug] 121#121: *2 http uri: "/"
2018/08/11 03:14:24 [debug] 121#121: *2 http args: ""
2018/08/11 03:14:24 [debug] 121#121: *2 http exten: ""
2018/08/11 03:14:24 [debug] 121#121: *2 posix_memalign: 0000559B96474FD0:4096 @16
2018/08/11 03:14:24 [debug] 121#121: *2 http process request header line
2018/08/11 03:14:24 [debug] 121#121: *2 http header: "Host: echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http header: "User-Agent: curl/7.58.0"
2018/08/11 03:14:24 [debug] 121#121: *2 http header: "Accept: */*"
2018/08/11 03:14:24 [debug] 121#121: *2 http header done
2018/08/11 03:14:24 [debug] 121#121: *2 event timer del: 3: 483464395
2018/08/11 03:14:24 [debug] 121#121: *2 generic phase: 0
2018/08/11 03:14:24 [debug] 121#121: *2 rewrite phase: 1
2018/08/11 03:14:24 [debug] 121#121: *2 http script value: "-"
2018/08/11 03:14:24 [debug] 121#121: *2 http script set $proxy_upstream_name
2018/08/11 03:14:24 [debug] 121#121: *2 test location: "/"
2018/08/11 03:14:24 [debug] 121#121: *2 using configuration "/"
2018/08/11 03:14:24 [debug] 121#121: *2 http cl:-1 max:1048576
2018/08/11 03:14:24 [debug] 121#121: *2 rewrite phase: 3
2018/08/11 03:14:24 [debug] 121#121: *2 lua rewrite handler, uri:"/" c:1
2018/08/11 03:14:24 [debug] 121#121: *2 rewrite phase: 3
2018/08/11 03:14:24 [debug] 121#121: *2 http script value: "default"
2018/08/11 03:14:24 [debug] 121#121: *2 http script set $namespace
2018/08/11 03:14:24 [debug] 121#121: *2 http script value: "http-svc"
2018/08/11 03:14:24 [debug] 121#121: *2 http script set $ingress_name
2018/08/11 03:14:24 [debug] 121#121: *2 http script value: "http-svc"
2018/08/11 03:14:24 [debug] 121#121: *2 http script set $service_name
2018/08/11 03:14:24 [debug] 121#121: *2 http script value: "80"
2018/08/11 03:14:24 [debug] 121#121: *2 http script set $service_port
2018/08/11 03:14:24 [debug] 121#121: *2 http script value: "/"
2018/08/11 03:14:24 [debug] 121#121: *2 http script set $location_path
2018/08/11 03:14:24 [debug] 121#121: *2 http script value: "default-http-svc-80"
2018/08/11 03:14:24 [debug] 121#121: *2 http script set $proxy_upstream_name
2018/08/11 03:14:24 [debug] 121#121: *2 rewrite phase: 4
2018/08/11 03:14:24 [debug] 121#121: *2 lua rewrite handler, uri:"/" c:1
2018/08/11 03:14:24 [debug] 121#121: *2 lua creating new thread
2018/08/11 03:14:24 [debug] 121#121: *2 lua reset ctx
2018/08/11 03:14:24 [debug] 121#121: *2 http cleanup add: 0000559B96475740
2018/08/11 03:14:24 [debug] 121#121: *2 lua run thread, top:0 c:1
2018/08/11 03:14:24 [debug] 121#121: *2 lua resume returned 0
2018/08/11 03:14:24 [debug] 121#121: *2 lua light thread ended normally
2018/08/11 03:14:24 [debug] 121#121: *2 lua deleting light thread
2018/08/11 03:14:24 [debug] 121#121: *2 post rewrite phase: 5
2018/08/11 03:14:24 [debug] 121#121: *2 generic phase: 6
2018/08/11 03:14:24 [debug] 121#121: *2 extraced opentracing span context from request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 starting opentracing request span for 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 starting opentracing location span for "/"(0000559B96505C98) in request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 add cleanup: 0000559B96475758
2018/08/11 03:14:24 [debug] 121#121: *2 generic phase: 7
2018/08/11 03:14:24 [debug] 121#121: *2 generic phase: 8
2018/08/11 03:14:24 [debug] 121#121: *2 generic phase: 9
2018/08/11 03:14:24 [debug] 121#121: *2 access phase: 10
2018/08/11 03:14:24 [debug] 121#121: *2 access phase: 11
2018/08/11 03:14:24 [debug] 121#121: *2 access phase: 12
2018/08/11 03:14:24 [debug] 121#121: *2 access phase: 13
2018/08/11 03:14:24 [debug] 121#121: *2 post access phase: 14
2018/08/11 03:14:24 [debug] 121#121: *2 generic phase: 15
2018/08/11 03:14:24 [debug] 121#121: *2 generic phase: 16
2018/08/11 03:14:24 [debug] 121#121: *2 http init upstream, client timer: 0
2018/08/11 03:14:24 [debug] 121#121: *2 epoll add event: fd:3 op:3 ev:80002005
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "echoheaders" "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "" "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "" "close"
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "22d7225341fe05df77be75b9a4b33b01"
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "" "22d7225341fe05df77be75b9a4b33b01"
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "10.192.0.3"
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "" "10.192.0.3"
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "80"
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "" "80"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "80"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "80"
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "80" "80"
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "http"
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "" "http"
2018/08/11 03:14:24 [debug] 121#121: *2 posix_memalign: 0000559B96472BD0:4096 @16
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "x-b3-traceid"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "527910c2890997ab"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "x-b3-spanid"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "70d1ab359bad5e75"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "x-b3-sampled"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "1"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "x-b3-parentspanid"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "f62321d7f9f3195b"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "x-b3-flags"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "0"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "Host"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: ""
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "Connection"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "close"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "X-Request-ID"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "22d7225341fe05df77be75b9a4b33b01"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "X-Real-IP"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "10.192.0.3"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "X-Forwarded-For"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "10.192.0.3"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "X-Forwarded-Host"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "X-Forwarded-Port"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "80"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "X-Forwarded-Proto"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "http"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "X-Original-URI"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "/"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "X-Scheme"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "http"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: ""
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: ""
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: ""
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header: "User-Agent: curl/7.58.0"
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header: "Accept: */*"
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header:
"GET / HTTP/1.1
x-b3-traceid: 527910c2890997ab
x-b3-spanid: 70d1ab359bad5e75
x-b3-sampled: 1
x-b3-parentspanid: f62321d7f9f3195b
x-b3-flags: 0
Host: echoheaders
Connection: close
X-Request-ID: 22d7225341fe05df77be75b9a4b33b01
X-Real-IP: 10.192.0.3
X-Forwarded-For: 10.192.0.3
X-Forwarded-Host: echoheaders
X-Forwarded-Port: 80
X-Forwarded-Proto: http
X-Original-URI: /
X-Scheme: http
User-Agent: curl/7.58.0
Accept: */*

"
2018/08/11 03:14:24 [debug] 121#121: *2 http cleanup add: 0000559B96475F60
2018/08/11 03:14:24 [debug] 121#121: *2 init keepalive peer
2018/08/11 03:14:24 [debug] 121#121: *2 get keepalive peer
2018/08/11 03:14:24 [debug] 121#121: *2 get rr peer, try: 1
2018/08/11 03:14:24 [debug] 121#121: *2 stream socket 77
2018/08/11 03:14:24 [debug] 121#121: *2 epoll add connection: fd:77 ev:80002005
2018/08/11 03:14:24 [debug] 121#121: *2 connect to 10.244.3.10:8080, fd:77 #3
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream connect: -2
2018/08/11 03:14:24 [debug] 121#121: *2 posix_memalign: 0000559B964961B0:128 @16
2018/08/11 03:14:24 [debug] 121#121: *2 event timer add: 77: 5000:483409395
2018/08/11 03:14:24 [debug] 121#121: *2 http finalize request: -4, "/?" a:1, c:2
2018/08/11 03:14:24 [debug] 121#121: *2 http request count:2 blk:0
2018/08/11 03:14:24 [debug] 121#121: *2 http run request: "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream check client, write event:1, "/"
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream request: "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream send request handler
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream send request
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream send request body
2018/08/11 03:14:24 [debug] 121#121: *2 chain writer buf fl:1 s:439
2018/08/11 03:14:24 [debug] 121#121: *2 chain writer in: 0000559B96475FB0
2018/08/11 03:14:24 [debug] 121#121: *2 writev: 439 of 439
2018/08/11 03:14:24 [debug] 121#121: *2 chain writer out: 0000000000000000
2018/08/11 03:14:24 [debug] 121#121: *2 event timer del: 77: 483409395
2018/08/11 03:14:24 [debug] 121#121: *2 event timer add: 77: 60000:483464399
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream request: "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream process header
2018/08/11 03:14:24 [debug] 121#121: *2 malloc: 0000559B96482A00:4096
2018/08/11 03:14:24 [debug] 121#121: *2 recv: eof:0, avail:1
2018/08/11 03:14:24 [debug] 121#121: *2 recv: fd:77 1005 of 4096
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy status 200 "200 OK"
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header: "Date: Sat, 11 Aug 2018 03:14:24 GMT"
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header: "Content-Type: text/plain"
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header: "Transfer-Encoding: chunked"
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header: "Connection: close"
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header: "Server: echoserver"
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy header done
2018/08/11 03:14:24 [debug] 121#121: *2 lua capture header filter, uri "/"
2018/08/11 03:14:24 [debug] 121#121: *2 headers more header filter, uri "/"
2018/08/11 03:14:24 [debug] 121#121: *2 filter http_cookie_flag is disabled
2018/08/11 03:14:24 [debug] 121#121: *2 HTTP/1.1 200 OK
Server: nginx/1.15.2
Date: Sat, 11 Aug 2018 03:14:24 GMT
Content-Type: text/plain
Transfer-Encoding: chunked
Connection: keep-alive
Vary: Accept-Encoding

2018/08/11 03:14:24 [debug] 121#121: *2 write new buf t:1 f:0 0000559B964730D0, pos 0000559B964730D0, size: 179 file: 0, size: 0
2018/08/11 03:14:24 [debug] 121#121: *2 http write filter: l:0 f:0 s:179
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy filter init s:200 h:0 c:1 l:-1
2018/08/11 03:14:24 [debug] 121#121: *2 tcp_nodelay
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 33 s:0
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 34 s:1
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 63 s:1
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0D s:1
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0A s:3
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0A s:4
2018/08/11 03:14:24 [debug] 121#121: *2 http proxy out buf 0000559B96482A9A 844
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0D s:5
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0A s:6
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 30 s:0
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0D s:1
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0A s:8
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0D s:9
2018/08/11 03:14:24 [debug] 121#121: *2 http chunked byte: 0A s:10
2018/08/11 03:14:24 [debug] 121#121: *2 http upstream process non buffered downstream
2018/08/11 03:14:24 [debug] 121#121: *2 http output filter "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 http copy filter: "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 lua capture body filter, uri "/"
2018/08/11 03:14:24 [debug] 121#121: *2 http postpone filter "/?" 0000559B96473188
2018/08/11 03:14:24 [debug] 121#121: *2 http chunk: 844
2018/08/11 03:14:24 [debug] 121#121: *2 write old buf t:1 f:0 0000559B964730D0, pos 0000559B964730D0, size: 179 file: 0, size: 0
2018/08/11 03:14:24 [debug] 121#121: *2 write new buf t:1 f:0 0000559B964732E0, pos 0000559B964732E0, size: 5 file: 0, size: 0
2018/08/11 03:14:24 [debug] 121#121: *2 write new buf t:0 f:0 0000000000000000, pos 0000559B96482A9A, size: 844 file: 0, size: 0
2018/08/11 03:14:24 [debug] 121#121: *2 write new buf t:0 f:0 0000000000000000, pos 0000559B95249D54, size: 2 file: 0, size: 0
2018/08/11 03:14:24 [debug] 121#121: *2 http write filter: l:0 f:1 s:1030
2018/08/11 03:14:24 [debug] 121#121: *2 http write filter limit 0
2018/08/11 03:14:24 [debug] 121#121: *2 writev: 1030 of 1030
2018/08/11 03:14:24 [debug] 121#121: *2 http write filter 0000000000000000
2018/08/11 03:14:24 [debug] 121#121: *2 http copy filter: 0 "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 finalize http upstream request: 0
2018/08/11 03:14:24 [debug] 121#121: *2 finalize http proxy request
2018/08/11 03:14:24 [debug] 121#121: *2 free keepalive peer
2018/08/11 03:14:24 [debug] 121#121: *2 free rr peer 1 0
2018/08/11 03:14:24 [debug] 121#121: *2 close http upstream connection: 77
2018/08/11 03:14:24 [debug] 121#121: *2 free: 0000559B964961B0, unused: 48
2018/08/11 03:14:24 [debug] 121#121: *2 event timer del: 77: 483464399
2018/08/11 03:14:24 [debug] 121#121: *2 reusable connection: 0
2018/08/11 03:14:24 [debug] 121#121: *2 http output filter "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 http copy filter: "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 lua capture body filter, uri "/"
2018/08/11 03:14:24 [debug] 121#121: *2 http postpone filter "/?" 00007FFFD5ED6250
2018/08/11 03:14:24 [debug] 121#121: *2 http chunk: 0
2018/08/11 03:14:24 [debug] 121#121: *2 write new buf t:0 f:0 0000000000000000, pos 0000559B95249D51, size: 5 file: 0, size: 0
2018/08/11 03:14:24 [debug] 121#121: *2 http write filter: l:1 f:0 s:5
2018/08/11 03:14:24 [debug] 121#121: *2 http write filter limit 0
2018/08/11 03:14:24 [debug] 121#121: *2 writev: 5 of 5
2018/08/11 03:14:24 [debug] 121#121: *2 http write filter 0000000000000000
2018/08/11 03:14:24 [debug] 121#121: *2 http copy filter: 0 "/?"
2018/08/11 03:14:24 [debug] 121#121: *2 http finalize request: 0, "/?" a:1, c:1
2018/08/11 03:14:24 [debug] 121#121: *2 set http keepalive handler
2018/08/11 03:14:24 [debug] 121#121: *2 http close request
2018/08/11 03:14:24 [debug] 121#121: *2 lua request cleanup: forcible=0
2018/08/11 03:14:24 [debug] 121#121: *2 lua log handler, uri:"/" c:1
2018/08/11 03:14:24 [debug] 121#121: *2 malloc: 0000559B964945B0:184
2018/08/11 03:14:24 [debug] 121#121: *2 http log handler
2018/08/11 03:14:24 [debug] 121#121: *2 http map started
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "/"
2018/08/11 03:14:24 [debug] 121#121: *2 http map: "/" "1"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "1"
2018/08/11 03:14:24 [debug] 121#121: *2 finishing opentracing location span for 0000559B96505C98 in request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "component" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "nginx" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "nginx.worker_pid" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$pid" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "121"
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "peer.address" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$remote_addr:$remote_port" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "10.192.0.3"
10.192.0.3 - [10.192.0.3] - - [11/Aug/2018:03:14:24 +0000] "GET / HTTP/1.1" 200 856 "-" "curl/7.58.0" 75 0.003 [default-http-svc-80] 10.244.3.10:8080 856 0.004 200 22d7225341fe05df77be75b9a4b33b01
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: ":"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "24608"
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "http.method" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$request_method" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "GET"
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "http.url" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$scheme://$http_host$request_uri" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "http"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "://"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "/"
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "http.host" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$http_host" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 finishing opentracing request span for 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "component" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "nginx" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "nginx.worker_pid" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$pid" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "121"
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "peer.address" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$remote_addr:$remote_port" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "10.192.0.3"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: ":"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "24608"
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "http.method" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$request_method" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "GET"
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "http.url" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$scheme://$http_host$request_uri" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "http"
2018/08/11 03:14:24 [debug] 121#121: *2 http script copy: "://"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "/"
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "http.host" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 executing opentracing script "$http_host" for request 0000559B9647E800
2018/08/11 03:14:24 [debug] 121#121: *2 http script var: "echoheaders"
2018/08/11 03:14:24 [debug] 121#121: *2 run cleanup: 0000559B96475758
2018/08/11 03:14:24 [debug] 121#121: *2 free: 0000559B96482A00
2018/08/11 03:14:24 [debug] 121#121: *2 free: 0000559B9647E7B0, unused: 0
2018/08/11 03:14:24 [debug] 121#121: *2 free: 0000559B96474FD0, unused: 0
2018/08/11 03:14:24 [debug] 121#121: *2 free: 0000559B96472BD0, unused: 1298
2018/08/11 03:14:24 [debug] 121#121: *2 free: 0000559B96527580
2018/08/11 03:14:24 [debug] 121#121: *2 hc free: 0000000000000000
2018/08/11 03:14:24 [debug] 121#121: *2 hc busy: 0000000000000000 0
2018/08/11 03:14:24 [debug] 121#121: *2 reusable connection: 1
2018/08/11 03:14:24 [debug] 121#121: *2 event timer add: 3: 75000:483479399
2018/08/11 03:14:24 [debug] 121#121: *2 http keepalive handler
2018/08/11 03:14:24 [debug] 121#121: *2 malloc: 0000559B96527580:1024
2018/08/11 03:14:24 [debug] 121#121: *2 recv: eof:1, avail:1
2018/08/11 03:14:24 [debug] 121#121: *2 recv: fd:3 0 of 1024
2018/08/11 03:14:24 [info] 121#121: *2 client 10.192.0.3 closed keepalive connection
2018/08/11 03:14:24 [debug] 121#121: *2 close http connection: 3
2018/08/11 03:14:24 [debug] 121#121: *2 event timer del: 3: 483479399
2018/08/11 03:14:24 [debug] 121#121: *2 reusable connection: 0
2018/08/11 03:14:24 [debug] 121#121: *2 free: 0000559B96527580
2018/08/11 03:14:24 [debug] 121#121: *2 free: 0000559B96494910, unused: 120
2018/08/11 03:14:24 [debug] 121#121: *4 http cleanup add: 0000559B96482880
2018/08/11 03:14:24 [debug] 121#121: *4 lua run thread, top:0 c:1
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket pool get keepalive peer
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket keepalive connection pool not found
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket connect timeout: 60000
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket network address given directly
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket resolve retval handler
2018/08/11 03:14:24 [debug] 121#121: *4 stream socket 3
2018/08/11 03:14:24 [debug] 121#121: *4 epoll add connection: fd:3 ev:80002005
2018/08/11 03:14:24 [debug] 121#121: *4 connect to unix:/tmp/prometheus-nginx.socket, fd:3 #5
2018/08/11 03:14:24 [debug] 121#121: *4 connected
2018/08/11 03:14:24 [debug] 121#121: *4 http cleanup add: 0000559B964947A0
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket connect: 0
2018/08/11 03:14:24 [debug] 121#121: *4 posix_memalign: 0000559B96492D90:128 @16
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket connected: fd:3
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket send timeout: 60000
2018/08/11 03:14:24 [debug] 121#121: *4 lua allocate new chainlink and new buf of size 324, cl:0000559B96496580
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket send data
2018/08/11 03:14:24 [debug] 121#121: *4 send: fd:3 324 of 324
2018/08/11 03:14:24 [debug] 121#121: *4 lua tcp socket sent all the data
2018/08/11 03:14:24 [debug] 121#121: *4 lua finalize socket
2018/08/11 03:14:24 [debug] 121#121: *4 lua http cleanup free: 0000559B964947A0
2018/08/11 03:14:24 [debug] 121#121: *4 lua close socket connection
2018/08/11 03:14:24 [debug] 121#121: *4 free: 0000559B96492D90, unused: 48
2018/08/11 03:14:24 [debug] 121#121: *4 reusable connection: 0
2018/08/11 03:14:24 [debug] 121#121: *4 lua resume returned 0
2018/08/11 03:14:24 [debug] 121#121: *4 lua light thread ended normally
2018/08/11 03:14:24 [debug] 121#121: *4 lua deleting light thread
2018/08/11 03:14:24 [debug] 121#121: *4 http lua finalize fake request: 0, a:1, c:1
2018/08/11 03:14:24 [debug] 121#121: *4 http lua fake request count:1
2018/08/11 03:14:24 [debug] 121#121: *4 http lua close fake request
2018/08/11 03:14:24 [debug] 121#121: *4 lua request cleanup: forcible=0
2018/08/11 03:14:24 [debug] 121#121: *4 http lua close fake http connection 00007F6B044BE6D8

@rnburn
Copy link
Collaborator

rnburn commented Aug 13, 2018

@aledbf - By default, nginx-opentracing creates a span to represent the processing of a the entire request and spans for each location block associated with the request. It can be useful if the request moves through multiple location blocks, but redundant if there's only one.

I think that parent span id represents the id of the request level span.

You can turn off location block spans with opentracing_trace_locations off;; then you shouldn't get any parent id.

@aledbf
Copy link
Author

aledbf commented Aug 13, 2018

@rnburn any idea how I can trace the issue with the duplication of ids?

@rnburn
Copy link
Collaborator

rnburn commented Aug 13, 2018

@aledbf - do the requests with the same trace-ids have the same x-request-id?

@aledbf
Copy link
Author

aledbf commented Aug 13, 2018

do the requests with the same trace-ids have the same x-request-id?

No. There's no repetition in the x-request-id header

@rnburn
Copy link
Collaborator

rnburn commented Aug 13, 2018

Can you reproduce it with a smaller docker-compose setup?

@Stono
Copy link

Stono commented Aug 14, 2018

@rnburn any ideas what may be causing this? Really missing having tracing enabled, but have had to disable it for now due to the collisions

@rnburn rnburn reopened this Aug 15, 2018
@rnburn
Copy link
Collaborator

rnburn commented Aug 15, 2018

@Stono - I'm not sure. I wasn't able to reproduce anything similar.

I set up a docker-compose example that uses ingress-nginx's image: https://github.com/rnburn/example/tree/master/nginx-duplicate/zipkin

You can run it with while true; do curl -s localhost:8080 | grep Traceid; done to see IDs but they're always different when I run

If you can modify nginx.conf to reproduce the problem with this minimal example, that would certainly help to figure out what's causing the id clashes.

@Stono
Copy link

Stono commented Aug 15, 2018

@aledbf can you pass over your config where you were able to duplicate?

@Stono
Copy link

Stono commented Aug 16, 2018

@aledbf @rnburn some more discovery...
When I have nginx worker processes set to 12, I get duplicate trace id's, when i have nginx worker processes set to 1, I have no duplicates??!

With 1 worker:

❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "377272f47b5e7cc5",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "9c88d136acb0a0b4",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "f0cfc2d6691c5503",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "d29253295ee981f0",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "35568e5b0260fe31",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "f82246221e317d39",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "126baefe9f58ccae",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "6d8a67faea18e67c",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "b0e62db1b6783836",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "699c544ba489b3e3",

With 12 workers:

/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "5de2eeacf39ffeed",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "5de2eeacf39ffeed",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "5ecf79c5975ac091",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "5ecf79c5975ac091",
/Users/karl.stoney/git/autotrader/charts/helm-infra-calico git/master
❯ curl https://app.platform-testing.testing.k8.atcloud.io/ 2>/dev/null | grep -i traceid
    "x-b3-traceid": "5de2eeacf39ffeed",

@aledbf
Copy link
Author

aledbf commented Aug 16, 2018

@rnburn I can reproduce the scenario mentioned by @Stono

@aledbf
Copy link
Author

aledbf commented Aug 16, 2018

@rnburn using https://github.com/rnburn/zipkin-cpp-opentracing/compare/master...aledbf:seed?expand=1 the issue is gone (I am not sure the impact in performance with this change)

@rnburn
Copy link
Collaborator

rnburn commented Aug 16, 2018

@aledbf - yeah, it looks like the thread_local storage is getting initialized in the master process, but not reinitialized after it forks the workers.

Unfortunately changing it like that is going to be costly since it will reseed the random number generator for each call to the function. But I'll do some research to see if there's a better way.

@rnburn
Copy link
Collaborator

rnburn commented Aug 16, 2018

@aledbf - Can you try the version from this PR: rnburn/zipkin-cpp-opentracing#27?

@aledbf
Copy link
Author

aledbf commented Aug 17, 2018

@rnburn it works as expected. Thanks for the quick fix!

@aledbf aledbf closed this as completed Aug 17, 2018
@rnburn
Copy link
Collaborator

rnburn commented Aug 17, 2018

@aledbf - https://github.com/rnburn/zipkin-cpp-opentracing/releases/tag/v0.5.2 has the fix.

abbi-gaurav added a commit to abbi-gaurav/kyma that referenced this issue Oct 2, 2018
crabtree pushed a commit to kyma-project/kyma that referenced this issue Oct 4, 2018
crabtree pushed a commit to kyma-project/kyma that referenced this issue Oct 4, 2018
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

3 participants