Pull request: https://github.com/aibasel/downward/pull/8

Merged and pushed. Thanks everyone for their help!

I don't think it is absolutely necessary. Also, I don't know if I would be able to write a good summary.

A TL;DR attempt: we continue with the current design. If we see that not having a global log makes things overly complicated when adapting the local log in most parts of the planner (issue921), we can re-open the discussion.

We had the meeting mentioned in the previous message. Does someone want to summarize the outcomes somewhere, or is this not necessary? If yes, I'd appreciate if someone else could do it for time reasons and because I couldn't stay until the end.

The pull request looks good to me if the others are happy with it. I didn't look at it in depth, and I focused on the code that implements logging rather than the code that uses logging, assuming that other eyes have already looked at the code.

There are also good arguments for not having a global logger, especially considering the move towards a more library-based perspective.

We are moving towards a design without or at least with minimal global state, which would enable things like users solving several different planning tasks concurrently as part of a larger system that involves planning as one component among many. In such a system, I think global logging causes issues. (Perhaps not insurmountable, but nevertheless.)

I'm also not convinced an LP variable should do logging. Perhaps there is a difference here between user-facing logging and things like debug outputs.

I'm not saying Florian doesn't have point, just want to mention there are two sides to this. Perhaps a meeting would be good?

Maybe we should keep the global logger then? For example in Python, you can do this everywhere

    import logging
    logging.warn("Velociraptors detected")

For a class like LPVariable, I definitely don't want to store a logger in every instance and passing a logger into every function that can potentially log something also seems like a bad choice.

> I'm not clear on how the logger should be used in classes that do not have a parse method. Say I have a class that is used in multiple heuristics (e.g. LPSolver, LPVariable). Do I have to add a verbosity option to all of the heuristics store a logger in all of them and pass it to this class before I can output something from there? Or should I create a logger from scratch inside the class?

The heuristic should have a logger and pass it to those classes that should log something. I agree that it is less convenient to produce output now, but I think that there is no easy alternative in C++ if you want to pass all output through some specific formatting.

In response to the email to downward-dev: the design felt like a lot of code was required to log something. Compared to a "cout" that only requires an include, the new design requires code in the parse method, the constructor, the header (to store the parser, and an include. Maybe adding the option as a default option to the heuristic base class alleviates some of this effort at least for heuristics.

I'm not clear on how the logger should be used in classes that do not have a parse method. Say I have a class that is used in multiple heuristics (e.g. LPSolver, LPVariable). Do I have to add a verbosity option to all of the heuristics store a logger in all of them and pass it to this class before I can output something from there? Or should I create a logger from scratch inside the class?

I updated the pull request (linked in the summary).

The point regarding being line-based is not new in this issue, but I added some documentation to LogProxy. 

What do you mean by "converted the g_log accesses"? That users adapted to it? 

Regarding communicating the change and making this part of the release: we also haven't communicated the change from cout to g_log yet, although this is already part of the main repository. Therefore, I think it wouldn't be bad if also the change of this issue was part of this release. Otherwise, we need to tell people now that they cannot use cout anymore, but g_log instead, only to tell them later on, that preferably, they should use a local log. But I don't insist - if you consider this change to be more work in progress than the change from cout to g_log, then it indeed makes sense to not bundle this with the near release. Independent of the decision, one part of the announcement would be the email about the release which contains the changes. Additionally, we could inform developers by writing to downward-dev (again: we haven't done so for the change from cout to g_log).

I'd be happier to merge this after the upcoming release because it's such a large change that we haven't had much time to work with, and because it is in some sense work of progress. If we push this out with the following release, we might already have converted the g_log accesses.

Some other points:

- This should have an entry in the change log.

- Some final code review would be useful. One point of emphasis for me would be to explain the design and usage of the log class a bit more, e.g. the fact that our logs are line-oriented and that "endl" must be used to terminate a log record (rather than just ending the line with '\n').

- Only few people have followed this issue, but the things we discussed here affect everyone, so we should think about how to communicate the design to the others.

I want to emphasize another point from the discussion, so that it is mentioned on the tracker.

Migrating away from using g_log doesn't necessarily mean that all code that currently writes to g_log needs access to a logger. As we move to a more systematic logging implementation, we can and should also rethink what we log and where.

We discussed that all command-line created objects should store their own LogProxy. This avoids using log objects for control flow (at least in the merge-and-shrink case mentioned below; the CEGAR + h^add case is a HACK anyway; there, we can set a silent log object for the Options objects used to create the h^add heuristics). 

In the long term, g_log should not be used but instead, all classes that log should use their own log (which of course can be the global one if using default options for it). In this issue, I adapted merge-and-shrink to have its own log because it previously had its own verbosity level. Additionally, I did the same for the search-related classes which also already used verbosity levels to some extent. issue921 (which triggered all of this) will then deal with using individual logs in other verbose parts of the code.

I updated the pull request. From my side, there is nothing more to do for this issue. Do you want to have another look?

As a preparation for our discussion on Tuesday, I created a new pull request on Github: https://github.com/aibasel/downward/pull/8

Sure, let us schedule a discussion. Are you 
available later today? When? That CEGAR 
creates a heuristic object for this is a 
design flaw that we already knew but deferred 
addressing and already bit us in other ways, 
so perhaps now is the time to address this. 
This is really an instance of the same thing.

TransitionSystem objects are created within a factored transition system or by the MIASM merge strategy when it copies existing factors to temporally compute products. In both cases, they are not created from command line and therefore would need to have a log passed from elsewhere to store the log in the class (btw. LogProxy also has a boolean "line_has_started"). The only way I see how this would work is to configure the log of the merge strategy to be silent. Of course this would silence all of its output, including for example the dumping of its options which the merge-and-shrink algorithm normally does at the start.

For CEGAR, the situation could not be easily repaired this way: the h^add heuristic would be created from a manually created options object. If we use the log that CEGAR has (because it is being created from command line), then we could either silence the entire CEGAR code or nothing, but not just the "initializing h^add heuristic..." which is what we want (or at least I want :-) ).

Maybe it is better to schedule a discussion indeed before spending more time writing? We can also come back to the scheduling of such a discussion in a few days if you don't want to plan anything right now.

We discussed eventually having LogProxy in a common base class used by all plugin-created classes (we really need a word for these classes...), so I think we'll move towards having a log available in such classes anyway. (Assuming they are command-line-configured, which I think the classes you mention are.) Perhaps this can inform the direction that we'll follow for now. It only costs one pointer, so it's not a significant cost.

Does this help for the next steps? Otherwise, we can schedule a discussion.

In the case of M&S (and many other places), I thought it would be better/easier to not store a logger in each class, but rather pass it to the methods which need it. For functions, this needs to be done anyway, and in the M&S scenario, the use case is that there is a common utility function for shrinking which uses the mentioned method. This function needs a log to be passed in.

I'm happy to have a live discussion about this if you can find the time for it; otherwise, this can wait.

I am not sure how well I can articulate this in a brief message, perhaps it's best to leave this for a later live discussion, perhaps also in the context of the code (which I cannot check right now, but let me know if you would like me to have a look as a priority).

It's mainly about the level of granularity at which behaviour is configured. If it's the whole class that is to be silenced, passing a silent logger to its constructor is an accepted code practice. If loggers are created and used at a much finer level of granularity, I would generally say that something might be off with the level of abstraction at which the output is controlled. The two cases you mention sound like it would be best to pass a silent logger to the constructor of these classes, and then the functions would not need anything passed in. But I haven't had a look at the code.

I don't understand. I thought the idea of having a verbosity level (or more generally, a configurable log) as a parameter for some function would be useful, among others, for exactly the use case of using the function with different verbosity levels. The function always "logs", but if the verbosity level of the log is silent, then it doesn't print anything.

The concrete use case is the method TransitionSystem::apply_abstraction: during the merge-and-shrink algorithm, we use the log of the algorithm to log the output of this method. However, the "score-based MIASM" strategy repeatedly copies transition systems and shrinks them, and at this point, we would like to use different log level. Another use case (part of issue961) will be CEGAR which repeatedly constructs h^add heuristic objects which produces lots of output which could be silenced.

I don't think this is good design. Log classes are meant to implement user-controllable output preferences, not control flow, i.e., functions that sometimes log and sometimes don't. It's best not to mix the two things (i.e., output suppressed because it was configured that way vs. something that should not output because of control logic).

In a normal case, I think the best option would be not to have logging be conditional. This may require some other code changes; it would be good to look at some specific cases that use this pattern currently.

If the first option doesn't work out and logging has to be conditional, I would add an explicit parameter flag such as "enable_logging" or "disable_logging" or "silent" or whatever to the function and test that instead. Hopefully you would not have to also pass in a logger because the logger is already stored in the instance.

In the third case, if we have to go down the path of specialized loggers instantiated from code, rather than adding special-purpose utility method like this, it may be a better idea would be to make the constructor of LogProxy more convenient so that we can write

  LogProxy(args...)

for

  LogProxy(make_shared<utils::Log>(args...))

in general. This is not difficult to do in C++11 with a variadic template constructor using perfect forwarding. (I would make the constructor explicit.)

But I would see it as a priority order: I would look at the first option first, then the second if necessary, then the third if necessary.

Sounds like a good idea, although we might need more and more of such special default loggers if we later add more option. But for the moment, I'd go with this suggestion.

Can we simply add a method to logging.h which returns a new silent LogProxy. This hides the class Log and would be shorter (utils::make_silent_log()).

Something which came up when propagating the new Log class through merge-and-shrink is that we now have to write

utils::LogProxy log(make_shared<utils::Log>(utils::Verbosity::SILENT));

if we want to use some function which we would like to silent. This is quite long (but still ok in my opinion), but it also means that we must continue to expose Log (in addition to LogProxy) in logging.h. Are we fine with this or does someone has a better idea of how to silence a method? (Previously, we would just pass utils::Verbosity::SILENT.)

get_stream would return a reference, not a copy. But we don't need it for now, so feel free to leave as is. Code looks good to me. (I already had a look before your message.)

I added LogProxy and reduced the functionality of Log to be a wrapper for Verbosity. ostream cannot be copy-constructed so I didn't know how to implement the get_stream method which you suggested.

The main thing that bothered me about the proxy solution is the duplication of methods, but I now realized that such a duplication is not actually necessary: it is enough to implement the methods on the proxy, and the "actual" Log object only needs to contain enough information to allow implementing the proxy. (For example, something like a get_verbosity() method and a get_stream() method, where get_stream() currently just returns cout.) This is essentially how the pImpl idiom works, and how our abstract tasks already work. The proxy class would essentially implement the public interface of the log, and the internal class that it wraps would essentially implement the private interface. Since it's a common recommendation that the private interface should not depend on the public interface, that doesn't actually sound like it should cause any design or duplication issues.

You're right; I oversaw that in the current implementation, a *copy* would be created instead of returning a reference/pointer to the global log object. So yes, there is no way around it.

I don't understand. It indeed sounds analogous to the RNG case to me, and there we need to store a shared_ptr<utils::RandomNumberGenerator> to refer to the RNG because it can either be a newly created object or the shared global RNG.

If we sometimes return an existing object to be used in other contexts and sometimes create a new instance, like you describe, we need a shared pointer and have the "(*log) << ..." issue that we discussed.

I think you're mainly thinking of the question whether "Log" is a "first-class" plug-in object, i.e., a plug-in type on the command line, with its own doc page, etc. That's indeed not the case, but that's not why we need the proxy.

In contrast to what we discussed today, at the moment, we actually wouldn't need a wrapper class such as LogProxy to wrap the actual Log because we don't create the Log objects from command line. Currently, there is only one option for Log, which is Verbosity, and "add_log_options_to_parser" simply adds the Verbosity option. Then, if Verbosity==Normal, we just return g_log and otherwise create a new Log instance. This is in analogy to Rng which depends on its only option "seed".

If we expect to have more options for Log in the future, then it might be worth turning Log into a plugin and creating it from command line, but I actually wouldn't advocate for it. (It would mean to have an "option" called log which could be used with only one choice because we won't have different Log classes.)

Yes, maybe we can have a quick live chat on this tomorrow morning. Regarding the names, it seems to be really hard to come up with something short and yet better suited.

The pull request looks good to me, modulo naming of methods. I left a comment on this on bitbucket. I'm not sure I fully understand the discussion, perhaps best to move it to live?

I had the same initial though as Malte with the base classes. Adding to each class the same code to handle the loggers is 1. annoying, and 2. ugly to maintain,
-> I vote for a common base class for configurable objects

If we use a base class to handle the logger code, then every class should use its own logger variable (if that is the same as g_log, then be it).

I didn't suggest to not store the log. The question I rather wanted to ask is whether you think it is okay that classes who don't want to get a specialized Log object continue to use g_log rather than using the helper methods to retrieve their "own" Log object, which would be a pointer to g_log in this case anyway.

If we don't store the log, don't we need to store an Options object instead? That seems roughly similar in code complexity. Ceteris paribus, I would prefer a solution where we don't call get_log_from_options repeatedly because it seems less future-proof (some things should logically happen when the log object is created/destroyed, so we might want to have a handle on its lifetime) and less in line with how we do things for other objects configured on the command line.

I've thought before that we might want to have a common base class for objects configured from the command line. Then common handling of the log could be handled by the base class. This is something I would like to consider when we move forward on the "command-line parsing creates factories rather than the final objects" idea.

I started working on this. When we discussed this step, we thought it would be a good idea to have the same logic as we use for creating rng objects:
- use function add_log_options_to_parser(parser)
- use function get_log_from_options(options) to retrieve the Log object, which would default to g_log if the options specific to Log would not be present in options (i.e., add_log_options_to_parser has not been called) or to a newly created Log.

The disadvantage I see with this is that *all* classes that currently produce output (= use g_log) would need to call "get_log_from_options" and to store a copy (pointer) of g_log. My first attempt to implement this for merge-and-shrink instead opts for the simpler solution where get_log_from_options always returns a new object. This method should only be used by classes which wish to have their own Log object, and they should call add_log_options_to_parser before. One disadvantage is that g_log would still be exposed (and created with a non-configurable normal verbosity level) and could accidentally be used instead of a local Log object.

Independently of the above design question, I added a verbosity level to the Log class. I'm not happy with the current methods is_normal, is_verbose etc. of Log.

Happy to here your thoughts: https://bitbucket.org/SilvanS/fd-dev/pull-requests/58/issue964/diff

Once issue963 is done, we want to allow modules to use local logger objects, configured to their needs, instead of the global one. In particular, the existing verbosity option should become part of the logger class.