From 80dacb895e9d5e3ea6efe1b309a33f426935daf4 Mon Sep 17 00:00:00 2001 From: Michael Davidsaver Date: Sat, 1 Feb 2020 12:56:33 -0800 Subject: [PATCH] log show time --- src/evhelper.cpp | 2 +- src/log.cpp | 41 ++++++++++++++++++++++++++++++++++++++--- src/pvxs/log.h | 23 ++++++++++++++++++----- src/server.cpp | 16 ++++++++-------- test/countdown.cpp | 2 +- test/mcat.cpp | 2 +- tools/pvxvct.cpp | 6 +++--- 7 files changed, 70 insertions(+), 22 deletions(-) diff --git a/src/evhelper.cpp b/src/evhelper.cpp index 8865c45..3f8dd90 100644 --- a/src/evhelper.cpp +++ b/src/evhelper.cpp @@ -258,7 +258,7 @@ void evsocket::bind(SockAddr& addr) const socklen_t slen = addr.size(); ret = getsockname(sock, &addr->sa, &slen); if(ret) - log_printf(logerr, Err, "Unable to fetch address of newly bound socket\n"); + log_printf(logerr, Err, "Unable to fetch address of newly bound socket\n%s", ""); } void evsocket::mcast_join(const SockAddr& grp, const SockAddr& iface) const diff --git a/src/log.cpp b/src/log.cpp index 758f078..9e1e108 100644 --- a/src/log.cpp +++ b/src/log.cpp @@ -23,6 +23,7 @@ #include #include #include +#include #include "evhelper.h" #include "utilpvt.h" @@ -31,11 +32,43 @@ typedef epicsGuard Guard; namespace pvxs { -namespace { - DEFINE_LOGGER(logerr, "pvxs.ev"); -epicsThreadOnceId logger_once = EPICS_THREAD_ONCE_INIT; +namespace detail { + +const char* log_prefix(const char* name, Level lvl) +{ + static thread_local char prefix[64]; + // YYYY-mm-ddTHH:MM:SS.FffFffFff + + epicsTimeStamp now; + size_t N; + if(epicsTimeGetCurrent(&now)) { + strcpy(prefix, ""); + N = strlen(prefix); + + } else { + N = epicsTimeToStrftime(prefix, sizeof(prefix), "%Y-%m-%dT%H:%M:%S.%9f", &now); + } + + const char *lname; + switch(lvl) { + case Level::Crit: lname = "CRIT"; break; + case Level::Err: lname = "ERR"; break; + case Level::Warn: lname = "WARN"; break; + case Level::Info: lname = "INFO"; break; + case Level::Debug: lname = "DEBUG"; break; + default: lname = "<\?\?\?>"; break; + } + + epicsSnprintf(prefix+N, sizeof(prefix)-N, " %s %s", lname, name); + + return prefix; +} + +} // namespace detail + +namespace { void evlog_handler(int severity, const char *msg) { @@ -153,6 +186,8 @@ void logger_prepare(void *unused) logger_gbl = new logger_gbl_t; } +epicsThreadOnceId logger_once = EPICS_THREAD_ONCE_INIT; + } // namespace int logger::init() diff --git a/src/pvxs/log.h b/src/pvxs/log.h index a74302d..c73682a 100644 --- a/src/pvxs/log.h +++ b/src/pvxs/log.h @@ -49,6 +49,13 @@ public: } }; +namespace detail { + +PVXS_API +const char* log_prefix(const char* name, Level lvl); + +} // namespace detail + //! Define a new logger global. //! @param VAR The (static) variable name passed to log_printf() and friends. //! @param NAME A name string in "A.B.C" form. @@ -63,14 +70,20 @@ void xerrlogHexPrintf(const void *buf, size_t buflen); //! void blahfn(int x) { //! log_printf(blah, Info, "blah happened with %d\n", x); //! @endcode -#define log_printf(LOGGER, LVL, ...) do{ if((LOGGER).test(::pvxs::Level::LVL)) errlogPrintf(__VA_ARGS__); }while(0) +#define log_printf(LOGGER, LVL, FMT, ...) do{ \ + if((LOGGER).test(::pvxs::Level::LVL)) \ + errlogPrintf("%s " FMT, ::pvxs::detail::log_prefix((LOGGER).name, ::pvxs::Level::LVL), __VA_ARGS__); \ +}while(0) -//! log_vprintf() is to log_printf() what vprintf() is to printf() -#define log_vprintf(LOGGER, LVL, FMT, ARGS) do{ if((LOGGER).test(::pvxs::Level::LVL)) errlogVprintf(FMT, ARGS); }while(0) +#define log_crit_printf(LOGGER, ...) log_printf(LOGGER, Debug, __VA_ARGS__) +#define log_err_printf(LOGGER, ...) log_printf(LOGGER, Debug, __VA_ARGS__) +#define log_warn_printf(LOGGER, ...) log_printf(LOGGER, Debug, __VA_ARGS__) +#define log_info_printf(LOGGER, ...) log_printf(LOGGER, Debug, __VA_ARGS__) +#define log_debug_printf(LOGGER, ...) log_printf(LOGGER, Debug, __VA_ARGS__) -#define log_hex_printf(LOGGER, LVL, BUF, BUFLEN, ...) do{ if((LOGGER).test(::pvxs::Level::LVL)) { \ +#define log_hex_printf(LOGGER, LVL, BUF, BUFLEN, FMT, ...) do{ if((LOGGER).test(::pvxs::Level::LVL)) { \ xerrlogHexPrintf(BUF, BUFLEN); \ - errlogPrintf(__VA_ARGS__); } \ + errlogPrintf("%s " FMT, ::pvxs::detail::log_prefix((LOGGER).name, ::pvxs::Level::LVL), __VA_ARGS__); } \ }while(0) //! Set level for a specific logger diff --git a/src/server.cpp b/src/server.cpp index f58af49..6ad06bd 100644 --- a/src/server.cpp +++ b/src/server.cpp @@ -425,7 +425,7 @@ Server::Pvt::~Pvt() void Server::Pvt::start() { - log_printf(serversetup, Debug, "Server Starting\n"); + log_printf(serversetup, Debug, "Server Starting\n%s", ""); // begin accepting connections state_t prev_state; @@ -438,7 +438,7 @@ void Server::Pvt::start() return; } state = Starting; - log_printf(serversetup, Debug, "Server starting\n"); + log_printf(serversetup, Debug, "Server starting\n%s", ""); for(auto& iface : interfaces) { if(evconnlistener_enable(iface.listener.get())) { @@ -460,7 +460,7 @@ void Server::Pvt::start() { // send first beacon immediately if(event_add(beaconTimer.get(), nullptr)) - log_printf(serversetup, Err, "Error enabling beacon timer on\n"); + log_printf(serversetup, Err, "Error enabling beacon timer on\n%s", ""); state = Running; }); @@ -470,7 +470,7 @@ void Server::Pvt::start() void Server::Pvt::stop() { - log_printf(serversetup, Debug, "Server Stopping\n"); + log_printf(serversetup, Debug, "Server Stopping\n%s", ""); // Stop sending Beacons state_t prev_state; @@ -484,7 +484,7 @@ void Server::Pvt::stop() state = Stopping; if(event_del(beaconTimer.get())) - log_printf(serversetup, Err, "Error disabling beacon timer on\n"); + log_printf(serversetup, Err, "Error disabling beacon timer on\n%s", ""); }); if(prev_state!=Running) return; @@ -566,7 +566,7 @@ void Server::Pvt::onSearch(const UDPManager::Search& msg) to_wire(H, Header{CMD_SEARCH_RESPONSE, pva_flags::Server, uint32_t(pktlen-8)}); if(!M.good() || !H.good()) { - log_printf(serverio, Crit, "Logic error in Search buffer fill\n"); + log_printf(serverio, Crit, "Logic error in Search buffer fill\n%s", ""); } else { (void)msg.reply(searchReply.data(), pktlen); } @@ -574,7 +574,7 @@ void Server::Pvt::onSearch(const UDPManager::Search& msg) void Server::Pvt::doBeacons(short evt) { - log_printf(serversetup, Debug, "Server beacon timer expires\n"); + log_printf(serversetup, Debug, "Server beacon timer expires\n%s", ""); VectorOutBuf M(true, beaconMsg); M.skip(8); // fill in header after body length known @@ -611,7 +611,7 @@ void Server::Pvt::doBeacons(short evt) timeval interval = {15, 0}; if(event_add(beaconTimer.get(), &interval)) - log_printf(serversetup, Err, "Error re-enabling beacon timer on\n"); + log_printf(serversetup, Err, "Error re-enabling beacon timer on\n%s", ""); } void Server::Pvt::doBeaconsS(evutil_socket_t fd, short evt, void *raw) diff --git a/test/countdown.cpp b/test/countdown.cpp index 712d95a..8ceb182 100644 --- a/test/countdown.cpp +++ b/test/countdown.cpp @@ -128,7 +128,7 @@ int main(int argc, char *argv[]) std::cout<<" "<