Is software logging necessary?

    I was encouraged to write this article by working with projects in which either the logging system as such was absent, or there was a miserable semblance of it, by which it was impossible to determine the problem, or even the approximate place of its appearance. Under cat there is a bit of theory and directly practical implementation of a class for writing logs in C ++.

    Introduction


    I often came across a complete lack of understanding of the purpose of logging in applications, although the logging system is far from a secondary phase in the development of the project. But, often, people understand this already at the stage of commissioning the project, when the introduction of a full-fledged logging system is a rather expensive process and as a result, they leave everything as it is. What do we have as a result? And we have a system in which any problem with the customer turns into a headache for the developer, because it is impossible to restore the causes of the problem for the customer, that is, the developer has only a description of the problem from the person who reproduced this problem. Unfortunately, we do not live in an ideal world and, as a rule, the description of the problem is uninformative, i.e. to users of the system are not competent testers and can not describe the problem in detail (there are certainly nice exceptions, but they are few). The logging problem is especially acute when it is not possible to reproduce the problem on its side.

    Common mistakes


    I would like to highlight the main logging errors that I came across:
    • The interface to the logs is a set of # define'ov under which a simple fprintf to a file is hidden. But what if a new thread appears? Or will you need more intelligent log handling? Correctly, everything will break and you will have to rewrite it.
    • The line output to the log is a concatenation of the name of the subsystem and the message itself. For example, in the module responsible for interacting with the database, a line like: “sql:". What is this line talking about? Yes, nothing, just about the fact that somewhere a query was made to the database.
    • No timestamp on log line output.
    • There is no threshold separation of logs, i.e. there is no way to disable part of the logs or turn them off completely (questionable option :))
    • Recording information in the log is too rare (for example, at the beginning and at the end of a file, without tracing it)
    • Uninformative entries (variable values ​​are not displayed, etc.)


    Why do we need logs?


    Below are just a few of the advantages that immediately come to mind:
    • The ability to quickly determine the causes of the problem, without sitting for hours in the debugger, trying to identify the problem.
    • The possibility of "remote debugging", that is, the ability to debug the application using the available logs from the customer (very useful when it is not possible to test your application without the participation of the customer)
    • Shifting part of the work to technical support. Ie support learns typical problems, sections in the logs, etc. After which they themselves will be able to determine the problems that lie on the surface, without distracting developers every time over trifles.


    A well-defined purpose of the logs, as well as tips for building a logging system are described here .
    I propose my implementation of a class that can be used to write logs, the implementation is inspired by the article link to which I gave above.
    The main settings that can be made in relation to the class:
    • Choosing a log file name
    • Choosing a directory where the log files will be stored
    • Turn on / off interprocess synchronization
    • Log file size limit
    • Limit the number of log files that can be saved in a directory
    • Setting the procedure that will be called when there is an error in writing to the log file, or when it is opened
    • Specifies a procedure that will change each line during recording, as the user needs. It is convenient when you do not want someone else to read your log.
    • The level of logs that can currently be displayed (there are 3 levels in the class: Normal, Advanced, and Debit). That is, it cuts off all the logs whose priority is above the threshold.

    The class is implemented using the boost library and is cross-platform, with the exception of the Timestamp () function, which is windows-dependent. F-Iya easily corresponded with any other OS, if necessary.

    Implementation:


    Logger.h
    #ifndef _LOGGER_
    #define _LOGGER_

    #include
    #include
    #include
    #include
    #include
    #include

    namespace smart_log
    {
        typedef void (*ErrorHandler)(const std::string&);
        typedef const std::string (*Obfuscater)(const std::string&);
    //This type provides constant which set the writing log mode.
    //If a current mode is bigger then methods mode the writing will be ignored.
    //It needs for log flood control
    enum LogLevel{eNormal, eExtended, eDebug};

        struct LogParameters
        {
            std::string m_strLogFileName;
            //Pointer to a function which does appropriate manipulations in case of a log corruption. Set to 0 if it doesn't need.
            ErrorHandler m_pErrorHandler;    
            //Pointer to a function which obfuscates each string writing to a log file. Set to 0 if it doesn't need.
            Obfuscater m_pObfuscater;
            size_t m_uiLogMaxSize;
            unsigned short m_siMaxSavedLogs;
            //Is the thread synchronization needed?
            bool m_bIsMultiThreaded;
            //Indicates whether log will be saved or not. If this flag is set then log will be saved when its size exceed m_uiLogMaxSize.
            //Use m_siMaxSavedLogs to control how many log files will be saved. If the current number of log files has reached the m_siMaxSavedLogs then
            //new saved log would replace the oldest one.
            bool m_bIsSaveLog;
            LogLevel m_xLogLevel;
            //Path to the log location. It will be created if no exists.
            boost::filesystem::path m_xLogSavedPath;
        };

        class Logger
        {
            //---------------------------------------Data
            size_t m_uiCurrentLogSize;
            short int m_siCurrentSavedLogs;
            LogParameters m_xParameters;
            std::ofstream m_xOfstream;
            boost::interprocess::named_mutex m_xMutex;
            //File name with full path in which it will be create
            boost::filesystem::path m_xFullFileName;
            //--------------------------------------Internal methods
        private:
            //Common method for message writing
            void WriteLog(LogLevel xLevel, const std::string& strMessage);
            void HandleLogSizeExcess();
            std::string Timestamp();
            void CreatePath(boost::filesystem::path xPath);
            //--------------------------------------Interface
        public:
            Logger(const LogParameters& xParameters);

            //Set of methods which concretize the common WriteLog method to log levels.
            void WriteNormalLog(const std::ostringstream& strMessage)
            {
                WriteLog( eNormal, strMessage.str() );
            }
            void WriteExtendedLog(const std::ostringstream& strMessage)
            {
                WriteLog( eExtended, strMessage.str() );
            }
            void WriteDebugLog(const std::ostringstream& strMessage)
            {
                WriteLog( eDebug, strMessage.str() );
            }
            //-----------------------------------Setters
            void SetErrorHandler(ErrorHandler pErrorHandler)
            {
                m_xParameters.m_pErrorHandler = pErrorHandler;
            }
            void SetLogMode(LogLevel xLevel)
            {
                m_xParameters.m_xLogLevel = xLevel;
            }
        };
    }
    #endif _LOGGER_

    * This source code was highlighted with Source Code Highlighter.


    Logger.cpp
    #include "Logger.h"
    #include
    #include
    #include
    #include
    #include
    #include

    namespace fs = boost::filesystem;
    namespace multiprocess = boost::interprocess;
    using namespace smart_log;

    Logger::Logger(const LogParameters& xParameters):
                    m_xParameters(xParameters),
                    m_xMutex(multiprocess::open_or_create,
                             (xParameters.m_strLogFileName + std::string("smart_logger_mutex") ).c_str() ),
                    m_uiCurrentLogSize(0)
    {
        m_xMutex.unlock();
        m_xOfstream.exceptions(std::ofstream::failbit | std::ofstream::badbit);
        m_xFullFileName = m_xParameters.m_xLogSavedPath;
        m_xFullFileName /= xParameters.m_strLogFileName;
    }

    void Logger::WriteLog(LogLevel xLevel, const std::string& strMessage)
    try
    {
        multiprocess::scoped_lock xLock;
        if(m_xParameters.m_bIsMultiThreaded)
        {
            xLock = multiprocess::scoped_lock(m_xMutex, multiprocess::defer_lock_type());
            xLock.lock();
        }
        CreatePath(m_xParameters.m_xLogSavedPath);
        
        //Don't do anything if the current log level less then the message demands
        if(xLevel > m_xParameters.m_xLogLevel)
            return;
        if(m_uiCurrentLogSize + strMessage.length() > m_xParameters.m_uiLogMaxSize)
            HandleLogSizeExcess();
        if( !m_xOfstream.is_open() )
            m_xOfstream.open( (m_xFullFileName.file_string() + "-" + Timestamp() + ".log").c_str() );
        //Make an output string
        std::ostringstream xStream;
        xStream << "[" << Timestamp() << "]: " << strMessage;
        const std::string& xFinalString = xStream.str();
        if(m_xParameters.m_pObfuscater)
            m_xOfstream << m_xParameters.m_pObfuscater(xFinalString) << std::endl;
        else
            m_xOfstream << xFinalString << std::endl;
        m_uiCurrentLogSize += strMessage.length();
    }
    catch (std::ofstream::failure xFail)
    {
        if(m_xParameters.m_pErrorHandler)
            m_xParameters.m_pErrorHandler("Problem with a file creation or writing to the already existing file.");
        else
            throw;
    }

    void Logger::HandleLogSizeExcess()
    {
        if(m_xOfstream.is_open())
            m_xOfstream.close();
        //Goes through the log directory and finds files which looks like "m_strLogFileName-*Timestamp*"
        fs::directory_iterator xEndIterator;
        std::set xFileList;
        for( fs::directory_iterator it(m_xParameters.m_xLogSavedPath); it != xEndIterator; ++it )
        {
            std::string xCurrentFile = it->path().filename();
            if( fs::is_regular_file(it->status()) )
                if(xCurrentFile.find(m_xParameters.m_strLogFileName) != std::string::npos)
                    xFileList.insert(xCurrentFile);
        }
        //If the log files number exceeds the m_siMaxSavedLogs then keep on removing
        //files until current files number won't be less then threshold
        if(m_xParameters.m_siMaxSavedLogs)
        {
            if(xFileList.size() >= m_xParameters.m_siMaxSavedLogs)
            {
                for(std::set::iterator it = xFileList.begin(); it != xFileList.end()
                    && xFileList.size() >= m_xParameters.m_siMaxSavedLogs;)
                {

                    fs::remove(fs::path(m_xParameters.m_xLogSavedPath) /= *it);
                    xFileList.erase(it++);
                }
            }
        }
        else//Save files property is turned off hence remove all existing log files
        {
            for(std::set::iterator it = xFileList.begin(); it != xFileList.end();)
            {
                fs::remove(fs::path(m_xParameters.m_xLogSavedPath) /= *it);
                xFileList.erase(it++);
            }
        }
        m_uiCurrentLogSize = 0;
        //Create a new file
        m_xOfstream.open( (m_xFullFileName.file_string() + "-" + Timestamp() + ".log").c_str() );
    }

    void Logger::CreatePath(fs::path xPath)
    try
    {
        //If a directory doesn't exist then try to create full path up to the required directory
        if( !fs::exists(m_xParameters.m_xLogSavedPath) )
        {
            fs::path xTmpPath;
            for(fs::path::iterator xIt = m_xParameters.m_xLogSavedPath.begin();
                xIt != m_xParameters.m_xLogSavedPath.end();
                ++xIt)

            {
                xTmpPath /= *xIt;
                if( !fs::exists(xTmpPath) )
                    fs::create_directory(xTmpPath);
            }
        }
     
    }
    catch (fs::basic_filesystem_error)
    {
        if(m_xParameters.m_pErrorHandler)
            m_xParameters.m_pErrorHandler("Problem with a directory creation");
        else
            throw;
    }

    std::string Logger::Timestamp()
    {
        SYSTEMTIME xTime;
        ::GetSystemTime(&xTime);
        std::ostringstream xStream;
        xStream << xTime.wDay << "."
                << xTime.wMonth << "."
                << xTime.wYear << "-"
                << xTime.wHour << "."
                << xTime.wMinute << "."
                << xTime.wSecond << "."
                << xTime.wMilliseconds;

        return xStream.str();
    }


    * This source code was highlighted with Source Code Highlighter.


    An example of creating a convenient interface to the class:
    #include "Logger.h"
    #include
    #include
    #include

    class LogInstance
    {
        static boost::scoped_ptr m_spLogger;
    public:
        static const boost::scoped_ptr& GetLog()
        {
            if(!m_spLogger)
            {
                smart_log::LogParameters xParams;
                xParams.m_bIsMultiThreaded = true;
                xParams.m_pErrorHandler = 0;
                xParams.m_pObfuscater = 0;
                xParams.m_siMaxSavedLogs = 0;
                xParams.m_strLogFileName = "log_file";
                xParams.m_uiLogMaxSize = 8192;
                xParams.m_xLogLevel = smart_log::eNormal;
                xParams.m_xLogSavedPath = "./log/log/log";
                m_spLogger.reset(new smart_log::Logger(xParams));
            }
            return m_spLogger;
        }

    };

    #define NORMAL_LOG(MSG)\
    {\
        std::ostringstream xStrm;\
        xStrm << __FILE__ << ": "<< __LINE__ << " " << __FUNCTION__ << "(): " << MSG;\
        LogInstance::GetLog()->WriteNormalLog(xStrm);\
    }
    #define EXTENDED_LOG(MSG)\
    {\
        std::ostringstream xStrm;\
        xStrm << __FILE__ << ": "<< __LINE__ << " " << __FUNCTION__ << "(): " << MSG;\
        LogInstance::GetLog()->WriteExtendedLog(xStrm);\
    }
    #define DEBUG_LOG(MSG)\
    {\
        std::ostringstream xStrm;\
        xStrm << __FILE__ << ": "<< __LINE__ << " " << __FUNCTION__ << "(): " << MSG;\
        LogInstance::GetLog()->WriteDebugLog(xStrm);\
    }

    * This source code was highlighted with Source Code Highlighter.


    I hope this post will encourage people who do not use logs to use them and I hope my implementation will be useful to them. Good luck debugging everyone :)

    Also popular now: