CloudWatch LogsがUnicodeエスケープ地獄になっていたのでLambda Test Toolとかで解決を模索してみた

はじめに

発端は、lambda関数で動いているERRORを確認するため、CloudWatch Logsでログを確認していた時のこと。
謎の文字列を発見。

{
  "timestamp": "2023-06-04T05:58:22.951Z",
  "level": "Warning",
  "message": "\u30E1\u30C3\u30BB\u30FC\u30B8\u306E\u8AAD\u307F\u8FBC\u307F\u306B\u5931\u6557\u3057\u307E\u3057\u305F"
}

なんだこれと思って調べたら、JSONでシリアライズされているはずの日本語が、
Unicodeエスケープされていました。

これはアプリケーション側の実装ミスと仮定して（その時はほぼ断定でしたが）、解決するために
色々模索していたので、犯人捜しと顛末に至る道程を記事にしてみました。

犯人捜しの始まり

疑惑1: JsonSerializerOptions の設定ミス？

最初に疑ったのは、冒頭でも記載しましたがアプリケーション側の設定ミスにあると考えました。
色々探していて、最初はここに目星をつけました。

jsonOptions = new()
{
    WriteIndented = false,
    Encoder = JavaScriptEncoder.Create(UnicodeRanges.All)  
};

UnicodeRanges.Allが何か悪さをしている、もしくはAWSでは効かないのかと考えました。

疑惑2: Parameter Storeの値の問題？

今回はParameter Storeで一部の値を設定していたので、
そちらも確認してみました。

確認してみると、

{
  "Messages": [
    {"Id": 1, "Text": "処理が完了しました。"}  
  ]
}

うーん、正常な日本語ですね～。。。
しかもここでは特にUnicodeをエスケープする箇所でもないので、ここは違いそうだなって早々に感じました。

疑惑3: UnicodeRanges.All の罠？

となると、UnicodeRanges.Allが非常に怪しいことになります。
検証するべく、僕が大好きな.NET Fiddleでテストしてみることにしました。

// 検証してみたテストコード
var testData = new { message = "パラメーター不正" };

var options1 = new JsonSerializerOptions 
{ 
    Encoder = JavaScriptEncoder.Create(UnicodeRanges.All) 
};
var options2 = new JsonSerializerOptions 
{ 
    Encoder = JavaScriptEncoder.UnsafeRelaxedJsonEscaping 
};

Console.WriteLine($"UnicodeRanges.All: {JsonSerializer.Serialize(testData, options1)}");
Console.WriteLine($"UnsafeRelaxedJsonEscaping: {JsonSerializer.Serialize(testData, options2)}");

JavaScriptEncoderライブラリのUnsafeRelaxedJsonEscapingも比較対象として、比べてみました。
これでおかしかったら、疑惑は確信に変わると思って実行しました。

結果:

UnicodeRanges.All: {"message":"パラメーター不正"}
UnsafeRelaxedJsonEscaping: {"message":"パラメーター不正"}

「あれ？どっちも正常じゃん...」。

Local Test Tool で検証

今度はローカル環境（Lambda Test Tool）で実行してみました。
ログでみるために、テストメソッドを作成してみました。

private SomeResponse CreateResponse(ILogger logger, object responseData, int statusCode = 200)
{
    // === Unicode エンコード検証用テスト ===
    var testText = "データ処理エラー";
    var testObj = new { directText = testText, source = "test" };
    
    logger.LogInformation($"現在のエンコーダー: {JsonSerializer.Serialize(testObj, _jsonOptions)}");
    
    var unsafeOptions = new JsonSerializerOptions 
    { 
        Encoder = JavaScriptEncoder.UnsafeRelaxedJsonEscaping 
    };
    logger.LogInformation($"Unsafeエンコーダー: {JsonSerializer.Serialize(testObj, unsafeOptions)}");
    
    // 実際のレスポンス作成
    return new SomeResponse
    {
        Status = statusCode,
        Data = JsonSerializer.Serialize(responseData), // ← ここがポイント
        ContentType = "application/json"
    };
}

結果:
ログ出力: {"directText":"データ処理エラー","source":"test"} ✅
レスポンスデータ: "errorMessage":"\u30C7\u30FC\u30BF\u51E6\u7406\u30A8\u30E9\u30FC" ❌

ログは正常なのにAPIレスポンスが、エスケープされていることがわかりました！
この原因は、よく確認すると2箇所で異なるシリアライズをしていました（上記コメントに注目）。

ですので、シリアライズを行う個所を統一するように修正しました。

Body = JsonSerializer.Serialize(body, _jsonOptions)  // _jsonOptions を追加

これで治りましたね！やったね！

しかし、さらなる謎

だがしかし、最初に見つけたJSONファイル内のCloudWatch Logsの問題は解決してない...。
改めて、CloudWatch Logsを確認してみました。

{
  "@message": "{\u30E1\u30C3\u30BB\u30FC\u30B8...}",  // ← Unicodeエスケープ
  "message": "メッセージの読み込みに失敗しました"  // ← 正常な日本語
}

ここで重要なことに気づきます。
「あれ？同じログなのに、@messageフィールド と JSON内のmessage で表示が違う？」

結論: AWS の仕様らしい

調査した結果、AWS公式ドキュメントで以下のことが判明しました。

• AWS Lambda .NET ランタイムは内部で System.Text.Json のデフォルト設定を使用。
  
  

• CloudWatch Logsは自動的にJSONフィールドを解析し、@message（生ログ）と message（解析済み）の両方を提供。
  
  

• GitHub Issue #1809でも同様の問題が報告済み。
  

なんと、AWSのもともとの仕組みのようだったようです。
しかもこれにより、@messageフィールドの生ログで調べるのではなく、解析済みフィールド（message）を使用すれば日本語で検索可能であることがわかりました。

終わりに

うーん、、、。（笑）
まさか、AWS上でそうなっているとは思いませんでした（笑）。
絶対アプリケーション側に問題があると思ったのですが、時にはそうでない時もあるのですね。

一応、調べるにあたって拝見したリンクもまとめておきます。
これを機に、少しでもAWSと仲良くしていきたいなと感じるばかりです！

参考・調査文献

AWS Lambda .NET GitHub Issue #1809
JSON Structured Logging for .NET Lambda Functions
CloudWatch Logs Insights Query Syntax