操作問い合わせ #3224
closedメッセージ発生原因・対処方法について
Description
メッセージ発生原因および対処方法についてご教授願います。
【検知メッセージ】 jobarg_server.logより
10/7 2:26～10/14 08:00
①825:20191007:022637.012 [ERROR] In jatrap_jobresult() error: the job is not running. inner_job_id: 2900506
10/14 12:00～
②829:20191014:120006.315 [ERROR] [JAHOST200004] In ja_host_getip() can not get the force flag and job id: inner_job_id [2900506]
③829:20191014:120006.393 [WARN] host 'バッチサーバ' does not exist. cnt0
④829:20191014:120006.393 [ERROR] In jatrap_auth_host() error: host 'バッチサーバ' is not authenticated
⑤832:20191014:120006.862 [ERROR] In message_send() failed to execute the command. command: (2) [/usr/bin/zabbix_sender -z '127.0.0.1' -p '10051' -s 'Zabbix server' -k 'jasender' -o '[2019/10/14 12:00:06] [ERROR] [JAHOST200004] In ja_host_getip() can not get the force flag and job id: inner_job_id [2900506] (USER NAME=none HOST=JAZServer JOBNET=none JOB= INNER_JOBNET_MAIN_ID=0)']
※サーバ名の部分のみ加工しています（'バッチサーバ'）
【状況】
■①のメッセージを断続的に検知した後、②～⑤のメッセージを断続的に検知する事象が発生。
※②～⑤のメッセージ検知以降は①は検知なし。
■DBの「ja_run_log_table」より、「inner_job_id: 2900506」に対応するジョブネットID・ジョブIDは判明するが、
該当ジョブネット・ジョブは正常終了しており、異常終了や実行中のまま残存するジョブネット・ジョブは存在しない。
また、他のジョブネット・ジョブの異常終了も発生していない。
■スケジュール登録している他ジョブ（12:00起動、14:00起動など）が起動または終了するタイミングでメッセージを検知し、
スケジュールジョブが実行されていない時間帯ではメッセージ検知は無い。
■メッセージに含まれるバッチサーバは、他のジョブネットからもコマンド発行しており、異常は発生していない。（疎通も問題ない）
【環境】
Jobarranger：Job Manager Version 3.4.0(Rev:7280)
DB：Server version: 5.5.56-MariaDB MariaDB Server
どうぞよろしくお願い致します。
Files
Updated by Anonymous about 5 years ago
- Status changed from 新規登録 to 回答中
ジョブアレンジャーのご利用ありがとうございます。
いくつか確認させてください。
■①のメッセージを断続的に検知した後、②～⑤のメッセージを断続的に検知する事象が発生。
※②～⑤のメッセージ検知以降は①は検知なし。
Q1.10/7に①のメッセージを断続的に検知した、というのはすべてjob_id [2900506]でのエラーでしょうか？
Q2.10/14の12:00～以降に初めて②③④⑤のエラーが発生したのでしょうか。
Q3.この②③④⑤のエラーはその後も繰り返し発生しているとのことですが
その際の②のjob_id は2900506で同じですか？
あと、以下2点を頂けますでしょうか。開示不可の項目は書き換えて頂いてOKです。
1.10/7 に①が発生した時間帯(2:26前後の関係する部分)の当該Agentサーバのagent.logとserver.log
2.当該AgentサーバのSQLiteのDBデータ
当該Agentサーバの /var/lib/jobarranger/ に行き、以下コマンドで取得の内容
# sqlite3 jobarg_agentd.db sqlite> select * from jobs where jobid = 2900506;
速やかな返信のためにサポート契約をご検討頂ければ幸甚です。
宜しくお願い致します。
Updated by Anonymous about 5 years ago
- File jobarg_server.log jobarg_server.log added
- File SQLite_command.txt SQLite_command.txt added
早々のご確認ありがとうございます。
インライン（⇒）にて返答致します。
Q1.10/7に①のメッセージを断続的に検知した、というのはすべてjob_id [2900506]でのエラーでしょうか？
⇒その通りです。
Q2.10/14の12:00～以降に初めて②③④⑤のエラーが発生したのでしょうか。
⇒その通りです。
Q3.この②③④⑤のエラーはその後も繰り返し発生しているとのことですが
その際の②のjob_id は2900506で同じですか？
⇒その通りです。
あと、以下2点を頂けますでしょうか。開示不可の項目は書き換えて頂いてOKです。
1.10/7 に①が発生した時間帯(2:26前後の関係する部分)の当該Agentサーバのagent.logとserver.log
⇒申し訳ありません。agent.logは残っておりませんでした。
server.logのみ添付します。
2.当該AgentサーバのSQLiteのDBデータ
当該Agentサーバの /var/lib/jobarranger/ に行き、以下コマンドで取得の内容
⇒「SQLite_command.txt」を参照ください。
どうぞよろしくお願い致します。
Updated by Anonymous about 5 years ago
ご回答、データの取得有難うございました。
追加で以下も訓えていただけますか。
Q4.この②③④⑤のエラーは10/14以降もいまだに発生していますか。
Q5.サーバ側のDBにて以下実行して頂けますか。
SELECT * FROM ja_run_job_table where inner_job_id = 2900506;
データはないと思われますが念のため確認したく。
Q.6 このAgentサーバで10/7以降でDiskフルの状態(Disk使用率100%)が起きていませんでしょうか？
また、agent.logですが、今現在のlog(log.oldがあればそれも)でよろしいですので拝見できますか。
よろしくお願いいたします。
Updated by Anonymous about 5 years ago
- File 20191023_ja_run_job_table.txt 20191023_ja_run_job_table.txt added
- File 20191023_jobarg_agentd.log 20191023_jobarg_agentd.log added
- File 20191023_jobarg_agentd.log.old 20191023_jobarg_agentd.log.old added
- File 20191023_jobarg_server.log 20191023_jobarg_server.log added
- File 20191023_jobarg_server.log.old 20191023_jobarg_server.log.old added
ご担当者様
ご確認ありがとうございます。
インライン（⇒）にて返答致します。
Q4.この②③④⑤のエラーは10/14以降もいまだに発生していますか。
⇒発生し続けています。
Q5.サーバ側のDBにて以下実行して頂けますか。
SELECT * FROM ja_run_job_table where inner_job_id = 2900506;
データはないと思われますが念のため確認したく。
⇒SQL実行結果を掲載致します。
!20191023_ja_run_job_table.txt!
Q.6 このAgentサーバで10/7以降でDiskフルの状態(Disk使用率100%)が起きていませんでしょうか？
⇒Zabbixで常時監視している/root、/usr、/varでは10/7以降でDISKフルは発生していません。
その他の領域も現状はDISKフル（または逼迫）の状態は発生していません。
また、agent.logですが、今現在のlog(log.oldがあればそれも)でよろしいですので拝見できますか。
⇒「20191023_jobarg_agentd.log」「20191023_jobarg_agentd.log.old」を参照願います。
また、server.logも合わせてUP致します。
「20191023_jobarg_server.log」「20191023_jobarg_server.log.old」
※サーバ名の部分のみ加工しています（'バッチサーバ'）
どうぞよろしくお願い致します。
Updated by Anonymous about 5 years ago
質問のご回答、ログの提供ありがとうございました。
状況から当該AgentサーバのSQLiteDBの状態がおかしくなっているのではないかと思われます。
頂いたログの分析情報を下部につけます。
もう2点確認させてください。
Q.7 jobid: 2900506を実行しているAgentサーバで、他のジョブは問題なく稼働していますでしょうか？
上記の回答がYesであれば、SQLiteDBそのものというより、2900506のレコードに問題があるのではないかと思います。
Q.8 当該Agentサーバログで20191023:9時台に以下のdelete処理が950件あります。
この950件のジョブは当該Agentサーバで1日に稼働したジョブ数と思いますが、そうでしょうか？
910:20191023:090000.503 [INFO] In ja_jobmain_remove_oldjob() delete jobid = 3049442 省略 910:20191023:090000.608 [INFO] In ja_jobmain_remove_oldjob() delete jobid = 3053977
対応策： 以下手順にて対応して頂けますでしょうか。
①一旦当該サーバのAgentを停止。
この時点で、念のためJobArrangerのプロセスが何も残っていないかをご確認下さい。psコマンドなどで。
②SQLiteDBのデータクリア。/var/lib/jobarranger/以下のファイルを削除(3つありますが全て)。
tmpディレクトリ以下に何かファイルが残っているようでしたらそれも全削除
③Agentを開始
結果をお知らせ頂ければ幸甚です。
宜しくお願い致します。
●通常のログ～911の行：SQLiteDBへのジョブの投入を経て、910行：SQLiteDBから取り出し実行、終了。 911:20191023:015910.712 [INFO] In ja_agent_begin() jobid: 3065895, method: 0 911:20191023:015910.713 [WARN] In ja_jobdb_get_status() can not find jobid: 3065895 911:20191023:015910.713 [INFO] In ja_jobdb_insert() jobid: 3065895 is created 911:20191023:015910.718 [INFO] jobid: 3065895, method: 0 is begin 910:20191023:015913.541 [INFO] In ja_job_object_list_executive () jobid: 3065895, type: command, status: BEGIN 910:20191023:015913.541 [INFO] jobid: 3065895, status: 0 910:20191023:020923.673 [INFO] In ja_job_object_list_executive() jobid: 3065895, status: END 910:20191023:020923.673 [INFO] In ja_agent_close() jobid: 3065895, status: 2 910:20191023:020923.707 [INFO] In ja_job_object_list_executive() jobid: 3065895, status: CLOSE ●問題の jobid: 2900506 のログ ～いきなり910行：SQLiteDBから取り出し実行 を延々と繰り返している 910:20191023:015912.521 [INFO] In ja_job_object_list_executive () jobid: 2900506, type: command, status: BEGIN 910:20191023:015912.521 [INFO] jobid: 2900506, status: 0 910:20191023:015926.712 [INFO] In ja_job_object_list_executive() jobid: 2900506, status: END 910:20191023:015926.712 [INFO] In ja_agent_close() jobid: 2900506, status: 2 910:20191023:015926.731 [INFO] In ja_job_object_list_executive() jobid: 2900506, status: CLOSE 910:20191023:020435.316 [INFO] In ja_job_object_list_executive () jobid: 2900506, type: command, status: BEGIN 910:20191023:020435.316 [INFO] jobid: 2900506, status: 0 910:20191023:020435.337 [INFO] In ja_job_object_list_executive() jobid: 2900506, status: END 910:20191023:020435.337 [INFO] In ja_agent_close() jobid: 2900506, status: 2 910:20191023:020435.363 [INFO] In ja_job_object_list_executive() jobid: 2900506, status: CLOSE ～省略～
Updated by Anonymous about 5 years ago
ご担当者様
ご確認ありがとうございます。
ご質問に対してはインライン（⇒）にて返答致します。
また、対応策について数点ご確認させてください。
Q.7 jobid: 2900506を実行しているAgentサーバで、他のジョブは問題なく稼働していますでしょうか？
⇒問題なく稼働しています。ジョブの異常終了はもちろん、実行中状態のまま遷移しないといった
現象は発生していません。
Q.8 当該Agentサーバログで20191023:9時台に以下のdelete処理が950件あります。
この950件のジョブは当該Agentサーバで1日に稼働したジョブ数と思いますが、そうでしょうか？
⇒そのとおりだと思われます。
実行結果表示からログ抽出してジョブ実行数を数えた結果が以下となりました。
・10/22 09:00～10/23 08:59の実行ジョブ数：951件
・10/23 00:00～10/23 23:59の実行ジョブ数：950件
■対応策（②SQLiteDBのデータクリア）についてのご質問
・実行中ジョブネット（ジョブフロー内で時刻待ちしている状態）が存在する状況で実施しても
問題ないか？
・/var/lib/jobarranger/配下のファイル削除後、これらのファイルは次のジョブ実行時に自動的に
再度作成されるのか？
・何か事前にバックアップしておくファイルは無いか。
どうぞよろしくお願い致します。
Updated by Anonymous about 5 years ago
ご回答有難うございます。
Q.7の回答からしますと、SQLiteDB自体としては問題ないのかと思います。
Q.8は処理ジョブ数の多さも何か影響があるかと思い確認しました。
■対応策について回答します。
・実行中ジョブネット（ジョブフロー内で時刻待ちしている状態）が存在する状況で実施しても
問題ないか？
このAgentサーバで実行中のジョブネットがないときに実施ください。
・/var/lib/jobarranger/配下のファイル削除後、これらのファイルは次のジョブ実行時に自動的に
再度作成されるのか？
その通りです。
・何か事前にバックアップしておくファイルは無いか。
特にありません。
削除が気になるようでしたら、一旦削除退避しておいてください。
入れ替えれば今の状態に戻せますので。
以上よろしくお願いいたします。
Updated by Anonymous about 5 years ago
ご担当者様
ご確認ありがとうございます。
対応策実施後、結果をご連携させて頂きます。
どうぞよろしくお願い致します。
Updated by Anonymous almost 5 years ago
ご担当者様
SQLiteDBのデータクリア実施により、エラーメッセージの発生が解消しました。
既存のスケジュールジョブ実行も問題なく行えています。
①Agent停止
②/var/lib/jobarranger/配下のファイル削除
③Agent起動
質問にご回答頂きましてありがとうございました。