操作問い合わせ #3803
未完了JOB開始前の ja_chk_job_begin() による異常判定について
説明
サポートご担当者様
お世話になっております。
以下質問させていただきたく、何卒ご回答の程、よろしくお願いいたします。
■事象
JobArranger内のジョブネット実行時、該当JOBにおいてja_agent_begin()が完了する前にja_chk_job_begin()が実行され、
結果的に該当JOBについてserver側で異常判定となってしまう事象が発生しております。
※別途JOBで定義してる処理は遅れて実行される
・対象JOBのagentログ
7152:20260319:013811.148 [INFO] In ja_chk_job_begin(), job status check starts. jobid : 172404074
7152:20260319:013811.149 [INFO] In ja_chk_job_begin(), running job does not exists. jobid :172404074
7152:20260319:013811.149 [INFO] In ja_chk_job_begin(),job check finished. jobid: 172404074
13774:20260319:013811.295 [INFO] In ja_agent_send(), job id :172404074 sent OK, job result sent to server IP 10.94.32.26,
13774:20260319:013811.295 [INFO] In ja_agent_close() jobid: 172404074 closed OK, status: -1, server ip : 10.94.32.26
13774:20260319:013811.295 [INFO] In ja_jobfile_remove(),job id :172404074's all data have been archived in close-folder.
7665:20260319:013813.092 [INFO] In ja_agent_begin(),jobid: 172404074, method: 0 is begin
13774:20260319:013814.370 [INFO] In ja_job_check_beginfile(),job id :172404074[172404074-20260319013813.job] is found, and will be starting.
13774:20260319:013814.370 [INFO] In ja_agent_run(),jobid: 172404074 process started.Status: 0
13774:20260319:013814.371 [INFO] In ja_job_check_beginfile(),job id :172404074[172404074-20260319013813.job] started and deleted begin file.
13774:20260319:013829.408 [INFO] In ja_job_exec_end(), job id : 172404074,total files read :7, process id : 8020 finished.
13774:20260319:013829.424 [WARN] job response message: the job is not running. inner_job_id: 172404074, Server IP 10.94.32.26
13774:20260319:013829.424 [INFO] In ja_agent_send(), job id :172404074 sent OK, job result sent to server IP 10.94.32.26,
13774:20260319:013829.424 [INFO] In ja_agent_close() jobid: 172404074 closed OK, status: 2, server ip : 10.94.32.26
13774:20260319:013829.425 [INFO] In ja_jobfile_remove(),job id :172404074's all data have been archived in close-folder.
13779:20260319:090110.267 [INFO] In ja_datafile_remove_oldjob() deleted [172404074_10-94-32-26.job] job file.
■気になる点
・対象JOBと同時間(01時38分)にスケジューリングされたJOBNETのJOBにおけるja_agent_begin()抜粋
30578:20260319:013608.674 [INFO] In ja_agent_begin(),jobid: 172403546, method: 0 is begin
30580:20260319:013608.686 [INFO] In ja_agent_begin(),jobid: 172403562, method: 0 is begin
30582:20260319:013608.700 [INFO] In ja_agent_begin(),jobid: 172403578, method: 0 is begin
30584:20260319:013608.709 [INFO] In ja_agent_begin(),jobid: 172403594, method: 0 is begin
30586:20260319:013608.722 [INFO] In ja_agent_begin(),jobid: 172403610, method: 0 is begin
30588:20260319:013608.741 [INFO] In ja_agent_begin(),jobid: 172403634, method: 0 is begin
30590:20260319:013608.761 [INFO] In ja_agent_begin(),jobid: 172403658, method: 0 is begin
30592:20260319:013608.770 [INFO] In ja_agent_begin(),jobid: 172403674, method: 0 is begin
30594:20260319:013608.791 [INFO] In ja_agent_begin(),jobid: 172403698, method: 0 is begin
30596:20260319:013608.795 [INFO] In ja_agent_begin(),jobid: 172403706, method: 0 is begin
30598:20260319:013608.803 [INFO] In ja_agent_begin(),jobid: 172403722, method: 0 is begin
30600:20260319:013608.817 [INFO] In ja_agent_begin(),jobid: 172403738, method: 0 is begin
30603:20260319:013608.828 [INFO] In ja_agent_begin(),jobid: 172403754, method: 0 is begin
30605:20260319:013608.847 [INFO] In ja_agent_begin(),jobid: 172403778, method: 0 is begin
30607:20260319:013608.853 [INFO] In ja_agent_begin(),jobid: 172403786, method: 0 is begin
30609:20260319:013608.871 [INFO] In ja_agent_begin(),jobid: 172403874, method: 0 is begin
30611:20260319:013608.877 [INFO] In ja_agent_begin(),jobid: 172403938, method: 0 is begin
30613:20260319:013608.894 [INFO] In ja_agent_begin(),jobid: 172403514, method: 0 is begin
30615:20260319:013608.904 [INFO] In ja_agent_begin(),jobid: 172403530, method: 0 is begin
30617:20260319:013608.922 [INFO] In ja_agent_begin(),jobid: 172403498, method: 0 is begin
30619:20260319:013608.939 [INFO] In ja_agent_begin(),jobid: 172403818, method: 0 is begin
30621:20260319:013608.956 [INFO] In ja_agent_begin(),jobid: 172403842, method: 0 is begin
30623:20260319:013608.968 [INFO] In ja_agent_begin(),jobid: 172403858, method: 0 is begin
30625:20260319:013608.980 [INFO] In ja_agent_begin(),jobid: 172403890, method: 0 is begin
30627:20260319:013609.004 [INFO] In ja_agent_begin(),jobid: 172403922, method: 0 is begin
1307:20260319:013616.072 [INFO] In ja_agent_begin(),jobid: 172403802, method: 0 is begin
1335:20260319:013616.215 [INFO] In ja_agent_begin(),jobid: 172403906, method: 0 is begin
上記ログのように一部のJOBのみja_agent_begin()が出力されるタイミングが数秒遅れるJOBがあります（別の時間帯でも発生）
その状況が発生した際に、あいだの時間帯にja_chk_job_begin()が実施された場合に本異常が発生します。
ja_chk_job_begin()の実施タイミングがよくわからず法則がわからない状態です。
■質問事項
本事象に関する仕様・原因や設定による回避策があれば、ご教示頂けますでしょうか。
■環境情報
・Job Arranger バージョン：6.0.9
・server：jobarranger-server-postgresql-6.0.9-1.el8.x86_64
・agent：jobarranger-agentd-6.0.9-1.el7.x86_64
匿名ユーザー さんが約2ヶ月前に更新
■気になる点
最初の投稿で上記に記載したログは別の時間帯(01時36分)で特にエラーが発生しなかったときのものでした。
改めて01時38分のja_agent_begin()抜粋ログについて記載いたします。
4646:20260319:013805.812 [INFO] In ja_agent_begin(),jobid: 172404130, method: 0 is begin
4648:20260319:013805.829 [INFO] In ja_agent_begin(),jobid: 172404266, method: 0 is begin
4650:20260319:013805.835 [INFO] In ja_agent_begin(),jobid: 172404322, method: 0 is begin
4652:20260319:013805.855 [INFO] In ja_agent_begin(),jobid: 172403970, method: 0 is begin
4654:20260319:013805.866 [INFO] In ja_agent_begin(),jobid: 172403986, method: 0 is begin
4656:20260319:013805.879 [INFO] In ja_agent_begin(),jobid: 172404002, method: 0 is begin
4658:20260319:013805.892 [INFO] In ja_agent_begin(),jobid: 172403954, method: 0 is begin
4660:20260319:013805.897 [INFO] In ja_agent_begin(),jobid: 172404018, method: 0 is begin
4662:20260319:013805.917 [INFO] In ja_agent_begin(),jobid: 172404042, method: 0 is begin
4664:20260319:013805.924 [INFO] In ja_agent_begin(),jobid: 172404050, method: 0 is begin
4666:20260319:013805.961 [INFO] In ja_agent_begin(),jobid: 172404098, method: 0 is begin
4668:20260319:013805.967 [INFO] In ja_agent_begin(),jobid: 172404106, method: 0 is begin
4670:20260319:013805.975 [INFO] In ja_agent_begin(),jobid: 172404114, method: 0 is begin
4672:20260319:013805.988 [INFO] In ja_agent_begin(),jobid: 172404146, method: 0 is begin
4674:20260319:013806.014 [INFO] In ja_agent_begin(),jobid: 172404178, method: 0 is begin
4676:20260319:013806.021 [INFO] In ja_agent_begin(),jobid: 172404186, method: 0 is begin
4678:20260319:013806.027 [INFO] In ja_agent_begin(),jobid: 172404202, method: 0 is begin
4680:20260319:013806.039 [INFO] In ja_agent_begin(),jobid: 172404218, method: 0 is begin
4682:20260319:013806.052 [INFO] In ja_agent_begin(),jobid: 172404234, method: 0 is begin
4684:20260319:013806.064 [INFO] In ja_agent_begin(),jobid: 172404250, method: 0 is begin
4686:20260319:013806.076 [INFO] In ja_agent_begin(),jobid: 172404282, method: 0 is begin
4688:20260319:013806.088 [INFO] In ja_agent_begin(),jobid: 172404298, method: 0 is begin
4691:20260319:013806.101 [INFO] In ja_agent_begin(),jobid: 172404314, method: 0 is begin
7665:20260319:013813.092 [INFO] In ja_agent_begin(),jobid: 172404074, method: 0 is begin
7679:20260319:013813.126 [INFO] In ja_agent_begin(),jobid: 172404162, method: 0 is begin保守サポート 担当362 さんが約2ヶ月前に更新
- ステータス を 担当者処理中 から 回答中 に変更
- 担当者 を 保守サポート 担当360 から 保守サポート 担当362 に変更
本事象に関する仕様・原因や設定による回避策があれば、ご教示頂けますでしょうか。
7152:20260319:013811.148 [INFO] In ja_chk_job_begin(), job status check starts. jobid : 172404074 7152:20260319:013811.149 [INFO] In ja_chk_job_begin(), running job does not exists. jobid :172404074 7152:20260319:013811.149 [INFO] In ja_chk_job_begin(),job check finished. jobid: 172404074 13774:20260319:013811.295 [INFO] In ja_agent_send(), job id :172404074 sent OK, job result sent to server IP 10.94.32.26, 13774:20260319:013811.295 [INFO] In ja_agent_close() jobid: 172404074 closed OK, status: -1, server ip : 10.94.32.26 13774:20260319:013811.295 [INFO] In ja_jobfile_remove(),job id :172404074's all data have been archived in close-folder. 7665:20260319:013813.092 [INFO] In ja_agent_begin(),jobid: 172404074, method: 0 is begin 13774:20260319:013814.370 [INFO] In ja_job_check_beginfile(),job id :172404074[172404074-20260319013813.job] is found, and will be starting. 13774:20260319:013814.370 [INFO] In ja_agent_run(),jobid: 172404074 process started.Status: 0 13774:20260319:013814.371 [INFO] In ja_job_check_beginfile(),job id :172404074[172404074-20260319013813.job] started and deleted begin file. 13774:20260319:013829.408 [INFO] In ja_job_exec_end(), job id : 172404074,total files read :7, process id : 8020 finished. 13774:20260319:013829.424 [WARN] job response message: the job is not running. inner_job_id: 172404074, Server IP 10.94.32.26 13774:20260319:013829.424 [INFO] In ja_agent_send(), job id :172404074 sent OK, job result sent to server IP 10.94.32.26, 13774:20260319:013829.424 [INFO] In ja_agent_close() jobid: 172404074 closed OK, status: 2, server ip : 10.94.32.26 13774:20260319:013829.425 [INFO] In ja_jobfile_remove(),job id :172404074's all data have been archived in close-folder. 13779:20260319:090110.267 [INFO] In ja_datafile_remove_oldjob() deleted [172404074_10-94-32-26.job] job file.
ログに基づくと、本件の主な原因は「エージェントがジョブ実行要求（run request）を受信する前に、ジョブ確認要求（check job request）を受信した」ことです。
また、強制停止要求後にジョブネットのステータスが変わらなかった理由は、JAZ サーバとエージェント間でタイミングのずれが発生していたため、サーバがエージェントからジョブ結果を受信できなかったからです。
■ 原因詳細
サーバは「run」要求を送信した後に「check job」要求を送るなど、順番にリクエストを送信します。
しかし、エージェント側ではこれらのリクエストを順不同で受信してしまい、「run」より先に「check job」が届く状況が発生しました。
このタイミング不整合により、PID がない状態で遷移ファイルが作成されるという遷移ファイルエラーが発生しました。
本件は Jobarranger のバグであり、check job request と run request のタイミング不一致が原因です。
今後のバージョンで修正される予定ですが、現時点では一時的な回避策はありません。
ご不便をおかけし申し訳ございません。
匿名ユーザー さんが約2ヶ月前に更新
サポートご担当者様
お世話になっております。
ご回答ありがとうございます。
----------------------
本件は Jobarranger のバグであり、check job request と run request のタイミング不一致が原因です。
今後のバージョンで修正される予定ですが、現時点では一時的な回避策はありません。
----------------------
上記について承知いたしました。
追加で下記について確認させていただけますでしょうか。
本事象について、Ver3.2よりVer6.0.9の方が発生しやすいなどありますでしょうか。
最近3.2から6.0.9へバージョンアップしたのですが、
同じスケジュール構成(同時間に予定しているJOBNETの多重度が同じ)にも関わらず新Verになってから急に発生するようになりました。
また、本事象は同時間に予定しているJOBNETの多重度が高いと発生しやすいと推測しているのですが、
何か発生条件等が判明しておりましたら情報を頂けると助かります。
以上、宜しくお願い致します。
保守サポート 担当362 さんが約1ヶ月前に更新
- ステータス を 担当者処理中 から 回答中 に変更
本事象について、Ver3.2よりVer6.0.9の方が発生しやすいなどありますでしょうか。
Ver. 3.2 にはエージェントステータスのチェック処理が存在しないため、この問題は Ver. 6.0.9 の方が発生しやすくなっています。
また、本事象は同時間に予定しているJOBNETの多重度が高いと発生しやすいと推測しているのですが、 何か発生条件等が判明しておりましたら情報を頂けると助かります。
「ネットワークレイテンシ」とは、JobArranger エージェントとサーバ間の通信における時間的な遅延を指します。
現時点では、エージェントとサーバ間のタイミングに起因する可能性以外に、明確な根本原因は特定できていません。
この動作は複数のジョブネットにまたがって発生する可能性もあります。
これは、チェックジョブ要求と実行要求の間で不一致が発生する場合があるためです。
したがって、上述の通り、条件は「実行（run）要求の後にチェックジョブ（check job）要求が送られる場合」に限られます。
本事象につきましては、根本的な解消のためにはコード修正が必要となります。
当該対応は、保守契約を締結いただいた場合に限り実施可能となります。
一方で、コミュニティサイト経由でのお問い合わせにつきましては、
バグ修正の提供を行うことができないため、誠に恐れ入りますが、
現状これ以上の対応を進めることができません。
何卒事情をご賢察のうえ、ご理解賜りますようお願い申し上げます。