Merge pull request #14969 from afishbeck/soapcallLOG

HPCC-24059 Additional SOAPCALL option to log text at end of soap request

Reviewed-By: Gavin Halliday <gavin.halliday@lexisnexis.com>
Reviewed-By: Richard Chapman <rchapman@hpccsystems.com>

common/thorhelper/thorsoapcall.cpp

@@ -33,6 +33,8 @@
 #include "zcrypt.hpp"
 #include "persistent.hpp"
 
+#include <memory>
+
 using roxiemem::OwnedRoxieString;
 
 #ifndef _WIN32
@@ -861,6 +863,7 @@ public:
         logMin = (flags & SOAPFlogmin) != 0;
         logXML = (flags & SOAPFlog) != 0;
         logUserMsg = (flags & SOAPFlogusermsg) != 0;
+        logUserTailMsg = (flags & SOAPFlogusertail) != 0;
 
         double dval = helper->getTimeout(); // In seconds, but may include fractions of a second...
         if (dval < 0.0) //not provided, or out of range
@@ -1168,6 +1171,16 @@ public:
             logctx.CTXLOG("%s: %.*s", wscCallTypeText(), lenText, text.getstr());
         }
     }
+    void addUserLogTailMsg(const byte * row, unsigned timeTaken)
+    {
+        if (logUserTailMsg)
+        {
+            size32_t lenText;
+            rtlDataAttr text;
+            helper->getLogTailText(lenText, text.refstr(), row);
+            logctx.CTXLOG("%s [time=%u]: %.*s", wscCallTypeText(), timeTaken, lenText, text.getstr());
+        }
+    }
     inline IXmlToRowTransformer * getRowTransformer() { return rowTransformer; }
     inline const char * wscCallTypeText() const { return wscType == STsoap ? "SOAPCALL" : "HTTPCALL"; }
 
@@ -1232,6 +1245,7 @@ protected:
     bool logXML;
     bool logMin;
     bool logUserMsg;
+    bool logUserTailMsg = false;
     bool aborted;
     const IContextLogger &logctx;
     unsigned flags;
@@ -1385,8 +1399,30 @@ void CWSCHelperThread::createXmlSoapQuery(IXmlWriterExt &xmlWriter, ConstPointer
     xmlWriter.outputEndNested("soap:Envelope");
 }
 
+class CWSUserLogCompletor
+{
+public:
+    CWSUserLogCompletor(CWSCHelper &wshelper, ConstPointerArray &rows) : helper(wshelper), inputRows(rows) {}
+    ~CWSUserLogCompletor()
+    {
+        //user log entries were output for the whole batch in the createXXXQuery routine above
+        //need to match each with a query complete log entry
+        unsigned timeTaken = msTick()-start;
+        ForEachItemIn(idx, inputRows)
+            helper.addUserLogTailMsg((const byte *)inputRows.item(idx), timeTaken);
+    }
+private:
+    unsigned start = msTick();
+    ConstPointerArray &inputRows;
+    CWSCHelper &helper;
+};
+
 void CWSCHelperThread::processQuery(ConstPointerArray &inputRows)
 {
+    std::unique_ptr<CWSUserLogCompletor> log;
+    if (master->logUserTailMsg)
+        log.reset(new CWSUserLogCompletor(*master, inputRows));
+
     unsigned xmlWriteFlags = 0;
     unsigned xmlReadFlags = ptr_ignoreNameSpaces;
     if (master->flags & SOAPFtrim)

ecl/hql/hqlgram.y

@@ -3768,6 +3768,12 @@ soapFlag
                             parser->normalizeExpression($3, type_string, false);
                             $$.setExpr(createExprAttribute(logAtom, $3.getExpr()), $1);
                         }
+    | TOK_LOG '(' expression ',' expression ')'
+                        {
+                            parser->normalizeExpression($3, type_string, false);
+                            parser->normalizeExpression($5, type_string, false);
+                            $$.setExpr(createExprAttribute(logAtom, $3.getExpr(), $5.getExpr()), $1);
+                        }
     | XML_TOKEN         {
                             $$.setExpr(createAttribute(xmlAtom));
                             $$.setPosition($1);

ecl/hqlcpp/hqlhtcpp.cpp

@@ -17965,7 +17965,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivitySOAP(BuildCtx & ctx, IHqlExpre
 
     IHqlExpression * namespaceAttr = expr->queryAttribute(namespaceAtom);
     IHqlExpression * responseAttr = expr->queryAttribute(responseAtom);
-    IHqlExpression * logText = NULL;
+    HqlExprArray logTextArray;
     bool logMin = false;
     bool logXml = false;
     ForEachChildFrom(i, expr, 1)
@@ -17977,7 +17977,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivitySOAP(BuildCtx & ctx, IHqlExpre
             if (!opt)
                 logXml = true;
             else if (!opt->isAttribute())
-                logText = opt;
+                unwindChildren(logTextArray, cur);
             else if (opt->queryName() == minAtom)
                 logMin = true;
         }
@@ -18005,7 +18005,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivitySOAP(BuildCtx & ctx, IHqlExpre
             doBuildVarStringFunction(instance->startctx, "getNamespaceVar", namespaceAttr->queryChild(1));
     }
 
-    if (logText)
+    if (logTextArray.length())
     {
         MemberFunction func(*this, instance->startctx, "virtual void getLogText(size32_t & __lenResult, char * & __result, const void * _left) override");
         if (dataset)
@@ -18014,8 +18014,21 @@ ABoundActivity * HqlCppTranslator::doBuildActivitySOAP(BuildCtx & ctx, IHqlExpre
             bindTableCursor(func.ctx, dataset, "left");
             bindTableCursor(func.ctx, dataset, "left", no_left, selSeq);
         }
-        doBuildFunctionReturn(func.ctx, unknownStringType, logText);
+        doBuildFunctionReturn(func.ctx, unknownStringType, &logTextArray.item(0));
     }
+
+    if (logTextArray.length()>1)
+    {
+        MemberFunction func(*this, instance->startctx, "virtual void getLogTailText(size32_t & __lenResult, char * & __result, const void * _left) override");
+        if (dataset)
+        {
+            func.ctx.addQuotedLiteral("const unsigned char * left = (const unsigned char *) _left;");
+            bindTableCursor(func.ctx, dataset, "left");
+            bindTableCursor(func.ctx, dataset, "left", no_left, selSeq);
+        }
+        doBuildFunctionReturn(func.ctx, unknownStringType, &logTextArray.item(1));
+    }
+
     bool usesContents = false;
     bool hasXpathHints = false;
     if (!isSink)
@@ -18082,8 +18095,10 @@ ABoundActivity * HqlCppTranslator::doBuildActivitySOAP(BuildCtx & ctx, IHqlExpre
             flags.append("|SOAPFpreserveSpace");
         if (logMin)
             flags.append("|SOAPFlogmin");
-        if (logText)
+        if (logTextArray.length())
             flags.append("|SOAPFlogusermsg");
+        if (logTextArray.length()>1)
+            flags.append("|SOAPFlogusertail");
         if (expr->hasAttribute(httpHeaderAtom))
             flags.append("|SOAPFhttpheaders");
         if (usesContents)
@@ -18158,7 +18173,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivityHTTP(BuildCtx & ctx, IHqlExpre
         doBuildVarStringFunction(instance->startctx, "queryOutputIteratorPath", separator->queryChild(0));
 
     IHqlExpression * namespaceAttr = expr->queryAttribute(namespaceAtom);
-    IHqlExpression * logText = NULL;
+    HqlExprArray logTextArray;
     bool logMin = false;
     bool logXml = false;
     ForEachChildFrom(i, expr, 1)
@@ -18170,7 +18185,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivityHTTP(BuildCtx & ctx, IHqlExpre
             if (!opt)
                 logXml = true;
             else if (!opt->isAttribute())
-                logText = opt;
+                unwindCommaCompound(logTextArray, opt);
             else if (opt->queryName() == minAtom)
                 logMin = true;
         }
@@ -18198,10 +18213,16 @@ ABoundActivity * HqlCppTranslator::doBuildActivityHTTP(BuildCtx & ctx, IHqlExpre
             doBuildVarStringFunction(instance->startctx, "getNamespaceVar", namespaceAttr->queryChild(1));
     }
 
-    if (logText)
+    if (logTextArray.length())
     {
         MemberFunction func(*this, instance->startctx, "virtual void getLogText(size32_t & __lenResult, char * & __result, const void * _left) override");
-        doBuildFunctionReturn(func.ctx, unknownStringType, logText);
+        doBuildFunctionReturn(func.ctx, unknownStringType, &logTextArray.item(0));
+    }
+
+    if (logTextArray.length()>1)
+    {
+        MemberFunction func(*this, instance->startctx, "virtual void getLogTailText(size32_t & __lenResult, char * & __result, const void * _left) override");
+        doBuildFunctionReturn(func.ctx, unknownStringType, &logTextArray.item(1));
     }
 
     bool usesContents = false;
@@ -18241,8 +18262,10 @@ ABoundActivity * HqlCppTranslator::doBuildActivityHTTP(BuildCtx & ctx, IHqlExpre
             flags.append("|SOAPFnamespace");
         if (logMin)
             flags.append("|SOAPFlogmin");
-        if (logText)
+        if (logTextArray.length())
             flags.append("|SOAPFlogusermsg");
+        if (logTextArray.length()>1)
+            flags.append("|SOAPFlogusertail");
         if (expr->hasAttribute(httpHeaderAtom))
             flags.append("|SOAPFhttpheaders");
         if (usesContents)

rtl/eclrtl/eclhelper_base.cpp

@@ -614,6 +614,7 @@ IXmlToRowTransformer * CThorSoapActionArg::queryInputTransformer() { return NULL
 const char * CThorSoapActionArg::getInputIteratorPath() { return NULL; }
 size32_t CThorSoapActionArg::onFailTransform(ARowBuilder & rowBuilder, const void * left, IException * e) { return 0; }
 void CThorSoapActionArg::getLogText(size32_t & lenText, char * & text, const void * left) { lenText =0; text = NULL; }
+void CThorSoapActionArg::getLogTailText(size32_t & lenText, char * & text, const void * left) { lenText =0; text = NULL; }
 const char * CThorSoapActionArg::getXpathHintsXml() { return nullptr;}
 const char * CThorSoapActionArg::getRequestHeader() { return nullptr; }
 const char * CThorSoapActionArg::getRequestFooter() { return nullptr; }
@@ -645,6 +646,7 @@ const char * CThorSoapCallArg::getRequestFooter() { return nullptr; }
 
 size32_t CThorSoapCallArg::onFailTransform(ARowBuilder & rowBuilder, const void * left, IException * e) { return 0; }
 void CThorSoapCallArg::getLogText(size32_t & lenText, char * & text, const void * left) { lenText =0; text = NULL; }
+void CThorSoapCallArg::getLogTailText(size32_t & lenText, char * & text, const void * left) { lenText =0; text = NULL; }
 
 //CThorParseArg
 

rtl/include/eclhelper.hpp

@@ -48,7 +48,7 @@ typedef unsigned short UChar;
 
 //Should be incremented whenever the virtuals in the context or a helper are changed, so
 //that a work unit can't be rerun.  Try as hard as possible to retain compatibility.
-#define ACTIVITY_INTERFACE_VERSION      652
+#define ACTIVITY_INTERFACE_VERSION      653
 #define MIN_ACTIVITY_INTERFACE_VERSION  650             //minimum value that is compatible with current interface
 
 typedef unsigned char byte;
@@ -2222,7 +2222,8 @@ enum
     SOAPFxpathhints     = 0x002000,
     SOAPFnoroot         = 0x004000,
     SOAPFjson           = 0x008000,
-    SOAPFxml            = 0x010000
+    SOAPFxml            = 0x010000,
+    SOAPFlogusertail    = 0x020000
 };
 
 struct IHThorWebServiceCallActionArg : public IHThorArg
@@ -2256,6 +2257,7 @@ struct IHThorWebServiceCallActionArg : public IHThorArg
     virtual const char * getXpathHintsXml() = 0; //iff SOAPFxpathhints
     virtual const char * getRequestHeader() = 0;
     virtual const char * getRequestFooter() = 0;
+    virtual void getLogTailText(size32_t & lenText, char * & text, const void * left) = 0;  // iff SOAPFlogusertail set
 };
 typedef IHThorWebServiceCallActionArg IHThorSoapActionArg ;
 typedef IHThorWebServiceCallActionArg IHThorHttpActionArg ;

rtl/include/eclhelper_base.hpp

@@ -817,6 +817,7 @@ class ECLRTL_API CThorSoapActionArg : public CThorSinkArgOf<IHThorSoapActionArg>
     virtual const char * getInputIteratorPath() override;
     virtual size32_t onFailTransform(ARowBuilder & rowBuilder, const void * left, IException * e) override;
     virtual void getLogText(size32_t & lenText, char * & text, const void * left) override;
+    virtual void getLogTailText(size32_t & lenText, char * & text, const void * left) override;
     virtual const char * getXpathHintsXml() override;
     virtual const char * getRequestHeader() override;
     virtual const char * getRequestFooter() override;
@@ -846,6 +847,7 @@ class ECLRTL_API CThorSoapCallArg : public CThorArgOf<IHThorSoapCallArg>
     virtual const char * getInputIteratorPath() override;
     virtual size32_t onFailTransform(ARowBuilder & rowBuilder, const void * left, IException * e) override;
     virtual void getLogText(size32_t & lenText, char * & text, const void * left) override;
+    virtual void getLogTailText(size32_t & lenText, char * & text, const void * left) override;
     virtual const char * getXpathHintsXml() override;
     virtual const char * getRequestHeader() override;
     virtual const char * getRequestFooter() override;

testing/regress/ecl/soapcall.ecl

@@ -72,7 +72,7 @@ END;
 
 // Test some failure cases
 
-output(SORT(SOAPCALL(d, blacklistedTargetURL,'soapbase', { unkname }, DATASET(ServiceOutRecord), onFail(doError(LEFT)),RETRY(0), log('SOAP: ' + unkname),TIMEOUT(1)), record));
+output(SORT(SOAPCALL(d, blacklistedTargetURL,'soapbase', { unkname }, DATASET(ServiceOutRecord), onFail(doError(LEFT)),RETRY(0), log('SOAP: ' + unkname, 'TAIL: ' + unkname),TIMEOUT(1)), record));
 output(SORT(SOAPCALL(targetURL,'soapbase', { string unkname := 'FAIL' }, dataset(ServiceOutRecord),onFail(doError2),RETRY(0), LOG(MIN), HTTPHEADER('Global-Id','12345678900'), HTTPHEADER('Caller-Id','4444')),record));
 output(SORT(SOAPCALL(d, targetURL,'soapbaseNOSUCHQUERY', { unkname }, DATASET(ServiceOutRecord), onFail(doError3(LEFT)),MERGE(25),PARALLEL(1),RETRY(0), LOG(MIN)), record));
 
@@ -91,5 +91,5 @@ FullServiceOutRecord :=
 
 //leak children when linked counted rows are enabled, because not all records are read
 //Use a count so the results are consistent, and nofold to prevent the code generator removing the child dataset...
-output(count(nofold(choosen(SOAPCALL(d, targetURL,'soapbase', { string unkname := d.unkname+'1' }, dataset(FullServiceOutRecord)),1))));
+output(count(nofold(choosen(SOAPCALL(d, targetURL,'soapbase', { string unkname := d.unkname+'1' }, dataset(FullServiceOutRecord), log('start: ' + unkname, 'end: ' + unkname)),1))));
 output(count(nofold(choosen(SOAPCALL(d, targetURL,'soapbase', { string unkname := d.unkname+'1' }, dataset(FullServiceOutRecord), merge(3)),2))));