malformed HTTP response from logging.googleapis.com:443 on connection #186

[tpetrov-lp]

I see a lot of messages like "malformed HTTP response from logging.googleapis.com:443 on connection #186" in the logs of our 1.8.11 deployment. It's ~200K warnings over 10h. (it's apparently coming from the stackdriver output plugin)
Looking through the code, it seems a few different responses can cause it - basically content length, status code and ending chunk. Have someone experienced this? Or should I check with Google if this can be really something with their response?

[agup006]

Adding @qingling128 from the Google side

[qingling128]

@tpetrov-lp - Hi, do you happen to have the full API response with a timestamp?

[tpetrov-lp]

@qingling128 I don't see the full api response logged from fluent-bit. Can it be turned on with some flag?
I am attaching a screenshot with some timestamps, but it happens pretty much constantly, so not sure if this helps at all.

[tuxillo]

I have the same warning repeating over and over but with the bigquery output plugin.

@tpetrov-lp have you tried enabling Log_Level trace under the SERVICE section and tls.debug 4 under the OUTPUT section? I might be missing something else but I think that gives a bit more information, not sure if the full response is there though.

BTW, expect a lot of output in the logs :)

[tpetrov-lp]

Yeah, I am a bit reluctant to running it in trace mode, because we have 200K msg/sec, so it will probably produce huge amount of logs. We can think about running it for a while if it will help, but I think that even in trace mode it does not log the full response.
@tuxillo if you have run it with trace enables, did you see some hints what the problem might be? I am pretty sure that it should be the same problem for BigQuery and StackDriver.

[dsludwig]

I am also encountering this issue. I enabled Log_Level trace and tls.debug 4 as suggested, but a complete response is not available. One symptom seems to be net_read returning only one byte at a time:

Jan 25 19:47:07 raspberrypi td-agent-bit[7945]: [2022/01/25 19:47:07] [trace] [io coro=0x75ee7240] [net_read] try up to 4082 bytes
Jan 25 19:47:07 raspberrypi td-agent-bit[7945]: [2022/01/25 19:47:07] [trace] [io coro=0x75ee7240] [net_read] ret=1
Jan 25 19:47:07 raspberrypi td-agent-bit[7945]: [2022/01/25 19:47:07] [trace] [io coro=0x75ee7240] [net_read] try up to 4081 bytes
Jan 25 19:47:07 raspberrypi td-agent-bit[7945]: [2022/01/25 19:47:07] [trace] [io coro=0x75ee7240] [net_read] ret=1
Jan 25 19:47:07 raspberrypi td-agent-bit[7945]: [2022/01/25 19:47:07] [ warn] [http_client] malformed HTTP response from logging.googleapis.com:443 on connection #36
Jan 25 19:47:07 raspberrypi td-agent-bit[7945]: [2022/01/25 19:47:07] [ warn] [output:stackdriver:stackdriver.1] http_do=-1

malformed-response.log

Edit:

Is this related to #4098? Is there an underlying error that is being presented as 1 byte read?

[tuxillo]

It seems that warning is printed on FLB_HTTP_ERROR after a call to process_data(), here:

fluent-bit/src/flb_http_client.c

Line 1222 in 1a52299

flb_warn("[http_client] malformed HTTP response from %s:%i on "

But that FLB_HTTP_ERROR can come from multiple places from the called function. I wonder if it would be worth adding some code to discriminate among those errors so debugging is easier in case of issues? Also a way of dumping the payload at a specific trace level, perhaps?

[tuxillo]

Has anybody made any progress? Thanks!

[nokute78]

@dsludwig I think it is related to #4098. Openssl error may be occurred.
What version are you using ? The error handling issue #4098 is fixed from v1.8.12.

See also: #4723 (comment)

[tuxillo]

@dsludwig did you try with the latest version?

[github-actions]

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 5 days. Maintainers can add the exempt-stale label.

[tuxillo]

Please don't close, I'll check my logs and version now.

[github-actions]

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 5 days. Maintainers can add the exempt-stale label.

[tuxillo]

Sorry for the late reply, the upgrade fixed the problem, thanks!

[github-actions]

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 5 days. Maintainers can add the exempt-stale label.

[github-actions]

This issue was closed because it has been stalled for 5 days with no activity.