I see this warning in the log:
WARNING: Available disk space (2681203712 bytes) is less than the user specified file buffer limit (2Gi times 2).

Could you configure hostmount or pvc for the MUX file buffer with more than 4GB?
    openshift_logging_mux_file_buffer_storage_type=hostmount
  or
    openshift_logging_mux_file_buffer_storage_type=pvc
    openshift_logging_mux_file_buffer_pvc_name=logging-mux-pvc
    openshift_logging_mux_file_buffer_pvc_size=4Gi (or more)

And when the error is reported, could you run these command lines and attach the output to this bz?

oc exec $MUX_POD -- ls -l /var/lib/fluentd

oc exec $ES_POD -- curl -s -k --cert /etc/elasticsearch/secret/admin-cert \
  --key /etc/elasticsearch/secret/admin-key "https://localhost:9200/_cat/indices?v"

Hit the issue again with the logging-mux file buffer storage configured with a 4Gi pvc as suggested in comment 1.

root@ip-172-31-11-80: ~ # oc exec $mux -- ls -l /var/lib/fluentd
total 33764
-rw-r--r--. 1 root root  455386 Aug 30 17:53 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.b557fc34c6c3d2b5e.log
-rw-r--r--. 1 root root  558315 Aug 30 17:51 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc2dc29017d08.log
-rw-r--r--. 1 root root 4193041 Aug 30 17:51 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc2df4c1ec5b8.log
-rw-r--r--. 1 root root 4193030 Aug 30 17:52 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc2ed2d4733db.log
-rw-r--r--. 1 root root 4193047 Aug 30 17:52 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc2f782eaa83a.log
-rw-r--r--. 1 root root 4193038 Aug 30 17:52 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc301f40facb5.log
-rw-r--r--. 1 root root 4193036 Aug 30 17:53 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc30fb0887f51.log
-rw-r--r--. 1 root root 4193043 Aug 30 17:53 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc330ba221aca.log
-rw-r--r--. 1 root root 4193045 Aug 30 17:53 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc3356a194a3e.log
-rw-r--r--. 1 root root 4193039 Aug 30 17:53 buffer-output-es-config.kubernetes.mux.var.log.containers.mux-mux.mux-mux_mux-undefined_mux-0123456789012345678901234567890123456789012345678901234567890123.log.q557fc34462fe8b1d.log


oc exec -n logging $POD -- curl --connect-timeout 2 -s -k --cert /etc/elasticsearch/secret/admin-cert --key /etc/elasticsearch/secret/admin-key https://logging-es:9200/_cat/indices?vhealth status index                                                        pri rep docs.count docs.deleted store.size pri.store.size 
green  open   .kibana                                                        1   0          1            0      3.1kb          3.1kb 
green  open   .operations.2017.08.30                                         1   0       1673            0   1020.5kb       1020.5kb 
green  open   project.svt0.e204fe47-8daa-11e7-bb99-02a1c4e79572.2017.08.30   1   0      54909            0      102mb          102mb

Marking this as severity high since the logging-mux pod goes into a state where it is chewing up a core and not forwarding anything to ES.

Thanks, Mike.

"_mux-undefined_" in the index name means, the mux clients are not sending the kubernetes namespace name.

input-post-forward-mux.conf: mux_namespace_name ${record['namespace_name'] || (tag_parts[0] == "project" && tag_parts[1]) || ENV["MUX_UNDEFINED_NAMESPACE"] || "mux-undefined"}

What is the MUX_CLIENT_MODE value set in the mux clients?  minimal?

Let's get some information from ES to see how it is keeping up with the ingestion rate: https://www.elastic.co/guide/en/elasticsearch/reference/2.4/cat-thread-pool.html#_thread_pool_fields

oc exec -n logging $POD -- curl --connect-timeout 2 -s -k --cert /etc/elasticsearch/secret/admin-cert --key /etc/elasticsearch/secret/admin-key https://logging-es:9200/_cat/thread_pool?v\&h=host,ba,bs,bq,bqs,br,bl,bc

Looking for any non-zero value in the br or bq column - this indicates that ES is having trouble keeping up with mux.  If the bc column is continually increasing, this indicates that ES is ingesting data

(In reply to Noriko Hosoi from comment #5)
> Thanks, Mike.
> 
> "_mux-undefined_" in the index name means, the mux clients are not sending
> the kubernetes namespace name.
> 
> input-post-forward-mux.conf: mux_namespace_name ${record['namespace_name']
> || (tag_parts[0] == "project" && tag_parts[1]) ||
> ENV["MUX_UNDEFINED_NAMESPACE"] || "mux-undefined"}
> 
> What is the MUX_CLIENT_MODE value set in the mux clients?  minimal?

It should be "maximal", which means the fluentd clients are doing all of the processing _except_ for kubernetes metadata, which should be done by mux.  For the OpenShift only use case, this is the whole point of mux, to offload the kubernetes metadata processing.

(In reply to Rich Megginson from comment #7)
> It should be "maximal", which means the fluentd clients are doing all of the
> processing _except_ for kubernetes metadata, which should be done by mux. 
> For the OpenShift only use case, this is the whole point of mux, to offload
> the kubernetes metadata processing.

Yes, that's what I expect, too.

@nhosoi the mux-undefined in the buffer file name is correct - this is what I would expect when clients send data that needs k8s metadata - https://github.com/openshift/origin-aggregated-logging/blob/master/fluentd/configs.d/input-post-forward-mux.conf#L81 - the rewrite tag filter tags those records with kubernetes.mux.var.log.containers.mux-mux.mux-mux.mux-undefined.

For records read from the journal by the fluentd mux clients, the CONTAINER_NAME should be in the record and should contain the correct kubernetes data which is used to look up the additional k8s metadata: https://github.com/openshift/origin-aggregated-logging/blob/master/fluentd/configs.d/filter-pre-mux.conf

Finally, these records are not re-tagged because at this point the tag doesn't matter, once the k8s metadata has been added.

@richm: ok, thanks!

From the logging-fluentd daemonset:

        - name: MUX_CLIENT_MODE
          value: maximal
        image: registry.ops.openshift.com/openshift3/logging-fluentd:v3.6.173.0.21


Even when things seem to be working well I see files appearing/disappearing from /var/lib/fluentd with mux-undefined in the name.   

The logging was working fine in this cluster and then hits this condition suddenly.  The logging-mux logs are quiet when everything is working OK.  

I can usually get it working again by deleting the bad files, re-tagging the nodes to restart logging-fluentd and re-scaling logging-mux to restart it.

I am attaching the full daemonset for logging-fluentd and the dc for logging-mux - let me know what other information might help.

Created attachment 1320259 [details]
logging-mux dc

Created attachment 1320260 [details]
logging-fluentd ds

(In reply to Mike Fiedler from comment #12)
> Created attachment 1320259 [details]
> logging-mux dc

Sorry for my ignorance...  What does this 'cpu: "1"' mean?

        resources:
          limits:
            cpu: "1"
            memory: 2Gi

This is my mux resources:

        resources:
          limits:
            cpu: 500m
            memory: 2Gi
          requests:
            memory: 2Gi

It means 1 core/CPU.   Same meaning as 1000m (millicore).   Fluentd can only use 1 core without the multi-process plugin, so I let it use a full core.  It is the same as removing the limit, which might be less confusing.

The instance where ES and logging-mux are running has 8 cores and 32GB RAM

Output from command in comment 6 immediately after triggering the issue:

root@ip-172-31-11-80: ~/svt/openshift_scalability # oc exec -n logging $POD -- curl --connect-timeout 2 -s -k --cert /etc/elasticsearch/secret/admin-cert --key /etc/elasticsearch/secret/admin-key https://logging-es:9200/_cat/thread_pool?v\&h=host,ba,bs,bq,bqs,br,bl,bc
host        ba bs bq bqs br bl   bc 
172.20.1.62  0  8  0  50  0  8 3935

I will run this periodically and watch for non-0 bq and br.

oc exec -n logging $POD --   curl -s -k --cert /etc/elasticsearch/secret/admin-cert   --key /etc/elasticsearch/secret/admin-key https://localhost:9200/_cat/thread_pool?v\&h=host,bulk.completed,bulk.rejected,bulk.queue,bulk.active,bulk.queueSize

host        bulk.completed bulk.rejected bulk.queue bulk.active bulk.queueSize 
172.20.1.62           3935             0          0           0             50

ok - let's find out why mux is throwing that exception - 

oc edit configmap logging-mux

just before the first output, add this:

<filter **>
  @type stdout
</filter>

then redeploy mux

mux will spew a lot of messages to its pod log, so we may have to revert this once we have reproduced the exception

Setting severity back down to medium since the issue is timing on namespace deletion.   When the issue occurs with persistent file buffer storage for mux, the "bad" buffers have to be deleted and logging-mux restarted for indexing to restart.

I don't think we can delete any logs.  If we mux has a buffer payload, we need to index it.  However, if we can't fetch the namespace information, we should still index it into the operations logs, adding some sort of tag so they can easily found.

I think this is related to https://bugzilla.redhat.com/show_bug.cgi?id=1493022 and possibly a dup

I'd like to amend comment 25, I don't think data from a namespace should land in the operations index.  Instead, I would like to propose that it land in an index using the namespace_id.  That way, if records are missing, they could be found via inspection later.

(In reply to Peter Portante from comment #27)
> I'd like to amend comment 25, I don't think data from a namespace should
> land in the operations index.  Instead, I would like to propose that it land
> in an index using the namespace_id.  That way, if records are missing, they
> could be found via inspection later.

Do you mean namespace_name?

(In reply to Rich Megginson from comment #28)
> Do you mean namespace_name?

Thanks, I incorrectly referred to namespace_id.  But if namespace_name is not available, we still have to save the log entry to some index that operations can review.

Created attachment 1330590 [details]
logging-logs-lab.tar.gz

Attached logs from an isolated new instance. It seems it's not related to the deletion of a namespace.
It happens in 2 fluentd pods out of 3.

Created attachment 1331832 [details]
var/lib/fluentd

Docker is configured to use journald log-driver on all nodes

I have a post about additional steps to get more information: https://richmegginson.livejournal.com/29741.html

Note: if you change the configmap to do this, be sure to change it back _immediately_ after reproducing the problem, as this will cause fluentd to spew a large volume of data.

In logging-fluentd 3.7.0-0.146, the symptoms are changed some.  The scenario is the same - delete projects with log records for those projects in flight. 

1)The message in the summary and description of this bz now identifies the field which is missing (detailed message below).   The log record is still dropped (tracked by this bz), but the cause of the error is much clearer.

2)In 3.7, it does not appear logging-mux gets "wedged"/stuck/hung when this error is seen - it continues to process additional log records.


2017-10-16 14:59:27 +0000 [error]: record cannot use elasticsearch index name type project_full: record is missing kubernetes.namespace_id field: {"message"=>"centos-logtest-2m0mh : 9146 : pltsv7c UIkDnWI w53XbuF 5T2fi16 rSz9FeR sO8udd8 CqMFXHt HWfNaPz MpoCAhP rc5JE1T 5PmQMWz 24m5XTe 44GDlMs fgg333a eOGHpXe mVQeORs 3yUwveU GCbbCFL lKnvRPm rpE4mlp 1YBqq5X mgJ7uoa 1VQIAkq Q1vcDlf 6DNCGhZ JQVq36V oSj3hH0 Y1zxPGE 1JppZ9S YRMrgE7 yzXoYRV KYsZ00z D5HEQgt hlH07GV QfvpAbz IdSD4rm 8oh3dEm RH4LBlf LVDf2be dJrEXnf DNqKAhN 0fgwd16 rVYn7QW 8jnvlXd o0pVrKq yWRO4FK Lg8K2Hy uGQoldq KSBApDL qdTM2c6 jRfDGo2 1WOVADQ kijJjwc Y23DhV7 14Vpi8T Cu1D6uG NFjBZwg 6ZK4d4o OplqWmR Yq0t3oD QvMCgQk kBEIYwV iE9qYI1 UgIuIcy IszjfCe oj3xVuV BZlhamz 18RDnaz TI9oZw9 rrglonY AIxiITW bC01VyL eQxcl1r jp4ARzC KG0lS7a KUuyhYd wSFi2kz o1ry07g 9BjdyZa LlHodLh RAI4g9o JvAqN05 vwuHtMt KYcS2px 4HGSgzg 0kV0G6y MFv5rM1 CDQElCj Za29ug9 VYTPYlO M2nEq7u Crtcxll ZFT5eI6 PNcYlQh ZPqAocy nTOODwC FONf0fn TUfzDWZ 3KcMuip YuezYdV X9puqct Et2LLXd 3OTt18Z pJn9WJq yWRU0DN 41GMLN3 s5qQcGC EqX2gkU gi9tbyG RrHjY41 wrxqhTD ktYwuNj 8nPRrxz 9V8WVgV S2djzxv eWvTy55 iAeHOBR 7Ktzp8u BhleJtj MldegvK e9CYpxw JbqVcBa nU7B96H rs16FXc Otvdbyl gqmuk1E Ma8Zol9 y12UUwY \n", "level"=>"info", "hostname"=>"ip-172-31-17-160.us-west-2.compute.internal", "pipeline_metadata"=>{"collector"=>{"ipaddr4"=>"172.22.0.116", "ipaddr6"=>"fe80::858:acff:fe16:74", "inputname"=>"fluent-plugin-systemd", "name"=>"fluentd", "received_at"=>"2017-10-16T14:57:34.607762+00:00", "version"=>"0.12.39 1.6.0"}, "normalizer"=>{"ipaddr4"=>"172.22.2.5", "ipaddr6"=>"fe80::ec7c:49ff:fe45:2d93", "inputname"=>"fluent-plugin-systemd", "name"=>"fluentd", "received_at"=>"2017-10-16T14:59:27.590889+00:00", "version"=>"0.12.39 1.6.0"}}, "@timestamp"=>"2017-10-16T14:57:33.960808+00:00", "CONTAINER_NAME"=>"k8s_centos-logtest.0_centos-logtest-2m0mh_svt8_0_01234567", "CONTAINER_ID_FULL"=>"b93345ce4c762916d349581ba27dd11b14954fe45183fb192dde4a4a5b988327", "docker"=>{"container_id"=>"b93345ce4c762916d349581ba27dd11b14954fe45183fb192dde4a4a5b988327"}, "kubernetes"=>{"container_name"=>"centos-logtest", "namespace_name"=>"svt8", "pod_name"=>"centos-logtest-2m0mh", "pod_id"=>"1f95265f-b282-11e7-b635-0211864528ea", "labels"=>{"run"=>"centos-logtest", "test"=>"centos-logtest"}, "host"=>"ip-172-31-17-160.us-west-2.compute.internal", "master_url"=>"https://ec2-54-200-230-39.us-west-2.compute.amazonaws.com:8443"}}

Closing as dup as new issue narrows the focus of the actual problem

*** This bug has been marked as a duplicate of bug 1500882 ***