Title Use global logger for all output
Priority feature Status resolved
Superseder Nosy List jendrik, malte, patfer, silvan
Assigned To silvan Keywords
Optional summary

Created on 2020-05-05.19:14:46 by silvan, last changed by jendrik.

msg9319 (view) Author: jendrik Date: 2020-05-12.15:29:22
Nice, thanks!
msg9317 (view) Author: silvan Date: 2020-05-12.15:25:34
I did.
msg9316 (view) Author: jendrik Date: 2020-05-12.15:07:23
If you haven't merged yet, you might want to use utils::g_log in the new stubborn sets plugin as well. I didn't want to change it to keep the code consistent.
msg9315 (view) Author: silvan Date: 2020-05-12.15:05:42
Ok, that was timing! Going to merge.
msg9314 (view) Author: silvan Date: 2020-05-12.15:05:08
Perfect. Malte, if your happy with my last commit (latest changes to CHANGES), then I'm ready to merge.
msg9313 (view) Author: malte Date: 2020-05-12.15:04:53
Looks ready to merge then?
msg9312 (view) Author: jendrik Date: 2020-05-12.14:58:23
Yes, I looked at the bundled parsers and also think that they don't need to be adapted.
msg9310 (view) Author: silvan Date: 2020-05-12.14:47:39
I updated again.

I also did some local tests with lab and found them to correctly run use the existing parsers (both for single and anytime searchers). @Jendrik: I used the lmcut example distributed with lab and copied it to test an anytime configuration. Do you think this suffices?
msg9297 (view) Author: malte Date: 2020-05-11.18:33:55
I left one further comment. From my side this is ready to merge if the others are happy. If this change is incompatible with current versions of downward-lab, we need to do something about this and let everybody (at least in Basel, perhaps on the Fast Downward list) know.
msg9296 (view) Author: silvan Date: 2020-05-11.12:58:25
I addressed the one comment which required action.
msg9293 (view) Author: malte Date: 2020-05-08.19:46:55
I added more. ;-) (Not much more.)
msg9289 (view) Author: silvan Date: 2020-05-08.14:53:44
I replied to some and addressed the rest. I also added a changelog entry.
msg9288 (view) Author: malte Date: 2020-05-08.13:52:30
I left some comments on Bitbucket. This also needs a changelog entry.
msg9287 (view) Author: silvan Date: 2020-05-08.13:24:26
I did the announced changes and went ahead and replace cout by g_log in 99 files :-)

Except for the plan and the last three lines of output, everything goes through g_log now and has [t=..., ... KB] prepended. 

The last three lines look something like:
Solution found.
Peak memory: 98852 KB
search exit code: 0

Since much of this output is concerned with reentrant writing, I didn't want to touch it.
msg9286 (view) Author: jendrik Date: 2020-05-08.11:40:50
The plan sounds good :-)
msg9285 (view) Author: silvan Date: 2020-05-08.11:11:46
The discussion regarding shared_ptr is relevant for issue964 where we want to introduce the option of having local Log objects. In this issue here, I think we should only make the global replacement of cout by g_log for the sake of making the following issues "reviewable".

So we keep the name as it is and I'll change the output of the search statistics as suggested.
msg9284 (view) Author: malte Date: 2020-05-07.17:40:22
A possible solution is to use a wrapper class that encapsulates the shared pointer and exposes the interface we want. There are two possible designs, one that ties this directly to the design of the Log class, and another that builds a kind of facade on top of a shared_ptr<Log>.

The first one results in less code, but somewhat tighter coupling.

The second one is more loosely coupled, but needs some boilerplate for every method of Log that we want to expose. At the moment this is not a big deal because (I think) we only use one method, "operator<<".

I think I prefer the second one at the moment, but the preference may change once we use this more heavily and code and see the practical pros and cons more clearly.
msg9283 (view) Author: jendrik Date: 2020-05-07.17:33:49
I see one disadvantage of storing the local log objects as shared_ptrs. For g_log, replacing the old code produces nice new code:

cout << "test" << endl;  becomes  g_log << "test" << endl;

If we use shared_ptrs to store the local log objects, however, we will have to write code like 

(*log) << "test" << endl;

which I think is less pretty than 

log << "test" << endl;

Can you think of a prettier solution for this?
msg9282 (view) Author: jendrik Date: 2020-05-07.17:23:29
> I wondered whether we should rename it to Logger and g_log to g_logger. Opinions?

I like the shorter name.

> [t=0.0308088s, 98812 KB] g=0, 1 evaluated, 0 expanded

I think changing these lines makes sense and I'd use the variant above to be in line with the other output (if the statistics are printed).

Adapting the Downward Lab is of course important, but we should choose the output we like best instead of focusing too much on backwards compatibility for the logs, I think.
msg9281 (view) Author: malte Date: 2020-05-07.17:10:08
I think that the C++ convention is to name after the thing you write to, so if you write to a stream, you use an ostream class etc. In that sense, I would say we write to a log, not to a logger, so I'm happy with the current name.

With the new logging mechanism, the old way of doing formatted output for g and f doesn't really make sense any more, so yes, I think we should change it. I like the formatting you gave in your example.

Eventually we want to do structured logging where we don't make up the output format on the spot. But that sounds like a larger challenge, and I'm not sure if we want to work on this right now.

I agree that one of the challenges is to make sure the experience with downward-lab is OK when we change the output.
msg9280 (view) Author: silvan Date: 2020-05-07.17:01:50
The Log class is now refactored accordingly (thanks Malte!):

I wondered whether we should rename it to Logger and g_log to g_logger. Opinions?

Regarding replacing cout by g_log/g_logger: during search, we already have formatted output:
New best heuristic value for cegar: 10
[g=0, 1 evaluated, 0 expanded, t=0.034337s, 98812 KB]
f = 10 [1 evaluated, 0 expanded, t=0.0343742s, 98812 KB]
Initial heuristic value for cegar: 10
pruning method: none
New best heuristic value for cegar: 9
[g=1, 4 evaluated, 1 expanded, t=0.0344762s, 98812 KB]
New best heuristic value for cegar: 8

Should we change this to something like
[t=0.0308088s, 98812 KB] [g=0, 1 evaluated, 0 expanded]
[t=0.0308088s, 98812 KB] g=0, 1 evaluated, 0 expanded

Also, if we changed all output related to the final search statistics such as expansions, we would probably need to adapt the parsers in lab accordingly. I assume we should still do so? Except for writing the plan to stdout which I think we agreed to keep.
msg9279 (view) Author: malte Date: 2020-05-07.14:29:33
Return the logger. That's the normal thing for a stream to do; the fact that we return std::cout is a weird and unusual trick.
msg9278 (view) Author: silvan Date: 2020-05-07.13:47:31
I remember that we discussed that the Log class should be improved to automatically detect std::endl. Unfortunately, I don't remember how we can achieve that we can chain several outputs to the class. Currently, operator<< returns std::cout which is then used for all further chained output. How can we chain output without returning std::cout?
msg9267 (view) Author: silvan Date: 2020-05-05.19:14:45
Before continuing to work on issue921, we want to handle all output in Fast Downward with a global logger object.
Date User Action Args
2020-05-12 15:29:22jendriksetmessages: + msg9319
2020-05-12 15:25:34silvansetmessages: + msg9317
2020-05-12 15:07:24jendriksetmessages: + msg9316
2020-05-12 15:05:43silvansetstatus: reviewing -> resolved
messages: + msg9315
2020-05-12 15:05:08silvansetmessages: + msg9314
2020-05-12 15:04:53maltesetmessages: + msg9313
2020-05-12 14:58:23jendriksetmessages: + msg9312
2020-05-12 14:47:39silvansetmessages: + msg9310
2020-05-11 18:33:55maltesetmessages: + msg9297
2020-05-11 12:58:25silvansetmessages: + msg9296
2020-05-08 19:46:55maltesetmessages: + msg9293
2020-05-08 14:53:44silvansetmessages: + msg9289
2020-05-08 13:52:30maltesetmessages: + msg9288
2020-05-08 13:24:27silvansetstatus: chatting -> reviewing
messages: + msg9287
2020-05-08 11:40:50jendriksetmessages: + msg9286
2020-05-08 11:11:46silvansetmessages: + msg9285
2020-05-07 17:40:22maltesetmessages: + msg9284
2020-05-07 17:33:49jendriksetmessages: + msg9283
2020-05-07 17:23:29jendriksetmessages: + msg9282
2020-05-07 17:10:09maltesetmessages: + msg9281
2020-05-07 17:01:51silvansetmessages: + msg9280
2020-05-07 14:29:33maltesetmessages: + msg9279
2020-05-07 13:47:31silvansetmessages: + msg9278
2020-05-06 08:23:36patfersetnosy: + patfer
2020-05-05 19:14:46silvancreate