Repository: dmwm/wmcore
Issue: MSMonitor crashing to parse dataset level subscription requests

**Impact of the bug**
ReqMgr2MS MSMonitor

**Describe the bug**
It looks like MSMonitor is failing to parse the data transfer output for a dataset subscription. Traceback will be provided below.

**How to reproduce it**
Need to check

**Expected behavior**
Failures need to be contained in a try/except block to avoid crashing the whole cycle.
In addition to that, we of course need to get this issue fixed.

**Additional context and error message**
Traceback:
```
2020-04-25 02:24:53,374:DEBUG:MSMonitor: Checking transfers for: pdmvserv_task_HIG-RunIIAutumn18NanoAODv7-00134__v1_T_200424_044920_3414
2020-04-25 02:24:53,374:DEBUG:MSMonitor: Checking transfers for: nwickram_RVCMSSW_11_1_0_pre6Pyquen_DiJet_pt80to120_2760GeV_PU__200422_193039_9660
2020-04-25 02:24:53,374:DEBUG:Service: Data is from the Service cache
2020-04-25 02:24:53,374:DEBUG:MSMonitor: Subscription result for dataset: /RelValHydjetQ_B12_5020GeV_2018/CMSSW_11_1_0_pre6-110X_upgrade2018_realistic_v9-v1/GEN-SIM and request ID: 2189272 was: {u'phedex': {u'request_date': u'2020-04-25 00:04:14 UTC', u'request_timestamp': 1587773054.37094, u'call_time': 0.01022, u'dataset': [{u'files': 5, u'name': u'/RelValHydjetQ_B12_5020GeV_2018/CMSSW_11_1_0_pre6-110X_upgrade2018_realistic_v9-v1/GEN-SIM', u'bytes': 10420036381, u'is_open': u'y', u'id': u'1519465', u'subscription': [{u'node': u'T1_FR_CCIN2P3_Disk', u'percent_files': 100, u'custodial': u'n', u'suspend_until': None, u'node_files': 5, u'level': u'DATASET', u'time_create': 1587694041.41837, u'move': u'n', u'request': 2189272, u'percent_bytes': 100, u'group': u'DataOps', u'priority': u'low', u'time_update': 1587694041.41837, u'node_id': 1861, u'suspended': u'n', u'time_start': None, u'node_bytes': 10420036381}]}], u'instance': u'prod', u'request_call': u'subscriptions', u'request_url': u'http://cmsweb.cern.ch:7001/phedex/datasvc/json/prod/subscriptions', u'request_version': u'2.5.0pre3-comp'}}
2020-04-25 02:24:53,375:ERROR:MSMonitor: ('Unknown exception processing the transfer records. Error: %s', "'block'")
Traceback (most recent call last):
  File "/data/srv/beHG2004f/sw/slc7_amd64_gcc630/cms/reqmgr2ms/0.2.2.pre5/lib/python2.7/site-packages/WMCore/MicroService/Unified/MSMonitor.py", line 106, in execute
    self.getTransferInfo(transferRecords)
  File "/data/srv/beHG2004f/sw/slc7_amd64_gcc630/cms/reqmgr2ms/0.2.2.pre5/lib/python2.7/site-packages/WMCore/MicroService/Unified/MSMonitor.py", line 144, in getTransferInfo
    completion = self._getTransferstatus(rec['dataset'], rec['transferIDs'])
  File "/data/srv/beHG2004f/sw/slc7_amd64_gcc630/cms/reqmgr2ms/0.2.2.pre5/lib/python2.7/site-packages/WMCore/MicroService/Unified/MSMonitor.py", line 186, in _getTransferstatus
    for blockRow in dsetRow['block']:
KeyError: 'block'
2020-04-25 02:24:53,388:INFO:MSManager: Total monitor execution time: 21 secs
```


Changed files:
src/python/WMCore/MicroService/Unified/MSMonitor.py

diff --git a/src/python/WMCore/MicroService/Unified/MSMonitor.py b/src/python/WMCore/MicroService/Unified/MSMonitor.py
index 2d6094257..31d51527c 100644
--- a/src/python/WMCore/MicroService/Unified/MSMonitor.py
+++ b/src/python/WMCore/MicroService/Unified/MSMonitor.py
@@ -124,7 +124,7 @@ class MSMonitor(MSCore):
             msg += "%d failed to get their transfer documents updated in CouchDB." % len(failedDocs)
             self.logger.info(msg)
         except Exception as ex:
-            msg = "Unknown exception processing the transfer records. Error: %s", str(ex)
+            msg = "Unknown exception processing the transfer records. Error: %s" % str(ex)
             self.logger.exception(msg)
             self.updateReportDict(summary, "error", msg)
         return summary
@@ -139,12 +139,15 @@ class MSMonitor(MSCore):
         tstamp = int(time.time())
         for doc in transferRecords:
             self.logger.debug("Checking transfers for: %s", doc['workflowName'])
-            for rec in doc.get('transfers', []):
-                # obtain new transfer ids and completion for given dataset
-                completion = self._getTransferstatus(rec['dataset'], rec['transferIDs'])
-                # Per Alan request, we'll update only completion and not tids
-                rec['completion'].append(round(completion, 2))
-            doc['lastUpdate'] = tstamp
+            try:
+                for rec in doc.get('transfers', []):
+                    # obtain new transfer ids and completion for given dataset
+                    completion = self._getTransferstatus(rec['dataset'], rec['transferIDs'])
+                    rec['completion'].append(round(completion, 2))
+                doc['lastUpdate'] = tstamp
+            except Exception as exc:
+                msg = "Unknown exception checking workflow %s. Error: %s"
+                self.logger.exception(msg, doc['workflowName'], str(exc))
 
     def _getTransferstatus(self, dataset, requestList):
         """
@@ -180,15 +183,25 @@ class MSMonitor(MSCore):
             else:
                 self.logger.debug("Subscription result for dataset: %s and request ID: %s was: %s",
                                   dataset, reqId, data)
-            # the response structure is nested as hell!
+            # very much nested, especially for a block level subscription
             for dsetRow in data['phedex']['dataset']:
                 # TODO: check what happens when we subscribe both the primary and parent in the same request
-                for blockRow in dsetRow['block']:
+                for blockRow in dsetRow.get('block', []):
                     for subs in blockRow['subscription']:
                         if subs['percent_files'] is None:
                             completion.append(0)
                         else:
                             completion.append(int(subs['percent_files']))
+            # check if it's a level subscription
+            for dsetRow in data['phedex']['dataset']:
+                if 'block' in dsetRow:
+                    # already handled by the block above
+                    break
+                for subs in dsetRow['subscription']:
+                    if subs['percent_files'] is None:
+                        completion.append(0)
+                    else:
+                        completion.append(int(subs['percent_files']))
         if not completion:
             return 0
         return sum(completion) / len(completion)