【STM32H723ZG入門④】ログ基盤編 | printfを拡張してみた

スポンサーリンク

この記事でできること

  • printfをそのまま使うのではなく、ログ基盤として拡張できる
  • どのモジュールのログか一目で分かるTAG付きログを実装できる
  • 起動時にハード異常を検出するPOST(自己診断)を追加できる
  • 「沈黙しないファームウェア」の土台を構築できる

はじめに

STM32 & 組み込みC言語開発が面白くて沼にハマりかけているgoldear@JiN_C125です。

【STM32H723ZG入門③】UART/USART編 | printfデバッグしてみた
この記事でできること STM32のUSARTをUART(非同期)として設定できる printfをPC(TeraTerm)へシリアル出力できる UARTとUSARTの違い(STM32の見え方)が分かる よくあるトラブル(表示されない/文字化け...

前回(入門③)ではUART/USARTでprintfデバッグができるようになりました。しかし、printfをそのまま使い続けるだけでは「使い勝手が悪いな」とも感じました。

具体的には以下の通りです。

  • ログが増えると読みにくい
  • どこから出たログか分からない
  • 重要なエラーが埋もれる
  • 起動時のハード異常に気づきにくい

この問題を解決するため、printfを「ログ基盤」として拡張していきます。

本記事では、ログレベル管理・TAG運用・起動時POST(自己診断)を実装し、沈黙しないファームウェアを作っていきます。

開発環境

  • 開発基板: STM32H723ZG
  • 開発環境: STM32CubeIDE
  • MCU設定: STM32CubeMX 設定済み(UART出力は入門③参照)
  • microSD: SPI接続
  • OLED:I2C接続

※ SDやOLEDの詳細実装は後続記事で解説予定です。本記事ではログ確認用途としてのみ使用します。

全体の流れ

今回の構成は次のとおりです。

  1. printf(UART出力)
  2. ログ基盤(utils/log.c)
  3. LOG_INFO() などのAPI経由で出力
  4. 起動時POSTで状態をまとめて表示

アプリ側からprintfを直接呼ばず、必ずログAPI経由で出力する設計にします。

Step1. ログ基盤ファイルを作成

utils配下に log.c / log.h を追加します。

<project>/
├─Core
  ├─Src
  | └─utils
  |    └─log.c
  ├─Inc
    └─utils
       └─log.h

utils フォルダは自分で作成してください

まずはログレベル定義とAPIを作成します。

#pragma once

// --- include ---
#include <stdint.h>

// --- define ---
// コンパイル時ログレベル(ここを変えると不要ログはビルドから消えます)
#ifndef LOG_COMPILETIME_MIN_LEVEL
#define LOG_COMPILETIME_MIN_LEVEL  LOG_LVL_INFO
#endif

// --- typedef ---
typedef enum
{
    LOG_LVL_DEBUG = 0,
    LOG_LVL_INFO,
    LOG_LVL_WARN,
    LOG_LVL_ERROR,
    LOG_LVL_FATAL,
    LOG_LVL_NONE
} log_level_t;

// --- function prototype ---
void log_printf(log_level_t lvl,
                const char* tag,
                const char* file,
                int line,
                const char* fmt, ...);

// --- macros ---
// file/line を自動付与して log_printf() に集約します
#define LOG_INFO(tag, fmt, ...) \
    do { \
        if ((LOG_LVL_INFO) >= LOG_COMPILETIME_MIN_LEVEL) { \
            log_printf(LOG_LVL_INFO, tag, __FILE__, __LINE__, fmt, ##__VA_ARGS__); \
        } \
    } while (0)

※ 例として LOG_INFO のみ掲載していますが、  
LOG_DEBUG / LOG_WARN / LOG_ERROR も同様の形式で定義しています。
  • ログレベル(DEBUG/INFO/WARN…)をenumで定義し、重要度を扱えるようにしています
  • LOG_COMPILETIME_MIN_LEVEL により、不要なログをコンパイル時に削減できます
  • LOG_INFO() などのマクロから __FILE__/__LINE__ を自動付与して log_printf() に集約しています

このファイルでは以下の役割を持たせています。

  • ログレベル(DEBUG / INFO / WARN など)の定義
  • コンパイル時に不要ログを削除する仕組み
  • printfを直接呼ばず、LOG_INFO() などのAPI経由で出力するためのマクロ

printfを直接使うと、ログの書き方が人それぞれになり、後から読んだときに非常に分かりにくくなります。

そこで出力方法をログAPIに統一し、常に同じフォーマットで表示されるようにしています

Step2. コード実装(ログ本体)

次は printf をラップして、ログフォーマットを統一します。

このファイルの役割はシンプルで、次の3点だけです。

  • ログレベルによるフィルタリング
  • TAG付きの統一フォーマットで出力
  • printf を最下層のI/Oとしてラップ
// --- include ---
#include <stdio.h>
#include <stdarg.h>

#include "utils/log.h"
#include "stm32h7xx_hal.h"

// --- variable declaration ---
static volatile log_level_t s_runtime_level = LOG_LVL_DEBUG;

// --- function prototype ---
static const char* level_to_str(log_level_t lvl);

// --- functions ---
void log_set_runtime_level(log_level_t lvl)
{
    s_runtime_level = lvl;
}

static const char* level_to_str(log_level_t lvl)
{
    switch (lvl)
    {
    case LOG_LVL_DEBUG: return "DBG";
    case LOG_LVL_INFO:  return "INF";
    case LOG_LVL_WARN:  return "WRN";
    case LOG_LVL_ERROR: return "ERR";
    case LOG_LVL_FATAL: return "FTL";
    default:            return "UNK";
    }
}

void log_printf(log_level_t lvl,
                const char* tag,
                const char* file,
                int line,
                const char* fmt, ...)
{
    // コンパイル時ログレベルでフィルタ(不要ログはここで捨てます)
    if (lvl < LOG_COMPILETIME_MIN_LEVEL)
    {
        return;
    }

    // 実行時ログレベルでフィルタ(動的に出力を絞れます)
    if (lvl < (log_level_t)s_runtime_level)
    {
        return;
    }

    // 時刻(ms)
    uint32_t tick = HAL_GetTick();

    // ヘッダ:時刻 + レベル + TAG + 発生箇所(file:line)
    printf("[%06lu][%s]", (unsigned long)tick, level_to_str(lvl));
    printf("[%s]", (tag  != NULL) ? tag  : "--");
    printf("[%s:%d] ", (file != NULL) ? file : "?", (file != NULL) ? line : 0);

    // 本文(printf互換)
    va_list ap;
    va_start(ap, fmt);
    vprintf(fmt, ap);
    va_end(ap);

    printf("\n");
}
  • コンパイル時+実行時の2段階フィルタで、不要なログを出さないようにしています
  • ログの先頭に 時刻(HAL_GetTick) を付けて、タイミングを追いやすくしています
  • TAG と file:line を付けて、どこで何が起きたか追跡しやすくしています
  • 本文は vprintf を使い、printfと同じ感覚でログを出せるようにしています

Step3. 動作確認

main.c からログAPIを呼び出して、実際に出力されることを確認します。

初期化後、無限ループの中など、好きな場所で構いませんが、今回は分かりやすく while(1) の外に1つ、中に2つ記述します。

#include "utils/log.h"

int main(void)
{
    HAL_Init();
    SystemClock_Config();

    // ここに追加
    LOG_INFO("BOOT", "system start");

    while (1)
    {
        LOG_INFO("MAIN", "hello log");
        LOG_WARN("TEST", "warning sample");

        HAL_Delay(1000);
    }
}

以下が出力例です。

[000001][INF][BOOT][main.c:20] system start
[001001][INF][MAIN][main.c:25] hello log
[002001][WRN][TEST][main.c:26] warning sample

※ これは出力例です。重要なのは、ログが常に同じフォーマットで出力されることです。tick値や file:line は変動します。

  • ログレベル(INF / WRN)が表示されます
  • TAG(MAIN / TEST)で出力元が分かります
  • file:line により発生箇所を特定できます
  • 時刻(ms)付きなのでタイミング解析にも使えます


printfと違い、常に同じフォーマットで出力されるため、後からログを追うのが非常に楽になります。

Step4. 内部解説(POST自己診断を入れる)

ログの真価は、起動時チェック(POST: Power On Self Test)で発揮されます。

組み込み開発では、外部モジュール(SDカードやOLEDなど)の接続不良・はんだ不良・差し忘れが頻繁に起きます。
そのため、起動直後に「今日の状態」を1行で報告させておくと、トラブルシュートが非常に楽になります。

ただし本記事の段階では、SD/OLEDのドライバ実装はまだ公開していません。
そこで今回は、POSTの“器”(結果を受け取ってまとめて表示する仕組み)だけを先に作ります。

  • SDカード/SPIやOLED/I2Cの実装は後続記事で解説します
  • 本記事では「POSTの考え方」と「まとめログの形式」を示します
app/boot.c
  └ POSTを実行して結果をまとめてログ出力
drv/sd_spi.c      (後続記事)
  └ SD初期化
utils/sd_selftest.c(後続記事)
  └ FatFs read/write/verify
drv/oled_i2c.c    (後続記事)
  └ OLED probe/init

次のようなステータス構造体を用意し、各チェック結果を格納します。

typedef struct
{
    uint8_t sd_ok;
    uint8_t fat_ok;
    uint8_t oled_ok;
} post_status_t;

最終的に起動時に、結果を1行でまとめて出力します。

LOG_INFO("BOOT", "POST: SD=%s FAT=%s OLED=%s",
         st.sd_ok   ? "OK" : "NG",
         st.fat_ok  ? "OK" : "NG",
         st.oled_ok ? "OK" : "NG");
[000123][INF][BOOT][boot.c:xx] POST: SD=OK FAT=OK OLED=NG

※ これは出力例です。tick値や file:line は環境やコード位置によって変わります。
重要なのは、起動直後に「今の状態」が1行で分かることです。

沈黙するFWは信用できません。まずは起動直後に状態を報告させます。

Step5. ハマりポイント・注意点

ログ基盤を入れずにprintfだけで開発を進めると、次のようなトラブルが発生しがちです。

Q. ログが増えてきたら、何が起きているのか分からなくなりました
A. printfを直接呼んでいるとフォーマットが統一されず、ログが読みづらくなります。LOG_INFO() などのAPIに統一しましょう。

Q. このログがどこから出たのか特定できません
A. TAGや file:line が無いのが原因です。出力元情報を必ず付与しましょう。

Q. DEBUGログを大量に出したら動作が重くなりました
A. printfは意外と重い処理です。ログレベルで出力を絞る設計にすると改善できます。

Q. 起動時に動かないことがあるのに原因が分かりません
A. POST(自己診断)が無いと、外部モジュールの接続不良に気づけません。起動時チェックを入れておきましょう。


ログ基盤は「後から追加するもの」ではなく、「最初に作る土台」です。

まとめ

今回は printf を拡張し、ログ基盤を実装しました。

この記事でできるようになったことを整理すると、次の通りです。

  • TAG付きで統一フォーマットのログを出力できるようになりました
  • DEBUG / INFO / WARN などのログレベル管理ができるようになりました
  • file:line や時刻付きで発生箇所を特定できるようになりました
  • 起動時POST(自己診断)でシステム状態を一目で確認できるようになりました

これらを最初に整備しておくことで、

  • デバッグ時間の短縮
  • 原因特定の高速化
  • 外部モジュールの接続ミスの早期発見
  • 後から機能追加してもログが崩れない

といったメリットが得られます。

printfは単なる出力手段ですが、ログ基盤は「開発効率を左右する土台設計」です。

沈黙するファームウェアは信用できません。まずは喋らせるところから始めてみてください。

次回は、今回POSTの中で触れた OLED(I2C接続)を実際に動かして表示を行う方法 を公開予定です。ログ基盤と組み合わせることで、状態表示付きの実用的なデバッグ環境を構築していきます。

前回

【STM32H723ZG入門③】UART/USART編 | printfデバッグしてみた
この記事でできること STM32のUSARTをUART(非同期)として設定できる printfをPC(TeraTerm)へシリアル出力できる UARTとUSARTの違い(STM32の見え方)が分かる よくあるトラブル(表示されない/文字化け...

次回: (準備中)

コメント