Debugging Zephyr for Beginners: printk() and the Logging Subsystem
Zephyr has a number of tools to aid in debugging during your development process. Today we’re focusing on the most available and widely useful of these: printing message to a terminal and enabling logging messages.
printk() is the printf() of the Zephyr world
Printing useful messages using printf() is a time-tested practice for getting programs up and running. Some frown upon using this as the main debugging approach, but don’t discount how incredibly useful it is as a first step.
printk("String: %s Length: %zd Pointer: %p\n", my_str, sizeof(my_str), my_str);
Zephyr builds this functionality right in with the `printk()` command so that you can have immediate feedback. These messages print out over a serial connection using the same style of conversion syntax as printf(). This automatically converts data types into the printable representation. In my example I’m debugging a string in c by printing out the string itself, the length, and the pointer address. The Linux docs are handy for those looking to drill down into the specifics of printk formatting.
Tip: Pay attention to Zephyr return codes!
Throughout the Zephyr samples you’ll see that it’s standard practice to test return codes and print them out when they are non-zero numbers. I have found these return codes to be indispensable when troubleshooting subsystems like i2c. The paradigm most often used is:
int ret = gpio_pin_configure(dev, PIN, GPIO_OUTPUT_ACTIVE | FLAGS);
if (ret < 0) {
printk("Pin config failed: %d", ret);
}
You can look up error codes in Zephyr docs. I was getting a -88, which is ENOSYS –function not implemented.
Use the Logging Subsystem as a Powerful Debugging Tool
Once you’ve seen the Zephyr logging subsystem, there is no replacement. Log messages automatically include a timestamp and report on what part of the application they come from. Data can be included in a few different ways, and these messages are queued so that they don’t interfere with time-dependent parts of your program.
Perhaps the best part is that you specify the importance of each message, allowing you to choose at compile time which logging messages will be included in the binary. This means you can pepper your program with debug-level messages and choose to leave them out of the production builds.
How to Enable Logging in Zephyr
To turn on logging, we need to do three things: tell our Kconfig that we want to use the subsystem, include the logging header file, and declare the module name.
Step 1: Add CONFIG_LOG=y to your project’s prj.conf file.
Like all subsystems in Zephyr, we need to tell CMake that we want to use it. The easiest way to do this is by adding CONFIG_LOG=y to the prj.conf file in the project directory.
Step 2: Add the header file to the top of your c file: #include <logging/log.h>
This one is straightforward. We want to use a C library so we have to include it in the main.c (and any other C files in the project).
Step 3: Declare the module
We need to tell the logging module where the message is coming from using a macro: LOG_MODULE_REGISTER(logging_blog);
There are a couple of important things to understand here. First, you will use any unique token you want in this macro, but make sure you don’t surround it in quotes. Second, as I just mentioned, this needs to be unique (in this example this is represented by logging_blog but could be any arbitrary phrase). If you have additional C files in your project, you either need to register different tokens, or more commonly just declare the file as part of the original module: LOG_MODULE_DECLARE(logging_blog);
There is an optional second argument and this is where you choose which logging events will be compiled into the application. By default, debug messages will not be shown, so you can declare your module to enable them: LOG_MODULE_REGISTER(logging_blog, LOG_LEVEL_DBG);. Logging levels run from 0 to 4 using the following suffixes: _NONE, _ERR, _WRN, _INF, _DBG.
How to use the Logging subsystem in Zephyr
Using the logging subsystem is just as easy as using printf: LOG_INF("Count: %d", count);. The log outputs for this example look like this:
[00:01:52.439,000] <inf> logging_blog: Count: 112 [00:01:53.439,000] <inf> logging_blog: Count: 113 [00:01:54.439,000] <inf> logging_blog: Count: 114 [00:01:55.439,000] <inf> logging_blog: Count: 115 [00:01:56.439,000] <inf> logging_blog: Count: 116 [00:01:57.439,000] <inf> logging_blog: Count: 117 [00:01:58.439,000] <inf> logging_blog: Count: 118 [00:01:59.439,000] <inf> logging_blog: Count: 119
We begin each line with a timestamp down to microseconds, the severity level (inf for INFO), followed by our printf-style message output. Look at the timestamps in this example–they are exactly one second apart. This drives home the power of the queuing system: the messages arrive at the terminal slightly delayed, but they don’t alter the k_msleep() timing that was used for this example.
You can use four different built-in severity levels for your logs by choosing a different macro: LOG_ERR(), LOG_WRN(), LOG_INF(), LOG_DBG(). Setting these different levels allows you to choose what gets included at compile time. If you made all your debugging messages using printk(), they will always compile into your code until you remove them from the C file. If you use LOG_DBG(), you can choose not to include that level of logging when you compile the production version of your code.
By default, debug-level messages will not be shown. As mentioned earlier, you have the option of specifying the maximum severity level to show whey you register your modules.
Hex dumping via logs
Logging lets you dump data arrays without the need to turn that data into something digestible first.
LOG_HEXDUMP_INF(my_data, sizeof(my_data), "Non-printable:");
I’ve given an array of values, the length of that array, and a string to use as the label for the log message. The logging subsystem will automatically show the hexadecimal representation of that data, as well as a string representation to the right, much as you’d expect from any hexdump program (you’ll need to scroll right in the example below).
[00:00:00.427,000] logging_blog: Non-printable:
01 fe 12 00 27 |....'
Other debugging tools for next time
Using logging can give you enough feedback to solve the majority of your development issues in Zephyr, but of course there are other tools available. In future posts we’ll discuss using virtual devices via QEMU to speed up debugging sessions because you won’t have to flash newly compiled binaries to hardware. And we plan to dive into on-chip debugging that lets you set break points and step through your code. Stay tuned!
