Audit log always contains HTTP/1.1 500 Internal Server Error

[sarvasana]

IIS 7.5
ModSecurityIIS 2.7.5
ASP.NET WebForms (also in MVC)

The audit log always contains the following error:

--040e0000-F--
HTTP/1.1 500 Internal Server Error

I have seen this error in other issues as well, but nobody seems to be bothered with it. What is causing this error? It seems like it is not returned to the browser.

[sarvasana]

I found the following code in server.c. It seems to be the only piece of code returning 500 errors.

AP_DECLARE(int) ap_index_of_response(int status)
{
static int shortcut[6] = {0, LEVEL_200, LEVEL_300, LEVEL_400,
LEVEL_500, RESPONSE_CODES};
int i, pos;

if (status < 100) {               /* Below 100 is illegal for HTTP status */
    return LEVEL_500;
}

for (i = 0; i < 5; i++) {
    status -= 100;
    if (status < 100) {
        pos = (status + shortcut[i]);
        if (pos < shortcut[i + 1]) {
            return pos;
        }
        else {
            return LEVEL_500;            /* status unknown (falls in gap) */
        }
    }
}
return LEVEL_500;                         /* 600 or above is also illegal */

}

[iokennedy]

Also always getting 500 Internal Server Error in audit log. Page is serving fine - browser is getting 200 status + IIS logs show 200.

IIS 8.5
Modsecurity 2.9.1
Webpage is default iisstart.htm that came with IIS.
No modsec rules defined

Here is the audit log (linked) followed by modsec debug.log (level 9).

20160920-220030-18086456109962362942.txt

[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Initialising transaction (txid 18086456109962362942).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Transaction context created (dcfg 403cbbc9d0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] First phase starting (dcfg 403cbbc9d0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Starting phase REQUEST_HEADERS.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Second phase starting (dcfg 403cbbc9d0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Input filter: This request does not have a body.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Starting phase REQUEST_BODY.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Hook insert_filter: Adding output filter (r 403cbc7fa0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][9] Output filter: Receiving output (f 403cbc9320, r 403cbc7fa0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Starting phase RESPONSE_HEADERS.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][9] Content Injection: Not enabled.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][9] Output filter: Bucket type POOL contains 694 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][9] Output filter: Bucket type EOS contains 0 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Output filter: Completed receiving response body (buffered full - 694 bytes).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Starting phase RESPONSE_BODY.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Output filter: Output forwarding complete.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Initialising logging.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Starting phase LOGGING.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Recording persistent data took 0 microseconds.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][4] Audit log: Logging this transaction.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iisstart.htm][9] Audit Log: Writing 214 bytes to primary concurrent index
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Initialising transaction (txid 18086456109962362943).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Transaction context created (dcfg 403cbbc9d0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] First phase starting (dcfg 403cbbc9d0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Starting phase REQUEST_HEADERS.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Second phase starting (dcfg 403cbbc9d0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Input filter: This request does not have a body.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Starting phase REQUEST_BODY.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Hook insert_filter: Adding output filter (r 403cbc7fa0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Receiving output (f 403cbc9350, r 403cbc7fa0).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Starting phase RESPONSE_HEADERS.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Content Injection: Not enabled.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 8192 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type POOL contains 453 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Output filter: Bucket type EOS contains 0 bytes.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Output filter: Completed receiving response body (buffered full - 98757 bytes).
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Starting phase RESPONSE_BODY.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Output filter: Output forwarding complete.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Initialising logging.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Starting phase LOGGING.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Recording persistent data took 0 microseconds.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][4] Audit log: Logging this transaction.
[20/Sep/2016:22:00:30 +0100] [WINDOWS/sid#403cbbbf40][rid#403cbc7fa0][/iis-85.png][9] Audit Log: Writing 213 bytes to primary concurrent index

[sarvasana]

Wow...I logged this issue nearly 3 years ago...

[vukitoso]

How to fix this error?

[martinhsv]

Hello @sarvasana and @Vebmaster ,

This item predates my involvement with the ModSecurity project ... by years.

I have never seen this effect in my pre-release testing of recent releases of ModSecurity for IIS. If this is (still) happening for you, presumably there is some unidentified factor that results in that effect for only some installations.

While I cannot suggest a true fix at this time, there are some things one could consider trying that may alleviate the inconvenience.

SInce it is likely that the immediate cause of the writes to the audit log, are due to the status code (as perceived by ModSecurity), you could consider adjusting the the configuration setting for SecAuditLogRelevantStatus to something like this to exclude all 5xx status codes:

SecAuditLogRelevantStatus "^(?:4(?!04))"

or this to exclude only the 500 status code:

SecAuditLogRelevantStatus "^(?:5(?!00)|4(?!04))"

[sarvasana]

This item predates my involvement with the ModSecurity project ... by years.

I have not been working with IIS since 2014. Thank god.
Good to know this filter exists though.

[martinhsv]

Hi @Vebmaster ,

I'm going to proceed to close this item. This is partly due to its extreme age and the fact that the original poster is no longer using the relevant technology.

If you believe you are experiencing the same symptom, I would invite you to create a new issue to that effect. If you do so, please use the issue template and include as much of the suggested information as you can.

It may be that what you are experiencing is similar to what is described here, or it may only be superficially similar and have a simple explanation. In any case, we can assess it based on it own facts.

[vukitoso]

@martinhsv Thanks a lot for your help.
The reason for this message was that the php script itself was returning a 500 error.
At first I thought that this was the problem of ModSecurity itself.