Improving Print Logging With Line Pos Info and Modern C++

No matter how proficient you are, I think, you might still use one of the primary methods of debugging: trace values using printf, TRACE, outputDebugString, etc… and then scan the output while debugging.

Adding information about the line number and the file where the log message comes from is a very efficient method that might save you a lot of time. In this post, I’ll describe one trick that is especially useful in Visual Studio but might also help in other IDE/compilers.

I’ll also show you how modern C++ and C++20 make code nicer.

The Trick

When you’re debugging C++ code, it’s very convenient to output values to console or the output window and scan the log. As simple as:

std::cout << "my val: " << val << '\n';

You can easily enhance this technique by adding LINE and FILE information. That way, you’ll see the source of that message. This might be very handy when you scan lots of logs.

In Visual Studio, there’s a trick that allows you to move quickly from the debug output window to a particular line of code.

All you have to do is to use the following format:

"%s(%d): %s", file, line, message

For example:

myfile.cpp(32) : Hello World

You can now double-click on the line in VS output window, and immediately VS opens myfile at line 32. See below:

Why is it so important? In my case, I’ve lost a lot of time when I tried to look for the origin of some log output. When I see a message, I copy it, search the solution, and then usually after scrolling around, I finally get to the right line of code. You cannot beat this double-clicking approach, which is much more efficient!

Now that you know the proper format of the message, how do you use it in the code? Let’s go step by step.

We’ll implement this code with “standard” C++, then move to modern C++, and finally see what’s coming with C++20.

Standard C++ for Visual Studio and Windows

For VS, first of all, you need to output the message using OutputDebugString (Win specific function):

    OutputDebugString("myfile.cpp(32) : super");

Secondly, it’s better to wrap the above function with a trace/log macro:

#define MY_TRACE(msg, ...) \
    MyTrace(__LINE__, __FILE__, msg, __VA_ARGS__)

You can use it in the following way:

MY_TRACE("hello world %d", myVar);

The above code calls the MyTrace function that internally calls OutputDebugString.

Why a macro? It’s for convenience. Otherwise, we would have to pass the line number and the filename manually. File and Line cannot be fetched inside MyTrace because it would always point to the source code where MyTrace is implemented — not the code that calls it.

What are __FILE__ and __LINE__? In Visual Studio (see msdn), those are predefined macros that can be used in your code. As the name suggests, they expand into the filename of the source code and the exact line in a given translation unit. To control the __FILE__ macro, you can use the compiler option /FC. The option makes filenames longer (full path), or shorter (relative to the solution dir). Please note that /FC is implied when using Edit and Continue.

Please note that __FILE__ and __LINE__ are also specified by the standard, so other compilers should also implement it. See in 19.8 Predefined macro names.

Same goes for __VA_ARGS__: see 19.3 Macro replacement - cpp.replace

And here’s the implementation of MyTrace:

void MyTrace(int line, const char *fileName, const char *msg, ...)
{
    va_list args;
    char buffer[256] = { 0 };
    sprintf_s(buffer, "%s(%d) : ", fileName, line);
    OutputDebugString(buffer);

    // retrieve the variable arguments
    va_start(args, msg);
    vsprintf_s(buffer, msg, args);
    OutputDebugString(buffer);
    va_end(args);
}

But macros are not nice… we have also those C-style va_start methods… can we use something else instead?

Let’s see what how can we use modern C++ here

Variadic Templates to the Rescue!

MyTrace supports a variable number of arguments… but we’re using va_start/va_end technique, which scans the arguments at runtime… but how about compile time?

In C++17, we can leverage fold expression and use the following code:

#define MY_TRACE_TMP(...) MyTraceImplTmp(__LINE__, __FILE__, __VA_ARGS__)

template <typename ...Args>
void MyTraceImplTmp(int line, const char* fileName, Args&& ...args)
{
    std::ostringstream stream;
    stream << fileName << "(" << line << ") : ";
    (stream << ... << std::forward<Args>(args)) << '\n';

    OutputDebugString(stream.str().c_str());
}

// use like:
MY_TRACE_TMP("hello world! ", 10, ", ", 42);

The above code takes a variable number of arguments and uses ostringstream to build a single string. Then the string goes to OutputDebugString.

This is only a basic implementation, and maybe not perfect. If you want you can experiment with the logging style and arrive with a fully compile-time approach.

There are also other libs that could help here: for example {fmt} or pprint - by J. Galowicz.

C++20 and No Macros?

During the last ISO meeting, the committee accepted std::source_location, which is a part of library fundamentals TS v2.

C++ Extensions for Library Fundamentals, Version 2 - 14.1 Class source_location

This new library type is declared as follows:

struct source_location {
    static constexpr source_location current() noexcept;
    constexpr source_location() noexcept;
    constexpr uint_least32_t line() const noexcept;
    constexpr uint_least32_t column() const noexcept;
    constexpr const char* file_name() const noexcept;
    constexpr const char* function_name() const noexcept;
  };

And here’s a basic example, adapted from cppreference/source_location:

#include <iostream>
#include <string_view>
#include <experimental/source_location>

using namespace std;
using namespace std::experimental; 

void log(const string_view& message, 
      const source_location& location = source_location::current())
{
    std::cout << "info:"
              << location.file_name() << ":"
              << location.line() << " "
              << location.function_name() << " "
              << message << '\n';         
}

int main()
{
    log("Hello world!");

    // another log
    log("super extra!");
}

We can rewrite or log example into:

template <typename ...Args>
void TraceLoc(const source_location& location, Args&& ...args)
{
    std::ostringstream stream;
    stream << location.file_name() << "(" << location.line() << ") : ";
    (stream << ... << std::forward<Args>(args)) << '\n';

    std::cout << stream.str();
}

Play with the code @Coliru
(source_location is not available in VS, so that’s why I used GCC)

Now, rather than using __FILE__ and __LINE__ we have a Standard Library object that wraps all the useful information.

Unfortunately, we cannot move that source location argument after variadic args… so, we still have to use macros to hide it.

Do you know how to fix it? so we can use a default argument at the end?

Ideally:

template <typename ...Args>
void TraceLoc(Args&& ...args, 
              const source_location& location = source_location::current())
{
   // ...
}

But I leave that as an open question.

Summary

In this article, I showed a useful technique that might enhance simple printf-style debugging and logging.

Initially, we took "standard" code that is mostly C-style, and then, we tried to update it with modern C++. The first thing was to use variadic template arguments. That way we can scan the input params at compile time, rather than use va_start/va_end C runtime functions. The next step was to look at the future implementation of source_location a new type that will come in C++20.

With source_location, we could skip using __FILE__ and __LINE__ predefined macros, but still, the logging macro (#define LOG(...)) is helpful as it can hide a default parameter with the location info.

Check out the code from the article on GitHub.

How about your compiler/IDE? Do you use such line/pos functionality as well? Maybe your logging library already contains such improvements?

Let us know in the comments below.