Unity公式LoggingのConfigurationを理解する

以前会社のテックブログの記事でUnity公式が出しているLoggingパッケージを紹介しました。

https://synamon.hatenablog.com/entry/unity_logging_package

記事では簡単な導入しか説明できませんでしたが、しばらく自分でも触ってみて所感やConfigurationの取り回しなどの理解が進んできました。

ちょうど同時期にRustのtracingクレートやPython公式のloggingモジュールを使ったサーバーでのLoggingを深く触っていたこともあり、一般的なLoggingへの理解が進んだこともあります。

本記事では改めてUnity公式のLoggingパッケージのConfigurationの取り回しや細かい注意点を紹介します。

環境

• Unity 2022.3.0f1
• com.unity.logging 1.0.11
• com.unity.burst 1.8.7

Configurationの解説

configurationに関する公式のドキュメントは下記になります。

https://docs.unity3d.com/Packages/com.unity.logging@1.0/manual/default-configuration.html

https://docs.unity3d.com/Packages/com.unity.logging@1.0/manual/custom-configuration.html

https://docs.unity3d.com/Packages/com.unity.logging@1.0/manual/sinks.html

Custom Configurationのページをベースに、Configurationで設定できる内容を詳しく見ていきます。

SyncMode

SyncModeの設定では、ログ出力の操作を同期的（Sync）に行うか、非同期的（Async）に行うかなどの指定ができます。

選べるオプションは下記です。

• FullSync : 全て同期的に出力する
• FullAsync : 全て非同期的に出力する
• FatalIsSync : LogLevelがFatalなものだけ同期的に、それ以外は非同期的に出力する

現在はSyncModeはグローバルな設定しかできず、出力先によって変えることは不可能のようです。

ログ出力の操作はファイル出力なども選択できるため、I/Oの操作を伴う可能性があります。

I/Oの操作はストレージアクセスの速度の遅さから比較的プロセスをブロッキングしやすいですが、UnityでメインスレッドをブロッキングしてしまうとUpdateの処理も止まってしまいFPSが低下し、ユーザー体験に悪影響を与えてしまいます。

アプリケーション本来の価値には寄与しづらいLoggingの機能でユーザー体験を下げてしまうのは好ましくありません。

そういったパフォーマンスの観点から非同期でログ出力を行うのが基本になりますが、非同期の場合はログ出力の完了前にUnityのアプリケーションが落ちてしまうとログ出力に失敗するという欠点もあります。

そのため、アプリケーションのクラッシュに関わるようなFatalなログは同期的に行い、それ以外はパフォーマンス重視で非同期的に行うのが FatalIsSync のオプションになります。

基本は FatalIsSync を使用するのがおすすめではありますが、非同期のログ出力時のエラーなどがデバッグしづらい場合もあるため、もし開発中にLoggingがうまく動作しない場合には FullSync にすることも有効です。

SyncModeの設定方法

SyncModeは LoggerConfig で設定ができ、下記のようにMethod Chainで SyncMode.XXX() のように設定できます。

Log.Logger = new Logger(
    new LoggerConfig()
	.SyncMode.FatalIsSync()
);

前述したように出力先別の設定はできないようです。

MinimumLevel

MinimumLevelの設定では、出力するLogLevelのフィルタの下限の指定ができます。

つまり、指定したLogLevel未満のログを出力しないよう設定することができます。

選べるオプションは下記です。

• Verbose
• Debug
• Info
• Warning
• Error
• Fatal

MinimumLevelの設定はグローバルに設定することも可能ですが、出力先によって変えることも可能です。

上記のLogLevelのログは常に出力したいとは限りません。

例えば下記のようなユースケース例があります。

• EditorのConsoleにあまりログを出しすぎても見づらくなってしまうので Info 以上に限定したい
• 開発中のデバッグを効率よく行うためにファイルには Debug の細かいログも出力したい
• Verbose にはセキュリティ上問題になりやすい情報も含まれるため、リリース時には出力されないようにしたい

実際のユースケースによって最適な運用は異なりますが、MinimumLevelの設定で柔軟に対応できます。

MinimumLevelの設定方法

MinimumLevelを一括で設定する場合は下記のように LoggerConfig で指定できます。

Log.Logger = new Logger(
    new LoggerConfig()
        .MinimumLevel.Debug()
);

出力先によって変えたい場合はSink側、つまり WriteTo.XXX() の部分で指定できます。

Log.Logger = new Logger(
    new LoggerConfig()
        .WriteTo.UnityEditorConsole(
	    minLevel: LogLevel.Info)
);

OutputTemplate

OutputTemplateの設定では、出力するログの形式をstringで指定できます。

その際下記のキーワードを { } で囲って変数のように指定することが可能です。

• Timestamp : 日時 (UTC)
• Level : LogLevel
• Message : ログの内容
• Stacktrace : スタックトレース
• NewLine : 改行
• Properties : （予約語）（JSON出力で使用される）

ただしUnityのConsole出力やJSONでのファイル出力など形式が固定されているSinkに対しては設定しても意味がないようです。

ログの形式も一行にコンパクトに表示したいケースや、可読性を重視したいケースなどプロジェクトや開発者によって様々ですので、OutputTemplateの設定で柔軟に対応できます。

余談ですが他言語のLoggingだともっと柔軟に表示内容をカスタマイズできたりしますが、Loggingは使用頻度が高く処理負荷に注意しないといけない側面もあるため、意図的に使用できる変数を限定しているのかもしれません。

OutputTemplateの設定方法

OutputTemplateを一括で設定する場合は下記のように LoggerConfig で指定できます。

Log.Logger = new Logger(
    new LoggerConfig()
        .OutputTemplate("{Timestamp} - {Level} - {Message}")
);

出力先によって変えたい場合はSink側、つまり WriteTo.XXX() の部分で指定できます。

Log.Logger = new Logger(
    new LoggerConfig()
        .WriteTo.File(
	    absFileName: "log.log",
	    outputTemplate: "{Timestamp} - {Level} - {Message}")
);

CaptureStacktrace

CaptureStacktraceの設定では、スタックトレースを取得するかの指定できます。

スタックトレースは開発時には重要な情報になりますが、スタックトレースを取得する処理は重いですし、ビルド時にIL2CPPや難読化をかけている場合には結局読めない場合もあるため、状況に合わせて設定するのがベストです。

CaptureStacktraceの設定方法

CaptureStacktraceは下記のように LoggerConfig で指定できます。

Log.Logger = new Logger(
    new LoggerConfig()
        .CaptureStacktrace(capture: true)
);

RedirectUnityLogs

RedirectUnityLogsの設定では、標準のログ出力である Debug.Log のログをLogginパッケージのログ出力に流すか指定できます。

全てのLoggingをパッケージのものでできるのが理想ではありますが、現実問題として過去のソースコードで外部のアセット・ライブラリはほぼ対応していません。

そのため、この設定で標準のLogをフックしてLoggingパッケージに流して運用する形が基本になるかと思います。

RedirectUnityLogsの設定方法

RedirectUnityLogsは下記のように LoggerConfig で指定できます。

Log.Logger = new Logger(
    new LoggerConfig()
        .RedirectUnityLogs(log: true)
);

RetrieveStartupLogs

RetrieveStartupLogsはドキュメントには設定項目として存在するのですが、ver1.0.11では利用できないようです。

Loggerの初期化以前のログをキャプチャして利用できるような機能のようなので、Loggerの初期化タイミングをシビアに考えなくて済むようになる良い機能なのですが。

Sink（Logの出力先）

Sink（Logの出力先）は標準で提供されている下記を使用することができます。

• File : テキストファイルへの出力
• JsonFile : JSON形式でのテキストファイルへの出力
• UnityEditorConsole : EditorのConsoleへの出力
• StdOut : OSの標準出力への出力
• UnityDebugLog : UnityEngine.Debug.Log への出力（デバッグ用）
• StringLogger : インメモリのStringへの出力（デバッグ用）

https://docs.unity3d.com/Packages/com.unity.logging@1.0/manual/sinks.html

Sink作成のメソッドのパラメータを明示的に指定することで、Sink毎にMinimumLevelやOutputTemplateを変更できます。

Sinkは複数指定することが可能です。

これらの選択肢以外にもSinkを自分で実装して .WriteTo.AddSinkConfig() に指定できます。

例えば外部のサーバーにログを送りたい場合にはSinkを自分で実装することで対応できるはずです。

Sinkの設定方法

Sinkは下記のように LoggerConfig で .WriteTo. に続ける形で指定できます。

Log.Logger = new Logger(
    new LoggerConfig()
        .WriteTo.UnityEditorConsole()
);

複数のSinkを指定したい場合も同様にChainさせます。

Log.Logger = new Logger(
    new LoggerConfig()
        .WriteTo.UnityEditorConsole()
	.WriteTo.File(absFileName:"Logs/Log.log")
);

Configurationの設定例

実運用でありそうなユースケースを想定したConfigurationの設定例を紹介します。

• SyncModeは FatalIsSync でバランス重視、開発時も運用時もFatalなログは確実に収集したい
• RedirectUnityLogs を true に設定して標準の Debug.Log をリダイレクトする（※後述する注意点に注意）
• ファイル名に日時の情報を含めて、いつアプリケーションを起動した時のログなのか分かりやすくする
• Editorでのデバッグ時と、Development BuildでのDebug時、Release時で設定を変えたい
  • Editor
    • 重要なログはConsoleに、詳細なログはFileに出力する
    • デバッグのためにStacktraceの情報を入れる
    • ログファイルはぱっと見られるよう Application.dataPath にファイルを配置する
  • Development
    • ビルドではConsoleは使用できないのでFile出力のみ
    • Debug以上の詳細なログ情報を出力する
    • デバッグのためにStacktraceの情報を入れる
    • Release時のログとは混ざらないようフォルダを分ける
    • スマホ環境などアクセス権限が厳しい場合を想定して Application.persistentDataPath にファイルを配置する
  • Release
    • File出力のみ
    • パフォーマンス重視でInfo以上の重要なログ情報のみ出力する
    • Stacktraceは不要

これを実際に設定しているのが下記です。

#nullable enable
using Unity.Logging;
using Unity.Logging.Sinks;

namespace XXX
{
    public static class Logging
    {
        public static void Initialize()
        {
            Log.Logger = new Logger(
#if UNITY_EDITOR
                EditorConfiguration()
#elif DEBUG
                DevelopmentConfiguration()
#else
                ReleaseConfiguration()
#endif
            );
        }

        private static LoggerConfig EditorConfiguration()
            => new LoggerConfig()
                .SyncMode.FatalIsSync()
                .RedirectUnityLogs(log:true)
                .WriteTo.UnityEditorConsole(
                    minLevel:LogLevel.Info,
                    captureStackTrace:true)
                .WriteTo.File(
                    absFileName:$"{UnityEngine.Application.dataPath}/../Logs/logging/client_editor_{System.DateTime.Now:yyyy-MM-dd_HH-mm-ss}.log",
                    minLevel:LogLevel.Debug,
                    captureStackTrace:true,
                    outputTemplate:"{Timestamp} [{Level}] {Message}{NewLine}{Stacktrace}");

        private static LoggerConfig DevelopmentConfiguration()
            => new LoggerConfig()
                .SyncMode.FatalIsSync()
                .RedirectUnityLogs(log:true)
                .WriteTo.File(
                    absFileName:$"{UnityEngine.Application.persistentDataPath}/Logs/logging_dev/client_dev_{System.DateTime.Now:yyyy-MM-dd_HH-mm-ss}.log",
                    minLevel:LogLevel.Debug,
                    captureStackTrace:true,
                    outputTemplate:"{Timestamp} [{Level}] {Message}{NewLine}{Stacktrace}");

