Hi,
We are running logstash on Kubernetes (deployed using logstash helm chart from elastic). Logstash periodically hangs and stops processing data with no errors. It uses filebeat input and sends data to elasticsearch. I am attaching debug level and trace level logs but I don't see anything indicating a reason for hang in the logs. I also checking logstash metrics using logstash APIs (Node stats, Node Info APIs) everything seems to be normal I don't see any errors. I also enabled DLQ to see if any bad data is causing logstash to hang but DLQ is empty. It has enough resources. We have 8 pods and each pod has 12 workers, bulk size is 4096, Heap - 10gb, ram- 12gb. No errors on Elasticsearch also. ES has enough capacity to accept data from logatsh. It will work again only if we restart. Can someone please help me with this issue? am I missing something here? I have been scratching my head with this issue for a while, any help or suggestion is highly appreciated.
filebeat and logstash version - 7.9.3
Debug logs:
[2021-02-05T07:05:50,780][DEBUG][org.logstash.beats.ConnectionHandler][main] 884460aa: batches pending: true
[2021-02-05T07:05:53,405][DEBUG][org.logstash.beats.ConnectionHandler][main] 4f6b0df8: reader and writer are idle, closing remote connection
[2021-02-05T07:05:53,475][DEBUG][org.logstash.beats.ConnectionHandler][main] 17aaab9e: batches pending: true
[2021-02-05T07:05:54,110][DEBUG][org.logstash.beats.ConnectionHandler][main] 8cff884d: batches pending: true
[2021-02-05T07:06:15,369][DEBUG][org.logstash.beats.ConnectionHandler][main] babac4ef: batches pending: true
[2021-02-05T07:06:21,704][DEBUG][org.logstash.beats.ConnectionHandler][main] b8f4c8f7: batches pending: true
[2021-02-05T07:06:28,794][DEBUG][org.logstash.beats.ConnectionHandler][main] a37e2da3: batches pending: true
[2021-02-05T07:06:29,834][DEBUG][org.logstash.beats.ConnectionHandler][main] 455c7c87: batches pending: true
[2021-02-05T07:06:42,113][DEBUG][org.logstash.beats.ConnectionHandler][main] 8cff884d: batches pending: true
[2021-02-05T07:06:50,779][DEBUG][org.logstash.beats.ConnectionHandler][main] b5569bb1: reader and writer are idle, closing remote connection
[2021-02-05T07:06:50,779][DEBUG][org.logstash.beats.ConnectionHandler][main] 6997090c: reader and writer are idle, closing remote connection
Trace logs
{"log":"[2021-02-25T01:44:01,890][TRACE][org.logstash.beats.BeatsParser][main] Transition, from: READ_FRAME_TYPE, to: READ_JSON_HEADER, requiring 8 bytes\n","stream":"stdout","time":"2021-02-25T01:44:01.890754938Z"}
{"log":"[2021-02-25T01:44:01,890][TRACE][org.logstash.beats.BeatsParser][main] Running: READ_JSON_HEADER\n","stream":"stdout","time":"2021-02-25T01:44:01.890759845Z"}
{"log":"[2021-02-25T01:44:01,890][TRACE][org.logstash.beats.BeatsParser][main] Transition, from: READ_JSON_HEADER, to: READ_JSON, requiring 2068 bytes\n","stream":"stdout","time":"2021-02-25T01:44:01.890765545Z"}
{"log":"[2021-02-25T01:44:01,890][TRACE][org.logstash.beats.BeatsParser][main] Running: READ_JSON\n","stream":"stdout","time":"2021-02-25T01:44:01.890769402Z"}
{"log":"[2021-02-25T01:44:01,890][TRACE][org.logstash.beats.BeatsParser][main] Sending batch size: 10, windowSize: 10 , seq: 10\n","stream":"stdout","time":"2021-02-25T01:44:01.890772744Z"}
{"log":"[2021-02-25T01:44:01,890][TRACE][org.logstash.beats.BeatsParser][main] Transition, from: READ_JSON, to: READ_HEADER, requiring 1 bytes\n","stream":"stdout","time":"2021-02-25T01:44:01.890776553Z"}
{"log":"[2021-02-25T01:44:01,890][TRACE][org.logstash.beats.BeatsParser][main] Transition, from: READ_HEADER, to: READ_HEADER, requiring 1 bytes\n","stream":"stdout","time":"2021-02-25T01:44:01.890780495Z"}
{"log":"[2021-02-25T01:44:01,890][DEBUG][org.logstash.beats.BeatsHandler][main] [local: ip:5044, remote: ip:33148] Received a new payload\n","stream":"stdout","time":"2021-02-25T01:44:01.890784681Z"}
{"log":"[2021-02-25T01:44:01,890][DEBUG][org.logstash.beats.BeatsHandler][main] [local: ip:5044, remote:ip:33148] Sending a new message for the listener, sequence: 1\n","stream":"stdout","time":"2021-02-25T01:44:01.890788886Z"}
{"log":"[2021-02-25T01:44:01,890][DEBUG][org.logstash.beats.BeatsHandler][main] [local: ip:5044, remote: ip:33148] Sending a new message for the listener, sequence: 2\n","stream":"stdout","time":"2021-02-25T01:44:01.891040359Z"}
{"log":"[2021-02-25T01:44:01,891][DEBUG][org.logstash.beats.BeatsHandler][main] [local: ip:5044, remote: ip:33148] Sending a new message for the listener, sequence: 3\n","stream":"stdout","time":"2021-02-25T01:44:01.891192425Z"}
{"log":"[2021-02-25T01:44:01,891][DEBUG][org.logstash.beats.BeatsHandler][main] [local: ip:5044, remote: ip:33148] Sending a new message for the listener, sequence: 4\n","stream":"stdout","time":"2021-02-25T01:44:01.891318493Z"}
{"log":"[2021-02-25T01:44:01,891][DEBUG][org.logstash.beats.BeatsHandler][main] [local: ip:5044, remote: ip:33148] Sending a new message for the listener, sequence: 5\n","stream":"stdout","time":"2021-02-25T01:44:01.891453701Z"}
{"log":"[2021-02-25T01:44:01,891][DEBUG][org.logstash.beats.BeatsHandler][main] [local: ip:5044, remote: ip:33148] Sending a new message for the listener, sequence: 6\n","stream":"stdout","time":"2021-02-25T01:44:01.891577583Z"}
{"log":"[2021-02-25T01:44:01,942][DEBUG][logstash.filters.grok ][main] Running grok filter {:event=\u003e#\u003cLogStash::Event:0x559b1c88\u003e}\n","stream":"stdout","time":"2021-02-25T01:44:01.942967337Z"}
{"log":"[2021-02-25T01:44:01,943][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Grok: adding tag {\"tag\"=\u003e\"service-logs\"}\n","stream":"stdout","time":"2021-02-25T01:44:01.943108881Z"}
{"log":"[2021-02-25T01:44:01,943][DEBUG][logstash.filters.grok ][main] Event now: {:event=\u003e#\u003cLogStash::Event:0x559b1c88\u003e}\n","stream":"stdout","time":"2021-02-25T01:44:01.943114819Z"}
{"log":"[2021-02-25T01:44:01,943][DEBUG][logstash.filters.grok ][main] Running grok filter {:event=\u003e#\u003cLogStash::Event:0x2552621d\u003e}\n","stream":"stdout","time":"2021-02-25T01:44:01.943118389Z"}
{"log":"[2021-02-25T01:44:01,943][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Grok: adding tag {\"tag\"=\u003e\"service-logs\"}\n","stream":"stdout","time":"2021-02-25T01:44:01.943176755Z"}
{"log":"[2021-02-25T01:44:01,943][DEBUG][logstash.filters.grok ][main] Event now: {:event=\u003e#\u003cLogStash::Event:0x2552621d\u003e}\n","stream":"stdout","time":"2021-02-25T01:44:01.943206083Z"}
{"log":"[2021-02-25T01:44:01,943][DEBUG][logstash.filters.grok ][main] Running grok filter {:event=\u003e#\u003cLogStash::Event:0x5283d02e\u003e}\n","stream":"stdout","time":"2021-02-25T01:44:01.943211876Z"}
{"log":"[2021-02-25T01:44:01,943][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Mutate: adding value to field {\"field\"=\u003e\"service\", \"value\"=\u003e[\"%{[kubernetes][labels][version]}\"]}\n","stream":"stdout","time":"2021-02-25T01:44:01.944018954Z"}
{"log":"[2021-02-25T01:44:01,943][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Mutate: adding value to field {\"field\"=\u003e\"service\", \"value\"=\u003e[\"%{[kubernetes][labels][version]}\"]}\n","stream":"stdout","time":"2021-02-25T01:44:01.94403852Z"}
\n","stream":"stdout","time":"2021-02-25T01:44:01.944271289Z"}
{"log":"[2021-02-25T01:44:01,944][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Mutate: adding value to field {\"field\"=\u003e\"env\", \"value\"=\u003e[\”qa\”]}\n”,”stream":"stdout","time":"2021-02-25T01:44:01.944317895Z"}
{"log":"[2021-02-25T01:44:01,944][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Mutate: adding value to field {\"field\"=\u003e\"env\", \"value\"=\u003e[\"qa\"]}\n","stream":"stdout","time":"2021-02-25T01:44:01.944324831Z"}
{"log":"[2021-02-25T01:44:01,944][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Mutate: adding value to field {\"field\"=\u003e\"env\", \"value\"=\u003e[\"qa"]}\n","stream":"stdout","time":"2021-02-25T01:44:01.94449618Z"}
{"log":"[2021-02-25T01:44:01,944][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Mutate: adding value to field {\"field\"=\u003e\"env\", \"value\"=\u003e[\"qa\"]}\n","stream":"stdout","time":"2021-02-25T01:44:01.944532063Z"}
{"log":"[2021-02-25T01:44:01,944][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Mutate: adding value to field {\"field\"=\u003e\"env\", \"value\"=\u003e[\"qa\"]}\n","stream":"stdout","time":"2021-02-25T01:44:01.944537823Z"}
{"log":"[2021-02-25T01:44:01,944][DEBUG][logstash.util.decorators ][main] filters/LogStash::Filters::Mutate: adding value to field {\"field\"=\u003e\"env\", \"value\"=\u003e[\"qa\"]}\n","stream":"stdout","time":"2021-02-25T01:44:01.944567966Z"}
{"log":"[2021-02-25T01:44:01,964][TRACE][org.logstash.beats.ConnectionHandler][main] d17927ce: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:01.964659221Z"}
{"log":"[2021-02-25T01:44:01,964][DEBUG][org.logstash.beats.ConnectionHandler][main] d17927ce: batches pending: true\n","stream":"stdout","time":"2021-02-25T01:44:01.964994299Z"}
{"log":"[2021-02-25T01:44:02,018][TRACE][org.logstash.beats.ConnectionHandler][main] 10670778: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.018478248Z"}
{"log":"[2021-02-25T01:44:02,019][TRACE][org.logstash.beats.ConnectionHandler][main] ba37d081: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.019710473Z"}
{"log":"[2021-02-25T01:44:02,021][TRACE][org.logstash.beats.ConnectionHandler][main] 87a7f754: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.021185259Z"}
{"log":"[2021-02-25T01:44:02,022][TRACE][org.logstash.beats.ConnectionHandler][main] e2b69fe9: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.022671898Z"}
{"log":"[2021-02-25T01:44:02,023][TRACE][org.logstash.beats.ConnectionHandler][main] f9ce1cf4: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.023832198Z"}
{"log":"[2021-02-25T01:44:02,025][TRACE][org.logstash.beats.ConnectionHandler][main] 2e07f8d7: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.025326283Z"}
{"log":"[2021-02-25T01:44:02,167][TRACE][org.logstash.beats.ConnectionHandler][main] 8504a7ba: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.167150128Z"}
{"log":"[2021-02-25T01:44:02,172][TRACE][org.logstash.beats.ConnectionHandler][main] cf43a099: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.172281441Z"}
{"log":"[2021-02-25T01:44:02,173][TRACE][org.logstash.beats.ConnectionHandler][main] fbc87fb6: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.173686724Z"}
{"log":"[2021-02-25T01:44:02,177][TRACE][org.logstash.beats.ConnectionHandler][main] ece63d13: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.177818582Z"}
{"log":"[2021-02-25T01:44:02,179][TRACE][org.logstash.beats.ConnectionHandler][main] e8294343: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.179194212Z"}
{"log":"[2021-02-25T01:44:02,180][TRACE][org.logstash.beats.ConnectionHandler][main] 44e61d03: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.180507313Z"}
{"log":"[2021-02-25T01:44:02,258][TRACE][org.logstash.beats.ConnectionHandler][main] e79126fa: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.258347827Z"}
{"log":"[2021-02-25T01:44:02,258][DEBUG][org.logstash.beats.ConnectionHandler][main] e79126fa: batches pending: true\n","stream":"stdout","time":"2021-02-25T01:44:02.25881117Z"}
{"log":"[2021-02-25T01:44:02,258][DEBUG][org.logstash.beats.ConnectionHandler][main] e79126fa: batches pending: true\n","stream":"stdout","time":"2021-02-25T01:44:02.25882012Z"}
{"log":"[2021-02-25T01:44:02,302][TRACE][org.logstash.beats.ConnectionHandler][main] 72fec9ee: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.30237665Z"}
{"log":"[2021-02-25T01:44:02,306][DEBUG][org.logstash.beats.ConnectionHandler][main] 72fec9ee: batches pending: true\n","stream":"stdout","time":"2021-02-25T01:44:02.306387405Z"}
{"log":"[2021-02-25T01:44:02,334][TRACE][org.logstash.beats.ConnectionHandler][main] 971ceda0: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.334648853Z"}
{"log":"[2021-02-25T01:44:02,335][TRACE][org.logstash.beats.ConnectionHandler][main] 31c69ef9: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.336124277Z"}
{"log":"[2021-02-25T01:44:02,337][TRACE][org.logstash.beats.ConnectionHandler][main] ddef05ab: channel activated\n","stream":"stdout","time":"2021-02-25T01:44:02.337392183Z"}