From 57fe708abc9d85a715c53da7d6fbf9fc33a534d6 Mon Sep 17 00:00:00 2001 From: Rodrigo Pastrana Date: Wed, 20 Sep 2023 10:25:47 -0400 Subject: [PATCH] HPCC-30301 JTrace log output inprovements - Sets output to JSON format - Ensures Parent span output is encapsulated - Adds cppunit test for json output - Utilizes beforeDispose - Introduces leaf/branch toString dynamic output - Exposes public toLog - Provides end-user trace info - Continues to provide developer level toString - Continues to provide nested toString info - Adds toLog unittest - Updates toString unittests - Uses toLog in trace ctr and ~ Signed-off-by: Rodrigo Pastrana --- system/jlib/jtrace.cpp | 133 ++++++++++++++++++++++++-------- system/jlib/jtrace.hpp | 1 + testing/unittests/jlibtests.cpp | 67 +++++++++++++++- 3 files changed, 167 insertions(+), 34 deletions(-) diff --git a/system/jlib/jtrace.cpp b/system/jlib/jtrace.cpp index 55fe2056783..18785d024d2 100644 --- a/system/jlib/jtrace.cpp +++ b/system/jlib/jtrace.cpp @@ -150,32 +150,79 @@ class CSpan : public CInterfaceOf ~CSpan() { if (span != nullptr) - { - StringBuffer out; - toString(out); - DBGLOG("Span end: (%s)", out.str()); span->End(); - } + } + + virtual void beforeDispose() override + { + StringBuffer out; + toLog(out); + DBGLOG("Span end: {%s}", out.str()); + } + + const char * getSpanID() const + { + return spanID.get(); } ISpan * createClientSpan(const char * name) override; ISpan * createInternalSpan(const char * name) override; - void toString(StringBuffer & out) const override + void toLog(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("\""); + + out.append(",\"TraceID\":\"").append(traceID.get()).append("\""); if (localParentSpan != nullptr) { - out.append(" localParentSpan: "); - localParentSpan->toString(out); + out.append(",\"ParentSpanID\": \""); + out.append(localParentSpan->getSpanID()); + out.append("\""); + } + } + } + + virtual void toString(StringBuffer & out) const + { + toString(out, true); + } + + virtual void toString(StringBuffer & out, bool isLeaf) const + { + out.append(",\"Name\":\"").append(name.get()).append("\""); + if (isLeaf) + { + 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(",\"SpanID\":\"").append(spanID.get()).append("\""); + + if (isLeaf) + { + out.append(",\"TraceID\":\"").append(traceID.get()).append("\"") + .append(",\"TraceFlags\":\"").append(traceFlags.get()).append("\""); + } + + if (localParentSpan != nullptr) + { + out.append(",\"ParentSpan\":{ "); + localParentSpan->toString(out, false); + out.append(" }"); } } }; @@ -316,9 +363,6 @@ class CSpan : public CInterfaceOf localParentSpan = parent; if (localParentSpan != nullptr) tracerName.set(parent->queryTraceName()); - //type = spanType; - - // init(); } CSpan(const char * spanName, const char * nameOfTracer) @@ -326,8 +370,6 @@ class CSpan : public CInterfaceOf name.set(spanName); localParentSpan = nullptr; tracerName.set(nameOfTracer); - //type = spanType; - } void init() @@ -347,8 +389,8 @@ class CSpan : public CInterfaceOf storeSpanContext(); StringBuffer out; - toString(out); - DBGLOG("Span start: (%s)", out.str()); + toLog(out); + DBGLOG("Span start: {%s}", out.str()); } } @@ -443,10 +485,16 @@ class CInternalSpan : public CSpan init(); } - void toString(StringBuffer & out) const override + void toLog(StringBuffer & out) const override + { + out.append("\"Type\":\"Internal\""); + CSpan::toLog(out); + } + + void toString(StringBuffer & out, bool isLeaf) const override { - out.append("Type: Internal"); - CSpan::toString(out); + out.append("\"Type\":\"Internal\""); + CSpan::toString(out, isLeaf); } }; @@ -460,10 +508,16 @@ class CClientSpan : public CSpan init(); } - void toString(StringBuffer & out) const override + void toLog(StringBuffer & out) const override + { + out.append("\"Type\":\"Client\""); + CSpan::toLog(out); + } + + void toString(StringBuffer & out, bool isLeaf) const override { - out.append("Type: Client"); - CSpan::toString(out); + out.append("\"Type\":\"Client\""); + CSpan::toString(out, isLeaf); } }; @@ -579,17 +633,32 @@ class CServerSpan : public CSpan init(); } - void toString(StringBuffer & out) const override + void toLog(StringBuffer & out) const override + { + out.append("\"Type\":\"Server\""); + CSpan::toLog(out); + + if (remoteParentSpanCtx.IsValid()) + { + out.append(",\"ParentSpanID\":\""); + char spanId[16] = {0}; + remoteParentSpanCtx.span_id().ToLowerBase16(spanId); + out.append(16, spanId) + .append("\""); + } + } + void toString(StringBuffer & out, bool isLeaf) const override { - out.append("Type: Server"); - CSpan::toString(out); + out.append("\"Type\":\"Server\""); + CSpan::toString(out, isLeaf); if (remoteParentSpanCtx.IsValid()) { - out.append(" remoteParentSpanID: "); + out.append(",\"ParentSpanID\":\""); char spanId[16] = {0}; remoteParentSpanCtx.span_id().ToLowerBase16(spanId); - out.append(16, spanId); + out.append(16, spanId) + .append("\""); } } }; diff --git a/system/jlib/jtrace.hpp b/system/jlib/jtrace.hpp index cf8d7e99630..5e5a84fb2ef 100644 --- a/system/jlib/jtrace.hpp +++ b/system/jlib/jtrace.hpp @@ -73,6 +73,7 @@ interface ISpan : extends IInterface virtual void addSpanEvent(const char * eventName) = 0; virtual bool getSpanContext(IProperties * ctxProps, bool otelFormatted) const = 0; virtual void toString(StringBuffer & out) const = 0; + virtual void toLog(StringBuffer & out) const = 0; virtual ISpan * createClientSpan(const char * name) = 0; virtual ISpan * createInternalSpan(const char * name) = 0; diff --git a/testing/unittests/jlibtests.cpp b/testing/unittests/jlibtests.cpp index 5f861add019..a3d30d51058 100644 --- 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(testMultiNestedSpanTraceOutput); CPPUNIT_TEST_SUITE_END(); const char * simulatedGlobalYaml = R"!!(global: @@ -298,8 +299,6 @@ class JlibTraceTest : public CppUnit::TestFixture CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected getSpanContext failure detected", true, getSpanCtxSuccess); const char * traceParent = retrievedSpanCtxAttributes->queryProp("remoteParentSpanID"); DBGLOG("testInvalidPropegatedServerSpan: traceparent: %s", traceParent); - //CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected Otel traceparent header len detected", (size_t)55, - // strlen(retrievedSpanCtxAttributes->queryProp("traceparent"))); } void testDisabledTracePropegatedValues() @@ -332,6 +331,70 @@ class JlibTraceTest : public CppUnit::TestFixture strcmp("4b960b3e4647da3f", retrievedSpanCtxAttributes->queryProp("remoteParentSpanID"))); } + void testMultiNestedSpanTraceOutput() + { + Owned mockHTTPHeaders = createProperties(); + createMockHTTPHeaders(mockHTTPHeaders, true); + + Owned serverSpan = queryTraceManager().createServerSpan("propegatedServerSpan", mockHTTPHeaders); + Owned clientSpan = serverSpan->createClientSpan("clientSpan"); + Owned internalSpan = clientSpan->createInternalSpan("internalSpan"); + Owned internalSpan2 = internalSpan->createInternalSpan("internalSpan2"); + + StringBuffer out; + out.set("{"); + internalSpan2->toLog(out); + out.append("}"); + { + Owned jtraceAsTree; + try + { + jtraceAsTree.setown(createPTreeFromJSONString(out.str())); + } + catch (IException *e) + { + StringBuffer msg; + msg.append("Unexpected toLog format failure detected: "); + e->errorMessage(msg); + e->Release(); + CPPUNIT_ASSERT_MESSAGE(msg.str(), false); + } + + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected toLog format failure detected", true, jtraceAsTree != nullptr); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'TraceID' entry in toLog output", true, jtraceAsTree->hasProp("TraceID")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'SpanID' entry in toLog output", true, jtraceAsTree->hasProp("SpanID")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'Name' entry in toLog output", true, jtraceAsTree->hasProp("Name")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'Type' entry in toLog output", true, jtraceAsTree->hasProp("Type")); + CPPUNIT_ASSERT_EQUAL_MESSAGE("Unexpected missing 'ParentSpanID' entry in toLog output", true, jtraceAsTree->hasProp("ParentSpanID")); + } + + out.set("{"); + internalSpan2->toString(out); + out.append("}"); + { + Owned jtraceAsTree; + try + { + jtraceAsTree.setown(createPTreeFromJSONString(out.str())); + } + catch (IException *e) + { + StringBuffer msg; + msg.append("Unexpected toString format failure detected: "); + e->errorMessage(msg); + e->Release(); + CPPUNIT_ASSERT_MESSAGE(msg.str(), false); + } + + 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 'ParentSpan/SpanID' entry in toString output", true, jtraceAsTree->hasProp("ParentSpan/SpanID")); + } + } + void testPropegatedServerSpan() { Owned mockHTTPHeaders = createProperties();