Qtのデバッグログ事情

はじめに

こんばんは。この記事は Qt Advent Calendar 2020 の7日目の記事です。
今回はQtアプリケーションのデバッグログ出力について、qDebugを使ったログ出力の方法、ログ出力のフィルタリングと出力フォーマット指定の方法、実行中のアプリケーションのログ出力を変更するアイディア辺りを書いていきます。

qDebugを使ってログ出力する

ソースコードの特定の位置でデバッグログ出力をする時は、このように書くことができます。

#include <QtCore/QDebug>

void func() {
    qDebug() << "hello qDebug" << 2020; // => hello qDebug 2020
    qDebug() << QString("id=%1, name=%2").arg(123).arg("name_123"); // => "id=123, name=name_123"
    qDebug() << QDateTime::currentDateTime(); // => QDateTime(2020-12-06 21:53:19.311 東京 (標準時) Qt::LocalTime)
    qDebug() << QList<double>{1.1, 1.2, 1.3}; // => (1.1, 1.2, 1.3)
    QFile file("/etc/fstab"); file.setObjectName("fstab_file");
    qDebug() << &file; // => QFile(0x4a7b6ffb50, name = "fstab_file")
}

• 出力結果は通常は標準エラー出力へ出力されます。
• char文字列や数値はそのまま出力できます。std::stringの出力は定義されていません（自分で定義することはできます）。
• QStringはダブルクォーテーション付きで出力されます。
• QDateTimeなどQtの値型の多くはそのまま出力できます。
• QListなどQtのコンテナ型はそのまま出力できます。
• QObjectの派生型はQObjectポインタとして出力することで、クラス名やオブジェクト名と共に出力されます。

qDebug() は QDebug クラスのインスタンスを返すマクロです。出力するログのレベルによって qInfo(), qWarning(), qCritical(), qFatal() と呼び分けて使用します。ただしqFatalはデフォルトのメッセージハンドラの実装では、メッセージ出力後にabortするので注意が必要です。

デフォルトのメッセージハンドラを変更するにはqInstallMessageHandler関数を使います。

自作クラスの出力

自作クラス等をログ出力する場合は、QDebugクラスへの出力オペレータを定義します。

class MyClass {
public:
    MyClass(int id, QString name) : id_(id), name_(name) {}
    int id() const {return id_;}
    const QString &name() const {return name_;}
private:
    int id_;
    QString name_;
};
QDebug operator<<(QDebug dbg, const MyClass &obj) {
    QDebugStateSaver stateSaver(dbg);
    return dbg.nospace().noquote() << QString("(%1, %2)").arg(obj.id()).arg(obj.name());
}

変数の出力ごとにスペースが挿入されるのが不要な時はQDebug::nospaceを、QStringの出力にダブルコーテーションが不要な時はQDebug::noquoteを使います。これらを使う場合は、関数を抜ける時に元に戻すためのRAIIオブジェクトとしてQDebugStateSaverを使うのが良いでしょう。

出力先のカスタマイズ

QDebugの出力先をカスタマイズしたい時、例えば標準エラー出力と自前のログファイルの両方に書き出したい場合は以下のようにqInstallMessageHandler関数でメッセージハンドラを自前の実装に変更します。

void logHandler(QtMsgType type, const QMessageLogContext &context, const QString &msg) {
    const auto &message = qFormatLogMessage(type, context, msg);
    QTextStream cerr(stderr);
    cerr << message << endl;
    QFile file("dynamic_logging_setting.log");
    if (!file.open(QIODevice::WriteOnly | QIODevice::Append | QIODevice::Text)) {
        cerr << "Cannot open log file:" << file.fileName();
        return;
    }
    QTextStream(&file) << message << endl;
}
int main(int argc, char *argv[]) {
    QCoreApplication app(argc, argv);
    qInstallMessageHandler(logHandler);
    ...
    return app.exec();
}

自前でメッセージハンドラを実装する場合でも、出力文字列の構築にはqFormatLogMessage関数を使用することをお勧めします。そうしておけば、環境変数で出力フォーマットを変更することができます。

