-
Bug
-
Resolution: Won't Do
-
Normal
-
None
-
Logging 5.3.7
-
False
-
None
-
False
-
NEW
-
NEW
-
Log Collection - Sprint 224, Log Collection - Sprint 225
Issue description:
Customer reports that when an application logs a numeric output and JSON parsing is enabled, then the numeric output is parsed as valid JSON. Following this, any actual JSON output will then be rejected by ElasticSearch:
dump an error event: error_class=Fluent::Plugin::ElasticsearchErrorHandler::ElasticsearchError error="400 - Rejected by Elasticsearch
Steps to reproduce the issue:
1. Set up OpenShift Logging (I reproduced the issue using OCP 4.8 and OpenShift Logging 5.3)
2. Enable JSON Parsing in the ClusterLogForwarder:
apiVersion: logging.openshift.io/v1
kind: ClusterLogForwarder
metadata:
name: instance
namespace: openshift-logging
spec:
outputDefaults:
elasticsearch:
structuredTypeKey: kubernetes.labels.logFormat
structuredTypeName: nologformat
pipelines:
- inputRefs:
- infrastructure
- audit
name: all-to-default
outputRefs:
- default
- inputRefs:
- application
name: application-json
outputRefs:
- default
parse: json
3. Create the following Pod to generate the numeric output plus the JSON output:
apiVersion: v1
kind: Pod
metadata:
name: fedora-log-test
spec:
containers:
- command:
- /bin/bash
- -c
- echo '1234' && echo '5678' && echo '{"test":1234}' && sleep infinity
image: registry.fedoraproject.org/fedora@sha256:63fa666e22333d85eaa6684fba51efe4b48dc5f5ff7b194cdc1fa1f1290b5c32
imagePullPolicy: IfNotPresent
name: fedora
resources: {}
Expected behaviour:
The first two lines are NOT interpreted as valid JSON and only the third line is parsed as JSON:
1234
5678
{"test":1234}
Actual output:
Only the first two lines are logged in ElasticSearch / Kibana:
Time message May 31st 2022, 09:27:26.276 1234 May 31st 2022, 09:27:26.276 5678
Fluentd fails with the following error:
$ oc logs collector-tfvc7 -c collector Setting each total_size_limit for 3 buffers to 6415029657 bytes Setting queued_chunks_limit_size for each buffer to 764 Setting chunk_limit_size for each buffer to 8388608 2022-05-31 07:26:05 +0000 [warn]: '@' is the system reserved prefix. It works in the nested configuration for now but it will be rejected: @timestamp 2022-05-31 07:26:07 +0000 [warn]: /var/log/ovn/acl-audit-log.log not found. Continuing without tailing it. 2022-05-31 07:27:28 +0000 [warn]: dump an error event: error_class=Fluent::Plugin::ElasticsearchErrorHandler::ElasticsearchError error="400 - Rejected by Elasticsearch" location=nil tag="kubernetes.var.log.containers.fedora-5b4f76ffff-pg4bg_simon1-project_fedora-5953dc2b505e7424f1b803ddfdf2720c935918cd61e0620ccedd9dc42668bea9.log" time=2022-05-31 07:27:27.385839853 +0000 record={"docker"=>{"container_id"=>"5953dc2b505e7424f1b803ddfdf2720c935918cd61e0620ccedd9dc42668bea9"}, "kubernetes"=>{"container_name"=>"fedora", "namespace_name"=>"simon1-project", "pod_name"=>"fedora-5b4f76ffff-pg4bg", "container_image"=>"registry.fedoraproject.org/fedora@sha256:63fa666e22333d85eaa6684fba51efe4b48dc5f5ff7b194cdc1fa1f1290b5c32", "container_image_id"=>"registry.fedoraproject.org/fedora@sha256:63fa666e22333d85eaa6684fba51efe4b48dc5f5ff7b194cdc1fa1f1290b5c32", "pod_id"=>"737b0828-97a9-4ade-91b1-fc449e3924b0", "pod_ip"=>"10.128.2.123", "host"=>"ip-10-0-144-2.eu-central-1.compute.internal", "master_url"=>"https://kubernetes.default.svc", "namespace_id"=>"8747ef26-f3ef-42a5-b2d2-4601807d0ae7", "namespace_labels"=>{"owner"=>"simon1", "kubernetes_io/metadata_name"=>"simon1-project"}, "flat_labels"=>["deployment=fedora", "pod-template-hash=5b4f76ffff"]}, "message"=>"{\"test\":1234}", "level"=>"unknown", "hostname"=>"ip-10-0-144-2.eu-central-1.compute.internal", "pipeline_metadata"=>{"collector"=>{"ipaddr4"=>"10.0.144.2", "inputname"=>"fluent-plugin-systemd", "name"=>"fluentd", "received_at"=>"2022-05-31T07:27:27.385307+00:00", "version"=>"1.7.4 1.6.0"}}, "openshift"=>{"sequence"=>513}, "@timestamp"=>"2022-05-31T07:27:26.276153+00:00", "viaq_index_name"=>"app-nologformat-write", "viaq_msg_id"=>"YmQyYzNjYjItYWNlOS00YTM2LTljNDUtYzgzODI2ODEzOWM1", "log_type"=>"application", "structured"=>{"test"=>1234}}
