OpenShift LoggingでJSONログを扱う

こんにちは、平田です。

アプリのログをJSON形式で出力し、OpenShift LoggingでJSONのまま保存してみます。

OpenShift Logging 5.1.0 からJSON形式のログをJSON構造のまま扱える(ElasticsearchのインデックスにJSONのまま入る)ようになったようです。これを試してみました。

まずJSON形式でログを吐くアプリを用意します。今回は quarkus-logging-json extension のインテグレーションテストを流用します。実行可能Jarにしておきます。

$ mvn -Dquarkus.package.type=uber-jar clean package

バイナリビルドでコンテナ化してOpenShiftにデプロイします。あとで使用するラベルを付けています。

$ oc new-project json-logging
$ oc new-build --name=quarkus-logging-json-app \
     --binary=true \
     --image-stream=ubi8-openjdk-11:1.3
$ oc start-build quarkus-logging-json-app \
     --from-file=target/quarkus-logging-json-integration-tests-1.1.2-SNAPSHOT-runner.jar
$ oc new-app quarkus-logging-json-app -l log-format=json

この状態でKibanaで見ると、messageフィールドにJSON形式のログ全体が文字列として(JSON構造でなく)保存されます。

次に、ClusterLogForwarderでJSONログの設定を入れます。デプロイ時に指定したラベルでJSONログとして扱うアプリを絞り込んでいます。spec.pipelines に指定した parse: json がポイントです。

apiVersion: logging.openshift.io/v1
kind: ClusterLogForwarder
metadata:
  name: instance 
  namespace: openshift-logging 
spec:
  inputs:
    - name: json-logging-apps
      application:
        selector:
          matchLabels:
            log-format: json
  pipelines:
    - inputRefs: 
        - json-logging-apps
      outputRefs: 
        - default 
      parse: json

これを oc apply したあとにログを何件か出すと、messageフィールドは元のまま、structuredフィールドにJSON構造で保管されるようになります。

Kibana にて structured内のフィールドを表示

Elasticsearchにインデックスされたログは以下のようになっています。例外をスローしてみたところ、スタックトレースが独立して保存されています(これはOpenShift Loggingでなく quarkus-logging-json の機能)。

