Sleds/K2Daemon/LogTrace.cpp

/*
 Modifications copyright (c)  2013 IOnU Security Inc. All rights reserved
 Added to IonU source repository in August 2013 by Kendrick Webster,
 based on public-domain code by Kendrick Webster.
-----------------------------------------------------------------------------
 Log trace message writer                                         2011 - 2013

 Written by Ken Webster <ken@kenwebster.org>
 [ other contributers can add their names here ]

 To the extent possible under law, the author(s) have dedicated all copyright
 and related and neighboring rights to this software to the public domain
 worldwide. This software is distributed without any warranty.

 See the CC0 Public Domain Dedication for details:
 <http://creativecommons.org/publicdomain/zero/1.0/>
-----------------------------------------------------------------------------
 LogTrace.cpp -- implementation of the interface defined in LogTrace.h.
 See LogTrace.h for a description of this module.
---------------------------------------------------------------------------*/
#include <sys/socket.h>
#include <netinet/in.h>
#include <stdlib.h>
#include <stdarg.h>
#include <stdio.h>
#include <string.h>
#include <chrono>
#include <thread>
#include <mutex>
#include <unordered_map>
#include <string>
#include "LogTrace.h"
#include "../libeye/eyelog.h"

using namespace sequencelogic;

static Log::config_t* logConfig = NULL;
namespace Log
{
    severity_t FilterLevel = debug3;
}

#define LOG_HOST_IP 0x7F000001  // 127.0.0.1 (loopback)
#define LOG_HOST_PORT 514

#define INVALID_SOCKET -1
#define SOCKET_ERROR   -1

static int sock = INVALID_SOCKET;
static struct sockaddr_in addr;

static void initSock(void)
{
	static bool fInitialized = false;
	if (!fInitialized)
	{
		fInitialized = true;
		sock = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP);
		addr.sin_family = AF_INET;
		addr.sin_port = htons(LOG_HOST_PORT);
		addr.sin_addr.s_addr = htonl(LOG_HOST_IP);		
	}
}

// Write specified number of chars (bytes) to the log daemon
static void logWrite(const char * pBuf, size_t len, Log::severity_t severity)
{
	if (NULL == pBuf || NULL == logConfig)
	{
		return;
	}
	
	if (severity > logConfig->filterLevel)
	{
		return;
	}
	
	if (logConfig->echoToUDP514)
	{
		initSock();
		if (INVALID_SOCKET != sock)
		{
			sendto(sock, pBuf, len, 0, (struct sockaddr *)&addr, sizeof(addr));
		}
	}
	
	if (logConfig->echoToStdout)
	{
		fwrite(pBuf, 1, len, stdout);
		fwrite("\n", 1, 1, stdout);
	}
	
    if (logConfig->logToFile)
    {
        EyeLog::LOG_LEVEL level;
        switch (severity)
        {
        case Log::emergency:      level = EyeLog::IONU_FATAL;  break;
        case Log::alert:          level = EyeLog::IONU_FATAL;  break;
        case Log::critical:       level = EyeLog::IONU_ERROR;  break;
        case Log::error:          level = EyeLog::IONU_ERROR;  break;
        case Log::warning:        level = EyeLog::IONU_WARN;   break;
        case Log::notice:         level = EyeLog::IONU_WARN;   break;
        case Log::informational:  level = EyeLog::IONU_INFO;   break;
        case Log::debug:          level = EyeLog::IONU_DEBUG;  break;
        case Log::debug2:         level = EyeLog::IONU_TRACE;  break;
        case Log::debug3:         level = EyeLog::IONU_TRACE;  break;
        default:                  level = EyeLog::IONU_TRACE;  break;
        }
        std::string msg (pBuf);
        EyeLog::GetInstance()->Log (level, msg);
    }
}

// copy the rightmost (len - 1) chars plus the NUL terminator from src to dst
// (len is buffer size, dst is always NUL-terminated)
static void rightstr(const char * src, char * dst, size_t len)
{
	size_t slen = strlen(src);
	if (slen > (len - 1))
	{
		memcpy(dst, src + (slen - (len - 1)), len);
	}
	else
	{
		memcpy(dst, src, slen + 1);
	}
}

static const char * severity_to_string(Log::severity_t severity)
{
	switch (severity)
	{
#define X(level, abbrev) \
	case Log::level: return #abbrev;
		LOG_TRACE_SEVERITY_LEVELS
#undef X
	default: return "---";
	}
}

