Skip to content

Distributed trace with checkout and anti-fraud functions is not connected in Elastic APM #1

Open
Open
Distributed trace with checkout and anti-fraud functions is not connected in Elastic APM#1

Description

@cyrille-leclerc
cyrille-leclerc
opened on Jun 28, 2021

Root Cause Analysis

⚠️ ❗ Each span and transaction document in Elastic APM is duplicated

What is the following error message

Jun 28, 2021 8:42:35 PM io.opentelemetry.sdk.internal.ThrottlingLogger doLog
WARNING: Failed to export spans. Error message: UNKNOWN: Permanent error: AccessDeniedException:

Summary

 Service Type traceparent
Checkout Function client 00-60da343b0d6df30835d711286793d398-6a8f436339bb89f2-01
Anti Fraud Function server 00-60da343b0d6df30835d711286793d398-6a8f436339bb89f2-01

Distributed Traces in Elastic

https://gist.github.com/cyrille-leclerc/3e91c8d318e531738517ffa8477f1291

Checkout Function

  • Trace parent emitted in the downstream HTTP request: traceparent: 00-60da343b0d6df30835d711286793d398-6a8f436339bb89f2-01
START RequestId: 9955c947-0e74-48d5-9ed2-2d776eae6076 Version: $LATEST
--
2021/06/28 20:42:35 [collector] Received event: {
"eventType": "INVOKE",
"deadlineMs": 1624912975301,
"requestId": "9955c947-0e74-48d5-9ed2-2d776eae6076",
"invokedFunctionArn": "arn:aws:lambda:eu-west-1:124526594281:function:checkout",
"tracing": {
"type": "X-Amzn-Trace-Id",
"value": "Root=1-60da343b-0d6df30835d711286793d398;Parent=2e1ff77d531e70cc;Sampled=1"
}
}
2021/06/28 20:42:35 [collector] Waiting for event...
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 INFO  ShoppingCartCheckoutRequestHandler:40 - Checkout order with Anti Fraud service https://aiq8loptkl.execute-api.eu-west-1.amazonaws.com/default
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - --> GET https://aiq8loptkl.execute-api.eu-west-1.amazonaws.com/default
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - X-Amzn-Trace-Id: Root=1-60da343b-0d6df30835d711286793d398;Parent=6a8f436339bb89f2;Sampled=1
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - traceparent: 00-60da343b0d6df30835d711286793d398-6a8f436339bb89f2-01
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - b3: 60da343b0d6df30835d711286793d398-6a8f436339bb89f2-1
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - X-B3-TraceId: 60da343b0d6df30835d711286793d398
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - X-B3-SpanId: 6a8f436339bb89f2
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - X-B3-Sampled: 1
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - --> END GET
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - <-- 200 https://aiq8loptkl.execute-api.eu-west-1.amazonaws.com/default (398ms)
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - content-type: application/json
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - content-length: 40
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - date: Mon, 28 Jun 2021 20:42:35 GMT
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - x-amzn-requestid: 6e85b15b-076c-42b4-9f9c-287e88522020
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - x-amz-apigw-id: Bp0ZTFB_joEFteg=
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - x-amzn-trace-id: Root=1-60da343b-0d6df30835d711286793d398
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - x-cache: Miss from cloudfront
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - via: 1.1 9d050fbf11362165fc47c03a14392c36.cloudfront.net (CloudFront)
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - x-amz-cf-pop: LHR61-C2
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - x-amz-cf-id: f7_pQAxyAgodos3QZx9nMtkFmDWoqEWEIiQKX7yapa3pL6WbjPgZQQ==
2021-06-28 20:42:35 9955c947-0e74-48d5-9ed2-2d776eae6076 DEBUG ShoppingCartCheckoutRequestHandler:28 - <-- END HTTP
2021-06-28T20:42:35.726Z	INFO	loggingexporter/logging_exporter.go:42	TracesExporter	{     "#spans": 2 }
2021-06-28T20:42:35.726Z	DEBUG	loggingexporter/logging_exporter.go:48	ResourceSpans #0
Resource labels:
-> cloud.provider: STRING(aws)
-> cloud.region: STRING(eu-west-1)
-> faas.name: STRING(checkout)
-> faas.version: STRING($LATEST)
-> service.name: STRING(checkout)
-> telemetry.sdk.language: STRING(java)
-> telemetry.sdk.name: STRING(opentelemetry)
-> telemetry.sdk.version: STRING(1.2.0)
InstrumentationLibrarySpans #0
InstrumentationLibrary io.opentelemetry.javaagent.okhttp-3.0
Span #0
Trace ID       : 60da343b0d6df30835d711286793d398
Parent ID      : 2b4afb0ca9a1c062
ID             : 6a8f436339bb89f2
Name           : HTTP GET
Kind           : SPAN_KIND_CLIENT
Start time     : 2021-06-28 20:42:35.3052175 +0000 UTC
End time       : 2021-06-28 20:42:35.70803311 +0000 UTC
Status code    : STATUS_CODE_UNSET
Status message :
Attributes:
-> http.method: STRING(GET)
-> http.url: STRING(https://aiq8loptkl.execute-api.eu-west-1.amazonaws.com/default)
-> http.flavor: STRING(1.1)
-> net.transport: STRING(ip_tcp)
-> net.peer.name: STRING(aiq8loptkl.execute-api.eu-west-1.amazonaws.com)
-> http.status_code: INT(200)
InstrumentationLibrarySpans #1
InstrumentationLibrary io.opentelemetry.aws-lambda-1.0
Span #0
Trace ID       : 60da343b0d6df30835d711286793d398
Parent ID      : 619bbd7e17b6d746
ID             : 2b4afb0ca9a1c062
Name           : /
Kind           : SPAN_KIND_SERVER
Start time     : 2021-06-28 20:42:35.304222271 +0000 UTC
End time       : 2021-06-28 20:42:35.708336539 +0000 UTC
Status code    : STATUS_CODE_UNSET
Status message :
Attributes:
-> faas.execution: STRING(9955c947-0e74-48d5-9ed2-2d776eae6076)
-> faas.trigger: STRING(http)
-> http.method: STRING(GET)
-> http.url: STRING(https://himkk66r78.execute-api.eu-west-1.amazonaws.com/)
-> cloud.account.id: STRING(124526594281)
-> http.user_agent: STRING(Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.114 Safari/537.36)
-> faas.id: STRING(arn:aws:lambda:eu-west-1:124526594281:function:checkout)
 
Jun 28, 2021 8:42:35 PM io.opentelemetry.sdk.internal.ThrottlingLogger doLog
WARNING: Failed to export spans. Error message: UNKNOWN: Permanent error: AccessDeniedException:
status code: 403, request id: d897d683-713d-4688-b9b7-8e6c897beb86
END RequestId: 9955c947-0e74-48d5-9ed2-2d776eae6076
REPORT RequestId: 9955c947-0e74-48d5-9ed2-2d776eae6076	Duration: 447.29 ms	Billed Duration: 448 ms	Memory Size: 384 MB	Max Memory Used: 258 MB	XRAY TraceId: 1-60da343b-0d6df30835d711286793d398	SegmentId: 2e1ff77d531e70cc	Sampled: true

Anti Fraud Function

  • Traceparent received from the upstream HTTP request: traceparent: 00-60da343b0d6df30835d711286793d398-6a8f436339bb89f2-01
START RequestId: 1f5046c8-f5fa-4b25-870e-de23ebebf0ad Version: $LATEST
--
2021/06/28 20:42:35 [collector] Received event: {
"eventType": "INVOKE",
"deadlineMs": 1624912975335,
"requestId": "1f5046c8-f5fa-4b25-870e-de23ebebf0ad",
"invokedFunctionArn": "arn:aws:lambda:eu-west-1:124526594281:function:antifraud",
"tracing": {
"type": "X-Amzn-Trace-Id",
"value": "Root=1-60da343b-0d6df30835d711286793d398;Parent=22e4733d3ba5ffa9;Sampled=1"
}
}
2021/06/28 20:42:35 [collector] Waiting for event...
2021-06-28 20:42:35 1f5046c8-f5fa-4b25-870e-de23ebebf0ad INFO  AntiFraudRequestHandler:24 - AntiFraudRequestHandler: header: [Accept-Encoding: gzip,b3: 60da343b0d6df30835d711286793d398-6a8f436339bb89f2-1,CloudFront-Forwarded-Proto: https,CloudFront-Is-Desktop-Viewer: true,CloudFront-Is-Mobile-Viewer: false,CloudFront-Is-SmartTV-Viewer: false,CloudFront-Is-Tablet-Viewer: false,CloudFront-Viewer-Country: IE,Host: aiq8loptkl.execute-api.eu-west-1.amazonaws.com,traceparent: 00-60da343b0d6df30835d711286793d398-6a8f436339bb89f2-01,User-Agent: okhttp/4.9.1,Via: 2.0 9d050fbf11362165fc47c03a14392c36.cloudfront.net (CloudFront),X-Amz-Cf-Id: f7_pQAxyAgodos3QZx9nMtkFmDWoqEWEIiQKX7yapa3pL6WbjPgZQQ==,X-Amzn-Trace-Id: Self=1-60da343b-4c96e41c4a70db9619fe1ed7;Root=1-60da343b-0d6df30835d711286793d398;Parent=6a8f436339bb89f2;Sampled=1,x-b3-sampled: 1,x-b3-spanid: 6a8f436339bb89f2,x-b3-traceid: 60da343b0d6df30835d711286793d398,X-Forwarded-For: 34.244.31.227, 130.176.6.92,X-Forwarded-Port: 443,X-Forwarded-Proto: https]
2021-06-28T20:42:35.667Z	INFO	loggingexporter/logging_exporter.go:42	TracesExporter	{     "#spans": 2 }
2021-06-28T20:42:35.667Z	DEBUG	loggingexporter/logging_exporter.go:48	ResourceSpans #0
Resource labels:
-> cloud.provider: STRING(aws)
-> cloud.region: STRING(eu-west-1)
-> faas.name: STRING(antifraud)
-> faas.version: STRING($LATEST)
-> service.name: STRING(antifraud)
-> telemetry.sdk.language: STRING(java)
-> telemetry.sdk.name: STRING(opentelemetry)
-> telemetry.sdk.version: STRING(1.2.0)
InstrumentationLibrarySpans #0
InstrumentationLibrary io.opentelemetry.javaagent.okhttp-3.0
Span #0
Trace ID       : 60da343b0d6df30835d711286793d398
Parent ID      : 069fafceab189d65
ID             : 753a3d9e7797aa84
Name           : HTTP GET
Kind           : SPAN_KIND_CLIENT
Start time     : 2021-06-28 20:42:35.340118785 +0000 UTC
End time       : 2021-06-28 20:42:35.630402741 +0000 UTC
Status code    : STATUS_CODE_UNSET
Status message :
Attributes:
-> http.url: STRING(https://www.google.com/)
-> http.method: STRING(GET)
-> http.status_code: INT(200)
-> net.transport: STRING(ip_tcp)
-> net.peer.name: STRING(www.google.com)
-> http.flavor: STRING(1.1)
InstrumentationLibrarySpans #1
InstrumentationLibrary io.opentelemetry.aws-lambda-1.0
Span #0
Trace ID       : 60da343b0d6df30835d711286793d398
Parent ID      : 942d7914a950bb5f
ID             : 069fafceab189d65
Name           : /
Kind           : SPAN_KIND_SERVER
Start time     : 2021-06-28 20:42:35.337719257 +0000 UTC
End time       : 2021-06-28 20:42:35.651489482 +0000 UTC
Status code    : STATUS_CODE_UNSET
Status message :
Attributes:
-> http.url: STRING(https://aiq8loptkl.execute-api.eu-west-1.amazonaws.com/)
-> faas.execution: STRING(1f5046c8-f5fa-4b25-870e-de23ebebf0ad)
-> faas.trigger: STRING(http)
-> http.method: STRING(GET)
-> faas.id: STRING(arn:aws:lambda:eu-west-1:124526594281:function:antifraud)
-> cloud.account.id: STRING(124526594281)
-> http.user_agent: STRING(okhttp/4.9.1)
 
Jun 28, 2021 8:42:35 PM io.opentelemetry.sdk.internal.ThrottlingLogger doLog
WARNING: Failed to export spans. Error message: UNKNOWN: Permanent error: AccessDeniedException:
status code: 403, request id: 5abd837d-23be-4192-a0d8-a943742d2d53
END RequestId: 1f5046c8-f5fa-4b25-870e-de23ebebf0ad
REPORT RequestId: 1f5046c8-f5fa-4b25-870e-de23ebebf0ad	Duration: 355.17 ms	Billed Duration: 356 ms	Memory Size: 384 MB	Max Memory Used: 261 MB	XRAY TraceId: 1-60da343b-0d6df30835d711286793d398	SegmentId: 22e4733d3ba5ffa9	Sampled: true

Initialization Phase



2021/06/28 20:42:02 [collector] Launching OpenTelemetry Lambda extension, version:  v0.1.0
--
2021-06-28T20:42:02.622Z	info	service/application.go:277	Starting otelcol...	{     "Version": "v0.1.0",     "NumCPU": 2 }
2021-06-28T20:42:02.623Z	info	service/application.go:185	Setting up own telemetry...
2021-06-28T20:42:02.623Z	info	service/application.go:220	Loading configuration...
2021-06-28T20:42:02.636Z	info	service/application.go:236	Applying configuration...
2021-06-28T20:42:02.637Z	info	builder/exporters_builder.go:274	Exporter was built.	{     "kind": "exporter",     "exporter": "otlp" }
2021-06-28T20:42:02.640Z	info	builder/exporters_builder.go:274	Exporter was built.	{     "kind": "exporter",     "exporter": "awsxray" }
2021-06-28T20:42:02.648Z	info	builder/exporters_builder.go:274	Exporter was built.	{     "kind": "exporter",     "exporter": "logging" }
2021-06-28T20:42:02.648Z	info	builder/pipelines_builder.go:204	Pipeline was built.	{     "pipeline_name": "traces",     "pipeline_datatype": "traces" }
2021-06-28T20:42:02.648Z	info	builder/pipelines_builder.go:204	Pipeline was built.	{     "pipeline_name": "metrics",     "pipeline_datatype": "metrics" }
2021-06-28T20:42:02.648Z	info	builder/receivers_builder.go:230	Receiver was built.	{     "kind": "receiver",     "name": "otlp",     "datatype": "traces" }
2021-06-28T20:42:02.648Z	info	builder/receivers_builder.go:230	Receiver was built.	{     "kind": "receiver",     "name": "otlp",     "datatype": "metrics" }
2021-06-28T20:42:02.648Z	info	service/service.go:155	Starting extensions...
2021-06-28T20:42:02.648Z	info	service/service.go:200	Starting exporters...
2021-06-28T20:42:02.648Z	info	builder/exporters_builder.go:92	Exporter is starting...	{     "kind": "exporter",     "name": "otlp" }
2021-06-28T20:42:02.648Z	info	builder/exporters_builder.go:97	Exporter started.	{     "kind": "exporter",     "name": "otlp" }
2021-06-28T20:42:02.648Z	info	builder/exporters_builder.go:92	Exporter is starting...	{     "kind": "exporter",     "name": "awsxray" }
2021-06-28T20:42:02.648Z	info	builder/exporters_builder.go:97	Exporter started.	{     "kind": "exporter",     "name": "awsxray" }
2021-06-28T20:42:02.648Z	info	builder/exporters_builder.go:92	Exporter is starting...	{     "kind": "exporter",     "name": "logging" }
2021-06-28T20:42:02.648Z	info	builder/exporters_builder.go:97	Exporter started.	{     "kind": "exporter",     "name": "logging" }
2021-06-28T20:42:02.648Z	info	service/service.go:205	Starting processors...
2021-06-28T20:42:02.648Z	info	builder/pipelines_builder.go:51	Pipeline is starting...	{     "pipeline_name": "traces",     "pipeline_datatype": "traces" }
2021-06-28T20:42:02.648Z	info	builder/pipelines_builder.go:62	Pipeline is started.	{     "pipeline_name": "traces",     "pipeline_datatype": "traces" }
2021-06-28T20:42:02.649Z	info	builder/pipelines_builder.go:51	Pipeline is starting...	{     "pipeline_name": "metrics",     "pipeline_datatype": "metrics" }
2021-06-28T20:42:02.649Z	info	builder/pipelines_builder.go:62	Pipeline is started.	{     "pipeline_name": "metrics",     "pipeline_datatype": "metrics" }
2021-06-28T20:42:02.649Z	info	service/service.go:210	Starting receivers...
2021-06-28T20:42:02.649Z	info	builder/receivers_builder.go:70	Receiver is starting...	{     "kind": "receiver",     "name": "otlp" }
2021-06-28T20:42:02.649Z	info	otlpreceiver/otlp.go:83	Starting GRPC server on endpoint 0.0.0.0:4317	{     "kind": "receiver",     "name": "otlp" }
2021-06-28T20:42:02.649Z	info	otlpreceiver/otlp.go:145	Setting up a second GRPC listener on legacy endpoint 0.0.0.0:55680	{     "kind": "receiver",     "name": "otlp" }
2021-06-28T20:42:02.649Z	info	otlpreceiver/otlp.go:83	Starting GRPC server on endpoint 0.0.0.0:55680	{     "kind": "receiver",     "name": "otlp" }
2021-06-28T20:42:02.649Z	info	builder/receivers_builder.go:75	Receiver started.	{     "kind": "receiver",     "name": "otlp" }
2021-06-28T20:42:02.649Z	info	service/application.go:197	Everything is ready. Begin running and processing data.
2021/06/28 20:42:02 Registered extension ID: "35f2f84d-ac61-43f3-86a1-0943dbdb8e99"
2021/06/28 20:42:02 [collector] Register response: {
"functionName": "antifraud",
"functionVersion": "$LATEST",
"handler": "com.myecommerce.lambda.antifraud.AntiFraudRequestHandler::handleRequest"
}
2021/06/28 20:42:02 [collector] Waiting for event...
START RequestId: d2f41524-7d49-4568-9fec-d5ea50f82a64 Version: $LATEST
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.
EXTENSION	Name: collector	State: Ready	Events: [INVOKE,SHUTDOWN]
2021/06/28 20:42:07 [collector] Received event: {
"eventType": "INVOKE",
"deadlineMs": 1624912947487,
"requestId": "d2f41524-7d49-4568-9fec-d5ea50f82a64",
"invokedFunctionArn": "arn:aws:lambda:eu-west-1:124526594281:function:antifraud",
"tracing": {
"type": "X-Amzn-Trace-Id",
"value": "Root=1-60da3410-30af136854c54e2537ec5b6e;Parent=6bb77897296f2707;Sampled=1"
}
}
2021/06/28 20:42:07 [collector] Waiting for event...

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions