Introduce Log4j 2 #20235

jasontedor · 2016-08-30T17:42:32Z

This pull request introduces Log4j 2, replacing the existing Log4j
implementation. With this pull request:

the custom logging configuration is removed, we now expose Log4j 2
configuration directly
the ESLogger wrapper is removed, we now expose the Log4j 2 API
directly

There are two TODOs that I will address, but I think that reviews should
get started:

documentation
remove LoggerMessageFormat

There is a follow-up item to update the logger usage checks to work
against Log4j 2, but that will be outside the scope of this PR.

Closes #16030, closes #17697

This commit disables the logger usage checks as they will not be compatible with Log4j 2. This disabling is temporary, they will return.

This commit introduces Log4j 2 to the stack.

rjernst · 2016-08-30T18:07:07Z

buildSrc/src/main/groovy/org/elasticsearch/gradle/precommit/PrecommitTasks.groovy

@@ -59,7 +59,7 @@ class PrecommitTasks {
             * use the NamingConventionsCheck we break the circular dependency
             * here.
             */
-            precommitTasks.add(configureLoggerUsage(project))
+            // precommitTasks.add(configureLoggerUsage(project))


Can you at least add a comment with this linking to a followup issue?

I opened #20243 and pushed 4e69ac0.

pickypg · 2016-08-30T18:25:48Z

Do we know why log4j2 doesn't offer the obvious overload here? If not, have we created an issue with them to add it?

Logger#trace(String message, Throwable t, Object... params);
Logger#debug(String message, Throwable t, Object... params);
// etc

rather than forcing practically every use with an exception to awkwardly construct a ParameterizedMessage as the first arg?

nik9000 · 2016-08-30T18:29:24Z

core/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

@@ -31,6 +34,12 @@
 */
 public class DeprecationLogger {

+    private final Logger logger;
+
+    public Logger getLogger() {


It is probably worth documenting why it is ok to let this thing leak from inside DeprecationLogger. I feel like we shouldn't let it be public at all so users have to go through the special purpose deprecation logging methods so we can curate how they are used and what they do more carefully.

Thanks for noticing this @nik9000. This is leftover from a debugging session. 😄 I pushed 0fdc5ca.

nik9000 · 2016-08-30T18:37:52Z

I feel like you've combined about 6 PRs worth of stuff into one. Ultimately we want the this but for the sake of all that is holy can you make smaller ones next time? Like:

Back ESLogger with log4j2 instead of log4j1.
Replace 200 usages of ESLogger with Logger.
Replace 200 more usages.
Replace 200 more usages.
Replace 200 more usages.
Remove ESLogger.

s1monw · 2016-08-30T18:38:50Z

++ @nik9000

nik9000 · 2016-08-30T18:39:25Z

rather than forcing practically every use with an exception to awkwardly construct a ParameterizedMessage as the first arg?

log4j2 has support for log.debug("message {} {} {}", param, param, param). I guess we don't want to use it?

pickypg · 2016-08-30T18:46:57Z

core/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

                } catch (IllegalStateException e) {
                    // ignored; it should be removed shortly
                }
            }

-            logger.debug(formattedMsg);
+            logger.warn(formattedMessage);


This changes the way that our deprecation logging works today. It used to default to being silent by using debug. I do prefer this change, but I'm not sure if we should be making it as part of this PR?

I strongly disagree with deprecation logging not being visible out of the box but if we do not want it in this PR I will remove it. What do @clintongormley, @nik9000, and @rjernst think?

I agree it should be visible out of the box.

(I also strongly disagree with it being hidden by default; I just didn't want that to slip into this PR as it's not really related)

I'm fine with changing it to warning.

After #20254, we have consensus to do this out-of-the-box by default, and I will configure the deprecation logger to be size-limited.

pickypg · 2016-08-30T18:49:30Z

log4j2 has support for log.debug("message {} {} {}", param, param, param)

Unless it parses the first param as the exception, which would be confusing, it's missing that overload. For loggers that don't have an exception, I strongly prefer that overload versus instantiating a ParameterizedMessage.

rjernst · 2016-08-30T18:49:35Z

rather than forcing practically every use with an exception to awkwardly construct a ParameterizedMessage as the first arg?

log4j2 has support for log.debug("message {} {} {}", param, param, param). I guess we don't want to use it?

I believe that can't work b/c the variant that supports an exception and varargs was removed in log4j2. However, I think instead we could use the Supplier+exception variant?

nik9000 · 2016-08-30T18:57:09Z

exception and varargs was removed in log4j2

I didn't catch that the first time around. Thanks for pointing that out.

This commit modifies the call sites that allocate a parameterized message to use a supplier so that allocations are avoided unless the log level is fine enough to emit the corresponding log message.

This commit adds a missing cast to logging message supplier on a single invocation receiving a parameterized message parameter.

pickypg · 2016-08-30T22:30:15Z

...rc/main/java/org/elasticsearch/action/admin/cluster/health/TransportClusterHealthAction.java

@@ -106,7 +107,7 @@ public void onNoLongerMaster(String source) {

                @Override
                public void onFailure(String source, Exception e) {
-                    logger.error(new ParameterizedMessage("unexpected failure during [{}]", source), e);
+                    logger.error((Supplier<?>) () -> new ParameterizedMessage("unexpected failure during [{}]", source), e);


I can't help but wonder if we shouldn't have a static helper function that does this for us?

public static Supplier<ParameterizedMessage> message(String message, Object... params) { return () -> new ParameterizedMessage(message, params); }

EDIT: forgot the () -> in the return.

It's of course another import, but it will probably be better than staring at (Supplier<?>) () -> new ParameterizedMessage(...) in so many places.

This commit fixes failing evil logger tests. The tests were failing after inadvertently configuring appenders on the parent and child logger.

pickypg · 2016-08-30T22:35:13Z

...rc/main/java/org/elasticsearch/action/admin/cluster/health/TransportClusterHealthAction.java

@@ -105,7 +107,7 @@ public void onNoLongerMaster(String source) {

                @Override
                public void onFailure(String source, Exception e) {
-                    logger.error("unexpected failure during [{}]", e, source);
+                    logger.error((Supplier<?>) () -> new ParameterizedMessage("unexpected failure during [{}]", source), e);


Comment got erased by the last commit. I can't help but wonder if we shouldn't have a static helper function that does this for us?

public static Supplier<ParameterizedMessage> message(String message, Object... params) { return () -> new ParameterizedMessage(message, params); }

It's of course another import, but it will probably be better than staring at (Supplier<?>) () -> new ParameterizedMessage(...) in so many places and it removes both of those imports.

Maybe, but then we would want to at least have a lot of extra overrides to avoid allocating a varargs array.

I think that would be a lot cleaner than what it is here. It can probably be a secondary PR that happens in smaller waves though.

The problem is that these overrides would then introduce boxing on any primitive arguments, and that is something that we want to avoid as well. I do not think it's feasible to do this.

But that's not any different than the current non-exception logging? log4j just creates a ton of overloads with Object parameters too to avoid the params, right?

But that's not any different than the current non-exception logging?

The whole point of going the org.apache.log4j.util.Supplier<?> route was to avoid creating a new instance of ParameterizedMessage if the log message is not going to be emitted. I don't think we want to go through this trouble to immediately turn around and trigger allocations from boxing and varargs (yes, the latter can be avoided with a lot of overrides but the former can not without adding silly overrides for every possible combination).

log4j just creates a ton of overloads with Object parameters too to avoid the params, right?

Yes.

Which boxing are you referring to? I'm not seeing what would be boxed here (that would not have already been boxed with the old code)?

@rjernst The proposal from @pickypg is for a method

public static Supplier<ParameterizedMessage> message(String message, Object... params) { return () -> new ParameterizedMessage(message, params); }

This will cause an allocation of an Object[] and all primitive arguments will be boxed to Objects. Adding overrides like

public static Supplier<ParameterizedMessage> message(String message, Object p1, Object p2) { return () -> new ParameterizedMessage(message, params); }

removes the Object[] allocation, but still any primitive arguments will be boxed to Objects.

These allocations/boxing will occur regardless of whether or not the log level is fine enough to emit the corresponding log message.

With the (Supplier<?>) () -> new ParameterizedMessage("{}", o) pattern (as in this PR) we avoid this boxing unless the log message is going to be emitted.

but still any primitive arguments will be boxed to Objects.

But this would have been the case with the old methods as well (so nothing would be changing).

Having to do the cast makes logging a pain to use parameterized messages. While creatinga bunch of overloaded helpers may be a pain, maybe it is worth it. Or maybe having this pain will lead us to not depend on logging so much, so it could be good. :) I could go either way.

This commit fixes failing max map count check test due to the use of a logging message supplier.

This commit fixes failing evil logging configuration tests. The test for resolving multiple configuration files was failing after 9a58fc2 removed some of the configuration needed for this test. The solution is revert the removal of that configuration, but remove additivity from the test logger to prevent the evil logger tests from failing.

This commit adds comments linking to an open issue regarding updating the logger usage check for the Log4j 2 API.

This commit enables CLI tools to have console logging. For the CLI tools, we skip configuring the logging infrastructure via the config file, and instead set the level only via a system property.

* master: Increase visibility of deprecation logger Skip transport client plugin installed on JDK 9 Explicitly disable Netty key set replacement percolator: Fail indexing percolator queries containing either a has_child or has_parent query. Make it possible for Ingest Processors to access AnalysisRegistry Allow RestClient to send array-based headers Silence rest util tests until the bogusness can be simplified Remove unknown HttpContext-based test as it fails unpredictably on different JVMs Tests: Improve rest suite names and generated test names for docs tests Add support for a RestClient base path

This commit removes code references to logging.yml in TranslogToolCli and PluginCli.

This commit updates the logging docs for Elasticsearch to reflect the migration to Log4j 2.

This commit updates the packaging tests for Log4j 2. Namely, these tests make assertions about logging.yml that should now be about log4j2.properties.

jasontedor · 2016-08-31T20:15:09Z

@clintongormley Would you please review the docs in 750033d?

* master: Avoid NPE in LoggingListener Randomly use Netty 3 plugin in some tests Skip smoke test client on JDK 9 Revert "Don't allow XContentBuilder#writeValue(TimeValue)" [docs] Remove coming in 2.0.0 Don't allow XContentBuilder#writeValue(TimeValue) [doc] Remove leftover from CONSOLE conversion Parameter improvements to Cluster Health API wait for shards (#20223) Add 2.4.0 to packaging tests list Docs: clarify scale is applied at origin+offest (#20242)

jasontedor · 2016-08-31T20:54:43Z

I feel like you've combined about 6 PRs worth of stuff into one. Ultimately we want the this but for the sake of all that is holy can you make smaller ones next time?

@nik9000 I've thought about this a lot since you left this comment and I've decided that I did the right thing here. What makes this PR so massive is the removal of ESLogger in favor of Logger, and the conversion of invocations of logger.(error|warn|info|debug|trace)(String, Throwable, Object...) into logger.$1(new ParameterizedMessage(String, Object...), Throwable). The latter must be done as soon as a logger instance is changed to Logger from ESLogger otherwise we end up invoking an override in the Log4j 2 API that will lose stacktraces (that will make debugging test failures nightmare for everyone). The additional problem is that the vast majority of logger fields come from AbstractComponent, AbstractIndexComponent and AbstractShardIndexComponent combined with the fact that we pass loggers around in various places in the API. In my mind, this basically means it is all or nothing for this conversion. I'm really sorry that it's so big, but I think that it needs to be this way.

rjernst · 2016-08-31T21:09:16Z

@jasontedor Whether or not we decide to go with a helper for making parameterized messages, this change LGTM. I know this branch is a huge pain to maintain, so let's get it in, and have a followup discussion on whether/when/how to simplify logging pain points further?

* master: Correct path.conf for integ-test-zip distribution

This commit modifies a pair of exception logging calls to use parameterized messages from Log4j.

jasontedor · 2016-09-01T03:38:52Z

Thanks for reviewing @nik9000, @pickypg and @rjernst!

LongGCDisruption simulates a Long GC by suspending all threads belonging to a node. That's fine, unless those threads hold shared locks that can prevent other nodes from running. Concretely the logging infrastructure, which is shared between the nodes, can cause some deadlocks. LongGCDisruption has protection for this, but it needs to be updated to point at log4j2 classes, introduced in elastic#20235 This commit also fixes improper handling of retry logic in LongGCDisruption and adds a protection against deadlocking the test code which activates the disruption (and uses logging too! :)). On top of that we have some new, evil and nasty tests.

LongGCDisruption simulates a Long GC by suspending all threads belonging to a node. That's fine, unless those threads hold shared locks that can prevent other nodes from running. Concretely the logging infrastructure, which is shared between the nodes, can cause some deadlocks. LongGCDisruption has protection for this, but it needs to be updated to point at log4j2 classes, introduced in #20235 This commit also fixes improper handling of retry logic in LongGCDisruption and adds a protection against deadlocking the test code which activates the disruption (and uses logging too! :)). On top of that we have some new, evil and nasty tests.

jasontedor added 2 commits August 30, 2016 13:28

Disable logger usage checks

5a8f2d7

This commit disables the logger usage checks as they will not be compatible with Log4j 2. This disabling is temporary, they will return.

Introduce Log4j 2

7da0cde

This commit introduces Log4j 2 to the stack.

jasontedor added >enhancement >breaking review :Core/Infra/Core Core issues without another label v5.0.0-beta1 >breaking-java labels Aug 30, 2016

rjernst reviewed Aug 30, 2016
View reviewed changes

nik9000 reviewed Aug 30, 2016
View reviewed changes

pickypg reviewed Aug 30, 2016
View reviewed changes

jasontedor added 2 commits August 30, 2016 18:17

Avoid allocating log parameterized messages

abf8a1a

This commit modifies the call sites that allocate a parameterized message to use a supplier so that allocations are avoided unless the log level is fine enough to emit the corresponding log message.

Add missing cast to logging message supplier

0853fc8

This commit adds a missing cast to logging message supplier on a single invocation receiving a parameterized message parameter.

pickypg reviewed Aug 30, 2016
View reviewed changes

Fix failing evil logger tests

9a58fc2

This commit fixes failing evil logger tests. The tests were failing after inadvertently configuring appenders on the parent and child logger.

pickypg reviewed Aug 30, 2016
View reviewed changes

jasontedor added 2 commits August 30, 2016 18:49

Fix failing max map count check test

abe3efd

This commit fixes failing max map count check test due to the use of a logging message supplier.

jasontedor mentioned this pull request Aug 31, 2016

Update logger usage check for Log4j 2 #20243

Closed

Add link to open logger usage issue

4e69ac0

This commit adds comments linking to an open issue regarding updating the logger usage check for the Log4j 2 API.

jasontedor added 2 commits August 31, 2016 09:05

Enable console logging for CLI tools

ac8c2e9

This commit enables CLI tools to have console logging. For the CLI tools, we skip configuring the logging infrastructure via the config file, and instead set the level only via a system property.

clintongormley removed the >enhancement label Aug 31, 2016

jasontedor added 3 commits August 31, 2016 15:50

Remove code references to logging.yml

487ffe8

This commit removes code references to logging.yml in TranslogToolCli and PluginCli.

Update docs for Log4j 2

750033d

This commit updates the logging docs for Elasticsearch to reflect the migration to Log4j 2.

Update packaging tests for Log4j 2

07d1a72

This commit updates the packaging tests for Log4j 2. Namely, these tests make assertions about logging.yml that should now be about log4j2.properties.

jasontedor added 2 commits August 31, 2016 22:34

Merge branch 'master' into log4j2

c98e790

* master: Correct path.conf for integ-test-zip distribution

Fix additional exception logging calls

d9064f4

This commit modifies a pair of exception logging calls to use parameterized messages from Log4j.

jasontedor merged commit db86ede into elastic:master Sep 1, 2016

jasontedor deleted the log4j2 branch September 1, 2016 03:34

This was referenced Sep 1, 2016

Configure test logging with Log4j 2 #20284

Merged

Size limit deprecation logs #20287

Merged

dadoonet mentioned this pull request Sep 2, 2016

Reintroduce default log level for AWS APIs #20294

Closed

jasontedor mentioned this pull request Sep 6, 2016

Remove Log4j 1 jar hell exemption #20336

Merged

bleskes mentioned this pull request Sep 6, 2016

Fix LongGCDisruption to be aware of log4j2 #20348

Merged

clintongormley added the v5.0.0-beta1 label Sep 14, 2016

clintongormley added :Core/Infra/Logging Log management and logging utilities and removed :Core/Infra/Core Core issues without another label labels Sep 17, 2016

dakrone mentioned this pull request Sep 27, 2016

Support JSON logging formatting #8786

Closed

1ambda mentioned this pull request Nov 7, 2016

[ZEPPELIN-1618] [WIP] Support ElasticSearch 5.0 apache/zeppelin#1598

Closed

10 tasks

azasypkin mentioned this pull request Jul 18, 2017

Logging should support JSON output elastic/kibana#12941

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Introduce Log4j 2 #20235

Introduce Log4j 2 #20235

jasontedor commented Aug 30, 2016 •

edited

Loading

rjernst Aug 30, 2016

jasontedor Aug 31, 2016

pickypg commented Aug 30, 2016

nik9000 Aug 30, 2016

jasontedor Aug 31, 2016

nik9000 commented Aug 30, 2016

s1monw commented Aug 30, 2016

nik9000 commented Aug 30, 2016

pickypg Aug 30, 2016

jasontedor Aug 30, 2016

rjernst Aug 30, 2016

pickypg Aug 30, 2016

nik9000 Aug 30, 2016

jasontedor Aug 31, 2016

pickypg commented Aug 30, 2016

rjernst commented Aug 30, 2016

nik9000 commented Aug 30, 2016

pickypg Aug 30, 2016 •

edited

Loading

pickypg Aug 30, 2016 •

edited

Loading

jasontedor Aug 31, 2016

pickypg Aug 31, 2016

jasontedor Aug 31, 2016

pickypg Aug 31, 2016

jasontedor Aug 31, 2016

rjernst Aug 31, 2016

jasontedor Aug 31, 2016

rjernst Aug 31, 2016

jasontedor commented Aug 31, 2016

jasontedor commented Aug 31, 2016

rjernst commented Aug 31, 2016

jasontedor commented Sep 1, 2016

Introduce Log4j 2 #20235

Introduce Log4j 2 #20235

Conversation

jasontedor commented Aug 30, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pickypg commented Aug 30, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nik9000 commented Aug 30, 2016

s1monw commented Aug 30, 2016

nik9000 commented Aug 30, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pickypg commented Aug 30, 2016

rjernst commented Aug 30, 2016

nik9000 commented Aug 30, 2016

pickypg Aug 30, 2016 • edited Loading

Choose a reason for hiding this comment

pickypg Aug 30, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasontedor commented Aug 31, 2016

jasontedor commented Aug 31, 2016

rjernst commented Aug 31, 2016

jasontedor commented Sep 1, 2016

jasontedor commented Aug 30, 2016 •

edited

Loading

pickypg Aug 30, 2016 •

edited

Loading

pickypg Aug 30, 2016 •

edited

Loading