開発メモ その459 .NET でビルドしたコンソールアプリにおいて NLog が一切ログを出せなくなった

Introduction

備忘録。
NLog を使ったコンソールアプリを dotnet publish を使って、RedHat で動かしたら…なぜか一切ログが出ない。

なぜ?

What happened?

原因は dotnet publish を実行した際のオプションの問題。
自分は下記のコマンドを実行していた。

$ dotnet publish -c Release -r linux-x64 --self-contained true -p:PublishTrimmed=true

問題の究明のために下記のプログラムを用意。

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;

using NLog;

namespace Demo
{

    internal sealed class Program
    {

        #region Fields

        private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

        #endregion

        #region Methods

        private static void Main(string[] args)
        {
            Logger.Info("Start");
        }

        #endregion

    }

}

NLog.confg は下記。

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <targets>
    <target
      name="ApplicationLogFile"
      xsi:type="File"
      layout="${longdate} [${uppercase:${level:padding=-5}}] ${message} ${exception:format=tostring}"
      fileName="${basedir}Logs\Application.${date:format=yyyyMMdd}.log"
      encoding="UTF-8"
      archiveFileName="${basedir}Logs\Application.archive.{#}.log"
      archiveEvery="Day"
      archiveNumbering="Date"
      maxArchiveFiles="90"
      archiveDateFormat="yyyyMMdd"
      header="[Start Logging]"
      footer="[End Logging]${newline}"  />
    <target
      name="ApplicationConsole"
      xsi:type="ColoredConsole"
      layout="${longdate} [${uppercase:${level:padding=-5}}] ${message} ${exception:format=tostring}" />
  </targets>

  <rules>
    <logger name="*" minlevel="Info" writeTo="ApplicationLogFile" />
    <logger name="*" minlevel="Info" writeTo="ApplicationConsole" />
  </rules>
</nlog>

この条件で実行すると…ログファイルどころかコンソールにさえ何も表示されない。
プログラムがクラッシュしているわけではないのはわかっていたので、 NLog に問題があると判断し、NLog.config に下記の設定を加える。

  <?xml version="1.0" encoding="utf-8" ?>
  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
-       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
+       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+       throwExceptions="true">

すると、実行時に NLog 側がロギング処理時の例外を上位アプリケーションに投げるようになる。

