Bug 1554293 - [3.9] logging-eventrouter event not formatted correctly in Elasticsearch when using MUX
Summary: [3.9] logging-eventrouter event not formatted correctly in Elasticsearch when...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Logging
Version: 3.9.0
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: 3.9.z
Assignee: Noriko Hosoi
QA Contact: Anping Li
URL:
Whiteboard:
Depends On:
Blocks: 1632892 1632895
TreeView+ depends on / blocked
 
Reported: 2018-03-12 11:00 UTC by Anping Li
Modified: 2018-12-13 19:27 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Cause: When fluentd is configured as the combination of collectors and MUX, event logs from the event were supposed to be processed by MUX not by the collector for the both MUX_CLIENT_MODE maximal and minimal. It is because if an event log is formatted in the collector (note: the event record is put under the kubernetes key), the log is forwarded to MUX and passed to the k8s-meta plugin there and the existing kubernetes record is overwritten. It wiped out the event info from the log. Fix 1: To avoid the replacement, if the log is from event router, the tag is rewritten to ${tag}.raw in input-post-forward-mux.conf, which makes the log treated in the MUX_CLIENT_MODE=minimal way. Fix 2: There was another bug in ansible. That is, the environment variable TRANSFORM_EVENTS was not set in MUX even if openshift_logging_install_eventrouter is set to true. Result: With these 2 fixes, the event logs are correctly logged when MUX is configured with MUX_CLIENT_MODE=maximal as well as minimal.
Clone Of:
: 1632892 1632895 (view as bug list)
Environment:
Last Closed: 2018-12-13 19:26:59 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
10 search outputs with "q=kubernetes.event.verb:*" (60.72 KB, text/plain)
2018-05-31 21:58 UTC, Noriko Hosoi
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2018:3748 0 None None None 2018-12-13 19:27:10 UTC

Description Anping Li 2018-03-12 11:00:17 UTC
Description of problem:
The logging-evnetrouter json logs is't well parsed. No document variable named kubernetes.event.verb/event in elasticsearch


Version-Release number of selected component (if applicable):
logging:v3.9.7

How reproducible:
always

Steps to Reproduce:
1. Deploy logging v3.9 with  logging-eventrouter on cri-o
openshift_logging_install_eventrouter=true
2. check the enventrouter log in elasticsearch 

Actual results:

No document varibale named kubernetes.event.verb/event 

