Browse Source

merge JSON-101 into default branch

JSON-105
Roker 4 years ago
parent
commit
8f180cb41b
12 changed files with 983 additions and 163 deletions
  1. +3
    -1
      server/Makefile
  2. +2
    -2
      server/Makefile.conf
  3. +19
    -22
      server/ev_server.cc
  4. +3
    -11
      server/ev_server.hh
  5. +109
    -110
      server/json-adapter.cc
  6. +3
    -3
      server/json-adapter.hh
  7. +18
    -5
      server/json_rpc.cc
  8. +550
    -0
      server/logger.cc
  9. +171
    -0
      server/logger.hh
  10. +17
    -0
      server/logger_config.hh
  11. +19
    -9
      server/main.cc
  12. +69
    -0
      server/unittest_logger.cc

+ 3
- 1
server/Makefile View File

@ -86,7 +86,9 @@ $(TARGET)-static: main.o libjson-adapter.a
$(TARGET_TEST): servertest.o libjson-adapter.a
$(CXX) $(CPPFLAGS) $^ $(LDFLAGS) $(LDLIBS) -o $@
$(TARGET_GTEST): unittest_json.o unittest_nfc.o unittest_decompose.o unittest_rpc.o gtest-all.o gtest_main.o libjson-adapter.a
$(TARGET_GTEST): unittest_json.o unittest_nfc.o unittest_decompose.o unittest_rpc.o \
unittest_logger.o \
gtest-all.o gtest_main.o libjson-adapter.a
$(CXX) $(CPPFLAGS) $^ $(LDFLAGS) $(LDLIBS) -o $@
libjson-adapter.a: $(ALL_OBJECTS)


+ 2
- 2
server/Makefile.conf View File

@ -70,7 +70,7 @@ ifeq ($(BUILD_FOR),Linux)
CXXFLAGS+= -w
endif
ifdef DEBUG
CXXFLAGS+= -O0 -g -ggdb
CXXFLAGS+= -O0 -g -ggdb -DDEBUG_ENABLED
else
CXXFLAGS+= -O3 -DNDEBUG
endif
@ -82,7 +82,7 @@ else ifeq ($(BUILD_FOR),Darwin)
CXXFLAGS+= -w
endif
ifdef DEBUG
CXXFLAGS+= -O0 -g
CXXFLAGS+= -O0 -g -DDEBUG_ENABLED
else
CXXFLAGS+= -O3 -DNDEBUG
endif


+ 19
- 22
server/ev_server.cc View File

@ -9,6 +9,7 @@
#include "json_rpc.hh"
#include "pep-utils.hh"
#include "gpg_environment.hh"
#include "logger.hh"
#include "server_version.hh"
#include <pEp/message_api.h>
@ -169,8 +170,9 @@ void ev_server::sendReplyString(evhttp_request* req, const char* contentType, co
evhttp_send_reply(req, 500, "evbuffer_add() failed.", outBuf);
}
Log() << "\n=== sendReplyString(): ret=" << ret << ", contentType=" << (contentType ? "«" + std::string(contentType)+ "»" : "NULL")
<< ", output=«" << outputText << "»." << std::endl;
Log() << Logger::Debug << "sendReplyString(): ret=" << ret
<< ", contentType=" << (contentType ? "«" + std::string(contentType)+ "»" : "NULL")
<< ", output=«" << outputText << "».";
}
@ -208,7 +210,7 @@ void ev_server::OnOtherRequest(evhttp_request* req, void*)
const evhttp_uri* uri = evhttp_request_get_evhttp_uri(req);
const char* path = evhttp_uri_get_path(uri);
const char* uri_string = evhttp_request_get_uri(req);
Log() << "** Request: [" << uri_string << "] " << (path? " Path: [" + std::string(path) + "]" : "null path") << "\n";
Log() << Logger::Debug << "** Request: [" << uri_string << "] " << (path? " Path: [" + std::string(path) + "]" : "null path") << "\n";
try{
if(path)
@ -216,7 +218,7 @@ void ev_server::OnOtherRequest(evhttp_request* req, void*)
const auto q = files.find(path);
if(q != files.end()) // found in "files" map
{
Log() << "\t found file \"" << q->second.fileName << "\", type=" << q->second.mimeType << ".\n";
Log() << Logger::Debug << "\t found file \"" << q->second.fileName.string() << "\", type=" << q->second.mimeType << ".\n";
sendFile( req, q->second.mimeType, q->second.fileName);
return;
}
@ -229,8 +231,9 @@ void ev_server::OnOtherRequest(evhttp_request* req, void*)
catch(const std::runtime_error& e)
{
const std::string error_msg = "Internal error caused by URI \"" + std::string(uri_string) + "\"";
// TODO: log e.what() to log file, but don't send it in HTTP error message
// because it might contain sensitive information, e.g. local file paths etc.!
// Log e.what() to log file, but DON'T send it in HTTP error message
// because it might contain sensitive information, e.g. local file paths etc.!
Log() << Logger::Error << "OnOtherRequest: " << error_msg << ". what:" << e.what();
evhttp_send_error(req, HTTP_INTERNAL, error_msg.c_str() );
}
};
@ -279,6 +282,7 @@ void ev_server::OnGetFunctions(evhttp_request* req, void*)
void ev_server::OnApiRequest(evhttp_request* req, void* obj)
{
Logger L( Log(), "OnApiReq");
evbuffer* inbuf = evhttp_request_get_input_buffer(req);
const size_t length = evbuffer_get_length(inbuf);
@ -296,24 +300,26 @@ void ev_server::OnApiRequest(evhttp_request* req, void* obj)
const std::string data_string(data.data(), data.data() + nr );
if(nr>0)
{
ja->Log() << "\tData: «" << data_string << "»\n";
L << Logger::Debug << "Data: «" << data_string << "»";
bool b = js::read( data_string, p);
if(p.type() == js::obj_type)
{
const js::Object& request = p.get_obj();
answer = call( functions, request, ja );
}else{
answer = make_error( JSON_RPC::PARSE_ERROR, "evbuffer_copyout does not return a JSON string. b=" + std::to_string(b), js::Value{data_string}, 42 );
const std::string error_msg = "evbuffer_copyout does not return a JSON string. b=" + std::to_string(b);
L << Logger::Error << error_msg;
answer = make_error( JSON_RPC::PARSE_ERROR, error_msg, js::Value{data_string}, 42 );
}
}else{
ja->Log() << "\tError: " << nr << ".\n";
L << Logger::Error << "Error: " << nr << ".\n";
answer = make_error( JSON_RPC::INTERNAL_ERROR, "evbuffer_copyout returns negative value", p, request_id );
}
}
catch(const std::exception& e)
{
Log() << "\tException: \"" << e.what() << "\"\n";
L << Logger::Error << "Exception: \"" << e.what() << "\"";
answer = make_error( JSON_RPC::INTERNAL_ERROR, "Got a std::exception: \"" + std::string(e.what()) + "\"", p, request_id );
}
@ -321,16 +327,10 @@ void ev_server::OnApiRequest(evhttp_request* req, void* obj)
};
std::ostream& ev_server::Log()
Logger& ev_server::Log()
{
*log_file << "evserver: ";
return *log_file;
}
void ev_server::setLogfile(std::ostream* new_logfile)
{
log_file = new_logfile ? new_logfile : &nulllogger;
static Logger L("evs");
return L;
}
@ -338,6 +338,3 @@ void ev_server::addSharks()
{
add_sharks = true;
}
std::ostream* ev_server::log_file = &nulllogger;

