Status 200 Response from Function Invocation but Function Didn't Actually Execute / Unexpected x-bb-proxy Header in Response

I have a lambda that’s invoked dozens or hundreds of times per day, sometimes in quick succession, without issue for months. Today, for the first time, an invocation received a 200 response, and yet the lambda was not in fact executed. (I’m able to tell that the lambda wasn’t executed because all logs from that particular invocation, and only that invocation, are missing, and because the effect the invocation would have had did not occur.)

Here’s the response from the problematic invocation where the lambda did not get executed.

        "status": 200,
        "headers": [
            {
                "value": "public, max-age=0, must-revalidate",
                "name": "cache-control"
            },
            {
                "value": "text/plain; charset=utf-8",
                "name": "content-type"
            },
            {
                "value": "Fri, 13 Aug 2021 15:30:40 GMT",
                "name": "date"
            },
            {
                "value": "0",
                "name": "age"
            },
            {
                "value": "0",
                "name": "content-length"
            },
            {
                "value": "True",
                "name": "x-bb-proxy"
            },
            {
                "value": "v2",
                "name": "x-bb-proxy-version"
            },
            {
                "value": "Netlify",
                "name": "server"
            },
            {
                "value": "01FD025ZYMNQAS8343RGRN8GJ7",
                "name": "x-nf-request-id"
            }
        ]

By contrast, here’s the response from an invocation at nearly the same time where the lambda did execute normally.

        "status": 200,
        "headers": [
            {
                "value": "no-cache",
                "name": "cache-control"
            },
            {
                "value": "application/json",
                "name": "content-type"
            },
            {
                "value": "Netlify",
                "name": "server"
            },
            {
                "value": "01FD025ZYMS7H60H1HB8PV6PKV",
                "name": "x-nf-request-id"
            },
            {
                "value": "1",
                "name": "age"
            },
            {
                "value": "Fri, 13 Aug 2021 15:30:41 GMT",
                "name": "date"
            },
            {
                "value": "0",
                "name": "content-length"
            }
        ]

As you can see, the problematic invocation has headers that don’t appear in normal invocations, namely x-bb-proxy and x-bb-proxy-version. The content-type is also different.

I’ve found no meaningful information on what the x-bb-* headers represent, just a handful of miscellaneous references in other support tickets without going into detail on these headers.

Regardless, evidently it’s possible to invoke a Netlify function and get a 200 response without the function in fact being executed. That’s quite concerning. What could be causing it?

Hey @AndrewK,

Thanks for your patience. You’re right, things do look a little strange. I’ve kindly asked our dev team to take a better look at this one. As soon as we hear back from them, we’ll be sure to update you!

Thanks Scott, I appreciate the reply. Looking forward to hearing more about the underlying cause and if there’s anything I can do to help.

Hey there!

The team can see that we returned response headers instead of calling the function and returning that response however it’s going to take a more thorough look to try and understand why.

In the meantime, are your current invocations executing as expected (i.e. was this a one-off?)

Thanks for the update.

I’ve checked my old logs, and I’ve found a handful of additional examples over the past 2 months. The one I originally posted about is the most recent – there are no new examples since then. I’ve included the older examples below. Note that these examples happen to be from different lambdas than the one I posted about originally.

