From fecdd52e707187e21e97a1b867de5ecd8ed49c20 Mon Sep 17 00:00:00 2001 From: Michael Davidsaver Date: Thu, 19 Dec 2019 17:47:21 -0800 Subject: [PATCH] update logging --- src/evhelper.cpp | 25 ++++----- src/log.cpp | 112 +++++++++++++++++++++++++++------------ src/pvxs/log.h | 45 +++++++++------- src/server.cpp | 40 +++++++------- src/serverchan.cpp | 20 +++---- src/serverconn.cpp | 70 ++++++++++++------------ src/serverget.cpp | 24 ++++----- src/serverintrospect.cpp | 4 +- src/serversource.cpp | 4 +- src/udp_collector.cpp | 22 ++++---- test/dummyserv.cpp | 16 +++--- tools/pvxvct.cpp | 24 ++++----- 12 files changed, 229 insertions(+), 177 deletions(-) diff --git a/src/evhelper.cpp b/src/evhelper.cpp index 753ecab..477bc33 100644 --- a/src/evhelper.cpp +++ b/src/evhelper.cpp @@ -26,7 +26,7 @@ namespace pvxs {namespace impl { -DEFINE_LOGGER(logerr, "evloop"); +DEFINE_LOGGER(logerr, "pvxs.loop"); struct evbase::Pvt : public epicsThreadRunable { @@ -53,18 +53,19 @@ struct evbase::Pvt : public epicsThreadRunable virtual ~Pvt() { if(event_base_loopexit(base, nullptr)) - log_printf(logerr, PLVL_CRIT, "evbase error while interrupting loop for %p\n", base); + log_printf(logerr, Crit, "evbase error while interrupting loop for %p\n", base); worker.exitWait(); event_base_free(base); } virtual void run() override final { - log_printf(logerr, PLVL_INFO, "Enter loop worker for %p\n", base); + log_printf(logerr, Info, "Enter loop worker for %p\n", base); int ret = event_base_loop(base, EVLOOP_NO_EXIT_ON_EMPTY); - log_printf(logerr, ret ? PLVL_CRIT : PLVL_INFO, "Exit loop worker: %d for %p\n", ret, base); + if(logerr.test(int(ret ? Level::Crit : Level::Info))) + errlogPrintf("Exit loop worker: %d for %p\n", ret, base); } }; @@ -80,7 +81,7 @@ evbase::evbase(const std::string &name, unsigned prio) throw std::runtime_error("evthread_make_base_notifiable() fails"); } pvt->base = base; - log_printf(logerr, PLVL_INFO, "Starting loop worker for %p\n", base); + log_printf(logerr, Info, "Starting loop worker for %p\n", base); pvt->worker.start(); } @@ -114,7 +115,7 @@ void dispatch_action(evutil_socket_t _fd, short _ev, void *raw) std::unique_ptr > action(reinterpret_cast*>(raw)); (*action)(); }catch(std::exception& e){ - log_printf(logerr, PLVL_CRIT, "evhelper::call unhandled error %s : %s\n", typeid(&e).name(), e.what()); + log_printf(logerr, Crit, "evhelper::call unhandled error %s : %s\n", typeid(&e).name(), e.what()); } } } @@ -150,7 +151,7 @@ void call_action(evutil_socket_t _fd, short _ev, void *raw) } args->wait.signal(); }catch(std::exception& e){ - log_printf(logerr, PLVL_CRIT, "evhelper::call unhandled error: %s\n", e.what()); + log_printf(logerr, Crit, "evhelper::call unhandled error: %s\n", e.what()); args->wait.signal(); } } @@ -236,7 +237,7 @@ void evsocket::bind(SockAddr& addr) const socklen_t slen = addr.size(); ret = getsockname(sock, &addr->sa, &slen); if(ret) - log_printf(logerr, PLVL_ERR, "Unable to fetch address of newly bound socket\n"); + log_printf(logerr, Err, "Unable to fetch address of newly bound socket\n"); } void evsocket::mcast_join(const SockAddr& grp, const SockAddr& iface) const @@ -250,7 +251,7 @@ void evsocket::mcast_join(const SockAddr& grp, const SockAddr& iface) const int ret = setsockopt(sock, IPPROTO_IP, IP_ADD_MEMBERSHIP, (char*)&req, sizeof(req)); if(ret) - log_printf(logerr, PLVL_ERR, "Unable to join mcast group %s on %s : %s\n", + log_printf(logerr, Err, "Unable to join mcast group %s on %s : %s\n", grp.tostring().c_str(), iface.tostring().c_str(), evutil_socket_error_to_string(evutil_socket_geterror(sock))); @@ -261,7 +262,7 @@ void evsocket::mcast_ttl(unsigned ttl) const { int ret = setsockopt(sock, IPPROTO_IP, IP_MULTICAST_TTL, (char*)&ttl, sizeof(ttl)); if(ret) - log_printf(logerr, PLVL_ERR, "Unable to set mcast TTL : %s\n", + log_printf(logerr, Err, "Unable to set mcast TTL : %s\n", evutil_socket_error_to_string(evutil_socket_geterror(sock))); // ipv6 variant? @@ -272,7 +273,7 @@ void evsocket::mcast_loop(bool loop) const unsigned char val = loop ? 1 : 0; int ret = setsockopt(sock, IPPROTO_IP, IP_MULTICAST_LOOP, (char*)&val, sizeof(val)); if(ret) - log_printf(logerr, PLVL_ERR, "Unable to set mcast loopback : %s\n", + log_printf(logerr, Err, "Unable to set mcast loopback : %s\n", evutil_socket_error_to_string(evutil_socket_geterror(sock))); // IPV6_MULTICAST_LOOP @@ -285,7 +286,7 @@ void evsocket::mcast_iface(const SockAddr& iface) const int ret = setsockopt(sock, IPPROTO_IP, IP_MULTICAST_IF, (char*)&iface->in.sin_addr, sizeof(iface->in.sin_addr)); if(ret) - log_printf(logerr, PLVL_ERR, "Unable to set mcast TTL : %s\n", + log_printf(logerr, Err, "Unable to set mcast TTL : %s\n", evutil_socket_error_to_string(evutil_socket_geterror(sock))); // IPV6_MULTICAST_IF diff --git a/src/log.cpp b/src/log.cpp index 27a6a47..8f411f9 100644 --- a/src/log.cpp +++ b/src/log.cpp @@ -5,8 +5,10 @@ */ #include -#include +#include #include +#include +#include // must include before epicsStdio.h to avoid clash with printf macro #include @@ -30,41 +32,42 @@ typedef epicsGuard Guard; namespace { using namespace pvxs; -DEFINE_LOGGER(logerr, "evlog"); +DEFINE_LOGGER(logerr, "pvxs.ev"); epicsThreadOnceId logger_once = EPICS_THREAD_ONCE_INIT; void evlog_handler(int severity, const char *msg) { const char *sevr = "<\?\?\?>"; - int lvl = PLVL_CRIT; + Level lvl = Level::Crit; switch(severity) { -#define CASE(EVLVL, PLVL) case EVENT_LOG_##EVLVL : lvl = PLVL_##PLVL; sevr = #PLVL; break - CASE(DEBUG, DEBUG); - CASE(MSG, INFO); - CASE(WARN, WARN); - CASE(ERR, ERR); +#define CASE(EVLVL, PLVL) case EVENT_LOG_##EVLVL : lvl = Level::PLVL; sevr = #PLVL; break + CASE(DEBUG, Debug); + CASE(MSG, Info); + CASE(WARN, Warn); + CASE(ERR, Err); #undef CASE } - log_printf(logerr, lvl, "libevent %s: %s\n", sevr, msg); + if(logerr.test(lvl)) + errlogPrintf("libevent %s: %s\n", sevr, msg); } int name2lvl(const std::string& name) { -#define CASE(LVL) if(name==#LVL) return PLVL_##LVL - CASE(DEBUG); - CASE(INFO); - CASE(WARN); - CASE(ERR); - CASE(CRIT); +#define CASE(LVL, Lvl) if(name==#LVL) return int(Level::Lvl) + CASE(DEBUG, Debug); + CASE(INFO, Info); + CASE(WARN, Warn); + CASE(ERR, Err); + CASE(CRIT, Crit); #undef CASE return 0; } struct logger_gbl_t { epicsMutex lock; - std::map config; + std::list> config; std::multimap loggers; logger_gbl_t() @@ -76,15 +79,30 @@ struct logger_gbl_t { { std::string name(logger->name); - loggers.emplace(name, logger); + int lvl = int(Level::Err); - auto it = config.find(name); - if(it!=config.end()) { - logger->lvl.store(it->second, std::memory_order_relaxed); - return it->second; + // see if this logger name has already been configured. + auto it = loggers.find(logger->name); + if(it!=loggers.end()) { + lvl = it->second->lvl.load(std::memory_order_relaxed); + + } else { + // nope + + for(auto& tup : config) { + if(std::regex_match(name, std::get<0>(tup))) { + lvl = std::get<2>(tup); + break; + } + } } - return PLVL_ERR; + + loggers.emplace(name, logger); + + logger->lvl.store(lvl, std::memory_order_relaxed); + + return lvl; } void set(const char *name, int lvl) @@ -92,14 +110,38 @@ struct logger_gbl_t { if(lvl<=0) lvl = 1; - // update config for loggers added later - config[name] = lvl; - - // apply to existing loggers - auto iters = loggers.equal_range(name); - for(; iters.first!=iters.second; ++iters.first) { - iters.first->second->lvl.store(lvl, std::memory_order_relaxed); + // convert name, with wildcards to a regexp + std::string exp("^"); + for(char c = *name; c!='\0'; c=*++name) { + if((c>='a' && c<='z') || (c>='A' && c<='Z') || (c>='0' && c<='9') || c=='_') + exp += c; + else if(c=='.') + exp += "\\."; + else if(c=='?') + exp += '.'; + else if(c=='*') + exp += ".*"; } + exp+='$'; + + for(auto& tup : config) { + if(std::get<1>(tup)==exp) { + // update of existing config + if(std::get<2>(tup)!=lvl) { + for(auto& pair : loggers) { + if(std::regex_match(pair.first, std::get<0>(tup))) { + pair.second->lvl.store(lvl, std::memory_order_relaxed); + } + } + } + return; + } + } + // new config + + std::regex re(exp); + + config.emplace_back(std::move(re), exp, lvl); } } *logger_gbl; @@ -112,21 +154,21 @@ void logger_prepare(void *unused) namespace pvxs { -int logger_init(logger *logger) +int logger::init() { - assert(logger->name); + assert(name); - int lvl = logger->lvl.load(); + int lvl = this->lvl.load(); if(lvl==-1) { // maybe we initialize - if(logger->lvl.compare_exchange_strong(lvl, PLVL_ERR)) { - // logger now has default config of PLVL_ERR + if(this->lvl.compare_exchange_strong(lvl, int(Level::Err))) { + // logger now has default config of Level::Err // we will fully initialize epicsThreadOnce(&logger_once, &logger_prepare, nullptr); assert(logger_gbl); Guard G(logger_gbl->lock); - lvl = logger_gbl->init(logger); + lvl = logger_gbl->init(this); } } return lvl; diff --git a/src/pvxs/log.h b/src/pvxs/log.h index ec123b6..e628b39 100644 --- a/src/pvxs/log.h +++ b/src/pvxs/log.h @@ -17,37 +17,41 @@ namespace pvxs { -#define PLVL_DEBUG 50 -#define PLVL_INFO 40 -#define PLVL_WARN 30 -#define PLVL_ERR 20 -#define PLVL_CRIT 10 +enum struct Level { + Debug = 50, + Info = 40, + Warn = 30, + Err = 20, + Crit = 10, +}; struct logger { const char *name; // atomic using epicsAtomic (std::atomic<> may not be statically initializable) std::atomic lvl; + constexpr logger(const char *name) :name(name), lvl{-1} {} + +private: + PVXS_API int init(); +public: + + inline bool test(int lvl) { + int cur = this->lvl.load(std::memory_order_relaxed); + if(cur==-1) cur = init(); + return cur>=lvl; + } + inline bool test(Level lvl) { + return test(int(lvl)); + } }; -#define LOGGER_INIT(NAME) {NAME, {-1}} - -#define DEFINE_LOGGER(VAR, NAME) static ::pvxs::logger VAR = LOGGER_INIT(NAME) - -PVXS_API int logger_init(logger *logger); - -static inline -bool _log_test(logger& logger, int lvl) -{ - int cur = logger.lvl.load(std::memory_order_relaxed); - if(cur==-1) cur = logger_init(&logger); - return cur>=lvl; -} +#define DEFINE_LOGGER(VAR, NAME) static ::pvxs::logger VAR{NAME} PVXS_API void xerrlogHexPrintf(const void *buf, size_t buflen, const char *fmt, ...) EPICS_PRINTF_STYLE(3,4); -#define log_test(LOGGER, LVL) ::pvxs::_log_test(LOGGER, LVL) +#define log_test(LOGGER, LVL) (LOGGER).test(::pvxs::Level::LVL) #define log_printf(LOGGER, LVL, ...) do{ if(log_test(LOGGER, LVL)) errlogPrintf(__VA_ARGS__); }while(0) @@ -57,6 +61,9 @@ void xerrlogHexPrintf(const void *buf, size_t buflen, //! Set level for a specific logger PVXS_API void logger_level_set(const char *name, int lvl); +inline void logger_level_set(const char *name, Level lvl) { + logger_level_set(name, int(lvl)); +} /** Configure logging from environment variable $PVXS_LOG * diff --git a/src/server.cpp b/src/server.cpp index 60da784..9ca7a0e 100644 --- a/src/server.cpp +++ b/src/server.cpp @@ -38,8 +38,8 @@ namespace pvxs { namespace server { using namespace impl; -DEFINE_LOGGER(serversetup, "server.setup"); -DEFINE_LOGGER(serverio, "server.io"); +DEFINE_LOGGER(serversetup, "pvxs.server.setup"); +DEFINE_LOGGER(serverio, "pvxs.server.io"); namespace { void split_into(std::vector& out, const char *inp) @@ -424,7 +424,7 @@ Server::Pvt::~Pvt() void Server::Pvt::start() { - log_printf(serversetup, PLVL_DEBUG, "Server Starting\n"); + log_printf(serversetup, Debug, "Server Starting\n"); // begin accepting connections state_t prev_state; @@ -433,17 +433,17 @@ void Server::Pvt::start() prev_state = state; if(state!=Stopped) { // already running - log_printf(serversetup, PLVL_DEBUG, "Server not stopped %d\n", state); + log_printf(serversetup, Debug, "Server not stopped %d\n", state); return; } state = Starting; - log_printf(serversetup, PLVL_DEBUG, "Server starting\n"); + log_printf(serversetup, Debug, "Server starting\n"); for(auto& iface : interfaces) { if(evconnlistener_enable(iface.listener.get())) { - log_printf(serversetup, PLVL_ERR, "Error enabling listener on %s\n", iface.name.c_str()); + log_printf(serversetup, Err, "Error enabling listener on %s\n", iface.name.c_str()); } - log_printf(serversetup, PLVL_DEBUG, "Server enabled listener on %s\n", iface.name.c_str()); + log_printf(serversetup, Debug, "Server enabled listener on %s\n", iface.name.c_str()); } }); if(prev_state!=Stopped) @@ -459,7 +459,7 @@ void Server::Pvt::start() { // send first beacon immediately if(event_add(beaconTimer.get(), nullptr)) - log_printf(serversetup, PLVL_ERR, "Error enabling beacon timer on\n"); + log_printf(serversetup, Err, "Error enabling beacon timer on\n"); state = Running; }); @@ -469,7 +469,7 @@ void Server::Pvt::start() void Server::Pvt::stop() { - log_printf(serversetup, PLVL_DEBUG, "Server Stopping\n"); + log_printf(serversetup, Debug, "Server Stopping\n"); // Stop sending Beacons state_t prev_state; @@ -477,13 +477,13 @@ void Server::Pvt::stop() { prev_state = state; if(state!=Running) { - log_printf(serversetup, PLVL_DEBUG, "Server not running %d\n", state); + log_printf(serversetup, Debug, "Server not running %d\n", state); return; } state = Stopping; if(event_del(beaconTimer.get())) - log_printf(serversetup, PLVL_ERR, "Error disabling beacon timer on\n"); + log_printf(serversetup, Err, "Error disabling beacon timer on\n"); }); if(prev_state!=Running) return; @@ -498,9 +498,9 @@ void Server::Pvt::stop() { for(auto& iface : interfaces) { if(evconnlistener_disable(iface.listener.get())) { - log_printf(serversetup, PLVL_ERR, "Error disabling listener on %s\n", iface.name.c_str()); + log_printf(serversetup, Err, "Error disabling listener on %s\n", iface.name.c_str()); } - log_printf(serversetup, PLVL_DEBUG, "Server disabled listener on %s\n", iface.name.c_str()); + log_printf(serversetup, Debug, "Server disabled listener on %s\n", iface.name.c_str()); } state = Stopped; @@ -523,7 +523,7 @@ void Server::Pvt::onSearch(const UDPManager::Search& msg) try { pair.second->onSearch(searchOp); }catch(std::exception& e){ - log_printf(serversetup, PLVL_ERR, "Unhandled error in Source::onSearch for '%s' : %s\n", + log_printf(serversetup, Err, "Unhandled error in Source::onSearch for '%s' : %s\n", pair.first.second.c_str(), e.what()); } } @@ -563,7 +563,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, PLVL_CRIT, "Logic error in Search buffer fill\n"); + log_printf(serverio, Crit, "Logic error in Search buffer fill\n"); } else { (void)msg.reply(searchReply.data(), pktlen); } @@ -571,7 +571,7 @@ void Server::Pvt::onSearch(const UDPManager::Search& msg) void Server::Pvt::doBeacons(short evt) { - log_printf(serversetup, PLVL_DEBUG, "Server beacon timer expires\n"); + log_printf(serversetup, Debug, "Server beacon timer expires\n"); VectorOutBuf M(true, beaconMsg); M.skip(8); // fill in header after body length known @@ -598,17 +598,17 @@ void Server::Pvt::doBeacons(short evt) if(ntx<0) { int err = evutil_socket_geterror(beaconSender.sock); - log_printf(serverio, PLVL_WARN, "Beacon tx error (%d) %s\n", + log_printf(serverio, Warn, "Beacon tx error (%d) %s\n", err, evutil_socket_error_to_string(err)); } else if(unsigned(ntx)(raw)->doBeacons(evt); }catch(std::exception& e){ - log_printf(serverio, PLVL_CRIT, "Unhandled error in beacon timer callback: %s\n", e.what()); + log_printf(serverio, Crit, "Unhandled error in beacon timer callback: %s\n", e.what()); } } diff --git a/src/serverchan.cpp b/src/serverchan.cpp index bb33750..7e5d00b 100644 --- a/src/serverchan.cpp +++ b/src/serverchan.cpp @@ -13,11 +13,11 @@ namespace pvxs {namespace impl { // message related to client state and errors -DEFINE_LOGGER(connsetup, "tcp.setup"); +DEFINE_LOGGER(connsetup, "pvxs.tcp.setup"); // related to low level send/recv -DEFINE_LOGGER(connio, "tcp.io"); +DEFINE_LOGGER(connio, "pvxs.tcp.io"); -DEFINE_LOGGER(serversetup, "server.setup"); +DEFINE_LOGGER(serversetup, "pvxs.server.setup"); ServerChan::ServerChan(const std::shared_ptr &conn, uint32_t sid, @@ -196,7 +196,7 @@ void ServerConn::handle_SEARCH() try { pair.second->onSearch(op); }catch(std::exception& e){ - log_printf(serversetup, PLVL_ERR, "Unhandled error in Source::onSearch for '%s' : %s\n", + log_printf(serversetup, Err, "Unhandled error in Source::onSearch for '%s' : %s\n", pair.first.second.c_str(), e.what()); } } @@ -283,12 +283,12 @@ void ServerConn::handle_CREATE_CHANNEL() pair.second->onCreate(std::move(op)); if(!op || chan->onOp || chan->onClose || chan->state!=ServerChan::Creating) { claimed = chan->state==ServerChan::Creating; - log_printf(connsetup, PLVL_DEBUG, "Client %s %s channel to %s through %s\n", peerName.c_str(), + log_printf(connsetup, Debug, "Client %s %s channel to %s through %s\n", peerName.c_str(), claimed?"accepted":"rejected", name.c_str(), pair.first.second.c_str()); break; } }catch(std::exception& e){ - log_printf(connsetup, PLVL_ERR, "Client %s Unhandled error in onCreate %s,%d %s : %s\n", peerName.c_str(), + log_printf(connsetup, Err, "Client %s Unhandled error in onCreate %s,%d %s : %s\n", peerName.c_str(), pair.first.second.c_str(), pair.first.first, typeid(&e).name(), e.what()); } @@ -321,7 +321,7 @@ void ServerConn::handle_CREATE_CHANNEL() // "spec" calls for uint16_t Access Rights here, but pvAccessCPP don't include this (it's useless anyway) if(!R.good()) { M.fault(); - log_printf(connio, PLVL_ERR, "Client %s Encode error in CreateChan\n", peerName.c_str()); + log_printf(connio, Err, "Client %s Encode error in CreateChan\n", peerName.c_str()); break; } } @@ -330,7 +330,7 @@ void ServerConn::handle_CREATE_CHANNEL() } if(!M.good()) { - log_printf(connio, PLVL_ERR, "Client %s Decode error in CreateChan\n", peerName.c_str()); + log_printf(connio, Err, "Client %s Decode error in CreateChan\n", peerName.c_str()); bev.reset(); } } @@ -348,14 +348,14 @@ void ServerConn::handle_DESTROY_CHANNEL() auto it = chanBySID.find(sid); if(it==chanBySID.end()) { - log_printf(connsetup, PLVL_DEBUG, "Client %s DestroyChan non-existant sid=%d cid=%d\n", peerName.c_str(), + log_printf(connsetup, Debug, "Client %s DestroyChan non-existant sid=%d cid=%d\n", peerName.c_str(), unsigned(sid), unsigned(cid)); return; } auto chan = it->second; if(chan->cid!=cid) { - log_printf(connsetup, PLVL_DEBUG, "Client %s provides incorrect CID with DestroyChan sid=%d cid=%d!=%d '%s'\n", peerName.c_str(), + log_printf(connsetup, Debug, "Client %s provides incorrect CID with DestroyChan sid=%d cid=%d!=%d '%s'\n", peerName.c_str(), unsigned(sid), unsigned(chan->cid), unsigned(cid), chan->name.c_str()); } diff --git a/src/serverconn.cpp b/src/serverconn.cpp index d097abb..a2ae29a 100644 --- a/src/serverconn.cpp +++ b/src/serverconn.cpp @@ -23,11 +23,11 @@ static const size_t tcp_readahead = 0x1000; namespace pvxs {namespace impl { // message related to client state and errors -DEFINE_LOGGER(connsetup, "tcp.setup"); +DEFINE_LOGGER(connsetup, "pvxs.tcp.setup"); // related to low level send/recv -DEFINE_LOGGER(connio, "tcp.io"); +DEFINE_LOGGER(connio, "pvxs.tcp.io"); -DEFINE_LOGGER(remote, "tcp.log"); +DEFINE_LOGGER(remote, "pvxs.remote.log"); ServerConn::ServerConn(ServIface* iface, evutil_socket_t sock, struct sockaddr *peer, int socklen) :iface(iface) @@ -41,7 +41,7 @@ ServerConn::ServerConn(ServIface* iface, evutil_socket_t sock, struct sockaddr * ,txBody(evbuffer_new()) ,nextSID(0) { - log_printf(connio, PLVL_DEBUG, "Client %s connects\n", peerName.c_str()); + log_printf(connio, Debug, "Client %s connects\n", peerName.c_str()); bufferevent_setcb(bev.get(), &bevReadS, &bevWriteS, &bevEventS, this); // initially wait for at least a header @@ -138,7 +138,7 @@ void auth_complete(ServerConn *self, const Status& sts) self->enqueueTxBody(CMD_CONNECTION_VALIDATED); - log_printf(connsetup, PLVL_DEBUG, "%s Auth complete with %d\n", self->peerName.c_str(), sts.code); + log_printf(connsetup, Debug, "%s Auth complete with %d\n", self->peerName.c_str(), sts.code); } void ServerConn::handle_CONNECTION_VALIDATION() @@ -159,24 +159,24 @@ void ServerConn::handle_CONNECTION_VALIDATION() // TODO store credentials if(!M.good()) { - log_printf(connio, PLVL_ERR, "Client %s Truncated/Invalid ConnValid from client\n", peerName.c_str()); + log_printf(connio, Err, "Client %s Truncated/Invalid ConnValid from client\n", peerName.c_str()); bev.reset(); return; } else { - log_printf(connsetup, PLVL_DEBUG, "Client %s authenticates using %s and %s\n", + log_printf(connsetup, Debug, "Client %s authenticates using %s and %s\n", peerName.c_str(), selected.c_str(), std::string(SB()<second; auto chan = op->chan.lock(); if(!chan || chan->sid!=sid) { - log_printf(connsetup, PLVL_ERR, "Client %s Cancel inconsistent Op\n", peerName.c_str()); + log_printf(connsetup, Err, "Client %s Cancel inconsistent Op\n", peerName.c_str()); return; } @@ -224,7 +224,7 @@ void ServerConn::handle_CANCEL_REQUEST() } else { // an allowed race - log_printf(connsetup, PLVL_DEBUG, "Client %s Cancel of non-executing Op\n", peerName.c_str()); + log_printf(connsetup, Debug, "Client %s Cancel of non-executing Op\n", peerName.c_str()); } } @@ -244,7 +244,7 @@ void ServerConn::handle_DESTROY_REQUEST() auto n = chan->opByIOID.erase(ioid); if(it==opByIOID.end() || n!=1) { - log_printf(connsetup, PLVL_WARN, "Client %s can't destroy non-existant op %u:%u\n", + log_printf(connsetup, Warn, "Client %s can't destroy non-existant op %u:%u\n", peerName.c_str(), unsigned(sid), unsigned(ioid)); } else { @@ -274,27 +274,29 @@ void ServerConn::handle_MESSAGE() auto it = opByIOID.find(ioid); if(it==opByIOID.end()) { - log_printf(connsetup, PLVL_DEBUG, "Client %s Message on non-existant ioid\n", peerName.c_str()); + log_printf(connsetup, Debug, "Client %s Message on non-existant ioid\n", peerName.c_str()); return; } auto chan = it->second->chan.lock(); + Level lvl; switch(mtype) { - case 0: mtype = PLVL_INFO; - case 1: mtype = PLVL_WARN; - case 2: mtype = PLVL_ERR; - default:mtype = PLVL_CRIT; + case 0: lvl = Level::Info; + case 1: lvl = Level::Warn; + case 2: lvl = Level::Err; + default:lvl = Level::Crit; } - log_printf(remote, mtype, "Client %s Channel %s Remote message: %s\n", - peerName.c_str(), chan ? "" : chan->name.c_str(), - msg.c_str()); + if(remote.test(lvl)) + errlogPrintf("Client %s Channel %s Remote message: %s\n", + peerName.c_str(), chan ? "" : chan->name.c_str(), + msg.c_str()); } void ServerConn::cleanup() { - log_printf(connsetup, PLVL_DEBUG, "Client %s Cleanup TCP Connection\n", peerName.c_str()); + log_printf(connsetup, Debug, "Client %s Cleanup TCP Connection\n", peerName.c_str()); auto it = iface->server->connections.find(this); if(it!=iface->server->connections.end()) { @@ -311,13 +313,13 @@ void ServerConn::bevEvent(short events) if(events&BEV_EVENT_ERROR) { int err = EVUTIL_SOCKET_ERROR(); const char *msg = evutil_socket_error_to_string(err); - log_printf(connio, PLVL_ERR, "Client %s connection closed with socket error %d : %s\n", peerName.c_str(), err, msg); + log_printf(connio, Err, "Client %s connection closed with socket error %d : %s\n", peerName.c_str(), err, msg); } if(events&BEV_EVENT_EOF) { - log_printf(connio, PLVL_DEBUG, "Client %s connection closed by peer\n", peerName.c_str()); + log_printf(connio, Debug, "Client %s connection closed by peer\n", peerName.c_str()); } if(events&BEV_EVENT_TIMEOUT) { - log_printf(connio, PLVL_WARN, "Client %s connection timeout\n", peerName.c_str()); + log_printf(connio, Warn, "Client %s connection timeout\n", peerName.c_str()); } bev.reset(); } @@ -337,11 +339,11 @@ void ServerConn::bevRead() assert(ret==sizeof(header)); // previously verified if(header[0]!=0xca || header[1]==0 || (header[2]&pva_flags::Server)) { - log_hex_printf(connio, PLVL_ERR, header, sizeof(header), "Client %s Protocol decode fault. Force disconnect.\n", peerName.c_str()); + log_hex_printf(connio, Err, header, sizeof(header), "Client %s Protocol decode fault. Force disconnect.\n", peerName.c_str()); bev.reset(); break; } - log_hex_printf(connio, PLVL_DEBUG, header, sizeof(header), "Client %s Receive header\n", peerName.c_str()); + log_hex_printf(connio, Debug, header, sizeof(header), "Client %s Receive header\n", peerName.c_str()); if(header[2]&pva_flags::Control) { // Control messages are not actually useful @@ -382,7 +384,7 @@ void ServerConn::bevRead() bool continuation = seg&pva_flags::SegLast; // true for mid or last. false for none for first if((continuation ^ expectSeg) || (continuation && header[3]!=segCmd)) { - log_printf(connio, PLVL_CRIT, "Client %s Peer segmentation violation %c%c 0x%02x==0x%02x\n", peerName.c_str(), + log_printf(connio, Crit, "Client %s Peer segmentation violation %c%c 0x%02x==0x%02x\n", peerName.c_str(), expectSeg?'Y':'N', continuation?'Y':'N', segCmd, header[3]); bev.reset(); @@ -400,7 +402,7 @@ void ServerConn::bevRead() // ready to process segBuf switch(segCmd) { default: - log_printf(connio, PLVL_DEBUG, "Client %s Ignore unexpected command 0x%02x\n", peerName.c_str(), segCmd); + log_printf(connio, Debug, "Client %s Ignore unexpected command 0x%02x\n", peerName.c_str(), segCmd); evbuffer_drain(segBuf.get(), evbuffer_get_length(segBuf.get())); break; #define CASE(OP) case CMD_##OP: handle_##OP(); break @@ -461,7 +463,7 @@ void ServerConn::bevEventS(struct bufferevent *bev, short events, void *ptr) try { conn->bevEvent(events); }catch(std::exception& e){ - log_printf(connsetup, PLVL_CRIT, "Client %s Unhandled error in bev event callback: %s\n", conn->peerName.c_str(), e.what()); + log_printf(connsetup, Crit, "Client %s Unhandled error in bev event callback: %s\n", conn->peerName.c_str(), e.what()); static_cast(ptr)->cleanup(); } } @@ -472,7 +474,7 @@ void ServerConn::bevReadS(struct bufferevent *bev, void *ptr) try { conn->bevRead(); }catch(std::exception& e){ - log_printf(connsetup, PLVL_CRIT, "Client %s Unhandled error in bev read callback: %s\n", conn->peerName.c_str(), e.what()); + log_printf(connsetup, Crit, "Client %s Unhandled error in bev read callback: %s\n", conn->peerName.c_str(), e.what()); static_cast(ptr)->cleanup(); } } @@ -483,7 +485,7 @@ void ServerConn::bevWriteS(struct bufferevent *bev, void *ptr) try { conn->bevWrite(); }catch(std::exception& e){ - log_printf(connsetup, PLVL_CRIT, "Client %s Unhandled error in bev write callback: %s\n", conn->peerName.c_str(), e.what()); + log_printf(connsetup, Crit, "Client %s Unhandled error in bev write callback: %s\n", conn->peerName.c_str(), e.what()); static_cast(ptr)->cleanup(); } } @@ -520,14 +522,14 @@ void ServIface::onConnS(struct evconnlistener *listener, evutil_socket_t sock, s auto self = static_cast(raw); try { if(peer->sa_family!=AF_INET) { - log_printf(connsetup, PLVL_CRIT, "Interface %s Rejecting !ipv4 client\n", self->name.c_str()); + log_printf(connsetup, Crit, "Interface %s Rejecting !ipv4 client\n", self->name.c_str()); evutil_closesocket(sock); return; } auto conn(std::make_shared(self, sock, peer, socklen)); self->server->connections[conn.get()] = std::move(conn); }catch(std::exception& e){ - log_printf(connsetup, PLVL_CRIT, "Interface %s Unhandled error in accept callback: %s\n", self->name.c_str(), e.what()); + log_printf(connsetup, Crit, "Interface %s Unhandled error in accept callback: %s\n", self->name.c_str(), e.what()); evutil_closesocket(sock); } } diff --git a/src/serverget.cpp b/src/serverget.cpp index 89d8031..e6bbe40 100644 --- a/src/serverget.cpp +++ b/src/serverget.cpp @@ -11,8 +11,8 @@ #include "serverconn.h" namespace pvxs { namespace impl { -DEFINE_LOGGER(connsetup, "tcp.setup"); -DEFINE_LOGGER(connio, "tcp.io"); +DEFINE_LOGGER(connsetup, "pvxs.tcp.setup"); +DEFINE_LOGGER(connio, "pvxs.tcp.io"); namespace { @@ -305,7 +305,7 @@ void ServerConn::handle_GPR(pva_app_msg_t cmd) from_wire_type_value(M, rxRegistry, pvRequest); if(!M.good()) { - log_printf(connio, PLVL_DEBUG, "Client %s\n Invalid op=%x/%x INIT\n", + log_printf(connio, Debug, "Client %s\n Invalid op=%x/%x INIT\n", peerName.c_str(), cmd, subcmd); bev.reset(); return; @@ -314,7 +314,7 @@ void ServerConn::handle_GPR(pva_app_msg_t cmd) auto& chan = lookupSID(sid); if(opByIOID.find(ioid)!=opByIOID.end()) { - log_printf(connsetup, PLVL_ERR, "Client %s reuses existing ioid %u\n", peerName.c_str(), unsigned(ioid)); + log_printf(connsetup, Err, "Client %s reuses existing ioid %u\n", peerName.c_str(), unsigned(ioid)); bev.reset(); return; } @@ -329,7 +329,7 @@ void ServerConn::handle_GPR(pva_app_msg_t cmd) opByIOID[ioid] = op; chan->opByIOID[ioid] = op; - log_printf(connsetup, PLVL_DEBUG, "Client %s Get INIT ioid=%u pvRequest=%s\n", + log_printf(connsetup, Debug, "Client %s Get INIT ioid=%u pvRequest=%s\n", peerName.c_str(), unsigned(ioid), std::string(SB()< op; auto it = opByIOID.find(ioid); if(it==opByIOID.end() || !(op=std::dynamic_pointer_cast(it->second))) { - log_printf(connio, PLVL_ERR, "Client %s Gets %s IOID %u\n", peerName.c_str(), + log_printf(connio, Err, "Client %s Gets %s IOID %u\n", peerName.c_str(), it==opByIOID.end() ? "non-existant" : "invalid", unsigned(ioid)); bev.reset(); return; } if(cmd!=CMD_RPC && !op->type) { - log_printf(connsetup, PLVL_ERR, "Client %s tries to Exec to early\n", peerName.c_str()); + log_printf(connsetup, Err, "Client %s tries to Exec to early\n", peerName.c_str()); bev.reset(); return; } @@ -369,7 +369,7 @@ void ServerConn::handle_GPR(pva_app_msg_t cmd) } if(!M.good()) { - log_printf(connio, PLVL_DEBUG, "Client %s\n Invalid op=%x/%x Get\n", + log_printf(connio, Debug, "Client %s\n Invalid op=%x/%x Get\n", peerName.c_str(), cmd, subcmd); bev.reset(); return; @@ -390,7 +390,7 @@ void ServerConn::handle_GPR(pva_app_msg_t cmd) op->subcmd = subcmd; op->state = ServerOp::Executing; - log_printf(connsetup, PLVL_DEBUG, "CLient %s Get executing\n", peerName.c_str()); + log_printf(connsetup, Debug, "CLient %s Get executing\n", peerName.c_str()); try { if(cmd==CMD_RPC && isput) { @@ -412,18 +412,18 @@ void ServerConn::handle_GPR(pva_app_msg_t cmd) ctrl->error("GET Not Implemented"); } else { - log_printf(connsetup, PLVL_ERR, "Client %s Get exec in incorrect command %d\n", + log_printf(connsetup, Err, "Client %s Get exec in incorrect command %d\n", peerName.c_str(), subcmd); } } catch(std::exception& e) { - log_printf(connsetup, PLVL_ERR, "Client %s Unhandled exception in onGet/Put/RPC %s : %s\n", + log_printf(connsetup, Err, "Client %s Unhandled exception in onGet/Put/RPC %s : %s\n", peerName.c_str(), typeid(e).name(), e.what()); if(ctrl) ctrl->error(e.what()); } } else { - log_printf(connsetup, PLVL_ERR, "CLient %s Get exec in incorrect state %d\n", + log_printf(connsetup, Err, "CLient %s Get exec in incorrect state %d\n", peerName.c_str(), op->state); } } diff --git a/src/serverintrospect.cpp b/src/serverintrospect.cpp index 3baf66a..df0139b 100644 --- a/src/serverintrospect.cpp +++ b/src/serverintrospect.cpp @@ -11,7 +11,7 @@ #include "serverconn.h" namespace pvxs { namespace impl { -DEFINE_LOGGER(connsetup, "tcp.setup"); +DEFINE_LOGGER(connsetup, "pvxs.tcp.setup"); namespace { struct ServerIntrospect : public ServerOp @@ -133,7 +133,7 @@ void ServerConn::handle_GET_FIELD() auto& chan = lookupSID(sid); if(opByIOID.find(ioid)!=opByIOID.end()) { - log_printf(connsetup, PLVL_ERR, "Client %s reuses existing ioid %d\n", peerName.c_str(), unsigned(ioid)); + log_printf(connsetup, Err, "Client %s reuses existing ioid %d\n", peerName.c_str(), unsigned(ioid)); return; } diff --git a/src/serversource.cpp b/src/serversource.cpp index ab7890e..088109b 100644 --- a/src/serversource.cpp +++ b/src/serversource.cpp @@ -11,7 +11,7 @@ namespace pvxs { namespace impl { -DEFINE_LOGGER(srvsrc, "server.src"); +DEFINE_LOGGER(srvsrc, "pvxs.server.src"); ServerSource::ServerSource(server::Server::Pvt* serv) :name("server") @@ -35,7 +35,7 @@ void ServerSource::onCreate(std::unique_ptr &&op) auto handle = std::move(op); // claim handle->onRPC([this](std::unique_ptr&& eop, Value&& raw) { - log_printf(srvsrc, PLVL_DEBUG, "Client %s calls %s\n", eop->peerName().c_str(), + log_printf(srvsrc, Debug, "Client %s calls %s\n", eop->peerName().c_str(), std::string(SB()< Guard; namespace pvxs {namespace impl { -DEFINE_LOGGER(logio, "udp.io"); -DEFINE_LOGGER(logsetup, "udp.setup"); +DEFINE_LOGGER(logio, "pvxs.udp.io"); +DEFINE_LOGGER(logsetup, "pvxs.udp.setup"); struct UDPCollector : public UDPManager::Search, public std::enable_shared_from_this @@ -62,7 +62,7 @@ struct UDPCollector : public UDPManager::Search, if(err==SOCK_EWOULDBLOCK || err==EAGAIN || err==SOCK_EINTR) { // nothing to do here } else { - log_printf(logio, PLVL_WARN, "UDP RX Error on %s : %s\n", name.c_str(), + log_printf(logio, Warn, "UDP RX Error on %s : %s\n", name.c_str(), evutil_socket_error_to_string(err)); } return false; // wait for more I/O @@ -71,7 +71,7 @@ struct UDPCollector : public UDPManager::Search, // maybe a zero (body) length packet? // maybe an OS error? - log_printf(logio, PLVL_INFO, "UDP ignore runt on %s\n", name.c_str()); + log_printf(logio, Info, "UDP ignore runt on %s\n", name.c_str()); return true; } else if(buf[0]!=0xca || buf[1]==0 || (buf[2]&(pva_flags::Control|pva_flags::SegMask))) { @@ -80,13 +80,13 @@ struct UDPCollector : public UDPManager::Search, // ignore incompatible version 0 // UDP packets can't contain control messages, or use segmentation - log_printf(logio, PLVL_INFO, "UDP ignore header%u %02x%02x%02x%02x on %s\n", + log_printf(logio, Info, "UDP ignore header%u %02x%02x%02x%02x on %s\n", unsigned(nrx), buf[0], buf[1], buf[2], buf[3], name.c_str()); return true; } - log_hex_printf(logio, PLVL_DEBUG, &buf[0], nrx, "UDP Rx %d from %s\n", nrx, src.tostring().c_str()); + log_hex_printf(logio, Debug, &buf[0], nrx, "UDP Rx %d from %s\n", nrx, src.tostring().c_str()); names.clear(); @@ -101,7 +101,7 @@ struct UDPCollector : public UDPManager::Search, from_wire(M, len); if(len > M.size() && M.good()) { - log_printf(logio, PLVL_INFO, "UDP ignore header%u %02x%02x%02x%02x on %s\n", + log_printf(logio, Info, "UDP ignore header%u %02x%02x%02x%02x on %s\n", unsigned(M.size()), M[0], M[1], M[2], M[3], name.c_str()); return true; @@ -210,7 +210,7 @@ struct UDPCollector : public UDPManager::Search, } void handle(short ev) { - log_printf(logio, PLVL_DEBUG, "UDP %p event %x\n", rx.get(), ev); + log_printf(logio, Debug, "UDP %p event %x\n", rx.get(), ev); if(!(ev&EV_READ)) return; @@ -223,7 +223,7 @@ struct UDPCollector : public UDPManager::Search, try { static_cast(raw)->handle(ev); }catch(std::exception& e) { - log_printf(logio, PLVL_CRIT, "Ignoring unhandled exception in UDPManager::handle(): %s\n", e.what()); + log_printf(logio, Crit, "Ignoring unhandled exception in UDPManager::handle(): %s\n", e.what()); } } @@ -264,7 +264,7 @@ UDPCollector::UDPCollector(const std::shared_ptr& manager, cons sock.bind(this->bind_addr); name = "UDP "+this->bind_addr.tostring(); - log_printf(logsetup, PLVL_INFO, "Bound to %s\n", name.c_str()); + log_printf(logsetup, Info, "Bound to %s\n", name.c_str()); if(event_add(rx.get(), nullptr)) throw std::runtime_error("Unable to create collector Rx event"); @@ -423,7 +423,7 @@ bool UDPCollector::reply(const void *msg, size_t msglen) const if(err==SOCK_EWOULDBLOCK || err==EAGAIN || err==SOCK_EINTR) { // nothing to do here } else { - log_printf(logio, PLVL_WARN, "UDP TX Error on %s : %s\n", name.c_str(), + log_printf(logio, Warn, "UDP TX Error on %s : %s\n", name.c_str(), evutil_socket_error_to_string(err)); } return false; // wait for more I/O diff --git a/test/dummyserv.cpp b/test/dummyserv.cpp index 473a322..3dd1594 100644 --- a/test/dummyserv.cpp +++ b/test/dummyserv.cpp @@ -52,10 +52,10 @@ public: { for(auto& op : search) { if(op.name()==name) { - log_printf(dummy, PLVL_INFO, "Claiming '%s'\n", op.name()); + log_printf(dummy, Info, "Claiming '%s'\n", op.name()); op.claim(); } else { - log_printf(dummy, PLVL_DEBUG, "Ignoring '%s'\n", op.name()); + log_printf(dummy, Debug, "Ignoring '%s'\n", op.name()); } } } @@ -74,17 +74,17 @@ public: std::shared_ptr chan(std::move(raw)); - log_printf(dummy, PLVL_INFO, "Create '%s'\n", chan->name().c_str()); + log_printf(dummy, Info, "Create '%s'\n", chan->name().c_str()); // callback when client creating Get/Put chan->onOp([this, chan](std::shared_ptr&& raw){ std::shared_ptr conn(std::move(raw)); - log_printf(dummy, PLVL_INFO, "Begin Operation on '%s'\n", chan->name().c_str()); + log_printf(dummy, Info, "Begin Operation on '%s'\n", chan->name().c_str()); conn->onGet([this, chan](std::unique_ptr&& raw) { // client executing Get or Put - log_printf(dummy, PLVL_INFO, "Exec Get on '%s'\n", chan->name().c_str()); + log_printf(dummy, Info, "Exec Get on '%s'\n", chan->name().c_str()); { epicsGuard G(lock); @@ -93,7 +93,7 @@ public: }); conn->onPut([this, chan](std::unique_ptr&& raw, Value&& top) { - log_printf(dummy, PLVL_INFO, "Exec Put on '%s'\n", chan->name().c_str()); + log_printf(dummy, Info, "Exec Put on '%s'\n", chan->name().c_str()); { epicsTimeStamp now; @@ -115,7 +115,7 @@ public: // callback when client executing RPC chan->onRPC([this, chan](std::unique_ptr&& raw, Value&& top) { - log_printf(dummy, PLVL_INFO, "Begin RPC on '%s' with %s\n", chan->name().c_str(), + log_printf(dummy, Info, "Begin RPC on '%s' with %s\n", chan->name().c_str(), std::string(SB()<("blah"); diff --git a/tools/pvxvct.cpp b/tools/pvxvct.cpp index 479910b..e35af89 100644 --- a/tools/pvxvct.cpp +++ b/tools/pvxvct.cpp @@ -170,20 +170,20 @@ int main(int argc, char *argv[]) bindaddrs.emplace_back(pva::SockAddr::any(AF_INET, 5076)); } - pva::logger_level_set("pvxvct", PLVL_INFO); + pva::logger_level_set("pvxvct", pvxs::Level::Info); pva::logger_config_env(); // from $PVXS_LOG - log_printf(out, PLVL_DEBUG, "Show Search: %s\nShow Beacon: %s\n", opts.client?"yes":"no", opts.server?"yes":"no"); + log_printf(out, Debug, "Show Search: %s\nShow Beacon: %s\n", opts.client?"yes":"no", opts.server?"yes":"no"); if(opts.client && opts.pvnames.empty()) { - log_printf(out, PLVL_DEBUG, "Show all PV names\n"); + log_printf(out, Debug, "Show all PV names\n"); } else { for(const auto& name : opts.pvnames) { - log_printf(out, PLVL_DEBUG, "Show PV: %s\n", name.c_str()); + log_printf(out, Debug, "Show PV: %s\n", name.c_str()); } } if(opts.peers.empty()) { - log_printf(out, PLVL_DEBUG, "No peer filter\n"); - } else if(log_test(out, PLVL_DEBUG)) { + log_printf(out, Debug, "No peer filter\n"); + } else if(log_test(out, Debug)) { for(const auto& tup : opts.peers) { in_addr addr, netmask; std::tie(addr.s_addr, netmask.s_addr) = tup; @@ -191,22 +191,22 @@ int main(int argc, char *argv[]) char nbuf[16]; evutil_inet_ntop(AF_INET, &addr, abuf, sizeof(abuf)); evutil_inet_ntop(AF_INET, &netmask, nbuf, sizeof(nbuf)); - log_printf(out, PLVL_DEBUG, "Show from %s/%s\n", abuf, nbuf); + log_printf(out, Debug, "Show from %s/%s\n", abuf, nbuf); } } auto searchCB = [&opts](const pva::UDPManager::Search& msg) { - log_printf(out, PLVL_INFO, "%s Searching for:\n", msg.src.tostring().c_str()); + log_printf(out, Info, "%s Searching for:\n", msg.src.tostring().c_str()); for(const auto pv : msg.names) { - log_printf(out, PLVL_INFO, " \"%s\"\n", pv.name); + log_printf(out, Info, " \"%s\"\n", pv.name); } }; auto beaconCB = [&opts](const pva::UDPManager::Beacon& msg) { const auto& guid = msg.guid; - log_printf(out, PLVL_INFO, "%s Beacon %02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x %s\n", + log_printf(out, Info, "%s Beacon %02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x %s\n", msg.src.tostring().c_str(), guid[0], guid[1], guid[2], guid[3], guid[4], guid[5], guid[6], guid[7], guid[8], guid[9], guid[10], guid[11], msg.server.tostring().c_str()); @@ -222,7 +222,7 @@ int main(int argc, char *argv[]) manager.onBeacon(baddr, beaconCB)); listeners.back().first->start(); listeners.back().second->start(); - log_printf(out, PLVL_DEBUG, "Bind: %s\n", baddr.tostring().c_str()); + log_printf(out, Debug, "Bind: %s\n", baddr.tostring().c_str()); } @@ -234,7 +234,7 @@ int main(int argc, char *argv[]) #endif done.wait(); - log_printf(out, PLVL_INFO, "Done\n"); + log_printf(out, Info, "Done\n"); errlogFlush(); return 0;