LogSender.cpp

Go to the documentation of this file.

/*
* This file is part of ArmarX.
*
* Copyright (C) 2011-2016, High Performance Humanoid Technologies (H2T), Karlsruhe Institute of Technology (KIT), all rights reserved.
*
* ArmarX is free software; you can redistribute it and/or modify
* it under the terms of the GNU General Public License version 2 as
* published by the Free Software Foundation.
*
* ArmarX is distributed in the hope that it will be useful, but
* WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License
* along with this program. If not, see <http://www.gnu.org/licenses/>.
*
* @package    ArmarXCore::core
* @author     Nils Adermann (naderman at naderman dot de)
* @date       2010
* @copyright  http://www.gnu.org/licenses/gpl-2.0.txt
*             GNU General Public License
*/
 
#include "LogSender.h"
 
#include <memory>
#include <optional>
 
#include <dlfcn.h>
#include <sys/syscall.h>
 
#include <boost/logic/tribool.hpp>
 
#include <IceUtil/Time.h>
 
#include <SimoxUtility/algorithm/string/string_tools.h>
 
#include <ArmarXCore/core/util/StringHelpers.h>
#include <ArmarXCore/interface/core/Log.h>
 
#include "SpamFilterData.h"
#include <cxxabi.h>
#include <execinfo.h>
 
namespace armarx
{
    struct LogSender::Impl
    {
        //! Flag to specify a minimum logging level for this LogSender<br/>
        //! usually is set by Logging-Class
        MessageTypeT minimumLoggingLevel;
 
        SpamFilterMapPtr spamFilter;
        bool cancelNextMessage;
        MessageTypeT currentSeverity;
 
        std::string currentFile;
        int currentLine;
        std::string currentFunction;
        LogTag currentTag;
        boost::logic::tribool printBackTrace;
 
        std::optional<Ice::Int> threadId;
 
        static std::mutex mutex;
    };
 
    LogPrx LogSender_logProxy;
    std::string LogSender_componentName;
    std::string LogSender_loggingGroup;
    std::vector<LogMessage> LogSender_buffer;
    std::mutex LogSender::Impl::mutex;
    bool LogSender_LoggingActivated = true;
    MessageTypeT LogSender_GlobalMinimumLoggingLevel = MessageTypeT::INFO;
    bool LogSender_ColoringActivated = true;
    bool LogSender_SendLogging = true;
    std::ostream LogSender_outbuf(std::cout.rdbuf());
    std::ostream LogSender_errbuf(std::cerr.rdbuf());
 
    LogSenderPtr
    LogSender::createLogSender()
    {
        try
        {
            return std::make_shared<LogSender>();
        }
        catch (...)
        {
            return nullptr;
        }
    }
 
    LogSender::LogSender() : impl(new Impl)
    {
        impl->minimumLoggingLevel = MessageTypeT::UNDEFINED;
        impl->cancelNextMessage = false;
        impl->currentSeverity = MessageTypeT::INFO;
        impl->printBackTrace = boost::logic::indeterminate;
 
        initConsole();
        resetLocation();
    }
 
    LogSender::LogSender(const std::string& componentName, LogPrx logProxy) : impl(new Impl)
    {
        impl->minimumLoggingLevel = MessageTypeT::UNDEFINED;
        impl->cancelNextMessage = false;
        impl->currentSeverity = MessageTypeT::INFO;
        impl->printBackTrace = true;
 
        initConsole();
        setProxy(componentName, logProxy);
        resetLocation();
    }
 
    LogSender::~LogSender()
    {
        if (!currentMessage.str().empty())
        {
            flush();
        }
    }
 
    void
    LogSender::setProxy(const std::string& componentName, LogPrx logProxy)
    {
        std::unique_lock lock(Impl::mutex);
        LogSender_logProxy = logProxy;
        LogSender_componentName = componentName;
 
        if (!logProxy)
        {
            return;
        }
 
        for (unsigned int i = 0; i < LogSender_buffer.size(); ++i)
        {
            LogSender_logProxy->writeLog(LogSender_buffer[i]);
        }
 
        LogSender_buffer.clear();
    }
 
    void
    LogSender::SetComponentName(const std::string& componentName)
    {
        std::unique_lock lock(Impl::mutex);
        LogSender_componentName = componentName;
    }
 
    void
    LogSender::SetLoggingGroup(const std::string& loggingGroup)
    {
        std::unique_lock lock(Impl::mutex);
        LogSender_loggingGroup = loggingGroup;
    }
 
