Repository: dmwm/wmcore
Issue: DB wrapper function not handling exceptions properly

There were oracle instabilities this morning and I see a few agents with components terminated. If I correctly understood the wrapper function, when there is a passable/temporary database exception it does not return data in the format that the timer wrapper (yes, a wrapper for the wrapped function :)) expects, which then fails to assign those values to tSpent, results.

Here is the long traceback from vocms0251 DBS3Upload:
```
2018-08-24 06:38:51,284:139873667856128:INFO:DBSUploadPoller:Loaded 0 blocks.
2018-08-24 06:55:27,679:139873667856128:ERROR:pool:Exception closing connection <cx_Oracle.Connection to CMS_WMBS_PROD11@CMSR>
Traceback (most recent call last):
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/pool.py", line 244, in _close_connection
    self._dialect.do_close(connection)
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 411, in do_close
    dbapi_connection.close()
OperationalError: ORA-03114: not connected to ORACLE

2018-08-24 06:55:27,684:139873667856128:ERROR:DBSUploadPoller:Unhandled exception while loading uploadable files for DatasetPath.
(OperationalError) ORA-03113: end-of-file on communication channel
Process ID: 79131
Session ID: 3426 Serial number: 53581
 'SELECT cst.type AS cktype, fcs.cksum AS cksum, fcs.fileid AS id FROM\\n                           dbsbuffer_file_checksums fcs INNER JOIN\\n                           dbsbuffer_checksum_type cst ON fcs.typeid = cst.id\\n                 
          WHERE fcs.fileid = :fileid' {'fileid': 110481}
2018-08-24 06:55:29,682:139873667856128:ERROR:DBExceptionHandler:<@========== WMException Start ==========@>
Exception Class: DBSUploadException
Message: Unhandled exception while loading uploadable files for DatasetPath.
(OperationalError) ORA-03113: end-of-file on communication channel
Process ID: 79131
Session ID: 3426 Serial number: 53581
 'SELECT cst.type AS cktype, fcs.cksum AS cksum, fcs.fileid AS id FROM\\n                           dbsbuffer_file_checksums fcs INNER JOIN\\n                           dbsbuffer_checksum_type cst ON fcs.typeid = cst.id\\n                 
          WHERE fcs.fileid = :fileid' {'fileid': 110481}
        ModuleName : WMComponent.DBS3Buffer.DBSUploadPoller
        MethodName : loadFiles
        ClassInstance : None
        FileName : /data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py
        ClassName : None
        LineNumber : 393
        ErrorNr : 0

Traceback: 
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py", line 385, in loadFiles
    loadedFiles = self.dbsUtil.findUploadableFilesByDAS(datasetpath=datasetpath)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSBufferUtil.py", line 133, in findUploadableFilesByDAS
    results = findFiles.execute(datasetpath=datasetpath, transaction=False)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/MySQL/LoadDBSFilesByDAS.py", line 259, in execute
    transaction = transaction)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMCore/Database/DBCore.py", line 160, in processData
    connection=connection, returnCursor=returnCursor))

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMCore/Database/DBCore.py", line 104, in executemanybinds
    resultproxy = connection.execute(s, bind)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 719, in execute
    return self._execute_text(object, multiparams, params)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 868, in _execute_text
    statement, parameters

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 954, in _execute_context
    context)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1116, in _handle_dbapi_exception
    exc_info

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 189, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 947, in _execute_context
    context)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 435, in do_execute
    cursor.execute(statement, parameters)

<@---------- WMException End ----------@>: Temp error will try later
Traceback (most recent call last):
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMCore/Database/DBExceptionHandler.py", line 28, in wrapper
    return f(*args, **kwargs)
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/Utils/Timers.py", line 24, in wrapper
    res = func(*arg, **kw)
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py", line 298, in algorithm
    self.loadFiles()
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py", line 393, in loadFiles
    raise DBSUploadException(msg)
DBSUploadException: <@========== WMException Start ==========@>
Exception Class: DBSUploadException
Message: Unhandled exception while loading uploadable files for DatasetPath.
(OperationalError) ORA-03113: end-of-file on communication channel
Process ID: 79131
Session ID: 3426 Serial number: 53581
 'SELECT cst.type AS cktype, fcs.cksum AS cksum, fcs.fileid AS id FROM\\n                           dbsbuffer_file_checksums fcs INNER JOIN\\n                           dbsbuffer_checksum_type cst ON fcs.typeid = cst.id\\n                           WHERE fcs.fileid = :fileid' {'fileid': 110481}
        ModuleName : WMComponent.DBS3Buffer.DBSUploadPoller
        MethodName : loadFiles
        ClassInstance : None
        FileName : /data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py
        ClassName : None
        LineNumber : 393
        ErrorNr : 0

Traceback: 
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSUploadPoller.py", line 385, in loadFiles
    loadedFiles = self.dbsUtil.findUploadableFilesByDAS(datasetpath=datasetpath)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/DBSBufferUtil.py", line 133, in findUploadableFilesByDAS
    results = findFiles.execute(datasetpath=datasetpath, transaction=False)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMComponent/DBS3Buffer/MySQL/LoadDBSFilesByDAS.py", line 259, in execute
    transaction = transaction)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMCore/Database/DBCore.py", line 160, in processData
    connection=connection, returnCursor=returnCursor))

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMCore/Database/DBCore.py", line 104, in executemanybinds
    resultproxy = connection.execute(s, bind)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 719, in execute
    return self._execute_text(object, multiparams, params)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 868, in _execute_text
    statement, parameters

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 954, in _execute_context
    context)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1116, in _handle_dbapi_exception
    exc_info

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 189, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 947, in _execute_context
    context)

  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/external/py2-sqlalchemy/0.9.6-comp/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 435, in do_execute
    cursor.execute(statement, parameters)

<@---------- WMException End ----------@>
2018-08-24 06:55:30,177:139873667856128:ERROR:BaseWorkerThread:Error in worker algorithm (1):

Backtrace:
  <WMComponent.DBS3Buffer.DBSUploadPoller.DBSUploadPoller object at 0x7f36e7a07750> 'NoneType' object is not iterable  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMCore/WorkerThreads/BaseWorkerThread.py", line 187, in __call__
    tSpent, results, _ = algorithmWithDBExceptionHandler(parameters)

2018-08-24 06:55:30,180:139873667856128:INFO:Harness:>>>Terminating worker threads
2018-08-24 06:55:30,181:139873667856128:ERROR:BaseWorkerThread:Error in event loop (2): <WMComponent.DBS3Buffer.DBSUploadPoller.DBSUploadPoller object at 0x7f36e7a07750> 'NoneType' object is not iterable
Backtrace:
  File "/data/srv/wmagent/v1.1.14.patch6/sw/slc7_amd64_gcc630/cms/wmagent/1.1.14.patch6/lib/python2.7/site-packages/WMCore/WorkerThreads/BaseWorkerThread.py", line 213, in __call__
    raise ex

2018-08-24 06:55:30,560:139873667856128:INFO:BaseWorkerThread:Worker thread <WMComponent.DBS3Buffer.DBSUploadPoller.DBSUploadPoller object at 0x7f36e7a07750> terminated
```

