Bug 1414810

Is there any missing data?  Can we see the fluentd logs to correlate that message with possibly something in the fluentd log?

That sort of thing happens during a bulk operation when the bulk service fails to create the index automatically.  There is a good chance this is related to a SearchGuard behavior preventing the new index from being created.

What version of Elasticsearch here?  I am going to guess 2.x.

Also, with regard to fluentd logs, if the are flowing in the same event stream as the bulk operation, that will be a problem.

@Peter, can you clarify what "..are flowing in the same event stream.." means?  Is this something we can modify

(In reply to Jeff Cantrill from comment #3)
> @Peter, can you clarify what "..are flowing in the same event stream.."
> means?  Is this something we can modify

Sorry, I should have said: "If log messages from the fluentd processes themselves are flowing into the same event stream as other logs from the system in which that fluentd process is running, then we might not even see the logs from fluentd since they would potentially be dropped along with other logs that don't get index.

Does that make sense?

Another reason we need a secondary data path for the logs from the logging infrastructure itself.

@(In reply to Rich Megginson from comment #1)
> Is there any missing data?  Can we see the fluentd logs to correlate that
> message with possibly something in the fluentd log?

I see some of the fluentd pods having to retry connection to the enrichment-fluentd service. Although most of them seem to be able to recover the connection.

disconnected host="logging-enrichment-fluentd" port=24284

http://pbench.perf.lab.eng.bos.redhat.com/results/ocp34-master-1/erd_fluentd_256ll_5wppn_20_200_3ES_1h/log/oc/post_test/pods/oc_logs-logging-fluentd-kutj4.log

http://pbench.perf.lab.eng.bos.redhat.com/results/ocp34-master-1/erd_fluentd_256ll_5wppn_20_200_3ES_1h/log/oc/post_test/pods/oc_logs-logging-fluentd-prwf3.log

http://pbench.perf.lab.eng.bos.redhat.com/results/ocp34-master-1/erd_fluentd_256ll_5wppn_20_200_3ES_1h/log/oc/post_test/pods/oc_logs-logging-fluentd-vm94g.log

Lukas do you have any input regarding this issue.  It doesn't seem we have any data loss.  Do you think we may wish to just document and move on?  Can we lower the priority as it does not seem to be a blocker. I am not sure what there is for us to do unless you have ideas

Ricardo,

Can you comment on the priority/severity of this issue?  It seems we have no data loss and fluentd is able to recover.  We are looking to move this off the blocker list.

@Peter, yes this is 2.x

@Jeff,

Both the pre-test and post-test logs show the same and "during the primary phase for action" might mean this happens during initial sharding operations.

It looks like an index was deleted while a bulk request was still in flight, which is very possible given that the test harness deletes all indices right in the beginning of the test in order to start recording data with "clean" indices.

Given that this is a [WARN] message which doesn't seem to repeat much in the logs I wouldn't say it is a blocker and can be lower prio.

Ah, so then this seems to be a bug with the test harness, right?

What is the requirement that indices be deleted before a test?  All logs for the test should have a timestamp that properly aligns with the test.  If you have a requirement to test how logging is handle from the initial instance, we should probably review that, because most problems in the field will come while the environment is in full use, no?

If we do need to start from scratch, then can't the test harness first turn off all the fluentd pods, then delete the indices, then turn the fluentd pods back on?

I agree based on this information that this is not a priority or a bug with OpenShift.

rMost likely, yes.
This was added as suggested by Lukas. At the beginning of each test, we delete all data in the indices from the previous runs, also to clear or have ES optimize any extra disk space used by those indices.

Does not seem realistic.

Perhaps we should curate indices at 1 week, run tests for one week to fill the environment, measuring as we go, and then take measurements when at capacity?

Lowering the priority as not a blocker and there is no data loss

Lukas, looking for your input here.

Seems I did not realise that you use shared ES cluster instance for several parallel/consecutive tests? Can you please explain me how and when you re-use the ES cluster for several tests then?

My recommendation was to always start with clean fresh ES cluster for each test to minimize the risk we interpret results incorrectly and make sure things like cache evictions, heavy GC cycles ... etc are not impacted by use of the cluster in previous tests...

(In reply to Lukas Vlcek from comment #14)
> Seems I did not realise that you use shared ES cluster instance for several
> parallel/consecutive tests? Can you please explain me how and when you
> re-use the ES cluster for several tests then?

Not sure this is about parallel testing or consecutive testing.  If fluentd pods are always running, and one deletes all the indices that they are writing to at the time, then there is always a chance a delete will take place during a bulk index operation, causing this problem.

Deleting indices while fluentd pods are running seems like a really bad idea.

> 
> My recommendation was to always start with clean fresh ES cluster for each
> test to minimize the risk we interpret results incorrectly and make sure
> things like cache evictions, heavy GC cycles ... etc are not impacted by use
> of the cluster in previous tests...

Certainly that is one mode of testing, but I am not sure how useful that is.  How often will a customer have a pristine environment?  If we measure logging in that environment, how can we compare that to what customers encounter in the live scenario?

It seems we need to rethink this testing strategy.

> Deleting indices while fluentd pods are running seems like a really bad idea.

I agree. I did not think about this context then I thought we can control it very precisely.

> How often will a customer have a pristine environment?  If we measure logging in that environment, how can we compare that to what customers encounter in the live scenario?

I understand. But we should be able to test with clean fresh ES as well. For example we want to be able to verify that under specific condition we can guarantee 100% logs delivery and indexing. This means we want the "total.doc.count = sum of all generated logs on all pods". For this type of tests we might need improve our testing environment?

(In reply to Lukas Vlcek from comment #17)
> 
> I understand. But we should be able to test with clean fresh ES as well. For
> example we want to be able to verify that under specific condition we can
> guarantee 100% logs delivery and indexing. This means we want the
> "total.doc.count = sum of all generated logs on all pods". For this type of
> tests we might need improve our testing environment?

We just need to turn off fluentd pods before we delete all indicies, no?

(In reply to Lukas Vlcek from comment #14)
> Seems I did not realise that you use shared ES cluster instance for several
> parallel/consecutive tests? Can you please explain me how and when you
> re-use the ES cluster for several tests then?
> 
> My recommendation was to always start with clean fresh ES cluster for each
> test to minimize the risk we interpret results incorrectly and make sure
> things like cache evictions, heavy GC cycles ... etc are not impacted by use
> of the cluster in previous tests...

I didn't run any parallel tests. Before each test starts, the indices are deleted so we don't have data from 10 pods per node vs 30 pods per node.
The test does not scale down the fluentd's to 0 after doing that, so a delete operation might be taking place while the fluentd's are already trying to send data.

If the problem here is deleting indices that are still in use, I would like to close this bug as WONTFIX.  Does everyone agree?

I don't believe this is a bug.  If "won't fix" implies that it is a bug, is there another category to use, like invalid or something?

Closing since there seems to be agreement that this is an unlikely and invalid scenario for a customer.