Allow to ignore superuser traffic with an option. (#10289)

* Allow to ignore superuser traffic with an option.

Also: Fix some accounting bugs.

* CHANGELOG.

* Implement separate accounting for superuser and user traffic.

* Fix VST case with no authentication.

* Add description of new user-only traffic statistics.

* Add figures for user traffic.

* Simplify forwarding accounting.

* Remove brackets in metrics names.

* Finalize naming of metrics.

CHANGELOG

@@ -1,6 +1,9 @@
 v3.5.2 (XXXX-XX-XX)
 -------------------
 
+* Separately account for superuser and user request traffic. This is
+  needed for Oasis.
+
 * Fixed issue #10270: Query: Expecting type Array or Object (while executing).
 
 * Fix a problem with AQL constrained sort in the cluster, which might abort

arangod/GeneralServer/GeneralCommTask.cpp

@@ -320,7 +320,10 @@ void GeneralCommTask::executeRequest(std::unique_ptr<GeneralRequest>&& request,
   // forward to correct server if necessary
   bool forwarded = handler->forwardRequest();
   if (forwarded) {
-    addResponse(*handler->response(), handler->stealStatistics());
+    RequestStatistics::SET_SUPERUSER(statistics(messageId));
+    // At this point the handler does not yet have the statistics objects,
+    // so we have to take it from the CommTask.
+    addResponse(*handler->response(), stealStatistics(messageId));
     return;
   }
 

arangod/GeneralServer/HttpCommTask.cpp

@@ -587,6 +587,11 @@ bool HttpCommTask::processRead(double startTime) {
 
   // authenticated
   if (authResult != rest::ResponseCode::SERVER_ERROR) {
+    // We want to separate superuser token traffic:
+    if (_incompleteRequest->authenticated() &&
+        _incompleteRequest->user().empty()) {
+      RequestStatistics::SET_SUPERUSER(stat);
+    }
     // prepare execution will send an error message
     RequestFlow cont = prepareExecution(*_incompleteRequest.get());
     if (cont == RequestFlow::Continue) {

arangod/GeneralServer/VstCommTask.cpp

@@ -325,8 +325,6 @@ bool VstCommTask::processRead(double startTime) {
     RequestStatistics::SET_READ_START(stat, startTime);
   }
 
-  RequestStatistics::SET_READ_END(statistics(chunkHeader._messageID));
-
   if (chunkHeader._isFirst && chunkHeader._chunk == 1) {
     // CASE 1: message is in one chunk
     if (!getMessageFromSingleChunk(chunkHeader, message, doExecute, vpackBegin, chunkEnd)) {
@@ -349,6 +347,12 @@ bool VstCommTask::processRead(double startTime) {
   }
 
   if (doExecute) {
+    // A message is complete! Now we need to do the accounting, first let's
+    // set the "read-end time":
+    RequestStatistics* stat = statistics(message.id());
+    RequestStatistics::SET_READ_END(stat);
+    RequestStatistics::ADD_RECEIVED_BYTES(stat, message.totalSize());
+
     VPackSlice header = message.header();
 
     if (Logger::logRequestParameters()) {
@@ -373,6 +377,11 @@ bool VstCommTask::processRead(double startTime) {
     // handle request types
     if (type == 1000) {  // auth
       handleAuthHeader(header, chunkHeader._messageID);
+      // Separate superuser traffic:
+      if (_authMethod != AuthenticationMethod::NONE && _authorized &&
+          _authToken._username.empty()) {
+        RequestStatistics::SET_SUPERUSER(stat);
+      }
     } else if (type == 1) {  // request
 
       // the handler will take ownership of this pointer
@@ -386,6 +395,12 @@ bool VstCommTask::processRead(double startTime) {
         _auth->userManager()->refreshUser(_authToken._username);
       }
 
+      // Separate superuser traffic:
+      if (_authMethod != AuthenticationMethod::NONE && _authorized &&
+          _authToken._username.empty()) {
+        RequestStatistics::SET_SUPERUSER(stat);
+      }
+
       RequestFlow cont = prepareExecution(*req.get());
 
       if (cont == RequestFlow::Continue) {

arangod/RestHandler/RestAdminStatisticsHandler.cpp

@@ -23,6 +23,7 @@
 #include "RestAdminStatisticsHandler.h"
 #include "GeneralServer/ServerSecurityFeature.h"
 #include "Statistics/Descriptions.h"
+#include "Statistics/RequestStatistics.h"
 #include "Statistics/StatisticsFeature.h"
 
 using namespace arangodb;
@@ -82,9 +83,13 @@ void RestAdminStatisticsHandler::getStatistics() {
   tmp.close();  // system
 
   tmp.add("client", VPackValue(VPackValueType::Object, true));
-  desc->clientStatistics(tmp);
+  desc->clientStatistics(tmp, RequestStatistics::Source::ALL);
   tmp.close();  // client
 
+  tmp.add("clientUser", VPackValue(VPackValueType::Object, true));
+  desc->clientStatistics(tmp, RequestStatistics::Source::USER);
+  tmp.close();  // clientUser
+
   tmp.add("http", VPackValue(VPackValueType::Object, true));
   desc->httpStatistics(tmp);
   tmp.close();  // http

arangod/Statistics/Descriptions.cpp

@@ -41,6 +41,8 @@ std::string stats::fromGroupType(stats::GroupType gt) {
       return "system";
     case stats::GroupType::Client:
       return "client";
+    case stats::GroupType::ClientUser:
+      return "clientUser";
     case stats::GroupType::Http:
       return "http";
     case stats::GroupType::Vst:
@@ -113,6 +115,9 @@ stats::Descriptions::Descriptions()
   _groups.emplace_back(Group{stats::GroupType::Client,
                              "Client Connection Statistics",
                              "Statistics about the connections."});
+  _groups.emplace_back(Group{stats::GroupType::ClientUser,
+                             "Client User Connection Statistics",
+                             "Statistics about the connections, only user traffic (ignoring superuser JWT traffic)."});
   _groups.emplace_back(Group{stats::GroupType::Http, "HTTP Request Statistics",
                              "Statistics about the HTTP requests."});
   _groups.emplace_back(Group{stats::GroupType::Server, "Server Statistics",
@@ -248,6 +253,60 @@ stats::Descriptions::Descriptions()
              // cuts: internal.connectionTimeDistribution,
              stats::Unit::Seconds, _connectionTimeCuts});
 
+  // Only user traffic:
+
+  _figures.emplace_back(
+      Figure{stats::GroupType::ClientUser,
+             "httpConnections",
+             "Client Connections",
+             "The number of connections that are currently open (only user traffic).",
+             stats::FigureType::Current,
+             stats::Unit::Number,
+             {}});
+
+  _figures.emplace_back(
+      Figure{stats::GroupType::ClientUser, "totalTime", "Total Time",
+             "Total time needed to answer a request (only user traffic).",
+             stats::FigureType::Distribution,
+             // cuts: internal.requestTimeDistribution,
+             stats::Unit::Seconds, _requestTimeCuts});
+
+  _figures.emplace_back(
+      Figure{stats::GroupType::ClientUser, "requestTime", "Request Time",
+             "Request time needed to answer a request (only user traffic).",
+             stats::FigureType::Distribution,
+             // cuts: internal.requestTimeDistribution,
+             stats::Unit::Seconds, _requestTimeCuts});
+
+  _figures.emplace_back(
+      Figure{stats::GroupType::ClientUser, "queueTime", "Queue Time",
+             "Queue time needed to answer a request (only user traffic).",
+             stats::FigureType::Distribution,
+             // cuts: internal.requestTimeDistribution,
+             stats::Unit::Seconds, _requestTimeCuts});
+
+  _figures.emplace_back(Figure{stats::GroupType::ClientUser, "bytesSent",
+                               "Bytes Sent",
+                               "Bytes sents for a request (only user traffic).",
+                               stats::FigureType::Distribution,
+                               // cuts: internal.bytesSentDistribution,
+                               stats::Unit::Bytes, _bytesSendCuts});
+
+  _figures.emplace_back(Figure{stats::GroupType::ClientUser, "bytesReceived",
+                               "Bytes Received",
+                               "Bytes received for a request (only user traffic).",
+                               stats::FigureType::Distribution,
+                               // cuts: internal.bytesReceivedDistribution,
+                               stats::Unit::Bytes, _bytesReceivedCuts});
+
+  _figures.emplace_back(
+      Figure{stats::GroupType::ClientUser, "connectionTime",
+             "Connection Time",
+             "Total connection time of a client (only user traffic).",
+             stats::FigureType::Distribution,
+             // cuts: internal.connectionTimeDistribution,
+             stats::Unit::Seconds, _connectionTimeCuts});
+
   _figures.emplace_back(Figure{stats::GroupType::Http,
                                "requestsTotal",
                                "Total requests",
@@ -412,7 +471,7 @@ static void FillDistribution(VPackBuilder& b, std::string const& name,
   b.close();
 }
 
-void stats::Descriptions::clientStatistics(velocypack::Builder& b) const {
+void stats::Descriptions::clientStatistics(velocypack::Builder& b, RequestStatistics::Source source) const {
   basics::StatisticsCounter httpConnections;
   basics::StatisticsCounter totalRequests;
   std::array<basics::StatisticsCounter, basics::MethodRequestsStatisticsSize> methodRequests;
@@ -433,7 +492,7 @@ void stats::Descriptions::clientStatistics(velocypack::Builder& b) const {
   basics::StatisticsDistribution bytesSent;
   basics::StatisticsDistribution bytesReceived;
 
-  RequestStatistics::fill(totalTime, requestTime, queueTime, ioTime, bytesSent, bytesReceived);
+  RequestStatistics::fill(totalTime, requestTime, queueTime, ioTime, bytesSent, bytesReceived, source);
 
   FillDistribution(b, "totalTime", totalTime);
   FillDistribution(b, "requestTime", requestTime);

arangod/Statistics/Descriptions.h

@@ -28,10 +28,12 @@
 #include <velocypack/Builder.h>
 #include <string>
 
+#include "Statistics/RequestStatistics.h"
+
 namespace arangodb {
 namespace stats {
 
-enum class GroupType { System, Client, Http, Vst, Server };
+enum class GroupType { System, Client, ClientUser, Http, Vst, Server };
 
 std::string fromGroupType(stats::GroupType);
 
@@ -75,7 +77,7 @@ class Descriptions final {
   std::vector<stats::Figure> const& figures() const { return _figures; }
 
   void serverStatistics(velocypack::Builder&) const;
-  void clientStatistics(velocypack::Builder&) const;
+  void clientStatistics(velocypack::Builder&, RequestStatistics::Source source) const;
   void httpStatistics(velocypack::Builder&) const;
   void processStatistics(velocypack::Builder&) const;
 

arangod/Statistics/RequestStatistics.cpp

@@ -124,26 +124,50 @@ void RequestStatistics::process(RequestStatistics* statistics) {
         totalTime = statistics->_writeEnd - statistics->_readStart;
       }
 
-      TRI_TotalTimeDistributionStatistics.addFigure(totalTime);
+      if (statistics->_superuser) {
+        TRI_TotalTimeDistributionStatistics.addFigure(totalTime);
 
-      double requestTime = statistics->_requestEnd - statistics->_requestStart;
+        double requestTime = statistics->_requestEnd - statistics->_requestStart;
-      TRI_RequestTimeDistributionStatistics.addFigure(requestTime);
+        TRI_RequestTimeDistributionStatistics.addFigure(requestTime);
 
-      double queueTime = 0.0;
+        double queueTime = 0.0;
+
+        if (statistics->_queueStart != 0.0 && statistics->_queueEnd != 0.0) {
+          queueTime = statistics->_queueEnd - statistics->_queueStart;
+          TRI_QueueTimeDistributionStatistics.addFigure(queueTime);
+        }
+
+        double ioTime = totalTime - requestTime - queueTime;
+
+        if (ioTime >= 0.0) {
+          TRI_IoTimeDistributionStatistics.addFigure(ioTime);
+        }
+
+        TRI_BytesSentDistributionStatistics.addFigure(statistics->_sentBytes);
+        TRI_BytesReceivedDistributionStatistics.addFigure(statistics->_receivedBytes);
+      } else {
+        TRI_TotalTimeDistributionStatisticsUser.addFigure(totalTime);
+
+        double requestTime = statistics->_requestEnd - statistics->_requestStart;
+        TRI_RequestTimeDistributionStatisticsUser.addFigure(requestTime);
+
+        double queueTime = 0.0;
+
+        if (statistics->_queueStart != 0.0 && statistics->_queueEnd != 0.0) {
+          queueTime = statistics->_queueEnd - statistics->_queueStart;
+          TRI_QueueTimeDistributionStatisticsUser.addFigure(queueTime);
+        }
+
+        double ioTime = totalTime - requestTime - queueTime;
+
+        if (ioTime >= 0.0) {
+          TRI_IoTimeDistributionStatisticsUser.addFigure(ioTime);
+        }
+
+        TRI_BytesSentDistributionStatisticsUser.addFigure(statistics->_sentBytes);
+        TRI_BytesReceivedDistributionStatisticsUser.addFigure(statistics->_receivedBytes);
 
-      if (statistics->_queueStart != 0.0 && statistics->_queueEnd != 0.0) {
-        queueTime = statistics->_queueEnd - statistics->_queueStart;
-        TRI_QueueTimeDistributionStatistics.addFigure(queueTime);
       }
-
-      double ioTime = totalTime - requestTime - queueTime;
-
-      if (ioTime >= 0.0) {
-        TRI_IoTimeDistributionStatistics.addFigure(ioTime);
-      }
-
-      TRI_BytesSentDistributionStatistics.addFigure(statistics->_sentBytes);
-      TRI_BytesReceivedDistributionStatistics.addFigure(statistics->_receivedBytes);
     }
   }
 
@@ -188,18 +212,36 @@ void RequestStatistics::fill(StatisticsDistribution& totalTime,
                              StatisticsDistribution& requestTime,
                              StatisticsDistribution& queueTime,
                              StatisticsDistribution& ioTime, StatisticsDistribution& bytesSent,
-                             StatisticsDistribution& bytesReceived) {
+                             StatisticsDistribution& bytesReceived,
+                             Source source) {
   if (!StatisticsFeature::enabled()) {
     // all the below objects may be deleted if we don't have statistics enabled
     return;
   }
 
-  totalTime = TRI_TotalTimeDistributionStatistics;
+  if (source == Source::USER) {
-  requestTime = TRI_RequestTimeDistributionStatistics;
+    totalTime = TRI_TotalTimeDistributionStatisticsUser;
-  queueTime = TRI_QueueTimeDistributionStatistics;
+    requestTime = TRI_RequestTimeDistributionStatisticsUser;
-  ioTime = TRI_IoTimeDistributionStatistics;
+    queueTime = TRI_QueueTimeDistributionStatisticsUser;
-  bytesSent = TRI_BytesSentDistributionStatistics;
+    ioTime = TRI_IoTimeDistributionStatisticsUser;
-  bytesReceived = TRI_BytesReceivedDistributionStatistics;
+    bytesSent = TRI_BytesSentDistributionStatisticsUser;
+    bytesReceived = TRI_BytesReceivedDistributionStatisticsUser;
+  } else {
+    totalTime = TRI_TotalTimeDistributionStatistics;
+    requestTime = TRI_RequestTimeDistributionStatistics;
+    queueTime = TRI_QueueTimeDistributionStatistics;
+    ioTime = TRI_IoTimeDistributionStatistics;
+    bytesSent = TRI_BytesSentDistributionStatistics;
+    bytesReceived = TRI_BytesReceivedDistributionStatistics;
+  }
+  if (source == Source::ALL) {
+    totalTime.add(TRI_TotalTimeDistributionStatisticsUser);
+    requestTime.add(TRI_RequestTimeDistributionStatisticsUser);
+    queueTime.add(TRI_QueueTimeDistributionStatisticsUser);
+    ioTime.add(TRI_IoTimeDistributionStatisticsUser);
+    bytesSent.add(TRI_BytesSentDistributionStatisticsUser);
+    bytesReceived.add(TRI_BytesReceivedDistributionStatisticsUser);
+  }
 }
 
 std::string RequestStatistics::timingsCsv() {
@@ -231,7 +273,8 @@ std::string RequestStatistics::to_string() {
      << "_async          " << _async << std::endl
      << "_tooLarge       " << _tooLarge << std::endl
      << "_executeError   " << _executeError << std::endl
-     << "_ignore         " << _ignore << std::endl;
+     << "_ignore         " << _ignore << std::endl
+     << "_superuser      " << _superuser << std::endl;
 
   return ss.str();
 }
@@ -278,4 +321,7 @@ void RequestStatistics::trace_log() {
 
   LOG_TOPIC("31657", TRACE, Logger::REQUESTS) << std::boolalpha << std::setprecision(20)
                                      << "_ignore         " << _ignore;
+
+  LOG_TOPIC("31658", TRACE, Logger::REQUESTS) << std::boolalpha << std::setprecision(20)
+                                     << "_superuser      " << _superuser;
 }

arangod/Statistics/RequestStatistics.h

@@ -144,14 +144,27 @@ class RequestStatistics {
     }
   }
 
+  static void SET_SUPERUSER(RequestStatistics* stat) {
+    if (stat != nullptr) {
+      stat->_superuser = true;
+    }
+  }
+
   double requestStart() const { return _requestStart; }
 
+  enum Source {
+    USER,
+    SUPERUSER,
+    ALL
+  };
+
   static void fill(basics::StatisticsDistribution& totalTime,
                    basics::StatisticsDistribution& requestTime,
                    basics::StatisticsDistribution& queueTime,
                    basics::StatisticsDistribution& ioTime,
                    basics::StatisticsDistribution& bytesSent,
-                   basics::StatisticsDistribution& bytesReceived);
+                   basics::StatisticsDistribution& bytesReceived,
+                   Source source);
 
   std::string timingsCsv();
   std::string to_string();
@@ -189,6 +202,7 @@ class RequestStatistics {
     _ignore = false;
     _released = true;
     _inQueue = false;
+    _superuser = false;
   }
 
   double _readStart;   // CommTask::processRead - read first byte of message
@@ -213,6 +227,7 @@ class RequestStatistics {
   bool _ignore;
   bool _released;
   bool _inQueue;
+  bool _superuser;
 };
 }  // namespace arangodb
 

arangod/Statistics/StatisticsFeature.cpp

@@ -70,6 +70,12 @@ StatisticsDistribution TRI_IoTimeDistributionStatistics(TRI_RequestTimeDistribut
 StatisticsDistribution TRI_QueueTimeDistributionStatistics(TRI_RequestTimeDistributionVectorStatistics);
 StatisticsDistribution TRI_RequestTimeDistributionStatistics(TRI_RequestTimeDistributionVectorStatistics);
 StatisticsDistribution TRI_TotalTimeDistributionStatistics(TRI_RequestTimeDistributionVectorStatistics);
+StatisticsDistribution TRI_BytesReceivedDistributionStatisticsUser(TRI_BytesReceivedDistributionVectorStatistics);
+StatisticsDistribution TRI_BytesSentDistributionStatisticsUser(TRI_BytesSentDistributionVectorStatistics);
+StatisticsDistribution TRI_IoTimeDistributionStatisticsUser(TRI_RequestTimeDistributionVectorStatistics);
+StatisticsDistribution TRI_QueueTimeDistributionStatisticsUser(TRI_RequestTimeDistributionVectorStatistics);
+StatisticsDistribution TRI_RequestTimeDistributionStatisticsUser(TRI_RequestTimeDistributionVectorStatistics);
+StatisticsDistribution TRI_TotalTimeDistributionStatisticsUser(TRI_RequestTimeDistributionVectorStatistics);
 
 }  // namespace basics
 }  // namespace arangodb

arangod/Statistics/StatisticsFeature.h

@@ -56,6 +56,12 @@ extern StatisticsDistribution TRI_IoTimeDistributionStatistics;
 extern StatisticsDistribution TRI_QueueTimeDistributionStatistics;
 extern StatisticsDistribution TRI_RequestTimeDistributionStatistics;
 extern StatisticsDistribution TRI_TotalTimeDistributionStatistics;
+extern StatisticsDistribution TRI_BytesReceivedDistributionStatisticsUser;
+extern StatisticsDistribution TRI_BytesSentDistributionStatisticsUser;
+extern StatisticsDistribution TRI_IoTimeDistributionStatisticsUser;
+extern StatisticsDistribution TRI_QueueTimeDistributionStatisticsUser;
+extern StatisticsDistribution TRI_RequestTimeDistributionStatisticsUser;
+extern StatisticsDistribution TRI_TotalTimeDistributionStatisticsUser;
 }  // namespace basics
 namespace stats {
 class Descriptions;

arangod/Statistics/StatisticsWorker.cpp

@@ -838,7 +838,7 @@ void StatisticsWorker::generateRawStatistics(VPackBuilder& builder, double const
   StatisticsDistribution bytesSent;
   StatisticsDistribution bytesReceived;
 
-  RequestStatistics::fill(totalTime, requestTime, queueTime, ioTime, bytesSent, bytesReceived);
+  RequestStatistics::fill(totalTime, requestTime, queueTime, ioTime, bytesSent, bytesReceived, RequestStatistics::Source::ALL);
 
   ServerStatistics const& serverInfo = ServerStatistics::statistics();
 

arangod/Statistics/figures.h

@@ -93,6 +93,19 @@ struct StatisticsDistribution {
     ++(*j);
   }
 
+  void add(StatisticsDistribution& other) {
+    MUTEX_LOCKER(lock, _mutex);
+    MUTEX_LOCKER(lock2, other._mutex);
+    TRI_ASSERT(_counts.size() == other._counts.size() &&
+               _cuts.size() == _cuts.size());
+    _count += other._count;
+    _total += other._total;
+    for (size_t i = 0; i < _counts.size(); ++i) {
+      TRI_ASSERT(i < _cuts.size() ? _cuts[i] == other._cuts[i] : true);
+      _counts[i] += other._counts[i];
+    }
+  }
+
   uint64_t _count;
   double _total;
   std::vector<double> _cuts;

arangod/V8Server/v8-statistics.cpp

@@ -225,7 +225,7 @@ static void JS_ClientStatistics(v8::FunctionCallbackInfo<v8::Value> const& args)
   StatisticsDistribution bytesSent;
   StatisticsDistribution bytesReceived;
 
-  RequestStatistics::fill(totalTime, requestTime, queueTime, ioTime, bytesSent, bytesReceived);
+  RequestStatistics::fill(totalTime, requestTime, queueTime, ioTime, bytesSent, bytesReceived, RequestStatistics::Source::ALL);
 
   FillDistribution(isolate, result, TRI_V8_ASCII_STRING(isolate, "totalTime"), totalTime);
   FillDistribution(isolate, result, TRI_V8_ASCII_STRING(isolate, "requestTime"), requestTime);

lib/Rest/VstMessage.h

@@ -73,6 +73,14 @@ struct VstInputMessage {
     return _buffer.size() - len;
   }
 
+  uint64_t id() const {
+    return _id;
+  }
+
+  uint64_t totalSize() const {
+    return _buffer.size();
+  }
+
  private:
   uint64_t _id;  // id zero signals invalid state
   velocypack::Buffer<uint8_t> _buffer;