Troubleshooting guide for CREAM

1 Checks to be done after installation and configuration

1.1 Check via browser

Open your browser (where a valid certificate must be installed)

  • For CREAM EMI1 (and previous versions) on:

https://hostname-of-cream-ce:8443/ce-cream/services

  • For CREAM EMI2 (using axis2) on:

https://hostname-of-cream-ce:8443/ce-cream/services/listServices

A page with link to the CREAM WSDL should be shown

1.2 Check the CREAM log file

Check in the CREAM log file ( /var/log/cream/glite-ce-cream.log) for the following strings:

CREAM started!

(BLParserClient) Connection with BLParser (xxx) correctly established

(Replace xxx with the name of your management system: lsf or pbs)

If they are not there, it means that CREAM has not started properly

1.3 Test glexec

  • Log on the CREAM CE
  • su tomcat -
  • Consider a user proxy (e.g. /tmp/user.proxy) for a user authorized to use that CREAM CE. This proxy file must belong to tomcat.tomcat
  • Issue the following:

export GLEXEC_MODE="lcmaps_get_account"
export GLEXEC_CLIENT_CERT=/tmp/user.proxy
/usr/sbin/glexec /usr/bin/id

This should return the id of the local user mapped to that Grid user.

Please note that this test makes sense only when the CREAM CE is configured to NOT use Argus. When the CREAM CE is instead configured to use Argus, glexec is not used at all in the CREAM CE node.

1.4 Test gridftp

Try a gsiftp (e.g. using globus-url-copy or uberftp) towards that CREAM CE. E.g.:

uberftp hostname-of-cream-ce>  "ls /etc"

1.5 Check if submissions are enabled

Try the following command from a UI:

glite-ce-allowed-submission <<hostname-of-cream-ce>>:8443

It should return:

Job Submission to this CREAM CE is enabled 

1.6 Try a direct submission

Try a submission to that CE using the glite-ce-job-submit command, e.g.:

$ /bin/cat test.jdl

[
executable="/bin/sleep";
arguments="1";
]

$ glite-ce-job-submit -a -r alice16.spbu.ru:8443/cream-pbs-dteam test.jdl 
https://alice16.spbu.ru:8443/CREAM336256203

Check the status of that job, which eventually should be DONE-OK:

$ glite-ce-job-status https://alice16.spbu.ru:8443/CREAM336256203


