Repository: dmwm/wmcore
Issue: Investigate the JobExtractionError error during bootstrap

Info from wmstats

```
Job Name: 24fdfab4-81c9-11e6-9565-001e67abef8c-27
    WMBS job id: 1548420
    Workflow: cerminar_Run2016B-v2-BTagCSV-23Sep2016_8020_160923_163236_9822
    Task: /cerminar_Run2016B-v2-BTagCSV-23Sep2016_8020_160923_163236_9822/DataProcessing
    Status: jobcooloff
    Input dataset: /BTagCSV/Run2016B-v2/RAW
    Site: T2_CH_CERN_HLT
    Agent: vocms0311.cern.ch
    ACDC URL: https://cmsweb.cern.ch/couchdb/acdcserver
    State Transition
    Exit code: 11003
    Retry count: 0
    Errors:
        CRITICAL
            JobExtractionError (Exit Code: 11003)

                Failed to extract Job 1548420
                1548420
```

condor.out

```
...
WMAgent bootstrap : Sat Oct  1 11:27:37 UTC 2016 : WMAgent is now running the job...
Startup.py : 2016-10-01T06:27:37 : loading job definition
WMAgent bootstrap : Sat Oct  1 11:27:37 UTC 2016 : WMAgent finished the job, is copying the pickled report
WMAgent bootstrap : Sat Oct  1 11:27:37 UTC 2016 : WMAgent is finished. The job had an exit code of 1
```

and condor.err