出力先をsyslogにしたい時は、Qt自体を -syslog オプション付きでconfigureしてビルドするだけでOKです。(@task_jp さんありがとうございます)

出力のフィルタリング

QT_LOGGING_RULES環境変数を設定すると、特定のログレベルのログのみを出力したり、抑制したりすることができます。例えばInfoレベルのログのみを出力する場合はこのようにします。

$ QT_LOGGING_RULES="*=false;*.info=true" path_to_your_app

ログの出力時にカテゴリを指定し、そのカテゴリによってもっと細かくログをフィルタリングすることもできます。QDebugヘッダの代わりにQLoggingCategoryヘッダをincludeし、qDebugの代わりにqCDebugを使用します。カテゴリはQ_LOGGING_CATEGORYマクロで定義します。複数の実装ファイルから使用するカテゴリはQ_DECLARE_LOGGING_CATEGORYマクロでヘッダファイルに宣言しましょう。
単一の実装ファイルで使うカテゴリはこんな感じになります。

#include <QLoggingCategory>
namespace {
Q_LOGGING_CATEGORY(myCategory, "myapp.somecategory")
}

void func() {
    qCDebug(myCategory) << "hello myCategory" << 2020;
}

私はほぼ実装ファイルローカルなカテゴリしか使用しないので、Qt Creatorのオプションの「テキストエディタ」－「テンプレート」にトリガー log として以下のスニペットを登録しています。

#include <QtCore/QLoggingCategory>

namespace {
Q_LOGGING_CATEGORY(loggingCategory, "$$")
} // unnamed namespace

他にも debug で qCDebug(loggingCategory) << とか info で qCInfo... とか登録しておくと、qDebugとほぼ変わらない気軽さで書けるので気に入っています。

フィルタのルールは環境変数のほかstatic関数 QLoggingCategory::setFilterRules を使ってプログラム実行中に変更することができます。（ルールのセパレータに改行しか受け付けないことに注意が必要です。）

その他フィルタ設定については Qtの公式ドキュメント が詳しいのでそちらもご参照くださいませ。

出力のフォーマットを指定する

QDebugの出力は、出力フォーマットを指定することで色々な情報と共に出力することができます。フォーマットは QT_MESSAGE_PATTERN 環境変数で指定します。出力できる情報は 公式ドキュメント にまとまっています。個人的にはミリ秒単位の時間とスレッドIDが出せるのが気に入っています。 コンソールへ色付きで出力する方法を紹介しているページ もあります。

一例として次のように指定した場合

QT_MESSAGE_PATTERN='%{time process} [%{threadid}] %{file}:%{line} => %{message}' ./myapp

一番上のコード例の出力はこのようになります。

     0.000 [1940] ../myapp/main.cpp:9 => hello qDebug 2020
     0.005 [1940] ../myapp/main.cpp:10 => "id=123, name=name_123"
     0.010 [1940] ../myapp/main.cpp:11 => QDateTime(2020-12-06 23:41:01.500 東京 (標準時) Qt::LocalTime)
     0.019 [1940] ../myapp/main.cpp:12 => (1.1, 1.2, 1.3)
     0.024 [1940] ../myapp/main.cpp:14 => QFile(0xada2dcf680, name = "fstab_file")

このフォーマットは qSetMessagePattern 関数でプログラム実行中に変更することができます。

アプリケーション実行中にログ設定を変更する

例えばQLocalServerとQLocalSocketを使用して、起動中のアプリケーションをコマンドラインから引数付きで叩くとログ設定を変更するように実装するとデバッグが捗るかもしれません。(Githubにサンプルを書きました。)
さらにそのコードを実装ファイルの関数に閉じ込め、 Q_COREAPP_STARTUP_FUNCTION した後に main.cpp を include するようなファイルを作れば、製品コードを汚さずにデバッグ時だけ動作中にログ設定を変更できるようにもできそうです。

おわりに

QDebug周りについて私の知っていることをツラツラと書いてみました。QDebug便利ですよね。昔は自前でログ出力用のマクロを書いたりしましたが、今は全部QDebugで良いんじゃないかなーと思っています。

明日は・・・まだ空いてますね。皆様ふるってご参加くださいませませ。