+ 3
- 11
server/ev_server.hh View File

@ -3,12 +3,13 @@
#ifndef EV_SERVER_HH
#define EV_SERVER_HH
#include "nulllogger.hh"
#include <string>
#include <boost/filesystem/path.hpp>
struct evhttp_request;
class Logger;
class ev_server
{
public:
@ -34,22 +35,13 @@ public:
// so changing it later might be useless.
static boost::filesystem::path path_to_html;
// if new_logfile is NULL, the logfile is reset to nulllogger.
static
void setLogfile(std::ostream* new_logfile);
// add sharks to the JSON Adapter
static
void addSharks();
protected:
// prints "evserver:" to the log and returns it to allow << chaining
static
std::ostream& Log();
private:
static
std::ostream* log_file;
Logger& Log();
};
#endif

+ 109
- 110
server/json-adapter.cc View File

@ -22,6 +22,7 @@
#include "security-token.hh"
#include "pep-utils.hh"
#include "ev_server.hh"
#include "logger.hh"
#include "server_version.hh"
#include <boost/filesystem.hpp>
@ -113,7 +114,7 @@ struct JsonAdapter::Internal
std::string token;
std::map<EventListenerKey, EventListenerValue> eventListener;
std::ostream& Log;
Logger Log;
unsigned start_port = 0;
unsigned end_port = 0;
unsigned port = 0;
@ -132,8 +133,8 @@ struct JsonAdapter::Internal
ThreadPtr sync_thread{nullptr, ThreadDeleter};
explicit Internal(std::ostream& logger)
: Log(logger)
explicit Internal()
: Log("JAI")
{}
Internal(const Internal&) = delete;
@ -336,8 +337,6 @@ ServerVersion JsonAdapter::version()
PEP_STATUS JsonAdapter::messageToSend(void* obj, message* msg)
{
JsonAdapter* ja = static_cast<JsonAdapter*>(obj);
@ -491,11 +490,10 @@ void* JsonAdapter::keyserverLookupThreadRoutine(void* arg)
return (void*) status;
}
extern std::ofstream* my_logfile;
JsonAdapter::JsonAdapter(std::ostream* logfile)
JsonAdapter::JsonAdapter()
: guard_0(Guard_0)
, i(new Internal( *logfile ))
, i(new Internal{})
, guard_1(Guard_1)
{
i->eventBase.reset(event_base_new());
@ -511,10 +509,10 @@ JsonAdapter::JsonAdapter(std::ostream* logfile)
JsonAdapter::~JsonAdapter()
{
check_guard();
Log() << "~JsonAdapter(): " << session_registry.size() << " sessions registered." << std::endl;
Log() << "~JsonAdapter(): " << session_registry.size() << " sessions registered.";
stopSync();
this->shutdown(nullptr);
Log() << "\t After stopSync() and shutdown() there are " << session_registry.size() << " sessions registered." << std::endl;
Log() << "\t After stopSync() and shutdown() there are " << session_registry.size() << " sessions registered.";
delete i;
i=nullptr;
}
@ -543,8 +541,6 @@ void JsonAdapter::prepare_run(const std::string& address, unsigned start_port, u
i->start_port = start_port;
i->end_port = end_port;
ev_server::setLogfile( &i->Log );
if(first_session == nullptr) // okay, we are the 1st:
{
// create a dummy session just to see whether the Engine is functional.
@ -561,111 +557,112 @@ void JsonAdapter::prepare_run(const std::string& address, unsigned start_port, u
}
}
Log() << "ThreadFunc: thread id " << std::this_thread::get_id() << ". \n Registry: " << to_string( session_registry ) << std::flush;
unsigned port_ofs = 0;
Log() << "ThreadFunc: thread id " << std::this_thread::get_id() << ". \n Registry: " << to_string( session_registry );
unsigned port_ofs = 0;
try_next_port:
auto* boundSock = evhttp_bind_socket_with_handle(i->evHttp.get(), i->address.c_str(), i->start_port + port_ofs);
if (!boundSock)
{
++port_ofs;
if(i->start_port + port_ofs > i->end_port)
{
throw std::runtime_error("Failed to bind server socket: "
"No free port between " + std::to_string(i->start_port) + " and " + std::to_string(i->end_port)
);
}
goto try_next_port;
}
if ((i->sock = evhttp_bound_socket_get_fd(boundSock)) == -1)
throw std::runtime_error("Failed to get server socket for next instance.");
i->port = i->start_port + port_ofs;
i->token = create_security_token(i->address, i->port, BaseUrl);
Log() << "Bound to port " << i->port << ", sec_token=\"" << i->token << "\"" << std::endl;
auto* boundSock = evhttp_bind_socket_with_handle(i->evHttp.get(), i->address.c_str(), i->start_port + port_ofs);
if (!boundSock)
{
++port_ofs;
if(i->start_port + port_ofs > i->end_port)
{
throw std::runtime_error("Failed to bind server socket: "
"No free port between " + std::to_string(i->start_port) + " and " + std::to_string(i->end_port)
);
}
goto try_next_port;
}
if ((i->sock = evhttp_bound_socket_get_fd(boundSock)) == -1)
throw std::runtime_error("Failed to get server socket for next instance.");
i->port = i->start_port + port_ofs;
i->token = create_security_token(i->address, i->port, BaseUrl);
Log() << "Bound to port " << i->port << ", sec_token=\"" << i->token << "\"";
}
void JsonAdapter::threadFunc()
{
try
Logger L("JA:tF");
try
{
const auto id = std::this_thread::get_id();
L << Logger::Info << " +++ Thread starts: isRun=" << i->running << ", id=" << id << ". +++";
const auto q=session_registry.find(id);
if(q==session_registry.end())
{
const auto id = std::this_thread::get_id();
Log() << " +++ Thread starts: isRun=" << i->running << ", id=" << id << ". +++" << std::endl;
const auto q=session_registry.find(id);
if(q==session_registry.end())
i->session = nullptr;
PEP_STATUS status = call_with_lock(&init, &i->session); // release(session) in ThreadDeleter
if(status != PEP_STATUS_OK || i->session==nullptr)
{
i->session = nullptr;
PEP_STATUS status = call_with_lock(&init, &i->session); // release(session) in ThreadDeleter
if(status != PEP_STATUS_OK || i->session==nullptr)
const std::string error_msg = "Cannot create session! PEP_STATUS: " + status_to_string(status) + ".";
L << Logger::Error << error_msg;
if( ! i->ignore_session_error)
{
const std::string error_msg = "Cannot create session! PEP_STATUS: " + status_to_string(status) + ".";
Log() << error_msg << std::endl;
if( ! i->ignore_session_error)
{
throw std::runtime_error(error_msg);
}
throw std::runtime_error(error_msg);
}
session_registry.emplace(id, this);
Log() << "\tcreated new session for this thread: " << static_cast<void*>(i->session) << "." << std::endl;
if(i->shall_sync && i->session) // startSync() does not make sense without session.
{
Log() << "\tstartSync()..." << std::endl;
startSync();
}
}else{
Log() << "\tsession for this thread: " << static_cast<void*>(q->second) << "." << std::endl;
}
std::unique_ptr<event_base, decltype(&event_base_free)> eventBase(event_base_new(), &event_base_free);
if (!eventBase)
throw std::runtime_error("Failed to create new base_event.");
std::unique_ptr<evhttp, decltype(&evhttp_free)> evHttp(evhttp_new(eventBase.get()), &evhttp_free);
if (!evHttp)
throw std::runtime_error("Failed to create new evhttp.");
evhttp_set_cb(evHttp.get(), ApiRequestUrl.c_str() , ev_server::OnApiRequest , this);
evhttp_set_cb(evHttp.get(), "/pep_functions.js" , ev_server::OnGetFunctions , this);
evhttp_set_gencb(evHttp.get(), ev_server::OnOtherRequest, nullptr);
if (i->sock == -1) // no port bound, yet
{
throw std::runtime_error("You have to call prepare_run() before run()!");
}
else
{
Log() << "\tnow I call evhttp_accept_socket()..." << std::endl;
if (evhttp_accept_socket(evHttp.get(), i->sock) == -1)
throw std::runtime_error("Failed to accept() on server socket for new instance.");
}
unsigned numnum = 1000000;
while(i->running)
session_registry.emplace(id, this);
L << Logger::Info << "\tcreated new session for this thread: " << static_cast<void*>(i->session) << ".";
if(i->shall_sync && i->session) // startSync() does not make sense without session.
{
// once we have libevent 2.1:
//event_base_loop(eventBase.get(), EVLOOP_NO_EXIT_ON_EMPTY);
// for libevent 2.0:
event_base_loop(eventBase.get(), EVLOOP_NONBLOCK);
std::this_thread::sleep_for(std::chrono::milliseconds(333));
Log() << "\r" << ++numnum << ". " << std::flush;
L << Logger::Info << "\tstartSync()...";
startSync();
}
}else{
L << Logger::Info << "\tsession for this thread: " << static_cast<void*>(q->second) << ".";
}
catch (const std::exception& e)
std::unique_ptr<event_base, decltype(&event_base_free)> eventBase(event_base_new(), &event_base_free);
if (!eventBase)
throw std::runtime_error("Failed to create new base_event.");
std::unique_ptr<evhttp, decltype(&evhttp_free)> evHttp(evhttp_new(eventBase.get()), &evhttp_free);
if (!evHttp)
throw std::runtime_error("Failed to create new evhttp.");
evhttp_set_cb(evHttp.get(), ApiRequestUrl.c_str() , ev_server::OnApiRequest , this);
evhttp_set_cb(evHttp.get(), "/pep_functions.js" , ev_server::OnGetFunctions , this);
evhttp_set_gencb(evHttp.get(), ev_server::OnOtherRequest, nullptr);
if (i->sock == -1) // no port bound, yet
{
Log() << " +++ std::exception in ThreadFunc: " << e.what() << std::endl;
initExcept = std::current_exception();
throw std::runtime_error("You have to call prepare_run() before run()!");
}
catch (...)
else
{
Log() << " +++ UNKNOWN EXCEPTION in ThreadFunc +++ " << std::endl;
initExcept = std::current_exception();
L << Logger::Info << "\tnow I call evhttp_accept_socket()...";
if (evhttp_accept_socket(evHttp.get(), i->sock) == -1)
throw std::runtime_error("Failed to accept() on server socket for new instance.");
}
Log() << " +++ Thread exit? isRun=" << i->running << ", id=" << std::this_thread::get_id() << ". initExcept is " << (initExcept?"":"not ") << "set. +++" << std::endl;
//unsigned numnum = 1000000;
while(i->running)
{
// once we have libevent 2.1:
//event_base_loop(eventBase.get(), EVLOOP_NO_EXIT_ON_EMPTY);
// for libevent 2.0:
event_base_loop(eventBase.get(), EVLOOP_NONBLOCK);
std::this_thread::sleep_for(std::chrono::milliseconds(333));
//Log() << "\r" << ++numnum << ". ";
}
}
catch (const std::exception& e)
{
L << Logger::Error << " +++ std::exception in ThreadFunc: " << e.what();
initExcept = std::current_exception();
}
catch (...)
{
L << Logger::Crit << " +++ UNKNOWN EXCEPTION in ThreadFunc +++ ";
initExcept = std::current_exception();
}
L << Logger::Info << " +++ Thread exit? isRun=" << i->running << ", id=" << std::this_thread::get_id() << ". initExcept is " << (initExcept?"":"not ") << "set. +++";
}
@ -673,13 +670,15 @@ void JsonAdapter::run()
try
{
check_guard();
Log() << "JS::run(): This is " << (void*)this << ", thread id " << std::this_thread::get_id() << "." << std::endl;
Log() << to_string( session_registry) << std::flush;
Logger L("JA:run");
L << Logger::Info << "This is " << (void*)this << ", thread id " << std::this_thread::get_id() << ".";
L << Logger::Debug << to_string( session_registry);
i->running = true;
for(int t=0; t<SrvThreadCount; ++t)
{
Log() << "Start Thread #" << t << "..." << std::endl;
L << Logger::Info << "Start Thread #" << t << "...";
ThreadPtr thread(new std::thread(staticThreadFunc, this), ThreadDeleter);
std::this_thread::sleep_for(std::chrono::milliseconds(500));
if (initExcept)
@ -690,15 +689,15 @@ try
}
i->threads.push_back(std::move(thread));
}
Log() << "All " << SrvThreadCount << " thread(s) started:" << std::endl;
L << Logger::Debug << "All " << SrvThreadCount << " thread(s) started:";
for(const auto& t:i->threads)
{
Log() << "\tthread_id()=" << t->get_id() << "." << std::endl;
L << Logger::Debug << "\tthread_id()=" << t->get_id() << ".";
}
}
catch (std::exception const &e)
{
Log() << "Exception caught in JsonAdapter::run(): \"" << e.what() << "\"" << std::endl;
Log(Logger::Error) << "Exception in JsonAdapter::run(): \"" << e.what() << "\"";
throw;
}
@ -707,7 +706,7 @@ void JsonAdapter::shutdown(timeval* t)
{
exit(0); // HACK for JSON-41
check_guard();
Log() << "JS::shutdown() was called." << std::endl;
Log() << "JS::shutdown() was called.";
i->running = false;
/**** FIXME: proper shutdown!
@ -718,10 +717,10 @@ void JsonAdapter::shutdown(timeval* t)
}
****/
Log() << "JS::shutdown(): event_base loop is finished.\n";
Log() << "\t there are " << i->threads.size() << " threads remaining in the threadpool." << std::endl;
Log() << "\t there are " << i->threads.size() << " threads remaining in the threadpool.";
for(const auto& t : i->threads)
{
Log() << "\t\tjoin() on id=" << t->get_id() << "...." << std::endl;
Log() << "\t\tjoin() on id=" << t->get_id() << "....";
t->join();
}
i->threads.clear();
@ -734,7 +733,7 @@ bool JsonAdapter::verify_security_token(const std::string& s) const
check_guard();
if(s!=i->token)
{
Log() << "sec_token=\"" << i->token << "\" (len=" << i->token.size() << ") is unequal to \"" << s << "\" (len=" << s.size() << ")!" << std::endl;
Log(Logger::Notice) << "sec_token=\"" << i->token << "\" (len=" << i->token.size() << ") is unequal to \"" << s << "\" (len=" << s.size() << ")!";
}
return s == i->token;
}
@ -782,10 +781,10 @@ void JsonAdapter::unregisterEventListener(const std::string& address, unsigned p
}
std::ostream& JsonAdapter::Log() const
Logger::Stream JsonAdapter::Log(Logger::Severity sev) const
{
check_guard();
return i->Log;
return std::move(i->Log << sev);
}


