The Audit Log: Introduction

This blog is part of the talk “Super Size your Security”, as presented at J and Beyond 2018, co-presented with Marco Dings, CTO ViryaGroup. The concept of the Audit Log starts at 5.20, and is availbale on YouTube.

The Case: Typical Security Incident

I want to start off this blog with a very practical and common security case, as illustrated above. In this case, a user installed a plugin to the Joomla! CMS one year ago. 10 days ago, a vulnerability in that plugin was discovered an publishd. You, as developer, are notified 2 days later and applied the patch within a day. Phew! Patched. That was fast.

CVE released, customer is calling

Now, the customer calls: “Has data been leaked?”

Three moments of vulnerability

Just after installation

The component was likely vulnerable ever since installation, however the security researchers have not yet discovered it. However, non-ethical security researchers might not publish all their research in the public domain. This means, the vulnerability might have been abused ever since installation.

After CVE relase

Exploitation of known vulnerabilites can happen within 5 hours, as was the case with the lateste Drupal vulnerability SA-CORE-2018-002, aka drupalgeddon2

Drupalgeddon2 timeline, exploitation within 5 hours

Just before the patch is applied

As proofed with drupalgeddon2, timeconstraints can be so tight, that you have been compromised before you have been able to read into the vulnerability, test the patch and patch the systems.

How often do I miss sleep over patches?

According to CVE Details, over 106 times for just Joomla!. Exploit-db has indexed over 1366 vulnerable Joomla! components, with 25 newly discovered vulnerabilities just this month.

exploit-db on Joomla! components

Logs to the rescue… or not?

Tail access log

Lets look for exploitation attempts in the access logs, and answer the question: have we been compromised? Here, we see a POST request to “/”. However, the POST body of this request is not logged. To get this level of detail, we need to capture the raw HTTP request.

HTTP request logging

Challenges with searching in raw HTTP requests

HTTP requests have mulitple input sources.

Input can be in multipart-data, the querystring, JSON, XML or a binary protocol.

grep is a pain: Stack Overflow answer to finding a ID

lookup_id() {
    local id
    grep -e ^ID: -e '<msisdn>' service.log | awk '
    BEGIN { RS="ID: "; FS="\n" } 
        if ($2) { 
           sub(/.*<msisdn>*/, "", $2)
           sub(/<\/msisdn>.*/, "", $2)
           print $2 " " $1 
    }' > msisdn_to_id
    lookup=$(grep $id msisdn_to_id | awk '{ print $2 }')
    awk 'BEGIN { RS="ID: "; ORS "\n" } 
    $1 == '$lookup' && !match($2, /^Address/)  { 
        print "ID: " $0 
    }' service.log
    rm msisdn_to_id

lookup_id 12345678

Queries must take several encodings into account, such as urlendocing.


Understanding HTTP requests requires knowledge about the application.

GET /wp-includes/css/buttons.css 404

It might be bad, or might not be bad, depending on which application is running on the webserver.

Querying for a data leakage event is hard.

You are looking for both a SQL injection as well as a changed SQL query. The latter is just plain unavailable in the HTTP request, you need to trace the SQL query in the applicaiton.

Building the Audit Log: JSON

The JSON format is quite a convenient format, as it provides structure, and is queryable very nicely: tools like jq let you query JSON on your local machine, and Elastic lets you visualize and query all your log documents.

Mapping the Input parameters

  "input": {
    "cookie": {
      "__cfduid": "d2b3157b7efc71b28ec97d00dd66bd7331514973921",
      "continueCode": "vm",
      "io": "IxZBpFgjxkNxnlHtAAAT"
    "http": {
      "get": {
        "q": "invalid')) UNION SELECT NULL,email,password,id,NULL, ..."
    "uri": "/rest/product/search?q=invalid%27))%20UNION%20SELECT%2 ..."

Did you spot the attack in the input already? Let me tell you, it is in the q parameter in the GET request. Looks like we’re dealing with a A1 - SQL Injection Attack

Adding Context

  "context": {
    "ip": "",
    "http": {
      "version": "HTTP/1.1",
      "userAgent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64;) Gecko...",
      "referer": "",
      "acceptMedia": "application/json, text/plain, /",
      "acceptEncoding": "gzip, deflate",
      "acceptLanguage": "en-US,en;q=0.5",
      "https": "false"

We want to know where the attack is coming from, so we are able to block further requests. The context is normalized, so we can just take the ip field. It also tells us about the browser, in the http.userAgent field. Maybe, they should be blocked in combination so other visitors from this IP are unaffected.

Adding Endpoint

  "endpoint": {
    "address": "",
    "name": "",
    "port": "80",
    "uri": "/rest/product/search?q=invalid%27))%20UNION%20SELECT% ...",
    "http": { 
      "code": "304", 
      "type": "GET"
    "php": { 
      "version": "7.1" 
    "host": { "name": "" },
    "localtime": "2018-04-16T13:59:50.904+0000"

The request went to Good to know, because this is a sensitive webshop that has access to user information.

Adding Traces

  "errors": [
      "code": 0,
      "description": "Executing (default): SELECT * FROM Products ...",
      "location": "/juice-shop/vendor/sequelize/lib/dialects/query.php",
      "line": 42,
      "type": "log",
      "generatedby": "PLUGIN",
      "hash": "-3619717855222641092",
      "context": [...]

The main question: was data leaked? The ORM loggs all queries in this application. Lets analyze the query in errors.description:

SELECT * FROM Products WHERE ((name LIKE '%invalid')) UNION SELECT NULL,email,password,id,NULL,NULL,NULL,NULL FROM USERS--%' OR description LIKE '%invalid')) UNION SELECT NULL,email,password,id,NULL,NULL,NULL,NULL FROM USERS--%') AND deletedAt IS NULL) ORDER BY name


Oops… A data leakage from the USERS table, where the email, password and id column have been compromised, due to a vulnerability in sequelize/lib/dialects/query.php.

Scoped Compromise

Even though a breach is bad news, we have been able to directly come to conlcusions.

Guaranteed no-compromise

This is a more interesting aspect to the audit log, as we have guarantees: our ADDRESSES table is not compromised. Yay ;)

Real-time grep for data leakages

We at BitSensor work hard on building technology on top of this audit log. We are introducing tools like grep for data leakages, parsing SQL queries, and hooking into security sensitive funtion calls. So you can rest assured, Slack will notify you what is going on - even before compromise.

Elastic BitSensor BLOCK Stack