******  JobID=[https://alice16.spbu.ru:8443/CREAM336256203]
   Status        = [DONE-OK]
   ExitCode      = [0]

1.7 Try a job cancellation

Try a submission to that CE using the glite-ce-job-submit command, and then try to cancel it (using the glite-ce-job-cancel command).

$ /bin/cat test.jdl

[
executable="/bin/sleep";
arguments="1000";
]

$ glite-ce-job-submit -a -r alice16.spbu.ru:8443/cream-pbs-dteam test.jdl 
https://alice16.spbu.ru:8443/CREAM510970530


$ glite-ce-job-cancel https://alice16.spbu.ru:8443/CREAM510970530

Check the status of that job, which eventually should be CANCELLED:

$ glite-ce-job-status https://alice16.spbu.ru:8443/CREAM510970530


******  JobID=[https://alice16.spbu.ru:8443/CREAM510970530
   Status        = [CANCELLED]
   ExitCode      = []
   Description   = [Cancelled by user]

1.8 Try a submission through the WMS

Try a submission to that CE through the WMS, i.e. using the glite-wms-job-submit command

2 Log files

In case of problems first of all check the log files. See http://wiki.italiangrid.org/twiki/bin/view/CREAM/ServiceReferenceCard#Logfile_locations_and_management for relevant information

3 Error messages

3.1 Batch system xxx not supported

Example:

$ glite-ce-job-submit -a -r cert-26.pd.infn.it:8443/cream-pbs-cream oo.jdl
2008-01-15 13:46:18,167 FATAL - MethodName=[jobRegister] Timestamp=[Tue 15
Jan 2008 13:46:18] ErrorCode=[0] Description=[system error]
FaultCause=[Batch System pbs not supported!]

This means that:

  • the batch system specified in the used CREAM CE id is not supported by that CREAM CE (this can be also because a wrong setting of the JOB_MANAGER variable, e.g. lcgpbs instead of pbs) or
  • when CREAM has been started, its BLParser was not running. In this case a error message is printed in the CREAM log file /var/log/cream/glite-ce-cream.log*) describing the problem. This message is something like:

org.glite.ce.cream.jobmanagement.cmdexecutor.blah.BLParserClient - initializeConnection: getting info about BLParser (xxx) from BLAH (retry count=yy/zz)
...
org.glite.ce.cream.jobmanagement.cmdexecutor.blah.BLParserClient - initializeConnection error: cannot get BLParser (lsf) HOST:PORT information from BLAH. Please, be sure that BLAH is properly configured and RESTART the CREAM service.

As batch system it is meant the value specified as JOB_MANAGER in the siteinfo.def. Please note that valid values are lsf, pbs and condor (and not lcgpbs, lcglsf, lcgcondor).

This value is reported in the /etc/blah.config file (attribute supported_lrms).

Suppose that you have lsf as this value.

As user tomcat from the CE node try the following:

$ /usr/bin/blahpd
$GahpVersion: 1.14.0 Mar 31 2008 INFN\ blahpd\ (poly,new_esc_format) $
BLAH_GET_HOSTPORT lsf

This should return:

S

Then type:

results

It should return something like

lsf 0 lsf/cream-35.pd.infn.it:56565

If this is the case (i.e. you are getting a value such as this one) your problem is likely the second one (i.e. the blparser was not running when tomcat was started).

For LSF, check also in the /etc/blah.config if the path of lsf.profile is correct.

3.2 The job cannot be submitted because the blparser service is not alive

Check if the BLAH blparser is running. If it is supposed to run but it is not running, check in its log file(s) ( /var/log/cream/glite-xxxparser.log for the old parser, /var/log/cream/glite-ce-bnotifier.log and /var/log/cream/glite-ce-bupdater.log for the new one) if something interesting is reported.

In case (re)start it ( /etc/init.d/glite-ce-blparser restart for the old one, /etc/init.d/glite-ce-blahparser restart for the new one) and then restart tomcat ( service tomcat5 restart)

In case your blparser node servers multiple CREAM CEs, please be sure to have followed the instructions reported at http://wiki.italiangrid.org/twiki/bin/view/CREAM/SystemAdministratorGuideForEMI1#1_4_5_1_Configuration_of_the_old

3.3 Delegation error: the proxy delegationID "xx" is not more valid!

Example:

$ glite-ce-job-submit -D de2 -r cream-02.pd.infn.it:8443/cream-lsf-cream
prren1.jdl
2008-01-28 11:27:04,859 FATAL - MethodName=[jobRegister] Timestamp=[Mon 28
Jan 2008 11:27:04] ErrorCode=[0] Description=[delegation error: the proxy delegationID "de2" is not more valid!;] FaultCause=[delegation proxy expired!]

This means that the used delegationID was found on the target CREAM CE, but it is not more valid (i.e. the proxy expired)

3.4 job id list file error: File [xxx] is not a CREAM job list file

Example:

$ glite-ce-job-status -i job_ids
2008-04-24 09:59:54,963 FATAL - File [job_ids] is not a CREAM job list file. Stop.

This means the [job_ids] file passed in the command line has not the right format

Here's an example of a file in the right format:

$ cat job_ids
##CREAMJOBS##
https://devel03.cnaf.infn.it:8443/CREAM683051516
https://devel03.cnaf.infn.it:8443/CREAM481684356
https://devel03.cnaf.infn.it:8443/CREAM333841302
https://devel03.cnaf.infn.it:8443/CREAM279829555
https://devel03.cnaf.infn.it:8443/CREAM334653961

3.5 bad UID for job execution

If your job fails with an error such as:

 ******  JobID=[https://ppsce03.pic.es:8443/CREAM880596078]
     Status        = [ABORTED]
     ExitCode      = []
     FailureReason = [BLAH error: submission command failed (exit code = 1) (stdout:) (stderr:qsub: Bad UID for job execution MSG=ruserok failed
 validating dteam017/dteam017 from ppsce03.pic.es-) N/A (jobId = CREAM880596078)]

notesthat the torque_server node has to contain the submission hosts (the CREAM CEs) in its /etc/hosts.equiv. Or in recent versions of torque consider the acl_hosts and acl_hosts_enable attributes in the Torque server configuration (see http://www.clusterresources.com/torquedocs21/a.bserverparameters.shtml#open)

3.6 org.glite.security.delegation.storage.GrDPStorageException

Example:

2009-09-10 15:48:16,082 ERROR - Received NULL fault; the error is due to
another cause:
FaultString=[org.glite.security.delegation.storage.GrDPStorageException:
Configuration error: delegation_factorynull] -
FaultCode=[SOAP-ENV:Server.userException] -
FaultSubCode=[SOAP-ENV:Server.userException] -
FaultDetail=[<ns1:hostname>vtb-generic-64.cern.ch</ns1:hostname>]

This is likely a problem with the mysql DB (e.g. mysql not accessible, problems with grants, etc.)

3.7 sudo: 0 incorrect password attempts

This means that there is an error in the sudoers file (e.g. the mapped user is not "enabled") created by yaim-cream-ce). So this is very likely a configuration problem.

3.8 Authorization error: Failed to get the local user id via glexec

This usually means an error while running glexec to get the local userid Check therefore the glexec log files (syslog or the log files defined in /etc/glexec.conf). You might also need to increase (setting to 5) the glexec/lcas/lcmaps debug levels in /etc/glexec.conf.

3.9 Cannot find grid-proxy-info

This means that the job wrapper running on the WN could not find the grid-proxy-info executable. This could be due to several reasons.The most common ones are:

  • the grid-proxy-info executable is not installed on the WN
  • the grid-proxy-info executable is not found (e.g. because it not in the path of the local account executing the job) on the WN
  • the which executable is not installed on the WN

3.10 Problem to detect the lifetime of the proxy

This means that the job wrapper running on the WN could not detect the lifetime of the proxy (using the grid-proxy-info command). This could be due to several reasons.The most common ones are:

  • the proxy for some reason was not staged on the WN
  • the grid-proxy-info executable was not found (or it was not in the path) on the WN
  • the which executable is not installed on the WN
  • in the case of CREAM configured with the shared file system and the SLURM support enabled, the shared directories may by all owned by the fake user "nobody" and not by the right users.

3.11 Cannot create the job's working directory! [failure reason = ">>> sudoers file: Alias `XYZ' already defined, line ABC <<<"]

This means that there is a syntax error in the sudoers file created by yaim-cream-ce. A likely reason if that the same VO as been enabled more than once in the siteinfo.def.

3.12 Transfer to CREAM failed due to exception: CREAM Register raised std::exception The endpoint is blacklisted

This problem can happen when submitting to CREAM through the WMS. This means that the CE was blacklisted by that WMS (in particular by the ICE component) because the connection to this CE from that WMS went in timeout (default value for timeout: 60 secs) for 3 times. The ICE blacklisting of a CREAM CE lasts for 30 minutes. In this period submissions to that CREAM CE by that WMS/ICE are not attempted and fail with this error message.

3.13 Cannot create the job's working directory! failure reason = "sudo: no tty present and no askpass program specified"

The problem happens if there are some problems with the sudoers file, which is created by yaim

3.14 User ABC not authorized for operation XYZ

This means that there was an authorization problem.

If the authorization is managed via gJAF, check first of all if the relevant VOMS role has been enabled in the grid-mapfile.

Then check if you have all the relevant .lsc files in /etc/grid-security/vomsdir/<VO> (there must be a file for each "supported" VOMS server for that VO) and if they are correct (please note that the VOMS server certificate in /etc/grid-security/vomsdir is not needed anymore and it is used only if the relevant lsc file is not foun)d.

If this was not enough, edit /etc/glite-ce-cream/log4j.properties

replacing:

log4j.logger.org.glite=info, fileout

with:

log4j.logger.org.glite=debug, fileout

and comment the following lines:

log4j.logger.org.glite.security=off
log4j.logger.org.glite.voms=off

Then restart tomcat

In glite-ce-cream.log the reason for the authorization problem should be explained

3.15 Authorization layer is not configured

This error on the client side may be caused by many different errors arising during the startup of the CREAM service. This is a list of possible reasons:

  • Argus PEP client doesn't support PKCS#8 format for the private key; this can be verified if the CREAM log appears the message
    No KeyPair object found in file /etc/grid-security/tomcat-key.pem
    
    .It is necessary to convert the format of the key to the old one (PKCS#1) with the following commands:
    openssl rsa -in /etc/grid-security/hostkey.pem -out /etc/grid-security/hostkey.pem.new
    mv /etc/grid-security/hostkey.pem.new /etc/grid-security/hostkey.pem
    chmod 400 /etc/grid-security/hostkey.pem
    
    and run the YAIM configurator.

3.16 Failed to create a delegation id for job <jobid>: reason is User <userDN> not authorized for operation <operation>

See what reported here

3.17 Cannot generate the job wrapper! the problem seems to be related to the jdl: Number mismatch for maxOutputSandboxSize = -1,000000000000000E+00"

This happens for submissions through the WMS to a CREAM CE deployed on a machine installed using a non-English ( en-US) language. This is because of different representations of decimal numbers. The workaround in this case is to uncomment the line:

LANG=en_US

in $CATALINA_HOME/conf/tomcat5.conf and then restart tomcat

3.18 Missing property local.user.id

On a CREAM-CE using Argus this means that ARGUS was not able to provide the mapping, or CREAM was not able to process it.

To check if the mapping is correctly done in Argus, look for a line like this in the Arugs PEP Server /var/log/argus/pepd/process.log:

2011-10-10 08:42:44.209Z - INFO [DFPMObligationHandler] - ACCOUNTMAP_OH: DN: CN=Valery Tschopp 9FEE5EE3,O=SWITCH,DC=slcs,DC=switch,DC=ch pFQAN: /dteam FQANs: [/dteam] mapped to POSIX account: PosixAccount{user=dteam024 group=dteam}

You might need to set the debug mode on for the obligation handler, editing /etc/argus/pepd/logging.xml adding the lines:

 
<logger name="org.glite.authz.pep.obligation.dfpmap">
<level value="DEBUG" />
</logger>

You can then restart the PEP server, but normally the logging configuration is automatically reload every 5 minutes.

3.19 InnoDB: ERROR: the age of the last checkpoint is ...

If the following error occurs (see the mysql log file: /var/log/mysqld.log)


InnoDB: ERROR: the age of the last checkpoint is , 
InnoDB: which exceeds the log group capacity .
InnoDB: If you are using big BLOB or TEXT rows,you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.

then you must resize the innodb log files.

see: http://wiki.italiangrid.org/twiki/bin/view/CREAM/SystemAdministratorGuideForEMI1#3_3_MySQL_database_How_to_resize

3.20 InnoDB: Problem with the log file sizes.

If the following error occurs (see the mysql log file: /var/log/mysqld.log):

InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
or a similar one:
InnoDB: Error: log file ./ib_logfile0 is of different size 0 5242880 bytes
InnoDB: than specified in the .cnf file 0 67108864 bytes! 

then the "innodb_log_file_size" property has been changed without moving the log files ib_log* to some place out of the the directory where the log files reside.

Follow these steps (see http://wiki.italiangrid.org/twiki/bin/view/CREAM/SystemAdministratorGuideForEMI1#3_3_MySQL_database_How_to_resize):

  • Stop the server.
    service mysqld stop
  • Move the log file sizes ib_log* to some place out of the the directory where the log files reside. Example:
    mv /var/lib/mysql/ib_logfile* /tmp
  • Start the server.
    service mysqld start
  • Check for errors in /var/log/mysqld.log file
  • Verify the correct size of the log files
    ls -lrth /var/lib/mysql/ib_logfile*

3.21 copyNewProxyToSandbox error: sudo: no tty present and no askpass program specified

This means that the sudo operation (which is used to copy the proxy to a user specific directory) failed, very likely because of an an error in the sudoers file (e.g. the relevant users are not authorized). This file is supposed to be filled by yaim.

4 Other problems

4.1 Job cancelled with description "Cancelled by CE admin"

All activities about the job are tracked on its "command history", that is a sort of recorder realized for the purpose of noting the main internal/external events (i.e. the commands) which condition the job's life cycle. So whenever CREAM receives a command for the specified job, it records the event on the related command history. Such commands could be expressly required to CREAM by the user (i.e. the owner of the job), or by the CREAM administrator which is a privileged user who can control all jobs, or by CREAM itself which sometimes must control the job in place of the user/admin (e.g. whenever the lease expires the associated jobs must be cancelled). Unfortunately the job's life cycle could be controlled externally by the batch system administrator (e.g. bkill, bstop, bresume etc) or by the batch system itself (e.g. the LRMS killed the job due to excessive memory usage) bypassing CREAM which ignores the command executed against the job and it will be aware through BLAH just about the job status change. Under this scenario, in case of job cancellation, CREAM is not able to know exactly what happened, who and why cancelled the job, and so it can just inform the user about the job cancellation with the message "Cancelled by CE admin" noted in the description field of the job status. At the present time CREAM is not able to provide further detailed information. The LRMS logs may contain some useful details for understanding who canceled the job, but this approach is batch system dependent and it needs more investigation. The hint for the user is to ask to the system administrator to investigate the cancellation reason by using the tools provided by the LRMS itself.

4.2 Dynamic information not published in the BDII

If dynamic information is not published in the resource BDII of the CREAM-CE and e.g. lcg-infosites reports 444444 as number of waiting jobs, on the CREAM CE tries to manually run the infoprovider script:

/sbin/runuser -s /bin/sh ldap -c "/var/lib/bdii/gip/plugin/glite-info-dynamic-ce" 

and check if some errors are returned.

If the information is correctly returned, check the BDII logs if some errors are reported.

4.3 High load caused by bupdater process

This can be because of a too high polling frequency when checking the status of the jobs. Follow this link for more information.

4.4 Job failure with reason=999

This can happen with the new BLAH BLparser when it is not able to detect the status of the job for more than x seconds. The default value for x is 86400. This value can be modified setting the attribute alldone_interval in /etc/blah.config, e.g.:

alldone_interval=100000

It is then necessary to restart the BLAH blparser:

/etc/init.d/glite-ce-blahparser restart 

4.5 Jobs are successfully submitted to Torque, but they stay in W status

Torque will put a job in 'W' when it cannot stage the job's input files. Check if grid accounts on your WNs can "scp" without password to the CE and/or the Torque server host.

4.6 Jobs submitted to LSF fails with errorcode 127

This is likely a problem with staging of files from/to the CE node to/from the WN. Check if the relevant LSF daemons run properly.

4.7 Jobs submitted to Torque are stuck in W status

The 'W' status means "waiting on stagein": that should never happen for grid jobs and signals a misconfiguration of the CE or the batch system. The most likely cause is explained here

5 Other troubleshooting hints

5.1 Saving the batch job submission script

If, for debugging purposes, it is necessary to save the script used by the BLAH component of CREAM to submit the job to the batch system, edit the files blah_common_submit_functions.sh and xxx_submit.sh (e.g. pbs_submit.sh) and comment all the occurrences of:

rm -f $bls_tmp_file

These scripts are in /usr/bin in EMI-1, in usr/libexec starting with EMI-2

5.2 Saving files on the worker node after job execution

For debugging purposes, it is possible to save the stdout, stderr and proxy files on the Worker Node after job execution.

This is done setting blah_debug_save_wn_files in /etc/blah.config on the CREAM CE node to an existing directory (on the WN) where the user running the job has the proper rights for writing.

A directory called XXX.debug will be created within the specified directory.

5.3 Check the queue of command/notifications still to be processed

If you want to check the queue of commands and notifications still to be processed, the mysql query command to be issued is:

  • For EMI-1:

use creamdb; select count(*), name from command group by name;

  • For EMI-2:

use creamdb; select count(*), name from command_queue group by name; 

If the CREAM CE is behaving properly, such queue should be always reasonable short.

5.4 Remove a delegationid

If for some reason you need to remove a delegation from the CREAM DB, use the following mysql commands:

use delegationdb;
delete from t_credential where dlg_id="pippo" and local_user = "pluto";

Of course replace pippo and pluto with the proper strings.

For submissions through the WMS, if a certain delegationid is removed, the ICE component of the WMS will detect it and will create a new delegation.

-- MassimoSgaravatto - 2011-04-27

Edit | Attach | PDF | History: r28 < r27 < r26 < r25 < r24 | Backlinks | Raw View | More topic actions
Topic revision: r28 - 2014-06-30 - LisaZangrando
 

This site is powered by the TWiki collaboration platformCopyright © 2008-2019 by the contributing authors. All material on this collaboration platform is the property of the contributing authors.
Ideas, requests, problems regarding TWiki? Send feedback