JSON-98: follow default JSON-98
authorClaudio Luck <claudio.luck@pep.foundation>
Mon, 13 Aug 2018 13:41:05 +0200
branchJSON-98
changeset 575b5f2cd8fdf5f
parent 565 4ff9d7fb0811
parent 573 18110f36d718
JSON-98: follow default
server/ev_server.cc
server/json_rpc.cc
     1.1 --- a/server/Makefile	Sun Jul 08 19:22:40 2018 +0200
     1.2 +++ b/server/Makefile	Mon Aug 13 13:41:05 2018 +0200
     1.3 @@ -86,7 +86,9 @@
     1.4  $(TARGET_TEST): servertest.o libjson-adapter.a
     1.5  	$(CXX) $(CPPFLAGS) $^ $(LDFLAGS) $(LDLIBS) -o $@
     1.6  
     1.7 -$(TARGET_GTEST): unittest_json.o unittest_nfc.o unittest_decompose.o unittest_rpc.o gtest-all.o gtest_main.o libjson-adapter.a
     1.8 +$(TARGET_GTEST): unittest_json.o unittest_nfc.o unittest_decompose.o unittest_rpc.o \
     1.9 +    unittest_logger.o \
    1.10 +    gtest-all.o gtest_main.o libjson-adapter.a
    1.11  	$(CXX) $(CPPFLAGS) $^ $(LDFLAGS) $(LDLIBS) -o $@
    1.12  
    1.13  libjson-adapter.a: $(ALL_OBJECTS)
     2.1 --- a/server/Makefile.conf	Sun Jul 08 19:22:40 2018 +0200
     2.2 +++ b/server/Makefile.conf	Mon Aug 13 13:41:05 2018 +0200
     2.3 @@ -70,7 +70,7 @@
     2.4          CXXFLAGS+= -w
     2.5      endif
     2.6      ifdef DEBUG
     2.7 -        CXXFLAGS+= -O0 -g -ggdb
     2.8 +        CXXFLAGS+= -O0 -g -ggdb -DDEBUG_ENABLED
     2.9      else
    2.10          CXXFLAGS+= -O3 -DNDEBUG
    2.11      endif
    2.12 @@ -82,7 +82,7 @@
    2.13          CXXFLAGS+= -w
    2.14      endif
    2.15      ifdef DEBUG
    2.16 -        CXXFLAGS+= -O0 -g
    2.17 +        CXXFLAGS+= -O0 -g -DDEBUG_ENABLED
    2.18      else
    2.19          CXXFLAGS+= -O3 -DNDEBUG
    2.20      endif
     3.1 --- a/server/ev_server.cc	Sun Jul 08 19:22:40 2018 +0200
     3.2 +++ b/server/ev_server.cc	Mon Aug 13 13:41:05 2018 +0200
     3.3 @@ -9,6 +9,7 @@
     3.4  #include "json_rpc.hh"
     3.5  #include "pep-utils.hh"
     3.6  #include "gpg_environment.hh"
     3.7 +#include "logger.hh"
     3.8  #include "server_version.hh"
     3.9  
    3.10  #include <pEp/message_api.h>
    3.11 @@ -215,8 +216,9 @@
    3.12  		evhttp_send_reply(req, 500, "evbuffer_add() failed.", outBuf);
    3.13  	}
    3.14  	
    3.15 -	Log() << "\n=== sendReplyString(): ret=" << ret << ", contentType=" << (contentType ? "«" + std::string(contentType)+ "»" : "NULL") 
    3.16 -		<< ", output=«" << outputText << "»." << std::endl;
    3.17 +	Log() << Logger::Debug << "sendReplyString(): ret=" << ret
    3.18 +		<< ", contentType=" << (contentType ? "«" + std::string(contentType)+ "»" : "NULL")
    3.19 +		<< ", output=«" << outputText << "».";
    3.20  }
    3.21  
    3.22  
    3.23 @@ -254,7 +256,7 @@
    3.24  	const evhttp_uri* uri = evhttp_request_get_evhttp_uri(req);
    3.25  	const char* path = evhttp_uri_get_path(uri);
    3.26  	const char* uri_string = evhttp_request_get_uri(req);
    3.27 -	Log() << "** Request: [" << uri_string << "] " << (path? " Path: [" + std::string(path) + "]" : "null path") << "\n";
    3.28 +	Log() << Logger::Debug << "** Request: [" << uri_string << "] " << (path? " Path: [" + std::string(path) + "]" : "null path") << "\n";
    3.29  	
    3.30  	try{
    3.31  		if(path)
    3.32 @@ -262,7 +264,7 @@
    3.33  			const auto q = files.find(path);
    3.34  			if(q != files.end()) // found in "files" map
    3.35  			{
    3.36 -			Log() << "\t found file \"" << q->second.fileName << "\", type=" << q->second.mimeType << ".\n";
    3.37 +			Log() << Logger::Debug << "\t found file \"" << q->second.fileName.string() << "\", type=" << q->second.mimeType << ".\n";
    3.38  				sendFile( req, q->second.mimeType, q->second.fileName);
    3.39  				return;
    3.40  			}
    3.41 @@ -275,8 +277,9 @@
    3.42  	catch(const std::runtime_error& e)
    3.43  	{
    3.44  		const std::string error_msg = "Internal error caused by URI \"" + std::string(uri_string) + "\"";
    3.45 -		// TODO: log e.what() to log file, but don't send it in HTTP error message
    3.46 -		//       because it might contain sensitive information, e.g. local file paths etc.!
    3.47 +		// Log e.what() to log file, but DON'T send it in HTTP error message
    3.48 +		// because it might contain sensitive information, e.g. local file paths etc.!
    3.49 +		Log() << Logger::Error << "OnOtherRequest: " << error_msg << ".  what:" << e.what();
    3.50  		evhttp_send_error(req, HTTP_INTERNAL, error_msg.c_str() );
    3.51  	}
    3.52  };
    3.53 @@ -325,6 +328,7 @@
    3.54  
    3.55  void ev_server::OnApiRequest(evhttp_request* req, void* obj)
    3.56  {
    3.57 +	Logger L( Log(), "OnApiReq");
    3.58  	evbuffer* inbuf = evhttp_request_get_input_buffer(req);
    3.59  	const size_t length = evbuffer_get_length(inbuf);
    3.60  
    3.61 @@ -342,24 +346,26 @@
    3.62  	const std::string data_string(data.data(), data.data() + nr );
    3.63  	if(nr>0)
    3.64  	{
    3.65 -		ja->Log() << "\tData: «" << data_string  << "»\n";
    3.66 +		L << Logger::Debug << "Data: «" << data_string  << "»";
    3.67  		bool b = js::read( data_string, p);
    3.68  		if(p.type() == js::obj_type)
    3.69  		{
    3.70  			const js::Object& request = p.get_obj();
    3.71  			answer = call( functions, request, ja );
    3.72  		}else{
    3.73 -			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 );
    3.74 +			const std::string error_msg = "evbuffer_copyout does not return a JSON string. b=" + std::to_string(b);
    3.75 +			L << Logger::Error << error_msg;
    3.76 +			answer = make_error( JSON_RPC::PARSE_ERROR, error_msg, js::Value{data_string}, 42 );
    3.77  		}
    3.78  	}else{
    3.79 -		ja->Log() << "\tError: " << nr << ".\n";
    3.80 +		L << Logger::Error << "Error: " << nr << ".\n";
    3.81  		answer = make_error( JSON_RPC::INTERNAL_ERROR, "evbuffer_copyout returns negative value", p, request_id );
    3.82  	}
    3.83  	
    3.84  	}
    3.85  	catch(const std::exception& e)
    3.86  	{
    3.87 -		Log() << "\tException: \"" << e.what() << "\"\n";
    3.88 +		L << Logger::Error << "Exception: \"" << e.what() << "\"";
    3.89  		answer = make_error( JSON_RPC::INTERNAL_ERROR, "Got a std::exception: \"" + std::string(e.what()) + "\"", p, request_id );
    3.90  	}
    3.91  
    3.92 @@ -367,16 +373,10 @@
    3.93  };
    3.94  
    3.95  
    3.96 -std::ostream& ev_server::Log()
    3.97 +Logger& ev_server::Log()
    3.98  {
    3.99 -	*log_file << "evserver: ";
   3.100 -	return *log_file;
   3.101 -}
   3.102 -
   3.103 -
   3.104 -void ev_server::setLogfile(std::ostream* new_logfile)
   3.105 -{
   3.106 -	log_file = new_logfile ? new_logfile : &nulllogger;
   3.107 +	static Logger L("evs");
   3.108 +	return L;
   3.109  }
   3.110  
   3.111  
   3.112 @@ -384,6 +384,3 @@
   3.113  {
   3.114  	add_sharks = true;
   3.115  }
   3.116 -
   3.117 -
   3.118 -std::ostream* ev_server::log_file = &nulllogger;
     4.1 --- a/server/ev_server.hh	Sun Jul 08 19:22:40 2018 +0200
     4.2 +++ b/server/ev_server.hh	Mon Aug 13 13:41:05 2018 +0200
     4.3 @@ -3,12 +3,13 @@
     4.4  #ifndef EV_SERVER_HH
     4.5  #define EV_SERVER_HH
     4.6  
     4.7 -#include "nulllogger.hh"
     4.8  #include <string>
     4.9  #include <boost/filesystem/path.hpp>
    4.10  
    4.11  struct evhttp_request;
    4.12  
    4.13 +class Logger;
    4.14 +
    4.15  class ev_server
    4.16  {
    4.17  public:
    4.18 @@ -34,22 +35,13 @@
    4.19  	// so changing it later might be useless.
    4.20  	static boost::filesystem::path path_to_html;
    4.21  	
    4.22 -	// if new_logfile is NULL, the logfile is reset to nulllogger.
    4.23 -	static
    4.24 -	void setLogfile(std::ostream* new_logfile);
    4.25 -	
    4.26  	// add sharks to the JSON Adapter
    4.27  	static
    4.28  	void addSharks();
    4.29  
    4.30  protected:
    4.31 -	// prints "evserver:" to the log and returns it to allow << chaining
    4.32  	static
    4.33 -	std::ostream& Log();
    4.34 -	
    4.35 -private:
    4.36 -	static
    4.37 -	std::ostream* log_file;
    4.38 +	Logger& Log();
    4.39  };
    4.40  
    4.41  #endif
     5.1 --- a/server/json-adapter.cc	Sun Jul 08 19:22:40 2018 +0200
     5.2 +++ b/server/json-adapter.cc	Mon Aug 13 13:41:05 2018 +0200
     5.3 @@ -22,6 +22,7 @@
     5.4  #include "security-token.hh"
     5.5  #include "pep-utils.hh"
     5.6  #include "ev_server.hh"
     5.7 +#include "logger.hh"
     5.8  #include "server_version.hh"
     5.9  
    5.10  #include <boost/filesystem.hpp>
    5.11 @@ -113,7 +114,7 @@
    5.12  	std::string token;
    5.13  	std::map<EventListenerKey, EventListenerValue> eventListener;
    5.14  	
    5.15 -	std::ostream& Log;
    5.16 +	Logger      Log;
    5.17  	unsigned    start_port    = 0;
    5.18  	unsigned    end_port      = 0;
    5.19  	unsigned    port          = 0;
    5.20 @@ -132,8 +133,8 @@
    5.21  	ThreadPtr   sync_thread{nullptr, ThreadDeleter};
    5.22  	
    5.23  	
    5.24 -	explicit Internal(std::ostream& logger)
    5.25 -	: Log(logger)
    5.26 +	explicit Internal()
    5.27 +	: Log("JAI")
    5.28  	{}
    5.29  	
    5.30  	Internal(const Internal&) = delete;
    5.31 @@ -336,8 +337,6 @@
    5.32  
    5.33  
    5.34  
    5.35 -
    5.36 -
    5.37  PEP_STATUS JsonAdapter::messageToSend(void* obj, message* msg)
    5.38  {
    5.39  	JsonAdapter* ja = static_cast<JsonAdapter*>(obj);
    5.40 @@ -491,11 +490,10 @@
    5.41  	return (void*) status;
    5.42  }
    5.43  
    5.44 -extern std::ofstream* my_logfile;
    5.45  
    5.46 -JsonAdapter::JsonAdapter(std::ostream* logfile)
    5.47 +JsonAdapter::JsonAdapter()
    5.48  : guard_0(Guard_0)
    5.49 -, i(new Internal( *logfile ))
    5.50 +, i(new Internal{})
    5.51  , guard_1(Guard_1)
    5.52  {
    5.53  	i->eventBase.reset(event_base_new());
    5.54 @@ -511,10 +509,10 @@
    5.55  JsonAdapter::~JsonAdapter()
    5.56  {
    5.57  	check_guard();
    5.58 -	Log() << "~JsonAdapter(): " << session_registry.size() << " sessions registered." << std::endl;
    5.59 +	Log() << "~JsonAdapter(): " << session_registry.size() << " sessions registered.";
    5.60  	stopSync();
    5.61  	this->shutdown(nullptr);
    5.62 -	Log() << "\t After stopSync() and shutdown() there are " << session_registry.size() << " sessions registered." << std::endl;
    5.63 +	Log() << "\t After stopSync() and shutdown() there are " << session_registry.size() << " sessions registered.";
    5.64  	delete i;
    5.65  	i=nullptr;
    5.66  }
    5.67 @@ -543,8 +541,6 @@
    5.68  	i->start_port = start_port;
    5.69  	i->end_port   = end_port;
    5.70  	
    5.71 -	ev_server::setLogfile( &i->Log );
    5.72 -	
    5.73  	if(first_session == nullptr) // okay, we are the 1st:
    5.74  	{
    5.75  	// create a dummy session just to see whether the Engine is functional.
    5.76 @@ -561,111 +557,112 @@
    5.77  	}
    5.78  	}
    5.79  	
    5.80 -				Log() << "ThreadFunc: thread id " << std::this_thread::get_id() << ". \n Registry: " << to_string( session_registry ) << std::flush;
    5.81 -				
    5.82 -				unsigned port_ofs = 0;
    5.83 +	Log() << "ThreadFunc: thread id " << std::this_thread::get_id() << ". \n Registry: " << to_string( session_registry );
    5.84 +	
    5.85 +	unsigned port_ofs = 0;
    5.86  try_next_port:
    5.87 -				auto* boundSock = evhttp_bind_socket_with_handle(i->evHttp.get(), i->address.c_str(), i->start_port + port_ofs);
    5.88 -				if (!boundSock)
    5.89 -				{
    5.90 -					++port_ofs;
    5.91 -					if(i->start_port + port_ofs > i->end_port)
    5.92 -					{
    5.93 -						throw std::runtime_error("Failed to bind server socket: "
    5.94 -							"No free port between " + std::to_string(i->start_port) + " and " + std::to_string(i->end_port)
    5.95 -							);
    5.96 -					}
    5.97 -					goto try_next_port;
    5.98 -				}
    5.99 -				
   5.100 -				if ((i->sock = evhttp_bound_socket_get_fd(boundSock)) == -1)
   5.101 -					throw std::runtime_error("Failed to get server socket for next instance.");
   5.102 -				
   5.103 -				i->port = i->start_port + port_ofs;
   5.104 -				i->token = create_security_token(i->address, i->port, BaseUrl);
   5.105 -				
   5.106 -				Log() << "Bound to port " << i->port << ", sec_token=\"" << i->token << "\"" << std::endl;
   5.107 +	auto* boundSock = evhttp_bind_socket_with_handle(i->evHttp.get(), i->address.c_str(), i->start_port + port_ofs);
   5.108 +	if (!boundSock)
   5.109 +	{
   5.110 +		++port_ofs;
   5.111 +		if(i->start_port + port_ofs > i->end_port)
   5.112 +		{
   5.113 +			throw std::runtime_error("Failed to bind server socket: "
   5.114 +				"No free port between " + std::to_string(i->start_port) + " and " + std::to_string(i->end_port)
   5.115 +				);
   5.116 +		}
   5.117 +		goto try_next_port;
   5.118 +	}
   5.119 +	
   5.120 +	if ((i->sock = evhttp_bound_socket_get_fd(boundSock)) == -1)
   5.121 +		throw std::runtime_error("Failed to get server socket for next instance.");
   5.122 +	
   5.123 +	i->port = i->start_port + port_ofs;
   5.124 +	i->token = create_security_token(i->address, i->port, BaseUrl);
   5.125 +	
   5.126 +	Log() << "Bound to port " << i->port << ", sec_token=\"" << i->token << "\"";
   5.127  }
   5.128  
   5.129  
   5.130  void JsonAdapter::threadFunc()
   5.131  {
   5.132 -		try
   5.133 +	Logger L("JA:tF");
   5.134 +	try
   5.135 +	{
   5.136 +		const auto id = std::this_thread::get_id();
   5.137 +		L << Logger::Info << " +++ Thread starts: isRun=" << i->running << ", id=" << id << ". +++";
   5.138 +		const auto q=session_registry.find(id);
   5.139 +		if(q==session_registry.end())
   5.140  		{
   5.141 -			const auto id = std::this_thread::get_id();
   5.142 -			Log() << " +++ Thread starts: isRun=" << i->running << ", id=" << id << ". +++" << std::endl;
   5.143 -			const auto q=session_registry.find(id);
   5.144 -			if(q==session_registry.end())
   5.145 +			i->session = nullptr;
   5.146 +			PEP_STATUS status = call_with_lock(&init, &i->session); // release(session) in ThreadDeleter
   5.147 +			if(status != PEP_STATUS_OK || i->session==nullptr)
   5.148  			{
   5.149 -				i->session = nullptr;
   5.150 -				PEP_STATUS status = call_with_lock(&init, &i->session); // release(session) in ThreadDeleter
   5.151 -				if(status != PEP_STATUS_OK || i->session==nullptr)
   5.152 +				const std::string error_msg = "Cannot create session! PEP_STATUS: " + status_to_string(status) + ".";
   5.153 +				L << Logger::Error << error_msg;
   5.154 +				if( ! i->ignore_session_error)
   5.155  				{
   5.156 -					const std::string error_msg = "Cannot create session! PEP_STATUS: " + status_to_string(status) + ".";
   5.157 -					Log() << error_msg << std::endl;
   5.158 -					if( ! i->ignore_session_error)
   5.159 -					{
   5.160 -						throw std::runtime_error(error_msg);
   5.161 -					}
   5.162 +					throw std::runtime_error(error_msg);
   5.163  				}
   5.164 -				
   5.165 -				session_registry.emplace(id, this);
   5.166 -				Log() << "\tcreated new session for this thread: " << static_cast<void*>(i->session) << "." << std::endl;
   5.167 -				if(i->shall_sync && i->session) // startSync() does not make sense without session.
   5.168 -				{
   5.169 -					Log() << "\tstartSync()..." << std::endl;
   5.170 -					startSync();
   5.171 -				}
   5.172 -			}else{
   5.173 -				Log() << "\tsession for this thread: "  << static_cast<void*>(q->second) << "." << std::endl;
   5.174  			}
   5.175  			
   5.176 -			std::unique_ptr<event_base, decltype(&event_base_free)> eventBase(event_base_new(), &event_base_free);
   5.177 -			if (!eventBase)
   5.178 -				throw std::runtime_error("Failed to create new base_event.");
   5.179 +			session_registry.emplace(id, this);
   5.180 +			L << Logger::Info << "\tcreated new session for this thread: " << static_cast<void*>(i->session) << ".";
   5.181 +			if(i->shall_sync && i->session) // startSync() does not make sense without session.
   5.182 +			{
   5.183 +				L << Logger::Info << "\tstartSync()...";
   5.184 +				startSync();
   5.185 +			}
   5.186 +		}else{
   5.187 +			L << Logger::Info << "\tsession for this thread: "  << static_cast<void*>(q->second) << ".";
   5.188 +		}
   5.189 +		
   5.190 +		std::unique_ptr<event_base, decltype(&event_base_free)> eventBase(event_base_new(), &event_base_free);
   5.191 +		if (!eventBase)
   5.192 +			throw std::runtime_error("Failed to create new base_event.");
   5.193 +		
   5.194 +		std::unique_ptr<evhttp, decltype(&evhttp_free)> evHttp(evhttp_new(eventBase.get()), &evhttp_free);
   5.195 +		if (!evHttp)
   5.196 +			throw std::runtime_error("Failed to create new evhttp.");
   5.197 +		
   5.198 +		evhttp_set_cb(evHttp.get(), ApiRequestUrl.c_str()    , ev_server::OnApiRequest    , this);
   5.199 +		evhttp_set_cb(evHttp.get(), "/pep_functions.js"      , ev_server::OnGetFunctions  , this);
   5.200 +		evhttp_set_gencb(evHttp.get(), ev_server::OnOtherRequest, nullptr);
   5.201 +		
   5.202 +		if (i->sock == -1) // no port bound, yet
   5.203 +		{
   5.204 +			throw std::runtime_error("You have to call prepare_run() before run()!");
   5.205 +		}
   5.206 +		else
   5.207 +		{
   5.208 +			L << Logger::Info << "\tnow I call evhttp_accept_socket()...";
   5.209 +			if (evhttp_accept_socket(evHttp.get(), i->sock) == -1)
   5.210 +				throw std::runtime_error("Failed to accept() on server socket for new instance.");
   5.211 +		}
   5.212 +		
   5.213 +		//unsigned numnum = 1000000;
   5.214 +		while(i->running)
   5.215 +		{
   5.216 +			// once we have libevent 2.1:
   5.217 +			//event_base_loop(eventBase.get(), EVLOOP_NO_EXIT_ON_EMPTY);
   5.218  			
   5.219 -			std::unique_ptr<evhttp, decltype(&evhttp_free)> evHttp(evhttp_new(eventBase.get()), &evhttp_free);
   5.220 -			if (!evHttp)
   5.221 -				throw std::runtime_error("Failed to create new evhttp.");
   5.222 -			
   5.223 -			evhttp_set_cb(evHttp.get(), ApiRequestUrl.c_str()    , ev_server::OnApiRequest    , this);
   5.224 -			evhttp_set_cb(evHttp.get(), "/pep_functions.js"      , ev_server::OnGetFunctions  , this);
   5.225 -			evhttp_set_gencb(evHttp.get(), ev_server::OnOtherRequest, nullptr);
   5.226 -			
   5.227 -			if (i->sock == -1) // no port bound, yet
   5.228 -			{
   5.229 -				throw std::runtime_error("You have to call prepare_run() before run()!");
   5.230 -			}
   5.231 -			else
   5.232 -			{
   5.233 -				Log() << "\tnow I call evhttp_accept_socket()..." << std::endl;
   5.234 -				if (evhttp_accept_socket(evHttp.get(), i->sock) == -1)
   5.235 -					throw std::runtime_error("Failed to accept() on server socket for new instance.");
   5.236 -			}
   5.237 -			
   5.238 -			unsigned numnum = 1000000;
   5.239 -			while(i->running)
   5.240 -			{
   5.241 -				// once we have libevent 2.1:
   5.242 -				//event_base_loop(eventBase.get(), EVLOOP_NO_EXIT_ON_EMPTY);
   5.243 -				
   5.244 -				// for libevent 2.0:
   5.245 -				event_base_loop(eventBase.get(), EVLOOP_NONBLOCK);
   5.246 -				std::this_thread::sleep_for(std::chrono::milliseconds(333));
   5.247 -				Log() << "\r" << ++numnum << ".   " << std::flush;
   5.248 -			}
   5.249 +			// for libevent 2.0:
   5.250 +			event_base_loop(eventBase.get(), EVLOOP_NONBLOCK);
   5.251 +			std::this_thread::sleep_for(std::chrono::milliseconds(333));
   5.252 +			//Log() << "\r" << ++numnum << ".   ";
   5.253  		}
   5.254 -		catch (const std::exception& e)
   5.255 -		{
   5.256 -			Log() << " +++ std::exception in ThreadFunc: " << e.what() << std::endl;
   5.257 -			initExcept = std::current_exception();
   5.258 -		}
   5.259 -		catch (...)
   5.260 -		{
   5.261 -			Log() << " +++ UNKNOWN EXCEPTION in ThreadFunc +++ " << std::endl;
   5.262 -			initExcept = std::current_exception();
   5.263 -		}
   5.264 -		Log() << " +++ Thread exit? isRun=" << i->running << ", id=" << std::this_thread::get_id() << ". initExcept is " << (initExcept?"":"not ") << "set. +++" << std::endl;
   5.265 +	}
   5.266 +	catch (const std::exception& e)
   5.267 +	{
   5.268 +		L << Logger::Error << " +++ std::exception in ThreadFunc: " << e.what();
   5.269 +		initExcept = std::current_exception();
   5.270 +	}
   5.271 +	catch (...)
   5.272 +	{
   5.273 +		L << Logger::Crit << " +++ UNKNOWN EXCEPTION in ThreadFunc +++ ";
   5.274 +		initExcept = std::current_exception();
   5.275 +	}
   5.276 +	L << Logger::Info << " +++ Thread exit? isRun=" << i->running << ", id=" << std::this_thread::get_id() << ". initExcept is " << (initExcept?"":"not ") << "set. +++";
   5.277  }
   5.278  
   5.279  
   5.280 @@ -673,13 +670,15 @@
   5.281  try
   5.282  {
   5.283  	check_guard();
   5.284 -	Log() << "JS::run(): This is " << (void*)this << ", thread id " << std::this_thread::get_id() << "." << std::endl;
   5.285 -	Log() << to_string( session_registry) << std::flush;
   5.286 +	Logger L("JA:run");
   5.287 +	
   5.288 +	L << Logger::Info << "This is " << (void*)this << ", thread id " << std::this_thread::get_id() << ".";
   5.289 +	L << Logger::Debug << to_string( session_registry);
   5.290  	
   5.291  	i->running = true;
   5.292  	for(int t=0; t<SrvThreadCount; ++t)
   5.293  	{
   5.294 -		Log() << "Start Thread #" << t << "..." << std::endl;
   5.295 +		L << Logger::Info << "Start Thread #" << t << "...";
   5.296  		ThreadPtr thread(new std::thread(staticThreadFunc, this), ThreadDeleter);
   5.297  		std::this_thread::sleep_for(std::chrono::milliseconds(500));
   5.298  		if (initExcept)
   5.299 @@ -690,15 +689,15 @@
   5.300  		}
   5.301  		i->threads.push_back(std::move(thread));
   5.302  	}
   5.303 -	Log() << "All " << SrvThreadCount << " thread(s) started:" << std::endl;
   5.304 +	L << Logger::Debug << "All " << SrvThreadCount << " thread(s) started:";
   5.305  	for(const auto& t:i->threads)
   5.306  	{
   5.307 -		Log() << "\tthread_id()=" << t->get_id() << "." << std::endl;
   5.308 +		L << Logger::Debug << "\tthread_id()=" << t->get_id() << ".";
   5.309  	}
   5.310  }
   5.311  catch (std::exception const &e)
   5.312  {
   5.313 -	Log() << "Exception caught in JsonAdapter::run(): \"" << e.what() << "\"" << std::endl;
   5.314 +	Log(Logger::Error) << "Exception in JsonAdapter::run(): \"" << e.what() << "\"";
   5.315  	throw;
   5.316  }
   5.317  
   5.318 @@ -707,7 +706,7 @@
   5.319  {
   5.320  	exit(0);  // HACK for JSON-41
   5.321  	check_guard();
   5.322 -	Log() << "JS::shutdown() was called." << std::endl;
   5.323 +	Log() << "JS::shutdown() was called.";
   5.324  	i->running = false;
   5.325  	
   5.326  	/**** FIXME: proper shutdown!
   5.327 @@ -718,10 +717,10 @@
   5.328  	}
   5.329  	****/
   5.330  	Log() << "JS::shutdown(): event_base loop is finished.\n";
   5.331 -	Log() << "\t there are " << i->threads.size() << " threads remaining in the threadpool." << std::endl;
   5.332 +	Log() << "\t there are " << i->threads.size() << " threads remaining in the threadpool.";
   5.333  	for(const auto& t : i->threads)
   5.334  	{
   5.335 -		Log() << "\t\tjoin() on id=" << t->get_id() << "...." << std::endl;
   5.336 +		Log() << "\t\tjoin() on id=" << t->get_id() << "....";
   5.337  		t->join();
   5.338  	}
   5.339  	i->threads.clear();
   5.340 @@ -734,7 +733,7 @@
   5.341  	check_guard();
   5.342  	if(s!=i->token)
   5.343  	{
   5.344 -		Log() << "sec_token=\"" << i->token << "\" (len=" << i->token.size() << ") is unequal to \"" << s << "\" (len=" << s.size() << ")!" << std::endl;
   5.345 +		Log(Logger::Notice) << "sec_token=\"" << i->token << "\" (len=" << i->token.size() << ") is unequal to \"" << s << "\" (len=" << s.size() << ")!";
   5.346  	}
   5.347  	return s == i->token;
   5.348  }
   5.349 @@ -782,10 +781,10 @@
   5.350  }
   5.351  
   5.352  
   5.353 -std::ostream& JsonAdapter::Log() const
   5.354 +Logger::Stream JsonAdapter::Log(Logger::Severity sev) const
   5.355  {
   5.356  	check_guard();
   5.357 -	return i->Log;
   5.358 +	return std::move(i->Log << sev);
   5.359  }
   5.360  
   5.361  
     6.1 --- a/server/json-adapter.hh	Sun Jul 08 19:22:40 2018 +0200
     6.2 +++ b/server/json-adapter.hh	Mon Aug 13 13:41:05 2018 +0200
     6.3 @@ -5,6 +5,7 @@
     6.4  #include <pEp/sync.h>
     6.5  #include "registry.hh"
     6.6  #include "context.hh"
     6.7 +#include "logger.hh"
     6.8  #include "server_version.hh"
     6.9  
    6.10  
    6.11 @@ -12,7 +13,7 @@
    6.12  {
    6.13  public:
    6.14  	// creates an instance of the JSON adapter. It tries to bind the first available port in the given range
    6.15 -	JsonAdapter(std::ostream* logfile);
    6.16 +	JsonAdapter();
    6.17  	
    6.18  	// calls shutdown() on the instance if it is still running().
    6.19  	virtual ~JsonAdapter();
    6.20 @@ -81,8 +82,7 @@
    6.21  	static pEp_identity* retrieveNextIdentity(void* obj);
    6.22  	static void* keyserverLookupThreadRoutine(void* arg);
    6.23  	
    6.24 -	// returns the associated log stream (either std::cerr or nulllogger)
    6.25 -	std::ostream& Log() const;
    6.26 +	Logger::Stream Log(Logger::Severity s = Logger::Severity::Debug) const;
    6.27  	
    6.28  	// will throw logic_error if guard variables contains illegal values, which means: *this is not a valid JsonAdapter object!
    6.29  	void check_guard() const;
     7.1 --- a/server/json_rpc.cc	Sun Jul 08 19:22:40 2018 +0200
     7.2 +++ b/server/json_rpc.cc	Mon Aug 13 13:41:05 2018 +0200
     7.3 @@ -3,6 +3,16 @@
     7.4  #include "json_spirit/json_spirit_writer.h"
     7.5  #include "json-adapter.hh"
     7.6  #include "security-token.hh"
     7.7 +#include "logger.hh"
     7.8 +
     7.9 +
    7.10 +Logger& Log()
    7.11 +{
    7.12 +	static Logger L("jrpc");
    7.13 +	return L;
    7.14 +}
    7.15 +
    7.16 +
    7.17  
    7.18  // Server side:
    7.19  
    7.20 @@ -12,12 +22,16 @@
    7.21  		ret.emplace_back( "jsonrpc", "2.0" );
    7.22  		ret.emplace_back( "id"     , id );
    7.23  		ret.emplace_back( "result" , result );
    7.24 +		
    7.25 +		DEBUG_OUT(Log(),  "make_result(): result: " + js::write(result) );
    7.26  		return ret;
    7.27  	}
    7.28  	
    7.29  	
    7.30  	js::Object make_error(JSON_RPC error_code, const std::string& error_message, const js::Value& data, int id)
    7.31  	{
    7.32 +		Log().error("make_error(): \"" + error_message + "\" data: " + js::write(data) );
    7.33 +		
    7.34  		js::Object err_obj;
    7.35  		err_obj.emplace_back( "code", int(error_code) );
    7.36  		err_obj.emplace_back( "message", error_message );
    7.37 @@ -64,6 +78,7 @@
    7.38  
    7.39  js::Object call(const FunctionMap& fm, const js::Object& request, Context* context)
    7.40  {
    7.41 +	Logger L("jrpc:call");
    7.42  	int request_id = -1;
    7.43  	try
    7.44  	{
    7.45 @@ -114,13 +129,11 @@
    7.46  		
    7.47  		const js::Array p = ( params.type()==js::array_type ? params.get_array() : js::Array{} );
    7.48  		
    7.49 -//		std::cerr << "=== Now I do the call!\n"
    7.50 -//			"\tmethod_name=\"" << method_name << "\","
    7.51 -//			"\tparams=" << js::write(params) << ". ===\n";
    7.52 +		DEBUG_OUT(L, "method_name=\"" + method_name + "\"\n"
    7.53 +					"params=" + js::write(params) );
    7.54  		
    7.55  		const js::Value result = fn->second->call(p, context);
    7.56 -//		std::cerr << "=== Result of call: " << js::write(result, js::raw_utf8) << ". ===\n";
    7.57 -//		std::cerr << "\tSessions: " << getSessions() << "\n";
    7.58 +		DEBUG_OUT(L, "result=" + js::write(result, js::raw_utf8) );
    7.59  		
    7.60  		return make_result(result, request_id);
    7.61  	}
     8.1 --- /dev/null	Thu Jan 01 00:00:00 1970 +0000
     8.2 +++ b/server/logger.cc	Mon Aug 13 13:41:05 2018 +0200
     8.3 @@ -0,0 +1,550 @@
     8.4 +#include "logger.hh"
     8.5 +#include "logger_config.hh"
     8.6 +
     8.7 +#include <algorithm>
     8.8 +#include <cassert>
     8.9 +#include <cstdarg>
    8.10 +#include <ctime>
    8.11 +#include <cstdlib>
    8.12 +#include <mutex>
    8.13 +#include <thread>
    8.14 +#include <sstream>
    8.15 +#include <vector>
    8.16 +#include <sys/time.h>
    8.17 +
    8.18 +#ifdef LOGGER_ENABLE_SYSLOG
    8.19 +extern "C" {
    8.20 +#include <syslog.h>
    8.21 +}
    8.22 +#endif // LOGGER_ENABLE_SYSLOG
    8.23 +
    8.24 +using Lock = std::lock_guard<std::recursive_mutex>;
    8.25 +
    8.26 +
    8.27 +
    8.28 +namespace LoggerS  // namespace containing all data for the Logger singleton. HACK!
    8.29 +{
    8.30 +	std::FILE* logfile = 0;
    8.31 +	std::recursive_mutex mut;
    8.32 +	Logger::Severity loglevel = Logger::DebugInternal;
    8.33 +	Logger::Target target = Logger::Target(-1);
    8.34 +	std::string filename;
    8.35 +	std::string ident;
    8.36 +	
    8.37 +	bool initialized = false;
    8.38 +	
    8.39 +	// config variables
    8.40 +	bool omit_timestamp = false;
    8.41 +	unsigned max_message_length = LOGGER_MAX_LOG_MESSAGE_LENGTH;
    8.42 +	unsigned max_line_length    = LOGGER_MAX_LINE_LENGTH;
    8.43 +
    8.44 +	void openfile();
    8.45 +	void opensyslog();
    8.46 +
    8.47 +	void start(const std::string& program_name, const std::string& filename = std::string())
    8.48 +	{
    8.49 +		ident = program_name;
    8.50 +		// TODO: use $TEMP, $TMP etc.
    8.51 +		opensyslog();
    8.52 +		if(target & Logger::Target::File)
    8.53 +		{
    8.54 +			LoggerS::filename = filename.empty() ? "/tmp/log-" + program_name + ".log" : filename;
    8.55 +			openfile();
    8.56 +		}
    8.57 +		initialized = true;
    8.58 +	}
    8.59 +
    8.60 +	void log(Logger::Severity s, const std::string& msg);
    8.61 +
    8.62 +#ifdef LOGGER_USE_ASCII_TAGS
    8.63 +	const char* Levelname[] =
    8.64 +		{
    8.65 +			"<<EMERGENCY>>",
    8.66 +			"<<ALERT>>",
    8.67 +			"<<CRITICAL>>",
    8.68 +			"<ERROR>",
    8.69 +			"<Warning>",
    8.70 +			"<Notice>",
    8.71 +			"<info>",
    8.72 +			"<>",  // Debug
    8.73 +			"! "   // DebugInternal
    8.74 +		};
    8.75 +	
    8.76 +	const char* const MultilineBracketFirst = "/";
    8.77 +	const char* const MultilineBracketMid   = "|";
    8.78 +	const char* const MultilineBracketLast  = "\\";
    8.79 +	const char* const MultilineWrap         = "|>";
    8.80 +	const char* const MultilineWrapContinue = "<|";
    8.81 +
    8.82 +#else
    8.83 +	const char* Levelname[] =
    8.84 +		{
    8.85 +			"»»EMERGENCY",
    8.86 +			"»»ALERT",
    8.87 +			"»»CRITICAL",
    8.88 +			"»ERROR",
    8.89 +			"»Warning",
    8.90 +			"»Notice",
    8.91 +			"»Info",
    8.92 +			"°",  // Debug
    8.93 +			"·"   // DebugInternal
    8.94 +		};
    8.95 +	
    8.96 +	const char* const MultilineBracketFirst = "⎡ ";
    8.97 +	const char* const MultilineBracketMid   = "⎢ ";
    8.98 +	const char* const MultilineBracketLast  = "⎣ ";
    8.99 +	const char* const MultilineWrap         = "↩";
   8.100 +	const char* const MultilineWrapContinue = "↪";
   8.101 +
   8.102 +#endif
   8.103 +
   8.104 +	struct LogfileCloser
   8.105 +	{
   8.106 +		~LogfileCloser()
   8.107 +		{
   8.108 +			if(LoggerS::logfile)
   8.109 +			{
   8.110 +				LoggerS::log(Logger::Debug, "Shutdown.");
   8.111 +				fputs("---<shutdown>---\n", LoggerS::logfile);
   8.112 +				fclose(LoggerS::logfile);
   8.113 +				LoggerS::logfile = nullptr;
   8.114 +			}
   8.115 +		}
   8.116 +	};
   8.117 +	
   8.118 +	// guess what.
   8.119 +	static LogfileCloser logfile_closer;
   8.120 +
   8.121 +} // end of namespace LoggerS
   8.122 +
   8.123 +
   8.124 +namespace {
   8.125 +
   8.126 +	void logSingleLine(FILE* logfile, const std::string& timestamp, const std::string& logline)
   8.127 +	{
   8.128 +		std::fputs(timestamp.c_str(), logfile);
   8.129 +		std::fputs(logline.c_str(), logfile);
   8.130 +		std::fputc('\n', logfile);
   8.131 +	}
   8.132 +
   8.133 +	void logMultiLine(FILE* logfile, const std::string& prefix, const std::vector<std::string>& lines)
   8.134 +	{
   8.135 +		assert( lines.size()>1 );
   8.136 +		
   8.137 +		// be robust, anyway. So:
   8.138 +		if(lines.empty())
   8.139 +		{
   8.140 +			return;
   8.141 +		}
   8.142 +		
   8.143 +		if(lines.size()==1)
   8.144 +		{
   8.145 +			logSingleLine(logfile, prefix, lines.at(0));
   8.146 +			return;
   8.147 +		}
   8.148 +		
   8.149 +		const size_t  last_line = lines.size()-1;
   8.150 +		
   8.151 +		std::fputs(prefix.c_str(), logfile);
   8.152 +		std::fputs(LoggerS::MultilineBracketFirst, logfile);
   8.153 +		std::fputs(lines[0].c_str(), logfile);
   8.154 +		std::fputc('\n', logfile);
   8.155 +		
   8.156 +		for(size_t q=1; q<last_line; ++q)
   8.157 +		{
   8.158 +			std::fputs(prefix.c_str(), logfile);
   8.159 +			std::fputs(LoggerS::MultilineBracketMid, logfile);
   8.160 +			std::fputs(lines[q].c_str(), logfile);
   8.161 +			std::fputc('\n', logfile);
   8.162 +		}
   8.163 +		
   8.164 +		std::fputs(prefix.c_str(), logfile);
   8.165 +		std::fputs(LoggerS::MultilineBracketLast, logfile);
   8.166 +		std::fputs(lines[last_line].c_str(), logfile);
   8.167 +		std::fputc('\n', logfile);
   8.168 +	}
   8.169 +
   8.170 +	// wrap an overlong line into several lines, incl. adding wrapping markers
   8.171 +	void wrapLongLine(const std::string& oneline, std::vector<std::string>& lines)
   8.172 +	{
   8.173 +		std::string::const_iterator begin = oneline.begin();
   8.174 +		std::string::const_iterator end   = oneline.begin();
   8.175 +		std::size_t ofs = 0;
   8.176 +		
   8.177 +		bool cont_line = false;
   8.178 +		do{
   8.179 +			begin=end;
   8.180 +			const unsigned delta = std::min( (size_t)Logger::getMaxLineLength(), oneline.size() - ofs );
   8.181 +			end += delta;
   8.182 +			ofs += delta;
   8.183 +			
   8.184 +			if(end != oneline.end())
   8.185 +			{
   8.186 +				while( (uint8_t(*end) >= 0x80) && (end>begin) )
   8.187 +				{
   8.188 +					// rewind
   8.189 +					--end;
   8.190 +					--ofs;
   8.191 +				}
   8.192 +			}
   8.193 +			
   8.194 +			lines.push_back(
   8.195 +					(cont_line ? LoggerS::MultilineWrapContinue : "") +
   8.196 +					std::string(begin, end) +
   8.197 +					(end!=oneline.end() ? LoggerS::MultilineWrap : "")
   8.198 +				);
   8.199 +			cont_line = true;
   8.200 +		}while( end != oneline.end() );
   8.201 +	}
   8.202 +	
   8.203 +} // end of anonymous namespace
   8.204 +
   8.205 +void Logger::start(const std::string& program_name, const std::string& filename)
   8.206 +{
   8.207 +	if(LoggerS::initialized==false)
   8.208 +	{
   8.209 +		LoggerS::start(program_name, filename);
   8.210 +		Logger& l = ::getLogger();
   8.211 +		l.debug("Logger has been started.");
   8.212 +	}
   8.213 +}
   8.214 +
   8.215 +
   8.216 +std::string Logger::gmtime(time_t t)
   8.217 +{
   8.218 +	char buf[24]; // long enough to hold YYYYY-MM-DD.hh:mm:ss" (y10k-safe!)
   8.219 +	std::tm     T;
   8.220 +	gmtime_r(&t, &T); // TODO: GNU extension also in std:: ?
   8.221 +	std::snprintf(buf, sizeof(buf)-1, "%04d-%02d-%02d.%02d:%02d:%02d",
   8.222 +		T.tm_year+1900, T.tm_mon+1, T.tm_mday, T.tm_hour, T.tm_min, T.tm_sec );
   8.223 +	
   8.224 +	return buf;
   8.225 +}
   8.226 +
   8.227 +
   8.228 +std::string Logger::gmtime(timeval t)
   8.229 +{
   8.230 +	char buf[31]; // long enough to hold YYYYY-MM-DD.hh:mm:ss.uuuuuu
   8.231 +	std::tm T;
   8.232 +	gmtime_r(&t.tv_sec, &T);  // TODO: GNU extension also in std:: ?
   8.233 +	std::snprintf(buf, sizeof(buf)-1, "%04d-%02d-%02d.%02d:%02d:%02d.%06lu",
   8.234 +	         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);
   8.235 +	
   8.236 +	return buf;
   8.237 +}
   8.238 +
   8.239 +
   8.240 +Logger::Severity Logger::getLevel() const
   8.241 +{
   8.242 +	return loglevel;
   8.243 +}
   8.244 +
   8.245 +
   8.246 +void Logger::setLevel(Severity s)
   8.247 +{
   8.248 +	// TODO: use C++17 std::clamp()
   8.249 +	loglevel = s<Emergency ? Emergency : (s>DebugInternal ? DebugInternal : s);
   8.250 +}
   8.251 +
   8.252 +
   8.253 +const std::string& Logger::getPrefix() const
   8.254 +{
   8.255 +	return prefix;
   8.256 +}
   8.257 +
   8.258 +
   8.259 +Logger::Target Logger::getDefaultTarget()
   8.260 +{
   8.261 +	return LoggerS::target;
   8.262 +}
   8.263 +
   8.264 +
   8.265 +void Logger::setDefaultTarget(Target t)
   8.266 +{
   8.267 +	LoggerS::target = t;
   8.268 +}
   8.269 +
   8.270 +
   8.271 +Logger::Severity Logger::getDefaultLevel()
   8.272 +{
   8.273 +	return LoggerS::loglevel;
   8.274 +}
   8.275 +
   8.276 +
   8.277 +void Logger::setDefaultLevel(Severity s)
   8.278 +{
   8.279 +	LoggerS::loglevel = s;
   8.280 +}
   8.281 +
   8.282 +
   8.283 +// set maximum length of a log message. Longer messages will be clipped!
   8.284 +void Logger::setMaxMessageLength(unsigned length)
   8.285 +{
   8.286 +	LoggerS::max_message_length = length;
   8.287 +}
   8.288 +
   8.289 +// set maximum length of a log _line_. Longer messages will be wrapped into several lines.
   8.290 +void Logger::setMaxLineLength(unsigned length)
   8.291 +{
   8.292 +	LoggerS::max_line_length = std::min(length, 64u*1024u);
   8.293 +}
   8.294 +
   8.295 +unsigned Logger::getMaxMessageLength()
   8.296 +{
   8.297 +	return LoggerS::max_message_length;
   8.298 +}
   8.299 +
   8.300 +unsigned Logger::getMaxLineLength()
   8.301 +{
   8.302 +	return LoggerS::max_line_length;
   8.303 +}
   8.304 +
   8.305 +
   8.306 +Logger::Logger(const std::string& my_prefix, Severity my_loglevel)
   8.307 +: prefix(my_prefix + ":")
   8.308 +{
   8.309 +	setLevel(my_loglevel == Severity::Inherited ? getDefaultLevel() : my_loglevel);
   8.310 +	start(my_prefix); // if not yet initialized.
   8.311 +}
   8.312 +
   8.313 +
   8.314 +Logger::Logger(Logger& parent, const std::string& my_prefix, Severity my_loglevel)
   8.315 +: Logger( parent.getPrefix() + my_prefix + ':', my_loglevel == Severity::Inherited ? parent.getLevel() : my_loglevel )
   8.316 +{
   8.317 +}
   8.318 +
   8.319 +
   8.320 +void Logger::log(Severity s, const char* format, ...)
   8.321 +{
   8.322 +	if(s<=loglevel && s<=LoggerS::loglevel)
   8.323 +	{
   8.324 +		va_list va;
   8.325 +		va_start(va, format);
   8.326 +		char buf[ LoggerS::max_line_length + 1];
   8.327 +		std::vsnprintf(buf, LoggerS::max_line_length, format, va);
   8.328 +		va_end(va);
   8.329 +		
   8.330 +		LoggerS::log(s, prefix + buf);
   8.331 +	}
   8.332 +}
   8.333 +
   8.334 +
   8.335 +void LogP(Logger::Severity s, Logger::Severity my_loglevel, const std::string& prefix, const char* format, va_list va)
   8.336 +{
   8.337 +	if(s<=my_loglevel && s<=LoggerS::loglevel)
   8.338 +	{
   8.339 +		char buf[ LoggerS::max_line_length + 1];
   8.340 +		std::vsnprintf(buf, LoggerS::max_line_length, format, va);
   8.341 +		LoggerS::log(s, prefix + buf );
   8.342 +	}
   8.343 +}
   8.344 +
   8.345 +
   8.346 +void Logger::log(Severity s, const std::string& logline)
   8.347 +{
   8.348 +	if(s<=loglevel && s<=LoggerS::loglevel)
   8.349 +	{
   8.350 +		LoggerS::log(s, prefix + logline);
   8.351 +	}
   8.352 +}
   8.353 +
   8.354 +
   8.355 +#define LOGGER_LAZY( fnname, severity ) \
   8.356 +	void Logger::fnname ( const std::string& line) { \
   8.357 +		log( Logger:: severity, line ); \
   8.358 +	} \
   8.359 +	void Logger:: fnname (const char* format, ...) { \
   8.360 +		va_list va;	va_start(va, format); \
   8.361 +		LogP( severity, loglevel, prefix, format, va ) ;\
   8.362 +		va_end(va); \
   8.363 +	} \
   8.364 +
   8.365 +
   8.366 +LOGGER_LAZY( emergency, Emergency)
   8.367 +LOGGER_LAZY( alert    , Alert    )
   8.368 +LOGGER_LAZY( critical , Crit     )
   8.369 +LOGGER_LAZY( error    , Error    )
   8.370 +LOGGER_LAZY( warning  , Warn     )
   8.371 +LOGGER_LAZY( notice   , Notice   )
   8.372 +LOGGER_LAZY( info     , Info     )
   8.373 +
   8.374 +#ifdef DEBUG_ENABLED
   8.375 +LOGGER_LAZY( debug    , Debug    )
   8.376 +LOGGER_LAZY( debugInternal , DebugInternal )
   8.377 +#else
   8.378 +// intentionally left blank.
   8.379 +// the methods are already defined as do-nothing inline functions in Logger.hh
   8.380 +#endif
   8.381 +
   8.382 +#undef LOGGER_LAZY
   8.383 +
   8.384 +
   8.385 +Logger& getLogger()
   8.386 +{
   8.387 +	Lock LCK(LoggerS::mut);
   8.388 +	static Logger log("#", Logger::Debug);
   8.389 +	return log;
   8.390 +}
   8.391 +
   8.392 +
   8.393 +// ---------- LoggerS ----------
   8.394 +
   8.395 +void LoggerS::openfile()
   8.396 +{
   8.397 +	logfile = std::fopen(filename.c_str(), "a");
   8.398 +	if(logfile==0)
   8.399 +	{
   8.400 +		perror("Could not open log file! ");
   8.401 +	}
   8.402 +}
   8.403 +
   8.404 +
   8.405 +
   8.406 +void LoggerS::opensyslog()
   8.407 +{
   8.408 +#ifdef LOGGER_ENABLE_SYSLOG
   8.409 +	openlog(ident.c_str(), 0, LOG_DAEMON);
   8.410 +#endif
   8.411 +}
   8.412 +
   8.413 +
   8.414 +static const std::string thread_alphabet = "0123456789_ABCDEFGHIJKLMNOPQRSTUVWXYZ";
   8.415 +static const unsigned thread_alph_len = thread_alphabet.size(); // shall be a prime number
   8.416 +static std::hash<std::thread::id> hash_tid;
   8.417 +
   8.418 +// create a three-digit base37 string of the current thread ID for easy grepping and filtering:
   8.419 +std::string thread_id()
   8.420 +{
   8.421 +	char buf[8] = { ' ', '\302', '\266', '?', '?', '?', ' ' };
   8.422 +	unsigned long long id = hash_tid(std::this_thread::get_id());
   8.423 +	buf[3] = thread_alphabet.at( id % thread_alph_len); id /= thread_alph_len;
   8.424 +	buf[4] = thread_alphabet.at( id % thread_alph_len); id /= thread_alph_len;
   8.425 +	buf[5] = thread_alphabet.at( id % thread_alph_len); id /= thread_alph_len;
   8.426 +	return std::string(buf, buf+7);
   8.427 +}
   8.428 +
   8.429 +
   8.430 +void LoggerS::log(Logger::Severity s, const std::string& logline)
   8.431 +{
   8.432 +	Lock LCK(mut);
   8.433 +	if(s<Logger::Emergency     ) s = Logger::Emergency;
   8.434 +	if(s>Logger::DebugInternal ) s = Logger::DebugInternal;
   8.435 +	
   8.436 +	// clipt and wrap:
   8.437 +	bool multiline = false;
   8.438 +	std::vector<std::string> lines;
   8.439 +	std::stringstream ss(logline);
   8.440 +	std::string oneline;
   8.441 +	while(std::getline(ss, oneline))
   8.442 +	{
   8.443 +		if(oneline.size() > max_line_length)
   8.444 +		{
   8.445 +			wrapLongLine(oneline, lines);
   8.446 +		}else{
   8.447 +			lines.push_back( std::move(oneline) );
   8.448 +		}
   8.449 +	}
   8.450 +	
   8.451 +	if(lines.size() > 1)
   8.452 +		multiline = true;
   8.453 +	
   8.454 +	// create header with timestamp
   8.455 +	if(target & (Logger::File | Logger::Console))
   8.456 +	{
   8.457 +		std::string timestamp;
   8.458 +		timestamp.reserve(45);
   8.459 +		
   8.460 +		if(omit_timestamp == false)
   8.461 +		{
   8.462 +			timestamp = Logger::gmtime(time(0));
   8.463 +		}
   8.464 +		
   8.465 +		timestamp.append( thread_id() );
   8.466 +		timestamp.append(Levelname[s]);
   8.467 +		timestamp.append(" :");
   8.468 +		
   8.469 +		if(target & Logger::Console)
   8.470 +		{
   8.471 +			if(multiline)
   8.472 +			{
   8.473 +				logMultiLine(stderr, timestamp, lines);
   8.474 +			}else{
   8.475 +				logSingleLine(stderr, timestamp, logline);
   8.476 +			}
   8.477 +		}
   8.478 +		if(target & Logger::File)
   8.479 +		{
   8.480 +			if(multiline)
   8.481 +			{
   8.482 +				logMultiLine(logfile, timestamp, lines);
   8.483 +			}else{
   8.484 +				logSingleLine(logfile, timestamp, logline);
   8.485 +			}
   8.486 +			std::fflush(logfile);
   8.487 +		}
   8.488 +	}
   8.489 +	
   8.490 +#ifdef LOGGER_ENABLE_SYSLOG
   8.491 +	if(target & Logger::Syslog)
   8.492 +	{
   8.493 +		syslog(s, "%s", logline.c_str());
   8.494 +	}
   8.495 +#endif
   8.496 +}
   8.497 +
   8.498 +
   8.499 +Logger::Stream::Stream(Logger* parent, Severity _sev)
   8.500 +: L(parent), sev(_sev)
   8.501 +{}
   8.502 +
   8.503 +
   8.504 +Logger::Stream::~Stream()
   8.505 +{
   8.506 +	if(L)
   8.507 +	{
   8.508 +		L->log(sev, s);
   8.509 +	}
   8.510 +}
   8.511 +
   8.512 +
   8.513 +template<class T>
   8.514 +const Logger::Stream& operator<<(const Logger::Stream& stream, const T& t)
   8.515 +{
   8.516 +	std::stringstream ss;
   8.517 +	ss << t;
   8.518 +	stream.s.append( ss.str());
   8.519 +	return stream;
   8.520 +}
   8.521 +
   8.522 +
   8.523 +const Logger::Stream& operator<<(const Logger::Stream& stream, const char*const t)
   8.524 +{
   8.525 +	stream.s.append( t );
   8.526 +	return stream;
   8.527 +}
   8.528 +
   8.529 +template<>
   8.530 +const Logger::Stream& operator<<(const Logger::Stream& stream, const bool& b)
   8.531 +{
   8.532 +	stream.s.append( b ? "true" : "false");
   8.533 +	return stream;
   8.534 +}
   8.535 +
   8.536 +template const Logger::Stream& operator<<(const Logger::Stream&, const int&);
   8.537 +template const Logger::Stream& operator<<(const Logger::Stream&, const long&);
   8.538 +template const Logger::Stream& operator<<(const Logger::Stream&, const unsigned&);
   8.539 +template const Logger::Stream& operator<<(const Logger::Stream&, const unsigned long&);
   8.540 +
   8.541 +template const Logger::Stream& operator<<(const Logger::Stream&, const std::string&);
   8.542 +template const Logger::Stream& operator<<(const Logger::Stream&, const double&);
   8.543 +
   8.544 +template const Logger::Stream& operator<<(const Logger::Stream&, const void*const&);
   8.545 +template const Logger::Stream& operator<<(const Logger::Stream&,       void*const&);
   8.546 +template const Logger::Stream& operator<<(const Logger::Stream&, const std::thread::id&);
   8.547 +
   8.548 +Logger::Stream operator<<(Logger& parent, Logger::Severity sev)
   8.549 +{
   8.550 +	return Logger::Stream(&parent, sev);
   8.551 +}
   8.552 +
   8.553 +// End of file
     9.1 --- /dev/null	Thu Jan 01 00:00:00 1970 +0000
     9.2 +++ b/server/logger.hh	Mon Aug 13 13:41:05 2018 +0200
     9.3 @@ -0,0 +1,171 @@
     9.4 +#ifndef LOGGER_HH
     9.5 +#define LOGGER_HH
     9.6 +
     9.7 +#include <cstdio>
     9.8 +#include <string>
     9.9 +#include <cerrno>
    9.10 +#include <sys/time.h>
    9.11 +
    9.12 +
    9.13 +#ifdef DEBUG_ENABLED
    9.14 +#define DEBUG_OUT( LL , ... )  LL.debug( __VA_ARGS__ )
    9.15 +#define DEBUGI_OUT( LL , ... )  LL.debugInternal( __VA_ARGS__ )
    9.16 +#else
    9.17 +#define DEBUG_OUT(...)  do{}while(0)
    9.18 +#define DEBUGI_OUT(...)  do{}while(0)
    9.19 +#endif
    9.20 +
    9.21 +#ifdef __GNUC__
    9.22 +#define PRINTF __attribute__((format (printf, 2,3) ))
    9.23 +#define PRINTF3 __attribute__((format (printf, 3,4) ))
    9.24 +#else
    9.25 +#define PRINTF
    9.26 +#define PRINTF3
    9.27 +#endif
    9.28 +
    9.29 +
    9.30 +class Logger;
    9.31 +
    9.32 +// get global Logger instance
    9.33 +Logger& getLogger();
    9.34 +
    9.35 +class Logger
    9.36 +{
    9.37 +public:
    9.38 +	enum Severity
    9.39 +	{
    9.40 +		Emergency,// The message says the system is unusable.
    9.41 +		Alert,    // Action on the message must be taken immediately.
    9.42 +		Crit,     // The message states a critical condition.
    9.43 +		Error,    // The message describes an error.
    9.44 +		Warn,     // The message is a warning.
    9.45 +		Notice,   // The message describes a normal but important event.
    9.46 +		Info,     // The message is purely informational.
    9.47 +		Debug,    // The message is only for interface debugging purposes.
    9.48 +		DebugInternal, // The message is for internal debugging purposes.
    9.49 +		
    9.50 +		Inherited=-1 // Use the same loglevel as the parent Logger (if any)
    9.51 +	};
    9.52 +
    9.53 +	enum Target
    9.54 +	{
    9.55 +		None = 0,
    9.56 +		Console=1, Syslog=2, File=4  // may be ORed together
    9.57 +	};
    9.58 +
    9.59 +	// shall be called before first log message.
    9.60 +	static void start(const std::string& program_name, const std::string& filename = "");
    9.61 +
    9.62 +	// returns a string in YYYY-MM-DD.hh:mm:ss format of the given time_t t
    9.63 +	static std::string gmtime(time_t t);
    9.64 +
    9.65 +	// returns a string in YYYY-MM-DD.hh:mm:ss.uuuuuu format (u=microseconds) of the given timval
    9.66 +	static std::string gmtime(timeval t);
    9.67 +
    9.68 +	void emergency(const char* format, ...) PRINTF;
    9.69 +	void emergency(const std::string& line);
    9.70 +
    9.71 +	void alert(const char* format, ...) PRINTF;
    9.72 +	void alert(const std::string& line);
    9.73 +
    9.74 +	void critical(const char* format, ...) PRINTF;
    9.75 +	void critical(const std::string& line);
    9.76 +
    9.77 +	void error(const char* format, ...) PRINTF;
    9.78 +	void error(const std::string& line);
    9.79 +
    9.80 +	void warning(const char* format, ...) PRINTF;
    9.81 +	void warning(const std::string& line);
    9.82 +
    9.83 +	void notice(const char* format, ...) PRINTF;
    9.84 +	void notice(const std::string& line);
    9.85 +
    9.86 +	void info(const char* format, ...) PRINTF;
    9.87 +	void info(const std::string& line);
    9.88 +
    9.89 +#ifdef DEBUG_ENABLED
    9.90 +	void debug(const char* format, ...) PRINTF;
    9.91 +	void debug(const std::string& line);
    9.92 +
    9.93 +	void debugInternal(const char* format, ...) PRINTF;
    9.94 +	void debugInternal(const std::string& line);
    9.95 +#else
    9.96 +	void debug(const char*, ...) PRINTF  { /* do nothing */ }
    9.97 +	void debug(const std::string&) { /* do nothing */ }
    9.98 +
    9.99 +	void debugInternal(const char*, ...) PRINTF { /* do nothing */ }
   9.100 +	void debugInternal(const std::string&) { /* do nothing */ }
   9.101 +#endif
   9.102 +
   9.103 +	void log(Severity s, const char* format, ...) PRINTF3; // C style
   9.104 +	void log(Severity s, const std::string& line); // C++ style :-)
   9.105 +
   9.106 +	// log messages with a lower severity are ignored
   9.107 +	void setLevel(Severity s);
   9.108 +	Severity getLevel() const;
   9.109 +
   9.110 +	static void setDefaultLevel(Severity s);
   9.111 +	static Severity getDefaultLevel();
   9.112 +
   9.113 +	static void setDefaultTarget(Target t);
   9.114 +	static Target getDefaultTarget();
   9.115 +
   9.116 +	// set maximum length of a log message. Longer messages will be clipped!
   9.117 +	static void setMaxMessageLength(unsigned length);
   9.118 +	
   9.119 +	// set maximum length of a log _line_. Longer messages will be wrapped into several lines.
   9.120 +	static void setMaxLineLength(unsigned length);
   9.121 +
   9.122 +	static unsigned getMaxMessageLength();
   9.123 +	static unsigned getMaxLineLength();
   9.124 +
   9.125 +	const std::string& getPrefix() const;
   9.126 +
   9.127 +	// if no explicit severity is given it is taken from default's severity
   9.128 +	explicit Logger(const std::string& my_prefix, Severity my_severity = Severity::Inherited);
   9.129 +	explicit Logger(Logger& parent, const std::string& my_prefix, Severity my_severity = Severity::Inherited);
   9.130 +
   9.131 +	// non-copyable:
   9.132 +	Logger(const Logger&) = delete;
   9.133 +	void operator=(const Logger&) = delete;
   9.134 +
   9.135 +
   9.136 +	class Stream
   9.137 +	{
   9.138 +	public:
   9.139 +		Stream(Logger* _L, Logger::Severity _sev);
   9.140 +		~Stream();
   9.141 +		
   9.142 +		mutable std::string s;
   9.143 +		
   9.144 +	private:
   9.145 +		Logger* L;
   9.146 +		const Logger::Severity sev;
   9.147 +	};
   9.148 +	
   9.149 +;
   9.150 +private:
   9.151 +	friend Logger& getLogger();
   9.152 +	const std::string prefix;
   9.153 +	Severity loglevel;
   9.154 +};
   9.155 +
   9.156 +	// creates a Stream, who collect data in pieces and logs it to the "parent" logger in its destructor with the given severity
   9.157 +	Logger::Stream operator<<(Logger& parent, Logger::Severity sev);
   9.158 +
   9.159 +	template<class T>
   9.160 +	const Logger::Stream& operator<<(const Logger::Stream&, const T&);
   9.161 +	const Logger::Stream& operator<<(const Logger::Stream&, const char*const);
   9.162 +
   9.163 +	inline
   9.164 +	const Logger::Stream& operator<<(const Logger::Stream& stream, char*const s)
   9.165 +	{
   9.166 +		return stream << const_cast<const char*>(s);
   9.167 +	}
   9.168 +
   9.169 +// clean up defines which may collide with other headers...
   9.170 +#undef PRINTF
   9.171 +#undef PRINTF3
   9.172 +
   9.173 +#endif // LOGGER_HH
   9.174 +
    10.1 --- /dev/null	Thu Jan 01 00:00:00 1970 +0000
    10.2 +++ b/server/logger_config.hh	Mon Aug 13 13:41:05 2018 +0200
    10.3 @@ -0,0 +1,17 @@
    10.4 +#ifndef LOGGER_CONFIG_HH
    10.5 +#define LOGGER_CONFIG_HH
    10.6 +
    10.7 +// maximum length of a log message. longer log messages will be clipped
    10.8 +#define LOGGER_MAX_LOG_MESSAGE_LENGTH (8192)
    10.9 +
   10.10 +// maximum length of a log line. longer lines will be wrapped/folded
   10.11 +#define LOGGER_MAX_LINE_LENGTH (1000)
   10.12 +
   10.13 +// enable logging to syslog
   10.14 +#define LOGGER_ENABLE_SYSLOG (1)
   10.15 +
   10.16 +// use ASCII-only characters to tag log lines
   10.17 +// #define LOGGER_USE_ASCII_TAGS (1)
   10.18 +
   10.19 +
   10.20 +#endif // LOGGER_CONFIG_HH
    11.1 --- a/server/main.cc	Sun Jul 08 19:22:40 2018 +0200
    11.2 +++ b/server/main.cc	Mon Aug 13 13:41:05 2018 +0200
    11.3 @@ -3,6 +3,7 @@
    11.4  #include "prefix-config.hh"
    11.5  #include "json-adapter.hh"
    11.6  #include "daemonize.hh"
    11.7 +#include "logger.hh"
    11.8  #include "nulllogger.hh"
    11.9  
   11.10  #include <thread>
   11.11 @@ -61,7 +62,7 @@
   11.12  		("add-sharks", po::bool_switch(&add_sharks), "Add sharks to the JSON Adapter.")
   11.13  #ifdef _WIN32
   11.14  		((STATUS_HANDLE), po::value<uintptr_t>(&status_handle)->default_value(0), "Status file handle, for internal use.")
   11.15 -#endif	
   11.16 +#endif
   11.17  	;
   11.18  	
   11.19  	po::variables_map vm;
   11.20 @@ -88,15 +89,18 @@
   11.21  	
   11.22  	if(logfile.empty())
   11.23  	{
   11.24 -		my_logfile = &nulllogger;
   11.25 +		Logger::setDefaultTarget(Logger::Target::None);
   11.26  	}else if(logfile == "stderr")
   11.27  	{
   11.28 -		my_logfile = &std::cerr;
   11.29 +		Logger::setDefaultTarget(Logger::Target::Console);
   11.30  	}else{
   11.31 -		real_logfile = std::make_shared<std::ofstream>( logfile, std::ios::app );
   11.32 -		my_logfile = real_logfile.get();
   11.33 +		Logger::setDefaultTarget(Logger::Target::File);
   11.34  	}
   11.35 +
   11.36 +	Logger::start("JsonAdapter", logfile);
   11.37  	
   11.38 +	Logger L("main");
   11.39 +	L.info("main logger started");
   11.40  	if(add_sharks)
   11.41  	{
   11.42  		ev_server::addSharks();
   11.43 @@ -104,8 +108,8 @@
   11.44  	
   11.45  	if( debug_mode == false )
   11.46  		daemonize (!debug_mode, (const uintptr_t) status_handle);
   11.47 -
   11.48 -	JsonAdapter ja( my_logfile );
   11.49 +	
   11.50 +	JsonAdapter ja;
   11.51  	ja.do_sync( do_sync)
   11.52  	  .ignore_session_errors( ignore_missing_session)
   11.53  	  ;
   11.54 @@ -136,13 +140,19 @@
   11.55  			}while(ja.running());
   11.56  		}
   11.57  		ja.shutdown(nullptr);
   11.58 -		ja.Log() << "Good bye. :-)" << std::endl;
   11.59 +		ja.Log() << "Good bye. :-)";
   11.60  		JsonAdapter::global_shutdown();
   11.61  	}
   11.62 +	catch(std::exception const& e)
   11.63 +	{
   11.64 +		std::cerr << "Inner exception caught in main(): \"" << e.what() << "\"" << std::endl;
   11.65 +		daemonize_commit(1);
   11.66 +		exit(8);
   11.67 +	}
   11.68  	catch (...)
   11.69  	{
   11.70  		daemonize_commit(1);
   11.71 -		exit(1);
   11.72 +		exit(9);
   11.73  	}
   11.74  }
   11.75  catch(std::exception const& e)
    12.1 --- /dev/null	Thu Jan 01 00:00:00 1970 +0000
    12.2 +++ b/server/unittest_logger.cc	Mon Aug 13 13:41:05 2018 +0200
    12.3 @@ -0,0 +1,69 @@
    12.4 +#include <gtest/gtest.h>
    12.5 +#include "logger.hh"
    12.6 +
    12.7 +namespace
    12.8 +{
    12.9 +	std::string longstring(unsigned length)
   12.10 +	{
   12.11 +		std::string s;
   12.12 +		s.reserve(length);
   12.13 +		for(unsigned u=0; u<length; ++u)
   12.14 +		{
   12.15 +			s += char( (u%94) + '!' );
   12.16 +		}
   12.17 +		return s;
   12.18 +	}
   12.19 +}
   12.20 +
   12.21 +
   12.22 +class LoggerTest : public ::testing::Test
   12.23 +{
   12.24 +	void SetUp()
   12.25 +	{
   12.26 +		Logger::start("unittest_logger");
   12.27 +	}
   12.28 +	
   12.29 +	void TearDown()
   12.30 +	{
   12.31 +		
   12.32 +	}
   12.33 +};
   12.34 +
   12.35 +
   12.36 +TEST_F( LoggerTest, Severities )
   12.37 +{
   12.38 +	Logger L("Severities");
   12.39 +	
   12.40 +	L.debug    ("This is debug");
   12.41 +	L.info     ("This is info");
   12.42 +	L.notice   ("This is notice");
   12.43 +	L.warning  ("This is warning");
   12.44 +	L.error    ("This is error");
   12.45 +	L.critical ("This is critical");
   12.46 +	L.alert    ("This is alert");
   12.47 +	L.emergency("This is emergency");
   12.48 +	
   12.49 +	L << Logger::Debug << "Debug via stream";
   12.50 +	L << Logger::Info      << "Info via stream";
   12.51 +	L << Logger::Notice    << "Notice via stream";
   12.52 +	L << Logger::Warn      << "Warning via stream";
   12.53 +	L << Logger::Error     << "Error via stream";
   12.54 +	L << Logger::Crit      << "Critical via stream";
   12.55 +	L << Logger::Alert     << "Alert via stream";
   12.56 +	L << Logger::Emergency << "Emergency via stream";
   12.57 +}
   12.58 +
   12.59 +TEST_F( LoggerTest, LongLine )
   12.60 +{
   12.61 +	Logger L("LongLine");
   12.62 +	
   12.63 +	char buffer[64];
   12.64 +	double length = 10.0;
   12.65 +	while(length < 4444)
   12.66 +	{
   12.67 +		snprintf(buffer, 63, "Length %d octets: ", int(length));
   12.68 +		L.notice( buffer + longstring(length));
   12.69 +		length *= 1.71;
   12.70 +	}
   12.71 +
   12.72 +}