Bug Hunting with CodeQL, an Rsyslog Case Study

Introduction

Large and unknown codebases can be daunting to approach, especially if there are time constraints that need to be respected. For this reason, thinking in broad terms and elaborating a well-scoped action plan is fundamental to the success of a code review task. As auditors, we need to focus on a particular set of programming issues, that is, those which have some kind of security impact. By thinking about this fact we can reduce and focus the scope of our search even further.

By definition, a security issue is a programming construct that, when influenced, directly or indirectly, by an attacker, leads the target program into an inconsistent state. With this in mind, we need to find places in which we, as an attacker, can influence the behavior of the software. Knowing the nature of rsyslog we understand that it somehow needs to read messages from a source in order to process them and then store them somewhere.

This rather fuzzy idea of the general architecture of rsyslog will be the starting point for our exploration of the inner workings of our target. To shed some light and discover more details about our target, we will use CodeQL to explore the codebase and extract some facts about how it operates.

Threat modeling

With a general idea of how the software works, we now need to define a threat model, that is, from the perspective of an attacker, what are the attack avenues that are relevant to our task?

In the case of rsyslog, defining the threat model is rather simple due to the uncomplicated nature of the software. We will conduct our source code review assuming that an attacker is able to generate log messages that will be processed by rsyslog. As we will see later in this post, there are several situations in which this is possible, ranging from network exposed ports to local UNIX sockets in the system. This model will be the guide we will use to explore attack opportunities that will ultimately lead to the discovery of three vulnerabilities.

Discovering program input

Program inputs are a way in which we can influence the behavior of the target software. Enumerating them is one of the most important steps in the code review process. It helps to have some knowledge of what the software does, so reading some documentation will certainly lead to more accurate results.

Since we know rsyslog needs a way to read data from somewhere, we can use a heuristic CodeQL query that gives us a slight idea of what is being read by the software. Simply put, we need to ask CodeQL “what functions call read-like system calls?”. The following query does exactly that.

import cpp

class ReadFunctionCall extends FunctionCall {
    ReadFunctionCall() {
        this.getTarget().getName() = "pread" or
        this.getTarget().getName() = "read" or
        this.getTarget().getName() = "readv" or
        this.getTarget().getName() = "recvfrom" or
        this.getTarget().getName() = "recvmsg" or
        this.getTarget().getName() = "recv"
    }
}

from ReadFunctionCall call
select call.getFile(), call.getEnclosingFunction(), call

Running the query gives us about 35 results which is a manageable number of entries to go through, looking at them one by one.

From these results we can infer some facts about the code. Apparently there is a plugin architecture that allows data to be read from diverse input sources. A quick look at the files will validate our intuitions about what each one of the modules does.

Message processing

From the previous list, we can pick one module to investigate and see what we can find. I personally like to pick things that look simple, so I chose UDP since it is a simple protocol. Also, my experience tells me that the way in which they read messages from diverse sources will create some common data structure shared among all the modules, so understanding one means we probably will get a feeling of how the rest works.

Going back to the query results list we can see that there is a function called processSocket inside the UDP input module (imudp.c), which calls recvmsg, let’s explore it a bit further:

static rsRetVal
processSocket(struct wrkrInfo_s *pWrkr, struct lstn_s *lstn, struct sockaddr_storage *frominetPrev, int *pbIsPermitted)
{
    ssize_t lenRcvBuf;
    multi_submit_t multiSub;
    smsg_t *pMsgs[CONF_NUM_MULTISUB];
    struct msghdr mh;
    struct iovec iov[1];

    multiSub.ppMsgs = pMsgs;
    multiSub.maxElem = CONF_NUM_MULTISUB;
    multiSub.nElem = 0;

    while(1) {
        memset(iov, 0, sizeof(iov));
        iov[0].iov_base = pWrkr->pRcvBuf;
        iov[0].iov_len = iMaxLine;

        memset(&mh, 0, sizeof(mh));
        mh.msg_name = &frominet;
        mh.msg_namelen = sizeof(struct sockaddr_storage);
        mh.msg_iov = iov;
        mh.msg_iovlen = 1;

        lenRcvBuf = recvmsg(lstn->sock, &mh, 0);

        if(lenRcvBuf < 0) {
            if(errno != EINTR && errno != EAGAIN) {
                rs_strerror_r(errno, errStr, sizeof(errStr));
                DBGPRINTF("INET socket error: %d = %s.\n", errno, errStr);
                LogError(errno, NO_ERRCODE, "imudp: error receiving on socket: %s", errStr);
            }

            ABORT_FINALIZE(RS_RET_ERR);
        }

        processPacket(lstn, frominetPrev, pbIsPermitted, pWrkr->pRcvBuf, lenRcvBuf, &stTime, ttGenTime, &frominet, mh.msg_namelen, &multiSub);
    }


finalize_it:
    multiSubmitFlush(&multiSub);
    RETiRet;
}

