X-Ray service map and traces are not shown

[arun-gupta]

Followed the blog https://aws.amazon.com/blogs/compute/application-tracing-on-kubernetes-with-aws-x-ray/

• Attached AWSXrayFullAccess to the IAM user
• k8s cluster is running in us-west-2, so updated Dockerfile to download daemon from that region
• Pushed the image to Docker Hub
• Deployed the Daemon Set
• Updated Helm charts by adding AWS_XRAY_DAEMON_ADDRESS
• invoked the app, but no traces are found
• Service name is resolvable from greeting:

sh-4.2$ ping xray-service.default
PING xray-service.default.svc.cluster.local (172.20.32.113) 56(84) bytes of data.
64 bytes from ip-172-20-32-113.us-west-2.compute.internal (172.20.32.113): icmp_seq=1 ttl=63 time=1.15 ms
64 bytes from ip-172-20-32-113.us-west-2.compute.internal (172.20.32.113): icmp_seq=2 ttl=63 time=1.36 ms
64 bytes from ip-172-20-32-113.us-west-2.compute.internal (172.20.32.113): icmp_seq=3 ttl=63 time=1.30 ms
64 bytes from ip-172-20-32-113.us-west-2.compute.internal (172.20.32.113): icmp_seq=4 ttl=63 time=1.26 ms
^C
--- xray-service.default.svc.cluster.local ping statistics ---
4 packets transmitted, 4 received, 0% packet loss, time 3004ms
rtt min/avg/max/mdev = 1.156/1.274/1.367/0.088 ms

But no service map or traces are updated in the console.

[ckassen]

@arun-gupta can you please check the log output from the X-Ray daemon container. It should show if it successfully wrote traces to the X-Ray service. Otherwise you'll see an error message there. Right now I guess that something's wrong with the IAM permissions.

[arun-gupta]

@ckassen The logs do not show any data:

k8s $ kubectl logs xray-daemon-7t5x8
2018-03-09T02:00:51Z [Info] Initializing AWS X-Ray daemon 2.1.0
2018-03-09T02:00:51Z [Info] Using buffer memory limit of 39 MB
2018-03-09T02:00:51Z [Info] 624 segment buffers allocated
2018-03-09T02:00:51Z [Info] Using region: us-west-2
k8s $ kubectl logs xray-daemon-sshzs 
2018-03-09T02:00:50Z [Info] Initializing AWS X-Ray daemon 2.1.0
2018-03-09T02:00:50Z [Info] Using buffer memory limit of 39 MB
2018-03-09T02:00:50Z [Info] 624 segment buffers allocated
2018-03-09T02:00:50Z [Info] Using region: us-west-2

What else should we be paying attention to?

[ckassen]

Okay, so daemon is running fine but is not receiving any traces. It seems that the app is not getting any traces. Looked at the code but could not spot any obvious mistakes. Can you double check that the app is trying to send traces to X-Ray? At least any incoming requests should be sent as traces to X-Ray.

[arun-gupta]

The application code is at https://github.com/aws-samples/aws-microservices-deploy-options/blob/master/services/greeting/src/main/java/org/aws/samples/compute/greeting/GreetingEndpoint.java. Is there anything else that needs to be done to send traces?

Seems like I may have to call subsegment.setXXX to send the data?

[ckassen]

Okay, deployed everything (unmodified) to my k8s cluster and now I'm seeing this in the logs: {"log":"\u001b[0m\u001b[31m2018-03-13 20:49:28,496 ERROR [com.amazonaws.xray.emitters.UDPEmitter] (default task-1) Error switching to provided daemon address xray-service.default.svc.cluster.eks set by environment variable AWS_XRAY_DAEMON_ADDRESS. Using loopback address by default.\n","stream":"stdout","time":"2018-03-13T20:49:28.497455332Z"}

For some reason the SDK is not sending traces to the X-Ray daemon endpoints.

Additionally I also get this message in the Wildfly logs, which I don't understand:
WARN [org.jboss.as.ee] (MSC service thread 1-2) WFLYEE0007: Not installing optional component com.amazonaws.xray.javax.servlet.AWSXRayServletAsyncListener due to an exception (enable DEBUG log level to see the cause)

[arun-gupta]

@kenfinnigan any idea about this?

[ckassen]