{"data":{"status":200,"body":"","headers":[{"value":"public, max-age=0, must-revalidate","name":"cache-control"},{"value":"text/plain; charset=utf-8","name":"content-type"},{"value":"Tue, 06 Jul 2021 19:17:09 GMT","name":"date"},{"value":"0","name":"age"},{"value":"0","name":"content-length"},{"value":"True","name":"x-bb-proxy"},{"value":"v2","name":"x-bb-proxy-version"},{"value":"Netlify","name":"server"},{"value":"01F9YM1CAXZ4T4NEDB129SW0A5","name":"x-nf-request-id"}]},"version":"2","type":"webhook_response"}
{"data":{"status":200,"body":"","headers":[{"value":"public, max-age=0, must-revalidate","name":"cache-control"},{"value":"text/plain; charset=utf-8","name":"content-type"},{"value":"Wed, 30 Jun 2021 13:51:48 GMT","name":"date"},{"value":"0","name":"age"},{"value":"0","name":"content-length"},{"value":"True","name":"x-bb-proxy"},{"value":"v2","name":"x-bb-proxy-version"},{"value":"Netlify","name":"server"},{"value":"01F9EK1AX1ZJNJJAXYBX5HJ94W","name":"x-nf-request-id"}]},"version":"2","type":"webhook_response"}
{"data":{"status":200,"body":"","headers":[{"value":"public, max-age=0, must-revalidate","name":"cache-control"},{"value":"text/plain; charset=utf-8","name":"content-type"},{"value":"Thu, 24 Jun 2021 17:48:38 GMT","name":"date"},{"value":"0","name":"age"},{"value":"0","name":"content-length"},{"value":"True","name":"x-bb-proxy"},{"value":"v2","name":"x-bb-proxy-version"},{"value":"Netlify","name":"server"},{"value":"6422d142-a8d4-4df2-9e91-347d72a550ba","name":"x-nf-request-id"}]},"version":"2","type":"webhook_response"}
{"data":{"status":200,"body":"","headers":[{"value":"public, max-age=0, must-revalidate","name":"cache-control"},{"value":"text/plain; charset=utf-8","name":"content-type"},{"value":"Tue, 22 Jun 2021 17:56:15 GMT","name":"date"},{"value":"0","name":"age"},{"value":"0","name":"content-length"},{"value":"True","name":"x-bb-proxy"},{"value":"v2","name":"x-bb-proxy-version"},{"value":"Netlify","name":"server"},{"value":"7ec89009-bfc1-4b06-a9f0-7c721af3f2af","name":"x-nf-request-id"}]},"version":"2","type":"webhook_response"}
{"data":{"status":200,"body":"","headers":[{"value":"public, max-age=0, must-revalidate","name":"cache-control"},{"value":"text/plain; charset=utf-8","name":"content-type"},{"value":"Tue, 22 Jun 2021 13:04:45 GMT","name":"date"},{"value":"0","name":"age"},{"value":"0","name":"content-length"},{"value":"True","name":"x-bb-proxy"},{"value":"v2","name":"x-bb-proxy-version"},{"value":"Netlify","name":"server"},{"value":"8a045044-8399-4756-b71e-23dcbac79d3d","name":"x-nf-request-id"}]},"version":"2","type":"webhook_response"}

For all of these, as well as the original example, I noticed something curious about the timing that may be a clue to the underlying issue. There’s at least one successful response to the lambda within 1 second after the problematic invocation, and there were no invocations at all for at least 10 seconds before the problematic invocation. I don’t have the sub-second request times, but looking at some other details I do have, I can see that the requests would have indeed been made within a second of each other, and quite likely much closer.

This suggests to me that perhaps there’s a race condition occasionally affecting concurrent, interleaved requests to the same lambda.

Thanks for this, @AndrewK, I’ll pass this on to the team in hope of a prognosis!

Hey, @AndrewK, has there been any reoccurrence of this? Our logs only persist for 30 days and this is proving hard to debug without reoccurrence!

Hi @Scott.

Yes, I’ve seen this recur two more times since we last spoke. Here are the most recent instances:

{"data":{"status":200,"body":"","headers":[{"value":"public, max-age=0, must-revalidate","name":"cache-control"},{"value":"text/plain; charset=utf-8","name":"content-type"},{"value":"Tue, 31 Aug 2021 13:02:33 GMT","name":"date"},{"value":"0","name":"age"},{"value":"0","name":"content-length"},{"value":"True","name":"x-bb-proxy"},{"value":"v2","name":"x-bb-proxy-version"},{"value":"Netlify","name":"server"},{"value":"01FEE4VQ9CXWY87QCA5KK99X0R","name":"x-nf-request-id"}]},"version":"2","type":"webhook_response"}
{"data":{"status":200,"body":"","headers":[{"value":"public, max-age=0, must-revalidate","name":"cache-control"},{"value":"text/plain; charset=utf-8","name":"content-type"},{"value":"Thu, 02 Sep 2021 17:42:58 GMT","name":"date"},{"value":"0","name":"age"},{"value":"0","name":"content-length"},{"value":"True","name":"x-bb-proxy"},{"value":"v2","name":"x-bb-proxy-version"},{"value":"Netlify","name":"server"},{"value":"01FEKSPKKK32NTE9XCVYAZR28Z","name":"x-nf-request-id"}]},"version":"2","type":"webhook_response"}

I’ve also confirmed that these two exhibit the same timing pattern I mentioned earlier, where there’s at least one normal invocation within a second after the problematic invocation. Would it be helpful to have the details of those invocations too?

One other detail that may be relevant: I have a separate Netlify site which also often invokes lambda functions in quick succession, but for that site my logs indicate this issue hasn’t occurred (even though the total number of invocations is similar between the two sites). This second site is much newer than the one where I’m seeing the issue, so perhaps it only affects older sites.

Thanks, @AndrewK, I’ll fwd this to the team to help them with their debug.

1 Like

Hiya and big props for your patience.

Good news! The team have pushed a probable fix for this edge case. Can you let me know if you have any reoccurrence from this point in time on?

Thanks Scott, good to know. Will do.

1 Like

Just wanted to circle back and mention that I haven’t seen this issue recur in the last two weeks, so it appears the fix was successful.

That’s great to know. But if you still do find something wrong, do report it.