Welcome, Guest. Please login or register. Did you miss your activation email?

Author Topic: More sophisticated logging and error reporting  (Read 14278 times)

0 Members and 2 Guests are viewing this topic.

Nexus

  • SFML Team
  • Hero Member
  • *****
  • Posts: 6287
  • Thor Developer
    • View Profile
    • Bromeon
More sophisticated logging and error reporting
« on: November 02, 2015, 09:00:36 am »
In the past, we've noticed that the current logging/reporting mechanism through sf::err() may not be flexible enough, e.g. here or here.

Possible features that can be discussed:
  • Division into different severity levels: error, warning, info, debug
  • Filtering (by level, or even module/functionality-wise)
  • Choosing the output streams (not only std::cerr)
  • Meta-information: time, source file, line
  • Ideally zero performance overhead for loggers disabled at compile time
For example, I could imagine a macro which creates an object with overloaded operator<<, that logs messages according to the current log configuration. Having a macro allows the collection of above-mentioned meta-information and complete away-optimization for statically disabled loggers.
SFML_LOG_E("An error with number " << 77)

Note that this thread is not about error handling, but logging. Whether to use boolean return types or exceptions is therefore not the topic here.
« Last Edit: November 02, 2015, 09:13:43 am by Nexus »
Zloxx II: action platformer
Thor Library: particle systems, animations, dot products, ...
SFML Game Development:

Laurent

  • Administrator
  • Hero Member
  • *****
  • Posts: 32498
    • View Profile
    • SFML's website
    • Email
Re: More sophisticated logging and error reporting
« Reply #1 on: November 02, 2015, 10:17:31 am »
In the future (SFML 3), detailed information about errors will be delivered through the new error reporting system (which will not be discussed here), for example exceptions. So what does this leave for the logging system itself? Developer warnings, mainly (for example, "an OpenGL call failed ..."). So do we really need to build a sophisticated logging system? Information that developers will want to catch/redirect are those given in case of error, ie. those not given by the logging system.

So... as a starting point, I think we should clarify the scope of this feature. To be sure that we won't over-engineer it ;)
« Last Edit: November 02, 2015, 10:19:11 am by Laurent »
Laurent Gomila - SFML developer

BurningEnlightenment

  • Guest
Re: More sophisticated logging and error reporting
« Reply #2 on: November 02, 2015, 01:19:03 pm »
Developer warnings, mainly (for example, "an OpenGL call failed ..."). So do we really need to build a sophisticated logging system? Information that developers will want to catch/redirect are those given in case of error, ie. those not given by the logging system.
This is true for trivial systems, but if you have a more complex system, you will usually need a bit more context information in order to efficiently track bugs down than most libraries can and do provide through their error reporting mechanism. Of course you can always utilize a step by step debugger, but the typical enduser doesn't have one and step by step debugging is quite time consuming, so a decent log can spare you time.

  • Division into different severity levels: error, warning, info, debug
  • Filtering (by level, or even module/functionality-wise)
  • Choosing the output streams (not only std::cerr)
  • Meta-information: time, source file, line
  • Ideally zero performance overhead for loggers disabled at compile time
I think that disabling the log system at compile time isn't that useful, because as a dev/library user you want the ability to read the debug information anyways and as an enduser you probably won't be able to provide useful context information without it as already stated. So I believe it is much more useful to implement a configurable almost zero overhead runtime filtering.
Furthermore I think 3. is far to unspecific; I propose to implement an API that works like so:
#include <SFML/System/Log.hpp>

void logEntryProcessor(void *userData, sf::Log::Channel channel, sf::Log::Level level, const std::string &message)
{
    // inject into some log framework or log directly to file/cerr/cout/etc.
}

int main( )
{
    sf::Log::Manager::setCustomLogEntryProcessor(&logEntryProcessor,  NULL);
    // any further log message will be processed by logEntryProcessor
}
This only requires the filtering and logEntryProcessor to be threadsafe. The former could easily be realised through atomics and the latter can use a mutex/async work queue/etc. The default log entry processor doesn't have to be more complicated than just outputting the metadata and the message to std::cerr (or sf::err if you don't want to break current redirection systems), because the preferred backend is strongly user dependent and it's easy for the user to integrate the SFML log with his preferred backend.
Time information is almost always unnecessary and if it is necessary the user can easily add it with a custom log processor method. File and line information are mostly unnecessary too (the log system shouldn't be abused as error reporting system), but since this is more common and can't be done with a custom log processor I would provide an additional macro for this like so:
#define SFML_LI __FILE__ << ":" << __LINE__ << ": " <<
sfLogNetErr(SFML_LI "the acutal error message as usual" << someStreamableVar);

For example, I could imagine a macro which creates an object with overloaded operator<<, that logs messages according to the current log configuration. Having a macro allows the collection of above-mentioned meta-information and complete away-optimization for statically disabled loggers.
SFML_LOG_E("An error with number " << 77)
I propose std::ostream and friends (or more precisly std::ostringstream), because they can serve all your needs or can be easily extended to do so, no need to reinvent the wheel. SFML_LOG_E contradicts the naming conventions; I propose sfLogErr or sfLogSysErr instead which do comply to the naming conventions and are less tedious to type.


Edit: I believe that SFML doesn't need a next generation log system, it just needs to be easy to integrate SFML into one of the various existing ones.
« Last Edit: November 02, 2015, 01:44:55 pm by BurningEnlightenment »

Nexus

  • SFML Team
  • Hero Member
  • *****
  • Posts: 6287
  • Thor Developer
    • View Profile
    • Bromeon
Re: More sophisticated logging and error reporting
« Reply #3 on: November 02, 2015, 02:15:38 pm »
Laurent is probably right, we should aim for something simple. Introducing dedicated classes for channels, levels, entry processors, log managers, thread safety etc. makes things overly complicated. SFML shouldn't aim to be a logging library.

Maybe we should ask ourselves, where does the current system lack? Logging is something that is more useful to SFML developers and contributors than to average end-users. And if the focus lies on internal use, an API in the conventional way may not even make sense... The currently only use of having sf::err() public is to allow redirection to different output sinks.

Disabling logs statically is useful, because a real-time multimedia library has to run fast, and I definitely don't want to force logging overhead on people who don't need it. Runtime filtering can never be as fast because you need to evaluate expressions that are passed to the logger, and if they're not used, this evaluation is a waste of time.

You're right about the naming convention. glCheck() and alCheck() are currently the only function-style macros, and maybe it's not ideal that they look like functions.
« Last Edit: November 02, 2015, 02:30:35 pm by Nexus »
Zloxx II: action platformer
Thor Library: particle systems, animations, dot products, ...
SFML Game Development:

Mario

  • SFML Team
  • Hero Member
  • *****
  • Posts: 879
    • View Profile
Re: More sophisticated logging and error reporting
« Reply #4 on: November 02, 2015, 02:35:32 pm »
How about using a single class/interface similar to how SFML's stream classes work?

class LogHandler : NonCopyable {
public:
    virtual onError(const sf::String &message) {}
    virtual onWarning(const sf::String &message) {}
    virtual onInformation(const sf::String &message) {}
    virtual onDebug(const sf::String &message) {}
}

These would then be called by stream operators depending the used instance, e.g. what's returned by sf::err().

Nexus

  • SFML Team
  • Hero Member
  • *****
  • Posts: 6287
  • Thor Developer
    • View Profile
    • Bromeon
Re: More sophisticated logging and error reporting
« Reply #5 on: November 02, 2015, 02:46:37 pm »
@Mario: So you would add an API to specify global log handlers, like the following?
sf::Log::addHandler(myHandler);

Also, I think these functions should take an additional parameter with the metadata (small struct). Or even only one function with parameter that contains all the information.
class LogHandler
{
public:
    struct Entry
    {
        Level level; // enum
        String file;
        unsigned int line;
        String message;
    };

    virtual void onLogEntry(const Entry& e) = 0;
};
Zloxx II: action platformer
Thor Library: particle systems, animations, dot products, ...
SFML Game Development:

BurningEnlightenment

  • Guest
Re: More sophisticated logging and error reporting
« Reply #6 on: November 02, 2015, 03:12:53 pm »
Disabling logs statically is useful, because a real-time multimedia library has to run fast, and I definitely don't want to force logging overhead on people who don't need it. Runtime filtering can never be as fast because you need to evaluate expressions that are passed to the logger, and if they're not used, this evaluation is a waste of time.
Runtime filtering (at least with my implementation) takes one function call, one map<int, int> (a very small one which could be optimized away for standard channels) lookup and two integer comparisons, so it should be faster than the current sf::err() approach. Combined with the current logging habits the performance impact is almost unmeasurable. Anyways we can simply introduce a CMake switch for removing logging from the release builds, this is quite easy to implement.

Laurent is probably right, we should aim for something simple. Introducing dedicated classes for channels, levels, entry processors, log managers, thread safety etc. makes things overly complicated. SFML shouldn't aim to be a logging library.

Maybe we should ask ourselves, where does the current system lack? Logging is something that is more useful to SFML developers and contributors than to average end-users. And if the focus lies on internal use, an API in the conventional way may not even make sense... The currently only use of having sf::err() public is to allow redirection to different output sinks.
Channel and Level are structs for type safety reasons as recommended by Scott Meyers Effective C++ and won't probably be used directly except for additional channel macro definitions. Furthermore there is no entry processor class, any function can serve as one which is the simplest possible solution in order to provide a properly redirectable message system. Neither there is a notable Manager class, it's just there in order to initialize the map at startup. If the log entry classification is already too much for you, you can scale the approach down to a simple sfLog() macro, removing the need for the Channel, Level, LogManager "classes", but providing a method to either remove the messages at compile time or to disable them at runtime using a global bool variable and of course it would allow redirection at log entry level opposed to the current redirection possibility at stream level.
Apart from that I think that my proof of concept can be easily adapted (probably within an hour) to satisfy your initially specified requirements and as already stated it is really simple to use, small and more efficient than the current sf::err() approach.
EDIT: I'm talking about this proof of concept.

If we can settle on an approach which allows for easy message level redirection, I will voluntarely replace sf::err() with the new Solution throughout the SFML libraries.
« Last Edit: November 02, 2015, 03:28:38 pm by BurningEnlightenment »

Nexus

  • SFML Team
  • Hero Member
  • *****
  • Posts: 6287
  • Thor Developer
    • View Profile
    • Bromeon
Re: More sophisticated logging and error reporting
« Reply #7 on: November 02, 2015, 03:27:27 pm »
Runtime filtering (at least with my implementation) takes one function call, one map<int, int> (a very small one which could be optimized away for standard channels) lookup and two integer comparisons, so it should be faster than the current sf::err() approach.
The requirement however is not "faster than sf::err()" (which is only used in error cases, where performance is usually not critical), but "fast", or even better "zero overhead when not used".

Combined with the current logging habits the performance impact is almost unmeasurable.
That depends strongly on the code path. Already an if statement in the wrong place can be measurable. And if we want to stay flexible, we should avoid unneeded constraints.

Anyways we can simply introduce a CMake switch for removing logging from the release builds, this is quite easy to implement.
Yes, and then we can as well let the user specify the log levels for Debug and Release. Macros are needed anyway. The problem is that this then leads to incompatible SFML distributions, so we have to come up with meaningful defaults that 99% of the people use.

Channel and Level are structs for type safety reasons as recommended by Scott Meyers Effective C++.
Why not enums? Why Channel at all?

any function can serve as one which is the simplest possible solution in order to provide a properly redirectable message system.
That's true, I'm not sure if we should prefer function pointers with void* over a class with virtual functions. Functions don't need memory management, but only as long as you don't pass an object via void*.

But I agree that simple "entry processing" can make sense, e.g. with a global function or an interface similar to the one shown in my last post.

Apart from that I think that my proof of concept can be easily adapted (probably within an hour) to satisfy your initially specified requirements and as already stated it is really simple to use, small and more efficient than the current sf::err() approach.
I know. The implementation is not the problem, the design and scope is. So let's not be overzealous... Such things need careful thought (especially if they become part of the API), unless we want to redesign everything in the next version again, and only very few people have given their opinion so far. Furthermore, logging is not the top priority right now ;)
« Last Edit: November 02, 2015, 03:35:09 pm by Nexus »
Zloxx II: action platformer
Thor Library: particle systems, animations, dot products, ...
SFML Game Development:

BurningEnlightenment

  • Guest
Re: More sophisticated logging and error reporting
« Reply #8 on: November 02, 2015, 04:02:08 pm »
That depends strongly on the code path. Already an if statement in the wrong place can be measurable. And if we want to stay flexible, we shouldn't put needless constraints.
Yes you are completely right. A single if statement can become measurable, but only in either very poorly designed applications or very rare use cases where SFML won't even be considered to be used ;).

The problem is that this then leads to incompatible SFML distributions, so we have to come up with meaningful defaults that 99% of the people use.
This is wrong. You can have ZERO overhead and 100% compatible binaries.

Channel and Level are structs for type safety reasons as recommended by Scott Meyers Effective C++.
Why not enums? Why Channel at all?
Enums aren't typesafe and clutter the namespace they are defined in. I would have used enum class if C++03 hadn't been a requirement.
Why channel? Because of usability: If I track a network bug, I'm not interested in log entries coming from the graphics subsystem. Furthermore it would allow SFML addons like SFGUI to use the same logging frontend and therefore the user wouldn't have to implement redirection for them seperately.

That's true, I'm not sure if we should prefer function pointers with void* over a class with virtual functions. Functions don't need memory management, but only as long as you don't pass an object via void*.
I think that a function to add log processors is overkill and unneeded, almost no one needs that multiplexing ability and it is easily implemented on top of a single global log processor. I changed my mind about the userdata pointer/class based approach: It's unnecessary, simply use a static function with globals (normally I wouldn't recommend globals, but in this case it doesn't matter, because the log backend is set on a global basis anyways.
« Last Edit: November 02, 2015, 04:04:18 pm by BurningEnlightenment »

Nexus

  • SFML Team
  • Hero Member
  • *****
  • Posts: 6287
  • Thor Developer
    • View Profile
    • Bromeon
Re: More sophisticated logging and error reporting
« Reply #9 on: November 02, 2015, 04:27:29 pm »
Quote from: BurningEnlightenment
Yes you are completely right. A single if statement can become measurable, but only in either very poorly designed applications or very rare use cases where SFML won't even be considered to be used ;).
Do you really not understand what I'm trying to say? If we want our logger to be usable universally within SFML, we have to make sure it can be optionally disabled, in order to have full verbosity when debugging and full speed for normal builds. As soon as we get into the situation "a log output here would be very useful, but I'm worried about the runtime overhead", we've done the fundamental design wrong.

Quote from: BurningEnlightenment
This is wrong. You can have ZERO overhead and 100% compatible binaries.
Only under constraints. You have to be extremely careful when linking differently compiled libraries. And it's not possible to use inline functions or other scenarios that may affect the binary interface.

Quote from: BurningEnlightenment
Enums aren't typesafe and clutter the namespace they are defined in.
They're typesafe among each other, just convertible to integers. We use the scoped enum idiom. Enums work very well in the rest of the SFML API, we're not going to switch to an obscure and uncommon technique ;)

Quote from: BurningEnlightenment
I think that a function to add log processors is overkill and unneeded, almost no one needs that multiplexing ability and it is easily implemented on top of a single global log processor.
I agree.

Quote from: BurningEnlightenment
I changed my mind about the userdata pointer/class based approach: It's unnecessary, simply use a static function with globals (normally I wouldn't recommend globals, but in this case it doesn't matter, because the log backend is set on a global basis anyways.
But it only hides the problem: it's not guaranteed that global/static objects outlive the logger, so we may get UB as well. I don't think there's a nice solution as long as SFML uses global objects itself.
Zloxx II: action platformer
Thor Library: particle systems, animations, dot products, ...
SFML Game Development:

BurningEnlightenment

  • Guest
Re: More sophisticated logging and error reporting
« Reply #10 on: November 02, 2015, 06:24:59 pm »
Quote from: BurningEnlightenment
This is wrong. You can have ZERO overhead and 100% compatible binaries.
Only under constraints. You have to be extremely careful when linking differently compiled libraries. And it's not possible to use inline functions or other scenarios that may affect the binary interface.
In our case we can simply remove the calls to the log system by defining sfLog(message) as nothing. We don't need to change any other function or class of the log system. Thus the API and ABI doesn't differ, all calls to the log system are removed by the preprocessor -> zero overhead.

Quote from: BurningEnlightenment
Enums aren't typesafe and clutter the namespace they are defined in.
They're typesafe among each other, just convertible to integers. We use the scoped enum idiom. Enums work very well in the rest of the SFML API, we're not going to switch to an obscure and uncommon technique
It's neither obscure nor uncommon, see Scott Meyers Effective C++ tip 18 & 19.
And I would not call this typesafe among each other:
enum e1 {E1V1,E1V2}; enum e2 {E2V1,E2V2};
int main( )
{
    e1 v1;
    e2 v2;
    bool b = v1 == v2 || v1 < v2 || v1 > v2; //<- valid c++
}
« Last Edit: November 02, 2015, 07:23:24 pm by BurningEnlightenment »

Jabberwocky

  • Full Member
  • ***
  • Posts: 157
    • View Profile
Re: More sophisticated logging and error reporting
« Reply #11 on: November 02, 2015, 07:04:59 pm »
Just a couple quick thoughts.

SFML's logging system should either be:
1.  A fully robust logging system that will cover most reasonable use cases.
or
2.  Easily redirected into another stream/file, so SFML users can set up their own logging system and easily direct sfml output into it.

As a user I don't care which.  I respect the team's decision on whether a feature-rich logging system is within the scope of SFML or not.

BurningEnlightenment

  • Guest