    LogSender&
    LogSender::operator<<(const std::chrono::nanoseconds& timestamp)
    {
        if (timestamp.count() > 1000)
        {
            return *this << std::chrono::duration_cast<std::chrono::microseconds>(timestamp);
        }
 
        currentMessage << timestamp.count() << " ns";
        return *this;
    }
 
    LogSender&
    LogSender::operator<<(const std::chrono::microseconds& timestamp)
    {
        if (timestamp.count() > 1000)
        {
            return *this << std::chrono::duration_cast<std::chrono::milliseconds>(timestamp);
        }
 
        if (timestamp.count() <= 1. / 1000)
        {
            return *this << std::chrono::duration_cast<std::chrono::nanoseconds>(timestamp);
        }
 
        currentMessage << timestamp.count() << " µs";
        return *this;
    }
 
    LogSender&
    LogSender::operator<<(const std::chrono::milliseconds& timestamp)
    {
        if (timestamp.count() > 1000)
        {
            return *this << std::chrono::duration_cast<std::chrono::seconds>(timestamp);
        }
 
        if (timestamp.count() <= 1. / 1000)
        {
            return *this << std::chrono::duration_cast<std::chrono::microseconds>(timestamp);
        }
 
        currentMessage << timestamp.count() << " ms";
        return *this;
    }
 
    LogSender&
    LogSender::operator<<(const std::chrono::seconds& timestamp)
    {
        if (timestamp.count() > 60)
        {
            return *this << std::chrono::duration_cast<std::chrono::minutes>(timestamp);
        }
 
        if (timestamp.count() <= 1. / 1000)
        {
            return *this << std::chrono::duration_cast<std::chrono::milliseconds>(timestamp);
        }
 
        currentMessage << timestamp.count() << " s";
        return *this;
    }
 
    LogSender&
    LogSender::operator<<(const std::chrono::minutes& timestamp)
    {
        if (timestamp.count() < 1. / 60)
        {
            return *this << std::chrono::duration_cast<std::chrono::seconds>(timestamp);
        }
 
        currentMessage << timestamp.count() << " min";
        return *this;
    }
 
    LogSender&
    LogSender::operator<<(const IceUtil::Time& timestamp)
    {
        double time_count = timestamp.toMicroSecondsDouble();
        std::string unit = "µs";
 
        if (time_count >= 1000)
        {
            time_count /= 1000;
            unit = "ms";
 
            if (time_count >= 1000)
            {
                time_count /= 1000;
                unit = "s";
 
                if (time_count >= 60)
                {
                    time_count /= 60;
                    unit = "min";
 
                    if (time_count >= 60)
                    {
                        time_count /= 60;
                        unit = "h";
 
                        if (time_count >= 24)
                        {
                            return *this << timestamp.toDateTime();
                        }
                    }
                }
            }
        }
 
        return *this << std::to_string(time_count) + " " + unit;
    }
 
    LogSender::ConsoleColor
    GetColorCode(MessageType type)
    {
        switch (type)
        {
            case eVERBOSE:
                return LogSender::eBlue;
                break;
 
            case eIMPORTANT:
                return LogSender::eGreen;
 
            case eWARN:
                return LogSender::eYellow;
                break;
 
            case eERROR:
            case eFATAL:
                return LogSender::eRed;
                break;
 
            default:
                return LogSender::eReset;
                break;
        }
    }
 
    std::string
    LogSender::GetColorCodeString(MessageTypeT verbosityLevel)
    {
 
        ConsoleColor colorCode = GetColorCode((MessageType)verbosityLevel);
        return GetColorCodeString(colorCode);
    }
 
    std::string
    LogSender::GetColorCodeString(ConsoleColor colorCode)
    {
        std::stringstream stream;
 
        if (colorCode == LogSender::eReset)
        {
            stream << "\033[0"
                   << "m";
        }
        else
        {
            stream << "\033[3" << colorCode << "m";
        }
 
        return stream.str();
    }
 
    void
    LogSender::resetLocation()
    {
        impl->currentFile = "";
        impl->currentLine = -1;
        impl->currentFunction = "";
    }
 
