add trace log level for tracking logic thread jobs

libabyss/main.cpp

@@ -39,7 +39,7 @@ struct DemoCall : public abyss::http::IRPCClientHandler
   bool HandleResponse(abyss::http::RPC_Response) override
   {
     llarp::LogInfo("response get");
-    m_Logic->queue_func([=]() { m_Callback(); });
+    LogicCall(m_Logic, m_Callback);
     return true;
   }
 

llarp/context.cpp

@@ -39,7 +39,7 @@ namespace llarp
   bool
   Context::CallSafe(std::function< void(void) > f)
   {
-    return logic && logic->queue_func(std::move(f));
+    return logic && LogicCall(logic, f);
   }
 
   void
@@ -482,8 +482,8 @@ extern "C"
   void
   llarp_main_signal(struct llarp_main *ptr, int sig)
   {
-    ptr->ctx->logic->queue_func(
-        std::bind(&llarp::Context::HandleSignal, ptr->ctx.get(), sig));
+    LogicCall(ptr->ctx->logic,
+              std::bind(&llarp::Context::HandleSignal, ptr->ctx.get(), sig));
   }
 
   int

llarp/dht/context.cpp

@@ -199,14 +199,14 @@ namespace llarp
       PutRCNodeAsync(const RCNode& val) override
       {
         auto func = std::bind(&Bucket< RCNode >::PutNode, Nodes(), val);
-        router->logic()->queue_func(func);
+        LogicCall(router->logic(), func);
       }
 
       void
       DelRCNodeAsync(const Key_t& val) override
       {
         auto func = std::bind(&Bucket< RCNode >::DelNode, Nodes(), val);
-        router->logic()->queue_func(func);
+        LogicCall(router->logic(), func);
       }
 
       const Key_t&

llarp/dns/server.cpp

@@ -39,10 +39,10 @@ namespace llarp
       m_Resolvers = resolvers;
       const llarp::Addr any("0.0.0.0", 0);
       auto self = shared_from_this();
