Arduino Smart Logging

The problem

Often when programming in Arduino you need some logging to the serial port. Most often this is done with a lot of “Serial.println” statements. To make some nice output the logging code easily becomes quite big. Here is an example that illustrates the problem:

#define NUMBER_OF_APPLES 100
uint8_t applesPerPerson = findApplesPerPerson( peopleAmount );
Serial.print( "If " );
Serial.print( peopleAmount );
Serial.print( " people shares " );
Serial.print( NUMBER_OF_APPLES );
Serial.print( " apple they each get " );
Serial.println( applesPerPerson );

 

So many lines of code just to show what’s going on. The debugging takes the focus away from the code!

 

My Solution

I designed a header file that can be imported into your sketch. It is very lightweight and is built on c++ directives and templates. The example above could be written like this:

#define NUMBER_OF_APPLES 100
uint8_t applesPerPerson = findApplesPerPerson( peopleAmount );
Serial << "If " << peopleAmount << " people shares " << NUMBER_OF_APPLES << " apples they each get " << applesPerPerson << endl;

 

But even better is to use log levels. Here is an example of doing excessive logging in a very simple program, without removing focus from the real code:

 

#include "Logging.h"

#define NUMBER_OF_APPLES 100

void setup()
{
	Serial.begin( 115200 );
	LOG_NOTICE( "SETUP", "Arduino just booted" );
}

void loop()
{
	uint8_t peopleAmount = random( 0, 3 );
	LOG_NOTICE( "LOOP", "The amount of people is: " << peopleAmount << " right now." );

	uint8_t applesPerPerson = findApplesPerPerson( peopleAmount );
	Serial << "If " << peopleAmount << " people shares " << NUMBER_OF_APPLES << " apples they each get " << applesPerPerson << endl;

	LOG_NOTICE( "LOOP", "Now sleeping for 10 seconds" );
	delay( 10000 );
}

uint8_t findApplesPerPerson(const uint8_t peopleAmount) {
	LOG_DEBUG( "CALC", "We got the amount " << peopleAmount << " people");
	if ( peopleAmount == 0 ) {
		LOG_ERROR( "CALC", "Can't divide by zero!" );
		return 0;
	} else {
		uint8_t result = NUMBER_OF_APPLES / peopleAmount;
		LOG_DEBUG( "CALC", NUMBER_OF_APPLES << " divided by " << peopleAmount << " is " << result );
		return result;
	}
}

 

If this program is run and the loglevel in the header file is set to 0, the output will be like this:

If 1 people shares 100 apples they each get 100
If 2 people shares 100 apples they each get 50
If 0 people shares 100 apples they each get 0

 

But if you for example set the loglevel to 6, you would get this:

000:00:00:00:000 NOTIC (SETUP) : Arduino just booted
000:00:00:00:000 NOTIC (LOOP) : The amount of people is: 1 right now.
If 1 people shares 100 apples they each get 100
000:00:00:00:020 NOTIC (LOOP) : Now sleeping for 10 seconds
000:00:00:10:027 NOTIC (LOOP) : The amount of people is: 2 right now.
If 2 people shares 100 apples they each get 50
000:00:00:10:042 NOTIC (LOOP) : Now sleeping for 10 seconds
000:00:00:20:048 NOTIC (LOOP) : The amount of people is: 0 right now.
000:00:00:20:055 ERROR (CALC) : Can't divide by zero!
If 0 people shares 100 apples they each get 0
000:00:00:20:064 NOTIC (LOOP) : Now sleeping for 10 seconds

 

Benefits

Just by changing one line in the header file, you choose how much logging you want to output. This makes it much more tempting to leave the debugging statements in the code (also being used as self explaining code instead of comments).

Because it’s all made with #define statements, it means that it only takes program/sram space when it’s actually enabled by setting the loglevel at compile time.

 

The Headerfile

Here is the code of the logging.h file:

#ifndef _LOGGING_h
#define _LOGGING_h

#define LOGLEVEL 6
#define LOG_TIME_FORMAT 2


// Streaming operator for serial print use.
template<class T> inline Print &operator <<( Print &obj, T arg ) {
	obj.print( arg ); return obj;
}
#define endl "\r\n"

/* Generate and print the trailing log timestamp.
		1 = (1234), showing time in seconds since boot. Generates lightweight inline code.
		2 = (001:02:03:04:005) ( day 1, hour 2, minute 3, second 4, millisecond 5 ). Much bigger code, but very readable
*/
#if LOG_TIME_FORMAT == 1
	#define LOG_FORMAT_TIME do { Serial << millis() / 1000; } while (0)
