vsnprintf with %s segfaults with GCC

Question

I use the following methods to write to a trace file (inspired by https://stackoverflow.com/a/16046064/283561)

void Tracing::Info( const char*  content, ...)
{
    va_list paramList;
    va_start( paramList, content );

    Tracing::AddRecord(boost::log::trivial::info, content, paramList);
    va_end( paramList );
}

void Tracing::AddRecord(boost::log::trivial::severity_level sev, const char* content, va_list paramList)
{       
    int size = vsnprintf(0, 0, content, paramList) + 1;
    if (size > 0)
    {
        boost::scoped_array<char> formattedString(new char[size]);
        vsnprintf(formattedString.get(), size, content, paramList);

        boost::log::sources::severity_logger_mt<boost::log::trivial::severity_level> & lg = my_logger::get();

        BOOST_LOG_SEV(lg, sev) << formattedString.get();
    }
}

If I call the method the following way under Linux (CentOS 7, GCC 4.8.2):

Tracing trace;
trace.Error("No %s root tag found!", rootTag.c_str());

it segfaults at the second call of vsnprintf in AddRecord().

If it's called with a numeric formatter (e.g. %i), it works fine. I've used these methods for years under Windows (VS2008/2010) with no problems.

Am I missing something obvious here?

You call `trace.Error()` but you show `Tracing::Info()`, which is confusing. — trojanfoe, Mar 31 '15 at 13:37
@AntonSavin That would be better (and remove `+ 1` when assigning `size`). As it stands the `if (size > 0)` is always true even for an empty message. — trojanfoe, Mar 31 '15 at 13:48
@trojanfoe trace is the actual object of the class Tracing. I clarified the question — Simon, Mar 31 '15 at 13:50

Anya Shenanigans · Accepted Answer · 2015-03-31T14:08:34.330

You can't reuse the va_list like that; you have to use the va_copy() routine to make a new va_list entity, and use that on the second vsprintf; something like:

void Tracing::AddRecord(boost::log::trivial::severity_level sev, const char* content, va_list paramList)
{
    va_list parm_copy;
    va_copy(parm_copy, paramList);
    int size = vsnprintf(0, 0, content, paramList) + 1;
    if (size > 0)
    {
        boost::scoped_array<char> formattedString(new char[size]);
        vsnprintf(formattedString.get(), size, content, parm_copy);

        boost::log::sources::severity_logger_mt<boost::log::trivial::severity_level> & lg = my_logger::get();

        BOOST_LOG_SEV(lg, sev) << formattedString.get();
    }
    va_end(parm_copy);
}

The problem is that the operation va_arg, which is used in the first vsnprintf alters the state of the va_list, making it invalid for use in the second vsnprintf as-is.

The problem can be easily seen by using a small C program.

#include <stdio.h>
#include <stdarg.h>

void
do_log(const char *item, va_list items)
{
#ifndef EVIL
    va_list itemcopy;
    va_copy(itemcopy, items);
#else
#define itemcopy items
#endif
    int len = vsnprintf(0, 0, item, items);
    if (len > 0) {
        char buffer[2048];
        vsnprintf(buffer, 2047, item, itemcopy);
        printf("%s\n", buffer);
    }
    va_end(itemcopy);
}

int
log_print(const char *item, ...)
{
    va_list items;
    va_start(items, item);
    do_log(item, items);
    va_end(items);
    return 0;
}

int
main(int argc, char **argv)
{
    log_print("These %d %d %d %d", 1, 2, 3, 4);
    log_print("Hello %s %s", "Mike", argv[0]);
}

Without -DEVIL, I get:

These 1 2 3 4
Hello Mike ./vargs

if we make with CFLAGS=-DEVIL, I get output (on OSX):

These 4 0 0 1570641464
Hello

On other platforms, it can crash.

Fixed my problem. Not sure, why it works with numeric formatters. — Simon, Mar 31 '15 at 14:04
The reason it 'kind of' works for numeric formatters is because they're not trying to dereference a pointer - as you can see from my sample code, when run on OSX, yields garbage output. It's the very definition of undefined behaviour. I corrected the error in the answer as well. — Anya Shenanigans, Mar 31 '15 at 14:10

vsnprintf with %s segfaults with GCC

1 Answers1