I think the components are already yielding the traceback, so in the DB wrapper function we can print only the error message, I think.

Changed files:
src/python/WMCore/Database/DBExceptionHandler.py

diff --git a/src/python/WMCore/Database/DBExceptionHandler.py b/src/python/WMCore/Database/DBExceptionHandler.py
index 526917580..4c7fc5097 100644
--- a/src/python/WMCore/Database/DBExceptionHandler.py
+++ b/src/python/WMCore/Database/DBExceptionHandler.py
@@ -16,7 +16,7 @@ def db_exception_handler(f):
     Only need to handle DB connection problem other db problems which need to rollback the transaction,
     shouldn't be included in this hanldler
 
-    TODO: instead of logging we can add logDB report
+    Warning: This only used, when original function return values are not used, or wrapped around Utils.Timer.timeFunc
     """
 
     @wraps(f)
@@ -27,19 +27,18 @@ def db_exception_handler(f):
         try:
             return f(*args, **kwargs)
         except Exception as ex:
-            raiseFlag = True
             msg = str(ex)
             for errStr in DB_CONNECTION_ERROR_STR:
                 if errStr in msg:
-                    logging.exception("%s: Temp error will try later", msg)
-                    raiseFlag = False
+                    logging.error("%s: Temp error will try later", msg)
 
                     if hasattr(myThread, "logdbClient") and myThread.logdbClient is not None:
                         myThread.logdbClient.post("DBConnection_error_handler", "warning")
 
-                    break
+                    # returns tuples of 3 since timeFunc returns (time to spend, result, func.__name__)
+                    return 0, None, f.__name__
 
-            if raiseFlag:
-                raise
+            # for other case raise the same exception
+            raise
 
     return wrapper