HPCC-31755 Soapcall LOG multi-line separator #19145

mckellyln · 2024-09-24T15:32:34Z

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:

github-actions · 2024-09-24T15:56:30Z

Jira Issue: https://hpccsystems.atlassian.net//browse/HPCC-31755

Jirabot Action Result:
Workflow Transition To: Merge Pending
Additional PR: #19145

jakesmith

@mckellyln - please see comments.

jakesmith · 2024-09-27T10:03:59Z

common/thorhelper/thorsoapcall.cpp

@@ -1951,10 +1952,19 @@ class CWSCAsyncFor : implements IWSCAsyncFor, public CInterface, public CAsyncFo
    {
        if (soapTraceLevel > 6 || master->logXML)
        {
-            if (!contentEncoded)
-                master->logctx.mCTXLOG("%s: request(%s)", master->wscCallTypeText(), request.str());
+            StringBuffer contentStr("");


trivial/style: ("") not needed.

jakesmith · 2024-09-27T12:14:47Z

ecl/hthor/hthor.cpp

+    StringBufferAdaptor soapSepAdaptor(soapSepStr);
+    agent.queryWorkUnit()->getDebugValue("soapLogSepString", soapSepAdaptor);
+    if (!soapSepStr.isEmpty())
+        soapSepString.clear().append(soapSepStr);


why not populate soapSepStr directly? :

StringBufferAdaptor soapSepAdaptor(soapSepString); agent.queryWorkUnit()->getDebugValue("soapLogSepString", soapSepAdaptor);

calling here (in activity init code) means it this will be called multiple times per job (if there are act based on this base per job). [ that's true of existing soapTraceLevel line too ]

Maybe nothing to worry about

jakesmith · 2024-09-27T12:18:56Z

common/thorhelper/thorsoapcall.cpp

@@ -50,6 +50,7 @@ using roxiemem::OwnedRoxieString;
 #define CONNECTION "Connection"

 unsigned soapTraceLevel = 1;
+StringBuffer soapSepString("");


trivial/style: ("") not needed.

jakesmith · 2024-09-27T12:22:33Z

common/thorhelper/thorsoapcall.cpp

+                request2.replaceString("\r\n", soapSepString.str());
+                request2.replaceString("\r", soapSepString.str());
+                request2.replaceString("\n", soapSepString.str());
+                master->logctx.mCTXLOG("%s: request(%s)%s", master->wscCallTypeText(), request2.str(), contentStr.str());


minor: the start of contentStr could be commoned up to include the "%s: request":

VStringBuffer contentStr("%s: request", master->wscCallTypeText());

jakesmith · 2024-09-27T12:31:38Z

common/thorhelper/thorsoapcall.hpp

@@ -86,5 +86,6 @@ interface IRoxieAbortMonitor
 extern THORHELPER_API unsigned soapTraceLevel;
 extern THORHELPER_API IWSCHelper * createSoapCallHelper(IWSCRowProvider *, IEngineRowAllocator * outputAllocator, const char *authToken, SoapCallMode scMode, ClientCertificate *clientCert, const IContextLogger &logctx, IRoxieAbortMonitor * roxieAbortMonitor);
 extern THORHELPER_API IWSCHelper * createHttpCallHelper(IWSCRowProvider *, IEngineRowAllocator * outputAllocator, const char *authToken, SoapCallMode scMode, ClientCertificate *clientCert, const IContextLogger &logctx, IRoxieAbortMonitor * roxieAbortMonitor);
+extern THORHELPER_API StringBuffer soapSepString;


this is going to cause the object to be copied where included I think.
Should either be a reference or a method
To be reference would mean the cpp would have to have code something like this:

static StringBuffer _soapSepString; StringBuffer &soapSepString = _soapSepString;

A method is probably cleanest.

jakesmith · 2024-09-27T12:42:57Z

common/thorhelper/thorsoapcall.cpp

+                response2.replaceString("\r\n", soapSepString.str());
+                response2.replaceString("\r", soapSepString.str());
+                response2.replaceString("\n", soapSepString.str());
+                master->logctx.mCTXLOG("%s: LEN=%d %sresponse(%s)", getWsCallTypeName(master->wscType),response.length(),chunked?"CHUNKED ":"", response2.str());


mCTXLOG (multiline CTXLOG) is parsing newline/carriage returns specifically to call multiple CTXLOG calls).
I think you should be calling logctx.CTXLOG after removing the newlines.

jakesmith · 2024-09-27T13:45:11Z

roxie/ccd/ccdstate.cpp

+            else if (stricmp(queryName, "control:soapLogSepString")==0)
+            {
+                if (control->hasProp("@string"))
+                    control->getProp("@string", soapSepString);


is this theoretically thread unsafe in combination with the placement of the code in HThorWSCBaseActivity::init() ?
e.g. if an activity is initializing when this thread is also initializing.

Also, if called multiple times soapSepString will grow (should be soapSepString.clear())

jakesmith · 2024-09-27T13:47:07Z

common/thorhelper/thorsoapcall.cpp

+                response2.append(response);
+                response2.replaceString("\r\n", soapSepString.str());
+                response2.replaceString("\r", soapSepString.str());
+                response2.replaceString("\n", soapSepString.str());


Quite expensive (to build up new StringBuffer with dbgheader+response), then call multiple replaceString's which will walk the whole response for each call.

It may be worth adding a function to append to a StringBuffer replacing the sequences with the new separator (or removing them) as it goes.
An efficient implementation could be quite simple if it only removed (meaning the target was guaranteed to be smaller than source).

NOTE this PR to optimize replaceString: #19187

mckellyln · 2024-10-06T22:21:23Z

@jakesmith thx, please re-review changes in commit 2

mckellyln · 2024-10-07T19:57:30Z

common/thorhelper/thorsoapcall.cpp

+}
+
+static void multiLineAppendReplace(StringBuffer &origStr, StringBuffer &newStr)
+{


As an opt, we could index for '\r' and then append chunks between newlines.

yes, if it was very time critical, might be worth two pass, so can allocate correct size once, reserve and use regular ptr's instead of calls to StringBuffer, but doubt worth it.

jakesmith

@mckellyln - looks good, a few minor/trivial comments

jakesmith · 2024-10-08T08:26:35Z

common/thorhelper/thorsoapcall.cpp

+StringBuffer soapSepString;
+static CriticalSection soapCrit;
+
+void setSoapSepString(StringBuffer &_soapSepString)


trivial/style: if no benefit to passing a StringBuffer as param vs simlp[e const char *, then we normally do later, it's more portable/usable (doesn't enforce having to need a StringBuffer when not needed).

jakesmith · 2024-10-08T08:27:31Z

common/thorhelper/thorsoapcall.cpp

+void setSoapSepString(StringBuffer &_soapSepString)
+{
+    CriticalBlock b(soapCrit);
+    soapSepString.clear().append(_soapSepString);


trivial: StringBuffer::set is equivalent

jakesmith · 2024-10-08T08:37:17Z

ecl/hthor/hthor.cpp

@@ -7741,8 +7741,7 @@ void CHThorWSCBaseActivity::init()
    StringBuffer soapSepStr;
    StringBufferAdaptor soapSepAdaptor(soapSepStr);
    agent.queryWorkUnit()->getDebugValue("soapLogSepString", soapSepAdaptor);
-    if (!soapSepStr.isEmpty())
-        soapSepString.clear().append(soapSepStr);
+    setSoapSepString(soapSepStr);


this means the default (and in thorsoapcall.cpp) is an empty string.
i.e. by default soap responses will be stripped of linefeeds and lines concatenated together. Is that what we want?
Shouldn't " " be set to default in thorsoapcall, and not changed here / elsewhere, unless option provided?

If soapSepString is empty (the default unless its set in config) then no translation is done.
I didn't think we should also allow only removal of the newlines.

jakesmith · 2024-10-08T08:38:15Z

thorlcr/graph/thgraph.cpp

-    getOpt(THOROPT_SOAP_LOG_SEP_STRING, soapSepString);
+    StringBuffer tmpSepString;
+    getOpt(THOROPT_SOAP_LOG_SEP_STRING, tmpSepString);
+    setSoapSepString(tmpSepString);


see other comment in hthor.cpp - shouldn't it default to something like " " in thorsoapcall.cpp - and only set/change here if property present? Otherwise default is to strip and join lines together.

jakesmith · 2024-10-08T10:13:32Z

common/thorhelper/thorsoapcall.cpp

@@ -50,6 +50,41 @@ using roxiemem::OwnedRoxieString;
 #define CONNECTION "Connection"

 unsigned soapTraceLevel = 1;
+StringBuffer soapSepString;


looks like this should now be a static

jakesmith · 2024-10-08T10:25:35Z

common/thorhelper/thorsoapcall.cpp

+}
+
+static void multiLineAppendReplace(StringBuffer &origStr, StringBuffer &newStr)
+{


yes, if it was very time critical, might be worth two pass, so can allocate correct size once, reserve and use regular ptr's instead of calls to StringBuffer, but doubt worth it.

jakesmith

@mckellyln - looks good. Please squash.

mckellyln · 2024-10-08T14:30:49Z

Thanks, squashed.

jakesmith · 2024-10-08T14:39:57Z

common/thorhelper/thorsoapcall.cpp

+    if (origStr.isEmpty())
+        return;
+    const char *cursor = origStr;
+    while (cursor)


should be while (*cursor) (or could be while (true) which it effectively is)

mckellyln · 2024-10-08T17:15:06Z

common/thorhelper/thorsoapcall.cpp

+static void multiLineAppendReplace(StringBuffer &origStr, StringBuffer &newStr)
+{
+    if (origStr.isEmpty())
+        return;


Perhaps we newStr.ensureCapacity(origStr.length()) before starting loop so we dont have to expand it more than once ?

if replacement separator was >1 char and existing separator was \n, it would still have to expand more than once.
an initial guess ensureCapacity wouldn't harm, but not sure worth it, unless this is going to intensively used.

I agree preallocate to the original size.

mckellyln · 2024-10-08T21:06:53Z

I don't understand failing test -

exec sudo snap install microk8s --channel=1.27/stable --classic { silent: false }
error: cannot perform the following tasks:

Download snap "microk8s" (7016) from channel "1.27/stable" (unexpected EOF)

I think this is unrelated to code changes ?

mckellyln · 2024-10-09T17:47:30Z

ok, a rerun of the tests shows all ok

ghalliday

Looks good, a few minor comments

ghalliday · 2024-10-10T14:21:08Z

common/thorhelper/thorsoapcall.cpp

+            StringBuffer contentStr;
+            if (contentEncoded)
+                contentStr.append(", content encoded.");
+            if ( (master->logXML) && (soapSepString.length() > 0) )


check: I think the master->logXML test can be deleted.

I left it and added comment - so we only do translation if LOG set in SOAPCALL args

ghalliday · 2024-10-10T14:22:05Z

common/thorhelper/thorsoapcall.cpp

+static void multiLineAppendReplace(StringBuffer &origStr, StringBuffer &newStr)
+{
+    if (origStr.isEmpty())
+        return;


I agree preallocate to the original size.

ghalliday · 2024-10-10T14:22:25Z

common/thorhelper/thorsoapcall.cpp

-        else if (soapTraceLevel > 8)
-            master->logctx.mCTXLOG("%s: LEN=%d %sresponse(%s)", getWsCallTypeName(master->wscType),response.length(),chunked?"CHUNKED ":"", response.str()); // not sure this is that useful but...
+        {
+            if ( (master->logXML) && (soapSepString.length() > 0) )


ghalliday · 2024-10-10T14:24:05Z

common/thorhelper/thorsoapcall.cpp

+
+void setSoapSepString(const char *_soapSepString)
+{
+    CriticalBlock b(soapCrit);


Remove the critical and the control: command to change it, and require that this is only called when no soapcalls are running, OR all access to this static needs to be in a critical block

Is it enough that we remove the control: dynamic setting of this ? As then its only set at job start or Roxie start.

mckellyln · 2024-10-10T15:16:57Z

@ghalliday updated PR, thank you. Will squash when ready.

ghalliday

@mckellyln please squash

ghalliday · 2024-10-14T14:23:40Z

ecl/hthor/hthor.cpp

@@ -7738,6 +7738,10 @@ void CHThorWSCBaseActivity::init()
        JBASE64_Encode(uidpair.str(), uidpair.length(), authToken, false);
    }
    soapTraceLevel = agent.queryWorkUnit()->getDebugValueInt("soapTraceLevel", 1);
+    StringBuffer soapSepStr;


future: Can use SCMStringBuffer to avoid the need for the adaptor.

Signed-off-by: M Kelly <[email protected]>

mckellyln · 2024-10-14T15:15:57Z

Squashed

mckellyln force-pushed the hpcc-31755 branch from c8dc2fc to 608dee7 Compare September 24, 2024 15:34

mckellyln requested a review from jakesmith September 25, 2024 12:09

jakesmith reviewed Sep 27, 2024

View reviewed changes

mckellyln requested a review from jakesmith October 6, 2024 22:21

mckellyln commented Oct 7, 2024

View reviewed changes

jakesmith reviewed Oct 8, 2024

View reviewed changes

mckellyln force-pushed the hpcc-31755 branch from 66f249b to f247c05 Compare October 8, 2024 14:16

mckellyln requested a review from jakesmith October 8, 2024 14:17

jakesmith approved these changes Oct 8, 2024

View reviewed changes

mckellyln force-pushed the hpcc-31755 branch from f247c05 to ce9e35d Compare October 8, 2024 14:30

jakesmith reviewed Oct 8, 2024

View reviewed changes

mckellyln force-pushed the hpcc-31755 branch from ce9e35d to 56ea895 Compare October 8, 2024 14:43

mckellyln commented Oct 8, 2024

View reviewed changes

ghalliday reviewed Oct 10, 2024

View reviewed changes

mckellyln force-pushed the hpcc-31755 branch from 56ea895 to 18265f5 Compare October 10, 2024 14:45

mckellyln requested a review from ghalliday October 10, 2024 15:16

ghalliday approved these changes Oct 14, 2024

View reviewed changes

HPCC-31755 Soapcall LOG multi-line separator

85f7475

Signed-off-by: M Kelly <[email protected]>

mckellyln force-pushed the hpcc-31755 branch from 9cb9432 to 85f7475 Compare October 14, 2024 15:14

ghalliday merged commit 6302a03 into hpcc-systems:candidate-9.6.x Oct 14, 2024
25 checks passed

HPCC-31755 Soapcall LOG multi-line separator #19145

HPCC-31755 Soapcall LOG multi-line separator #19145

Conversation

mckellyln commented Sep 24, 2024

Type of change:

Checklist:

Smoketest:

Testing:

github-actions bot commented Sep 24, 2024

jakesmith 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

mckellyln commented Oct 6, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jakesmith 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

jakesmith left a comment

Choose a reason for hiding this comment

mckellyln commented Oct 8, 2024

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

mckellyln commented Oct 8, 2024

mckellyln commented Oct 9, 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

mckellyln commented Oct 10, 2024

ghalliday left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mckellyln commented Oct 14, 2024