Logging to help with troubleshooting. Raspberry Pi Pico and Micropython centric

Alrighty… Let’s get the obvious part of the discussion on this topic out of the way…

There are a wide range of possible mechanisms for troubleshooting depending on the skill level of the practitioner, the complexity of the code and the capabilities of the platform. In short, you will ultimately fall to using the techniques that work for you the best depending on your circumstances.

I am capturing the description of this method, not because I think it is the best or even if I think that it’s advisable. It suited me for a task and so I believed that it might suit me again at some time in the future. Therefore I thought I should write this down so that I don’t forget what the code does, and what better place to write it down than in a book :-).

This particular piece of code is written to capture notes as our Micropython code executes and to write those notes into a log file so that we can examine them at a later date. The particular occasion I needed something like this was when I had a Pico that would run for many days and would then fail. I couldn’t determine why it was failing, and so I decided that a piece of code that would write lines to a file so that I could see when and where the failure occurred would be a good start.

Therefore, the way this piece of code would be used is if we place the initial set-up and function definition at the start of the program we are troubleshooting and then we place the small note capturing code at various places where we want to know that the program has gotten to or looking at values that we want to check.

It captures the time that the event is written, the size of the log file and the message that we want to pass to it. This message can be text and / or values.

Enough talk, this is what it looks like;

import os
from machine import RTC

rtc = RTC()
rtc.datetime()

#Check to see if file present and create if necessary
try:
    os.stat('/log.dat')
    print("File Exists")
except:
    print("File Missing")
    f = open("log.dat", "w")
    f.close()
    
def log(loginfo:str):
    # Format the timestamp
    timestamp=rtc.datetime()
    timestring="%04d-%02d-%02d %02d:%02d:%02d"%(timestamp[0:3] +
                                                timestamp[4:7])
    # Check the file size
    filestats = os.stat('/log.dat')
    filesize = filestats[6]

    if(filesize<200000):
        try:
            log = timestring +" "+ str(filesize) +" "+ loginfo +"\n"
            print(log)
            with open("log.dat", "at") as f:
                f.write(log)
        except:
            print("Problem saving file")

# sample usage
val = 456
text = "some information"
combo = text + " " + str(val)
log(combo)

To make life easier for future me (and hopefully you) here’s the description of some of the parts.

We import the os module and RTC from machine

import os
from machine import RTC

rtc = RTC()
rtc.datetime()

This is so that we can us the os module to determine the size of the file we are generating and to make sure that we don’t write so large a file that it overwhelms our available storage.

RTC is used to generate a timestamp so that we know when an event occurs. Of course, if we don’t set the time initially, we are going to be left with a time stamp that starts at 2021-01-01 00:00:00. We could connect to NTP time first if we had a network connection, but that’s not always going to be available. This way we will at least have a feel for how our comments are being captured relative to each other and the time that the program started. There are several different time modules that we could use to do this. time, utime, and possibly others. Each has some slight differences in terms of the start of the timestamp or similar, and I fell on RTC. It does the job.

If the file that we’re going to use for capturing our information doesn’t exist, we need to create it.

#Check to see if file present and create if necessary
try:
    os.stat('/log.dat')
    print("File Exists")
except:
    print("File Missing")
    f = open("log.dat", "w")
    f.close()

The first use of the open command to append information to a file will create the file if it doesn’t exist, but we will want to check the size of the file before we write anything to it, so this small piece of code checks for its existence and if it isn’t there creates it.

Then we get into the function definition.

We find the time and format it as a string in a nice tidy format. For those of you who are writing your dates in a dd/mm/yyyy format, using the alternative of yyyy/mm/dd makes it easier to sort.

    # Format the timestamp
    timestamp=rtc.datetime()
    timestring="%04d-%02d-%02d %02d:%02d:%02d"%(timestamp[0:3] +
                                                timestamp[4:7])

We can then check out the file size;

    # Check the file size
    filestats = os.stat('/log.dat')
    filesize = filestats[6]

The os.stat call responds with a range of different metrics (not all of which are applicable for every platform). The one we want is accessed as [6] in the array.

After checking to make sure that our file hasn’t grown too large we combine the time, the size of the file and the information that we want to note specifically (this comes from then individual calls to the function in the program).

            log = timestring +" "+ str(filesize) +" "+ loginfo +"\n"
            print(log)
            with open("log.dat", "at") as f:
                f.write(log)

We also add a newline "\n" in to break the lines up.

The final block of the code is the piece that we would put in a range of places in our program to capture information.

# sample usage
val = 456
text = "some information"
combo = text + " " + str(val)
log(combo)

This is obviously just a sample, but we have a value val that could be any number used in the program and a comment some information that again could be something that acts as a reference for that portion of the code that we’re wanting to know something about. For example, it could be when the program starts and then when the device connects to the network, and then if it strikes an error in reading a value from a sensor.