```
Traceback (most recent call last):
  File "Startup.py", line 15, in <module>
    job = Bootstrap.loadJobDefinition()
  File "/storage/local/data1/condor/execute/dir_1529846/glide_PMCpkr/execute/dir_1735873/job/WMCore.zip/WMCore/WMRuntime/Bootstrap.py", line 153, in loadJobDefinition
WMCore.WMRuntime.Bootstrap.BootstrapException: BootstrapException
Message: Failed to extract Job 1548420
1548420
        ModuleName : WMCore.WMRuntime.Bootstrap
        MethodName : loadJobDefinition
        ClassInstance : None
        FileName : /storage/local/data1/condor/execute/dir_1529846/glide_PMCpkr/execute/dir_1735873/job/WMCore.zip/WMCore/WMRuntime/Bootstrap.py
        ClassName : None
        LineNumber : 153
        ErrorNr : 0

Traceback:
  File "/storage/local/data1/condor/execute/dir_1529846/glide_PMCpkr/execute/dir_1735873/job/WMCore.zip/WMCore/WMRuntime/Bootstrap.py", line 148, in loadJobDefinition
    job = package[index]


cp: cannot stat `WMTaskSpace/Report*.pkl': No such file or directory
ls: cannot access WMTaskSpace: No such file or directory
ls: cannot access WMTaskSpace/*: No such file or directory
```


Changed files:
src/python/WMCore/WMRuntime/Startup.py, src/python/WMCore/WMRuntime/Bootstrap.py

diff --git a/src/python/WMCore/WMRuntime/Bootstrap.py b/src/python/WMCore/WMRuntime/Bootstrap.py
index 48c87c7be..c52943f93 100644
--- a/src/python/WMCore/WMRuntime/Bootstrap.py
+++ b/src/python/WMCore/WMRuntime/Bootstrap.py
@@ -5,35 +5,28 @@ _TaskSpace_
 Frontend module for setting up TaskSpace & StepSpace areas within a job.
 """
 
-
-
-
-
 import inspect
 import pickle
 import os
 import os.path
-import logging
 import threading
-import sys
 import socket
+import logging
 from logging.handlers import RotatingFileHandler
 
-from WMCore.WMException        import WMException
-from WMCore.WMRuntime          import TaskSpace
-from WMCore.WMRuntime          import StepSpace
-from WMCore                    import WMLogging
+from WMCore.WMException import WMException
+from WMCore.WMRuntime import TaskSpace
+from WMCore.WMRuntime import StepSpace
 from WMCore.WMRuntime.Watchdog import Watchdog
 
 from WMCore.DataStructs.JobPackage import JobPackage
-from WMCore.WMSpec.WMWorkload      import WMWorkloadHelper
-
-from WMCore.Storage.SiteLocalConfig import loadSiteLocalConfig, SiteConfigError, SiteLocalConfig
+from WMCore.WMSpec.WMWorkload import WMWorkloadHelper
 import WMCore.FwkJobReport.Report as Report
+from WMCore.Storage.SiteLocalConfig import loadSiteLocalConfig, SiteConfigError
 
 
 class BootstrapException(WMException):
-    #TODO: make awesome
+    """ An awesome exception """
     pass
 
 
@@ -51,27 +44,25 @@ def getSyncCE():
     if 'GLOBUS_GRAM_JOB_CONTACT' in os.environ:
         #  //
         # // OSG, Sync CE from Globus ID
-        #//
+        # //
         val = os.environ['GLOBUS_GRAM_JOB_CONTACT']
         try:
             host = val.split("https://", 1)[1]
             host = host.split(":")[0]
             result = host
-        except:
-            pass
+        except Exception:
+            logging.warn("Failed to extract SynCE from globus")
         return result
 
     if 'NORDUGRID_CE' in os.environ:
         #  //
         # // ARC, Sync CE from env. var. submitted with the job by JobSubmitter
-        #//
+        # //
         return os.environ['NORDUGRID_CE']
 
     return result
 
 
-
-
 def establishTaskSpace(**args):
     """
     _establishTaskSpace_
@@ -81,6 +72,7 @@ def establishTaskSpace(**args):
     """
     return TaskSpace.TaskSpace(**args)
 
+
 def establishStepSpace(**args):
     """
     _establishStepSpace_
@@ -90,6 +82,7 @@ def establishStepSpace(**args):
     """
     return StepSpace.StepSpace(**args)
 
+
 def locateWMSandbox():
     """
     _locateWMSandbox_
@@ -112,6 +105,7 @@ def locateWMSandbox():
     wmsandboxLoc = wmsandboxLoc.replace("__init__.py", "")
     return wmsandboxLoc
 
+
 def loadJobDefinition():
     """
     _loadJobDefinition_
@@ -131,7 +125,7 @@ def loadJobDefinition():
     except Exception as ex:
         msg = "Failed to load JobPackage:%s\\n" % packageLoc
         msg += str(ex)
-        createErrorReport(exitCode = 11001, errorType = "JobPackageError", errorDetails = msg)
+        createErrorReport(exitCode=11001, errorType="JobPackageError", errorDetails=msg)
         raise BootstrapException(msg)
 
     try:
@@ -139,26 +133,24 @@ def loadJobDefinition():
     except ImportError as ex:
         msg = "Failed to import WMSandbox.JobIndex module\\n"
         msg += str(ex)
-        createErrorReport(exitCode = 11002, errorType = "JobIndexError", errorDetails = msg)
+        createErrorReport(exitCode=11002, errorType="JobIndexError", errorDetails=msg)
         raise BootstrapException(msg)
 
     index = WMSandbox.JobIndex.jobIndex
 
     try:
         job = package[index]
-    except Exception as ex:
-        msg = "Failed to extract Job %i\\n" % (index)
-        msg += str(ex)
-        createErrorReport(exitCode = 11003, errorType = "JobExtractionError", errorDetails = msg)
+    except Exception:
+        msg = "Failed to extract job index %i " % index
+        msg += "from the jobPackage directory: %s\\n" % package.get('directory')
+        msg += "Found a total of %d indexes in the JobPackage.\\n" % len(package)
+        createErrorReport(exitCode=11003, errorType="JobExtractionError", errorDetails=msg)
         raise BootstrapException(msg)
-    diagnostic = """
-    Job Index = %s
-    Job Instance = %s
-    """ % (index, job)
-    logging.info(diagnostic)
+    logging.info("Job Index = %s\\nJob Instance = %s\\n", index, job)
 
     return job
 
+
 def loadWorkload():
     """
     _loadWorkload_
@@ -175,8 +167,6 @@ def loadWorkload():
     return WMWorkloadHelper(wmWorkload)
 
 
-
-
 def loadTask(job):
     """
     _loadTask_
@@ -190,27 +180,27 @@ def loadTask(job):
     try:
         task = workload.getTaskByPath(job['task'])
     except KeyError as ex:
-        msg =  "Task name not in job object"
+        msg = "Task name not in job object"
         msg += str(ex)
-        createErrorReport(exitCode = 11103, errorType = "TaskNotInJob", errorDetails = msg,
-                          logLocation = "Report.%i.pkl" % job['retry_count'])
+        createErrorReport(exitCode=11103, errorType="TaskNotInJob", errorDetails=msg,
+                          logLocation="Report.%i.pkl" % job['retry_count'])
         raise BootstrapException(msg)
     except Exception as ex:
         msg = "Error looking up task %s\\n" % job['task']
         msg += str(ex)
-        createErrorReport(exitCode = 11101, errorType = "TaskLookupError", errorDetails = msg,
-                          logLocation = "Report.%i.pkl" % job['retry_count'])
+        createErrorReport(exitCode=11101, errorType="TaskLookupError", errorDetails=msg,
+                          logLocation="Report.%i.pkl" % job['retry_count'])
         raise BootstrapException(msg)
-    if task == None:
+    if task is None:
         msg = "Unable to look up task %s from Workload\\n" % job['task']
         msg += "Task name not matched"
-        createErrorReport(exitCode = 11102, errorType = "TaskNotFound", errorDetails = msg,
-                          logLocation = "Report.%i.pkl" % job['retry_count'])
+        createErrorReport(exitCode=11102, errorType="TaskNotFound", errorDetails=msg,
+                          logLocation="Report.%i.pkl" % job['retry_count'])
         raise BootstrapException(msg)
     return task
 
 
-def createInitialReport(job, task, logLocation):
+def createInitialReport(job, logLocation):
     """
     _createInitialReport_
 
@@ -223,20 +213,19 @@ def createInitialReport(job, task, logLocation):
         # For now, assume that we did this on purpose
         msg = "Couldn't find SiteConfig"
         logging.error(msg)
-        #TODO: Make less goatballs for testing purposes
+        # TODO: Make less goatballs for testing purposes
         return
 
-    report  = Report.Report()
-
+    report = Report.Report()
 
-    report.data.WMAgentJobID   = job.get('id', None)
+    report.data.WMAgentJobID = job.get('id', None)
     report.data.WMAgentJobName = job.get('name', None)
-    report.data.pnn            = siteCfg.localStageOut.get('phedex-node', 'Unknown')
-    report.data.siteName       = getattr(siteCfg, 'siteName', 'Unknown')
-    report.data.hostName       = socket.gethostname()
-    report.data.ceName         = getSyncCE()
-    report.data.completed      = False
-    report.setTaskName(taskName = job.get('task', 'TaskNotFound'))
+    report.data.pnn = siteCfg.localStageOut.get('phedex-node', 'Unknown')
+    report.data.siteName = getattr(siteCfg, 'siteName', 'Unknown')
+    report.data.hostName = socket.gethostname()
+    report.data.ceName = getSyncCE()
+    report.data.completed = False
+    report.setTaskName(taskName=job.get('task', 'TaskNotFound'))
 
     # Not so fond of this, but we have to put the master
     # report way up at the top so it's returned if the
@@ -247,9 +236,8 @@ def createInitialReport(job, task, logLocation):
     return
 
 
-
-def createErrorReport(exitCode, errorType, errorDetails = None,
-                      logLocation = "Report.0.pkl"):
+def createErrorReport(exitCode, errorType, errorDetails=None,
+                      logLocation="Report.0.pkl"):
     """
     _createErrorReport_
 
@@ -258,27 +246,24 @@ def createErrorReport(exitCode, errorType, errorDetails = None,
     sticks the error in there.
     """
 
-
     try:
         siteCfg = loadSiteLocalConfig()
     except SiteConfigError:
         # For now, assume that we did this on purpose
         msg = "Couldn't find SiteConfig"
         logging.error(msg)
-        #TODO: Make this not suck goatballs when you are just running tests
+        # TODO: Make this not suck goatballs when you are just running tests
         return
-    report  = Report.Report()
-
-
-    report.data.pnn         = siteCfg.localStageOut.get('phedex-node', 'Unknown')
-    report.data.siteName       = getattr(siteCfg, 'siteName', 'Unknown')
-    report.data.hostName       = socket.gethostname()
-    report.data.ceName         = getSyncCE()
-    report.data.completed      = False
+    report = Report.Report()
 
+    report.data.pnn = siteCfg.localStageOut.get('phedex-node', 'Unknown')
+    report.data.siteName = getattr(siteCfg, 'siteName', 'Unknown')
+    report.data.hostName = socket.gethostname()
+    report.data.ceName = getSyncCE()
+    report.data.completed = False
 
-    report.addError(stepName = 'CRITICAL', exitCode = exitCode,
-                    errorType = errorType, errorDetails = errorDetails)
+    report.addError(stepName='CRITICAL', exitCode=exitCode,
+                    errorType=errorType, errorDetails=errorDetails)
 
     reportPath = os.path.join(os.getcwd(), '../', logLocation)
     report.save(reportPath)
@@ -286,9 +271,6 @@ def createErrorReport(exitCode, errorType, errorDetails = None,
     return
 
 
-
-
-
 def setupLogging(logDir):
     """
     _setupLogging_
@@ -304,9 +286,9 @@ def setupLogging(logDir):
         logHandler.setFormatter(logFormatter)
         logging.getLogger().addHandler(logHandler)
         logging.getLogger().setLevel(logging.INFO)
-        #This is left in as a reminder for debugging purposes
-        #SQLDEBUG turns your log files into horrible messes
-        #logging.getLogger().setLevel(logging.SQLDEBUG)
+        # This is left in as a reminder for debugging purposes
+        # SQLDEBUG turns your log files into horrible messes
+        # logging.getLogger().setLevel(logging.SQLDEBUG)
 
         myThread = threading.currentThread()
         myThread.logger = logging.getLogger()
@@ -324,7 +306,7 @@ def setupMonitoring(logPath):
 
     """
     try:
-        monitor = Watchdog(logPath = logPath)
+        monitor = Watchdog(logPath=logPath)
         myThread = threading.currentThread
         myThread.watchdogMonitor = monitor
         return monitor
diff --git a/src/python/WMCore/WMRuntime/Startup.py b/src/python/WMCore/WMRuntime/Startup.py
index 03c35b92c..c62461368 100644
--- a/src/python/WMCore/WMRuntime/Startup.py
+++ b/src/python/WMCore/WMRuntime/Startup.py
@@ -17,10 +17,8 @@ if __name__ == '__main__':
     task = Bootstrap.loadTask(job)
     print("Startup.py : %s : setting up monitoring" % time.strftime("%Y-%m-%dT%H:%M:%S"))
     logLocation = "Report.%i.pkl" % job['retry_count']
-    Bootstrap.createInitialReport(job = job,
-                                  task = task,
-                                  logLocation = logLocation)
-    monitor = Bootstrap.setupMonitoring(logPath = logLocation)
+    Bootstrap.createInitialReport(job=job, logLocation=logLocation)
+    monitor = Bootstrap.setupMonitoring(logPath=logLocation)
 
     print("Startup.py : %s : setting up logging" % time.strftime("%Y-%m-%dT%H:%M:%S"))
     Bootstrap.setupLogging(os.getcwd())
@@ -30,8 +28,8 @@ if __name__ == '__main__':
     print("Startup.py : %s : executing task" % time.strftime("%Y-%m-%dT%H:%M:%S"))
     task.execute(job)
     print("Startup.py : %s : completing task" % time.strftime("%Y-%m-%dT%H:%M:%S"))
-    task.completeTask(jobLocation = os.getcwd(),
-                      logLocation = logLocation)
+    task.completeTask(jobLocation=os.getcwd(),
+                      logLocation=logLocation)
     print("Startup.py : %s : shutting down monitor" % time.strftime("%Y-%m-%dT%H:%M:%S"))
     os.fchmod(1, 0o664)
     os.fchmod(2, 0o664)