Repository: dmwm/wmcore
Issue: MS: Transferor failing to resolve dataset with list of runs

**Impact of the bug**
ReqMgr2MS

**Describe the bug**
Sharad informed us via slack that there are a few workflows stuck in `assigned` status. That means workflows are not managing to go through Transferor microservice. The following workflows are failing in every single cycle:
```
pdmvserv_Run2018D-PromptReco-v2_MinimumBias_02Apr2020_200405_131159_8658
pdmvserv_Run2018D-PromptReco-v2_NoBPTX_02Apr2020_200405_134338_5982
pdmvserv_Run2018D-PromptReco-v2_ZeroBias_02Apr2020_200405_131617_328
pdmvserv_Run2018D-v1_Cosmics_UL18_200310_120327_334
pdmvserv_Run2018D-v1_ZeroBias_UL18_kBMTF_200323_083343_5990
```

**How to reproduce it**
Need to find out what is the exact DBS call and whether there are any limitations on the DBS side (like length of the list of runs)

**Expected behavior**
The DBS data discovery should not fail. In case it fails, we should at least know where exactly it failed and with which API/query string.

**Additional context and error message**
Some of the log in ms-transferor
```
2020-04-07 01:48:10,669:INFO:RequestInfo: Going to process 5 requests.
2020-04-07 01:48:10,672:INFO:RequestInfo: Processing request: pdmvserv_Run2018D-v1_Cosmics_UL18_200310_120327_334, with campaigns: set([u'UltraLegacy2018']), and input data as:
[{'campaign': u'UltraLegacy2018',
  'name': u'/Cosmics/Run2018D-v1/RAW',
  'type': 'primary'}]
2020-04-07 01:48:10,672:INFO:RequestInfo: Processing request: pdmvserv_Run2018D-v1_ZeroBias_UL18_kBMTF_200323_083343_5990, with campaigns: set([u'UltraLegacy2018']), and input data as:
[{'campaign': u'UltraLegacy2018',
  'name': u'/ZeroBias/Run2018D-v1/RAW',
  'type': 'primary'}]
2020-04-07 01:48:10,673:INFO:RequestInfo: Processing request: pdmvserv_Run2018D-PromptReco-v2_ZeroBias_02Apr2020_200405_131617_328, with campaigns: set([u'NANOAODRun2DataProd']), and input data as:
[{'campaign': u'NANOAODRun2DataProd',
  'name': u'/ZeroBias/Run2018D-PromptReco-v2/MINIAOD',
  'type': 'primary'}]
2020-04-07 01:48:10,673:INFO:RequestInfo: Processing request: pdmvserv_Run2018D-PromptReco-v2_MinimumBias_02Apr2020_200405_131159_8658, with campaigns: set([u'NANOAODRun2DataProd']), and input data as:
[{'campaign': u'NANOAODRun2DataProd',
  'name': u'/MinimumBias/Run2018D-PromptReco-v2/MINIAOD',
  'type': 'primary'}]
2020-04-07 01:48:10,673:INFO:RequestInfo: Processing request: pdmvserv_Run2018D-PromptReco-v2_NoBPTX_02Apr2020_200405_134338_5982, with campaigns: set([u'NANOAODRun2DataProd']), and input data as:
[{'campaign': u'NANOAODRun2DataProd',
  'name': u'/NoBPTX/Run2018D-PromptReco-v2/MINIAOD',
  'type': 'primary'}]
2020-04-07 01:48:10,673:INFO:RequestInfo: Unified method processing 5 requests
2020-04-07 01:48:10,674:DEBUG:RequestInfo: ### getParentDatasets: 0.0 sec
2020-04-07 01:48:10,674:INFO:RequestInfo: Fetching pileup dataset sizes for 0 datasets against PhEDEx: https://cmsweb.cern.ch/phedex/datasvc/json/prod
2020-04-07 01:48:10,674:INFO:RequestInfo: Fetching pileup dataset location for 0 datasets against PhEDEx: https://cmsweb.cern.ch/phedex/datasvc/json/prod
2020-04-07 01:48:10,674:DEBUG:RequestInfo: ### getSecondaryDatasets: 0.0 sec
2020-04-07 01:48:10,674:INFO:RequestInfo: Fetching block info for 5 datasets against PhEDEx: https://cmsweb.cern.ch/phedex/datasvc/json/prod
2020-04-07 01:48:11,366:INFO:RequestInfo: Fetching blocks matching a list of runs for pdmvserv_Run2018D-v1_Cosmics_UL18_200310_120327_334
2020-04-07 01:48:11,395:ERROR:RequestInfo: Failed to retrieve blocks by dataset and run. Details: No JSON object could be decoded
2020-04-07 01:48:11,395:ERROR:RequestInfo: Workflow: pdmvserv_Run2018D-v1_Cosmics_UL18_200310_120327_334 will be retried in the next cycle
2020-04-07 01:48:11,397:INFO:RequestInfo: Fetching blocks matching a list of runs for pdmvserv_Run2018D-v1_ZeroBias_UL18_kBMTF_200323_083343_5990
2020-04-07 01:48:11,424:ERROR:RequestInfo: Failed to retrieve blocks by dataset and run. Details: No JSON object could be decoded
2020-04-07 01:48:11,424:ERROR:RequestInfo: Workflow: pdmvserv_Run2018D-v1_ZeroBias_UL18_kBMTF_200323_083343_5990 will be retried in the next cycle
2020-04-07 01:48:11,426:INFO:RequestInfo: Fetching blocks matching a list of runs for pdmvserv_Run2018D-PromptReco-v2_ZeroBias_02Apr2020_200405_131617_328
2020-04-07 01:48:11,449:ERROR:RequestInfo: Failed to retrieve blocks by dataset and run. Details: No JSON object could be decoded
2020-04-07 01:48:11,449:ERROR:RequestInfo: Workflow: pdmvserv_Run2018D-PromptReco-v2_ZeroBias_02Apr2020_200405_131617_328 will be retried in the next cycle
2020-04-07 01:48:11,450:INFO:RequestInfo: Fetching blocks matching a list of runs for pdmvserv_Run2018D-PromptReco-v2_MinimumBias_02Apr2020_200405_131159_8658
2020-04-07 01:48:11,498:ERROR:RequestInfo: Failed to retrieve blocks by dataset and run. Details: No JSON object could be decoded
2020-04-07 01:48:11,498:ERROR:RequestInfo: Workflow: pdmvserv_Run2018D-PromptReco-v2_MinimumBias_02Apr2020_200405_131159_8658 will be retried in the next cycle
...
```

Changed files:
src/python/WMCore/MicroService/Unified/RequestInfo.py, src/python/WMCore/MicroService/Unified/Common.py

diff --git a/src/python/WMCore/MicroService/Unified/Common.py b/src/python/WMCore/MicroService/Unified/Common.py
index e62193416..af66ea2cc 100644
--- a/src/python/WMCore/MicroService/Unified/Common.py
+++ b/src/python/WMCore/MicroService/Unified/Common.py
@@ -15,6 +15,8 @@ import math
 import re
 import time
 
+from Utils.IteratorTools import grouper
+
 try:
     from urllib import quote, unquote
 except ImportError:
@@ -62,6 +64,7 @@ def dbsInfo(datasets, dbsUrl):
         return datasetBlocks, datasetSizes, datasetTransfers
 
     urls = ['%s/blocks?detail=True&dataset=%s' % (dbsUrl, d) for d in datasets]
+    logging.info("Executing %d requests against DBS 'blocks' API, with details", len(urls))
     data = multi_getdata(urls, ckey(), cert())
 
     for row in data:
@@ -98,6 +101,7 @@ def getPileupDatasetSizes(datasets, phedexUrl):
         return sizeByDset
 
     urls = ['%s/blockreplicas?dataset=%s' % (phedexUrl, dset) for dset in datasets]
+    logging.info("Executing %d requests against PhEDEx 'blockreplicas' API", len(urls))
     data = multi_getdata(urls, ckey(), cert())
 
     for row in data:
@@ -142,6 +146,7 @@ def getBlockReplicasAndSize(datasets, phedexUrl, group=None):
         return dsetBlockSize
 
     urls = ['%s/blockreplicas?dataset=%s' % (phedexUrl, dset) for dset in datasets]
+    logging.info("Executing %d requests against PhEDEx 'blockreplicas' API", len(urls))
     data = multi_getdata(urls, ckey(), cert())
 
     for row in data:
@@ -194,6 +199,7 @@ def getPileupSubscriptions(datasets, phedexUrl, group=None, percentMin=99):
         url += "percent_min=%s&dataset=%s"
     urls = [url % (percentMin, dset) for dset in datasets]
 
+    logging.info("Executing %d requests against PhEDEx 'subscriptions' API", len(urls))
     data = multi_getdata(urls, ckey(), cert())
 
     for row in data:
@@ -225,7 +231,10 @@ def getBlocksByDsetAndRun(datasetName, runList, dbsUrl):
     if isinstance(runList, set):
         runList = list(runList)
 
-    urls = ['%s/blocks?run_num=%s&dataset=%s' % (dbsUrl, str(runList).replace(" ", ""), datasetName)]
+    urls = []
+    for runSlice in grouper(runList, 50):
+        urls.append('%s/blocks?run_num=%s&dataset=%s' % (dbsUrl, str(runSlice).replace(" ", ""), datasetName))
+    logging.info("Executing %d requests against DBS 'blocks' API, with run_num list", len(urls))
     data = multi_getdata(urls, ckey(), cert())
 
     for row in data:
@@ -254,6 +263,7 @@ def getFileLumisInBlock(blocks, dbsUrl, validFileOnly=1):
     runLumisByBlock = {}
     urls = ['%s/filelumis?validFileOnly=%d&block_name=%s' % (dbsUrl, validFileOnly, quote(b)) for b in blocks]
     # limit it to 10 concurrent calls not to overload DBS
+    logging.info("Executing %d requests against DBS 'filelumis' API, concurrency limited to 10", len(urls))
     data = multi_getdata(urls, ckey(), cert(), num_conn=10)
 
     for row in data:
@@ -280,6 +290,7 @@ def findBlockParents(blocks, dbsUrl):
     """
     parentsByBlock = {}
     urls = ['%s/blockparents?block_name=%s' % (dbsUrl, quote(b)) for b in blocks]
+    logging.info("Executing %d requests against DBS 'blockparents' API", len(urls))
     data = multi_getdata(urls, ckey(), cert())
     for row in data:
         blockName = unquote(row['url'].rsplit('=')[-1])
@@ -314,6 +325,7 @@ def getRunsInBlock(blocks, dbsUrl):
     """
     runsByBlock = {}
     urls = ['%s/runs?block_name=%s' % (dbsUrl, quote(b)) for b in blocks]
+    logging.info("Executing %d requests against DBS 'runs' API", len(urls))
     data = multi_getdata(urls, ckey(), cert())
     for row in data:
         blockName = unquote(row['url'].rsplit('=')[-1])
@@ -330,6 +342,7 @@ def getRunsInBlock(blocks, dbsUrl):
 def phedexInfo(datasets, phedexUrl):
     "Fetch PhEDEx info about nodes for all datasets"
     urls = ['%s/blockreplicasummary?dataset=%s' % (phedexUrl, d) for d in datasets]
+    logging.info("Executing %d requests against PhEDEx 'blockreplicasummary' API", len(urls))
     data = multi_getdata(urls, ckey(), cert())
     blockNodes = {}
     for row in data:
@@ -628,6 +641,7 @@ def findParent(datasets, dbsUrl):
         return parentByDset
 
     urls = ['%s/datasetparents?dataset=%s' % (dbsUrl, d) for d in datasets]
+    logging.info("Executing %d requests against DBS 'datasetparents' API", len(urls))
     data = multi_getdata(urls, ckey(), cert())
 
     for row in data:
diff --git a/src/python/WMCore/MicroService/Unified/RequestInfo.py b/src/python/WMCore/MicroService/Unified/RequestInfo.py
index 5cd4c1521..e0a5b42b6 100644
--- a/src/python/WMCore/MicroService/Unified/RequestInfo.py
+++ b/src/python/WMCore/MicroService/Unified/RequestInfo.py
@@ -429,7 +429,9 @@ class RequestInfo(MSCore):
                 try:
                     blocks = getBlocksByDsetAndRun(dset, runWhite, dbsUrl)
                 except Exception as exc:
-                    self.logger.error("Failed to retrieve blocks by dataset and run. Details: %s", str(exc))
+                    msg = "Failed to retrieve blocks by dataset '%s'and run: %s\\n" % (dset, runWhite)
+                    msg += "Error details: %s" % str(exc)
+                    self.logger.error(msg)
                     raise
                 for block in blocks:
                     if block in blocksDict: