Log revamp #255
Log revamp #255
Conversation
maarzt
force-pushed
the
log-revamp
branch
2 times, most recently
from
02af11d to
20c7e1d
Compare
maarzt
force-pushed
the
log-revamp
branch
3 times, most recently
from
779b675 to
c7baaa6
Compare
|
Hey @maarzt, just wanted to chime in quickly that I have not forgotten about this work! It is high up on my priority list now. I probably will not have time to check it today, but will try to go through everything on Monday. |
|
Hi @ctrueden,
|
|
Quick update: I still, frustratingly, have not gotten to this code review + discussion. It is still at/near the very top of my list. Unfortunately, I first need to fix the broken HTTPS certs on one of the SciJava server machines (so that e.g. https://maven.imagej.net/ starts working again, and continues working into the future, including automatic cert renewals). There is no way I will complete that work, and circle back around to this PR, before the end of this week. However, I just wanted to let you know that it is still very much on my radar, in queue. |
|
Hey @ctrueden, I thought about this logger stuff again and again. Mainly I could not find any useful application of the LogService.channel feature introduced in this PR. (Since I don't like forwarding stdout and err to log channels.) After some discussions, I think the current solution in master is quite close to a pretty good solution. When executing a Command, we give an object to it (LogService), which is used by to Command for logging. This pattern is simple and powerful. As the caller, who provides LogService, has full control of the log messages. This gives a simple solution to the user story I described in #253: Plugin A simply creates it's custom LogService and hands it over the plugin B when calling pulgin B. This gives plugin A full control over plugin B's log messages. Plugin A can display the messages in it's on logging panel, and it can forward the logging messages to a central logging window. Problem solved without changing scijav. Cheers |
|
But there is a second goal. We want the Console window to be smarter when dealing with log messages. First of all the Console window should listen to ConsoleService to get stdout and stderr. Second the Console window should listen directly to LogService to get the all log messages with all meta data. Then I will add functionality to the Console window like search, filtering, log level adjustment and customizable pop up conditions, and it will be much smarter. Here comes the third goal. We want meta data, that tells us where the log messages come from. But how do we retrieve this information. I'm afraid inspection the stack trace will be slow an buggy. Because retrieving the stack trace is slow (throwing a exception is slightly dirty hack). And the question: Which class to pick from the call stack is hard to answer, and will result in unexpected behavior. @ctrueden What do you think. Might this idea be better than inspecting the stack trace? What would be the way to go, without breaking the rules. |
| import java.util.HashMap; | ||
| import java.util.Map; | ||
| import java.util.Properties; | ||
| import java.util.*; |
There was a problem hiding this comment.
SciJava style is to never use wildcard imports.
And in general: please keep changes in a patch set atomic, and matching what the commit message says is being changed. If you really wanted to change the imports like this, it should be its own commit.
| @@ -49,10 +47,7 @@ | |||
|
|
|||
| private String name; | |||
|
|
|||
| /** List of listeners for logging events. */ | |||
There was a problem hiding this comment.
Why delete the javadoc? It wasn't hurting anything.
| private ArrayList<LogListener> listeners; | ||
|
|
||
| private LogListener[] cachedListeners; | ||
| private List<LogListener> listeners = new CopyOnWriteArrayList<>(); |
There was a problem hiding this comment.
This is very cool to know about. Thanks!
| listeners.add(l); | ||
| cacheListeners(); | ||
| } | ||
| listeners.add(Objects.requireNonNull(l)); |
There was a problem hiding this comment.
I agree that we should be requiring non-null here at this level. However, that is a separate conceptual change, which would be better as its own commit. Or else the commit message here should state that it is also changing that behavior.
| import org.junit.Before; | ||
| import org.junit.Test; | ||
|
|
||
| import java.util.*; |
There was a problem hiding this comment.
Please use the IDE's import organization function to enumerate all the classes, instead of using wildcards.
| private static <T> T removeFuture(Future<T> future) { | ||
| try { | ||
| return future.get(); | ||
| } catch (InterruptedException | ExecutionException e) { |
There was a problem hiding this comment.
SciJava style is:
try {
doStuff();
}
catch (final MyException exc) {
handleStuff();
}There was a problem hiding this comment.
I will add this coding conventions to http://imagej.net/Coding_style.
And put the description of how to the Eclipse coding style for IntelliJ to a more prominent position.
| Iterator<?> ia = a.iterator(); | ||
| Iterator<?> ib = b.iterator(); | ||
| boolean result = a.size() == b.size(); | ||
| while(result && ia.hasNext() && ib.hasNext()) |
There was a problem hiding this comment.
SciJava style is while (condition) with leading space. Same for if, for etc.
| return result; | ||
| } | ||
|
|
||
| private static <T> boolean allEqual(Iterable<T> l, BiFunction<T, T, Boolean> equals) { |
There was a problem hiding this comment.
Super general! Shall we put this into org.scijava.test.TestUtils?
| public void run() throws InterruptedException { | ||
| List<List<Logger>> results = runParallelCollectResults(10, this::getLoggers); | ||
| boolean passed = allEqual(results, MultiThreadingTest::referencesInListEqual); | ||
| assertTrue(passed); |
There was a problem hiding this comment.
Could collapse this into an assertAllEqual static method in org.scijava.test.TestUtils. Of course, there is value in having allEqual which returns boolean as well. How about if that lives in org.scijava.util somewhere? Right now we have ArrayUtils and ListUtils. However, we are moving more toward the ImgLib2-style (and core Java style) of plurals for utility classes. Any suggestions? Happy to move/reorganize/deprecate existing stuff into better structure along these lines.
There was a problem hiding this comment.
I am not sure if assertAllEqual will be used more than once.
There are many class in org.scijava.util what would be more appropriate ListUtils or MiscUtils?
| /** | ||
| * @author Matthias Arzt | ||
| */ | ||
| class LogLevelStrategy { |
There was a problem hiding this comment.
This is a cool idea.
However, could we make LogLevelStrategy an interface, and have a DefaultLogLevelStrategy which implements it along these lines? Then people can more easily override the behavior.
I also prefer everything public whenever possible. You'll notice SJC has basically no package-private level classes... I can articulate my reasons for that if you really want to know. But I pretty much prefer either public or private whenever possible. And protected only when absolutely necessary, and package-private nearly never.
| @@ -107,7 +125,7 @@ public void removeLogListener(final LogListener l) { | |||
| } | |||
|
|
|||
| @Override | |||
| public void notifyListeners(final int level, final Object msg, | |||
| public void notifyListeners(final LogLevel level, final Object msg, | |||
There was a problem hiding this comment.
The Integer enum pattern has a lot of drawbacks.
So, in general I very much agree with you. However, in this case, I think using integers, or maybe even doubles, actually makes more sense, for similar reasons to why we use doubles for priority (see org.scijava.Priority).
You can imagine wanting to be more verbose than TRACE. You can also imagine wanting to be "more verbose than INFO, but less than WARN, which would be an argument for using double here.
What means level == 0 or LogLevel.NONE? (It's possible meaning "unknown log level" is better expressed by a null reference.)
The idea of 0 i.e. NONE is that nothing should be logged, of course. That is different than "unknown" or null. Actually, I would not allow nulls here... another reason int happens to be handy, since primitives cannot be null.
What means level == -1? (Better throw an exception if it's an error.)
I agree that negative levels are not defined here, since 0/NONE is the bottommost behavior. So, we should indeed perform bounds checking and throw an exception if negative values are given anywhere in this API.
What's the maximum log level? (Now it's clearly LogLevel.TRACE.)
Does there need to be an explicit maximum? I don't think so. It is always possible to be "more verbose" than everything else that has ever existed...
There was a problem hiding this comment.
And there is another reason not to introduce LogLevel: it breaks backwards API compatibility. The changes done earlier in this topic branch were done very carefully so that existing consumers of LogService will actually keep working without recompilation—at least in theory. 😉 If you want to introduce LogLevel, we need to keep all the existing signatures that use int level also, deprecate them, and have them delegate to the new signatures. Otherwise, this change needs to target SJC 3.0.0, which is the next major i.e. breaking release.
| throw new IllegalArgumentException(); | ||
| } | ||
|
|
||
| public boolean isHigherThan(LogLevel level) { |
There was a problem hiding this comment.
Why not implement Comparable? Although again: I personally do not think we need/want an enum here. Too restrictive. And an extensible enum pattern seems like overkill, since there is no additional metadata we need to attach to each level, besides its int value.
There was a problem hiding this comment.
Actually, there is one single piece of metadata: the label. E.g., 0=NONE, 3=INFO. This would be nice if it were extensible... and actually, it's easy to do so by following the extensible enum pattern. Take a look at net.imagej.axis.AxisType and net.imagej.axis.Axes. Would this sort of pattern satisfy you here, @maarzt? It is significantly more complex, but would allow custom log levels to name themselves. Otherwise, we could achieve the same thing by adding a method to LogService which lets people register new labels with custom log levels. This seems overly fancy and potentially error-prone to me, since we need to implement lots of methods to support it. E.g.: what if two LogLevels exist with the same int level but different labels? Easier to simply stick with int.
|
Some general comments about the commit message style: we use imperative tense, with no period in the subject line. Please avoid prefixes like "Refactor:" and "Refactoring:". See the Coding style page, which links to this and that articles on Git commit messages. |
| @@ -0,0 +1,57 @@ | |||
| /* | |||
There was a problem hiding this comment.
Please remove the conflicts list from the commit message. It's not relevant to the actual patch, only some transient rebase.
| import java.io.StringWriter; | ||
|
|
||
| /** | ||
| * @author Matthias Arzt |
There was a problem hiding this comment.
Please add at least a one-sentence description of the class to the javadoc here.
| /** | ||
| * @author Matthias Arzt | ||
| */ | ||
| public class DefaultLogFormatter implements LogFormatter{ |
There was a problem hiding this comment.
SciJava style is implements FooBar { with leading space before the curly brace.
| import org.scijava.Named; | ||
|
|
||
| /** | ||
| * @author Matthias Arzt |
There was a problem hiding this comment.
Please add javadoc. The easiest and most standard for tests is simply:
/**
* Tests {@link DefaultLogFormatter}.
*
* @author Matthias Arzt
*/
| return t; | ||
| } | ||
|
|
||
| class NamedObject implements Named { |
There was a problem hiding this comment.
Why not private class, just to be safe?
| final PrintWriter message = new PrintWriter(sw); | ||
| message.print(level.prefix()); | ||
| final String s = source.getName(); | ||
| if (!s.equals("default")) |
There was a problem hiding this comment.
This seems really hacky, to do a string check for the name "default" instead of something based on Java types.
| @Override | ||
| public void alwaysLog(final LogLevel level, final Object msg, final Throwable t) { | ||
| final String message = level.prefix() + msg; | ||
| // NB: Emit severe messages to stderr, and less severe ones to stdout. |
There was a problem hiding this comment.
I appreciate refactoring to make things easier to read and understand, but it is very important to keep the NB notes instead of throwing them away. Every NB note indicates something of particular note, and often unintuitive, to developers reading the code. See http://imagej.net/Coding_style#Javadoc_and_comments
We are going to add support for multiple Logger objects in the same SciJava context. The LogService instance will itself be the default Logger, but there will be others as well.
This change eliminates the various protected log methods of
AbstractLogService, in favor of a single method:
alwaysLog(int level, Object message, Throwable t)
All other logging methods in the Logger interface now have default
implementations which funnel to this method, which should make it
simpler to implement this interface.
This change also introduces new methods for logging information at any
arbitrary log level:
log(int level, Object message)
log(int level, Throwable t)
log(int level, Object message, Throwable t)
All level-specific logging methods now lean on these general-purpose log
methods, which do the level threshold check, and then call alwaysLog.
Move code for log level estimation to new class LogLevelStrategy to separate responsibilities.
Extract code for calling class detection to new class CallingClassUtils. Classes that should be ignored by the calling class detection should be annotated with IgnoreAsCallingClass.
ListenableLogger provides an interface for sending and receiving log messages. ListenableLogger extends the even simpler Logger interface. The Logger interface should be used in client code that only produces log messages, but doesn't process those messages.
This provides an Implementation of ListenableLogger that can be used independently from AbstractLogService. It will be usefull for the implementation of sub loggers.
Logger A being a sub logger of logger B, means logger A forwards the messages it receives to B.
A client might want to log to a given Logger instance, and at the same time listen to it's own (and only to it's own) log messages. The client can achieve this, by deriving a ListenableLogger with the new methods from the give Logger instance. The client will have to log and listen to the ListenableLogger. The messages will automatically be forwarded to the given Logger instance.
This PreprocessorPlugin affects modules with a single Parameter of type Logger. It will get a logger from LogService, that is named like the module's class and assign it to the Parameter.
A client can retrieve a private logger by calling Loggers.newRoot(). This ListenableLogger will be independent of LogService. If the logging of a client should be disable Loggers.silent() can be used as Logger. NB: DefaultListenableLogger is not public because it's implementation might change for maintenance reasons, and client code should not depend on it.
Beside of being hard to understand, the initialization of MultiplePrintStream in DefaultConsoleService was not synchronized correctly. The global resources System.out and System.err where modified like this: read, modify, write. This can fail if two DefaultConsoleServices (in two scijava contexts) do it in parallel. This problem is solved in ListenableSystemStreams by using singletons.
…essage Added a method containsLog to OutputEvent, For OutputEvents containing a log message, the method containsLog will return true.
Log messages need to be stored, before they can be displayed. LogRecorder is suited for this purpose. It can act as LogListener and record log messages for several concurrent threads. At the same time stored log messages can be red asynchronously using Iterators.
|
To make it easier for us to work on this together, I have taken the latest work here, rebased it to do some cleanups, and then pushed it as Hence: closing in favor of #272. |
Proposals concerning pull request #253: