Make logging messages more informative

[bilderbuchi]

Some logging messages don't really tell where they were triggered. Someone needs to go through them and add information as to what module triggered the message. @danomatika has already volunteered to do this some time.

[ofTheo]

what about a macro? would be nice to show the filename for notices and the filename + line no for warnings and errors

[danomatika]

I think filenames are overkill and not user friendly. They are always absolute paths and are baked in for precompiled libs ... so filename errors become really long and might say /User/Theo/.../ofClass.cpp :D.

Also, they encourage people to dig inside the core code, which in itself is not a bad thing, but beyond what an error message should do.

All I propose is this:

ofLog(OF_LOG_WARNING, "couldn't load image");

becomes this:

ofLog(OF_LOG_WARNING, "ofImage: couldn't load image"); 

This way you have a better idea as to what happened. Any addon can log the string "couldn't load image" ...

[ofTheo]

oh yeah - I was wondering if it would be possible to have the filename automatically so it would be ofLog(OF_LOG_WARNING, "ofImage.cpp: couldn't load image");

just a little easier. but I guess sometimes we have a bunch of classes in one file.

what you said looks good.

[danomatika]

A fancy solution in the long run is to use the log module name with the stream classes, so you could could make certain things verbose for debugging.

ofLogVerbose("ofImage") << "loading image " << filename;
...

if(bLoaded)
    ofLogWarning("ofImage") << "couldn't load image");
ofLogVerbose("ofImage") << "loaded image " << filename << " successfully";

Then if you are debugging ofImage, you can do this:

ofSetLogLevel("ofImage", OF_LOG_VERBOSE);

[bilderbuchi]

How would this work for the ofLog(OF_LOG_ERROR,"Whatever %d", index ); syntax? Additional argument? Cause I'd be in favour of keeping this way of calling ofLog alive, I like it more than the stream operator.

[danomatika]

Well the module stuff was a design idea for the future.

ofLog(OF_LOG_ERROR,"Whatever %d", index );

should become this

ofLog(OF_LOG_ERROR,"ofClass: Whatever %d", index );

[danomatika]

Come on. It's not a big deal to just add the string ... I'm in the habit of doing so. :D

[bilderbuchi]

I didn't want to imply that it's too big a deal...

[elliotwoods]

wasn't there a PR recently by Kyle which was switching out all old uses of ofLog from the core to use the new stream / module-friendly syntax?

also how about ofLogError("ofCore::ofImage") to differentiate strongly from ofLogError("ofxImageLoader") ?

[danomatika]

I don't recall a PR. We mainly started with removing all the printfs.

The stream usage is up to the powers that be. I think baby steps are good at this point.

"ofCore::ofImage" seems too long and "ofImage" is sufficiently different from "ofxImageLoader".

[elliotwoods]

how about ofLog(of::Image) ;) but i shouldn't joke here about 15 people are now getting notifications for every message

[danomatika]

Disable notifications for this issue then.

[bilderbuchi]

This will only disable notifications for him, I would think.

[gameoverhack]

Macro's can be really good for this, and save a LOT of trouble keeping track of, and updating strings.

We use typeid(*this).name() and __FUNCTION__ in our loggers to give the name of the clase and the name of the function making the call.

The macro's look like:

\#if \__STDC_VERSION__ < 199901L
\# if \__GNUC__ >= 2
\#  define \__func__ \__FUNCTION__
\# else
\#  define \__func__ "\<unknown>"
\# endif
\#endif

\#define LOG(level, str)        LoggerSingleton::Instance()->log(level, typeid(*this).name(), \__func__, (str))
\#define LOG_ERROR(str)     LOG(JU_LOG_ERROR, (str))
\#define LOG_WARNING(str)   LOG(JU_LOG_WARNING, (str))
\#define LOG_NOTICE(str)        LOG(JU_LOG_NOTICE, (str))
\#define LOG_VERBOSE(str)   LOG(JU_LOG_VERBOSE, (str))

Obviously they'd need to be changed to suit the oF Logger API...but being able to get the class name and function name means that there is no need to use user-define 'module' names, and it's super easy to see exactly what/where the log message is coming from...

...we also add a date/timestamp to every log message, and have an API for turning on and off the amount of info output from the logger, eg., setShowLogType(bool b), setShowDate/Time(bool b), setShowClass(bool b), setShowFunction(bool b), so that for simple things we just get the logged string, but for more complex debugging we can turn on the info we need...we also use a whitespace pad function to keep it neat...

With everything turned on, the output looks like this:

[17/10/2011 - 20:32:22 :: VERB :: 14DataController::setState      ]: Setting STATE == kDATACONTROLLER_SCENE_PARSING (1)
[17/10/2011 - 20:32:22 :: NOTE :: 14DataController::DataController]: Initialising with data/config_properties.xml
[17/10/2011 - 20:32:22 :: VERB :: 17PropertyXMLParser::parseXML   ]: Discovering properties
[17/10/2011 - 20:32:22 :: NOTE :: 13GraphicLoader::GraphicLoader  ]: Start loading graphic assets from path: graphics

EDIT: realised git markdown swallows the whitespace pad - but basically it pads the final ']:' to the longest date/time/type/class::func string, so that the log messages are all aligned and 'easier' on the eye

[danomatika]

Function names are nice but, like file names and line numbers, they are overkill especially for newcomers to C++. Sure it let's you know exactly where the problem happened, but a concise error message can do the same thing.

Also, I think we prefer not to use macros in OF so far.

[gameoverhack]

I find that logic a little hard to follow: on the one hand we are advocating manually including either a) a text ref to the classname eg, ofLog(OF_LOG_WARNING, "ofImage: couldn't load image"); or b) a text ref to the class and function name (which is already happening in the core), eg., ofLog(OF_LOG_WARNING, "ofBaseVideoPlayer::previousFrame not implemented");

...but then you are saying that having this is overkill for a newcomer?

Is it overkill or actually what we should do?

If it's what we should do (which is what I'm hearing you say), then I am suggesting that a Macro makes that far easier. It also allows for (as I have suggested) making it possible to turn that amount of info on and off...so then you get the best of both worlds - lot's of info when you want it; less info when you don't.

So if it's just about using a Macro - let's talk about that!

I can see from an historical point of view this is more of a stumbling block - Macro's are generally frowned upon, and essentially not in use in oF core. However, it would be good to hear why (in this specific) case we don't want to use a one... I see Theo suggesting the same thing (although I agree that filename and number are messier than just the class::function)...

Other than 'we don't do that', the main issue I see to with using a macro is that (so far) I haven't got a neat solution to providing just one macro that can handle both:

ofLogVerbose() << ...; and ofLog(OF_LOG_VERBOSE, ...);

What other problems are there?

[arturoc]

the way i've been using this is:

class ofImage{
public:
static string LOG_NAME="ofImage"

}

then in functions inside ofImage:

ofLogError(LOG_NAME) << "some error";

that way from outside you can do:

ofSetLogLevel(OF_LOG_VERBOSE,ofImage::LOG_NAME);

[bilderbuchi]

I think we should do it in an automatic way, like Matt suggested. Manually adding a string which is basically just the class name feels not so elegant to me. This has the added benefit that we could easily switch this (and other info) on/off, as Matt already mentioned. This sounds really neat. Isn't there a way to do it without macros (if we don't want to use macros so much)?

[gameoverhack]

I don't think there's anyway to do the automatic method without macros - essentially it relies on the FUNCTION and LINE calls being executed from within the function calling them.

I've implemented a Logger class with all the suggested functionality above. The only 'elegance' issue is that it's not possible to overload a Macro definition so I needed to use LOG(level, msg) and CLOG(level) << msg << etc << endl to get it to work like std::cout.

Nice thing about it is that cout can be found/replaced with CLOG(level) and works just the same.

Having switches for the amount of data in the log is nice too. Most of the time i just log the message, but if i need function name, line number, date and or time I can just turn them on.

I'll wrap it up like an addon and post a link.

The only reason to not do it is because of the Macro's methinks - in all other ways it simplifies the logger class significantly AND simultaneously provides more logging information.

[gameoverhack]

I've just been playing around with this. It's not possible to do the automatic logging of function/class/line number etc without a macro.

One thing I did find is that it's possible to change the way we use OF_LOG_VERBOSE, OF_LOG_NOTICE etc.

Basically if these were changed from enum's to defines the necessary info could be wrapped up in their definition, eg:

#define LOGTRICK_VERBOSE LOG_VERBOSE, typeid(this).name(), __func__, __LINE__

Or you could just pass the necessary info using a define for it alone, eg:

#define LOG_INFO typeid(this).name(), __func__, __LINE__

It's kind of a hack and possibly (depending on your brain) worse than using a define for the LOG and CLOG style commands.

I wrapped my code up addon style if anyone wants to have a look: https://github.com/gameoverhack/ofxLogger

[elliotwoods]

Just to poke in, I think both class name and function are highly valuable, so far I've been doing that manually in my own code, but oF macro's would be lovely (even if we didn't use them by default in the core).

We could also have ofSetLogContent(OF_LOG_MESSAGE | OF_LOG_TIMESTAMP | OF_LOG_LEVEL | OF_LOG_LINE_NUMBER | OF_LOG_CLASS_NAME | OF_LOG_FUNCTION_NAME); if we do go down the macro route.

[ofTheo]

@elliotwoods @gameoverhack totally agree. I could imagine it being something that you might want to enable only for errors / warnings though.

But the ofSetLogContent approach is quite interesting too.

Either way I would be interested in making logging more powerful and granular. @danomatika did a lot of work on this and we haven't really put it into use yet.

Maybe it would be good to have a feature discussion issue ( similar to #1391 ), to flush out what it should be?

[danomatika]

I think logging should be kept in perspective of the end users, not the developers. I only repeat that super long log headers with obfuscated source file paths, line numbers, etc have no meaning to newbies and can be daunting. Simple, well written error messages which include the class name can be just as easy to parse by devs and users.

For most things, the time spent simply writing the name of the class in the message string manually is not outweighed by the time spent working out/maintaining an obfuscated macro system that does the same thing, let alone all of the others.

In any case, if everyone wants this, then fine, go ahead. I just think that there are points when the engineer/computer scientist side of us gets bogged down in areas of diminishing returns in order to find the "perfect solution" and this could be one of those ...

Just my 2 cents.

[gameoverhack]

Could be overly complex - could be relatively simple too...

Anyway I've had a little play around with adding a C-Style interface and sprintf-like support and flags for setting when to use/not use information.

Still uses more macro's than i'd like - only way around that is to drop ofxLogVerbose, ofxLogNotice style calls...and can't overload those calls either - so not perfect ;)

But my latest changes allow the ofxLog(LOG_VERBOSE) << "something" and ofxLog(LOG_VERBOSE, "Some other thing") to be completely transparent to the user and only uses a Macro for the LOG_LEVEL part.

For me i like it...

Definitely might be spending too long on it though ;-)

[kylemcdonald]

i think these things make sense:

1. making the error messages more informative
2. allowing for contextual logging

using automatic macros from displaying the line number, filename, etc -- i don't think that's so helpful. that's what a debugger is for.

here are what the error messages look like right now: http://pastebin.com/yvrMLZ4W (with grep -Pr "(^|\s)ofLog(Error|Verbose|Notice|Warning|FatalError)?\(" *)

[kylemcdonald]

i'm working on these error messages right now in https://github.com/kylemcdonald/openFrameworks/commits/fix-better-errors

[danomatika]

This looks good Kyle. In the least, we need to at least have basic, solid messages in the core.

[bilderbuchi]

I'm pushing this back to 0073.

[danomatika]

Awe. I thought we were in agreement, it looks good.

[bilderbuchi]

I don't dispute that we're in agreement, but this issue doesn't have a PR yet, milestone date is tomorrow, and we got a whole bunch of other issues which are either more important or already have PRs attached, so we have to prioritize. Having said that, if you (or anyone) whip up a PR and it gets polished/approved/merged in time for 0072, everyone will be happy. It's just that it would be better if we focused our collective resources on the more pressing issues until the release is out.

[danomatika]

I thought Kyle had made a PR? If not, I'll make one now.

[danomatika]

Ah wait, I was thinking of shortening the OF log headers only. Kyle's commits include lots of error messages cleanups. Sorry, I misunderstood. We should definitely review these next week. Definitely push back for 0073.

[kylemcdonald]

yeah push back to 0073, i don't have the time to finish going through all the log messages before 0072... sorry :(

plus a big chunk of them are in ofArduino and ofSerial anyway, which i think @joshuajnoble has a lot of changes to.

[kylemcdonald]

i'm going to de-assign myself from this, because i haven't been able to keep up with the discussion about macro-based ways of solving this problem. if someone else could take it over, that'd be awesome.

[bilderbuchi]

Pushing back issues without assignee to 0.8.1.

[danomatika]

I'm sorry to see this slip, especially after all the work in Maine. I've gone ahead and started this, should be done soon.

No macros, just plain, old hand text file editing.

[danomatika]

Don't close this yet because we got #2285 done. In writing that PR, I'm not making the statement that I think a more flexible logging system isn't needed. It just seems we haven't settled on anything and I felt like we needed to at least flesh out the messages we already have, especially with a larger release change like 0.8.0.

What's ironic is that I actually had a flexible ofxLogger with variables headers, timestamps, file writing etc back for OF 007 using the Poco::Logger. We just didn't have the time to work out the bugs. The current system is really a simplified rewrite of that by arturo.

Hehe. Ok, now that we have a cleaner message set to work with, how can we make it better?

[kylemcdonald]

i'm going to close this because #2285 answers the original issue description.

but there are definitely points raised in the above discussion that are not covered by #2285. i think the best way to address that is by creating a new issue that either proposes a specific feature or identifies a specific bug, perhaps drawing on some of this discussion.

[bilderbuchi]

Maybe also a logging superissue makes sense where we can talk about direction, then farm out specific points into separate issues. should also collect/reference the rest of the open logging issues: #929, #1033, #1165, #1098.