{
  "_index": ".operations.2018.03.12",
  "_type": "com.redhat.viaq.common",
  "_id": "ZTM3N2JjNzUtZTBkZC00YWVmLTlmNGMtYTBjMTRjZmJiZTE0",
  "_score": null,
  "_source": {
    "logtag": "F",
    "message": "Readiness probe failed: Get https://10.130.0.4:8443/healthz: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)",
    "level": "info",
    "hostname": "ip-172-18-10-156.ec2.internal",
    "kubernetes": {
      "container_name": "kube-eventrouter",
      "namespace_name": "default",
      "pod_name": "logging-eventrouter-1-ftx2t",
      "pod_id": "8e1614ba-25cc-11e8-841e-0e4dd8e76b72",
      "labels": {
        "component": "eventrouter",
        "deployment": "logging-eventrouter-1",
        "deploymentconfig": "logging-eventrouter",
        "logging-infra": "eventrouter",
        "provider": "openshift"
      },
      "host": "ip-172-18-10-156.ec2.internal",
      "master_url": "https://kubernetes.default.svc.cluster.local",
      "namespace_id": "58706956-25c8-11e8-afac-0e4dd8e76b72"
    },
    "pipeline_metadata": {
      "collector": {
        "original_raw_message": "{\"verb\":\"ADDED\",\"event\":{\"metadata\":{\"name\":\"apiserver-hlqkn.151b1dd1c2cfdac3\",\"namespace\":\"openshift-template-service-broker\",\"selfLink\":\"/api/v1/namespaces/openshift-template-service-broker/events/apiserver-hlqkn.151b1dd1c2cfdac3\",\"uid\":\"fbed4399-25e1-11e8-841e-0e4dd8e76b72\",\"resourceVersion\":\"29542\",\"creationTimestamp\":\"2018-03-12T10:41:55Z\"},\"involvedObject\":{\"kind\":\"Pod\",\"namespace\":\"openshift-template-service-broker\",\"name\":\"apiserver-hlqkn\",\"uid\":\"f0bd3c4a-25c9-11e8-841e-0e4dd8e76b72\",\"apiVersion\":\"v1\",\"resourceVersion\":\"3090\",\"fieldPath\":\"spec.containers{c}\"},\"reason\":\"Unhealthy\",\"message\":\"Readiness probe failed: Get https://10.130.0.4:8443/healthz: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)\",\"source\":{\"component\":\"kubelet\",\"host\":\"ip-172-18-2-200.ec2.internal\"},\"firstTimestamp\":\"2018-03-12T08:08:05Z\",\"lastTimestamp\":\"2018-03-12T10:41:55Z\",\"count\":5,\"type\":\"Warning\"}}",
        "ipaddr4": "10.131.0.11",
        "ipaddr6": "fe80::8c80:b3ff:fea2:e97d",
        "inputname": "fluent-plugin-systemd",
        "name": "fluentd",
        "received_at": "2018-03-12T10:41:56.637246+00:00",
        "version": "0.12.42 1.6.0"
      },
      "normalizer": {
        "ipaddr4": "10.131.0.12",
        "ipaddr6": "fe80::3094:eaff:fea2:24de",
        "inputname": "fluent-plugin-systemd",
        "name": "fluentd",
        "received_at": "2018-03-12T10:42:01.729247+00:00",
        "version": "0.12.42 1.6.0"
      }
    },
    "@timestamp": "2018-03-12T10:41:55Z",
    "viaq_msg_id": "ZTM3N2JjNzUtZTBkZC00YWVmLTlmNGMtYTBjMTRjZmJiZTE0",
    "CONTAINER_NAME": "k8s_kube-eventrouter.0_logging-eventrouter-1-ftx2t_default_0_01234567",
    "CONTAINER_ID_FULL": "573df1f4a30e76d83ff14e2386c6c608965d554e628428e5198acf92e4daa3c1",
    "docker": {
      "container_id": "573df1f4a30e76d83ff14e2386c6c608965d554e628428e5198acf92e4daa3c1"
    }
  },
  "fields": {
    "@timestamp": [
      1520851315000
    ],
 "pipeline_metadata.normalizer.received_at": [
      1520851321729
    ],
    "pipeline_metadata.collector.received_at": [
      1520851316637
    ]
  },
  "highlight": {
    "kubernetes.pod_name": [
      "@kibana-highlighted-field@logging-eventrouter-1-ftx2t@/kibana-highlighted-field@"
    ]
  },
  "sort": [
    1520851315000
  ]
}


Expected results:
The logging Event router format json are well parsed.

Additional info:

Comment 1 Jan Wozniak 2018-03-12 14:11:39 UTC
could you please provide exactly which fluentd image have you used?

I tried to reproduce with built from master and I see correct processing:

"_index" : ".operations.2018.03.12",
"_type" : "com.redhat.viaq.common",
"_id" : "OGJkOTY0Y2QtMTE5NC00YzJhLTgyMjMtY2NjNDkwOGQ1MTY1",
"_score" : 1.9674063,
"_source" : {
  "logtag" : "F",
  "docker" : {
    "container_id" : "d51c283fb613eaf22eae25d509d1a5649f64c59531529d57b57923664fa2aa18"
  },
  "kubernetes" : {
    "container_name" : "kube-eventrouter",
    "namespace_name" : "default",
    "pod_name" : "logging-eventrouter-1-f6dg5",
    "pod_id" : "b430ade4-25fa-11e8-b625-5254001ecf30",
    "labels" : {
      "component" : "eventrouter",
      "deployment" : "logging-eventrouter-1",
      "deploymentconfig" : "logging-eventrouter",
      "logging-infra" : "eventrouter",
      "provider" : "openshift"
    },
    "host" : "crio",
    "master_url" : "https://kubernetes.default.svc.cluster.local",
    "namespace_id" : "be9444b3-0d96-11e8-90b6-5254001ecf30",
    "event" : {
      "metadata" : {
        "name" : "logging-curator-1-dvdfz.151b2fd95f66a559",
        "namespace" : "logging",
        "selfLink" : "/api/v1/namespaces/logging/events/logging-curator-1-dvdfz.151b2fd95f66a559",
        "uid" : "a6613796-25fa-11e8-b625-5254001ecf30",
        "resourceVersion" : "390450"
      },
      "involvedObject" : {
        "kind" : "Pod",
        "namespace" : "logging",
        "name" : "logging-curator-1-dvdfz",
        "uid" : "a40f434b-25fa-11e8-b625-5254001ecf30",
        "apiVersion" : "v1",
        "resourceVersion" : "390308",
        "fieldPath" : "spec.containers{curator}"
      },
      "reason" : "BackOff",
      "source" : {
        "component" : "kubelet",
        "host" : "crio"
      },
      "firstTimestamp" : "2018-03-12T13:38:29Z",
      "lastTimestamp" : "2018-03-12T13:38:57Z",
      "count" : 2,
      "type" : "Normal",
      "verb" : "ADDED"
    }
  },
  "message" : "Back-off pulling image \"docker.io/openshift/origin-logging-curator:v3.9.0\"",
  "level" : "info",
  "hostname" : "crio",
  "pipeline_metadata" : {
    "collector" : {
      "original_raw_message" : "{\"verb\":\"ADDED\",\"event\":{\"metadata\":{\"name\":\"logging-curator-1-dvdfz.151b2fd95f66a559\",\"namespace\":\"logging\",\"selfLink\":\"/api/v1/namespaces/logging/events/logging-curator-1-dvdfz.151b2fd95f66a559\",\"uid\":\"a6613796-25fa-11e8-b625-5254001ecf30\",\"resourceVersion\":\"390450\",\"creationTimestamp\":\"2018-03-12T13:38:29Z\"},\"involvedObject\":{\"kind\":\"Pod\",\"namespace\":\"logging\",\"name\":\"logging-curator-1-dvdfz\",\"uid\":\"a40f434b-25fa-11e8-b625-5254001ecf30\",\"apiVersion\":\"v1\",\"resourceVersion\":\"390308\",\"fieldPath\":\"spec.containers{curator}\"},\"reason\":\"BackOff\",\"message\":\"Back-off pulling image \\\"docker.io/openshift/origin-logging-curator:v3.9.0\\\"\",\"source\":{\"component\":\"kubelet\",\"host\":\"crio\"},\"firstTimestamp\":\"2018-03-12T13:38:29Z\",\"lastTimestamp\":\"2018-03-12T13:38:57Z\",\"count\":2,\"type\":\"Normal\"}}",
      "ipaddr4" : "10.128.0.240",
      "ipaddr6" : "fe80::804f:8cff:fec5:e3ea",
      "inputname" : "fluent-plugin-systemd",
      "name" : "fluentd",
      "received_at" : "2018-03-12T13:39:46.200738+00:00",
      "version" : "0.12.42 1.6.0"
    }
  },
  "@timestamp" : "2018-03-12T13:38:29Z",
  "viaq_msg_id" : "OGJkOTY0Y2QtMTE5NC00YzJhLTgyMjMtY2NjNDkwOGQ1MTY1"
}

Comment 2 Anping Li 2018-03-12 23:25:19 UTC
@jan, logging-fluentd:v3.9.7

Comment 3 Anping Li 2018-03-13 02:52:28 UTC
The issue only exist when mux was enabled.

Comment 4 Jan Wozniak 2018-03-15 12:31:47 UTC
it looks like it is not specific to cri-o, the behavior with eventrouter and MUX is shown on docker as well, it is probably related to this

`openshift_logging_use_mux`: ... send raw logs to mux and turn off the k8s metadata plugin...

The event formatting happens in k8s metadata filter plugin