+ 3
- 3
server/json-adapter.hh View File

@ -5,6 +5,7 @@
#include <pEp/sync.h>
#include "registry.hh"
#include "context.hh"
#include "logger.hh"
#include "server_version.hh"
@ -12,7 +13,7 @@ class JsonAdapter : public Context
{
public:
// creates an instance of the JSON adapter. It tries to bind the first available port in the given range
JsonAdapter(std::ostream* logfile);
JsonAdapter();
// calls shutdown() on the instance if it is still running().
virtual ~JsonAdapter();
@ -81,8 +82,7 @@ public:
static pEp_identity* retrieveNextIdentity(void* obj);
static void* keyserverLookupThreadRoutine(void* arg);
// returns the associated log stream (either std::cerr or nulllogger)
std::ostream& Log() const;
Logger::Stream Log(Logger::Severity s = Logger::Severity::Debug) const;
// will throw logic_error if guard variables contains illegal values, which means: *this is not a valid JsonAdapter object!
void check_guard() const;


+ 18
- 5
server/json_rpc.cc View File

@ -3,6 +3,16 @@
#include "json_spirit/json_spirit_writer.h"
#include "json-adapter.hh"
#include "security-token.hh"
#include "logger.hh"
Logger& Log()
{
static Logger L("jrpc");
return L;
}
// Server side:
@ -12,12 +22,16 @@
ret.emplace_back( "jsonrpc", "2.0" );
ret.emplace_back( "id" , id );
ret.emplace_back( "result" , result );
DEBUG_OUT(Log(), "make_result(): result: " + js::write(result) );
return ret;
}
js::Object make_error(JSON_RPC error_code, const std::string& error_message, const js::Value& data, int id)
{
Log().error("make_error(): \"" + error_message + "\" data: " + js::write(data) );
js::Object err_obj;
err_obj.emplace_back( "code", int(error_code) );
err_obj.emplace_back( "message", error_message );
@ -64,6 +78,7 @@ using json_spirit::find_value;
js::Object call(const FunctionMap& fm, const js::Object& request, Context* context)
{
Logger L("jrpc:call");
int request_id = -1;
try
{
@ -113,13 +128,11 @@ js::Object call(const FunctionMap& fm, const js::Object& request, Context* conte
const js::Array p = ( params.type()==js::array_type ? params.get_array() : js::Array{} );
// std::cerr << "=== Now I do the call!\n"
// "\tmethod_name=\"" << method_name << "\","
// "\tparams=" << js::write(params) << ". ===\n";
DEBUG_OUT(L, "method_name=\"" + method_name + "\"\n"
"params=" + js::write(params) );
const js::Value result = fn->second->call(p, context);
// std::cerr << "=== Result of call: " << js::write(result, js::raw_utf8) << ". ===\n";
// std::cerr << "\tSessions: " << getSessions() << "\n";
DEBUG_OUT(L, "result=" + js::write(result, js::raw_utf8) );
return make_result(result, request_id);
}


+ 550
- 0
server/logger.cc View File

@ -0,0 +1,550 @@
#include "logger.hh"
#include "logger_config.hh"
#include <algorithm>
#include <cassert>
#include <cstdarg>
#include <ctime>
#include <cstdlib>
#include <mutex>
#include <thread>
#include <sstream>
#include <vector>
#include <sys/time.h>
#ifdef LOGGER_ENABLE_SYSLOG
extern "C" {
#include <syslog.h>
}
#endif // LOGGER_ENABLE_SYSLOG
using Lock = std::lock_guard<std::recursive_mutex>;
namespace LoggerS // namespace containing all data for the Logger singleton. HACK!
{
std::FILE* logfile = 0;
std::recursive_mutex mut;
Logger::Severity loglevel = Logger::DebugInternal;
Logger::Target target = Logger::Target(-1);
std::string filename;
std::string ident;
bool initialized = false;
// config variables
bool omit_timestamp = false;
unsigned max_message_length = LOGGER_MAX_LOG_MESSAGE_LENGTH;
unsigned max_line_length = LOGGER_MAX_LINE_LENGTH;
void openfile();
void opensyslog();
void start(const std::string& program_name, const std::string& filename = std::string())
{
ident = program_name;
// TODO: use $TEMP, $TMP etc.
opensyslog();
if(target & Logger::Target::File)
{
LoggerS::filename = filename.empty() ? "/tmp/log-" + program_name + ".log" : filename;
openfile();
}
initialized = true;
}
void log(Logger::Severity s, const std::string& msg);
#ifdef LOGGER_USE_ASCII_TAGS
const char* Levelname[] =
{
"<<EMERGENCY>>",
"<<ALERT>>",
"<<CRITICAL>>",
"<ERROR>",
"<Warning>",
"<Notice>",
"<info>",
"<>", // Debug
"! " // DebugInternal
};
const char* const MultilineBracketFirst = "/";
const char* const MultilineBracketMid = "|";
const char* const MultilineBracketLast = "\\";
const char* const MultilineWrap = "|>";
const char* const MultilineWrapContinue = "<|";
#else
const char* Levelname[] =
{
"»»EMERGENCY",
"»»ALERT",
"»»CRITICAL",
"»ERROR",
"»Warning",
"»Notice",
"»Info",
"°", // Debug
"·" // DebugInternal
};
const char* const MultilineBracketFirst = "";
const char* const MultilineBracketMid = "";
const char* const MultilineBracketLast = "";
const char* const MultilineWrap = "";
const char* const MultilineWrapContinue = "";
#endif
struct LogfileCloser
{
~LogfileCloser()
{
if(LoggerS::logfile)
{
LoggerS::log(Logger::Debug, "Shutdown.");
fputs("---<shutdown>---\n", LoggerS::logfile);
fclose(LoggerS::logfile);
LoggerS::logfile = nullptr;
}
}
};
// guess what.
static LogfileCloser logfile_closer;
} // end of namespace LoggerS
namespace {
void logSingleLine(FILE* logfile, const std::string& timestamp, const std::string& logline)
{
std::fputs(timestamp.c_str(), logfile);
std::fputs(logline.c_str(), logfile);
std::fputc('\n', logfile);
}
void logMultiLine(FILE* logfile, const std::string& prefix, const std::vector<std::string>& lines)
{
assert( lines.size()>1 );
// be robust, anyway. So:
if(lines.empty())
{
return;
}
if(lines.size()==1)
{
logSingleLine(logfile, prefix, lines.at(0));
return;
}
const size_t last_line = lines.size()-1;
std::fputs(prefix.c_str(), logfile);
std::fputs(LoggerS::MultilineBracketFirst, logfile);
std::fputs(lines[0].c_str(), logfile);
std::fputc('\n', logfile);
for(size_t q=1; q<last_line; ++q)
{
std::fputs(prefix.c_str(), logfile);
std::fputs(LoggerS::MultilineBracketMid, logfile);
std::fputs(lines[q].c_str(), logfile);
std::fputc('\n', logfile);
}
std::fputs(prefix.c_str(), logfile);
std::fputs(LoggerS::MultilineBracketLast, logfile);
std::fputs(lines[last_line].c_str(), logfile);
std::fputc('\n', logfile);
}
// wrap an overlong line into several lines, incl. adding wrapping markers
void wrapLongLine(const std::string& oneline, std::vector<std::string>& lines)
{
std::string::const_iterator begin = oneline.begin();
std::string::const_iterator end = oneline.begin();
std::size_t ofs = 0;
bool cont_line = false;
do{
begin=end;
const unsigned delta = std::min( (size_t)Logger::getMaxLineLength(), oneline.size() - ofs );
end += delta;
ofs += delta;
if(end != oneline.end())
{
while( (uint8_t(*end) >= 0x80) && (end>begin) )
{
// rewind
--end;
--ofs;
}
}
lines.push_back(
(cont_line ? LoggerS::MultilineWrapContinue : "") +
std::string(begin, end) +
(end!=oneline.end() ? LoggerS::MultilineWrap : "")
);
cont_line = true;
}while( end != oneline.end() );
}
} // end of anonymous namespace
void Logger::start(const std::string& program_name, const std::string& filename)
{
if(LoggerS::initialized==false)
{
LoggerS::start(program_name, filename);
Logger& l = ::getLogger();
l.debug("Logger has been started.");
}
}
std::string Logger::gmtime(time_t t)
{
char buf[24]; // long enough to hold YYYYY-MM-DD.hh:mm:ss" (y10k-safe!)
std::tm T;
gmtime_r(&t, &T); // TODO: GNU extension also in std:: ?
std::snprintf(buf, sizeof(buf)-1, "%04d-%02d-%02d.%02d:%02d:%02d",
T.tm_year+1900, T.tm_mon+1, T.tm_mday, T.tm_hour, T.tm_min, T.tm_sec );
return buf;
}
std::string Logger::gmtime(timeval t)
{
char buf[31]; // long enough to hold YYYYY-MM-DD.hh:mm:ss.uuuuuu
std::tm T;
gmtime_r(&t.tv_sec, &T); // TODO: GNU extension also in std:: ?
std::snprintf(buf, sizeof(buf)-1, "%04d-%02d-%02d.%02d:%02d:%02d.%06lu",
T.tm_year+1900, T.tm_mon+1, T.tm_mday, T.tm_hour, T.tm_min, T.tm_sec, (long unsigned)t.tv_usec);
return buf;
}
Logger::Severity Logger::getLevel() const
{
return loglevel;
}
void Logger::setLevel(Severity s)
{
// TODO: use C++17 std::clamp()
loglevel = s<Emergency ? Emergency : (s>DebugInternal ? DebugInternal : s);
}
const std::string& Logger::getPrefix() const
{
return prefix;
}
Logger::Target Logger::getDefaultTarget()
{
return LoggerS::target;
}
void Logger::setDefaultTarget(Target t)
{
LoggerS::target = t;
}
Logger::Severity Logger::getDefaultLevel()
{
return LoggerS::loglevel;
}
void Logger::setDefaultLevel(Severity s)
{
LoggerS::loglevel = s;
}
// set maximum length of a log message. Longer messages will be clipped!
void Logger::setMaxMessageLength(unsigned length)
{
LoggerS::max_message_length = length;
}
// set maximum length of a log _line_. Longer messages will be wrapped into several lines.
void Logger::setMaxLineLength(unsigned length)
{
LoggerS::max_line_length = std::min(length, 64u*1024u);
}
unsigned Logger::getMaxMessageLength()
{
return LoggerS::max_message_length;
}
unsigned Logger::getMaxLineLength()
{
return LoggerS::max_line_length;
}
Logger::Logger(const std::string& my_prefix, Severity my_loglevel)
: prefix(my_prefix + ":")
{
setLevel(my_loglevel == Severity::Inherited ? getDefaultLevel() : my_loglevel);
start(my_prefix); // if not yet initialized.
}
Logger::Logger(Logger& parent, const std::string& my_prefix, Severity my_loglevel)
: Logger( parent.getPrefix() + my_prefix + ':', my_loglevel == Severity::Inherited ? parent.getLevel() : my_loglevel )
{
}
void Logger::log(Severity s, const char* format, ...)
{
if(s<=loglevel && s<=LoggerS::loglevel)
{
va_list va;
va_start(va, format);
char buf[ LoggerS::max_line_length + 1];
std::vsnprintf(buf, LoggerS::max_line_length, format, va);
va_end(va);
LoggerS::log(s, prefix + buf);
}
}
void LogP(Logger::Severity s, Logger::Severity my_loglevel, const std::string& prefix, const char* format, va_list va)
{
if(s<=my_loglevel && s<=LoggerS::loglevel)
{
char buf[ LoggerS::max_line_length + 1];
std::vsnprintf(buf, LoggerS::max_line_length, format, va);
LoggerS::log(s, prefix + buf );
}
}
void Logger::log(Severity s, const std::string& logline)
{
if(s<=loglevel && s<=LoggerS::loglevel)
{
LoggerS::log(s, prefix + logline);
}
}
#define LOGGER_LAZY( fnname, severity ) \
void Logger::fnname ( const std::string& line) { \
log( Logger:: severity, line ); \
} \
void Logger:: fnname (const char* format, ...) { \
va_list va; va_start(va, format); \
LogP( severity, loglevel, prefix, format, va ) ;\
va_end(va); \
} \
LOGGER_LAZY( emergency, Emergency)
LOGGER_LAZY( alert , Alert )
LOGGER_LAZY( critical , Crit )
LOGGER_LAZY( error , Error )
LOGGER_LAZY( warning , Warn )
LOGGER_LAZY( notice , Notice )
LOGGER_LAZY( info , Info )
#ifdef DEBUG_ENABLED
LOGGER_LAZY( debug , Debug )
LOGGER_LAZY( debugInternal , DebugInternal )
#else
// intentionally left blank.
// the methods are already defined as do-nothing inline functions in Logger.hh
#endif
#undef LOGGER_LAZY
Logger& getLogger()
{
Lock LCK(LoggerS::mut);
static Logger log("#", Logger::Debug);
return log;
}
// ---------- LoggerS ----------
void LoggerS::openfile()
{
logfile = std::fopen(filename.c_str(), "a");
if(logfile==0)
{
perror("Could not open log file! ");
}
}
void LoggerS::opensyslog()
{
#ifdef LOGGER_ENABLE_SYSLOG
openlog(ident.c_str(), 0, LOG_DAEMON);
#endif
}
static const std::string thread_alphabet = "0123456789_ABCDEFGHIJKLMNOPQRSTUVWXYZ";
static const unsigned thread_alph_len = thread_alphabet.size(); // shall be a prime number
static std::hash<std::thread::id> hash_tid;
// create a three-digit base37 string of the current thread ID for easy grepping and filtering:
std::string thread_id()
{
char buf[8] = { ' ', '\302', '\266', '?', '?', '?', ' ' };
unsigned long long id = hash_tid(std::this_thread::get_id());
buf[3] = thread_alphabet.at( id % thread_alph_len); id /= thread_alph_len;
buf[4] = thread_alphabet.at( id % thread_alph_len); id /= thread_alph_len;
buf[5] = thread_alphabet.at( id % thread_alph_len); id /= thread_alph_len;
return std::string(buf, buf+7);
}
void LoggerS::log(Logger::Severity s, const std::string& logline)
{
Lock LCK(mut);
if(s<Logger::Emergency ) s = Logger::Emergency;
if(s>Logger::DebugInternal ) s = Logger::DebugInternal;
// clipt and wrap:
bool multiline = false;
std::vector<std::string> lines;
std::stringstream ss(logline);
std::string oneline;
while(std::getline(ss, oneline))
{
if(oneline.size() > max_line_length)
{
wrapLongLine(oneline, lines);
}else{
lines.push_back( std::move(oneline) );
}
}
if(lines.size() > 1)
multiline = true;
// create header with timestamp
if(target & (Logger::File | Logger::Console))
{
std::string timestamp;
timestamp.reserve(45);
if(omit_timestamp == false)
{
timestamp = Logger::gmtime(time(0));
}
timestamp.append( thread_id() );
timestamp.append(Levelname[s]);
timestamp.append(" :");
if(target & Logger::Console)
{
if(multiline)
{
logMultiLine(stderr, timestamp, lines);
}else{
logSingleLine(stderr, timestamp, logline);
}
}
if(target & Logger::File)
{
if(multiline)
{
logMultiLine(logfile, timestamp, lines);
}else{
logSingleLine(logfile, timestamp, logline);
}
std::fflush(logfile);
}
}
#ifdef LOGGER_ENABLE_SYSLOG
if(target & Logger::Syslog)
{
syslog(s, "%s", logline.c_str());
}
#endif
}
Logger::Stream::Stream(Logger* parent, Severity _sev)
: L(parent), sev(_sev)
{}
Logger::Stream::~Stream()
{
if(L)
{
L->log(sev, s);
}
}
template<class T>
const Logger::Stream& operator<<(const Logger::Stream& stream, const T& t)
{
std::stringstream ss;
ss << t;
stream.s.append( ss.str());
return stream;
}
const Logger::Stream& operator<<(const Logger::Stream& stream, const char*const t)
{
stream.s.append( t );
return stream;
}
template<>
const Logger::Stream& operator<<(const Logger::Stream& stream, const bool& b)
{
stream.s.append( b ? "true" : "false");
return stream;
}
template const Logger::Stream& operator<<(const Logger::Stream&, const int&);
template const Logger::Stream& operator<<(const Logger::Stream&, const long&);
template const Logger::Stream& operator<<(const Logger::Stream&, const unsigned&);
template const Logger::Stream& operator<<(const Logger::Stream&, const unsigned long&);
template const Logger::Stream& operator<<(const Logger::Stream&, const std::string&);
template const Logger::Stream& operator<<(const Logger::Stream&, const double&);
template const Logger::Stream& operator<<(const Logger::Stream&, const void*const&);
template const Logger::Stream& operator<<(const Logger::Stream&, void*const&);
template const Logger::Stream& operator<<(const Logger::Stream&, const std::thread::id&);
Logger::Stream operator<<(Logger& parent, Logger::Severity sev)
{
return Logger::Stream(&parent, sev);
}
// End of file

+ 171
- 0
server/logger.hh View File

@ -0,0 +1,171 @@
#ifndef LOGGER_HH
#define LOGGER_HH
#include <cstdio>
#include <string>
#include <cerrno>
#include <sys/time.h>
#ifdef DEBUG_ENABLED
#define DEBUG_OUT( LL , ... ) LL.debug( __VA_ARGS__ )
#define DEBUGI_OUT( LL , ... ) LL.debugInternal( __VA_ARGS__ )
#else
#define DEBUG_OUT(...) do{}while(0)
#define DEBUGI_OUT(...) do{}while(0)
#endif
#ifdef __GNUC__
#define PRINTF __attribute__((format (printf, 2,3) ))
#define PRINTF3 __attribute__((format (printf, 3,4) ))
#else
#define PRINTF
#define PRINTF3
#endif
class Logger;
// get global Logger instance
Logger& getLogger();
class Logger
{
public:
enum Severity
{
Emergency,// The message says the system is unusable.
Alert, // Action on the message must be taken immediately.
Crit, // The message states a critical condition.
Error, // The message describes an error.
Warn, // The message is a warning.
Notice, // The message describes a normal but important event.
Info, // The message is purely informational.
Debug, // The message is only for interface debugging purposes.
DebugInternal, // The message is for internal debugging purposes.
Inherited=-1 // Use the same loglevel as the parent Logger (if any)
};
enum Target
{
None = 0,
Console=1, Syslog=2, File=4 // may be ORed together
};
// shall be called before first log message.
static void start(const std::string& program_name, const std::string& filename = "");
// returns a string in YYYY-MM-DD.hh:mm:ss format of the given time_t t
static std::string gmtime(time_t t);
// returns a string in YYYY-MM-DD.hh:mm:ss.uuuuuu format (u=microseconds) of the given timval
static std::string gmtime(timeval t);
void emergency(const char* format, ...) PRINTF;
void emergency(const std::string& line);
void alert(const char* format, ...) PRINTF;
void alert(const std::string& line);
void critical(const char* format, ...) PRINTF;
void critical(const std::string& line);
void error(const char* format, ...) PRINTF;
void error(const std::string& line);
void warning(const char* format, ...) PRINTF;
void warning(const std::string& line);
void notice(const char* format, ...) PRINTF;
void notice(const std::string& line);
void info(const char* format, ...) PRINTF;
void info(const std::string& line);
#ifdef DEBUG_ENABLED
void debug(const char* format, ...) PRINTF;
void debug(const std::string& line);
void debugInternal(const char* format, ...) PRINTF;
void debugInternal(const std::string& line);
#else
void debug(const char*, ...) PRINTF { /* do nothing */ }
void debug(const std::string&) { /* do nothing */ }
void debugInternal(const char*, ...) PRINTF { /* do nothing */ }
void debugInternal(const std::string&) { /* do nothing */ }
#endif
void log(Severity s, const char* format, ...) PRINTF3; // C style
void log(Severity s, const std::string& line); // C++ style :-)
// log messages with a lower severity are ignored
void setLevel(Severity s);
Severity getLevel() const;
static void setDefaultLevel(Severity s);
static Severity getDefaultLevel();
static void setDefaultTarget(Target t);
static Target getDefaultTarget();
// set maximum length of a log message. Longer messages will be clipped!
static void setMaxMessageLength(unsigned length);
// set maximum length of a log _line_. Longer messages will be wrapped into several lines.
static void setMaxLineLength(unsigned length);
static unsigned getMaxMessageLength();
static unsigned getMaxLineLength();
const std::string& getPrefix() const;
// if no explicit severity is given it is taken from default's severity
explicit Logger(const std::string& my_prefix, Severity my_severity = Severity::Inherited);
explicit Logger(Logger& parent, const std::string& my_prefix, Severity my_severity = Severity::Inherited);
// non-copyable:
Logger(const Logger&) = delete;
void operator=(const Logger&) = delete;
class Stream
{
public:
Stream(Logger* _L, Logger::Severity _sev);
~Stream();
mutable std::string s;
private:
Logger* L;
const Logger::Severity sev;
};
;
private:
friend Logger& getLogger();
const std::string prefix;
Severity loglevel;
};
// creates a Stream, who collect data in pieces and logs it to the "parent" logger in its destructor with the given severity
Logger::Stream operator<<(Logger& parent, Logger::Severity sev);
template<class T>
const Logger::Stream& operator<<(const Logger::Stream&, const T&);
const Logger::Stream& operator<<(const Logger::Stream&, const char*const);
inline
const Logger::Stream& operator<<(const Logger::Stream& stream, char*const s)
{
return stream << const_cast<const char*>(s);
}
// clean up defines which may collide with other headers...
#undef PRINTF
#undef PRINTF3
#endif // LOGGER_HH

+ 17
- 0
server/logger_config.hh View File

@ -0,0 +1,17 @@
#ifndef LOGGER_CONFIG_HH
#define LOGGER_CONFIG_HH
// maximum length of a log message. longer log messages will be clipped
#define LOGGER_MAX_LOG_MESSAGE_LENGTH (8192)
// maximum length of a log line. longer lines will be wrapped/folded
#define LOGGER_MAX_LINE_LENGTH (1000)
// enable logging to syslog
#define LOGGER_ENABLE_SYSLOG (1)
// use ASCII-only characters to tag log lines
// #define LOGGER_USE_ASCII_TAGS (1)
#endif // LOGGER_CONFIG_HH

+ 19
- 9
server/main.cc View File

@ -3,6 +3,7 @@
#include "prefix-config.hh"
#include "json-adapter.hh"
#include "daemonize.hh"
#include "logger.hh"
#include "nulllogger.hh"
#include <thread>
@ -61,7 +62,7 @@ try
("add-sharks", po::bool_switch(&add_sharks), "Add sharks to the JSON Adapter.")
#ifdef _WIN32
((STATUS_HANDLE), po::value<uintptr_t>(&status_handle)->default_value(0), "Status file handle, for internal use.")
#endif
#endif
;
po::variables_map vm;
@ -88,15 +89,18 @@ try
if(logfile.empty())
{
my_logfile = &nulllogger;
Logger::setDefaultTarget(Logger::Target::None);
}else if(logfile == "stderr")
{
my_logfile = &std::cerr;
Logger::setDefaultTarget(Logger::Target::Console);
}else{
real_logfile = std::make_shared<std::ofstream>( logfile, std::ios::app );
my_logfile = real_logfile.get();
Logger::setDefaultTarget(Logger::Target::File);
}
Logger::start("JsonAdapter", logfile);
Logger L("main");
L.info("main logger started");
if(add_sharks)
{
ev_server::addSharks();
@ -104,8 +108,8 @@ try
if( debug_mode == false )
daemonize (!debug_mode, (const uintptr_t) status_handle);
JsonAdapter ja( my_logfile );
JsonAdapter ja;
ja.do_sync( do_sync)
.ignore_session_errors( ignore_missing_session)
;
@ -136,13 +140,19 @@ try
}while(ja.running());
}
ja.shutdown(nullptr);
ja.Log() << "Good bye. :-)" << std::endl;
ja.Log() << "Good bye. :-)";
JsonAdapter::global_shutdown();
}
catch(std::exception const& e)
{
std::cerr << "Inner exception caught in main(): \"" << e.what() << "\"" << std::endl;
daemonize_commit(1);
exit(8);
}
catch (...)
{
daemonize_commit(1);
exit(1);
exit(9);
}
}
catch(std::exception const& e)


+ 69
- 0
server/unittest_logger.cc View File

@ -0,0 +1,69 @@
#include <gtest/gtest.h>
#include "logger.hh"
namespace
{
std::string longstring(unsigned length)
{
std::string s;
s.reserve(length);
for(unsigned u=0; u