From 9503cc66f0ca1576f534b6c85d92420c7b1da234 Mon Sep 17 00:00:00 2001 From: Jeff Becker Date: Tue, 16 Apr 2019 09:20:48 -0400 Subject: [PATCH] add disk worker based file flusher logger make format remove package.json --- contrib/node/package.json | 12 ----- llarp/CMakeLists.txt | 1 + llarp/ev/ev.cpp | 3 ++ llarp/ev/ev_sun.hpp | 5 +- llarp/messages/relay_commit.cpp | 2 +- llarp/profiling.cpp | 9 ++-- llarp/profiling.hpp | 8 +-- llarp/router/router.cpp | 23 +++++++++ llarp/router/router.hpp | 5 ++ llarp/service/endpoint.cpp | 9 ++-- llarp/util/android_logger.cpp | 3 +- llarp/util/android_logger.hpp | 7 ++- llarp/util/file_logger.cpp | 89 +++++++++++++++++++++++++++++++++ llarp/util/file_logger.hpp | 61 ++++++++++++++++++++++ llarp/util/logger_syslog.hpp | 4 +- llarp/util/logstream.hpp | 8 ++- llarp/util/ostream_logger.cpp | 2 +- llarp/util/ostream_logger.hpp | 4 +- llarp/util/syslog_logger.cpp | 2 +- llarp/util/threadpool.h | 4 +- llarp/util/win32_logger.hpp | 2 + 21 files changed, 225 insertions(+), 38 deletions(-) delete mode 100644 contrib/node/package.json create mode 100644 llarp/util/file_logger.cpp create mode 100644 llarp/util/file_logger.hpp diff --git a/contrib/node/package.json b/contrib/node/package.json deleted file mode 100644 index bdf30c57c..000000000 --- a/contrib/node/package.json +++ /dev/null @@ -1,12 +0,0 @@ -{ - "name": "lokinet", - "version": "0.0.0", - "description": "lokinet god awful node binding", - "main": "lokinet.js", - "private": true, - "gypfile": true, - "dependencies": { - "bindings": "~1.2.1", - "node-addon-api": "^1.0.0" - } -} \ No newline at end of file diff --git a/llarp/CMakeLists.txt b/llarp/CMakeLists.txt index 567a074c8..7a5cf4692 100644 --- a/llarp/CMakeLists.txt +++ b/llarp/CMakeLists.txt @@ -16,6 +16,7 @@ set(LIB_UTIL_SRC util/json.cpp util/logger.cpp util/android_logger.cpp + util/file_logger.cpp util/ostream_logger.cpp util/syslog_logger.cpp util/win32_logger.cpp diff --git a/llarp/ev/ev.cpp b/llarp/ev/ev.cpp index 1bdef1c07..df8a858d4 100644 --- a/llarp/ev/ev.cpp +++ b/llarp/ev/ev.cpp @@ -54,6 +54,9 @@ llarp_ev_loop_run_single_process(llarp_ev_loop_ptr ev, ev->update_time(); logic->tick_async(ev->time_now()); llarp_threadpool_tick(tp); + // tick log stream at the VERY END of the tick cycle so that all logs + // flush + llarp::LogContext::Instance().logStream->Tick(ev->time_now()); } } } diff --git a/llarp/ev/ev_sun.hpp b/llarp/ev/ev_sun.hpp index 8716e6379..fc0e15b08 100644 --- a/llarp/ev/ev_sun.hpp +++ b/llarp/ev/ev_sun.hpp @@ -78,9 +78,8 @@ namespace llarp }; }; // namespace llarp -struct llarp_poll_loop - : public llarp_ev_loop, - public std::enable_shared_from_this< llarp_poll_loop > +struct llarp_poll_loop : public llarp_ev_loop, + public std::enable_shared_from_this< llarp_poll_loop > { upoll_t* upollfd; diff --git a/llarp/messages/relay_commit.cpp b/llarp/messages/relay_commit.cpp index af1540ced..308c5d54a 100644 --- a/llarp/messages/relay_commit.cpp +++ b/llarp/messages/relay_commit.cpp @@ -281,7 +281,7 @@ namespace llarp using namespace std::placeholders; if(self->record.work && self->record.work->IsValid( - std::bind(&Crypto::shorthash, crypto, _1, _2), now)) + std::bind(&Crypto::shorthash, crypto, _1, _2), now)) { llarp::LogDebug("LRCM extended lifetime by ", self->record.work->extendedLifetime, " seconds for ", diff --git a/llarp/profiling.cpp b/llarp/profiling.cpp index 21370a04a..2b843e76c 100644 --- a/llarp/profiling.cpp +++ b/llarp/profiling.cpp @@ -76,7 +76,8 @@ namespace llarp return (pathSuccessCount * chances) > pathFailCount; } - static bool constexpr checkIsGood(uint64_t fails, uint64_t success, uint64_t chances) + static bool constexpr checkIsGood(uint64_t fails, uint64_t success, + uint64_t chances) { if(fails > 0) return success / fails > chances; @@ -90,7 +91,7 @@ namespace llarp { return checkIsGood(connectTimeoutCount, connectGoodCount, chances); } - + bool RouterProfile::IsGoodForPath(uint64_t chances) const { @@ -98,7 +99,7 @@ namespace llarp } bool - Profiling::IsBadForConnect(const RouterID & r, uint64_t chances) + Profiling::IsBadForConnect(const RouterID& r, uint64_t chances) { lock_t lock(&m_ProfilesMutex); auto itr = m_Profiles.find(r); @@ -108,7 +109,7 @@ namespace llarp } bool - Profiling::IsBadForPath(const RouterID & r, uint64_t chances) + Profiling::IsBadForPath(const RouterID& r, uint64_t chances) { lock_t lock(&m_ProfilesMutex); auto itr = m_Profiles.find(r); diff --git a/llarp/profiling.hpp b/llarp/profiling.hpp index e9d18bd29..e3a33dc0d 100644 --- a/llarp/profiling.hpp +++ b/llarp/profiling.hpp @@ -64,13 +64,13 @@ namespace llarp LOCKS_EXCLUDED(m_ProfilesMutex); /// check if this rotuer should have paths built over it - bool - IsBadForPath(const RouterID & r, uint64_t chances = 8) + bool + IsBadForPath(const RouterID& r, uint64_t chances = 8) LOCK_RETURNED(m_ProfilesMutex); /// check if this router should be connected directly to - bool - IsBadForConnect(const RouterID & r, uint64_t chances = 8) + bool + IsBadForConnect(const RouterID& r, uint64_t chances = 8) LOCKS_EXCLUDED(m_ProfilesMutex); void diff --git a/llarp/router/router.cpp b/llarp/router/router.cpp index 9f7342557..1686b556c 100644 --- a/llarp/router/router.cpp +++ b/llarp/router/router.cpp @@ -14,6 +14,7 @@ #include #include #include +#include #include #include #include @@ -847,6 +848,28 @@ namespace llarp LogContext::Instance().logStream = std::make_unique< SysLogStream >(); #endif } + if(StrEq(key, "file")) + { + LogInfo("open log file: ", val); + FILE *logfile = ::fopen(val, "a"); + if(logfile) + { + LogContext::Instance().logStream = + std::make_unique< FileLogStream >(diskworker(), logfile, 500); + LogInfo("started logging to ", val); + } + else if(errno) + { + LogError("could not open log file at '", val, "': ", strerror(errno)); + errno = 0; + } + else + { + LogError("failed to open log file at '", val, + "' for an unknown reason, bailing tf out kbai"); + ::abort(); + } + } } else if(StrEq(section, "lokid")) { diff --git a/llarp/router/router.hpp b/llarp/router/router.hpp index 9436ecb74..c564ddb9f 100644 --- a/llarp/router/router.hpp +++ b/llarp/router/router.hpp @@ -86,6 +86,11 @@ namespace llarp // path to write our self signed rc to fs::path our_rc_file = "rc.signed"; + // use file based logging? + bool m_UseFileLogging = false; + // default log file path + fs::path logfile = "lokinet.log"; + // our router contact RouterContact _rc; diff --git a/llarp/service/endpoint.cpp b/llarp/service/endpoint.cpp index 609461750..0d38128d7 100644 --- a/llarp/service/endpoint.cpp +++ b/llarp/service/endpoint.cpp @@ -1460,11 +1460,12 @@ namespace llarp size_t tries = 5; do { - nodedb->select_random_hop_excluding(hops[hop], {hops[hop - 1].pubkey, remote}); + nodedb->select_random_hop_excluding(hops[hop], + {hops[hop - 1].pubkey, remote}); --tries; - } while( - m_Endpoint->Router()->routerProfiling().IsBadForPath(hops[hop].pubkey) - && tries > 0); + } while(m_Endpoint->Router()->routerProfiling().IsBadForPath( + hops[hop].pubkey) + && tries > 0); return tries > 0; } return false; diff --git a/llarp/util/android_logger.cpp b/llarp/util/android_logger.cpp index 5302ecc98..20c9a26d1 100644 --- a/llarp/util/android_logger.cpp +++ b/llarp/util/android_logger.cpp @@ -36,8 +36,7 @@ namespace llarp } void - AndroidLogStream::Print(LogLevel lvl, const char* tag, - const std::string& msg) const + AndroidLogStream::Print(LogLevel lvl, const char* tag, const std::string& msg) { std::string str("lokinet|"); str += tag; diff --git a/llarp/util/android_logger.hpp b/llarp/util/android_logger.hpp index 838cb5bb8..71bfe7350 100644 --- a/llarp/util/android_logger.hpp +++ b/llarp/util/android_logger.hpp @@ -13,7 +13,12 @@ namespace llarp int lineno) const override; void - Log(LogLevel lvl, const std::string& msg) const override; + Log(LogLevel lvl, const std::string& msg) override; + + void + PostLog(std::stringstream&) const override{}; + + void Tick(llarp_time_t) override; }; } // namespace llarp diff --git a/llarp/util/file_logger.cpp b/llarp/util/file_logger.cpp new file mode 100644 index 000000000..d73bd8bb4 --- /dev/null +++ b/llarp/util/file_logger.cpp @@ -0,0 +1,89 @@ +#include +#include + +namespace llarp +{ + FileLogStream::FileLogStream(llarp_threadpool *disk, FILE *f, + llarp_time_t flushInterval) + : m_Disk(disk), m_File(f), m_FlushInterval(flushInterval) + { + } + + FileLogStream::~FileLogStream() + { + fflush(m_File); + fclose(m_File); + } + + bool + FileLogStream::ShouldFlush(llarp_time_t now) const + { + if(m_LastFlush >= now) + return false; + const auto dlt = now - m_LastFlush; + return dlt >= m_FlushInterval; + } + + void + FileLogStream::PreLog(std::stringstream &ss, LogLevel lvl, const char *fname, + int lineno) const + { + switch(lvl) + { + case eLogNone: + break; + case eLogDebug: + ss << "[DBG] "; + break; + case eLogInfo: + ss << "[NFO] "; + break; + case eLogWarn: + + ss << "[WRN] "; + break; + case eLogError: + ss << "[ERR] "; + break; + } + ss << "(" << thread_id_string() << ") " << log_timestamp() << " " << fname + << ":" << lineno << "\t"; + } + + void + FileLogStream::Print(LogLevel, const char *, const std::string &msg) + { + m_Lines.emplace_back(msg); + } + + void + FileLogStream::Tick(llarp_time_t now) + { + if(ShouldFlush(now)) + FlushLinesToDisk(now); + } + + void + FileLogStream::FlushLinesToDisk(llarp_time_t now) + { + FlushEvent *ev = new FlushEvent(std::move(m_Lines), m_File); + llarp_threadpool_queue_job(m_Disk, {ev, &FlushEvent::HandleFlush}); + m_LastFlush = now; + } + + void + FileLogStream::FlushEvent::HandleFlush(void *user) + { + static_cast< FileLogStream::FlushEvent * >(user)->Flush(); + } + + void + FileLogStream::FlushEvent::Flush() + { + for(const auto &line : lines) + fprintf(f, "%s\n", line.c_str()); + fflush(f); + delete this; + } + +} // namespace llarp \ No newline at end of file diff --git a/llarp/util/file_logger.hpp b/llarp/util/file_logger.hpp new file mode 100644 index 000000000..fd9a4a338 --- /dev/null +++ b/llarp/util/file_logger.hpp @@ -0,0 +1,61 @@ +#ifndef LLARP_UTIL_FILE_LOGGER_HPP +#define LLARP_UTIL_FILE_LOGGER_HPP + +#include +#include +#include + +namespace llarp +{ + /// fluhsable file based log stream + struct FileLogStream : public ILogStream + { + FileLogStream(llarp_threadpool* disk, FILE* f, llarp_time_t flushInterval); + + ~FileLogStream(); + + void + PreLog(std::stringstream& out, LogLevel lvl, const char* fname, + int lineno) const override; + + void + Print(LogLevel, const char*, const std::string& msg) override; + + void + Tick(llarp_time_t now) override; + + void + PostLog(std::stringstream&) const override{}; + + private: + struct FlushEvent + { + FlushEvent(std::deque< std::string > l, FILE* file) + : lines(std::move(l)), f(file) + { + } + + const std::deque< std::string > lines; + FILE* const f; + + void + Flush(); + static void + HandleFlush(void*); + }; + + bool + ShouldFlush(llarp_time_t now) const; + + void + FlushLinesToDisk(llarp_time_t now); + + llarp_threadpool* m_Disk; + FILE* m_File; + const llarp_time_t m_FlushInterval; + llarp_time_t m_LastFlush = 0; + std::deque< std::string > m_Lines; + }; +} // namespace llarp + +#endif \ No newline at end of file diff --git a/llarp/util/logger_syslog.hpp b/llarp/util/logger_syslog.hpp index 7f52cfac4..5b236cda9 100644 --- a/llarp/util/logger_syslog.hpp +++ b/llarp/util/logger_syslog.hpp @@ -12,10 +12,12 @@ namespace llarp int lineno) const override; void - Print(LogLevel lvl, const char* tag, const std::string& msg) const override; + Print(LogLevel lvl, const char* tag, const std::string& msg) override; void PostLog(std::stringstream& ss) const override; + + void Tick(llarp_time_t) override{}; }; } // namespace llarp #endif diff --git a/llarp/util/logstream.hpp b/llarp/util/logstream.hpp index 898ae487d..1ca183fd2 100644 --- a/llarp/util/logstream.hpp +++ b/llarp/util/logstream.hpp @@ -4,6 +4,8 @@ #include #include #include +#include + namespace llarp { /// logger stream interface @@ -15,10 +17,14 @@ namespace llarp PreLog(std::stringstream& out, LogLevel lvl, const char* fname, int lineno) const = 0; virtual void - Print(LogLevel lvl, const char* filename, const std::string& msg) const = 0; + Print(LogLevel lvl, const char* filename, const std::string& msg) = 0; virtual void PostLog(std::stringstream& out) const = 0; + + /// called every end of event loop tick + virtual void + Tick(llarp_time_t now) = 0; }; using ILogStream_ptr = std::unique_ptr< ILogStream >; diff --git a/llarp/util/ostream_logger.cpp b/llarp/util/ostream_logger.cpp index c98eb07ac..9abdcb10e 100644 --- a/llarp/util/ostream_logger.cpp +++ b/llarp/util/ostream_logger.cpp @@ -44,7 +44,7 @@ namespace llarp } void - OStreamLogStream::Print(LogLevel, const char*, const std::string& msg) const + OStreamLogStream::Print(LogLevel, const char*, const std::string& msg) { m_Out << msg; } diff --git a/llarp/util/ostream_logger.hpp b/llarp/util/ostream_logger.hpp index 0ba91d172..4937b4a52 100644 --- a/llarp/util/ostream_logger.hpp +++ b/llarp/util/ostream_logger.hpp @@ -19,11 +19,13 @@ namespace llarp int lineno) const override; void - Print(LogLevel lvl, const char* tag, const std::string& msg) const override; + Print(LogLevel lvl, const char* tag, const std::string& msg) override; virtual void PostLog(std::stringstream& ss) const override; + void Tick(llarp_time_t) override{}; + private: std::ostream& m_Out; }; diff --git a/llarp/util/syslog_logger.cpp b/llarp/util/syslog_logger.cpp index 1db55b6ef..e15ad853c 100644 --- a/llarp/util/syslog_logger.cpp +++ b/llarp/util/syslog_logger.cpp @@ -31,7 +31,7 @@ namespace llarp } void - SysLogStream::Print(LogLevel lvl, const char*, const std::string& msg) const + SysLogStream::Print(LogLevel lvl, const char*, const std::string& msg) { switch(lvl) { diff --git a/llarp/util/threadpool.h b/llarp/util/threadpool.h index b425890ee..463ef0994 100644 --- a/llarp/util/threadpool.h +++ b/llarp/util/threadpool.h @@ -16,8 +16,8 @@ struct llarp_threadpool std::queue< std::function< void(void) > > jobs GUARDED_BY(m_access); llarp_threadpool(int workers, const char *name) - : impl( - std::make_unique< llarp::thread::ThreadPool >(workers, workers * 128)) + : impl(std::make_unique< llarp::thread::ThreadPool >(workers, + workers * 128)) { (void)name; } diff --git a/llarp/util/win32_logger.hpp b/llarp/util/win32_logger.hpp index 6b902bef9..c3214193b 100644 --- a/llarp/util/win32_logger.hpp +++ b/llarp/util/win32_logger.hpp @@ -18,6 +18,8 @@ namespace llarp void PostLog(std::stringstream& s) const override; + void Tick(llarp_time_t) override{}; + bool isConsoleModern = true; // qol fix so oldfag clients don't see ugly escapes HANDLE fd1 = GetStdHandle(STD_OUTPUT_HANDLE);