Comment 5 Rich Megginson 2018-03-15 15:15:02 UTC
(In reply to Jan Wozniak from comment #4)
> it looks like it is not specific to cri-o, the behavior with eventrouter and
> MUX is shown on docker as well, it is probably related to this
> 
> `openshift_logging_use_mux`: ... send raw logs to mux and turn off the k8s
> metadata plugin...

Not exactly.

> 
> The event formatting happens in k8s metadata filter plugin

Not exactly.

The event formatting happens in the viaq plugin: https://github.com/ViaQ/fluent-plugin-viaq_data_model/blob/master/lib/fluent/plugin/filter_viaq_data_model.rb#L328
and
https://github.com/ViaQ/fluent-plugin-viaq_data_model/blob/master/lib/fluent/plugin/filter_viaq_data_model_systemd.rb#L122

In order to use mux, fluentd has to be configured with MUX_CLIENT_MODE=maximal or minimal.  In either case, fluentd does not do the k8s meta lookup - instead, mux is supposed to do that.  So what should be happening is:

fluentd sends record without event to mux
mux does k8s lookup and adds metadata including event
the viaq plugin formats the event data

Comment 6 Jan Wozniak 2018-03-23 15:39:59 UTC
Thanks for the clarification Rich. I would like to ask you for your opinion on how to fix this providing few more details

I currently observe following sequence, please correct if it's wrong:
1) fluentd: reads event from eventrouter stdout
2) fluentd: k8_meta filter - is skipped in favor of mux
3) fluentd: viaq filter - either k8s_json_file or k8s_journal formatter moves "event" inside "kubernetes" field, creates one if it does not exist, and in this case it does not exist because k8_meta was skipped
4) mux: receives the log
5) mux: k8_meta filter - puts k8 metadata into the record, overrides anything that has already been there [1, 2]
6) mux: viaq filter - given the record tag matches **mux, the k8_json_file and k8s_journal formatters are not called here and formatters are skipped entirely [3]

(In reply to Rich Megginson from comment #5)
> fluentd sends record without event to mux
> mux does k8s lookup and adds metadata including event
> the viaq plugin formats the event data
Would that mean allowing formatters in mux? Currently, I think they are skipped [3]

I see potentially three ways how to fix this.
A) skip event processing in fluentd and enable k8s_json_file or k8s_journal formatters in mux
B) move event processing outside of formatters directly into filter() [4], disable event processing in fluentd and enable in mux
C) change k8_meta filter in such way that it respects already existing "kubernetes" field and merges the new information in instead of overwriting everything

If you see an option D that would be fantastic, otherwise please let me know if you prefer A, B, or C. I am personally in favor of C, because it should prevent any other potential issue in the pipeline if we later include another plugin that modifies "kubernetes" field in any way.




[1] https://github.com/fabric8io/fluent-plugin-kubernetes_metadata_filter/blob/master/lib/fluent/plugin/filter_kubernetes_metadata.rb#L325

[2] https://github.com/fabric8io/fluent-plugin-kubernetes_metadata_filter/blob/master/lib/fluent/plugin/filter_kubernetes_metadata.rb#L286

[3] https://github.com/openshift/origin-aggregated-logging/blob/master/fluentd/configs.d/openshift/filter-viaq-data-model.conf#L18-L24

[4] https://github.com/ViaQ/fluent-plugin-viaq_data_model/blob/master/lib/fluent/plugin/filter_viaq_data_model.rb#L452

Comment 7 Rich Megginson 2018-03-29 16:31:36 UTC
So the event data is added to the record by the k8s meta filter?  If so, then yes, looks like a bug in the processing of MUX_CLIENT_MODE=maximal records on the mux server side - we still need to do the event processing - I think we'll have to change the way we do the **mux tagging, so that we will do the k8s-meta filter _and_ the viaq filter with filter processing for k8s records.  The code assumes that the k8s meta filter does not add any new data that would affect subsequent formatting, but this assumption is wrong in the case of events.

Comment 8 Noriko Hosoi 2018-05-31 21:58:46 UTC
Created attachment 1446436 [details]
10 search outputs with "q=kubernetes.event.verb:*"

I tried to reproduce the problem with the MUX (MUX_CLIENT_MODE=maximal is set to collector fluentd) / docker combination, but it seems it's working as expected (see also the attachement).  Please note that I'm testing with upstream release-3.9.  I'm wondering this issue has been already fixed???

Comment 10 Noriko Hosoi 2018-08-02 18:51:05 UTC
Hi @Anping,

Whenever you have a chance, could you please try this test case with the current v3.9 version?  I could not reproduce the problem.  Thanks!

