Know your logs!

thumb_up 0
thumb_down 0

In this article, we are going to look at how we can implement a very simple, but powerful and elegant logging API in C.

Most of the time while debugging software/hardware problems, we are in a fix with one glaring question in mind "which logs do I look at?". Many developers keep signature footprints on their logs - like country jargon - embedded in them. For example I was working for a company where the logs would print on the console something like this: "arm ched khani" (Tampering with arm); or even a more hilarious one like "gaddi aayi ve"

Legend to symbols used
Image credits

I was working for a company where the logs would print on the console something like this: "arm ched khani" (Tampering with arm); or even a more hilarious one like "gaddi aayi ve"

While it is okay to have a good sense of humour, there are a few basic problems with this kind of logging:

  1. You and only you know what the log means
  2. You might not be able to handle more than 2 or 3 projects
  3. You might not really know where these logs got hit from
  4. You are a shit crass coder just out of school. (Noob!)

When adding logging information to the code, it should follow some standards. By standards, I mean your own standards. All your logs should be aligned with some concept and should preferably print out on the console or get logged into a file so that they are easy to read and are in a definitive manner. For example it would have been much more intuitive if the examples above were logged as:

[ 16:36 August 24 - 2015 ] arm_status.cpp | get_arm_status | 1008 | CRITICAL : Arm moved by human intervention

[ 16:48 August 24 - 2015 ] car_status.cpp | poll_car_status | 1209 | INFO : New car has arrived

Now these logs can be understood by fairly anyone. They give information regarding the time of the logs, which file and functions spit out the logs and finally the lines at which information was logged. Moreover they tell us whether the log is general information, an error or of a critical type.

Hopefully, this is motivating enough for you to want to start using such logging in your code. So how do we do it? A friend of mine - keeping him out of the trouble of getting all the credits - helped and taught me how to log in C and C++. Although there are a lot of debuggers readily available off the shelf, I'm not a very library fond kind of guy (really, any kind of library!). On the contrary, my own modules give me the power to bend them when,how and whichever way I like. Let's get started!

So, the first thing to do is to categorize your logs into sub groups like:

  1. DEBUG
  2. INFO
  3. ERROR
  4. CRITICAL
  5. FATAL

Of course, these are just my own categories. You could use them as is, or make your own fancy groups, or as a good shortcut, take a peek into the header files from syslog (syslog.h). Let's define them in a file named logging_levels.h:

/*--------------------------------------------------------------*/
/*!@brief define the following macros to enable disable logging */
#define LOGGING_DEBUG
#define LOGGING_INFO
#define LOGGING_ERROR
#define LOGGING_CRITICAL
#define LOGGING_FATAL

Now the use of these defines is that we can shut up mute any of these sub categories of logs by just removing the macro for them. For example if we do not want the DEBUG category logs to be recorded on the console or in the logging file, all we need to do is :

/*--------------------------------------------------------------*/
/*!@brief define the following macros to enable disable logging */
//#define LOGGING_DEBUG
#define LOGGING_INFO
#define LOGGING_ERROR
#define LOGGING_CRITICAL
#define LOGGING_FATAL

The next logical thing to do is come up with the different types of logging we want to support. I propose two categories here:

  1. Logging in a File
  2. Logging on Console

As always, we can come up with a lot of them; but for starters, let's keep just these two. Let's define them too:

/*-----------------------------------------------------------------------*/
/*!@brief define the following macros to enable console or file printing */
//#define LOGGING_ON_CONSOLE
#define LOGGING_IN_FILES

#ifndef LOGGING_IN_FILES
    #ifndef LOGGING_ON_CONSOLE
        #error "NEITHER LOGGING_ON_CONSOLE NOR LOGGING_IN_FILES WAS ACTIVATED"
    #endif /* LOGGING_ON_CONSOLE */
#endif /* LOGGING_IN_FILES */
    
#ifdef LOGGING_ON_CONSOLE
    #ifdef LOGGING_IN_FILES
        #error "BOTH LOGGING_ON_CONSOLE AND LOGGING_IN_FILES CANNOT BE ACTIVATED TOGETHER"
    #endif /* LOGGING_IN_FILES */
