Repository: dmwm/wmcore
Issue: CouchDBCleanup ReqMgr2 thread deleting documents not ready yet for deletion

**Impact of the bug**
ReqMgr2

**Describe the bug**
As reported in the "cms-pdmv-pnr-ops" slack organization, there are two workflows sitting in `staging` status which no longer have their transfer document in CouchDB `reqmgr_auxiliary` db [1], which makes their evaluation to fail in MSMonitor, thus remaining in the `staging` status forever.

From MSTransferor log, those workflows have been properly handled by the new microservice and the transfer document created [2]. So I had to look at the component cleaning up those transfer documents from CouchDB, which is the CouchDBCleanup ReqMgr2 cherrypy thread, and here is where that transfer document got deleted [3].

The date that transfer document got deleted (and apparently hundred of other transfer documents) match the CMSWEB production redeployment in the last Wednesday. That means, there is likely a very specific scenario (couchdb unavailable? reqmgr2 unavailable? etc) which allows transfer documents to get deleted.

**How to reproduce it**
No clue.

**Expected behavior**
Transfer documents should never be deleted for workflows sitting in `staging` status. Here is how it was implemented and the list of statuses that must be respected [4].
In addition to debuging, tracking and fixing that bug / race condition, we should re-create those transfer documents such that those workflows can proceed.

**Additional context and error message**
[1] MSMonitor log (ms-monitor-20210416-ms-monitor-77649d6db5-dj44p.log):
```
2021-04-16 16:01:18,532:WARNING:GenericDataCache: Passive failure while looking data up in the memory cache. Error: url=https://cmsweb.cern.ch:8443/reqmgr2/data/transferinfo/pdmvserv_task_EXO-RunIIFall17NanoAODv7-05572__v1_T_210119_113111_258, code=404, reason=Not Found, headers={'X-Error-Http': '404', 'Content-Encoding': 'gzip', 'Transfer-Encoding': 'chunked', 'X-Rest-Time': '24252.892 us', 'Vary': 'Accept-Encoding', 'Server': 'openresty/1.15.8.2', 'X-Error-Detail': 'No such instance', 'X-Rest-Status': '206', 'Date': 'Fri, 16 Apr 2021 14:01:18 GMT', 'Content-Type': 'text/html;charset=utf-8', 'CMS-Server-Time': 'D=81662 t=1618581678448489', 'X-Error-Id': '71ea6e74fe5822cd1bc8a6e026c4cc5c'}
2021-04-16 16:03:37,856:WARNING:GenericDataCache: Passive failure while looking data up in the memory cache. Error: url=https://cmsweb.cern.ch:8443/reqmgr2/data/transferinfo/pdmvserv_task_EXO-RunIIFall17NanoAODv7-05570__v1_T_210119_113053_5846, code=404, reason=Not Found, headers={'X-Error-Http': '404', 'Content-Encoding': 'gzip', 'Transfer-Encoding': 'chunked', 'X-Rest-Time': '25206.089 us', 'Vary': 'Accept-Encoding', 'Server': 'openresty/1.15.8.2', 'X-Error-Detail': 'No such instance', 'X-Rest-Status': '206', 'Date': 'Fri, 16 Apr 2021 14:03:37 GMT', 'Content-Type': 'text/html;charset=utf-8', 'CMS-Server-Time': 'D=35915 t=1618581817818197', 'X-Error-Id': '6628bec01f93cbd7f047552a3de0ae67'}
```

[2] MSTransferor log from Jan 20th:
```
2021-01-20 14:28:28,217:INFO:MSTransferor: Transfer requests successful for pdmvserv_task_EXO-RunIIFall17NanoAODv7-05570__v1_T_210119_113053_5846. Summary: [{'campaignName': u'RunIIFall17NanoAODv7',
  'completion': [0.0],
  'dataType': 'primary',
  'dataset': u'/DarkHiggs_MonoHs_HsToWWTojjlnu_mhs_300_mx_150_mZp_800_TuneCP5_13TeV-madgraph-pythia8/RunIIFall17MiniAODv2-PU2017_12Apr2018_94X_mc2017_realistic_v14-v2/MINIAODSIM',
  'transferIDs': [u'2bd7eebd63bb44c58d1590ee48514675',
                  u'b3762b44fbcb4a1b84829a1c8a96ffc9',
                  u'd9b9250857bf4a77ad628e31091bff14',
                  u'0b4e3a481fd54445843f5487449f2c40',
                  u'049ebcfe8f384e6bb6e1a57abf6ce49e',
                  u'e673f707e45e42d69b82d29889d9bebd',
                  u'7f16afb4188f426882019927709c5637',
                  u'd78cc62b12d243b4aba2dc59567a8c51',
                  u'6a6edd7501534ec2960bd183d7b6cce6',
                  u'fb3819f1450c41709e75ea2a3565c3a1',
                  u'ba3fef103a6041cfab7b6fcdf22926c8',
                  u'c06913d000dd4a8381d3a743c055246d']}]
2021-01-20 14:28:28,308:INFO:ReqMgrAux: Update in-place: False for transfer doc: pdmvserv_task_EXO-RunIIFall17NanoAODv7-05570__v1_T_210119_113053_5846 was successful.
2021-01-20 14:28:28,309:INFO:MSTransferor: Transfer document successfully created in CouchDB for: pdmvserv_task_EXO-RunIIFall17NanoAODv7-05570__v1_T_210119_113053_5846
2021-01-20 14:28:28,309:INFO:MSCore: MSTransferor updating pdmvserv_task_EXO-RunIIFall17NanoAODv7-05570__v1_T_210119_113053_5846 status to: staging
```

[3] CouchDB Cleanup log (couchCleanup-reqmgr2-tasks-6b69547cb4-szwjq-20210407.log):
```
couchCleanup-reqmgr2-tasks-6b69547cb4-szwjq-20210407.log:2021-04-07 09:37:02,754:INFO:CouchDBCleanup:Deleting transfer document: pdmvserv_task_EXO-RunIIFall17NanoAODv7-05570__v1_T_210119_113053_5846
```

[4] https://github.com/dmwm/WMCore/pull/9574

Changed files:
src/python/WMCore/ReqMgr/CherryPyThreads/CouchDBCleanup.py

diff --git a/src/python/WMCore/ReqMgr/CherryPyThreads/CouchDBCleanup.py b/src/python/WMCore/ReqMgr/CherryPyThreads/CouchDBCleanup.py
index 6dad693a7..49dba4eae 100644
--- a/src/python/WMCore/ReqMgr/CherryPyThreads/CouchDBCleanup.py
+++ b/src/python/WMCore/ReqMgr/CherryPyThreads/CouchDBCleanup.py
@@ -17,6 +17,9 @@ class CouchDBCleanup(CherryPyPeriodicTask):
 
         super(CouchDBCleanup, self).__init__(config)
         self.reqDB = RequestDBReader(config.reqmgrdb_url)
+        # create another object to always retrieve up-to-date views (no stale)
+        self.reqDBNoStale = RequestDBReader(config.reqmgrdb_url)
+        self.reqDBNoStale._setNoStale()
         self.reqmgrAux = ReqMgrAux(config.reqmgr2_url, logger=self.logger)
         # statuses that we want to keep the transfer documents
         self.transferStatuses = ["assigned", "staging", "staged", "acquired",
@@ -37,29 +40,34 @@ class CouchDBCleanup(CherryPyPeriodicTask):
         Cleanup TRANSFER documents from the reqmgr_auxiliary CouchDB.
         The list of status can be expanded in the future
         """
-        self.logger.info("Fetching TRANSFER documents from CouchDB...")
+        self.logger.info("Fetching all the TRANSFER documents from CouchDB...")
 
-        transferDocs = self.reqmgrAux.getTransferInfo("ALL_DOCS")
+        transferDocs = []
+        for row in self.reqmgrAux.getTransferInfo("ALL_DOCS"):
+            transferDocs.append(row['workflowName'])
         if not transferDocs:
             self.logger.info("  there are no transfer documents in the database.")
             return
-        auxDocs = []
-        for row in transferDocs:
-            auxDocs.append(row['workflowName'])
+        self.logger.info("%d transfer documents retrieved from the database.", len(transferDocs))
 
-        results = self.reqDB._getCouchView("bystatus", {}, self.transferStatuses)
+        self.logger.info("Fetching workflows from CouchDB for statuses: %s", self.transferStatuses)
+        results = self.reqDBNoStale._getCouchView("bystatus", {}, self.transferStatuses)
+        if not results["rows"]:
+            self.logger.info("  there are no workflows matching those statuses.")
+            return
         activeRequests = []
         for row in results["rows"]:
             activeRequests.append(row["id"])
+        self.logger.info("%d workflows retrieved from the database.", len(activeRequests))
 
-        # now find transfer docs that are not active in the system
-        transferDocs = []
-        for transferDoc in auxDocs:
-            if transferDoc not in activeRequests:
-                transferDocs.append(transferDoc)
-        self.logger.info("Found %d transfer documents to delete", len(transferDocs))
-
+        # now find transfer documents (workflows) that are not active in the system
+        docsToDelete = []
         for wflowName in transferDocs:
+            if wflowName not in activeRequests:
+                docsToDelete.append(wflowName)
+        self.logger.info("Found %d transfer documents to delete", len(docsToDelete))
+
+        for wflowName in docsToDelete:
             self.logger.info("Deleting transfer document: %s", wflowName)
             try:
                 self.reqmgrAux.deleteConfigDoc("transferinfo", wflowName)
@@ -95,8 +103,8 @@ class CouchDBCleanup(CherryPyPeriodicTask):
                     self.logger.warning("  request '%s' already deleted", req)
                 else:
                     total += len(deleted)
-                    self.logger.info("request %s deleted", req)
+                    self.logger.info("ACDC collection %s deleted", req)
             except Exception as ex:
                 self.logger.error("Failed to delete request: %s, will try again later. Error: %s", req, str(ex))
-        self.logger.info("total %s requests deleted", total)
+        self.logger.info("Total %s ACDC collections deleted", total)
         return