Minecraft ログ 文字化け qiitaでGoogle検索してもそれっぽいのがなかったので。
環境
- forge-1.14.4-28.0.41.jar
ForgeじゃなくてもバニラのMinecraftでもlog4j2を使っているので同じような手順が適用可能。1.12.2とかでも同様のことができる。
背景
Minecraftサーバーを動かしていて、ログが
[29Aug2019 11:04:41.022] [Server thread/INFO] [net.minecraft.server.dedicated.DedicatedServer/]: [Server] ?????????
[29Aug2019 11:09:36.309] [Server thread/INFO] [net.minecraft.server.dedicated.DedicatedServer/]: [Server] ???
のように29Aug2019 23:02:40.595と欧米式の表示になっていて見辛い。しかも日本語部分が?に文字化けしてしまっている。
どうにかして日本語をUTF8で格納し、日付を2019/09/20 11:19:35.359のように日本語にしたい。
しかもjar自体を改造することなくjarを起動するコマンド側で処理したい。現状の起動スクリプトは負荷対策周りの記述を割愛すると次のようになっており、ここに小細工をしてロギングを変えたい。
/usr/lib/jvm/java-1.8.0-openjdk-amd64/bin/java \
-jar forge-1.14.4-28.0.41.jar \
nogui
方法
log4j2の設定ファイルの参照先をjar外にする
log4j2の設定ファイルはjarの中にある
現状の出力の制御がどこに記述されているかというと、jarの中である。
$ zipinfo forge-1.14.4-28.0.41.jar | grep log4j
-rw---- 2.0 fat 5420 bl defN 19-Aug-05 01:22 log4j2.xml
$ unzip -p forge-1.14.4-28.0.41.jar log4j2.xml
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" packages="net.minecrell.terminalconsole,net.minecrell.terminalconsole.util,com.mojang.util,cpw.mods.modlauncher.log">
<filters>
<ThresholdFilter level="WARN" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
<MarkerFilter marker="NETWORK_PACKETS" onMatch="${sys:forge.logging.marker.networking:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="CLASSLOADING" onMatch="${sys:forge.logging.marker.classloading:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="LAUNCHPLUGIN" onMatch="${sys:forge.logging.marker.launchplugin:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="CLASSDUMP" onMatch="${sys:forge.logging.marker.classdump:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="AXFORM" onMatch="${sys:forge.logging.marker.axform:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="EVENTBUS" onMatch="${sys:forge.logging.marker.eventbus:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="DISTXFORM" onMatch="${sys:forge.logging.marker.distxform:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="SCAN" onMatch="${sys:forge.logging.marker.scan:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="REGISTRIES" onMatch="${sys:forge.logging.marker.registries:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="REGISTRYDUMP" onMatch="${sys:forge.logging.marker.registrydump:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="SPLASH" onMatch="${sys:forge.logging.marker.splash:-DENY}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="FORGEMOD" onMatch="${sys:forge.logging.marker.forgemod:-ACCEPT}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="LOADING" onMatch="${sys:forge.logging.marker.loading:-ACCEPT}" onMismatch="NEUTRAL"/>
<MarkerFilter marker="CORE" onMatch="${sys:forge.logging.marker.core:-ACCEPT}" onMismatch="NEUTRAL"/>
</filters>
<Appenders>
<TerminalConsole name="Console">
<PatternLayout>
<LoggerNamePatternSelector defaultPattern="%highlight{[%d{HH:mm:ss.SSS}] [%t/%level] [%c{2.}/%markerSimpleName]: %minecraftFormatting{%msg}%n%tEx}" disableAnsi="${sys:forge.logging.noansi:-true}">
<!-- don't include the full logger name for Mojang's logs since they use full class names and it's very verbose -->
<PatternMatch key="net.minecraft." pattern="%highlight{[%d{HH:mm:ss.SSS}] [%t/%level] [minecraft/%logger{1}]: %minecraftFormatting{%msg}%n%tEx}"/>
<PatternMatch key="com.mojang." pattern="%highlight{[%d{HH:mm:ss.SSS}] [%t/%level] [mojang/%logger{1}]: %minecraftFormatting{%msg}%n%tEx}"/>
</LoggerNamePatternSelector>
</PatternLayout>
</TerminalConsole>
<Queue name="ServerGuiConsole" ignoreExceptions="true">
<PatternLayout>
<LoggerNamePatternSelector defaultPattern="[%d{HH:mm:ss.SSS}] [%t/%level] [%c{2.}/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n">
<!-- don't include the full logger name for Mojang's logs since they use full class names and it's very verbose -->
<PatternMatch key="net.minecraft." pattern="[%d{HH:mm:ss.SSS}] [%t/%level] [minecraft/%logger{1}]: %minecraftFormatting{%msg}{strip}%n"/>
<PatternMatch key="com.mojang." pattern="[%d{HH:mm:ss.SSS}] [%t/%level] [mojang/%logger{1}]: %minecraftFormatting{%msg}{strip}%n"/>
</LoggerNamePatternSelector>
</PatternLayout>
</Queue>
<RollingRandomAccessFile name="File" fileName="logs/latest.log" filePattern="logs/%d{yyyy-MM-dd}-%i.log.gz">
<PatternLayout pattern="[%d{ddMMMyyyy HH:mm:ss.SSS}] [%t/%level] [%logger/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n%xEx"/>
<Policies>
<TimeBasedTriggeringPolicy/>
<OnStartupTriggeringPolicy/>
</Policies>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="DebugFile" fileName="logs/debug.log" filePattern="logs/debug-%i.log.gz">
<PatternLayout pattern="[%d{ddMMMyyyy HH:mm:ss.SSS}] [%t/%level] [%logger/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n%xEx"/>
<Policies>
<OnStartupTriggeringPolicy/>
<SizeBasedTriggeringPolicy size="200MB"/>
</Policies>
<DefaultRolloverStrategy max="5" fileIndex="min"/>
</RollingRandomAccessFile>
</Appenders>
<Loggers>
<!-- make sure mojang's logging is set to 'info' so that their LOGGER.isDebugEnabled() behavior isn't active -->
<Logger level="${sys:forge.logging.mojang.level:-info}" name="com.mojang"/>
<Logger level="${sys:forge.logging.mojang.level:-info}" name="net.minecraft"/>
<Logger level="${sys:forge.logging.classtransformer.level:-info}" name="cpw.mods.modlauncher.ClassTransformer"/>
<Root level="all">
<AppenderRef ref="Console" level="${sys:forge.logging.console.level:-info}"/>
<AppenderRef ref="ServerGuiConsole" level="${sys:forge.logging.console.level:-info}"/>
<AppenderRef ref="File" level="${sys:forge.logging.file.level:-info}"/>
<AppenderRef ref="DebugFile" level="${sys:forge.logging.debugFile.level:-trace}"/>
</Root>
</Loggers>
</Configuration>
問題の記述はddMMMyyyyだ。これに従うと29Aug2019という表示が出てくる。
まずは設定ファイルの参照先をこれではなく、jarの外にsrcというディレクトリを作ってその中に格納したlog4j2.xmlにすることを目指す。
単にcpを追加しただけではダメだった
まず初めに設定ファイルを./src/log4j2.xmlにコピーし、少し改造して起動スクリプトを以下のように変更したが、これは失敗だった。
# 失敗作
/usr/lib/jvm/java-1.8.0-openjdk-amd64/bin/java \
-cp src \
-jar forge-1.14.4-28.0.41.jar \
nogui
なんかsrcの中にあるファイルを認識してくれない。きっと-jarで指定したらjarの中のものが優先でもされるのだろう。今回はここは肝じゃないので深追いはしないで次のアプローチを試す。
jarファイルをcpに追加するとうまくいく
そこで、-jarではなく、jarファイルをcpに追加してjarの中で指定されているメインクラスを直接叩く方式を考える。
メインクラスはjarの中に記述されており、以下のコマンドで確認できる。
$ unzip -p forge-1.14.4-28.0.41.jar META-INF/MANIFEST.MF | less
大量に中身が出てくるが、Main-Class: net.minecraftforge.server.ServerMainという行を見つけることができる。スクリプトを以下のように書き換えた。
/usr/lib/jvm/java-1.8.0-openjdk-amd64/bin/java \
-cp src:forge-1.14.4-28.0.41.jar \
net.minecraftforge.server.ServerMain \
nogui
結果、ちゃんと参照先が変わった。
jarの中に別のライブラリのjarが大量に格納されていて、それも展開してcpに追加しなければならないかと心配だったが、そこは上手いことやってくれたみたいで、普通にMinecraftのサーバーが起動した。
これでlog4j2.xmlを自由に弄れるようになった。
プロパティを追加して設定ファイルの参照先ファイル名を指定できたら（#TODO）これの方がいいが、これで不具合もなく成功したし検証するのがだるいのでとりあえずこれでいく。
変更箇所
まずlog4j2.xmlの構造がどうなっているのかを説明しよう。
全体の構造としては、次のようになっている。
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" packages="net.minecrell.terminalconsole,net.minecrell.terminalconsole.util,com.mojang.util,cpw.mods.modlauncher.log">
<filters>
ここにはログのフィルタが書かれているが、今回は関係ないので飛ばす。
</filters>
<Appenders>
Appenderとは出力先のことで、Appenderを複数書くと複数の場所に出力させることができる。
出力先にはコンソール・サーバーGUI（Minecraftサーバーをnogui指定なしで呼び出したときに出てくるあれ）・ログファイルなどがある。
</Appenders>
<Loggers>
ここでは取り扱うログレベルとかが書かれているが、今回はそんなに関係ないので飛ばす。
ただし、Appenderを追加してバニラのMinecraftでもdebugログファイルを作りたいみたいな案件の場合、ここも弄る必要がある。
</Loggers>
</Configuration>
今回やりたいのは出力形式の変更なので、Appendersの中を変更すればよい。とりあえずlogs/latest.logに対する改変内容だけを説明するが、debugログやコンソール出力に対する制御も同様の手順で出来る。
logs/latest.logに対するログ出力を設定している部分を載せる。
<RollingRandomAccessFile name="File" fileName="logs/latest.log" filePattern="logs/%d{yyyy-MM-dd}-%i.log.gz">
<PatternLayout pattern="[%d{ddMMMyyyy HH:mm:ss.SSS}] [%t/%level] [%logger/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n%xEx"/>
<Policies>
<TimeBasedTriggeringPolicy/>
<OnStartupTriggeringPolicy/>
</Policies>
</RollingRandomAccessFile>
まずlatest.logへの出力はどんな機構で行われているかというと、RollingRandomAccessFileというものである。
Rollingとはログファイルをなんらかの判定（Policies）（毎日0時とか、ログが200MBに到達したらとか）に従って分割し、圧縮して保存する機構を指す。ここでは時間ベースの判定とプログラムが起動した時点でのローリングが指定されている。時間ベースの判定とは、多分圧縮ファイルの出力ファイル名が変わった時にローリングするみたいな奴だろう。filePattern="logs/%d{yyyy-MM-dd}-%i.log.gz"に圧縮ファイルの出力ファイル名のパターンが書かれている。多分これの-ddを消すと月に1回ローリングとかになるんじゃないかと思うが、ここでは特に扱わない。
出力フォーマットは、<PatternLayout pattern="[%d{ddMMMyyyy HH:mm:ss.SSS}] [%t/%level] [%logger/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n%xEx"/>という記述が指定している。今回は、両方の案件が出力形式の制御なので、両方ともPatternLayoutタグを弄ることになる。
日付フォーマットの変更
日付フォーマットを以下のように変更した。
<PatternLayout pattern="[%d{ddMMMyyyy HH:mm:ss.SSS}] [%t/%level] [%logger/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n%xEx"/>
↓
<PatternLayout pattern="[%d{yyyy/MM/dd HH:mm:ss.SSS}] [%t/%level] [%logger/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n%xEx"/>
ddMMMyyyyをyyyy/MM/ddに変更したことで、日本人的に馴染みのあるフォーマットになったと思う。詳しい設定方法については多分検索すれば日本語の資料が出てくると思うので割愛。
エンコーディングをUTF8に変更
エンコーディングを変えるには、PatternLayoutにcharset属性を指定すればよい。
<PatternLayout pattern="[%d{yyyy/MM/dd HH:mm:ss.SSS}] [%t/%level] [%logger/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n%xEx"/>
↓
<PatternLayout charset="utf-8" pattern="[%d{yyyy/MM/dd HH:mm:ss.SSS}] [%t/%level] [%logger/%markerSimpleName]: %minecraftFormatting{%msg}{strip}%n%xEx"/>
あとは同様のことをdebug用の設定にも行えば、latestもdebugも同じようになる。
結果を示す。
[2019/09/20 11:04:35.080] [Server thread/INFO] [net.minecraft.world.server.ChunkManager/]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[2019/09/20 11:04:35.080] [Server thread/INFO] [net.minecraft.world.server.ChunkManager/]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[2019/09/20 11:04:41.022] [Server thread/INFO] [net.minecraft.server.dedicated.DedicatedServer/]: [Server] てすと
[2019/09/20 11:09:36.309] [Server thread/INFO] [net.minecraft.server.dedicated.DedicatedServer/]: [Server] てすろ
【余談】tmuxの文字化け
tmuxを使っているとそれでも日本語が＿になってしまう。それはこれの記事で対処できる。
- tmux使用時に日本語が表示されないとき(アンダースコアになってしまう）の対処法
既に立っているtmuxに再接続するときもtmux -u aのように-u指定が必要となる。
まとめ
手順
-
log4j2.xmlをjarの中から引っこ抜いてきて、src/log4j2.xmlに配置する - 起動スクリプトを改変する
-
-cpにsrc:forge-なんとか.jarを追加する - メインクラスをjarの中から調べてきて、
-jarを使わずに直接呼び出すようにする
-
-
src/log4j2.xmlを改造する-
PatternLayoutのpattern属性で日付部分を%d{yyyy/MM/dd HH:mm:ss.SSS}にする -
PatternLayoutにcharset="utf-8"属性を追加する
-
結果
これが
[20Sep2019 11:04:41.022] [Server thread/INFO] [net.minecraft.server.dedicated.DedicatedServer/]: [Server] ???
このようになる
[2019/09/20 11:04:41.022] [Server thread/INFO] [net.minecraft.server.dedicated.DedicatedServer/]: [Server] てすと