Hi All,
Sorry, lengthy.
I've just had a complaint from t2k that about half of ~400 jobs failed with
Current Status: Aborted
Status Reason: failed (LB query failed)
both at the RAL and Imperial WMS.
Googling this error just seems to suggest it's not uncommon, but no hint whatsoever what is wrong.
My own WMS here seems to be reasonably happy right now, and if I do a grep in the log, there is nothing suspicious, at the end it just says:
workload_manager_events.log:18 Jan, 23:03:41 -I: [Info] operator()(dispatcher_utils.cpp:218): new jobsubmit for https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA
workload_manager_events.log:18 Jan, 23:03:44 -I: [Info] checkRequirement(matchmakerISMImpl.cpp:89): MM for job: https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA (9/12533 [3] )
workload_manager_events.log:18 Jan, 23:03:44 -I: [Info] operator()(submit_request.cpp:478): https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA delivered
workload_manager_events.log:18 Jan, 23:14:24 -I: [Info] operator()(dispatcher_utils.cpp:218): new jobresubmit for https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA
workload_manager_events.log:18 Jan, 23:14:24 -E: [Error] unrecoverable(submit_request.cpp:111): https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA failed ( failed (LB query failed))
The job went to a cream CE as far as I can tell:
2011-01-18 23:03:45,057 INFO - iceCommandSubmit::try_to_submit() - TID=[140441744] For GridJobID [https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA] CREAM Returned CREAM-JOBID [https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568] DB_ID []
2011-01-18 23:03:45,059 DEBUG - iceCommandSubmit::try_to_submit() - TID=[140441744] Going to START CreamJobID [https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568] related to GridJobID [https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA]...
2011-01-18 23:03:45,191 INFO - iceLBContext::setLoggingJob - Setting log job to jobid=[https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA] LB server=[wmslb01.hep.ph.ic.ac.uk:9000] (port is not used, actually...)
2011-01-18 23:03:45,191 INFO - iceLBLogger::logEvent() - Cream Transfer OK Event - [gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568"]
2011-01-18 23:03:45,214 DEBUG - filelist_request_purger - removing request [ Arguments = [ JobAd = [ requirements = ( ( Member("VO-t2k.org-ND280-v8r5p9",other.GlueHostApplicationSoftwareRunTimeEnvironment) && ( !RegExp("shef.ac.uk",other.GlueCEUniqueID) ) && other.GlueCEPolicyMaxCPUTime > 1200 ) && ( other.GlueCEStateStatus == "Production" ) ) && !RegExp(".*sdj$",other.GlueCEUniqueID); RetryCount = 3; edg_jobid = "https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA"; lrms_type = "torque"; CeApplicationDir = "/stage/sl3-lcg-exp/t2ksgm"; GlobusResourceContactString = "lcgce05.gridpp.rl.ac.uk:8443/cream-pbs"; OutputSandboxPath = "/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA/output"; ce_id = "lcgce05.gridpp.rl.ac.uk:8443/cream-pbs-grid500M"; MyProxyServer = "lcgrbp01.gridpp.rl.ac.uk"; AllowZippedISB = true; QueueName = "grid500M"; JobType = "normal"; InputSandboxDestFileName = { "geniefc-10-17-46.sh" }; SignificantAttributes = { "Requirements","Rank","FuzzyRank" }; Executable = "geniefc-10-17-46.sh"; OutputSandboxDestURI = { "gsiftp://wms01.hep.ph.ic.ac.uk:2811/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA/output/stdout","gsiftp://wms01.hep.ph.ic.ac.uk:2811/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA/output/stderr" }; CertificateSubject = "/C=UK/O=eScience/OU=Imperial/L=Physics/CN=james dobson"; X509UserProxy = "/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA/user.proxy"; StdOutput = "stdout"; VOMS_FQAN = "/t2k.org/Role=NULL/Capability=NULL"; OutputSandbox = { "stdout","stderr" }; LB_sequence_code = "UI=000000:NS=0000000004:WM=000004:BH=0000000000:JSS=000000:LM=000000:LRMS=000000:APP=000000:LBS=000000"; InputSandboxPath = "/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA/input"; VirtualOrganisation = "t2k.org"; rank = -other.GlueCEStateEstimatedResponseTime; Type = "job"; ShallowRetryCount = 10; CeRequirements = "true && ( true && ( true && Member(\"VO-t2k.org-ND280-v8r5p9\",other.GlueHostApplicationSoftwareRunTimeEnvironment) && other.GlueCEPolicyMaxCPUTime > 1200 ) )"; StdError = "stderr"; WMPInputSandboxBaseURI = "gsiftp://wms01.hep.ph.ic.ac.uk:2811/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA"; DefaultRank = -other.GlueCEStateEstimatedResponseTime; ReallyRunningToken = "gsiftp://wms01.hep.ph.ic.ac.uk/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA/token.txt"; ZippedISB = { "ISBfiles_S6Q0LX8bTIVIlI7tUg_q9A_0.tar.gz" }; InputSandbox = { "gsiftp://wms01.hep.ph.ic.ac.uk:2811/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA/input/geniefc-10-17-46.sh","gsiftp://wms01.hep.ph.ic.ac.uk:2811/var/glite/SandboxDir/i0/https_3a_2f_2fwmslb01.hep.ph.ic.ac.uk_3a9000_2fi0o1aa5KK-Dm8Tf_5fLnnPaA/input/.BrokerInfo" } ] ]; Command = "Submit"; Source = 2; Protocol = "1.0.0" ]
2011-01-18 23:14:23,261 DEBUG - iceCommandStatusPoller::update_single_job() - Updating ICE's database for gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568" status = [REGISTERED] exit_code = [] failure_reason = [] description = []
2011-01-18 23:14:23,262 DEBUG - iceCommandStatusPoller::update_single_job() - Updating ICE's database for gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568" status = [PENDING] exit_code = [] failure_reason = [] description = []
----> Now the next bit I would interpret as the job actually having failed to at the local batch system level, but why does this error not get propagated ?
2011-01-18 23:14:23,263 DEBUG - iceCommandStatusPoller::update_single_job() - Updating ICE's database for gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568" status = [ABORTED] exit_code = [] failure_reason = [BLAH error: submission command failed (exit code = 1) (stdout:) (stderr:pbs_iff: cannot read reply from pbs_server-No Permission.-qsub: cannot connect to server lcgbatch01.gridpp.rl.ac.uk (errno=15007) Unauthorized Request -TERM environment variable not set.-) N/A (jobId = CREAM503909568)] description = []
2011-01-18 23:14:23,264 INFO - iceLBContext::setLoggingJob - Setting log job to jobid=[https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA] LB server=[wmslb01.hep.ph.ic.ac.uk:9000] (port is not used, actually...)
2011-01-18 23:14:23,264 INFO - iceLBLogger::logEvent() - Job Aborted Event, reason=[BLAH error: submission command failed (exit code = 1) (stdout:) (stderr:pbs_iff: cannot read reply from pbs_server-No Permission.-qsub: cannot connect to server lcgbatch01.gridpp.rl.ac.uk (errno=15007) Unauthorized Request -TERM environment variable not set.-) N/A (jobId = CREAM503909568)] - [gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568"]
2011-01-18 23:14:23,301 DEBUG - Ice::resubmit_or_purge_job() - Removing purged job [gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568"] from ICE's database
2011-01-18 23:14:23,315 INFO - iceLBContext::setLoggingJob - Setting log job to jobid=[https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA] LB server=[wmslb01.hep.ph.ic.ac.uk:9000] (port is not used, actually...)
2011-01-18 23:14:23,316 INFO - iceLBLogger::logEvent() - ICE Resubmission Event, reason=[Job resubmitted by ICE] - [gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568"]
2011-01-18 23:14:23,329 INFO - iceLBContext::setLoggingJob - Setting log job to jobid=[https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA] LB server=[wmslb01.hep.ph.ic.ac.uk:9000] (port is not used, actually...)
2011-01-18 23:14:23,329 INFO - iceLBLogger::logEvent() - NS Enqueued Start Event, qname=[/var/glite/workload_manager/jobdir] - [gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568"]
2011-01-18 23:14:23,341 INFO - Ice::resubmit_job() - Putting [[ arguments = [ id = "https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA"; lb_sequence_code = "UI=000000:NS=0000000004:WM=000004:BH=0000000000:JSS=000002:LM=000010:LRMS=000000:APP=000000:LBS=000000" ]; command = "jobresubmit"; version = "1.0.0" ]] to WM's Input file
2011-01-18 23:14:23,341 INFO - iceLBContext::setLoggingJob - Setting log job to jobid=[https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA] LB server=[wmslb01.hep.ph.ic.ac.uk:9000] (port is not used, actually...)
2011-01-18 23:14:23,342 INFO - iceLBLogger::logEvent() - NS Enqueued OK Event, qname=[/var/glite/workload_manager/jobdir] - [gridJobID="https://wmslb01.hep.ph.ic.ac.uk:9000/i0o1aa5KK-Dm8Tf_LnnPaA" CREAMJobID="https://lcgce05.gridpp.rl.ac.uk:8443/CREAM503909568"]
Does anybody have an idea what is going on here ?
Thanks,
Daniela
--
-----------------------------------------------------------
[log in to unmask]
HEP Group/Physics Dep
Imperial College
Tel: +44-(0)20-75947810
http://www.hep.ph.ic.ac.uk/~dbauer/
