Bug 1734592

Summary: Empty fields are skipped when set SKIP_EMPTY=false and USE_MMEXTERNAL=false in rsyslog daemonset.
Product: OpenShift Container Platform Reporter: Qiaoling Tang <qitang>
Component: LoggingAssignee: Noriko Hosoi <nhosoi>
Status: CLOSED NOTABUG QA Contact: Qiaoling Tang <qitang>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 4.2.0CC: aos-bugs, mburke, rmeggins
Target Milestone: ---   
Target Release: 4.2.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-10-04 21:56:19 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Qiaoling Tang 2019-07-31 01:43:06 UTC
Description of problem:
set SKIP_EMPTY=false USE_MMEXTERNAL=false and MERGE_JSON_LOG=true, then generate some json logs contain some empty fields, check logs in ES or Kibana, the empty fields are skipped:
oc get ds rsyslog -oyaml:

          env:
          - name: LOGGING_FILE_PATH
            value: /var/log/rsyslog/rsyslog.log
          - name: LOGGING_FILE_SIZE
            value: "1024000"
          - name: LOGGING_FILE_AGE
            value: "10"
          - name: CROND_OPTIONS
          - name: RSYSLOG_WORKDIRECTORY
            value: /var/lib/rsyslog.pod
          - name: MERGE_JSON_LOG
            value: "true"
          - name: SKIP_EMPTY
            value: "false"
          - name: USE_MMEXTERNAL
            value: "false"

log in pod:
{"@version":1,"@timestamp":"2019-07-30T21:20:26.000-0400","sequence":57791,"loggerClassName":"org.jboss.logmanager.Logger","loggerName":"stdout","level":"INFO","threadName":"EJB default - 3","message":"timer: Hello from control: 1564536026000","threadId":127,"mdc":{},"ndc":"","log-handler":"CONSOLE"}

log in Kibana:
{
  "_index": "project.json1.edcf1ed0-b298-11e9-a642-000d3a9364a8.2019.07.30",
  "_type": "com.redhat.viaq.common",
  "_id": "1593C8BCC5C24782ABFD57AE87452D39",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2019-07-30T21:20:26.000-0400",
    "@version": 1,
    "docker": {
      "container_id": "277f89a7b10a77226fb308978b453f7860a020c18c99449d74ea868cc731b922"
    },
    "file": "/var/log/containers/log4j2-ex-1-h8sxv_json1_log4j2-ex-277f89a7b10a77226fb308978b453f7860a020c18c99449d74ea868cc731b922.log",
    "hostname": "qe-qitang-gt5mr-worker-centralus3-b2b9x",
    "kubernetes": {
      "container_name": "log4j2-ex",
      "creation_timestamp": "2019-07-30T07:09:10Z",
      "host": "qe-qitang-gt5mr-worker-centralus3-b2b9x",
      "labels": {
        "app": "log4j2-ex",
        "deployment": "log4j2-ex-1",
        "deploymentconfig": "log4j2-ex"
      },
      "master_url": "https://kubernetes.default.svc.cluster.local:443",
      "namespace_id": "edcf1ed0-b298-11e9-a642-000d3a9364a8",
      "namespace_name": "json1",
      "pod_id": "cc83186e-b2aa-11e9-b0cb-000d3a909a5e",
      "pod_name": "log4j2-ex-1-h8sxv"
    },
    "level": "info",
    "log-handler": "CONSOLE",
    "loggerClassName": "org.jboss.logmanager.Logger",
    "loggerName": "stdout",
    "message": "timer: Hello from control: 1564536026000",
    "offset": "9609810",
    "pipeline_metadata": {
      "collector": {
        "inputname": "imfile",
        "ipaddr4": "10.0.32.5",
        "ipaddr6": "::ffff:10.0.32.5",
        "name": "rsyslog",
        "original_raw_message": "{\"@version\":1,\"@timestamp\":\"2019-07-30T21:20:26.000-0400\",\"sequence\":57791,\"loggerClassName\":\"org.jboss.logmanager.Logger\",\"loggerName\":\"stdout\",\"level\":\"INFO\",\"threadName\":\"EJB default - 3\",\"message\":\"timer: Hello from control: 1564536026000\",\"threadId\":127,\"mdc\":{},\"ndc\":\"\",\"log-handler\":\"CONSOLE\"}",
        "received_at": "2019-07-31T01:20:26.001181+00:00",
        "version": "8.37.0-9.el7 "
      }
    },
    "sequence": 57791,
    "threadId": 127,
    "threadName": "EJB default - 3"
  },
  "fields": {
    "@timestamp": [
      1564536026000
    ],
    "pipeline_metadata.collector.received_at": [
      1564536026001
    ]
  },
  "sort": [
    1564536026000
  ]
}

