Commit cc0cea09 authored by Lukas Riedel's avatar Lukas Riedel

Use loggers for terminal output, except transport model

* Introduce global names for loggers and use them for retrieval
* Remove config file keys 'verbose' and fix values for 'logLevel'
* Add new functions for creating and retrieving loggers, even without
    MPIHelper (for critial messages)
* Create base loggers in 'main' functions of applications and tests
parent 9839303e
......@@ -175,16 +175,10 @@ adding an empty line, make text **bold** or ``monospaced``.
</category>
<category name="output">
<parameter name="verbose">
<definition> Overall verbosity of the program </definition>
<suggestion> 0 </suggestion>
<values> 0, 1, 2, 3 </values>
</parameter>
<parameter name="logLevel">
<definition> Logging level of the core functions. </definition>
<suggestion> warn </suggestion>
<values> trace, debug, info, warn, err, crit </values>
<suggestion> info </suggestion>
<values> trace, debug, info, warning, error, critical </values>
</parameter>
</category>
......
......@@ -35,13 +35,7 @@ adding an empty line, make text **bold** or ``monospaced``.
<parameter name="logLevel">
<definition> Logging level of the Richards solver. </definition>
<suggestion> info </suggestion>
<values> trace, debug, info, warn, err, crit </values>
</parameter>
<parameter name="verbose">
<definition> Verbosity of the Richards simulation </definition>
<suggestion> 0 </suggestion>
<values> 0, 1, 2, 3 </values>
<values> trace, debug, info, warning, error, critical </values>
</parameter>
<parameter name="outputPath">
......
......@@ -54,7 +54,7 @@ private:
//! Config file tree
const Dune::ParameterTree& _config;
//! Verbosity of this class
const int _verbose;
const std::shared_ptr<spdlog::logger> _log;
//! The mode for reading the grid.
GridMode _grid_mode;
//! Typedef for the created grid mapper
......@@ -65,15 +65,17 @@ public:
const Dune::MPIHelper& helper):
_helper(helper),
_config(config),
_verbose(_config.get<int>("output.verbose"))
_log(Dorie::get_logger(log_base))
{
const auto grid_type = _config.get<std::string>("grid.gridType");
if (grid_type == "rectangular")
_grid_mode = GridMode::rectangular;
else if (grid_type == "gmsh")
_grid_mode = GridMode::gmsh;
else
else {
_log->error("Unsupported grid type: {}", grid_type);
DUNE_THROW(IOError, "Unsupported grid type!");
}
check_parallel_allowed();
}
......@@ -99,6 +101,8 @@ public:
grid, element_index_map, boundary_index_map);
}
else {
_log->error("DORiE expects to work on UGGrid for "
"grid type: gmsh");
DUNE_THROW(IOError, "Incompatible GridTypes and grid creation "
<< "algorithms");
}
......@@ -123,9 +127,9 @@ public:
{
if (_helper.size() > 1
&& not std::is_same_v<YaspGrid<Grid::dimension>, Grid>) {
std::cout << "WARNING! DORiE's solver does not support parallel "
<< "execution on unstructured grids. This will likely result "
<< "in a fatal exception." << std::endl;
_log->warn("DORiE's solver does not support parallel "
"execution on unstructured grids. This will likely "
"result in a fatal exception (later on)");
return false;
}
......@@ -142,19 +146,11 @@ private:
std::tuple<std::shared_ptr<Grid>, std::vector<int>, std::vector<int>>
create_gmsh_grid () const
{
Dune::Timer timer;
ios_base_all_saver restore(std::cout);
const int level = _config.get<int>("grid.initialLevel");
const std::string meshfilename = _config.get<std::string>("grid.gridFile");
if (_verbose > 0 && _helper.rank()==0){
std::cout << "GRID SETUP:" << std::endl;
std::cout << " Reading Gmsh file " << meshfilename;
if (_verbose < 3)
std::cout << " quietly" << std::endl;
else
std::cout << std::endl << "--- GMSH READER OUTPUT ---" << std::endl;
}
_log->info("Creating an unstructured grid from GMSH input file: {}",
meshfilename);
Dune::GridFactory<Grid> factory;
std::vector<int> boundary_index_map;
......@@ -164,22 +160,13 @@ private:
meshfilename,
boundary_index_map,
element_index_map,
_verbose > 2 ? true : false
false // verbose
);
}
auto grid = std::shared_ptr<Grid>(factory.createGrid());
grid->globalRefine(level);
if(_verbose>0 && _helper.rank()==0){
if (_verbose > 2)
std::cout << "--- GMSH READER OUTPUT END ---" << std::endl;
std::cout << " Global Refinement level: " << level << std::endl;
if (_verbose > 1) {
std::cout << std::setprecision(4) << std::scientific;
std::cout << "::: grid setup time" << std::setw(12) << timer.elapsed() << std::endl;
}
}
_log->debug(" Applying global refinement of level: {}", level);
grid->globalRefine(level);
return std::make_tuple(grid, element_index_map, boundary_index_map);
}
......@@ -193,29 +180,18 @@ private:
create_rect_grid () const
{
Dune::Timer timer;
ios_base_all_saver restore(std::cout);
const auto level = _config.get<int>("grid.initialLevel");
const auto upperRight = _config.get<Dune::FieldVector<double, _dim>>("grid.extensions");
const auto elements = _config.get<std::array<unsigned int, _dim>>("grid.cells");
_log->info("Creating a rectangular grid in {}D", Grid::dimension);
_log->debug(" Grid extensions: {}", to_string(upperRight));
_log->debug(" Grid cells: {}", to_string(elements));
auto grid = grid_cube_construction<Grid>(upperRight, elements);
grid->globalRefine(level);
if(_verbose > 0 && _helper.rank()==0){
std::cout << "GRID SETUP:" << std::endl;
std::cout << " Creating Rectangular Grid in " << _dim << " Dimensions." << std::endl;
std::cout << " Grid Extensions: ";
for (unsigned int i=0; i<_dim; i++)
std::cout << upperRight[i] << " ";
std::cout << std::endl;
std::cout << " Grid Cells: ";
for (unsigned int i=0; i<_dim; i++)
std::cout << elements[i] << " ";
std::cout << std::endl;
std::cout << " Global Refinement level: " << level << std::endl;
std::cout << std::setprecision(4) << std::scientific;
std::cout << "::: grid setup time" << std::setw(12) << timer.elapsed() << std::endl;
}
_log->debug(" Applying global refinement of level: {}", level);
grid->globalRefine(level);
// get the element index map from an H5 file
auto [element_index_map, cells] = read_element_index_map_from_file();
......@@ -295,7 +271,10 @@ private:
1,
std::multiplies<int>());
// fill index map with the global id and copy over the cells
_log->debug("Mapping global medium index '{}' to entire grid",
global_id);
element_index_map.resize(total_size, global_id);
std::copy(elements.begin(), elements.end(), cells.begin());
......@@ -304,9 +283,12 @@ private:
// load heterogeneous mapping
auto dataset_name = _config.get<std::string>("grid.mappingFileDataset");
_log->debug("Loading medium mapping from file. "
"Filename: {}, Dataset: {}",
file_path, dataset_name);
// create H5 file reader
H5File file(file_path, _verbose);
H5File file(file_path);
// Read the data
file.read_dataset(dataset_name,
......@@ -317,12 +299,18 @@ private:
// check if cells has correct size and extensions
if (cells.size() != Grid::dimension) {
_log->error("Mapping dataset dimensions do not match "
"grid dimensions. Expected: {}, Read: {}",
Grid::dimension, cells.size());
DUNE_THROW(IOError, "Mapping dataset has wrong dimensions!");
}
for (size_t i = 0; i < _dim; ++i) {
if (cells[i] != elements[i]) {
DUNE_THROW(IOError, "Mapping dataset extensions don't match"
<< " the grid!");
_log->error("Mapping dataset extensions do not match grid "
"extensions. Expected: {}, Read: {}",
to_string(elements), to_string(cells));
DUNE_THROW(IOError, "Mapping dataset extensions don't match "
" the grid");
}
}
......
......@@ -12,6 +12,91 @@
@todo document models
@}
@defgroup Logging Terminal Logging
@{
@ingroup Common
@brief Utilities for nicely formatted terminal output of the whole program
## Overview
DORiE uses (and vendors) the utility program spdlog
(https://github.com/gabime/spdlog) for formatting its terminal output.
This module contains some utility functions and definitions to ease its use.
We destinguish two types of loggers by their respective use:
- The *basic* logger is used by utility or helper functions and classes
that can be used anywhere inside the program. Its log level can usually
be considered relatively low (less messages). Create it with
Dorie::create_base_logger, and retrieve it with Dorie::log_base.
- The *model* loggers log actions occurring inside models. Their log level
is usually higher (more messages). Create it with Dorie::create_logger,
and retrieve it with the respective name.
spdlog registers loggers using a singleton instance. Therefore, already
created loggers can be retrieved from anywhere in the program, using
only their name. These names are pre-defined in this module to ensure that
loggers are retrieved consistently.
DORiE can generally be executed in parallel on multiple processes. Creating
a logger therefore requires the `Dune::MPIHelper` to adapt the output
format and reduce logging levels on all but the primary process.
All functions for creating loggers correctly handle the case where a logger
of this name already exists, in which case a warning will be issued and the
respective logger will be updated.
## Logging Guidelines
Use a logger for **all** messages referring to the user. We use the
pre-defined log levels of spdlog to format the massages and indicate their
importance. **Simply use neither `cout` nor `cerr`!**
- `critial`: The program aborts now. Use sparingly, or only in the
topmost `catch` statement. Display the thrown exception here.
- `error`: The program encountered an error it cannot resolve. This is
usually related to errors in the user's input, so its helpful to display
the input parameters again and tell why they don't work.
- `warning`: The program encountered contradicting states it can resolve.
- `info`: The regular information level. Use this for logging larger
algorithms and displaying information like "Reading file XYZ...".
Only display recurring information here if it does not clutter the output.
- `debug`: More detailed information on the current program state. This may
include frequently recurring information. Also use this to relay
additional information on the input files specified by the user.
- `trace`: True debugging output. Display granular steps of the program and
meta-data of algorithms.
If log messages refer to their immediate predecessor, and cannot occur
without it, this relation can be indicated by indenting with *two spaces*.
Use log messages to display error messages instead of exceptions! Log messages
are easier to use and will render more nicely in the terminal. After logging
the error verbosely, throw an exception with a shorter error message.
Query the current log level of the logger only if it enforces a certain
format of subsequent messages. The log level `debug` should not result in
different *debug* messages than the level `trace`, unless there is a very
good reason for it.
To indicate that a character sequence inside the terminal output is an input
variable, place it at the end of the message and/or after a colon.
Alternatively, use apostrophes as delimiters.
Good:
Could not open file: filename.xyz
Parameter 'name' incompatible to setting 'value'
Bad:
name incompatible to value
Also, do not include the header `<spdlog/spdlog.h>` directly, but only the
respective logging header inside DORiE.
@}
@defgroup Models Models
@defgroup LocalOperators Local operators
......
......@@ -9,6 +9,8 @@
#include <hdf5.h>
#include <dune/dorie/common/logging.hh>
namespace Dune {
namespace Dorie {
......@@ -17,8 +19,8 @@ class H5File
{
private:
//! Verbosity of this class
const int _verbose;
//! The logger of this instance
const std::shared_ptr<spdlog::logger> _log;
//! ID of the H5 file
hid_t _file_id;
//! ID of the currently opened group
......@@ -26,14 +28,16 @@ private:
public:
/// Open the H5 file and its base group.
/** \param file_path Path to the H5 file
* \param verbose Verbosity of the output
/**
* \param file_path Path to the H5 file
*/
explicit H5File(const std::string& file_path, const int verbose):
_verbose(verbose),
explicit H5File(const std::string& file_path):
_log(get_logger(log_base)),
_file_id(-1),
_group_id(-1)
{
_log->info("Opening H5 file: {}", file_path);
// set up property list for collective I/O
hid_t h5_plist_id = H5Pcreate(H5P_FILE_ACCESS);
H5Pset_fapl_mpio(h5_plist_id, MPI_COMM_WORLD, MPI_INFO_NULL);
......@@ -49,7 +53,8 @@ public:
// check for errors regardless of build type
if (_file_id < 0) {
throw std::runtime_error("Cannot open H5 file " + file_path);
_log->error("Failed to open H5 file: {}", file_path);
throw std::runtime_error("Cannot open H5 file");
}
// open the base group
......@@ -59,6 +64,8 @@ public:
/// Close the H5 file when this object is destroyed
~H5File ()
{
_log->trace("Closing H5 file");
// close the opened group
herr_t status = H5Gclose(_group_id);
assert(status > -1);
......@@ -81,9 +88,11 @@ public:
}
// open the new group
_log->trace("Opening H5 group: {}", group_path);
_group_id = H5Gopen(_file_id, group_path.c_str(), H5P_DEFAULT);
if (_group_id < 0) {
throw std::runtime_error("Cannot open H5 group " + group_path);
_log->error("Failed to open H5 group: {}", group_path);
throw std::runtime_error("Error opening H5 group");
}
}
......@@ -111,20 +120,19 @@ public:
std::vector<ext_t>& shape
)
{
if(_verbose > 1) {
std::cout << "Reading H5 parameter field " << dataset_path
<< std::endl;
}
_log->info("Reading H5 dataset: {}", dataset_path);
// open a subgroup if the dataset path is nested
const auto dataset_name = open_nested_dataset(dataset_path);
// open the dataset
_log->trace("Opening H5 dataset: {}", dataset_name);
hid_t dataset_id = H5Dopen(_group_id,
dataset_name.c_str(),
H5P_DEFAULT);
if (dataset_id < 0) {
throw std::runtime_error("Cannot open dataset " + dataset_path);
_log->error("Failed to open H5 dataset: {}", dataset_path);
throw std::runtime_error("Error opening H5 dataset");
}
// get the dataspace
......@@ -133,6 +141,7 @@ public:
// get the dimension (2-d or 3-d)
const hsize_t arr_dim = H5Sget_simple_extent_ndims(dataspace_id);
_log->debug(" Dataset dimensions: {}", arr_dim);
// get the size of the problem
std::vector<hsize_t> dims(arr_dim, 0);
......@@ -140,6 +149,9 @@ public:
dims.data(),
0);
assert(status > -1);
// log dataset extensions as read
_log->debug(" Dataset extensions: {}", to_string(dims));
const auto local_size = std::accumulate(dims.begin(),
dims.end(),
......@@ -176,8 +188,9 @@ public:
);
if (status < 0) {
throw std::runtime_error("Error reading data from dataset "
+ dataset_path);
_log->error("Failed to read data from H5 dataset: {}",
dataset_path);
throw std::runtime_error("Error reading H5 dataset");
}
// close the identifiers
......
......@@ -13,12 +13,21 @@
namespace Dune {
namespace Dorie {
/// The name for retrieving the basic/common logger
inline const std::string log_base = "base";
/**
* \addtogroup Logging
* @{
*/
/// Wrapper around the function spdlog::get which throws exceptions
/** \param name
* \throw InvalidStateException If the logger does not exist
/// The name of the basic/common logger
inline const std::string log_base = "base";
/// The name of the Richards model logger
inline const std::string log_richards = "RIC";
/// The name of the Transport model logger
inline const std::string log_transport = "SOL";
/// Wrapper around the function spdlog::get, which throws exceptions
/** \param name The name of the logger to retrieve
* \throw InvalidStateException The logger does not exist
*/
inline std::shared_ptr<spdlog::logger> get_logger (const std::string name)
{
......@@ -36,14 +45,17 @@ namespace
/// Create a logger or retrieve it if it already exists
/** \param name The name of the logger (also used for lookup)
* \param warn_on_exist Issue a warning if the logger already exists.
*/
std::shared_ptr<spdlog::logger> create_or_get (const std::string name)
std::shared_ptr<spdlog::logger> create_or_get (
const std::string name,
const bool warn_on_exist=true)
{
auto logger = spdlog::get(name);
if (not logger) {
logger = spdlog::stdout_color_mt(name);
}
else {
else if (logger && warn_on_exist) {
logger->warn("Skipping creation of logger '{}' because "
"it already exists.", name);
}
......@@ -55,7 +67,7 @@ namespace
/// Create a logger with a certain name and log level.
/** If created in parallel, reduce log level for loggers that are not
* on the primary process (rank 0). Sets new logging levels if the
* logger(s) already exist.
* logger(s) already exist(s).
* \param name Name of the logger
* \param helper The Dune MPIHelper
* \param level The log level of the (primary) logger.
......@@ -95,7 +107,7 @@ inline std::shared_ptr<spdlog::logger> create_logger (
/// Create the basic DORiE logger with a certain log level and fixed name.
/** If created in parallel, reduce log level for loggers that are not
* on the primary process (rank 0). Sets new logging levels if the
* logger(s) already exist. The logger automatically receives the name
* logger(s) already exist(s). The logger automatically receives the name
* Dune::Dorie::log_base and can be retrieved with its value.
* \param helper The Dune MPIHelper
* \param level The log level of the (primary) logger.
......@@ -139,8 +151,8 @@ inline std::shared_ptr<spdlog::logger> create_base_logger (
const spdlog::level::level_enum level = spdlog::level::warn
)
{
// create the logger if it does not already exist
auto logger = create_or_get(log_base);
// create or fetch the logger, do not issue warnings
auto logger = create_or_get(log_base, false);
// "[HH:MM:SS.mmm level] <message>"
logger->set_pattern("%^[%T.%e %L]%$ %v");
......@@ -148,6 +160,24 @@ inline std::shared_ptr<spdlog::logger> create_base_logger (
return logger;
}
template<typename Vec>
inline std::string to_string (const Vec& vec)
{
std::string ret;
for (auto&& value : vec) {
static_assert(std::is_arithmetic_v<
std::remove_reference_t<decltype(value)>>,
"Only arithmetic types can be transformed to a string");
ret += std::to_string(value) + ", ";
}
// remove final comma
return ret.substr(0, ret.length()-2);
}
/**
* @} // addtogroup Logging
*/
} // namespace Dorie
} // namespace Dune
......
......@@ -96,10 +96,10 @@ public:
void virtual write_data() const
{
if (_output_policy != OutputPolicy::None) {
_log->error("The basic simulation does not implement writing data. "
_log->error("This simulation does not implement writing data. "
"Override this function if you set a different output policy "
"than None");
DUNE_THROW(Dune::IOError,"Simulation can't write data!");
DUNE_THROW(Dune::IOError, "'write_data' not implemented!");
}
}
......@@ -108,8 +108,9 @@ public:
*/
virtual void mark_grid()
{
DUNE_THROW(Dune::NotImplemented,
"Simulation can't mark the grid for adaptivity!");
_log->error("This simulation does not implement an algorithm for marking "
"the grid");
DUNE_THROW(Dune::NotImplemented, "'mark_grid' not implemented!");
}
/*-----------------------------------------------------------------------*//**
......@@ -123,11 +124,16 @@ public:
*/
virtual void adapt_grid()
{
if (_adapt_policy != AdaptivityPolicy::None)
DUNE_THROW(Dune::NotImplemented,"Simulation can't be adapted!");
else
DUNE_THROW(Dune::InvalidStateException,"Simulation uses adaptivity"
<< "policy None. Method adapt() must not be called!");
if (_adapt_policy != AdaptivityPolicy::None) {
_log->error("This simulation does not implement a grid adaptation "
"algorithm.");
DUNE_THROW(Dune::NotImplemented, "'adapt_grid' not implemented");
}
else {
_log->error("Calling 'adapt_grid' on a simulation with "
"AdaptivityPolicy::None. Grid adaptation refused");
DUNE_THROW(Dune::InvalidStateException, "Invalid adaptation policy");
}
}
/*-----------------------------------------------------------------------*//**
......
......@@ -6,6 +6,7 @@
#include <dune/common/exceptions.hh>
#include <dune/common/parametertree.hh>
#include <dune/dorie/common/logging.hh>
namespace Dune{
namespace Dorie{
......@@ -21,7 +22,8 @@ private:
R suggested_dt; //!< suggestion for the next dt
bool use_dt_suggestion; //!< flag for suggested dt
int it; //!< current number of allowed iterations for Newton solver
int verbose; //!< verbosity level
//! logger of this instance
const std::shared_ptr<spdlog::logger> _log;
const R dtmax, dtmin; //!< time step limits
const R eps; //!< error margin
const R dtinc, dtdec; //!< time step mutliplicators
......@@ -42,7 +44,7 @@ public:
, dt(config.get<R>("time.startTimestep"))
, suggested_dt(dt)
, use_dt_suggestion(false)
, verbose(config.get<int>("output.verbose"))
, _log(Dorie::get_logger(log_base))
, dtmax(config.get<R>("time.maxTimestep"))
, dtmin(config.get<R>("time.minTimestep"))
, eps(dtmin/10.0)
......@@ -54,23 +56,16 @@ public:
, itmin(config.get<int>("time.minIterations"))
, tsc(tsc_)
{
if(helper.rank()!=0){
verbose=0;
if (not input_valid()) {
DUNE_THROW(IOError, "Invalid input for time controller");
}
userInputCheck();
// Check whether first time step needs adjustment
const R changeTime = tsc.getNextTimeStamp(time);
if(changeTime>0.0 && time+dt >= changeTime){
dt = changeTime-time-eps;
if(verbose>2){
std::cout << "ADAPTING TIME STEP: DT : "
<< std::setprecision(4) << std::scientific << dt
<< std::endl;
std::cout << " Boundary condition change:"
<< std::setprecision(4) << std::scientific
<< changeTime << std::endl;
}
_log->trace("Adapting time step to change in boundary condition at "
"{:.2e}", changeTime);
}
it=calcIterations(dt);
......@@ -114,7 +109,6 @@ public:
*/
bool validate (const bool exc)
{
bool adapt_to_end = false, adapt_to_bc = false;
R changeTime = 0.0;
if (!exc) // solution was successfully computed
......@@ -143,50 +137,31 @@ public:
if(changeTime < 0.0 && time+dt > tEnd){
// time step adjustment to tEnd
dt = tEnd-time;
adapt_to_end = true;
_log->trace("Adjusting time step to simulation end at: {:.2e}",
tEnd);
}
else if(changeTime > 0.0 && time+dt >= changeTime){
// time step adjustment to BC Change
dt = changeTime-time-eps;
adapt_to_bc = true;
_log->trace("Adapting time step to change in boundary condition at "
"{:.2e}", changeTime);
}
}
else // Newton solver threw error. Time is not advanced
{
if (dt <= dtmin)
DUNE_THROW(Exception,"Newton Solver does not converge at dtmin and itmax!");
if (dt <= dtmin) {
_log->error("Solver threw an exception at minimal time step "
"{:.2e}. Time step cannot be reduced", dt);
DUNE_THROW(Exception,"Solver fails at minimal time step");
}
dt = std::max(dt*dtdec,dtmin);
}
// Calculate new iterations based on adapted time step
it=calcIterations(dt);
// Output
if(verbose>2){
std::cout << "ADAPTING TIME STEP: DT : "
<< std::setprecision(4) << std::scientific
<< dt << std::endl;
if(adapt_to_end)
std::cout << " Simulation end: "
<< std::setprecision(4) << std::scientific
<< tEnd << std::endl;
else if(adapt_to_bc)
std::cout << " Boundary condition change: "
<< std::setprecision(4) << std::scientific