logger.h

Go to the documentation of this file.

// Evo C++ Library
/* Copyright 2019 Justin Crowell
Distributed under the BSD 2-Clause License -- see included file LICENSE.txt for details.
*/

#pragma once
#ifndef INCL_evo_logger_h
#define INCL_evo_logger_h

#include "io.h"
#include "file.h"
#include "substring.h"
#include "atomic_buffer_queue.h"
#include "thread.h"
#include "time.h"
#include "enum.h"


#define EVO_LOG_ALERT(LOGGER, MSG) { if (LOGGER.check(LOG_LEVEL_ALERT)) LOGGER.log_direct(LOG_LEVEL_ALERT, MSG); }

#define EVO_LOG_ERROR(LOGGER, MSG) { if (LOGGER.check(LOG_LEVEL_ERROR)) LOGGER.log_direct(LOG_LEVEL_ERROR, MSG); }

#define EVO_LOG_WARN(LOGGER, MSG) { if (LOGGER.check(LOG_LEVEL_WARN)) LOGGER.log_direct(LOG_LEVEL_WARN, MSG); }

#define EVO_LOG_INFO(LOGGER, MSG) { if (LOGGER.check(LOG_LEVEL_INFO)) LOGGER.log_direct(LOG_LEVEL_INFO, MSG); }

#define EVO_LOG_DEBUG(LOGGER, MSG) { if (LOGGER.check(LOG_LEVEL_DEBUG)) LOGGER.log_direct(LOG_LEVEL_DEBUG, MSG); }

#define EVO_LOG_DEBUG_LOW(LOGGER, MSG) { if (LOGGER.check(LOG_LEVEL_DEBUG_LOW)) LOGGER.log_direct(LOG_LEVEL_DEBUG_LOW, MSG); }


namespace evo {

class ExceptionLogger : public Exception
    { EVO_CREATE_EXCEPTION_IMPL(ExceptionLogger, Exception) };


enum LogLevel {
    LOG_LEVEL_DISABLED = 0, 
    LOG_LEVEL_ALERT,        
    LOG_LEVEL_ERROR,        
    LOG_LEVEL_WARN,         
    LOG_LEVEL_INFO,         
    LOG_LEVEL_DEBUG,        
    LOG_LEVEL_DEBUG_LOW     
};

static const LogLevel LOG_LEVEL_REMAP[] = {
    LOG_LEVEL_ALERT,
    LOG_LEVEL_DEBUG,
    LOG_LEVEL_DEBUG_LOW,
    LOG_LEVEL_ERROR,
    LOG_LEVEL_INFO,
    LOG_LEVEL_WARN
};

EVO_ENUM_REMAP(LogLevel, LOG_LEVEL_ALERT, LOG_LEVEL_DEBUG_LOW, LOG_LEVEL_DISABLED, LOG_LEVEL_REMAP,
    "alert",
    "debug",
    "debug_low",
    "error",
    "info",
    "warn"
);


namespace impl {
    template<uint SZ>
    struct LoggerMsg {
        typedef LoggerMsg<SZ> This;

        static const uint BUF_SIZE = SZ;

        SysNativeTimeStamp timestamp;
        LogLevel level;
        uint32 size;
        uint32 aux_size;
        char* aux_buf;
        char buf[BUF_SIZE];

        LoggerMsg() : size(0), aux_size(0), aux_buf(NULL) {
        }

        ~LoggerMsg() {
            if (aux_buf != NULL)
                ::free(aux_buf);
        }

