pulsar [fix][broker] Fix dynamic change the log4j2 log level

Motivation

I switched the log level from info to debug by the pulsar.log.level and pulsar.log.root.level values in the log4j2.yaml file, but there is no debug log for pulsar in the console.

The following is the log4j2 debug log(LOG4J_DEBUG=true bin/pulsar standalone -nfw):

DEBUG StatusLogger Watching configuration '/Users/zixuan/repo/pulsar/conf/log4j2.yaml' for lastModified Sat Feb 03 18:07:39 CST 2024 (1706954859387)
DEBUG StatusLogger Apache Log4j Core 2.18.0 initializing configuration YamlConfiguration[location=/Users/zixuan/repo/pulsar/conf/log4j2.yaml]
...
DEBUG StatusLogger Completed parsing configuration
DEBUG StatusLogger Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property].
DEBUG StatusLogger createProperty(name="pulsar.log.dir", value="logs", Configuration(pulsar))
DEBUG StatusLogger Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property].
DEBUG StatusLogger createProperty(name="pulsar.log.file", value="pulsar.log", Configuration(pulsar))
DEBUG StatusLogger Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property].
DEBUG StatusLogger createProperty(name="pulsar.log.immediateFlush", value="false", Configuration(pulsar))
DEBUG StatusLogger Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property].
DEBUG StatusLogger createProperty(name="pulsar.log.appender", value="RoutingAppender", Configuration(pulsar))
DEBUG StatusLogger Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property].
DEBUG StatusLogger createProperty(name="pulsar.log.root.level", value="debug", Configuration(pulsar))
DEBUG StatusLogger Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property].
DEBUG StatusLogger createProperty(name="pulsar.log.level", value="debug", Configuration(pulsar))
DEBUG StatusLogger Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property].
DEBUG StatusLogger createProperty(name="pulsar.routing.appender.default", value="Console", Configuration(pulsar))
DEBUG StatusLogger Building Plugin[name=properties, class=org.apache.logging.log4j.core.config.PropertiesPlugin].
DEBUG StatusLogger configureSubstitutor(={pulsar.log.dir=logs, pulsar.log.file=pulsar.log, pulsar.log.immediateFlush=false, pulsar.log.appender=RoutingAppender, pulsar.log.root.level=debug, pulsar.log.level=debug, pulsar.routing.appender.default=Console}, Configuration(pulsar))
...
DEBUG StatusLogger Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
DEBUG StatusLogger createAppenderRef(ref="RoutingAppender", level="INFO", Filter=null)
...
DEBUG StatusLogger Started configuration YamlConfiguration[location=/Users/zixuan/repo/pulsar/conf/log4j2.yaml] OK.

You can see the RoutingAppender uses the INFO level in the above log.

In the bin/pulsar, we use the system properties to set the log4j2 log level, and it looks higher priority than the log4j2.yaml file.

When I remove the PULSAR_LOG_LEVEL and PULSAR_LOG_ROOT_LEVEL variables in the bin/pulsar, and then change the log level from info to debug in the log4j2.yaml file, it works fine.

Modifications

When the PULSAR_LOG_LEVEL or PULSAR_LOG_ROOT_LEVEL is set by the user, we set the log level by system properties.

Note: This way doesn't support changing the log level by the log4j2.yaml.

Documentation

[ ] doc
[ ] doc-required
[x] doc-not-needed
[ ] doc-complete

Feb 03 '24 15:02 nodece

There has been performance regressions when this has been changed in the past. I'll review next week.

Feb 03 '24 16:02 lhotari

Although I think this change is somewhat reasonable, it should be a breaking change that we may discuss first on dev@.

If the log4j2.yaml log level is different from the system properties, this is a breaking change.

Usually, when the user changes the log level by the log4j2.yaml file, this change will not take effect because we are using system properties to set the log level. Therefore, the user will set the PULSAR_LOG_LEVEL or PULSAR_LOG_ROOT_LEVEL variable to change the log level, and now it doesn't seem to have any breaking changes.

Feb 03 '24 16:02 nodece

There has been performance regressions when this has been changed in the past. I'll review next week.

When using the DEBUG level, there are performance issues. This is the cost of using the DEBUG level.

More context:

https://github.com/apache/pulsar/pull/12941
https://github.com/apache/pulsar/pull/8908

Feb 03 '24 17:02 nodece

In the bin/pulsar, we use the system properties to set the log4j2 log level, and it looks higher priority than the log4j2.yaml file.

When I remove the PULSAR_LOG_LEVEL and PULSAR_LOG_ROOT_LEVEL variables in the bin/pulsar, and then change the log level from info to debug in the log4j2.yaml file, it works fine.

If you are modifying log4j2.yaml directly, just go ahead and use a completely different property name than pulsar.log.root.level and pulsar.log.level. You need to use PULSAR_LOG_LEVEL and PULSAR_LOG_ROOT_LEVEL to change the levels when using the default log4j2.yaml.

Feb 05 '24 06:02 lhotari

In the bin/pulsar, we use the system properties to set the log4j2 log level, and it looks higher priority than the log4j2.yaml file. When I remove the PULSAR_LOG_LEVEL and PULSAR_LOG_ROOT_LEVEL variables in the bin/pulsar, and then change the log level from info to debug in the log4j2.yaml file, it works fine.

If you are modifying log4j2.yaml directly, just go ahead and use a completely different property name than pulsar.log.root.level and pulsar.log.level.

This is a workaround, but I don't want to change the pulsar.log.root.level and pulsar.log.level names, and I prefer to change the value.

You need to use PULSAR_LOG_LEVEL and PULSAR_LOG_ROOT_LEVEL to change the levels when using the default log4j2.yaml.

This way requires restarting the broker.

Feb 05 '24 07:02 nodece

This is a workaround, but I don't want to change the pulsar.log.root.level and pulsar.log.level names, and I prefer to change the value.

I provided clear reasons why I'm not supporting this change. You have a workaround by providing a custom log4j2.yaml. There's a way to improve the experience for everyone by documenting this.

This way requires restarting the broker.

That is how it is currently designed. The environment variables are used as the source of truth in the default configuration of Pulsar. If you want to change that, you can always use your own log4j2.yaml. Is that a problem for you? We could always change the default way of configuring things, but that would have to be consistent across all usages. Please check my previous comment for details.

Feb 05 '24 07:02 lhotari

Thanks for your explanation!

Usually, we only need to modify the property from the log4j2.yaml, I hope this is an out-of-the-box feature.

  Properties:
    Property:
      - name: "pulsar.log.dir"
        value: "logs"
      - name: "pulsar.log.file"
        value: "pulsar.log"
      - name: "pulsar.log.immediateFlush"
        value: "false"
      - name: "pulsar.log.appender"
        value: "RoutingAppender"
      - name: "pulsar.log.root.level"
        value: "info"
      - name: "pulsar.log.level"
        value: "info"
      - name: "pulsar.routing.appender.default"
        value: "Console"

As you said, I need to make a new log4j2.yaml instead of Pulsar's log4j2.yaml, this will increase the cost of operation and maintenance personnel.

Feb 05 '24 07:02 nodece

As you said, I need to make a new log4j2.yaml instead of Pulsar's log4j2.yaml, this will increase the cost of operation and maintenance personnel.

You didn't seem to read my arguments why I'm not supporting this change. Please go back to read https://github.com/apache/pulsar/pull/22017#pullrequestreview-1861988153 carefully. I'm happy to explain in more detail.

Feb 05 '24 07:02 lhotari

As you said, I need to make a new log4j2.yaml instead of Pulsar's log4j2.yaml, this will increase the cost of operation and maintenance personnel.

What is your real use case if this is a problem? It's not a major change that you need to do. run a replace "pulsar.log." -> "my.log." and you are done. :) Is that a problem for you?

Feb 05 '24 07:02 lhotari

There's a way to improve the experience for everyone by documenting this.

Sure, we require a Pulsar log document, which is an important thing for debugging the Pulsar.

Because of consistency, I think it's a bad idea to allow modifying log4j2.yaml directly for one property but not for another. You didn't seem to read my arguments why I'm not supporting this change. Please go back to read https://github.com/apache/pulsar/pull/22017#pullrequestreview-1861988153 carefully. I'm happy to explain in more detail.

If you think the way I modified the log level is correct, I can also update other properties.

I know your arguments. Because of consistency, there are also pulsar.log.appender, pulsar.log.dir, pulsar.log.immediateFlush, pulsar.routing.appender.default.

Therefore, you suggest that I replace the default log4j2.yaml(replace "pulsar.log." -> "my.log."). I know this is a simple thing, but I don't want to do that, and I also want to keep consistency with Apache Pulsar. That's why I made this PR.

In my scenario, when the Pulsar is running, I only want to dynamically change the log level for debugging the Pulsar bug. Therefore, I think by modifying the pulsar.log.level and pulsar.log.root.level values from the info level to the debug level, the Pulsar will print the debug log.

Same issue: https://github.com/apache/pulsar/issues/14298

If you have any better ideas, please let me know.

Feb 05 '24 15:02 nodece