Repository: dmwm/wmcore
Issue: DBS3Upload crashes querying wmstatsserver (timed out)

Apparently it hit all the production agents yesterday. 
Issue reported in this JIRA: https://its.cern.ch/jira/browse/CMSCOMPPR-6208

Once the DBS3Upload starts its cycle, it queries wmstatsserver for StepChain parentage, which fails with a `SSLError('The read operation timed out',)`.
We've seen it in the past, for some reason that are very rare cases in which wmstats API just takes too long to respond.

Ideally we should:
* not crash the component
* record this problem in LogDB
* have a sequential counter of this problem, if it happens X cycles in a row, then and only then crash the component (this one might be left to the future though).


Full traceback is below:
```
2019-06-03 11:05:43,997:140199953839872:INFO:DBSUploadPoller:Starting the DBSUpload Polling Cycle
2019-06-03 11:15:45,081:140199953839872:WARNING:Requests:Http request failed, retrying once again..
2019-06-03 11:25:46,180:140199953839872:WARNING:Service:The cachefile /storage/local/data1/cmsdataops/srv/wmagent/v1.2.2.patch2/install/wmagent/DBS3Upload/.wmcore_cache/.wmcore_cache_42935/requests/cmsweb.cern.ch:8443/15744094587142094_G
ET_filtered_requests?RequestType=StepChain&ParentageResolved=False&mask=ChainParentageMap does not exist and the service at https://cmsweb.cern.ch:8443/wmstatsserver/data/filtered_requests?RequestType=StepChain&ParentageResolved=False&ma
sk=ChainParentageMap raised a SSLError('The read operation timed out',) when accessed
2019-06-03 11:25:46,246:140199953839872:ERROR:BaseWorkerThread:Error in worker algorithm (1):
Backtrace:
  <WMComponent.DBS3Buffer.DBSUploadPoller.DBSUploadPoller object at 0x7f82d87789d0> <@========== WMException Start ==========@>
Exception Class: DBSUploadException
Message: Unknown failure while fetching parentage map from WMStats. Error: ('The read operation timed out',)
        ModuleName : WMComponent.DBS3Buffer.DBSUploadPoller
        MethodName : updateDatasetParentageCache
        ClassInstance : None
        FileName : /data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py
        ClassName : None
        LineNumber : 351
        ErrorNr : 0

Traceback: 
  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py", line 340, in updateDatasetParentageCache
    self.datasetParentageCache = self.wmstatsServerSvc.getChildParentDatasetMap()

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/WMStatsServer/WMStatsServer.py", line 105, in getChildParentDatasetMap
    results = self.getFilteredActiveData(filter, mask)

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/WMStatsServer/WMStatsServer.py", line 92, in getFilteredActiveData
    return self._getResult(callname, verb="GET")

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/WMStatsServer/WMStatsServer.py", line 43, in _getResult
    verb=verb, contentType=contentType)

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/Service.py", line 205, in refreshCache
    self.getData(cachefile, url, inputdata, incoming_headers, encoder, decoder, verb, contentType)

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/Service.py", line 319, in getData
    raise he

<@---------- WMException End ----------@>  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/WorkerThreads/BaseWorkerThread.py", line 182, in __call__
    tSpent, results, _ = algorithmWithDBExceptionHandler(parameters)
  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Database/DBExceptionHandler.py", line 36, in wrapper
    return f(*args, **kwargs)
  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/Utils/Timers.py", line 24, in wrapper
    res = func(*arg, **kw)
  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py", line 311, in algorithm
    if self.updateDatasetParentageCache() is False:
  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py", line 351, in updateDatasetParentageCache
    raise DBSUploadException(msg)

2019-06-03 11:25:46,246:140199953839872:INFO:Harness:>>>Terminating worker threads
2019-06-03 11:25:46,246:140199953839872:ERROR:BaseWorkerThread:Error in event loop (2): <WMComponent.DBS3Buffer.DBSUploadPoller.DBSUploadPoller object at 0x7f82d87789d0> <@========== WMException Start ==========@>
Exception Class: DBSUploadException
Message: Unknown failure while fetching parentage map from WMStats. Error: ('The read operation timed out',)
        ModuleName : WMComponent.DBS3Buffer.DBSUploadPoller
        MethodName : updateDatasetParentageCache
        ClassInstance : None
        FileName : /data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py
        ClassName : None
        LineNumber : 351
        ErrorNr : 0

Traceback: 
  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py", line 340, in updateDatasetParentageCache
    self.datasetParentageCache = self.wmstatsServerSvc.getChildParentDatasetMap()

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/WMStatsServer/WMStatsServer.py", line 105, in getChildParentDatasetMap
    results = self.getFilteredActiveData(filter, mask)

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/WMStatsServer/WMStatsServer.py", line 92, in getFilteredActiveData
    return self._getResult(callname, verb="GET")

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/WMStatsServer/WMStatsServer.py", line 43, in _getResult
    verb=verb, contentType=contentType)

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/Service.py", line 205, in refreshCache
    self.getData(cachefile, url, inputdata, incoming_headers, encoder, decoder, verb, contentType)

  File "/data/srv/wmagent/v1.2.2.patch2/sw/slc7_amd64_gcc630/cms/wmagent/1.2.2.patch2/lib/python2.7/site-packages/WMCore/Services/Service.py", line 319, in getData
    raise he

<@---------- WMException End ----------@>
```

Changed files:
src/python/WMComponent/DBS3Buffer/DBSUploadPoller.py

diff --git a/src/python/WMComponent/DBS3Buffer/DBSUploadPoller.py b/src/python/WMComponent/DBS3Buffer/DBSUploadPoller.py
index 376ba44c7..c0f7d1e60 100644
--- a/src/python/WMComponent/DBS3Buffer/DBSUploadPoller.py
+++ b/src/python/WMComponent/DBS3Buffer/DBSUploadPoller.py
@@ -331,6 +331,8 @@ class DBSUploadPoller(BaseWorkerThread):
         Return True to indicate it successfully fetched the parentage
         map. If there was an exception, return False
         """
+        myThread = threading.currentThread()
+
         success = True
         if not self.wmstatsServerSvc:
             self.datasetParentageCache = {}
@@ -340,18 +342,22 @@ class DBSUploadPoller(BaseWorkerThread):
             self.datasetParentageCache = self.wmstatsServerSvc.getChildParentDatasetMap()
         except Exception as ex:
             reason = getattr(ex, 'reason', '')
-            msg = 'Failed to fetch parentage map from WMStats, skipping this cycle.'
+            msg = 'Failed to fetch parentage map from WMStats, skipping this cycle. '
             if 'Service Unavailable' in reason or 'Proxy Error' in reason or\\
                             'Error reading from remote server' in reason:
                 msg += 'Error: %s' % reason
             elif 'Connection refused' in str(ex):
                 msg += 'Error: %s' % str(ex)
+            elif 'The read operation timed out' in str(ex):
+                msg += 'Error: %s' % str(ex)
             else:
                 msg = "Unknown failure while fetching parentage map from WMStats. Error: %s" % str(ex)
                 raise DBSUploadException(msg)
-
             logging.warning(msg)
+            myThread.logdbClient.post("DBS3Upload_parentMap", msg, "warning")
             success = False
+        else:
+            myThread.logdbClient.delete("DBS3Upload_parentMap", "warning", this_thread=True)
 
         return success