    void
    LogSender::log(MessageTypeT severity, std::string message)
    {
        simox::alg::trim(message);
        if (impl->cancelNextMessage)
        {
            impl->cancelNextMessage = false;
            return;
        }
 
        if (!LogSender_LoggingActivated)
        {
            return;
        }
 
        if (severity < impl->minimumLoggingLevel)
        {
            return;
        }
 
        if (impl->minimumLoggingLevel == MessageTypeT::UNDEFINED &&
            severity < LogSender_GlobalMinimumLoggingLevel)
        {
            return;
        }
 
        IceUtil::Time time = IceUtil::Time::now();
 
        std::string catStr;
 
        if (!impl->currentTag.tagName.empty())
        {
            catStr = "[" + impl->currentTag.tagName + "]: ";
        }
        else
        {
            catStr = "[" + CropFunctionName(impl->currentFunction) + "]: ";
        }
 
        std::string outputStr;
 
        if (LogSender_ColoringActivated)
        {
            outputStr += GetColorCodeString(severity);
 
            if (severity >= MessageTypeT::FATAL)
            {
                outputStr += "\033[1m"; // Bold text
            }
        }
 
        outputStr += "[" + time.toDateTime().substr(time.toDateTime().find(' ') + 1) + "]" + "[" +
                     LogSender_componentName + "]" + catStr;
 
        if (LogSender_ColoringActivated)
        {
            outputStr += GetColorCodeString(eReset);
        }
 
        outputStr += message;
 
        if (LogSender_ColoringActivated)
        {
            outputStr += LogSender::GetColorCodeString(eReset);
        }
 
        LogMessage msg;
        msg.who = LogSender_componentName;
        msg.group = LogSender_loggingGroup;
        msg.time = time.toMicroSeconds();
        msg.tag = impl->currentTag.tagName;
        msg.type = (MessageType)severity;
        msg.what = message;
        msg.file = impl->currentFile;
        msg.line = impl->currentLine;
        msg.function = impl->currentFunction;
        msg.threadId = impl->threadId ? *impl->threadId : getThreadId();
 
        if ((severity >= MessageTypeT::WARN && boost::logic::indeterminate(impl->printBackTrace)) ||
            impl->printBackTrace)
        {
            msg.backtrace = CreateBackTrace();
        }
 
        if (LogSender_SendLogging && LogSender_logProxy)
        {
            LogSender_logProxy->begin_writeLog(
                msg); // use async function, so that it returns faster
        }
 
 
        try
        {
            std::unique_lock lock(
                Impl::mutex); // std::cout is not threadsafe and also lock for inserting into buffer
 
            if (severity >= MessageTypeT::ERROR)
            {
                LogSender_errbuf << "[" << msg.threadId << "]" << outputStr << std::endl;
            }
            else
            {
                LogSender_outbuf << "[" << msg.threadId << "]" << outputStr << std::endl;
            }
 
            if (!LogSender_logProxy)
            {
                LogSender_buffer.push_back(msg);
            }
 
            resetLocation();
        }
        catch (...)
        {
            std::cout << outputStr << std::endl;
            return; // mutex may be deleted already if the system shuts down at this moment
        }
    }
 
    long
    LogSender::getThreadId()
    {
        return syscall(SYS_gettid);
    }
 
    long
    LogSender::getProcessId()
    {
#ifdef WIN32
        return 0;
#else
        return getpid();
#endif
    }
 
    void
    LogSender::flush()
    {
 
        log(impl->currentSeverity, currentMessage.str());
        currentMessage.str(""); // reset
    }
 
    std::string
    LogSender::CropFunctionName(std::string const& originalFunctionName)
    {
        unsigned int maxLength = 40;
        std::string result;
 
        if (originalFunctionName.length() <= maxLength)
        {
            return originalFunctionName;
        }
 
        std::string beforeFunctionName =
            originalFunctionName.substr(0, originalFunctionName.rfind("::"));
        std::string::size_type namespaceDotsPos =
            beforeFunctionName.find("::", beforeFunctionName.find(' '));
 
        if (namespaceDotsPos != std::string::npos)
        {
            std::string afterClassName =
                originalFunctionName.substr(originalFunctionName.rfind("::"));
            result = beforeFunctionName.substr(namespaceDotsPos + 2) + afterClassName;
        }
        else
        {
            result = originalFunctionName;
        }
 
        if (result.length() <= maxLength)
        {
            return result;
        }
 
 
        result = result.substr(0, result.find("("));
        result += "(...)";
 
        return result;
    }
 
    std::string
    LogSender::CreateBackTrace(int linesToSkip)
    {
        void* callstack[128];
        const int nMaxFrames = sizeof(callstack) / sizeof(callstack[0]);
        char buf[1024];
 
        int nFrames = ::backtrace(callstack, nMaxFrames);
        char** symbols = backtrace_symbols(callstack, nFrames);
 
        std::ostringstream trace_buf;
 
        for (int i = linesToSkip; i < nFrames; i++)
        {
            Dl_info info;
 
            if (dladdr(callstack[i], &info) && info.dli_sname)
            {
                char* demangled = nullptr;
                int status = -1;
 
                if (info.dli_sname[0] == '_')
                {
                    demangled = abi::__cxa_demangle(info.dli_sname, nullptr, nullptr, &status);
                }
 
                snprintf(buf,
                         sizeof(buf),
                         "%-3d %*p %s + %zd\n",
                         i - linesToSkip + 1,
                         int(2 + sizeof(void*) * 2),
                         callstack[i],
                         status == 0                 ? demangled
                         : info.dli_sname == nullptr ? symbols[i]
                                                     : info.dli_sname,
                         (char*)callstack[i] - (char*)info.dli_saddr);
                free(demangled);
            }
            else
            {
                snprintf(buf,
                         sizeof(buf),
                         "%-3d %*p %s\n",
                         i - linesToSkip + 1,
                         int(2 + sizeof(void*) * 2),
                         callstack[i],
                         symbols[i]);
            }
 
            trace_buf << buf;
        }
 
        free(symbols);
 
        if (nFrames == nMaxFrames)
        {
            trace_buf << "[truncated]\n";
        }
 
        return trace_buf.str();
    }
 
    MessageTypeT
    LogSender::getSeverity()
    {
        return impl->currentSeverity;
    }
 
    LogSenderPtr
    LogSender::setFile(const std::string& file)
    {
        impl->currentFile = file;
        return shared_from_this();
    }
 
    LogSenderPtr
    LogSender::setLine(int line)
    {
        impl->currentLine = line;
        return shared_from_this();
    }
 
    LogSenderPtr
    LogSender::setFunction(const std::string& function)
    {
        impl->currentFunction = function;
        return shared_from_this();
    }
 
    LogSenderPtr
    LogSender::setLocalMinimumLoggingLevel(MessageTypeT level)
    {
        impl->minimumLoggingLevel = level;
        return shared_from_this();
    }
 
    LogSenderPtr
    LogSender::setBacktrace(bool printBackTrace)
    {
        impl->printBackTrace = printBackTrace;
        return shared_from_this();
    }
 
    LogSenderPtr
    LogSender::setThreadId(Ice::Int tid)
    {
        impl->threadId = tid;
        return shared_from_this();
    }
 
    LogSenderPtr
    LogSender::setTag(const LogTag& tag)
    {
        impl->currentTag = tag;
        return shared_from_this();
    }
 
    //LogSenderPtr LogSender::setSpamFilter(SpamFilterMapPtr spamFilter)
    //{
    //    this->spamFilter = spamFilter;
    //    return shared_from_this();
    //}
 
    std::string
    LogSender::levelToString(MessageTypeT type)
    {
        switch (type)
        {
            case MessageTypeT::DEBUG:
                return "Debug";
 
            case MessageTypeT::VERBOSE:
                return "Verbose";
 
            case MessageTypeT::INFO:
                return "Info";
 
            case MessageTypeT::IMPORTANT:
                return "Important";
 
            case MessageTypeT::WARN:
                return "Warning";
 
            case MessageTypeT::ERROR:
                return "Error";
 
            case MessageTypeT::FATAL:
                return "Fatal";
 
            default:
                return "Undefined";
        }
    }
 
    MessageTypeT
    LogSender::StringToLevel(const std::string& typeStr)
    {
        if (simox::alg::to_lower(typeStr) == "debug")
        {
            return MessageTypeT::DEBUG;
        }
 
        if (simox::alg::to_lower(typeStr) == "verbose")
        {
            return MessageTypeT::VERBOSE;
        }
 
        if (simox::alg::to_lower(typeStr) == "important")
        {
            return MessageTypeT::IMPORTANT;
        }
 
        if (simox::alg::to_lower(typeStr) == "warning")
        {
            return MessageTypeT::WARN;
        }
 
        if (simox::alg::to_lower(typeStr) == "error")
        {
            return MessageTypeT::ERROR;
        }
 
        if (simox::alg::to_lower(typeStr) == "fatal")
        {
            return MessageTypeT::FATAL;
        }
 
        return MessageTypeT::UNDEFINED;
    }
 
    void
    LogSender::SetGlobalMinimumLoggingLevel(MessageTypeT level)
    {
        if (level == LogSender_GlobalMinimumLoggingLevel)
        {
            return;
        }
 
        LogSender_GlobalMinimumLoggingLevel = level;
        std::cout << "setting global logging level to " << LogSender::levelToString(level)
                  << std::endl;
    }
 
    MessageTypeT
    LogSender::GetGlobalMinimumLoggingLevel()
    {
        return LogSender_GlobalMinimumLoggingLevel;
    }
 
    void
    LogSender::SetLoggingActivated(bool activated, bool showMessage)
    {
        if (LogSender_LoggingActivated && showMessage && !activated)
        {
            std::cout << "logging is now DEACTIVATED" << std::endl;
        }
 
        if (activated && LogSender_LoggingActivated != activated && showMessage)
        {
            std::cout << "logging is now ACTIVATED" << std::endl;
        }
        LogSender_LoggingActivated = activated;
    }
 
    void
    LogSender::SetSendLoggingActivated(bool activated)
    {
        LogSender_SendLogging = activated;
    }
 
    void
    LogSender::SetColoredConsoleActivated(bool activated)
    {
        LogSender_ColoringActivated = activated;
    }
 
    void
    LogSender::initConsole()
    {
        static bool initialized = false;
 
        if (!initialized)
        {
            initialized = true;
            char* termType = getenv("TERM");
 
            if (termType != nullptr)
            {
                std::string termTypeStr(termType);
 
                if (termTypeStr != "xterm" && termTypeStr != "emacs" &&
                    termTypeStr != "xterm-256color")
                {
                    LogSender::SetColoredConsoleActivated(false);
                }
            }
            else
            {
                LogSender::SetColoredConsoleActivated(false);
            }
        }
    }
 
    template <>
    ARMARXCORE_IMPORT_EXPORT LogSender&
        LogSender::operator<< <LogSender::ConsoleColor>(const LogSender::ConsoleColor& colorCode)
    {
        currentMessage << LogSender::GetColorCodeString(colorCode);
 
        return *this;
    }
 
    template <>
    LogSender& LogSender::operator<< <MessageTypeT>(const MessageTypeT& severity)
    {
        impl->currentSeverity = severity;
 
        return *this;
    }
 
    template <>
    LogSender& LogSender::operator<< <LogTag>(const LogTag& tag)
    {
        impl->currentTag = tag;
 
        return *this;
    }
 
    template <>
    LogSender& LogSender::operator<< <LogSender::manipulator>(const manipulator& manipulator)
    {
        (this->*manipulator)();
 
        return *this;
    }
 
    LogSender&
    LogSender::operator<<(const StandardEndLine& manipulator)
    {
        flush();
 
        return *this;
    }
 
    template <>
    LogSender& LogSender::operator<< <bool>(const bool& duality)
    {
        if (duality)
        {
            currentMessage << "true";
        }
        else
        {
            currentMessage << "false";
        }
 
        return *this;
    }
 
    template <>
    LogSender& LogSender::operator<< <SpamFilterDataPtr>(const SpamFilterDataPtr& spamFilterData)
    {
        if (!spamFilterData)
        {
            return *this;
        }
 
        std::unique_lock lock(*spamFilterData->mutex);
        float deactivationDurationSec = spamFilterData->durationSec;
        SpamFilterMapPtr spamFilter = spamFilterData->filterMap;
        std::string id = impl->currentFile + ":" + to_string(impl->currentLine);
        auto it = spamFilter->find(spamFilterData->identifier);
 
        if (it != spamFilter->end())
        {
            auto itSub = it->second.find(id);
            IceUtil::Time durationEnd = IceUtil::Time::now() + IceUtil::Time::milliSecondsDouble(
                                                                   deactivationDurationSec * 1000);
 
            if (itSub == it->second.end())
            {
                itSub = it->second.insert(std::make_pair(id, durationEnd)).first;
                impl->cancelNextMessage = false;
            }
            else if (IceUtil::Time::now() < itSub->second)
            {
                impl->cancelNextMessage = true;
            }
            else
            {
                impl->cancelNextMessage = false;
                itSub->second = durationEnd;
            }
        }
 
        return *this;
    }
} // namespace armarx