How to correlate IIS, Application and SQL Server Audit logs to achieve full stack audit.

Introduction

In my previous post I've talked about using domain events to capture "what" has changed inside the domain. In this article I am going to provide an example of how you can create a correlation id to correlate IIS, Domain and SQL Server Audit logs. 

Solution Requirements 

• As a security analyst I would like to be able to see where the requests came from so that I can identify the malicious user so that we can block this user or pass this user's identification information to the company. 
• As a security analyst I would like to be able to see what user's request has changed so that I can identify a software bug or a malicious user behavior.  
• As a software engineer I don't want to log away web request meta data or SQL requests inside my application as I don't want to maintain this code and data.

Problem

How do you correlate below logs? 

IIS W3C Log

#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status time-taken
2016-09-04 20:24:22 ::1 GET / - 80 - ::1 Mozilla/5.0+(Windows+NT+6.3)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/52.0.2743.116+Safari/537.36 - 200 0 0 612

Please note that there is no unique id.

 

Application Domain Event Log

<d2p1:eventdto>
    <d2p1:args xmlns:d5p1="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
    <d5p1:keyvalueofstringstring>
        <d5p1:key>FirstName</d5p1:key>
        <d5p1:value>Zan</d5p1:value>
        </d5p1:keyvalueofstringstring>
        <d5p1:keyvalueofstringstring>
        <d5p1:key>LastName</d5p1:key>
        <d5p1:value>Kavtaskin</d5p1:value>
        </d5p1:keyvalueofstringstring>
        <d5p1:keyvalueofstringstring>
        <d5p1:key>Email</d5p1:key>
        <d5p1:value>zan.kavtaskin@someemail.com</d5p1:value>
        </d5p1:keyvalueofstringstring>
        <d5p1:keyvalueofstringstring>
        <d5p1:key>Country</d5p1:key>
        <d5p1:value>1</d5p1:value>
    </d5p1:keyvalueofstringstring>
    </d2p1:args>
    <d2p1:created>2016-09-03T15:55:52.4805906+01:00</d2p1:created>
    <d2p1:type>CustomerCreated</d2p1:type>
</d2p1:eventdto>

 

SQL Server Audit Log

 

So, how do you correlate above logs? Obvious answer would be some kind of a correlation id. This approach makes sense inside your application as you have control over it. However, what about IIS? Each web request meta data is written away to the log before (sometimes even after) it hits your application.

 

Solution

1. Create the correlation id hash

IIS will capture variables like IP address, User Agent, Path, Verb, etc in the log (see above). As you know what you are storing in the IIS log, you can get these variables out of the request header inside of your application and create a W3C correlation id hash.

public interface IRequestCorrelationIdentifier
{
    string CorrelationID { get; }
}
    
public class W3CWebRequestCorrelationIdentifier : IRequestCorrelationIdentifier
{
    public string CorrelationID { get; private set; }

    public W3CWebRequestCorrelationIdentifier()
    {
        /* #Customise your correlation ID here
         * More request identification variables you add easier 
         * it's going to be to find the relevant W3C request when you hash it
         * 
         * Below is just an example of variables and hash algorithm that you can use:
         */
        string rawCorrelationID = string.Join("_",
                HttpContext.Current.Request.ServerVariables["REMOTE_ADDR"],
                HttpContext.Current.Request.Params["LOGON_USER"],
                HttpContext.Current.Request.UserAgent != null ? 
                    HttpContext.Current.Request.UserAgent.ToString().Replace(" ", "+") : "-",
                HttpContext.Current.Request.Path,
                HttpContext.Current.Request.QueryString.ToString() ?? "-",
                new DateTime(HttpContext.Current.Timestamp.Ticks).ToUniversalTime().ToString("yyyy-MM-dd HH:mm:ss")
            );

        StringBuilder hashBuilder = new StringBuilder();
        using (MD5 md5 = MD5.Create())
        {
            byte[] hash = md5.ComputeHash(Encoding.UTF8.GetBytes(rawCorrelationID));
            for (int i = 0; i < hash.Length; i++)
                hashBuilder.Append(hash[i].ToString("X2"));
        }

        this.CorrelationID = hashBuilder.ToString();
    }
}

Would like to see a working example? It's right here on GitHub. 

 

You might be thinking, what's the point? Now you are just storing a hash correlation id, this hash is not stored in the IIS logs. Well, when you will need to investigate an issue you will know what days this issue has occurred, you will just need to run similar code over the IIS logs for a certain date range to generate hash codes and you will find the matching correlation ids (there is a bit more to it, see "Searching W3C Logs" section at the bottom).

2. Register correlation identifier 

IRequestCorrelationIdentifier can then be registered with your dependency injection framework with a life style of a per web request. This will ensure that all components in that web request pipeline get the same correlation id. 

container.Register(Component.For<IRequestCorrelationIdentifier>().ImplementedBy<WebRequestCorrelationIdentifier>().LifeStyle.PerWebRequest);

Would like to see a working example? It's right here on GitHub. 

 

3. Log everything away with the correlation id

You are now ready to use IRequestCorrelationIdentifier inside your application. Here is how you can use it with domain event logging:

public class DomainEventHandle<TDomainEvent> : Handles<TDomainEvent>
    where TDomainEvent : DomainEvent
{
    IDomainEventRepository domainEventRepository;
    IRequestCorrelationIdentifier requestCorrelationIdentifier;

    public DomainEventHandle(IDomainEventRepository domainEventRepository,
        IRequestCorrelationIdentifier requestCorrelationIdentifier)
    {
        this.domainEventRepository = domainEventRepository;
        this.requestCorrelationIdentifier = requestCorrelationIdentifier;
    }

    public void Handle(TDomainEvent @event)
    {
        @event.Flatten();
        @event.CorrelationID = this.requestCorrelationIdentifier.CorrelationID;
        this.domainEventRepository.Add(@event);
    }

Would like to see a working example? It's right here on GitHub. 

 

4. Enable IIS logging

5. Enable SQL Server Auditing

Microsoft has recently released SQL Server Auditing feature. It logs away all raw SQL statements that were executed against your database. As you now have correlation ids, all you have to do is get the correlation id and search your XEL files. Here is an example XEL filter screen where I am searching for a correlation id:

If it will find the correlation id inside the "statement" field it will return the relevant rows:

 

By clicking on the row you will get audit event breakdown:

This is extremely powerful as you can identify all changes and now you can correlate them all. 

Searching W3C logs

The following situations can occur: 

• IIS will log the web request few seconds after your application has already processed it 
• Your application will process the request few seconds after IIS has logged your web request 

Why is this significant? Correlation id hash codes are generated with date time variables inside your application. Your application doesn't know what timestamp IIS has used. Which means when you search IIS W3C logs and you hash same variables you might not find the expected correlation id. Delay between IIS and your application is only +-2 seconds (this is what I found during my testing). So, when you search your IIS W3C logs, just generate 4 additional hash codes and search on them as well. 

Here is an example:

Your application has hashed the following: -_/_index=aa23ab2a-5d9a-4018-99e6-c50d2abfbad4_2016-09-03 23:04:21 

It produced the following hash: 93cad82c735b913dea5c722500ea6d22

You might not find anything when you search for 93cad82c735b913dea5c722500ea6d22. If you don't, just hash the following as well +-2 seconds:

-_/_index=aa23ab2a-5d9a-4018-99e6-c50d2abfbad4_2016-09-03 23:04:19      ->(-2)

-_/_index=aa23ab2a-5d9a-4018-99e6-c50d2abfbad4_2016-09-03 23:04:20       ->(-1)

-_/_index=aa23ab2a-5d9a-4018-99e6-c50d2abfbad4_2016-09-03 23:04:22       ->(+1)

-_/_index=aa23ab2a-5d9a-4018-99e6-c50d2abfbad4_2016-09-03 23:04:23       ->(+2)

Conclusion

Pros:

• Don't have to create a custom IIS log formatter  
• Don't have to write away request meta data inside your own application, IIS logging take cares of it for you 
• It's very hard to fake the correlation id as it's created server side and not passed through from the client 
• Events and Logs can be stored with the same correlation id 
• Same approach can be used to generate hash not just for IIS but also for other up stream systems such as Queues.

Cons:

• When you search your W3C logs you might need to generate 4 additional hashes to find your correlation id 

 

This is a low maintenance full stack logging solution where you need to write and manage minimal amount of code and data. 

If you don't really care about IIS W3C log correlation then just generate a random correlation id ( Guid.NewGuid() will do the job perfectly) instead and use it in your stack.