#elif LOG_TIME_FORMAT == 2 
	#define MS_IN_DAY 86400000
	#define MS_IN_HOUR 3600000
	#define MS_IN_MINUTE 60000
	#define MS_IN_SECOND  1000
	#define LOG_FORMAT_TIME do \
	{ \
		long logTime = millis(); \
		unsigned short days = logTime / MS_IN_DAY; \
		unsigned char hours = ( logTime % MS_IN_DAY ) / MS_IN_HOUR; \
		unsigned char minutes = ( ( logTime % MS_IN_DAY ) % MS_IN_HOUR ) / MS_IN_MINUTE; \
		unsigned char seconds = ( ( ( logTime % MS_IN_DAY ) % MS_IN_HOUR ) % MS_IN_MINUTE ) / MS_IN_SECOND; \
		unsigned short ms = ( ( ( ( logTime % MS_IN_DAY ) % MS_IN_HOUR ) % MS_IN_MINUTE ) % MS_IN_SECOND ); \
		char logFormattedTime[17]; \
		sprintf( logFormattedTime, "%03u:%02u:%02u:%02u:%03u", days, hours, minutes, seconds, ms ); \
		Serial << logFormattedTime; \
	} while (0)
#endif // LOG_TIME_FORMAT

// Default do no logging...
#define LOG_EMERGENCY(svc, content) do {} while (0)
#define LOG_ALERT(svc, content)     do {} while (0)
#define LOG_CRITICAL(svc, content)  do {} while (0)
#define LOG_ERROR(svc, content)     do {} while (0)
#define LOG_WARNING(svc, content)   do {} while (0)
#define LOG_NOTICE(svc, content)    do {} while (0)
#define LOG_INFO(svc, content)      do {} while (0)
#define LOG_DEBUG(svc, content)	    do {} while (0)

// Depending on log level, add code for logging
#if LOGLEVEL >= 0
	#define LOG_EMERGENCY(svc, content) do { LOG_FORMAT_TIME; Serial << "  EMERGENCY (" << svc << ") : " << content << endl; } while(0)
	#if LOGLEVEL >=1 
		#define LOG_ALERT(svc, content)	do { LOG_FORMAT_TIME; Serial << "  ALART     (" << svc << ") : " << content << endl; } while(0)
		#if LOGLEVEL >= 2
			#define LOG_CRITICAL(svc, content) do { LOG_FORMAT_TIME; Serial << "  CRITICAL  (" << svc << ") : " << content << endl; } while(0)
			#if LOGLEVEL >= 3
				#define LOG_ERROR(svc, content) do { LOG_FORMAT_TIME; Serial << "  ERROR     (" << svc << ") : " << content << endl; } while(0)
				#if LOGLEVEL >= 4
					#define LOG_WARNING(svc, content) do { LOG_FORMAT_TIME; Serial << "  WARNING   (" << svc << ") : " << content << endl; } while(0)
					#if LOGLEVEL >= 5
						#define LOG_NOTICE(svc, content) do { LOG_FORMAT_TIME; Serial << "  NOTIC     (" << svc << ") : " << content << endl; } while(0)
						#if LOGLEVEL >= 6
							#define LOG_INFO(svc, content) do { LOG_FORMAT_TIME; Serial << "  INFO      (" << svc << ") : " << content << endl; } while(0)
							#if LOGLEVEL >= 7
								#define LOG_DEBUG(svc, content) do { LOG_FORMAT_TIME; Serial << "  DEBUG     (" << svc << ") : " << content << endl; } while(0)
							#endif // LOGLEVEL >= 7
						#endif // LOGLEVEL >= 6
					#endif // LOGLEVEL >= 5
				#endif // LOGLEVEL >= 4
			#endif // LOGLEVEL >= 3
		#endif // LOGLEVEL >= 2
	#endif // LOGLEVEL >= 1
#endif // LOGLEVEL >= 0

#endif

 

The only thing you need to set is the LOGLEVEL and the LOG_TIME_FORMAT in the top. If you want to save memory you can change to LOG_TIME_FORMAT to 1 which only shows the time unformattet in seconds since boot.

The loglevels are:

0: EMERGENCY
1: ALERT
2: CRITICAL
3: ERROR
4: WARNING
5: NOTICE
6: INFO
7: DEBUG

 

Try compiling your sketch at different loglevels and watch how your consumed memory changes! No more excuses to remove debugging code from your sketch 🙂

Leave a Reply

Your email address will not be published. Required fields are marked *