Hpcc 30370 Instrument soapcall function calls #18336

rpastrana · 2024-02-24T04:41:54Z

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:

rpastrana · 2024-02-26T16:41:37Z

common/thorhelper/thorsoapcall.cpp

@@ -738,7 +738,7 @@ interface IWSCAsyncFor: public IInterface
    virtual void processException(const Url &url, ConstPointerArray &inputRows, IException *e) = 0;
    virtual void checkTimeLimitExceeded(unsigned * _remainingMS) = 0;

-    virtual void createHttpRequest(Url &url, StringBuffer &request) = 0;
+    virtual void createHttpRequest(Url &url, StringBuffer &request, IProperties * traceHeaders) = 0;


client span declared in function handling soaprequest, and passes clientheaders into the createrequest function, optionally we could set the client span as the "active" span

rpastrana · 2024-02-26T16:43:47Z

common/thorhelper/thorsoapcall.cpp

@@ -2504,13 +2524,15 @@ class CWSCAsyncFor : implements IWSCAsyncFor, public CInterface, public CAsyncFo
                {
                    if (master->timeLimitExceeded)
                    {
+                        clientSpan->recordError("time_limit_exceeded");


"time_limit_exceeded" is likely only good enough to denote the type of error encountered, but do we want to supply full log messages? or maybe something in between.
This is likely going to be handled differently on case-by-case basis

rpastrana · 2024-02-26T16:45:11Z

common/thorhelper/thorsoapcall.cpp

@@ -2640,22 +2672,36 @@ class CWSCAsyncFor : implements IWSCAsyncFor, public CInterface, public CAsyncFo
                }
                numRetries++;
                master->logctx.CTXLOG("Retrying: attempt %d of %d", numRetries, master->maxRetries);
+                clientSpan->recordException(e);


identical exceptions are recorded and do not overwrite each other

rpastrana · 2024-02-26T16:49:46Z

This PR is dep on #18335

rpastrana · 2024-02-28T15:58:03Z

@ghalliday I'm not convinced this is where you wanted the client span. Also, how do we feel about setting client spans as active span

ghalliday

A few comments inline.

Some other comments:

The title of the PR does not have the right format, which means it isn't associated with the jira.
The commented out code that should be cleaned up before it is ready for review

The jira suggests adding an internal scope for the soapcall, and client scopes for each of the soapcalls instances. That could be added as a subsequent PR, but if that is the plan it should be noted. (If implemented it would be simplest with the master->activitySpan mentioned in the comments)

ghalliday · 2024-02-29T11:38:38Z

common/thorhelper/thorsoapcall.cpp

+
+        Owned<ISpan> clientSpan;
+        ISpan * activeSpan = master->logctx.queryActiveSpan();
+        clientSpan.setown(activeSpan->createClientSpan(spanName.str()));


style: clearer to have the declaration of the variable at the same place it is initialised. i.e.

Owned<ISpan> clientSpan(activeSpan->createClientSpan(spanName.str()));

or

Owned<ISpan> clientSpan = activeSpan->createClientSpan(spanName.str());

style: clearer to have the declaration of the variable at the same place it is initialised. i.e.

Owned<ISpan> clientSpan(activeSpan->createClientSpan(spanName.str()));

or

Owned<ISpan> clientSpan = activeSpan->createClientSpan(spanName.str());

Agreed. To be fair, I borrowed this from one of your commits:
https://github.com/hpcc-systems/HPCC-Platform/blame/cb3794d81c594a7be5c25cb7e9e99fa44ab0249c/esp/services/ws_ecl/ws_ecl_service.cpp#L1981C18-L1981C28

Looking through the history of that change does bring up a question about our ability to depend on activeSpan != nullptr

ghalliday · 2024-02-29T11:39:57Z

common/thorhelper/thorsoapcall.cpp

+        url.getUrlString(spanName);
+
+        Owned<ISpan> clientSpan;
+        ISpan * activeSpan = master->logctx.queryActiveSpan();


This should probably be master->activitySpan (see summary comments)

ghalliday · 2024-02-29T11:40:23Z

common/thorhelper/thorsoapcall.cpp

+        Owned<ISpan> clientSpan;
+        ISpan * activeSpan = master->logctx.queryActiveSpan();
+        clientSpan.setown(activeSpan->createClientSpan(spanName.str()));
+        //master->logctx.setActiveSpan(clientSpan.get());


commented out code needs cleaning up...

ghalliday · 2024-02-29T11:42:14Z

common/thorhelper/thorsoapcall.cpp

+        //fprintf(stderr, "clientspan clientheader: %s\n", clientHeaders->queryProp("traceparent"));
+
+        createHttpRequest(url, request, clientHeaders.get());
+        clientSpan->setSpanAttribute("target_host", url.host.get());


Should be "network.peer_address" - see https://opentelemetry.io/docs/specs/semconv/http/http-spans/

ghalliday · 2024-02-29T11:43:19Z

common/thorhelper/thorsoapcall.cpp

@@ -2544,6 +2571,7 @@ class CWSCAsyncFor : implements IWSCAsyncFor, public CInterface, public CAsyncFo
                bool keepAlive2;
                StringBuffer contentType;
                int rval = readHttpResponse(response, socket, keepAlive2, contentType);
+                clientSpan->setSpanAttribute("http.code", (int64_t)rval);


"http.response.status_code" see https://opentelemetry.io/docs/specs/semconv/http/http-spans/

ghalliday · 2024-02-29T11:44:09Z

common/thorhelper/thorsoapcall.cpp

                        master->logctx.CTXLOG("%s exiting: time limit (%ums) exceeded", getWsCallTypeName(master->wscType), master->timeLimitMS);
                        processException(url, inputRows, e);
                        return;
                    }

                    if (e->errorCode() == ROXIE_ABORT_EVENT)
                    {
+                        clientSpan->recordError("roxie_abort");//simplified error msg, or verbose log style message?


"aborted" would be better.

ghalliday · 2024-02-29T11:48:15Z

common/thorhelper/thorsoapcall.cpp

@@ -2504,13 +2524,15 @@ class CWSCAsyncFor : implements IWSCAsyncFor, public CInterface, public CAsyncFo
                {
                    if (master->timeLimitExceeded)
                    {
+                        clientSpan->recordError("time_limit_exceeded");


I think it would be a good idea to always report an error number.
The error message should be human readable - that seems to be the implication of https://opentelemetry.io/docs/specs/semconv/exceptions/exceptions-spans/.

ghalliday · 2024-02-29T11:48:53Z

common/thorhelper/thorsoapcall.cpp

                        proto = PersistentProtocol::ProtoTLS;
+                        clientSpan->setSpanAttribute("target_protocol", "https");


"network.protocol.name" (https://opentelemetry.io/docs/specs/semconv/attributes-registry/network/)

ghalliday · 2024-02-29T11:50:16Z

common/thorhelper/thorsoapcall.cpp

                }
            }
            try
            {
                checkTimeLimitExceeded(&remainingMS);
                checkRoxieAbortMonitor(master->roxieAbortMonitor);
+                //per spec an http client span should be created here


This comment poses the question, "why isn't it?" Should the comment be deleted?

To avoid being pedantic, but I feel it should be added.
I'm thinking the existing span would change to an internal and this http span would be a client span, child of the internal.

ghalliday · 2024-02-29T11:51:09Z

common/thorhelper/thorsoapcall.cpp

@@ -2575,6 +2603,8 @@ class CWSCAsyncFor : implements IWSCAsyncFor, public CInterface, public CAsyncFo
                    else if (keepAlive)
                        persistentHandler->add(socket, &ep, proto);
                }
+
+                clientSpan->recordSuccess("SoapCall Succeded");


I don't think this benefits from an associated message. It doesn't convey any new information.

common/thorhelper/thorsoapcall.cpp

ghalliday

A few comments, but in general it looks really good. I'll revisit again, but probably merge as-is, and revisit these issues in a follow on PR.

ghalliday · 2024-03-18T17:11:55Z

common/thorhelper/thorsoapcall.cpp

@@ -1038,6 +1058,7 @@ class CWSCHelper : implements IWSCHelper, public CInterface
        if (wscType == STsoap)


It would be worth adding an attribute for the activity id - that will be very useful to the developer.

activitySpanScope->setSpanAttrubute("activity.id", )?

It might need to be a new parameter.

This sounds useful, but couldn't find a reasonable way to pass that info down to the helper

I added HPCC-31527 to add that as a separate task - it is relatively high priority.

ghalliday · 2024-03-18T17:12:16Z

common/thorhelper/thorsoapcall.cpp

@@ -1182,6 +1203,7 @@ class CWSCHelper : implements IWSCHelper, public CInterface

        if (wscMode == SCrow)
        {
+            activitySpanScope->setSpanAttribute("activity.mode", "SCrow");


I don't think activity.mode will be worth recording.

seems reasonable, I'll remove

ghalliday · 2024-03-18T17:18:52Z

common/thorhelper/thorsoapcall.cpp

                keepAlive = keepAlive && keepAlive2;

                if (soapTraceLevel > 4)
                    master->logctx.CTXLOG("%s: received response (%s) from %s:%d", getWsCallTypeName(master->wscType),master->service.str(), url.host.str(), url.port);

                if (rval != 200)
                {
+                    socketOperationSpan->setSpanStatus(false);


I see you have inverted the condition. It would be clearer if the function was renamed to

setSpanSuccess(true|false)

or something that makes it clear what the parameter means.
(Also now not needed because of the recordError() calls).

changing, but this is def still needed regardless of the recordError calls.

ghalliday · 2024-03-18T17:21:58Z

common/thorhelper/thorsoapcall.cpp

                }
            }
            try
            {
                checkTimeLimitExceeded(&remainingMS);
                checkRoxieAbortMonitor(master->roxieAbortMonitor);
+
+                StringBuffer spanName("SoapCall Socket Operation - ");


Not convinced about this name. I suspect it should not contain the url. I'm not 100% sure what it should be though.

Ok, you're not giving me much to go on. Changing it to Socket Write, which is 100% accurate, but in my opinion not as helpful. If that name doesn't convince you either, we'll have to discuss face to face and work out a name

ghalliday · 2024-03-19T16:22:43Z

@rpastrana I was going to merge and added https://hpccsystems.atlassian.net/browse/HPCC-31493 to track the changes, but the commits are a bit strange - they need squashing.

ghalliday

@rpastrana looks really good. A few minor issues picked up on a final scan - some caused by changes while this PR was in process.

ghalliday · 2024-03-27T10:07:43Z

common/thorhelper/thorsoapcall.cpp

@@ -1038,6 +1058,7 @@ class CWSCHelper : implements IWSCHelper, public CInterface
        if (wscType == STsoap)


I added HPCC-31527 to add that as a separate task - it is relatively high priority.

ghalliday · 2024-03-27T10:14:08Z

common/thorhelper/thorsoapcall.cpp

                }
            }
            try
            {
                checkTimeLimitExceeded(&remainingMS);
                checkRoxieAbortMonitor(master->roxieAbortMonitor);
+                Owned<ISpan> socketOperationSpan = master->activitySpanScope->createClientSpan("Socket Write");


Not convinced this span name is correct - but that can be revised later. I tried looking at https://opentelemetry.io/docs/specs/semconv/http/http-spans/#method-placeholder, but it wasn't very helpful!

ghalliday · 2024-03-27T10:14:44Z

common/thorhelper/thorsoapcall.cpp

                }
            }
            try
            {
                checkTimeLimitExceeded(&remainingMS);
                checkRoxieAbortMonitor(master->roxieAbortMonitor);
+                Owned<ISpan> socketOperationSpan = master->activitySpanScope->createClientSpan("Socket Write");


Should be an OwnedSpanScope rather than Owned

ghalliday · 2024-03-27T10:17:03Z

testing/unittests/jlibtests.cpp

@@ -289,14 +289,14 @@ class JlibTraceTest : public CppUnit::TestFixture
        {
            OwnedSpanScope serverSpan = queryTraceManager().createServerSpan("failedErrorSpanEscaped", emptyMockHTTPHeaders);
            SpanError * error = new SpanError("hello");
-            error->setSpanStatus(true, true);
+            error->setSpanStatusSuccess(true, true);


Should be (false, true)

ghalliday · 2024-03-27T10:17:27Z

testing/unittests/jlibtests.cpp

@@ -289,14 +289,14 @@ class JlibTraceTest : public CppUnit::TestFixture
        {
            OwnedSpanScope serverSpan = queryTraceManager().createServerSpan("failedErrorSpanEscaped", emptyMockHTTPHeaders);
            SpanError * error = new SpanError("hello");


error leaks. Simpler (as you have done elsewhere) to use a local variable instead.

same below line 299

ghalliday · 2024-03-27T10:18:06Z

testing/unittests/jlibtests.cpp

            serverSpan->recordError(*error);
        }//{ "type": "span", "name": "failedErrorSpanEscaped", "trace_id": "634f386c18a6140544c980e0d5a15905", "span_id": "e2f59c48f63a8f82", "start": 1709675508231168974, "duration": 7731717678, "status": "Error", "kind": "Server", "description": "hello", "instrumented_library": "unittests", "events":[ { "name": "Exception", "time_stamp": 1709675512164430668, "attributes": {"escaped": 1,"message": "hello" } } ] }

        {
            OwnedSpanScope serverSpan = queryTraceManager().createServerSpan("failedErrEscapedMsgErrCode", emptyMockHTTPHeaders);
            SpanError * error = new SpanError();
-            error->setSpanStatus(true, true);
+            error->setSpanStatusSuccess(true, true);


Also (false, true)

- Remove unnecessary commented out code - Rename setSpanStatus param to spanSucceeded - Adds escapeScope param - Adds method to setSpanURL attributes - Creates new span wrapping socket operations - Creates soapcall activity level span Signed-off-by: Rodrigo Pastrana <[email protected]>

rpastrana · 2024-03-28T16:01:23Z

@ghalliday tested successfully. Reverted SpanError failed flags in jlib tests

rpastrana commented Feb 26, 2024

View reviewed changes

rpastrana changed the title ~~Hpcc 30370 soap call span~~ Hpcc 30370 Instrument soapcall function calls Feb 26, 2024

rpastrana requested a review from ghalliday February 28, 2024 15:55

ghalliday reviewed Feb 29, 2024

View reviewed changes

rpastrana force-pushed the HPCC-30370-SoapCallSpan branch 2 times, most recently from 56df44a to dfc526c Compare March 13, 2024 03:14

rpastrana requested a review from ghalliday March 14, 2024 13:28

rpastrana commented Mar 14, 2024

View reviewed changes

common/thorhelper/thorsoapcall.cpp Show resolved Hide resolved

ghalliday reviewed Mar 18, 2024

View reviewed changes

rpastrana force-pushed the HPCC-30370-SoapCallSpan branch from 14e976d to 688badf Compare March 26, 2024 02:27

rpastrana requested a review from ghalliday March 26, 2024 02:34

ghalliday reviewed Mar 27, 2024

View reviewed changes

rpastrana force-pushed the HPCC-30370-SoapCallSpan branch 5 times, most recently from 0d3dc4f to f4ebb6f Compare March 28, 2024 02:42

rpastrana force-pushed the HPCC-30370-SoapCallSpan branch from f4ebb6f to 00e8c34 Compare March 28, 2024 15:57

ghalliday approved these changes Mar 28, 2024

View reviewed changes

ghalliday merged commit 14dab01 into hpcc-systems:candidate-9.4.x Mar 28, 2024
48 checks passed

		proto = PersistentProtocol::ProtoTLS;
		clientSpan->setSpanAttribute("target_protocol", "https");

		@@ -1038,6 +1058,7 @@ class CWSCHelper : implements IWSCHelper, public CInterface
		if (wscType == STsoap)

Hpcc 30370 Instrument soapcall function calls #18336

Hpcc 30370 Instrument soapcall function calls #18336

Conversation

rpastrana commented Feb 24, 2024 • edited Loading

Type of change:

Checklist:

Smoketest:

Testing:

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rpastrana commented Feb 26, 2024

rpastrana commented Feb 28, 2024

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

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 Mar 19, 2024

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

rpastrana commented Mar 28, 2024

rpastrana commented Feb 24, 2024 •

edited

Loading