Building a Flexible Logging Library for Arduino, Part 3

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, I received client feedback and changed the initial library design.

Today, we will add a new strategy for logging to an SD card.

Table of Contents:

  1. Refactoring the Default Implementations
  2. SD Logger
    1. Exploration
    2. Implementation
  3. Building Our Example
  4. Refactoring, Again
  5. Documentation
  6. Putting it All Together
  7. Further Reading

Refactoring the Default Implementations

Before adding any new features, I want to take a moment to refactor the existing design. The goal of the refactor is to reduce boilerplate code when adding a new strategy.

Rather than forcing every derived class to implement their own size, capacity, flush, and clear (because they are pure virtual functions), we are going to supply default implementations. Users can override the default behaviors with custom behavior.

The size and capacity functions will return an invalid value in the default implementation. AsI write this, I’m feeling less strongly about defaults here: perhaps every derived class should have to override these functions. If it ends up being problematic, I can adjust it later.

 virtual size_t size() const noexcept
    {
        return -1;
    }

    virtual size_t capacity() const noexcept
    {
        return -1;
    }

The flush and clear function defaults are simply no-ops, like log_customprefix.

 virtual void flush() noexcept {}
    virtual void clear() noexcept {}

SD Logger

The main bulk of today’s work is adding a new logging strategy. The client’s primary aim is to write the logs to an SD card.

The client is using the Teensy 3.6 platform. We’ll base our strategy off of the SDFat-beta library because of its SDIO and Teensy support.

Exploration

I haven’t used the SdFat beta library before, so I’m not sure how it works. Before I dive into my implementation, I need to explore the library to understand it better. Luckily, the library provides a Teensy SDIO example.

First, I ran the sketch and compared the multiple communication strategies. SDIO seems to be the best route from a write speed perspective.

Looking through the example code, these snippets all stand out as something we will incorporate into our logging strategy:

// These types will be needed
SdFs sd;
FsFile file;

// We need to call sd.begin()
sd.begin(SdioConfig(FIFO_SDIO)

// When we open a file, we want to add O_APPEND and use O_WRITE instead of RDRW
if (!file.open("TeensyDemo.bin", O_RDWR | O_CREAT)) { 
    errorHalt("open failed"); 
} 

// We can truncate
file.truncate(0)

// Here's how we would write our log buffer buffer to the file:
if (nb != file.write(buf, nb)) { 
        errorHalt("write failed"); 
} 

// We will need to close the file
file.close()

Now that we’ve seen how the library operates and identified key lines of code from the example sketch, we can dive into creating our class.

Implementation

For the initial pass, we’ll create an SD Logger that uses a circular buffer and writes to a single file. This is the simplest use case. Once we’re confident in the basic operation, we can add log rotation support.

We will keep our default constructor:

SDFileLogger() : LoggerBase() {}

We will define a standard filename:

const char* filename_ = "log.txt";

I imported the example code’s errorHalt function as a private function within the class. This function can be called when an error condition is detected. We read the error code from the SD card filesystem object, output text via printf, and spin in an infinite loop.

I included the errorHalt function for debugging purposes. Since I’m not familiar with the library, mistakes are likely to occur.

This function needs the instance of the SD class, which tells me that I need to store the pointer to the filesystem object as a private member variable.

void errorHalt(const char* msg)
{
    printf("Error: %s\n", msg);
    if (fs_->sdErrorCode())
    {
        if (fs_->sdErrorCode() == SD_CARD_ERROR_ACMD41)
        {
            printf("Try power cycling the SD card.\n");
        }
        printSdErrorSymbol(&Serial, fs_->sdErrorCode());
        printf("ErrorData: 0x%x\n", fs_->sdErrorData());
    }
    while (true) {}
}

We also need to open the log file when the device boots up, clearing its contents if it already exists. We’ll keep with Arduino tradition and add a begin() member function that handles these needs.

Note that begin takes in an SdFs instance. We expect the user to initialize the filesystem before passing it to the begin function. This is where we’ll set the value of our private fs_ member variable.

void begin(SdFs& sd_inst)
{
    fs_ = &sd_inst;

    if (file_.open(filename_, O_WRITE | O_CREAT))
    {
        errorHalt("Failed to open file");
    }

    // Clear current file contents
    file_.truncate(0);

    file_.close();
}

I began the logging implementation by copying over our circular log buffer logic. I also added the required log buffer data members. I hard-coded the size to 512 bytes for now. Once the functionality is tested, we can refactor the design so users can specify the size.

private:
  char buffer_[512] = {0};
  stdext::ring_span<char> log_buffer_{buffer_, buffer_ + 512};

The idea for this implementation will be to log to a circular log buffer in memory. Whenever the buffer fills up, or whenever a user manually calls flush, the contents of the buffer will be written to the log file.

I want to start with an easy case, so I’m just going to write the underlying buffer_ contents to the file rather than worrying about properly wrapping text in the circular buffer. We can refine the approach once we know the overall strategy functions correctly.

void flush() noexcept final
{
    if (!file_.open(filename_, O_WRITE | O_APPEND))
    {
        errorHalt("Failed to open file");
    }

    auto count = size();
    if(count != file_.write(buffer_, count))
    {
        errorHalt("Failed to write to log file");
    }

    file_.close();
}

This is an opportunity to exercise the custom prefix functionality by printing millis() into the log:

void log_customprefix() noexcept final
{
    print("[%d ms]", millis());
}

Building Our Example

We’re using an Arduino library with Teensy hardware, so let’s test the functionality out by creating an example sketch.

First, we need to include our logger class and make sure everything compiles:

#include "SDFileLogger.h"

So far, so good. Next, we’ll expand our test sketch to initialize Serial port and the SD card:

#include "SDFileLogger.h"

SdFs sd;

void setup()
{
    Serial.begin(115200);
    sd.begin(SdioConfig(FIFO_SDIO));
}

void loop()
{

}

Everything is still working, so now we add our logger:

#include "SDFileLogger.h"

SDFileLogger Log;
SdFs sd;

void setup()
{
  Serial.begin(115200);
  sd.begin(SdioConfig(FIFO_SDIO));
  Log.begin(sd);
}

void loop()
{

}

That compiles. Now we can build out a full sketch with log statements. We’ll also enable echo-to-console support so we can see log statements over Serial.

Here’s our final example sketch:

#include "SDFileLogger.h"

static SDFileLogger Log;
static SdFs sd;
static int iterations = 0;

void setup()
{
  Serial.begin(115200);
  sd.begin(SdioConfig(FIFO_SDIO));
  Log.begin(sd);
  Log.echo(true);
  Log.debug("Finished with setup(), first log statement to SD card\n");
}

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

  if((iterations % 10) == 0)
  {
    Log.flush();
  }

  delay(1000);
}

When I run the example, I see log statements printed to the Serial console (with timestamps!), and there is a log.txt file on the SD card. Let’s look at the contents:

<D> [312 ms] Finished with setup(), first log statement to SD card
<I> [312 ms] Loop iteration 0
<I> [1312 ms] Loop iteration 1
<I> [2312 ms] Loop iteration 2
<I> [3312 ms] Loop iteration 3
<I> [4312 ms] Loop iteration 4
<I> [5312 ms] Loop iteration 5
<I> [6312 ms] Loop iteration 6
<I> [7312 ms] Loop iteration 7
<I> [8312 ms] Loop iteration 8
<I> [9312 ms] Loop iteration 9
[14318 ms] Loop iteration 14
<I> [15318 ms] Loop iteration 15
<I> [16318 ms] Loop iteration 16
<I> [17318 ms] Loop iteration 17
<I> [18318 ms] Loop iteration 18
<I> [19318 ms] Loop iteration 19
[4312 ms] Loop iteration 4
<I> [5312 ms] Loop iteration 5
<I> [6312 ms] Loop iteration 6
<I> [7312 ms] Loop iteration 7
<I> [8312 ms] Loop iteration 8
<I> [9312 ms] Loop iteration 9
<I> [10318 ms] Loop iteration 10
<I> [11318 ms] Loop iteration 11
<I> [12318 ms] Loop iteration 12
<I> [13318 ms] Loop iteration 13
<I> 

Woo! Progress!

Our logging statements made it to the log file, but they are out of order – as we expected. We used a circular buffer but printed the underlying data buffer without handling positioning or wrapping. That was a good-enough approach for testing, but that’s not a shippable solution.

Refactoring, Again

Rather than using a circular buffer, we’ll emulate a basic queue using a raw array and a counter.

char buffer_[BUFFER_SIZE] = {0};
size_t counter = 0;

We need to adjust log_putc() to match the new approach. We should also take a moment to add auto-flushing logic.

void log_putc(char c) noexcept final
{
  buffer_[counter] = c;
  counter++;

  if(counter == BUFFER_SIZE)
  {
    flush();
  }
}

The clear function becomes much simpler:

void clear() noexcept final
{
    counter = 0;
}

We also need to update the flush function:

void flush() noexcept final
{
    if (!file_.open(filename_, O_WRITE | O_APPEND))
    {
        errorHalt("Failed to open file");
    }

    if(counter != file_.write(buffer_, counter))
    {
        errorHalt("Failed to write to log file");
    }

    counter = 0;
    file_.close();
}

Hm, the compiler threw an error. Apparently additional interfaces need to be updated:

arduino-logger/src/SDFileLogger.h:33:10: error: 'log_buffer_' was not declared in this scope
   return log_buffer_.size();
          ^
arduino-logger/src/SDFileLogger.h: In member function 'virtual size_t SDFileLogger::capacity() const':
arduino-logger/src/SDFileLogger.h:38:10: error: 'log_buffer_' was not declared in this scope
   return log_buffer_.capacity();

We’ll adjust size to give us the total size of the file, and capacity to reflect the size of the size of the SD card.

size_t size() const noexcept final
{
    return file_.size();
}

size_t capacity() const noexcept final
{
    // size in blocks * bytes per block (512 Bytes = 2^9)
    return fs_ ? fs_->card()->sectorCount()<< 9 : 0;
}

Now let’s see how our log looks:

<D> [456 ms] Finished with setup(), first log statement to SD card
<I> [456 ms] Loop iteration 0
<I> [1456 ms] Loop iteration 1
<I> [2456 ms] Loop iteration 2
<I> [3456 ms] Loop iteration 3
<I> [4456 ms] Loop iteration 4
<I> [5456 ms] Loop iteration 5
<I> [6456 ms] Loop iteration 6
<I> [7456 ms] Loop iteration 7
<I> [8456 ms] Loop iteration 8
<I> [9456 ms] Loop iteration 9
<I> [10462 ms] Loop iteration 10
<I> [11462 ms] Loop iteration 11
<I> [12462 ms] Loop iteration 12
<I> [13462 ms] Loop iteration 13
<I> [14462 ms] Loop iteration 14
<I> [15462 ms] Loop iteration 15
<I> [16462 ms] Loop iteration 16
<I> [17462 ms] Loop iteration 17
<I> [18463 ms] Loop iteration 18
<I> [19463 ms] Loop iteration 19

That’s the proper order, so let’s document the new strategy and ship it!

Documentation

We must update the README with two new pieces of information:

  • Notes on the new SDFileLogger class
  • Notes on the new example we created

Putting it All Together

I always like to stop at a shippable point to make a release. This allows me to get code to my clients as early as possible for testing, review, and feedback. We also have a reliable checkpoint to return to if something breaks down during future development efforts.

While working on this article, my client asked me whether the SD logging strategy would support an Arduino Mega (it doesn’t!). He also asked whether we can get a reboot reason added to the logging library. We’ll tackle those two tasks in the next article.

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.3.0 with SD file logging support" 0.3.0
git push --tags
Enumerating objects: 21, done.
Counting objects: 100% (21/21), done.
Delta compression using up to 4 threads
Compressing objects: 100% (15/15), done.
Writing objects: 100% (16/16), 3.12 KiB | 1.56 MiB/s, done.
Total 16 (delta 9), reused 0 (delta 0)
remote: Resolving deltas: 100% (9/9), completed with 5 local objects.
To github.com:embeddedartistry/arduino-logger.git
 * [new tag]         0.3.0 -> 0.3.0

Further Reading

Share Your Thoughts

This site uses Akismet to reduce spam. Learn how your comment data is processed.