Bug 1486473

This is https://bugzilla.redhat.com/show_bug.cgi?id=1473788

At least, I'm assuming the user is using docker --log-driver=journald.

If so, the user can manually create and edit the fluentd configs as configmaps and set       

buffer_queue_full_action block

as in https://github.com/openshift/origin-aggregated-logging/commit/329021457bc55b1f55d3488ccfa2fcf258e9da47

and please clone https://bugzilla.redhat.com/show_bug.cgi?id=1473788 for 3.5 and 3.4

Actually I believe they are using json log driver, let me confirm

Can we get someone to attach the output of: https://github.com/openshift/origin-aggregated-logging/blob/master/hack/logging-dump.sh

Steven can you clairfy this statement:

> For instance on 8/7 from 2 pm to 3 pm, there were 2.5 million log messages 
> received in Log Insight but only 1.5 million log messages received in 
> ElasticSearch.  The following hour, the counts were 2.7 million for both.

This would imply there is no message loss but they are beind indexed slower then the customer would expect or desire.  Might this be a fluentd CPU limitation similar to what we have seen in our CI environment.  The default CPU can inhibit message throughput.

How so? if it was simply taking longer for the logs to show up, I would expect some hours where ES has more new logs than loginsight, as it's compensating for previous hours. This fact that logs are legitimately dropped is also supported by the fact that some logs never show up; if they're expecting messages:

A, B, C

They might only see:

A, C

I don't have a good solution to allow you to set the `buffer_queue_full_action block` in such a way that will make upgrades easy.  Here is one way to do it.  Perhaps there is a better way:

- get the fluentd pod name

- oc exec $fluentd_pod -- cat /etc/fluent/configs.d/openshift/output-operations.conf > output-operations.conf

- oc exec $fluentd_pod -- cat /etc/fluent/configs.d/openshift/output-applications.conf > output-applications.conf

- oc exec $fluentd_pod -- cat /etc/fluent/configs.d/openshift/output-es-config.conf > output-es-config.conf

- oc exec $fluentd_pod -- cat /etc/fluent/configs.d/openshift/output-es-ops-config.conf > output-es-ops-config.conf

If you are using ES_COPY let me know.

- edit output-es-config.conf and output-es-ops-config.conf - just before the </store> at the end of the file, add this line:

      buffer_queue_full_action "#{ENV['BUFFER_QUEUE_FULL_ACTION'] || 'block'

- edit output-operations.conf - replace the line

  @include output-es-ops-config.conf

with the contents of the file output-es-ops-config.conf that you just edited

- edit output-applications.conf - replace the line

  @include output-es-config.conf

with the contents of the file output-es-config.conf that you just edited

- redeploy fluentd

Sorry, one more step before redeploy fluentd

- oc edit configmap logging-fluentd

replace the line

      @include configs.d/openshift/output-operations.conf

with the contents of the edited output-operations.conf file

replace the line

      @include configs.d/openshift/output-applications.conf

with the contents of the edited output-applications.conf file

(In reply to Rich Megginson from comment #13)
> Sorry, one more step before redeploy fluentd
> 
> - oc edit configmap logging-fluentd
> 
> replace the line
> 
>       @include configs.d/openshift/output-operations.conf
> 
> with the contents of the edited output-operations.conf file
> 
> replace the line
> 
>       @include configs.d/openshift/output-applications.conf
> 
> with the contents of the edited output-applications.conf file

I was able to override output-es-config.conf and add the following via the ConfigMap

apiVersion: v1
data:
  fluent.conf: |

    @include configs.d/openshift/system.conf

    @include configs.d/openshift/input-pre-*.conf
    @include configs.d/dynamic/input-docker-*.conf
    @include configs.d/openshift/input-post-*.conf

    <label @INGRESS>

      @include configs.d/openshift/filter-pre-*.conf
      @include configs.d/openshift/filter-retag-journal.conf
      @include configs.d/openshift/filter-k8s-meta.conf
      @include configs.d/openshift/filter-kibana-transform.conf
      @include configs.d/openshift/filter-k8s-record-transform.conf
      @include configs.d/openshift/filter-syslog-record-transform.conf
      @include configs.d/openshift/filter-common-data-model.conf
      @include configs.d/openshift/filter-post-*.conf

    <filter kubernetes.**.router**>
      @type grep
      exclude1 message does not have the required certificates
    </filter>

      @include configs.d/openshift/output-pre-*.conf
      @include configs.d/openshift/output-operations.conf
      @include configs.d/user/output-applications.conf
    </label>
  output-applications.conf: |
    <match **>
      @type copy
      @include output-es-config.conf
      @include output-extra-*.conf
      @include ../dynamic/es-copy-config.conf
      @include secure-forward.conf
    </match>
  output-es-config.conf: |
    <store>
      @type elasticsearch_dynamic
      host "#{ENV['ES_HOST']}"
      port "#{ENV['ES_PORT']}"
      scheme https
      index_name project.${record['kubernetes']['namespace_name']}.${record['kubernetes']['namespace_id']}.${Time.parse(record['@timestamp']).getutc.strftime(@logstash_dateformat)}
      user fluentd
      password changeme

      client_key "#{ENV['ES_CLIENT_KEY']}"
      client_cert "#{ENV['ES_CLIENT_CERT']}"
      ca_file "#{ENV['ES_CA']}"

      type_name com.redhat.viaq.common

      flush_interval 5s
      max_retry_wait 300
      disable_retry_limit
      buffer_type memory
      buffer_queue_limit "#{ENV['BUFFER_QUEUE_LIMIT'] || '1024' }"
      buffer_chunk_limit "#{ENV['BUFFER_SIZE_LIMIT'] || '1m' }"
      buffer_queue_full_action "#{ENV['BUFFER_QUEUE_FULL_ACTION'] || 'block'}"
    </store>
  secure-forward.conf: |
    <store>
      @type secure_forward

      self_hostname ${HOSTNAME}
      shared_key thisisasharedkey
      flush_interval 5s
      max_retry_wait 300
      buffer_type memory
      buffer_queue_limit "#{ENV['BUFFER_QUEUE_LIMIT'] || '1024' }"
      buffer_chunk_limit "#{ENV['BUFFER_SIZE_LIMIT'] || '1m' }"
      buffer_queue_full_action "#{ENV['BUFFER_QUEUE_FULL_ACTION'] || 'block'}"

      secure yes
      enable_strict_verification yes
      ca_cert_path /run/secrets/kubernetes.io/serviceaccount/ca.crt
      <server>
        host syslog-relay.log-relay.svc.cluster.local
        port 24284
      </server>
    </store>
  throttle-config.yaml: ""
kind: ConfigMap
metadata:
  creationTimestamp: null
  labels:
    logging-infra: support
  name: logging-fluentd


I just have one question regarding BUFFER_QUEUE_FULL_ACTION if I should be sing block or exception.

*** Bug 1486936 has been marked as a duplicate of this bug. ***

> I just have one question regarding BUFFER_QUEUE_FULL_ACTION if I should be using block or exception.

Use 'block' which is the default you have above.  So you don't have to do anything to use 'block'.

Note that you have only implemented support for buffer_queue_full_action for the applications/containers outputs - you may still run into buffer queue full problems for the operations outputs.

@Freddy,

Can you answer Rich's comment from c#31.

Note.  We have made changes in current release to address this issue. We will backport the 'block' setting.

(In reply to Jeff Cantrill from comment #32)
> @Freddy,
> 
> Can you answer Rich's comment from c#31.
> 
> Note.  We have made changes in current release to address this issue. We
> will backport the 'block' setting.

Done.
"Lagging is better than dropping records"

Confirmed the commit https://github.com/openshift/origin-aggregated-logging/commit/20b31dc5d30086fe7b190884e310fe1547ac2e8a is in openshift3/logging-fluentd:3.5.0-38.

@Mike  Could we confirm the fix work well in v3.5 in  the number of very highly escalated cases?

Completed testing on logging-fluentd:3.5.0-38, here is summery

openshift v3.5.5.31.41
kubernetes v1.5.2+43a9be4
etcd 3.1.0

Environment
1 master m4.xlarge 
3 m4.2xlarge infra instances with es version - logging-elasticsearch:3.5.0
20 m4.large compute nodes with fluentd version logging-fluentd:3.5.0-38 

Here are few cycles completed
6.25M 1K messages/hr - no messages were dropped (87 messages/sec per node)
10M 1K messages/hr - around 15% messages were dropped (139 messages/sec per node)
12.5M 1K messages/hr - around 20% messages were dropped (174 messages/sec per node)

For 3.7 we are seeing good rate without any drop is 60M messages/hr.

Here is the logging inventory I used
[oo_first_master]
ec2-54-244-179-229.us-west-2.compute.amazonaws.com

[oo_first_master:vars]
deployment_type=openshift-enterprise
openshift_release=v3.5.0

openshift_logging_install_logging=true
openshift_logging_use_ops=false
openshift_logging_master_url=https://ec2-54-244-179-229.us-west-2.compute.amazonaws.com:8443
openshift_logging_master_public_url=https://ec2-54-244-179-229.us-west-2.compute.amazonaws.com:8443
openshift_logging_kibana_hostname=kibana.apps.1107-jbb.qe.rhcloud.com
openshift_logging_kibana_ops_hostname=kibana.apps.1107-jbb.qe.rhcloud.com
openshift_logging_namespace=logging
openshift_logging_image_prefix=registry.ops.openshift.com/openshift3/
openshift_logging_image_version=3.5.0
openshift_logging_es_pvc_dynamic=true
openshift_logging_es_pvc_size=100Gi
openshift_logging_es_cluster_size=3
openshift_logging_es_ops_allow_cluster_reader=true
openshift_logging_es_ops_pvc_dynamic=true
openshift_logging_es_ops_pvc_size=50Gi

The results in comment 40 are using the OOTB requests and limits for 3.5 logging deployments.   For ES this is an 8G memory limit and for fluentd it is a 100m cpu limit and 512Mi memory limit.   We will do one more run of the 6.25 and 10 million/hr rates with the limits set to the new defaults in https://github.com/openshift/openshift-ansible/pull/5748 which was backported to 3.6, but not 3.5.

Disregard comment 41 - those limits (8Gi memory for ES and 100m cpu/512Mi memory for fluentd) match the values in 3.7.    Results as they stand are with the OOTB requests/limits.

Is it possible these messages are being dropped by _journald_ and not fluentd?  IIRC 3.5 uses docker --log-driver=journald by default, and journald is known to drop logs when using the defaults for rate limiting.

(In reply to Rich Megginson from comment #44)
> Is it possible these messages are being dropped by _journald_ and not
> fluentd?  IIRC 3.5 uses docker --log-driver=journald by default, and
> journald is known to drop logs when using the defaults for rate limiting.

Yes, this was addressed in a separate bugzilla and applies to OpenShift 3.7 by default in the November 28th errata raising RateLimitBurst=10000 with RateLimitInterval=1s.

https://bugzilla.redhat.com/show_bug.cgi?id=1445797

In separate discussion there are other bugs and potential factors not accounted for in this topic including Docker not releasing file descriptors and sd_journal leaking descriptors that may contribute as well.

https://bugzilla.redhat.com/show_bug.cgi?id=1534827
https://bugzilla.redhat.com/show_bug.cgi?id=1540538

(In reply to Brian J. Beaudoin from comment #45)
> (In reply to Rich Megginson from comment #44)
> > Is it possible these messages are being dropped by _journald_ and not
> > fluentd?  IIRC 3.5 uses docker --log-driver=journald by default, and
> > journald is known to drop logs when using the defaults for rate limiting.
> 
> Yes, this was addressed in a separate bugzilla and applies to OpenShift 3.7
> by default in the November 28th errata raising RateLimitBurst=10000 with
> RateLimitInterval=1s.
> 
> https://bugzilla.redhat.com/show_bug.cgi?id=1445797

AFAIK there is no problem with 3.7 - the problem was with 3.5.  Can you confirm that you see message loss with 3.7?

> 
> In separate discussion there are other bugs and potential factors not
> accounted for in this topic including Docker not releasing file descriptors
> and sd_journal leaking descriptors that may contribute as well.
> 
> https://bugzilla.redhat.com/show_bug.cgi?id=1534827
> https://bugzilla.redhat.com/show_bug.cgi?id=1540538

. . . if the issue can be reproduced on 3.7

(In reply to Rich Megginson from comment #46)
> AFAIK there is no problem with 3.7 - the problem was with 3.5.  Can you
> confirm that you see message loss with 3.7?

I’ve asked the same questions. We’ve got an active case study with a heavily modified 3.4 installation and a previous case study on 3.6 in September 2017. We haven’t been presented with any evidence based on the December or January 3.6 updates nor have we seen specific reports of 3.7 following the November 28 update.

> > https://bugzilla.redhat.com/show_bug.cgi?id=1534827
> > https://bugzilla.redhat.com/show_bug.cgi?id=1540538
> 
> . . . if the issue can be reproduced on 3.7

I’m pushing to get more information. At present our documentation states we’ve deprecated support for json-file in favor of journald but we’re still referencing older studies as a case against. If this has not been resolved in 3.7 we need to know.

For 3.7 the dropped message scenarios I am aware of.

a) As mentioned above, you hit message throttling in journald
b) if json-file logging is used, the number/size of retained logs (docker configuration) is inadequate for the message rates.  We use 3 log files x 100MB each but it would depend greatly on the app that is logging.
c) https://bugzilla.redhat.com/show_bug.cgi?id=1541429 is reproducible in 3.7 and can result in message loss.  It is being investigated.

(In reply to Mike Fiedler from comment #48)
> For 3.7 the dropped message scenarios I am aware of.
> 
> a) As mentioned above, you hit message throttling in journald

That appeared to be addressed for 3.7 specifically by tuning throttling. Note rate limiting is not raised to the point to allow for 60M messages per hour, it is set to 36M messages per hour (10K per second).

https://bugzilla.redhat.com/show_bug.cgi?id=1445797
https://access.redhat.com/errata/RHSA-2017:3188


> b) if json-file logging is used, the number/size of retained logs (docker
> configuration) is inadequate for the message rates.  We use 3 log files x
> 100MB each but it would depend greatly on the app that is logging.

From observation, fluentd will follow file renames on the json-file currently being tailed but does not the rename on the new file created. If there are 3 files named A B C, it will follow A as it is renamed to B and C. When finished reading C, fluentd will start following A effectively dropping 100MB of logs in the file named B.

Raising max-size to slow file turnover is effective in mitigating the issue with json-file. However, as fluentd will never start reading the middle file, max-size > 2 is not effective for mitigating that issue. As different applications log at different rates and the Docker log-opt settings are global, using journald is viewed as the better option if this is viable.


> c) https://bugzilla.redhat.com/show_bug.cgi?id=1541429 is reproducible in
> 3.7 and can result in message loss.  It is being investigated.

Quoting the bug reported against 3.9, "This occurs even at very low message rates" with failure occurring at message rates under 3 messages per second (not thousands). That isn't a performance issue, it's completely and utterly broken.

Closing current release as well as the customer case is closed, no recent activity

The needinfo request[s] on this closed bug have been removed as they have been unresolved for 500 days