Follow-up issue: issue1052

Thanks, everyone! :-)

Merged.

I updated the change log entry. As discussed in the sprint two weeks ago, there is nothing else we want to do in this issue. A new issue will take care of removing all of the remaining use cases of g_log. If nobody objects, I will later merge this one.

If the reviewers are happy, I'm happy with seeing it merged. I think this touched lots of Option objects, so does this add new options on the command-line for configuring the log levels? I would expect that it does, in which case I wouldn't mark it as "for developers" and would explain in the change log entry that and how people can now control log levels.

I addressed the comments and we had some further discussion. I also added a change log entry. Please let me know if this needs further changes.

I reviewed the entire changes without much prior knowledge and left a bunch of comments on the pull request.

We had the meeting mentioned in the previous message. It focused more broadly on future evolutions of the logging code, and we created issue1051 to keep track of this part of the discussion.

This future direction also answers Silvan's first question in msg10645: in the future, every log message has an associated log level (such as debug, info, warning), and this means that the desired log level is needed inside a print_* method in order to produce it with the appropriate level. Since print_* also has access to the logger, it is then guaranteed to have access to all information needed to decide whether something should be logger, so the check that we currently have should be inside print_*, not at the site where print_* is called. (No need to have the same test twice.)

Regarding the warnings, in the future they should be a level that is prioritized higher than normal but still suppressible, so we should have a method like "is_at_least_warning" to guard them. Not sure what to do about this if such a level doesn't currently exist. Perhaps just add such a method even if it always returns true so that we can already update the code that does the logging to this world. If this means a lot of passing loggers around, that's not great, but I think such warnings should generally still go through the logging mechanism.

There may currently be some warnings or errors where we can't go through the logging mechanism (at least not via the loggers of components like evaluators) because we haven't yet reached the part of the processing where we're inside a component (e.g. inside the option parsers). For now, I think these should use g_log where possible and where this makes sense, but cout and cerr might still be appropriate in certain special circumstances. For example, in the out of memory handler we're only allowed to call certain kinds of methods that are reentrant. It probably makes sense to leave these special parts alone for the time being.

Having a meeting to discuss these sounds good. Like I indicated on Discord, I think some of the answers might depend on how we want to evolve the logging functionality in general in the future, so I suggest letting @everyone know about the meeting.

We pushed this further by getting rid of g_log in *all* heuristics, introducing a member logger in the heuristic base class. 

Some questions we should discuss:
- do we want print_* methods to always have an if-guard of the form log.is_at_least_* guarding their entire body or do we think that the caller is responsible to only call the method if they want to produce output.
- we sometimes print "warnings", which is output that doesn't lead to termination (like errors, which are print on stderr). In the current PR, we don't if-guard them at all, i.e., we always print them. In some parts of the code, in particular, the PDB code, we had to pass around the logger through quite a few functions just to ensure we print the warning via the logger. Should we reconsider using cout for warnings in general?

I submitted a review. The changed files look good with a few questions.

I brought this issue up to date and (re-)created a pull request: https://github.com/aibasel/downward/pull/96/files

Judging by the messages below, Jendrik once already reviewed the changes. However, since the merge was huge, I suggest to have another round of reviewing. Anyone volunteering?

We decided to proceed as follows:
- issue963 will replace cout by g_log in the planner (including working on the Logger class to recognize endl) 
- issue964 will add an option to use local Logger objects (shared_ptr) and move the current functionality of verbosity levels to the Logger class. Similarly to g_rng, users use the default global logger if not specifying the option.
- this issue: add the logger option instead of the verbosity option to modules that produce lots of output or that should be silenced.

Before you make any planner-wide changes (here on in a separate issue), I recommend to comment out most of the files in the CMake file (or use a selective build) and focus on a few example files until we're happy with the design.

> Also, how would using g_log work? We would need to have a global verbosity level then.

I think g_log can be removed once we have access to Log objects everywhere.

Regarding issue589: we could eventually add methods to the Log class for structured output such as log.statistics("variables", num_variables);

Regarding prepending the time and memory output: I agree that this should only be done if the user thinks it adds useful information. We could use the following syntax for plain output

if (log.is_verbose())
    log << "Variables: " << num_variables << endl;

and for prepending time and memory usage:

if (log.is_verbose())
    log.resources << "Variables: " << num_variables << endl;

(For this the Log::resources member would simply be an instance of the current Log class, which we could encapsulate in the new Log class.)

I think always going through a logger would be good practice, and we can discuss which output the logger should make. We should be clear about the different logging use cases, and that having parsable statistics is only one of them. So I agree a greater discussion of this would be useful.

I agree with Silvan's comment that I would not use "log" to check verbosity, but then use another mechanism (cout) for the actual output. I think that mixes responsibilities and loses much of the benefit of using a logger (e.g. being able to control where the logging ends up, and in which format the output is printed).

I don't like this suggestion too much because it requires using a Log object everywhere I want to have (controlled) output. I know that the cegar code extensively (exclusively?) uses the Log class to output progress (more precisely: g_log), but I'm not a fan of reading [t = ..., ... KB] prepended to all of my output mostly because I'm using my own timers, and therefore I never use Log. Looking at the users of g_log/Log, I see that actually *only* the cegar code uses it :-) So yes, we should definitely consolidate our logging mechanisms.

Your suggestion to add Verbosity to Log would still not convince me to use it, because I find your suggested solution of using 
if (log.is_verbose())
    cout << "Variables: " << num_variables << endl;
to avoid [t=...] not ideal as this means to only use log for asking for the verbosity level, which is the same as storing Verbosity instead of Log in my class. Also, how would using g_log work? We would need to have a global verbosity level then.

However, if using Log really helps towards issue589, then I'm more willing to use that class. But in its current form, I don't see how it helps: wasn't the idea for automatically parsing statistics to use a unique form of output? I'm totally fine with using a dedicated Log class for such special-purpose output, but most of my output is not related to statistics (and should not be parsed), but to progress, and I would prefer to keep it to a simple cout.

I think we need to discuss this in more detail to make a good decision.

The changes look fine to me.

Looking at the patch as a whole again, however, I'm not sure if we shouldn't be moving in a slightly different direction. We're currently passing around the Verbosity enum to control the logging output. Wouldn't a dedicated logging object be more suited for the task? Such an object could hold the Verbosity enum and the code could look roughly the same as it does now, except that we query Log::verbosity instead of querying the Verbosity enum directly.

So instead of

if (verbosity >= utils::Verbosity::VERBOSE)
    cout << "Variables: " << num_variables << endl;

we would write

if (log.verbosity >= utils::Verbosity::VERBOSE)
    cout << "Variables: " << num_variables << endl;

and we could add helper methods to reduce the boilerplate code

if (log.is_verbose())
    cout << "Variables: " << num_variables << endl;

If we decide to add the Verbosity enum to the existing utils::Log class, users could even decide on a case-by-case basis whether to also log the time and peak memory usage for their log messages by using "log" instead of "cout":

if (log.is_verbose())
    log << "Variables: " << num_variables << endl;

Having access to a dedicated logging object instead of the enum would also make extending our logging mechanism easier in the future. For example, it would simplify adding more structured statistics output (issue589).

I did another iteration, adding the option to the landmark code and changing the meaning of "silent" to actually not output anything at all (in the module in question).

I left two comments on Bitbucket.

Any news on that front? :-) I think all that would need to be done is that you, Jendrik, would check if my last commits addressed your comments.

I addressed them and also addressed my own comments on Manuel's code, since these were not yet taken care of. I created a new pull request because I don't have writing rights on Manuel's repo:
https://bitbucket.org/SilvanS/fd-dev/pull-requests/55/issue921/diff

Sure, I left some comments.

I think merging this issue is low-effort; Jendrik, could you maybe have a look if the levels of verbosity make sense for CEGAR?

Thanks! I left a few more comments on the diff. Jendrik, I'll leave thinking
about levels of the CEGAR output to you :-)

Here are the outputs of the different configurations.
I think providing the output is better than providing the pairwise diffs.

http://ai.cs.unibas.ch/_tmp_files/heusner/ipdb-verbose.log
http://ai.cs.unibas.ch/_tmp_files/heusner/ipdb-normal.log
http://ai.cs.unibas.ch/_tmp_files/heusner/ipdb-silent.log

http://ai.cs.unibas.ch/_tmp_files/heusner/cegar-debug.log
http://ai.cs.unibas.ch/_tmp_files/heusner/cegar-verbose.log
http://ai.cs.unibas.ch/_tmp_files/heusner/cegar-normal.log
http://ai.cs.unibas.ch/_tmp_files/heusner/cegar-silent.log

http://ai.cs.unibas.ch/_tmp_files/heusner/diverse_potentials-verbose.log
http://ai.cs.unibas.ch/_tmp_files/heusner/diverse_potentials-normal.log
http://ai.cs.unibas.ch/_tmp_files/heusner/diverse_potentials-silent.log

I added some initial comments.

I think that generally we want the verbosity option on the level of Heuristic
(possibly even Evaluator at some point). All heuristics not "supporting" that
option could document this. This way, the "add_verbosity_options..." could be
added once in the "add_heuristic_options...".

Also, some decisions regarding using VERBOSE or NORMAL seem a bit arbitrary at
this point. Furthermore, it is hard to make sure that each possible output is
guarded or was considered to be guarded by the verbosity level in case if it
should always be printed. I therefore suggest that you produce three diffs of
log files for affected configurations, so that we can discuss what should be
printed and what shouldn't at different levels.

I added the verbosity option to the ipdb, cegar and diverse_potentials
heuristics. These were the three heuristics which produced the largest output in
issue744 (besides of to merge_and_shrink).

Here is the pull request:
https://bitbucket.org/manuel_h/downward/pull-requests/7/issue921/diff

It remains to discuss whether we want to provide the option to all heuristics.

Another issue is that for example cegar uses a landmark factory which produces
its own output. To control the output of a landmark factory, we would need the
verbosity option for landmark factories as well. Compared to the output of some
heuristics, the output of landmark factories is negligible.

*now

In issue744, we used the verbosity option from M&S for the search engines to be
able to reduce output during search. Some heuristics also produce lots of
output, e.g., iPDB or more generally, heuristics with a precomputation phase.
Adding support for the verbosity levels we know have for such heuristics should
be easy. We need to discuss if we want to use this feature for all heuristics or
rather only for some selected ones.