ctestで実行したQt TestのログがGithub ActionsのWindows runnerで消える by ioriayane.relog.tech

状況

ctestに--output-on-failureを付与して実行するとFailしたテストのみstdoutやstderrに出力された内容を表示してくれます。

ですが、Github ActionsのWindows runner上で実行した場合に表示されませんでした（当然、手元のPCで表示されます）。

下図のとおり矢印の部分になにか表示されそうな空白があるのみです。

ctestはテストフォルダのLastTest.logというファイルに下記のような内容が記録されるはずなのですが、

auto

Start testing: Jun 12 23:05 東京 (標準時)
----------------------------------------------------------
1/1 Testing: LogTest
1/1 Test: LogTest
Command: "path/to/tests/log_test/LogTest.exe"
Directory: path/to/tests/log_test
"LogTest" start time: Jun 12 23:05 東京 (標準時)
Output:
----------------------------------------------------------
********* Start testing of log_test *********
Config: Using QtTest library 6.8.1, Qt 6.8.1 (x86_64-little_endian-llp64 shared (dynamic) debug build; by MSVC 2022), windows 11
PASS   : log_test::initTestCase()
print to stderr
print to stdout
PASS   : log_test::test_LogAccess()
PASS   : log_test::test_LogManager()
PASS   : log_test::test_LogManager_daily()
PASS   : log_test::test_LogManager_monthly()
PASS   : log_test::test_LogManager_select()
PASS   : log_test::test_LogManager_statistics()
PASS   : log_test::test_LogOperator()
PASS   : log_test::test_LogStatisticsListModel()
PASS   : log_test::test_LogFeedListModel()
PASS   : log_test::cleanupTestCase()
Totals: 11 passed, 0 failed, 0 skipped, 0 blacklisted, 38895ms
********* Finished testing of log_test *********
<end of output>
Test time =  39.28 sec
----------------------------------------------------------
Test Passed.
"LogTest" end time: Jun 12 23:05 東京 (標準時)
"LogTest" time elapsed: 00:00:39
----------------------------------------------------------

End testing: Jun 12 23:05 東京 (標準時)

下記のようになってしまいます（Github Actionsのログ画面と同じです）。

auto

6/10 Testing: LogTest
6/10 Test: LogTest
Command: "C:/a/Hagoromo/Hagoromo/build-hagoromo/tests/log_test/LogTest.exe"
Directory: C:/a/Hagoromo/Hagoromo/build-hagoromo/tests/log_test
"LogTest" start time: Jun 12 00:13 Tokyo Standard Time
Output:
----------------------------------------------------------
<end of output>
Test time =  76.11 sec
----------------------------------------------------------
Test Failed.
"LogTest" end time: Jun 12 00:14 Tokyo Standard Time
"LogTest" time elapsed: 00:01:16
----------------------------------------------------------

Qt Testのアプリが出力しているであろう********* Start testing of log_test *********から********* Finished testing of log_test *********がごっそり抜けます。

切り分け

テストの中でfprintf()を使って出力をしてみたところ、下図のように出力されました。

つまり、Qt Testの仕組みを使って出力される内容が消えており、Qtが何らか影響していることがわかりました。

ctestやGithub Actionsはおそらく悪くありません（いや、ローカルPCと同じコードを実行して差があるのだからGithub Actionsの環境になにか足りないのは確定なのですが解決方法はわかりませんでした）。

なお、Windows Runner Drops CTest Failure Output #1206にて同様と思われる事例が報告されていますが、やはり解決していません。

原因

Qt Testのログ出力がプレーンテキストモードの場合、出力にWindows APIのOutputDebugStringA()を使用しているために発生しています。

このAPIはデバッガで接続している場合に出力を接続元に出力します。WindowsのGUIアプリはコンソールと繋がっていないため、こういったAPIが用意されているようです。

で、なぜかActionsの環境にはデバッガがないようでctestが記録できなかったということのようです。

テストの開始メッセージを例に上げると下記のようになっています。

コード

C++

void QPlainTestLogger::startLogging()
{
    QAbstractTestLogger::startLogging();


    char buf[1024];
    if (QTestLog::verboseLevel() < 0) {
        std::snprintf(buf, sizeof(buf), "Testing %s\n", QTestResult::currentTestObjectName());
    } else {
        std::snprintf(buf, sizeof(buf),
                      "********* Start testing of %s *********\n"
                      "Config: Using QtTest library " QTEST_VERSION_STR
                      ", %s, %s %s\n", QTestResult::currentTestObjectName(), QLibraryInfo::build(),
                      qPrintable(QSysInfo::productType()), qPrintable(QSysInfo::productVersion()));
    }
    outputMessage(buf);
}

void QPlainTestLogger::outputMessage(const char *str)
{
#if defined(Q_OS_WIN)
    // Log to system log only if output is not redirected and stderr not preferred
    if (stream == stdout && !QtPrivate::shouldLogToStderr()) {
        OutputDebugStringA(str);
        return;
    }
#elif defined(Q_OS_ANDROID)
    __android_log_write(ANDROID_LOG_INFO, "QTestLib", str);
#endif
    outputString(str);
}

outputMessage()のQ_OS_WINで有効化されているところが問題の箇所です。

よく見ると出力先のストリームがstdoutで!QtPrivate::shouldLogToStderr()（ログをstderrに出力するべき）になってないときに問題のOutputDebugStringA()が使われます。

この条件を崩せば下記のように実装されているoutputString()の方が呼ばれてめでたく出力されるはずです。

コード

C++

void QAbstractTestLogger::outputString(const char *msg)
{
    QTEST_ASSERT(stream);
    QTEST_ASSERT(msg);

    char *filtered = new char[strlen(msg) + 1];
    strcpy(filtered, msg);
    filterUnprintable(filtered);

    ::fputs(filtered, stream);
    ::fflush(stream);

    delete [] filtered;
}

ということでQtPrivate::shouldLogToStderr()の内容を見てみます。

コード

C++

bool shouldLogToStderr()
{
    static bool forceStderrLogging = qEnvironmentVariableIntValue("QT_FORCE_STDERR_LOGGING");
    return forceStderrLogging || stderrHasConsoleAttached();
}

なんと環境変数QT_FORCE_STDERR_LOGGINGで制御できるではありませんか！

結論

事前に下記を設定します。

auto

set QT_FORCE_STDERR_LOGGING=1

以上！