Merge pull request #12611 from wangkx/h20914

HPCC-20914 Log why extra log line is added to ESP log

Reviewed-By: Anthony Fishbeck <anthony.fishbeck@lexisnexis.com>
Reviewed-By: Richard Chapman <rchapman@hpccsystems.com>

esp/bindings/http/platform/httpservice.cpp

@@ -64,7 +64,7 @@ CEspHttpServer::~CEspHttpServer()
             //has been logged and it should not be logged here.
             ctx->setProcessingTime();
             if ((ctx->queryHasException() || (ctx->queryProcessingTime() > getSlowProcessingTime())) &&
-                !getEspLogRequests() && (getEspLogLevel() <= LogNormal))
+                (getEspLogRequests() == LogRequestsWithIssuesOnly))
             {
                 StringBuffer logStr;
                 logStr.appendf("%s %s", m_request->queryMethod(), m_request->queryPath());
@@ -73,7 +73,12 @@ CEspHttpServer::~CEspHttpServer()
                 if (paramStr && *paramStr)
                     logStr.appendf("?%s", paramStr);
 
-                DBGLOG("Request[%s]", logStr.str());
+                if (ctx->queryHasException())
+                    DBGLOG("Request with exception. Request[%s]", logStr.str());
+                else
+                    DBGLOG("Request with long processing time: %u seconds. Request[%s]",
+                        (unsigned) (ctx->queryProcessingTime() * 0.001), logStr.str());
+
                 if (m_request->isSoapMessage())
                 {
                     StringBuffer requestStr;

esp/bindings/http/platform/httptransport.cpp

@@ -630,7 +630,7 @@ int CHttpMessage::receive(bool alwaysReadContent, IMultiException *me)
             DBGLOG("length of content read = %d", m_content.length());
     }
 
-    if (getEspLogRequests() || getEspLogLevel()>LogNormal)
+    if (getEspLogRequests() == LogRequestsAlways)
         logMessage(LOGCONTENT, "HTTP content received:\n");
     return 0;
 }
@@ -802,7 +802,7 @@ int CHttpMessage::send()
     int retcode = 0;
 
     // If m_content is empty but m_content_stream is set, the stream will not be logged here.
-    if (getEspLogResponses() || getEspLogLevel(queryContext())>LogNormal)
+    if (getEspLogResponses())
     {
         logMessage(headers.str(), "Sending out HTTP headers:\n", "Authorization:[~\r\n]*", "Authorization: (hidden)");
         if(m_content_length > 0 && m_content.length() > 0)
@@ -1897,7 +1897,7 @@ int CHttpRequest::processHeaders(IMultiException *me)
         lenread = m_bufferedsocket->readline(oneline, MAX_HTTP_HEADER_LEN + 1, me);
     }
 
-    if (getEspLogRequests() || getEspLogLevel()>LogNormal)
+    if (getEspLogRequests() == LogRequestsAlways)
         logMessage(LOGHEADERS, "HTTP request headers received:\n");
 
     if(m_content_length > 0 && m_MaxRequestEntityLength > 0 && m_content_length > m_MaxRequestEntityLength && (!isUpload(false)))
@@ -2447,7 +2447,7 @@ int CHttpResponse::receive(bool alwaysReadContent, IMultiException *me)
             DBGLOG("length of content read = %d", m_content.length());
     }
     
-    if ((getEspLogRequests() || getEspLogLevel()>LogNormal))
+    if (getEspLogRequests() == LogRequestsAlways)
         logMessage(LOGCONTENT, "HTTP response content received:\n");
     return 0;
 

esp/platform/espcfg.cpp

@@ -261,7 +261,7 @@ CEspConfig::CEspConfig(IProperties* inputs, IPropertyTree* envpt, IPropertyTree*
     // load options
     const char* level = m_cfg->queryProp("@logLevel");
     m_options.logLevel = level ? atoi(level) : LogMin;
-    m_options.logReq = m_cfg->getPropBool("@logRequests", true);
+    m_options.logReq = readLogRequest(m_cfg->queryProp("@logRequests"));
     m_options.logResp = m_cfg->getPropBool("@logResponses", false);
     m_options.txSummaryLevel = m_cfg->getPropInt("@txSummaryLevel", LogMin);
     m_options.txSummaryResourceReq = m_cfg->getPropBool("@txSummaryResourceReq", false);
@@ -518,7 +518,6 @@ CEspConfig::CEspConfig(IProperties* inputs, IPropertyTree* envpt, IPropertyTree*
     }
 }
 
-
 void CEspConfig::sendAlert(int severity, char const * descr, char const * subject) const
 {
 }

esp/platform/espcfg.ipp

@@ -90,14 +90,14 @@ struct builtin
 struct esp_option
 {   
     LogLevel logLevel;
-    bool logReq;
+    LogRequest logReq;
     bool logResp;
     LogLevel txSummaryLevel;
     bool txSummaryResourceReq;
     StringAttr frameTitle;
     unsigned slowProcessingTime; //default 30 seconds
 
-    esp_option() : logReq(false), logResp(false), logLevel(LogMin), txSummaryLevel(LogMin), txSummaryResourceReq(false), slowProcessingTime(30000)
+    esp_option() : logReq(LogRequestsNever), logResp(false), logLevel(LogMin), txSummaryLevel(LogMin), txSummaryResourceReq(false), slowProcessingTime(30000)
     { }
 };
 

esp/platform/espcontext.cpp

@@ -820,6 +820,22 @@ static IEspContainer*& getContainer()
     return gContainer;
 }
 
+LogRequest readLogRequest(char const* req)
+{
+    if (isEmptyString(req))
+        return LogRequestsNever;
+
+    if (strieq(req, "all"))
+        return LogRequestsAlways;
+    if (strieq(req, "never"))
+        return LogRequestsNever;
+    if (strieq(req, "only-ones-with-issues"))
+        return LogRequestsWithIssuesOnly;
+    if (strToBool(req))
+        return LogRequestsAlways;
+    return LogRequestsNever;
+}
+
 LogLevel getEspLogLevel() { return getEspLogLevel(NULL); }
 
 LogLevel getEspLogLevel(IEspContext* ctx)
@@ -858,11 +874,11 @@ bool getTxSummaryResourceReq()
     return false;
 }
 
-bool getEspLogRequests()
+LogRequest getEspLogRequests()
 {
     if (getContainer())
         return getContainer()->getLogRequests();
-    return false;
+    return LogRequestsNever;
 }
 
 bool getEspLogResponses()

esp/platform/espcontext.hpp

@@ -120,9 +120,10 @@ esp_http_decl void getEspUrlParams(IEspContext& ctx, StringBuffer& params, const
 esp_http_decl void addEspNativeArray(StringBuffer& schema, const char* xsdType, const char* arrayType);
 esp_http_decl void checkRequest(IEspContext& ctx);
 
+esp_http_decl LogRequest readLogRequest(char const* req);
 esp_http_decl LogLevel getEspLogLevel(IEspContext* );
 esp_http_decl LogLevel getEspLogLevel();
-esp_http_decl bool getEspLogRequests();
+esp_http_decl LogRequest getEspLogRequests();
 esp_http_decl bool getEspLogResponses();
 esp_http_decl LogLevel getTxSummaryLevel();
 esp_http_decl bool getTxSummaryResourceReq();

esp/platform/espp.hpp

@@ -54,7 +54,7 @@ private:
     bool m_exiting;
     bool m_useDali;
     LogLevel m_logLevel;
-    bool m_logReq;
+    LogRequest m_logReq;
     bool m_logResp;
     LogLevel txSummaryLevel;
     bool txSummaryResourceReq;
@@ -151,13 +151,13 @@ public:
     }
 
     void setLogLevel(LogLevel level) { m_logLevel = level; }
-    void setLogRequests(bool logReq) { m_logReq = logReq; }
+    void setLogRequests(LogRequest logReq) { m_logReq = logReq; }
     void setLogResponses(bool logResp) { m_logResp = logResp; }
     void setTxSummaryLevel(LogLevel level) { txSummaryLevel = level; }
     void setTxSummaryResourceReq(bool logReq) { txSummaryResourceReq = logReq; }
 
     LogLevel getLogLevel() { return m_logLevel; }
-    bool getLogRequests() { return m_logReq; }
+    LogRequest getLogRequests() { return m_logReq; }
     bool getLogResponses() { return m_logResp; }
     LogLevel getTxSummaryLevel() { return txSummaryLevel; }
     bool getTxSummaryResourceReq() { return txSummaryResourceReq; }

esp/scm/esp.ecm

@@ -74,6 +74,13 @@ typedef enum AuthError_
     EspAuthErrorNotAuthorized
 } AuthError;
 
+typedef enum LogRequest_
+{
+    LogRequestsNever,
+    LogRequestsWithIssuesOnly,
+    LogRequestsAlways
+} LogRequest;
+
 #define ESPCTX_NO_NAMESPACES    0x00000001
 #define ESPCTX_WSDL             0x00000010
 #define ESPCTX_WSDL_EXT         0x00000100
@@ -220,8 +227,8 @@ interface IEspContainer : extends IInterface
     virtual void exitESP() = 0;
     virtual void setLogLevel(LogLevel level) = 0;
     virtual LogLevel getLogLevel() = 0;
-    virtual bool getLogRequests() = 0;
-    virtual void setLogRequests(bool logReq) = 0;
+    virtual LogRequest getLogRequests() = 0;
+    virtual void setLogRequests(LogRequest logReq) = 0;
     virtual bool getLogResponses() = 0;
     virtual void setLogResponses(bool logResp) = 0;
     virtual void setTxSummaryLevel(LogLevel level) = 0;

esp/scm/ws_espcontrol.ecm

@@ -20,7 +20,7 @@ EspInclude(common);
 ESPrequest [nil_remove] SetLoggingRequest
 {
     int LoggingLevel;
-    bool LogRequests;
+    string LogRequests;
     bool LogResponses;
 };
 

esp/services/espcontrol/ws_espcontrolservice.cpp

@@ -190,8 +190,7 @@ bool CWSESPControlEx::onSetLogging(IEspContext& context, IEspSetLoggingRequest&
 
         if (!req.getLoggingLevel_isNull())
             m_container->setLogLevel(req.getLoggingLevel());
-        if (!req.getLogRequests_isNull())
-            m_container->setLogRequests(req.getLogRequests());
+        m_container->setLogRequests(readLogRequest(req.getLogRequests()));
         if (!req.getLogResponses_isNull())
             m_container->setLogResponses(req.getLogResponses());
         resp.setStatus(0);

initfiles/componentfiles/configschema/xsd/esp.xsd

@@ -349,8 +349,9 @@
                 <xs:attribute name="componentfilesDir" type="xs:string"
                               hpcc:presetValue="${COMPONENTFILES_PATH}" hpcc:displayName="Component Files Dir"
                               hpcc:tooltip="Sets the componentfiles directory"/>
-                <xs:attribute name="logRequests" type="xs:boolean" hpcc:presetValue="true"
-                              hpcc:displayName="Log Requests"/>
+                <xs:attribute name="logRequests" type="xs:string" hpcc:presetValue="never"
+                              hpcc:displayName="Log Requests"
+                              hpcc:tooltip="never|only-ones-with-issues|all"/>
                 <xs:attribute name="logResponses" type="xs:boolean" hpcc:presetValue="false"
                               hpcc:displayName="Log Responses"/>
                 <xs:attribute name="txSummaryLevel" type="xs:nonNegativeInteger" hpcc:presetValue="1"

initfiles/componentfiles/configxml/esp.xsd.in

@@ -983,7 +983,13 @@
                     </xs:appinfo>
                 </xs:annotation>
             </xs:attribute>
-            <xs:attribute name="logRequests" type="xs:boolean" use="optional" default="true"/>
+            <xs:attribute name="logRequests" type="xs:string" use="optional" default="never">
+                <xs:annotation>
+                    <xs:appinfo>
+                        <tooltip>never|only-ones-with-issues|all</tooltip>
+                    </xs:appinfo>
+                </xs:annotation>
+            </xs:attribute>
             <xs:attribute name="logResponses" type="xs:boolean" use="optional" default="false"/>
             <xs:attribute name="txSummaryLevel" type="xs:nonNegativeInteger" use="optional" default="1">
                 <xs:annotation>

initfiles/etc/DIR_NAME/environment.xml.in

@@ -258,7 +258,7 @@
               formOptionsAccess="false"
               httpConfigAccess="true"
               logLevel="1"
-              logRequests="false"
+              logRequests="never"
               logResponses="false"
               txSummaryLevel="1"
               txSummaryResourceReq="false"

testing/regress/environment.xml.in

@@ -255,7 +255,7 @@
               formOptionsAccess="false"
               httpConfigAccess="true"
               logLevel="1"
-              logRequests="false"
+              logRequests="never"
               logResponses="false"
               txSummaryLevel="1"
               txSummaryResourceReq="false"