Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc1
    • Fix Version/s: 2.1
    • Component/s: API
    • Labels:
      None

      Description

      I've got some ideas on how to improve the LoggerStream idea that I added a little while ago. The main thing I'd like to do is extract an interface from it, rename the default implementation to SimpleLoggerStream (part of the SimpleLogger stuff), and allow log4j implementations to specify a different implementation if desired.

      In doing this, I'm not sure where specifically I'd prefer the getStream methods to be. Right now, it's in Logger, but really, it could be in LoggerContext instead. I don't think I should be required to get a Logger just to get a LoggerStream.

      Now if only the java.io package used interfaces instead of classes. This would be so much easier to design!

      1. PerfTestCalcLocation.java
        2 kB
        Bruce Brouwer
      2. MyBenchmark.java
        3 kB
        Bruce Brouwer
      3. log4j2-loggerStream.patch
        14 kB
        Bruce Brouwer
      4. log4j2-547-remove-streams.patch
        24 kB
        Bruce Brouwer
      5. log4j2-547-new-module.patch
        117 kB
        Bruce Brouwer
      6. log4j2-547-builders.patch
        18 kB
        Bruce Brouwer
      7. log4j2-547-bbrouwer.patch
        81 kB
        Bruce Brouwer
      8. 0001-PrintStream-API-update.patch
        48 kB
        Matt Sicker

        Issue Links

          Activity

          Hide
          Matt Sicker added a comment -

          Here's what I had in mind.

          Show
          Matt Sicker added a comment - Here's what I had in mind.
          Hide
          Ralph Goers added a comment -

          After looking at the patch it makes me wonder if we shouldn't just remove the LoggerStream stuff entirely. At first glance it seems odd and complicated to have the LoggerStream move into the LoggerContext. After thinking about it I understand why this is a better approach, but I'm still wondering if there is any real benefit to supporting LoggerStream vs the cost of maintaining it.

          Show
          Ralph Goers added a comment - After looking at the patch it makes me wonder if we shouldn't just remove the LoggerStream stuff entirely. At first glance it seems odd and complicated to have the LoggerStream move into the LoggerContext. After thinking about it I understand why this is a better approach, but I'm still wondering if there is any real benefit to supporting LoggerStream vs the cost of maintaining it.
          Hide
          Bruce Brouwer added a comment - - edited

          In looking at LoggerStream, I can see how it could help me when shelling out to commands when all I want to do is log the output of that shelled command. There is some non-trivial stuff that LoggerStream is doing, so I don't want to get rid of that concept.

          But I agree that as it stands, the most helpful part of LoggerStream is actually the HelperStream. I'm including a patch that gets rid of LoggerStream and instead returns a plain old PrintWriter. This involved making a LoggerWriter which does basically what HelperStream did before.

          I don't see a whole lot of value adding this to the LoggerContext. In the end it needs an AbstractLogger anyway, so why not get it from the AbstractLogger.

          Oh, and I called the method .printWriter(...) instead of .getStream(...). First, the old .getStream didn't even return an OutputStream, it returned something that extended PrintWriter. And also, by removing the .get part, users might not expect to get the exact same PrintWriter instance each time they call it. In this case, I don't think I would want to get the same instance each time.

          Show
          Bruce Brouwer added a comment - - edited In looking at LoggerStream, I can see how it could help me when shelling out to commands when all I want to do is log the output of that shelled command. There is some non-trivial stuff that LoggerStream is doing, so I don't want to get rid of that concept. But I agree that as it stands, the most helpful part of LoggerStream is actually the HelperStream. I'm including a patch that gets rid of LoggerStream and instead returns a plain old PrintWriter. This involved making a LoggerWriter which does basically what HelperStream did before. I don't see a whole lot of value adding this to the LoggerContext. In the end it needs an AbstractLogger anyway, so why not get it from the AbstractLogger. Oh, and I called the method .printWriter(...) instead of .getStream(...). First, the old .getStream didn't even return an OutputStream, it returned something that extended PrintWriter. And also, by removing the .get part, users might not expect to get the exact same PrintWriter instance each time they call it. In this case, I don't think I would want to get the same instance each time.
          Hide
          Ralph Goers added a comment -

          I'm going to look at it a bit more after I apply the patch, but at first glance I like this patch a lot more.

          Show
          Ralph Goers added a comment - I'm going to look at it a bit more after I apply the patch, but at first glance I like this patch a lot more.
          Hide
          Matt Sicker added a comment -

          I like this print writer patch better, too. The only reason my patch started getting complicated was due to the call stack getting weird if you didn't make a decorate class for PrintStream or similar. Then it became next to impossible to figure out the calling class to construct it properly.

          Show
          Matt Sicker added a comment - I like this print writer patch better, too. The only reason my patch started getting complicated was due to the call stack getting weird if you didn't make a decorate class for PrintStream or similar. Then it became next to impossible to figure out the calling class to construct it properly.
          Hide
          Ralph Goers added a comment -

          Bruce's patch was applied in revision 1573212. Please verify that this addresses the problem and works and then close.

          Show
          Ralph Goers added a comment - Bruce's patch was applied in revision 1573212. Please verify that this addresses the problem and works and then close.
          Hide
          Bruce Brouwer added a comment -

          One thing I noticed I missed. We might want to synchronize on buf in the close() method.

          Show
          Bruce Brouwer added a comment - One thing I noticed I missed. We might want to synchronize on buf in the close() method.
          Hide
          Bruce Brouwer added a comment -

          Also, you should be able to delete LoggerStream and LoggerStreamTest

          Show
          Bruce Brouwer added a comment - Also, you should be able to delete LoggerStream and LoggerStreamTest
          Hide
          Matt Sicker added a comment -

          Just as I suspected. By not decorating PrintWriter, now the calling information says that java.io.Writer is the calling class.

          Show
          Matt Sicker added a comment - Just as I suspected. By not decorating PrintWriter, now the calling information says that java.io.Writer is the calling class.
          Hide
          Bruce Brouwer added a comment -

          I wasn't picking up on that. I'll take a look at it. I think I know now what you're saying the problem is.

          Show
          Bruce Brouwer added a comment - I wasn't picking up on that. I'll take a look at it. I think I know now what you're saying the problem is.
          Hide
          Matt Sicker added a comment -

          Needs correct caller information. I'll submit a patch for the unit tests in just a moment.

          Show
          Matt Sicker added a comment - Needs correct caller information. I'll submit a patch for the unit tests in just a moment.
          Hide
          Matt Sicker added a comment -

          Here's a unit test to demonstrate the calling class and calling method information. Originally, I was going to split the two test methods into four, but really, they're both testing the same functionality, so it made sense to combine them. As you can see, running the tests on the current trunk will fail, but only once it gets to verifying the contents of the log message created via the print writer.

          Show
          Matt Sicker added a comment - Here's a unit test to demonstrate the calling class and calling method information. Originally, I was going to split the two test methods into four, but really, they're both testing the same functionality, so it made sense to combine them. As you can see, running the tests on the current trunk will fail, but only once it gets to verifying the contents of the log message created via the print writer.
          Hide
          Bruce Brouwer added a comment - - edited

          Thanks, I'll use those unit tests.

          Here's what I was thinking and a quick spike proved it works. If I pass the FQCN to the LoggerWriter and make the FQCN=java.io.PrintWriter, I get the correct call information. I don't have to decorate any classes. But is that too hacky to give PrintWriter as the FQCN to the LoggerWriter?

          Also, I didn't realize initially that you were using PrintStream, not PrintWriter. In some ways, I prefer your idea of using PrintStream. It is easier to turn a PrintStream into a PrintWriter than the other way around. Or do you think there is value in keeping both?

          Show
          Bruce Brouwer added a comment - - edited Thanks, I'll use those unit tests. Here's what I was thinking and a quick spike proved it works. If I pass the FQCN to the LoggerWriter and make the FQCN=java.io.PrintWriter, I get the correct call information. I don't have to decorate any classes. But is that too hacky to give PrintWriter as the FQCN to the LoggerWriter? Also, I didn't realize initially that you were using PrintStream, not PrintWriter. In some ways, I prefer your idea of using PrintStream. It is easier to turn a PrintStream into a PrintWriter than the other way around. Or do you think there is value in keeping both?
          Hide
          Matt Sicker added a comment -

          Yeah, I chose PrintStream originally because you could just wrap it in a PrintWriter. Using java.io.PrintWriter as the FQCN doesn't seem too hacky considering that's the class being used for method calls. I wasn't sure that would work properly, though, as it the call stack then depends on which method in PrintWriter you call (which can differ based on the JDK in use at the time and the internal class structure). If you've got more than one JDK installed, it would be good to test out any fix in as many different environments as possible (e.g., JDK 6, 7, 8, and even a different JVM if possible like JRockit).

          Show
          Matt Sicker added a comment - Yeah, I chose PrintStream originally because you could just wrap it in a PrintWriter. Using java.io.PrintWriter as the FQCN doesn't seem too hacky considering that's the class being used for method calls. I wasn't sure that would work properly, though, as it the call stack then depends on which method in PrintWriter you call (which can differ based on the JDK in use at the time and the internal class structure). If you've got more than one JDK installed, it would be good to test out any fix in as many different environments as possible (e.g., JDK 6, 7, 8, and even a different JVM if possible like JRockit).
          Hide
          Bruce Brouwer added a comment - - edited

          So, I've been thinking about the actual use case for this feature. I was thinking it would be even more helpful if I grabbed a writer that actually wrapped another writer. This way I could "spy" on the writer and send all its content to a Logger and to the actual writer. I'm thinking of a method signatures like this:

          public Writer writer(Writer writer, Level level);
          public Writer writer(Writer writer, Marker marker, Level level);
          public OutputStream stream(OutputStream stream, Level level);
          public OutputStream stream(OutputStream stream, Marker marker, Level level);
          

          We could also provide ones basically like before:

          public Writer writer(Level level);
          public Writer writer(Marker marker, Level level);
          public OutputStream stream(Level level);
          public OutputStream stream(Marker marker, Level level);
          

          Maybe we would keep the PrintWriter/PrintStream variants as well. But then why stop there. We could spy on Readers as well:

          public Reader reader(Reader reader, Level level);
          public Reader reader(Reader reader, Marker marker, Level level);
          public InputStream stream(InputStream stream, Level level);
          public InputStream stream(InputStream stream, Marker marker, Level level);
          

          Making this all work is not really any harder than what is already there.

          But now we're starting to really pollute the Logger interface with stuff that 99% of the time I'll never want or use. What if we took it a different direction and didn't put these reader/writer methods on Logger, but instead put them on LogManager or even a new class LogStreaming. Now I could get one of these things with code like this:

          Writer writer = LogStreaming.writer(MyExample.class, myWriter, Level.WARNING);
          

          We could go even further and add debug/warn/info/error methods on here as well:

          Writer writer = LogStreaming.debugWriter(MyExample.class, myWriter);
          

          This goes along with another idea I had in LOG4J-242 which would make a fluent interface for log4j. I eventually decided that all that stuff doesn't belong in Logger either, so instead I would want a FluentLogManager instead of LogManager.

          Now back to the whole FQCN thing. If I do the hack I mentioned coupled with these new methods I described, if I were to pass in a PrintWriter to this writer method, then using the FQCN of PrintWriter will determine the caller is the caller of the PrintWriter I passed in, and not the one being created by the writer method.

          Furthermore, the reason I would want one of these Writers is to pass to some function that expects a Writer, and therefore the call stack will not be from my code anyway and then the caller location probably won't be as useful to me as I would want.

          So, what are your thoughts on all of these ideas? Am I making this more complicated than it should be?

          Show
          Bruce Brouwer added a comment - - edited So, I've been thinking about the actual use case for this feature. I was thinking it would be even more helpful if I grabbed a writer that actually wrapped another writer. This way I could "spy" on the writer and send all its content to a Logger and to the actual writer. I'm thinking of a method signatures like this: public Writer writer(Writer writer, Level level); public Writer writer(Writer writer, Marker marker, Level level); public OutputStream stream(OutputStream stream, Level level); public OutputStream stream(OutputStream stream, Marker marker, Level level); We could also provide ones basically like before: public Writer writer(Level level); public Writer writer(Marker marker, Level level); public OutputStream stream(Level level); public OutputStream stream(Marker marker, Level level); Maybe we would keep the PrintWriter/PrintStream variants as well. But then why stop there. We could spy on Readers as well: public Reader reader(Reader reader, Level level); public Reader reader(Reader reader, Marker marker, Level level); public InputStream stream(InputStream stream, Level level); public InputStream stream(InputStream stream, Marker marker, Level level); Making this all work is not really any harder than what is already there. But now we're starting to really pollute the Logger interface with stuff that 99% of the time I'll never want or use. What if we took it a different direction and didn't put these reader/writer methods on Logger, but instead put them on LogManager or even a new class LogStreaming. Now I could get one of these things with code like this: Writer writer = LogStreaming.writer(MyExample.class, myWriter, Level.WARNING); We could go even further and add debug/warn/info/error methods on here as well: Writer writer = LogStreaming.debugWriter(MyExample.class, myWriter); This goes along with another idea I had in LOG4J-242 which would make a fluent interface for log4j. I eventually decided that all that stuff doesn't belong in Logger either, so instead I would want a FluentLogManager instead of LogManager. Now back to the whole FQCN thing. If I do the hack I mentioned coupled with these new methods I described, if I were to pass in a PrintWriter to this writer method, then using the FQCN of PrintWriter will determine the caller is the caller of the PrintWriter I passed in, and not the one being created by the writer method. Furthermore, the reason I would want one of these Writers is to pass to some function that expects a Writer, and therefore the call stack will not be from my code anyway and then the caller location probably won't be as useful to me as I would want. So, what are your thoughts on all of these ideas? Am I making this more complicated than it should be?
          Hide
          Gary Gregory added a comment -

          This streaming aspect of Log4j2 really looks and feels so different from what we started with that I agree, it should not live in the Logger interface.

          You could hang the factory methods in LogManager, I like having ONE root class. LogStreaming is not a great name, if you MUST have a separate class, maybe StreamingLogManager or LogManagerStreams...

          Show
          Gary Gregory added a comment - This streaming aspect of Log4j2 really looks and feels so different from what we started with that I agree, it should not live in the Logger interface. You could hang the factory methods in LogManager, I like having ONE root class. LogStreaming is not a great name, if you MUST have a separate class, maybe StreamingLogManager or LogManagerStreams...
          Hide
          Matt Sicker added a comment - - edited

          I'm starting to see two ways this can go: as part of the API, or a separate module dependent on log4j-api (similar to fluent-hc from HttpComponents). I like the idea of going the full java.io route for spying and such (which can help log I/O as well as provide a path for logger-less code to transition to real loggers).

          As for the one root class, of course LogManager should have the API available to create the streams and reader/writers, but that could easily be delegated just like how most of the methods in LogManager already delegate to a LoggerContextFactory.

          Edit: if we made a fluent API, it would definitely make sense to put it in its own module such as fluent-logging or log4j-fluent (more consistent naming there at least). Fluent APIs are neat, but they're also limited in functionality (which is the point) and really belong in separate modules. Then again, I'm all about modules lately, so I might be a bit biased.

          Show
          Matt Sicker added a comment - - edited I'm starting to see two ways this can go: as part of the API, or a separate module dependent on log4j-api (similar to fluent-hc from HttpComponents). I like the idea of going the full java.io route for spying and such (which can help log I/O as well as provide a path for logger-less code to transition to real loggers). As for the one root class, of course LogManager should have the API available to create the streams and reader/writers, but that could easily be delegated just like how most of the methods in LogManager already delegate to a LoggerContextFactory. Edit: if we made a fluent API, it would definitely make sense to put it in its own module such as fluent-logging or log4j-fluent (more consistent naming there at least). Fluent APIs are neat, but they're also limited in functionality (which is the point) and really belong in separate modules. Then again, I'm all about modules lately, so I might be a bit biased.
          Hide
          Bruce Brouwer added a comment -

          Matt, you're going down the exact same thought-path I am.

          The way I'm looking at it, there are a number of alternate log4j interfaces available, some of which haven't come to light yet. There's the slf4j interface and the jcl interface. I'm starting to think of this streaming API in the same light, putting it in log4j-streaming. And I agree, my fluent api should go in another module: log4j-fluent.

          I like keeping the Logger interface more along the lines of the "classic" log4j interface without adding a bunch of other methods. Because of my viewpoint, I would prefer having a different root class that accessed this streaming API. I don't have a strong preference for the actual name, I kind of like StreamingLogManager. This new root class would live in log4j-streaming and not impact the classic nature of the LogManager interface.

          Is it too big of a change to introduce a new artifact this late in the game? Should the streaming API be pushed off to 2.1? But I like how there is general agreement to get it out of Logger.

          Show
          Bruce Brouwer added a comment - Matt, you're going down the exact same thought-path I am. The way I'm looking at it, there are a number of alternate log4j interfaces available, some of which haven't come to light yet. There's the slf4j interface and the jcl interface. I'm starting to think of this streaming API in the same light, putting it in log4j-streaming. And I agree, my fluent api should go in another module: log4j-fluent. I like keeping the Logger interface more along the lines of the "classic" log4j interface without adding a bunch of other methods. Because of my viewpoint, I would prefer having a different root class that accessed this streaming API. I don't have a strong preference for the actual name, I kind of like StreamingLogManager. This new root class would live in log4j-streaming and not impact the classic nature of the LogManager interface. Is it too big of a change to introduce a new artifact this late in the game? Should the streaming API be pushed off to 2.1? But I like how there is general agreement to get it out of Logger.
          Hide
          Matt Sicker added a comment -

          Considering the OSGi support tends to introduce more new modules every time we do anything with it, I don't think that additional modules are all that big a deal. It's important that each module does one thing and does it well. For convenience reasons, it's easy to just add log4j-core to your classpath and not worry too much, but it's also gotten rather bloated in terms of features when you look at it from a modular perspective.

          When it comes to doing things this late in the game, I was under the impression that any API changes and such should be all done before 2.0.0.RELEASE (or whatever it will be called; I like that name for the OSGi version because RELEASE comes alphabetically after RC, so it's considered a "newer" version according to OSGi versioning standards as well as Maven). However, adding API (not changing it, but adding to it) is perfectly fine in 2.x releases according to the usual semantic versioning standards.

          The tl;dr of this is that I'd support holding off introducing the streaming/java.io API until 2.1. However, if we did that, I would highly suggest removing the existing PrintStream/LoggerStream functionality to prevent future API headaches.

          Show
          Matt Sicker added a comment - Considering the OSGi support tends to introduce more new modules every time we do anything with it, I don't think that additional modules are all that big a deal. It's important that each module does one thing and does it well. For convenience reasons, it's easy to just add log4j-core to your classpath and not worry too much, but it's also gotten rather bloated in terms of features when you look at it from a modular perspective. When it comes to doing things this late in the game, I was under the impression that any API changes and such should be all done before 2.0.0.RELEASE (or whatever it will be called; I like that name for the OSGi version because RELEASE comes alphabetically after RC, so it's considered a "newer" version according to OSGi versioning standards as well as Maven). However, adding API (not changing it, but adding to it) is perfectly fine in 2.x releases according to the usual semantic versioning standards. The tl;dr of this is that I'd support holding off introducing the streaming/java.io API until 2.1. However, if we did that, I would highly suggest removing the existing PrintStream/LoggerStream functionality to prevent future API headaches.
          Hide
          Gary Gregory added a comment -

          Please, not another jar.

          Show
          Gary Gregory added a comment - Please, not another jar.
          Hide
          Matt Sicker added a comment -

          For the streaming interface? Sure, it makes sense as part of the normal API. The OSGi bundles, however, are meant to be split up into several JARs. It doesn't affect you if you just use log4j-core outside of an OSGi environment. For OSGi users, though, it would be nice to only have to load the bundles relevant to your configuration needs.

          Show
          Matt Sicker added a comment - For the streaming interface? Sure, it makes sense as part of the normal API. The OSGi bundles, however, are meant to be split up into several JARs. It doesn't affect you if you just use log4j-core outside of an OSGi environment. For OSGi users, though, it would be nice to only have to load the bundles relevant to your configuration needs.
          Hide
          Bruce Brouwer added a comment -

          If we were going to put the streaming interface in -core or -api, then I agree with Gary that there is no use for another JAR. If, however, we decide this streaming API isn't part of the core of log4j (as I am of the opinion), then I vote to put that in a -streaming JAR. That would include StreamingLogManager.

          I personally don't mind the extra JAR if it requires me to explicitly choose to include it for the desired functionality (like slf4j or jcl). I'm a big user of Spring and I felt the same way when they broke that up into a whole bunch of JARs. Now it just seems like common practice to have smaller, more targeted JARs. Sometimes it can be a pain to know which jar has a particular class, but http://search.maven.org class search makes that easy to figure out.

          Do you think we can gain consensus to just remove it completely until after 2.0 is released? Maybe some time will help us settle on a direction.

          Show
          Bruce Brouwer added a comment - If we were going to put the streaming interface in -core or -api, then I agree with Gary that there is no use for another JAR. If, however, we decide this streaming API isn't part of the core of log4j (as I am of the opinion), then I vote to put that in a -streaming JAR. That would include StreamingLogManager. I personally don't mind the extra JAR if it requires me to explicitly choose to include it for the desired functionality (like slf4j or jcl). I'm a big user of Spring and I felt the same way when they broke that up into a whole bunch of JARs. Now it just seems like common practice to have smaller, more targeted JARs. Sometimes it can be a pain to know which jar has a particular class, but http://search.maven.org class search makes that easy to figure out. Do you think we can gain consensus to just remove it completely until after 2.0 is released? Maybe some time will help us settle on a direction.
          Hide
          Matt Sicker added a comment -

          I think it would depend on how many classes the streaming interface would really add. While I do like using proper modularity for things, it does make it a hassle to use without a corresponding bom. For example, search for "arquillian" on search.maven.org and tell me that's not a pain in the ass without the bom pom specifying all the proper version numbers to use for its various modules. I think it's a neat idea in theory, but in practice, there needs to be better documentation.

          Speaking of Spring and splitting everything up like that, I came across that issue in a rather direct way: the javadocs for Spring Framework specify all these neat classes available, but in reality, you could end up specifying like 10 JARs just to get things you thought were all in the core framework. There's certainly a documentation problem.

          Show
          Matt Sicker added a comment - I think it would depend on how many classes the streaming interface would really add. While I do like using proper modularity for things, it does make it a hassle to use without a corresponding bom. For example, search for "arquillian" on search.maven.org and tell me that's not a pain in the ass without the bom pom specifying all the proper version numbers to use for its various modules. I think it's a neat idea in theory, but in practice, there needs to be better documentation. Speaking of Spring and splitting everything up like that, I came across that issue in a rather direct way: the javadocs for Spring Framework specify all these neat classes available, but in reality, you could end up specifying like 10 JARs just to get things you thought were all in the core framework. There's certainly a documentation problem.
          Hide
          Gary Gregory added a comment -

          This clearly belongs in the api and/or core, not in a separate jar. The api and/or core part depends on whether you want underlying implementations to change based on the backend (log4j, slf4j, and so on).

          Just redo the code now, it has our attention and momentum now.

          Show
          Gary Gregory added a comment - This clearly belongs in the api and/or core, not in a separate jar. The api and/or core part depends on whether you want underlying implementations to change based on the backend (log4j, slf4j, and so on). Just redo the code now, it has our attention and momentum now.
          Hide
          Bruce Brouwer added a comment -

          Yes, the default search in search.maven.org can yield a ton of stuff. I'm talking about the advanced search where you can specify a fully qualified class name. And I agree, the Spring docs don't make it clear enough which JARs you need for any particular feature.

          As for the bom, that's a great idea. I created LOG4J2-558.

          Show
          Bruce Brouwer added a comment - Yes, the default search in search.maven.org can yield a ton of stuff. I'm talking about the advanced search where you can specify a fully qualified class name. And I agree, the Spring docs don't make it clear enough which JARs you need for any particular feature. As for the bom, that's a great idea. I created LOG4J2-558 .
          Hide
          Gary Gregory added a comment -

          Telling people they have to search some website to locate a class A in a jar B... is just nonesense and a barrier to sane development. Then class B shows up in jar A and B, then it depends what version, bleh. I beg projects to provide all-in-one jars and be done with it. Optimizing for size on disk/downloads can be done later if its a bottle neck...

          Show
          Gary Gregory added a comment - Telling people they have to search some website to locate a class A in a jar B... is just nonesense and a barrier to sane development. Then class B shows up in jar A and B, then it depends what version, bleh. I beg projects to provide all-in-one jars and be done with it. Optimizing for size on disk/downloads can be done later if its a bottle neck...
          Hide
          Bruce Brouwer added a comment -

          It sounds like the log4j team supports keeping this in core. I will put together a patch unless anyone else volunteers.

          I'll put the factory methods in LogManager as this being considered part of the core of log4j.

          Show
          Bruce Brouwer added a comment - It sounds like the log4j team supports keeping this in core. I will put together a patch unless anyone else volunteers. I'll put the factory methods in LogManager as this being considered part of the core of log4j.
          Hide
          Bruce Brouwer added a comment -

          Ok, I need a bit of advice. In LogManager, I get access to a Logger. Is it ok to just cast that to AbstractLogger or is there some better way?

          Show
          Bruce Brouwer added a comment - Ok, I need a bit of advice. In LogManager, I get access to a Logger. Is it ok to just cast that to AbstractLogger or is there some better way?
          Hide
          Remko Popma added a comment -

          If you need AbstractLogger functionality that is not in the Logger interface you have little choice but to fail if this is not available... So casting is okay, I think.

          Show
          Remko Popma added a comment - If you need AbstractLogger functionality that is not in the Logger interface you have little choice but to fail if this is not available... So casting is okay, I think.
          Hide
          Bruce Brouwer added a comment -

          Here is my solution to LoggerStream (log4j2-547-bbrouwer.patch). It includes logger versions of InputStream, BufferedInputStream, Reader, BufferedReader, OutputStream, PrintStream, Writer and PrintWriter.

          Something missing from the current LoggerPrintStream is that it cannot handle character sets other than the default system character set. In this patch, InputStream, BufferedInputStream, OutputStream and PrintStream can all handle any specified character set. Supporting other character sets is the reason for some of the extra complexity in this patch.

          Also, because of the wide variety of options for creating them, there are multiple constructors to all of these classes. This goes with the spirit of the corresponding classes in Java where they are created by calling their constructors.

          Because of the wide variety of options, this would add a significant amount of new methods on the LogManager interface. I am proposing that we not do that. As directed, I put this in log4j-api, but I want to make one last request that this not be included in log4j-api but rather in a new artifact called log4j-streams. These new classes stand alone on their own and I see little value in adding corresponding factory methods in LogManager for each constructor specified by these classes.

          This patch relies on my latest patch in LOG4J2-555 and because of the overlap with some classes in the LOG4J-555 patch, I am not able to cleanly provide a patch that gets rid of LoggerStream and LoggerWriter and the existing printStream and printWriter methods in LogManager. It is my intent that these all be removed should this patch be accepted.

          Show
          Bruce Brouwer added a comment - Here is my solution to LoggerStream (log4j2-547-bbrouwer.patch). It includes logger versions of InputStream, BufferedInputStream, Reader, BufferedReader, OutputStream, PrintStream, Writer and PrintWriter. Something missing from the current LoggerPrintStream is that it cannot handle character sets other than the default system character set. In this patch, InputStream, BufferedInputStream, OutputStream and PrintStream can all handle any specified character set. Supporting other character sets is the reason for some of the extra complexity in this patch. Also, because of the wide variety of options for creating them, there are multiple constructors to all of these classes. This goes with the spirit of the corresponding classes in Java where they are created by calling their constructors. Because of the wide variety of options, this would add a significant amount of new methods on the LogManager interface. I am proposing that we not do that. As directed, I put this in log4j-api, but I want to make one last request that this not be included in log4j-api but rather in a new artifact called log4j-streams. These new classes stand alone on their own and I see little value in adding corresponding factory methods in LogManager for each constructor specified by these classes. This patch relies on my latest patch in LOG4J2-555 and because of the overlap with some classes in the LOG4J-555 patch, I am not able to cleanly provide a patch that gets rid of LoggerStream and LoggerWriter and the existing printStream and printWriter methods in LogManager. It is my intent that these all be removed should this patch be accepted.
          Hide
          Matt Sicker added a comment -

          Thanks for reminding me. I added the unit tests. Bruce, could you add a couple tests to log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/CallerInformationTest.java to verify caller information correctness?

          Show
          Matt Sicker added a comment - Thanks for reminding me. I added the unit tests. Bruce, could you add a couple tests to log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/CallerInformationTest.java to verify caller information correctness?
          Hide
          Bruce Brouwer added a comment -

          So, I put all this stream stuff in package org.apache.logging.log4j.streams inside the log4j-api project. It seems awkward to me to put these tests inside log4j-core when the code it is testing is inside log4j-api. To me, it seems like another reason to pull this into its own artifact called log4j-streams. This way there is nothing related to these streams in log4j-api, and the log4j-streams artifact could pull in log4j-core as a test dependency for the purpose of making this caller information test.

          I'm going to make some separate caller-info test classes inside log4j-core, but in the org.apache.logging.log4j.streams package (not org.apache.logging.log4j.core.streams) just so we can look at what we are talking about, but I don't expect things to stay where they are represented in my next patch.

          Show
          Bruce Brouwer added a comment - So, I put all this stream stuff in package org.apache.logging.log4j.streams inside the log4j-api project. It seems awkward to me to put these tests inside log4j-core when the code it is testing is inside log4j-api. To me, it seems like another reason to pull this into its own artifact called log4j-streams. This way there is nothing related to these streams in log4j-api, and the log4j-streams artifact could pull in log4j-core as a test dependency for the purpose of making this caller information test. I'm going to make some separate caller-info test classes inside log4j-core, but in the org.apache.logging.log4j.streams package (not org.apache.logging.log4j. core .streams ) just so we can look at what we are talking about, but I don't expect things to stay where they are represented in my next patch.
          Hide
          Bruce Brouwer added a comment -

          It was definitely a good call to write these tests. I'm running into all kinds of trouble. The various InputStream and Reader tests were easy to fix, but I'm struggling to see what should be done with PrintStream. Check out this call stack:

          LoggerPrintStream.write(byte[], int, int) line: 113	
          StreamEncoder.writeBytes() line: 221 [local variables unavailable]	
          StreamEncoder.implFlushBuffer() line: 291 [local variables unavailable]	
          StreamEncoder.flushBuffer() line: 104 [local variables unavailable]	
          OutputStreamWriter.flushBuffer() line: 185 [local variables unavailable]	
          LoggerPrintStream(PrintStream).write(char[]) line: 505	
          LoggerPrintStream(PrintStream).print(char[]) line: 653	
          LoggerPrintStream.print(char[]) line: 158	
          LoggerPrintStream(PrintStream).println(char[]) line: 792	
          LoggerPrintStream.println(char[]) line: 208	
          LoggerPrintStreamCallerInfoTest.print_chararray() line: 74	
          

          The FQCN logic trips up pretty quickly as it looks at that top element, which is the FQCN it is looking for, so it return the next item down in the call stack, which is sun.nio.cs.StreamEncoder. The only thing I can think of to make this work is to go back to the way this was before I started messing around with this and LoggerPrintStream simply delegates to another PrintStream.

          Should this delegate mechanism be what we use for all of these streams?

          Show
          Bruce Brouwer added a comment - It was definitely a good call to write these tests. I'm running into all kinds of trouble. The various InputStream and Reader tests were easy to fix, but I'm struggling to see what should be done with PrintStream. Check out this call stack: LoggerPrintStream.write( byte [], int , int ) line: 113 StreamEncoder.writeBytes() line: 221 [local variables unavailable] StreamEncoder.implFlushBuffer() line: 291 [local variables unavailable] StreamEncoder.flushBuffer() line: 104 [local variables unavailable] OutputStreamWriter.flushBuffer() line: 185 [local variables unavailable] LoggerPrintStream(PrintStream).write( char []) line: 505 LoggerPrintStream(PrintStream).print( char []) line: 653 LoggerPrintStream.print( char []) line: 158 LoggerPrintStream(PrintStream).println( char []) line: 792 LoggerPrintStream.println( char []) line: 208 LoggerPrintStreamCallerInfoTest.print_chararray() line: 74 The FQCN logic trips up pretty quickly as it looks at that top element, which is the FQCN it is looking for, so it return the next item down in the call stack, which is sun.nio.cs.StreamEncoder . The only thing I can think of to make this work is to go back to the way this was before I started messing around with this and LoggerPrintStream simply delegates to another PrintStream. Should this delegate mechanism be what we use for all of these streams?
          Hide
          Remko Popma added a comment -

          Interesting. This looks like a problem in the stack trace-walking logic to me: it ignores the possibility that the FQCN appears multiple times and assumes the first hit is the correct one. If the strack trace-walking logic were to read bottom-up it would correctly return LoggerPrintStreamCallerInfoTest.print_chararray() line: 74 as the location, no?

          Show
          Remko Popma added a comment - Interesting. This looks like a problem in the stack trace-walking logic to me: it ignores the possibility that the FQCN appears multiple times and assumes the first hit is the correct one. If the strack trace-walking logic were to read bottom-up it would correctly return LoggerPrintStreamCallerInfoTest.print_chararray() line: 74 as the location, no?
          Hide
          Bruce Brouwer added a comment -

          Yes, walking bottom-up would definitely solve this problem and would work in probably 99% of cases. One cost, though, that I can think of is that usually the entry we are looking for is usually closest to the top of the stack trace, not the bottom. So there might be a performance hit in the bottom-up approach.

          Also, in this case, I could theoretically pass a a LoggerPrintStream wrapping a FilterOutputStream wrapping another LoggerPrintStream. I have no idea why anyone would do that, but in this situation, the top down approach would be the only way that could identify the correct caller info.

          I'm not prepared to advocate for switching to a bottom-up approach, but if you thought it was best, I would be in support of it.

          If, we don't go for bottom-up, then I'll have to switch this to a delegating pattern, rather than simply subclassing PrintWriter.

          Show
          Bruce Brouwer added a comment - Yes, walking bottom-up would definitely solve this problem and would work in probably 99% of cases. One cost, though, that I can think of is that usually the entry we are looking for is usually closest to the top of the stack trace, not the bottom. So there might be a performance hit in the bottom-up approach. Also, in this case, I could theoretically pass a a LoggerPrintStream wrapping a FilterOutputStream wrapping another LoggerPrintStream. I have no idea why anyone would do that, but in this situation, the top down approach would be the only way that could identify the correct caller info. I'm not prepared to advocate for switching to a bottom-up approach, but if you thought it was best, I would be in support of it. If, we don't go for bottom-up, then I'll have to switch this to a delegating pattern, rather than simply subclassing PrintWriter.
          Hide
          Remko Popma added a comment -

          FYI, this logic lives in Log4JLogEvent#calcLocation; I think the expensive part of this method is the call to Thread.currentThread().getStackTrace(), and looping over the resulting array to do String comparisons is relatively cheap. So I suspect the performance impact would be minimal. (On the other hand I have seen Spring-based applications with ridiculously deep stack traces, and it does all add up, so you could be right...)

          About the corner case of LoggerPrintStream #1 (providing the FQCN) wrapping a FilterOutputStream, wrapping another LoggerPrintStream #2 (also providing an FQCN), wouldn't the stack trace look like the below, so only the bottom-up approach would give correct results?

          LoggerPrintStream.someMethod() 
          FilterOutputStream.someMethod() 
          LoggerPrintStream.someMethod() 
          ApplicationClass_TheCaller.theMethod() <-- the calling class we want to print in location info
          
          Show
          Remko Popma added a comment - FYI, this logic lives in Log4JLogEvent#calcLocation ; I think the expensive part of this method is the call to Thread.currentThread().getStackTrace() , and looping over the resulting array to do String comparisons is relatively cheap. So I suspect the performance impact would be minimal. (On the other hand I have seen Spring-based applications with ridiculously deep stack traces, and it does all add up, so you could be right...) About the corner case of LoggerPrintStream #1 (providing the FQCN) wrapping a FilterOutputStream, wrapping another LoggerPrintStream #2 (also providing an FQCN), wouldn't the stack trace look like the below, so only the bottom-up approach would give correct results? LoggerPrintStream.someMethod() FilterOutputStream.someMethod() LoggerPrintStream.someMethod() ApplicationClass_TheCaller.theMethod() <-- the calling class we want to print in location info
          Hide
          Ralph Goers added a comment -

          I would not be in favor of reversing the processing of the stack. When I was working with the Liferay portal it would have stacks that had hundreds of entries. I am sure that in cases such as this (which I doubt is unusual) I would expect there to be a noticeable hit in performance.

          I am still wondering if supporting streams is more trouble than it is worth. I'm tempted to say it should go in some sort of "extras" library. I am at the point where I don't think we can throw everything everybody wants into the main project.

          Show
          Ralph Goers added a comment - I would not be in favor of reversing the processing of the stack. When I was working with the Liferay portal it would have stacks that had hundreds of entries. I am sure that in cases such as this (which I doubt is unusual) I would expect there to be a noticeable hit in performance. I am still wondering if supporting streams is more trouble than it is worth. I'm tempted to say it should go in some sort of "extras" library. I am at the point where I don't think we can throw everything everybody wants into the main project.
          Hide
          Matt Sicker added a comment -

          I'm thirding the +1 for putting this in a separate module such as log4j-stream. I know that I'd find it useful in this shitty framework I have to use at work (ATG, damn Oracle product they don't care about anymore since they bought the company ATG) where plenty of their classes use PrintStream-logging where you provide a PrintStream for various methods or classes to log to (even though they provide a sort of commons-logging style API in the first place!).

          Show
          Matt Sicker added a comment - I'm thirding the +1 for putting this in a separate module such as log4j-stream. I know that I'd find it useful in this shitty framework I have to use at work (ATG, damn Oracle product they don't care about anymore since they bought the company ATG) where plenty of their classes use PrintStream-logging where you provide a PrintStream for various methods or classes to log to (even though they provide a sort of commons-logging style API in the first place!).
          Hide
          Bruce Brouwer added a comment -

          My comments of performance were me remembering the code I saw in ClassLoaderContextSelector, which I think actually doesn't come into play in this scenario. So, it probably is as simple as getting the stack trace (the expensive part) and iterating over the list doing a few string comparisons (maybe a few hundred). Would it help if I made a little performance test comparison?

          As for my comment about top-down being more technically correct, I was thinking that in the short stack trace example that Remko outlined, I think the top LoggerPrintStream should report its caller as FilterOutputStream.someMethod(), not ApplicationClass_TheCaller.theMethod(). However, in probably 90%+ of cases, the more useful caller to report would be ApplicationClass_TheCaller.theMethod(), which would be discovered by the bottom-up approach. It's an interesting edge case, but probably not worth worrying about.

          Show
          Bruce Brouwer added a comment - My comments of performance were me remembering the code I saw in ClassLoaderContextSelector , which I think actually doesn't come into play in this scenario. So, it probably is as simple as getting the stack trace (the expensive part) and iterating over the list doing a few string comparisons (maybe a few hundred). Would it help if I made a little performance test comparison? As for my comment about top-down being more technically correct, I was thinking that in the short stack trace example that Remko outlined, I think the top LoggerPrintStream should report its caller as FilterOutputStream.someMethod() , not ApplicationClass_TheCaller.theMethod() . However, in probably 90%+ of cases, the more useful caller to report would be ApplicationClass_TheCaller.theMethod() , which would be discovered by the bottom-up approach. It's an interesting edge case, but probably not worth worrying about.
          Hide
          Bruce Brouwer added a comment -

          I decided to run a quick performance test. You can see the tester code in PerfTestCalcLocation.java, which I attached. The alternate calcLocation code I wrote looks like this (which is actually much simpler than the current code:

          public static StackTraceElement calcLocation2(final String fqcnOfLogger) {
              if (fqcnOfLogger == null) {
                  return null;
              }
              final StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
          
              // start 2 below, just in case the last entry happens to match the FQCN
              for (int i = stackTrace.length - 2; i >= 0; i--) {
                  if (fqcnOfLogger.equals(stackTrace[i].getClassName())) {
                      return stackTrace[i + 1];
                  }
              }
              return null;
          }
          

          And here are the performance results:

          10 deep: Top-down: 83653 ops/sec, bottom-up: 86745 ops/sec, -3.5644684% slower
          50 deep: Top-down: 24557 ops/sec, bottom-up: 24033 ops/sec, 2.180336% slower
          100 deep: Top-down: 12854 ops/sec, bottom-up: 12927 ops/sec, -0.5647125% slower
          200 deep: Top-down: 6640 ops/sec, bottom-up: 6640 ops/sec, 0.0% slower
          500 deep: Top-down: 2623 ops/sec, bottom-up: 2630 ops/sec, -0.26615906% slower
          

          It appears that the direction we traverse the stack trace has negligible impact on the performance, no matter how deep the stack trace. I've never seen the results go above 3% slower over multiple runs, and often, it shows it going faster.

          So if performance is the only concern, I kind of like the idea of switching to the bottom-up approach.

          Show
          Bruce Brouwer added a comment - I decided to run a quick performance test. You can see the tester code in PerfTestCalcLocation.java , which I attached. The alternate calcLocation code I wrote looks like this (which is actually much simpler than the current code: public static StackTraceElement calcLocation2( final String fqcnOfLogger) { if (fqcnOfLogger == null ) { return null ; } final StackTraceElement[] stackTrace = Thread .currentThread().getStackTrace(); // start 2 below, just in case the last entry happens to match the FQCN for ( int i = stackTrace.length - 2; i >= 0; i--) { if (fqcnOfLogger.equals(stackTrace[i].getClassName())) { return stackTrace[i + 1]; } } return null ; } And here are the performance results: 10 deep: Top-down: 83653 ops/sec, bottom-up: 86745 ops/sec, -3.5644684% slower 50 deep: Top-down: 24557 ops/sec, bottom-up: 24033 ops/sec, 2.180336% slower 100 deep: Top-down: 12854 ops/sec, bottom-up: 12927 ops/sec, -0.5647125% slower 200 deep: Top-down: 6640 ops/sec, bottom-up: 6640 ops/sec, 0.0% slower 500 deep: Top-down: 2623 ops/sec, bottom-up: 2630 ops/sec, -0.26615906% slower It appears that the direction we traverse the stack trace has negligible impact on the performance, no matter how deep the stack trace. I've never seen the results go above 3% slower over multiple runs, and often, it shows it going faster. So if performance is the only concern, I kind of like the idea of switching to the bottom-up approach.
          Hide
          Remko Popma added a comment -

          Micro-benchmarks can be tricky stuff. Do you get the same results if you first measure bottom-up, then top-down? Or start with recurse(500), and work down to recurse(100)?

          Things that make it tricky:

          • avoid measuring during the first 3-10 seconds after the JVM started, as JVM initialization is still taking place in parallel
          • Hotspot will compile "hot" code to native code. The default threshold is after 10,000 invocations. So in the example this will happen sometime while you are measuring.
          • During compilation, hotspot will look at places to optimize. The loop can be unrolled, and statements in the loop re-ordered. If hotspot determines the code has no side-effects (doesn't change any state) and doesn't return a value, it may decide to optimize by simply not executing that code... Same results, but a lot faster.

          If you have time, please take a look at JMH.
          JHM is specifically designed to avoid these and other pitfalls.

          Show
          Remko Popma added a comment - Micro-benchmarks can be tricky stuff. Do you get the same results if you first measure bottom-up, then top-down? Or start with recurse(500), and work down to recurse(100)? Things that make it tricky: avoid measuring during the first 3-10 seconds after the JVM started, as JVM initialization is still taking place in parallel Hotspot will compile "hot" code to native code. The default threshold is after 10,000 invocations. So in the example this will happen sometime while you are measuring. During compilation, hotspot will look at places to optimize. The loop can be unrolled, and statements in the loop re-ordered. If hotspot determines the code has no side-effects (doesn't change any state) and doesn't return a value, it may decide to optimize by simply not executing that code... Same results, but a lot faster. If you have time, please take a look at JMH . JHM is specifically designed to avoid these and other pitfalls.
          Hide
          Bruce Brouwer added a comment -

          I took a stab at JMH. When I pulled out the code that actually takes the stack trace (using a pre-generated stack trace) and left only the iterating code, it shows the current code to be much faster. However, when you throw in the generation of the stack trace, it looks like it becomes inconsequential. Here are the results for a stack trace that is 200 entries deep.

          Benchmark                    Mode   Samples         Mean   Mean error    Units
          o.s.MyBenchmark.bottomUp    thrpt       200        6.923        0.036   ops/ms
          o.s.MyBenchmark.topDown     thrpt       200        6.913        0.034   ops/ms
          

          I've attached the benchmark code, too as MyBenchmark.java. This could be skewed somewhat as part of this time is spent making a recursive call of 208 methods deep just to make the call to build the stack trace, but I wasn't coming up with a better way to generate the stack trace and have it be part of the benchmark results.

          Show
          Bruce Brouwer added a comment - I took a stab at JMH. When I pulled out the code that actually takes the stack trace (using a pre-generated stack trace) and left only the iterating code, it shows the current code to be much faster. However, when you throw in the generation of the stack trace, it looks like it becomes inconsequential. Here are the results for a stack trace that is 200 entries deep. Benchmark Mode Samples Mean Mean error Units o.s.MyBenchmark.bottomUp thrpt 200 6.923 0.036 ops/ms o.s.MyBenchmark.topDown thrpt 200 6.913 0.034 ops/ms I've attached the benchmark code, too as MyBenchmark.java . This could be skewed somewhat as part of this time is spent making a recursive call of 208 methods deep just to make the call to build the stack trace, but I wasn't coming up with a better way to generate the stack trace and have it be part of the benchmark results.
          Hide
          Bruce Brouwer added a comment -

          Perhaps we can agree to at least remove the streaming stuff from log4j-api. This way if we can't resolve the streaming solution before 2.0, we at least won't have it in the API where it will have to be supported forever.

          Show
          Bruce Brouwer added a comment - Perhaps we can agree to at least remove the streaming stuff from log4j-api. This way if we can't resolve the streaming solution before 2.0, we at least won't have it in the API where it will have to be supported forever.
          Hide
          Bruce Brouwer added a comment -

          I've added log4j2-547-new-module.patch. It makes a new module called log4j-streams. It also changes the direction of looking for FQCN. It also includes tests to show that FQCN works for the streams. As I cannot create a branch, I'm providing this patch. You can decide how to apply this patch, either as a branch or into trunk.

          Show
          Bruce Brouwer added a comment - I've added log4j2-547-new-module.patch. It makes a new module called log4j-streams. It also changes the direction of looking for FQCN. It also includes tests to show that FQCN works for the streams. As I cannot create a branch, I'm providing this patch. You can decide how to apply this patch, either as a branch or into trunk.
          Hide
          Matt Sicker added a comment -

          Added in r1587396.

          Show
          Matt Sicker added a comment - Added in r1587396.
          Hide
          Matt Sicker added a comment -

          Although I'd recommend creating builders instead of giant constructors, but that's somewhat of a style opinion I guess.

          Show
          Matt Sicker added a comment - Although I'd recommend creating builders instead of giant constructors, but that's somewhat of a style opinion I guess.
          Hide
          Bruce Brouwer added a comment - - edited

          I like the builder idea too. I was just following the pattern that all other Java related streams take. So I decided to take a stab at it with log4j2-547-builders.patch.

          Also in that patch are some things that I missed originally, so here's what it includes:

          • LoggerStreams.Builder (and related classes)
          • Updated log4j-bom to include streams
          • Moved helper classes into a .helpers package

          I haven't written the tests because I wanted to hear some feedback on the approach.

          Show
          Bruce Brouwer added a comment - - edited I like the builder idea too. I was just following the pattern that all other Java related streams take. So I decided to take a stab at it with log4j2-547-builders.patch. Also in that patch are some things that I missed originally, so here's what it includes: LoggerStreams.Builder (and related classes) Updated log4j-bom to include streams Moved helper classes into a .helpers package I haven't written the tests because I wanted to hear some feedback on the approach.
          Hide
          Matt Sicker added a comment -

          Added in revision 1588797 on the experimental branch.

          Show
          Matt Sicker added a comment - Added in revision 1588797 on the experimental branch.
          Hide
          Remko Popma added a comment -

          This module is now merged into master but still needs some documentation.

          Show
          Remko Popma added a comment - This module is now merged into master but still needs some documentation.
          Hide
          Matt Sicker added a comment -

          Implemented in 2.1.

          Show
          Matt Sicker added a comment - Implemented in 2.1.

            People

            • Assignee:
              Matt Sicker
              Reporter:
              Matt Sicker
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development