Running everything locally and traces are being sent, so app code is working correctly apparently.

2018-03-13 22:03:38,499 DEBUG [com.amazonaws.xray.javax.servlet.AWSXRayServletFilter] (default task-2) AWSXRayServletFilter is beginning to process request: HttpServletRequestImpl [ GET /sso/login ] 2018-03-13 22:03:38,499 DEBUG [com.amazonaws.xray.strategy.sampling.LocalizedSamplingStrategy] (default task-2) Determining shouldTrace decision for: serviceName: localhost:8081 path: /sso/login method: GET 2018-03-13 22:03:38,500 DEBUG [com.amazonaws.xray.strategy.sampling.LocalizedSamplingStrategy] (default task-2) Applicable sampling rule: service_name: null http_method: null url_path: null fixed_target: 1 rate: 0.05 2018-03-13 22:03:38,500 DEBUG [com.amazonaws.xray.javax.servlet.AWSXRayServletFilter] (default task-2) Sampling strategy decided SAMPLED. 2018-03-13 22:03:38,502 DEBUG [com.amazonaws.xray.AWSXRayRecorder] (default task-2) Ending segment named 'greeting'. 2018-03-13 22:03:38,503 DEBUG [com.amazonaws.xray.emitters.UDPEmitter] (default task-2) { "name" : "greeting", "id" : "1ac6d52d97879beb", "start_time" : 1.5209750185E9, "trace_id" : "1-5aa83caa-5bdb1dce31fe2ddbf0000a87", "end_time" : 1.520975018503E9, "error" : true, "http" : { "request" : { "method" : "GET", "client_ip" : "127.0.0.1", "url" : "http://localhost:8081/sso/login", "user_agent" : "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.186 Safari/537.36" }, "response" : { "status" : 404 } }, "aws" : { "xray" : { "sdk_version" : "1.3.1", "sdk" : "X-Ray for Java" } }, "service" : { "runtime" : "Java HotSpot(TM) 64-Bit Server VM", "runtime_version" : "1.8.0_161" } } 2018-03-13 22:03:38,504 DEBUG [com.amazonaws.xray.emitters.UDPEmitter] (default task-2) Sending UDP packet.

[ckassen]

