Upcoming Events
Unite 2010
11/10 - 11/12 @ Montréal, Canada

GDC China
12/5 - 12/7 @ Shanghai, China

Asia Game Show 2010
12/24 - 12/27  

GDC 2011
2/28 - 3/4 @ San Francisco, CA

More events...
Quick Stats
94 people currently visiting GDNet.
2406 articles in the reference section.

Help us fight cancer!
Join SETI Team GDNet!
Link to us Events 4 Gamers
Intel sponsors gamedev.net search:

Error Logging

There comes a time in every young engine's life when... things don't quite work as they should. Sockets don't connect, resources can't be found... if we're ever going to have a hope of finding and fixing the problems, we are of course going to need to know about them. So we have a system for recording errors as and when they occur - 'error logging.' In truth, logfiles can and should be used for recording all kinds of events, not just errors - if something's going wrong and not recording what, recording the things that *are* working will help you find the problem by process of elimination.

We could just create an ofstream object and store it in a global variable - such a method works (up to a point) but is pretty basic. We can do better than that! Our logging system will support multiple logfiles, predefined localisable messages, and parameter replacement.

Multiple logfiles are just useful. In extreme cases this could mean one logfile per subsystem - one each for video errors, sound errors, etcetera; I'm not going to go that far, and just have 3 logfiles (CLIENT, SERVER, and APP). CLIENT and SERVER will record - you guessed it - log files relevant to the Client or Server portions of the program (Client includes all the Video, Sound, and other 'player-end' tasks - Server will tend to be less used, but will record connections being opened and closed, games being started and stopped, and AI/physics messages), while APP will record Kernel-level messages, along with those messages that don't seem to 'fit' into CLIENT and SERVER. You can, of course, record a message to more than one logfile at a time.

"Predefined localisable messages," more often known as a "string table", allow you to store some common strings somewhere, load them in, and then reference them by ID number - rather than hard-coding the message into your app. This saves a large amount of space (because strings aren't being duplicated), and also makes it very easy to translate all the messages into another language.

"Parameter replacement" is the technique demonstrated by the old C string functions like printf() - special 'field codes' in the string get replaced with actual values that get passed in seperately. So, strings can be more generalised - rather than needing one string for each error number, you could just use a single string with a field code ("Error code %i") and pass the error number in alongside it. We'll be using the printf() syntax for field codes - mainly because we'll be using a special form of the printf() function to build our messages from the strings and arguments. Furthermore, you can store messages with field codes in the strings table - and that's where things start getting really interesting.

For the time being, though, let's get started. There's just one last thing I need to mention - the method of storing the strings file. It's generally a good idea if the strings can be stored where curious users can't tamper with them - adding or removing field codes where they're not expected could cause some serious problems. Under Linux and MacOS, we've not really got anywhere tamper-proof to keep the strings - we'll have to make do with a read-only file. On Windows, however, we can store the string table as a resource, built into the executable. That's why you'll see two versions of the LoadStrings() function; one reads the strings from the resources area, and the other reads from a file on disk. Conditional compilation is used to compile the right one on the right platform.

Enough waffle. Here's the class:

//first, a few predefined constants
const int LOG_APP=1;
const int LOG_CLIENT=2;
const int LOG_SERVER=4;
//LOG_USER is used to display the log message to the user - i.e. in a dialog box
const int LOG_USER=8;

#define MAX_LOG_STRINGS 256

class CLog  
{
   protected:
      CLog();
   
      std::ofstream appLog;
      std::ofstream clientLog;
      std::ofstream serverLog;
   
      std::string logStrings[MAX_LOG_STRINGS];
      bool LoadStrings();
   
   public:
      static CLog &Get();
   
      bool Init();
   
      void Write(int target, const char *msg, ...);
      void Write(int target, unsigned long msgID, ...);
};

Pretty straightforward. The log is a Singleton, which is why you see a protected constructor and a static Get() function - trying to have more than one CLog object at any time simply wouldn't work, because they'd both be trying to open the same files, and would cause a sharing violation. The files themselves are accessed through std::ofstream objects. The strings table, once loaded by the LoadStrings() function, is stored in the logStrings array - you could use a vector, but I didn't (because it doesn't *really* need to be dynamically expandable.. when are you going to need more than 256 slots for log messages?). Then, moving down to the public section of the class, there's the destructor and aforementioned Get() function; then, an Init() function, which is responsible for actually opening the logfiles and calling the LoadStrings() function - this isn't done by the constructor, because if it fails, there's no way of knowing; with an explicit Init() function, we're reminded to check the return code. It also gives us total control over when the log is started up.

Finally, the Write() functions. Each takes an int that tells you where the message should be logged to (by ORing together the LOG_* codes defined above); then, one takes a string pointer (for hard-coded strings), and one takes a unsigned long (for string table ID number). Then, each takes some kind of nebulous '...'. What's that about, you ask?

'...'s are known as 'ellipses,' and are how we achieve 'variable argument lists.' Given that the message we're using may contain 5 field codes or 50, the number of values we pass with it will vary - and that includes the situation where there are no arguments. So, we use the '...' to denote that any number of arguments can follow the fixed ones (and there must be at least one fixed one, even if it's just a dummy one). We don't actually need to process the list ourselves in the Write() functions - a good thing, because variables being passed in lose all type information and become a pain to work with - we just need to retrieve a pointer to the list, and pass it on to the special printf() function, vsprintf().

Here's the functions themselves:

CLog::CLog()
{
   //the constructor doesn't do anything, but we need it for our singleton to work correctly
}

CLog &CLog::Get()
{
   static CLog log;
   return log;
}

bool CLog::Init()
{
   appLog.open("applog.txt");
   clientLog.open("clntlog.txt");
   serverLog.open("srvrlog.txt");
   //user errors get logged to client

   //load the strings file
   if(!LoadStrings())return false;

   return true;
}

void CLog::Write(int target, const char *msg, ...)
{
   va_list args; va_start(args,msg);
   char szBuf[1024];
   vsprintf(szBuf,msg,args);

   if(target&LOG_APP)
   {
      appLog<<szBuf<<"\n";
#ifdef DEBUG
      appLog.flush();
#endif
   }
   if(target&LOG_CLIENT)
   {
      clientLog<<szBuf<<"\n";
#ifdef DEBUG
      clientLog.flush();
#endif
   }
   if(target&LOG_SERVER)
   {
      serverLog<<szBuf<<"\n";
#ifdef DEBUG
      serverLog.flush();
#endif
   }
   if(target&LOG_USER)
   {
#ifdef WIN32
      MessageBox(NULL,szBuf,"Message",MB_OK);
#else
#error User-level logging is not yet implemented for this platform.
#endif
   }
}

void CLog::Write(int target, unsigned long msgID, ...)
{
   va_list args; va_start(args, msgID);
   char szBuf[1024];
   vsprintf(szBuf,logStrings[msgID].c_str(),args);
   Write(target,szBuf);
}

#ifdef WIN32
//under Win32, the strings get read in from a string table resource
bool CLog::LoadStrings()
{
   for(unsigned long i=0;i<MAX_LOG_STRINGS;i++)
   {
      char szBuf[1024];
      if(!LoadString(GetModuleHandle("engine"),i,szBuf,1024))
         break; //returning 0 means no more strings
      logStrings[i]=szBuf;
   }
   return true;
}

#else
//other platforms load the strings in from strings.txt
bool CLog::LoadStrings()
{
   std::ifstream in("strings.txt");
   if(!in.is_open())return false;

   DWORD index=0;

   while(!in.eof())
   {
      char szBuf[1024];
      in.getline(szBuf,1024);
      stringsFile[index++]=szBuf;
   }

   return true;
}

#endif

After reading that, there's probably a few things you're wondering about:

Firstly, that va_list business. That's how we work with variable argument lists; we create a pointer of type va_list (it maps to char*, in the headers), and use the va_start() macro to get it pointing to the right place, by passing va_start the argument *immediately before* the list - va_start gets a pointer to that, adds on its size, and stores that in va_list (or something along those lines, at least). We can then pass va_list to vsprintf(), which happily processes it for us.

Next, the flush() calls. In theory, this should make sure that the message you've just written actually gets saved to disk, rather than being stored in a cache somewhere; given that your app is still unstable in debug builds, a crash would cause you to lose log messages in that cache (and those log messages would probably tell you how and why you crashed). I say 'in theory,' because it didn't actually *work* for me; I left it in because it's *meant* to. Tracing the flush() call through the documentation gets to basic_streambuf::sync(), which "endeavours to synchronize the controlled streams with any associated external streams," that is, it tries to get the in-memory object into the same state as the file on disk (by changing the file on disk). I would guess that it's failing there; if you can tell me why, kudos.

I didn't mention the LOG_USER option before. You should have figured out what it does by now, but if you haven't - it displays the message to the user (i.e. in a pop-up message box). You can use this for the really important messages, like 'The game failed to start because it's got a hangover.' However, implementation of this is platform-dependent, which is why you see the #ifdef WIN32 lines in there. There's also a #error statement - if you try and build this on a platform other than Windows at the moment, it won't let you build because that LOG_USER functionality isn't implemented. All non-windows users need to do is add an #elif defined MY_PLATFORM_FLAG before the #else line, and they'll be free to implement the message box for their own platform; I've not done any platform other than Windows because I'm not confident I'll get it right. :)

It's probably worth noting that the string-table-based version of the Write() function uses the plain version to do the actual logging. It's nice like that. It's also an example of passing no arguments in the variable-argument list; the plain Write() function will handle that fine, as you will see.





Miscellanous Utilities

Contents
  Introduction
  Memory Management
  Smart Pointers
  Error Logging
  Miscellanous Utilities

  Source code
  Printable version
  Discuss this article

The Series
  Part I
  Part II
  Part III
  Part IV
  Part V