Здесь мы рассмотрим наиболее доступные и широко используемые возможности отладки проектов Zephyr: печать сообщения в терминал и разрешение сообщений лога (перевод статьи [1]).

В мире Zephyr функция printk это аналог printf. Пример:

printk("String: %s Length: %zd Pointer: %p\n", my_str, sizeof(my_str), my_str);

Сообщение printk выводится через последовательное соединение точно так же, как это обычно работает с printf. Типы данных автоматически преобразуются в печатаемое представление. Специфику формата printk хорошо поясняет руководство Linux [2].

Коды возврата из функций. Примеры кода Zephyr используют стандартную практику проверки кодов возврата и печатают код возврата как код ошибки, когда код не равен 0. Описание кодов возврата можно найти в документации Zephyr.

int ret = gpio_pin_configure(dev, PIN, GPIO_OUTPUT_ACTIVE | FLAGS);

if (ret < 0)
{
   printk("Pin config failed: %d", ret);
}

[Система лога]

Сообщения лога Zephyr [3] включают сетку времени и информацию о том, в каком месте приложения было выведено сообщение. Данные могут быть подключены несколькими разными способами, и сообщения лога могут быть поставлены в очередь, чтобы они не влияли на критичные ко времени выполнения части вашей программы.

Хорошей практикой будет указать важность каждого сообщения, позволяя во время компиляции выбрать, какие сообщения будут включены в двоичный файл. Это означает, что вы можете передать своей программе сообщения уровня отладки, и не выводить их в сборках производственных релизов.

Как разрешить лог. Чтобы включить вывод сообщения лога, нам нужно сделать 3 вещи: настроить Kconfig на использование подсистемы лога, подключить файл заголовка и декларировать имя модуля, связанного с сообщением лога.

Шаг 1: добавьте CONFIG_LOG=y в свой файл проекта prj.conf.

Так же, как и для всех подсистем в Zephyr, нам нужно указать CMake, какую функцию нужно использовать. Самый простой способ это сделать - добавить CONFIG_LOG=y в файл prj.conf, находящийся в директории проекта.

Шаг 2: добавить подключение заголовка log.h в модуль, где будут использоваться функции вывода в лог:

#include < logging/log.h>

Шаг 3: декларация модуля. Нам нужно указать модулю лога, откуда поступает сообщение. Это делается с помощью макроса LOG_MODULE_REGISTER(logging_blog).

Здесь надо понимать несколько важных вещей. Во-первых, вы будете использовать любой уникальный токен в этом макросе, какой захотите, однако убедитесь, что его значение не заключено в кавычки. Во-вторых, как уже упоминалось, токен нужно сделать уникальным (в этом примере он представлен как logging_blog, но это может быть произвольная фраза). Если у вас есть дополнительные C-файлы в проекте, то нужно либо зарегистрировать в каждом из них различающиеся токены, или как более общий случай просто декларировать файл как часть оригинального модуля: LOG_MODULE_DECLARE(logging_blog);.

У этого макроса есть опциональный второй аргумент, в котором можно выбрать, какие события лога будут компилироваться в приложение. По умолчанию сообщения отладки не будут отображаться, но вы можете декларировать свой модуль так, чтобы в нем эти отладочные сообщения разрешить: LOG_MODULE_REGISTER(logging_blog, LOG_LEVEL_DBG);. Уровни вывода в лог от 0 и 4 используют следующие суффиксы для LOG_LEVEL: _NONE, _ERR, _WRN, _INF, _DBG.

Как в Zephyr использовать систему лога. Подсистема лога используется так же просто, как и printf: LOG_INF("Count: %d", count);. Например, сообщения вывода в лог могут выглядеть примерно так:

[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

Каждая строка лога начинается с метки времени, выраженной обычно с точностью до миллисекунды, за ней идет обозначение уровня "серьезности" сообщения, severity level (inf для INFO), после чего идет токен, обозначающий модуль, из которого был вывод сообщения, и затем выводится сам текст сообщения в стиле printf. Обратите внимание, что в этом примере метки времени соседних строк лога различаются на 1 секунду. Это показывает работу системы очередей: сообщения достигают терминала с небольшой задержкой, однако они не меняют тайминг функции k_msleep(), используемой для этого примера.

Вы можете использовать 4 различные встроенные уровни серьезности лога путем выбора одного из макросов LOG_ERR(), LOG_WRN(), LOG_INF(), LOG_DBG(). Установка этих различных уровней позволяет выбрать в момент компиляции, какие именно сообщения будут выводиться в скомпилированном приложении. Если вы все свои отладочные сообщения будете посылать с помощью printk(), то они всегда будут встроены в код и будут выводиться, пока вы их не удалите из файла C. Если вы для вывода использовали LOG_DBG(), то сможете выбрать не включать вывод отладочных сообщений в производственном релизе кода.

По умолчанию сообщения уровня debug не показываются. Как уже упоминалось выше, у вас есть опция указать максимальный уровень "серьезности" сообщений лога (maximum severity level), когда регистрируете их для своего модуля.

Hex дамп в логе. Существует возможность вывести в лог значения данных как hex-дампа с помощью функции LOG_HEXDUMP_INF:

LOG_HEXDUMP_INF(my_data, sizeof(my_data), "Non-printable:");

В параметрах LOG_HEXDUMP_INF указывается начала данных (в виде указателя или имени массива), количество данных в байтах и строка, используемая как метка в сообщении лога. Подсистема лога автоматически покажет шестнадцатеричное представление этих данных, и справа строковое их представление - в виде, как его генерирует программа hexdump.

[Ссылки]

1. Debugging Zephyr for Beginners: printk() and the Logging Subsystem site:golioth.io.
2. How to get printk format specifiers right site:kernel.org.
3. Zephyr Logging site:docs.zephyrproject.org.