HPCC-30301 JTrace log output inprovements

- Sets output to JSON format - Fixes derived destructor toString - Ensures Parent span output is encapsulated - Adds heads-up note on base destructor - Adds cppunit test for json output Signed-off-by: Rodrigo Pastrana <[email protected]>
hpcc-systems · Sep 20, 2023 · c003fb0 · c003fb0
1 parent 5f388e5
commit c003fb0
Show file tree

Hide file tree

Showing 2 changed files with 77 additions and 19 deletions.
diff --git a/system/jlib/jtrace.cpp b/system/jlib/jtrace.cpp
@@ -147,35 +147,36 @@ class CSpan : public CInterfaceOf<ISpan>
 {
 public:
     CSpan() = delete;
-    ~CSpan()
+    virtual ~CSpan()
     {
+        //Derived class specific behavior such as toString() should be
+        //called from the destructor of the derived class
         if (span != nullptr)
-        {
-            StringBuffer out;
-            toString(out);
-            DBGLOG("Span end: (%s)", out.str());
             span->End();
-        }
     }
 
     ISpan * createClientSpan(const char * name) override;
     ISpan * createInternalSpan(const char * name) override;
 
     void toString(StringBuffer & out) const override
     {
+        out.append(",\"Name\":\"").append(name.get()).append("\"");
+        if (!isEmptyString(hpccGlobalId.get()))
+            out.append(",\"HPCCGlobalID\":\"").append(hpccGlobalId.get()).append("\"");
+        if (!isEmptyString(hpccCallerId.get()))
+            out.append(",\"HPCCCallerID\":\"").append(hpccCallerId.get()).append("\"");
+
         if (span != nullptr)
         {
-            out.append(" Name: ").append(name.get())
-            .append(" SpanID: ").append(spanID.get())
-            .append(" TraceID: ").append(traceID.get())
-            .append(" TraceFlags: ").append(traceFlags.get())
-            .append(" HPCCGlobalID: ").append(hpccGlobalId.get())
-            .append(" HPCCCallerID: ").append(hpccCallerId.get());
+            out.append(",\"SpanID\":\"").append(spanID.get()).append("\"")
+            .append(",\"TraceID\":\"").append(traceID.get()).append("\"")
+            .append(",\"TraceFlags\":\"").append(traceFlags.get()).append("\"");
 
             if (localParentSpan != nullptr)
             {
-                out.append(" localParentSpan: ");
+                out.append(",\"LocalParentSpan\":{ ");
                 localParentSpan->toString(out);
+                out.append(" }");
             }
         }
     };
@@ -348,7 +349,7 @@ class CSpan : public CInterfaceOf<ISpan>
 
             StringBuffer out;
             toString(out);
-            DBGLOG("Span start: (%s)", out.str());
+            DBGLOG("Span start: {%s}", out.str());
         }
     }
 
@@ -436,6 +437,13 @@ class CSpan : public CInterfaceOf<ISpan>
 class CInternalSpan : public CSpan
 {
 public:
+    ~CInternalSpan() override
+    {
+        StringBuffer out;
+        toString(out);
+        DBGLOG("Span end: {%s}", out.str());
+    }
+
     CInternalSpan(const char * spanName, CSpan * parent)
     : CSpan(spanName, parent)
     {
@@ -445,14 +453,21 @@ class CInternalSpan : public CSpan
 
     void toString(StringBuffer & out) const override
     {
-        out.append("Type: Internal");
+        out.append("\"Type\":\"Internal\"");
         CSpan::toString(out);
     }
 };
 
 class CClientSpan : public CSpan
 {
 public:
+    ~CClientSpan() override
+    {
+        StringBuffer out;
+        toString(out);
+        DBGLOG("Span end: {%s}", out.str());
+    }
+
     CClientSpan(const char * spanName, CSpan * parent)
     : CSpan(spanName, parent)
     {
@@ -462,7 +477,7 @@ class CClientSpan : public CSpan
 
     void toString(StringBuffer & out) const override
     {
-        out.append("Type: Client");
+        out.append("\"Type\":\"Client\"");
         CSpan::toString(out);
     }
 };
@@ -563,6 +578,14 @@ class CServerSpan : public CSpan
     }
 
 public:
+
+    ~CServerSpan() override
+    {
+        StringBuffer out;
+        toString(out);
+        DBGLOG("Span end: {%s}", out.str());
+    }
+
     CServerSpan(const char * spanName, const char * tracerName_, StringArray & httpHeaders)
     : CSpan(spanName, tracerName_)
     {
@@ -581,15 +604,16 @@ class CServerSpan : public CSpan
 
     void toString(StringBuffer & out) const override
     {
-        out.append("Type: Server");
+        out.append("\"Type\":\"Server\"");
         CSpan::toString(out);
 
         if (remoteParentSpanCtx.IsValid())
         {
-            out.append(" remoteParentSpanID: ");
+            out.append(",\"RemoteParentSpanID\":\"");
             char spanId[16] = {0};
             remoteParentSpanCtx.span_id().ToLowerBase16(spanId);
-            out.append(16, spanId);
+            out.append(16, spanId)
+            .append("\"");
         }
     }
 };

diff --git a/testing/unittests/jlibtests.cpp b/testing/unittests/jlibtests.cpp
@@ -53,6 +53,7 @@ class JlibTraceTest : public CppUnit::TestFixture
         CPPUNIT_TEST(testPropegatedServerSpan);
         CPPUNIT_TEST(testInvalidPropegatedServerSpan);
         CPPUNIT_TEST(testInternalSpan);
+        CPPUNIT_TEST(testMultiNestedSpan);
     CPPUNIT_TEST_SUITE_END();
 
     const char * simulatedGlobalYaml = R"!!(global:
@@ -332,6 +333,39 @@ class JlibTraceTest : public CppUnit::TestFixture
             strcmp("4b960b3e4647da3f", retrievedSpanCtxAttributes->queryProp("remoteParentSpanID")));
     }
 
+    void testMultiNestedSpan()
+    {
+        Owned<IProperties> mockHTTPHeaders = createProperties();
+        createMockHTTPHeaders(mockHTTPHeaders, true);
+
+        Owned<ISpan> serverSpan = queryTraceManager().createServerSpan("propegatedServerSpan", mockHTTPHeaders);
+        Owned<ISpan> clientSpan = serverSpan->createClientSpan("clientSpan");
+        Owned<ISpan> internalSpan = clientSpan->createInternalSpan("internalSpan");
+        Owned<ISpan> internalSpan2 = internalSpan->createInternalSpan("internalSpan2");
+
+        StringBuffer out;
+        out.set("{");
+        internalSpan2->toString(out);
+        out.append("}");
+
+        try
+        {
+            Owned<IPropertyTree> jtraceAsTree = createPTreeFromJSONString(out.str());
+
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected toString format failure detected", true, jtraceAsTree != nullptr);
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'TraceID' entry in toString output", true, jtraceAsTree->hasProp("TraceID"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'SpanID' entry in toString output", true, jtraceAsTree->hasProp("SpanID"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'Name' entry in toString output", true, jtraceAsTree->hasProp("Name"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'Type' entry in toString output", true, jtraceAsTree->hasProp("Type"));
+            CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'LocalParentSpan' entry in toString output", true, jtraceAsTree->hasProp("LocalParentSpan"));
+        }
+        catch (...)
+        {
+            CPPUNIT_ASSERT_MESSAGE("Unexpected toString format failure detected", false);
+        }
+
+    }
+
     void testPropegatedServerSpan()
     {
         Owned<IProperties> mockHTTPHeaders = createProperties();