Unable to authenticate user [logstash_internal] for REST request [/bulk]

oscardoudou · April 6, 2023, 3:33am

logstash 7.17.9


[2023-04-05T22:50:02,837][ERROR][logstash.outputs.elasticsearch][main] Encountered a retryable error (will retry with exponential backoff) {:code=>401, :url=>"http://server:9200/_bulk", :content_length=>63205, :body=>"{\"error\":{\"root_cause\":[{\"type\":\"security_exception\",\"reason\":\"unable to authenticate user [logstash_internal] for REST request [/_bulk]\",\"header\":{\"WWW-Authenticate\":\"Basic realm=\\\"security\\\" charset=\\\"UTF-8\\\"\"}}],\"type\":\"security_exception\",\"reason\":\"unable to authenticate user [logstash_internal] for REST request [/_bulk]\",\"header\":{\"WWW-Authenticate\":\"Basic realm=\\\"security\\\" charset=\\\"UTF-8\\\"\"}},\"status\":401}"}

[2023-04-05T22:50:02,837][DEBUG][org.apache.http.impl.conn.PoolingHttpClientConnectionManager][main] Connection [id: 15][route: {}->http://server:9200] can be kept alive indefinitely

[2023-04-05T22:50:02,837][DEBUG][org.apache.http.impl.conn.DefaultManagedHttpClientConnection][main] http-outgoing-15: set socket timeout to 0

[2023-04-05T22:50:02,837][DEBUG][org.apache.http.impl.conn.PoolingHttpClientConnectionManager][main] Connection released: [id: 15][route: {}->http://server:9200][total available: 3; route allocated: 3 of 100; total allocated: 3 of 1000]

[2023-04-05T22:50:02,837][ERROR][logstash.outputs.elasticsearch][main] Encountered a retryable error (will retry with exponential backoff) {:code=>401, :url=>"http://server:9200/_bulk", :content_length=>57598, :body=>"{\"error\":{\"root_cause\":[{\"type\":\"security_exception\",\"reason\":\"unable to authenticate user [logstash_internal] for REST request [/_bulk]\",\"header\":{\"WWW-Authenticate\":\"Basic realm=\\\"security\\\" charset=\\\"UTF-8\\\"\"}}],\"type\":\"security_exception\",\"reason\":\"unable to authenticate user [logstash_internal] for REST request [/_bulk]\",\"header\":{\"WWW-Authenticate\":\"Basic realm=\\\"security\\\" charset=\\\"UTF-8\\\"\"}},\"status\":401}"}

[2023-04-05T22:50:03,949][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}

[2023-04-05T22:50:03,949][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}

[2023-04-05T22:50:04,071][DEBUG][logstash.outputs.file ][main] Starting flush cycle

[2023-04-05T22:50:04,071][DEBUG][logstash.outputs.file ][main] Flushing file {:path=>"/tmp/yz_test", :fd=>#<IOWriter:0x7be556d2 @active=true, @io=#<File:/tmp/yz_test>>}

[2023-04-05T22:50:06,071][DEBUG][logstash.outputs.file ][main] Starting flush cycle

[2023-04-05T22:50:06,071][DEBUG][logstash.outputs.file ][main] Flushing file {:path=>"/tmp/yz_test", :fd=>#<IOWriter:0x7be556d2 @active=true, @io=#<File:/tmp/yz_test>>}

[2023-04-05T22:50:07,123][WARN ][org.logstash.execution.ShutdownWatcherExt] {"inflight_count"=>391, "stalling_threads_info"=>{"other"=>[{"thread_id"=>58, "name"=>"[main]<beats", "current_call"=>"[...]/vendor/bundle/jruby/2.5.0/gems/logstash-input-beats-6.5.0-java/lib/logstash/inputs/beats.rb:263:in `run'"}], ["LogStash::Filters::Grok", {"match"=>{"message"=>"%{TIMESTAMP_ISO8601:timestamp} +%{WORD:loglevel} +%{NUMBER:PID} --- \\[%{DATA:thread}\\] %{DATA:class} +: %{GREEDYDATA:logmessage}"}, "id"=>"02b8f13bb22504e5013a38110f968204c7e0a3eabdab3ae7af45d0b7714586a3"}]=>[{"thread_id"=>51, "name"=>"[main]>worker0", "current_call"=>"[...]/vendor/bundle/jruby/2.5.0/gems/stud-0.0.23/lib/stud/interval.rb:89:in `sleep'"}, {"thread_id"=>52, "name"=>"[main]>worker1", "current_call"=>"[...]/vendor/bundle/jruby/2.5.0/gems/stud-0.0.23/lib/stud/interval.rb:89:in `sleep'"}, {"thread_id"=>53, "name"=>"[main]>worker2", "current_call"=>"[...]/vendor/bundle/jruby/2.5.0/gems/stud-0.0.23/lib/stud/interval.rb:89:in `sleep'"}, {"thread_id"=>54, "name"=>"[main]>worker3", "current_call"=>"[...]/vendor/bundle/jruby/2.5.0/gems/stud-0.0.23/lib/stud/interval.rb:89:in `sleep'"}]}}

[2023-04-05T22:50:08,072][DEBUG][logstash.outputs.file ][main] Starting flush cycle

elasticsearch 7.17.9


[2023-04-05T22:53:15,101][WARN ][o.e.x.s.a.RealmsAuthenticator] [server.cargosphere.co] Authentication to realm default_native failed - Password authentication failed for logstash_internal

[2023-04-05T22:53:15,101][WARN ][o.e.x.s.a.RealmsAuthenticator] [server.cargosphere.co] Authentication to realm default_native failed - Password authentication failed for logstash_internal

[2023-04-05T22:53:15,101][WARN ][o.e.x.s.a.RealmsAuthenticator] [server.cargosphere.co] Authentication to realm default_native failed - Password authentication failed for logstash_internal

initially I thought it is bc password unmatched, so I update with

curl -u elasticadmin:elasticadmin -X POST "http://us2vml168044:9200/_security/user/logstash_internal/_password" -H 'Content-Type: application/json' -d'
{
  "password": "yourpassword"
}'

but when I call /authenticate endpoint, user logstash_internal seems just fine

[yz@server ~]$ curl -u logstash_internal:yourpassword -X GET "http://server:9200/_xpack/security/_authenticate"
{"username":"logstash_internal","roles":["logstash_writer"],"full_name":null,"email":null,"metadata":{},"enabled":true,"authentication_realm":{"name":"default_native","type":"native"},"lookup_realm":{"name":"default_native","type":"native"},"authentication_type":"realm"}

I'm kind of lost. How should I fix this?
The only fishy thing I noticed is that:
Initially I used a non-existing template path in output section of pipeline conf, so I changed it to

output {
        elasticsearch {
                hosts => "${ES_HOST}:${ES_PORT}"
                user => "${ES_USER}"
                password => "${ES_PASS}"
                index => "logstash-urs-log"
                template => "/path/to/existing/template.json"
                template_name => 'urs-log'
        }
}

and make sure all pipelines referenciingES_PASS ES_USER in a env file
Then I restarted the logstash service without any hang.
But from then on, everytime I systemctl restart logstash after updating password of logstash_internal user in ES, prompts never returns, it just hang there. (Personally I feel like restart shouldn't be necessary for user credential update, but I run out of solution just did it anyway )
Does this failed-to-restart have thing to do with TimeoutStopSec=infinity in service unit file? I tried to send SIGHUP to logstash process, but get Operation not permitted. I guess this is default policy to prevent data loss. which make me wonder even if I fix the authenticate issue, how should I restart without data loss or stop the service by force is the only way?

leandrojmp · April 6, 2023, 4:31am

Hello,

Can you provide a little more context about your issue? It is not clear and you shared a couple of debut logs without explaining what the issue is.

The warning logs you shared indicates a password authentication error, you need to check the user and password.

If you are using the username and password from environment variables and you change the password in Elasticsearch, you need to change it in the environment variable and restart Logstash as the variables are only loaded when Logstash start, this is described in the documentation.

Environment variables are immutable. If you update the environment variable, you’ll have to restart Logstash to pick up the updated value.

oscardoudou · April 6, 2023, 5:35am

Sorry about lack of context.
I'm trying to send log from a file to elasticsearch.
The logstash input is currently read from a file and output event to elasticsearch index via an index template.
I could see index_template created in kibana(only a skeleton, no mapping though), but corresponding index wasn't created.

Recalled process:

add the first version of pipeline.conf with hardcoded password

output {
        elasticsearch {
                hosts => "server:9200"
                user => "logstash_internal"
                password => "changeme"
                template => "/path/to/non-existing-template.json"
                template_name => 'urs-log'
...

observation1: see logstash log complaining about the template.json path provided in output is not found(not sure if I restart logstash at this point, probably not, I guess it can detect change?)
2. fix path issue to index template & restart logstash(definitely restart).
observation 2: not found error is gone, but seeing the Unable to authenticate issue in logstash and Password authentication failed in elasticsearch log

Realize multiple pipeline using same_user but different password

Unify password

changing hardcoded the password in output section to env var
update logstash_internal password in ES
observation3: elasticsearch log still shows Password authentication failed,
can't restart logstash, prompt never return to me , failed to send SIGHUP to process due to Operation not permitted.

pipeline.conf final version

input {
        file {
                path => "/var/log/spring-boot/universal-rate-service-converter/app.log"
                start_position => "beginning"
                sincedb_path => "/dev/null"
        }
        beats {
                port => 5044
        }
}
filter {
    grok {
        match => { "message" => "" }
    }
}
output {
        elasticsearch {
                hosts => "${ES_HOST}:${ES_PORT}"
                user => "${ES_USER}"
                password => "${ES_PASS}"
                index => "logstash-urs-log"
                template => "/etc/logstash/conf.d/urs-log.json"
                template_name => 'urs-log'
        }
}

I'm pretty sure I didn't change the env file value, I do add more reference to them in my new pipeline.conf . So technically, this shouldn't need to restart, correct?

But it seem to me that logstash stuck at a state that still reference old password is the only way to explain this situation. Probably also why my index_template is created, but there is not mapping in it, because path is in valid?

So my concern now is how can I restart the logstash without causing data loss.

leandrojmp · April 6, 2023, 12:59pm

How are you running Logstash? As a service?

If you changed the password and you are using this password through environment variables, you need to change the value in for the variables and you need to restart Logstash, without a restart Logstash will keep using the old value.

can't restart logstash, prompt never return to me , failed to send SIGHUP to process due to Operation not permitted .

If you didn't restart logstash, then it still uses the old value, also, this Operation not permitted message doesn't seem to be from Logstash, but from your Operating System regarding some permissions you have. Did you send the SIGHUP as the logstash user or root?

Not sure you can, what is your current error in your logs? Please share then, except the DEBUG lines, they do not help on this case and only make everything hard to understand.

If you are still getting Authorization errors this mean that the password is still wrong, you need to restart Logstash, if a SIGHUP doesn't work you need to force the restart and this may lead to data loss.

system · May 4, 2023, 1:00pm

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