Azure App service 400 Bad request! — A STORY

Problem

A Node API setup on Azure app service has been working perfectly fine. All of a sudden, there is a User who can access some API Endpoints while not some others (API returns a HTTP status Code 400). There is a new user who when added into the app can’t access the API at all. WHAAT?!

So, whats HTTP status Code 400 Bad Request ? the 4XX errors signify that the Client seemed to have Erred. 400 in particular means that the request could not be understood by the server due to malformed syntax and the client SHOULD NOT repeat the request without modifications.

More precisely:

• User A is able to access 2 endpoints (x and y), not another one (z) on PROD API. Gets 400 returned on z.
• User B is unable to access any Endpoint (not x, y and z) on PROD API. Gets 400 returned on x, y and z.

Nature of application

The App consists of an AngularJS (4.X) web app that makes API calls to a Node Service, both deployed on Azure App Services.

Authentication

The application has Easy Auth set up for Authentication (as shown below).

The application is registered on the API URL with the Web and APIs listed in the Return URIs of the registration. This setting allows the URIs listed here to use AAD against the same Registration. All the URIs would work with the same AuthToken issued by AAD for the particular User.

Initial Investigations

• Checked the code to confirm that there are no 400's being returned from Code — None.
• Replicated the API calls using postman. — Yes, the behavior could be replicated using postman. This ruled out the possibility that the Web Client is messing up when making a call.
• Checked the JWT tokens being passed in headers and confirmed that they are fine. — Had the right expiry time set, did not have any specific roles that would throw the API call out.
• Checked the Api logs to make sure that there are no Errors being logged as a part of the call. — There were no Logs at all. Made sure that the app does not have unhanded errors and there were appropriate Try-Catches. This showed that the Error was being returned even before the call reaches the API code, as expected for a 400 error.
• Checked the App service Logs — Enable the App service logs as below. I have chosen File System for Web server logging and chosen only 35MB to be retained at a time with retention of 4 days, so that there is not much saved on the Virtual Machine which otherwise might start slowing down the Application. Once this is done, you can check the application using kudu tools.

Click on CMD or Power shell as shown below to see the API items.

Now you can see the App service LogFiles folder as shown below.

You see a bunch of log files in it as below. I checked if any relevant logs can be found.

The DetailedErrors folder contains a file each for all individual failed Requests. below is a log of the 400 that was returned. The Most likely causes section is empty, that’s frustrating!

• Log the IISNode errors— The application in Question is a node.js app that is Hosted in IIS.
• Here, since the iisnode handler is used to the run node processes on IIS, the following configuration in the web.config file would allow logging errors thrown by nodejs.

<configuration>
<system.webServer>
.
.
<iisnode loggingEnabled="true"
logDirectory="iisnode"
debuggingEnabled="true"
debuggingHeaderEnabled="true"
debuggerPortRange="5058-6058"
debuggerPathSegment="debug"
maxLogFileSizeInKB="128"
maxTotalLogFileSizeInKB="1024"
maxLogFiles="20"
devErrorsEnabled="True"
flushResponse="false"
enableXFF="false"
promoteServersVars=""
configOverrides="iisnode.yaml"
watchedFiles="web.config;*.js"/>"
<httpErrors existingResponse="PassThrough"/>
</system.webServer>
<system.web>
<customErrors mode="Off">
</system.web>
</configuration>

Along with the above, make this change in your Node server app.js to write a log when there is a clientError Event. Refer https://nodejs.org/api/http.html for the entire list of Node Http Server Events.

server.on(‘clientError’, (err, socket) => {
socket.end(‘400 Bad Request\r\n\r\n’);
log.error({ err: err }, `ATTENTION!!!! HTTP/1.1 400 Bad Request`);
});

This allows the error to be logged and Voilà! This gets logged.

{“name”:”app”,”hostname”:”RD0003FF6A73C0",”pid”:20252,”level”:50,”err”:{“message”:”Parse Error”,”name”:”Error”,”stack”:”Error: Parse Error”,”code”:”HPE_HEADER_OVERFLOW”},”msg”:”ATTENTION!!!! HTTP/1.1 400 Bad Request”,”time”:”2020–07–10T05:39:42.548Z”,”v”:0}

Look at the Error Code! it says HPE_HEADER_OVERFLOW that means that the Header is longer than expected. Investigating the Headers, revealed that the Tokens for the Failing Calls were indeed longer than most calls. Reason? Some users had a longer JWT token issued hence hit the limit (did not expect that). Sometimes, the limit was hit just because the URL was long.

November 2018 update of NodeJs, set a limit on large HTTP header size (denial of service for headers > 8192 bytes). Refer this https://nodejs.org/en/blog/vulnerability/november-2018-security-releases/#denial-of-service-with-large-http-headers-cve-2018-12121

While it is true that your app should have a limit on Header size, the limit set by Node is waaaaaay small.

Now, how do you update the Server to accept larger HTTP Headers so that we get rid ofthis HTTP Headers problem? Do the following, add the following Environment Key and value with the size you want set on your app.

That’s all! NO MORE HTTP BAD REQUEST!

Hope this helps somebody running into this problem :-)