This function simply reads a single UDP message from a socket called lstn->sock. Then it passes the read bytes placed in pWrkr->pRcvBuf to the function named processPacket. What kind of processing does this function do over the read bytes? Let’s explore some of its code.

static rsRetVal
processPacket(struct lstn_s *lstn, struct sockaddr_storage *frominetPrev, int *pbIsPermitted, uchar *rcvBuf, ssize_t lenRcvBuf, struct syslogTime *stTime, time_t ttGenTime, struct sockaddr_storage *frominet, socklen_t socklen, multi_submit_t *multiSub)
{
    smsg_t *pMsg = NULL;
    
    if(bDoACLCheck) {
        // REMOVED: Access control lists checks ...
    } else {
        *pbIsPermitted = 1; /* no check -> everything permitted */
    }

    if(*pbIsPermitted != 0)  {
        CHKiRet(msgConstructWithTime(&pMsg, stTime, ttGenTime));
        
        MsgSetRawMsg(pMsg, (char*)rcvBuf, lenRcvBuf);
        pMsg->msgFlags  = NEEDS_PARSING | PARSE_HOSTNAME | NEEDS_DNSRESOL;
        
        CHKiRet(ratelimitAddMsg(lstn->ratelimiter, multiSub, pMsg));
        STATSCOUNTER_INC(lstn->ctrSubmit, lstn->mutCtrSubmit);
    }

finalize_it:
    if(iRet != RS_RET_OK) {
        if(pMsg != NULL && iRet != RS_RET_DISCARDMSG) {
            msgDestruct(&pMsg);
        }
    }

    RETiRet;
}

As can be seen in the code, this function’s main task is to do access control checks. That is, verifying certain properties of the origin of the packet, and then, if the packet is permitted, creating an smsg_t object to be enqueued into the processing queue. It also checks if the message should be rate limited in order to avoid issues like denial of service or simply too many logs.

Now that we know that all read messages are put into a queue, we can take a look at who uses said messages, but first, it makes sense to understand the smsg_t type. In the code snippet above, we can see that there are only two functions that work with the pMsg object, one called msgConstructWithTime and the other MsgSetRawMsg. From the names we can infer what they do, the first is basically a constructor that initializes some fields and the second is a way to set the contents of the raw message. Since we are interested in things we can influence, we will take a deeper look at the last function:

void MsgSetRawMsg(smsg_t *const pThis, const char *const pszRawMsg, const size_t lenMsg)
{
    if (pThis->pszRawMsg != pThis->szRawMsg)
        free(pThis->pszRawMsg);

    deltaSize = (int)lenMsg - pThis->iLenRawMsg; /* value < 0 in truncation case! */
    pThis->iLenRawMsg = lenMsg;
    if (pThis->iLenRawMsg < CONF_RAWMSG_BUFSIZE)
    {
        /* small enough: use fixed buffer (faster!) */
        pThis->pszRawMsg = pThis->szRawMsg;
    }
    else if ((pThis->pszRawMsg = (uchar *)malloc(pThis->iLenRawMsg + 1)) == NULL)
    {
        /* truncate message, better than completely loosing it... */
        pThis->pszRawMsg = pThis->szRawMsg;
        pThis->iLenRawMsg = CONF_RAWMSG_BUFSIZE - 1;
    }

    memcpy(pThis->pszRawMsg, pszRawMsg, pThis->iLenRawMsg);
    pThis->pszRawMsg[pThis->iLenRawMsg] = '\0'; /* this also works with truncation! */
    
    /* correct other information */
    if (pThis->iLenRawMsg > pThis->offMSG)
        pThis->iLenMSG += deltaSize;
    else
        pThis->iLenMSG = 0;
}

From that code we can extract some interesting information:

• The field pszRawMsg is a pointer to a buffer where user-controlled data is stored.
• If a message is small enough it will go to a fixed buffer located inside the msg structure.
• If it is not small, then a heap buffer is allocated.
• The data is copied to said buffer.
• The field iLenMSG contains the size of the raw data received.

Data flow exploration

Having gained this knowledge, we can already start to think about interesting things like where does attacker-influenced data flow? To get some answers, let’s craft a simple CodeQL query and see where the results take us.

One of the most helpful abstractions in QL is the creation of custom classes. These classes group certain results that share common properties defined by us. These classes can later be used in other queries and they greatly simplify more involved queries. In the following query we have defined two of such classes, one named RawMessageFieldAccess which groups all field accesses to fields named pszRawMsg, and RawMsgAccessFunction which groups all the functions that contain at least one RawMessageFieldAccess inside their body.

import cpp

class RawMessageFieldAccess extends FieldAccess {
    RawMessageFieldAccess() {
        this.getTarget().getName() = "pszRawMsg"
    }
}

class RawMsgAccessFunction extends Function {
    RawMsgAccessFunction() {
        any(RawMessageFieldAccess access).getEnclosingFunction() = this
    }
}

from RawMsgAccessFunction access
select access.getFile(), access

With this query we get about 29 results so we know that there are 29 potential places where we can influence the behavior of the software! Let’s take a look at them and see how we can refine those results. For instance, there are two functions that look like they return a pointer into the data, they are named getMSG and getRawMsg respectively. What if we extend our original query to return the functions that call these.

import cpp

class RawMessageFieldAccess extends FieldAccess {
    RawMessageFieldAccess() {
        this.getTarget().getName() = "pszRawMsg"
    }
}

class RawMsgAccessFunction extends Function {
    RawMsgAccessFunction() {
        any(RawMessageFieldAccess access).getEnclosingFunction() = this
        or
        exists(
            FunctionCall call |
            call.getEnclosingFunction() = this and (
                call.getTarget().getName() = "getMSG" or
                call.getTarget().getName() = "getRawMsg"
            )
        )
    }
}

from RawMsgAccessFunction access
select access.getFile(), access

With this extended query we now get 20 more results! With CodeQL it is important to explore the results in an iterative way in order to refine / expand queries.

Going back to the results of the last query we can get an overview of how the data is processed by different functions:

From this list we can appreciate that there are some functions that seem to be part of the main program and other are plugins to parse specific log formats. We can also see that there seems to be some kind of compressed log format. Let’s check the uncompressMessage function and see if it is implemented correctly.

static rsRetVal uncompressMessage(smsg_t *pMsg)
{
    pszMsg = pMsg->pszRawMsg;
    lenMsg = pMsg->iLenRawMsg;

    if(lenMsg > 0 && *pszMsg == 'z') {
        int ret;
        iLenDefBuf = glbl.GetMaxLine();
        CHKmalloc(deflateBuf = malloc(iLenDefBuf + 1));
        ret = uncompress((uchar *) deflateBuf, &iLenDefBuf, (uchar *) pszMsg+1, lenMsg-1);

        if(ret != Z_OK) {
            FINALIZE;
        }
        MsgSetRawMsg(pMsg, (char*)deflateBuf, iLenDefBuf);
    }
    
finalize_it:
    if(deflateBuf != NULL)
        free(deflateBuf);

    RETiRet;
}

As can be seen from the snippet, a non-empty log message starting with the letter z will make rsyslog try to decompress the whole message. This routine uncompress is part of the zlib package, which has a history of vulnerabilities. So we have found an extended attack surface, where zlib is exposed in such a trivial way that an attacker could potentially compromise the system, if they have a working exploit for zlib. Fortunately, in this case, the function seems to be implemented correctly, so let’s move on to the other results.

The next result that catches my attention is the function ParseMsg, from its path it looks like it is part of the runtime of the software so it will probably be high up in the hierarchy of processing. Taking a quick look at it, we can verify that it simply acts as a dispatcher for parsing routines named parse / parse2 that are implemented in plugins. So let’s focus on these functions that historically are the most difficult to implement correctly. Again, a simple CodeQL query will give us the places we want to look at:

import cpp

class ParseFunction extends Function {
    ParseFunction() {
        this.getName() = "parse" or
        this.getName() = "parse2"
    }
}

from ParseFunction parse
select parse.getFile(), parse

Finding bugs

Now that we have some results that are limited in scope, we can start to do some code reading to see if we can find some bugs. The results we got using CodeQL are an excellent way to stay on the right path and get a sense of the area we have covered. Keeping the focus and direction of the audit effort is crucial to the success of our task.

Source code reading is a great way to understand more about your target and the more you know about it, the more ideas you get about how it can be broken. This concept is why I think CodeQL is an excellent tool for auditors, it lets us model our ideas and convert them into queries. In the following section we will see this concept in action.

Heap memory corruption in pmaixforwardedfrom.c

This module is in charge of adapting the AIX system log messages to a format that can subsequently be parsed by other, maybe more standard, log parsers. As with anything that needs to convert from one format to another, there will be some kind of parsing and memory juggling.

The format of an AIX message is:

<PRIORITY>[TIMESTAMP] [PREFIX] [HOSTNAME]:[MESSAGE]

And an example AIX log messages looks like this:

<46>Dec 11 03:41:12 Message forwarded from hostname:syslogd: restart

Now, with a clear idea of what messages look like, let’s dig into the code and see what we find.

Note: I’ve formatted the original code to fit the blogpost and I’ve also annotated it to make it easier to follow. All my annotations start with a C++ style comment with the following format // #n: comment

#define OpeningText "Message forwarded from "
#define OpeningText2 "From "

BEGINparse
    uchar *p2parse;
    int lenMsg;
    int skipLen = 0;
CODESTARTparse
    // #1: Skip the PRIORITY.
    lenMsg = pMsg->iLenRawMsg - pMsg->offAfterPRI;
    p2parse = pMsg->pszRawMsg + pMsg->offAfterPRI;
    
    // #2: Skip any whitespaces.
    while(lenMsg && *p2parse == ' ') {
        --lenMsg;
        ++p2parse;
    }

    if((unsigned) lenMsg < 24) {
        ABORT_FINALIZE(RS_RET_COULD_NOT_PARSE);
    }

    // #3: Skip the TIMESTAMP.
    lenMsg -= 16;
    p2parse += 16;

    if(!strncasecmp((char*) p2parse, OpeningText, sizeof(OpeningText)-1))
        skipLen = 23;

    if(!strncasecmp((char*) p2parse, OpeningText2, sizeof(OpeningText2)-1))
        skipLen = 5;

    if(!skipLen) {
        ABORT_FINALIZE(RS_RET_COULD_NOT_PARSE);
    }
    
    // #4: Skip PREFIX.
    lenMsg -=skipLen;
    memmove(p2parse, p2parse + skipLen, lenMsg);
    *(p2parse + lenMsg) = '\n';
    *(p2parse + lenMsg + 1)  = '\0';
    pMsg->iLenRawMsg -= skipLen;
    pMsg->iLenMSG -= skipLen;
    
    // #5: Look for a ':' or a ' ' inside the remaining log message.
    while(lenMsg && *p2parse != ' ' && *p2parse != ':') {
        --lenMsg;
        ++p2parse;
    }
    
    // #6: Check if we have found a ':' _and_ if the length of the message is not zero.
    if (lenMsg && *p2parse != ':') {
        DBGPRINTF("not a AIX message forwarded from mangled log but similar enough that the preamble has been removed\n");
        ABORT_FINALIZE(RS_RET_COULD_NOT_PARSE);
    }
    
    // #7: Decrement the lenght of the message.
    lenMsg -=1;
    
    // #8: Shift the whole message by one byte.
    memmove(p2parse, p2parse + 1, lenMsg);
    
    *(p2parse + lenMsg) = '\n';
    *(p2parse + lenMsg + 1)  = '\0';
    pMsg->iLenRawMsg -=1;
    pMsg->iLenMSG -=1;
finalize_it:
ENDparse

In broad terms this parser tries to validate and remove superfluous information in an AIX log message. To do so, the parser tries to locate a log message delimiter (#5), in this case a space or a colon, but fails to account for strings that do not satisfy such constraints. If the string does not match, then the variable lenMsg will reach the value zero and will skip the sanity check (#6) that detects invalid log messages. The message will then be considered valid, and the parser will eat up the non-existent colon delimiter. Doing so, it will decrement lenMsg, a signed integer, whose value was zero and now becomes minus one. The following step in the parser is to shift the contents of the message to the left. It does this by calling memmove with appropriate pointers to the target and destination strings, but the lenMsg will now be interpreted as a huge value, causing a heap overflow.

This vulnerability has been assigned CVE-2019-17041 and was patched in the following pull request https://github.com/rsyslog/rsyslog/pull/3884/files by adding additional sanity checks.

Heap memory corruption in pmcisconames.c

Now that we have our first vulnerability, we have two options, one is to go to the next result in our CodeQL results list and the other is to model this vulnerability in CodeQL and make the engine do our job for us. Let’s explore the latter option and see if we can find any variants of this bug.

First, we need to abstract our vulnerability in order to encode it into a query. As with most things in programming, it helps to break down the problem into bite-sized chunks so let’s enumerate what we need to do:

• Locate all places where pszRawMsg is used.
• Check if one of those places is a loop condition.

Simple enough, right? This sounds like a simple task for grep, but as you think about this issue you’ll realize that there are some corner cases where pattern matching is not suited for the task. For instance, what happens if the pointer pszRawMsg is copied into another variable and then it is used in the while expression condition? Moreover, what if there is intra-procedural data flow? The answer is that, depending on our approach, we may miss true positives. This is a hard problem to solve but fortunately the TaintTracking module does just that for us!

The following query will use local taint tracking. That is, it performs taint tracking limited to the body of a single function, to find all accesses to the field pszRawMsg, and then it will flag all the cases in which a loop condition expression depends on the data of this field.

The TaintTracking module requires us to declare a source and a sink to let the engine know that there must be a link between them by using TaintTracking::localTaint. The next step is to limit the source to be a RawMessageFieldAccess and specify that the sink must be any of the children in the loop condition (that’s why we use * in the getAChild*() call).

import cpp
import semmle.code.cpp.dataflow.DataFlow
import semmle.code.cpp.dataflow.TaintTracking

class RawMessageFieldAccess extends FieldAccess {
    RawMessageFieldAccess() {
        this.getTarget().getName() = "pszRawMsg"
    }
}

from
    DataFlow::Node source, DataFlow::Node sink, RawMessageFieldAccess access, WhileStmt loop
where
    TaintTracking::localTaint(source, sink) and
    source.asExpr() = access and
    sink.asExpr() = loop.getCondition().getAChild*()
select
    "Loop iterates data from:", source, sink

This query gives us about 75 results, and if we focus on the result shown below, we can see that indeed there is a variant of the same bug:

/* now look for the next space to walk past the hostname */
while(lenMsg && *p2parse != ' ') {
    --lenMsg;
    ++p2parse;
}

/* skip the space after the hostname */
lenMsg -=1;
p2parse +=1;

/* if the syslog tag is : and the next thing starts with a % assume that this is a mangled cisco log and fix it */
if(strncasecmp((char*) p2parse, OpeningText, sizeof(OpeningText)-1) != 0) {
    /* wrong opening text */
    DBGPRINTF("not a cisco name mangled log!\n");
        ABORT_FINALIZE(RS_RET_COULD_NOT_PARSE);
}

/* bump the message portion up by two characters to overwrite the extra : */
lenMsg -=2;
memmove(p2parse, p2parse + 2, lenMsg); // b. Heap corruption happens here.
*(p2parse + lenMsg) = '\n';
*(p2parse + lenMsg + 1)  = '\0';
pMsg->iLenRawMsg -=2;
pMsg->iLenMSG -=2;

The conditions are almost the same as with the first bug. This time, in order to corrupt memory, the attacker has to put the heap state of the target process into a state that allows them to bypass the strncasecmp function that stops the overflow from happening. Setting up the heap state in rsyslog is trivial, given the nature of the logging messages (raw packets read from the network and copied on the heap).

This vulnerability has been assigned CVE-2019-17042 and was patched in the following pull request https://github.com/rsyslog/rsyslog/pull/3883 by adding additional sanity checks.

Out of bounds read access in pmdb2diag.c

Once I had exhausted the “variant” results we got from the last query, I decided to keep auditing manually and see what else I could get. I kept my focus on the different parsing modules and finally I reached the DB2 log message format parser. The purpose of this module is similar to the AIX one, to get the data out of a specific log message and discard what’s not considered useful.

Since rsyslog is designed to be blazing fast, the code sometimes tries to do things in a way that improves performance. This fact usually leads to code that is slightly more complex, but at the machine level it employs fewer computing cycles. A direct consequence of increased code complexity is an increased risk of producing incorrect, or partially correct code, such as the mistake we will explain in the following paragraphs.

The parser starts by checking that there are at least 4 bytes after the priority tag (#1). If there is enough space, the parser advances the buffer up to the position where the log level / severity tag is supposed to be present. To reduce the number of memory accesses required to check the severity of the log message, the author of the module takes advantage of the fact that each log “severity” tag starts with a unique letter. By reading only the first byte, they know that the parser should skip a fixed number of bytes to reach the next state of the parser. The sizes it can skip range from 4 to 8 bytes depending on the severity of the message. This fact invalidates the check at #1, since now the parser can skip at most 8 bytes thus potentially parsing strings from outside the defined buffer at #4.

BEGINparse2
    struct tm tm;
    char *ms, *timepos, *pid, *prog, *eprog, *backslash, *end, *lvl;
    int lprog, lpid, lvl_len;
    char buffer[128];
CODESTARTparse2
    // #1: This will check that we have at least 4 bytes of log level info.
    if(pMsg->iLenRawMsg - (int)pMsg->offAfterPRI < pInst->levelpos+4)
        ABORT_FINALIZE(RS_RET_COULD_NOT_PARSE);
    
    // #2: Skip the message and go directly to the log level string.	
    lvl = (char*)(pMsg->pszRawMsg + pMsg->offAfterPRI + pInst->levelpos);
    
    // #3: Here depending on the start letter of the log level, it will get the lvl_len for the log level string.
    // It assumes there is enough space in the message, but this is wrong, we only checked for 4 extra bytes at (a)
    switch (*lvl) {
    case 'C': /* Critical */
        pMsg->iSeverity = LOG_EMERG;
        lvl_len = 8;
        break;
    case 'A': /* Alert */
        pMsg->iSeverity = LOG_ALERT;
        lvl_len = 5;
        break;
    case 'S': /* Severe */
        pMsg->iSeverity = LOG_CRIT;
        lvl_len = 6;
        break;
    case 'E': /* Error / Event */
        pMsg->iSeverity = (lvl[1] == 'r') ? LOG_ERR : LOG_NOTICE;
        lvl_len = 5;
        break;
    case 'W': /* Warning */
        pMsg->iSeverity = LOG_WARNING;
        lvl_len = 7;
        break;
    case 'I': /* Info */
        pMsg->iSeverity = LOG_INFO;
        lvl_len = 4;
        break;
    case 'D': /* Debug */
        pMsg->iSeverity = LOG_DEBUG;
        lvl_len = 5;
        break;
    default:
        /* perhaps the message does not contain a proper level if so don't parse the log */
        ABORT_FINALIZE(0);
    }	

    // NOTE: Removed for brevity ...

    // #4: Here we will access memory outside our heap 
    // buffer since lvl_len can be 4 bytes off.
    pid = strchr((char*)pMsg->pszRawMsg + pInst->levelpos + lvl_len, ':');

This vulnerability has been assigned CVE-2019-17040 and was patched in the following pull request https://github.com/rsyslog/rsyslog/pull/3875 by adding additional sanity checks.

Vulnerability disclosure timeline

All the bugs were reported together and they were addressed as a whole by the vendor as detailed in the following timeline:

• September, 20th 2019 - Vendor gets a report of the issues.
• September, 20th 2019 - Vendor agrees to review findings.
• September, 30th 2019 - Vendor acknowledges and fixes the bugs.
• October, 1st 2019 - Vendor releases fixed version.