Controlling output using Adafruit Logger in CircuitPython

Print statements are the standard debugging and tracing tool for programs running on microcontrollers in non-real-time sections of code. Print statements are a great tool to generate basic output as long as you always want the output and always want the output to go to a serial port.  

Use the logger if you want to be able to turn print statements on and off without having to continually re-comment and de-comment them.

The Adafruit logging library lets you throttle your log output reducing the amount generated. It lets categorize your logging criticality with levels like DEBUG, INFO, WARN, ERROR, etc.  The logger then lets you set the minimum level of criticality for messages to actually be emitted.  If you set your filter level at WARN then no DEBUG or INFO messages show up in the logs/console. This can speed up an application and reduce resource usage while retaining the ability to enable more information if you need it. 

The logging library also lets you treat that log output as a datastream that can be sent somewhere else like an SD card or an alternate UART. 

This chart shows how logging is used in the sample program referenced below.

References

Installing Logging

Install adafruit_logging.mpy in your controller's /lib directory.  You can download the appropriate zip file containing it from the Adafruit GitHub site. this is how it looks on my Windows machine.

Configuring Logging

You must import the logging library and initialize it. The library supports multiple independently configure loggers in case you want different levels or different logging targets in your program.  I only needed one logger with all the output going to the USB serial port.

I created the logger once and injected the logger instance into every class or function where I use it. 

import adafruit_logging as logging

logger = logging.getLogger("main")
logger.setLevel(logging.INFO)

main(target_neopixels, num_neopixels, default_step, logger)

Here I injected the logger it into main() that then logged messages using   logger.info()   logger.debug()  and logger.error().  The logger has been configured at the INFO level. 

  • logger.info()  and logger.error() messages appear while logger.debug()  are filtered out.
  • logger.debug()  message in the text will appear if we change the logging filter level to logging.DEBUG

def main(neopixel_pin, neopixel_count, default_step, logger):
    logger.info("type something and press and hit enter (newline)")
    ...
    ...
...
    if mystr.startfswith("#"):
...
        logger.debug(f"patterns: {patterns}")
...
    else:
        logger.error(f"Unrecognized command: '{mystr}'")

Sample Output

Sample output with the same commands at two different logging levels

Logging at INFO level

logger.setLevel(logging.INFO)
  1. The request for help resulted in print() driven output.  
  2. There is no debug() output.
  3. We see an error() message when bad input was provided
code stopped by auto-reload. Reloading soon.
soft reboot

Auto-reload is on. Simply save files over USB to run them or enter REPL to disable.
main.py output:
55850.468: INFO - type something and press and hit enter (newline)
?
Usage: [?|#|B|G|LI|LD] ?: help B: blank G: get current #nnrrggbb-msec LD: logger.DEBUG LI: logger.INFO
#FF000404-300
#FF202000-800-#FF000404-300

55968.356: ERROR - Unrecognized command: ''



Logging at DEBUG level

logger.setLevel(logging.DEBUG)
  1. The request for help resulted in print() driven output.  
  2. We see an error() message when bad input was provided
  3. The logging level is changed on the fly to DEBUG
  4. DEBUG level messages appear for accepting the input and for state changes
Code stopped by auto-reload. Reloading soon.
soft reboot

Auto-reload is on. Simply save files over USB to run them or enter REPL to disable.
main.py output:
56249.313: INFO - type something and press and hit enter (newline)
?
Usage: [?|#|B|G|LI|LD] ?: help B: blank G: get current #nnrrggbb-msec LD: logger.DEBUG LI: logger.INFO
  #nnrrggbb-msec#nnrrggbb-msec Ex: #ff400000-1000#ff000040-1000

55968.356: ERROR - Unrecognized command: ''
LD
#FF000404-300
56281.967: DEBUG - patterns: ['', 'FF000404-300']
56281.981: DEBUG - processing: FF000404-300
56281.981: DEBUG - Received: (255,(0, 4, 4),300)
56282.001: DEBUG - active_patterns: [(255,(0, 4, 4),300,0)]
56282.001: DEBUG - Updating: (255,(0, 4, 4),300)
#FF202000-800-#FF000404-300
56294.203: DEBUG - patterns: ['', 'FF202000-800-', 'FF000404-300']
56294.203: DEBUG - processing: FF202000-800-
56294.217: DEBUG - Received: (255,(32, 32, 0),0)
56294.217: DEBUG - active_patterns: [(255,(32, 32, 0),1000,0)]
56294.217: DEBUG - processing: FF000404-300
56294.231: DEBUG - Received: (255,(0, 4, 4),300)
56294.231: DEBUG - active_patterns: [(255,(32, 32, 0),1000,0), (255,(0, 4, 4),300,0)]
56294.250: DEBUG - Updating: (255,(32, 32, 0),1000)
56295.829: DEBUG - Updating: (255,(0, 4, 4),300)
56296.372: DEBUG - Updating: (255,(32, 32, 0),1000)
56298.032: DEBUG - Updating: (255,(0, 4, 4),300)
56298.575: DEBUG - Updating: (255,(32, 32, 0),1000)

Changing logging levels on the fly

The logging level can be changed at any time in-code. Some programs have a way of changing the logging level on demand in order to triage a running system.  The sample program show above accepts Serial commands LD and LI to change the logging filter level between DEBUG and INFO

Video 

References

#CircuitPython2023

Revision History

Created 2023 02

Comments

Popular posts from this blog

Understanding your WSL2 RAM and swap - Changing the default 50%-25%

Installing the RNDIS driver on Windows 11 to use USB Raspberry Pi as network attached

DNS for Azure Point to Site (P2S) VPN - getting the internal IPs