Comment 11 Anping Li 2018-09-19 08:00:21 UTC
There is still no kubernetes.verb and kubernetes.event items when mux are enabled.
{
  "_index": ".operations.2018.09.19",
  "_type": "com.redhat.viaq.common",
  "_id": "NzMwMzgzMmYtZDA4YS00NjIwLWI1NTMtYWZlZmY1ZjM1OTEz",
  "_score": null,
  "_source": {
    "message": "MountVolume.SetUp succeeded for volume \"deployer-token-47g96\" ",
    "level": "info",
    "hostname": "qe-39stage2node-registry-router-1",
    "kubernetes": {
      "container_name": "kube-eventrouter",
      "namespace_name": "default",
      "pod_name": "logging-eventrouter-1-48vhr",
      "pod_id": "9964d802-bbdf-11e8-91d9-fa163e85dfa0",
      "labels": {
        "component": "eventrouter",
        "deployment": "logging-eventrouter-1",
        "deploymentconfig": "logging-eventrouter",
        "logging-infra": "eventrouter",
        "provider": "openshift"
      },
      "host": "qe-39stage2node-registry-router-1",
      "master_url": "https://kubernetes.default.svc.cluster.local",
      "namespace_id": "bbf334b0-bbcb-11e8-9802-fa163e85dfa0"
    },
    "pipeline_metadata": {
      "collector": {
        "original_raw_message": "{\"verb\":\"ADDED\",\"event\":{\"metadata\":{\"name\":\"logging-es-data-master-g0nuul4r-1-deploy.1555bd4b83e3e014\",\"namespace\":\"openshift-logging\",\"selfLink\":\"/api/v1/namespaces/openshift-logging/events/logging-es-data-master-g0nuul4r-1-deploy.1555bd4b83e3e014\",\"uid\":\"a19fe0da-bbdf-11e8-91d9-fa163e85dfa0\",\"resourceVersion\":\"30966\",\"creationTimestamp\":\"2018-09-19T07:42:59Z\"},\"involvedObject\":{\"kind\":\"Pod\",\"namespace\":\"openshift-logging\",\"name\":\"logging-es-data-master-g0nuul4r-1-deploy\",\"uid\":\"a17d41a3-bbdf-11e8-91d9-fa163e85dfa0\",\"apiVersion\":\"v1\",\"resourceVersion\":\"30961\"},\"reason\":\"SuccessfulMountVolume\",\"message\":\"MountVolume.SetUp succeeded for volume \\\"deployer-token-47g96\\\" \",\"source\":{\"component\":\"kubelet\",\"host\":\"qe-39stage2master-etcd-1\"},\"firstTimestamp\":\"2018-09-19T07:42:59Z\",\"lastTimestamp\":\"2018-09-19T07:42:59Z\",\"count\":1,\"type\":\"Normal\"}}\n",
        "ipaddr4": "10.130.1.24",
        "ipaddr6": "fe80::1413:60ff:fe6c:d45e",
        "inputname": "fluent-plugin-systemd",
        "name": "fluentd",
        "received_at": "2018-09-19T07:43:29.328489+00:00",
        "version": "0.12.43 1.6.0"
      },
      "normalizer": {
        "ipaddr4": "10.128.1.229",
        "ipaddr6": "fe80::e027:92ff:fe35:8f72",
        "inputname": "fluent-plugin-systemd",
        "name": "fluentd",
        "received_at": "2018-09-19T07:45:49.324547+00:00",
        "version": "0.12.43 1.6.0"
      }
    },
    "@timestamp": "2018-09-19T07:42:59Z",
    "viaq_msg_id": "NzMwMzgzMmYtZDA4YS00NjIwLWI1NTMtYWZlZmY1ZjM1OTEz",
    "CONTAINER_NAME": "k8s_kube-eventrouter.0_logging-eventrouter-1-48vhr_default_0_01234567",
    "CONTAINER_ID_FULL": "a3adfd8d18e03c64e3b400e1de5b640a75fa1872fa3df12ec2c515b8c0a9fc5c",
    "docker": {
      "container_id": "a3adfd8d18e03c64e3b400e1de5b640a75fa1872fa3df12ec2c515b8c0a9fc5c"
    }
  },
  "fields": {
    "@timestamp": [
      1537342979000
    ],
    "pipeline_metadata.normalizer.received_at": [
      1537343149324
    ],
    "pipeline_metadata.collector.received_at": [
      1537343009328
    ]
  },
  "sort": [
    1537342979000
  ]
}

Comment 12 Anping Li 2018-09-19 10:05:44 UTC
A document pushed without mux pods:

