Formatted Logging Function in C++ (similar to printf). All too easy.

 

One of the code posts I created a few weeks ago referenced one of the utility logging functions that I have created for use in my applications/tools. It has certainly made my life a lot easier and I have several derivations of it for various situations. This function is called in much the same way as printf and sprintf. You simply provide a format string (“Contents of x = %d\r\n”), and some parameters, and the function puts it all together into a formatted string. As a side note, on Unix/Linux systems I will use ‘\n‘ for a newline/Line Feed (ASCII character 10). On Windows systems, I will use ‘\r\n‘, which represents the Carriage Return and Line Feed characters (ASCII 13 and 10). If you’re ever opening a text file on Windows that only uses ‘\n‘, open it in Wordpad and then save the file. After that, Notepad and other basic text editing applications should be able to interpret the newlines. But I digress…. again. The code example below is written for Windows (it calls some Win32 API), however the code to generate the formatted string would be valid on a Linux system.

Logging_LogSystem("This function can be called in a similar fashion to %s.\r\n", "printf()");

As you can see in the above example, the custom formatted logging function is being called in the same manner that printf would. Now let’s look at the code behind that function. As always, I’m going to declare the variable as it’s used, rather than at the top of the function. I find this helps give context to variables when providing an explanation. As you’ll see in the example code file referenced at the end of the post, I declare all of the variables at the start of the function, not spread throughout the function.

#include <windows.h>
#include <stdio.h>

#define LOG_BUFFER 512
#define LOG_PREFIX "Application1"
#define PATH_APPLICATION "C:\\Temp"

These are the only two include files that we need for this example. These include files provide the standard string manipulation functions we need plus the core Win32 API set. I’ve also added some definitions related to buffer size and log location so that they can be used by the logging function.

int Logging_LogSystem(char *szLogFormat, ...)
{
	int iRetVal = TRUE;

Cleanup:
	return iRetVal;
}

When defining the function, we need to include all of the mandatory function parameters first, and then include the ‘‘ characters to represent the variable parameter list. I have also defined a variable, iRetVal, to include the return code of the function.

	char *szVarList;
	char szLogString[LOG_BUFFER];

	va_start(szVarList, szLogFormat);
	if (_vsnprintf_s(szLogString, sizeof(szLogString), _TRUNCATE, szLogFormat, szVarList) == -1)
		szLogString[sizeof(szLogString) - 1] = '\0';
	va_end(szVarList);

These 6 lines do all of the work for us. The va_start and va_end macros are required, and are valid on both Windows and Linux. The _vsnprintf_s is a Win32 only function (Linux uses vsnprintf), that creates the formatted string. When developing code on Windows it’s always a good idea to use the printf_s, sprintf_s and other _s functions. These were introduced I believe in the 2008 Visual C Runtime, and provide a more secure version of the base functions – basically the functions want you to tell them how big the target memory buffer is in an attempt to avoid a buffer overflow. I’ve limited the log buffer to 512 bytes (including the terminating null character). This is more than sufficient for my needs. If more than 511 bytes of text are produced though, the _vsnprintf_s function returns -1, and the string is truncated (setting the final byte to ‘‘. I don’t expect that to be an issue in my applications, but the code is able to operate regardless under that condition.

	SYSTEMTIME sTime;
	char szFileName[MAX_PATH];

	GetLocalTime(&sTime);

	sprintf_s(szFileName, sizeof(szFileName), "%s\\Logs\\%s-%04d%02d%02d.Log", PATH_APPLICATION, LOG_PREFIX, sTime.wYear, sTime.wMonth, sTime.wDay);

There’s nothing fancy here. I’m simply determining the current local time in order to determine the filename of the log file.

	hLogFile = CreateFile(szFileName, GENERIC_READ | GENERIC_WRITE, 0, NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
	if (hLogFile != INVALID_HANDLE_VALUE)
	{
		if (SetFilePointer(hLogFile, 0, 0, FILE_END) == INVALID_SET_FILE_POINTER)
		{
			sprintf_s(szErrorString, sizeof(szErrorString), "Error: %s() - %s() - %d\r\n", __FUNCTION__, "SetFilePointer", GetLastError());
			iRetVal = FALSE;
			goto Error;
		}

		sprintf_s(szDateTime, sizeof(szDateTime), "%02d:%02d:%02d ", sTime.wHour, sTime.wMinute, sTime.wSecond);

		if (!WriteFile(hLogFile, szDateTime, (int) strlen(szDateTime), &dwLength, NULL))
		{
			sprintf_s(szErrorString, sizeof(szErrorString), "Error: %s() - %s() - %d\r\n", __FUNCTION__, "WriteFile", GetLastError());
			iRetVal = FALSE;
			goto Error;
		}

		if (!WriteFile(hLogFile, szLogString, (int) strlen(szLogString), &dwLength, NULL))
		{
			sprintf_s(szErrorString, sizeof(szErrorString), "Error: %s() - %s() - %d\r\n", __FUNCTION__, "WriteFile", GetLastError());
			iRetVal = FALSE;
			goto Error;
		}
	}
	else
	{
		sprintf_s(szErrorString, sizeof(szErrorString), "Error: %s() - %s() - %d\r\n", __FUNCTION__, "CreateFile", GetLastError());
		iRetVal = FALSE;
		goto Error;
	}

	goto Cleanup;

That’s more or less standard code to open and create a log file. The code creates or opens the log file with the name previously determined. It then moves the file pointer to the end of the file so that we can append to our log file rather than overwrite its contents. After that, I’m creating a string containing the time of the message before then writing the time stamp and the formatted string to the file.

Error:
	// Use alternate log for error condition (Syslog, Event Log etc)
	// Error captured in szErrorString

	printf(szErrorString);

Cleanup:
	if (hLogFile)
		CloseHandle(hLogFile);

	return iRetVal;

This last piece of code handles the error condition when we are unable to write to the log file. Typically another avenue would be used to store this information so that the application support team can respond. It could be a Syslog message, a new entry in the Windows Event Log, or even an SNMP Trap.

The logging function that we’ve just looked at opens and closes the log file handle each time the function is called. Alternatively, the application may have chosen to hold the log file open for the duration, rather than on use. As always, it depends on your requirement 🙂

I’ve uploaded the code file here.

~ Mike

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s