lumigo-io / lumigo-node

Lumigo's Node.js Distributed Tracing and Performance Agent
https://lumigo.io
Apache License 2.0
76 stars 12 forks source link

fix: remove lumigo from stack when error is raised from a promise after the lambdas execution finished #506

Closed eyalgolan closed 2 months ago

eyalgolan commented 3 months ago

Description: if an unhandled promise exception is raised after a lambda's execution was finished, then the logic in removeLumigoFromStacktrace didn't run on that exception's stacktrace. Therefore the tracer's lines were part of the stacktrace presented.

Jira ticket: see here.

eyalgolan commented 3 months ago

Also created a layer and add to a lambda running mjs, and it works properly. There is no need to duplicate the added code to the auto-handler as the issue doesn't occur there:

Test Event Name
(unsaved) test event

Response
{
  "errorType": "Runtime.UnhandledPromiseRejection",
  "errorMessage": "Error: I am an error",
  "trace": [
    "Runtime.UnhandledPromiseRejection: Error: I am an error",
    "    at file:///var/runtime/index.mjs:1276:17",
    "    at /opt/nodejs/node_modules/@lumigo/tracer/dist/tracer/tracer.js:274:37",
    "    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)"
  ]
}

Function Logs
wBaH2qmMqsxm1Eb1Qe3A6xi8UDmEjEefjUy6DzjNCov57tYsdte3QoRRxSiYow7pgQlBLyepUUBbHnR6Nqqk6ckwJJ6QiYzYAcRixwKR/BxlKXfHCBViEYJegoVlK5c29wHUJFuSZdZXx/JQHOqGLKrP2IpGsQcyNb/cQie9B6JGH0sCWu8aBfST6IiDcUiwbnbH1opSWaXMb9aTlVLqzhAkEuITwUVVWcvdIoC+QP+3iEH9PU0HWgsEz/rhPFd9BBwv+iXd5lLvN8upZbNynce0kUipgg3Vavw1/r2t0RJE0mI0yRj9QiV0Pmow2quHtgY6nQEphsbLUvaLkWjMi6Pm9t8ZtAzLcG9mGwp419jJG/DEiJuLrL0PYx9QZqS+xaTbd1fkN7+Pa1agfxkB/ti7sZum6/lP5aWwW5Jgl1FNGFdRJgX0ExtS6/X/hClJG1wJ8B4h/6GitK+10XiZKtHOyZrDwqPm3X/1sDNt1bG149dw6BqRwfYdjxmo+zUS6UlVtfO3UQFtA23pErgg31nA\",\"LUMIGO_DEBUG\":\"true\",\"AWS_XRAY_CONTEXT_MISSING\":\"LOG_ERROR\",\"_AWS_XRAY_DAEMON_PORT\":\"2000\",\"LUMIGO_IS_WRAPPED\":\"TRUE\",\"_X_AMZN_TRACE_ID\":\"Root=1-66c1d5e6-29b6fc2f1abe98721ed0e385;Parent=4748b3903a26cd38;Sampled=0;Lineage=d229f2a2:0\",\"LUMIGO_IS_WARM\":\"TRUE\"}","name":"nodetest","type":"function","ended":1723979239276,"event":"{}","started":1723979231677,"maxFinishTime":1723979234676,"error":{"type":"Runtime.UnhandledPromiseRejection","message":"Error: I am an error","stacktrace":"Runtime.UnhandledPromiseRejection: Error: I am an error\n    at new Promise (<anonymous>)\n    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)"},"return_value":"null","lumigo_execution_tags_no_scrub":[]}
2024-08-18T11:07:19.277Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Span created" {"type":"enrichment","id":"e1419a1d-0558-c1a9-ca4f-c94012d790b1","droppedSpansReasons":{},"totalSpans":1,"token":"t_261abf28c3d84d5ab8aa4","transaction_id":"29b6fc2f1abe98721ed0e385","lumigo_execution_tags_no_scrub":[],"sending_time":1723979239277}
2024-08-18T11:07:19.277Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Enrichment span created" {"type":"enrichment","id":"e1419a1d-0558-c1a9-ca4f-c94012d790b1","droppedSpansReasons":{},"totalSpans":2,"token":"t_261abf28c3d84d5ab8aa4","transaction_id":"29b6fc2f1abe98721ed0e385","lumigo_execution_tags_no_scrub":[],"sending_time":1723979239277}
2024-08-18T11:07:19.277Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Filtered [0] spans out"
2024-08-18T11:07:19.277Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Filtering and scrubbing, Took: [0ms]"
2024-08-18T11:07:19.277Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Starting request to edge" {"url":"https://eyalgolan-edge-app-us-west-2.eyalgolan.golumigo.com/api/spans","headers":{"Authorization":"t_261abf28c3d84d5ab8aa4","User-Agent":"@lumigo/tracer$1.99.2","Content-Type":"application/json"},"bodySize":5922}
2024-08-18T11:07:19.336Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Edge request completed" {"statusText":"OK","status":200,"data":"ok\n"}
2024-08-18T11:07:19.337Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Edge request completed" {"statusText":"OK","status":200,"data":"ok\n"}
2024-08-18T11:07:19.337Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Spans sent [223ms, 2 spans]" ["cafacb61-2726-4ee9-b6a3-1c25eeb2f79a","08c965b7-d71d-ad04-9c94-ce6923907bac"]
2024-08-18T11:07:19.337Z    796e5817-e110-4920-a665-6f21afe830a3    INFO    #LUMIGO# - DEBUG - "Tracer ended" {"transactionId":"3e282acf3cf1382711f3c60b","totalSpans":2}
2024-08-18T11:07:19.337Z    796e5817-e110-4920-a665-6f21afe830a3    ERROR   Unhandled Promise Rejection     {"errorType":"Runtime.UnhandledPromiseRejection","errorMessage":"Error: I am an error","reason":{"errorType":"Error","errorMessage":"I am an error","stack":["Error: I am an error","    at file:///var/task/index.mjs:10:15"]},"promise":{},"stack":["Runtime.UnhandledPromiseRejection: Error: I am an error","    at file:///var/runtime/index.mjs:1276:17","    at /opt/nodejs/node_modules/@lumigo/tracer/dist/tracer/tracer.js:274:37","    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)"]}
END RequestId: 796e5817-e110-4920-a665-6f21afe830a3
REPORT RequestId: 796e5817-e110-4920-a665-6f21afe830a3  Duration: 956.04 ms Billed Duration: 957 ms Memory Size: 128 MB Max Memory Used: 85 MB  Status: error   Error Type: Runtime.ExitError

Request ID
796e5817-e110-4920-a665-6f21afe830a3

The one tracer line that is visible there - also happens for the fix added for some reason, even though the regex is catching this.

codecov[bot] commented 3 months ago

Codecov Report

Attention: Patch coverage is 87.50000% with 1 line in your changes missing coverage. Please review.

Project coverage is 99.33%. Comparing base (4e438b5) to head (645432f). Report is 554 commits behind head on master.

Files Patch % Lines
src/tracer/tracer.ts 66.66% 1 Missing :warning:
Additional details and impacted files ```diff @@ Coverage Diff @@ ## master #506 +/- ## =========================================== - Coverage 100.00% 99.33% -0.67% =========================================== Files 19 42 +23 Lines 1165 2721 +1556 Branches 246 758 +512 =========================================== + Hits 1165 2703 +1538 - Misses 0 17 +17 - Partials 0 1 +1 ```

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

doriaviram commented 2 months ago

:tada: This PR is included in version 1.99.3 :tada:

The release is available on:

Your semantic-release bot :package::rocket: