Graylog2 / Graylog2/graylog2-server

HTTP GELF Input silently drops most messages

Open
#13,959 13 comments 0 reactions 0 assignees View on GitHub
bug to-verify triaged
Dominant language
Java
Stars
8.1k
Forks
1.1k
Avg merge
1d 20h
Merged PRs (30d)
217

Description

## Expected Behavior

This morning my Graylog was working as intended. It's a docker-compose set-up running behind an Apache TLS reverse proxy. I had to update the FQDN of the server. I added a new virtual host with the new FQDN. I also kept the old virtualhost. Then I updated my services' log configurations to point to the new FQDN for logging. I expected things to keep working.

## Current Behavior

I noticed that suddenly I was receiving _very few_ log messages, but not none. I reverted the changes of the services' configuration, and started testing the new FQDN using cURL:

```bash
while true
do curl -i -X POST -H 'Content-Type: application/json' -d '{ "version": "1.1", "host": "redacted.com", "short_message": "A short message", "level": 5, "_some_info": "foo" }' 'https://redacted.example.org/gelf'
sleep 3
done
```

I noticed that of the cURL messages, sent every 3 seconds, I received approximately one per minute on average.

I reverted my changes and went back to using the old FQDN. However the problem persisted.

Currently I can look at the input, see that the amount of messages received is 0/minute, the data received counters are slowly increasing, and when I look in the apache access logs I see that it responds a HTTP 202 for tens of log messages per second, none of which show up in graylog.

Everything I can see at the HTTP layer works perfectly fine. Each message is acknowledged with a HTTP 202. The Graylog GUI running behind the same proxy, including Apache OIDC (mod authz_oidc) + trusted proxy authentication works fine. Nevertheless, I get an average of **40** log messages an hour in Graylog the last 24 hours, even though the actual amount sent by the servers is around **6,000** an hour.

If I stop the HTTP Gelf input, I immediately see the stream of POSTS log errors.

Here's the full trace7 apache2 output of a proxied request:

```log
[Tue Nov 15 08:41:41.483634 2022] [core:trace5] [pid 2809430:tid 140008686089984] protocol.c(708): [client 52.233.195.70:61163] Request received from client: POST /gelf HTTP/1.1
[Tue Nov 15 08:41:41.483733 2022] [http:trace4] [pid 2809430:tid 140008686089984] http_request.c(436): [client 52.233.195.70:61163] Headers received from client:
[Tue Nov 15 08:41:41.483748 2022] [http:trace4] [pid 2809430:tid 140008686089984] http_request.c(439): [client 52.233.195.70:61163] Host: REDACTED
[Tue Nov 15 08:41:41.483758 2022] [http:trace4] [pid 2809430:tid 140008686089984] http_request.c(439): [client 52.233.195.70:61163] Cache-Control: no-cache
[Tue Nov 15 08:41:41.483767 2022] [http:trace4] [pid 2809430:tid 140008686089984] http_request.c(439): [client 52.233.195.70:61163] Content-Type: application/json; charset=utf-8
[Tue Nov 15 08:41:41.483775 2022] [http:trace4] [pid 2809430:tid 140008686089984] http_request.c(439): [client 52.233.195.70:61163] Content-Length: 455
[Tue Nov 15 08:41:41.483797 2022] [proxy:trace2] [pid 2809430:tid 140008686089984] mod_proxy.c(687): [client 52.233.195.70:61163] AH03461: attempting to match URI path '/gelf' against prefix '/gelf' for proxying
[Tue Nov 15 08:41:41.483809 2022] [proxy:trace1] [pid 2809430:tid 140008686089984] mod_proxy.c(773): [client 52.233.195.70:61163] AH03464: URI path '/gelf' matches proxy handler 'proxy:http://127.0.0.1:12202/gelf'
[Tue Nov 15 08:41:41.483833 2022] [authz_core:debug] [pid 2809430:tid 140008686089984] mod_authz_core.c(845): [client 52.233.195.70:61163] AH01628: authorization result: granted (no directives)
[Tue Nov 15 08:41:41.483844 2022] [core:trace3] [pid 2809430:tid 140008686089984] request.c(310): [client 52.233.195.70:61163] request authorized without authentication by access_checker_ex hook: /gelf
[Tue Nov 15 08:41:41.483860 2022] [proxy_http:trace1] [pid 2809430:tid 140008686089984] mod_proxy_http.c(62): [client 52.233.195.70:61163] HTTP: canonicalising URL //127.0.0.1:12202/gelf
[Tue Nov 15 08:41:41.483895 2022] [proxy:trace2] [pid 2809430:tid 140008686089984] proxy_util.c(2145): [client 52.233.195.70:61163] http: found worker http://127.0.0.1:12202/gelf for http://127.0.0.1:12202/gelf
[Tue Nov 15 08:41:41.483908 2022] [proxy:debug] [pid 2809430:tid 140008686089984] mod_proxy.c(1254): [client 52.233.195.70:61163] AH01143: Running scheme http handler (attempt 0)
[Tue Nov 15 08:41:41.483944 2022] [proxy_http:trace1] [pid 2809430:tid 140008686089984] mod_proxy_http.c(1985): [client 52.233.195.70:61163] HTTP: serving URL http://127.0.0.1:12202/gelf
[Tue Nov 15 08:41:41.483956 2022] [proxy:debug] [pid 2809430:tid 140008686089984] proxy_util.c(2341): AH00942: HTTP: has acquired connection for (127.0.0.1)
[Tue Nov 15 08:41:41.483982 2022] [proxy:debug] [pid 2809430:tid 140008686089984] proxy_util.c(2395): [client 52.233.195.70:61163] AH00944: connecting http://127.0.0.1:12202/gelf to 127.0.0.1:12202
[Tue Nov 15 08:41:41.483998 2022] [proxy:debug] [pid 2809430:tid 140008686089984] proxy_util.c(2604): [client 52.233.195.70:61163] AH00947: connected /gelf to 127.0.0.1:12202
[Tue Nov 15 08:41:41.484036 2022] [proxy:trace2] [pid 2809430:tid 140008686089984] proxy_util.c(2886): HTTP: reusing backend connection 127.0.0.1:41896<>127.0.0.1:12202
[Tue Nov 15 08:41:41.484051 2022] [core:trace6] [pid 2809430:tid 140008686089984] core_filters.c(519): [remote 127.0.0.1:12202] will flush because of FLUSH bucket
[Tue Nov 15 08:41:41.484776 2022] [proxy_http:trace3] [pid 2809430:tid 140008686089984] mod_proxy_http.c(1361): [client 52.233.195.70:61163] Status from backend: 202
[Tue Nov 15 08:41:41.484801 2022] [proxy_http:trace4] [pid 2809430:tid 140008686089984] mod_proxy_http.c(1016): [client 52.233.195.70:61163] Headers received from backend:
[Tue Nov 15 08:41:41.484813 2022] [proxy_http:trace4] [pid 2809430:tid 140008686089984] mod_proxy_http.c(1039): [client 52.233.195.70:61163] content-length: 0
[Tue Nov 15 08:41:41.484826 2022] [proxy_http:trace4] [pid 2809430:tid 140008686089984] mod_proxy_http.c(1039): [client 52.233.195.70:61163] connection: keep-alive
[Tue Nov 15 08:41:41.484841 2022] [proxy_http:trace3] [pid 2809430:tid 140008686089984] mod_proxy_http.c(1724): [client 52.233.195.70:61163] start body send
[Tue Nov 15 08:41:41.484853 2022] [proxy:debug] [pid 2809430:tid 140008686089984] proxy_util.c(2356): AH00943: http: has released connection for (127.0.0.1)
[Tue Nov 15 08:41:41.484874 2022] [http:trace3] [pid 2809430:tid 140008686089984] http_filters.c(1125): [client 52.233.195.70:61163] Response sent with status 202, headers:
[Tue Nov 15 08:41:41.484885 2022] [http:trace5] [pid 2809430:tid 140008686089984] http_filters.c(1134): [client 52.233.195.70:61163] Date: Tue, 15 Nov 2022 07:41:41 GMT
[Tue Nov 15 08:41:41.484895 2022] [http:trace5] [pid 2809430:tid 140008686089984] http_filters.c(1137): [client 52.233.195.70:61163] Server: Apache/2.4.41 (Ubuntu)
[Tue Nov 15 08:41:41.484905 2022] [http:trace4] [pid 2809430:tid 140008686089984] http_filters.c(955): [client 52.233.195.70:61163] content-length: 0
[Tue Nov 15 08:41:41.484935 2022] [proxy_http:trace2] [pid 2809430:tid 140008686089984] mod_proxy_http.c(1870): [client 52.233.195.70:61163] end body send
```

## Context
Running in docker-compose on Ubuntu VPS

## Your Environment

* Graylog Version: docker graylog/graylog:4.3.9
* Elasticsearch Version: docker.elastic.co/elasticsearch/elasticsearch:7.17.2 (because of Log4J, I know it's not officially supported, but it's been running on this version without issues for a long time already.)
* MongoDB Version: docker mongo:5.0
* Operating System: Ubuntu 20.04.4 LTS host

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.