Log4j 2
  1. Log4j 2
  2. LOG4J2-555

Location-based functionality broken in AbstractLoggerWrapper subclasses

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc1
    • Fix Version/s: 2.0-rc2
    • Component/s: API, Core
    • Labels:
      None

      Description

      How to reproduce

      • Create a custom logger that extends AbstractLoggerWrapper (or generate one with the tool attached to LOG4J2-519)
      • In the custom logger provide a public method that invokes the log(Level, String) method
      • Configure a pattern layout that uses location, like %C for the logger FQCN
      • From a sample app, call the public method on your custom logger.
      • The output will show the class name of the custom logger instead of the class name of the calling class in the sample application.

      Cause
      AbstractLogger's FQCN field is static final and initialized to AbstractLogger.class.getName(). Then, in Log4jLogEvent#calcLocation(), when walking over the stack trace elements, the element following the FQCN is returned. So only loggers that directly subclass from AbstractLogger will work correctly. Loggers that inherit from AbstractLoggerWrapper are two levels removed from AbstractLogger and the calcLocation() method will not work correctly.

      Solution
      I think AbstractLogger's FQCN field should be made non-static, and initialized to getClass().getName() in the constructor of AbstractLogger. Log4jLogEvent#calcLocation() can then be modified to return the StackElement whose class name matches the FQCN, instead of the next element. Location-based functionality should then work for arbitrarily deep subclass hierarchies of AbstractLogger.

      1. log4j2-555-bbrouwer.patch
        125 kB
        Bruce Brouwer
      2. log4j2-555-bbrouwer-2.patch
        130 kB
        Bruce Brouwer
      3. LOG4J2-555-delegate.patch
        43 kB
        Remko Popma
      4. log4j2-555-gg-v3.diff
        127 kB
        Gary Gregory

        Issue Links

          Activity

          Hide
          Remko Popma added a comment -

          Renamed LoggerProvider to ExtendedLogger and renamed AbstractLoggerProvider back to AbstractLogger after discussion on the log4j-dev mailing list.
          Committed in revision 1600200.

          Show
          Remko Popma added a comment - Renamed LoggerProvider to ExtendedLogger and renamed AbstractLoggerProvider back to AbstractLogger after discussion on the log4j-dev mailing list. Committed in revision 1600200.
          Hide
          Remko Popma added a comment - - edited

          Fixed in revision 1580445, based on log4j2-555-bbrouwer-2.patch with Gary's changes.

          I also modified log4j-1.2-api Category (slightly different from the patch):
          forcedLog (line 337) now calls logger.logMessage instead of logger.logIfEnabled.
          maybeLog (line 431) now calls logger.logMessage instead of logger.logIfEnabled.

          Show
          Remko Popma added a comment - - edited Fixed in revision 1580445, based on log4j2-555-bbrouwer-2.patch with Gary's changes. I also modified log4j-1.2-api Category (slightly different from the patch): forcedLog (line 337) now calls logger.logMessage instead of logger.logIfEnabled. maybeLog (line 431) now calls logger.logMessage instead of logger.logIfEnabled.
          Hide
          Bruce Brouwer added a comment -

          All good points from everyone. Yes, it appears that all of the points that everyone made are things I simply missed. I am also ok with renaming the LoggerProvider log methods to logIfEnabled. I definitely appreciate all the extra eyes reviewing my code. I'm not planning on providing another patch as it sounds like Remko will clean it up.

          Show
          Bruce Brouwer added a comment - All good points from everyone. Yes, it appears that all of the points that everyone made are things I simply missed. I am also ok with renaming the LoggerProvider log methods to logIfEnabled . I definitely appreciate all the extra eyes reviewing my code. I'm not planning on providing another patch as it sounds like Remko will clean it up.
          Hide
          Remko Popma added a comment -

          Gary, looks like our messages crossed. I agree with your solution to avoid the potentially unnecessary call to messageFactory.newMessage.

          Bruce, one more small thing I noticed: line 1160 of AbstractLogger in log4j-555-bbrouwer-2.patch:

          public void log(final Level level, final Marker marker, final Object message, final Throwable t) {
              if (isEnabled(level, marker, message, t)) {
                  logMessage(FQCN, level, marker, message, t);
              }
          }
          

          Should this not be the below instead?

          public void log(final Level level, final Marker marker, final Object message, final Throwable t) {
              log(FQCN, level, marker, message, t);
          }
          

          Finally, I strongly feel we should have a different name for the "internal API" LoggerProvider.log methods (used by implementers/extenders) and the "external API" Logger.log methods (used by users). I propose we rename the LoggerProvider log methods to logIfEnabled. Other names would be fine too, just not "log"

          If nobody objects I will rename the LoggerProvider log methods to logIfEnabled and commit Bruce's "2" patch plus Gary's changes tomorrow (my tomorrow, that is Saturday night US time).

          Show
          Remko Popma added a comment - Gary, looks like our messages crossed. I agree with your solution to avoid the potentially unnecessary call to messageFactory.newMessage . Bruce, one more small thing I noticed: line 1160 of AbstractLogger in log4j-555-bbrouwer-2.patch: public void log( final Level level, final Marker marker, final Object message, final Throwable t) { if (isEnabled(level, marker, message, t)) { logMessage(FQCN, level, marker, message, t); } } Should this not be the below instead? public void log( final Level level, final Marker marker, final Object message, final Throwable t) { log(FQCN, level, marker, message, t); } Finally, I strongly feel we should have a different name for the "internal API" LoggerProvider.log methods (used by implementers/extenders) and the "external API" Logger.log methods (used by users). I propose we rename the LoggerProvider log methods to logIfEnabled . Other names would be fine too, just not "log" If nobody objects I will rename the LoggerProvider log methods to logIfEnabled and commit Bruce's "2" patch plus Gary's changes tomorrow (my tomorrow, that is Saturday night US time).
          Hide
          Gary Gregory added a comment -

          All of Bruce's "2" patch plus my changes. Bruce: verify that I did not drop anything...

          Show
          Gary Gregory added a comment - All of Bruce's "2" patch plus my changes. Bruce: verify that I did not drop anything...
          Hide
          Gary Gregory added a comment - - edited

          Thank you for the review Remko Popma. These are all good points.

          WRT

          in AbstractLogger the debug/trace/info/...(Object objMessage) methods now call log(FQCN, Level.XXX, null, messageFactory.newMessage(message), null); so a Message object may be created unnecessarily if isEnabled later returns false

          I wonder if we should fix this. On one hand:
          This would have to be fixed because creating objects for nothing will be a giant GC hit, to be considered a leak IMO.

          OTOH, this would assume the call site is not guarded with a isDebugEnabled() for example, so the 'leak' can be fixed by adding the guard clause.

          It depends what we define the contract for this method and class to be WRT to bullet proofing against this kind of 'leak'.

          The code with patch is:

              /**
               * Logs a message object with the {@link Level#DEBUG DEBUG} level.
               * 
               * @param message the message object to log.
               */
              @Override
              public void debug(final Object message) {
                  log(FQCN, Level.DEBUG, null, messageFactory.newMessage(message), null);
              }
          

          The obvious fix is:

              public void debug(final Object message) {
                  if (isEnabled(Level.DEBUG)) {
                      log(FQCN, Level.DEBUG, null, messageFactory.newMessage(message), null);
                  }
              }
          

          But we have both:

          org.apache.logging.log4j.spi.AbstractLogger.log(String, Level, Marker, Message, Throwable)
          org.apache.logging.log4j.spi.AbstractLogger.log(String, Level, Marker, Object, Throwable)
          

          Why not:

              @Override
              public void debug(final Object message) {
                  log(FQCN, Level.DEBUG, null, message, null);
              }
          

          ?

          A local build with the patch and this change builds OK with 'mvn test'.

          Show
          Gary Gregory added a comment - - edited Thank you for the review Remko Popma . These are all good points. WRT in AbstractLogger the debug/trace/info/...(Object objMessage) methods now call log(FQCN, Level.XXX, null, messageFactory.newMessage(message), null); so a Message object may be created unnecessarily if isEnabled later returns false I wonder if we should fix this. On one hand: This would have to be fixed because creating objects for nothing will be a giant GC hit, to be considered a leak IMO. OTOH, this would assume the call site is not guarded with a isDebugEnabled() for example, so the 'leak' can be fixed by adding the guard clause. It depends what we define the contract for this method and class to be WRT to bullet proofing against this kind of 'leak'. The code with patch is: /** * Logs a message object with the {@link Level#DEBUG DEBUG} level. * * @param message the message object to log. */ @Override public void debug( final Object message) { log(FQCN, Level.DEBUG, null , messageFactory.newMessage(message), null ); } The obvious fix is: public void debug( final Object message) { if (isEnabled(Level.DEBUG)) { log(FQCN, Level.DEBUG, null , messageFactory.newMessage(message), null ); } } But we have both: org.apache.logging.log4j.spi.AbstractLogger.log( String , Level, Marker, Message, Throwable) org.apache.logging.log4j.spi.AbstractLogger.log( String , Level, Marker, Object , Throwable) Why not: @Override public void debug( final Object message) { log(FQCN, Level.DEBUG, null , message, null ); } ? A local build with the patch and this change builds OK with 'mvn test'.
          Hide
          Remko Popma added a comment - - edited

          I've finished reviewing log4j-555-bbrouwer-2.patch.
          Things I liked:

          • simplified code, reduced duplication in AbstractLogger and slf4j-impl.SLF4JLogger
          • LoggerProvider interface removes need to cast to AbstractLogger when extending/customizing Logger
          • clearer distinction between "external" API log methods for users and "internal" API logMessage method for extenders (but see below)

          TBD:

          • in AbstractLogger the debug/trace/info/...(Object objMessage) methods now call log(FQCN, Level.XXX, null, messageFactory.newMessage(objMessage), null); so a Message object may be created unnecessarily if isEnabled later returns false. EDIT: this looks like a mistake, not a design issue: these methods can just call AbstractLogger.log(String, Level, Marker, Object, Throwable) (line 1313 of patched AbstractLogger) without calling messageFactory.newMessage(objMessage)
          • the new (internal API) log methods introduced in the LoggerProvider interface are confusingly similar to the external API log methods (same method name, only the order of parameters is different). How about renaming them to logIfEnabled or something else?
          Show
          Remko Popma added a comment - - edited I've finished reviewing log4j-555-bbrouwer-2.patch. Things I liked: simplified code, reduced duplication in AbstractLogger and slf4j-impl.SLF4JLogger LoggerProvider interface removes need to cast to AbstractLogger when extending/customizing Logger clearer distinction between "external" API log methods for users and "internal" API logMessage method for extenders (but see below) TBD: in AbstractLogger the debug/trace/info/...(Object objMessage) methods now call log(FQCN, Level.XXX, null, messageFactory.newMessage(objMessage), null); so a Message object may be created unnecessarily if isEnabled later returns false. EDIT: this looks like a mistake, not a design issue: these methods can just call AbstractLogger.log(String, Level, Marker, Object, Throwable) (line 1313 of patched AbstractLogger) without calling messageFactory.newMessage(objMessage) the new (internal API) log methods introduced in the LoggerProvider interface are confusingly similar to the external API log methods (same method name, only the order of parameters is different). How about renaming them to logIfEnabled or something else?
          Hide
          Bruce Brouwer added a comment - - edited

          After thinking some more about my change to log4j-jcl Log4jLog, I could quite easily be convinced to revert that back to extending AbstractLoggerWrapper. I could see some convenience in simply casting Log4jLog between jcl's Log and log4j's Logger interface. For example, if I was using jcl's interface to log4j, I could simply cast to a jcl Log to log4j's Logger to use the different logger streams depicted in LOG4J2-547.

          However, if we do that, then we should probably do the same thing to log4j-slf4j-impl's SLF4JLogger so it can also be cast to log4j's Logger interface. I suppose this change could be tracked in a separate JIRA.

          So what do people think? Should these alternate logging implementations be made so it is easy to cast to log4j's Logger interface, or should we try to keep the interface to these alternate logging implementations as free as possible of log4j public methods?

          Oh, and I now see that my comment about log4j-to-slf4j SLF4JLogger.logMessage was in error. It is fine as it is (which is how it remains in the patch)

          I also see that I was remiss in finishing up JavaDoc. If people like the direction of log4j-555-bbrouwer-2.patch, I can make a new patch, or I will commit to submitting a documentation patch if this is applied before that new patch.

          Show
          Bruce Brouwer added a comment - - edited After thinking some more about my change to log4j-jcl Log4jLog, I could quite easily be convinced to revert that back to extending AbstractLoggerWrapper. I could see some convenience in simply casting Log4jLog between jcl's Log and log4j's Logger interface. For example, if I was using jcl's interface to log4j, I could simply cast to a jcl Log to log4j's Logger to use the different logger streams depicted in LOG4J2-547 . However, if we do that, then we should probably do the same thing to log4j-slf4j-impl's SLF4JLogger so it can also be cast to log4j's Logger interface. I suppose this change could be tracked in a separate JIRA. So what do people think? Should these alternate logging implementations be made so it is easy to cast to log4j's Logger interface, or should we try to keep the interface to these alternate logging implementations as free as possible of log4j public methods? Oh, and I now see that my comment about log4j-to-slf4j SLF4JLogger.logMessage was in error. It is fine as it is (which is how it remains in the patch) I also see that I was remiss in finishing up JavaDoc. If people like the direction of log4j-555-bbrouwer-2.patch , I can make a new patch, or I will commit to submitting a documentation patch if this is applied before that new patch.
          Hide
          Gary Gregory added a comment -

          I think I like log4j2-555-bbrouwer-2.patch so far. All tests pass with the patch applied to trunk. I'd like to spend more time looking at this. Hopefully we'll get more feedback from the others.

          Show
          Gary Gregory added a comment - I think I like log4j2-555-bbrouwer-2.patch so far. All tests pass with the patch applied to trunk. I'd like to spend more time looking at this. Hopefully we'll get more feedback from the others.
          Hide
          Bruce Brouwer added a comment -

          I ran the performance test on my Windows 7 64-bit laptop while plugged in. It is a single-proc, 4 core Intel i7 2.7GHz machine with 8GB RAM.

          Show
          Bruce Brouwer added a comment - I ran the performance test on my Windows 7 64-bit laptop while plugged in. It is a single-proc, 4 core Intel i7 2.7GHz machine with 8GB RAM.
          Hide
          Remko Popma added a comment -

          Thanks for the overview. It is helpful to not only know what you are doing but also why you are doing it.

          Thanks also for running the performance test. These numbers tend to vary between runs, and I suspect the difference between before and after is not significant. (Meaning that your changes did not make performance worse. ) Some platforms are more consistent than others, but for example on my Windows laptop I see large differences between runs. What OS & hardware (cpu, #cores) did you use?

          I should update the performance test to print only throughput with standard deviation and omit the (useless) latency numbers. The same test framework also has a latency-only test mode but currently processing/pretty-printing those results is not automated yet.

          A final note on performance testing: I've started to look at JMH for benchmarking log4j performance. Looks promising.

          Show
          Remko Popma added a comment - Thanks for the overview. It is helpful to not only know what you are doing but also why you are doing it. Thanks also for running the performance test. These numbers tend to vary between runs, and I suspect the difference between before and after is not significant. (Meaning that your changes did not make performance worse. ) Some platforms are more consistent than others, but for example on my Windows laptop I see large differences between runs. What OS & hardware (cpu, #cores) did you use? I should update the performance test to print only throughput with standard deviation and omit the (useless) latency numbers. The same test framework also has a latency-only test mode but currently processing/pretty-printing those results is not automated yet. A final note on performance testing: I've started to look at JMH for benchmarking log4j performance. Looks promising.
          Hide
          Bruce Brouwer added a comment -

          I wanted to give an overview of what my patch is trying to do:

          1. Simplify most logger methods to be one line of code
          2. Allow classes that wrap a logger (e.g. using AbstractLoggerWrapper) to use one line of code to log. To accomplish this, I created all the variants of the log(...) methods that now take a FQCN as the first parameter.
          3. Created an interface called LoggerProvider that AbstractLogger implements. This I think makes it a bit clearer what extra methods are needed beyond what is in the Logger interface to succesfully wrap a logger. This also allows for different (future) logger implementations that don't need to extend AbstractLogger.
          4. I changed LoggerContext to return LoggerProvider. Most people don't tend to go after the LoggerContext, so most people won't see this. But by doing this here, it makes it clear that loggers coming from here are guaranteed to have this extra functionality, and it eliminates some casting done in the code
          5. I tried to fix some of the method parameter ordering to be consistent: fqcn, level, marker, message, ... This patch doesn't cover all cases where this could be done but in the cases were I was changing method signatures anyway, I thought I would make the order consistent.

          You may notice that this patch includes a change to log4j-jcl Log4jLog.java. This was not absolutely necessary, but it seemed somehow wrong to me to rely on the fact that the method signatures of jcl match up perfectly to log4j2. The patch implementation also prevents leaking a bunch of other public methods into the implementation coming from AbstractLogger and AbstractLoggerWrapper. If others don't agree with me, it would be easy to revert Log4jLog.java back to what it was before, but instead of the first constructor parameter being AbstractLogger, it would change to LoggerProvider.

          I also just noticed that log4j-to-slf4j SLF4JLogger.logMessage has an unnecessary switch statement. That should probably be cleaned up as switching it to simply call logger.log(FQCN, level, getMarker(marker), ...) would actually be more performant, not only because it eliminates the switch statement, but it would also go through fewer method invocations. Do you want me to provide an updated patch that does this?

          Finally, I ran PerfTestDriver, just the "Loggers all async" tests. I am not sure what the best thing is to do to communicate performance, but this is what I did. I was kind of surprised to see that this patch is actually consistently more performant than the current log4j2 code (at least that's how I'm reading it).

          Original:

          1. Log4j2: Loggers all async (single thread): throughput: 12,746,429 ops/sec. latency(ns): avg=980.2 99% < 8192.0 99.99% < 1101004.8 (494079 samples)
          2. Log4j2: Loggers all async (4 threads): throughput: 6,603,641 ops/sec. latency(ns): avg=3157.4 99% < 5120.0 99.99% < 8703180.8 (3376684 samples)
          3. Log4j2: Loggers all async (2 threads): throughput: 3,505,632 ops/sec. latency(ns): avg=1103.5 99% < 5324.8 99.99% < 2516582.4 (2339717 samples)

          After:

          1. Log4j2: Loggers all async (single thread): throughput: 13,612,251 ops/sec. latency(ns): avg=8463.0 99% < 8192.0 99.99% < 2936012.8 (344455 samples)
          2. Log4j2: Loggers all async (4 threads): throughput: 7,395,284 ops/sec. latency(ns): avg=2690.5 99% < 5939.2 99.99% < 8231321.6 (5952262 samples)
          3. Log4j2: Loggers all async (2 threads): throughput: 4,639,382 ops/sec. latency(ns): avg=1079.2 99% < 6144.0 99.99% < 2464153.6 (2312163 samples)

          Show
          Bruce Brouwer added a comment - I wanted to give an overview of what my patch is trying to do: Simplify most logger methods to be one line of code Allow classes that wrap a logger (e.g. using AbstractLoggerWrapper) to use one line of code to log. To accomplish this, I created all the variants of the log(...) methods that now take a FQCN as the first parameter. Created an interface called LoggerProvider that AbstractLogger implements. This I think makes it a bit clearer what extra methods are needed beyond what is in the Logger interface to succesfully wrap a logger. This also allows for different (future) logger implementations that don't need to extend AbstractLogger. I changed LoggerContext to return LoggerProvider. Most people don't tend to go after the LoggerContext, so most people won't see this. But by doing this here, it makes it clear that loggers coming from here are guaranteed to have this extra functionality, and it eliminates some casting done in the code I tried to fix some of the method parameter ordering to be consistent: fqcn, level, marker, message, ... This patch doesn't cover all cases where this could be done but in the cases were I was changing method signatures anyway, I thought I would make the order consistent. You may notice that this patch includes a change to log4j-jcl Log4jLog.java. This was not absolutely necessary, but it seemed somehow wrong to me to rely on the fact that the method signatures of jcl match up perfectly to log4j2. The patch implementation also prevents leaking a bunch of other public methods into the implementation coming from AbstractLogger and AbstractLoggerWrapper. If others don't agree with me, it would be easy to revert Log4jLog.java back to what it was before, but instead of the first constructor parameter being AbstractLogger, it would change to LoggerProvider. I also just noticed that log4j-to-slf4j SLF4JLogger.logMessage has an unnecessary switch statement. That should probably be cleaned up as switching it to simply call logger.log(FQCN, level, getMarker(marker), ...) would actually be more performant, not only because it eliminates the switch statement, but it would also go through fewer method invocations. Do you want me to provide an updated patch that does this? Finally, I ran PerfTestDriver, just the "Loggers all async" tests. I am not sure what the best thing is to do to communicate performance, but this is what I did. I was kind of surprised to see that this patch is actually consistently more performant than the current log4j2 code (at least that's how I'm reading it). Original: 1. Log4j2: Loggers all async (single thread): throughput: 12,746,429 ops/sec. latency(ns): avg=980.2 99% < 8192.0 99.99% < 1101004.8 (494079 samples) 2. Log4j2: Loggers all async (4 threads): throughput: 6,603,641 ops/sec. latency(ns): avg=3157.4 99% < 5120.0 99.99% < 8703180.8 (3376684 samples) 3. Log4j2: Loggers all async (2 threads): throughput: 3,505,632 ops/sec. latency(ns): avg=1103.5 99% < 5324.8 99.99% < 2516582.4 (2339717 samples) After: 1. Log4j2: Loggers all async (single thread): throughput: 13,612,251 ops/sec. latency(ns): avg=8463.0 99% < 8192.0 99.99% < 2936012.8 (344455 samples) 2. Log4j2: Loggers all async (4 threads): throughput: 7,395,284 ops/sec. latency(ns): avg=2690.5 99% < 5939.2 99.99% < 8231321.6 (5952262 samples) 3. Log4j2: Loggers all async (2 threads): throughput: 4,639,382 ops/sec. latency(ns): avg=1079.2 99% < 6144.0 99.99% < 2464153.6 (2312163 samples)
          Hide
          Bruce Brouwer added a comment -

          I fixed the problems with the failing tests. Everything now passes.

          Show
          Bruce Brouwer added a comment - I fixed the problems with the failing tests. Everything now passes.
          Hide
          Gary Gregory added a comment -

          With Bruce's patch I get:

          Failed tests:
            RewriteAppenderTest.rewriteTest:83 Incorrect number of events. Expected 1, got 0
            JSONRoutingAppender2Test.routingTest:79 Incorrect number of events. Expected 1, got 0
            JSONRoutingAppenderTest.routingTest:79 Incorrect number of events. Expected 1, got 0
            RoutingAppenderTest.routingTest:79 Incorrect number of events. Expected 1, got 0
            RoutingAppenderWithJndiTest.routingTest:103 Incorrect number of events. Expected 1, got 0
            RoutingDefaultAppenderTest.routingTest:79 Incorrect number of events. Expected 1, got 0
          
          Tests run: 539, Failures: 6, Errors: 0, Skipped: 12
          
          [INFO] ------------------------------------------------------------------------
          [INFO] Reactor Summary:
          [INFO]
          [INFO] Apache Log4j 2 .................................... SUCCESS [  1.136 s]
          [INFO] Apache Log4j API .................................. SUCCESS [ 47.379 s]
          [INFO] Apache Log4j Core ................................. FAILURE [09:06 min]
          [INFO] Apache Log4J Core OSGi Async ...................... SKIPPED
          [INFO] Apache Log4J Core OSGi JPA ........................ SKIPPED
          [INFO] Apache Log4j 1.x Compatibility API ................ SKIPPED
          [INFO] Apache Log4J 1.x Compatibility Bundle ............. SKIPPED
          [INFO] Apache Log4J Core OSGi Net ........................ SKIPPED
          [INFO] Apache Log4J Core OSGi CouchDB .................... SKIPPED
          [INFO] Apache Log4J Core OSGi MongoDB .................... SKIPPED
          [INFO] Apache Log4J Core OSGi ............................ SKIPPED
          [INFO] Apache Log4j to SLF4J Adapter ..................... SKIPPED
          [INFO] Apache Log4j to SLF4J ............................. SKIPPED
          [INFO] Apache Log4j SLF4J Binding ........................ SKIPPED
          [INFO] Apache Log4j for SLF4J ............................ SKIPPED
          [INFO] Apache Log4J Core OSGi Bundles .................... SKIPPED
          [INFO] Apache Log4j Commons Logging Bridge ............... SKIPPED
          [INFO] Apache Log4j Flume NG Bridge ...................... SKIPPED
          [INFO] Apache Log4j Tag Library .......................... SKIPPED
          [INFO] Apache Log4j JMX GUI .............................. SKIPPED
          [INFO] Apache Log4j Samples .............................. SKIPPED
          [INFO] Apache Log4j Samples: Flume - Common .............. SKIPPED
          [INFO] Apache Log4j Samples: Flume - Remote .............. SKIPPED
          [INFO] Apache Log4j Samples: Flume - Embedded ............ SKIPPED
          [INFO] Apache Log4j 2 BOM ................................ SKIPPED
          [INFO] ------------------------------------------------------------------------
          [INFO] BUILD FAILURE
          [INFO] ------------------------------------------------------------------------
          

          Can you provide another patch?

          Show
          Gary Gregory added a comment - With Bruce's patch I get: Failed tests: RewriteAppenderTest.rewriteTest:83 Incorrect number of events. Expected 1, got 0 JSONRoutingAppender2Test.routingTest:79 Incorrect number of events. Expected 1, got 0 JSONRoutingAppenderTest.routingTest:79 Incorrect number of events. Expected 1, got 0 RoutingAppenderTest.routingTest:79 Incorrect number of events. Expected 1, got 0 RoutingAppenderWithJndiTest.routingTest:103 Incorrect number of events. Expected 1, got 0 RoutingDefaultAppenderTest.routingTest:79 Incorrect number of events. Expected 1, got 0 Tests run: 539, Failures: 6, Errors: 0, Skipped: 12 [INFO] ------------------------------------------------------------------------ [INFO] Reactor Summary: [INFO] [INFO] Apache Log4j 2 .................................... SUCCESS [ 1.136 s] [INFO] Apache Log4j API .................................. SUCCESS [ 47.379 s] [INFO] Apache Log4j Core ................................. FAILURE [09:06 min] [INFO] Apache Log4J Core OSGi Async ...................... SKIPPED [INFO] Apache Log4J Core OSGi JPA ........................ SKIPPED [INFO] Apache Log4j 1.x Compatibility API ................ SKIPPED [INFO] Apache Log4J 1.x Compatibility Bundle ............. SKIPPED [INFO] Apache Log4J Core OSGi Net ........................ SKIPPED [INFO] Apache Log4J Core OSGi CouchDB .................... SKIPPED [INFO] Apache Log4J Core OSGi MongoDB .................... SKIPPED [INFO] Apache Log4J Core OSGi ............................ SKIPPED [INFO] Apache Log4j to SLF4J Adapter ..................... SKIPPED [INFO] Apache Log4j to SLF4J ............................. SKIPPED [INFO] Apache Log4j SLF4J Binding ........................ SKIPPED [INFO] Apache Log4j for SLF4J ............................ SKIPPED [INFO] Apache Log4J Core OSGi Bundles .................... SKIPPED [INFO] Apache Log4j Commons Logging Bridge ............... SKIPPED [INFO] Apache Log4j Flume NG Bridge ...................... SKIPPED [INFO] Apache Log4j Tag Library .......................... SKIPPED [INFO] Apache Log4j JMX GUI .............................. SKIPPED [INFO] Apache Log4j Samples .............................. SKIPPED [INFO] Apache Log4j Samples: Flume - Common .............. SKIPPED [INFO] Apache Log4j Samples: Flume - Remote .............. SKIPPED [INFO] Apache Log4j Samples: Flume - Embedded ............ SKIPPED [INFO] Apache Log4j 2 BOM ................................ SKIPPED [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE [INFO] ------------------------------------------------------------------------ Can you provide another patch?
          Hide
          Remko Popma added a comment -

          At first glance this accomplishes the same as what I was trying to do, but without the enums. It looks simpler. I need to take a more detailed look later, but just looking at AbstractLogger I like your patch better than my solution.

          Show
          Remko Popma added a comment - At first glance this accomplishes the same as what I was trying to do, but without the enums. It looks simpler. I need to take a more detailed look later, but just looking at AbstractLogger I like your patch better than my solution.
          Hide
          Bruce Brouwer added a comment -

          I've attached my patch that takes care of the FQCN issues. AbstractLogger is reduced by 171 lines and it does not involve that fun little enum trick that Remko proposed. This has impact to anything that extends AbstractLogger, which is included in my patch. I haven't finished checking all the tests as I'm getting some weird testing errors that I think are unrelated to my changes, but I'll check yet.

          My initial performance numbers show it is just as fast as before, but I'll post more complete numbers later.

          Show
          Bruce Brouwer added a comment - I've attached my patch that takes care of the FQCN issues. AbstractLogger is reduced by 171 lines and it does not involve that fun little enum trick that Remko proposed. This has impact to anything that extends AbstractLogger, which is included in my patch. I haven't finished checking all the tests as I'm getting some weird testing errors that I think are unrelated to my changes, but I'll check yet. My initial performance numbers show it is just as fast as before, but I'll post more complete numbers later.
          Hide
          Remko Popma added a comment -

          The enums (like MsgBuilder) use the double-dispatch pattern as a clean way to avoid introducing a conditional. Avoiding a branch means the CPU doesn't need to do branch prediction (potential cache miss/pipeline stall).

          The purpose of the refactoring in the patch was to

          1. reduce semi-duplicate code in many AbstractLogger methods
          2. extract elements of the if(isEnabled(...){log(...);}_ pattern so these elements can be re-used in extended/custom loggers
          3. these reusable elements in turn make managing the FQCN less onerous for custom/extended loggers: these loggers don't need to repeat the if(isEnabled(...){log(...);}_ pattern but instead can have a one-line implementation that calls the doLog(...) method.

          So to me, this patch solves the FQCN problem this ticket was created for. If we decide to reject this patch I don't mind not having a solution but just keeping things the way they are. I don't think the FQCN is a huge problem and I would not be in favor of much added complexity just to make FQCN easier to manage for the rare use case of custom/extended loggers. Any extra classes/interfaces should carry their own weight so to speak and have benefits other than FQCN, IMHO.

          Would the stream/writer loggers benefit from the patch attached here? (I haven't checked...)

          Show
          Remko Popma added a comment - The enums (like MsgBuilder) use the double-dispatch pattern as a clean way to avoid introducing a conditional. Avoiding a branch means the CPU doesn't need to do branch prediction (potential cache miss/pipeline stall). The purpose of the refactoring in the patch was to reduce semi-duplicate code in many AbstractLogger methods extract elements of the if(isEnabled(...){log(...);}_ pattern so these elements can be re-used in extended/custom loggers these reusable elements in turn make managing the FQCN less onerous for custom/extended loggers: these loggers don't need to repeat the if(isEnabled(...){log(...);}_ pattern but instead can have a one-line implementation that calls the doLog(...) method. So to me, this patch solves the FQCN problem this ticket was created for. If we decide to reject this patch I don't mind not having a solution but just keeping things the way they are. I don't think the FQCN is a huge problem and I would not be in favor of much added complexity just to make FQCN easier to manage for the rare use case of custom/extended loggers. Any extra classes/interfaces should carry their own weight so to speak and have benefits other than FQCN, IMHO. Would the stream/writer loggers benefit from the patch attached here? (I haven't checked...)
          Hide
          Bruce Brouwer added a comment -

          That MsgBuilder stuff looks interesting. I'm not sure I'm for it yet. It is not incompatible with my ideas.

          I'm working on my own patch for this that I will post soon and I hope to receive feedback.

          There are a few things I'm trying to do to make it easier for things using the wrapper.

          • Instead of FQCN invading the API, which isn't terribly flexible, I've created a SourceLocator interface and related classes. This way custom loggers could use multiple FQCNs or something completely different.
          • Make the interface LoggerProvider in the spi package which extends Logger and which AbstractLogger implements. This has a few more isEnabled and log methods available which make it possible for extended loggers to use efficiently. LoggerContext would start to return LoggerProvider instead of just Logger, and other code would stop casting to AbstractLogger and could instead use the LoggerProvider interface.

          That second point ends up making more methods public on the concrete implementations. I had an alternative idea in LOG4J2-562 that would prevent these methods from needing to go public. I'll post my patch soon. I'll try to get performance numbers, too.

          Show
          Bruce Brouwer added a comment - That MsgBuilder stuff looks interesting. I'm not sure I'm for it yet. It is not incompatible with my ideas. I'm working on my own patch for this that I will post soon and I hope to receive feedback. There are a few things I'm trying to do to make it easier for things using the wrapper. Instead of FQCN invading the API, which isn't terribly flexible, I've created a SourceLocator interface and related classes. This way custom loggers could use multiple FQCNs or something completely different. Make the interface LoggerProvider in the spi package which extends Logger and which AbstractLogger implements. This has a few more isEnabled and log methods available which make it possible for extended loggers to use efficiently. LoggerContext would start to return LoggerProvider instead of just Logger, and other code would stop casting to AbstractLogger and could instead use the LoggerProvider interface. That second point ends up making more methods public on the concrete implementations. I had an alternative idea in LOG4J2-562 that would prevent these methods from needing to go public. I'll post my patch soon. I'll try to get performance numbers, too.
          Hide
          Remko Popma added a comment -

          Hotspot compiles to native code if the method is "hot" enough (>40,000 or 50,000 calls). During the compile, I expect the extra method invocations are optimized away.

          In fact, since SimplePerfTest uses the DefaultConfiguration (level=ERROR) but the test logs at DEBUG level, I wouldn't be surprised if Hotspot optimizes the whole loop away because it isn't actually causing any side-effects (doing any work)...

          You'd be surprised at how different what actually gets executed looks from the original java source. http://m.youtube.com/watch?v=UwB0OSmkOtQ

          Show
          Remko Popma added a comment - Hotspot compiles to native code if the method is "hot" enough (>40,000 or 50,000 calls). During the compile, I expect the extra method invocations are optimized away. In fact, since SimplePerfTest uses the DefaultConfiguration (level=ERROR) but the test logs at DEBUG level, I wouldn't be surprised if Hotspot optimizes the whole loop away because it isn't actually causing any side-effects (doing any work)... You'd be surprised at how different what actually gets executed looks from the original java source. http://m.youtube.com/watch?v=UwB0OSmkOtQ
          Hide
          Ralph Goers added a comment -

          The change does make the code a little less error prone. However, I really am surprised there isn't a hit to SimplePerfTest given extra calls and parameters are being introduced. But I can't argue with test results. I guess I'm +0.5 on this.

          Show
          Ralph Goers added a comment - The change does make the code a little less error prone. However, I really am surprised there isn't a hit to SimplePerfTest given extra calls and parameters are being introduced. But I can't argue with test results. I guess I'm +0.5 on this.
          Hide
          Remko Popma added a comment -

          I did some performance tests but did not see any significant difference. SimplePerfTest gave very similar results before and after applying the patch.

          I also ran the org.apache.logging.log4j.core.async.perftest.PerfTestDriver tests with -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector to make all loggers asynchronous. Again the differences between before and after are within the standard deviation:

            Before   After (1)   After (2)  
            Ops/sec stdev Ops/sec stdev Ops/sec stdev
          1 thread 4,306,635 680,748 4,035,179 154,953 4,727,986 1,274,861
          2 threads 3,177,743 2,204,713 2,223,271 722,988 2,786,508 700,968
          4 threads 3,020,324 1,960,143 3,443,250 1,643,893 3,839,109 2,997,553

          So I guess it is just a matter of do we like the original code better or the new code better?

          Show
          Remko Popma added a comment - I did some performance tests but did not see any significant difference. SimplePerfTest gave very similar results before and after applying the patch. I also ran the org.apache.logging.log4j.core.async.perftest.PerfTestDriver tests with -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector to make all loggers asynchronous. Again the differences between before and after are within the standard deviation:   Before   After (1)   After (2)     Ops/sec stdev Ops/sec stdev Ops/sec stdev 1 thread 4,306,635 680,748 4,035,179 154,953 4,727,986 1,274,861 2 threads 3,177,743 2,204,713 2,223,271 722,988 2,786,508 700,968 4 threads 3,020,324 1,960,143 3,443,250 1,643,893 3,839,109 2,997,553 So I guess it is just a matter of do we like the original code better or the new code better?
          Hide
          Remko Popma added a comment -

          I completely agree that if there is any performance impact at all, we should not do this.

          Also, to clarify, I really don't want to over-complicate things. The idea I mentioned in an earlier comment of having a set of FQCNs was just a thought experiment and I now think that the benefit for custom loggers is not worth any added complexity. Custom loggers are a rare case and simply documenting "custom loggers must use the abstract log(Marker, String, Level, Message, Throwable) method because they must specify their own FQCN" is probably sufficient.

          The attached patch reduces complexity a little bit in many places (7 x 14 methods) and adds complexity in one place (the enums and the doLog method). I'd like feedback on whether other people think this is a good trade-off. Perhaps this is just a matter of taste? Anyway, feedback welcome.

          I'll do some performance testing and post the results.

          Show
          Remko Popma added a comment - I completely agree that if there is any performance impact at all, we should not do this. Also, to clarify, I really don't want to over-complicate things. The idea I mentioned in an earlier comment of having a set of FQCNs was just a thought experiment and I now think that the benefit for custom loggers is not worth any added complexity. Custom loggers are a rare case and simply documenting "custom loggers must use the abstract log(Marker, String, Level, Message, Throwable) method because they must specify their own FQCN" is probably sufficient. The attached patch reduces complexity a little bit in many places (7 x 14 methods) and adds complexity in one place (the enums and the doLog method). I'd like feedback on whether other people think this is a good trade-off. Perhaps this is just a matter of taste? Anyway, feedback welcome. I'll do some performance testing and post the results.
          Hide
          Ralph Goers added a comment -

          Have you run before and after on the performance tests - especially SimplePerfTest. Any time you make changes to the API that change the code that checks for logging being enabled you need to run this - ideally on a few different machines.

          The first couple of times I ran the test with the patch applied it seemed slower, but after running it a few more times it appears there isn't much difference, at least on my machine.

          Show
          Ralph Goers added a comment - Have you run before and after on the performance tests - especially SimplePerfTest. Any time you make changes to the API that change the code that checks for logging being enabled you need to run this - ideally on a few different machines. The first couple of times I ran the test with the patch applied it seemed slower, but after running it a few more times it appears there isn't much difference, at least on my machine.
          Hide
          Remko Popma added a comment -

          Inspired by Gary's call for a refactoring, please find attached patch. This eliminates most of the semi-duplicate code in AbstractLogger and reduces the class length by 115 lines.

          It also provides a clear example to follow for custom/extended logger authors (I hope). At least the code generated by the tool attached to LOG4J2-519 can be reduced by following the same pattern.

          Thoughts?

          Show
          Remko Popma added a comment - Inspired by Gary's call for a refactoring, please find attached patch. This eliminates most of the semi-duplicate code in AbstractLogger and reduces the class length by 115 lines. It also provides a clear example to follow for custom/extended logger authors (I hope). At least the code generated by the tool attached to LOG4J2-519 can be reduced by following the same pattern. Thoughts?
          Hide
          Remko Popma added a comment - - edited

          I won't have time to work out the details for another 2 weeks or so, so let me draw the big picture of the refactoring I have in mind.

          The goal of the refactoring is to reduce the lines of code in the convenience methods (what is currently almost, but not quite duplicate code). These methods would end up delegating to a single doLog() method (in both AbstractLogger and Extended/Custom Loggers, not sure about the Writers). For example, the current code in AbstractLogger looks like this:

          public void error(final String message, final Object... params) {
              if (isEnabled(Level.ERROR, null, message, params)) {
                  final Message msg = messageFactory.newMessage(message, params);
                  log(null, FQCN, Level.ERROR, msg, msg.getThrowable());
              }
          }
          

          the above would become

          public void error(final String message, final Object... params) {
              doLog(Enabled.stringVarargs, null, FQCN, Level.ERROR, MsgBuilder.stringVarargs,
                      message, null, params);
          }
          

          The idea is to create enums for all isEnabled() methods, and passing this enum value to the doLog method instead of calling the isEnabled method directly in error().

          The new doLog method would look something like this:

          private void doLog(Enabled enabled, Marker marker, String FQCN, Level level, MsgBuilder builder,
                  String message, Throwable throwable, Object... params) {
              Message msg = builder.build(message, throwable, params);
              if (enabled.isEnabled(this, level, marker, msg, throwable)) {
                  log(marker, FQCN, level, msg, msg.getThrowable());
              }
          }
          

          Each of the 5 enum values for Enabled has a different implementation of the isEnabled method that ignores some parameters, so we end up with the same behaviour as what AbstractLogger currently does, with a few extra method invocations in between (that Hotspot can easily optimize out).

          A similar enum mechanism can be used to create the Message object (tentatively named MsgBuilder).

          So the trade-off is we gain a simpler implementation for the existing convenience methods
          (6 levels times 14 methods = 84 methods where we go from 3-4 lines to 1 line).

          And in return we need to add the new doLog method above as well as enums for Enabled and MsgBuilder. The enums can be public static inner classes of AbstractLogger so they can be re-used in Extended/Custom loggers.

          This also means there would be no need to track FQCNs in the class hierarchy. I'm kind of moving away from any kind of central FQCN tracking. It is much simpler if each AbstractLogger subclass manages its own FQCN.

          Thoughts?

          Show
          Remko Popma added a comment - - edited I won't have time to work out the details for another 2 weeks or so, so let me draw the big picture of the refactoring I have in mind. The goal of the refactoring is to reduce the lines of code in the convenience methods (what is currently almost, but not quite duplicate code). These methods would end up delegating to a single doLog() method (in both AbstractLogger and Extended/Custom Loggers, not sure about the Writers). For example, the current code in AbstractLogger looks like this: public void error( final String message, final Object ... params) { if (isEnabled(Level.ERROR, null , message, params)) { final Message msg = messageFactory.newMessage(message, params); log( null , FQCN, Level.ERROR, msg, msg.getThrowable()); } } the above would become public void error( final String message, final Object ... params) { doLog(Enabled.stringVarargs, null , FQCN, Level.ERROR, MsgBuilder.stringVarargs, message, null , params); } The idea is to create enums for all isEnabled() methods, and passing this enum value to the doLog method instead of calling the isEnabled method directly in error() . The new doLog method would look something like this: private void doLog(Enabled enabled, Marker marker, String FQCN, Level level, MsgBuilder builder, String message, Throwable throwable, Object ... params) { Message msg = builder.build(message, throwable, params); if (enabled.isEnabled( this , level, marker, msg, throwable)) { log(marker, FQCN, level, msg, msg.getThrowable()); } } Each of the 5 enum values for Enabled has a different implementation of the isEnabled method that ignores some parameters, so we end up with the same behaviour as what AbstractLogger currently does, with a few extra method invocations in between (that Hotspot can easily optimize out). A similar enum mechanism can be used to create the Message object (tentatively named MsgBuilder ). So the trade-off is we gain a simpler implementation for the existing convenience methods (6 levels times 14 methods = 84 methods where we go from 3-4 lines to 1 line). And in return we need to add the new doLog method above as well as enums for Enabled and MsgBuilder. The enums can be public static inner classes of AbstractLogger so they can be re-used in Extended/Custom loggers. This also means there would be no need to track FQCNs in the class hierarchy. I'm kind of moving away from any kind of central FQCN tracking. It is much simpler if each AbstractLogger subclass manages its own FQCN. Thoughts?
          Hide
          Bruce Brouwer added a comment -

          As for the Set idea, I think that is close to what we need (sans proxies). I don't want this to walk up the class hierarchy, though. For what I was working on for LOG4J2-547 regarding the LoggerStream, I would be providing a subclass of Writer or OutputStream (e.g. LoggerWriter or LoggerOutputStream). These may wrap another Writer or OutputStream. If you simply walked up the class hierarchy of LoggerWriter, you would be watching for FQCNs of Writer, such as the wrapped Writer would also extend. This might cause this locator logic to incorrectly identify which class stack element was the outer most call stack used for locating caller information.

          I think it would be better if we simply gave the FQCN parameter a collection of FQCNs. If I knew I extended every method of AbstractLogger, then why bother checking for AbstractLogger in the call stack.

          Show
          Bruce Brouwer added a comment - As for the Set idea, I think that is close to what we need (sans proxies). I don't want this to walk up the class hierarchy, though. For what I was working on for LOG4J2-547 regarding the LoggerStream, I would be providing a subclass of Writer or OutputStream (e.g. LoggerWriter or LoggerOutputStream). These may wrap another Writer or OutputStream. If you simply walked up the class hierarchy of LoggerWriter, you would be watching for FQCNs of Writer, such as the wrapped Writer would also extend. This might cause this locator logic to incorrectly identify which class stack element was the outer most call stack used for locating caller information. I think it would be better if we simply gave the FQCN parameter a collection of FQCNs. If I knew I extended every method of AbstractLogger, then why bother checking for AbstractLogger in the call stack.
          Hide
          Bruce Brouwer added a comment -

          Would it be crazy to use a Java Proxy to proxy the loggers and have the proxy figure out the call stack? This should work fine when you're just dealing with the Logger interface. I don't know exactly what kind of performance impact this would create. Maybe there would be a way to detect if a logger is using a location pattern layout like %C and only proxy it if necessary.

          This wouldn't help for the extended loggers unless they implemented an interface. For those it could fall back to using cglib (most likely would be an optional dependency)

          I don't know if this is worth exploring, but I thought I would throw it out as an idea.

          Show
          Bruce Brouwer added a comment - Would it be crazy to use a Java Proxy to proxy the loggers and have the proxy figure out the call stack? This should work fine when you're just dealing with the Logger interface. I don't know exactly what kind of performance impact this would create. Maybe there would be a way to detect if a logger is using a location pattern layout like %C and only proxy it if necessary. This wouldn't help for the extended loggers unless they implemented an interface. For those it could fall back to using cglib (most likely would be an optional dependency) I don't know if this is worth exploring, but I thought I would throw it out as an idea.
          Hide
          Remko Popma added a comment -

          I do have a refactoring in mind that would replace the four lines of code with one line. This would be applicable to both the Generate tool and AbstractLogger. The goal is merely to reduce the almost-but-not-quite-duplicate code and still work correctly for the FQCN issue mentioned in this ticket. Not sure it it will help you with the stream stuff.

          Work is extremely busy now and I may not be able to work on this in the next few weeks.

          Show
          Remko Popma added a comment - I do have a refactoring in mind that would replace the four lines of code with one line. This would be applicable to both the Generate tool and AbstractLogger. The goal is merely to reduce the almost-but-not-quite-duplicate code and still work correctly for the FQCN issue mentioned in this ticket. Not sure it it will help you with the stream stuff. Work is extremely busy now and I may not be able to work on this in the next few weeks.
          Hide
          Bruce Brouwer added a comment -

          I am also very interested in knowing where this lands. I'm working on LOG4J2-547, the LoggerStream API. In a sense I am writing a logger wrapper, but I am unable to extend AbstractLoggerWrapper or AbstractLogger as I need to extend Writer or OutputStream.

          Show
          Bruce Brouwer added a comment - I am also very interested in knowing where this lands. I'm working on LOG4J2-547 , the LoggerStream API. In a sense I am writing a logger wrapper, but I am unable to extend AbstractLoggerWrapper or AbstractLogger as I need to extend Writer or OutputStream.
          Hide
          Remko Popma added a comment -

          Hey Gary! I missed your comment. Yeah, I know! The generated code now basically looks very similar to the AbstractLogger implementation of the convenience methods for the built-in levels:

          public void customLevel(...) {
              if (logger.isEnabled(lots, of, parameters)) {
                  Message msg = createMessage();
                  logger.log(marker, fqcn, level, msg, throwable);
              }
          }
          

          Where before it looked like:

          public void customLevel(...) {
              logger.log(available, parameters);
          }
          

          Perhaps a nice solution for this would also allow the code in AbstractLogger to be simplified...

          Refactoring may be possible, both in the Generate tool and in AbstractLogger. Be aware there are some subtleties with the Throwable that may or may not be the last parameter in logging methods that take a varargs parameter.

          Show
          Remko Popma added a comment - Hey Gary! I missed your comment. Yeah, I know! The generated code now basically looks very similar to the AbstractLogger implementation of the convenience methods for the built-in levels: public void customLevel(...) { if (logger.isEnabled(lots, of, parameters)) { Message msg = createMessage(); logger.log(marker, fqcn, level, msg, throwable); } } Where before it looked like: public void customLevel(...) { logger.log(available, parameters); } Perhaps a nice solution for this would also allow the code in AbstractLogger to be simplified... Refactoring may be possible, both in the Generate tool and in AbstractLogger. Be aware there are some subtleties with the Throwable that may or may not be the last parameter in logging methods that take a varargs parameter.
          Hide
          Remko Popma added a comment -

          I keep thinking there must be a more robust way to achieve this... So far, the best I've been able to come up with is instead of having a single FQCN, we can have a Set of all FQCNs of the class hierarchy of loggers that extend AbstractLogger. When a logger instance is constructed, it builds that Set in the constructor, starting with getClass(), then keep calling cls.getParent() until either AbstractLogger is found or null.

          So for a generated extended logger the set would be { ExtendedLogger, AbstractLoggerWrapper, AbstractLogger }, and for a "normal" logger obtained from LogManager the set would be { core.Logger, AbstractLogger }.

          Unfortunately this breaks down for custom loggers that don't extend from AbstractLoggerWrapper but instead have an AbstractLoggerWrapper field that they delegate calls to. How to add the FQCN of such custom loggers to the FQCN Set of the AbstractLoggerWrapper that they delegate to? (And wouldn't this just move the problem: now custom logger authors need to remember to add the custom logger FQCN to the FQCN Set of its AbstractLoggerWrapper field, which is almost as bad as saying "don't use these methods, you can call only this one"...)

          And then of course there is the cost-benefit trade-off: how much effort to spend on this... Perhaps just updating the docs is good enough. I just wanted to write my thoughts down, I may revisit this later.

          Show
          Remko Popma added a comment - I keep thinking there must be a more robust way to achieve this... So far, the best I've been able to come up with is instead of having a single FQCN, we can have a Set of all FQCNs of the class hierarchy of loggers that extend AbstractLogger. When a logger instance is constructed, it builds that Set in the constructor, starting with getClass() , then keep calling cls.getParent() until either AbstractLogger is found or null . So for a generated extended logger the set would be { ExtendedLogger, AbstractLoggerWrapper, AbstractLogger }, and for a "normal" logger obtained from LogManager the set would be { core.Logger, AbstractLogger }. Unfortunately this breaks down for custom loggers that don't extend from AbstractLoggerWrapper but instead have an AbstractLoggerWrapper field that they delegate calls to. How to add the FQCN of such custom loggers to the FQCN Set of the AbstractLoggerWrapper that they delegate to? (And wouldn't this just move the problem: now custom logger authors need to remember to add the custom logger FQCN to the FQCN Set of its AbstractLoggerWrapper field, which is almost as bad as saying "don't use these methods, you can call only this one"...) And then of course there is the cost-benefit trade-off: how much effort to spend on this... Perhaps just updating the docs is good enough. I just wanted to write my thoughts down, I may revisit this later.
          Hide
          Gary Gregory added a comment -

          methods 3 or 4 lines: no opportunity for refactoring?

          Show
          Gary Gregory added a comment - methods 3 or 4 lines: no opportunity for refactoring?
          Hide
          Remko Popma added a comment -

          With hindsight I probably saw the getMessageFactory method but thought I could avoid using it.

          I just updated the Generate tool in LOG4J2-519 and having to go through the log(Marker, String, Level, Message, Throwable) method was quite painful. Method implementations are now three or four lines instead of one line, and there is a need to pass null parameters now.

          I'm not complaining, just noticing that the previous implementation was more intuitive so documentation is probably necessary if the longer and less intuitive implementation is the only correct way to do things.

          Show
          Remko Popma added a comment - With hindsight I probably saw the getMessageFactory method but thought I could avoid using it. I just updated the Generate tool in LOG4J2-519 and having to go through the log(Marker, String, Level, Message, Throwable) method was quite painful. Method implementations are now three or four lines instead of one line, and there is a need to pass null parameters now. I'm not complaining, just noticing that the previous implementation was more intuitive so documentation is probably necessary if the longer and less intuitive implementation is the only correct way to do things.
          Hide
          Remko Popma added a comment - - edited

          Interesting! I see the difficulty now: apps may call a method in the subclass or in AbstractLogger, so any stacktrace-walking should work for both.

          If custom loggers must use the log(Marker, String, Level, Message, Throwable) method, AbstractLogger should at least make its MessageFactory available to subclasses. The fact that this is not available was what made me call the other log methods in the custom logger in LOG4J2-519. EDIT: I overlooked the getter method for this.

          Still, it seems a bit... fragile to ask subclasses to use only that particular method. I'll think a bit more if there isn't an alternative. Thanks for the explanation!

          Show
          Remko Popma added a comment - - edited Interesting! I see the difficulty now: apps may call a method in the subclass or in AbstractLogger, so any stacktrace-walking should work for both. If custom loggers must use the log(Marker, String, Level, Message, Throwable) method, AbstractLogger should at least make its MessageFactory available to subclasses. The fact that this is not available was what made me call the other log methods in the custom logger in LOG4J2-519 . EDIT: I overlooked the getter method for this. Still, it seems a bit... fragile to ask subclasses to use only that particular method. I'll think a bit more if there isn't an alternative. Thanks for the explanation!
          Hide
          Ralph Goers added a comment - - edited

          AbstractLogger is correct. Applications that invoke its methods will work correctly. The problem here is that all the calls from a custom logger should use the log(final Marker marker, final String fqcn, final Level level, final Message data, final Throwable t) method of AbstractLoggerWrapper and provide the fqcn.

          I should add that at one point AbstractLogger had code similar to what you are suggesting. It generally did not work because in most cases the application is not calling a method in the subclass but is directly calling a method in AbstractLogger, thus the FQCN needs to be for AbstractLogger, not the subclass.

          I should also add that when AbstractLogger was first written it only had a single abstract log method. Last year all the other log methods were added to allow callers more flexibility to log at a specific level. We should document that those methods are for users and should never be used by a Logger implementation.

          Show
          Ralph Goers added a comment - - edited AbstractLogger is correct. Applications that invoke its methods will work correctly. The problem here is that all the calls from a custom logger should use the log(final Marker marker, final String fqcn, final Level level, final Message data, final Throwable t) method of AbstractLoggerWrapper and provide the fqcn. I should add that at one point AbstractLogger had code similar to what you are suggesting. It generally did not work because in most cases the application is not calling a method in the subclass but is directly calling a method in AbstractLogger, thus the FQCN needs to be for AbstractLogger, not the subclass. I should also add that when AbstractLogger was first written it only had a single abstract log method. Last year all the other log methods were added to allow callers more flexibility to log at a specific level. We should document that those methods are for users and should never be used by a Logger implementation.

            People

            • Assignee:
              Remko Popma
              Reporter:
              Remko Popma
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development