        void set(LogLevel msglevel, const SubString& msg) {
            assert( msg.size() <= UInt32::MAX );

            timestamp.set_utc();
            level = msglevel;

            const char* p = msg.data();
            uint32 remain_size = msg.size();
            if (remain_size > BUF_SIZE) {
                ::memcpy(buf, p, BUF_SIZE);
                p += BUF_SIZE;
                remain_size -= BUF_SIZE;

                if (aux_buf != NULL) {
                    if (remain_size > aux_size)
                        ::free(aux_buf); // old buffer too small
                    else
                        goto copy; // old buffer ok
                }

                // New aux_buf
                aux_size = remain_size;
                aux_buf = (char*)::malloc(aux_size);

            copy:
                // Copy remaining part to aux_buf
                ::memcpy(aux_buf, p, remain_size);
                size = msg.size();
            } else {
                if (aux_buf != NULL) {
                    ::free(aux_buf);
                    aux_buf  = NULL;
                    aux_size = 0;
                }
                ::memcpy(buf, p, remain_size);
                size = remain_size;
            }
        }

        void get_buf_sizes(uint32& buf1_size, uint32& buf2_size) {
            if (size <= BUF_SIZE) {
                buf1_size = size;
                buf2_size = 0;
            } else {
                buf1_size = BUF_SIZE;
                buf2_size = size - BUF_SIZE;
            }
        }

        // aux_buf is swapped, buf is copied from src (not swapped), src.size is set to 0
        This& operator=(const This& src) {
            This& src_mutable = const_cast<This&>(src); // assign operator arg must be const, overridding for performance

            // Copy timestamp and level
            timestamp = src.timestamp;
            level = src.level;

            // Copy main buffer up to size from src
            size = src.size;
            if (src.size > 0) {
                ::memcpy(buf, src.buf, size);
                src_mutable.size = 0;
            }

            // Swap aux buffers
            swap(aux_buf, src_mutable.aux_buf);
            swap(aux_size, src_mutable.aux_size);
            return *this;
        }
    };
}

class LoggerBase {
public:
    virtual ~LoggerBase() {
    }

    virtual bool get_error(String& msg) {
        EVO_PARAM_UNUSED(msg);
        return false;
    }

    virtual void set_level(LogLevel level) {
        level_.store(level);
    }

    virtual void rotate() {
    }

    virtual void log_direct(LogLevel level, const SubString& msg) = 0;

    bool check(LogLevel level) const {
        return (level <= level_.load());
    }

    bool log(LogLevel level, const SubString& msg) {
        if (level <= level_.load()) {
            log_direct(level, msg);
            return true;
        }
        return false;
    }

protected:
    AtomicInt level_;   
};


template<class T=LoggerBase>
struct LoggerPtr {
    typedef T LoggerType;   

    LoggerType* ptr;    

    LoggerPtr() : ptr(NULL) {
    }

    LoggerPtr(LoggerType* newptr) : ptr(newptr) {
    }

    LoggerPtr(const LoggerPtr& src) : ptr(src.ptr) {
    }

    LoggerPtr& operator=(const LoggerPtr& src) {
        ptr = src.ptr;
        return *this;
    }

    void set() {
        ptr = NULL;
    }

    void set(LoggerType* newptr) {
        ptr = newptr;
    }

    bool check(LogLevel level) const {
        return (ptr != NULL && ptr->check(level));
    }

    void log_direct(LogLevel level, const SubString& msg) {
        ptr->log_direct(level, msg);
    }

    bool log(LogLevel level, const SubString& msg) {
        if (ptr != NULL && ptr->check(level)) {
            ptr->log_direct(level, msg);
            return true;
        }
        return false;
    }
};


template<uint MSG_BUF_SIZE=512>
class Logger : public LoggerBase {
public:
    typedef Logger<MSG_BUF_SIZE> This;      

    static const uint MESSAGE_BUFFER_SIZE = MSG_BUF_SIZE;   
    static const SizeT DEFAULT_QUEUE_SIZE = 256;            

    Logger(SizeT queue_size=DEFAULT_QUEUE_SIZE) : queue_(queue_size), outfile_(NL_SYS, false), thread_(consumer, this), local_time_(false) {
        level_.store(LOG_LEVEL_WARN);
    }

    ~Logger() {
        shutdown();
    }

    uint get_message_buffer_size() const {
        return MESSAGE_BUFFER_SIZE;
    }

    void set_local_time(bool local_time) {
        local_time_ = local_time;
    }

    bool get_error(String& msg) {
        Condition::Lock lock(condmutex_);
        if (errmsg_.null())
            return false;
        msg = errmsg_;
        errmsg_.set();
        return true;
    }

    void rotate() {
        rotate_.store(1);
    }

    void log_direct(LogLevel level, const SubString& msg) {
        Msg qitem;
        qitem.set(level, msg);
        queue_.add(qitem);
        if (condmutex_.trylock()) { // non-blocking
            condmutex_.notify();
            condmutex_.unlock();
        }
    }
    
    bool open(const SubString& path, bool excep=EVO_EXCEPTIONS) {
        if (thread_.thread_active()) {
            const SubString MSG("Logger can't open a file while thread already active");
            Condition::Lock lock(condmutex_);
            errmsg_.set().reserve(MSG.size() + filepath_.size()) << MSG << filepath_;
            return false;
        } else {
            // No mutex locks needed while thread is inactive
            filepath_ = path;
            if (filepath_.empty()) {
                errmsg_ = "Logger can't open empty file path";
                EVO_THROW_ERR_CHECK(evo::ExceptionLogger, errmsg_, EInval, excep);
                return false;
            }
        #if defined(_WIN32)
            if (filepath_.ends('/') || filepath_.ends('\\') || filepath_.ends(':')) {
        #else
            if (filepath_.ends('/')) {
        #endif
                const SubString MSG("Logger can't open invalid file path, must be a file not a directory: ");
                errmsg_.set().reserve(MSG.size() + filepath_.size()) << MSG << filepath_;
                EVO_THROW_ERR_CHECK(evo::ExceptionLogger, errmsg_, EInval, excep);
                return false;
            }
            if (!outfile_.open(filepath_.cstr(), oAPPEND)) {
                const Error err = outfile_.error();
                errmsg_.set() << "Logger can't open: " << filepath_;
                EVO_THROW_ERR_CHECK(evo::ExceptionLogger, errmsg_, err, excep);
                errormsg_out(errmsg_ << " -- ", err);
                return false;
            }
            outfile_ << NL;
        }
        errmsg_.set();
        return true;
    }

    bool start_thread(bool excep=EVO_EXCEPTIONS) {
        if (!thread_.thread_active()) {
            // No mutex locks needed while thread is inactive
            errmsg_.set();
            if (!outfile_.isopen()) {
                const SubString MSG("Logger file not open, must open() first before start_thread()");
                errmsg_.set().reserve(MSG.size() + filepath_.size()) << MSG << filepath_;
                EVO_THROW_ERR_CHECK(evo::ExceptionLogger, errmsg_, EInvalOp, excep);
                return false;
            } else if (!thread_.thread_start()) {
                errmsg_ = "Logger thread failed to start";
                EVO_THROW_ERR_CHECK(evo::ExceptionLogger, errmsg_, EFail, excep);
                return false;
            }
        }
        return true;
    }

    bool start(const SubString& path, bool excep=EVO_EXCEPTIONS) {
        return (open(path, excep) && start_thread(excep));
    }

    void shutdown() {
        if (thread_.thread_active()) {
            shutdown_.store(1);
            condmutex_.lock_notify();
            thread_.thread_join();
        }
    }

private:
    typedef impl::LoggerMsg<MSG_BUF_SIZE> Msg;

    AtomicBufferQueue<Msg> queue_;

    String errmsg_;
    String filepath_;
    File   outfile_;
    Thread thread_;
    Condition condmutex_;
    AtomicInt shutdown_;
    AtomicInt rotate_;
    bool local_time_;

    static void consumer(void* arg) {
        const char BEGIN_DELIM = '[';
        const SubString MSG_DELIM("] ", 2);
        const char* LEVEL_STR[] = { "ALRT", "ERRR", "WARN", "INFO", "dbug", "dbgl" };
        const StrSizeT LEVEL_LEN = 4;

        const ulong WAKE_TIMEOUT_MS = 500;
        Logger& logger = *(Logger*)arg;
        bool closed = false;
        ulong drop_count = 0;

        DateTime dt;
        Msg msg;
        uint32 buf1_size, buf2_size;
        for (;;) {
            // Consume all messages in queue
            while (logger.queue_.pop(msg)) {
                if (closed) {
                    ++drop_count;
                } else {
                    if (logger.local_time_)
                        msg.timestamp.convert_local_dt_notz(dt);
                    else
                        msg.timestamp.convert_utc_dt(dt);
                    dt.tz.set();

                    logger.outfile_ << BEGIN_DELIM;
                    dt.format(logger.outfile_, ':') << ' ';
                    if (msg.level > LOG_LEVEL_DISABLED && msg.level <= LOG_LEVEL_DEBUG_LOW)
                        logger.outfile_ << SubString(LEVEL_STR[(int)msg.level - 1], LEVEL_LEN);
                    else
                        logger.outfile_ << FmtInt(msg.level).width(LEVEL_LEN, ' ');

                    logger.outfile_ << MSG_DELIM;

                    bool error = false;
                    msg.get_buf_sizes(buf1_size, buf2_size);
                    if (buf1_size > 0 && logger.outfile_.writebin(msg.buf, buf1_size) < buf1_size)
                        error = true;
                    else if (buf2_size > 0 && logger.outfile_.writebin(msg.aux_buf, buf2_size) < buf2_size)
                        error = true;
                    else
                        logger.outfile_ << NL;
                    if (error || !logger.outfile_) {
                        // Unable to write to file
                        ++drop_count;
                        logger.outfile_.close();
                        closed = true;

                        Condition::Lock lock(logger.condmutex_);
                        logger.errmsg_.set() << "Logger file write error: " << logger.filepath_ << " -- ";
                        errormsg_out(logger.errmsg_, logger.outfile_.error());
                        break;
                    }
                }
            }
            if (logger.shutdown_.load())
                break;

            if (closed || logger.rotate_.load()) {
                // Log re-open (rotation or log closed from error)
                {
                    Condition::Lock lock(logger.condmutex_);
                    logger.outfile_.close();
                    if (logger.outfile_.open(logger.filepath_.cstr(), oAPPEND)) {
                        logger.outfile_ << NL;
                        if (closed)
                            logger.outfile_ << "[] Logger recovered from error (lost: " << drop_count << "): " << logger.errmsg_ << NL;
                        logger.errmsg_.set();
                        closed = false;
                        drop_count = 0;
                    } else if (!closed) {
                        logger.errmsg_.set() << "Logger can't open: " << logger.filepath_ << " -- ";
                        errormsg_out(logger.errmsg_, logger.outfile_.error());
                        closed = true;
                    }
                }
                logger.rotate_.store(0);
            }

            // Wait for more messages -- logging is lock-free (non-blocking) so this must wake up regularly in case a message signal was missed
            logger.condmutex_.wait(WAKE_TIMEOUT_MS, false);
            logger.condmutex_.unlock();
        }
        logger.shutdown_.store(0);
    }
};


class LoggerInert {
public:
    LoggerInert(SizeT queue_size=0) {
        EVO_PARAM_UNUSED(queue_size);
    }

    bool get_error(String&)
        { return false; }

    uint get_message_buffer_size() const
        { return 0; }

    void set_level(LogLevel) { }

    void set_local_time(bool) { }

    void rotate() { }

    bool check(LogLevel) const
        { return false; }

    void log_direct(LogLevel, const SubString&) { }

    bool log(LogLevel, const SubString&)
        { return false; }

    bool start(const SubString&, bool excep=EVO_EXCEPTIONS) {
        EVO_PARAM_UNUSED(excep);
        return true;
    }

    void shutdown() { }
};


}
#endif