Bug: [Tracer] instrumentFetch breaks when using proxy

[tenjaa]

Expected Behavior

Do not throw an error.

Current Behavior

Throws an error.

Code snippet

import {RetryAgent, ProxyAgent} from 'undici';

const agent = new RetryAgent(
  new ProxyAgent({
    token: `Basic <SOME SECRET PASSWORD>`,
    uri: `http://our-proxy-url:8080`,
  }),
);

agent.request(<call to the API>);

Steps to Reproduce

1. Have an environment where you can only access the internet through a proxy
2. Instantiate tracer with "captureHTTPsRequests: false,"
3. Instantiate agent (see code snippet)
4. Call tracer.provider.instrumentFetch() <= just to narrow down, that it is this path we are going instead of captureHTTPsGlobal()
5. Call some api with the proxy agent

Possible Solution

Looking at

powertools-lambda-typescript/packages/tracer/src/provider/utilities.ts

Line 60 in 263db2d

const getRequestURL = (

it seems that the diagnostics channel returns the proxy url as origin and the url we try to call as path which seems to be wrong.
And this can obviously not be parsed as url and an error gets thrown.

When using getRequestUrl in

powertools-lambda-typescript/packages/tracer/src/provider/ProviderService.ts

Line 122 in 263db2d

const requestURL = getRequestURL(request);

it gets converted back into a string anyway.

So a possible solution I could imagine would be to not parse the URL but to just return a string or an object based on the diagnostics channel data.

Powertools for AWS Lambda (TypeScript) version

2.22.0

AWS Lambda function runtime

22.x

Packaging format used

npm

Execution logs

{
  "errorType": "TypeError",
  "errorMessage": "Invalid URL",
  "code": "ERR_INVALID_URL",
  "input": "http://<PROXY_URL>:8080api.github.com:443",
  "stack": [
    "TypeError: Invalid URL",
    "    at new URL (node:internal/url:818:25)",
    "    at getRequestURL (/node_modules/@aws-lambda-powertools/tracer/lib/esm/provider/utilities.js:46:16)",
    "    at onRequestStart (/node_modules/@aws-lambda-powertools/tracer/lib/esm/provider/ProviderService.js:77:32)",
    "    at Channel.publish (node:diagnostics_channel:150:9)",
    "    at new Request (/node_modules/undici/lib/core/request.js:192:23)",
    "    at Client.[dispatch] (/node_modules/undici/lib/dispatcher/client.js:300:21)",
    "    at Client.dispatch (/node_modules/undici/lib/dispatcher/dispatcher-base.js:148:28)",
    "    at Pool.[dispatch] (/node_modules/undici/lib/dispatcher/pool-base.js:140:28)",
    "    at Pool.dispatch (/node_modules/undici/lib/dispatcher/dispatcher-base.js:148:28)",
    "    at Pool.connect (/node_modules/undici/lib/api/api-connect.js:100:10)"
  ]
}

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #typescript channel on our Powertools for AWS Lambda Discord: Invite link

[dreamorosi]

Hi @tenjaa, thank you for the detailed bug report.

I'll finish working on another pull request and start troubleshooting this right away - I'll share more info once I have more details.

[daschaa]

@dreamorosi we are aware that this might be an issue from the node DiagnosticChannel class, but we thought maybe you have a workaround/solution for us 😇

[tenjaa]

I took the opportunity to look a bit deeper into undici and might have found something. But maybe I didn't because I have never worked on undici and this is just from going through that code.
There are a few steps missing but maybe it helps to get started.

My goal was to find out how the diagnostics channel is written.
I started in https://github.com/nodejs/undici/blob/a93a8602992487d7a1c3aba9c40c571e308a7110/lib/core/diagnostics.js#L17 which gets referenced in several places.

The relevant reference is probably https://github.com/nodejs/undici/blob/a93a8602992487d7a1c3aba9c40c571e308a7110/lib/core/request.js#L192. This is how a request is created and the only time channels.create.publish (the channel the powertools tracer subscribed to) is mentioned.
In there we also see, that it just passes the request object and that gets populated based on how it is called.

As we are using the proxy agent, I took a closer look there: https://github.com/nodejs/undici/blame/a93a8602992487d7a1c3aba9c40c571e308a7110/lib/dispatcher/proxy-agent.js#L189
They are rewriting the path as origin + path which kinda maps to the error log we got as there is an additional origin in there.

And in https://github.com/nodejs/undici/blame/a93a8602992487d7a1c3aba9c40c571e308a7110/lib/dispatcher/proxy-agent.js#L137 the path gets replaced by :${defaultProtocolPort(opts.protocol)} which would explain why in our error message there is no path but just a port.

Looking at the linked commit, this was apparently done, to mimic curls behavior. Maybe that is required and not an error? I don't know.

This would probably explain why there is such a weird origin / path in the diagnostics channel as they are just forwarding what is used to make the connection.

[dreamorosi]

Hi @tenjaa, thanks for the additional info.

First off, I want to confirm the bug report - I am able to consistently reproduce the issue. I have been working on this for a few hours and since we have a release going out today we were trying to find a fix to potentially include it, but while we have made some progress we don't feel confident releasing our current fix/workaround.

As you pointed out, the error is being thrown here. This is called when a new subsegment for a fetch request is being opened (here). Specifically, this is the point where we inspect the request sent in the diagnostics channel and try to get the full url so that we can include it in the subsegment metadata.

When using a proxy there are two requests being done in this order:

• first request to final host (i.e. GET https://foo.com)
• second request to connect to the proxy (i.e. CONNECT http://proxy:8000)

The second one, which is done to open the tunnel with the proxy includes a non-standard origin + path combination (i.e. proxy:8000 + foo.com) that once concatenated and ran through the new URL() results in an invalid URL which in turns throws an error.

My first idea was to change the logic that obtains the origin to something like the one below to essentially exclude the original url and keep only the proxy address as origin:

const getRequestURL = (request) => {
  if (typeof request.origin === 'string') {
      let path = request.path ? request.path : '';
      try {
          new URL(path);
          return request.origin;
      } catch {}

      return new URL(`${request.origin}${path}`);
  }
  if (request.origin instanceof URL) {
      request.origin.pathname = request.path || '';
      return request.origin;
  }
  return undefined;
};

This would have been fine because the CONNECT request would have been a subsegment of the first one generating a segment hierarchy like this:

• ### index.handler
  • remote GET foo.com
    • remote CONNECT proxy:8000

This would bypass the error, however I am observing that the the CONNECT request never triggers the onClose lifecycle as it's implemented today, resulting in a dangling subsegment and essentially trace data loss.

I was able to do a hacky patch to manually close the segment and get to what I think (at this stage at least) is the correct segment hierarchy, but I am not confident with the implementation to roll it out:

For the sake of testing, I also tried reproducing the issue with the aws-sdk-node-fetch module, which is a community-contributed package part of the AWS X-Ray SDK for Node.js and that uses a different implementation based on monkey-patching as opposed to diagnostics channel.

The code would look something like this, and it's compatible with Powertools for AWS Tracer:

import { Tracer } from "@aws-lambda-powertools/tracer";
import { captureLambdaHandler } from "@aws-lambda-powertools/tracer/middleware";
import middy from "@middy/core";
import { ProxyAgent } from "undici";
import { captureFetchGlobal } from "aws-xray-sdk-fetch"; // import alternative module

const tracer = new Tracer({
  serviceName: "tracerproxy",
  captureHTTPsRequests: false, // disable Powertools tracing (note that it also disables http/https patching)
});
captureFetchGlobal(); // use alternative patching
const client = new ProxyAgent({
  uri: "http://proxy:8080",
  token: "foo",
});

class HttpError extends Error {
  public code?: number;
  constructor(message: string, code?: number) {
    super(message);
    this.name = "HttpError";
    this.code = code;
  }
}

export const handler = middy()
  .use(captureLambdaHandler(tracer))
  .handler(async () => {
    try {
      const res = await fetch("https://www.uol.com.br", {
        dispatcher: client,
        signal: AbortSignal.timeout(2000),
      });
      console.debug("Response status:", res.status);
      if (!res.ok) {
        throw new HttpError(`HTTP error! status: ${res.status}`, res.status);
      }
    } catch (error) {
      console.error("Error fetching URL:", error);
      if (error instanceof HttpError) {
        return {
          statusCode: error.code,
        };
      }
      return {
        statusCode: 500,
      };
    }

    return {
      statusCode: 200,
    };
});

This implementation doesn't throw an error, but completely ignores the second CONNECT request to the proxy, which is not represented in the visualization nor the trace data.

Details

{
    "Id": "1-6865533b-17e945e63c745c1d22765bb8",
    "Duration": 1.512,
    "LimitExceeded": false,
    "Segments": [
        {
            "Id": "ecb0c68ce44733eb",
            "Document": {
                "id": "ecb0c68ce44733eb",
                "name": "TracerproxyFn",
                "start_time": 1751470907.591522,
                "trace_id": "1-6865533b-17e945e63c745c1d22765bb8",
                "end_time": 1751470908.603158,
                "parent_id": "6499d8bd45b606d3",
                "aws": {
                    "account_id": "123456789012",
                    "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:TracerproxyFn",
                    "cloudwatch_logs": [
                        {
                            "log_group": "/aws/lambda/TracerproxyFn"
                        }
                    ],
                    "resource_names": [
                        "TracerproxyFn"
                    ]
                },
                "annotations": {
                    "aws:responseLatency": 891.183,
                    "aws:runtimeOverhead": 119.713,
                    "aws:responseDuration": 0.121
                },
                "origin": "AWS::Lambda::Function",
                "subsegments": [
                    {
                        "id": "54344046cfe35635",
                        "name": "Init",
                        "start_time": 1751470907.240557,
                        "end_time": 1751470907.586379
                    },
                    {
                        "id": "36cc6926eb4f1ed6",
                        "name": "Overhead",
                        "start_time": 1751470908.481,
                        "end_time": 1751470908.600713
                    },
                    {
                        "id": "51cc209c3af32e03",
                        "name": "## index.handler",
                        "start_time": 1751470907.592,
                        "end_time": 1751470908.461,
                        "annotations": {
                            "ColdStart": true,
                            "Service": "tracerproxy"
                        },
                        "subsegments": [
                            {
                                "id": "91858bf7118a7a63",
                                "name": "www.uol.com.br",
                                "start_time": 1751470907.623,
                                "end_time": 1751470908.363,
                                "http": {
                                    "request": {
                                        "url": "https://www.uol.com.br/",
                                        "method": "GET"
                                    },
                                    "response": {
                                        "status": 200,
                                        "content_length": 133975
                                    }
                                },
                                "namespace": "remote"
                            }
                        ]
                    }
                ]
            }
        },
        {
            "Id": "6499d8bd45b606d3",
            "Document": {
                "id": "6499d8bd45b606d3",
                "name": "TracerproxyFn",
                "start_time": 1751470907.093,
                "trace_id": "1-6865533b-17e945e63c745c1d22765bb8",
                "end_time": 1751470908.605,
                "http": {
                    "response": {
                        "status": 200
                    }
                },
                "aws": {
                    "request_id": "0d07cef0-2700-462a-9dd6-31a16fc7e6d9"
                },
                "origin": "AWS::Lambda",
                "resource_arn": "arn:aws:lambda:eu-west-1:123456789012:function:TracerproxyFn"
            }
        },
        {
            "Id": "25c85f370e087ba4",
            "Document": {
                "id": "25c85f370e087ba4",
                "name": "www.uol.com.br",
                "start_time": 1751470907.623,
                "trace_id": "1-6865533b-17e945e63c745c1d22765bb8",
                "end_time": 1751470908.363,
                "parent_id": "91858bf7118a7a63",
                "inferred": true,
                "http": {
                    "request": {
                        "url": "https://www.uol.com.br/",
                        "method": "GET"
                    },
                    "response": {
                        "status": 200,
                        "content_length": 133975
                    }
                }
            }
        }
    ]
}

At this stage I am unsure whether this is the correct or desired behavior, and as I mentioned I am unsure about my workaround, so I decided to move forward with the release. This will allow us to spend more time over the next days to continue troubleshooting and investigating solutions.

Our next steps for now will roughly be the following:

• understand how other Powertools for AWS implementations as well as other APM solutions (i.e. DataDog SDK) handle this case
• understand whether the CONNECT request is supposed to trigger an onClose event
• potentially propose a fix based on the findings from the points above

Given the above, if you want to have some level of tracing, you could consider using the aws-xray-sdk-fetch in conjunction with Powertools for AWS. Admittedly our support for that module is best effort and we have very limited testing besides some manual test for this analysis - if you decide to go this route I'd encourage you to test the module thoroughly, especially around its interaction with the Tracer.

Finally, assuming we find a way to trace it, how would you expect the trace data for this proxy request to be represented (if at all)?

[tenjaa]

Thanks for the quick and thorough response!

Finally, assuming we find a way to trace it, how would you expect the trace data for this proxy request to be represented (if at all)?

My first chain of though was, that you wouldn't use a proxy voluntarily for just a few requests. This is usually some corporate environment that is locked down and you know that each request (maybe except calls directly to AWS, but again, you do know which requests that are) goes through the proxy.

We do have pretty awesome tools to monitor our proxy. So if something goes wrong, and I assume it is the proxy breaking, I would first look there and not into XRay.

But even if I would look into XRay and see all my requests to github.com are broken I instantly know; it is either our implementation, GitHub or the proxy and then use our internal tools to debug the proxy (if the github status page has no information and we verified it is probably not us).

So I would say skipping the proxy as a segment would be fine from my point of view. Especially if it makes the fix easier.
All I am interested in is if I call github.com/orgs/org-a/... or github.com/orgs/org-b/.... Having the request body easily available would be a nice bonus as well.

I will think about it over the next few days and also try to reach out some colleagues and if anyone has a strong different opinion would report back here.