Rework logging in ASTE

[davidscn]

The current logging of all aste components is inconsistent and quite hard to read.

1. The preciceMap cpp function use easylogging and prints output in case the -v flag is set on the command line. This leads to something like the follwing: 2022-01-11 13:25:11,311 VERBOSE-1 [default] <msg>. Since the verbose logger on level 1 is the only logger we use in aste, there is no value in printing VERBOSE-1 [default]. Date and time (and duration?) are in my opinion useless as well, but debatable. Giving aste to users, useful information would include the name of the application (aste or preciceMap) and the participant. This becomes especially important in order to distinguish aste output from preCICE output.
2. The python scripts follow a logging pattern according to INFO:root:. Again, it would be nice to have the executing script in the instead of the logging type and the executing unit. Maybe it would even be nice to print initially a summary of the parsed input arguments and what the script will do, e.g., [vtk_calculator] Input mesh: <in-mesh>, [vtk_calculator] function: <function>...

[kursatyurt]

What would be a good format for preciceMap? I thought something like (<rank>) 13:25:11 [ASTE:<participant_name>]: <msg>

For python scripts again something like hh:mm:ss [scripts_name]: <msg>

[fsimonis]

As a side note: A viable alternative to easylogger could be to use a boost logger instead.

That would at least remove the file from the code base.

[kursatyurt]

As a side note: A viable alternative to easylogger could be to use a boost logger instead.

That would at least remove the file from the code base.

Thanks for the reminder, I will consider it, boost logger is used in preCICE, right?

@MakisH may you have any suggestions for logger format?

[MakisH]

Thanks for the reminder, I will consider it, boost logger is used in preCICE, right?

Yes: https://github.com/precice/precice/blob/develop/src/logging/Logger.cpp

@MakisH may you have any suggestions for logger format?

Some aspects I would consider:

• I would not add date/time, unless time is really important (e.g., to sort the mixed output from multiple ranks), as it makes the files difficult to compare. But I understand that this is probably the reason it is like this at the moment, so that's ok.
• I would try to start with a prefix that makes it easy to search for and distinguish it (but nicely align it) with the preCICE output. It is kind of standard by now that we use format="---[precice] %ColorizedSeverity% %Message%" in all tutorials, in the OpenFOAM adapter we use ---[preciceAdapter]. However, since everything here will be either from ASTE, or from preCICE, I don't see any such need.

Could you attach here a complete log file as an example?

[davidscn]

I would not add date/time, unless time is really important (e.g., to sort the mixed output from multiple ranks), as it makes the files difficult to compare. But I understand that this is probably the reason it is like this at the moment, so that's ok.

For me, the output from the master rank would probably be sufficient for most of the time. The advantage of the boost logger is that one can directly give the rank specification in the filter. I usually also like a small and proper header including some information on the current run. In the deal.II solver, it looks for example the following way

-----------------------------------------------------------------------------
--     . running with 16 threads
--     . adapter revision f13fe51 on branch develop
--     . deal.II 10.0.0-pre (revision e373e9a689 on branch master)
-----------------------------------------------------------------------------

@MakisH here is an example on the aste logging

2022-01-27 11:30:48,930 VERBOSE-1 [default] Loading mesh from ../../../../meshes/0.02/2/0.02_0.vtu
2022-01-27 11:30:48,930 VERBOSE-1 [default] Loading mesh from ../../../../meshes/0.02/2/0.02_1.vtu
2022-01-27 11:30:48,932 VERBOSE-1 [default] Loading mesh from ../../../../meshes/0.009/2/0.009_1.vtu
2022-01-27 11:30:48,932 VERBOSE-1 [default] Loading mesh from ../../../../meshes/0.009/2/0.009_0.vtu
2022-01-27 11:30:48,932 VERBOSE-1 [default] The mesh contains: 361 Vertices, 361 Data Points, 64 Edges, 702 Triangles 0 Quadrilaterals 
2022-01-27 11:30:48,933 VERBOSE-1 [default] Mesh Setup: 1) Vertices
2022-01-27 11:30:48,933 VERBOSE-1 [default] Mesh Setup: 2) Edges
2022-01-27 11:30:48,933 VERBOSE-1 [default] Mesh Setup: 2.1) Gather Unique Edges
2022-01-27 11:30:48,933 VERBOSE-1 [default] The mesh contains: 563 Vertices, 563 Data Points, 103 Edges, 1106 Triangles 0 Quadrilaterals 
2022-01-27 11:30:48,933 VERBOSE-1 [default] Mesh Setup: 1) Vertices
2022-01-27 11:30:48,933 VERBOSE-1 [default] Mesh Setup: 2) Edges
2022-01-27 11:30:48,933 VERBOSE-1 [default] Mesh Setup: 2.1) Gather Unique Edges
2022-01-27 11:30:48,934 VERBOSE-1 [default] Mesh Setup: 2.2) Register Edges
2022-01-27 11:30:48,934 VERBOSE-1 [default] Mesh Setup: 3) Triangles
2022-01-27 11:30:48,934 VERBOSE-1 [default] Mesh Setup: 4) Quadrilaterals
2022-01-27 11:30:48,935 VERBOSE-1 [default] Mesh Setup Took 2ms (0ms for vertices, 1ms for connectivity)
2022-01-27 11:30:48,935 VERBOSE-1 [default] Mesh setup completed on Rank 0
2022-01-27 11:30:48,935 VERBOSE-1 [default] Mesh Setup: 2.2) Register Edges
2022-01-27 11:30:48,935 VERBOSE-1 [default] Mesh Setup: 3) Triangles
2022-01-27 11:30:48,936 VERBOSE-1 [default] Mesh Setup: 4) Quadrilaterals
2022-01-27 11:30:48,936 VERBOSE-1 [default] Mesh Setup Took 3ms (0ms for vertices, 3ms for connectivity)
2022-01-27 11:30:48,936 VERBOSE-1 [default] Mesh setup completed on Rank 1
2022-01-27 11:30:48,936 VERBOSE-1 [default] The mesh contains: 1754 Vertices, 1754 Data Points, 139 Edges, 3464 Triangles 0 Quadrilaterals 
2022-01-27 11:30:48,936 VERBOSE-1 [default] Mesh Setup: 1) Vertices
2022-01-27 11:30:48,936 VERBOSE-1 [default] Mesh Setup: 2) Edges
2022-01-27 11:30:48,936 VERBOSE-1 [default] Mesh Setup: 2.1) Gather Unique Edges
2022-01-27 11:30:48,937 VERBOSE-1 [default] The mesh contains: 2548 Vertices, 2548 Data Points, 215 Edges, 5055 Triangles 0 Quadrilaterals 
2022-01-27 11:30:48,937 VERBOSE-1 [default] Mesh Setup: 1) Vertices
2022-01-27 11:30:48,937 VERBOSE-1 [default] Mesh Setup: 2) Edges
2022-01-27 11:30:48,937 VERBOSE-1 [default] Mesh Setup: 2.1) Gather Unique Edges
2022-01-27 11:30:48,944 VERBOSE-1 [default] Mesh Setup: 2.2) Register Edges
2022-01-27 11:30:48,944 VERBOSE-1 [default] Mesh Setup: 2.2) Register Edges
2022-01-27 11:30:48,945 VERBOSE-1 [default] Mesh Setup: 3) Triangles
2022-01-27 11:30:48,945 VERBOSE-1 [default] Mesh Setup: 3) Triangles
2022-01-27 11:30:48,948 VERBOSE-1 [default] Mesh Setup: 4) Quadrilaterals
2022-01-27 11:30:48,948 VERBOSE-1 [default] Mesh Setup Took 11ms (0ms for vertices, 11ms for connectivity)
2022-01-27 11:30:48,948 VERBOSE-1 [default] Mesh setup completed on Rank 1
2022-01-27 11:30:48,948 VERBOSE-1 [default] Mesh Setup: 4) Quadrilaterals
2022-01-27 11:30:48,948 VERBOSE-1 [default] Mesh Setup Took 11ms (0ms for vertices, 10ms for connectivity)
2022-01-27 11:30:48,948 VERBOSE-1 [default] Mesh setup completed on Rank 0
2022-01-27 11:31:18,960 VERBOSE-1 [default] Read mesh for t=0 from ../../../../meshes/0.02/2/0.02_0.vtu
2022-01-27 11:31:18,960 VERBOSE-1 [default] Read mesh for t=0 from ../../../../meshes/0.02/2/0.02_1.vtu
2022-01-27 11:31:18,961 VERBOSE-1 [default] This roundmesh contains: 361 Vertices, 361 Data Points, 64 Edges, 702 Triangles 0 Quadrilaterals 
2022-01-27 11:31:18,961 VERBOSE-1 [default] Data written: 0.326745, 0.277649, 0.265374, 0.547907, 0.305518, 0.260854, 0.402217, 0.434923, 1.7788, 1.77365 ...
2022-01-27 11:31:18,961 VERBOSE-1 [default] This roundmesh contains: 563 Vertices, 563 Data Points, 103 Edges, 1106 Triangles 0 Quadrilaterals 
2022-01-27 11:31:18,961 VERBOSE-1 [default] Data written: 1.67552, 0.97918, 0.97918, 0.975949, 0.129255, -0.218489, -0.218715, -0.218915, 0.846651, -0.178568 ...
2022-01-27 11:31:18,971 VERBOSE-1 [default] Data read: 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 ...
2022-01-27 11:31:18,971 VERBOSE-1 [default] Data read: 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 ...
2022-01-27 11:31:18,973 VERBOSE-1 [default] Writing results to "mapped_0.vtu"
2022-01-27 11:31:18,973 VERBOSE-1 [default] Writing results to "mapped_1.vtu"

[MakisH]

That's indeed quite wide. I guess the best would indeed be to use boost.log and make the formatting easily configurable, with timestamps disabled by default. If you don't need the timestamps, I wonder if any of the 2022-01-27 11:30:48,930 VERBOSE-1 [default] is useful.

I usually also like a small and proper header including some information on the current run.

This is definitely a very good idea!

[fsimonis]

The timings for vertices, edges and triangles are kind of a pain to read as the easylogger format doesn't contain the rank.

I introduced these timings to improve the connectivity generation times, however, most of this will become obsolete once we implement https://github.com/precice/precice/issues/1153.

[kursatyurt]

ATM ASTE cpp has only two options for logging so-called verbose (logging enabled) and normal (logging disabled) mode.

Other tools have different levels of logging (INFO, DEBUG, etc.). To ensure consistency between the tools, I would like to change --verbose option to --log [log_level]. While using boost log as the logger.

The Boost log has many different settings for logging from trivial loggers to very customized ones. Which one would be fits better for such a case, I would like to learn your opinions about that change. @fsimonis @DavidSCN

[davidscn]

I'm not a specialist regarding the boost logger, but as a general remark I would say that the complexity of aste cpp is small compared to preCICE and we shouldn't make it too complicated in terms of log levels. I would maybe add a default INFO log, a WARNING log and (as verbose variant) a DEBUG log. If you want to change the verbose flag, we should forward it to the DEBUG level so that we don't break compatibility somehow. The customization options of the boost logger are very neat and probably a feature of the logger itself. Still, a more boost experienced comment from @fsimonis might be valuable.

[kursatyurt]

Closed by #103