Logstash stops getting events once in 3 days

RAM_NATHAN · May 31, 2021, 11:39am

We are using Logstash 7.4.2. Once in 3-4 days, Logstash stops processing events and its not parsing new events till we restart the service. We see only below error in log

, :body=>"{"error":{"root_cause":[{"type":"action_request_validation_exception","reason":"Validation Failed: 1: id is missing;"}],"type":"action_request_validation_exception","reason":"Validation Failed: 1: id is missing;"},"status":400}"}

My output file content is below

output 
{
	if[eventID]=="002E000A"   
	{
  	 if[update_event]=="true"
           {
            elasticsearch 
            { 
                hosts => ["localhost:9200"]
               document_id => "%{authsid}"
               index =>  "dashboard_write"
               script => "ctx._source.loginCount= params.event.get('loginCount');
                       ctx._source.contractName= params.event.get('contractName');
                        ctx._source.userName= params.event.get('userName');
                         ctx._source.sessionID= params.event.get('sessionID');
                         ctx._source.eventID= params.event.get('eventID');"
              doc_as_upsert => "true"
               action => "update"  
              ilm_enabled => false			   
            }
                 

            }
          else
          {
  elasticsearch 
            {
  hosts => ["localhost:9200"]
               document_id => "%{sessionID}"
               index =>  "dashboard_write"
			   ilm_enabled => false
}

}
  	}

	#We need to still store risk events in ES,as there may be a case of risk events w/o IDP login. IDP login events will delete these records if it extracts the data
        else if[eventID]=="002E0047" or [eventID]=="002E0027"
        {
            elasticsearch
            {
                 hosts => ["localhost:9200"]
               document_id => "%{authsid}"
               index =>  "dashboard_write"
         # this may not append if two applications using different contracts,as that //will have diff sessionID. So in that case check in NAM, ideally you should //get three events in the order 002E0525,002E0514,002E0514 in case of two //application accessed in same session
                script => "ctx._source.riskLevel= params.event.get('riskLevel');
                       ctx._source.eventType= params.event.get('eventType');
                        ctx._source.failedCount= params.event.get('failedCount');"
              doc_as_upsert => "true"
               action => "update"    
ilm_enabled => false			   
            }
  
        }

        else  if[eventID]=="002E0525"
        {
           elasticsearch
            {
               hosts => ["localhost:9200"]
               document_id => "%{sessionID}"
              script => "ctx._source.username = params.event.get('userName');
                       ctx._source.contractName= params.event.get('contractName');
                        ctx._source.deviceID= params.event.get('deviceID');
                         ctx._source.browsername= params.event.get('browserName');
                         ctx._source.devicename= params.event.get('deviceName');"
						 
               doc_as_upsert => "true"

               action => "update"


               index =>  "dashboard_write"
			   ilm_enabled => false
               
          
            }
  
           
        }

        else if[eventID]=="002E000C"
        {
            elasticsearch
            {
               hosts => ["localhost:9200"]
               index =>  "dashboard_write"
               ilm_enabled => false
            }
       
          
        }
    else if[eventID]=="002E001F"
        {
            elasticsearch
            {
               hosts => ["localhost:9200"]
               index =>  "dashboard_write"
               ilm_enabled => false
            }
    
        }
        
        else if[eventID]=="002E0514" or [eventID]=="002E0102" or [eventID]== "002E0029"
        {
		   if[sid]!="null"
		   {
            elasticsearch
            {
               hosts => ["localhost:9200"]
               document_id => "%{sid}"
               index =>  "dashboard_write"
         
                script => "if(ctx._source.appdata== null)
                         {
                           ctx._source.appdata = new ArrayList(); 
                        } 
                        ctx._source.appdata.add(params.event.get('appdata'))"
              doc_as_upsert => "true"

               action => "update"
			   ilm_enabled => false
            }
			}
			else
			{
			elasticsearch
            {
               hosts => ["localhost:9200"]
               index =>  "dashboard_write"
			   ilm_enabled => false
            }
			}
   
       
        }
        
        
        else if[eventID]=="002E0606"
        {
          if [usersCount] 
          {
            elasticsearch
            {
               hosts => ["localhost:9200"]
               index =>  "dashboard_write"
			   ilm_enabled => false
            }

          
          }
        } 
       
}

What could be reason for above error?

Badger · May 31, 2021, 2:56pm

What is the actual exception? Is it BadResponseCodeError?

RAM_NATHAN · June 1, 2021, 4:20am

I found only this error in logs

:body=>"{"error":{"root_cause":[{"type":"action_request_validation_exception","reason":"Validation Failed: 1: id is missing;"}],"type":"action_request_validation_exception","reason":"Validation Failed: 1: id is missing;"},"status":400}"}

RAM_NATHAN · June 3, 2021, 4:27am

Can someone please update?

Badger · June 3, 2021, 3:43pm

Please post the complete error message.

RAM_NATHAN · June 4, 2021, 3:23am

I found only this error as I mentioned in my previous comment. Its continously throwing above same error , but not processing new events. It seems evident that this error is the cause. I just wanted to know what is meaning of this error

Badger · June 4, 2021, 4:00pm

It probably means that one of the items in a bulk request is missing the id field. However, you are not helping us to help you by refusing to show us the entire error message.

RAM_NATHAN · June 5, 2021, 1:30pm

I wish I could share more error. Unfortunately I dont have much error log. I have below in logstash plain log in debug mode

[2021-05-05T18:16:49,820][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:16:54,382][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:17:14,393][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:17:18,594][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:17:19,395][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:17:19,395][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:17:24,398][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:17:24,398][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:17:29,401][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:17:29,401][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:17:34,404][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:17:46,200][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:17:49,412][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:17:49,412][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:17:51,008][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:17:53,821][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:17:54,415][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:17:54,415][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:19,427][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:19,428][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:22,597][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:18:24,430][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:24,431][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:29,433][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:29,434][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:34,436][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:34,436][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:39,439][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:39,439][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:44,441][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:44,441][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:49,444][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:49,444][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:50,202][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:18:54,447][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:54,447][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:18:55,009][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:18:57,823][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:18:59,450][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:18:59,450][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:04,453][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:04,453][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:09,456][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:09,456][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:14,458][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:14,459][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:19,462][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:19,462][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:24,464][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:24,464][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:26,599][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:19:29,466][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:29,466][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:34,469][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:34,469][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:39,471][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:39,471][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:44,474][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:44,474][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:49,477][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:49,477][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:54,205][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}
[2021-05-05T18:19:54,481][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-05-05T18:19:54,481][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-05-05T18:19:59,011][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}

[2021-05-05T18:20:01,823][ERROR][logstash.outputs.elasticsearch][events] Encountered a retryable error. Will Retry with exponential backoff  {:code=>400, :url=>"http://localhost:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"}],\"type\":\"action_request_validation_exception\",\"reason\":\"Validation Failed: 1: id is missing;\"},\"status\":400}"}

Badger · June 5, 2021, 1:51pm

The "Encountered a retryable error. Will Retry ..." tells you that the code is handling a BadResponseCodeError exception.

An elasticsearch bulk request expects something like

POST _bulk
{ "index" : { "_index" : "test", "_id" : "1" } }
{ "field1" : "value1" }

I think this error is telling you it got

POST _bulk
{ "index" : { "_index" : "test", "_id" : "" } }
{ "field1" : "value1" }

RAM_NATHAN · June 7, 2021, 3:03am

Thanks for the clarification. let me try to dig further. One more question

Upon further analysis, Im able to reproduce

POST _bulk
{ "update" : {"_id" : "", "_index" : "dashboard_write"} }
{ "doc" : {"field2" : "value2"},"doc_as_upsert" : true}

This issue is happening only in case of Update/Delete with id field is empty or missing

"error": {
    "root_cause": [
      {
        "type": "action_request_validation_exception",
        "reason": "Validation Failed: 1: id is missing;"
      }
    ],
    "type": "action_request_validation_exception",
    "reason": "Validation Failed: 1: id is missing;"
  },
  "status": 400

After this error , logstash stops processing other events and retrying multiple times to parse failed events. Can we handle this error somehow and makes logstash works fine?

Now we are restarting logstash to fix this

Badger · June 7, 2021, 5:11pm

logstash has an at-least-once delivery model, so certain problems can cause it to hang forever. There is more discussion on this here and here. Changing that would require code changes.

system · July 5, 2021, 5:12pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Missing event while report to elastic search Logstash	1	430	May 14, 2020
How to find missing logs in Logstash? Logstash	1	1374	August 3, 2018
I can't parse my logs anymore Logstash	7	542	August 7, 2018
Could not index event to Elasticsearch. "reason"=>"if _id is specified it must not be empty"} Logstash	11	7625	June 25, 2020
New event not inserted Logstash	8	746	November 26, 2020

Logstash stops getting events once in 3 days

Related topics