Debugging MicroPython after removing the serial connection can be tricky. We'll explore how to write your MicroPython print statements to log file on an SD card for a typical ESP dev board.

The main goals are:

  • Log to file as soon as possible
    • First to SOC memory
    • Then to SD card
    • Start out with normal prints (log to serial connection)
  • Give logs meaningful name
    • Start out with run count
    • Change to date time name file when information is available

Start a logger right away

While the goal is to log to an SD card file, we still want to see logs before that over the serial connection. So we'll make the logger available ASAP and fall back to normal print statements until a file is available. We'll start out with a very simple logger (/debug/logger.py):

class Logger:
    def __init__(self) -> None:
        print('logger init')
        super().__init__()

    def print(self, *args):
        print(*args)

The Logger instance is needed throughout your app, so we'll store it as a singleton (/singletons.py):

from debug.logger import Logger

_logger = Logger()


def get_logger():
    if not _logger:
        raise Exception('logger not yet set')
    return _logger

To use it we simply need to do (/main.py):

from singletons import get_logger  # Returns singleton Logger instance
logger = get_logger()
logger.print('We are in business')

Run counter

To distinguish between subsequent logs we can include the run count in the log name. We'll need to get that count from somewhere that can survive reset and power cycles. So let's store the run count in a file.

The BootCounter class (debug/boot_counter.py) does this as follows:

/main.py:

from singletons import get_logger  # Returns singleton Logger instance


class BootCounter:
    count = 1

    def __init__(self, path) -> None:
        super().__init__()

        logger = get_logger()
        logger.print('opening file: ', path)
        try:
            file = open(path, 'r')
            try:
                line = file.readline()
                if not line:
                    logger.print('no boot count found, starting from 1')
                    self.count = 1
                else:
                    try:
                        count = int(line)
                        logger.print('read count from file: ', count)
                        self.count = count + 1
                    except Exception as e:
                        logger.print('error reading line: ', line, e)
                        self.count = 1

            except Exception as e:
                logger.print('problem processing boot count file', e)
            finally:
                file.close()
        except OSError as e:
            logger.print('problem opening file for reading', path, e)

        try:
            file = open(path, 'w')
            try:
                file.write(str(self.count))
                logger.print('boot count written: ', self.count)
            except Exception as e:
                logger.print('problem writing boot count', e)
            finally:
                file.close()
        except OSError as e:
            logger.print('problem opening file for writing', path, e)

There's a lot going on in the BootCounter. The gist is to start counting on 1 if our counter file is not found or is unreadable. And when read we increment the count and try to write it back to file.

This can be run using:

from singletons import get_logger  # Returns singleton Logger instance
from debug.boot_counter import BootCounter

logger = get_logger()
logger.print('main.py called')

boot_count_path = '/boot_count'
counter = BootCounter(boot_count_path)

log_file = f'log-{counter.count}.txt'
logger.print(log_file)

On the first run the file will not exist:

MPY: soft reboot
logger init
main.py called
opening file:  /boot_count
problem opening file for reading /boot_count [Errno 2] ENOENT
boot count written:  1
log-1.txt

On subsequent runs we use the counter is read and incremented:

MPY: soft reboot
logger init
main.py called
opening file:  /boot_count
read count from file:  1
boot count written:  2
log-2.txt

And in case the boot_count file is unreadable (in this example it contains "abc"), we'll fall back to count 1 and start over:

MPY: soft reboot
logger init
main.py called
opening file:  /boot_count
error reading line:  abc invalid syntax for integer with base 10
boot count written:  1
log-1.txt

Write logs to SD card with SOC memory fallback

The Logger class will keep track of the file it is writing to and use that if available. First the open_log_file function should be called. After that the log file can be moved. The log contents are copied over manually. This prevented a occasional EPERM error I was having on my board. In your case you might get away with a simple os.rename(old_path, new_path) call.

The full Logger class code (/debug/logger.py):

import os


class Logger:
    _path = None
    _file = None

    def __init__(self) -> None:
        print('logger init')
        super().__init__()

    def open_log_file(self, path):
        """
        Write to initial log file
        """
        self._path = path
        self.print('opening log file: ' + self._path)
        self._file = open(self._path, 'w')
        self.print('logger log file opened')

    def move_file(self, new_path):
        """
        Move logs to another file, manually copies over file line by line
         because `os.rename` sometimes errors out with a "EPERM" exception on my chip
        """
        self.print('moving log file to: ' + new_path)
        try:
            self._file.close()
            self._file = None
            old_path = self._path
            self._path = None
            try:
                old_file = open(old_path, 'r')
                new_file = open(new_path, 'w')
                lines = old_file.readlines()
                for line in lines:
                    new_file.write(line)
                self._file = new_file
                self.print('log file moved: ', old_path, ' -> ', new_path)
                self._path = new_path
            finally:
                old_file.close()
            os.remove(old_path)
        except Exception as e:
            self.print('failed to move logs: ', e)
            self._file = None
            self._path = None

    def print(self, *args):
        message = ''
        for x in args:
            message += str(x) + ' '
        if self._file:
            print(message)  # Also print so can be seen when debugging using serial connection
            self._file.write(message + '\n')
            self._file.flush()  # We want our logs to be written immediately
        else:
            print('No log file yet, msg: ', message)

The main limitations here is that any logs written before writing to a file are not written to file. And your main SOC memory main fill up quickly depending on your situation. For me those limitations are acceptable, but you should quite quickly be able to remedy both.

Now that we have the Logger, we'll write the log to the onboard memory. That way you can catch errors in the SD card mounting process and so on. After that we can move our log files to the SD card.

The following code uses 3 log files. First a temporary file is created with the run count in the name on the SOC memory. This is then moved to a temporary file with the same name on the SD card. Finally, we set the ESP real time clock using the internet and the NTP protocol. After that we can get the date and time and use that in the name for another file on the SD card.

Here is how it all comes together (/main.py):

import time
from config import config
from connectivity.sd import mount_sd
from connectivity.time import set_ntp_time
from connectivity.wifi import connect_ssid
from debug.boot_counter import BootCounter
from singletons import get_logger
from util.folder import mkdir_if_not_exist

logger = get_logger()

logger.print('*** Not yet written to file ***')
counter = BootCounter('/boot_count')

mkdir_if_not_exist('/log')
logger.open_log_file(f'/log/run-{counter.count}.txt')
logger.print('*** written to SOC memory temporary file ***')

sd = mount_sd('/sd')
mkdir_if_not_exist('/sd/log')
logger.move_file(f'/sd/log/run-{counter.count}.txt')
logger.print('*** written to SD temporary log file ***')

connect_ssid(config.get('SSID'), config.get('PW'))
secs = set_ntp_time()
[year, month, mday, hour, minute, second, _, _] = time.localtime(secs)
name = f'{year}-{month}-{mday}-{hour}h{minute}m{second}s-run-{counter.count}.txt'
log_dir_path = '/sd/log'
new_path = f'/sd/log/{name}'
logger.move_file(new_path)

logger.print('*** written to SD card datetime log file ***')

Running the above (for the 39th time) produced:

  1. temp file /log/run-39.txt
  2. temp file /sd/log/run-39.txt, and
  3. the final file /sd/log/2022-1-6-20h19m13s-run-39.txt

The contents of the final log file

logger log file opened 
*** written to SOC memory temporary file *** 
setting SDCard pins 
mounting 
sd contents:  ['.Spotlight-V100', 'config.json', 'log', '.Trashes'] 
Creation of the directory /sd/log failed (probably exists) 
moving log file to: /sd/log/run-39.txt 
log file moved:  /log/run-39.txt  ->  /sd/log/run-39.txt 
*** written to SD temporary log file *** 
connecting to network... 
network config: .... 
setting rtc time set using ntp server... 
time set, secs:  694815553 , local:  (2022, 1, 6, 20, 19, 13, 3, 6) 
moving log file to: /sd/log/2022-1-6-20h19m13s-run-39.txt 
log file moved:  /sd/log/run-39.txt  ->  /sd/log/2022-1-6-20h19m13s-run-39.txt 
*** written to SD card datetime log file *** 

With that you should have logging in your application that can be easily checked by reading the SD card. I hope these code snippets helped you out. Please let me know if it did or let me know of problems via Twitter.

And in case you are wondering, here are some of the utility functions used:

Util functions

Here is the code used to do some common stuff. The code isn't trying to catch every exception and such, but it should get the job done.

Mount sd card

Mounting an SD card is a matter of finding out which pins you need to use. For the Wemos Lolin D32 PRO those are pins 4, 18, 19, 23:

/connectivity/sd.py:

import os, machine
from singletons import get_logger

logger = get_logger()


def mount_sd(mount_dir):
    """
    SD Mounting code for Wemos Lolin D32 PRO
    :param mount_dir: path string, e.g.: /sd
    :return:
    """
    logger.print('setting SDCard pins')
    try:
        sd = machine.SDCard(slot=2, sck=18, mosi=23, miso=19, cs=4)
    except OSError as e:
        if e.errno == -259:
            logger.print('error: -259, SPI already in use')  # Happens sometimes on soft reboot
            logger.print('resetting')
            machine.reset()
    logger.print('mounting')
    os.mount(sd, mount_dir, readonly=False)
    logger.print('sd contents: ', os.listdir(mount_dir))
    return sd

Create directory if not yet existing

/util/folder.py:

import os
from singletons import get_logger

logger = get_logger()


def mkdir_if_not_exist(path):
    try:
        os.mkdir(path)
    except OSError:
        logger.print("Creation of the directory %s failed (probably exists)" % path)

Connect to WiFi

/connectivity/wifi.py:

from singletons import get_logger

logger = get_logger()


def connect_ssid(ssid, pw):
    if not ssid or not pw:
        logger.print('missing ssid/pw: ', ssid, pw)
        return
    import network
    wlan = network.WLAN(network.STA_IF)
    wlan.active(True)
    if not wlan.isconnected():
        logger.print('connecting to network...')
        wlan.config(reconnects=2)
        wlan.connect(ssid, pw)
        while not wlan.isconnected():
            pass
    logger.print('network config:', wlan.ifconfig())

Set time using NTP library

/connectivity/time.py:

import ntptime
import time
from singletons import get_logger

logger = get_logger()


def set_ntp_time():
    logger.print('setting rtc time set using ntp server...')
    ntptime.settime()
    secs = time.time()
    logger.print('time set, secs: ', secs, ', local: ', time.localtime(secs))
    return secs