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 Signed-off-by: Rodrigo Pastrana <[email protected]>
hpcc-systems · Apr 18, 2024 · 8f97317 · 8f97317
1 parent 931ee83
commit 8f97317
Show file tree

Hide file tree

Showing 6 changed files with 161 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,21 @@ 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
-
+//should trace/span be included in the standard fields? As-is, stderr output will not include trace/span
 #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 +377,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 +410,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 +598,35 @@ class jlib_decl LogMsgJobInfo
     bool                      isDeserialized = false;
 };
 
+class jlib_decl LogMsgTraceInfo
+{
+public:
+    LogMsgTraceInfo() {}
+    LogMsgTraceInfo(ISpan * span)
+    {
+        if (span)
+        {
+            Owned<IProperties> retrievedSpanCtxAttributes = createProperties();
+            queryThreadedActiveSpan()->getSpanContext(retrievedSpanCtxAttributes.get());
+            //too many string copies? maybe store LogMsgTraceInfo in thread context instead of ispan?
+            if (retrievedSpanCtxAttributes->hasProp("traceID"))
+                setTraceID(retrievedSpanCtxAttributes->queryProp("traceID"));
+            if (retrievedSpanCtxAttributes->hasProp("spanID")) //can we ever have a spanid sans traceid?
+                setSpanID(retrievedSpanCtxAttributes->queryProp("spanID"));
+        }
+    }
+
+    ~LogMsgTraceInfo() {};
+
+    const char * queryTraceID() const { return traceID.get();}
+    const char * querySpanID() const { return spanID.get();};
+    void setTraceID(const char * theTraceID) { traceID.set(theTraceID);};
+    void setSpanID(const char * theSpanID) { spanID.set(theSpanID);};
+private:
+    StringAttr          traceID = "UNK";
+    StringAttr          spanID = "UNK";
+};
+
 class jlib_decl LogMsg : public CInterface
 {
 public:
@@ -615,6 +654,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
@@ -1487,8 +1487,8 @@ void OwnedSpanScope::clear()
 {
     if (span)
     {
-        setThreadedActiveSpan(prevSpan);
         span->endSpan();
+        setThreadedActiveSpan(prevSpan);
         span.clear();
     }
 }

diff --git a/testing/unittests/jlibtests.cpp b/testing/unittests/jlibtests.cpp
@@ -66,6 +66,7 @@ class JlibTraceTest : public CppUnit::TestFixture
         CPPUNIT_TEST(manualTestsEventsOutput);
         CPPUNIT_TEST(manualTestsDeclaredFailures);
         CPPUNIT_TEST(manualTestScopeEnd);
+        CPPUNIT_TEST(testActiveSpans);
 
         //CPPUNIT_TEST(testJTraceJLOGExporterprintResources);
         //CPPUNIT_TEST(testJTraceJLOGExporterprintAttributes);
@@ -442,7 +443,7 @@ class JlibTraceTest : public CppUnit::TestFixture
     {
         Owned<IProperties> emptyMockHTTPHeaders = createProperties();
         OwnedSpanScope serverSpan = queryTraceManager().createServerSpan("propegatedServerSpan", emptyMockHTTPHeaders);
-
+ERRLOG("Random");
         Owned<IProperties> retrievedSpanCtxAttributes = createProperties();
         serverSpan->getSpanContext(retrievedSpanCtxAttributes);
 
@@ -453,12 +454,12 @@ class JlibTraceTest : public CppUnit::TestFixture
 
         {
             OwnedSpanScope internalSpan = serverSpan->createClientSpan("clientSpan");
-
+ERRLOG("Random2");
             //retrieve clientSpan context with the intent to propogate otel and HPCC context
             {
                 Owned<IProperties> retrievedSpanCtxAttributes = createProperties();
                 internalSpan->getSpanContext(retrievedSpanCtxAttributes);
-
+ERRLOG("Random3");
                 CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing localParentSpanID detected", true,
                  retrievedSpanCtxAttributes->hasProp("localParentSpanID"));
 
@@ -567,6 +568,71 @@ class JlibTraceTest : public CppUnit::TestFixture
         }
     }
 
+    void testActiveSpans()
+    {
+        {
+            Owned<IProperties> spanContext = createProperties();
+            ISpan * activeSpan =  queryThreadedActiveSpan();
+
+            CPPUNIT_ASSERT_MESSAGE("Threaded Active Span == nullptr!", activeSpan != nullptr);
+
+            activeSpan->getSpanContext(spanContext);
+
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected TraceID detected when no active trace/span expected", false, spanContext->hasProp("traceID"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected SpanID detected when no active trace/span expected", false, spanContext->hasProp("spanID"));
+        }
+
+        {
+            Owned<IProperties> mockHTTPHeaders = createProperties();
+            createMockHTTPHeaders(mockHTTPHeaders, false);
+            ISpan * notActiveSpan = queryTraceManager().createServerSpan("notActiveSpan", mockHTTPHeaders);
+
+            CPPUNIT_ASSERT_MESSAGE("Not Active Span == nullptr!", notActiveSpan != nullptr);
+            Owned<IProperties> spanContext = createProperties();
+            notActiveSpan->getSpanContext(spanContext);
+
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing TraceID detected", true, spanContext->hasProp("traceID"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing SpanID detected", true, spanContext->hasProp("spanID"));
+
+            ISpan * activeSpan2 =  queryThreadedActiveSpan();
+
+            CPPUNIT_ASSERT_MESSAGE("Threaded Active Span == nullptr!", activeSpan2 != nullptr);
+
+            Owned<IProperties> spanContext2 = createProperties();
+            activeSpan2->getSpanContext(spanContext2);
+
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected TraceID detected when no active trace/span expected", false, spanContext2->hasProp("traceID"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected SpanID detected when no active trace/span expected", false, spanContext2->hasProp("spanID"));
+        }
+
+        {
+            Owned<IProperties> mockHTTPHeaders = createProperties();
+            createMockHTTPHeaders(mockHTTPHeaders, false);
+            OwnedSpanScope currentSpanScope = queryTraceManager().createServerSpan("currentSpanScope", mockHTTPHeaders);
+
+            CPPUNIT_ASSERT_MESSAGE("currentSpanScope Span == nullptr!", currentSpanScope != nullptr);
+
+            Owned<IProperties> currentSpanContext = createProperties();
+            currentSpanScope->getSpanContext(currentSpanContext);
+
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing TraceID detected when active trace/span expected", true, currentSpanContext->hasProp("traceID"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing SpanID detected when active trace/span expected", true, currentSpanContext->hasProp("spanID"));
+
+            ISpan * activeSpan =  queryThreadedActiveSpan();
+
+            CPPUNIT_ASSERT_MESSAGE("Threaded Active Span == nullptr!", activeSpan != nullptr);
+
+            Owned<IProperties> activeSpanContext = createProperties();
+            activeSpan->getSpanContext(activeSpanContext);
+
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing TraceID detected when active trace/span expected", true, activeSpanContext->hasProp("traceID"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing SpanID detected when active trace/span expected", true, activeSpanContext->hasProp("spanID"));
+
+            DBGLOG("This log entry should report traceID: '%s' and spanID: '%s'", currentSpanContext->queryProp("traceID"), currentSpanContext->queryProp("spanID"));
+            //15:07:56.490232  3788 720009f32a9db04f68f2b6545717ebe5 a7ef8749b5926acf This log entry should report traceID: '720009f32a9db04f68f2b6545717ebe5' and spanID: 'a7ef8749b5926acf'
+        }
+    }
+
     void testInvalidPropegatedServerSpan()
     {
         Owned<IProperties> mockHTTPHeaders = createProperties();

diff --git a/testing/unittests/unittests.cpp b/testing/unittests/unittests.cpp
@@ -177,7 +177,7 @@ int main(int argc, const char *argv[])
         }
     }
     if (verbose)
-        queryStderrLogMsgHandler()->setMessageFields(MSGFIELD_time|MSGFIELD_microTime|MSGFIELD_milliTime|MSGFIELD_thread);
+        queryStderrLogMsgHandler()->setMessageFields(MSGFIELD_trace|MSGFIELD_span|MSGFIELD_time|MSGFIELD_microTime|MSGFIELD_milliTime|MSGFIELD_thread);
     else
         removeLog();