Error: cannot invoke setopt() - perform() is currently running

[amaltaro]

Given that it has been happening much more often in the last months, I think it's time to tackle this issue.
The problem seems to be in the dbs-client, which affects both global and local workqueue (WorkQueueManager).

I haven't looked into how to reproduce it - I believe it's even not reproducible - and it happens in a random way. @vkuznet since you conceived the pycurl module, perhaps you have an idea of what this problem might be?

Here is a traceback [1] extracted from the global workqueue.

[1]

2019-05-25 00:09:38,042:INFO:LogDB:<LogDB(url=https://cmsweb-testbed.cern.ch/couchdb/wmstats_logdb, identifier=global_workqueue, agent=1)>
2019-05-25 00:09:39,080:ERROR:CherryPyPeriodicTask:Periodic Thread ERROR pycurl.error cannot invoke setopt() - perform() is currently running
2019-05-25 00:09:45,129:ERROR:CherryPyPeriodicTask: Traceback (most recent call last):
2019-05-25 00:09:45,157:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/workqueue/1.2.3.pre4/lib/python2.7/site-packages/WMCore/REST/CherryPyPeriodicTask.py", line 91, in run
2019-05-25 00:09:45,157:ERROR:CherryPyPeriodicTask:     self.taskFunc(self.config)
2019-05-25 00:09:45,157:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/workqueue/1.2.3.pre4/lib/python2.7/site-packages/WMCore/GlobalWorkQueue/CherryPyThreads/LocationUpdateTask.py", line 24, in updateDataLocation
2019-05-25 00:09:45,157:ERROR:CherryPyPeriodicTask:     globalQ.updateLocationInfo()
2019-05-25 00:09:45,157:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/workqueue/1.2.3.pre4/lib/python2.7/site-packages/WMCore/WorkQueue/WorkQueue.py", line 720, in updateLocationInfo
2019-05-25 00:09:45,157:ERROR:CherryPyPeriodicTask:     result = self.dataLocationMapper()
2019-05-25 00:09:45,157:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/workqueue/1.2.3.pre4/lib/python2.7/site-packages/WMCore/WorkQueue/DataLocationMapper.py", line 198, in __call__
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:     dataLocations, fullResync = DataLocationMapper.__call__(self, dataItems, fullResync)
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/workqueue/1.2.3.pre4/lib/python2.7/site-packages/WMCore/WorkQueue/DataLocationMapper.py", line 100, in __call__
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:     if isGlobalDBS(dbs):
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/workqueue/1.2.3.pre4/lib/python2.7/site-packages/WMCore/WorkQueue/DataLocationMapper.py", line 38, in isGlobalDBS
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:     dbs.dbs.serverinfo()
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/dbs3-client/3.7.8-comp/lib/python2.7/site-packages/dbs/apis/dbsClient.py", line 1532, in serverinfo
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:     return self.__callServer("serverinfo")
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/dbs3-client/3.7.8-comp/lib/python2.7/site-packages/dbs/apis/dbsClient.py", line 197, in __callServer
2019-05-25 00:09:45,158:ERROR:CherryPyPeriodicTask:     self.http_response = method_func(self.url, method, params, data, request_headers)
2019-05-25 00:09:45,159:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/dbs3-pycurl-client/3.7.8-comp/lib/python2.7/site-packages/RestClient/RestApi.py", line 34, in get
2019-05-25 00:09:45,159:ERROR:CherryPyPeriodicTask:     return http_request(self._curl)
2019-05-25 00:09:45,159:ERROR:CherryPyPeriodicTask:   File "/data/srv/beHG1906b/sw/slc7_amd64_gcc630/cms/dbs3-pycurl-client/3.7.8-comp/lib/python2.7/site-packages/RestClient/RequestHandling/HTTPRequest.py", line 51, in __call__
2019-05-25 00:09:45,159:ERROR:CherryPyPeriodicTask:     curl_object.setopt(key, value)
2019-05-25 00:09:45,159:ERROR:CherryPyPeriodicTask: error: cannot invoke setopt() - perform() is currently running

[vkuznet]

The DBS RestAPI has a single curl object instance. The get method of this class is used in many cases and it race condition happens this single curl object can't set options until it perform some operations, e.g. like get request.

The fix should be to create a dynamic pool of curl objects and use this pool in get/post requests where pool will give a curl object for an operation to perform and when it is done this object will be returned to the pool.

[amaltaro]

Ok, I thought it was on the client side while performing multiple requests under the same curl/connection object.
Given that it's on the DBSServer side, I'll open a GH issue for DBS (and perhaps you can help Yuyi to get that sorted out).

[vkuznet]

Here is a fix: dmwm/DBS#610

[amaltaro]

There seems to be work to be done in the WMCore land, see this debugging/comment:
dmwm/DBS#610 (comment)