My New Logging System for C++

I’ve been experimenting lately with better ways to get good logging under C++.

This is what I wanted to achieve when I started my latest project:

• Stack trace, similar to what you get from C# and .NET in general
• Easy to use
• Work with HRESULT-s, and Windows’ GetLastError()

HRRESULTs are COM’s way of handling exceptions in an easy to marshal cross-process manner. They behave exactly as exceptions, most of the time – once you FAIL(hr), you usually return hr, this propagating the exception down the calling methods. Thus, if we recorded each FAIL(hr), would easily get a .NET-like stack trace.

.NET stack traces contain another useful feature (besides the calling stack itself): it tells you where you failed: method name and source code location. In C++, we have __FILE__, __LINE__, and the non-standard __FUNCSIG__.

Now, my projects at work are Windows-based, and, unfortunately, Microsoft implemented UNICODE way back when it was believed that all there is can be encoded in 16 bits. That is, all UNICODE text is UTF16LE encoded, and you have to use wchar_t-s and prefix your strings with L.

Since __FILE__ and __FUNCSIG__ are normal strings, we will need a few macro helpers to widen them:

#define WSTRIGIFY(x) L#x
#define WSTRINGIFY_STRING(x) L##x
#define WSTRINGIFY_MACRO(x) WSTRIGIFY(x)
#define WSTRINGIFY_STRING_MACRO(x) WSTRINGIFY_STRING(x)

#define __WFILE__ WSTRINGIFY_STRING_MACRO(__FILE__)
#define __WLINE__ WSTRINGIFY_MACRO(__LINE__)
#define __WFUNCSIG__ WSTRINGIFY_STRING_MACRO(__FUNCSIG__)

Remember, stringify-ing a macro is the process of getting the compiler expand macro arguments as string literals. Since we don’t want string arguments to be expanded as L"\"some value\"", we need the additional WSTRINGIFY_STRING/WSTRINGIFY_STRING_MACRO pair.

Now that we have the wide string versions of __FILE__, __LINE__, and __FUNCSIG__, we can combine them in a single literal (the C/C++ compiler combines adjacent string literals):

.. which would output something like:

d:\dev\mmkeys2\utilities.cpp(140): long __cdecl InitializeCommonControls(void)
  Expression "::InitCommonControlsEx(&cc)"

Notice that we copy the Visual Studio syntax of file.cpp(line): – if we print this to the Output window and double-click on the line, Visual Studio’s editor will jump right into utilities.cpp at line 140!

To take things one step further, it’d be nice to print out the failed HRESULT and the text representation of the message via FormatMessage:

#define LOG_HR(expr, hr) LogErorWithHresult(LOG_HR_LOCATION(expr,hr), hr)
#define ASSERT_HR_CODE(expr, code) { HRESULT hr = expr; if (FAILED(hr)) { LOG_HR(expr, hr); return code; } }
#define ASSERT_HR(expr) { HRESULT hr = expr; if (FAILED(hr)) {  LOG_HR(expr, hr); return hr; } }
#define ASSERT_WIN(expr) if (!(expr)) { HRESULT hr = HRESULT_FROM_WIN32(GetLastError()); LOG_HR(expr, hr); return hr; }
#define ASSERT(expr, code) if (!(expr)) { LOG_HR(expr, code); return code; }

void LogErorWithHresult(const wchar_t* location, long hresult);
void LogErrorMessage(const wchar_t* message);

Once we’ve defined LOG_HR_LOCATION, the rest is easy:

• ASSERT checks if an expression evaluates to false, and returns a custom error code
• ASSERT_WIN uses GetLastError as return code
• ASSERT_HR uses whatever expr evaluates to as return code
• ASSERT_HR_CODE is the same as above, but returns a custom error code

All macros assume that your methods have the standard COM signature: HRESULT SomeMethod(/*args...*/). As mentioned before, the whole call-stack idea rests on the assumption that you follow the COM error handling model – that is, you don’t use C++ exceptions.

