Project

General

Profile

その他問い合わせ #3550

[ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [1181758], message [ZBX_TCP_READ() failed: [4] Interrupted system call]について

Added by Anonymous 11 months ago. Updated 9 months ago.

Status:
回答中
Priority:
通常
Assignee:
-
Start date:
11/06/2020

Description

お世話になっております。
11/02 16時にジョブエラーを確認いたしました。ジョブ自体は終了している模様ですがエラーが出ております。
発生原因について教えていただけますでしょうか。

43697:20201102:160046.810 [ERROR] In ja_tcp_recv_to() message: ZBX_TCP_READ() failed: [4] Interrupted system call
43695:20201102:160046.811 [ERROR] In ja_tcp_recv_to() message: ZBX_TCP_READ() failed: [4] Interrupted system call
43693:20201102:160046.811 [ERROR] In ja_tcp_recv_to() message: ZBX_TCP_READ() failed: [4] Interrupted system call
43699:20201102:160046.827 [ERROR] In ja_tcp_recv_to() message: ZBX_TCP_READ() failed: [4] Interrupted system call
43701:20201102:160046.827 [ERROR] In ja_tcp_recv_to() message: ZBX_TCP_READ() failed: [4] Interrupted system call
43703:20201102:160046.833 [ERROR] In ja_tcp_recv_to() message: ZBX_TCP_READ() failed: [4] Interrupted system call
43701:20201102:160046.839 [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [1239343], message [ZBX_TCP_READ() failed: [4] Interrupted system call]
43703:20201102:160046.839 [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [1239350], message [ZBX_TCP_READ() failed: [4] Interrupted system call]
43693:20201102:160046.840 [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [1239297], message [ZBX_TCP_READ() failed: [4] Interrupted system call]
43695:20201102:160046.840 [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [1239310], message [ZBX_TCP_READ() failed: [4] Interrupted system call]
43699:20201102:160046.841 [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [1239330], message [ZBX_TCP_READ() failed: [4] Interrupted system call]
43697:20201102:160046.842 [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [1239319], message [ZBX_TCP_READ() failed: [4] Interrupted system call]

Files

jobarranger.zip (946 KB) jobarranger.zip Anonymous, 11/06/2020 03:29 PM

Updated by Anonymous 10 months ago

たまに来る人です。

agentのリソースが足りない見たいです。
the database is busy.多発されています。

ご確認お願い致します。
以上です。

Updated by Anonymous 10 months ago

匿名のユーザ様、ご回答ありがとうございます。
確認をしてみます。

Updated by Anonymous 10 months ago

リソース値の設定等はどちらを確認すればいいでしょうか。
確認してみましたが、そういったパラーメータは見当たらなかったので。

Updated by Anonymous 10 months ago

agent logにはなんと書いてありますか?

以上です。

Updated by Anonymous 10 months ago

下記のメッセージが確認できました。該当時間中のサーバはCPU利用率の高い時間ではありましたが、張り付かない程度の状態でした。
88954:20201102:160030.018 [WARN] the database is busy.
88953:20201102:160042.636 [WARN] the database is busy.

88953:20201102:160132.034 [ERROR] job response message: the job is not running. inner_job_id: 1239310
88953:20201102:160133.430 [ERROR] job response message: the job is not running. inner_job_id: 1239319
88953:20201102:160130.691 [ERROR] job response message: the job is not running. inner_job_id: 1239297
88953:20201102:160134.663 [ERROR] job response message: the job is not running. inner_job_id: 1239343
88953:20201102:160139.595 [ERROR] job response message: the job is not running. inner_job_id: 1239330
88953:20201102:160140.723 [ERROR] job response message: the job is not running. inner_job_id: 1239350

Updated by 保守サポート 担当 9 months ago

ジョブアレンジャーのご利用ありがとうございます。

頂いたログの解析結果、問題の発生理由(推定)をお知らせいたします。

Server.logの★[JARUNICONJOB200012] Cannot send dataは、Agentがジョブ終了後にその終了通知電文をServer側に送り、
Serverがその通知に対し返信電文を送れない”Cannot send data”と言っているものです。

エラーが [ZBX_TCP_READ() failed: [4] Interrupted system call] であることから、何らかの理由でAgentサーバで問題が起きていた、と推定します。
[ZBX_TCP_READ() failed: ... はJobArranger AgentとServer間の通信で何らかの問題があったときに時に出るエラーです。
「何らかの問題」は、環境、タイミングによると考えられこの情報だけでは特定は困難ですなのですが、
過去の事例より、今回のケースはAgentサーバが反応できない、固まっていたというケースが疑われます。

理由は、Server.log のCannot send dataエラーに出ている6つのinner_jobid は全てAgent.logにありますので、同じAgentで実行されております。
つまりこれらのjob は全て同じAgentで一斉に実行されたものです。
11/02の16時過ぎの"command, status: BEGIN"の行は30件ありました。"command, status: BEGIN"の行はAgentのジョブ実行開始を意味します。
つまり同じAgentで16時過ぎに多数のジョブが一斉に実行されています。
これが「Agentサーバが反応できない、固まっていた」という状況を引き起こしていたと推定します。

Serverが最後に"the job is not running"と言っているのは、Agentの再送応答に対し既にそのジョブはServer側では終了している為に言っているものです。

普段は問題なくとも、ジョブの実行内容はデータ量などにより負荷は日々違っていることは考えられますので、稀におきる問題になりえます。

対策としてはジョブの集中を分散する、サーバの性能/チューニングで対応する等が考えられます。
※性能/チューニング事項は本QAの対象外となります。

以下は job_id: 1239343 に絞ってServer,Agentログを抽出したものです。
問題解析のログの読み方の例としてご活用下さい。

Server.log
  43701:20201102:160046.827 [ERROR] In ja_tcp_recv_to() message: ZBX_TCP_READ() failed: [4] Interrupted system call
★43701:20201102:160046.839 [ERROR] [JARUNICONJOB200012] Cannot send data:inner_jobid [1239343], message [ZBX_TCP_READ() failed: [4] Interrupted system call]
  43701:20201102:160047.056 [INFO] [JAJOBNETRUN000001] In ja_set_runerr() job execution error. inner_job_id: 1239343 status is RUNERR jobnet_id: p_sqr_cif_n64, job_id: p_sqr_cif_n64/JOB-1, user_name: P_SQUARE, job_exit_cd: , icon_status: 2
  15406:20201102:160134.657 [ERROR] In jatrap_jobresult() error: the job is not running. inner_job_id: 1239343
Agent.log
●今回のエラー発生 jobid: 1239343, 
  88954:20201102:160105.227 [INFO] In ja_agent_begin() jobid: 1239343, method: 0
  88954:20201102:160106.164 [WARN] In ja_jobdb_get_status() can not find jobid: 1239343
  88954:20201102:160106.453 [INFO] In ja_jobdb_insert() jobid: 1239343 is created
  88954:20201102:160109.263 [INFO] jobid: 1239343, method: 0 is begin
  88953:20201102:160124.884 [INFO] In ja_job_object_list_executive () jobid: 1239343, type: command, status: BEGIN
  88953:20201102:160124.884 [INFO] jobid: 1239343, status: 0
  88953:20201102:160134.615 [INFO] In ja_job_object_list_executive() jobid: 1239343, status: END 
  88953:20201102:160134.653 [INFO] In ja_agent_close() jobid: 1239343, status: 2

  88953:20201102:160134.663 [ERROR] job response message: the job is not running. inner_job_id: 1239343
  88953:20201102:160134.787 [INFO] In ja_job_object_list_executive() jobid: 1239343,  status: CLOSE

●正常例 jobid: 1239273, 
  88954:20201102:160028.566 [INFO] In ja_agent_begin() jobid: 1239273, method: 0
  88954:20201102:160031.018 [WARN] In ja_jobdb_get_status() can not find jobid: 1239273
  88954:20201102:160032.339 [INFO] In ja_jobdb_insert() jobid: 1239273 is created
  88954:20201102:160038.077 [INFO] jobid: 1239273, method: 0 is begin
  88953:20201102:160057.426 [INFO] In ja_job_object_list_executive () jobid: 1239273, type: command, status: BEGIN
  88953:20201102:160057.913 [INFO] jobid: 1239273, status: 0
  88953:20201102:160121.690 [INFO] In ja_job_object_list_executive() jobid: 1239273, status: END
  88953:20201102:160121.723 [INFO] In ja_agent_close() jobid: 1239273, status: 2
  88953:20201102:160122.046 [INFO] In ja_job_object_list_executive() jobid: 1239273, status: CLOSE

お問合せはご契約ユーザ様を最優先で対応しております。
本一般QAサイトでの回答は、かなり遅くなることがございます。
速やかな返信・対応のためにサポート契約をご検討頂ければ幸甚です。
宜しくお願い致します。

#7

Updated by 保守サポート 担当 9 months ago

  • Status changed from 新規登録 to 回答中

Updated by Anonymous 9 months ago

ご回答ありがとうございます。
ご教示いただいた内容についても参考にさせていただきます。

Also available in: Atom PDF