Uploaded image for project: 'OpenShift Logging'
  1. OpenShift Logging
  2. LOG-2666

JSON Parsing parses numeric output as JSON structure

    XMLWordPrintable

Details

    • False
    • None
    • False
    • NEW
    • NEW
    • Log Collection - Sprint 224, Log Collection - Sprint 225

    Description

      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}}

      Attachments

        Activity

          People

            vimalkum@redhat.com Vimal Kumar
            rhn-support-skrenger Simon Krenger
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: