Merge #6073: feat: add logging for RPC HTTP requests: command, user, http-code, time of running

1a691bd100 feat: add logging for RPC HTTP requests: command, user, http-code, time of running (Konstantin Akimov)

Pull request description:

  ## Issue being fixed or feature implemented
  Currently there is no way to gather stats for http rpc in dash core. This PR aim to change it.

  ## What was done?
  Implemented some basic stats for each RPC request:
   - rpc command
   - flag "is external"
   - http status
   - time to serve query (rpc time, not http time)

  ## How Has This Been Tested?
  See new logs:
  ```log
  [httpworker.0] [httprpc.cpp:100] [~RpcHttpRequest] -- HTTP RPC request handled: user=platform-user command=getbestblockhash is_external=false status=200 elapsed_time_ms=0
  [httpworker.2] [httprpc.cpp:100] [~RpcHttpRequest] -- HTTP RPC request handled: user=platform-user command=quorum is_external=false status=500 elapsed_time_ms=0
  [httpworker.3] [httprpc.cpp:100] [~RpcHttpRequest] -- HTTP RPC request handled: user=platform-user command= is_external=false status=401 elapsed_time_ms=0
  [httpworker.3] [httprpc.cpp:100] [~RpcHttpRequest] -- HTTP RPC request handled: user=platform-user command=getbestblockhash is_external=true status=200 elapsed_time_ms=28
  [httpworker.0] [httprpc.cpp:100] [~RpcHttpRequest] -- HTTP RPC request handled: user=operator command=getbestblockhash is_external=false status=200 elapsed_time_ms=0
  ```

  ## Breaking Changes
  N/A
  It doesn't change behavior of rpc server and http server.

  ## Checklist:
  - [x] I have performed a self-review of my own code
  - [x] I have commented my code, particularly in hard-to-understand areas
  - [ ] I have added or updated relevant unit/integration/functional/e2e tests
  - [ ] I have made corresponding changes to the documentation
  - [x] I have assigned this pull request to a milestone

ACKs for top commit:
  PastaPastaPasta:
    utACK 1a691bd100

Tree-SHA512: b62fceedb9a901e87c23c4aa6e6dfa7226d44da84a081ea245b40e7ff887103302147cebe0f7ff90bf9c8d4fa9ecafbaa6f25f39d2008f62c4f2beeef2877b57

src/httprpc.cpp

@@ -72,7 +72,36 @@ static std::vector<std::vector<std::string>> g_rpcauth;
 static std::map<std::string, std::set<std::string>> g_rpc_whitelist;
 static bool g_rpc_whitelist_default = false;
 
-static void JSONErrorReply(HTTPRequest* req, const UniValue& objError, const UniValue& id)
+extern std::vector<std::string> g_external_usernames;
+class RpcHttpRequest
+{
+public:
+    HTTPRequest* m_req;
+    int64_t m_startTime;
+    int m_status{0};
+    std::string user;
+    std::string command;
+
+    RpcHttpRequest(HTTPRequest* req) :
+        m_req{req},
+        m_startTime{GetTimeMicros()}
+    {}
+
+    ~RpcHttpRequest()
+    {
+        const bool is_external = find(g_external_usernames.begin(), g_external_usernames.end(), user) != g_external_usernames.end();
+        LogPrint(BCLog::BENCHMARK, "HTTP RPC request handled: user=%s command=%s external=%s status=%d elapsed_time_ms=%d\n", user, command, is_external, m_status, (GetTimeMicros() - m_startTime) / 1000);
+    }
+
+    bool send_reply(int status, const std::string& response = "")
+    {
+        m_status = status;
+        m_req->WriteReply(status, response);
+        return m_status == HTTP_OK;
+    }
+};
+
+static bool JSONErrorReply(RpcHttpRequest& rpcRequest, const UniValue& objError, const UniValue& id)
 {
     // Send error reply from json-rpc error object
     int nStatus = HTTP_INTERNAL_SERVER_ERROR;
@@ -88,8 +117,8 @@ static void JSONErrorReply(HTTPRequest* req, const UniValue& objError, const Uni
 
     std::string strReply = JSONRPCReply(NullUniValue, objError, id);
 
-    req->WriteHeader("Content-Type", "application/json");
+    rpcRequest.m_req->WriteHeader("Content-Type", "application/json");
-    req->WriteReply(nStatus, strReply);
+    return rpcRequest.send_reply(nStatus, strReply);
 }
 
 //This function checks username and password against -rpcauth
@@ -146,24 +175,25 @@ static bool RPCAuthorized(const std::string& strAuth, std::string& strAuthUserna
     return multiUserAuthorized(strUserPass);
 }
 
-static bool HTTPReq_JSONRPC(const CoreContext& context, HTTPRequest* req, bool external = false)
+static bool HTTPReq_JSONRPC(const CoreContext& context, HTTPRequest* req)
 {
+    RpcHttpRequest rpcRequest(req);
+
     // JSONRPC handles only POST
     if (req->GetRequestMethod() != HTTPRequest::POST) {
-        req->WriteReply(HTTP_BAD_METHOD, "JSONRPC server handles only POST requests");
+        return rpcRequest.send_reply(HTTP_BAD_METHOD, "JSONRPC server handles only POST requests");
-        return false;
     }
     // Check authorization
     std::pair<bool, std::string> authHeader = req->GetHeader("authorization");
     if (!authHeader.first) {
         req->WriteHeader("WWW-Authenticate", WWW_AUTH_HEADER_DATA);
-        req->WriteReply(HTTP_UNAUTHORIZED);
+        return rpcRequest.send_reply(HTTP_UNAUTHORIZED);
-        return false;
     }
 
     JSONRPCRequest jreq(context);
+
     jreq.peerAddr = req->GetPeer().ToString();
-    if (!RPCAuthorized(authHeader.second, jreq.authUser)) {
+    if (!RPCAuthorized(authHeader.second, rpcRequest.user)) {
         LogPrintf("ThreadRPCServer incorrect password attempt from %s\n", jreq.peerAddr);
 
         /* Deter brute-forcing
@@ -172,9 +202,9 @@ static bool HTTPReq_JSONRPC(const CoreContext& context, HTTPRequest* req, bool e
         UninterruptibleSleep(std::chrono::milliseconds{250});
 
         req->WriteHeader("WWW-Authenticate", WWW_AUTH_HEADER_DATA);
-        req->WriteReply(HTTP_UNAUTHORIZED);
+        return rpcRequest.send_reply(HTTP_UNAUTHORIZED);
-        return false;
     }
+    jreq.authUser = rpcRequest.user;
 
     try {
         // Parse request
@@ -189,16 +219,16 @@ static bool HTTPReq_JSONRPC(const CoreContext& context, HTTPRequest* req, bool e
         bool user_has_whitelist = g_rpc_whitelist.count(jreq.authUser);
         if (!user_has_whitelist && g_rpc_whitelist_default) {
             LogPrintf("RPC User %s not allowed to call any methods\n", jreq.authUser);
-            req->WriteReply(HTTP_FORBIDDEN);
+            return rpcRequest.send_reply(HTTP_FORBIDDEN);
-            return false;
 
         // singleton request
         } else if (valRequest.isObject()) {
             jreq.parse(valRequest);
+            rpcRequest.command = jreq.strMethod;
+
             if (user_has_whitelist && !g_rpc_whitelist[jreq.authUser].count(jreq.strMethod)) {
                 LogPrintf("RPC User %s not allowed to call method %s\n", jreq.authUser, jreq.strMethod);
-                req->WriteReply(HTTP_FORBIDDEN);
+                return rpcRequest.send_reply(HTTP_FORBIDDEN);
-                return false;
             }
             UniValue result = tableRPC.execute(jreq);
 
@@ -217,8 +247,7 @@ static bool HTTPReq_JSONRPC(const CoreContext& context, HTTPRequest* req, bool e
                         std::string strMethod = find_value(request, "method").get_str();
                         if (!g_rpc_whitelist[jreq.authUser].count(strMethod)) {
                             LogPrintf("RPC User %s not allowed to call method %s\n", jreq.authUser, strMethod);
-                            req->WriteReply(HTTP_FORBIDDEN);
+                            return rpcRequest.send_reply(HTTP_FORBIDDEN);
-                            return false;
                         }
                     }
                 }
@@ -229,15 +258,13 @@ static bool HTTPReq_JSONRPC(const CoreContext& context, HTTPRequest* req, bool e
             throw JSONRPCError(RPC_PARSE_ERROR, "Top-level object parse error");
 
         req->WriteHeader("Content-Type", "application/json");
-        req->WriteReply(HTTP_OK, strReply);
+        return rpcRequest.send_reply(HTTP_OK, strReply);
     } catch (const UniValue& objError) {
-        JSONErrorReply(req, objError, jreq.id);
+        return JSONErrorReply(rpcRequest, objError, jreq.id);
-        return false;
     } catch (const std::exception& e) {
-        JSONErrorReply(req, JSONRPCError(RPC_PARSE_ERROR, e.what()), jreq.id);
+        return JSONErrorReply(rpcRequest, JSONRPCError(RPC_PARSE_ERROR, e.what()), jreq.id);
-        return false;
     }
-    return true;
+    assert(false);
 }
 
 static bool InitRPCAuthentication()

src/httpserver.cpp

@@ -154,8 +154,8 @@ static struct evhttp* eventHTTP = nullptr;
 static std::vector<CSubNet> rpc_allow_subnets;
 //! Work queue for handling longer requests off the event loop thread
 static std::unique_ptr<WorkQueue<HTTPClosure>> g_work_queue{nullptr};
-//! List of 'external' RPC users
+//! List of 'external' RPC users (global variable, used by httprpc)
-static std::vector<std::string> g_external_usernames;
+std::vector<std::string> g_external_usernames;
 //! Handlers for (sub)paths
 static std::vector<HTTPPathHandler> pathHandlers;
 //! Bound listening sockets