Bug 1729316 - rsyslog log collector creating operations index with no date in the name
Summary: rsyslog log collector creating operations index with no date in the name
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Logging
Version: 4.2.0
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: 4.2.0
Assignee: Rich Megginson
QA Contact: Anping Li
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-07-11 22:34 UTC by Eric Matysek
Modified: 2019-10-16 06:33 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-10-16 06:33:27 UTC
Target Upstream Version:


Attachments (Terms of Use)
Operations index dump (26.58 KB, text/plain)
2019-07-15 15:24 UTC, Eric Matysek
no flags Details


Links
System ID Priority Status Summary Last Updated
Github openshift cluster-logging-operator pull 212 None None None 2019-07-15 21:59:48 UTC
Red Hat Product Errata RHBA-2019:2922 None None None 2019-10-16 06:33:39 UTC

Description Eric Matysek 2019-07-11 22:34:20 UTC
Description of problem:
rsyslog log collector from 4.2 image creates an extra operations index.
health status index                  uuid                   pri rep docs.count docs.deleted store.size pri.store.size
green  open   .kibana                n1dbWNFpQVSdMpFL0YMqtw   1   1          5            0    170.2kb         85.1kb
green  open   .operations...         H5YKqxuoQ6K-XtzPloWzIA   2   1         16            0       75kb         40.4kb
green  open   .operations.2019.07.11 KDEl-ZyPSImOHGBpFjjJ3w   2   1     352811            0    854.3mb        431.8mb
green  open   .searchguard           SiCeN2KmSYGwE3y2spOC3A   1   1          0            0    149.4kb         74.7kb


Version-Release number of selected component (if applicable):
4.2 clusterlogging operator

How reproducible:
Every time for me

Steps to Reproduce:
1. Deploy 4.2 clusterlogging operator with rsyslog log collector

Actual results:
.operations... index getting created alongside correctly named index

Expected results:
Only operations index with date should be created like so
.operations.2019.07.11

Additional info:

Comment 1 Noriko Hosoi 2019-07-11 23:09:55 UTC
It's likely $!@timestamp is missing for some logs...

"20-viaq-templates.conf"
template(name="prefix_index_template" type="list") {
    property(name="$.viaq_index_prefix")
    property(name="$!@timestamp" dateFormat="rfc3339" position.from="1" position.to="4")
    constant(value=".")
    property(name="$!@timestamp" dateFormat="rfc3339" position.from="6" position.to="7")
    constant(value=".")
    property(name="$!@timestamp" dateFormat="rfc3339" position.from="9" position.to="10")

Comment 2 Noriko Hosoi 2019-07-11 23:20:08 UTC
Could you retrieve the records from .operations... and share them with us?  There are 16 of them.

> green  open   .operations...         H5YKqxuoQ6K-XtzPloWzIA   2   1         16            0       75kb         40.4kb

Comment 3 Rich Megginson 2019-07-12 00:40:02 UTC
(In reply to Noriko Hosoi from comment #1)
> It's likely $!@timestamp is missing for some logs...

Then we'll need to add some logic to 65-viaq-formatting.conf

We set @timestamp here for journald logs: https://github.com/openshift/cluster-logging-operator/blob/master/files/rsyslog/65-viaq-formatting.conf#L223
and here for container logs: https://github.com/openshift/cluster-logging-operator/blob/master/files/rsyslog/65-viaq-formatting.conf#L239

So it's likely we're getting records that are not from journald, and not from container logs.  In that case, we will need to add an else clause here: https://github.com/openshift/cluster-logging-operator/blob/master/files/rsyslog/65-viaq-formatting.conf#L247 like

} else if strlen(!$@timestamp) == 0 then {
    set $!@timestamp = exec_template('cnvt_to_viaq_timestamp');
}

unless we can find some field in these records that would make a more suitable @timestamp

Comment 4 Rich Megginson 2019-07-12 03:38:22 UTC
These records are really strange:

oc exec -c elasticsearch $espod -- es_util --query=.operations.../_search?pretty 

  "hits" : {
    "total" : 345,
    "max_score" : 1.0,
    "hits" : [
      {
        "_index" : ".operations...",
        "_type" : "com.redhat.viaq.common",
        "_id" : "BD32CF6C40544F61BF0D85CA6F8C1ECE",
        "_score" : 1.0,
        "_source" : {
          "level" : "unknown",
          "pipeline_metadata" : {
            "collector" : {
              "name" : "rsyslog",
              "inputname" : "rsyslogd",
              "received_at" : "2019-07-12T03:08:55.026971+00:00",
              "ipaddr4" : "10.0.160.87",
              "ipaddr6" : "::ffff:10.0.160.87",
              "version" : "8.37.0-9.el7 "
            }
          }
        }
      },
      {
        "_index" : ".operations...",
        "_type" : "com.redhat.viaq.common",
        "_id" : "3EB7747E54BB42A5BFB8F2D32B8C6F8D",
        "_score" : 1.0,
        "_source" : {
          "level" : "unknown",
          "pipeline_metadata" : {
            "collector" : {
              "name" : "rsyslog",
              "inputname" : "rsyslogd",
              "received_at" : "2019-07-12T03:09:31.869790+00:00",
              "ipaddr4" : "10.0.160.87",
              "ipaddr6" : "::ffff:10.0.160.87",
              "version" : "8.37.0-9.el7 "
            }
          }
        }
      },
 
These are some sort of rsyslog internal log messages. They apparently have no message field, probably just a "msg" field.  These should probably be going to the rsyslog.log file - not sure why they aren't.

Comment 5 Noriko Hosoi 2019-07-12 06:06:36 UTC
Can we just stop if there's no message?   Something like this?  (Or stop if there's no @timestamp?)

diff --git a/files/rsyslog/65-viaq-formatting.conf b/files/rsyslog/65-viaq-formatting.conf
index 7acadb2d..6fb1ce37 100644
--- a/files/rsyslog/65-viaq-formatting.conf
+++ b/files/rsyslog/65-viaq-formatting.conf
@@ -42,6 +42,10 @@ if strlen($!MESSAGE) > 0 then {
     unset $!unparsed-data;
 }
 
+if strlen($!message) == 0 then {
+    stop
+}
+
 if strlen($!_MACHINE_ID) > 0 then {

Comment 6 Rich Megginson 2019-07-12 13:32:15 UTC
(In reply to Noriko Hosoi from comment #5)
> Can we just stop if there's no message?   Something like this?  (Or stop if
> there's no @timestamp?)
> 

That's a possibility.  I would like to understand what those records are.

Comment 7 Eric Matysek 2019-07-15 15:24:39 UTC
Created attachment 1590807 [details]
Operations index dump

Comment 8 Rich Megginson 2019-07-15 16:10:34 UTC
I think I've figured out the problem and am working on a solution - https://github.com/richm/cluster-logging-operator/commit/9a240ee83341674b084ea37bfa83bc18aa909ffb

Comment 10 Qiaoling Tang 2019-07-17 07:56:52 UTC
Verified in ose-cluster-logging-operator-v4.2.0-201907161019

Comment 11 Qiaoling Tang 2019-07-26 07:05:04 UTC
Reopen this bug: I got some index like: ".operations.]..", ".operations..."  

$ oc exec elasticsearch-cdm-4loozj9x-2-76cd864797-vfwnh -- indices
Defaulting container name to elasticsearch.
Use 'oc describe pod/elasticsearch-cdm-4loozj9x-2-76cd864797-vfwnh -n openshift-logging' to see all of the containers in this pod.
Fri Jul 26 06:56:39 UTC 2019
health status index                                                            uuid                   pri rep docs.count docs.deleted store.size pri.store.size
green  open   .operations.]..                                                  29eJJWsPS_CPgbfpbufPPw   2   1          0            0          0              0
green  open   .kibana                                                          rN5hq_F4Qsu4inn6rMWwLA   1   1          5            0          0              0
green  open   .kibana.af6615b8667e56f05cfd9d4bd371847d9ece3226                 _msmAelRRXSzP0Y_IxxkBw   1   1          6            1          0              0
green  open   .searchguard                                                     MaiCbdpBQ6u-XCPgT0_VAg   1   1          5            0          0              0
green  open   project.project1.20f838d6-af72-11e9-a853-0a2835a0bf96.2019.07.26 ctOLMu1IR9y1Ljip5l-BrQ   2   1        317            0          0              0
green  open   project.test1.53cb7dbe-af4b-11e9-ae24-06889c886410.2019.07.26    OiMGDT7SQUGHjQZBaql5hA   2   1       1111            0          1              0
green  open   .operations...                                                   ejUIAMOjRxGrGSIENYDokA   2   1          2            0          0              0
green  open   .kibana.647a750f1787408bf50088234ec0edd5a6a9b2ac                 Xl3aXs3qR3WeEoKKGprnVg   1   1          4            0          0              0
green  open   project.test2.b43926c1-af71-11e9-a853-0a2835a0bf96.2019.07.26    x4ntzZcRR-SSSp6nphhmGw   2   1        330            0          0              0
green  open   .operations.2019.07.26                                           qcDPAxnlRx6lOCBWeU7S0A   2   1    1722704            0       4951           2599

Logs:
$ oc exec elasticsearch-cdm-4loozj9x-2-76cd864797-vfwnh -- es_util --query=.operations.../_search?pretty
Defaulting container name to elasticsearch.
Use 'oc describe pod/elasticsearch-cdm-4loozj9x-2-76cd864797-vfwnh -n openshift-logging' to see all of the containers in this pod.
{
  "took" : 2,
  "timed_out" : false,
  "_shards" : {
    "total" : 2,
    "successful" : 2,
    "skipped" : 0,
    "failed" : 0
  },
  "hits" : {
    "total" : 2,
    "max_score" : 1.0,
    "hits" : [
      {
        "_index" : ".operations...",
        "_type" : "com.redhat.viaq.common",
        "_id" : "4E97B87FAE38484EB2AEF4AEE130E575",
        "_score" : 1.0,
        "_source" : {
          "PRIORITY" : "6",
          "_UID" : "0",
          "_TRANSPORT" : "stdout",
          "_SYSTEMD_UNIT" : "kubelet.service",
          "_SYSTEMD_SLICE" : "system.slice",
          "message" : "I0726 05:34:14.544141    1125 helpers.go:822] eviction manager: observations: signal=imagefs.inodesFree, available: 62328747, capacity: 62389184, time: 2019-07-26 05:34:14.540032051 +0000 UTC m=+16993.401240058",
          "pipeline_metadata" : {
            "collector" : {
              "original_raw_message" : "I0726 05:34:14.544141    1125 helpers.go:822] eviction manager: observations: signal=imagefs.inodesFree, available: 62328747, capacity: 62389184, time: 2019-07-26 05:34:14.540032051 +0000 UTC m=+16993.401240058",
              "name" : "rsyslog",
              "inputname" : "imjournal",
              "received_at" : "2019-07-26T05:34:14.544275+00:00",
              "ipaddr4" : "10.0.152.44",
              "ipaddr6" : "::ffff:10.0.152.44",
              "version" : "8.37.0-9.el7 "
            }
          },
          "systemd" : {
            "t" : {
              "MACHINE_ID" : "ec207729b5454dfbb2d3518d4b31f5ff",
              "STREAM_ID" : "c4f0676f3bc645b9a9688f1ad60cfd7e",
              "SYSTEMD_INVOCATION_ID" : "2d48a809cd0c49a2ba6ca09edc9193bd",
              "BOOT_ID" : "43d2e9db94974f6a9fb42e69109a0493",
              "CAP_EFFECTIVE" : "3fffffffff",
              "CMDLINE" : "/usr/bin/hyperkube kubelet --config=/etc/kubernetes/kubelet.conf --bootstrap-kubeconfig=/etc/kubernetes/kubeconfig --rotate-certificates --kubeconfig=/var/lib/kubelet/kubeconfig --container-runtime=remote --container-runtime-endpoint=/var/run/crio/crio.sock --node-labels=node-role.kubernetes.io/master,node.openshift.io/os_id=rhcos --minimum-container-ttl-duration=6m0s --cloud-provider=aws --volume-plugin-dir=/etc/kubernetes/kubelet-plugins/volume/exec --register-with-taints=node-role.kubernetes.io/master=:NoSchedule --v=3",
              "COMM" : "hyperkube",
              "EXE" : "/usr/bin/hyperkube",
              "GID" : "0",
              "HOSTNAME" : "ip-10-0-152-44",
              "PID" : "1125",
              "SELINUX_CONTEXT" : "system_u:system_r:unconfined_service_t:s0",
              "SYSTEMD_CGROUP" : "/system.slice/kubelet.service"
            },
            "u" : {
              "SYSLOG_FACILITY" : "3",
              "SYSLOG_IDENTIFIER" : "hyperkube"
            }
          },
          "level" : "unknown"
        }
      },
      {
        "_index" : ".operations...",
        "_type" : "com.redhat.viaq.common",
        "_id" : "E5790A4CCD7044FCB5F223BBA9C2F2CB",
        "_score" : 1.0,
        "_source" : {
          "PRIORITY" : "6",
          "SYSLOG_FACILITY" : "3",
          "_UID" : "0",
          "_GID" : "0",
          "_SYSTEMD_SLICE" : "system.slice",
          "_CAP_EFFECTIVE" : "3fffffffff",
          "_TRANSPORT" : "stdout",
          "_HOSTNAME" : "ip-10-0-149-153",
          "_SELINUX_CONTEXT" : "system_u:system_r:unconfined_service_t:s0",
          "_BOOT_ID" : "6c9112ac7c6e48d88add55d6bb269b61",
          "_STREAM_ID" : "cae7d2c85c7f4fcf861411144db44b89",
          "SYSLOG_IDENTIFIER" : "hyperkube",
          "_PID" : "1127",
          "_COMM" : "hyperkube",
          "_EXE" : "/usr/bin/hyperkube",
          "_CMDLINE" : "/usr/bin/hyperkube kubelet --config=/etc/kubernetes/kubelet.conf --bootstrap-kubeconfig=/etc/kubernetes/kubeconfig --kubeconfig=/var/lib/kubelet/kubeconfig --container-runtime=remote --container-runtime-endpoint=/var/run/crio/crio.sock --node-labels=node-role.kubernetes.io/worker,node.openshift.io/os_id=rhcos --minimum-container-ttl-duration=6m0s --volume-plugin-dir=/etc/kubernetes/kubelet-plugins/volume/exec --cloud-provider=aws --v=3",
          "_SYSTEMD_CGROUP" : "/system.slice/kubelet.service",
          "_SYSTEMD_UNIT" : "kubelet.service",
          "_SYSTEMD_INVOCATION_ID" : "e297241f18bd42cebb70095e4c7400c7",
          "message" : "I0726 04:13:07.957944    1127 prober.go:125] Readiness probe for \"grafana-b8978fdd6-hfxw4_openshift-monitoring(7928296b-af41-11e9-a23d-06889c886410):grafana-proxy\" succeeded",
          "pipeline_metadata" : {
            "collector" : {
              "original_raw_message" : "I0726 04:13:07.957944    1127 prober.go:125] Readiness probe for \"grafana-b8978fdd6-hfxw4_openshift-monitoring(7928296b-af41-11e9-a23d-06889c886410):grafana-proxy\" succeeded",
              "name" : "rsyslog",
              "inputname" : "imjournal",
              "received_at" : "2019-07-26T04:13:07.957980+00:00",
              "ipaddr4" : "10.0.149.153",
              "ipaddr6" : "::ffff:10.0.149.153",
              "version" : "8.37.0-9.el7 "
            }
          },
          "systemd" : {
            "t" : {
              "MACHINE_ID" : "ec287995983b6ec3b77e4e5ae70125c1"
            },
            "u" : {
              "SYSLOG_FACILITY" : "3"
            }
          },
          "level" : "unknown"
        }
      }
    ]
  }
}


Not always happen, and I don't konw how to reproduce.

Image: ose-logging-rsyslog-v4.2.0-201907251819, ose-cluster-logging-operator-v4.2.0-201907251819

Comment 12 Rich Megginson 2019-07-26 18:02:46 UTC
the docs count for .operations.].. is 0 - I'm not even sure how rsyslog can create an empty index . . .

Comment 13 Rich Megginson 2019-07-26 22:02:59 UTC
I am unable to reproduce.  I'm trying with the latest 4.2, latest logging images. I've tried deploying with fluentd initially, then switching to rsyslog, then deleting all of the rsyslog pods, then switching to fluentd, then switching back to rsyslog.  I've also tried deploying with rsyslog enabled initially in the cr.yaml.

And ideas about how to reproduce this issue would be appreciated.

Comment 14 Qiaoling Tang 2019-07-29 08:08:03 UTC
@Rich I found some steps to reproduce this issue, but the phenomenon is not the same as comment 11:

1. oc set env ds/rsyslog MERGE_JSON_LOG=true USE_MMEXTERNAL=true
2. wait for several minutes, check indices in es, no issue
3. oc set env ds/rsyslog USE_MMEXTERNAL=true SKIP_EMPTY=true
4. check the indices:
$ oc exec elasticsearch-cdm-vr6ncif9-1-6d6c448645-pmhsm -- indices
Defaulting container name to elasticsearch.
Use 'oc describe pod/elasticsearch-cdm-vr6ncif9-1-6d6c448645-pmhsm -n openshift-logging' to see all of the containers in this pod.
Mon Jul 29 07:46:11 UTC 2019
health status index                                                         uuid                   pri rep docs.count docs.deleted store.size pri.store.size
green  open   project.json2.e51688e8-b1c6-11e9-8ae6-066839be5150...         Tb1SnunsRYW08J_qGLyn7A   2   1         60            0          0              0
green  open   project.json1.d99e9fea-b1c6-11e9-99f1-0a1af4e2ab48...         eE1DjiVYQyayJdo4VmLkWA   2   1         76            0          0              0
green  open   .searchguard                                                  KuzqtFZkRtyYXGXN0N6_WA   1   1          5            0          0              0
green  open   .kibana                                                       sw6jAqLZQViZjSAz-GFCJQ   1   1          5            1          0              0
green  open   .kibana.af6615b8667e56f05cfd9d4bd371847d9ece3226              NBLsi7AkTYWUPyFe_TSG0g   1   1          6            2          0              0
green  open   .operations...                                                DZORpTA6QwGpl8v7XnqC8g   2   1       5108            0          8              4
green  open   project.json2.e51688e8-b1c6-11e9-8ae6-066839be5150.2019.07.29 7P82Z7D6TU2By286TZIr2A   2   1        381            0          0              0
green  open   .operations.2019.07.29                                        _CH6kKrBQsCV8nT05x5sNA   2   1      27033            0         83             41
green  open   .kibana.647a750f1787408bf50088234ec0edd5a6a9b2ac              bdpMbVSRRHef31Cu46zSnQ   1   1          3            0          0              0
green  open   project.json1.d99e9fea-b1c6-11e9-99f1-0a1af4e2ab48.2019.07.29 yjEfgVBpRlyGy-Qe7PAhpg   2   1        279            0          0              0
5. wait for a while, check the indices again:
$ oc exec elasticsearch-cdm-vr6ncif9-1-6d6c448645-pmhsm -- indices
Defaulting container name to elasticsearch.
Use 'oc describe pod/elasticsearch-cdm-vr6ncif9-1-6d6c448645-pmhsm -n openshift-logging' to see all of the containers in this pod.
Mon Jul 29 07:47:02 UTC 2019
health status index                                                         uuid                   pri rep docs.count docs.deleted store.size pri.store.size
green  open   project.json2.e51688e8-b1c6-11e9-8ae6-066839be5150...         Tb1SnunsRYW08J_qGLyn7A   2   1        110            0          0              0
green  open   project.json1.d99e9fea-b1c6-11e9-99f1-0a1af4e2ab48...         eE1DjiVYQyayJdo4VmLkWA   2   1        126            0          0              0
green  open   .searchguard                                                  KuzqtFZkRtyYXGXN0N6_WA   1   1          5            0          0              0
green  open   .kibana                                                       sw6jAqLZQViZjSAz-GFCJQ   1   1          5            1          0              0
green  open   .kibana.af6615b8667e56f05cfd9d4bd371847d9ece3226              NBLsi7AkTYWUPyFe_TSG0g   1   1          6            2          0              0
green  open   .operations...                                                DZORpTA6QwGpl8v7XnqC8g   2   1       8969            0         13              6
green  open   project.json2.e51688e8-b1c6-11e9-8ae6-066839be5150.2019.07.29 7P82Z7D6TU2By286TZIr2A   2   1        381            0          0              0
green  open   .operations.2019.07.29                                        _CH6kKrBQsCV8nT05x5sNA   2   1      27033            0         83             41
green  open   .kibana.647a750f1787408bf50088234ec0edd5a6a9b2ac              bdpMbVSRRHef31Cu46zSnQ   1   1          3            0          0              0
green  open   project.json1.d99e9fea-b1c6-11e9-99f1-0a1af4e2ab48.2019.07.29 yjEfgVBpRlyGy-Qe7PAhpg   2   1        279            0          0              0

The logs were sent to index with suffix `...` and not sent to `xxxxxxxx.date`
Logs:

      {
        "_index" : "project.json1.d99e9fea-b1c6-11e9-99f1-0a1af4e2ab48...",
        "_type" : "com.redhat.viaq.common",
        "_id" : "38A308C95C6D4840AB7DA135BAF96401",
        "_score" : 1.0,
        "_source" : {
          "originalmsg" : "2019-07-29T07:44:54.001564645+00:00 stdout F {\"@version\":1,\"@timestamp\":\"2019-07-29T03:44:54.001-0400\",\"sequence\":6013,\"loggerClassName\":\"org.jboss.logmanager.Logger\",\"loggerName\":\"stdout\",\"level\":\"INFO\",\"threadName\":\"EJB default - 5\",\"message\":\"timer: Hello from control: 1564386294001\",\"threadId\":144,\"mdc\":{},\"ndc\":\"\",\"log-handler\":\"CONSOLE\"}",
          "unparsed-data" : "2019-07-29T07:44:54.001564645+00:00 stdout F {\"@version\":1,\"@timestamp\":\"2019-07-29T03:44:54.001-0400\",\"sequence\":6013,\"loggerClassName\":\"org.jboss.logmanager.Logger\",\"loggerName\":\"stdout\",\"level\":\"INFO\",\"threadName\":\"EJB default - 5\",\"message\":\"timer: Hello from control: 1564386294001\",\"threadId\":144,\"mdc\":{},\"ndc\":\"\",\"log-handler\":\"CONSOLE\"}"
        }
      },
      {
        "_index" : ".operations...",
        "_type" : "com.redhat.viaq.common",
        "_id" : "080709CBA9ED47DC858334F2578847E7",
        "_score" : 1.0,
        "_source" : {
          "originalmsg" : "2019-07-29T07:45:29.015612013+00:00 stderr F 2019/07/29 07:45:29 oauthproxy.go:775: 10.129.2.7:54734 invalid Authorization header Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6IiJ9.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJvcGVuc2hpZnQtbW9uaXRvcmluZyIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VjcmV0Lm5hbWUiOiJwcm9tZXRoZXVzLWFkYXB0ZXItdG9rZW4tamZobGgiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlcnZpY2UtYWNjb3VudC5uYW1lIjoicHJvbWV0aGV1cy1hZGFwdGVyIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQudWlkIjoiMTQ0YjNmNWMtYjE5YS0xMWU5LTlkMmItMDY2ODM5YmU1MTUwIiwic3ViIjoic3lzdGVtOnNlcnZpY2VhY2NvdW50Om9wZW5zaGlmdC1tb25pdG9yaW5nOnByb21ldGhldXMtYWRhcHRlciJ9.L8E4M7-5x3T542IUEi2Mi898ABcYpvp-zni_a3nwe-Y1zwxsbgrmsZGNn2dqCTRGmaRl_LYu_p0Lq3Ql9_78FcCSvc5kzfBgULPoBNikKvb_zR6cQjOaiJ6pZk8zpqSi3nqrw_3QwSzdfrgrf-LO0nm8hq6JDpiRBAjaPY2XdXlN1F9orLYzpnP5JFKEoKr9Am0vfa9ue3kIVtiFry28MMZcFOEve9D6ynEWrbAcd11BgLkM8Dx0hF1PpNHLyh8fJcZITBbYolj5pvZutS7aRCnqpYvouol1yVmlun1wDaFkY4aOxsQf6mp3J0eXR2PBGn8CtmOLPMQxb8trRqrAhA",
          "unparsed-data" : "2019-07-29T07:45:29.015612013+00:00 stderr F 2019/07/29 07:45:29 oauthproxy.go:775: 10.129.2.7:54734 invalid Authorization header Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6IiJ9.eyJpc3MiOiJrdWJlcm5ldGVzL3NlcnZpY2VhY2NvdW50Iiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9uYW1lc3BhY2UiOiJvcGVuc2hpZnQtbW9uaXRvcmluZyIsImt1YmVybmV0ZXMuaW8vc2VydmljZWFjY291bnQvc2VjcmV0Lm5hbWUiOiJwcm9tZXRoZXVzLWFkYXB0ZXItdG9rZW4tamZobGgiLCJrdWJlcm5ldGVzLmlvL3NlcnZpY2VhY2NvdW50L3NlcnZpY2UtYWNjb3VudC5uYW1lIjoicHJvbWV0aGV1cy1hZGFwdGVyIiwia3ViZXJuZXRlcy5pby9zZXJ2aWNlYWNjb3VudC9zZXJ2aWNlLWFjY291bnQudWlkIjoiMTQ0YjNmNWMtYjE5YS0xMWU5LTlkMmItMDY2ODM5YmU1MTUwIiwic3ViIjoic3lzdGVtOnNlcnZpY2VhY2NvdW50Om9wZW5zaGlmdC1tb25pdG9yaW5nOnByb21ldGhldXMtYWRhcHRlciJ9.L8E4M7-5x3T542IUEi2Mi898ABcYpvp-zni_a3nwe-Y1zwxsbgrmsZGNn2dqCTRGmaRl_LYu_p0Lq3Ql9_78FcCSvc5kzfBgULPoBNikKvb_zR6cQjOaiJ6pZk8zpqSi3nqrw_3QwSzdfrgrf-LO0nm8hq6JDpiRBAjaPY2XdXlN1F9orLYzpnP5JFKEoKr9Am0vfa9ue3kIVtiFry28MMZcFOEve9D6ynEWrbAcd11BgLkM8Dx0hF1PpNHLyh8fJcZITBbYolj5pvZutS7aRCnqpYvouol1yVmlun1wDaFkY4aOxsQf6mp3J0eXR2PBGn8CtmOLPMQxb8trRqrAhA"
        }
      },


What's more, I saw an index `.operations.t..` after setting several environment variables in ds rsyslog:
$ oc exec elasticsearch-cdm-4gy21okc-1-7484699747-l579m -- indices
Defaulting container name to elasticsearch.
Use 'oc describe pod/elasticsearch-cdm-4gy21okc-1-7484699747-l579m -n openshift-logging' to see all of the containers in this pod.
Mon Jul 29 08:01:18 UTC 2019
health status index                                                         uuid                   pri rep docs.count docs.deleted store.size pri.store.size
green  open   .kibana.647a750f1787408bf50088234ec0edd5a6a9b2ac              nqofYqyFS7WIw2xu3b-uLQ   1   1          3            0          0              0
green  open   project.json1.d99e9fea-b1c6-11e9-99f1-0a1af4e2ab48.2019.07.29 oYQ4D91pRwiAZLj18-BRYQ   2   1        542            0          1              0
green  open   .kibana.af6615b8667e56f05cfd9d4bd371847d9ece3226              Ve9fZ0pvT6Os3OcH19inbQ   1   1          5            2          0              0
green  open   .searchguard                                                  JsADD-XmSeqY5JUuyy46EA   1   1          5            0          0              0
green  open   .kibana                                                       MTR6yztFQNeP60ClECuzJQ   1   1          1            0          0              0
green  open   project.json2.e51688e8-b1c6-11e9-8ae6-066839be5150.2019.07.29 aQgrgievTR2-XZzi4H8P5g   2   1        575            0          1              0
green  open   .operations.t..                                               EYP5y2bcTXeXRZlu0o5GgQ   2   1          0            0          0              0
green  open   .operations.2019.07.29                                        Ei20Auy3QHeKgkzGyYERvw   2   1      46085            0        133             68

Here are what I did, but I'm not sure if you could reproduce the issue by doing the same steps:
oc set env ds/rsyslog LOGGING_FILE_SIZE=50000
oc set env ds/rsyslog LOGGING_FILE_SIZE=50000 LOGGING_FILE_AGE=5
oc set env ds/rsyslog LOGGING_FILE_SIZE=50000 LOGGING_FILE_AGE=6
oc set env ds/rsyslog LOGGING_FILE_SIZE=50000 LOGGING_FILE_AGE=6 LOGGING_FILE_PATH=/var/log/test/rsyslog.log
oc set env ds/rsyslog MERGE_JSON_LOG=true

Comment 15 Rich Megginson 2019-07-29 14:36:25 UTC
ok - so looks like there are two problems related to when MERGE_JSON_LOG=true

1) If there is a problem parsing to JSON, we need to restore the original "message" field and remove the "originalmsg" and "unparsed-data" fields.
2) If the JSON data has a "@timestamp" field, we need to convert it to the canonical format, or otherwise determine its format, so that we can use it to construct the date part of the index name

Comment 16 Rich Megginson 2019-07-31 19:02:36 UTC
I opened https://bugzilla.redhat.com/show_bug.cgi?id=1734951 for the case where we don't want the originalmsg and unparsed-data fields left over in the record.

Otherwise, it looks as though https://github.com/openshift/cluster-logging-operator/pull/212 fixes both the .operations.t.. as well as the .operations... problems

Before I applied https://github.com/openshift/cluster-logging-operator/pull/212, I was seeing the bad indices - after applying 212, I cannot reproduce the problem.  So it looks like removing the secrets, sa, and configmaps out from under a running daemonset is bad, and making sure we tear down the resources in the right order is important.

Comment 17 Rich Megginson 2019-08-01 02:18:19 UTC
(In reply to Rich Megginson from comment #16)
> I opened https://bugzilla.redhat.com/show_bug.cgi?id=1734951 for the case
> where we don't want the originalmsg and unparsed-data fields left over in
> the record.
> 

Correction - it is https://github.com/openshift/cluster-logging-operator/pull/218 that looks like it fixes both the .operations.t.. as well as the .operations... problems

Comment 19 Eric Matysek 2019-08-06 16:43:50 UTC
I no longer see the incorrectly named operations indices

health status index                                            uuid                   pri rep docs.count docs.deleted store.size pri.store.size
green  open   .kibana.baf1e970b1934c8a77385b8e421420ff7c43ce22 IWBtf9NNSRitFj0PHDeHvw   1   1          5            2    181.5kb         90.7kb
green  open   .kibana                                          FhMDgQCeR1mUFnDuXwUT5g   1   1          5            0    112.2kb         54.8kb
green  open   .searchguard                                     iyLoC01vQGeDcfpDVyCh7g   1   1          0            0    161.8kb           81kb
green  open   .kibana.647a750f1787408bf50088234ec0edd5a6a9b2ac qNzJTkv5R06s1R--bTOqKA   1   1          2            1      105kb         52.5kb
green  open   .operations.2019.08.06                           dumJI16PSyK7C5nfqkkm5A   3   1     174440            0    245.1mb        122.4mb

Comment 20 errata-xmlrpc 2019-10-16 06:33:27 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-2019:2922


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