Re: [Condor-users] condor-g jobs failing - stuck in STAGE_OUT

["Lila Klektau" <lmk@xxxxxxx>]

On Wed, 23 Jun 2004 21:53:51 -0500, Jaime Frey <jfrey@xxxxxxxxxxx> wrote:

> It looks like the globus-url-copy to stage out the job files is hanging  
> on the gatekeeper machine. We've seen this problem with globus-url-copy  
> in other situations, but haven't been able to determine the cause. If  
> you could add/change the following line to your condor_config file,  
> reproduce the problem, and send me the resulting gridmanager log file,  
> it'd be a great help in figuring out how to make condor-g better at  
> working around this problem:
>
> GRIDMANAGER_DEBUG = D_FULLDEBUG

Thanks for the reply,

I've been trying to recreate the problem, with full debugging, but I'm  
noticing two different outputs.  In one case, the job is not attempting to  
restart and netstat shows no connections on the condor-g machine to the  
remote resource, but the remote resource shows CLOSE_WAIT connections with  
the condor-g machine.  This is the tail end of the GridmanagerLog file for  
that:

6/24 10:16:47 [22515] Updating classad values for 859.0:
6/24 10:16:47 [22515]    GlobusStatus = 128
6/24 10:16:47 [22515] leaving doContactSchedd()
6/24 10:16:52 [22515] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 10:17:37 [22515] GAHP <- 'RESULTS'
6/24 10:17:37 [22515] GAHP -> 'S' '0'
6/24 10:17:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:18:37 [22515] GAHP <- 'RESULTS'
6/24 10:18:37 [22515] GAHP -> 'S' '0'
6/24 10:18:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:18:52 [22515] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 10:19:37 [22515] GAHP <- 'RESULTS'
6/24 10:19:37 [22515] GAHP -> 'S' '0'
6/24 10:19:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:20:16 [22515] (859.0) doEvaluateState called: gmState  
GM_SUBMITTED, globusState 128
6/24 10:20:16 [22515] (859.0) gm state change: GM_SUBMITTED ->  
GM_PROBE_JOBMANAGER
6/24 10:20:16 [22515] GAHP <- 'GRAM_JOB_STATUS 25  
https://mercury.uvic.ca:40053/9165/1088097296/'
6/24 10:20:16 [22515] GAHP -> 'S'
6/24 10:20:17 [22515] GAHP <- 'RESULTS'
6/24 10:20:17 [22515] GAHP -> 'S' '1'
6/24 10:20:17 [22515] GAHP -> '25' '0' '0' '128'
6/24 10:20:17 [22515] (859.0) doEvaluateState called: gmState  
GM_PROBE_JOBMANAGER, globusState 128
6/24 10:20:17 [22515] (859.0) gm state change: GM_PROBE_JOBMANAGER ->  
GM_SUBMITTED
6/24 10:20:37 [22515] GAHP <- 'RESULTS'
6/24 10:20:37 [22515] GAHP -> 'S' '0'
6/24 10:20:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:20:52 [22515] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 10:21:37 [22515] GAHP <- 'RESULTS'
6/24 10:21:37 [22515] GAHP -> 'S' '0'
6/24 10:21:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:22:37 [22515] GAHP <- 'RESULTS'
6/24 10:22:37 [22515] GAHP -> 'S' '0'
6/24 10:22:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:22:52 [22515] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 10:23:37 [22515] GAHP <- 'RESULTS'
6/24 10:23:37 [22515] GAHP -> 'S' '0'
6/24 10:23:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:24:37 [22515] GAHP <- 'RESULTS'
6/24 10:24:37 [22515] GAHP -> 'S' '0'
6/24 10:24:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:24:40 [22515] CheckProxies called
6/24 10:24:40 [22515]   will call CheckProxies again in 600 seconds
6/24 10:24:52 [22515] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 10:25:17 [22515] (859.0) doEvaluateState called: gmState  
GM_SUBMITTED, globusState 128
6/24 10:25:17 [22515] (859.0) gm state change: GM_SUBMITTED ->  
GM_PROBE_JOBMANAGER
6/24 10:25:17 [22515] GAHP <- 'GRAM_JOB_STATUS 26  
https://mercury.uvic.ca:40053/9165/1088097296/'
6/24 10:25:17 [22515] GAHP -> 'S'
6/24 10:25:17 [22515] GAHP <- 'RESULTS'
6/24 10:25:17 [22515] GAHP -> 'S' '1'
6/24 10:25:17 [22515] GAHP -> '26' '0' '0' '128'
6/24 10:25:17 [22515] (859.0) doEvaluateState called: gmState  
GM_PROBE_JOBMANAGER, globusState 128
6/24 10:25:17 [22515] (859.0) gm state change: GM_PROBE_JOBMANAGER ->  
GM_SUBMITTED
6/24 10:25:37 [22515] GAHP <- 'RESULTS'
6/24 10:25:37 [22515] GAHP -> 'S' '0'
6/24 10:25:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:26:37 [22515] GAHP <- 'RESULTS'
6/24 10:26:37 [22515] GAHP -> 'S' '0'
6/24 10:26:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:26:52 [22515] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 10:27:37 [22515] GAHP <- 'RESULTS'
6/24 10:27:37 [22515] GAHP -> 'S' '0'
6/24 10:27:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:28:37 [22515] GAHP <- 'RESULTS'
6/24 10:28:37 [22515] GAHP -> 'S' '0'
6/24 10:28:38 [22515] checkResources(): 1 resources, 0 are down
6/24 10:28:52 [22515] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.


If I let it keep going, similar messages will just be repeated.

However, in other cases a job restart is attempted (this is the one I have  
noticed many times before, where netstat shows connections on both sides  
and a new log file on remote resource is created every minute).  This is  
the corresponding tail end of the GridmanagerLog file:

6/24 08:39:37 [18272] GAHP <- 'RESULTS'
6/24 08:39:37 [18272] GAHP -> 'S' '0'
6/24 08:39:38 [18272] checkResources(): 1 resources, 0 are down
6/24 08:40:20 [18272] (814.0) doEvaluateState called: gmState  
GM_SUBMITTED, globusState 128
6/24 08:40:20 [18272] (814.0) gm state change: GM_SUBMITTED ->  
GM_PROBE_JOBMANAGER
6/24 08:40:20 [18272] GAHP <- 'GRAM_JOB_STATUS 59  
https://mercury.uvic.ca:40023/30935/1088091305/'
6/24 08:40:20 [18272] GAHP -> 'S'
6/24 08:40:20 [18272] GAHP <- 'RESULTS'
6/24 08:40:20 [18272] GAHP -> 'S' '1'
6/24 08:40:20 [18272] GAHP -> '59' '0' '0' '128'
6/24 08:40:20 [18272] (814.0) doEvaluateState called: gmState  
GM_PROBE_JOBMANAGER, globusState 128
6/24 08:40:20 [18272] (814.0) gm state change: GM_PROBE_JOBMANAGER ->  
GM_SUBMITTED
6/24 08:40:37 [18272] GAHP <- 'RESULTS'
6/24 08:40:37 [18272] GAHP -> 'S' '0'
6/24 08:40:38 [18272] checkResources(): 1 resources, 0 are down
6/24 08:40:52 [18272] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 08:41:37 [18272] GAHP <- 'RESULTS'
6/24 08:41:37 [18272] GAHP -> 'S' '0'
6/24 08:41:38 [18272] checkResources(): 1 resources, 0 are down
6/24 08:42:37 [18272] GAHP <- 'RESULTS'
6/24 08:42:37 [18272] GAHP -> 'S' '0'
6/24 08:42:38 [18272] checkResources(): 1 resources, 0 are down
6/24 08:42:52 [18272] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 08:43:37 [18272] GAHP <- 'RESULTS'
6/24 08:43:37 [18272] GAHP -> 'S' '0'
6/24 08:43:38 [18272] checkResources(): 1 resources, 0 are down
6/24 08:44:37 [18272] GAHP <- 'RESULTS'
6/24 08:44:37 [18272] GAHP -> 'S' '0'
6/24 08:44:38 [18272] checkResources(): 1 resources, 0 are down
6/24 08:44:40 [18272] CheckProxies called
6/24 08:44:40 [18272]   (re)caching proxy 1
6/24 08:44:40 [18272] GAHP <- 'CACHE_PROXY_FROM_FILE 1 /tmp/x509up_u505'
6/24 08:44:40 [18272] GAHP -> 'S'
6/24 08:44:40 [18272] GAHP <- 'USE_CACHED_PROXY 1'
6/24 08:44:40 [18272] GAHP -> 'S'
6/24 08:44:40 [18272]   will call CheckProxies again in 600 seconds
6/24 08:44:40 [18272] (814.0) doEvaluateState called: gmState  
GM_SUBMITTED, globusState 128
6/24 08:44:40 [18272] (814.0) gm state change: GM_SUBMITTED ->  
GM_REFRESH_PROXY
6/24 08:44:40 [18272] GAHP <- 'GRAM_JOB_REFRESH_PROXY 60  
https://mercury.uvic.ca:40023/30935/1088091305/'
6/24 08:44:40 [18272] GAHP -> 'S'
6/24 08:44:40 [18272] GAHP <- 'RESULTS'
6/24 08:44:40 [18272] GAHP -> 'S' '1'
6/24 08:44:40 [18272] GAHP -> '60' '10'
6/24 08:44:40 [18272] (814.0) doEvaluateState called: gmState  
GM_REFRESH_PROXY, globusState 128
6/24 08:44:40 [18272] (814.0) gmState GM_REFRESH_PROXY, globusState 128:  
refresh_credentials() returned Globus error 10
6/24 08:44:40 [18272] (814.0) gm state change: GM_REFRESH_PROXY ->  
GM_STOP_AND_RESTART
6/24 08:44:40 [18272] GAHP <- 'GRAM_JOB_SIGNAL 61  
https://mercury.uvic.ca:40023/30935/1088091305/ 9 NULL'
6/24 08:44:40 [18272] GAHP -> 'S'
6/24 08:44:40 [18272] GAHP <- 'RESULTS'
6/24 08:44:40 [18272] GAHP -> 'S' '1'
6/24 08:44:40 [18272] GAHP -> '61' '0' '0' '128'
6/24 08:44:40 [18272] (814.0) doEvaluateState called: gmState  
GM_STOP_AND_RESTART, globusState 128
6/24 08:44:40 [18272] (814.0) gm state change: GM_STOP_AND_RESTART ->  
GM_RESTART
6/24 08:44:40 [18272] GAHP <- 'GRAM_JOB_REQUEST 62  
mercury.uvic.ca:2119/jobmanager-pbs https://gcgate01.phys.uvic.ca:43460/ 1  
&(rsl_substitution=(GRIDMANAGER_GASS_URL\ https://gcgate01.phys.uvic.ca:43461))(restart=https://mercury.uvic.ca:40023/30935/1088091305/)(remote_io_url=$(GRIDMANAGER_GASS_URL))(proxy_timeout=240)'
6/24 08:44:40 [18272] GAHP -> 'S'
6/24 08:44:41 [18272] GAHP <- 'RESULTS'
6/24 08:44:41 [18272] GAHP -> 'S' '1'
6/24 08:44:41 [18272] GAHP -> '62' '124'  
'https://mercury.uvic.ca:40023/30935/1088091305/'
6/24 08:44:41 [18272] (814.0) doEvaluateState called: gmState GM_RESTART,  
globusState 128
6/24 08:44:41 [18272] (814.0) gm state change: GM_RESTART -> GM_INIT
6/24 08:44:41 [18272] (814.0) gm state change: GM_INIT -> GM_REGISTER
6/24 08:44:41 [18272] GAHP <- 'GRAM_JOB_CALLBACK_REGISTER 63  
https://mercury.uvic.ca:40023/30935/1088091305/  
https://gcgate01.phys.uvic.ca:43460/'
6/24 08:44:41 [18272] GAHP -> 'S'
6/24 08:44:41 [18272] GAHP <- 'RESULTS'
6/24 08:44:41 [18272] GAHP -> 'S' '1'
6/24 08:44:41 [18272] GAHP -> '63' '0' '130' '4'
6/24 08:44:41 [18272] (814.0) doEvaluateState called: gmState GM_REGISTER,  
globusState 128
6/24 08:44:41 [18272] (814.0) globus state change: STAGE_OUT -> FAILED
6/24 08:44:41 [18272] (814.0) gm state change: GM_REGISTER ->  
GM_STDIO_UPDATE
6/24 08:44:41 [18272] GAHP <- 'GRAM_JOB_SIGNAL 64  
https://mercury.uvic.ca:40023/30935/1088091305/ 7  
&(remote_io_url=https://gcgate01.phys.uvic.ca:43461)(invalid=bad)(invalid=bad)'
6/24 08:44:41 [18272] GAHP -> 'S'
6/24 08:44:41 [18272] (814.0) doEvaluateState called: gmState  
GM_STDIO_UPDATE, globusState 4
6/24 08:44:41 [18272] in doContactSchedd()
6/24 08:44:41 [18272] GRIDMANAGER_TIMEOUT_MULTIPLIER is undefined, using  
default value of 0
6/24 08:44:41 [18272] SEC_DEBUG_PRINT_KEYS is undefined, using default  
value of False
6/24 08:44:41 [18272] AUTHENTICATE_FS: used file /tmp/qmgr_QPq9At, status:  
1
6/24 08:44:41 [18272] Updating classad values for 814.0:
6/24 08:44:41 [18272] leaving doContactSchedd()
6/24 08:44:41 [18272] GAHP <- 'RESULTS'
6/24 08:44:41 [18272] GAHP -> 'S' '1'
6/24 08:44:41 [18272] GAHP -> '64' '94' '0' '4'
6/24 08:44:41 [18272] (814.0) doEvaluateState called: gmState  
GM_STDIO_UPDATE, globusState 4
6/24 08:44:41 [18272] (814.0) gm state change: GM_STDIO_UPDATE ->  
GM_SUBMITTED
6/24 08:44:41 [18272] (814.0) gm state change: GM_SUBMITTED -> GM_FAILED
6/24 08:44:41 [18272] (814.0) gm state change: GM_FAILED -> GM_RESTART
6/24 08:44:52 [18272] DaemonCore::IsPidAlive(): kill returned EPERM,  
assuming pid 3366 is alive.
6/24 08:45:37 [18272] GAHP <- 'RESULTS'
6/24 08:45:37 [18272] GAHP -> 'S' '0'
6/24 08:45:38 [18272] checkResources(): 1 resources, 0 are down
6/24 08:45:41 [18272] (814.0) doEvaluateState called: gmState GM_RESTART,  
globusState 4
6/24 08:45:41 [18272] GAHP <- 'GRAM_JOB_REQUEST 65  
mercury.uvic.ca:2119/jobmanager-pbs https://gcgate01.phys.uvic.ca:43460/ 1  
&(rsl_substitution=(GRIDMANAGER_GASS_URL\ https://gcgate01.phys.uvic.ca:43461))(restart=https://mercury.uvic.ca:40023/30935/1088091305/)(remote_io_url=$(GRIDMANAGER_GASS_URL))(proxy_timeout=240)'
6/24 08:45:41 [18272] GAHP -> 'S'
6/24 08:45:41 [18272] GAHP <- 'RESULTS'
6/24 08:45:41 [18272] GAHP -> 'S' '1'
6/24 08:45:41 [18272] GAHP -> '65' '124'  
'https://mercury.uvic.ca:40023/30935/1088091305/'
6/24 08:45:41 [18272] (814.0) doEvaluateState called: gmState GM_RESTART,  
globusState 4
6/24 08:45:41 [18272] (814.0) gm state change: GM_RESTART -> GM_INIT
6/24 08:45:41 [18272] (814.0) gm state change: GM_INIT -> GM_REGISTER
6/24 08:45:41 [18272] GAHP <- 'GRAM_JOB_CALLBACK_REGISTER 66  
https://mercury.uvic.ca:40023/30935/1088091305/  
https://gcgate01.phys.uvic.ca:43460/'
6/24 08:45:41 [18272] GAHP -> 'S'
6/24 08:45:41 [18272] GAHP <- 'RESULTS'
6/24 08:45:41 [18272] GAHP -> 'S' '1'
6/24 08:45:41 [18272] GAHP -> '66' '0' '130' '4'
6/24 08:45:41 [18272] (814.0) doEvaluateState called: gmState GM_REGISTER,  
globusState 4
6/24 08:45:41 [18272] (814.0) gm state change: GM_REGISTER ->  
GM_STDIO_UPDATE
6/24 08:45:41 [18272] GAHP <- 'GRAM_JOB_SIGNAL 67  
https://mercury.uvic.ca:40023/30935/1088091305/ 7  
&(remote_io_url=https://gcgate01.phys.uvic.ca:43461)(invalid=bad)(invalid=bad)'
6/24 08:45:41 [18272] GAHP -> 'S'
6/24 08:45:42 [18272] GAHP <- 'RESULTS'
6/24 08:45:42 [18272] GAHP -> 'S' '1'
6/24 08:45:42 [18272] GAHP -> '67' '94' '0' '4'
6/24 08:45:42 [18272] (814.0) doEvaluateState called: gmState  
GM_STDIO_UPDATE, globusState 4
6/24 08:45:42 [18272] (814.0) gm state change: GM_STDIO_UPDATE ->  
GM_SUBMITTED
6/24 08:45:42 [18272] (814.0) gm state change: GM_SUBMITTED -> GM_FAILED
6/24 08:45:42 [18272] (814.0) gm state change: GM_FAILED -> GM_RESTART

I would have sent whole log files, but the problem only appears when  
multiple jobs are run at once, so log files get quite big and they  
exceeded the maximum size allowed for posting to this list.  Let me know  
if it would help to have them and I'll send them offline.

-Lila Klektau