void LogErorWithHresult(const wchar_t* location, long hresult)
{
  const size_t SYSTEM_MESSAGE_LEN = 100;
  const size_t FINAL_MESSAGE_LEN = 200;

  wchar_t systemMessage[SYSTEM_MESSAGE_LEN];

  DWORD len = ::FormatMessage(
    FORMAT_MESSAGE_FROM_SYSTEM
    | FORMAT_MESSAGE_IGNORE_INSERTS,
    nullptr, hresult, 0, systemMessage, SYSTEM_MESSAGE_LEN, nullptr);

  wstringstream finalMessage;
  finalMessage 
    << location     
    << L"\n\tHRESULT 0x" << hex << setw(8) << setfill(L'0') << hresult
    << L": " << systemMessage;

  LogErrorMessage(finalMessage.str().c_str());
}

LogErorWithHresult is quite straightforward – it extracts the system message string and appends to the output of LOG_HR_LOCATION.

void LogErrorMessage(const wchar_t* message)
{
  ::OutputDebugString(message);

#if defined(_DEBUG)
  if (::IsDebuggerPresent())
  {
    ::DebugBreak();
  }
#endif
  // write to file, etc...
}

LogErrorMessage is the heart of the logging system: you can plug in writing to the Output window, appending to a log file, for example.

For a conclusion, I’ll give the output of a sample usage of the logging API

HRESULT InitializeCommonControls();
int Run(int cmdShow);
//...
HRESULT Window::MapGlobalHotkeys()
{
  ASSERT( m_winHandle, E_ILLEGAL_METHOD_CALL );

  ASSERT_HR( RegisterGlobalHotkey(Hotkey_ToggleVolume, VK_F10) );
  ASSERT_HR( RegisterGlobalHotkey(Hotkey_VolumeUp, VK_F12) );
  ASSERT_HR( RegisterGlobalHotkey(Hotkey_VolumeDown, VK_F11) );
  ASSERT_HR( RegisterGlobalHotkey(Hotkey_PlayPause, VK_HOME) );
  ASSERT_HR( RegisterGlobalHotkey(Hotkey_Stop, VK_END) );
  ASSERT_HR( RegisterGlobalHotkey(Hotkey_PlayNext, VK_NEXT) );
  ASSERT_HR( RegisterGlobalHotkey(Hotkey_PlayPrevious, VK_PRIOR) );

  return S_OK;
}

HRESULT Window::RegisterGlobalHotkey(int id, UINT vk)
{
  ASSERT( id >= First_Hotkey && id < Count_Hotkeys, E_INVALIDARG );

  ASSERT_WIN( FALSE != (m_isMappingRegistered[id] =
    ::RegisterHotKey(m_winHandle + 5, id, MOD_ALT | MOD_CONTROL, vk) )
  );

  return S_OK;
}

//..

int Run(int cmdShow)
{
  ASSERT_HR_CODE(InitializeCommonControls(), 1);

  Window window;
  ASSERT_HR_CODE(window.Create(), 1);
  ASSERT_HR_CODE(window.Show(cmdShow), 1);
  ASSERT_HR_CODE(window.MapGlobalHotkeys(), 1);

  MSG msg;
  while (GetMessageW(&msg, nullptr, 0, 0))
  {
    TranslateMessage(&msg);
    DispatchMessageW(&msg);
  }
  return static_cast(msg.wParam);
}

becomes

Window.cpp(162): long __cdecl Window::RegisterGlobalHotkey(int,unsigned int)
  Expression "0 != (m_isMappingRegistered[id] = ::RegisterHotKey(m_winHandle + 5, id, 0x0001 | 0x0002, vk) )"
  HRESULT 0x80070578: Invalid window handle.

Window.cpp(145): long __cdecl Window::MapGlobalHotkeys(void)
  Expression "RegisterGlobalHotkey(Hotkey_ToggleVolume, 0x79)"
  HRESULT 0x80070578: Invalid window handle.

MMKeys2.cpp(37): int __cdecl Run(int)
  Expression "window.MapGlobalHotkeys()"
  HRESULT 0x80070578: Invalid window handle.

Of course, it can still be expanded (as in: don’t print the expression/hresult lines every time), but I believe this is a very good start!