$ ./Demo 
Unhandled exception. System.TypeInitializationException: The type initializer for 'Demo.Program' threw an exception.
 ---> NLog.NLogConfigurationException: Exception when loading configuration /home/t-takeuchi/Work/publish/NLog.config
 ---> NLog.NLogConfigurationException: Failed to create Target of type: File
 ---> System.ArgumentException: Target symbol-name is unknown: 'File'
   at NLog.Config.Factory`2.CreateInstance(String itemName)
   at NLog.Config.LoggingConfigurationParser.FactoryCreateInstance[T](String classType, INamedItemFactory`2 factory)
   --- End of inner exception stack trace ---
   at NLog.Config.LoggingConfigurationParser.FactoryCreateInstance[T](String classType, INamedItemFactory`2 factory)
   at NLog.Config.LoggingConfigurationParser.CreateTargetType(String targetTypeName)
   at NLog.Config.LoggingConfigurationParser.ParseTargetsElement(ValidatedConfigurationElement targetsElement)
   at NLog.Config.LoggingConfigurationParser.ParseNLogSection(ILoggingConfigurationElement configSection)
   at NLog.Config.XmlLoggingConfiguration.ParseNLogSection(ILoggingConfigurationElement configSection)
   at NLog.Config.LoggingConfigurationParser.LoadConfig(ILoggingConfigurationElement nlogConfig, String basePath)
   at NLog.Config.XmlLoggingConfiguration.ParseNLogElement(ILoggingConfigurationElement nlogElement, String filePath, Boolean autoReloadDefault)
   at NLog.Config.XmlLoggingConfiguration.ParseTopLevel(NLogXmlElement content, String filePath, Boolean autoReloadDefault)
   at NLog.Config.XmlLoggingConfiguration.Initialize(XmlReader reader, String fileName, Boolean ignoreErrors)
   --- End of inner exception stack trace ---
   at NLog.Config.XmlLoggingConfiguration.Initialize(XmlReader reader, String fileName, Boolean ignoreErrors)
   at NLog.Config.XmlLoggingConfiguration..ctor(XmlReader reader, String fileName, LogFactory logFactory)
   at NLog.Config.LoggingConfigurationFileLoader.LoadXmlLoggingConfiguration(XmlReader xmlReader, String configFile, LogFactory logFactory)
   at NLog.Config.LoggingConfigurationFileLoader.LoadXmlLoggingConfigurationFile(LogFactory logFactory, String configFile)
   at NLog.Config.LoggingConfigurationFileLoader.TryLoadLoggingConfiguration(LogFactory logFactory, String configFile, LoggingConfiguration& config)
   at NLog.Config.LoggingConfigurationFileLoader.TryLoadFromFilePaths(LogFactory logFactory, String filename)
   at NLog.Config.LoggingConfigurationFileLoader.Load(LogFactory logFactory, String filename)
   at NLog.Config.LoggingConfigurationWatchableFileLoader.Load(LogFactory logFactory, String filename)
   at NLog.LogFactory.get_Configuration()
   at NLog.LogFactory.GetLoggerThreadSafe(String name, Type loggerType)
   at NLog.LogFactory.GetLogger(String name)
   at NLog.LogManager.GetCurrentClassLogger()
   at Demo.Program..cctor() in D:\Works\OpenSource\Demo2\templates\Console\DotNet\9.0\sources\Demo\Program.cs:line 16
   --- End of inner exception stack trace ---
   at Demo.Program.Main(String[] args) in D:\Works\OpenSource\Demo2\templates\Console\DotNet\9.0\sources\Demo\Program.cs:line 24
Aborted (core dumped)

眺めていると、 CreateInstance(String itemName) の文字に気が付く。
リフレクションに失敗して、ロギングに必要なクラスが探せていないのでは?、と推測が働き -p:PublishTrimmed=true が原因だと思い至った次第である。

そもそも、 dotbet publish 実行時に

$ dotnet publish -c Release -r linux-x64 --self-contained true -p:PublishTrimmed=true
復元が完了しました (1.4 秒)
  Demo 1 件の警告付きで成功しました (9.7 秒) → bin\Release\net9.0\linux-x64\publish\
    C:\Users\TAKUYA\.nuget\packages\nlog\5.0.0\lib\netstandard2.0\NLog.dll : warning IL2104: Assembly 'NLog' produced trim warnings. For more information see https://aka.ms/il2104

11.8 秒後に 1 件の警告付きで成功しました をビルド

のように警告は出ていたのである…
凡ミスぅ。

言い訳だが、PublishTrimmed を使うと生成されるバイナリが格段に小さくなるので魅力的でもあり、それでウキウキしていたのもある。
上記の簡単なプログラムでさえ、これだけの違いがある。

項目	PublishTrimmed あり	PublishTrimmed なし
ファイル数	60	191
合計ファイルサイズ	26.2 MB	76.7 MB

PublishTrimmed を外せば動くのはわかるが、警告に出ているように対策はある。
問題となった NLog 自体はトリムで軽くなるとはいえ、1 MB にも満たないアセンブリなので、軽量化する意味は乏しい。

なので、NLog のみトリムを除外する方式を採用する。
*.csproj に下記の設定を追加することで解決できる。

+ <ItemGroup>
+   <TrimmerRootAssembly Include="NLog" />
+ </ItemGroup>

追加後、-p:PublishTrimmed=true を加えて再度ビルドすると、ファイル数が 70、合計ファイルサイズが 27.5 MB と微増するが、問題なくログが出るようになる。