{
  "_index": ".operations.2018.09.19",
  "_type": "com.redhat.viaq.common",
  "_id": "ZTcxZjUzZWEtZmM4My00YmY2LWJiN2UtNWE1ZGQ4NzgxYWIy",
  "_score": null,
  "_source": {
    "docker": {
      "container_id": "f5b62da7fd57c1092d813c3ac52569229fe848af1ef85a091d3139491017852c"
    },
    "kubernetes": {
      "container_name": "kube-eventrouter",
      "namespace_name": "default",
      "pod_name": "logging-eventrouter-1-tmw92",
      "pod_id": "dfe1e2c1-bbe5-11e8-91d9-fa163e85dfa0",
      "labels": {
        "component": "eventrouter",
        "deployment": "logging-eventrouter-1",
        "deploymentconfig": "logging-eventrouter",
        "logging-infra": "eventrouter",
        "provider": "openshift"
      },
      "host": "qe-39stage2node-registry-router-1",
      "master_url": "https://kubernetes.default.svc.cluster.local",
      "namespace_id": "bbf334b0-bbcb-11e8-9802-fa163e85dfa0",
      "event": {
        "metadata": {
          "name": "logging-es-data-master-4ysme13t-1-qkgwf.1555bfc326511819",
          "namespace": "openshift-logging",
          "selfLink": "/api/v1/namespaces/openshift-logging/events/logging-es-data-master-4ysme13t-1-qkgwf.1555bfc326511819",
          "uid": "f29be195-bbe5-11e8-91d9-fa163e85dfa0",
          "resourceVersion": "37183"
        },
        "involvedObject": {
          "kind": "Pod",
          "namespace": "openshift-logging",
          "name": "logging-es-data-master-4ysme13t-1-qkgwf",
          "uid": "e8f36d43-bbe5-11e8-91d9-fa163e85dfa0",
          "apiVersion": "v1",
          "resourceVersion": "37131",
          "fieldPath": "spec.containers{proxy}"
        },
        "reason": "Pulled",
        "source": {
          "component": "kubelet",
          "host": "qe-39stage2master-etcd-1"
        },
        "firstTimestamp": "2018-09-19T08:28:12Z",
        "lastTimestamp": "2018-09-19T08:28:12Z",
        "count": 1,
        "type": "Normal",
        "verb": "ADDED"
      }
    },
    "message": "Container image \"registry.access.stage.redhat.com/openshift3/oauth-proxy:v3.9\" already present on machine",
    "level": "info",
    "hostname": "qe-39stage2node-registry-router-1",
    "pipeline_metadata": {
      "collector": {
        "original_raw_message": "{\"verb\":\"ADDED\",\"event\":{\"metadata\":{\"name\":\"logging-es-data-master-4ysme13t-1-qkgwf.1555bfc326511819\",\"namespace\":\"openshift-logging\",\"selfLink\":\"/api/v1/namespaces/openshift-logging/events/logging-es-data-master-4ysme13t-1-qkgwf.1555bfc326511819\",\"uid\":\"f29be195-bbe5-11e8-91d9-fa163e85dfa0\",\"resourceVersion\":\"37183\",\"creationTimestamp\":\"2018-09-19T08:28:12Z\"},\"involvedObject\":{\"kind\":\"Pod\",\"namespace\":\"openshift-logging\",\"name\":\"logging-es-data-master-4ysme13t-1-qkgwf\",\"uid\":\"e8f36d43-bbe5-11e8-91d9-fa163e85dfa0\",\"apiVersion\":\"v1\",\"resourceVersion\":\"37131\",\"fieldPath\":\"spec.containers{proxy}\"},\"reason\":\"Pulled\",\"message\":\"Container image \\\"registry.access.stage.redhat.com/openshift3/oauth-proxy:v3.9\\\" already present on machine\",\"source\":{\"component\":\"kubelet\",\"host\":\"qe-39stage2master-etcd-1\"},\"firstTimestamp\":\"2018-09-19T08:28:12Z\",\"lastTimestamp\":\"2018-09-19T08:28:12Z\",\"count\":1,\"type\":\"Normal\"}}\n",
        "ipaddr4": "10.130.1.27",
        "ipaddr6": "fe80::287b:91ff:fe4c:7afd",
        "inputname": "fluent-plugin-systemd",
        "name": "fluentd",
        "received_at": "2018-09-19T08:28:30.919078+00:00",
        "version": "0.12.43 1.6.0"
      }
    },
    "@timestamp": "2018-09-19T08:28:12Z",
    "viaq_msg_id": "ZTcxZjUzZWEtZmM4My00YmY2LWJiN2UtNWE1ZGQ4NzgxYWIy"
  },
  "fields": {
    "@timestamp": [
      1537345692000
    ],
    "pipeline_metadata.collector.received_at": [
      1537345710919
    ],
    "kubernetes.event.firstTimestamp": [
      1537345692000
    ]
  },
  "highlight": {
    "kubernetes.pod_name": [
      "@kibana-highlighted-field@logging-eventrouter-1-tmw92@/kibana-highlighted-field@"
    ]
  },
  "sort": [
    1537345692000
  ]
}

Comment 13 Noriko Hosoi 2018-09-19 18:37:37 UTC
Thanks for retesting, Anping.  I'm trying to figure out what makes the difference between your test result and mine in #c8.
https://bugzilla.redhat.com/attachment.cgi?id=1446436

When you deploy the openshift-logging with mux, what value is set to MUX_CLIENT_MODE?  It's default to maximal.  To verify it, could you check if /etc/fluent/configs.d/openshift/filter-k8s-meta.conf exists in the fluentd and the mux pods?

Comment 14 Noriko Hosoi 2018-09-19 22:56:30 UTC
Sorry, Anping.  Please ignore #c13.  I could reproduce the problem.

Comment 16 openshift-github-bot 2018-09-26 22:13:02 UTC
Commits pushed to master at https://github.com/openshift/openshift-ansible

https://github.com/openshift/openshift-ansible/commit/e215ce7c5d8fc8dc8bf248ae03a4507859ef4df0
Bug 1554293 - logging-eventrouter event not formatted correctly in Elasticsearch when using MUX

If openshift_logging_install_eventrouter is true, set TRANSFORM_EVENTS true in MUX, as well.

https://github.com/openshift/openshift-ansible/commit/c00b9804f0eb10b3d129e9ca3e6fa7dd63bc26da
Merge pull request #10207 from nhosoi/bz1554293

Bug 1554293 - logging-eventrouter event not formatted correctly in El…

Comment 17 openshift-github-bot 2018-09-28 15:41:59 UTC
Commits pushed to master at https://github.com/openshift/origin-aggregated-logging

https://github.com/openshift/origin-aggregated-logging/commit/de1bed7b93d5e819ece6e2ce57a8b01b7c761b94
Bug 1554293 - logging-eventrouter event not formatted correctly in Elasticsearch when using MUX

When fluentd is configured as a collector and MUX, event logs from the event
router need to be processed by MUX not by the collector fluentd for the both
MUX_CLIENT_MODE=maximal and minimal cases.  It is because if an event log is
formatted in the collector (note: the event record is put under the kubernetes
key), the log is forwarded to MUX and passed to the k8s-meta plugin and the
existing kubernetes record is overwritten.

To avoid the replacement, if the log is from event router, the tag is rewritten
to ${tag}.raw in input-post-forward-mux.conf, which makes the log treated in
the MUX_CLIENT_MODE=minimal way.

There was another bug in ansible.  That is, the environment variable TRANSFORM_
EVENTS was not set in MUX even if openshift_logging_install_eventrouter is set
to true.  This PR fixes the issue.
https://github.com/openshift/openshift-ansible/pull/10207

In Fluentd run.sh, "process_kubernetes_events false" is set in the filter-viaq-
data-model plugin to suppress processing the event logs.  It is _not_ set, i.e.,
event router log processing is enabled, when TRANSFORM_EVENTS is true and the
fluentd is standalone (no MUX configured) or the fluentd is MUX.

Correct the order of shutdown fluentd, reset MUX_CLIENT_MODE, then restart.

https://github.com/openshift/origin-aggregated-logging/commit/414c62c62f27919be9b473cc4cf3d169fbe1130a
Merge pull request #1357 from nhosoi/bz1554293

Bug 1554293 - logging-eventrouter event not formatted correctly in El…

Comment 22 Anping Li 2018-11-29 09:59:40 UTC
Works well with openshift3/logging-fluentd/images/v3.9.55-1

Comment 24 errata-xmlrpc 2018-12-13 19:26:59 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:3748


Note You need to log in before you can comment on or make changes to this bug.