Re: More sophisticated logging and error reporting
« Reply #12 on: November 02, 2015, 07:19:16 pm »
SFML's logging system should either be:
1.  A fully robust logging system that will cover most reasonable use cases.
No I don't think so. Adding a fully robust logging system to SFML would be like adding a fully standard compliant SMTP/POP3/IMAP protocol implementation to the network library - out of scope ;).

Jabberwocky

  • Full Member
  • ***
  • Posts: 157
    • View Profile
Re: More sophisticated logging and error reporting
« Reply #13 on: November 02, 2015, 08:10:55 pm »
SFML's logging system should either be:
1.  A fully robust logging system that will cover most reasonable use cases.
No I don't think so. Adding a fully robust logging system to SFML would be like adding a fully standard compliant SMTP/POP3/IMAP protocol implementation to the network library - out of scope ;).

I respect your opinion. 

Still, I'd say error logging is a near-necessity for most graphics or network programs.  So it's not insanely out of scope.  These are both areas in which things go wrong all the time, often on an end-user's computer.  Logging is a critical tool in helping diagnose those errors.

But there are a lot of other logging options out there.  So it's not a big deal if we need to use one of those, or roll one ourselves.

I could see it either way.

Mario

  • SFML Team
  • Hero Member
  • *****
  • Posts: 879
    • View Profile
Re: More sophisticated logging and error reporting
« Reply #14 on: November 02, 2015, 11:15:48 pm »
@Mario: So you would add an API to specify global log handlers, like the following?
sf::Log::addHandler(myHandler);

Yes, something like that.

 

anything