Building a Flexible Logging Library for Arduino, Part 2

6 January 2020 by Phillip Johnston • Last updated 15 December 2021

A client asked me to write a logging library for a project using the Arduino SDK. Since the library will be open-source, I’m running an experiment. I will document the design, development, and feedback cycles on this project. I hope to expose readers to a real development process, feedback on a design, and how to adjust based on that feedback.

In the previous article, we discussed my client’s requirements for this library, set up the project structure, and created a minimal implementation. The goal was to take an agile approach and get review on a minimal implementation before continuing with development.

Today’s article will discuss the review feedback. I’ll refactor the library to address that feedback.

Table of Contents:

1. Review Feedback
   1. Analyzing the Feedback
   2. Making a Plan
   3. A Note About Macros
2. Refactoring
   1. Eliminating the Need for Macros With A Singleton
   2. Test Refactoring
   3. Tracing Macros
3. Updating Examples
4. Updating Documentation
5. Putting it All Together
6. Further Reading

Review Feedback

I joked on the Embedded.fm Slack channel that the alternate title for this article should be “How to Handle Review Feedback with Grace”. I would summarize the feedback I received from my client as “Great start, but can you change pretty much everything about it?” A realistic response. This is why we work in small chunks!

First, a positive note from the client:

I agree with having the default mode be simple to configure and use. And then more advanced features can come at the cost of more complexity.

Here’s a summary of the feedback I received from my client’s review:

• Request: that the library also work with ATMega 2560 Arduino board
  • (We’ve been working off of a Teensy 3.6)
  • He sent me a templated Arduino circular buffer library for this, which I’ll incorporate
• If the instance is static, I’m curious about your pros & cons of using macros versus static methods and values.
  • (e.g. Log::warn("..."), Log::level = log::CRITICAL;)
  • Concern is for coding guidelines that discourage macros
• It’s not obvious that it needs to be singleton. Might be useful to have multiple loggers at some point.
  • If desirable to only have one instance, users can enforce that by convention. (just instantiate one)
• Please test a bit with Arduino 1.5 version soon to see if it supports the language features you’re using
  • One product uses 1.5. Another uses 1.6/1.8.
  • If not, I vote continuing with 1.6/1.8 version, and we can ponder 1.5 later
• I’m curious about whether you can isolate the Arduino-specific aspects. Might be easier to use in code run in tests.
• Consider generalizing the project name for broader C++ use. The library is generic, but it also specifically supports Arduino (and doesn’t use streams).
• When you get to adding millis(), consider making the start and ending of each log message configurable: time, file/method/line, etc.
  • If the formatting method was virtual, a user could overload it
  • Maybe millis() can be one of your examples, but encourage people to pick a timer for their application’s needs
  • Another approach: Inject a default clock, but make it replaceable
• Could avoid having a time field and let the user do almost all formatting, via strategy pattern or virtual method.

I’m a seasoned programmer, and I’ve been subject to review processes for a decade. But I have to tell you, it always stings to receive a long laundry list of feedback spread across 4–5 emails. I needed to step back for a few minutes. Then, when I reread the feedback, I realized how many good ideas the client provided.

I continued the discussion on one major point with the client: the use of macros. Part of the reason was to hide the ugly singleton access using the inst() function, which we can avoid by various means. But there are two other major reasons to use macros: compile-time removal of log statements and access to file, function, and line number information.

I will explore whether I can create a similar compile-out effect using templates in the base class, which would help eliminate macros. But there’s no pre-C++20 method for accessing the file, function, and line number information without the preprocessor.

My client provided a wonderful suggestion:

I’m wondering if there could be a TRACE(...) macro that prints the file, line, etc. For example, Log::error("null pointer. %s\n", TRACE());

That’s a great idea! We can give more control to the user.

Analyzing the Feedback

The interesting thing about the feedback is that the points are all requests, not demands. My client does not know the best way forward, and I’m still the expert in the driver’s seat. However, I would be foolish to ignore all the requests. I would be equally foolish to think all the requests share the same priority. We can’t (and won’t) implement everything at once.

I will bucket the feedback into three different bins, and will prioritize the bins differently:

1. Interface & Behavior
2. Compatibility
3. Communication problems

I want to handle interface and behavior changes as best as I can right now:

• Make the interface work if a user wants to avoid macros (e.g. log.warn(), Logger::warn())
• Support easier use without a singleton
• Implement a TRACE() macro
• Add a new formatting function which subclasses can override
  • This can have default behavior in the log class, or it can be empty default behavior
• Explore whether to add time-stamping to the formatting function (or find another strategy altogether)

