Make better debug print system

[kunitoki]

When developing and debugging (especially on plugins), it should be straight forward to enable / disable debugging printf's per-module: this way i would enable debugging only for the plugin or module under testing, and turn it off for the others.

We should have this kind of priority, something like :

1- Ability to enable or disable GLOBAL debugging print statements in all part of mapnik (everything)
2- Ability to enable or disable PER-GLOBAL-MODULE debugging print statements (core, plugins)
3- Ability to enable or disable PER-MODULE debugging print statements (single logical module)

A higher level control lower levels (if we have a 3rd level enabled but i disable level 2 for the same logical scope, then no debug output)...

MAPNIK_DEBUG
    |
    --------- MAPNIK_DEBUG_CORE
    |                |
    |                ---------- MAPNIK_DEBUG_CORE_RENDERER
    |                |
    |                ---------- MAPNIK_DEBUG_CORE_METAWRITER
    |
    --------- MAPNIK_DEBUG_PLUGINS
    |                |
    |                ---------- MAPNIK_DEBUG_PLUGIN_SHAPE
    |                |
    |                ---------- MAPNIK_DEBUG_PLUGIN_OGR
...

Also, to ease runtime control, let decide at runtime if we want to see the debugging or not (via map or session property) ?

[kunitoki]

Something started in debug-plugins branch: https://github.com/mapnik/mapnik/tree/debug-plugins

[kunitoki]

@springmeyer
what do you think of the progress https://github.com/mapnik/mapnik/compare/debug-plugins

now when ENABLE_LOG is True (or DEBUG = True) you can turn on and off debugging in datasources (useful when you want to check everything in pre-production environment where you build in release mode, but you want debug output)

also, i've enable statistics for datasources when ENABLE_STATS is True

[kunitoki]

I'm testing a full std::ostream replacement instead of using std::clog, where you can define where to output the logs, file or console, and control the formatting.

[springmeyer]

looking good (I'll comment more when I have time to compile/test). Also, yes def a good idea to support writing not only to stderr but also files, etc!

Also, just a heads up that sometime soon (next week or two) I want to work on merging master...move_bind_logic_to_layer. I realize this could have many conflicts so likely best to have your debug work hit master first.

[springmeyer]

also another heads up - we need to replace the timer with boost::timer/chrono at some point so the timer can be used on windows - I presume the interface can be kept the same however so it should be no problem using it for now.

[kunitoki]

yeah, makes sense. i would like to work on this a little more to define at least a logging class based on the ostream. i will try to merge back the branch at start of the next week (not later than wednesday).

[springmeyer]

@kunitoki - logging class sounds good.

re: merging, I would prefer that all commits are collapsed into a single commit and then applied to master rather than actually merging as is (which interleaves). Sound good? The poor mans approach to this is:

git diff origin/master > all changes.diff
git checkout master
git apply changes.diff
git branch new-debug
git ci -a -m "implement new debug system"
# then set up a pull request to merge that new branch with a single commit

[kunitoki]

ok will do like you suggest, thanx !

btw, isn't that the purpose of the rebase command (collect the changes as one big patch file to apply to another git tree) ?

http://book.git-scm.com/4_rebasing.html

[springmeyer]

Yes, its like rebasing. That is why I said "poor mans" approach. The only benefit to the poor mans approach is that it leaves the existing history of the first branch untouched (which can be useful for reviewing until the work is done).

[springmeyer]

Just had a chance to compile and test both the STATS and LOG modes independently - very nice!

[kunitoki]

@springmeyer

check if this works for you: https://gist.github.com/2311551

[kunitoki]

I vastly improved the logging facilities. There are a few things to discuss:

• there are some parts in the library where we output deliberately to cerr/clog without checking for DEBUG or LOG. what should we do with those ? always log ? this may not be what the user wants.
• i see in your csv plugin that you are using "strict" and "quiet" options. i think we should add those options to the global datasource (so each plugin inherit them) and merge the "quiet" with my "log" option.
• we now have mapnik::log(), probably would be cool if we can create mapnik::warn() - mapnik::debug() - mapnik::error() and threat them differently, based on some global variables.
• statistics are going now to clog directly, but probably they should use mapnik::log() ?

other things to do:

• handle sending mapnik::log() to a file by using clog.rdbuf
• figure out how to handle different levels of logging (info-debug-warning-error) or eventually (quiet-normal-verbose)

[springmeyer]

wow. amazing work.

[springmeyer]

compiling without logging I get compile errors because MAPNIK_LOG_FORMAT is not defined. This fixes (what do you think?):

diff --git a/include/mapnik/debug.hpp b/include/mapnik/debug.hpp
index 3abe245..a556ceb 100644
--- a/include/mapnik/debug.hpp
+++ b/include/mapnik/debug.hpp
@@ -23,6 +23,14 @@
 #ifndef MAPNIK_DEBUG_HPP
 #define MAPNIK_DEBUG_HPP

+#ifdef MAPNIK_DEBUG
+#define MAPNIK_DEBUG_AS_BOOL true
+#else
+#define MAPNIK_DEBUG_AS_BOOL false
+#endif
+
+#ifdef MAPNIK_LOG
+
 // mapnik
 #include <mapnik/global.hpp>

@@ -39,12 +47,6 @@
 #include <ostream>
 #include <fstream>

-#ifdef MAPNIK_DEBUG
-#define MAPNIK_DEBUG_AS_BOOL true
-#else
-#define MAPNIK_DEBUG_AS_BOOL false
-#endif
-
 #ifndef MAPNIK_LOG_FORMAT
 #error Must run configure again to regenerate the correct log format string. See LOG_FORMAT_STRING scons option.
 #endif
@@ -124,4 +126,6 @@ namespace mapnik {

 }

-#endif
+#endif // MAPNIK_LOG
+
+#endif // MAPNIK_DEBUG_HPP

[kunitoki]

ah sure. will fix it asap thanx

ps. the error when MAPNIK_LOG_FORMAT is not defined should go away as we release. or eventually i could pick up a default in the file itself.

[kunitoki]

we now need to define the policies on how to handle notices / warnings / errors and their respective strictness (when and if they throw at all).

[springmeyer]

now hitting (with clang++):

src/debug.cpp:27:9: error: use of undeclared identifier 'severity'
        severity::type severity::severity_level_ =
        ^
src/debug.cpp:27:24: error: use of undeclared identifier 'severity'
        severity::type severity::severity_level_ =
                       ^
2 errors generated.

[kunitoki]

I think we are practically done with the new logging system. But we have some pendings todo as well:

• create some python tests for checking correctness of severity and for debug to file handling
• i think that warn / error / fatal output a should be retained even if we don't want MAPNIK_LOG. what do you think ?
• handle plugin strictness, or throw or output an error to the log
• redirect spirit grammar error output to this system (mapnik/json/feature_*.hpp still uses clog)
• refactor the timer class and stats code to use the new output system (instead of using clog)
• rewrite RENDERING_STATS in feature_style_processor.cpp to use the new system

[lightmare]

I run ./configure DEBUG=yes

Configuring on Linux in *debug mode*...

then ./configure --help shows

DEBUG actual: True
ENABLE_LOG actual: False

there is a comment saying that ENABLE_LOG is enabled by default in debug mode,
but at first I asked "is it?" -- after finding out that the script works as advertised
(it acts as if it was enabled, SConstruct +1434), I think it would be less surprising if
the value in --help output matched the actual behaviour

next comes DEFAULT_LOG_SEVERITY, which I didn't specify so it gets default value "error" (SConstruct +349)
but then at SConstruct +1419 this default kicks in, while perhaps it should follow the else branch -- otherwise the branch seems redundant, I don't think triggering it with DEFAULT_LOG_SEVERITY="", just to end up with "error" or "debug" based on the value of DEBUG, is very useful

[kunitoki]

DEBUG = True will enable logging in source code regardless of the ENABLE_LOG flag.

For the other problem i've checked in some changes in 0e5dcbd

[kunitoki]

I've done a bit of digging and there are still some parts of the mapnik library + plugins that still uses std::cerr and std::clog directly. When we will convert everything to the new logging system i can close the issue.

[springmeyer]

great, thanks for helping find the last ones @kunitoki!

[kunitoki]

Closing this, as it has been already implemented. It still need some more documentation in the wiki ( https://github.com/mapnik/mapnik/wiki/Runtime-Logging ), otherwise is working very well.