Hi Frederic,
Indeed, it sounds like the same thing I noticed and reported here a long time ago:
https://lists.infn.it/sympa/arc/cream-discuss/2011-09/msg00000.html
https://lists.infn.it/sympa/arc/cream-discuss/2011-09/msg00001.html
It happens often and is annoying. It sounds like there has been no update on the relevant CREAM issue, but an alternative would be if pilot
factories (or whatever other clients) do not request purging, or just employ a delay before requesting a purge of the job data, as Massimo
suggested. That would be very nice but I'm not sure how to make it happen. Maybe someone familiar with APF pilot factories can comment.
Thanks,
-rt
Ryan Taylor
Grid & Cloud Computing Specialist
Data Centre Services, University Systems
University of Victoria
On 04/03/2014 09:33 AM, SCHAER Frederic wrote:
> Hi,
>
> This is weird.
>
> We occasionnally (and even often) see pbs_mom copy errors, and usually this we think this is because jobs were held too long, deleted by users
> or whatever.
>
> But I just cought this one that I hardly understand : it’s as the CREAM CE (EMI3) was removing/purging the sandboxes too quickly, even before
> the pbs_mom could have time to recopy sandboxes.
>
> Off course, I checked the time on the nodes, they are all in sync.
>
> These are the logs of the CREAM CE for one job :
>
> 03 Apr 2014 17:29:54,822 org.glite.ce.creamapi.jobmanagement.cmdexecutor.AbstractJobExecutor - JOB CREAM808031582 STATUS CHANGED: RUNNING =>
> REALLY-RUNNING [localUser=atlpilot012] [workerNode=wn238.datagrid.cea.fr] [delegationId=1396248411.47070]
>
> 03 Apr 2014 17:35:04,551 org.glite.ce.creamapi.jobmanagement.cmdexecutor.AbstractJobExecutor - JOB CREAM808031582 STATUS CHANGED: REALLY-RUNNING
> => DONE-OK [failureReason=reason=0] [exitCode=0] [localUser=atlpilot012] [workerNode=wn238.datagrid.cea.fr] [delegationId=1396248411.47070]
>
> 03 Apr 2014 17:35:16,346 org.glite.ce.cream.cmdmanagement.CommandManager - new command [NAME="JOB_PURGE"; PRIORITY_LEVEL=2;
> IS_ASYNCHRONOUS=true; STATUS=ACCEPTED; CATEGORY="JOB_MANAGEMENT"; EXECUTOR_NAME="BLAHExecutor";
> USER_ID="CN_Robot__ATLAS_Fr_Factory_1_CN_445173_CN_atlasfr1_OU_Users_OU_Organic_Units_DC_cern_DC_ch_atlas_Role_pilot_Capability_NULL";
> CREATION_TIME="Thu Apr 03 17:35:16 CEST 2014"; JOB_ID_LIST={ CREAM808031582; CREAM054894612; CREAM527577702 }; PRIORITY_LEVEL="0";
> EXECUTION_MODE="S"; IS_ADMIN="false"; REMOTE_REQUEST_ADDRESS="134.158.108.56"; LOCAL_USER="atlpilot012"; USER_DN="CN=Robot: ATLAS Fr Factory
> 1,CN=445173,CN=atlasfr1,OU=Users,OU=Organic Units,DC=cern,DC=ch"; USER_FQAN={ /atlas/Role=pilot/Capability=NULL;
> /atlas/Role=NULL/Capability=NULL; /atlas/fr/Role=NULL/Capability=NULL; /atlas/lcg1/Role=NULL/Capability=NULL;
> /atlas/team/Role=NULL/Capability=NULL }; LOCAL_USER_GROUP="atlpilot"]
>
> 03 Apr 2014 17:35:17,081 org.glite.ce.cream.cmdmanagement.CommandManager - new command [ID=10819199; NAME="JOB_PURGE"; PRIORITY_LEVEL=0;
> IS_ASYNCHRONOUS=true; STATUS=EXECUTING; CATEGORY="JOB_MANAGEMENT"; EXECUTOR_NAME="BLAHExecutor";
> USER_ID="CN_Robot__ATLAS_Fr_Factory_1_CN_445173_CN_atlasfr1_OU_Users_OU_Organic_Units_DC_cern_DC_ch_atlas_Role_pilot_Capability_NULL";
> CREATION_TIME="Thu Apr 03 17:35:16 CEST 2014"; START_PROCESSING_TIME="Thu Apr 03 17:35:17 CEST 2014"; JOB_ID="CREAM808031582";
> PRIORITY_LEVEL="0"; EXECUTION_MODE="S"; IS_ADMIN="false"; REMOTE_REQUEST_ADDRESS="134.158.108.56"; LOCAL_USER="atlpilot012"; USER_DN="CN=Robot:
> ATLAS Fr Factory 1,CN=445173,CN=atlasfr1,OU=Users,OU=Organic Units,DC=cern,DC=ch"; LOCAL_USER_GROUP="atlpilot"; USER_FQAN={
> /atlas/Role=pilot/Capability=NULL; /atlas/Role=NULL/Capability=NULL; /atlas/fr/Role=NULL/Capability=NULL; /atlas/lcg1/Role=NULL/Capability=NULL;
> /atlas/team/Role=NULL/Capability=NULL }]
>
> 03 Apr 2014 17:35:18,200 org.glite.ce.cream.jobmanagement.db.table.JobTable - Job deleted. JobId = CREAM808031582
>
> 03 Apr 2014 17:35:18,202 org.glite.ce.creamapi.jobmanagement.cmdexecutor.AbstractJobExecutor - purge: purged job CREAM808031582
>
> 03 Apr 2014 17:36:30,732 org.glite.ce.creamapi.jobmanagement.cmdexecutor.AbstractJobExecutor - job CREAM808031582 not found!
>
> So, for the CREAM, job is done at à 17:35:04, and same for the torque – well, the torque thinks it’s one second later, but the cream cannot
> notice that before the torque, since it’s wtching the logs.
>
> [root@node07 ~]# grep -r 3960377 /var/lib/torque/server_priv/accounting/201404*
>
> /var/lib/torque/server_priv/accounting/20140403:04/03/2014 17:25:58;Q;3960377.node07.datagrid.cea.fr;queue=atlasana
>
> /var/lib/torque/server_priv/accounting/20140403:04/03/2014 17:29:44;S;3960377.node07.datagrid.cea.fr;user=atlpilot012 group=atlpilot
> account=t2atlasanaysis jobname=cream_808031582 queue=atlasana ctime=1396538758 qtime=1396538758 etime=1396538758 start=1396538984
> [log in to unmask] exec_host=wn238.datagrid.cea.fr/23 Resource_List.pcput=48:00:00 Resource_List.pvmem=4096mb
> Resource_List.vmem=6500mb Resource_List.walltime=72:00:00
>
> /var/lib/torque/server_priv/accounting/20140403:04/03/2014 17:35:05;E;3960377.node07.datagrid.cea.fr;user=atlpilot012 group=atlpilot
> account=t2atlasanaysis jobname=cream_808031582 queue=atlasana ctime=1396538758 qtime=1396538758 etime=1396538758 start=1396538984
> [log in to unmask] exec_host=wn238.datagrid.cea.fr/23 Resource_List.pcput=48:00:00 Resource_List.pvmem=4096mb
> Resource_List.vmem=6500mb Resource_List.walltime=72:00:00 session=13169 end=1396539305 Exit_status=0 resources_used.cput=00:00:33
> resources_used.mem=89784kb resources_used.vmem=708400kb resources_used.walltime=00:05:21
>
> But on the WN, It looks like the pbs_mom fails recopying files **after** the sandboxes were purged … ???
>
> Apr 3 17:35:33 wn238 pbs_mom: LOG_ERROR::sys_copy, command '/usr/bin/scp -rpB err_cream_808031582_StandardError
> [log in to unmask]:/var/cream_sandbox/atlpilot/CN_Robot__ATLAS_Fr_Factory_1_CN_445173_CN_atlasfr1_OU_Users_OU_Organic_Units_DC_cern_DC_ch_atlas_Role_pilot_Capability_NULL_atlpilot012/80/CREAM808031582/StandardError'
> failed with status=1, giving up after 4 attempts
>
> Apr 3 17:35:33 wn238 pbs_mom: LOG_ERROR::req_cpyfile, Unable to copy file err_cream_808031582_StandardError to
> [log in to unmask]:/var/cream_sandbox/atlpilot/CN_Robot__ATLAS_Fr_Factory_1_CN_445173_CN_atlasfr1_OU_Users_OU_Organic_Units_DC_cern_DC_ch_atlas_Role_pilot_Capability_NULL_atlpilot012/80/CREAM808031582/StandardError
>
> Apr 3 17:35:33 wn238 pbs_mom: LOG_ERROR::req_cpyfile, #012#012Unable to copy file err_cream_808031582_StandardError to
> [log in to unmask]:/var/cream_sandbox/atlpilot/CN_Robot__ATLAS_Fr_Factory_1_CN_445173_CN_atlasfr1_OU_Users_OU_Organic_Units_DC_cern_DC_ch_atlas_Role_pilot_Capability_NULL_atlpilot012/80/CREAM808031582/StandardError#012***
> error from copy#012scp:
> /var/cream_sandbox/atlpilot/CN_Robot__ATLAS_Fr_Factory_1_CN_445173_CN_atlasfr1_OU_Users_OU_Organic_Units_DC_cern_DC_ch_atlas_Role_pilot_Capability_NULL_atlpilot012/80/CREAM808031582/StandardError:
> No such file or directory#012*** end error output
>
> What am I missing ?
>
> Would this mean that the job is reported as “finished” by torque, even before the output sandboxes are copied ?
>
> If so, how to work that around ?
>
> Regards
>
|