Not on-call this sprint, but had some free time and was reading about a production issue. Eventually got looped in.
A dependent service was receiving 500s and this can be seen in the IIS logs:
3/24/21
8:26:35.000 PM
2021-03-25 03:26:35 W3SVC2 10.12.1.86 POST /someApp/v1/action/add - 443 - 10.12.29.62 Mozilla/5.0+(Windows+NT;+Windows+NT+10.0;+en-US)+WindowsPowerShell/5.1.19041.610 - 500 0 0 0 192.168.11.81
host = server1 source = C:\inetpub\logs\LogFiles\W3SVC2\u_ex123456_x.log sourcetype = IIS_SOMEAPP
There were no corresponding application logs for the expected X-Correlation-ID.
Recently we had patched the .NET Runtime from 3.1.2 to 3.1.12 and there was suspicion that this could have broken things since errors occurred fairly soon after the patching.
To be sure it wasn't something in the code, we've reviewed the middleware specific to handling exceptions thrown by the underlying code. First thing we do after catching any exception from invocation of the next middleware was logging the exception.
Reproduction in the production is tricky since I didn't have all the information or access necessary to conduct requests through curl/Postman. Same patching was done in the lowest integration environment so we tried to do some reproduction there.
The issue occurs externally when the requests are made through our API Gateway (Apigee) via a mobile app. The issue does not occur when the external endpoint is called from Postman. Issue does not occur when hitting the endpoint directly without Apigee internally.
While we looped in a Microsoft Support Engineer to run traces and dumps via Debug Diag (tool I've used in my previous life as a SE myself), I took a look at the offline Apigee traces captured. The trace contained one from the mobile app through Apigee and the other was from Postman.
After gathering all the information that was necessary for a request to the problematic endpoint (we were missing this in our Postman collection for an API we own), I was able to reproduce the issue initially by exporting the call to curl and Powershell's Invoke-Method and adding all the headers in the trace for the call right before hitting our API. Had some issues with curl with long strings.
$jwt = "someJwt"
$headers = @{}"
$headers.Add("Content-Type", "application/json")
$headers.Add("X-Correlation-ID", "2b67f0c6-213f-4428-a671-465bedbac432")
$headers.Add("Authorization", "Bearer $jwt")
$headers.Add("Cookie", "TS013ed3bf=01491400961a9ec42373082500bb24e99619eedb2f16e366885ecdb865075fdf5ac46827d15e7c1d8f56c6329f30f0184abe88d057")
$headers.Add("Accept", "*/*")
$headers.Add("Accept-Encoding", "gzip")
$headers.Add("Request-Context", "appId=cid-v1:0acaabc1-fbfd-423b-91e5-42898a9d2264")
$headers.Add("Request-Id", "|967b153d4242ed19a40e058128aefff1.bf7afc3dee3db54a.")
$headers.Add("traceparent", "00-967b153d4242ed19a40e058128aefff1-bf7afc3dee3db54a-01")
$headers.Add("tracestate", "az=cid-v1:0acaabc1-fbfd-423b-91e5-42898a9d2264")
$headers.Add("X-Forwarded-For", "192.168.17.60,10.125.2.10")
$headers.Add("X-Forwarded-Port", "443")
$headers.Add("X-Forwarded-Proto", "https")
$headers.Add("X-Mashery-Oauth-Client-Id", "someClientId")
$headers.Add("X-Mashery-Oauth-User-Context", "")
$headers.Add("X-Original-User-Agent", "okhttp/4.8.0")
$headers.Add("X-SomeCompany-Oauth-Client-Id", "someClientId")
$headers.Add("X-SomeCompany-Oauth-User-Context", "")
$body = "{
`n `"variables`": {
`n `"actionInput`": {
`n `"details`": {
`n `"firstName`": `"Test`",
`n `"lastName`": `"Tester`",
`n `"emailAddress`": `"testuser12345@somedomain.com`",
`n `"postalCode`": `"98048`"
`n },
`n `"token`": `"sometoken`",
`n `"someTransactionId`": `"924e626b-1783-4784-8d39-11dfb832a9e1`",
`n `"someIdentifier`": `"f011565d-2111-42ef-bebc-1e0bdf6350ad`"
`n }
`n }
`n}"
Invoke-RestMethod 'https://test.somecompany.com/someApp/v1/action/add' -Method 'POST' -Headers $headers -Body $body
Output:
Invoke-RestMethod : The remote server returned an error: (500) Internal Server Error.
At line:1 char:1
+ Invoke-RestMethod 'https://test.somecompany.com/someApp/v1/ ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo : InvalidOperation: (System.Net.HttpWebRequest:HttpWebRequest) [Invoke-RestMethod], WebException
+ FullyQualifiedErrorId : WebCmdletWebResponseException,Microsoft.PowerShell.Commands.InvokeRestMethodCommand
Booyah... no application logs show up, but IIS logs indicate the 500.
Now through process of elimination of the request headers, I can see that this little guy is causing all the hub-bub:
--header 'X-Forwarded-For: 192.168.17.60,10.125.2.10'
I try again with just one IP:
--header 'X-Forwarded-For: 192.168.17.60'
IT WORKS! The request succeeds (or the equivalent of success in that the API core code is reached and application logs are written).
I try a different endpoint that hasn't had issues with a base case of not including X-Forwarded-For. It works. I try the same endpoint with two comma separate IPs, it DOESN'T work. The comma seems to be the main issue as I've used other delimiters with a 400 HTTP response code back.
Workaround
Current workaround is to add some additional logic to the Apigee flow to only take the last IP in the XFF header. This still doesn't fix any internal clients sending more than one comma-separated IPs.
The long term fix is to remove this module if it isn't critical.
Further Investigation
Some time was spent looking at the release notes and code for .NET Core 3.1.2 to 3.1.12. It wasn't fruitful.
Digging around the lower test environment where the issue can be reproduced. I looked at options to transform the XFF header with URL Rewrite IIS plugin/extension. This isn't helpful in the case of incoming request headers. I then poked around and saw that we actually have a custom field for X-Forwarded-For in Logging. Removing this didn't change fix the issue.
I toyed with the idea of creating a custom IIS provider/module, but decided to see what was there currently. Scrolling to the bottom:
What is this XffHttpModule?
I removed it and retested. SUCCESS!
WTF
What does this module do? Did it get installed as part of the latest security patches?
Let's find out...
Using Cutter I was able gain some insight into the origins of the dll. I know it's unmanaged due to the IIS Modules screenshot.
Turns out this is a library was internal to our company.
Now to track down the source actual source if it exists. Reading assembly isn't my forte. At some point, I'd like to build that skill set for this type of reverse engineering/debugging.
Searching through our entire organization within Github Enterprise, I can see commit references to XffHttpHeader in several commits. Looks like they are just binaries (the dll and it's 32-bit counterpart). From the commit details, it looks like these were migrated from an old TFS instance using something like git-tfs. Coincidentally, I am working on a story related to migrating some code from this TFS instance to git related to (Same-Site cookies).
Source:
http://teamsystem.somecompany.net:8080/tfs/SomeCompany/SomeCompany/_versionControl?path=%24%2FSomeCompany%2FTools%2FMisc%2FXffHttpModule&version=T&_a=contents
Looking at the XffHttpModule.cpp, this source was basically this: devcentral.f5.com/articles/x-forwarded-for-..
Now living here: github.com/techiemac/F5XFFHttpModule
Digging around some more, it was reported that this custom module was created to log client IPs from X-Forwarded-For headers for IIS 7 instead of the proxy IP (could be the load balancer). The functionality is built in for IIS 8 and up.
Tracking down everything needed to build the project without updating the Platform Toolset (checked in as Visual Studio 2012 - v110) was time consuming. I didn't want to install VS 2012 on this brand new machine. I chose instead to setup an Azure VM with VS2012.
After compiling the source found in what I would guess is the latest branch, I wanted to be sure it was the same code as what was found on the server:
Get-FileHash .\src\XffHttpModule\x64\Release\XffHttpModule.dll | Format-List
Algorithm : SHA256
Hash : E245197229015A14610472C718040EAE4499C4EB5AE7FA5865635F4462394E22
Path : C:\Forensics\HttpModules\src\XffHttpModule\x64\Release\XffHttpModule.dll
Get-FileHash .\FromServer\XffHttpModule.dll | Format-List
Algorithm : SHA256
Hash : E245197229015A14610472C718040EAE4499C4EB5AE7FA5865635F4462394E22
Path : C:\Forensics\HttpModules\FromServer\XffHttpModule.dll
Cool, let's backup the existing XffHttpModule.dll, compile the existing code with Debug configuration, then drop the .dll and corresponding .pdb onto the IIS server, start the application pool.
We see that a XffModule log file gets created to the root.
Successful request with value for one IP:
============================================
Reading profile information from 'C:\inetpub\HttpModules\XffHttpModule.ini'
Using custom header value of 'X-Forwarded-For'
--> Registering X-Forwarded-For HTTP Module (XffHttpModule)...
(OARS) = OnAcquireRequestState, header = 'X-Forwarded-For'
(OARS) : Found 'X-Forwarded-For' with value of '192.168.17.60'
(OSR) = OnSendResponse
(OSR) = OnSendResponse
(OSR) : Replacing Client IP '10.35.34.234' with XFF value of '192.168.17.60'
<-- Deregistering X-Forwarded-For HTTP Module (XffHttpModule)...
Request that generates an error with two IPs:
============================================
Reading profile information from 'C:\inetpub\HttpModules\XffHttpModule.ini'
Using custom header value of 'X-Forwarded-For'
--> Registering X-Forwarded-For HTTP Module (XffHttpModule)...
(OARS) = OnAcquireRequestState, header = 'X-Forwarded-For'
(OARS) : Found 'X-Forwarded-For' with value of '192.168.17.60'
(OSR) = OnSendResponse
(OSR) = OnSendResponse
(OSR) : Replacing Client IP '10.35.34.234' with XFF value of '192.168.17.60'
<-- Deregistering X-Forwarded-For HTTP Module (XffHttpModule)...
--> Registering X-Forwarded-For HTTP Module (XffHttpModule)...
(OARS) = OnAcquireRequestState, header = 'X-Forwarded-For'
(OARS) : Found 'X-Forwarded-For' with value of '192.168.17.60,10.125.2.10'
(OARS) : Proxy detected in value, removing proxy info and using '192.168.17.60'
(OSR) = OnSendResponse
(OSR) = OnSendResponse
(OSR) = OnSendResponse
(OSR) : Replacing Client IP '10.35.34.234' with XFF value of '192.168.17.60'
<-- Deregistering X-Forwarded-For HTTP Module (XffHttpModule)...
============================================
Reading profile information from 'C:\inetpub\HttpModules\XffHttpModule.ini'
Using custom header value of 'X-Forwarded-For'
--> Registering X-Forwarded-For HTTP Module (XffHttpModule)...
(OARS) = OnAcquireRequestState, header = 'X-Forwarded-For'
(OSR) = OnSendResponse
(OSR) = OnSendResponse
(OSR) : Replacing Client IP ''10.35.34.234' with XFF value of '192.168.17.60'
<-- Deregistering X-Forwarded-For HTTP Module (XffHttpModule)...
I tried compiling with the code from a fork of F5XFFHttpModule since it has some changes not present in the the source I found. Tested with the same 500 error and no response. With added logging, it should be noted that no exception is ever thrown from this module and FAILED(hr) is not true when 500 occurs.
Nothing in the code stands out to me other than this block:
// Check for any additional proxy fields
// ie. X-Forwarded-For: 10.10.10.10, 1.2.3.4, 5.6.7.8
TCHAR *sep = _tcschr(pszHeaderValue, _T(','));
if ( NULL != sep )
{
*sep = _T('\0');
DebugMessage(_T("(OARS) : Proxy detected in value, removing proxy info and using '%s'\n"), pszHeaderValue);
}
sep = _tcschr(pszHeaderValue, _T(';'));
if ( NULL != sep )
{
*sep = _T('\0');
DebugMessage(_T("(OARS) : Proxy detected in value, removing proxy info and using '%s'\n"), pszHeaderValue);
}
Sometimes we'll see in the logs for X-Forwarded-For header value:
Just an example:
234.180.253.154\u000085.128.69.144
That's a null unicode character (\u0000).
In the block above, it seems like they just want to set the character pointer to null character so that the psZHeaderValue character array just has the first IP address since anything after the null character won't count as part of that header value string.
What happens if I comment out that line?
Success...
Something doesn't like setting that character pointer to a '\0'.
Could this be something with character size/Unicode? Could this be related to the security patching in which request header values can't contain any null characters?
This is valid C++ code and here is a repl/fiddle of that logic.
This inserted snippet will fix the issue and in that the X-Forwarded-Header value is set with just the first IP address and the module doesn't prevent processing to our IIS hosted ASP.NET Core API:
pRequest->SetHeader(GetHeaderName(), pszHeaderValue, (USHORT)strlen(pszHeaderValue), true);
*sep = _T(',');
The character pointer is set back to zero after the SetHeader function takes in the altered one IP value and we just set the character pointer back to the delimiter/comma.
3/26/21
1:08:44.000 PM
2021-03-26 01:08:44 W3SVC2 10.12.1.86 POST /someApp/v1/action/add - 443 - 10.35.40.210 PostmanRuntime/7.26.10 - 201 0 0 6297 192.168.11.81
host = server1 source = C:\inetpub\logs\LogFiles\W3SVC2\u_ex123456_x.log sourcetype = IIS_SOMEAPP
The actual client IP is 10.35.40.210. Server IP is 10.12.1.86. X-Forwarded-For first value is 192.168.11.81.
The integration environment (the next test environment) where the .NET Core Runtime was reverted back to 3.1.2 and the original XffHttpModule was still installed/enabled does not reproduce the 500 and I can get a response back from the API code itself.
3/26/21
1:10:21.000 PM
2021-03-26 01:10:21 W3SVC2 10.12.5.44 POST /someApp/v1/action/add - 443 - 10.35.40.210 PostmanRuntime/7.26.10 - 201 0 0 360 192.168.11.81
host = server1 source = C:\inetpub\logs\LogFiles\W3SVC2\u_ex123456_x.log sourcetype = IIS_SOMEAPP
The actual client IP is 10.35.40.210. Server IP is 10.12.5.44. X-Forwarded-For first value is 192.168.11.81.
From the debug logs:
...
(OSR) : Replacing Client IP '10.35.40.210' with XFF value of '192.168.11.81, 104.209.243.66'
...
This isn't happening according to the IIS logs. We just get the X-Forwarded-For value altered to just be the first one. Looks to be a second issue in the OnSendResponse function, specifically SetLogData isn't working:
if ( 0 != _tcsncmp(pLogData->ClientIp, m_pszHeaderValue, 128) )
{
DebugMessage(_T("(OSR) : Replacing Client IP '%s' with XFF value of '%s'"), pLogData->ClientIp, m_pszHeaderValue);
pLogData->ClientIp = "1.2.3.4";//(PCHAR)m_pszHeaderValue;
pLogData->ClientIpLength = _tcslen(m_pszHeaderValue);
hr = pProvider->SetLogData((HTTP_LOG_DATA *)pLogData);
if ( FAILED(hr) )
{
pProvider->SetErrorStatus(hr);
}
}
else
{
DebugMessage(_T("(OSR) : Client IP == XFF value == '%s' - Not performing replacement"), m_pszHeaderValue);
}
It seems version 3.1.3 and 3.1.12 (inclusive) has changed access to character pointers to the X-Forwarded-For value character array.
I've forked off techiemac/F5XFFHttpModule for my current changes that allows update to X-Forwarded-For without the 500 response. The replacement of ClientIP is a separate issue.
Summary
Initial hypothesis was that something in the version of the .NET Runtime has caused X-Forwarded-For header to fail on IIS with multiple comma-separated IP addresses. Determined that a custom IIS module was used to alter the X-Forwarded-For header. Suspicion verified by finding and updating source (C++), compiling in debug configuration and examining loggings. Access to header values has changed between version 3.1.3 and 3.1.12 causing Internal Server Error (500) responses to be returned with no logs.
Key Takeaways
- Wish we used containers everywhere.
- Legacy code/systems/modules strikes again.
- Get some more experience with reading assembly.
- Get some more experience with reverse engineering using Cutter.