Logging to an SD memory card on a Teensy 4.1

While my robot “Raven” uses MicroRos to communicate between my TeensyMonitor board, which is based on a Teensy 4.1 device, there are times when software faults happen and the information I need to debug the fault doesn’t get transmitted as a ROS message. To overcome that, I have a software module on the TeensyMonitor board that logs a lot of information to an SD memory card. After a fault is detected, I can pull that memory card off from the TeensyMonitor board and plug it into another computer and look at the text log files for diagnostic information.

A problem with the built-in SD card on the Teensy 4.1, using the Arduino SD library is that the availableForWrite function always returns zero, so the example code for non-blocking I/O doesn’t work. This means that writes to the card necessarily block until complete. In a robot, any operation that takes a long time can be hazardous to the safety of the robot. In my library, while not eliminating the problem I attempt to reduce the problem by writing data in 4K byte chunks to the SD card. The result is that my average loop calls per second reduces from around 200 loop calls per second to about 175. This, of course, is specific to the work I do per loop call, which involves reading over a dozen sensors and sending as well as receiving messages via MicroRos.

A previous article explained my use of TModule in my software stack, which injects software module performance monitoring into each of my modules, so I won’t explain that framework again here. To use this logging module, you initialize it simply by including one line of code in you main “.ino” file, namely

TSd& sd = TSd::singleton();

Then you add lines to the log file via a call like:

TSd::singleton().log("INFO [MyModule::myFunction] Some message here");

Which will write to the log file a line similar to:

[0000111.428] INFO MyModule::myFunction] Some message here

Where the number in brackets is the number of milliseconds that have elapsed since the Arduino started up.

Here is the header file, “tsd.h” for the module:

#pragma once

#include <Regexp.h>
#include <SD.h>

#include "tmodule.h"

// A class used to write logging information to an SD memory card.
//
// On setup, the SD card is examined for any existing files with names like
// "LOG12345.TXT", where "12345" is a 5-digit serial number. A new log file
// will be created on the card with a name having a serial number of one higher
// than any existing log file name,or LOG00001.TXT if no existing log files
// were found.
//
// Every time TSd::singleton().log() is called, the message is added to a
// string buffer. When the buffer becomes full enough, it is written as one
// large chunck of text to the log file. This is done so that lots of little
// writes are done, which would slow down the outer loop of the Arduino device.
//
// The downside is that if the card is pulled from the Arduino device, the last
// chunk of text won't have been written to the device. Currently, there is a fair 
// number of things written to the log file so if you just wait a few seconds before
// pulling the card, the interesting thing you were looking for in the log file may
// have been actually successfully written to the file before you pulled the card.
//
// This is intended to be used the the TModule software module as part of the
// TeensyMonitor stack. So all you need to do to instantiate and get this module
// going is to call TSd::singleton() in your ".ino" file before calling TModule::setup().
//
// If a write to the card fails, perhaps because the card is full or the card has been
// pulled from the Arduino device, further writes are not attempted until the system
// is restarted.

class TSd : TModule {
 public:
  // Write message to log file.
  void log(const char* message);

  // Singleton constructor.
  static TSd& singleton();

 protected:
  // From TModule.
  void loop();

  // From TModule.
  virtual const char* name() { return "TSd"; }

  void setup();

 private:
  // Private constructor.
  TSd();

  static void regexpMatchCallback(const char* match, const unsigned int length,
                                  const MatchState& matchState);

  // Used to hold a big chunk of data so writes are fewer.
  String data_buffer_;

  // The SD card device.
  static SDClass g_sd_;

  // Used to find to highest log file number already on the SD card.
  static int g_highestExistingLogFileNumber_;

  // Has SD device been properly initialized?
  static bool g_initialized_;

  // The file handle for the log file on the SD card device.
  static File g_logFile_;

  // Singleton instance.
  static TSd* g_singleton_;
};

Here the the body file, “tsd.cpp”

#include "tsd.h"

#include <Arduino.h>
#include <Regexp.h>
#include <SD.h>
#include <stdint.h>

// #include "tmicro_ros.h"

void TSd::log(const char* message) {
  static const unsigned int kChunkSize = 4096;
  if (g_initialized_) {
    char log_message[256];
    uint32_t now = millis();
    snprintf(log_message, sizeof(log_message), "[%07ld.%03ld] %s\n", now / 1000,
             now % 1000, message);
    data_buffer_ += log_message;
    if (data_buffer_.length() >= kChunkSize) {
      size_t bytes_written = g_logFile_.write(data_buffer_.c_str(), kChunkSize);
      if (bytes_written > 0) {
        g_logFile_.flush();
      } else {
        // Assume the card has been removed or is failing.
        g_initialized_ = false;
      }

      data_buffer_.remove(0, kChunkSize);
    }
  }
}

void TSd::loop() {}

void TSd::regexpMatchCallback(const char* match, const unsigned int length,
                              const MatchState& matchState) {
  char regexMatchString[10];  // Big enough to hold 5-digit file serial number.
  matchState.GetCapture(regexMatchString, 0);  // Get 0-th match from regexp.
  int logSerialNumberAsInt = atoi(regexMatchString);
  if (logSerialNumberAsInt > TSd::g_highestExistingLogFileNumber_) {
    TSd::g_highestExistingLogFileNumber_ = logSerialNumberAsInt;
  }
}

void TSd::setup() {
  data_buffer_.reserve(8192);
  g_highestExistingLogFileNumber_ = 0;
  g_initialized_ = false;
  if (!g_sd_.begin(BUILTIN_SDCARD)) {
    // ERROR Unable to access builtin SD card.
  } else {
    File rootDirectory = g_sd_.open("/");
    while (true) {
      File nextFileInDirectory = rootDirectory.openNextFile();
      if (!nextFileInDirectory) break;
      char fileName[256];
      strncpy(fileName, nextFileInDirectory.name(), sizeof(fileName));
      MatchState matchState;
      matchState.Target(fileName);
      matchState.GlobalMatch("LOG(%d+).TXT", regexpMatchCallback);
    }

    char
        newLogFileName[20];  // Big enough to hold file name like: LOG12345.TXT.
    sprintf(newLogFileName, "LOG%05d.TXT", ++g_highestExistingLogFileNumber_);
    g_logFile_ = g_sd_.open(newLogFileName, FILE_WRITE);
    if (!g_logFile_) {
      char diagnosic_message[128];
      snprintf(diagnosic_message, sizeof(diagnosic_message),
               "ERROR [TSd::setup] Unable to create new log file: '%s'",
               newLogFileName);
    } else {
      g_initialized_ = true;
      ;
    }
  }
}

TSd::TSd() : TModule(TModule::kSd) {}

TSd& TSd::singleton() {
  if (!g_singleton_) {
    g_singleton_ = new TSd();
  }

  return *g_singleton_;
}

SDClass TSd::g_sd_;

int TSd::g_highestExistingLogFileNumber_ = 0;

bool TSd::g_initialized_ = false;

File TSd::g_logFile_;

TSd* TSd::g_singleton_ = nullptr;