Bug 1846094

Peri,

This may be related to the correction of the buffers you merged based on:

2020-06-10 17:02:29 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2020-06-10 17:02:30 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block

Since the logs are not getting pushed maybe we are bumping into some backoff (e.g. exponential?)

I am hitting this even at low message rates (100 messages/second/node) across 10 pods/node

Moving to UpcomingSprint as unlikely to address before EOS

Running this test with:

* Eric M's SVT workload generator
* Default configuration
* Modifications to generator to allow 180 pods as NS should not be an issue: 'LABEL_ALL_NODES=true REPLICAS=180 NUM_LINES=45000 RATE=4500 ansible-playbook -v -i inventory workloads/logging.yml'
* Default ES configs

This is a shorter test but I don't see the expected number of logs come through.  I don't think fluent is wedged as we have run into the missed logged messages.  The pos file on one node shows they were read completely:

$ oc exec fluentd-25bb5 -- cat /var/log/es-containers.log.pos | grep logtest
/var/log/containers/centos-logtest-xsrhc_logtest-0_centos-logtest-4baf5f819a8c0c8d200ad028b55c39fbce5aa54c3a517ec9958505eddc356123.log	ffffffffffffffff	000000000fe037c9
/var/log/containers/centos-logtest-lkhmr_logtest-0_centos-logtest-bd40c78bb9913c90d703175a221d6bb6b35718652a5ed518267feb7c2898d407.log	ffffffffffffffff	00000000100645eb
/var/log/containers/centos-logtest-s77cg_logtest-0_centos-logtest-cf1172cc83dc0e9b288c755cfefd05810fbb4e418ae4c7c470bb08857759d1f9.log	ffffffffffffffff	0000000010201ac7

Agree ES is not loaded.

Rerunning and reverting: https://github.com/openshift/cluster-logging-operator/commit/8ceb6215e369ebbb754ab2da263c8c67d7a624b8

Found a possible way to reproduce the "wedged" scenario.  It appears the number of worker nodes has something to do with it which would imply ES does as well.
Case A:  All messages indexed
Case B:  The symptoms of this BZ, fluentd stops sending, gets backed up on buffer files and no further messages indexed.

Both cases, ES is running on 3 x m5.8xlarge with requests for 28 vCPU and 61Gi

Case A: 3 m5.xlarge worker nodes running 10 application pods, each logging at 50 messages second.  500 messages/second/node and 1500 messages/second total for cluster
Case B: 10 m5.xlarge worker nodes running 10 application pods each logging at 50 messages second.  500 messages/second/node and 5000 messages/second total for cluster

In case A all messages indexed.  In case B, logging stops after ~475K-750K messages indexed (number varies, but seems to be around there>

For case B (bad case),  ES is not showing high CPU, memory or IO.   There are no rejects and no obvious messages in the ES log)

Another hint that ES might be involved is that Prometheus endpoint data for ES stops exactly when the indexing stops.   I will attach the OS CPU/Memory graphs for one of the ES nodes.

Here are the ES queues when indexing stops:


host        name                rejected completed queue size active largest
10.129.8.18 analyze                    0         0     0    0      0       0
10.129.8.18 fetch_shard_started        0         0     0    0      0       0
10.129.8.18 fetch_shard_store          0         0     0    0      0       0
10.129.8.18 flush                      0       106     0    2      0       3
10.129.8.18 force_merge                0         0     0    0      0       0
10.129.8.18 generic                    0      1102     0    4      0       4
10.129.8.18 get                        0       874     0   28      0      28
10.129.8.18 index                      0         0     0    0      0       0
10.129.8.18 listener                   0         0     0    0      0       0
10.129.8.18 management                 0     57115     0    5      1       5
10.129.8.18 refresh                    0      5977     0    3      0       3
10.129.8.18 search                     0         0     0    0      0       0
10.129.8.18 search_throttled           0         0     0    0      0       0
10.129.8.18 snapshot                   0         0     0    0      0       0
10.129.8.18 warmer                     0     17831     0    5      0       5
10.129.8.18 write                      0     63231     0   28      0      28
10.131.8.17 analyze                    0         0     0    0      0       0
10.131.8.17 fetch_shard_started        0         0     0    0      0       0
10.131.8.17 fetch_shard_store          0         0     0    0      0       0
10.131.8.17 flush                      0       106     0    2      0       3
10.131.8.17 force_merge                0         0     0    0      0       0
10.131.8.17 generic                    0      4174     0    4      0       4
10.131.8.17 get                        0         0     0    0      0       0
10.131.8.17 index                      0         0     0    0      0       0
10.131.8.17 listener                   0         0     0    0      0       0
10.131.8.17 management                 0     57060     0    4      1       4
10.131.8.17 refresh                    0      5968     0    3      0       3
10.131.8.17 search                     0         0     0    0      0       0
10.131.8.17 search_throttled           0         0     0    0      0       0
10.131.8.17 snapshot                   0         0     0    0      0       0
10.131.8.17 warmer                     0     17887     0    5      0       5
10.131.8.17 write                      0     63239     0   28      0      28
10.130.8.18 analyze                    0         0     0    0      0       0
10.130.8.18 fetch_shard_started        0         0     0    0      0       0
10.130.8.18 fetch_shard_store          0         0     0    0      0       0
10.130.8.18 flush                      0       108     0    2      0       3
10.130.8.18 force_merge                0         0     0    0      0       0
10.130.8.18 generic                    0      4092     0    4      0       4
10.130.8.18 get                        0       879     0   28      0      28
10.130.8.18 index                      0         0     0    0      0       0
10.130.8.18 listener                   0         0     0    0      0       0
10.130.8.18 management                 0     56463     0    5      1       5
10.130.8.18 refresh                    0      8863     0    3      0       3
10.130.8.18 search                     0         0     0    0      0       0
10.130.8.18 search_throttled           0         0     0    0      0       0
10.130.8.18 snapshot                   0         0     0    0      0       0
10.130.8.18 warmer                     0     17885     0    5      0       5

(In reply to Mike Fiedler from comment #8)
> Found a possible way to reproduce the "wedged" scenario.  It appears the
> 
> Case A: 3 m5.xlarge worker nodes running 10 application pods, each logging
> at 50 messages second.  500 messages/second/node and 1500 messages/second
> total for cluster
> Case B: 10 m5.xlarge worker nodes running 10 application pods each logging
> at 50 messages second.  500 messages/second/node and 5000 messages/second
> total for cluster

Are these not the cases we have already identified in https://bugzilla.redhat.com/show_bug.cgi?id=1833486 where upon reverting https://github.com/openshift/cluster-logging-operator/commit/8ceb6215e369ebbb754ab2da263c8c67d7a624b8 we can support 2500 m/s which is consistent with 4.4 but anything higher we have message loss not actually messages sitting in buffers?  In my short tests, any rates higher then 2500 m/s using the default fluent cpu (100mi) results in message loss meaning fluent is only shipping the messages it knows about

Put UpcomingSprint, as ongoing investigation is not conclusive yet.

Closing per https://bugzilla.redhat.com/show_bug.cgi?id=1846174#c12