HPCC-15207 Serialize ESP TxSummary items based on a log level

1. Always to store a TXSummary item with the log level even if
the log level is greater than preconfigured ESP TxSummaryLevel.
2. Add logLevel as an input of CTxSummary::serialize() and only
serialize a TxSummary item if its logLevel is equal to or lower
than the input.
3. Use preconfigured ESP TxSummaryLevel to serialize TxSummary
items when ESP writes TxSummary into ESP log.

Signed-off-by: wangkx <kevin.wang@lexisnexis.com>

esp/platform/cumulativetimer.hpp

@@ -20,6 +20,7 @@
 
 #include "jiface.hpp"
 #include "jutil.hpp"
+#include "esp.hpp"
 
 // Utility class for tracking cumulative elapsed time. Once instantiated, an
 // instance's total time can be updated multiple times. When used with the
@@ -49,6 +50,8 @@ public:
     {
     }
 
+    inline void setLogLevel(const LogLevel _logLevel) { logLevel = _logLevel; };
+    inline LogLevel getLogLevel() const { return logLevel; }
     inline unsigned __int64 getTotalMillis() const { return mTotalTime; }
     inline void reset() { mTotalTime = 0; }
 
@@ -102,6 +105,7 @@ private:
 
     unsigned __int64 mNestingDepth;
     unsigned __int64 mTotalTime;
+    LogLevel logLevel;
 
 private:
     CumulativeTimer& operator =(const CumulativeTimer&) = delete;

esp/platform/espcontext.cpp

@@ -114,6 +114,8 @@ public:
     ~CEspContext()
     {
         flushTraceSummary();
+        if (m_txSummary)
+            m_txSummary->log(getTxSummaryLevel());
     }
     virtual void addOptions(unsigned opts){options|=opts;}
     virtual void removeOptions(unsigned opts){opts&=~opts;}
@@ -490,34 +492,34 @@ public:
 
     virtual void addTraceSummaryValue(LogLevel logLevel, const char *name, const char *value)
     {
-        if (m_txSummary && (getTxSummaryLevel() >= logLevel))
-            m_txSummary->append(name, value);
+        if (m_txSummary && !isEmptyString(name))
+            m_txSummary->append(name, value, logLevel);
     }
 
     virtual void addTraceSummaryValue(LogLevel logLevel, const char *name, __int64 value)
     {
-        if (m_txSummary && (getTxSummaryLevel() >= logLevel))
-            m_txSummary->append(name, value);
+        if (m_txSummary && !isEmptyString(name))
+            m_txSummary->append(name, value, logLevel);
     }
 
     virtual void addTraceSummaryTimeStamp(LogLevel logLevel, const char *name)
     {
-        if (m_txSummary && (getTxSummaryLevel() >= logLevel) && name && *name)
-            m_txSummary->append(name, m_txSummary->getElapsedTime(), "ms");
+        if (m_txSummary && !isEmptyString(name))
+            m_txSummary->append(name, m_txSummary->getElapsedTime(), "ms", TokenSerializer(), logLevel);
     }
     virtual void flushTraceSummary()
     {
         updateTraceSummaryHeader();
-        if (m_txSummary && (getTxSummaryLevel() >= LogMin))
+        if (m_txSummary)
         {
-            m_txSummary->set("auth", authStatus.get());
-            m_txSummary->append("total", m_processingTime, "ms");
+            m_txSummary->set("auth", authStatus.get(), LogMin);
+            m_txSummary->append("total", m_processingTime, "ms", TokenSerializer(), LogMin);
         }
     }
     virtual void addTraceSummaryCumulativeTime(LogLevel logLevel, const char* name, unsigned __int64 time)
     {
-        if (m_txSummary && (getTxSummaryLevel() >= logLevel))
-            m_txSummary->updateTimer(name, time);
+        if (m_txSummary && !isEmptyString(name))
+            m_txSummary->updateTimer(name, time, logLevel);
     }
     virtual CumulativeTimer* queryTraceSummaryCumulativeTimer(const char* name)
     {
@@ -661,12 +663,12 @@ bool CEspContext::isMethodAllowed(double version, const char* optional, const ch
 
 void CEspContext::updateTraceSummaryHeader()
 {
-    if (m_txSummary && (getTxSummaryLevel() >= LogMin))
+    if (m_txSummary)
     {
-        m_txSummary->set("activeReqs", m_active);
+        m_txSummary->set("activeReqs", m_active, LogMin);
         VStringBuffer user("%s%s%s", (queryUserId() ? queryUserId() : ""), (m_peer.length() ? "@" : ""), m_peer.str());
         if (!user.isEmpty())
-            m_txSummary->set("user", user.str());
+            m_txSummary->set("user", user.str(), LogMin);
 
         VStringBuffer reqSummary("%s", httpMethod.isEmpty() ? "" : httpMethod.get());
         if (!m_servName.isEmpty() || !servMethod.isEmpty())
@@ -685,11 +687,11 @@ void CEspContext::updateTraceSummaryHeader()
             reqSummary.append("v").append(m_clientVer);
         }
         if (!reqSummary.isEmpty())
-            m_txSummary->set("req", reqSummary.str());
+            m_txSummary->set("req", reqSummary.str(), LogMin);
         if (m_hasException)
         {
-            m_txSummary->set("excepttime", m_exceptionTime);
-            m_txSummary->set("exceptcode", m_exceptionCode);
+            m_txSummary->set("excepttime", m_exceptionTime, LogMin);
+            m_txSummary->set("exceptcode", m_exceptionCode, LogMin);
         }
     }
 }

esp/platform/txsummary.cpp

@@ -38,7 +38,6 @@ CTxSummary::CTxSummary(unsigned creationTime)
 
 CTxSummary::~CTxSummary()
 {
-    log();
     clear();
 }
 
@@ -66,7 +65,7 @@ bool CTxSummary::contains(const char* key) const
     return __contains(key);
 }
 
-bool CTxSummary::append(const char* key, const char* value)
+bool CTxSummary::append(const char* key, const char* value, const LogLevel logLevel)
 {
     VALIDATE_KEY(key);
 
@@ -75,11 +74,11 @@ bool CTxSummary::append(const char* key, const char* value)
     if (__contains(key))
         return false;
 
-    m_entries.push_back({key, value});
+    m_entries.push_back({key, value, logLevel});
     return true;
 }
 
-bool CTxSummary::set(const char* key, const char* value)
+bool CTxSummary::set(const char* key, const char* value, const LogLevel logLevel)
 {
     VALIDATE_KEY(key);
 
@@ -87,9 +86,12 @@ bool CTxSummary::set(const char* key, const char* value)
     Entries::iterator it = find_if(m_entries.begin(), m_entries.end(), MATCH_KEY);
 
     if (it != m_entries.end())
+    {
         it->value.set(value);
+        it->logLevel = logLevel;
+    }
     else
-        m_entries.push_back({key, value});
+        m_entries.push_back({key, value, logLevel});
 
     return true;
 }
@@ -110,7 +112,7 @@ CumulativeTimer* CTxSummary::queryTimer(const char* name)
     return timer;
 }
 
-bool CTxSummary::updateTimer(const char* name, unsigned long long delta)
+bool CTxSummary::updateTimer(const char* name, unsigned long long delta, const LogLevel logLevel)
 {
     Owned<CumulativeTimer> timer;
 
@@ -120,15 +122,19 @@ bool CTxSummary::updateTimer(const char* name, unsigned long long delta)
         return false;
 
     timer->add(delta);
+    timer->setLogLevel(logLevel);
     return true;
 }
 
-void CTxSummary::serialize(StringBuffer& buffer) const
+void CTxSummary::serialize(StringBuffer& buffer, const LogLevel logLevel) const
 {
     CriticalBlock block(m_sync);
 
     for (const Entry& entry : m_entries)
     {
+        if (entry.logLevel > logLevel)
+            continue;
+
         if (entry.value.length())
             buffer.appendf("%s=%s;", entry.key.str(), entry.value.str());
         else
@@ -137,16 +143,17 @@ void CTxSummary::serialize(StringBuffer& buffer) const
 
     for (const std::pair<TimerKey, TimerValue>& entry : m_timers)
     {
-        buffer.appendf("%s=%" I64F "ums;", entry.first.str(), entry.second->getTotalMillis());
+        if (entry.second->getLogLevel() <= logLevel)
+            buffer.appendf("%s=%" I64F "ums;", entry.first.str(), entry.second->getTotalMillis());
     }
 }
 
-void CTxSummary::log()
+void CTxSummary::log(const LogLevel logLevel)
 {
     if (__contains("user") || __contains("req"))
     {
         StringBuffer summary;
-        serialize(summary);
+        serialize(summary, logLevel);
         DBGLOG("TxSummary[%s]", summary.str());
     }
 }

esp/platform/txsummary.hpp

@@ -22,6 +22,7 @@
 #include "jmutex.hpp"
 #include "cumulativetimer.hpp"
 #include "tokenserialization.hpp"
+#include "esp.hpp"
 #include "esphttp.hpp"
 #include <list>
 #include <map>
@@ -51,21 +52,23 @@ public:
     virtual unsigned getElapsedTime() const;
 
     // Appends all summary entries to the given buffer.
-    virtual void serialize(StringBuffer& buffer) const;
+    virtual void serialize(StringBuffer& buffer, const LogLevel logLevel = LogMin) const;
 
     // Adds the unique key and value to the end of the summary.
     // Returns true if the key value pair are added to the summary. Returns
     // false if the key is NULL, empty, or not unique within the summary.
-    virtual bool append(const char* key, const char* value);
+    virtual bool append(const char* key, const char* value, const LogLevel logLevel = LogMin);
     template <typename TValue, typename TSuffix = const char*, class TSerializer = TokenSerializer>
-    bool append(const char* key, const TValue& value, const TSuffix& suffix = "", const TSerializer& serializer = TSerializer());
+    bool append(const char* key, const TValue& value, const TSuffix& suffix = "", const TSerializer& serializer = TSerializer(), const LogLevel logLevel = LogMin);
 
     // Updates the value associated with an existing key, or appends the key
     // and value to the summary if it is not already found. Returns false if
     // the key is NULL or empty. Returns true otherwise.
-    virtual bool set(const char* key, const char* value);
+    virtual bool set(const char* key, const char* value, const LogLevel logLevel = LogMin);
     template <typename TValue, typename TSuffix = const char*, class TSerializer = TokenSerializer>
-    bool set(const char* key, const TValue& value, const TSuffix& suffix = "", const TSerializer& serializer = TSerializer());
+    bool set(const char* key, const TValue& value, const TSuffix& suffix = "", const TSerializer& serializer = TSerializer(), const LogLevel logLevel = LogMin);
+
+    void log(const LogLevel logLevel);
 
     // Fetches an existing or new instance of a named CumulativeTime. The name
     // must not be NULL or empty, but it may be a duplicate of an existing
@@ -75,20 +78,20 @@ public:
 
     // Adds the given milliseconds to an existing or new named CumulativeTimer.
     // The same conditions as for getTimer apply.
-    virtual bool updateTimer(const char* name, unsigned long long delta);
+    virtual bool updateTimer(const char* name, unsigned long long delta, const LogLevel logLevel = LogMin);
 
 protected:
     // Log the summary contents on destruction.
     ~CTxSummary();
 
 private:
-    void log();
     bool __contains(const char* key) const;
 
     struct Entry
     {
         StringAttr key;
         StringAttr value;
+        LogLevel logLevel;
     };
 
     using Entries = std::list<Entry>;
@@ -105,22 +108,22 @@ private:
 
 // Convenience wrapper of the default append method.
 template <typename TValue, typename TSuffix, class TSerializer>
-inline bool CTxSummary::append(const char* key, const TValue& value, const TSuffix& suffix, const TSerializer& serializer)
+inline bool CTxSummary::append(const char* key, const TValue& value, const TSuffix& suffix, const TSerializer& serializer, const LogLevel logLevel)
 {
     StringBuffer buffer;
     serializer.serialize(value, buffer);
     serializer.serialize(suffix, buffer);
-    return append(key, serializer.str(buffer));
+    return append(key, serializer.str(buffer), logLevel);
 }
 
 // Convenience wrapper of the default set method.
 template <typename TValue, typename TSuffix, class TSerializer>
-inline bool CTxSummary::set(const char* key, const TValue& value, const TSuffix& suffix, const TSerializer& serializer)
+inline bool CTxSummary::set(const char* key, const TValue& value, const TSuffix& suffix, const TSerializer& serializer, const LogLevel logLevel)
 {
     StringBuffer buffer;
     serializer.serialize(value, buffer);
     serializer.serialize(suffix, buffer);
-    return set(key, serializer.str(buffer));
+    return set(key, serializer.str(buffer), logLevel);
 }
 
 #endif // TXSUMMARY_HPP