Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

inputs.influxdb_listener with influx_parser_type = "upstream" - superfluous response.WriteHeader #10900

Closed
Trovalo opened this issue Mar 28, 2022 · 30 comments · Fixed by #10976
Closed
Labels
bug unexpected problem or unintended behavior platform/windows

Comments

@Trovalo
Copy link
Collaborator

Trovalo commented Mar 28, 2022

Relevant telegraf.conf

[[inputs.influxdb_listener]]
  service_address = ":8186"
  read_timeout = "10s"
  write_timeout = "10s"

  influx_parser_type = "upstream"

Logs from Telegraf

http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)

ref: https://github.com/influxdata/telegraf/blob/b9e66f8b9a2d97e09a7e2c1ff5b2bc08bc4eeebc/plugins/inputs/influxdb_listener/influxdb_listener.go#L504

System info

Telegraf 1.22.0 on WIndows

Docker

No response

Steps to reproduce

  1. use inputs.influxdb_listener with the new upstream parser
  2. you will get the error reported above

Using the old parser does not trigger any error.

From what we've seen, despite this error, the data are still passing and everything seems to work, the main issue is that the log gets flooded by error messages

Expected behavior

not getting errors

Actual behavior

the error superfluous response.WriteHeader call is triggered continuously (every ~1sec)

Additional info

No response

@Trovalo Trovalo added the bug unexpected problem or unintended behavior label Mar 28, 2022
@powersj
Copy link
Contributor

powersj commented Mar 28, 2022

Hi,

Thanks for trying out the new parser and the bug report. I think you are right that the message is coming from the call to badRequest. Could you run with --debug to collect the other debug message that comes before this:

		h.Log.Debugf("Error parsing the request body: %v", err.Error())
		if err := badRequest(res, err.Error()); err != nil {
			h.Log.Debugf("error in bad-request: %v", err)

Thanks!

@Trovalo
Copy link
Collaborator Author

Trovalo commented Mar 31, 2022

here you go:

2022-03-31T08:31:22Z I! [inputs.influxdb_listener] Started HTTP listener service on :8181
2022-03-31T08:31:31Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
2022-03-31T08:31:31Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
2022-03-31T08:31:31Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
2022-03-31T08:31:31Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
2022-03-31T08:31:31Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
2022-03-31T08:31:31Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body

@powersj
Copy link
Contributor

powersj commented Mar 31, 2022

Ah, that interesting that is actually from here, before we have even got to the parser.

Using the old parser does not trigger any error.

This is copy-paste code from the previous parser logic as well so until after this block there should be no differences, so this surprises me.

@Trovalo
Copy link
Collaborator Author

Trovalo commented Mar 31, 2022

I'm sending encoded data (content_encoding = "gzip") to the gateway, but out of curiosity I've also tried content_encoding = "identity" and I get the very same error.

I there something else I can provide to help out?

@powersj
Copy link
Contributor

powersj commented Mar 31, 2022

I there something else I can provide to help out?

Do you happen to have an example input you could share with me to help reproduce this? Ideally, if we could run something like:

echo 'metrics,name=test value=42' | gzip | curl -v -i --data-binary @- -H "Content-Encoding: gzip" http://localhost:8186/write

to help me reproduce and work through whatever is going on.

@Trovalo
Copy link
Collaborator Author

Trovalo commented Apr 1, 2022

While trying to locate what lines were raising the error (by only enabling subsets of my collection) I've found that even just sending the internal monitor data (inputs.internal) will raise an error... therefore you should be able to replicate it without problems, here is the line protocol anyway (exported it by redirecting the result of --test to a file)
lines.txt

@Trovalo
Copy link
Collaborator Author

Trovalo commented Apr 11, 2022

@powersj were you able to replicate the issue?

@powersj
Copy link
Contributor

powersj commented Apr 11, 2022

@Trovalo - I've been out of the office so still catching up. I did try to send the lines you provided and was unable to reproduce any issues:

[agent]
  omit_hostname = false

[[outputs.file]]

[[inputs.influxdb_listener]]
  influx_parser_type = "upstream"

What I sent:

echo 'internal_memstats,company=quantumdatis_demo,host=QDSRVMONITOR,telegraf_instance=telegraf.dev alloc_bytes=5639512i,frees=17209i,heap_alloc_bytes=5639512i,heap_idle_bytes=5505024i,heap_in_use_bytes=6881280i,heap_objects=11381i,heap_released_bytes=5095424i,heap_sys_bytes=12386304i,mallocs=28590i,num_gc=2i,pointer_lookups=0i,sys_bytes=17984104i,total_alloc_bytes=8262392i 1648825166000000000' | gzip | curl -v -i --data-binary @- -H "Content-Encoding: gzip" http://localhost:8186/write
echo 'internal_write,company=quantumdatis_demo,host=QDSRVMONITOR,output=influxdb,telegraf_instance=telegraf.dev,version=1.2.2 buffer_limit=15000i,buffer_size=0i,errors=0i,metrics_added=0i,metrics_dropped=0i,metrics_filtered=0i,metrics_written=0i,write_time_ns=0i 1648825166000000000' | gzip | curl -v -i --data-binary @- -H "Content-Encoding: gzip" http://localhost:8186/write
echo 'internal_process,company=quantumdatis_demo,host=QDSRVMONITOR,processor=converter,telegraf_instance=telegraf.dev,version=1.2.2 errors=0i 1648825166000000000' | gzip | curl -v -i --data-binary @- -H "Content-Encoding: gzip" http://localhost:8186/write
echo 'internal_process,company=quantumdatis_demo,host=QDSRVMONITOR,processor=strings,telegraf_instance=telegraf.dev,version=1.2.2 errors=0i 1648825166000000000' | gzip | curl -v -i --data-binary @- -H "Content-Encoding: gzip" http://localhost:8186/write
echo 'internal_process,company=quantumdatis_demo,host=QDSRVMONITOR,processor=rename,telegraf_instance=telegraf.dev,version=1.2.2 errors=0i 1648825166000000000' | gzip | curl -v -i --data-binary @- -H "Content-Encoding: gzip" http://localhost:8186/write
echo 'internal_agent,company=quantumdatis_demo,go_version=1.17.6,host=QDSRVMONITOR,telegraf_instance=telegraf.dev,version=1.2.2 gather_errors=0i,metrics_dropped=0i,metrics_gathered=1i,metrics_written=0i 1648825166000000000' | gzip | curl -v -i --data-binary @- -H "Content-Encoding: gzip" http://localhost:8186/write
echo 'internal_gather,company=quantumdatis_demo,host=QDSRVMONITOR,input=internal,telegraf_instance=telegraf.dev,version=1.2.2 errors=0i,gather_time_ns=0i,metrics_gathered=1i 1648825166000000000' | gzip | curl -v -i --data-binary @- -H "Content-Encoding: gzip" http://localhost:8186/write
2022-04-11T16:06:04Z I! Starting Telegraf 1.23.0-777f8bf7
2022-04-11T16:06:04Z I! Loaded inputs: influxdb_listener
2022-04-11T16:06:04Z I! Loaded aggregators: 
2022-04-11T16:06:04Z I! Loaded processors: 
2022-04-11T16:06:04Z I! Loaded outputs: file
2022-04-11T16:06:04Z I! Tags enabled: host=ryzen
2022-04-11T16:06:04Z I! [agent] Config: Interval:10s, Quiet:false, Hostname:"ryzen", Flush Interval:10s
2022-04-11T16:06:04Z D! [agent] Initializing plugins
2022-04-11T16:06:04Z D! [agent] Connecting outputs
2022-04-11T16:06:04Z D! [agent] Attempting connection to [outputs.file]
2022-04-11T16:06:04Z D! [agent] Successfully connected to outputs.file
2022-04-11T16:06:04Z D! [agent] Starting service inputs
2022-04-11T16:06:04Z I! [inputs.influxdb_listener] Started HTTP listener service on :8186
2022-04-11T16:06:14Z D! [outputs.file] Buffer fullness: 0 / 10000 metrics
internal_memstats,company=quantumdatis_demo,host=QDSRVMONITOR,telegraf_instance=telegraf.dev alloc_bytes=5639512i,frees=17209i,heap_alloc_bytes=5639512i,heap_idle_bytes=5505024i,heap_in_use_bytes=6881280i,heap_objects=11381i,heap_released_bytes=5095424i,heap_sys_bytes=12386304i,mallocs=28590i,num_gc=2i,pointer_lookups=0i,sys_bytes=17984104i,total_alloc_bytes=8262392i 1648825166000000000
internal_write,company=quantumdatis_demo,host=QDSRVMONITOR,output=influxdb,telegraf_instance=telegraf.dev,version=1.2.2 buffer_limit=15000i,buffer_size=0i,errors=0i,metrics_added=0i,metrics_dropped=0i,metrics_filtered=0i,metrics_written=0i,write_time_ns=0i 1648825166000000000
internal_process,company=quantumdatis_demo,host=QDSRVMONITOR,processor=converter,telegraf_instance=telegraf.dev,version=1.2.2 errors=0i 1648825166000000000
internal_process,company=quantumdatis_demo,host=QDSRVMONITOR,processor=strings,telegraf_instance=telegraf.dev,version=1.2.2 errors=0i 1648825166000000000
internal_process,company=quantumdatis_demo,host=QDSRVMONITOR,processor=rename,telegraf_instance=telegraf.dev,version=1.2.2 errors=0i 1648825166000000000
internal_agent,company=quantumdatis_demo,go_version=1.17.6,host=QDSRVMONITOR,telegraf_instance=telegraf.dev,version=1.2.2 gather_errors=0i,metrics_dropped=0i,metrics_gathered=1i,metrics_written=0i 1648825166000000000
internal_gather,company=quantumdatis_demo,host=QDSRVMONITOR,input=internal,telegraf_instance=telegraf.dev,version=1.2.2 errors=0i,gather_time_ns=0i,metrics_gathered=1i 1648825166000000000
2022-04-11T16:06:24Z D! [outputs.file] Wrote batch of 7 metrics in 72.03µs

I tried setting up a second telegraf with this config:

[agent]
  omit_hostname = false

[[outputs.http]]
    url = "http://localhost:8186/write"

[[inputs.internal]]

and have had it sending data without issue.

Any other thoughts on what I might need to do to reproduce? Thanks!

@andrewbierbaum
Copy link

I'm seeing this as well. I'm using a number of different listeners to sort imcoming ports.

Apr 11 19:57:06 influxdbhost systemd[1]: Starting The plugin-driven server agent for reporting metrics into InfluxDB...
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! Starting Telegraf 1.22.1
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! Loaded inputs: influxdb_listener (21x) internal prometheus
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! Loaded aggregators:
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! Loaded processors:
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! Loaded outputs: influxdb_v2 (23x)
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! Tags enabled: host=jng4m1influxdb2.jenga.skytap.com
Apr 11 19:57:06 influxdbhost systemd[1]: Started The plugin-driven server agent for reporting metrics into InfluxDB.
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [agent] Config: Interval:10s, Quiet:false, Hostname:"jng4m1influxdb2.jenga.skytap.com", Flush Interval:10s
Apr 11 19:57:06 influxdbhost puppet-agent[4416]: (/Stage[main]/Profile::Influxdb/Service[telegraf.service]) Triggered 'refresh' from 21 events
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8224
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8229
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8201
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8200
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8226
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8230
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8227
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8254
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8204
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8203
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8205
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8222
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8232
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8206
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8234
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8207
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8208
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8252
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8253
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8219
Apr 11 19:57:06 influxdbhost telegraf[6157]: 2022-04-11T19:57:06Z I! [inputs.influxdb_listener] Started HTTP listener service on :8238
Apr 11 19:57:07 influxdbhost telegraf[6157]: 2022-04-11T19:57:07Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 19:57:08 influxdbhost telegraf[6157]: 2022-04-11T19:57:08Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 19:57:08 influxdbhost telegraf[6157]: 2022-04-11T19:57:08Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 19:57:09 influxdbhost telegraf[6157]: 2022-04-11T19:57:09Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 19:57:09 influxdbhost crontab[6285]: (root) LIST (root)
Apr 11 19:57:09 influxdbhost telegraf[6157]: 2022-04-11T19:57:09Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 19:57:09 influxdbhost puppet-agent[4416]: Applied catalog in 10.54 seconds
Apr 11 19:57:10 influxdbhost telegraf[6157]: 2022-04-11T19:57:10Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.(*InfluxDBListener).handleWriteInternalParser (influxdb_listener.go:377)
Apr 11 19:57:10 influxdbhost telegraf[6157]: 2022-04-11T19:57:10Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.(*InfluxDBListener).handleWriteInternalParser (influxdb_listener.go:377)
Apr 11 19:57:10 influxdbhost telegraf[6157]: 2022-04-11T19:57:10Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.(*InfluxDBListener).handleWriteInternalParser (influxdb_listener.go:377)
Apr 11 19:57:11 influxdbhost telegraf[6157]: 2022-04-11T19:57:11Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 19:57:11 influxdbhost telegraf[6157]: 2022-04-11T19:57:11Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)

@andrewbierbaum
Copy link

updating /lib/systemd/system/telegraf.service to include --debug then systemctl daemon-reload followed by systemctl restart telegraf produced the following

Apr 11 20:10:19 influxdbhost telegraf[6926]: 2022-04-11T20:10:19Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 11 20:10:19 influxdbhost telegraf[6926]: 2022-04-11T20:10:19Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 20:10:19 influxdbhost telegraf[6926]: 2022-04-11T20:10:19Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
Apr 11 20:10:19 influxdbhost telegraf[6926]: 2022-04-11T20:10:19Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 11 20:10:19 influxdbhost telegraf[6926]: 2022-04-11T20:10:19Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 20:10:19 influxdbhost telegraf[6926]: 2022-04-11T20:10:19Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
Apr 11 20:10:20 influxdbhost telegraf[6926]: 2022-04-11T20:10:20Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.(*InfluxDBListener).handleWriteInternalParser (influxdb_listener.go:377)
Apr 11 20:10:20 influxdbhost telegraf[6926]: 2022-04-11T20:10:20Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.(*InfluxDBListener).handleWriteInternalParser (influxdb_listener.go:377)
Apr 11 20:10:20 influxdbhost telegraf[6926]: 2022-04-11T20:10:20Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.(*InfluxDBListener).handleWriteInternalParser (influxdb_listener.go:377)
Apr 11 20:10:21 influxdbhost telegraf[6926]: 2022-04-11T20:10:21Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 11 20:10:21 influxdbhost telegraf[6926]: 2022-04-11T20:10:21Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 20:10:21 influxdbhost telegraf[6926]: 2022-04-11T20:10:21Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
Apr 11 20:10:21 influxdbhost telegraf[6926]: 2022-04-11T20:10:21Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 11 20:10:21 influxdbhost telegraf[6926]: 2022-04-11T20:10:21Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 20:10:21 influxdbhost telegraf[6926]: 2022-04-11T20:10:21Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
Apr 11 20:10:26 influxdbhost telegraf[6926]: 2022-04-11T20:10:26Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 11 20:10:26 influxdbhost telegraf[6926]: 2022-04-11T20:10:26Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
Apr 11 20:10:26 influxdbhost telegraf[6926]: 2022-04-11T20:10:26Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body

@powersj
Copy link
Contributor

powersj commented Apr 11, 2022

@andrewbierbaum are you also using influx_parser_type = "upstream" as a part of your influxdb_listener config?

@andrewbierbaum
Copy link

Yes, that is what I was attempting, and it started throwing these messages upon changing it to upstream.

@Trovalo
Copy link
Collaborator Author

Trovalo commented Apr 12, 2022

Any other thoughts on what I might need to do to reproduce? Thanks!

I'm running on Windows, maybe is something related to that. @andrewbierbaum which OS are you using?

@andrewbierbaum
Copy link

I'm on Linux, Ubuntu 18.04

powersj added a commit to powersj/telegraf that referenced this issue Apr 12, 2022
Throughout the influx parsing logic there are checks for receiving an
EOF body. When received the parsing logic returns. When content is gzip
we check for any error and return that error, but do not do any specific
chesk for EOF.

Fixes: influxdata#10900
@powersj
Copy link
Contributor

powersj commented Apr 12, 2022

@andrewbierbaum, @Trovalo,

Given the error is about parsing an EOF, I believe your metrics are correctly getting parsed. Throughout the code we have places where we specifically check for EOF and if we get that error, return or move on. I am thinking that this is yet another case of that, but without reproducing I do not yet feel confident of this. I have put up PR #10976 that does add this check but wanted to see if you two could give the artifacts in that PR a try.

Thanks!

powersj added a commit to powersj/telegraf that referenced this issue Apr 12, 2022
Throughout the influx parsing logic there are checks for receiving an
EOF body. When received the parsing logic returns. When content is gzip
we check for any error and return that error, but do not do any specific
chesk for EOF.

Fixes: influxdata#10900
powersj added a commit to powersj/telegraf that referenced this issue Apr 12, 2022
Throughout the influx parsing logic there are checks for receiving an
EOF body. When received the parsing logic returns. When content is gzip
we check for any error and return that error, but do not do any specific
chesk for EOF.

Fixes: influxdata#10900
@andrewbierbaum
Copy link

@powersj
I have a dev environment that I could pretty easily test this change, but I could use some directions on how to carry out the PR test.

@Trovalo
Copy link
Collaborator Author

Trovalo commented Apr 12, 2022

@andrewbierbaum, @Trovalo,

Given the error is about parsing an EOF, I believe your metrics are correctly getting parsed. Throughout the code we have places where we specifically check for EOF and if we get that error, return or move on. I am thinking that this is yet another case of that, but without reproducing I do not yet feel confident of this. I have put up PR #10976 that does add this check but wanted to see if you two could give the artifacts in that PR a try.

Thanks!

I should be able to try it tomorrow, thanks.

@powersj
Copy link
Contributor

powersj commented Apr 12, 2022

@andrewbierbaum the PR just had a comment added to it by the telegraf-tiger. In the comment are links to download various artifacts that are built using the PR. Included are DEB, RPM, tarball, etc. If you could download one of those and add it to your dev environment that would be awesome.

Thanks again!

@andrewbierbaum
Copy link

andrewbierbaum commented Apr 12, 2022

@powersj I was able to wget and install it cleanly. Restarting telegraf with --debug present produced a similar set of errors as above

18:28 andrewbierbaum@influxhost:~$ wget https://output.circle-artifacts.com/output/job/134a21df-9d8a-4555-a36c-d4b8c669ed01/artifacts/0/build/dist/telegraf_1.23.0~23cd3eca-0_amd64.deb
18:29 andrewbierbaum@influxhost:~$ sudo dpkg --install ~/telegraf_1.23.0~23cd3eca-0_amd64.deb
18:37 andrewbierbaum@influxhost:/etc/telegraf/telegraf.d$ apt-cache policy telegraf
telegraf:
  Installed: 1.23.0-0
  Candidate: 1.23.0-0
  Version table:
 *** 1.23.0-0 100
        100 /var/lib/dpkg/status
     1.22.1-1 500
        500 http://artifactorymirror1/artifactory/influxdata-deb/ubuntu bionic/stable amd64 Packages
18:37 andrewbierbaum@influxhost:/etc/telegraf/telegraf.d$ sudo systemctl restart telegraf
18:37 andrewbierbaum@influxhost:/etc/telegraf/telegraf.d$ sudo systemctl status telegraf | cat
● telegraf.service - The plugin-driven server agent for reporting metrics into InfluxDB
   Loaded: loaded (/lib/systemd/system/telegraf.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2022-04-12 18:37:50 UTC; 4s ago
     Docs: https://github.com/influxdata/telegraf
 Main PID: 11438 (telegraf)
    Tasks: 8 (limit: 2322)
   CGroup: /system.slice/telegraf.service
           └─11438 /usr/bin/telegraf -config /etc/telegraf/telegraf.conf -config-directory /etc/tselegraf/telegraf.d --debug

Apr 12 18:37:51 influxhost telegraf[11438]: 2022-04-12T18:37:51Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
Apr 12 18:37:52 influxhost telegraf[11438]: 2022-04-12T18:37:52Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 12 18:37:52 influxhost telegraf[11438]: 2022-04-12T18:37:52Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:457)
Apr 12 18:37:52 influxhost telegraf[11438]: 2022-04-12T18:37:52Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
Apr 12 18:37:54 influxhost telegraf[11438]: 2022-04-12T18:37:54Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 12 18:37:54 influxhost telegraf[11438]: 2022-04-12T18:37:54Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:457)
Apr 12 18:37:54 influxhost telegraf[11438]: 2022-04-12T18:37:54Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
Apr 12 18:37:54 influxhost telegraf[11438]: 2022-04-12T18:37:54Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 12 18:37:54 influxhost telegraf[11438]: 2022-04-12T18:37:54Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:457)
Apr 12 18:37:54 influxhost telegraf[11438]: 2022-04-12T18:37:54Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body

@powersj
Copy link
Contributor

powersj commented Apr 12, 2022

@andrewbierbaum thank you for giving it a shot! I just pushed another update and artifacts are already posted that will print some debug messages, can you give that a shot? Sorry for the back and forth :\

@andrewbierbaum
Copy link

@powersj It's a quick test on my side, so happy to keep testing

@powersj
Copy link
Contributor

powersj commented Apr 19, 2022

Were either of you able to run the latest PR artifacts on #10976? I was hoping to get the output to see what is happening when a failure occurs. Thanks!

@andrewbierbaum
Copy link

andrewbierbaum commented Apr 19, 2022

@powersj Sorry, I misunderstood your previous message from last week or I could have run it when you updated it last week.

18:51 andrewbierbaum@influxhost:~$ sudo dpkg --install ~/telegraf_1.23.0~7f96f6ff-0_amd64.deb
(Reading database ... 97795 files and directories currently installed.)
Preparing to unpack .../telegraf_1.23.0~7f96f6ff-0_amd64.deb ...
Unpacking telegraf (1.23.0-0) over (1.23.0-0) ...
Setting up telegraf (1.23.0-0) ...
18:53 andrewbierbaum@influxhost:~$ sudo systemctl stop telegraf
18:53 andrewbierbaum@influxhost:~$ sudo systemctl start telegraf
18:53 andrewbierbaum@influxhost:~$ sudo systemctl status telegraf | cat
● telegraf.service - The plugin-driven server agent for reporting metrics into InfluxDB
   Loaded: loaded (/lib/systemd/system/telegraf.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2022-04-19 18:53:15 UTC; 5s ago
     Docs: https://github.com/influxdata/telegraf
 Main PID: 4758 (telegraf)
    Tasks: 8 (limit: 2322)
   CGroup: /system.slice/telegraf.service
           └─4758 /usr/bin/telegraf -config /etc/telegraf/telegraf.conf -config-directory /etc/telegraf/telegraf.d

Apr 19 18:53:15 influxhost telegraf[4758]: 2022-04-19T18:53:15Z I! [inputs.influxdb_listener] Started HTTP listener service on :8208
Apr 19 18:53:15 influxhost telegraf[4758]: 2022-04-19T18:53:15Z I! [inputs.influxdb_listener] Started HTTP listener service on :8252
Apr 19 18:53:15 influxhost telegraf[4758]: 2022-04-19T18:53:15Z I! [inputs.influxdb_listener] Started HTTP listener service on :8253
Apr 19 18:53:15 influxhost telegraf[4758]: 2022-04-19T18:53:15Z I! [inputs.influxdb_listener] Started HTTP listener service on :8219
Apr 19 18:53:15 influxhost telegraf[4758]: 2022-04-19T18:53:15Z I! [inputs.influxdb_listener] Started HTTP listener service on :8238
Apr 19 18:53:17 influxhost telegraf[4758]: 2022-04-19T18:53:17Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:459)
Apr 19 18:53:18 influxhost telegraf[4758]: 2022-04-19T18:53:18Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:459)
Apr 19 18:53:19 influxhost telegraf[4758]: 2022-04-19T18:53:19Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:459)
Apr 19 18:53:19 influxhost telegraf[4758]: 2022-04-19T18:53:19Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:459)
Apr 19 18:53:20 influxhost telegraf[4758]: 2022-04-19T18:53:20Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.(*InfluxDBListener).handleWriteInternalParser (influxdb_listener.go:327)

Looks like at least a similar output. Let me know if I can help at all.

@dayvar14
Copy link
Contributor

I'm getting a similar error