#endif /* LOGGING_ON_CONSOLE */

#ifdef LOGGING_IN_FILES
    #ifdef LOGGING_ON_CONSOLE
        #error "BOTH LOGGING_ON_CONSOLE AND LOGGING_IN_FILES CANNOT BE ACTIVATED TOGETHER"
    #endif /* LOGGING_ON_CONSOLE */
#endif /* LOGGING_IN_FILES */

So if you want to get logs printed on console, you define LOGGING_ON_CONSOLE and if you want the logs to be logged into a file you define LOGGING_IN_FILES. Interestingly, the rest of the code makes sure that we do not define both LOGGING_ON_CONSOLE and LOGGING_IN_FILES simultaneously. If we do so my mistake, the code would simply not compile and would give a compilation error :

"BOTH LOGGING_ON_CONSOLE AND LOGGING_IN_FILES CANNOT BE ACTIVATED TOGETHER"

Based on the two types of loggings (a.) on console and (b.) in files, we now define what these two logging should do:

/*------------------------------------------------*/
/*!@brief Macros to be define where to print logs */

#ifdef LOGGING_IN_FILES
    #define LOG_PRINT(file_ptr,fmt, args...) \
    do {				\
    fprintf(file_ptr,"\n" fmt, ##args);\
    fflush(file_ptr);\
    } while (0)
#endif /* LOGGING_IN_FILES */

#ifdef LOGGING_ON_CONSOLE
    #define LOG_PRINT(file_ptr,fmt, args...) \
    do {				\
    printf("\n" fmt, ##args);\
    fflush(stdout);\
    } while (0)
#endif /* LOGGING_ON_CONSOLE */

Intuitive enough? The first chunk of code under the (preprocessor) conditional #ifdef LOGGING_IN_FILES gets compiled if the macro LOGGING_IN_FILES is defined. The second chunk of code under #ifdef LOGGING_ON_CONSOLE gets compiled if the macro LOGGING_ON_CONSOLE is defined. We have already taken care earlier that both of them cannot be defined together!

This particular chunk of code defined the macro : LOG_PRINT(file_ptr,fmt,args...)

  1. The argument file_ptr is the pointer to the file where the logs are to be logged. In case LOGGING_ON_CONSOLE is defined, it is just ignored.
  2. The argument fmt is the format string that was included in logging. Something like Ceased to move any further as counter is not %d
  3. The argument args... is a multiple argument which would have all arguments after the format string

Hence LOGGING_IN_FILES defines LOG_PRINT(file_ptr,fmt,args...) in such a way that it appends a "\n" to the log automatically and uses fprintf to push the logs to the file pointed by file_ptr. On the contrary LOGGING_ON_CONSOLE defines LOG_PRINT(file_ptr,fmt,args...) in such a way that it appends a "\n" to the log automatically and uses printf to push the logs to standard console. Also note that we can do away with using fprintf and printf differently by using stderr or stdout in case of console logs. But, we'll let that be for the sake of illustration.

Interestingly, I have used fflush after both of them. This is on your plate. Try it out with and without fflush and see what happens. :-)

Now that we have defined the macros that would print/push logs, let's define the end user macros to start using our logging structure:

/*-----------------------------------------------------*/
/*!@brief Macros to be define the DEBUG logging Macros */
#ifdef LOGGING_DEBUG
    #define DEBUG_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | DEBUG : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define DEBUG_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_DEBUG */

/*----------------------------------------------------*/
/*!@brief Macros to be define the INFO logging Macros */
#ifdef LOGGING_INFO
    #define INFO_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | INFO : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define INFO_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_INFO */

/*-----------------------------------------------------*/
/*!@brief Macros to be define the ERROR logging Macros */
#ifdef LOGGING_ERROR
    #define ERROR_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | ERROR : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define ERROR_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_ERROR */

/*--------------------------------------------------------*/
/*!@brief Macros to be define the CRITICAL logging Macros */
#ifdef LOGGING_CRITICAL
    #define CRITICAL_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | CRITICAL : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define CRITICAL_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_CRITICAL */

/*-----------------------------------------------------*/
/*!@brief Macros to be define the FATAL logging Macros */
#ifdef LOGGING_FATAL
    #define FATAL_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | FATAL CRASH !!! : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); while(1); } while (0)
#else
    #define FATAL_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_FATAL */

HOLY FFSHIT (sorry) CRAP!

Yea! I know. Let's just take up one and you could figure out the rest. I will only explain the definition of the macro DEBUG_MSG:

/*-----------------------------------------------------*/
/*!@brief Macros to be define the DEBUG logging Macros */
#ifdef LOGGING_DEBUG
    #define DEBUG_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | DEBUG : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define DEBUG_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_DEBUG */

Remember we could disable the logs subcategorized as DEBUG by just not defining the macro LOGGING_DEBUG. Let me explain how that works. If the LOGGING_DEBUG is defined DEBUG_MSG is defined as nothing:

#define DEBUG_MSG(file_ptr, fmt, args...)

So the macro expands to nothing.

Let's get to when the macro LOGGING_DEBUG is defined. The macro DEBUG_MSG expands to our earlier defined macro LOG_PRINT. It has arguments:

  1. The argument file_ptr is the pointer to the file where the logs are to be logged. In case LOGGING_ON_CONSOLE is defined, it is just ignored.
  2. Adds date and time via function return log_date_time(); adds filename, functioname and Line of execution via __FILE__, __func__ and __LINE__ respectively; It also adds the keyword DEBUG to the log to that one knows it is a Debug log.

For the function log_date_time() one can define one's own function to return a string with date and time. I define it as:

/*----------------------------------------------------------------------------*/
/* Function : log_date_time */
/*----------------------------------------------------------------------------*/
/*!
  @ brief This API returns back the current time and date
  @ details This API returns back the current time and date
  @ pre-requirements
  @ param void

  @ return int * Pointer to the string containing the time and date
*/
int8 * log_date_time ( void )
{
  /* Local Variables */
  time_t current_time;  
  int8 * date_and_time = NULL;
  uint32 counter = 0;

  /* Validation */

  /* Algorithm */
  current_time = time ( NULL );
  date_and_time = ctime( & current_time );
  for ( counter = 0; '\0' != date_and_time[counter]; counter ++ )
  {
    if ( '\n' == date_and_time[counter] )
    {
      date_and_time[counter] = '\0';
      break;
    }
  }
  return ( date_and_time );
}/* log_date_time */

So how do we use this logging?

That should be pretty (and) simple. Here. Use the following macros in your code to log:

  1. DEBUG_MSG for debug logging
  2. INFO_MSG for information logging
  3. ERROR_MSG for error logging
  4. CRITICAL_MSG for critical logging
  5. FATAL_MSG for fatal logging and stopping the code

Example:

CRITICAL_MSG ( general_log_file, "Device Init failed : %d : halting for ever", device_init_status );
ERROR_MSG ( general_log_file, "event %d handler not present", event );
INFO_MSG ( general_log_file, "creating instance for diablo %d", diablo_test_drive_id[diablo_counter] );

Also, it is interesting that while we're pushing logs into files directly, we may push different logs into different log files. But how to manage that would be a different post altogether. Here is the code for the entire file logging_levels.h. Happy logging and debugging!

 /*
  @file logging_levels.h

  @author Saurav Agarwala
  @created on 08/14/2015
  @brief This file contains the logging levels

  @details This file contains the logging levels
*/

#ifndef LOGGING_LEVELS_H_
#define LOGGING_LEVELS_H_

#ifdef __cplusplus
extern "C" {
#endif

/*==============================================================================
                               INCLUDE FILES
==============================================================================*/

#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <unistd.h>
#include <errno.h>

/*==============================================================================
                      DEFINITIONS AND TYPES : MACROS
==============================================================================*/
/*----------------------------------------------------------------------------*/
/*!@brief define the following macros to enable disable logging */
#define LOGGING_DEBUG
#define LOGGING_INFO
#define LOGGING_ERROR
#define LOGGING_CRITICAL
#define LOGGING_FATAL

/*-----------------------------------------------------------------------*/
/*!@brief define the following macros to enable console or file printing */
//#define LOGGING_ON_CONSOLE
#define LOGGING_IN_FILES

#ifndef LOGGING_IN_FILES
    #ifndef LOGGING_ON_CONSOLE
        #error "NEITHER LOGGING_ON_CONSOLE NOR LOGGING_IN_FILES WAS ACTIVATED"
    #endif /* LOGGING_ON_CONSOLE */
#endif /* LOGGING_IN_FILES */
    
#ifdef LOGGING_ON_CONSOLE
    #ifdef LOGGING_IN_FILES
        #error "BOTH LOGGING_ON_CONSOLE AND LOGGING_IN_FILES CANNOT BE ACTIVATED TOGETHER"
    #endif /* LOGGING_IN_FILES */
#endif /* LOGGING_ON_CONSOLE */

#ifdef LOGGING_IN_FILES
    #ifdef LOGGING_ON_CONSOLE
        #error "BOTH LOGGING_ON_CONSOLE AND LOGGING_IN_FILES CANNOT BE ACTIVATED TOGETHER"
    #endif /* LOGGING_ON_CONSOLE */
#endif /* LOGGING_IN_FILES */

/*------------------------------------------------*/
/*!@brief Macros to be define where to print logs */

#ifdef LOGGING_IN_FILES
    #define LOG_PRINT(file_ptr,fmt, args...) \
    do {				\
    fprintf(file_ptr,"\n" fmt, ##args);\
    fflush(file_ptr);\
    } while (0)
#endif /* LOGGING_IN_FILES */

#ifdef LOGGING_ON_CONSOLE
    #define LOG_PRINT(file_ptr,fmt, args...) \
    do {				\
    printf("\n" fmt, ##args);\
    fflush(stdout);\
    } while (0)
#endif /* LOGGING_ON_CONSOLE */

/*-----------------------------------------------------*/
/*!@brief Macros to be define the DEBUG logging Macros */
#ifdef LOGGING_DEBUG
    #define DEBUG_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | DEBUG : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define DEBUG_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_DEBUG */

/*----------------------------------------------------*/
/*!@brief Macros to be define the INFO logging Macros */
#ifdef LOGGING_INFO
    #define INFO_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | INFO : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define INFO_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_INFO */

/*-----------------------------------------------------*/
/*!@brief Macros to be define the ERROR logging Macros */
#ifdef LOGGING_ERROR
    #define ERROR_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | ERROR : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define ERROR_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_ERROR */

/*--------------------------------------------------------*/
/*!@brief Macros to be define the CRITICAL logging Macros */
#ifdef LOGGING_CRITICAL
    #define CRITICAL_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | CRITICAL : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); } while (0)
#else
    #define CRITICAL_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_CRITICAL */

/*-----------------------------------------------------*/
/*!@brief Macros to be define the FATAL logging Macros */
#ifdef LOGGING_FATAL
    #define FATAL_MSG(file_ptr, fmt, args...) \
    do { LOG_PRINT(file_ptr,"[ %s ] %s | %s | %d | FATAL CRASH !!! : " fmt, log_date_time(), __FILE__, __func__, __LINE__, ## args); while(1); } while (0)
#else
    #define FATAL_MSG(file_ptr, fmt, args...)
#endif/* LOGGING_FATAL */
    
/*==============================================================================
                      DEFINITIONS AND TYPES : ENUMS
==============================================================================*/


/*==============================================================================
                   DEFINITIONS AND TYPES : STRUCTURES
==============================================================================*/


/*==============================================================================
                           EXTERNAL DECLARATIONS
==============================================================================*/


/*==============================================================================
                           FUNCTION PROTOTYPES
==============================================================================*/

#ifdef __cplusplus
} // extern "C"
#endif

#endif /* LOGGING_LEVELS_H_ */
Discussions Notes