Cloud Loggingにサブスレッドで出力したログが出ない件

Cloud Logginについて

GCPでログを扱うなら、Cloud Loggingは避けて通れない道です。適当にログを吐くコードでを埋め込んでおいて、ブラウザを立ち上げてGCPコンソールのログビューアで表示。しかも30日前くらいまで遡って表示可能。

Cloud Loggingのライブラリの使い方に慣れれば、出力するログのフォーマットもかなり自由に弄べます。ほとんどのGCPサービス・言語で利用できますし、使い方も同じです。

こんなに便利なツールがあるなら、避ける理由などありません。それくらいに便利です。

症状

しかしCloud Loggingには、ログがまともに出ない問題があります。具体的には、

• サブスレッドから出力したログが、ログビューアに表示されない。主にGCEで発生。
• サブスレッドから出力したログが、ログビューア上では実際より後の時刻のログに交じって出力される。主にGAEで発生。

メインスレッドから出力すると問題ありません。しかしFirestoreのトランザクションなど、仕様書に明記されていないもののこっそりワーカスレッドを生成して処理しているケースでも上記の問題が発生します。時にはCloud BuildのビルドログがGAEアプリの実行ログに混じることも。

現状

これについてネットで調べても特に情報がないなあと思っていたのですが、ついに公式サイトに載っているのを見つけました。

「Java8 ランタイム環境」の「スレッド」の注釈に説明されています。

注: Java スレッド作成 API を使用する場合、Cloud Trace はリクエスト ID を正しく表示しません。Google は現在この問題の解決に取り組んでいます。

なんと、まだ対応中でした。何年も前から発生しているので早く直してほしいですね。

GCEでCloud Loggingを使用してログ出力してみる

 GCPでログを利用したいときはCloud Loggingが便利です。

GAE/Javaならjava.util.logging.Loggerクラスを使えば当たり前にGCPコンソールでログが見れます。もっと緻密に制御したいなら、Javaライブラリならcom.google.cloud.loggingパッケージを使用すれば、構造を持ったログも可能になります。ログに適当な名前を付けてその名前でフィルタして、GCSに長期保存とか、BigQueryで解析に使うとかも出来るようになります。

GAEと同じようにGCEからCloud Loggingにログ出力しようとしたのですが、意外と苦労しました。とりあえずCloud Loggingにログ出力するまでの手順を紹介します。とりあえずなのですべての方法を説明するわけではありません。

ログ出力の手段

GCPにはログ出力の手段がたくさんあります。

1. エージェントを使用する
   公式ドキュメントでは「Loggingエージェント」または「以前のLoggingエージェント」と記載されいるものと、「Opsエージェント」の2種類があります。どちらもsyslogや既存のアプリケーションが出力するログをCloud Loggingにリダイレクトしてくれるものです。
   自分で作ったアプリのログを出力するには、自分で構成を行う必要があります。自作アプリのデバッグなどの用途では、ちょっと手間が増えます。
2. Loggingライブラリを使用する
   こちらはコード中から任意のタイミング・内容でログを出力できるので、自作アプリのデバッグなどの用途に向きます。
   Javaで使えるものはさらに複数あり、logbackアベンダーを使用する/java.util.loggingパッケージを使用する/Cloud Loggingクライアントライブラリを使用する、となります。
3. REST APIを使用する
   REST APIのリクエストエンドポイントを直接コールする方法です。これを簡略化してくれるものがCloud Loggingライブラリと思って間違いないと思います。

この記事で紹介するのは「2. Loggingライブラリを使用する」のjava.util.loggingパッケージを使用する方法です。Javaの標準パッケージなのでおなじみですね。

VMインスタンスの作成

まずは準備として「Loggingツールを使用したクイックスタート」に記載されているとおりにVMインスタンスを作成します。注意が必要なのはアクセススコープで「すべての Cloud API に完全アクセス権を許可」のチェックが必要なくらいのはずです。

不安なら「gcloudツールを使用してログエントリを書き込む」に記載の手順で、ログ出力を試してみることもできます。

java.util.loggingパッケージの使用

準備

「java.util.loggingハンドラ」に載っているとおりに、pom.xmlを編集してライブラリを読み込みます。

logging.properties構成ファイルは、なくてもデフォルト設定で動作します。

Javaコード

「java.util.loggingハンドラ」に載っているスニペットそのままでは、ログは標準出力にしか出ません。ここでしばらくつまづきましたが、再トライして気付きました。

「デフォルトの Java Logging API ハンドラから」の『ハンドラ』の文字だけハイパーリンクになっていますが、ここからcom.google.cloud.logging.LoggingHandlerクラスのリファレンスに遷移できます。このクラスの説明には以下の記述があります。

To add a LoggingHandler to an existing Logger and be sure to avoid infinite recursion when logging, use the addHandler(Logger, LoggingHandler) method.

つまりLoggerインスタンスに、LoggingHandler.addHander()メソッドを利用してLoggingHanderインスタンスを追加する必要があります。

しかし実際にこのメソッドを追加してLogger.info()メソッドでログ出力をしてみると、以下の例外が発生しました。

Sep 08, 2021 4:59:15 AM io.grpc.internal.ManagedChannelImpl$2 uncaughtException

SEVERE: [Channel<1>: (logging.googleapis.com:443)] Uncaught exception in the SynchronizationContext. Panic!

java.lang.IllegalStateException: Could not find policy 'pick_first'. Make sure its implementation is either registered to LoadBalancerRegistry or included in M

ETA-INF/services/io.grpc.LoadBalancerProvider from your jar files.

        at io.grpc.internal.AutoConfiguredLoadBalancerFactory$AutoConfiguredLoadBalancer.<init>(AutoConfiguredLoadBalancerFactory.java:92)

        at io.grpc.internal.AutoConfiguredLoadBalancerFactory.newLoadBalancer(AutoConfiguredLoadBalancerFactory.java:63)

        at io.grpc.internal.ManagedChannelImpl.exitIdleMode(ManagedChannelImpl.java:406)

        at io.grpc.internal.ManagedChannelImpl$RealChannel$2.run(ManagedChannelImpl.java:978)

        at io.grpc.SynchronizationContext.drain(SynchronizationContext.java:95)

        at io.grpc.SynchronizationContext.execute(SynchronizationContext.java:127)

        at io.grpc.internal.ManagedChannelImpl$RealChannel.newCall(ManagedChannelImpl.java:975)

        at com.google.api.gax.grpc.GrpcChannelUUIDInterceptor.interceptCall(GrpcChannelUUIDInterceptor.java:52)

        at io.grpc.ClientInterceptors$InterceptorChannel.newCall(ClientInterceptors.java:156)

        at com.google.api.gax.grpc.GrpcHeaderInterceptor.interceptCall(GrpcHeaderInterceptor.java:80)

        at io.grpc.ClientInterceptors$InterceptorChannel.newCall(ClientInterceptors.java:156)

        at com.google.api.gax.grpc.GrpcMetadataHandlerInterceptor.interceptCall(GrpcMetadataHandlerInterceptor.java:55)

        at io.grpc.ClientInterceptors$InterceptorChannel.newCall(ClientInterceptors.java:156)

        at io.grpc.internal.ManagedChannelImpl.newCall(ManagedChannelImpl.java:917)

        at io.grpc.internal.ForwardingManagedChannel.newCall(ForwardingManagedChannel.java:63)

        at com.google.api.gax.grpc.ChannelPool.newCall(ChannelPool.java:143)

        at com.google.api.gax.grpc.GrpcClientCalls.newCall(GrpcClientCalls.java:99)

        at com.google.api.gax.grpc.GrpcDirectCallable.futureCall(GrpcDirectCallable.java:60)

        at com.google.api.gax.grpc.GrpcExceptionCallable.futureCall(GrpcExceptionCallable.java:64)

        at com.google.api.gax.rpc.AttemptCallable.call(AttemptCallable.java:87)

        at com.google.api.gax.rpc.RetryingCallable.futureCall(RetryingCallable.java:63)

        at com.google.api.gax.rpc.RetryingCallable.futureCall(RetryingCallable.java:41)

        at com.google.api.gax.tracing.TracedUnaryCallable.futureCall(TracedUnaryCallable.java:75)

        at com.google.api.gax.rpc.UnaryCallable$1.futureCall(UnaryCallable.java:126)

        at com.google.api.gax.rpc.UnaryCallable.futureCall(UnaryCallable.java:87)

        at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.write(GrpcLoggingRpc.java:278)

        at com.google.cloud.logging.LoggingImpl.writeAsync(LoggingImpl.java:836)

        at com.google.cloud.logging.LoggingImpl.writeLogEntries(LoggingImpl.java:804)

        at com.google.cloud.logging.LoggingImpl.write(LoggingImpl.java:766)

        at com.google.cloud.logging.LoggingHandler.publish(LoggingHandler.java:237)

        at java.util.logging.Logger.log(Logger.java:738)

        at java.util.logging.Logger.doLog(Logger.java:765)

        at java.util.logging.Logger.log(Logger.java:788)

        at java.util.logging.Logger.info(Logger.java:1490)

        at xxx.xxxx.TestApp.main(TestApp.java:30)

この例外についてネットで検索してみると、以下の記事が見つかります。Cloud LoggingではなくFirestoreのアクセスのようですが、発生している例外はほぼ同じ内容です。

「Compiled Jar keeps throwing: Uncaught exception in the SynchronizationContext」

最初この記事を見たときは回答が1つしかついていないので解決していないのかと思ったのですが、「and it works fine now!」の記述があるとおり解決していました。約1週間かけての自己解決でした。

この記事を参考にログ出力が可能になったのが、以下のスニペットです。背景が黄色の行が、公式ドキュメントのスニペットに対して追加した部分です。公式ドキュメントにはLoadBalancerRegistryは一切登場しないので正しい解決方法かどうかは分かりませんが、期待どおりに動いています。標準出力に出ていたログはそのままで、GCPコンソールのログビューアでログが見えるようになりました。

    private static final Logger LOGGER = Logger.getLogger(SampleLogger.class.getName());

    public static void main(String[] args) {
        LoggingHandler.addHandler(LOGGER, new LoggingHandler());
        LoadBalancerRegistry.getDefaultRegistry().register(new PickFirstLoadBalancerProvider());

        LOGGER.info("test log");
    }

ログ出力結果

出力結果には以下の様に、各行あたり2つの日時が出力されてしまいます。

• Cloud Loggingが追加した日時 : GCPコンソールのロケール依存
• VMインスタンスのjava.util.logging.Loggerが追加した日時 : UTC

java.util.logging.Loggerをカスタマイズして日時をとってしまえば、2つ日時が出るのを解消できそうです。

おまけ : Cloud Loggingクライアントライブラリ

java.util.loggingパッケージでは単純な文字列の出力が行えるのみです。しかしCloud Loggingクライアントライブラリ(com.google.cloud.loggingパッケージ)を使用すれば、構造を持ったログも出力可能になります。

GAEなら「Using the client library」に記載のスニペットどおりで期待動作したのですが、GCEのVMインスタンスから出力してGCPコンソールのログビューアで見えるまではまだ出来ていません。

機会があったら、いずれまた。