Compatibility changes I consider the lowest priority. Making sure that the code can compile on AVR is easy, and I just created another Circular Buffer strategy using the AVR-compatible Queue class that my client shared. However, testing with Arduino 1.5 will take me off into the weeds, so I will defer that task for the moment. To make sure I don’t forget, I filed an issue.

Two items from the feedback list were interesting, and highlight communication problems from my side:

• I’m curious about whether you can isolate the Arduino-specific aspects. Might be easier to use in code run in tests.
• Consider generalizing the project name for broader C++ use. The library is generic, but it also specifically supports Arduino (and doesn’t use streams).

I designed and implemented the initial code so it had no Arduino dependencies, and I can run it in a test harness. That wasn’t clear to my client, and that’s a flaw in my communication.

Part of the problem is highlighted in the second point, which is to generalize the name and communicate that the library also supports Arduino. This is a great idea, but I don’t want to worry about branding while creating the API. So I filed another issue to track that task. We’ll take care of it before the series ends.

Refactoring

Before we add new features, we will address the client’s feedback along these lines:

• Make the interface work if a user wants to avoid macros (e.g. log.warn(), Logger::warn())
• Support easier use without a singleton
• Implement a TRACE() macro
• Add a new formatting function which subclasses can override
  • This can have default behavior in the log class, or it can be empty default behavior
• Explore whether to add time-stamping to the formatting function (or find another strategy altogether)

I want to expand the test coverage for the Circular Buffer class, which is a great way to test the base class. I’ll also see if I can add host-side tests for the AVR circular buffer class.

Eliminating the Need for Macros With A Singleton

One reason we had a macro was to hide the PlatformLogger::inst(). prefix for all logging calls. We can adjust the class so we have static methods which wrap the inst() internally. We supply arguments via variadic templates and forward them to the actual instance.

Here’s how our global instance enforcer looks now:

template<class TLogger>
class PlatformLogger_t
{
  public:
    PlatformLogger_t() = default;
    ~PlatformLogger_t() = default;

    static TLogger& inst()
    {
        static TLogger logger_;
        return logger_;
    }

    template<typename... Args>
    inline static void critical(const char* fmt, const Args&... args)
    {
        inst().critical(fmt, std::forward<const Args>(args)...);
    }

    template<typename... Args>
    inline static void error(const char* fmt, const Args&... args)
    {
        inst().error(fmt, std::forward<const Args>(args)...);
    }

    template<typename... Args>
    inline static void warning(const char* fmt, const Args&... args)
    {
        inst().warning(fmt, std::forward<const Args>(args)...);
    }

    template<typename... Args>
    inline static void info(const char* fmt, const Args&... args)
    {
        inst().info(fmt, std::forward<const Args>(args)...);
    }

    template<typename... Args>
    inline static void debug(const char* fmt, const Args&... args)
    {
        inst().debug(fmt, >std::forward<const Args>(args)...);
    }
};

For completeness, I’ll also add flush/clear/echo/level, all just forward to the instance:

    inline static void flush()
    {
        inst().flush();
    }

    inline static void clear()
    {
        inst().clear();
    }

    inline static log_level_e level(log_level_e l)
    {
        return inst().level(l);
    }

    inline static bool echo(bool en)
    {
        return inst().echo(en);
    }

We can adjust our logging macros to use the new calls. The macros are necessary for supporting compile-time removal of unwanted log statements, but we will try to get rid of that requirement if possible.

#if LOG_LEVEL >= LOG_LEVEL_CRITICAL
#ifndef logcritical
#define logcritical(...) PlatformLogger::critical(__VA_ARGS__)
#endif
#else
#define logcritical(...)
#endif

#if LOG_LEVEL >= LOG_LEVEL_ERROR
#ifndef logerror
#define logerror(...) PlatformLogger::error(__VA_ARGS__)
#endif
#else
#define logerror(...)
#endif

#if LOG_LEVEL >= LOG_LEVEL_WARNING
#ifndef logwarning
#define logwarning(...) PlatformLogger::warning(__VA_ARGS__)
#endif
#else
#define logwarning(...)
#endif

#if LOG_LEVEL >= LOG_LEVEL_INFO
#ifndef loginfo
#define loginfo(...) PlatformLogger::info(__VA_ARGS__)
#endif
#else
#define loginfo(...)
#endif

#if LOG_LEVEL >= LOG_LEVEL_DEBUG
#ifndef logdebug
#define logdebug(...) PlatformLogger::debug(__VA_ARGS__)
#endif
#else
#define logdebug(...)
#endif

#define logflush() PlatformLogger::flush();
#define loglevel(lvl) PlatformLogger::level(lvl);
#define logecho(echo) PlatformLogger::echo(lvl);
#define logclear() PlatformLogger::clear();

We need to build equivalent logging calls into our LoggerBase class, since we’re forwarding these calls to calls of the same name. They don’t exist. What we need to do is create mirror calls, strip off inline/static, and then have them forward the arguments to the log() function with the corresponding level argument:

template<typename... Args>
void critical(const char* fmt, const Args&... args)
{
    log(log_level_e::critical, fmt, std::forward<const Args>(args)...);
}

template<typename... Args>
void error(const char* fmt, const Args&... args)
{
    log(log_level_e::error, fmt, std::forward<const Args>(args)...);
}

template<typename... Args>
void warning(const char* fmt, const Args&... args)
{
    log(log_level_e::warning, fmt, std::forward<const Args>(args)...);
}

template<typename... Args>
void info(const char* fmt, const Args&... args)
{
    log(log_level_e::info, fmt, std::forward<const Args>(args)...);
}

template<typename... Args>
void debug(const char* fmt, const Args&... args)
{
    >log(log_level_e::debug, fmt, >std::forward<const Args>(args)...);
}

Now that these functions exist, I think I want to make log() a protected member of the class. But that will break our tests, and I don’t want to do that yet. The other thing to keep in mind is that with the macro form, we can compile out log levels. We can probably think of a way to do that in the base class using some template logic, but that’s another thing I will defer for the moment. For now, we want to make sure the new API direction works.

Since we’ve added std::forward, we must include the corresponding header:

#include <utility>

Now to check our changes. First, we compile and run tests: nothing should fail.

make; ./buildresults/arduino_logger_tests
[5/5] Linking target arduino_logger_tests.
==========================================================
All tests passed (23 assertions in 5 test cases)

Woo!

Test Refactoring

I did bad TDD-ing here, I just made changes without having tests. Let’s correct that and write some tests for the new functions.

We can start by refactoring this test case:

TEST_CASE("Log interface", "[ArduinoLogger]")
{
    CircularLogBufferLogger<1024> l;

    auto expected_size = strlen("Test str") + 1;
    l.log(log_level_e::warning, "Test str"); // <--- Refactor this
    CHECK(expected_size <= l.size());

    // Change level so debug statements should be ignored
    l.level(log_level_e::warning);

    // Logging at an unsupported level should result in no size change
    expected_size = l.size();
    l.log(log_level_e::debug, "Gotcha"); // <--- Refactor this
    CHECK(expected_size == l.size());
}

Instead of .log(), I changed the lines to use the appropriate level-related call:

l.warning("Test str");

I run tests and they still pass. Great. We should check all levels, and perhaps we should make sure each level sets the prefix (e.g., “<!>” for critical).

While I’m looking at the test case above, I also notice that I hate how I calculate the expected_size. We can get an exact size because we know the prefix lengths:

constexpr size_t prefix_len = 4;
constexpr size_t int_prefix_len = 6;

Now we can create nicer tests cases:

const char* test_string = "Test str";
auto expected_size = strlen(test_string) + prefix_len;
l.warning(test_string);
CHECK(expected_size == l.size());

Now, I want to expand that test case to check the output from the buffer for each log level:

log_buffer_output.clear();
logger.critical(test_string);
CHECK(expected_size == logger.size());
logger.flush();
CHECK(log_buffer_output == construct_string(log_level_e::critical, test_string));

Which reveals an error:

../test/ArduinoLoggerTests.cpp:60: FAILED:
  CHECK( log_buffer_output == construct_string(log_level_e::critical, test_string) )
with expansion:
  "<!> Test str" == "!Test str"

Looking over the code, I’d have to leak an internal implementation detail to test this:

fctprintf(&LoggerBase::log_putc_bounce, this, "<%s> ", 
    LOG_LEVEL_TO_SHORT_C_STRING(l));

Instead, I think I should adjust the short name definitions to include the < and > characters:

#define LOG_LEVEL_CRITICAL_PREFIX "<!> "
#define LOG_LEVEL_ERROR_PREFIX "<E> "
#define LOG_LEVEL_WARNING_PREFIX "<W> "
#define LOG_LEVEL_INFO_PREFIX "<I> "
#define LOG_LEVEL_DEBUG_PREFIX "<D> "
#define LOG_LEVEL_INTERRUPT_PREFIX "<int> "

Leaving our prefix log statement as:

fctprintf(&LoggerBase::log_putc_bounce, this, "%s", 
    LOG_LEVEL_TO_SHORT_C_STRING(l));

Now the tests pass.

Other test refactoring I handled while I’m in this file:

• Add distinct test cases for clearing the buffer, flushing the buffer, and run-time filtering
• Rename the file to CircularBufferLoggerTests.cpp
• Create a duplicate test file for AVRCircularBufferLogger
• Createtest_helper.hpp and .cpp files, where I put:
  • _putchar
  • std::string log_buffer_output
  • Definitions for prefix lengths
  • The construct_string helper

Tracing Macros

We’ve corrected our previous bad testing, so let’s apply TDD to the next problem: creating a TRACE() macro.

We’ll create two variants:

1. TRACE(), which prints the current file and line number
2. FUNC(), wich prints the current function

For this, I will create a new test file called CoreLoggerTests.cpp.

First, we’ll define an empty test case and make it fail:

TEST_CASE("TRACE Macro", "[CoreLogger]")
{
    CHECK(true == false);
}

We can see that it fails, so we’re in the build:

../test/CoreLoggerTests.cpp:8: FAILED:
  CHECK( true == false )

Now, before we dive in, let’s experiment and see what our __FILE__ and __LINE__ macros print:

File: ../test/CoreLoggerTests.cpp
Line: 9

Hm. I don’t really want full relative path to the file. I’d prefer just the filename. After some Googling, I found a C++11 approach to generating a short file name during compile-time. I will pull the __SHORT_FILE__ macro and associated code into our logger library. We’ll write a test to make sure it works:

TEST_CASE("Short File Macro", "[CoreLogger]")
{
    CHECK(std::string_view("CoreLoggerTests.cpp") == 
        std::string_view(__SHORT_FILE__));
}

Well, now back to TDD-ing. I want to construct a failing test case that I want to get working. To do this, I should envision how I want my result to look. Let’s go for this format: “CoreLoggerTests.cpp:9”.

TEST_CASE("TRACE Macro", "[CoreLogger]")
{
    std::string_view trace_string{TRACE()};
    std::string compare_string = std::string(__SHORT_FILE__) + ":" 
        + std::to_string(__LINE__ - `);
    CHECK(trace_string == compare_string);
}

Now I compile, and the build fails because I don’t have a TRACE() macro or function:

../test/CoreLoggerTests.cpp:10:32: error: use of undeclared identifier 'TRACE'
        std::string_view trace_string{TRACE()};

I can define a placeholder in my library header. It won’t do anything legitimate yet, because I want to see the build succeed but the test fail.

#define TRACE() "fail"

Checking the test results:

../test/CoreLoggerTests.cpp:10: FAILED:
  CHECK( trace_string == compare_string )
with expansion:
  fail == "CoreLoggerTests.cpp:8"

Great, just what we wanted. Now we can make the TRACE() macro match our expected output. Because we defined __SHORT_FILE__ using a constexpr function, we can’t user the standard string token pasting preprocessor tricks. Instead, we’ll leverage the same constexpr function, but we’ll paste the __LINE__ information before stripping off the directory structure:

#define STRINGPASTE(x) #x
#define TOSTRING(x) STRINGPASTE(x)
#define TRACE() ({constexpr cstr sf__ {past_last_slash(__FILE__ ":" TOSTRING(__LINE__))}; sf__;})

Which leads us to a successful test!

=========================================================
All tests passed (61 assertions in 14 test cases)

FUNC() is a little harder within a Catch test, since this is an example function name:

  void ____C_A_T_C_H____T_E_S_T____2()

So what we need for this test case is a wrapper function with a known name where we can call the macro:

static std::string check_func_name(void)
{
    return std::string(FUNC());
}

The test case will look like this:

TEST_CASE("Func Macro", "[CoreLogger]")
{
    CHECK(std::string_view("check_func_name") == 
        std::string_view(check_func_name()));
}

And as usual with TDD, we’ll end with the implementation, which is a simple wrapper:

#define FUNC() __FUNCTION__

Customizable Formatting

The next feature requested is a customizable formatting prefix for the log statements. Normally, I’d take a policy-based design approach with a template class, but for an Arduino-level library that might be a bit too much. So let’s just use the strategy pattern. We’ll add a virtual custom input function to the interface, and it will represent a step in the overall log() process.

To begin the process, I will start with a refactoring effort. We will give users the option to print something to the log, so we want to simplify the fctprintf call.

Let’s make a wrapper function. It can be public because maybe users want to write something directly to the log, like a TRACE() line.

/// Prints directly to the log with no extra characters added to the message.
template<typename... Args>
void print(const Args&... args) noexcept
{
    fctprintf(&LoggerBase::log_putc_bounce, this, args...);
}

Then we update the calls in log():

// Add our prefix
print("%s", LOG_LEVEL_TO_SHORT_C_STRING(l));

// Send the primary log statement
print(fmt, args...);

The question is: do we want to have the custom format sting appear before or after the level prefix?

[0088381ms] <!> This is a message
<!> [0088381ms] This is a message

I prefer the latter, so I’ll go with that and we’ll see what the client says. If we wanted to be even more customizable, we could add a field before the marker, after the marker, and at the end of the statement. We may get there eventually, but for now I’m sticking with the simplest option: one place for customization.

Then in log() we say:

            // Add our prefix
            print("%s", LOG_LEVEL_TO_SHORT_C_STRING(l));

            log_customprefix();

            // Send the primary log statement
            print(fmt, args...);

Huh, well, this approach will not work with our current printf() echoing. I don’t want to make a duplicate function call for printing.

            if(echo_)
            {
                printf("<%s> ", LOG_LEVEL_TO_SHORT_C_STRING(l));

                // cppcheck-suppress wrongPrintfScanfArgNum
                printf("%s", fmt, args...);
            }

Let’s clean this up a bit. We can merge the if(echo_) check and printf() into print(), resulting in:

/// Prints directly to the log with no extra characters added to the message.
    template<typename... Args>
    void print(const Args&... args) noexcept
    {
        fctprintf(&LoggerBase::log_putc_bounce, this, args...);

        if(echo_)
        {
            // cppcheck-suppress wrongPrintfScanfArgNum
            printf(args...);
        }
    }

Crisis averted.

Updating Examples

We now have greater flexibility in working with the library, so we need examples that showcase different styles of use.

The existing examples work with a global static logger instance and the macros that allow compile-time removal of log statements. They still have value, but now we need to showcase declaring a single instance of a logger class and direct use of the global instance macros.

For our first new example, we’ll interact with the PlatformLogger class directly instead of using macros. We still include platform_logger.h to provide access to the global instance.

#include "platform_logger.h"

static int iterations = 0;

void setup() {
  Serial.begin(115200);
  PlatformLogger::debug("This line is added to the log buffer from setup\n");
}

void loop() {
  // put your main code here, to run repeatedly:
  PlatformLogger::info("Loop iteration %d\n", iterations);
  iterations++;

  if((iterations % 10) == 0)
  {
    printf("Log buffer contents:\n");
    PlatformLogger::flush();
  }

  delay(1000);
}

Our next example will show declaring a local instance of a logger and using it directly.

#include <CircularBufferLogger.h>

CircularLogBufferLogger<512> Log;

static int iterations = 0;

void setup() {
  Serial.begin(115200);
  Log.debug("This line is added to the log buffer from setup\n");
}

void loop() {
  // put your main code here, to run repeatedly:
  Log.info("Loop iteration %d\n", iterations);
  iterations++;

  if((iterations % 10) == 0)
  {
    printf("Log buffer contents:\n");
    Log.flush();
  }

  delay(1000);
}

Now we need to document the usage differences in the README.

Updating Documentation

We need to update the documentation to reflect these changes in the library:

• Using the global logger interface (without macros)
• Declaring and using a local logger instance

I’ll also take this time to fill out a section in the README marked TODO: creating your own logging strategy. This is where I’ll document the new ability to specify a custom prefix in log messages.

Putting it All Together

Well, I think that’s enough for one day. And, coincidentally, as I finish writing this my client is pinging me about the latest changes. He’s interested in converting some of his Serial.Print() calls over to the new log format. Let’s send him the new API and see what he thinks.

In the next article, I’ll also implement two new features to move the project forward: logging to a file on an SD card and time-stamping.

I created a tag to track this point in the project, so you can go look at the code as it is described in this article.

git tag -m "Tagging 0.2.1 with improvements made after 0.2.0 interface update." 0.2.1
git push --tags
Enumerating objects: 22, done.
Counting objects: 100% (22/22), done.
Delta compression using up to 4 threads
Compressing objects: 100% (15/15), done.
Writing objects: 100% (15/15), 3.98 KiB | 1018.00 KiB/s, done.
Total 15 (delta 9), reused 0 (delta 0)
remote: Resolving deltas: 100% (9/9), completed with 7 local objects.
To github.com:embeddedartistry/arduino-logger.git
 * [new tag]         0.2.1 -> 0.2.1

Further Reading

• arduino-logger GitHub Repository
• Building a Printf Library for Arduino
• Building a Flexible Logging Library for Arduino, Part 1
• Building a Flexible Logging Library for Arduino, Part 3
• Arduino Library-to-Library Dependencies
• Teensy 3.6 Dev Board
• Arduino Logging Library