Router errors 502 of POST requests "Undocumented"

The default behavior in the Ruby Fly adapter is to replay all POST requests as early as possible in the middleware stack. But even there, the Rails default web server (Puma) will buffer large requests to disk before passing them to Rails.

We’ll need to see how express handles things.

I think we can get replay to account for this (it’s the point of the buffer, after all). It’s more complex, though, and going to take some time to work out all the wrinkles.

I’ve improved things by adding an express middleware before parsing the body to redirect everything that’s not a GET request to the primary region. And I also have read-only and write-only clients for my postgres db so that way even if I do write in a GET request, it still works without issue (useful for session refreshes for example).

I think this is a pretty solid solution to this problem. Thanks for all your help on this @kurt and @jsierles :slight_smile:

1 Like

@jerome actually found that weird body parsing bug. Definitely let us know if there’s another 502 with an Undocumented error, though. This should be pretty stable.

1 Like

I got another one :frowning:

2021-09-21T22:07:21.803487120Z proxy[3a12ae8b] gru [error] error.code=1 error.message="Undocumented" request.method="POST" request.url="https://kent.dev/calls/record/new?_data=routes%2Fcalls.record%2Fnew" request.id="01FG56CBAWEE2SNEP1PWGN6MBY" response.status=502 

They tried twice with the same result.

The “Undocumented” error is very unfortunate. I’ll be working on improving that a bit more.

The request seems to have hit a gru edge server, then went to scl for your app. Your app then replied with the fly-replay header. Our edge then forwarded this to dfw.

Something is odd in the logs I’m seeing. I’m going to set a much higher log level for your app specifically (in our proxy logs) to see if anything interesting happens.

I’ll check for errors myself, but if you see one and I haven’t replied yet, please let me know.

They did try again two hours ago and it failed. I’ll ask them to try again so we can get more logs.

Just saw a ton of these in a row:

2021-09-22T04:21:01.879762677Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-TXUYAVU2.js" request.id="01FG5VRAH1QABCKEN60ZE97VZ3" response.status=502 
2021-09-22T04:21:01.879852987Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/calls?_data=routes%2Fcalls" request.id="01FG5VRAGGB8PVNCFTHX6AZRJR" response.status=502 
2021-09-22T04:21:01.879887131Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-TBZWVEP5.js" request.id="01FG5VRAH9GZ8HEK0TPNA8BDRC" response.status=502 
2021-09-22T04:21:01.879915920Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-W3S32BQM.js" request.id="01FG5VRAH99Q326RQ6W5H0VZ69" response.status=502 
2021-09-22T04:21:01.882541560Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/chats?_data=routes%2Fchats" request.id="01FG5VRCXQ69JJS05FRCARFE5Y" response.status=502 
2021-09-22T04:21:01.882930341Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/routes/chats/index-MFQY3T37.js" request.id="01FG5VRCYPWDCV06WPX8TWNDEV" response.status=502 
2021-09-22T04:21:01.883243760Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-ODG2IO5V.js" request.id="01FG5VRAHESWY37QMHCKRH686D" response.status=502 
2021-09-22T04:21:01.883584714Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/routes/calls-UDG7ZUAP.js" request.id="01FG5VRAH1XKXZ00XAH6GY8JJ4" response.status=502 
2021-09-22T04:21:01.883775829Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-N4MMAILK.js" request.id="01FG5VRAH1WM0AQ5QVA12SX1WS" response.status=502 
2021-09-22T04:21:01.884935342Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/courses?_data=routes%2Fcourses%2Findex" request.id="01FG5VREEZDW1C3C63KMK7B54H" response.status=502 
2021-09-22T04:21:01.885136621Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/routes/discord-2C4Q4IWY.js" request.id="01FG5VREJNZD7BSC5ANCRN602G" response.status=502 
2021-09-22T04:21:01.885337561Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/routes/chats-4KEN6NOO.js" request.id="01FG5VRCYN5ZDE0MX92FVDKV63" response.status=502 
2021-09-22T04:21:01.885570348Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/routes/courses/index-A23MDSLR.js" request.id="01FG5VREFJBEXW43D0290EB6HT" response.status=502 
2021-09-22T04:21:01.885773433Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-2TYN2QP2.js" request.id="01FG5VRCYPZ2N596TTJ62QHZFM" response.status=502 
2021-09-22T04:21:01.886306628Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-MITHI5HD.js" request.id="01FG5VREJP1P3YMWC41MQ45G4S" response.status=502 
2021-09-22T04:21:01.886393771Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-QWQT3QOY.js" request.id="01FG5VREGHZT9H2EA09Z67GH3A" response.status=502 
2021-09-22T04:21:01.886878874Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-ZCIQI2JJ.js" request.id="01FG5VRCYP2NW9PJYDKT40NXH9" response.status=502 
2021-09-22T04:21:01.887094199Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/discord?_data=routes%2Fdiscord" request.id="01FG5VREJPKJNKX1TM8165Z0T3" response.status=502 
2021-09-22T04:21:01.887379463Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/?_data=routes%2Findex" request.id="01FG5VRDKXFKFAK0392NCYQHFX" response.status=502 
2021-09-22T04:21:01.887644815Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-DNRD5EDF.js" request.id="01FG5VRCYP1TMMBEMXG40APYB8" response.status=502 
2021-09-22T04:21:01.888139912Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/build/_shared/chunk-MUQTLTSQ.js" request.id="01FG5VREGHVE1ACPVAW0EFWNH2" response.status=502 
2021-09-22T04:21:01.888664857Z proxy[0d856b31] lga [error] error.code=1 error.message="Undocumented" request.method="GET" request.url="https://kent.dev/chats?_data=routes%2Fchats%2Findex" request.id="01FG5VRCYNK23M075NNAP5450V" response.status=502 

They came right after this issue though: Big error and I have no idea what it means. · Issue #1608 · evanw/esbuild · GitHub so I’m guessing it’s related. I’m pushing a fix for that issue right now. Hopefully this resolves most of these 502 problems (though the last one I reported I don’t think is related to the OOM issue).

I had someone else make some requests and got this (they tried three times):

2021-09-22T10:28:55.812377072Z proxy[01e62fbb] fra [error] error.code=1 error.message="Undocumented" request.method="POST" request.url="https://kent.dev/calls/record/new?_data=routes%2Fcalls.record%2Fnew" request.id="01FG6GT6V4Z78Q097A00Z23GGF" response.status=502 

...

2021-09-22T10:32:41.809035555Z proxy[01e62fbb] fra [error] error.code=1 error.message="Undocumented" request.method="POST" request.url="https://kent.dev/calls/record/new?_data=routes%2Fcalls.record%2Fnew" request.id="01FG6H13FQ1BTC9KKW3SD9SRGK" response.status=502 

...

2021-09-22T10:33:59.550844171Z proxy[01e62fbb] fra [error] error.code=1 error.message="Undocumented" request.method="POST" request.url="https://kent.dev/calls/record/new?_data=routes%2Fcalls.record%2Fnew" request.id="01FG6H3FD1P7F5EMP5VHYPF60X" response.status=502 

We can improve the GET errors you saw. These were “connection reset by peer” from your app. Meaning it should fall in the “app connection” errors category.

I didn’t get the logs I wish I did for the POST requests. I’m pushing another update momentarily that might help.

If they do try again, it’s easier to sort through the logs if they only try once.

Is there any way I can trigger these myself? It would much easier to debug.

I disabled the replay again because it was impacting my users. Unfortunately I’m not sure how to reproduce. Seems like it happens to some users hitting non-primary region servers when they are submitting a recording at https://kent.dev/calls/record/new and I have replay enabled.

Do you know how big the POST bodies are? These errors match what we see in tests when our a Rails app parses a whole body and the request is quite large. I am wondering if the way those recordings are encoded balloon the request body somehow.

I don’t have any way to know the size of those. Here’s the commit where I removed the replay code: disable replay due to · kentcdodds/remix-kentcdodds@a41292c · GitHub

You’ll notice that I don’t even use the body parser middleware at all. All I do before the replay code is the redirect code and disabling the x-powered-by header.

We’re digging through Express, it’s quite possible it reads the whole body even before middleware. We’re going to launch a second instance of your app (assuming you’re cool with it) to see if we can replicate these things.

That sounds great :+1:

@kurt Did anything come of this? I feel like this is tied to my problem where my app hangs after trying to read the body of the request (also an express app, also Remix).

We haven’t been able to replicate with our own setup, sadly. We’ve fixed several body reading edge cases in the last few weeks though. Do you have a way to replicate the body read hangs?