HPCC-30350 Add open telemetry support to roxie/hthor/thor #17822

ghalliday · 2023-09-26T16:03:15Z

Type of change:

This change is a bug fix (non-breaking change which fixes an issue).
This change is a new feature (non-breaking change which adds functionality).
This change improves the code (refactor or other change that does not change the functionality)
This change fixes warnings (the fix does not alter the functionality or the generated code)
This change is a breaking change (fix or feature that will cause existing behavior to change).
This change alters the query API (existing queries will have to be recompiled)

Checklist:

Smoketest:

Send notifications about my Pull Request position in Smoketest queue.
Test my draft Pull Request.

Testing:

ghalliday · 2023-09-26T16:06:28Z

@rpastrana @afishbeck this is ready for review.
I have tested with the new end-to-end testing query with the following parameters:

<?xml version="1.0" encoding="UTF-8"?>
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:SOAP-ENC="http://schemas.xmlsoap.org/soap/encoding/">
 <soap:Body>
  <soaptest_mainserviceRequest xmlns="urn:hpccsystems:ecl:soaptest_mainservice" traceLevel="2" logFullQueries="1">
   <searchwords>one,and,sheep,when,richard,king</searchwords>
   <url>http://.:9876</url>
  </soaptest_mainserviceRequest>
 </soap:Body>
</soap:Envelope>

And the traceid/spanid was created and the remote span id was recorded for the child soapcalls.
It needs careful reviewing, especially that no regressions have been introduced in roxie. (I will re-review tomorrow.)
It is based on a previous PR that you are both tagged on as well.

github-actions · 2023-09-26T16:43:13Z

https://track.hpccsystems.com/browse/HPCC-30350
Jira updated

rpastrana

@ghalliday looks good, left a few questions and suggestions on minor concerns.

rpastrana · 2023-09-26T17:50:25Z

system/jlib/jtrace.cpp

+    virtual void getLogPrefix(StringBuffer & out) const override
+    {
+        const char * caller = queryCallerId();
+        if (caller)


!isEmptyString ?

I will change

rpastrana · 2023-09-26T17:51:26Z

system/jlib/jtrace.cpp

+        if (caller)
+        {
+            out.append('[');
+            if (caller)


is test on L:259 enough?

The outer condition is not right - I have since fixed.

rpastrana · 2023-09-26T17:51:53Z

system/jlib/jtrace.cpp

+                out.appendf("caller:%s", caller);
+
+            const char *local = queryLocalId();
+            if (local && *local)


!isEmptyString ?

rpastrana · 2023-09-26T17:52:40Z

system/jlib/jtrace.cpp

+            const char *local = queryLocalId();
+            if (local && *local)
+            {
+                if (caller)


rpastrana · 2023-09-26T17:53:24Z

system/jlib/jtrace.cpp

    const char * queryTraceName() const
    {
        return tracerName.get();
    }

+    virtual const char* queryGlobalId() const override


in this file we typically have a new line between method definitions.

rpastrana · 2023-09-26T17:56:42Z

system/jlib/jtrace.cpp

@@ -518,6 +515,12 @@ class CServerSpan : public CSpan
                hpccGlobalId.set(httpHeaders->queryProp(kGlobalIdHttpHeaderName));
            else if (httpHeaders->hasProp(kLegacyGlobalIdHttpHeaderName))
                hpccGlobalId.set(httpHeaders->queryProp(kLegacyGlobalIdHttpHeaderName));
+            else if (hasMask(flags, SpanFlags::EnsureGlobalId))
+            {
+                StringBuffer gen_id;


minor, but var name doesn't follow file convention

rpastrana · 2023-09-26T17:59:58Z

system/jlib/jtrace.cpp

+                StringBuffer gen_id;
+                appendGloballyUniqueId(gen_id);
+                hpccGlobalId.set(gen_id.str());
+            }


looking over the new span flags, I notice we're not handling 'EnsureTraceId' here, and now I'm wondering what that flag's intention is.

What is the current behavior if a server span is created but there is not a trace header? Do we end up with a server span with it's own trace-id, but no reference to a remote parent span?

It may not be needed - I will delete for the moment, and can add back in later.

rpastrana · 2023-09-26T18:08:12Z

system/jlib/jlog.cpp

@@ -2863,25 +2868,33 @@ class DummyLogCtx : implements IContextLogger
    {
        return 0;
    }
-    virtual void setGlobalId(const char *id, SocketEndpoint &ep, unsigned pid) override
+    virtual void setActiveSpan(ISpan * span) override


minor, but this overloads the OTel "active span" concept, but it seems to convey a slightly different meaning. I would consider another term (not sure what it would be)

From what I've seen of the OTel active span concept it's basically for single threaded applications. I see this as the "per query" version of the active span concept.

From what I've seen of the OTel active span concept it's basically for single threaded applications. I see this as the "per query" version of the active span concept.

@afishbeck is this in reply to my comment to Gavin?
If so, it is still overloading the term and can be misunderstood. It should go without saying, and I'm sure you'll agree, we should avoid any/all potential confusion if possible.

Right, I could see someone already familiar with the OTel API making an assumption about what this means when they read the name.

Any suggestions for a better name? setCurrentSpan()?

current span was my immediate thought as well.

I think "current span" would be fine here.

rpastrana · 2023-09-26T18:08:54Z

system/jlib/jlog.cpp

@@ -2822,10 +2822,15 @@ void IContextLogger::logOperatorException(IException *E, const char *file, unsig
 }
 class CRuntimeStatisticCollection;

+/*
+  This class is used to implement the defauult log context - especially used for engines that only support a single query at a time


very minor, 'default'

afishbeck

@ghalliday some comments / questions.

afishbeck · 2023-09-26T18:13:45Z

esp/services/ws_ecl/ws_ecl_service.cpp

        if (globalId.length())
        {
            workunit->setDebugValue("GlobalId", globalId.str(), true);
-            workunit->setDebugValue("GlobalIdHeader", globalIdHeader.str(), true);  //use same header received


@ghalliday @rpastrana Note for when the ESP instrumentation is done, but I would expect open telemetry headers to also be added to the workunit here.

Yes - I would actually expect this to now call the new function recordTraceDebugOptions()

afishbeck · 2023-09-26T18:18:13Z

common/thorhelper/thorsoapcall.cpp

+            {
+                const char * key = iter->getPropKey();
+                if (!httpHeaderBlockContainsHeader(httpheaders, key))
+                    request.append(key).append(": ").append(traceHeaders->queryProp(key)).append("\r\n");


Is there any chance the value is empty?

Pass. I'll add a check.

afishbeck · 2023-09-26T18:39:47Z

roxie/ccd/ccdlistener.cpp

-            s.append("]");
+        ensureContextLogger();
+
+        Owned<ISpan> requestSpan = queryTraceManager().createServerSpan("request", headers, flags);


Should be passing allHeaders?

Well spotted. I will fix.

afishbeck · 2023-09-26T18:48:09Z

system/jlib/jlog.cpp

@@ -2863,25 +2868,33 @@ class DummyLogCtx : implements IContextLogger
    {
        return 0;
    }
-    virtual void setGlobalId(const char *id, SocketEndpoint &ep, unsigned pid) override
+    virtual void setActiveSpan(ISpan * span) override


From what I've seen of the OTel active span concept it's basically for single threaded applications. I see this as the "per query" version of the active span concept.

common/thorhelper/thorsoapcall.cpp

afishbeck · 2023-09-26T19:02:31Z

roxie/ccd/ccdlistener.cpp

@@ -1308,6 +1302,7 @@ class RoxieWorkUnitWorker : public RoxieQueryWorker
            StringBuffer s;
            logctx.getStats(s);

+            //MORE: logctx.queryActiveSpan()->getLogPrefix() or similar.


Agreed we need a consistent way of doing this for each flavor of tracing. And longer term we will need to make sure there is enough info to tie traces and log lines together so the tools can hop between the two.

afishbeck · 2023-09-26T19:10:58Z

roxie/ccd/ccdprotocol.cpp

-                    msgctx->setTransactionId(uid, nullptr, false);
-                else
+
+                msgctx->startSpan(uid, httpHelper.queryRequestHeaders());


I'm not too clear on how this interacts with or replaces the span created above, currently line 1801:

msgctx->startSpan(nullptr, httpHelper.queryRequestHeaders());

Should this really just be setting attributes on the initial span. For example if necessary updating the global-id header or related attributes?

I meant to delete the 1st one - I will fix. You should not be able to update the global-id/trace-id once the span has been started. Other properties are ok though.

afishbeck · 2023-09-26T19:33:22Z

system/jlib/jtrace.cpp

+                StringBuffer gen_id;
+                appendGloballyUniqueId(gen_id);
+                hpccGlobalId.set(gen_id.str());
+            }


What is the current behavior if a server span is created but there is not a trace header? Do we end up with a server span with it's own trace-id, but no reference to a remote parent span?

afishbeck · 2023-09-26T20:25:13Z

roxie/ccd/ccdprotocol.cpp

            }
        }

+        msgctx->startSpan(nullptr, httpHelper.queryRequestHeaders());


Spans will be used to analyze timings. Since there is a delay from when the socket was accepted and when the span is created I think we should have saved off the real start times and pass them in here to be used for the span.

From the open telemetry c++ sdk docs:

struct StartSpanOptions
{
// Optionally sets the start time of a Span.
//
// If the start time of a Span is set, timestamps from both the system clock
// and steady clock must be provided.
//
// Timestamps from the steady clock can be used to most accurately measure a
// Span's duration, while timestamps from the system clock can be used to most
// accurately place a Span's
// time point relative to other Spans collected across a distributed system.
common::SystemTimestamp start_system_time;
common::SteadyTimestamp start_steady_time;

Created HPCC-30374 and pasted your comment from here in there.

ghalliday

I will push an update.

common/thorhelper/thorsoapcall.cpp

ghalliday · 2023-09-27T09:02:42Z

common/thorhelper/thorsoapcall.cpp

+            {
+                const char * key = iter->getPropKey();
+                if (!httpHeaderBlockContainsHeader(httpheaders, key))
+                    request.append(key).append(": ").append(traceHeaders->queryProp(key)).append("\r\n");


Pass. I'll add a check.

ghalliday · 2023-09-27T09:04:07Z

esp/services/ws_ecl/ws_ecl_service.cpp

        if (globalId.length())
        {
            workunit->setDebugValue("GlobalId", globalId.str(), true);
-            workunit->setDebugValue("GlobalIdHeader", globalIdHeader.str(), true);  //use same header received


Yes - I would actually expect this to now call the new function recordTraceDebugOptions()

ghalliday · 2023-09-27T12:13:03Z

roxie/ccd/ccdlistener.cpp

-            s.append("]");
+        ensureContextLogger();
+
+        Owned<ISpan> requestSpan = queryTraceManager().createServerSpan("request", headers, flags);


Well spotted. I will fix.

ghalliday · 2023-09-27T12:15:54Z

roxie/ccd/ccdprotocol.cpp

            }
        }

+        msgctx->startSpan(nullptr, httpHelper.queryRequestHeaders());


Created HPCC-30374 and pasted your comment from here in there.

ghalliday · 2023-09-27T12:18:55Z

roxie/ccd/ccdprotocol.cpp

-                    msgctx->setTransactionId(uid, nullptr, false);
-                else
+
+                msgctx->startSpan(uid, httpHelper.queryRequestHeaders());


I meant to delete the 1st one - I will fix. You should not be able to update the global-id/trace-id once the span has been started. Other properties are ok though.

ghalliday · 2023-09-27T12:20:41Z

system/jlib/jlog.cpp

@@ -2863,25 +2868,33 @@ class DummyLogCtx : implements IContextLogger
    {
        return 0;
    }
-    virtual void setGlobalId(const char *id, SocketEndpoint &ep, unsigned pid) override
+    virtual void setActiveSpan(ISpan * span) override


Any suggestions for a better name? setCurrentSpan()?

ghalliday · 2023-09-27T12:21:06Z

system/jlib/jtrace.cpp

+    virtual void getLogPrefix(StringBuffer & out) const override
+    {
+        const char * caller = queryCallerId();
+        if (caller)


I will change

ghalliday · 2023-09-27T12:21:25Z

system/jlib/jtrace.cpp

+        if (caller)
+        {
+            out.append('[');
+            if (caller)


The outer condition is not right - I have since fixed.

ghalliday · 2023-09-27T12:24:21Z

system/jlib/jtrace.cpp

+                StringBuffer gen_id;
+                appendGloballyUniqueId(gen_id);
+                hpccGlobalId.set(gen_id.str());
+            }


It may not be needed - I will delete for the moment, and can add back in later.

ghalliday · 2023-09-27T13:48:08Z

@afishbeck @rpastrana rebased and issues addressed (2 new commits, 1 from changes I spotted, and second in response to reviews)

rpastrana

@ghalliday I didn't find any worthwhile issues.

afishbeck

@ghalliday A couple of general comments, and I think you were going to rename ActiveSpan, otherwise ready to approve.

afishbeck · 2023-09-27T15:57:29Z

helm/hpcc/values.schema.json

@@ -1743,12 +1743,12 @@
        "httpCallerIdHeader": { 
          "type": "string",
          "default": "HPCC-Caller-Id",
-          "description": "HTTP Header field to use for sending and receiving CallerId"
+          "description": "HTTP Header field to use for sending and receiving CallerId (deprecated and ignored)"


Should disappear when rebased?

afishbeck · 2023-09-27T15:59:54Z

system/jlib/jlog.cpp

@@ -2863,25 +2868,33 @@ class DummyLogCtx : implements IContextLogger
    {
        return 0;
    }
-    virtual void setGlobalId(const char *id, SocketEndpoint &ep, unsigned pid) override
+    virtual void setActiveSpan(ISpan * span) override


I think "current span" would be fine here.

afishbeck · 2023-09-27T16:13:04Z

system/jlib/jtrace.cpp

@@ -351,11 +301,57 @@ class CSpan : public CInterfaceOf<ISpan>
        return opentelemetry::trace::SpanContext::GetInvalid();
    }

+    virtual void getLogPrefix(StringBuffer & out) const override


Similar comment elsewhere. We want to avoid verbosity but ultimately should the span id be included here so that log processors can tie the trace info to the log lines. It makes for really nice navigation through the UI?

We have to maintain bw compatibility with the global-id services. But long term I hope that the global-id and local-id become attributes of the span and we only log the span-id.
The back end could then tie everything together. But that requires coordination with Kevin L. and Shanaka.

richardkchapman

One comment

richardkchapman · 2023-09-28T07:43:24Z

roxie/ccd/ccdlistener.cpp

+
+        Owned<IProperties> traceHeaders = extractTraceDebugOptions(wu);
+        Owned<ISpan> requestSpan = queryTraceManager().createServerSpan(wu->queryWuid(), traceHeaders);
+        updateDummyContextLogger().setActiveSpan(requestSpan);


Not sure why this would not be something like logxtx.setActiveSpan(requestSpan). What is the dummy context logger for?

Signed-off-by: Gavin Halliday <[email protected]>

ghalliday requested review from rpastrana and afishbeck September 26, 2023 16:03

rpastrana reviewed Sep 26, 2023

View reviewed changes

afishbeck reviewed Sep 26, 2023

View reviewed changes

ghalliday commented Sep 27, 2023

View reviewed changes

ghalliday force-pushed the issue30350 branch from dd3d336 to e5f3441 Compare September 27, 2023 13:47

ghalliday requested a review from afishbeck September 27, 2023 13:47

rpastrana approved these changes Sep 27, 2023

View reviewed changes

afishbeck reviewed Sep 27, 2023

View reviewed changes

ghalliday force-pushed the issue30350 branch 2 times, most recently from ac588bc to 429f1f7 Compare September 28, 2023 07:34

ghalliday requested a review from richardkchapman September 28, 2023 07:43

richardkchapman requested changes Sep 28, 2023

View reviewed changes

HPCC-30350 Add open telemetry support to roxie/hthor/thor

12afc8f

Signed-off-by: Gavin Halliday <[email protected]>

ghalliday force-pushed the issue30350 branch from 429f1f7 to 12afc8f Compare September 28, 2023 12:48

ghalliday requested a review from richardkchapman September 28, 2023 12:51

richardkchapman approved these changes Sep 28, 2023

View reviewed changes

ghalliday merged commit 1e8dd86 into hpcc-systems:candidate-9.4.x Sep 28, 2023

HPCC-30350 Add open telemetry support to roxie/hthor/thor #17822

HPCC-30350 Add open telemetry support to roxie/hthor/thor #17822

Conversation

ghalliday commented Sep 26, 2023 • edited Loading

Type of change:

Checklist:

Smoketest:

Testing:

ghalliday commented Sep 26, 2023

github-actions bot commented Sep 26, 2023

rpastrana left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rpastrana Sep 26, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

afishbeck left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ghalliday left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ghalliday commented Sep 27, 2023

rpastrana left a comment

Choose a reason for hiding this comment

afishbeck left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

richardkchapman left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ghalliday commented Sep 26, 2023 •

edited

Loading

rpastrana Sep 26, 2023 •

edited

Loading