// format and send a log message
static void logprintf_va(
	const char * source_file,
	unsigned int source_line,
	Log::severity_t severity,
	const char * format,
	va_list marker)
{
	char sz[1024], sz2[1280];
	size_t len = vsnprintf(sz, sizeof(sz), format, marker);
	if (len >= sizeof(sz))
	{
		len = sizeof(sz) - 1;
	}

	uint16_t seq;
	{
		static std::mutex mtx;
		static uint16_t sn = 0;
		mtx.lock();
		seq = sn++;
		sn %= 1000;
		mtx.unlock();
	}
	
	unsigned int elapsed_s, elapsed_us, delta_s, delta_us;
	{
		using std::chrono::duration_cast;
		using std::chrono::microseconds;
		using std::chrono::steady_clock;
		
		steady_clock::time_point now = steady_clock::now();
		static steady_clock::time_point start = now;
		static steady_clock::time_point prior = now;
		uint64_t elapsed_microseconds = duration_cast<microseconds>(now - start).count();
		uint64_t delta_microseconds;
		{
			static std::mutex mtx;
			mtx.lock();
			delta_microseconds = duration_cast<microseconds>(now - prior).count();
			prior = now;
			mtx.unlock();
		}
		
		elapsed_s = static_cast<unsigned int>(elapsed_microseconds / 1000000);
		elapsed_us = static_cast<unsigned int>(elapsed_microseconds % 1000000);
		delta_s = static_cast<unsigned int>(delta_microseconds / 1000000);
		delta_us = static_cast<unsigned int>(delta_microseconds % 1000000);
	}
	
    unsigned int elapsed_m, elapsed_h, elapsed_d;
    {
        elapsed_m = elapsed_s / 60; elapsed_s %= 60;
        elapsed_h = elapsed_m / 60; elapsed_m %= 60;
        elapsed_d = elapsed_h / 24; elapsed_h %= 24;
    }
    
#if 0 // K2Daemon is single-threaded so the thread number is always 1
	unsigned int thread_number;
	{
		typedef std::unordered_map<std::thread::id, unsigned int> map_t;
		static map_t map;
		std::thread::id tid = std::this_thread::get_id();
		static unsigned int n = 1;
		static std::mutex mtx;
		mtx.lock();
		map_t::const_iterator it = map.find(tid);
		if (map.end() == it)
		{
			map[tid] = thread_number = n++;
		}
		else
		{
			thread_number = it->second;
		}
		mtx.unlock();
	}
#endif
	
	char szF[25];
	rightstr(source_file, szF, sizeof(szF));
	const char * szf = strrchr(szF, '/');
	szf = szf ? (szf + 1) : szF;
		
	len = snprintf(sz2, sizeof(sz2),
		"%.3d %3d,%.2d:%.2d:%.2d.%.6d %3d.%.6d %24s %4d %s::%s",
		seq, elapsed_d, elapsed_h, elapsed_m, elapsed_s, elapsed_us, delta_s, delta_us,
		szf, source_line, severity_to_string(severity), sz);
		
	if (len >= sizeof(sz2))
	{
		len = sizeof(sz2) - 1;
	}
	logWrite(sz2, len, severity);
}

static void loghexdump_(
	const char * source_file,
	unsigned int source_line,
	Log::severity_t severity,
	const void * d,
	size_t n)
{
	std::string s;
	int addr = 0;
	int bytes = 0;
	const uint8_t* c = reinterpret_cast<const uint8_t*>(d);
	while (n--)
	{
		char b[3];
		snprintf(b, sizeof(b), "%.2X", *c++);
		s += b;
		switch (++bytes)
		{
		case 8:
			s += "  ";
			break;
			
		case 16:
			logprintf_1(source_file, source_line, severity, "%.4X:  %s", addr, s.c_str());
			s = "";
			addr += 16;
			bytes = 0;
			break;
			
		default:
			s += ' ';
			break;
		}
	}
	if (s.length())
	{
		if (addr > 0)
		{
			logprintf_1(source_file, source_line, severity, "%.4X:  %s", addr, s.c_str());
		}
		else
		{
			logprintf_1(source_file, source_line, severity, "%s", s.c_str());
		}
	}
}

//-------------------------------------------------------------------------
// Module interface functions
// See header for descriptions
//-------------------------------------------------------------------------

void logprintf_1(
	const char * source_file,
	unsigned int source_line,
	Log::severity_t severity,
	const char * format,
	...)
{
	va_list marker;
	va_start(marker, format);
	logprintf_va(source_file, source_line, severity, format, marker);
	va_end(marker);
}
	
void loghexdump_1(
	const char * source_file,
	unsigned int source_line,
	Log::severity_t severity,
	const void * d,
	size_t n)
{
	loghexdump_(source_file, source_line, severity, d, n);
}

// ---------- Log initialization and cleanup ----------
void Log::Initialize(config_t* config)
{
	logConfig = config;
    if (config)
    {
        Log::FilterLevel = config->filterLevel;
        if (config->logToFile)
        {
            // If log file was specified as "syslog" then write to syslog rather than our own log file
            if (config->file.length() >= 6 && config->file.compare (config->file.length() - 6, 6, "syslog") == 0) {
                IONUCONFIGLOG(config->shortIdentifier.c_str(), "", EyeLog::IONU_TRACE, EyeLog::IONU_SYSLOG, "%t%m");
            }
            else {
                IONUCONFIGFILELOG(config->shortIdentifier.c_str(), "", EyeLog::IONU_TRACE, config->file.c_str(),
                                  (config->echoToSyslog ? EyeLog::IONU_SYSLOG : EyeLog::IONU_FILE), "%t%m");
                EyeLog::GetInstance()->SetMaxLogFile(config->nBytesPerFileMax);
                EyeLog::GetInstance()->SetLogFiles(static_cast<int>(config->nFilesMax));
            }
        }
    }
    if (config && config->logToFile)
    {
        logprintf(Log::informational, "Log file: %s", config->file.c_str());
    }
}

void Log::Finalize(void)
{
    if (logConfig && logConfig->logToFile)
    {
        IONUCLOSELOG();
    }
}