2022-04-19T21:54:13Z I! Using config file: /etc/telegraf/telegraf.conf
2022-04-19T21:54:13Z I! Starting Telegraf 1.22.1-67f4874c
2022-04-19T21:54:13Z I! Loaded inputs: cloud_pubsub (3x) influxdb_listener internal
2022-04-19T21:54:13Z I! Loaded aggregators: 
2022-04-19T21:54:13Z I! Loaded processors: converter regex (2x)
2022-04-19T21:54:13Z I! Loaded outputs: cloud_pubsub health influxdb prometheus_client
2022-04-19T21:54:13Z I! Tags enabled: 
2022-04-19T21:54:13Z I! [agent] Config: Interval:30s, Quiet:false, Hostname:"", Flush Interval:30s
2022-04-19T21:54:13Z D! [agent] Initializing plugins
2022-04-19T21:54:13Z D! [agent] Connecting outputs
2022-04-19T21:54:13Z D! [agent] Attempting connection to [outputs.health]
2022-04-19T21:54:13Z I! [outputs.health] Listening on http://[::]:80
2022-04-19T21:54:13Z D! [agent] Successfully connected to outputs.health
2022-04-19T21:54:13Z D! [agent] Attempting connection to [outputs.influxdb]
2022-04-19T21:54:13Z D! [agent] Successfully connected to outputs.influxdb
2022-04-19T21:54:13Z D! [agent] Attempting connection to [outputs.prometheus_client]
2022-04-19T21:54:13Z I! [outputs.prometheus_client] Listening on http://[::]:9273/metrics
2022-04-19T21:54:13Z D! [agent] Successfully connected to outputs.prometheus_client
2022-04-19T21:54:13Z D! [agent] Attempting connection to [outputs.cloud_pubsub]
2022-04-19T21:54:13Z D! [agent] Successfully connected to outputs.cloud_pubsub
2022-04-19T21:54:13Z D! [agent] Starting service inputs
2022-04-19T21:54:13Z I! [inputs.cloud_pubsub] Starting receiver for subscription nginxlog-metrics-us-east1-sub...
2022-04-19T21:54:13Z I! [inputs.cloud_pubsub] Starting receiver for subscription fpmlog-metrics-us-east1-sub...
2022-04-19T21:54:13Z I! [inputs.cloud_pubsub] Starting receiver for subscription mysqlslowlog-metrics-us-east1-sub...
2022-04-19T21:54:13Z I! [inputs.influxdb_listener] Started HTTP listener service on :8186
2022-04-19T21:54:43Z D! [outputs.influxdb] Wrote batch of 41 metrics in 6.121036ms
2022-04-19T21:54:43Z D! [outputs.influxdb] Buffer fullness: 0 / 20000 metrics
2022-04-19T21:54:45Z D! [outputs.cloud_pubsub] Wrote batch of 41 metrics in 26.302829ms
2022-04-19T21:54:45Z D! [outputs.cloud_pubsub] Buffer fullness: 0 / 45000 metrics
2022-04-19T21:54:46Z D! [outputs.health] Wrote batch of 11 metrics in 1.457µs
2022-04-19T21:54:46Z D! [outputs.health] Buffer fullness: 0 / 45000 metrics
2022-04-19T21:54:46Z D! [outputs.prometheus_client] Wrote batch of 11 metrics in 144.561µs
2022-04-19T21:54:46Z D! [outputs.prometheus_client] Buffer fullness: 0 / 45000 metrics
2022-04-19T21:55:04Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
2022-04-19T21:55:04Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)
2022-04-19T21:55:04Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
2022-04-19T21:55:15Z D! [outputs.influxdb] Wrote batch of 12 metrics in 4.366207ms
2022-04-19T21:55:15Z D! [outputs.influxdb] Buffer fullness: 0 / 20000 metrics
2022-04-19T21:55:16Z D! [outputs.cloud_pubsub] Wrote batch of 12 metrics in 22.84714ms
2022-04-19T21:55:16Z D! [outputs.cloud_pubsub] Buffer fullness: 0 / 45000 metrics
2022-04-19T21:55:17Z D! [outputs.prometheus_client] Wrote batch of 11 metrics in 122.733µs
2022-04-19T21:55:17Z D! [outputs.prometheus_client] Buffer fullness: 0 / 45000 metrics
2022-04-19T21:55:20Z D! [outputs.health] Wrote batch of 11 metrics in 1.359µs
2022-04-19T21:55:20Z D! [outputs.health] Buffer fullness: 0 / 45000 metrics
2022-04-19T21:55:23Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
2022-04-19T21:55:23Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:504)

powersj added a commit to powersj/telegraf that referenced this issue Apr 21, 2022
@powersj
Copy link
Contributor

powersj commented Apr 21, 2022

@andrewbierbaum I have pushed yet another artifact, could you give that a try?

Thanks!

@andrewbierbaum
Copy link

@powersj

19:21 andrewbierbaum@influxhost:~$ wget https://output.circle-artifacts.com/output/job/58ad9f9a-0edc-40e0-8f9f-a42f5dc3224b/artifacts/0/build/dist/telegraf_1.23.0~040ea484-0_amd64.deb
19:22 andrewbierbaum@influxhost:~$ sudo dpkg -i telegraf_1.23.0~040ea484-0_amd64.deb
[sudo] password for andrewbierbaum:
(Reading database ... 97795 files and directories currently installed.)
Preparing to unpack telegraf_1.23.0~040ea484-0_amd64.deb ...
Unpacking telegraf (1.23.0-0) over (1.23.0-0) ...
Setting up telegraf (1.23.0-0) ...
19:22 andrewbierbaum@influxhost:~$ sudo systemctl restart telegraf
19:22 andrewbierbaum@influxhost:~$ sudo systemctl status telegraf | cat
● telegraf.service - The plugin-driven server agent for reporting metrics into InfluxDB
   Loaded: loaded (/lib/systemd/system/telegraf.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2022-04-21 19:22:40 UTC; 2s ago
     Docs: https://github.com/influxdata/telegraf
 Main PID: 24560 (telegraf)
    Tasks: 8 (limit: 2322)
   CGroup: /system.slice/telegraf.service
           └─24560 /usr/bin/telegraf -config /etc/telegraf/telegraf.conf -config-directory /etc/telegraf/telegraf.d

Apr 21 19:22:40 influxhost telegraf[24560]: 2022-04-21T19:22:40Z I! [inputs.influxdb_listener] Started HTTP listener service on :8208
Apr 21 19:22:40 influxhost telegraf[24560]: 2022-04-21T19:22:40Z I! [inputs.influxdb_listener] Started HTTP listener service on :8252
Apr 21 19:22:40 influxhost telegraf[24560]: 2022-04-21T19:22:40Z I! [inputs.influxdb_listener] Started HTTP listener service on :8253
Apr 21 19:22:40 influxhost telegraf[24560]: 2022-04-21T19:22:40Z I! [inputs.influxdb_listener] Started HTTP listener service on :8219
Apr 21 19:22:40 influxhost telegraf[24560]: 2022-04-21T19:22:40Z I! [inputs.influxdb_listener] Started HTTP listener service on :8238
Apr 21 19:22:42 influxhost telegraf[24560]: 2022-04-21T19:22:42Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:463)
Apr 21 19:22:44 influxhost telegraf[24560]: 2022-04-21T19:22:44Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:463)
Apr 21 19:22:44 influxhost telegraf[24560]: 2022-04-21T19:22:44Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:463)
Apr 21 19:22:45 influxhost telegraf[24560]: 2022-04-21T19:22:45Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:463)
Apr 21 19:22:45 influxhost telegraf[24560]: 2022-04-21T19:22:45Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:463)

still looks like a similar output

@powersj
Copy link
Contributor

powersj commented Apr 21, 2022

       └─24560 /usr/bin/telegraf -config /etc/telegraf/telegraf.conf -config-directory /etc/telegraf/telegraf.d

Can you add --debug to the command, please?

@andrewbierbaum
Copy link

@powersj sure, here is the output. I thought I still had that on from previous, but must have removed it at some point.

19:33 andrewbierbaum@influxhost:~$ sudo vim /lib/systemd/system/telegraf.service
19:33 andrewbierbaum@influxhost:~$ grep ExecStar /lib/systemd/system/telegraf.service
ExecStart=/usr/bin/telegraf -config /etc/telegraf/telegraf.conf -config-directory /etc/telegraf/telegraf.d $TELEGRAF_OPTS --debug
19:34 andrewbierbaum@influxhost:~$ sudo systemctl daemon-reload
19:34 andrewbierbaum@influxhost:~$ sudo systemctl restart telegraf
19:34 andrewbierbaum@influxhost:~$ sudo systemctl status telegraf | cat
● telegraf.service - The plugin-driven server agent for reporting metrics into InfluxDB
   Loaded: loaded (/lib/systemd/system/telegraf.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2022-04-21 19:34:24 UTC; 2s ago
     Docs: https://github.com/influxdata/telegraf
 Main PID: 25066 (telegraf)
    Tasks: 8 (limit: 2322)
   CGroup: /system.slice/telegraf.service
           └─25066 /usr/bin/telegraf -config /etc/telegraf/telegraf.conf -config-directory /etc/telegraf/telegraf.d --debug

Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:463)
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z D! [inputs.influxdb_listener] using upstream parser
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z D! [inputs.influxdb_listener] using internal parser
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z D! [inputs.influxdb_listener] error using new gzip reader
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z D! [inputs.influxdb_listener] 'EOF': 'EOF'
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z D! [inputs.influxdb_listener] Error decompressing request body: EOF
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z I! http: superfluous response.WriteHeader call from github.com/influxdata/telegraf/plugins/inputs/influxdb_listener.badRequest (influxdb_listener.go:463)
Apr 21 19:34:25 influxhost telegraf[25066]: 2022-04-21T19:34:25Z D! [inputs.influxdb_listener] error in bad-request: http: request method or response status code does not allow body

powersj added a commit to powersj/telegraf that referenced this issue Apr 25, 2022
powersj added a commit to powersj/telegraf that referenced this issue Apr 25, 2022
The influxdb_listener input plugin, when using the upstream parser had
bad logic that would write first using the new upstream parser and then
attempt to parse the data again with the internal parser right after.
This was leading to EOF errors on the internal parser because the data
had already been read.

Fixes: influxdata#10900
@powersj
Copy link
Contributor

powersj commented Apr 25, 2022

@andrewbierbaum,

[inputs.influxdb_listener] using upstream parser
[inputs.influxdb_listener] using internal parser

Doh! These log lines reveal the issue: when using the upstream parser, my bad logic was using the upstream parser and then always trying to write the data we just did again with the internal parser. I have pushed a fix and would appreciate another test once artifacts are posted in ~20mins.

Thanks very much for the back and forth!

edit: artifacts are up!

@andrewbierbaum
Copy link

@powersj I now see a clean output from sudo systemctl status telegraf that otherwise was giving the above error instantly. It appears to be fixed as far as I can tell. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug unexpected problem or unintended behavior platform/windows
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants