Skip to content

Commit

Permalink
Merge pull request #17792 from rpastrana/HPCC-30301-JtraceToStringNested
Browse files Browse the repository at this point in the history 
HPCC-30301 JTrace log output improvements

Reviewed-by: Gavin Halliday <[email protected]>
Merged-by: Gavin Halliday <[email protected]>
  • Loading branch information
@ghalliday
ghalliday authored Sep 27, 2023
2 parents 9a9066c + 57fe708 commit cc3d39c
Show file tree
Hide file tree
Showing 3 changed files with 167 additions and 34 deletions.
133 changes: 101 additions & 32 deletions system/jlib/jtrace.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -150,32 +150,79 @@ class CSpan : public CInterfaceOf<ISpan>
~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(" }");
}
}
};
Expand Down Expand Up @@ -316,18 +363,13 @@ class CSpan : public CInterfaceOf<ISpan>
localParentSpan = parent;
if (localParentSpan != nullptr)
tracerName.set(parent->queryTraceName());
//type = spanType;

// init();
}

CSpan(const char * spanName, const char * nameOfTracer)
{
name.set(spanName);
localParentSpan = nullptr;
tracerName.set(nameOfTracer);
//type = spanType;

}

void init()
Expand All @@ -347,8 +389,8 @@ class CSpan : public CInterfaceOf<ISpan>
storeSpanContext();

StringBuffer out;
toString(out);
DBGLOG("Span start: (%s)", out.str());
toLog(out);
DBGLOG("Span start: {%s}", out.str());
}
}

Expand Down Expand Up @@ -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);
}
};

Expand All @@ -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);
}
};

Expand Down Expand Up @@ -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("\"");
}
}
};
Expand Down
1 change: 1 addition & 0 deletions system/jlib/jtrace.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
67 changes: 65 additions & 2 deletions testing/unittests/jlibtests.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -332,6 +331,70 @@ class JlibTraceTest : public CppUnit::TestFixture
strcmp("4b960b3e4647da3f", retrievedSpanCtxAttributes->queryProp("remoteParentSpanID")));
}

void testMultiNestedSpanTraceOutput()
{
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->toLog(out);
out.append("}");
{
Owned<IPropertyTree> 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<IPropertyTree> 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<IProperties> mockHTTPHeaders = createProperties();
Expand Down

0 comments on commit cc3d39c

Please sign in to comment.