        private static LoggerConfig ReleaseConfiguration()
            => new LoggerConfig()
                .SyncMode.FatalIsSync()
                .RedirectUnityLogs(log:true)
                .WriteTo.File(
                    absFileName:$"{UnityEngine.Application.persistentDataPath}/Logs/logging/client_release_{System.DateTime.Now:yyyy-MM-dd_HH-mm-ss}.log",
                    minLevel:LogLevel.Info,
                    captureStackTrace:false,
                    outputTemplate:"{Timestamp} [{Level}] {Message}");
    }
}

あくまで設定例ですので実際に使用される際はご自身のプロジェクトの性質や好みに合わせて設定を調整していただければと思います。

公式のドキュメントにConfigurationの作例がないため参考になれば嬉しいです。

注意点

1. 日本語の文字が含まれるテキストをフォーマットしてLog出力しようとするとEditorがフリーズする場合がある

ver1.0.11現在では、例えば Log.Info("{0}", "こんにちは"); のようにフォーマットされる文字列に日本語などのアルファベット以外の文字が含まれている場合にEditorがフリーズする不具合を確認しています。

再現性があるためBugReportも報告しています。

※ 2023/08/02 追記
BugReportの進捗報告からver1.0.8では発生しないらしいです。
ただUnity2022.3でコンパイルエラーが出る不具合があるため、バージョンによっては使用できませんのでご注意ください。
調査は進んでいるみたいですので、近々修正されるかと思います。

※ 2023/09/23 追記
9/11に更新されたver1.0.16にてBugReportを出していたこちらの不具合が修正されたようです。

Fixed an issue where using a string that requires more than 2 bytes per character when encoded in UTF-8 in a formatted log would result in either an exception being thrown or the editor hanging, depending on the sync mode.

https://docs.unity3d.com/Packages/com.unity.logging@1.0/changelog/CHANGELOG.html

そのためもし日本語のテキストを利用する可能性のあるLogは、一時的に UnityEngine.DebugLogFormat() に差し替えるなどの対応をした方が良いかもしれません。

またフリーズする場合はログも出力されないため原因が分からないですが、SyncModeを FullSync にすると例外のログが出てUnityの再生を止める際にフリーズするといった挙動に変わるため、SyncModeを変えることも試してみていただければ。

そもそもLoggingパッケージを導入しないというのも当然取りうる選択肢ではありますが、個人的にはLogLevelの細かさやConfigurationの自由度の高さは捨てるには惜しいため修正されるのを待とうと思っています。

2. 使用できるUnityのバージョンは 2022.2.15f1 以上

使用可能なバージョンの明記がドキュメントにはありませんでしたが、Burstなどの依存関係の問題か2022.2.15f1以上になるようです。

2021.3.0f1ではコンパイルエラーになりました。

LTSの2022.3を使用する場合には問題なく使用できますが、Burstの不具合もあったりするためもしLoggingの内部でBurst関連のエラーが出る場合にはBurstのバージョンを変えてみると良いかもしれません。

直近だと 1.8.4 だと発生した内部のエラーが　1.8.7 では発生しないといった現象も確認していて、自分は明示的に 1.8.7 を指定して使用しています。

おわりに

LoggingのConfigurationを詳しく解説しながら具体的な設定例を紹介しました。

解説した内容を基にご自身のプロジェクトのユースケースに合わせたConfigurationの設定をしていただければと思います。

実際にしばらく使ってみても、注意点にも書いた不具合もありますがそれでも高度なLoggingが利用できるのは魅力です。

過去には自分でLoggingの機能を作成したこともあるのですが、パフォーマンスとカスタマイズ性を気にしながら作るのはそれなりに骨が折れるので、公式から提供されるのはとても助かります。

公式のドキュメントを含めてもまだまだ情報が少ないので、もし触ってみたいけどどう触ったらいいか分からないという方の参考になればと思います。