Logstash: Changing the log level via the API does not work.

[jakelandis]

As described at https://www.elastic.co/guide/en/logstash/current/logging.html#_logging_apis , it not actually possible to change the log level via the API.

To reproduce:
create a configuration file:

input { stdin{} }
filter {}
output { stdout {codec => rubydebug }}

Add the following to config/log4j2.properties

logger.c.name = logstash.config.source.local.configpathloader
logger.c.level = debug

Run logstash with config reload (to help illustrate the issue)
bin/logstash --config.reload.automatic -f ~/config/test.conf

You should see periodic messages like:
[2017-05-31T09:10:31,064][DEBUG][logstash.config.source.local.configpathloader] Reading config file ...
(as expected)

Query the API

curl -XGET 'localhost:9600/_node/logging?pretty'
...
"logstash.config.source.local.configpathloader" : "DEBUG",

(as expected)

Now attempt to change it INFO via the API

curl -XPUT 'localhost:9600/_node/logging?pretty' -H 'Content-Type: application/json' -d'
{
   "logger.logstash.config.source.local.configpathloader":"INFO"
}
'
>   "acknowledged" : true

(as expected)

Query again...

curl -XGET 'localhost:9600/_node/logging?pretty'
...
    "logstash.config.source.local.configpathloader" : "DEBUG",
...

(this is the bug)
nothing changed.

and the debug message continues

[DEBUG][logstash.config.source.local.configpathloader] Reading config file ...
continues. 

(so the logger is actually in debug still)

This issue is not isolated to overriding pre-existing values in the log4j2.properties (I only am using that for an example)

Another way to reproduce:

Removing any custom loggers from the log4j2.properties

Query the API

curl -XGET 'localhost:9600/_node/logging?pretty'
...    
"logstash.config.source.local.configpathloader" : "INFO",

Now attempt to change it to DEBUG

curl -XPUT 'localhost:9600/_node/logging?pretty' -H 'Content-Type: application/json' -d'
{
   "logger.logstash.config.source.local.configpathloader":"DEBUG"
}
'
>   "acknowledged" : true

(as expected)

Query the API

curl -XGET 'localhost:9600/_node/logging?pretty'
...    
"logstash.config.source.local.configpathloader" : "INFO",

...but no change

Note - I have not tested the root logger.

[jakelandis]

I have some early thoughts and dirty prototype for the fix. I hope to get to this soon.

[jakelandis]

The root cause of this issue is that log4j2 context we initialize is different from the log4j2 context that we are setting. I was able to prove this by stepping through the code and comparing the hash codes _(within same JVM instance)_ of the LoggerContext in use during Configurator.initialize and the LoggerContext in use by the Configurator.setLevel method.

The Configurator.initialize ends up calling:

factory.getContext(FQCN, loader, externalContext, false, configLocation, name);

Configurator.setLevel ends up ends up calling

 factory.getContext(FQCN, null, null, currentContext, null, null);

Notice the config location is null when called by Configurator.setLevel. This results in initializing one object, and setting the level on another.

Per Log4j2's documentation

You can set a logger’s level with the class Configurator from Log4j Core. Be aware that the Configurator class is not part of the public API.

This almost seems like a bug in Log4j2, such that there does not appear to be a graceful way to both initialize and then reconfigure. However, since reconfiguration from the code isn't supported, that makes the case for a bug difficult to make.

Perhaps this worked in a prior version of log4j2 ?

To fix this we basically need to replicate the Configurator.setLevel public method found in the org.apache.logging.log4j.core.config package, but using the context we established in Ruby at startup, NOT the one discovered via LoggerContext.getContext(false) via Configurator.setLevel _which results in the wrong context_

I have the fix coded _(~20 lines ported from log4j2 Java methods)_, but still working through the tests.