{
  "_index": "app-json-logging-000001",
  "_type": "_doc",
  "_id": "NzQ0YWIyN2EtYjc5YS00YzNkLWE2N2UtOWIzMmExN2YzNTU4",
  "_version": 1,
  "_score": null,
  "_source": {
    "kubernetes": {
      "container_image_id": "image-registry.openshift-image-registry.svc:5000/json-logging/quarkus-logging-json-app@sha256:1bb12756c42362c1bf9cfc8b8e108b90ba3b722e37045cbab4fafe66a45ca06d",
      "container_name": "quarkus-logging-json-app",
      "namespace_id": "cce0ae22-3aae-491d-9d53-5212b375c5da",
      "flat_labels": [
        "deployment=quarkus-logging-json-app",
        "log-format=json",
        "pod-template-hash=66d78c78bc"
      ],
      "pod_ip": "10.128.1.1",
      "host": "ip-10-0-133-42.ap-southeast-1.compute.internal",
      "master_url": "https://kubernetes.default.svc",
      "pod_id": "3c1a0971-bc03-4427-81f1-13b3c9549cc5",
      "namespace_labels": {
        "openshift-pipelines_tekton_dev/namespace-reconcile-version": "v1.5",
        "kubernetes_io/metadata_name": "json-logging"
      },
      "container_image": "image-registry.openshift-image-registry.svc:5000/json-logging/quarkus-logging-json-app@sha256:1bb12756c42362c1bf9cfc8b8e108b90ba3b722e37045cbab4fafe66a45ca06d",
      "namespace_name": "json-logging",
      "pod_name": "quarkus-logging-json-app-66d78c78bc-cpx7w"
    },
    "viaq_msg_id": "NzQ0YWIyN2EtYjc5YS00YzNkLWE2N2UtOWIzMmExN2YzNTU4",
    "level": "error",
    "message": "{\"timestamp\":\"2022-01-06T02:51:11.058Z\",\"sequence\":107,\"loggerClassName\":\"org.jboss.logging.Logger\",\"loggerName\":\"io.quarkus.vertx.http.runtime.QuarkusErrorHandler\",\"level\":\"ERROR\",\"message\":\"HTTP Request to /hello/broken failed, error id: 3dec9709-d2f0-44c7-ae15-bc325a88fc53-2\",\"threadName\":\"executor-thread-0\",\"threadId\":18,\"hostName\":\"quarkus-logging-json-app-66d78c78bc-cpx7w\",\"processName\":\"quarkus-logging-json-integration-tests-1.1.2-SNAPSHOT-runner.jar\",\"processId\":1,\"stackTrace\":\"org.jboss.resteasy.spi.UnhandledException: java.lang.RuntimeException: broken\\n\\tat org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:105)\\n\\tat org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:359)\\n\\tat org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:218)\\n\\tat org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:519)\\n\\tat org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)\\n\\tat org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)\\n\\tat org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)\\n\\tat org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)\\n\\tat org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)\\n\\tat io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)\\n\\tat io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)\\n\\tat io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:91)\\n\\tat io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)\\n\\tat org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)\\n\\tat org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)\\n\\tat org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)\\n\\tat org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)\\n\\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\\n\\tat java.base/java.lang.Thread.run(Thread.java:829)\\nCaused by: java.lang.RuntimeException: broken\\n\\tat io.quarkiverse.loggingjson.it.GreetingResource.broken(GreetingResource.java:26)\\n\\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\\n\\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\\n\\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\\n\\tat java.base/java.lang.reflect.Method.invoke(Method.java:566)\\n\\tat org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)\\n\\tat org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)\\n\\tat org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)\\n\\tat org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)\\n\\tat org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)\\n\\tat org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)\\n\\tat org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)\\n\\tat org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)\\n\\tat org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)\\n\\tat org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)\\n\\tat org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)\\n\\t... 15 more\\n\",\"errorType\":\"org.jboss.resteasy.spi.UnhandledException\",\"errorMessage\":\"java.lang.RuntimeException: broken\",\"myCustomField\":\"and my custom value\"}",
    "docker": {
      "container_id": "6c346526979b637737b5c1cd36336dcda7ec3046fd6eedc1d329bd4fb552393a"
    },
    "hostname": "ip-10-0-133-42.ap-southeast-1.compute.internal",
    "log_type": "application",
    "@timestamp": "2022-01-06T02:51:11.060355+00:00",
    "pipeline_metadata": {
      "collector": {
        "received_at": "2022-01-06T02:51:11.578126+00:00",
        "name": "fluentd",
        "inputname": "fluent-plugin-systemd",
        "version": "1.7.4 1.6.0",
        "ipaddr4": "10.0.133.42"
      }
    },
    "structured": {
      "hostName": "quarkus-logging-json-app-66d78c78bc-cpx7w",
      "loggerClassName": "org.jboss.logging.Logger",
      "level": "ERROR",
      "errorType": "org.jboss.resteasy.spi.UnhandledException",
      "errorMessage": "java.lang.RuntimeException: broken",
      "message": "HTTP Request to /hello/broken failed, error id: 3dec9709-d2f0-44c7-ae15-bc325a88fc53-2",
      "threadName": "executor-thread-0",
      "myCustomField": "and my custom value",
      "threadId": 18,
      "sequence": 107,
      "processName": "quarkus-logging-json-integration-tests-1.1.2-SNAPSHOT-runner.jar",
      "processId": 1,
      "stackTrace": "org.jboss.resteasy.spi.UnhandledException: java.lang.RuntimeException: broken\n\tat org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:105)\n\tat org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:359)\n\tat org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:218)\n\tat org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:519)\n\tat org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)\n\tat org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)\n\tat org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)\n\tat org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)\n\tat org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)\n\tat io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)\n\tat io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)\n\tat io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:91)\n\tat io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)\n\tat org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)\n\tat org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)\n\tat org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)\n\tat org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:829)\nCaused by: java.lang.RuntimeException: broken\n\tat io.quarkiverse.loggingjson.it.GreetingResource.broken(GreetingResource.java:26)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.base/java.lang.reflect.Method.invoke(Method.java:566)\n\tat org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)\n\tat org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)\n\tat org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)\n\tat org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)\n\tat org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)\n\tat org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)\n\tat org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)\n\tat org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)\n\tat org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)\n\tat org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)\n\tat org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)\n\t... 15 more\n",
      "loggerName": "io.quarkus.vertx.http.runtime.QuarkusErrorHandler",
      "timestamp": "2022-01-06T02:51:11.058Z"
    }
  },
  "fields": {
    "@timestamp": [
      "2022-01-06T02:51:11.060Z"
    ],
    "pipeline_metadata.collector.received_at": [
      "2022-01-06T02:51:11.578Z"
    ]
  },
  "highlight": {
    "kubernetes.namespace_name": [
      "@kibana-highlighted-field@json-logging@/kibana-highlighted-field@"
    ]
  },
  "sort": [
    1641437471060
  ]
}

コメントを残す

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です