こんにちは、平田です。
アプリのログを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構造で保管されるようになります。
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
]
}