この文書ではPBS Professionalのserverログに出力される「Post job file processing error」
についての理解・デバックの例を説明します。
当文書では以下の4台で環境を構成している例を用いて説明します。
pbs-head: 管理サーバ pbs_server,pbs_sched,pbs_commの各デーモンが稼働
node01: 計算ノード pbs_momデーモンが稼働
node02: 計算ノード pbs_momデーモンが稼働
front-end: コマンド実行専用サーバ PBSコマンドのみをインストール
* 各サーバのホスト名とIPの紐づけは以下の通りです。
192.168.57.132 pbs-head
192.168.57.133 node01
192.168.57.137 node02
192.168.57.138 front-end
典型的な「Post job file processing error」は、計算ノードで実行したジョブの生成した
アウトプットファイルをQsub実行ホストにscpなどでコピーしようとした際、
何らかのエラーによりコピーバックできなかった場合に記録されます。
問題がない場合、以下のようにアウトプットファイル *.o<jobid>, *.e<jobid> が
qsubしたホスト・ディレクトリにコピーバックされます。
1.1.1. テストジョブを実行
[user01@front-end ~]$ cat test.sh
#!/bin/sh
sleep 10
echo "Hello PBS!"
[[user01@front-end ~]$ qsub test.sh
48.pbs-head
[user01@front-end ~]$ qstat
Job id Name User Time Use S Queue
---------------- ---------------- ---------------- -------- - -----
48.pbs-head test.sh user01 0 R workq
1.1.2. テストジョブ終了後にアウトプットファイルがqsub実行マシン・ディレクトリに
コピーバックされていることを確認します。
以下のように ジョブ名.o<jobid>, ジョブ名.e<jobid>が確認できます。
[user01@front-end ~]$ qstat
[user01@front-end ~]$ ls | grep 48
test.sh.e48
test.sh.o48
[user01@front-end ~]$ ls | grep 48 | xargs cat
Hello PBS!
当記事はPost job file processing errorを発生させデバック情報を取得する方法を例示します。
それには、リモートホストで実行したqsubがpbs serverで受け入れられジョブが実行できるこ
とが前提となりますので、ここでは、補足情報としてリモートホストで実行したqsubが
pbs_serverに受け入れられない主なケースを例示します。
1.2.1. pbs_serverデーモンがListenしているTCP 15001ポートへコマンドが到達しないケース
[user01@front-end ~]$ echo 'sleep 30' | qsub
No route to host
qsub: cannot connect to server pbs-hea (errno=15010)
上記の原因は、qsub実行ホストからpbs_serverデーモンがListenしているTCP 15001ポートへ届かないケース
が疑われます。よって、firewallでTCP 15001ポートがdropされていないこと、または、
名前解決でpbs_serverデーモン稼働ホスト-qsub実行ホスト間で矛盾がないことを確認します。
1.2.2. UID/hostが整合しないケース
[user01@front-end ~]$ echo 'sleep 30' | qsub
qsub: Bad UID for job execution
上記はqsub実行ユーザのユーザID/hostnameが実行権限をもっていないケースが疑われます。
よって、flatuidサーバ属性を有効にして、hostnameの確認を行わないように設定
(hosts.equivの確認を省略させる）。
[root@pbs-head ~]# qmgr -c 's s flatuid=true'
もしくは、/etc/hosts.equivファイルを作成、実行を許可するhostnameを記載するなどを試してください。
[root@pbs-head etc]# cat /etc/hosts.equiv
front-end
PBSが最初に使用するコピーメソッドを確認します。
以下は、scpを最初のコピーメソッドとして使用する設定例です。
コピーメソッドはジョブが実行される計算ノード上で実行され、qsub実行マシンがコピー先に
なるので計算ノード上で確認します。
* pbs_mom稼働マシン(計算ノード)の設定
[root@node01 ~]# cat /etc/pbs.conf | grep PBS_SCP
PBS_SCP=/usr/bin/scp
[root@node01 ~]# which scp
/usr/bin/scp
設定されているコピーメソッドであるscpを失敗させれば「Post job file processing error」が発生します。
本例では、意図的にfront-end(qsub実行ホスト）側で、計算ノードnode01(pbs_mom稼働ホスト/計算ノード）の
authorized_keysをコメントアウトしてscpを失敗させてみます。
2.2.1. authorized_keysのnode01(計算ノード）設定をコメントアウトする
[user01@front-end ~]$ cat ~/.ssh/authorized_keys
ssh-rsa <key省略> user01@pbs-head.localdomain
#ssh-rsa <key省略> user01@node01.localdomain
ssh-rsa <key省略> user01@node02.localdomain
2.2.2. テストジョブを実行
* コピーメソッドで指定したコピー処理（ここではscp）は数回リトライします。よって、
ジョブプロセス終了後の"Exiting"ステータス(以下では"S"列が"E"と表示）が通常より長い間表示されます。
（なお、単純にアウトプットファイル容量が大きい場合も同様に"E"が長く表示されます）
[user01@front-end ~]$ qsub test.sh
49.pbs-head
[user01@front-end ~]$ qstat
Job id Name User Time Use S Queue
---------------- ---------------- ---------------- -------- - -----
49.pbs-head test.sh user01 00:00:00 R workq
[user01@front-end ~]$
[user01@front-end ~]$ qstat
Job id Name User Time Use S Queue
---------------- ---------------- ---------------- -------- - -----
49.pbs-head test.sh user01 00:00:00 E workq
[user01@front-end ~]$ qstat
2.2.3. テストジョブ終了後にアウトプットファイルがqsub実行マシン・ディレクトリにコピーバック
されていることを確認します。
(この例では意図的に失敗させているので戻っていません。）
[user01@front-end ~]$ ls | grep 49
[user01@front-end ~]$
2.2.4. tracejobコマンドでpbs-head(pbs_server稼働マシン）のログを抜粋して「Post job file processing error」
を確認する。
* 以下出力中に「Post job file processing error」が確認できます。これが記録されている場合、
計算ノードからのコピーに失敗している場合があります。
[user01@front-end ~]$ ssh pbs-head tracejob 49
Job: 49.pbs-head
08/16/2023 18:26:43 L Considering job to run
08/16/2023 18:26:43 S Updated job state to 81 and substate to 10
08/16/2023 18:26:43 S enqueuing into workq, state Q hop 1
08/16/2023 18:26:43 S Job Queued at request of user01@front-end, owner = user01@front-end, job name = test.sh, queue = workq
08/16/2023 18:26:43 S Job Run at request of Scheduler@pbs-head on exec_vnode (node01:ncpus=1)
08/16/2023 18:26:43 L Job run
08/16/2023 18:26:43 S Updated job state to 82 and substate to 41
08/16/2023 18:26:45 S Received session ID for job: 8315
08/16/2023 18:26:45 S Updated job state to 82 and substate to 42
08/16/2023 18:26:54 S Obit received momhop:1 serverhop:1 state:R substate:42
08/16/2023 18:26:54 S Updated job state to 69 and substate to 50
08/16/2023 18:26:54 S Updated job state to 69 and substate to 51
08/16/2023 18:28:28 S Post job file processing error * ここに記録されています。
08/16/2023 18:28:28 S Updated job state to 69 and substate to 52
08/16/2023 18:28:28 S Updated job state to 69 and substate to 53
08/16/2023 18:28:28 S Obit received momhop:1 serverhop:1 state:E substate:53
08/16/2023 18:28:28 S Exit_status=0 resources_used.cpupercent=0 resources_used.cput=00:00:00 resources_used.mem=3248kb resources_used.ncpus=1 resources_used.vmem=336884kb resources_used.walltime=00:00:10
[user01@front-end ~]$
[0] 0:user01@front-end:~*
* トレースジョブはPBSデーモンログの抜粋を出力するコマンドです。
* 以下抜粋より、実行されたコマンド(scp -v -r -p -t /home/user01/test.sh.o49)
とそのコマンドのデバック情報が確認でき、Permission関連のエラーであることが分かります。
[user01@front-end ~]$ ssh node01 tracejob 49 | head -n 15
Job: 49.pbs-head
08/16/2023 18:26:43 M Started, pid = 8315
08/16/2023 18:26:53 M task 00000001 terminated
08/16/2023 18:26:53 M Terminated
08/16/2023 18:26:53 M task 00000001 cput=00:00:00
08/16/2023 18:26:53 M kill_job
08/16/2023 18:26:53 M node01 cput=00:00:00 mem=3248kb
08/16/2023 18:26:53 M Obit sent
08/16/2023 18:26:54 M copy file request received
08/16/2023 18:28:28 M Unable to copy file /var/spool/pbs/spool/49.pbs-head.OU to front-end:/home/user01/test.sh.o49
08/16/2023 18:28:28 M front-end: Connection refused
08/16/2023 18:28:28 M h host front-end, user user01, command scp -v -r -p -t /home/user01/test.sh.o49
08/16/2023 18:28:28 M OpenSSH_7.4p1, OpenSSL 1.0.2k-fips 26 Jan 2017
[user01@front-end ~]$ ssh node01 tracejob 49 | tail -n 15
08/16/2023 18:28:28 M debug1: Trying private key: /home/user01/.ssh/id_dsa
08/16/2023 18:28:28 M debug1: Trying private key: /home/user01/.ssh/id_ecdsa
08/16/2023 18:28:28 M debug1: Trying private key: /home/user01/.ssh/id_ed25519
08/16/2023 18:28:28 M debug1: No more authentication methods to try.
08/16/2023 18:28:28 M Permission denied (publickey,gssapi-keyex,gssapi-with-mic,password).
08/16/2023 18:28:28 M lost connection
08/16/2023 18:28:28 M >>> end error output
08/16/2023 18:28:28 M Output retained on that host in: /var/spool/pbs/undelivered/49.pbs-head.OU
08/16/2023 18:28:28 M ---->>>>
08/16/2023 18:28:28 M Staged 0/2 items out over 0:01:34
08/16/2023 18:28:28 M no active tasks
08/16/2023 18:28:28 M Obit sent
08/16/2023 18:28:28 M delete job request received
08/16/2023 18:28:28 M kill_job
08/16/2023 18:28:28 M delete job request received
[user01@front-end ~]$
*実際にエラーになったSCPコマンドを実行することによってより柔軟なデバックが可能になります。
[3.1]で確認したtracejobのアウトプットより以下のコピーに失敗したことが分かります。
unable to copy file /var/spool/pbs/spool/49.pbs-head.OU to front-end:/home/user01/test.sh.o49
また、実行ユーザはuser01で実行コマンドは"scp -v -r -p -t /home/user01/test.sh.o49"です。
08/16/2023 18:28:28 M h host front-end, user use01, command scp -v -r -p -t /home/user01/test.sh.o49
上記より、以下のようなSCPコマンドを直接実行することで、よりSCPに特化した情報をデバック情報として取得することも可能です。
*以下からpasswordが必要な部分でscpの処理が停止していることが分かります。
[user01@node01 ~]$ scp -v -r -p /var/spool/pbs/spool/49.pbs-head.OU front-end:/home/user01/test.sh.o49
...
...
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /home/user01/.ssh/id_rsa
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug1: Trying private key: /home/user01/.ssh/id_dsa
debug1: Trying private key: /home/user01/.ssh/id_ecdsa
debug1: Trying private key: /home/user01/.ssh/id_ed25519
debug1: Next authentication method: password
user01@front-end's password: