Необходимо ли логирование программ?

К написанию данной статьи меня сподвиг опыт работы с проектами в которых либо отсутсвоала система логирования как таковая, либо присутствовало ее жалкое подобие, по которому было невозможно ни определить проблему, ни даже примерное место ее появления. Под катом немного теории и непосредственно практическая реализация класса для записи логов на С++.

Вступление

Мне часто приходилось сталкиваться с полным отсутствием понимания назначения логирования в приложениях, хотя система логирования это далеко не второстепенная фаза в разработке проекта. Но, зачастую, люди это понимают уже на стадии сдачи поекта, когда введение полноценной системы логирования — процесс достаточно затратный и как результат, оставляют все как есть. Что в результате имеем? А имеем мы систему, в которой любая проблема у заказчика превращается в головную боль разработчика, т.к невозможно восстановить причины возникновения проблемы у заказчика, т.е у разработчика есть только описание проблемы от человека, у которого эта проблема воспроизвелась. К сожалению, мы живем не в идеальном мире и как правило описания проблемы носит малоинформативный характер, т.к пользователи системы не являются грамотными тестерами и не могут описать проблему подробно(есть конечно приятные исключения, но их мало). Особенно остро проблема логирования стоит когда нет возможности воспроизведения проблемы на своей стороне.

Типичные ошибки

Я бы хотел выделить основные ошибки логирования с которыми я сталкивался:

• Интерфейс к логам является набором #define'ов под которыми скрывается простой fprintf в файл. А что если появится новый поток? Или понадобится более умная обработка логов? Правильно все сломается и придется переписывать.
• Строчка выводимая в лог является конкантенацией имени подсистемы и непосредственно сообщения. Например в модуле ответсвенном за взаимодействие с БД, строчка типа: «sql: <SQL_QUERY_TEXT>». О чем говорит эта строчка? Да ни чем, просто о факте, что где-то был выполнен запрос к БД.
• Нет timestamp при выводе строки лога.
• Нет порогового разделения логов, т.е нет возможности отключить часть логов или выключить их совсем(сомнительная опция :) )
• Слишком редкая запись информации в лог(например в начале и в конце ф-ии, без трассировки ее)
• Малоинформативные записи(не выводится значения переменных и т.д)

Зачем нужны логи?

Ниже перечислены лишь несколько плюсов, которые сразу приходят в голову:

• Возможность быстрого определения причин проблемы, без многочасового сидения в дебагере, пытаясь определить проблему.
• Возможность «удаленной отладки», т.е возможность отлаживать приложение по имеющимся логам от заказчика(очень полезно когда нет возможности тестировать свое приложение без участия заказчика)
• Перекладывания части работы на техническую поддержку. Т.е support обучается типовым проблемам, секциям в логах и т.д. После чего они сами в состоянии будут определить лежащие на поверхности проблемы, не отвлекая каждый раз разработчиков по пустякам.

Хорошо расписанное назначение логов, а также советы по построению системы логирования расписаны здесь.
Я предлагаю свою реализацию класса, который может применятся для записи логов, реализация вдохновлена статьей ссылку на котрую я дал выше.
Основные настройки которые могут быть выполнены по отношению к классу:

• Выбор имени лог файла
• Выбор директории где будут храниться лог файлы
• Включение\выключение межпроцессорной синхронизации
• Ограничение размера лог файла
• Ограничение числа лог файлов, которые могут быть сохранены в директории
• Задание процедуры, котрая будет вызвана при ошибке в записи в лог файл, или при его открытии
• Задание процедуры, которая будет изменять каждую строчку при записи, так, как необходимо пользователю. Удобно, когда Вы не хотите, чтобы кто-то посторонний читал Ваш лог.
• Уровень логов, которые в данный момент могут быть выведены(всего в классе представлен 3 уровня: Обычный, Расширеный и Дебажный). Т.е отсекает все логи приоритет которых выше порога.

Класс реализован с использованием библиотеки boost и является кроссплатформенным за исключением ф-ии Timestamp() которая является windows-зависимой. Ф-ия легко переписывается под любую другую ОС, при необходимости.

Реализация:

Logger.h

#ifndef _LOGGER_
#define _LOGGER_

#include <string>
#include <fstream>
#include <sstream>
#include <boost/interprocess/sync/named_mutex.hpp>
#include <boost/scoped_ptr.hpp>
#include <boost/filesystem/path.hpp>

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 <ctime>
#include <boost/filesystem/operations.hpp>
#include <boost/interprocess/sync/scoped_lock.hpp>
#include <set>
#include <algorithm>
#include <windows.h>

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<boost::interprocess::named_mutex> xLock;
    if(m_xParameters.m_bIsMultiThreaded)
    {
        xLock = multiprocess::scoped_lock<multiprocess::named_mutex>(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<std::string> 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<std::string>::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<std::string>::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<fs::path>)
{
    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.

Пример создания удобного интерфейса к классу:

#include "Logger.h"
#include <boost/scoped_ptr.hpp>
#include <sstream>
#include <iostream>

class LogInstance
{
    static boost::scoped_ptr<smart_log::Logger> m_spLogger;
public:
    static const boost::scoped_ptr<smart_log::Logger>& 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.

Надеюсь этим постом я сподвигну людей не использующих логи, на их использование и надеюсь моя реализацию будет им полезна. Удачной всем отладки :)