Details

    • Type: Improvement Improvement
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Done
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      I propose that we do a thorough examination of how we use loggers over the whole project. There are many instances of loggers being shared between classes that make troubleshooting difficult, and we can probably clean up some of the usage that has accumulated over numerous code moves and refactorings.

      Because this has the potential to scope wildly out of control, I would like to break the work down into several subtasks.

      • Loggers should be declared all three of private static final when possible. This both helps avoid the situations described in later bullets, and might provide a very minor performance improvement.
      • Distinct classes should not use loggers from other classes, unless they are explicitly delegated to do so.
      • Subclasses should declare their own loggers instead of relying on loggers from parent classes.
      • Examine if forbidden-api or some other tool(s) can help maintain this, once we reach a desired state.

      Each bullet might turn into one or more tasks, depending on how invasive individual changes become.

        Activity

        Hide
        Shawn Heisey added a comment -

        Regarding task #2, making loggers private is one aspect of not using loggers from other classes, but I don't think there's any way to prevent one class from creating a logger within itself that is tied to another class. This discussion leads into something I've been trying to do for a while: Declare a logger with identical code in every class.

        This code works, but creates a logger for each instance of the class, which is less than ideal, especially for very large installs:

        	private final Logger log = LoggerFactory.getLogger(this.getClass());
        

        Every idea I've come up with for creating a static logger without needing the class name has failed.

        Show
        Shawn Heisey added a comment - Regarding task #2, making loggers private is one aspect of not using loggers from other classes, but I don't think there's any way to prevent one class from creating a logger within itself that is tied to another class. This discussion leads into something I've been trying to do for a while: Declare a logger with identical code in every class. This code works, but creates a logger for each instance of the class, which is less than ideal, especially for very large installs: private final Logger log = LoggerFactory.getLogger( this .getClass()); Every idea I've come up with for creating a static logger without needing the class name has failed.
        Hide
        Mike Drob added a comment -

        I believe that in Java 8 you can do something like...

        private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().getClass());
        

        But I have no idea how efficient that construction is.

        Show
        Mike Drob added a comment - I believe that in Java 8 you can do something like... private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().getClass()); But I have no idea how efficient that construction is.
        Hide
        Shawn Heisey added a comment -

        I found something that seems to work, and I think will work in both Java 7 and 8:

          private static final Logger log = LoggerFactory
            .getLogger(Thread.currentThread().getStackTrace()[1].getClass());
        
        Show
        Shawn Heisey added a comment - I found something that seems to work, and I think will work in both Java 7 and 8: private static final Logger log = LoggerFactory .getLogger( Thread .currentThread().getStackTrace()[1].getClass());
        Hide
        Mike Drob added a comment -

        What specifically are we trying to solve by doing it that way? Prevent copy-paste errors? I think it would be more intuitive to figure out a static analysis rule to catch bad usage and keep things idiomatic rather than trying to find workarounds on JVM limitations.

        Show
        Mike Drob added a comment - What specifically are we trying to solve by doing it that way? Prevent copy-paste errors? I think it would be more intuitive to figure out a static analysis rule to catch bad usage and keep things idiomatic rather than trying to find workarounds on JVM limitations.
        Hide
        Shawn Heisey added a comment -

        A static method could be added to a utility class, using the Thread call that I found. A call to that method can be used in every class that needs a logger.

          private static final log = SomeUtilClass.getDefaultLogger();
        
        Show
        Shawn Heisey added a comment - A static method could be added to a utility class, using the Thread call that I found. A call to that method can be used in every class that needs a logger. private static final log = SomeUtilClass.getDefaultLogger();
        Hide
        Shawn Heisey added a comment -

        Yes, copy/paste errors are a possible source of problems with loggers. Having identical code would eliminate that as a problem. Because the code I quoted above is somewhat verbose, a utility method would make it a little safer.

        Show
        Shawn Heisey added a comment - Yes, copy/paste errors are a possible source of problems with loggers. Having identical code would eliminate that as a problem. Because the code I quoted above is somewhat verbose, a utility method would make it a little safer.
        Hide
        Mike Drob added a comment -

        Using a utility method still wouldn't enforce that the Logger is declared private static final, which is the bigger issue, I think.

        How does it work with subclassing? I imagine that it still returns a logger for the base class, but I'm not 100% sure on that.

        I'm currently hesitant about replacing all of the Logger declarations with a snippet like this because I'd like to give the benefit of the doubt to the existing code. There might be some reason that a few classes currently share loggers, and I'd feel more comfortable looking at each of those in turn, rather than replacing everything at once.

        Show
        Mike Drob added a comment - Using a utility method still wouldn't enforce that the Logger is declared private static final, which is the bigger issue, I think. How does it work with subclassing? I imagine that it still returns a logger for the base class, but I'm not 100% sure on that. I'm currently hesitant about replacing all of the Logger declarations with a snippet like this because I'd like to give the benefit of the doubt to the existing code. There might be some reason that a few classes currently share loggers, and I'd feel more comfortable looking at each of those in turn, rather than replacing everything at once.
        Hide
        Shawn Heisey added a comment -

        If there is a legitimate reason to share loggers, then there's no reason that the logger can't be created as it is now with the class name, but the majority of classes could use the utility method. We wouldn't necessarily need to use the utility for them all, but it would be a helpful pattern to use for the general case.

        Yes, devs will still have to self-enforce the use of "private static final" for the logger objects. I don't think there's anything that can be done to require it.

        Show
        Shawn Heisey added a comment - If there is a legitimate reason to share loggers, then there's no reason that the logger can't be created as it is now with the class name, but the majority of classes could use the utility method. We wouldn't necessarily need to use the utility for them all, but it would be a helpful pattern to use for the general case. Yes, devs will still have to self-enforce the use of "private static final" for the logger objects. I don't think there's anything that can be done to require it.
        Hide
        Mark Miller added a comment -

        Personally, I would not worry about a legit reason for sharing loggers. I don't believe it exists.

        Show
        Mark Miller added a comment - Personally, I would not worry about a legit reason for sharing loggers. I don't believe it exists.
        Hide
        Yonik Seeley added a comment -

        I guess it depends on how one views loggers.
        Classes can be implementation details. Different loggers (and logger configuration) are more interface than anything else. Hence if one does a little code refactoring (an implementation change... say pulling something out into a private utility class), does it always make sense to change the logger? My gut says no.

        But as I said in the email thread, the majority of the sharing cases may be due to laziness.

        Show
        Yonik Seeley added a comment - I guess it depends on how one views loggers. Classes can be implementation details. Different loggers (and logger configuration) are more interface than anything else. Hence if one does a little code refactoring (an implementation change... say pulling something out into a private utility class), does it always make sense to change the logger? My gut says no. But as I said in the email thread, the majority of the sharing cases may be due to laziness.
        Hide
        Shawn Heisey added a comment - - edited

        That [1] will probably need to be changed to [2] if the code is placed in a utility class, like I saw here:
        http://jira.qos.ch/browse/SLF4J-296

        Show
        Shawn Heisey added a comment - - edited That [1] will probably need to be changed to [2] if the code is placed in a utility class, like I saw here: http://jira.qos.ch/browse/SLF4J-296
        Hide
        Mark Miller added a comment -

        Much simpler to just give each class it's own logger. I don't think it matters either way, which is why I never worry about these changes.

        Show
        Mark Miller added a comment - Much simpler to just give each class it's own logger. I don't think it matters either way, which is why I never worry about these changes.
        Hide
        Uwe Schindler added a comment - - edited

        You can do this since Java 7, I now use this anywhere. The code uses a "trick". You need a so-called caller-sensitive method (marked @CallerSensitive) and somehow get the class it detected. Since Java 7 you can use MethodHandles.lookup(). This returns a lookup for the class that called the Lookup factory. The lookup has the class it was created for - and voilá you can use it

        import java.lang.invoke.MethodHandles;
        //...
        private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
        

        I use that pattern everywhere in my code now. Thanks also to the following blog post: http://marxsoftware.blogspot.de/2013/01/portable-logger-names-with-java7.html

        Show
        Uwe Schindler added a comment - - edited You can do this since Java 7, I now use this anywhere. The code uses a "trick". You need a so-called caller-sensitive method (marked @CallerSensitive) and somehow get the class it detected. Since Java 7 you can use MethodHandles.lookup(). This returns a lookup for the class that called the Lookup factory. The lookup has the class it was created for - and voilá you can use it import java.lang.invoke.MethodHandles; //... private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); I use that pattern everywhere in my code now. Thanks also to the following blog post: http://marxsoftware.blogspot.de/2013/01/portable-logger-names-with-java7.html
        Hide
        Uwe Schindler added a comment - - edited

        I would not do this. Creating a stack trace for every class is slow and not helpful if Hotspot optimized stack traces away (may happen!).

        The following code fragment is copypaste safe and works since Java 7 (and fast like hell because it uses the @CallerSensitive internal annotation in Java).

        The code uses a "trick": Since Java 7 you can use MethodHandles.lookup(). This returns a lookup for the class that called the Lookup factory. The lookup has the class it was created for - and voilá you can use it

        import java.lang.invoke.MethodHandles;
        //...
        private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
        

        I use that pattern everywhere in my code now. Thanks also to the following blog post: http://marxsoftware.blogspot.de/2013/01/portable-logger-names-with-java7.html

        Show
        Uwe Schindler added a comment - - edited I would not do this. Creating a stack trace for every class is slow and not helpful if Hotspot optimized stack traces away (may happen!). The following code fragment is copypaste safe and works since Java 7 (and fast like hell because it uses the @CallerSensitive internal annotation in Java). The code uses a "trick": Since Java 7 you can use MethodHandles.lookup(). This returns a lookup for the class that called the Lookup factory. The lookup has the class it was created for - and voilá you can use it import java.lang.invoke.MethodHandles; //... private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); I use that pattern everywhere in my code now. Thanks also to the following blog post: http://marxsoftware.blogspot.de/2013/01/portable-logger-names-with-java7.html
        Hide
        Uwe Schindler added a comment - - edited

        Works also in Java 7. And its fast like hell. Stack traces are slow. Also your code example is wrong. getClass() -> lookupClass()

        Show
        Uwe Schindler added a comment - - edited Works also in Java 7. And its fast like hell. Stack traces are slow. Also your code example is wrong. getClass() -> lookupClass()
        Hide
        Uwe Schindler added a comment -

        Much simpler to just give each class it's own logger. I don't think it matters either way, which is why I never worry about these changes.

        +1

        Show
        Uwe Schindler added a comment - Much simpler to just give each class it's own logger. I don't think it matters either way, which is why I never worry about these changes. +1
        Hide
        Uwe Schindler added a comment -

        FYI: Forbiddenapis cannot check for static/nonstatic logging patterns. You need to use something else. But you can use the Java 7+ MethodHandles trick to make a copypaste-safe template (that we may add to our Eclipse rules when creating new classes in Solr).

        Show
        Uwe Schindler added a comment - FYI: Forbiddenapis cannot check for static/nonstatic logging patterns. You need to use something else. But you can use the Java 7+ MethodHandles trick to make a copypaste-safe template (that we may add to our Eclipse rules when creating new classes in Solr).
        Hide
        Shawn Heisey added a comment -

        Thanks, Uwe!

        I did try and use MethodHandles when Mike mentioned it, but eclipse didn't offer me the option to import the class when I pasted that code in, so I thought Java 7 didn't have the option. Your code example included the import, so I pasted that into my test code first, and now it looks good.

        That code is compact enough that using a copy of it in every class doesn't worry me. The code using Thread and Stacktrace is quite verbose, and I get nervous when I see really long method chains and retrieval of specific array elements. Hearing that the code is slow is another reason to avoid it.

        Show
        Shawn Heisey added a comment - Thanks, Uwe! I did try and use MethodHandles when Mike mentioned it, but eclipse didn't offer me the option to import the class when I pasted that code in, so I thought Java 7 didn't have the option. Your code example included the import, so I pasted that into my test code first, and now it looks good. That code is compact enough that using a copy of it in every class doesn't worry me. The code using Thread and Stacktrace is quite verbose, and I get nervous when I see really long method chains and retrieval of specific array elements. Hearing that the code is slow is another reason to avoid it.
        Hide
        Uwe Schindler added a comment - - edited

        I did try and use MethodHandles when Mike mentioned it, but eclipse didn't offer me the option to import the class when I pasted that code in, so I thought Java 7 didn't have the option.

        Eclipse is sometimes not good to work with copypasted code. If you cklick on class names it used it is ery bad to resolve them correctly. If you type in the code char by char it works quite fine. If you type "MethodHandles." then it offers you the lookup() method asap (which imports while selecting it). It is indeed strange.

        Another pattern for logging I see very often is importless loggers. Because the logging code and its imports (for this pattern actually 3 imports: factory, logger, method handles) clutters the imports with stuff nowhere used in the class; many people declare their loggers with a single line using class names including packages. By this you dont need imports and its friendly for copypaste:

        private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(java.lang.invoke.MethodHandles.lookup().lookupClass());
        
        Show
        Uwe Schindler added a comment - - edited I did try and use MethodHandles when Mike mentioned it, but eclipse didn't offer me the option to import the class when I pasted that code in, so I thought Java 7 didn't have the option. Eclipse is sometimes not good to work with copypasted code. If you cklick on class names it used it is ery bad to resolve them correctly. If you type in the code char by char it works quite fine. If you type "MethodHandles." then it offers you the lookup() method asap (which imports while selecting it). It is indeed strange. Another pattern for logging I see very often is importless loggers. Because the logging code and its imports (for this pattern actually 3 imports: factory, logger, method handles) clutters the imports with stuff nowhere used in the class; many people declare their loggers with a single line using class names including packages. By this you dont need imports and its friendly for copypaste: private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(java.lang.invoke.MethodHandles.lookup().lookupClass());
        Hide
        Mike Drob added a comment -

        Ah, missed the lookupClass. Thanks for corroborating this.

        Show
        Mike Drob added a comment - Ah, missed the lookupClass. Thanks for corroborating this.
        Hide
        Mike Drob added a comment -

        I'll work on putting together a patch that uses the MethodHandles approach.

        Show
        Mike Drob added a comment - I'll work on putting together a patch that uses the MethodHandles approach.
        Hide
        Jason Gerlowski added a comment -

        Hey Mike, just an FYI- I've got a patch almost finished that uses the MethodHandles approach. There was a little bit of back and forth about it on SOLR-8330 ("Remove shared loggers" subtask), but I guess I should've mentioned that I'd started on it here as well. My bad.

        You're welcome to take it if you've also already started. Just wanted to let you know so we're not duplicating effort here.

        Show
        Jason Gerlowski added a comment - Hey Mike, just an FYI- I've got a patch almost finished that uses the MethodHandles approach. There was a little bit of back and forth about it on SOLR-8330 ("Remove shared loggers" subtask), but I guess I should've mentioned that I'd started on it here as well. My bad. You're welcome to take it if you've also already started. Just wanted to let you know so we're not duplicating effort here.
        Hide
        Mike Drob added a comment -

        I hadn't had a chance to start on the MethodHandles patch, feel free to continue on SOLR-8330. My progress is up on SOLR-8325, it might save you some effort to build on top of that.

        Show
        Mike Drob added a comment - I hadn't had a chance to start on the MethodHandles patch, feel free to continue on SOLR-8330 . My progress is up on SOLR-8325 , it might save you some effort to build on top of that.
        Hide
        Mike Drob added a comment -

        Closing this out since it looks like all of the child tasks are completed and there is no work left.

        Show
        Mike Drob added a comment - Closing this out since it looks like all of the child tasks are completed and there is no work left.

          People

          • Assignee:
            Unassigned
            Reporter:
            Mike Drob
          • Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development