Better Logger API

[Lord-Kamina]

Do you want to request a feature or report a bug?

Feature

What did you expect to see?

Our current logger is pretty good IMO, but writing messages is pretty cumbersome. It would be nice if someone could whip-up a better API to use it; maybe relying on libfmt or printf?

I was thinking something like

Logger.messageLevel(subsystem, message);

Any takers?

[Tronic]

I was working on something like this a long time ago, although to address a different problem: there is a bug causing log messages to get garbled when multiple threads log at the same time. I turns out that there are so many places in Performous codebase that log something, that any such change would require major effort. Anything like

std::clog << "subsystem/level: " << msg << std::endl;

would at least need to be rewritten to write only a single string chunk:

std::clog << std::string("subsystem/level: ") + msg + "\n" << std::flush;

... and I'm not quite sure if that even solves the race condition, but it certainly makes it happen less often.

Yes, you could keep two logging APIs, one with a simpler formatter like you are proposing, but then the codebase is littered with two different types of logging. Writing a script to convert any existing logging in code to the new system would also be far from trivial.

It would certainly be nice to have this fixed but getting it done properly requires at least a week's worth of work (40 hours) that could probably be spent better on other things.

P.S. How come there are no gameplay improvements in Performous at all? Everyone seems to be dancing around it and improving everything else in Performous without touching the most important part. It seems as if people are using this project to practice coding, build systems and such, without actually ever playing the game :O

[OznOg]

We could achieve the best of both world by using some proxy object to bufferize data before sending to stdout. Just tried something like that:

struct Log {

    static inline constexpr const char *getTag() {
        #ifdef LOGTAG
        return LOGTAG; // use per file user defined tag to prevent copy paste alll the way
        #else
        return nullptr;
        #endif
    }

    static Log E(const char *tag = getTag()) { return Log(Level::Error, tag); }
    static Log W(const char *tag = getTag()) { return Log(Level::Warning, tag); }
    static Log N(const char *tag = getTag()) { return Log(Level::Notice, tag); }
    static Log I(const char *tag = getTag()) { return Log(Level::Info, tag); }
    static Log D(const char *tag = getTag()) { return Log(Level::Debug, tag); }
    static Log V(const char *tag = getTag()) { return Log(Level::Verbose, tag); }

    enum class Level { Error, Warning, Notice, Info, Debug, Verbose, };

    Log(Level l, const char *tag = getTag()) : level(l) { if (!tag) tag = "performous"; log << tag << '/' << level2str(level) << ':' << ' '; }

    ~Log() { std::clog << log.str(); }

    template <class T>
    std::ostream& operator<<(T &&t) { return log << std::forward<T>(t); }

    private:
    static constexpr const char *level2str(const Level &l) {
        switch (l) {
        case Level::Error: return "error";
        case Level::Warning: return "warning";
        case Level::Notice: return "notice";
        case Level::Info: return "info";
        case Level::Debug: return "debug";
        case Level::Verbose: return "verbose";
        }
        return "twilightzone"; // to shut-up compiler
    }
    const Level level;
    std::stringstream log;

    Log(Log &&l) = default;
};

then in code you can use: Log::I("core") << "Loading assets." << std::endl; or even #define LOGTAG "core" // at top of file

Log::I() << "Loading assets." << std::endl;

one could even remove the trailing std::endl and put it in the Log class itself.

My two pence...

[OznOg]

That said, the are also many logging libraries we could use, if we prefer on shelf solution.

[Lord-Kamina]

I was working on something like this a long time ago, although to address a different problem: there is a bug causing log messages to get garbled when multiple threads log at the same time. I turns out that there are so many places in Performous codebase that log something, that any such change would require major effort. Anything like

std::clog << "subsystem/level: " << msg << std::endl;

would at least need to be rewritten to write only a single string chunk:

std::clog << std::string("subsystem/level: ") + msg + "\n" << std::flush;

... and I'm not quite sure if that even solves the race condition, but it certainly makes it happen less often.

Yes, you could keep two logging APIs, one with a simpler formatter like you are proposing, but then the codebase is littered with two different types of logging. Writing a script to convert any existing logging in code to the new system would also be far from trivial.

It would certainly be nice to have this fixed but getting it done properly requires at least a week's worth of work (40 hours) that could probably be spent better on other things.

P.S. How come there are no gameplay improvements in Performous at all? Everyone seems to be dancing around it and improving everything else in Performous without touching the most important part. It seems as if people are using this project to practice coding, build systems and such, without actually ever playing the game :O

Well I really haven't played in a while; I used to play A LOT at my previous work that entailed being in the middle of nowhere with 30 drunken soldiers but almost none of my normal friends or acquaintances like karaoke much.

RESTinio does have a logging API relying on an ostream that was trivial to adapt to work with the current performous system; I doubt it's much of an improvement over the current system but perhaps it could be used as a base to improve on?

[Tronic]

I'd suggest

logger.info("songs", "Loaded", m_songs.size(), "songs")

The first argument is subsystem name and the rest are converted into strings and concatenated (with spaces added between).

There are 163 logging statements in the codebase that would need to be rewritten. Perhaps most can be done by sed replace but it will definitely require fixing by hand.

[Baklap4]

Hmm as i'm from a c# base i think it'd be even nicer to just use a string.format notation, i think the c++ conversion from that is printf with arguments (string interpolation)

logger.info("songs", $"Loaded {m_songs.size()} songs") < Not sure if this is valid syntax or logger.info("songs", std::format("Loaded {} songs", m_songs.size()))

The same as @Tronic suggests but with a bit more interpolation instead of comma-seperating the whole string.. First argument is indeed the subsystem. Also we need to define a list of subsystems.

[OznOg]

I'd suggest

logger.info("songs", "Loaded", m_songs.size(), "songs")

The first argument is subsystem name and the rest are converted into strings and concatenated (with spaces added between).

That should not be big deal to have such a thing, The question that comes to my mind is "what is logger?". Actually, what is this object supposed to do? (I'm thinking of the initialization order fiasco for the global).

There are 163 logging statements in the codebase that would need to be rewritten. Perhaps most can be done by sed replace but it will definitely require fixing by hand.

This is mostly a detail, ok, sed can do much and even if we need some fixes by hand, it is just a one shot pain (mostly like fixing warnings). The most important is to get something that appeal to us so that it does not need to be re-done in 6 months.

@Baklap4 For the std::format proposal, I think this could be implemented using c++14, but maybe quite a lot of work for this feature... to be discussed

That said, I keep thinking that the operator<< is more natural for c++ dev, but this is just my opinion, if you guys are for not using it, that'll be fine too.

[Tronic]

Format could be used via argument forwarding too, so that the second argument is always the format string. I don't particularly like either << or explicit std::format as they are useless clutter in a logging system where most messages require some formatting/conversions.

[twollgam]

This one suggested by @Tronic

logger.info("songs", "Loaded", m_songs.size(), "songs")

would enable this too (btw it is c++20)

logger.info("songs", std::format("Loaded {} songs", m_songs.size()))

or with an user defined literal for example

logger.info("songs", "Loaded {} songs"_f, m_songs.size())

Better logger is not a global object. I think all members of this class can be static and RAII initialized in main
for example.