Formatting Strings for Logging

Introduction

I’ve been working on a project, and I needed to add logging to the app. I wanted a log formatting function that can take a prefix and a format string (think a sprintf-type format string but safer). This function needs to be more than just an sprintf knockoff; it also needs to prefix the date and time to the message. Oh, the messages are passed in without a new line, so we need to add that too.

The Log Function

The log function needs to be smart so just wrapping vasprintf isn’t good enough.

char *str_log(const char *prefix, const char *fmt, ...)
{
    char    *msg        = NULL;
    char     myfmt[512];
    char    *myfmt_a    = NULL;
    char    *myfmt_ptr;
    size_t   myfmt_len;
    char     mytime[26];
    va_list  ap;
    time_t   now;
    int      ret;

    if (fmt == NULL)
        return NULL;

    if (prefix == NULL)
        prefix = "";

    now = time(NULL);
    memcpy(mytime, ctime(&now), sizeof(mytime));
    mytime[24] = '\0';

    myfmt_len = strlen(mytime) + 2 + strlen(prefix) + 2 + strlen(fmt) + 2;
    if (myfmt_len < sizeof(myfmt)) {
        myfmt_ptr = myfmt;
    } else {
        myfmt_a   = malloc(myfmt_len);
        myfmt_a[myfmt_len-1] = '\0';
        myfmt_ptr = myfmt_a;
    }
    snprintf(myfmt_ptr, myfmt_len, "%s %s%s%s%s%s\n", mytime,
             *prefix=='\0'?"":"\"", prefix, *prefix=='\0'?"":"\"",
             *prefix=='\0'?"":" ",
             fmt);

    va_start(ap, fmt);
    ret = vasprintf(&msg, myfmt_ptr, ap);
    if (myfmt_a != NULL)
        free(myfmt_a);
    va_end(ap);

    if (ret == -1)
        return NULL;
    return msg;
}

This log function meets all the requirements: time, prefix, format, arguments. It works by first creating a string with the time and prefix. Then it puts that plus the format passed into the function into a buffer. Finally, our new format string and the other arguments are passed into vasprintf, which handles putting the full message together. This implementation is optimized for a short format but can take one of any length.

Let’s break down how it works piece by piece.

if (fmt == NULL)
    return NULL;

No format means we don’t have anything to log.

if (prefix == NULL)
    prefix = "";

prefix will be used with functions like strlen and, as we know, strlen gets crash happy when it’s passed NULL. We could check if prefix is NULL before each time we use it, but that’s tedious. Let’s set it to "" so it’s always safe to use.

now = time(NULL);
memcpy(mytime, ctime(&now), sizeof(mytime));

Now we generate the time string using ctime. We have to use an intermediate time variable with ctime because it takes a pointer. It would be nice if we could pass the time in directly but alas, that’s not possible.

The buffer being used is 26 bytes because ctime will always return a 26-byte string: 24 bytes for the data, 1 byte for a trailing ‘\n’, and finally 1 bytes for the NULL terminator. If we can use ctime_r we should use it because it is thread-safe. It also saves us from needing to use memcpy. We’d end up with: ctime_r(&now, mytime); instead.

mytime[24] = '\0';

We don’t want the newline that ctime outputs because we want the time part of the entry to be on the same line as the rest of the message. The newline will always be at index 24, so kill it.

myfmt_len = strlen(mytime) + 2 + strlen(prefix) + 2 + strlen(fmt) + 2;

Now we determine the length of the format string with the time and prefix prepended. The fixed numbers (three 2s, totaling 6) are there for the prepend formatting. The +6 is needed to account for:

Space after time.
Quote before prefix
Quote after prefix
Space after prefix.
New line at end.
NULL terminator.

if (myfmt_len < sizeof(myfmt)) {
    myfmt_ptr = myfmt;
} else {
    myfmt_a   = malloc(myfmt_len);
    myfmt_a[myfmt_len-1] = '\0';
    myfmt_ptr = myfmt_a;
}

First, check if the format we’re building will fit into a stack buffer. This is a small optimization to prevent a malloc every time this function is called. If the new format is larger than the buffer, we need to malloc. myfmt_ptr is used to track which buffer is being used.

snprintf(myfmt_ptr, myfmt_len, "%s %s%s%s%s%s\n", mytime,
         *prefix=='\0'?"":"\"", prefix, *prefix=='\0'?"":"\"",
         *prefix=='\0'?"":" ",
         fmt);

Put together the new format, which is ’time “prefix” fmt’. If set, the prefix will have quotes around it. If empty, the quotes will be omitted.

va_start(ap, fmt);
ret = vasprintf(&msg, myfmt_ptr, ap);
if (myfmt_a != NULL)
    free(myfmt_a);
va_end(ap);

Since we can have all kinds of different length inputs we can’t use a fixed size static buffer. There is no possible way to know how much data will be logged. Instead, vasprintf is used because it will return (in an out parameter) an allocated string.

if (ret == -1)
    return NULL;
return msg;

All that’s left is for us to check whether the string was created successfully and return it so it can be passed on for logging. Be it to a file or something like syslog.

Testing

Lets write a simple test app and give this log function a try.

#include <stdarg.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <time.h>

int main(int argc, char **argv)
{
    char *l;

    l = str_log("abc", "123");
    printf("%s", l);
    free(l);

    l = str_log(NULL, "xyz");
    printf("%s", l);
    free(l);

    l = str_log("ALL", "%d: %d: %s", 4, -1, "message");
    printf("%s", l);
    free(l);

    return 0;
}

Mon Jan 21 19:52:23 2019 "abc" 123
Mon Jan 21 19:52:23 2019 xyz
Mon Jan 21 19:52:23 2019 "ALL" 4: -1: message

The output looks like what we’d expect to see.

Other Thoughts

This logging function takes a string prefix, which doesn’t make much sense when you’re using a format string because you could make the prefix part of the message. What makes more sense is to take an enum value of log levels and have the level as a string added to the message. All we’d need is an enum to string function and treat just like we do the prefix in this function.

Introduction#

The Log Function#

Testing#

Other Thoughts#

Introduction

The Log Function

Testing

Other Thoughts