Project

General

Profile

操作問い合わせ #3224

メッセージ発生原因・対処方法について

Added by Anonymous about 1 month ago. Updated 17 days ago.

Status:
回答中
Priority:
急いで
Assignee:
-
Start date:
10/17/2019
Due date:
10/25/2019
% Done:

0%

Estimated time:

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

どうぞよろしくお願い致します。

jobarg_server.log (359 KB) jobarg_server.log Anonymous, 10/18/2019 06:03 PM
SQLite_command.txt (771 Bytes) SQLite_command.txt Anonymous, 10/18/2019 06:03 PM
20191023_ja_run_job_table.txt (3.15 KB) 20191023_ja_run_job_table.txt Anonymous, 10/23/2019 09:22 AM
20191023_jobarg_agentd.log (638 KB) 20191023_jobarg_agentd.log Anonymous, 10/23/2019 09:47 AM
20191023_jobarg_agentd.log.old (1020 KB) 20191023_jobarg_agentd.log.old Anonymous, 10/23/2019 09:47 AM
20191023_jobarg_server.log (510 KB) 20191023_jobarg_server.log Anonymous, 10/23/2019 09:47 AM
20191023_jobarg_server.log.old (1020 KB) 20191023_jobarg_server.log.old Anonymous, 10/23/2019 09:48 AM

History

#1 Updated by 保守サポート 担当 about 1 month 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;

速やかな返信のためにサポート契約をご検討頂ければ幸甚です。

宜しくお願い致します。

#2 Updated by Anonymous about 1 month ago

早々のご確認ありがとうございます。
インライン(⇒)にて返答致します。

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」を参照ください。

どうぞよろしくお願い致します。

#3 Updated by 保守サポート 担当 about 1 month 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があればそれも)でよろしいですので拝見できますか。

よろしくお願いいたします。

#4 Updated by Anonymous about 1 month ago

ご担当者様
ご確認ありがとうございます。

インライン(⇒)にて返答致します。

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」
  ※サーバ名の部分のみ加工しています('バッチサーバ')

どうぞよろしくお願い致します。

#5 Updated by 保守サポート 担当 29 days 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
~省略~

#6 Updated by Anonymous 26 days 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/配下のファイル削除後、これらのファイルは次のジョブ実行時に自動的に
  再度作成されるのか?
 ・何か事前にバックアップしておくファイルは無いか。

どうぞよろしくお願い致します。

#7 Updated by 保守サポート 担当 24 days ago

ご回答有難うございます。

Q.7の回答からしますと、SQLiteDB自体としては問題ないのかと思います。
Q.8は処理ジョブ数の多さも何か影響があるかと思い確認しました。

■対応策について回答します。

 ・実行中ジョブネット(ジョブフロー内で時刻待ちしている状態)が存在する状況で実施しても
  問題ないか?

このAgentサーバで実行中のジョブネットがないときに実施ください。

 ・/var/lib/jobarranger/配下のファイル削除後、これらのファイルは次のジョブ実行時に自動的に
  再度作成されるのか?

その通りです。

 ・何か事前にバックアップしておくファイルは無いか。

特にありません。
削除が気になるようでしたら、一旦削除退避しておいてください。
入れ替えれば今の状態に戻せますので。

以上よろしくお願いいたします。

#8 Updated by Anonymous 17 days ago

ご担当者様
ご確認ありがとうございます。

対応策実施後、結果をご連携させて頂きます。

どうぞよろしくお願い致します。

Also available in: Atom PDF