Setting AWS_XRAY_DAEMON_ADDRESS to xray-service.default:2000 changes the error to
{"log":"\u001b[0m\u001b[0m2018-03-13 21:23:21,590 INFO [com.amazonaws.xray.emitters.UDPEmitter] (default task-1) Environment variable AWS_XRAY_DAEMON_ADDRESS is set. Emitting to daemon on address xray-service.default:2000\n","stream":"stdout","time":"2018-03-13T21:23:21.591306275Z"} {"log":"\u001b[0m\u001b[31m2018-03-13 21:23:21,710 ERROR [io.undertow.request] (default task-3) UT005023: Exception handling request to /resources/greeting: java.lang.IllegalArgumentException: unresolved address\n","stream":"stdout","time":"2018-03-13T21:23:21.712016534Z"} {"log":"\u0009at java.net.DatagramPacket.setSocketAddress(DatagramPacket.java:316)\n","stream":"stdout","time":"2018-03-13T21:23:21.7120534Z"} {"log":"\u0009at java.net.DatagramPacket.\u003cinit\u003e(DatagramPacket.java:144)\n","stream":"stdout","time":"2018-03-13T21:23:21.712057855Z"} {"log":"\u0009at java.net.DatagramPacket.\u003cinit\u003e(DatagramPacket.java:178)\n","stream":"stdout","time":"2018-03-13T21:23:21.71206129Z"} {"log":"\u0009at com.amazonaws.xray.emitters.UDPEmitter.sendData(UDPEmitter.java:127)\n","stream":"stdout","time":"2018-03-13T21:23:21.712065243Z"} {"log":"\u0009at com.amazonaws.xray.emitters.UDPEmitter.sendSegment(UDPEmitter.java:111)\n","stream":"stdout","time":"2018-03-13T21:23:21.712068503Z"} {"log":"\u0009at com.amazonaws.xray.AWSXRayRecorder.endSegment(AWSXRayRecorder.java:399)\n","stream":"stdout","time":"2018-03-13T21:23:21.712071288Z"} {"log":"\u0009at com.amazonaws.xray.javax.servlet.AWSXRayServletFilter.postFilter(AWSXRayServletFilter.java:370)\n","stream":"stdout","time":"2018-03-13T21:23:21.712084059Z"} {"log":"\u0009at com.amazonaws.xray.javax.servlet.AWSXRayServletFilter.doFilter(AWSXRayServletFilter.java:166)\n","stream":"stdout","time":"2018-03-13T21:23:21.712087272Z"} {"log":"\u0009at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)\n","stream":"stdout","time":"2018-03-13T21:23:21.712090289Z"} {"log":"\u0009at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)\n","stream":"stdout","time":"2018-03-13T21:23:21.7120931Z"} {"log":"\u0009at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)\n","stream":"stdout","time":"2018-03-13T21:23:21.712096096Z"} {"log":"\u0009at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)\n","stream":"stdout","time":"2018-03-13T21:23:21.712099069Z"} {"log":"\u0009at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)\n","stream":"stdout","time":"2018-03-13T21:23:21.712101951Z"} {"log":"\u0009at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)\n","stream":"stdout","time":"2018-03-13T21:23:21.712105Z"} {"log":"\u0009at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)\n","stream":"stdout","time":"2018-03-13T21:23:21.71210824Z"} {"log":"\u0009at org.wildfly.swarm.generated.FaviconErrorHandler.handleRequest(FaviconErrorHandler.java:61)\n","stream":"stdout","time":"2018-03-13T21:23:21.71211112Z"} {"log":"\u0009at io.undertow.server.handlers.PathHandler.handleRequest(PathHandler.java:94)\n","stream":"stdout","time":"2018-03-13T21:23:21.712114095Z"} {"log":"\u0009at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)\n","stream":"stdout","time":"2018-03-13T21:23:21.712116909Z"} {"log":"\u0009at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)\n","stream":"stdout","time":"2018-03-13T21:23:21.712120041Z"} {"log":"\u0009at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)\n","stream":"stdout","time":"2018-03-13T21:23:21.712123041Z"} {"log":"\u0009at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)\n","stream":"stdout","time":"2018-03-13T21:23:21.712127367Z"} {"log":"\u0009at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)\n","stream":"stdout","time":"2018-03-13T21:23:21.712130467Z"} {"log":"\u0009at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)\n","stream":"stdout","time":"2018-03-13T21:23:21.712134028Z"} {"log":"\u0009at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)\n","stream":"stdout","time":"2018-03-13T21:23:21.712137238Z"} {"log":"\u0009at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)\n","stream":"stdout","time":"2018-03-13T21:23:21.712140364Z"} {"log":"\u0009at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)\n","stream":"stdout","time":"2018-03-13T21:23:21.712143272Z"} {"log":"\u0009at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)\n","stream":"stdout","time":"2018-03-13T21:23:21.712146257Z"} {"log":"\u0009at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)\n","stream":"stdout","time":"2018-03-13T21:23:21.71217573Z"} {"log":"\u0009at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)\n","stream":"stdout","time":"2018-03-13T21:23:21.712182909Z"} {"log":"\u0009at org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)\n","stream":"stdout","time":"2018-03-13T21:23:21.712185904Z"} {"log":"\u0009at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)\n","stream":"stdout","time":"2018-03-13T21:23:21.712188919Z"} {"log":"\u0009at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)\n","stream":"stdout","time":"2018-03-13T21:23:21.712191768Z"} {"log":"\u0009at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)\n","stream":"stdout","time":"2018-03-13T21:23:21.712194674Z"} {"log":"\u0009at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)\n","stream":"stdout","time":"2018-03-13T21:23:21.712197678Z"} {"log":"\u0009at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)\n","stream":"stdout","time":"2018-03-13T21:23:21.712200679Z"} {"log":"\u0009at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)\n","stream":"stdout","time":"2018-03-13T21:23:21.712203666Z"} {"log":"\u0009at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)\n","stream":"stdout","time":"2018-03-13T21:23:21.712206591Z"} {"log":"\u0009at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)\n","stream":"stdout","time":"2018-03-13T21:23:21.712209647Z"} {"log":"\u0009at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)\n","stream":"stdout","time":"2018-03-13T21:23:21.712213686Z"} {"log":"\u0009at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)\n","stream":"stdout","time":"2018-03-13T21:23:21.712216962Z"} {"log":"\u0009at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)\n","stream":"stdout","time":"2018-03-13T21:23:21.712220147Z"} {"log":"\u0009at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)\n","stream":"stdout","time":"2018-03-13T21:23:21.712223171Z"} {"log":"\u0009at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)\n","stream":"stdout","time":"2018-03-13T21:23:21.712226051Z"} {"log":"\u0009at io.undertow.server.Connectors.executeRootHandler(Connectors.java:326)\n","stream":"stdout","time":"2018-03-13T21:23:21.712229048Z"} {"log":"\u0009at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812)\n","stream":"stdout","time":"2018-03-13T21:23:21.712231876Z"} {"log":"\u0009at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n","stream":"stdout","time":"2018-03-13T21:23:21.712234811Z"} {"log":"\u0009at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n","stream":"stdout","time":"2018-03-13T21:23:21.712237676Z"} {"log":"\u0009at java.lang.Thread.run(Thread.java:748)\n","stream":"stdout","time":"2018-03-13T21:23:21.71224066Z"} {"log":"\n","stream":"stdout","time":"2018-03-13T21:23:21.712243487Z"}

[kenfinnigan]

The warning about a class being ignored usually means there's a WELD CNFE issue so the bean can't be instantiated

[arun-gupta]

Created a kops cluster:

Deployed the artifacts as explained at https://github.com/aws-samples/aws-microservices-deploy-options#monitoring-aws-x-ray-1

Ensure service name is resolvable from the pod:

ssh -i <key> admin@k8s-worker-host
admin@ip-172-20-66-114:~$ sudo docker ps | grep gree
admin@ip-172-20-66-114:~$ sudo docker ps | grep gree
c94c7d7c12eb        arungupta/greeting@sha256:60177ef597d2182682db28a0e7e707fb659403d4f721d4347491b2bf5c040c2b                                     "/deployments/run-..."   8 hours ago         Up 8 hours                              k8s_greeting_myapp-greeting-6df6b6799c-gjrp5_default_30672430-2775-11e8-979c-06b860720bce_0
fc73f105bff3        gcr.io/google_containers/pause-amd64:3.0                                                                                       "/pause"                 8 hours ago         Up 8 hours                              k8s_POD_myapp-greeting-6df6b6799c-gjrp5_default_30672430-2775-11e8-979c-06b860720bce_0
admin@ip-172-20-66-114:~$ sudo docker exec -it c94c7d7c12eb sh
sh-4.2$ ping xray-service.default
PING xray-service.default.svc.cluster.local (172.20.66.114) 56(84) bytes of data.
64 bytes from ip-172-20-66-114.us-west-2.compute.internal (172.20.66.114): icmp_seq=1 ttl=64 time=0.043 ms
64 bytes from ip-172-20-66-114.us-west-2.compute.internal (172.20.66.114): icmp_seq=2 ttl=64 time=0.057 ms
64 bytes from ip-172-20-66-114.us-west-2.compute.internal (172.20.66.114): icmp_seq=3 ttl=64 time=0.059 ms
^C
--- xray-service.default.svc.cluster.local ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2000ms
rtt min/avg/max/mdev = 0.043/0.053/0.059/0.007 ms

Now access the endpoint from terminal:

~ $ curl http://$(kubectl get svc/myapp-webapp -o jsonpath='{.status.loadBalancer.ingress[0].hostname}')

Check the logs of X-Ray daemon:

~ $ kubectl logs xray-daemon-rl6dt
2018-03-14T10:46:59Z [Info] Initializing AWS X-Ray daemon 2.1.0
2018-03-14T10:46:59Z [Info] Using buffer memory limit of 39 MB
2018-03-14T10:46:59Z [Info] 624 segment buffers allocated
2018-03-14T10:46:59Z [Info] Using region: us-west-2
~ $ kubectl logs xray-daemon-z9qkf
2018-03-14T10:46:59Z [Info] Initializing AWS X-Ray daemon 2.1.0
2018-03-14T10:46:59Z [Info] Using buffer memory limit of 39 MB
2018-03-14T10:46:59Z [Info] 624 segment buffers allocated
2018-03-14T10:46:59Z [Info] Using region: us-west-2

No logs are shown

[arun-gupta]

#145 fixed it