現在GCP(Google Cloud Platform)を使う案件に携わっており「OpenTelemetry Instrumentation for Java」を利用してトレース情報をCloud Traceへ連携する仕組みになっているのですが・・・TraceIDとSpanIDがCloud Loggingへ正しく連携できていないことが判明しました
一応・・・ログの中にはTraceIDとSpanIDの値が設定されている項目はあるのですが、Cloud Loggingの機能で求められている項目として連携できていませんでした

2021-09-30:
logback.xmlでの設定変更で正しく連携できるようにするPRがマージされたため、対応方法などを更新しました。この機能改善に伴い、Spring Cloud GCP 2.0.4以前と2.0.5以降で対処方法が異なります。2021年の10月中頃に2.0.5をリリースする予定とのことです。

2021-12-11:
12/2にMRが取り込まれた2.0.6がリリースされていました！！

どのように連携されていたのか？

Cloud Logginの構造化ロギングのLogEntryフィールドでいうところの「jsonPayload」の中の「trace_id」と「span_id」という項目で連携されていました。

LogEntryフィールドでの連携イメージ(関係ない項目は割愛)

{
  "jsonPayload": {
    "message" : "Application is starting!",
    "span_id" : "000000000000004a",
    "trace_id" : "06796866738c859f2f19b7cfb3214824"
  }
}

これはアプリケーションからは以下のように連携されていたことが原因でした。具体的には・・・「OpenTelemetry Instrumentation for Java」がロガーのMDC(Mapped Diagnostic Context)へ設定した値がそのままJSON項目として出力されている状態でした。

アプリケーションがログ出力していたJSONイメージ(関係ない項目は割愛)

{
  "message" : "Application is starting!",
  "span_id" : "000000000000004a",
  "trace_id" : "06796866738c859f2f19b7cfb3214824"
}

どのように連携されるべきなのか？

Cloud Loggingへ正しく連携するためには以下のような形で連携する必要があります。このように連携することで、Cloud Loggingの機能で使ったトレーシング機能を効率的に活用することができます。

あるべきLogEntryフィールドへの連携イメージ(関係ない項目は割愛)

{
  "jsonPayload": {
    "message" : "Application is starting!"
  },
  "spanId" : "000000000000004a",
  "trace" : "projects/my-projectid/traces/06796866738c859f2f19b7cfb3214824"
}

正しくCloud Loggingへ連携するためには、アプリケーションが出力するJSON形式のログを以下のようにする必要はありました。

アプリケーションがログ出力する際のあるべきJSONイメージ(関係ない項目は割愛)

{
  "message" : "Application is starting!",
  "logging.googleapis.com/spanId" : "000000000000004a",
  "logging.googleapis.com/trace" : "projects/my-projectid/traces/06796866738c859f2f19b7cfb3214824"
}

なぜ正しく連携されなかったのか？

ログ出力にはSpring Cloud GCPのログ機能を利用してCloud Loggingで解釈可能なJSONをログ出力するようにしていたのですが・・・Spring Cloud GCPのログ機能が期待しているMDCのキーと「OpenTelemetry Instrumentation for Java」がMDCに設定するキーが異なっていたためでした。

具体的には・・・・

Spring Cloud GCPのログ機能が期待するキー名： traceId と spanId
「OpenTelemetry Instrumentation for Java」が設定するキー名： trace_id と span_id

という違いがありました。実は・・・v0.16.0までは互換性があったのですが、v0.17.0で名前が変わって互換性がなくなっていました

NOTE:

Spring Cloud GCPのログ機能は、Spring Cloud Sleuth(Springのトレーシング関連のサブプロジェクト)と組み合わせて利用することを想定した機能のようなので、トレーシング自体をSpring Cloud Sleuthを使うようにした方が良いのかもしれません

どのようにすれば正しく連携されるようになるのか？

私が携わっている案件では「Spring Cloud Sleuth」をこれから導入するという選択肢はなさそう（難しそう）なので・・・本エントリーでは「OpenTelemetry Instrumentation for Java」と「Sprng Cloud GCPのログ機能」の組み合わせに対する対処案を２つ紹介したいと思います。ちなみに・・・ここで紹介する方法は、ローカルで期待するJSONになることは確認しましたが実際のGCP環境で動作確認はしていませんので、そのあたりは悪しからずご了承ください

Spring Cloud GCPのログ機能の拡張ポイントを使う(2.0.6以降)

Spring Cloud GCP 2.0.6より、連携するTraceIDとSpanIDを取得するMDCキーをカスタマイズできるように機能改善されているので、その仕組みを利用して「OpenTelemetry Instrumentation for Java」がMDCに設定するキーを参照するように修正します。

Logbackの設定を変更します。

logbackの設定(変更前)

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <include resource="com/google/cloud/spring/logging/logback-json-appender.xml" />
  <root>
    <level>info</level>
    <appender-ref ref="CONSOLE_JSON"/>
  </root>
</configuration>

logbackの設定(変更後)

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="CONSOLE_JSON" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
      <layout class="com.google.cloud.spring.logging.StackdriverJsonLayout">
　　　　　　　　　　　　  <traceIdMDCField>trace_id</traceIdMDCField> <!-- MDCキーを指定する -->
        <spanIdMDCField>span_id</spanIdMDCField> <!-- MDCキーを指定する -->
     　</layout>
    </encoder>
  </appender>
  <root>
    <level>info</level>
    <appender-ref ref="CONSOLE_JSON"/>
  </root>
</configuration>

Spring Cloud GCPのログ機能の拡張ポイントを使う(2.0.1〜2.0.5)

Spring Cloud GCPの2.0.1〜2.0.5を利用している場合は、JSONに含める項目をカスタマイズするための拡張ポイントが用意されているので、その仕組みを利用することでTraceIDとSpanIDを正しい形式で連携することができます。

まず、JsonLoggingEventEnhancerインタフェースの実装クラスを作成します。

JsonLoggingEventEnhancerの実装例

package com.example.demo;

import ch.qos.logback.classic.spi.ILoggingEvent;
import com.google.cloud.spring.core.DefaultGcpProjectIdProvider;
import com.google.cloud.spring.logging.JsonLoggingEventEnhancer;
import com.google.cloud.spring.logging.StackdriverTraceConstants;
import org.springframework.util.StringUtils;

import java.util.Map;

public class GoogleTracingJsonLoggingEventEnhancer implements JsonLoggingEventEnhancer {
  private String projectId;
  private boolean presentProjectId;

  public GoogleTracingJsonLoggingEventEnhancer() {
    setProjectId(new DefaultGcpProjectIdProvider().getProjectId()); // プロジェクトIDの設定
  }

  public void setProjectId(String projectId) {
    if (StringUtils.hasText(projectId)) {
      this.projectId = projectId;
      this.presentProjectId = true;
    }
  }

  @Override
  public void enhanceJsonLogEntry(Map<String, Object> jsonMap, ILoggingEvent event) {
    if (!presentProjectId) {
      return;
    }
    // SpanIDの設定
    String spanId = event.getMDCPropertyMap().get("span_id");
    if (StringUtils.hasText(spanId)) {
      jsonMap.put(StackdriverTraceConstants.SPAN_ID_ATTRIBUTE, spanId);
      jsonMap.remove("span_id"); // MDC項目としてJSON化された項目は消しておく
    }
    // TraceIDの設定
    String traceId = event.getMDCPropertyMap().get("trace_id");
    if (StringUtils.hasText(traceId)) {
      jsonMap.put(StackdriverTraceConstants.TRACE_ID_ATTRIBUTE, StackdriverTraceConstants.composeFullTraceName(this.projectId, traceId));
      jsonMap.remove("trace_id"); // MDC項目としてJSON化された項目は消しておく
    }

  }

}

Logbackの設定を変更します。

logbackの設定(変更前)

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <include resource="com/google/cloud/spring/logging/logback-json-appender.xml" />
  <root>
    <level>info</level>
    <appender-ref ref="CONSOLE_JSON"/>
  </root>
</configuration>

logbackの設定(変更後)

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="CONSOLE_JSON" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
      <layout class="com.google.cloud.spring.logging.StackdriverJsonLayout">
      　　<loggingEventEnhancer> <!-- 実装したクラスを指定する -->
　　　　　　　　　　　　　　　　com.example.demo.GoogleTracingJsonLoggingEventEnhancer
　　　　　　　　　　　　　　</loggingEventEnhancer>
     　</layout>
    </encoder>
  </appender>
  <root>
    <level>info</level>
    <appender-ref ref="CONSOLE_JSON"/>
  </root>
</configuration>

NOTE:

Spring Cloud GCP 2.0.0以前では、ここで紹介した拡張ポイントが用意されていないため、StackdriverJsonLayoutを継承してメソッドをオーバライドするような改修が必要になります（本エントリでは継承による改修方法の説明は割愛します）。

MDCのキーを置き換える

暫定対処感が半端ないですが・・・MDCのキーをSpring Cloud GCPのログ機能が期待するキーに置き換えることで正しい形式で連携することもできそうです。

まず、MDCのキーを置き換えるユーティリティメソッドを用意します。

package com.example.demo;

import org.slf4j.MDC;
import org.springframework.util.StringUtils;

public class TracingUtil {

  private TracingUtil() {
    // NOP
  }

  /**
   * 「opentelemetry-java-instrumentation」で設定されたMDCを「Spring Cloud」で扱えるMDC形式へ置き換える.
   */
  public static void replaceMDCKeyToSpringCloudFormat() {
    replace("traceId", "trace_id");
    replace("spanId", "span_id");
  }

  public static void clearMDC() {
    MDC.remove("traceId");
    MDC.remove("spanId");
  }

  private static void replace(String newKey, String oldKey) {
    String value = MDC.get(oldKey);
    if (StringUtils.hasText(value)) {
      MDC.put(newKey, value);
      MDC.remove(oldKey);
    }
  }

}

トレーシングを開始するメソッドの中でMDCの置き換えとMDCのクリア処理を組み込みます。

@WithSpan
public void execute() {
  try {
    TracingUtil.replaceMDCKeyToSpringCloudFormat(); // ログトレーシングが必要な処理を実行する前にMCDキーを置き換えておく
    service.execute();
  } finally {
    TracingUtil.clearMDC(); // 置き換えたMDCキーは念のため消しておく
  }
}

う〜ん・・・なんか残念なコードですね

まとめ

２つ対処方法を紹介しましたが・・・基本的には「Spring Cloud GCPのログ機能の拡張ポイントを使う！！」方法で対応するのが良いのかな〜と思います。Spring Cloud GCPのログ機能の方で、JSON化する際にSpanIDとTraceIDを取得する際のMDCキーをカスタマイズでいるようにしてもらえると嬉しい気はするな〜 → Issue作ってプルリク出してみようかな〜 → マージされたので2.0.6からlogback.xmlの設定変更だけで対応することができます