Version-Release number of selected component (if applicable):
ose-cluster-logging-operator-v4.2.0-201907292219
ose-logging-rsyslog-v4.2.0-201907291819

How reproducible:
Always

Steps to Reproduce:
1. Deploy logging using rsyslog as log collector
2. oc set env ds/rsyslog MERGE_JSON_LOG=true SKIP_EMPTY=false USE_MMEXTERNAL=false
3. create new project, then create an app to generate json logs in the new project
4. check logs in Kibana

Actual results:
The empty fields are skipped

Expected results:
The empty fields should be kept.

Additional info:

Comment 2 Qiaoling Tang 2019-08-02 08:17:36 UTC
Tested with ose-cluster-logging-operator/images/v4.2.0-201908020219, the issue isn't fixed

$ oc exec rsyslog-h22t6 -- env |grep -e SKIP -e USE -e JSON
Defaulting container name to rsyslog.
Use 'oc describe pod/rsyslog-h22t6 -n openshift-logging' to see all of the containers in this pod.
SKIP_EMPTY=false
USE_MMEXTERNAL=false
MERGE_JSON_LOG=true

$ oc exec rsyslog-h22t6 -- logs |grep INFO
Defaulting container name to rsyslog.
Use 'oc describe pod/rsyslog-h22t6 -n openshift-logging' to see all of the containers in this pod.
INFO: Disabling Prometheus endpoint
INFO: Disabling Prometheus endpoint
INFO: Disabling Prometheus endpoint
INFO: Disabling Prometheus endpoint

the empty fields are skipped:

    "level": "info",
    "log-handler": "CONSOLE",
    "loggerClassName": "org.jboss.logmanager.Logger",
    "loggerName": "stdout",
    "message": "timer: Hello from control: 1564733597000",
    "offset": "6735231",
    "pipeline_metadata": {
      "collector": {
        "inputname": "imfile",
        "ipaddr4": "10.0.144.162",
        "ipaddr6": "::ffff:10.0.144.162",
        "name": "rsyslog",
        "original_raw_message": "{\"@version\":1,\"@timestamp\":\"2019-08-02T04:13:17.001-0400\",\"sequence\":19374,\"loggerClassName\":\"org.jboss.logmanager.Logger\",\"loggerName\":\"stdout\",\"level\":\"INFO\",\"threadName\":\"EJB default - 6\",\"message\":\"timer: Hello from control: 1564733597000\",\"threadId\":146,\"mdc\":{},\"ndc\":\"\",\"log-handler\":\"CONSOLE\"}",
        "received_at": "2019-08-02T08:13:17.001453+00:00",
        "version": "8.37.0-9.el7 "
      }
    },
    "sequence": 19374,
    "threadId": 146,
    "threadName": "EJB default - 6"

Comment 4 Qiaoling Tang 2019-08-06 06:02:57 UTC
Bug verification blocked by https://bugzilla.redhat.com/show_bug.cgi?id=1737286

Comment 5 Qiaoling Tang 2019-08-07 01:28:49 UTC
Verified with ose-cluster-logging-operator-v4.2.0-201908061819

Comment 6 Michael Burke 2019-10-04 20:35:22 UTC
Can this BZ be closed?

Comment 7 Noriko Hosoi 2019-10-04 21:56:19 UTC
(In reply to Michael Burke from comment #6)
> Can this BZ be closed?

Yes, I believe so.  Thanks, Michael!