2021/09/11

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のアクセスのようですが、発生している例外はほぼ同じ内容です。

最初この記事を見たときは回答が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コンソールのログビューアで見えるまではまだ出来ていません。
機会があったら、いずれまた。
at 0 件のコメント:
Labels: , , ,
登録: 投稿 (Atom)