opentelemetry-lambda
opentelemetry-lambda copied to clipboard
Published
20 hours ago •
open-telemetry
open-telemetry
Change to collector causing issues with nodejs
I did some digging to figure out what exactly was causing the issue I was seeing and it appears to be related to PR #194.
I am pretty new to go so I really don't know why this causes an issue 😅 Also I only tested this with nodejs but it is possible it is causing trouble in other environment I just haven't tested those 🤷♂️
Here are the steps I took to build everything and a sample of the Cloudwatch logs I am seeing
- run
make publish-layerin thecollectorfolder to have a local build of the collector - run
npm iin thenodejsfolder - Run
terraform initin thenodejs/integration-tests/aws-sdk/wrapper - Run
terraform applyto deploy - Run a GET request on the endpoint that was exposed on API gateway.
Then in CloudWatch I am just seeing the following followed by a timeout from lambda and API gateway
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| timestamp | message |
|---------------|-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| 1640891812819 | 2021/12/30 19:16:52 [collector] Launching OpenTelemetry Lambda extension, version: v0.1.0 |
| 1640891812834 | 2021-12-30T19:16:52.834Z info service/collector.go:186 Applying configuration... |
| 1640891812835 | 2021-12-30T19:16:52.834Z info builder/exporters_builder.go:254 Exporter was built. {"kind": "exporter", "name": "logging"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/pipelines_builder.go:222 Pipeline was built. {"name": "pipeline", "name": "metrics"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/pipelines_builder.go:222 Pipeline was built. {"name": "pipeline", "name": "traces"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/receivers_builder.go:224 Receiver was built. {"kind": "receiver", "name": "otlp", "datatype": "metrics"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/receivers_builder.go:224 Receiver was built. {"kind": "receiver", "name": "otlp", "datatype": "traces"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info service/service.go:86 Starting extensions... |
| 1640891812835 | 2021-12-30T19:16:52.835Z info service/service.go:91 Starting exporters... |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/exporters_builder.go:40 Exporter is starting... {"kind": "exporter", "name": "logging"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/exporters_builder.go:48 Exporter started. {"kind": "exporter", "name": "logging"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info service/service.go:96 Starting processors... |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/pipelines_builder.go:54 Pipeline is starting... {"name": "pipeline", "name": "metrics"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/pipelines_builder.go:65 Pipeline is started. {"name": "pipeline", "name": "metrics"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/pipelines_builder.go:54 Pipeline is starting... {"name": "pipeline", "name": "traces"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/pipelines_builder.go:65 Pipeline is started. {"name": "pipeline", "name": "traces"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info service/service.go:101 Starting receivers... |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/receivers_builder.go:68 Receiver is starting... {"kind": "receiver", "name": "otlp"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info otlpreceiver/otlp.go:68 Starting GRPC server on endpoint 0.0.0.0:4317 {"kind": "receiver", "name": "otlp"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info otlpreceiver/otlp.go:86 Starting HTTP server on endpoint 0.0.0.0:4318 {"kind": "receiver", "name": "otlp"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info otlpreceiver/otlp.go:141 Setting up a second HTTP listener on legacy endpoint 0.0.0.0:55681 {"kind": "receiver", "name": "otlp"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info otlpreceiver/otlp.go:86 Starting HTTP server on endpoint 0.0.0.0:55681 {"kind": "receiver", "name": "otlp"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info builder/receivers_builder.go:73 Receiver started. {"kind": "receiver", "name": "otlp"} |
| 1640891812835 | 2021-12-30T19:16:52.835Z info service/telemetry.go:92 Setting up own telemetry... |
| 1640891812836 | 2021-12-30T19:16:52.836Z info service/telemetry.go:116 Serving Prometheus metrics {"address": ":8888", "level": "basic", "service.instance.id": "27f930a5-d42a-4826-af98-8b11dc15fec2", "service.version": "latest"} |
| 1640891812836 | 2021-12-30T19:16:52.836Z info service/collector.go:235 Starting otelcol... {"Version": "v0.1.0", "NumCPU": 2} |
| 1640891812836 | 2021-12-30T19:16:52.836Z info service/collector.go:131 Everything is ready. Begin running and processing data. |
| 1640891822826 | START RequestId: 80ac2185-73a7-4743-8b6d-5b4edb2d1ee4 Version: $LATEST |
| 1640891823432 | 2021/12/30 19:17:03 [collector] Launching OpenTelemetry Lambda extension, version: v0.1.0 |
| 1640891823469 | 2021-12-30T19:17:03.469Z info service/collector.go:186 Applying configuration... |
| 1640891823469 | 2021-12-30T19:17:03.469Z info builder/exporters_builder.go:254 Exporter was built. {"kind": "exporter", "name": "logging"} |
| 1640891823469 | 2021-12-30T19:17:03.469Z info builder/pipelines_builder.go:222 Pipeline was built. {"name": "pipeline", "name": "traces"} |
| 1640891823469 | 2021-12-30T19:17:03.469Z info builder/pipelines_builder.go:222 Pipeline was built. {"name": "pipeline", "name": "metrics"} |
| 1640891823469 | 2021-12-30T19:17:03.469Z info builder/receivers_builder.go:224 Receiver was built. {"kind": "receiver", "name": "otlp", "datatype": "traces"} |
| 1640891823470 | 2021-12-30T19:17:03.469Z info builder/receivers_builder.go:224 Receiver was built. {"kind": "receiver", "name": "otlp", "datatype": "metrics"} |
| 1640891823470 | 2021-12-30T19:17:03.469Z info service/service.go:86 Starting extensions... |
| 1640891823470 | 2021-12-30T19:17:03.469Z info service/service.go:91 Starting exporters... |
| 1640891823470 | 2021-12-30T19:17:03.469Z info builder/exporters_builder.go:40 Exporter is starting... {"kind": "exporter", "name": "logging"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info builder/exporters_builder.go:48 Exporter started. {"kind": "exporter", "name": "logging"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info service/service.go:96 Starting processors... |
| 1640891823470 | 2021-12-30T19:17:03.470Z info builder/pipelines_builder.go:54 Pipeline is starting... {"name": "pipeline", "name": "traces"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info builder/pipelines_builder.go:65 Pipeline is started. {"name": "pipeline", "name": "traces"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info builder/pipelines_builder.go:54 Pipeline is starting... {"name": "pipeline", "name": "metrics"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info builder/pipelines_builder.go:65 Pipeline is started. {"name": "pipeline", "name": "metrics"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info service/service.go:101 Starting receivers... |
| 1640891823470 | 2021-12-30T19:17:03.470Z info builder/receivers_builder.go:68 Receiver is starting... {"kind": "receiver", "name": "otlp"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info otlpreceiver/otlp.go:68 Starting GRPC server on endpoint 0.0.0.0:4317 {"kind": "receiver", "name": "otlp"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info otlpreceiver/otlp.go:86 Starting HTTP server on endpoint 0.0.0.0:4318 {"kind": "receiver", "name": "otlp"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info otlpreceiver/otlp.go:141 Setting up a second HTTP listener on legacy endpoint 0.0.0.0:55681 {"kind": "receiver", "name": "otlp"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info otlpreceiver/otlp.go:86 Starting HTTP server on endpoint 0.0.0.0:55681 {"kind": "receiver", "name": "otlp"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info builder/receivers_builder.go:73 Receiver started. {"kind": "receiver", "name": "otlp"} |
| 1640891823470 | 2021-12-30T19:17:03.470Z info service/telemetry.go:92 Setting up own telemetry... |
| 1640891823471 | 2021-12-30T19:17:03.471Z info service/telemetry.go:116 Serving Prometheus metrics {"address": ":8888", "level": "basic", "service.instance.id": "0c59d806-ac4d-4b29-88e7-55cfea4607df", "service.version": "latest"} |
| 1640891823471 | 2021-12-30T19:17:03.471Z info service/collector.go:235 Starting otelcol... {"Version": "v0.1.0", "NumCPU": 2} |
| 1640891823471 | 2021-12-30T19:17:03.471Z info service/collector.go:131 Everything is ready. Begin running and processing data. |
| 1640891842847 | EXTENSION Name: collector State: Started Events: [] |
| 1640891842847 | END RequestId: 80ac2185-73a7-4743-8b6d-5b4edb2d1ee4 |
| 1640891842847 | REPORT RequestId: 80ac2185-73a7-4743-8b6d-5b4edb2d1ee4 Duration: 20020.53 ms Billed Duration: 20000 ms Memory Size: 384 MB Max Memory Used: 31 MB |
| 1640891842847 | 2021-12-30T19:17:22.847Z 80ac2185-73a7-4743-8b6d-5b4edb2d1ee4 Task timed out after 20.02 seconds |
| 1640891843166 | 2021/12/30 19:17:23 [collector] Launching OpenTelemetry Lambda extension, version: v0.1.0 |
| 1640891843196 | 2021-12-30T19:17:23.196Z info service/collector.go:186 Applying configuration... |
| 1640891843196 | 2021-12-30T19:17:23.196Z info builder/exporters_builder.go:254 Exporter was built. {"kind": "exporter", "name": "logging"} |
| 1640891843196 | 2021-12-30T19:17:23.196Z info builder/pipelines_builder.go:222 Pipeline was built. {"name": "pipeline", "name": "traces"} |
| 1640891843196 | 2021-12-30T19:17:23.196Z info builder/pipelines_builder.go:222 Pipeline was built. {"name": "pipeline", "name": "metrics"} |
| 1640891843196 | 2021-12-30T19:17:23.196Z info builder/receivers_builder.go:224 Receiver was built. {"kind": "receiver", "name": "otlp", "datatype": "traces"} |
| 1640891843197 | 2021-12-30T19:17:23.196Z info builder/receivers_builder.go:224 Receiver was built. {"kind": "receiver", "name": "otlp", "datatype": "metrics"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info service/service.go:86 Starting extensions... |
| 1640891843197 | 2021-12-30T19:17:23.197Z info service/service.go:91 Starting exporters... |
| 1640891843197 | 2021-12-30T19:17:23.197Z info builder/exporters_builder.go:40 Exporter is starting... {"kind": "exporter", "name": "logging"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info builder/exporters_builder.go:48 Exporter started. {"kind": "exporter", "name": "logging"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info service/service.go:96 Starting processors... |
| 1640891843197 | 2021-12-30T19:17:23.197Z info builder/pipelines_builder.go:54 Pipeline is starting... {"name": "pipeline", "name": "traces"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info builder/pipelines_builder.go:65 Pipeline is started. {"name": "pipeline", "name": "traces"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info builder/pipelines_builder.go:54 Pipeline is starting... {"name": "pipeline", "name": "metrics"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info builder/pipelines_builder.go:65 Pipeline is started. {"name": "pipeline", "name": "metrics"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info service/service.go:101 Starting receivers... |
| 1640891843197 | 2021-12-30T19:17:23.197Z info builder/receivers_builder.go:68 Receiver is starting... {"kind": "receiver", "name": "otlp"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info otlpreceiver/otlp.go:68 Starting GRPC server on endpoint 0.0.0.0:4317 {"kind": "receiver", "name": "otlp"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info otlpreceiver/otlp.go:86 Starting HTTP server on endpoint 0.0.0.0:4318 {"kind": "receiver", "name": "otlp"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info otlpreceiver/otlp.go:141 Setting up a second HTTP listener on legacy endpoint 0.0.0.0:55681 {"kind": "receiver", "name": "otlp"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info otlpreceiver/otlp.go:86 Starting HTTP server on endpoint 0.0.0.0:55681 {"kind": "receiver", "name": "otlp"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info builder/receivers_builder.go:73 Receiver started. {"kind": "receiver", "name": "otlp"} |
| 1640891843197 | 2021-12-30T19:17:23.197Z info service/telemetry.go:92 Setting up own telemetry... |
| 1640891843198 | 2021-12-30T19:17:23.198Z info service/telemetry.go:116 Serving Prometheus metrics {"address": ":8888", "level": "basic", "service.instance.id": "8dbe0f4d-2c62-406f-b5ad-cf9178feebe3", "service.version": "latest"} |
| 1640891843198 | 2021-12-30T19:17:23.198Z info service/collector.go:235 Starting otelcol... {"Version": "v0.1.0", "NumCPU": 2} |
| 1640891843198 | 2021-12-30T19:17:23.198Z info service/collector.go:131 Everything is ready. Begin running and processing data. |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Originally posted by @Danwakeem in https://github.com/open-telemetry/opentelemetry-lambda/discussions/199
Yeah I'm experiencing this issue as well.
It looks like my handler isn't called - all my handler currently does is log the event payload out.
Remove the layer - everything works fine and the event is logged. Add it back - lambda times out with no output produced.
It does this with both the nodejs layer and "arn:aws:lambda:ap-southeast-2:901920570463:layer:aws-otel-collector-ver-0-39-0:1"
Hey thanks for posting this issue! I wished I had seen this before trying to debug our issue this weekend 🥲
I should have a a fix for this in https://github.com/open-telemetry/opentelemetry-lambda/pull/207, please let me know if you think there is still an issue! 😄