-      m_ClientLogic->queue_func([=]() {
+      LogicCall(m_ClientLogic, [=]() {
         llarp_ev_add_udp(self->m_ClientLoop.get(), &self->m_Client, any);
       });
-      m_ServerLogic->queue_func([=]() {
+      LogicCall(m_ServerLogic, [=]() {
         llarp_ev_add_udp(self->m_ServerLoop.get(), &self->m_Server, addr);
       });
       return true;
@@ -65,8 +65,9 @@ namespace llarp
       auto self       = static_cast< Proxy* >(u->user)->shared_from_this();
       // yes we use the server loop here because if the server loop is not the
       // client loop we'll crash again
-      self->m_ServerLogic->queue_func(
-          [self, addr, msgbuf]() { self->HandlePktServer(addr, msgbuf); });
+      LogicCall(self->m_ServerLogic, [self, addr, msgbuf]() {
+        self->HandlePktServer(addr, msgbuf);
+      });
     }
 
     void
@@ -76,8 +77,9 @@ namespace llarp
       const llarp::Addr addr(*from);
       Buffer_t msgbuf = CopyBuffer(buf.underlying);
       auto self       = static_cast< Proxy* >(u->user)->shared_from_this();
-      self->m_ServerLogic->queue_func(
-          [self, addr, msgbuf]() { self->HandlePktClient(addr, msgbuf); });
+      LogicCall(self->m_ServerLogic, [self, addr, msgbuf]() {
+        self->HandlePktClient(addr, msgbuf);
+      });
     }
 
     llarp::Addr
@@ -100,7 +102,7 @@ namespace llarp
     Proxy::SendServerMessageTo(llarp::Addr to, Message msg)
     {
       auto self = shared_from_this();
-      m_ServerLogic->queue_func([to, msg, self]() {
+      LogicCall(m_ServerLogic, [to, msg, self]() {
         std::array< byte_t, 1500 > tmp = {{0}};
         llarp_buffer_t buf(tmp);
         if(msg.Encode(&buf))
@@ -118,7 +120,7 @@ namespace llarp
     Proxy::SendClientMessageTo(llarp::Addr to, Message msg)
     {
       auto self = shared_from_this();
-      m_ClientLogic->queue_func([to, msg, self]() {
+      LogicCall(m_ClientLogic, [to, msg, self]() {
         std::array< byte_t, 1500 > tmp = {{0}};
         llarp_buffer_t buf(tmp);
         if(msg.Encode(&buf))
@@ -151,7 +153,7 @@ namespace llarp
 
       const Addr requester = itr->second;
       auto self            = shared_from_this();
-      m_ServerLogic->queue_func([=]() {
+      LogicCall(m_ServerLogic, [=]() {
         // forward reply to requester via server
         const llarp_buffer_t tmpbuf(buf);
         llarp_ev_udp_sendto(&self->m_Server, requester, tmpbuf);
@@ -222,7 +224,7 @@ namespace llarp
         // new forwarded query
         tx.from         = PickRandomResolver();
         m_Forwarded[tx] = from;
-        m_ClientLogic->queue_func([=] {
+        LogicCall(m_ClientLogic, [=] {
           // do query
           const llarp_buffer_t tmpbuf(buf);
           llarp_ev_udp_sendto(&self->m_Client, tx.from, tmpbuf);
@@ -232,7 +234,7 @@ namespace llarp
       {
         // send the query again because it's probably FEC from the requester
         const auto resolver = itr->first.from;
-        m_ClientLogic->queue_func([=] {
+        LogicCall(m_ClientLogic, [=] {
           // send it
           const llarp_buffer_t tmpbuf(buf);
           llarp_ev_udp_sendto(&self->m_Client, resolver, tmpbuf);

llarp/ev/ev_libuv.cpp

@@ -7,13 +7,8 @@
 
 namespace libuv
 {
-  /// call a function in logic thread via a handle
-  template < typename Handle, typename Func >
-  void
-  Call(Handle* h, Func f)
-  {
-    static_cast< Loop* >(h->loop->data)->Call(f);
-  }
+#define LoopCall(h, ...) \
+  LogicCall(static_cast< Loop* >((h)->loop->data)->m_Logic, __VA_ARGS__)
 
   struct glue
   {
@@ -110,8 +105,8 @@ namespace libuv
     OnOutboundConnect(uv_connect_t* c, int status)
     {
       conn_glue* self = static_cast< conn_glue* >(c->data);
-      Call(self->Stream(),
-           std::bind(&conn_glue::HandleConnectResult, self, status));
+      LoopCall(self->Stream(),
+               std::bind(&conn_glue::HandleConnectResult, self, status));
       c->data = nullptr;
     }
 
@@ -145,7 +140,7 @@ namespace libuv
       if(nread >= 0)
       {
         auto* conn = static_cast< conn_glue* >(stream->data);
-        Call(stream, std::bind(&conn_glue::Read, conn, buf->base, nread));
+        LoopCall(stream, std::bind(&conn_glue::Read, conn, buf->base, nread));
         return;
       }
       else if(nread < 0)
@@ -262,7 +257,7 @@ namespace libuv
     OnClosed(uv_handle_t* h)
     {
       conn_glue* conn = static_cast< conn_glue* >(h->data);
-      Call(h, std::bind(&conn_glue::HandleClosed, conn));
+      LoopCall(h, std::bind(&conn_glue::HandleClosed, conn));
     }
 
     static void
@@ -329,7 +324,7 @@ namespace libuv
       if(status == 0)
       {
         conn_glue* conn = static_cast< conn_glue* >(stream->data);
-        Call(stream, std::bind(&conn_glue::Accept, conn));
+        LoopCall(stream, std::bind(&conn_glue::Accept, conn));
       }
       else
       {
@@ -347,7 +342,7 @@ namespace libuv
     OnTick(uv_check_t* t)
     {
       conn_glue* conn = static_cast< conn_glue* >(t->data);
-      Call(t, std::bind(&conn_glue::Tick, conn));
+      LoopCall(t, std::bind(&conn_glue::Tick, conn));
     }
 
     void
@@ -416,7 +411,7 @@ namespace libuv
     OnTick(uv_check_t* t)
     {
       ticker_glue* ticker = static_cast< ticker_glue* >(t->data);
-      Call(t, ticker->func);
+      LoopCall(t, ticker->func);
     }
 
     bool
@@ -586,7 +581,7 @@ namespace libuv
     void
     Tick()
     {
-      Call(&m_Handle, std::bind(&llarp_ev_pkt_pipe::tick, m_Pipe));
+      LoopCall(&m_Handle, std::bind(&llarp_ev_pkt_pipe::tick, m_Pipe));
     }
 
     static void
@@ -626,7 +621,7 @@ namespace libuv
     OnTick(uv_check_t* h)
     {
       pipe_glue* pipe = static_cast< pipe_glue* >(h->data);
-      Call(h, std::bind(&pipe_glue::Tick, pipe));
+      LoopCall(h, std::bind(&pipe_glue::Tick, pipe));
     }
 
     bool
@@ -668,7 +663,7 @@ namespace libuv
     OnTick(uv_check_t* timer)
     {
       tun_glue* tun = static_cast< tun_glue* >(timer->data);
-      Call(timer, std::bind(&tun_glue::Tick, tun));
+      LoopCall(timer, std::bind(&tun_glue::Tick, tun));
     }
 
     static void

llarp/ev/ev_libuv.hpp

@@ -92,19 +92,12 @@ namespace libuv
       m_Logic = l;
     }
 
-    /// call function in logic thread
-    template < typename F >
-    void
-    Call(F f)
-    {
-      m_Logic->queue_func(f);
-    }
+    std::shared_ptr< llarp::Logic > m_Logic;
 
    private:
     uv_loop_t m_Impl;
     uv_timer_t m_TickTimer;
     std::atomic< bool > m_Run;
-    std::shared_ptr< llarp::Logic > m_Logic;
   };
 
 }  // namespace libuv

llarp/ev/ev_win32.cpp

@@ -727,7 +727,7 @@ llarp_win32_loop::tick_listeners()
 {
   llarp_ev_loop::tick_listeners();
   for(auto& func : m_Tickers)
-    m_Logic->queue_func([func]() { func(); });
+    LogicCall(m_Logic, func);
 }
 
 bool

llarp/handlers/exit.cpp

@@ -23,7 +23,7 @@ namespace llarp
     ExitHandlerFlush(llarp_tun_io *tun)
     {
       auto *ep = static_cast< ExitEndpoint * >(tun->user);
-      ep->GetRouter()->logic()->queue_func(std::bind(&ExitEndpoint::Flush, ep));
+      LogicCall(ep->GetRouter()->logic(), std::bind(&ExitEndpoint::Flush, ep));
     }
 
     ExitEndpoint::ExitEndpoint(const std::string &name, AbstractRouter *r)

llarp/handlers/tun.cpp

@@ -310,7 +310,7 @@ namespace llarp
     {
       auto self = shared_from_this();
       FlushSend();
-      RouterLogic()->queue_func([=] {
+      LogicCall(RouterLogic(), [=] {
         self->m_ExitMap.ForEachValue(
             [](const auto &exit) { exit->FlushUpstream(); });
         self->Pump(self->Now());
@@ -749,7 +749,7 @@ namespace llarp
     void
     TunEndpoint::Tick(llarp_time_t now)
     {
-      EndpointLogic()->queue_func([&]() {
+      LogicCall(EndpointLogic(), [&]() {
         m_ExitMap.ForEachValue([&](const auto &exit) {
           this->EnsureRouterIsKnown(exit->Endpoint());
           exit->Tick(now);
@@ -982,8 +982,9 @@ namespace llarp
         }
         return false;
       };
-      self->EndpointLogic()->queue_func(std::bind(
-          &TunEndpoint::FlushToUser, self->shared_from_this(), sendpkt));
+      LogicCall(self->EndpointLogic(),
+                std::bind(&TunEndpoint::FlushToUser, self->shared_from_this(),
+                          sendpkt));
     }
 
     void

llarp/iwp/session.cpp

@@ -557,7 +557,8 @@ namespace llarp
         recvMsgs->emplace_back(std::move(pkt));
       }
       LogDebug("decrypted ", recvMsgs->size(), " packets from ", m_RemoteAddr);
-      m_Parent->logic()->queue_func(
+      LogicCall(
+          m_Parent->logic(),
           std::bind(&Session::HandlePlaintext, shared_from_this(), recvMsgs));
     }
 

llarp/link/server.cpp

@@ -161,7 +161,7 @@ namespace llarp
           LogInfo("pending session at ", itr->first, " timed out");
           // defer call so we can acquire mutexes later
           auto self = itr->second->BorrowSelf();
-          m_Logic->queue_func([&, self]() {
+          LogicCall(m_Logic, [&, self]() {
             this->HandleTimeout(self.get());
             self->Close();
           });
@@ -470,7 +470,7 @@ namespace llarp
     auto logic = link->logic();
     if(logic == nullptr)
       return;
-    logic->queue_func([pkts, link]() {
+    LogicCall(logic, [pkts, link]() {
       auto itr = pkts->begin();
       while(itr != pkts->end())
       {

llarp/messages/relay_commit.cpp

@@ -410,7 +410,7 @@ namespace llarp
         // we are the farthest hop
         llarp::LogDebug("We are the farthest hop for ", info);
         // send a LRSM down the path
-        self->context->logic()->queue_func([=]() {
+        LogicCall(self->context->logic(), [=]() {
           SendPathConfirm(self);
           self->decrypter = nullptr;
         });
@@ -419,7 +419,7 @@ namespace llarp
       {
         // forward upstream
         // we are still in the worker thread so post job to logic
-        self->context->logic()->queue_func([=]() {
+        LogicCall(self->context->logic(), [=]() {
           SendLRCM(self);
           self->decrypter = nullptr;
         });

llarp/messages/relay_status.cpp

@@ -222,7 +222,7 @@ namespace llarp
                                      std::shared_ptr< LR_StatusMessage > msg)
   {
     auto func = std::bind(&LR_StatusMessage::SendMessage, router, nextHop, msg);
-    router->pathContext().logic()->queue_func(func);
+    LogicCall(router->logic(), func);
   }
 
   void

llarp/nodedb.cpp

@@ -122,7 +122,7 @@ llarp_nodedb::InsertAsync(llarp::RouterContact rc,
     this->Insert(rc);
     if(logic && completionHandler)
     {
-      logic->queue_func([completionHandler] { completionHandler(); });
+      LogicCall(logic, completionHandler);
     }
   });
 }

llarp/path/path.cpp

@@ -155,7 +155,7 @@ namespace llarp
       {
         llarp::LogDebug("LR_Status message processed, path build successful");
         auto self = shared_from_this();
-        r->logic()->queue_func([=]() { self->HandlePathConfirmMessage(r); });
+        LogicCall(r->logic(), [=]() { self->HandlePathConfirmMessage(r); });
       }
       else
       {
@@ -206,8 +206,8 @@ namespace llarp
           llarp::LogDebug("Path build failed for an unspecified reason");
         }
         auto self = shared_from_this();
-        r->logic()->queue_func(
-            [=]() { self->EnterState(ePathFailed, r->Now()); });
+        LogicCall(r->logic(),
+                  [=]() { self->EnterState(ePathFailed, r->Now()); });
       }
 
       // TODO: meaningful return value?
@@ -411,9 +411,9 @@ namespace llarp
         msg.pathid = TXID();
         ++idx;
       }
-      r->logic()->queue_func(std::bind(&Path::HandleAllUpstream,
-                                       shared_from_this(), std::move(sendmsgs),
-                                       r));
+      LogicCall(r->logic(),
+                std::bind(&Path::HandleAllUpstream, shared_from_this(),
+                          std::move(sendmsgs), r));
     }
 
     void
@@ -482,9 +482,9 @@ namespace llarp
         sendMsgs[idx].X = buf;
         ++idx;
       }
-      r->logic()->queue_func(std::bind(&Path::HandleAllDownstream,
-                                       shared_from_this(), std::move(sendMsgs),
-                                       r));
+      LogicCall(r->logic(),
+                std::bind(&Path::HandleAllDownstream, shared_from_this(),
+                          std::move(sendMsgs), r));
     }
 
     void

llarp/path/pathbuilder.cpp

@@ -98,7 +98,7 @@ namespace llarp
       {
         // farthest hop
         // TODO: encrypt junk frames because our public keys are not eligator
-        logic->queue_func(std::bind(result, shared_from_this()));
+        LogicCall(logic, std::bind(result, shared_from_this()));
       }
       else
       {

llarp/path/transit_hop.cpp

@@ -132,9 +132,9 @@ namespace llarp
                         info.upstream, " to ", info.downstream);
         ++idx;
       }
-      r->logic()->queue_func(std::bind(&TransitHop::HandleAllDownstream,
-                                       shared_from_this(), std::move(sendmsgs),
-                                       r));
+      LogicCall(r->logic(),
+                std::bind(&TransitHop::HandleAllDownstream, shared_from_this(),
+                          std::move(sendmsgs), r));
     }
 
     void
@@ -152,9 +152,9 @@ namespace llarp
         msg.X      = buf;
         ++idx;
       }
-      r->logic()->queue_func(std::bind(&TransitHop::HandleAllUpstream,
-                                       shared_from_this(), std::move(sendmsgs),
-                                       r));
+      LogicCall(r->logic(),
+                std::bind(&TransitHop::HandleAllUpstream, shared_from_this(),
+                          std::move(sendmsgs), r));
     }
 
     void
@@ -183,7 +183,7 @@ namespace llarp
           r->SendToOrQueue(info.upstream, &msg);
         }
       }
-      r->linkManager().PumpLinks();
+      r->PumpLL();
     }
 
     void
@@ -196,7 +196,7 @@ namespace llarp
                         info.upstream, " to ", info.downstream);
         r->SendToOrQueue(info.downstream, &msg);
       }
-      r->linkManager().PumpLinks();
+      r->PumpLL();
     }
 
     void
@@ -435,7 +435,7 @@ namespace llarp
     TransitHop::QueueDestroySelf(AbstractRouter* r)
     {
       auto func = std::bind(&TransitHop::SetSelfDestruct, shared_from_this());
-      r->logic()->queue_func(func);
+      LogicCall(r->logic(), func);
     }
   }  // namespace path
 }  // namespace llarp

llarp/router/outbound_message_handler.cpp

@@ -167,9 +167,8 @@ namespace llarp
   {
     if(callback)
     {
-      auto func = std::bind(callback, status);
-      _logic->queue_func(
-          [self = this, func]() { self->m_Killer.TryAccess(func); });
+      auto f = std::bind(callback, status);
+      LogicCall(_logic, [self = this, f]() { self->m_Killer.TryAccess(f); });
     }
   }
 

llarp/router/outbound_session_maker.cpp

@@ -219,7 +219,7 @@ namespace llarp
     if(ShouldConnectTo(router))
     {
       auto fn = std::bind(&OutboundSessionMaker::DoEstablish, this, router);
-      _logic->queue_func(fn);
+      LogicCall(_logic, fn);
     }
   }
 
@@ -326,7 +326,7 @@ namespace llarp
     for(const auto &callback : movedCallbacks)
     {
       auto func = std::bind(callback, router, type);
-      _logic->queue_func(func);
+      LogicCall(_logic, func);
     }
 
     {

llarp/router/router.cpp

@@ -307,7 +307,7 @@ namespace llarp
       return;
     auto *self          = static_cast< Router * >(user);
     self->ticker_job_id = 0;
-    self->logic()->queue_func(std::bind(&Router::Tick, self));
+    LogicCall(self->logic(), std::bind(&Router::Tick, self));
     self->ScheduleTicker(orig);
   }
 

llarp/service/async_key_exchange.cpp

@@ -69,7 +69,7 @@ namespace llarp
       self->msg.version = LLARP_PROTO_VERSION;
       // encrypt and sign
       if(self->frame->EncryptAndSign(self->msg, K, self->m_LocalIdentity))
-        self->logic->queue_func(std::bind(&AsyncKeyExchange::Result, self));
+        LogicCall(self->logic, std::bind(&AsyncKeyExchange::Result, self));
       else
       {
         LogError("failed to encrypt and sign");

llarp/service/endpoint.cpp

@@ -1046,7 +1046,8 @@ namespace llarp
     {
       const auto& sessions = m_state->m_SNodeSessions;
       auto& queue          = m_state->m_InboundTrafficQueue;
-      EndpointLogic()->queue_func([&]() {
+
+      LogicCall(EndpointLogic(), [&]() {
         // send downstream packets to user for snode
         for(const auto& item : sessions)
           item.second.first->FlushDownstream();

llarp/service/lookup.cpp

@@ -26,7 +26,7 @@ namespace llarp
       if(!msg)
         return false;
       endpoint = path->Endpoint();
-      r->logic()->queue_func([=]() { path->SendRoutingMessage(*msg, r); });
+      LogicCall(r->logic(), [=]() { path->SendRoutingMessage(*msg, r); });
       return true;
     }
   }  // namespace service

llarp/service/protocol.cpp

@@ -343,8 +343,8 @@ namespace llarp
         std::shared_ptr< ProtocolMessage > msg = std::move(self->msg);
         path::Path_ptr path                    = std::move(self->path);
         const PathID_t from                    = self->frame.F;
-        self->logic->queue_func(
-            [=]() { ProtocolMessage::ProcessAsync(path, from, msg); });
+        LogicCall(self->logic,
+                  [=]() { ProtocolMessage::ProcessAsync(path, from, msg); });
         delete self;
       }
     };
@@ -409,8 +409,9 @@ namespace llarp
       }
       msg->handler            = handler;
       const PathID_t fromPath = F;
-      logic->queue_func(
-          [=]() { ProtocolMessage::ProcessAsync(recvPath, fromPath, msg); });
+      LogicCall(logic, [=]() {
+        ProtocolMessage::ProcessAsync(recvPath, fromPath, msg);
+      });
       return true;
     }
 

llarp/service/sendcontext.cpp

@@ -100,7 +100,7 @@ namespace llarp
           LogError(self->m_Endpoint->Name(), " failed to sign message");
           return;
         }
-        self->m_Endpoint->RouterLogic()->queue_func([self, f, path]() {
+        LogicCall(self->m_Endpoint->RouterLogic(), [self, f, path]() {
           self->Send(f, path);
           self->FlushUpstream();
         });

llarp/util/logging/android_logger.cpp

@@ -14,9 +14,10 @@ namespace llarp
     switch(lvl)
     {
       case eLogNone:
-        break;
-      case eLogDebug:
-        ss << "[DBG] ";
+        return;
+      case eLogTrace:
+        ss << "[TRC] ";
+        break case eLogDebug : ss << "[DBG] ";
         break;
       case eLogInfo:
         ss << "[NFO] ";
@@ -49,6 +50,9 @@ namespace llarp
     str += tag;
     switch(lvl)
     {
+      case eLogTrace:
+        __android_log_write(ANDROID_LOG_TRACE, str.c_str(), msg.c_str());
+        return;
       case eLogDebug:
         __android_log_write(ANDROID_LOG_DEBUG, str.c_str(), msg.c_str());
         return;

llarp/util/logging/logger.hpp

@@ -236,15 +236,29 @@ namespace llarp
   */
 }  // namespace llarp
 
+#define LogTrace(...) _Log(llarp::eLogTrace, LOG_TAG, __LINE__, __VA_ARGS__)
 #define LogDebug(...) _Log(llarp::eLogDebug, LOG_TAG, __LINE__, __VA_ARGS__)
 #define LogInfo(...) _Log(llarp::eLogInfo, LOG_TAG, __LINE__, __VA_ARGS__)
 #define LogWarn(...) _Log(llarp::eLogWarn, LOG_TAG, __LINE__, __VA_ARGS__)
 #define LogError(...) _Log(llarp::eLogError, LOG_TAG, __LINE__, __VA_ARGS__)
+
+#define LogTraceTag(tag, ...) _Log(llarp::eLogTrace, tag, __LINE__, __VA_ARGS__)
 #define LogDebugTag(tag, ...) _Log(llarp::eLogDebug, tag, __LINE__, __VA_ARGS__)
 #define LogInfoTag(tag, ...) _Log(llarp::eLogInfo, tag, __LINE__, __VA_ARGS__)
 #define LogWarnTag(tag, ...) _Log(llarp::eLogWarn, tag, __LINE__, __VA_ARGS__)
 #define LogErrorTag(tag, ...) _Log(llarp::eLogError, tag, __LINE__, __VA_ARGS__)
 
+#define LogTraceExplicit(tag, line, ...) \
+  _Log(llarp::eLogTrace, tag, line, __VA_ARGS__)
+#define LogDebugExplicit(tag, line, ...) \
+  _Log(llarp::eLogDebug, tag, line, __VA_ARGS__)
+#define LogInfoExplicit(tag, line, ...) \
+  _Log(llarp::eLogInfo, tag, line __VA_ARGS__)
+#define LogWarnExplicit(tag, line, ...) \
+  _Log(llarp::eLogWarn, tag, line, __VA_ARGS__)
+#define LogErrorExplicit(tag, line, ...) \
+  _Log(llarp::eLogError, tag, line, __VA_ARGS__)
+
 #ifndef LOG_TAG
 #define LOG_TAG "default"
 #endif

llarp/util/logging/loglevel.cpp

@@ -7,6 +7,8 @@ namespace llarp
   {
     switch(lvl)
     {
+      case eLogTrace:
+        return "TRC";
       case eLogDebug:
         return "DBG";
       case eLogInfo:

llarp/util/logging/loglevel.hpp

@@ -7,6 +7,7 @@ namespace llarp
   // probably will need to move out of llarp namespace for c api
   enum LogLevel
   {
+    eLogTrace,
     eLogDebug,
     eLogInfo,
     eLogWarn,

llarp/util/logging/ostream_logger.cpp

@@ -18,7 +18,8 @@ namespace llarp
       switch(lvl)
       {
         case eLogNone:
-          break;
+          return;
+        case eLogTrace:
         case eLogDebug:
           ss << (char)27 << "[0m";
           break;

llarp/util/logging/syslog_logger.cpp

@@ -23,6 +23,7 @@ namespace llarp
     {
       case eLogNone:
         return;
+      case eLogTrace:
       case eLogDebug:
         ::syslog(LOG_DEBUG, "%s", msg.c_str());
         return;

llarp/util/logging/win32_logger.cpp

@@ -34,6 +34,8 @@ namespace llarp
       {
         case eLogNone:
           break;
+        case eLogTrace:
+          ss << "[TRC] ";
         case eLogDebug:
           ss << "[DBG] ";
           break;

llarp/util/thread/logic.cpp

@@ -39,7 +39,8 @@ namespace llarp
   bool
   Logic::queue_job(struct llarp_thread_job job)
   {
-    return job.user && job.work && queue_func(std::bind(job.work, job.user));
+    return job.user && job.work
+        && LogicCall(this, std::bind(job.work, job.user));
   }
 
   void
@@ -47,31 +48,50 @@ namespace llarp
   {
     llarp::LogDebug("logic thread stop");
     // stop all timers from happening in the future
-    queue_func(std::bind(&llarp_timer_stop, m_Timer));
+    LogicCall(this, std::bind(&llarp_timer_stop, m_Timer));
     // stop all operations on threadpool
     llarp_threadpool_stop(m_Thread);
   }
 
   bool
-  Logic::queue_func(std::function< void(void) > func)
+  Logic::_traceLogicCall(std::function< void(void) > func, const char* tag,
+                         int line)
   {
+#define TAG (tag ? tag : LOG_TAG)
+#define LINE (line ? line : __LINE__)
     // wrap the function so that we ensure that it's always calling stuff one at
     // a time
-    auto f = [self = this, func]() { self->m_Killer.TryAccess(func); };
+
+    LogTraceExplicit(TAG, LINE, "queue");
+
+    auto f = [self = this, func, tag, line]() {
+      LogTraceExplicit(TAG, LINE, "exec");
+      self->m_Killer.TryAccess(func);
+      LogTraceExplicit(TAG, LINE, "return");
+    };
     if(m_Thread->LooksFull(5))
     {
-      LogWarn(
-          "holy crap, we are trying to queue a job onto the logic thread but "
-          "it looks full");
+      LogWarnExplicit(TAG, LINE,
+                      "holy crap, we are trying to queue a job onto the logic "
+                      "thread but "
+                      "it looks full");
+
       if(can_flush())
       {
         // we are calling in the logic thread and our queue looks full
         // defer call to a later time so we don't die like a little bitch
-        call_later(m_Thread->GuessJobLatency() / 2, f);
+        const auto delay = m_Thread->GuessJobLatency() / 2;
+
+        LogWarnExplicit(TAG, LINE, "deferring call by ", delay, " ms");
+        call_later(delay, f);
         return true;
       }
     }
-    return llarp_threadpool_queue_job(m_Thread, f);
+    auto ret = llarp_threadpool_queue_job(m_Thread, f);
+    LogTraceExplicit(TAG, LINE, "==");
+    return ret;
+#undef TAG
+#undef LINE
   }
 
   void

llarp/util/thread/logic.hpp

@@ -27,7 +27,8 @@ namespace llarp
     queue_job(struct llarp_thread_job job);
 
     bool
-    queue_func(std::function< void(void) > func);
+    _traceLogicCall(std::function< void(void) > func, const char* filename,
+                    int lineo);
 
     uint32_t
     call_later(const llarp_timeout_job& job);
@@ -53,4 +54,16 @@ namespace llarp
   };
 }  // namespace llarp
 
+#ifndef LogicCall
+#if defined(LOKINET_DEBUG)
+#ifdef LOG_TAG
+#define LogicCall(l, ...) l->_traceLogicCall(__VA_ARGS__, LOG_TAG, __LINE__)
+#else
+#define LogicCall(l, ...) l->_traceLogicCall(__VA_ARGS__, __FILE__, __LINE__)
+#endif
+#else
+#define LogicCall(l, ...) l->_traceLogicCall(__VG_ARGS__, 0, 0)
+#endif
+#endif
+
 #endif

test/link/test_llarp_link.cpp

@@ -127,7 +127,7 @@ struct LinkLayerTest : public test::LlarpTest< llarp::sodium::CryptoLibSodium >
   Context Bob;
 
   bool success = false;
-  const bool shouldDebug = true;
+  const bool shouldDebug = false;
 
   llarp_ev_loop_ptr netLoop;
   std::shared_ptr< Logic > m_logic;
@@ -144,7 +144,7 @@ struct LinkLayerTest : public test::LlarpTest< llarp::sodium::CryptoLibSodium >
   {
     oldLevel = llarp::LogContext::Instance().minLevel;
     if(shouldDebug)
-      llarp::SetLogLevel(eLogDebug);
+      llarp::SetLogLevel(eLogTrace);
     oldRCLifetime              = RouterContact::Lifetime;
     RouterContact::BlockBogons = false;
     RouterContact::Lifetime    = 500;
@@ -285,7 +285,7 @@ TEST_F(LinkLayerTest, TestIWP)
   ASSERT_TRUE(Alice.Start(m_logic, netLoop, AlicePort));
   ASSERT_TRUE(Bob.Start(m_logic, netLoop, BobPort));
 
-  m_logic->queue_func([&]() { ASSERT_TRUE(Alice.link->TryEstablishTo(Bob.GetRC())); });
+  LogicCall(m_logic, [&]() { ASSERT_TRUE(Alice.link->TryEstablishTo(Bob.GetRC())); });
 
   RunMainloop();
   ASSERT_TRUE(Alice.IsGucci());