その他問い合わせ #3546
closed毎日スケジュール実行されているジョブが、稀にエラーになる
Description
保守サポートご担当者様
お世話になります。
https://www.jobarranger.info/redmine/issues/3482
上記問い合わせをさせていただいた者です。
前回は、丁寧なご回答を頂きまして、誠に有難うございました。
前回と似た内容のエラーが発生し、内容をご確認頂きたい次第です。
■以下3ファイルを添付させていただきます。
・JobArrangerAgentのSQLite:jobarg_agentd.db
・JobArrangerAgentのログ:jobarg_agentd.log
・JobArrangerServerのログ:jobarg_server.log
※SQLiteにつきまして、以下のSQLで一部のデータを空更新させていただいております。
レコード自体の削除等は行っていません。
UPDATE "jobs" SET "argument" = NULL , "script" = '' , "env" = NULL , "std_out" = NULL , "std_err" = NULL;
■以下内容は、前回と同様です。
・エラー発生するジョブは、毎回異なる
・エラー発生したジョブの前後のジョブは、正常に動作している
・2台のWindowsServerでは、同時刻に同内容の処理を実行している
・エラー発生箇所のジョブでは、ジョブネットアイコンを6並列で実行しているので、2台のWindowsSereverで最大12ジョブ同時にジョブが動作する可能性がある
・zabbix監視データより、エラー発生時刻のサーバー負荷やNW負荷は平時と変わらない
■今回のエラー内容は以下です。
[2020/10/14 05:00:56] [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [851894], message [received data is null] (USER NAME=Server-Sub-Admin HOST=SUN096019073 JOBNET=IZM_2_DA1_01 JOB=IZM_2_DA1_01/2_DA2_01_05/01_05_03 INNER_JOBNET_MAIN_ID=69214)
・エラー発生したジョブネットは、以下画像の赤枠のもので、前回は赤枠右の別ジョブネットで発生していました。
・前回はエラーコード「JARUNAGENT200004」でしたが、今回は「JARUNICONJOB200012」と異なりました。
※エラーメッセージ「received data is null」は同じです。
・SQLite内に、エラー発生したjobid「851894」は存在しないようでした。
・前回ご教示頂いた、時刻待ち合わせアイコン等で、ジョブネットの実行時間をずらす対応は、未実施の状態で発生しました。
バージョン情報(前回と同じです)¶
■JobArrangerServer
・CentOS Linux release 7.7.1908
・zabbix_server:4.0.17
・Job Arranger Server v4.1.0
・PostgreSQL 12.1
■クライアント(同内容が2台)
・Windows Server 2016 Standard
・zabbix_agentd Win64 (service) (Zabbix) 4.0.17
・Job Arranger Agent Win64 (service) v4.1.0
誠に恐れ入りますが、改めてエラー原因や対策等、ログやSQLiteから調査頂けますでしょうか。
何卒、よろしくお願いいたします。
Files
Updated by Anonymous over 4 years ago
- Status changed from 新規登録 to 回答中
ジョブアレンジャーのご利用ありがとうございます。
エラーに関して状況のご説明、ログ、SQLiteDBの資料提供有難うございます。
サーバログに出ております inner_jobid [851894]は、Agentログにはありません。
同時刻帯にはjobid: 851892、851897 はAgentログに出ており、SQLiteDBのデータにもあります。
同じく同時刻帯にAgentログに以下のエラーが数件出ています。
[ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction]★
このエラーは、SQLiteが出しているエラーです。検索しますとその理由は一筋縄ではいかない模様です。
これらの状況から、サーバから送付されたジョブ実行データがAgent側でSQLiteが取込みに失敗して実行されなかったように思われます。
以下について、情報を頂けますか?
①20201014:0500時台では、3件エラーが出ていますが、問題になったジョブはこの一件だけでしょうか?
20201014:0523時台では、2件エラーがありますが、こちらはいかがですか?
それ以前にもこのAgentログでは頻発しているようですが、それら発生の時にはジョブ未実行エラーは起きていますか?
②ジョブのエラーは2台のWindowsServerで、同様に起きますか?
③また、このサーバはどういったマシンでしょうか?(AWS、VMwareなどの仮想サーバ?)
ご確認お願いいたします。
---SQLiteDBのデータ sqlite> select * from jobs where jobid = 851894; 無し sqlite> select * from jobs where jobid = 851892; 851892|1|20200310162755318|0|extjob||||0|3|268860|1602619244|1602619244||||0|0|||10.96.19.71 sqlite> select * from jobs where jobid = 851897; 851897|1|20200310162755318|0|command||||0|3|271992|1602619260|1602619263||||0|0|||10.96.19.71
---Server.log 13425:20201014:050056.604 [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [851894], message [received data is null] 13425:20201014:050056.716 [INFO] [JAJOBNETRUN000001] In ja_set_runerr() job execution error. inner_job_id: 851894 status is RUNERR jobnet_id: IZM_2_DA1_01, job_id: IZM_2_DA1_01/2_DA2_01_05/01_05_03, user_name: Server-Sub-Admin, job_exit_cd: 0, icon_status: 2 ---Agent.log 3352:20201014:050044.806 [INFO] In ja_job_object_list_executive () jobid: 851892, type: extjob, status: BEGIN 3352:20201014:050044.806 [INFO] jobid: 851892, status: 0 3352:20201014:050045.244 [INFO] In ja_job_object_list_executive() jobid: 851892, status: END 3352:20201014:050045.244 [INFO] In ja_agent_close() jobid: 851892, status: 2 3356:20201014:050046.322 [INFO] In ja_agent_begin() jobid: 851897, method: 0 3356:20201014:050046.400 [WARN] In ja_jobdb_get_status() can not find jobid: 851897 3356:20201014:050046.463 [INFO] In ja_jobdb_insert() jobid: 851897 is created 3352:20201014:050046.525 [INFO] In ja_job_object_list_executive() jobid: 851892, status: CLOSE 3352:20201014:050046.525 [INFO] In ja_job_object_list_executive () jobid: 851905, type: extjob, status: BEGIN 3352:20201014:050046.541 [INFO] jobid: 851905, status: 0 3356:20201014:050046.557 [INFO] jobid: 851897, method: 0 is begin ~~~省略 3352:20201014:050051.035 [INFO] In ja_job_object_list_executive () jobid: 851855, type: command, status: BEGIN 3352:20201014:050051.035 [INFO] jobid: 851855, status: 0 3352:20201014:050051.285 [INFO] In ja_job_object_list_executive () jobid: 851868, type: command, status: BEGIN 3352:20201014:050051.301 [INFO] jobid: 851868, status: 0 3352:20201014:050052.567 [INFO] In ja_job_object_list_executive () jobid: 851881, type: command, status: BEGIN 3352:20201014:050052.567 [INFO] jobid: 851881, status: 0 3352:20201014:050054.057 [INFO] In ja_job_object_list_executive() jobid: 851855, status: END 3352:20201014:050054.072 [INFO] In ja_agent_close() jobid: 851855, status: 2 3352:20201014:050054.400 [INFO] In ja_job_object_list_executive() jobid: 851855, status: CLOSE 3356:20201014:050055.276 [INFO] In ja_agent_begin() jobid: 851858, method: 0 3356:20201014:050055.354 [WARN] In ja_jobdb_get_status() can not find jobid: 851858 3352:20201014:050055.432 [ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction]★ 3356:20201014:050055.432 [INFO] In ja_jobdb_insert() jobid: 851858 is created 3356:20201014:050055.541 [INFO] jobid: 851858, method: 0 is begin 3352:20201014:050056.651 [INFO] In ja_job_object_list_executive() jobid: 851868, status: END 3352:20201014:050056.651 [INFO] In ja_agent_close() jobid: 851868, status: 2 3352:20201014:050056.982 [INFO] In ja_job_object_list_executive() jobid: 851868, status: CLOSE 3356:20201014:050057.900 [INFO] In ja_agent_begin() jobid: 851871, method: 0 3356:20201014:050057.979 [WARN] In ja_jobdb_get_status() can not find jobid: 851871 3352:20201014:050058.010 [ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction]★ 3356:20201014:050058.057 [INFO] In ja_jobdb_insert() jobid: 851871 is created 3356:20201014:050058.150 [INFO] jobid: 851871, method: 0 is begin 3352:20201014:050059.229 [INFO] In ja_job_object_list_executive() jobid: 851881, status: END 3352:20201014:050059.229 [INFO] In ja_agent_close() jobid: 851881, status: 2 3352:20201014:050059.557 [INFO] In ja_job_object_list_executive() jobid: 851881, status: CLOSE 3356:20201014:050059.823 [INFO] In ja_agent_begin() jobid: 851884, method: 0 3356:20201014:050059.901 [WARN] In ja_jobdb_get_status() can not find jobid: 851884 3356:20201014:050059.979 [INFO] In ja_jobdb_insert() jobid: 851884 is created
---Agent.log [cannot start a transaction within a transaction] 抜粋 3356:20201013:120015.275 [ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction] ~~~省略 3352:20201014:050037.582 [ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction] 3352:20201014:050055.432 [ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction] 3352:20201014:050058.010 [ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction] 3352:20201014:052307.356 [ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction] 3352:20201014:052313.958 [ERROR] query failed: [BEGIN IMMEDIATE;] error [cannot start a transaction within a transaction]
弊社ではご契約ユーザ様向け回答を最優先で実施しております。
速やかな返信のためにサポート契約をご検討頂ければ幸甚です。
宜しくお願い致します。
Updated by Anonymous over 4 years ago
保守サポートご担当者様
お世話になります。ご回答頂きまして誠に有難うございます。
質問に返答させていただきます。
①20201014:0500時台では、3件エラーが出ていますが、問題になったジョブはこの一件だけでしょうか?
20201014:0523時台では、2件エラーがありますが、こちらはいかがですか?
それ以前にもこのAgentログでは頻発しているようですが、それら発生の時にはジョブ未実行エラーは起きていますか?
問題になったジョブは、問い合わせさせていただきました一件のみです。
0523時台の2件のエラー時も、ジョブのエラーは発生していません。
また同様の[cannot start a transaction within a transaction]のエラーは、本日時点でも頻発していますが、ジョブのエラーは発生しておりません。
②ジョブのエラーは2台のWindowsServerで、同様に起きますか?
同構成の2台のWindowsServerで、現時点では片方の1台でのみ発生しております。
③また、このサーバはどういったマシンでしょうか?(AWS、VMwareなどの仮想サーバ?)
オンプレサーバーであり、クラウドや仮想サーバーではありません。
以上、お手数をおかけしますが、改めてご確認をおねがいいたします。
何卒、よろしくお願いいたします。
Updated by Anonymous over 4 years ago
質問へのご返答、有難うございました。
SQLiteエラーが関係してAgent側でSQLiteが取込みに失敗して実行されなかったかと思いましたが、
①の回答からは、同じSQLiteエラーでも問題ないケースの方が多いということですね。
Agentサーバへのデータ伝達そのものがうまく行っていない可能性もあります。
サーバログに出ておりますCannot send data は、JAZサーバ-->Agentにjobの実行データを正常に送れていない状況で出るメッセージです。
[received data is null]が続いている場合はAgentからのレスポンスがないことを意味しています。
ですのでAgentがデータを受け取って返せないのか、受け取れていないのかの両方の可能性があります。
②で回答いただきました通り、同構成の2台のWindowsServerで片方の1台でのみ発生していること、
また発生している一台でも必ず起きるわけではなく、稀な発生であること、
これら状況を鑑みますと、JobArrangerの問題ではなくこれは環境的な問題、一時的・瞬間的な高負荷等(これは通信状況も含みます)により、Agentがサーバから送られる実行データに反応できない状況が発生している、と考えるのが妥当かと思います。
当該エージェントの状況を詳細に取得し、発生時点で何かのプロセス、通信その他はないか追及すると何かわかるかもしれません。
Windowsの実行プロセスがなにかそのタイミングで動いているとか、そういった詳細です。
また、原因が不明な中での回避策としては以前も上げましたが、実行タイミングをずらし、同一Agentでの同時ジョブ実行を減らすことは一案です。
弊社ではかなりの多数ジョブ同時実行でも問題ないことは確認しておりますが、環境その他諸条件が異なりますのでその「多数」レベルを同列に考えることは難しく。
単純にサーバを変える、スペックをあげることで起きなくなることも考えられます。
尚、弊社では「標準保守サポートサービス」の他、別途チューニングに関するサポートのご相談も可能です。
サポート契約をご検討頂ければ幸甚です。
宜しくお願い致します。