Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1924329

Summary: fluentd fails to deliver message with Server returned nothing (no headers, no data)
Product: OpenShift Container Platform Reporter: Sergey Yedrikov <syedriko>
Component: LoggingAssignee: Sergey Yedrikov <syedriko>
Status: CLOSED ERRATA QA Contact: Qiaoling Tang <qitang>
Severity: urgent Docs Contact:
Priority: high    
Version: 4.5CC: agawand, akaris, andcosta, anli, aos-bugs, apaladug, george.anastasiou, hchatter, igreen, jcantril, jswensso, kperrier, mmohan, nnosenzo, ocasalsa, openshift-bugs-escalate, periklis, puraut, stwalter, syedriko
Target Milestone: ---   
Target Release: 4.5.z   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: logging-exploration
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Cause: The default HTTP read and write timeouts in the Elasticsearch proxy were set to 5 seconds. Consequence: The Elasticsearch proxy times out connections between fluentd and Elasticsearch too soon in some bulk insertion situations. Fix: Increase the default HTTP read and write timeouts in the Elasticsearch proxy to 1 minute. Provide command-line options in Elasticsearch proxy that control HTTP timeouts in the field. Result: The Elasticsearch proxy no longer times out connections between fluentd and Elasticsearch prematurely. Command-line parameters of Elasticsearch proxy allow to control HTTP timeouts in Elasticsearch proxy in the field.
 Story Points: ---
Clone Of: 1924258 Environment:
Last Closed: 2021-03-03 04:32:28 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1924258    
Bug Blocks:    

Comment 1 Jeff Cantrill 2021-02-08 20:55:27 UTC 
*** Bug 1912579 has been marked as a duplicate of this bug. ***
Comment 7 Qiaoling Tang 2021-02-19 03:08:22 UTC 
Verified with elasticsearch-operator.4.5.0-202102172235.p0
Comment 10 George Anastasiou 2021-02-28 18:48:34 UTC 
Hi,

In OCP4.5 i tried to apply the workaround by modifing the proxy image based on https://access.redhat.com/solutions/5837201

I keep getting the same error, perhaps not with the same frequency

```
2021-02-28 18:40:24 +0000 [warn]: [clo_default_output_es] buffer flush took longer time than slow_flush_log_threshold: elapsed_time=36.299287780188024 slow_flush_log_threshold=20.0 plugin_id="clo_default_output_es"
2021-02-28 18:40:24 +0000 [warn]: [clo_default_output_es] retry succeeded. chunk_id="5bb5221b998fabb3a5869b882b798063"
2021-02-28 18:40:31 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:40:44 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:40:56 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:41:08 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:41:19 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:41:33 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:41:44 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:42:18 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:42:29 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:42:54 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:43:06 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:43:19 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:43:32 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:43:47 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:43:59 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:44:07 +0000 [warn]: [clo_default_output_es] failed to flush the buffer. retry_time=0 next_retry_seconds=2021-02-28 18:44:08 +0000 chunk="5bb531829aae8bf547bad711110b3416" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="could not push logs to Elasticsearch cluster ({:host=>\"elasticsearch.openshift-logging.svc.cluster.local\", :port=>9200, :scheme=>\"https\", :user=>\"fluentd\", :password=>\"obfuscated\"}): Server returned nothing (no headers, no data)"
  2021-02-28 18:44:07 +0000 [warn]: suppressed same stacktrace
2021-02-28 18:44:12 +0000 [warn]: [clo_default_output_es] failed to flush the buffer. retry_time=1 next_retry_seconds=2021-02-28 18:44:13 +0000 chunk="5bb532021111722ca7a3db7336e8ed3b" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="could not push logs to Elasticsearch cluster ({:host=>\"elasticsearch.openshift-logging.svc.cluster.local\", :port=>9200, :scheme=>\"https\", :user=>\"fluentd\", :password=>\"obfuscated\"}): Server returned nothing (no headers, no data)"
  2021-02-28 18:44:12 +0000 [warn]: suppressed same stacktrace
2021-02-28 18:44:16 +0000 [warn]: [clo_default_output_es] failed to flush the buffer. retry_time=2 next_retry_seconds=2021-02-28 18:44:18 +0000 chunk="5bb531829aae8bf547bad711110b3416" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="could not push logs to Elasticsearch cluster ({:host=>\"elasticsearch.openshift-logging.svc.cluster.local\", :port=>9200, :scheme=>\"https\", :user=>\"fluentd\", :password=>\"obfuscated\"}): Server returned nothing (no headers, no data)"
  2021-02-28 18:44:16 +0000 [warn]: suppressed same stacktrace
2021-02-28 18:44:23 +0000 [warn]: [clo_default_output_es] failed to flush the buffer. retry_time=3 next_retry_seconds=2021-02-28 18:44:27 +0000 chunk="5bb532021111722ca7a3db7336e8ed3b" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="could not push logs to Elasticsearch cluster ({:host=>\"elasticsearch.openshift-logging.svc.cluster.local\", :port=>9200, :scheme=>\"https\", :user=>\"fluentd\", :password=>\"obfuscated\"}): Server returned nothing (no headers, no data)"
  2021-02-28 18:44:23 +0000 [warn]: suppressed same stacktrace
2021-02-28 18:44:24 +0000 [warn]: [clo_default_output_es] retry succeeded. chunk_id="5bb531829aae8bf547bad711110b3416"
2021-02-28 18:44:29 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:44:36 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:44:41 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:44:46 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:44:51 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:45:23 +0000 [warn]: [clo_default_output_es] failed to flush the buffer. retry_time=0 next_retry_seconds=2021-02-28 18:45:24 +0000 chunk="5bb519b2a84863c2a641c864454f0840" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="could not push logs to Elasticsearch cluster ({:host=>\"elasticsearch.openshift-logging.svc.cluster.local\", :port=>9200, :scheme=>\"https\", :user=>\"fluentd\", :password=>\"obfuscated\"}): Server returned nothing (no headers, no data)"
  2021-02-28 18:45:23 +0000 [warn]: suppressed same stacktrace
2021-02-28 18:45:29 +0000 [warn]: [clo_default_output_es] failed to flush the buffer. retry_time=1 next_retry_seconds=2021-02-28 18:45:30 +0000 chunk="5bb519b2a80642b2b9989a3c85a88263" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="could not push logs to Elasticsearch cluster ({:host=>\"elasticsearch.openshift-logging.svc.cluster.local\", :port=>9200, :scheme=>\"https\", :user=>\"fluentd\", :password=>\"obfuscated\"}): Server returned nothing (no headers, no data)"
  2021-02-28 18:45:29 +0000 [warn]: suppressed same stacktrace
2021-02-28 18:45:31 +0000 [warn]: [clo_default_output_es] failed to flush the buffer. retry_time=2 next_retry_seconds=2021-02-28 18:45:33 +0000 chunk="5bb519b2a84863c2a641c864454f0840" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="could not push logs to Elasticsearch cluster ({:host=>\"elasticsearch.openshift-logging.svc.cluster.local\", :port=>9200, :scheme=>\"https\", :user=>\"fluentd\", :password=>\"obfuscated\"}): Server returned nothing (no headers, no data)"
  2021-02-28 18:45:31 +0000 [warn]: suppressed same stacktrace
2021-02-28 18:45:35 +0000 [warn]: [clo_default_output_es] retry succeeded. chunk_id="5bb519b2a80642b2b9989a3c85a88263"
2021-02-28 18:45:40 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:45:52 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:46:05 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:46:17 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:46:29 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:46:39 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:46:50 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:47:02 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:47:14 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:47:25 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:47:37 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:47:44 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:47:49 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
2021-02-28 18:47:58 +0000 [warn]: [clo_default_output_es] failed to write data into buffer by buffer overflow action=:block
```
Comment 11 Sergey Yedrikov 2021-03-01 00:48:02 UTC 
(In reply to George Anastasiou from comment #10)
> Hi,
> 
> In OCP4.5 i tried to apply the workaround by modifing the proxy image based
> on https://access.redhat.com/solutions/5837201
> 
> I keep getting the same error, perhaps not with the same frequency
> 

Hi George,

Could you check two things:
- you're indeed running the es-proxy image prescribed in the workaround
- es-proxy logs, anything interesting there?

Regards,
Sergey.
Comment 12 George Anastasiou 2021-03-01 09:35:51 UTC 
(In reply to Sergey Yedrikov from comment #11)
> (In reply to George Anastasiou from comment #10)
> > Hi,
> > 
> > In OCP4.5 i tried to apply the workaround by modifing the proxy image based
> > on https://access.redhat.com/solutions/5837201
> > 
> > I keep getting the same error, perhaps not with the same frequency
> > 
> 
> Hi George,
> 
> Could you check two things:
> - you're indeed running the es-proxy image prescribed in the workaround
> - es-proxy logs, anything interesting there?
> 
> Regards,
> Sergey.

Hi Sergey,

Yes i am running on the right image:

---
      image: registry.redhat.io/openshift4/ose-elasticsearch-proxy:v4.5.0-202012120433.p0
      image: registry.redhat.io/openshift4/ose-elasticsearch-proxy:v4.5.0-202012120433.p0
      imageID: registry.redhat.io/openshift4/ose-elasticsearch-proxy@sha256:5f54b0199de160f625eda9d8805579617b41e994bc7c846315fa5ac38a09a87a
      image: registry.redhat.io/openshift4/ose-elasticsearch-proxy:v4.5.0-202012120433.p0
      image: registry.redhat.io/openshift4/ose-elasticsearch-proxy:v4.5.0-202012120433.p0
      imageID: registry.redhat.io/openshift4/ose-elasticsearch-proxy@sha256:5f54b0199de160f625eda9d8805579617b41e994bc7c846315fa5ac38a09a87a
      image: registry.redhat.io/openshift4/ose-elasticsearch-proxy:v4.5.0-202012120433.p0
      image: registry.redhat.io/openshift4/ose-elasticsearch-proxy:v4.5.0-202012120433.p0
      imageID: registry.redhat.io/openshift4/ose-elasticsearch-proxy@sha256:5f54b0199de160f625eda9d8805579617b41e994bc7c846315fa5ac38a09a87a
---

Not really anything interesting, below message only keeps coming

---
time="2021-03-01T09:33:29Z" level=info msg="Handling request \"authorization\""
time="2021-03-01T09:33:29Z" level=info msg="Handling request \"authorization\""
time="2021-03-01T09:33:30Z" level=info msg="Handling request \"authorization\""
time="2021-03-01T09:33:34Z" level=info msg="Handling request \"authorization\""
---

Regards,
George
Comment 13 Sergey Yedrikov 2021-03-01 16:58:53 UTC 
Hi George,

Let's look further then. Are you seeing the same picture in the logs of all fluentd pods? Is there anything interesting in the log of elasticsearch containers?

Regards,
Sergey.
Comment 15 errata-xmlrpc 2021-03-03 04:32:28 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 (OpenShift Container Platform 4.5.33 extras update), 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-2021:0430