HPCC-29334 Associate log entries w/ active trace

- Add support for JLog Trace and Span columns - Update logging README with new cols - Avoids uncaught exceptions - Adds trace/span fields as default log layout - Adds trace/span fields to unittests log output - Adds various active span unittests - Ends span before reverting active threaded span so jlog output includes trace/span columns - Adds ISpan query Trace/Span ID methods - Jlog tracks linked Ispan Signed-off-by: Rodrigo Pastrana <[email protected]>
hpcc-systems · May 9, 2024 · 192720f · 192720f
1 parent 931ee83
commit 192720f
Show file tree

Hide file tree

Showing 7 changed files with 198 additions and 15 deletions.
diff --git a/helm/examples/logging/README.md b/helm/examples/logging/README.md
@@ -94,7 +94,7 @@ Log output verbosity can be adjusted from "critical messages only" (1) up to "re
 
 ### Log Data Column Configuration
 
-The available log data columns include messageid(MID), audience(AUD), class(CLS), date(DAT), time(TIM), millitime(MLT), microtime(MCT), nanotime(NNT), processid(PID), threadid(TID), node(NOD), job(JOB), use(USE), session(SES), code(COD), component(COM), quotedmessage(QUO), prefix(PFX), all(ALL), and standard(STD). The log data columns (or fields) configuration is controlled by the `<section>`.logging.fields value, comprised of 3 letter codes delimited by the aggregation operator (+) or the removal operator (-).
+The available log data columns include traceid(TRC), spanid(SPN), messageid(MID), audience(AUD), class(CLS), date(DAT), time(TIM), millitime(MLT), microtime(MCT), nanotime(NNT), processid(PID), threadid(TID), node(NOD), job(JOB), use(USE), session(SES), code(COD), component(COM), quotedmessage(QUO), prefix(PFX), all(ALL), and standard(STD). The log data columns (or fields) configuration is controlled by the `<section>`.logging.fields value, comprised of 3 letter codes delimited by the aggregation operator (+) or the removal operator (-).
 
     For example, all component log output should include the standard columns except the job ID column:
     helm install myhpcc ./hpcc --set global.logging.fields="STD-JOB"

diff --git a/system/jlib/jlog.cpp b/system/jlib/jlog.cpp
@@ -131,7 +131,7 @@ void LogMsgSysInfo::deserialize(MemoryBuffer & in)
 
 class LoggingFieldColumns
 {
-    const EnumMapping MsgFieldMap[16] =
+    const EnumMapping MsgFieldMap[18] =
     {
         { MSGFIELD_msgID,     "MsgID    " },
         { MSGFIELD_audience,  "Audience " },
@@ -148,6 +148,8 @@ class LoggingFieldColumns
         { MSGFIELD_job,       "JobID  " },
         { MSGFIELD_user,      "UserID  " },
         { MSGFIELD_component, "Compo " },
+        { MSGFIELD_trace,     "Trace " },
+        { MSGFIELD_span,      "Span " },
         { MSGFIELD_quote,     "Quoted "}
     };
     const unsigned sizeMsgFieldMap = arraysize(MsgFieldMap);
@@ -298,6 +300,10 @@ static const LogMsgJobInfo queryDefaultJobInfo()
     return LogMsgJobInfo(queryThreadedJobId(), UnknownUser);
 }
 
+static const LogMsgTraceInfo queryActiveTraceInfo()
+{
+    return LogMsgTraceInfo(queryThreadedActiveSpan());
+}
 
 LogMsg::LogMsg(LogMsgJobId id, const char *job) : category(MSGAUD_programmer, job ? MSGCLS_addid : MSGCLS_removeid), sysInfo(), jobInfo(id), remoteFlag(false)
 {
@@ -306,20 +312,20 @@ LogMsg::LogMsg(LogMsgJobId id, const char *job) : category(MSGAUD_programmer, jo
 }
 
 LogMsg::LogMsg(const LogMsgCategory & _cat, LogMsgId _id, LogMsgCode _code, const char * _text, unsigned port, LogMsgSessionId session)
-  : category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), msgCode(_code), remoteFlag(false)
+  : category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), traceInfo(queryActiveTraceInfo()),  msgCode(_code), remoteFlag(false)
 {
     text.append(_text);
 }
 
 LogMsg::LogMsg(const LogMsgCategory & _cat, LogMsgId _id, LogMsgCode _code, size32_t sz, const char * _text, unsigned port, LogMsgSessionId session)
-  : category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), msgCode(_code), remoteFlag(false)
+  : category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), traceInfo(queryActiveTraceInfo()), msgCode(_code), remoteFlag(false)
 {
     text.append(sz, _text);
 }
 
 LogMsg::LogMsg(const LogMsgCategory & _cat, LogMsgId _id, LogMsgCode _code, const char * format, va_list args,
        unsigned port, LogMsgSessionId session)
-  : category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), msgCode(_code), remoteFlag(false)
+  : category(_cat), sysInfo(_id, port, session), jobInfo(queryDefaultJobInfo()), traceInfo(queryActiveTraceInfo()), msgCode(_code), remoteFlag(false)
 {
     text.valist_appendf(format, args);
 }
@@ -387,6 +393,16 @@ StringBuffer & LogMsg::toStringPlain(StringBuffer & out, unsigned fields) const
         else
             out.appendf("usr=%" I64F "u ", jobInfo.queryUserID());
     }
+    if(fields & MSGFIELD_trace)
+    {
+        //it seems the existing convention is to use 3 char abbreviation
+        out.appendf("trc=%s ", traceInfo.queryTraceID());
+    }
+    if (fields & MSGFIELD_span)
+    {
+        //it seems the existing convention is to use 3 char abbreviation
+        out.appendf("spn=%s ", traceInfo.querySpanID());
+    }
     if (fields & MSGFIELD_quote)
         out.append('"');
     if (fields & MSGFIELD_prefix)
@@ -471,6 +487,14 @@ StringBuffer & LogMsg::toStringXML(StringBuffer & out, unsigned fields) const
         else
             out.append("UserID=\"").append(jobInfo.queryUserID()).append("\" ");
     }
+    if(fields & MSGFIELD_trace)
+    {
+        out.append("TraceID=\"").append(traceInfo.queryTraceID()).append("\" ");
+    }
+    if (fields & MSGFIELD_span)
+    {
+        out.append("SpanID=\"").append(traceInfo.querySpanID()).append("\" ");
+    }
 #ifdef LOG_MSG_NEWLINE
     if(fields & MSGFIELD_allJobInfo) out.append("\n     ");
 #endif
@@ -546,6 +570,14 @@ StringBuffer & LogMsg::toStringJSON(StringBuffer & out, unsigned fields) const
         else
             out.append(", \"USER\": \"").append(jobInfo.queryUserID()).append("\"");
     }
+    if(fields & MSGFIELD_trace)
+    {
+        out.appendf("\"TRACEID\"=\"%s\"", traceInfo.queryTraceID());
+    }
+    if (fields & MSGFIELD_span)
+    {
+        out.appendf("\"SPANID\"=\"%s\"",traceInfo.querySpanID());
+    }
     if((fields & MSGFIELD_code) && (msgCode != NoLogMsgCode))
         out.append(", \"CODE\": \"").append(msgCode).append("\"");
 
@@ -610,6 +642,14 @@ StringBuffer & LogMsg::toStringTable(StringBuffer & out, unsigned fields) const
     {
         out.appendf("%-7s ", jobInfo.queryJobIDStr());
     }
+    if(fields & MSGFIELD_trace)
+    {
+        out.appendf("%s ", traceInfo.queryTraceID());
+    }
+    if(fields & MSGFIELD_span)
+    {
+        out.appendf("%s ", traceInfo.querySpanID());
+    }
     if(fields & MSGFIELD_user)
     {
         if(jobInfo.queryUserID() == UnknownUser)
@@ -2300,7 +2340,7 @@ void setupContainerizedLogMsgHandler()
 
         if (logConfig->hasProp(logFieldsAtt))
         {
-            //Supported logging fields: AUD,CLS,DET,MID,TIM,DAT,PID,TID,NOD,JOB,USE,SES,COD,MLT,MCT,NNT,COM,QUO,PFX,ALL,STD
+            //Supported logging fields: TRC,SPN,AUD,CLS,DET,MID,TIM,DAT,PID,TID,NOD,JOB,USE,SES,COD,MLT,MCT,NNT,COM,QUO,PFX,ALL,STD
             const char *logFields = logConfig->queryProp(logFieldsAtt);
             if (!isEmptyString(logFields))
                 theStderrHandler->setMessageFields(logMsgFieldsFromAbbrevs(logFields));

diff --git a/system/jlib/jlog.hpp b/system/jlib/jlog.hpp
@@ -318,19 +318,20 @@ typedef enum
     MSGFIELD_component   = 0x010000,
     MSGFIELD_quote       = 0x020000,
     MSGFIELD_prefix      = 0x040000,
-    MSGFIELD_last        = 0x040000,
+    MSGFIELD_trace       = 0x080000,
+    MSGFIELD_span        = 0x100000,
+    MSGFIELD_last        = 0x100000,
     MSGFIELD_all         = 0xFFFFFF
 } LogMsgField;
 
 #ifdef _WIN32
 #define MSGFIELD_STANDARD LogMsgField(MSGFIELD_timeDate | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix | MSGFIELD_audience)
 #define MSGFIELD_LEGACY LogMsgField(MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix)
 #else
-
 #ifdef _CONTAINERIZED
-#define MSGFIELD_STANDARD LogMsgField(MSGFIELD_job | MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_class | MSGFIELD_audience)
+#define MSGFIELD_STANDARD LogMsgField(MSGFIELD_span | MSGFIELD_trace | MSGFIELD_job | MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_class | MSGFIELD_audience)
 #else
-#define MSGFIELD_STANDARD LogMsgField(MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix | MSGFIELD_audience)
+#define MSGFIELD_STANDARD LogMsgField(MSGFIELD_span | MSGFIELD_trace | MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix | MSGFIELD_audience)
 #endif
 #define MSGFIELD_LEGACY LogMsgField(MSGFIELD_timeDate | MSGFIELD_milliTime | MSGFIELD_msgID | MSGFIELD_process | MSGFIELD_thread | MSGFIELD_code | MSGFIELD_quote | MSGFIELD_prefix)
 #endif
@@ -375,6 +376,10 @@ inline const char * LogMsgFieldToString(LogMsgField field)
         return("Component");
     case MSGFIELD_quote:
         return("Quote");
+    case MSGFIELD_trace:
+        return("Trace ID");
+    case MSGFIELD_span:
+        return("Span ID");
     default:
         return("UNKNOWN");
     }
@@ -404,6 +409,10 @@ inline unsigned LogMsgFieldFromAbbrev(char const * abbrev)
         return MSGFIELD_job;
     if(strnicmp(abbrev, "USE", 3)==0)
         return MSGFIELD_user;
+    if(strnicmp(abbrev, "TRC", 3)==0)
+        return MSGFIELD_trace;
+    if(strnicmp(abbrev, "SPN", 3)==0)
+        return MSGFIELD_span;
     if(strnicmp(abbrev, "SES", 3)==0)
         return MSGFIELD_session;
     if(strnicmp(abbrev, "COD", 3)==0)
@@ -588,6 +597,41 @@ class jlib_decl LogMsgJobInfo
     bool                      isDeserialized = false;
 };
 
+#define UNK_LOG_ENTRY "UNK"
+class jlib_decl LogMsgTraceInfo
+{
+public:
+    LogMsgTraceInfo() = default;
+    LogMsgTraceInfo(ISpan * _span) : span(_span)
+    {
+    }
+
+    const char * queryTraceID() const
+    {
+        if (span)
+        {
+            const char * traceId = span->queryTraceId();
+            if (traceId)
+                return traceId;
+        }
+        return UNK_LOG_ENTRY;
+    }
+
+    const char * querySpanID() const
+    {
+        if (span)
+        {
+            const char * spanId = span->querySpanId();
+            if (spanId)
+                return spanId;
+        }
+        return UNK_LOG_ENTRY;
+    }
+
+private:
+    Linked<ISpan> span;
+};
+
 class jlib_decl LogMsg : public CInterface
 {
 public:
@@ -615,6 +659,7 @@ class jlib_decl LogMsg : public CInterface
     LogMsgCategory            category;
     LogMsgSysInfo             sysInfo;
     LogMsgJobInfo             jobInfo;
+    LogMsgTraceInfo           traceInfo;
     LogMsgCode                msgCode = NoLogMsgCode;
     StringBuffer              text;
     bool                      remoteFlag = false;

diff --git a/system/jlib/jtrace.cpp b/system/jlib/jtrace.cpp
@@ -791,6 +791,16 @@ class CSpan : public CInterfaceOf<ISpan>
         recordError(SpanError(msg.str(), e->errorCode(), spanFailed, escapedScope));
     };
 
+    virtual const char * queryTraceId() const override
+    {
+        return traceID.get(); 
+    }
+
+    virtual const char * querySpanId() const override
+    {
+        return spanID.get();
+    }
+
 protected:
     CSpan(const char * spanName)
     {
@@ -901,6 +911,9 @@ class CNullSpan final : public CInterfaceOf<ISpan>
     virtual void recordError(const SpanError & error) override {};
     virtual void setSpanStatusSuccess(bool spanSucceeded, const char * statusMessage) override {}
 
+    virtual const char * queryTraceId() const override { return nullptr; }
+    virtual const char * querySpanId() const override { return nullptr; }
+
     virtual const char* queryGlobalId() const override { return nullptr; }
     virtual const char* queryCallerId() const override { return nullptr; }
     virtual const char* queryLocalId() const override { return nullptr; }
@@ -1487,8 +1500,8 @@ void OwnedSpanScope::clear()
 {
     if (span)
     {
-        setThreadedActiveSpan(prevSpan);
         span->endSpan();
+        setThreadedActiveSpan(prevSpan);
         span.clear();
     }
 }

diff --git a/system/jlib/jtrace.hpp b/system/jlib/jtrace.hpp
@@ -124,6 +124,8 @@ interface ISpan : extends IInterface
     virtual void recordException(IException * e, bool spanFailed = true, bool escapedScope = true) = 0;
     virtual void recordError(const SpanError & error = SpanError()) = 0;
     virtual void setSpanStatusSuccess(bool spanSucceeded, const char * statusMessage = NO_STATUS_MESSAGE) = 0;
+    virtual const char * queryTraceId() const = 0;
+    virtual const char * querySpanId() const = 0;
 
     virtual ISpan * createClientSpan(const char * name) = 0;
     virtual ISpan * createInternalSpan(const char * name) = 0;