プロジェクト

全般

プロフィール

その他問い合わせ #2475

完了

JobArranger3.0.0にて、ジョブを実行するとJobArrangerサーバのサービスが再起動する

匿名ユーザー さんが7年以上前に追加. 約4年前に更新.

ステータス:
終了
優先度:
高め
担当者:
-
開始日:
2017/02/28

説明

お世話になっております。

・説明
下記の環境でJobArranger2.1.1→JobArranger3.0.0アップデート後、一部のジョブ実行をしたところ、JobArrangerサーバのサービスが再起動してジョブがタイムアウトになります。
(ジョブ自体は完了していますが、JobArrangerマネージャーではタイムアウトしています)
※JobArranger2.1.1では該当しているジョブは問題なく終了しております

・環境
サーバ
JobArranger_Server_3.0.0
Agent
JobArranger_Agent_3.0.0
OS:centos7

・エラー内容
6873:20170228:114655.266 [INFO] [JASERVER000001] Starting Job Arranger Server. Job Arranger 3.0.0 (revision 7065).
6873:20170228:114655.268 [INFO] [JASERVER000003] server #0 started [main process]
6884:20170228:114655.273 [INFO] [JASERVER000004] server #11 started [message send #1]
6885:20170228:114655.274 [INFO] [JASERVER000004] server #12 started [self-monitoring #1]
6881:20170228:114655.275 [INFO] [JASERVER000004] server #8 started [job trapper #5]
6876:20170228:114655.275 [INFO] [JASERVER000004] server #3 started [check the running job #1]
6877:20170228:114655.276 [INFO] [JASERVER000004] server #4 started [job trapper #1]
6874:20170228:114655.276 [INFO] [JASERVER000004] server #1 started [start and check the jobnet #1]
6878:20170228:114655.277 [INFO] [JASERVER000004] server #5 started [job trapper #2]
6879:20170228:114655.277 [INFO] [JASERVER000004] server #6 started [job trapper #3]
6880:20170228:114655.278 [INFO] [JASERVER000004] server #7 started [job trapper #4]
6883:20170228:114655.278 [INFO] [JASERVER000004] server #10 started [jobnet boot #1]
6875:20170228:114655.279 [INFO] [JASERVER000004] server #2 started [start the job #1]
6882:20170228:114655.280 [INFO] [JASERVER000004] server #9 started [job loader #1]

6873:20170228:114747.424 [CRIT] One child process died (PID:6880,exitcode/signal:11). Exiting ...
6873:20170228:114749.452 [INFO] [JASERVER000002] Job Arranger Server stopped. Job Arranger 3.0.0 (revision 7065).
6901:20170228:114749.701 [INFO] [JASERVER000001] Starting Job Arranger Server. Job Arranger 3.0.0 (revision 7065).
6901:20170228:114749.704 [INFO] [JASERVER000003] server #0 started [main process]
6912:20170228:114749.708 [INFO] [JASERVER000004] server #11 started [message send #1]
6913:20170228:114749.710 [INFO] [JASERVER000004] server #12 started [self-monitoring #1]
6909:20170228:114749.711 [INFO] [JASERVER000004] server #8 started [job trapper #5]
6904:20170228:114749.712 [INFO] [JASERVER000004] server #3 started [check the running job #1]
6905:20170228:114749.714 [INFO] [JASERVER000004] server #4 started [job trapper #1]
6902:20170228:114749.714 [INFO] [JASERVER000004] server #1 started [start and check the jobnet #1]
6906:20170228:114749.716 [INFO] [JASERVER000004] server #5 started [job trapper #2]
6907:20170228:114749.717 [INFO] [JASERVER000004] server #6 started [job trapper #3]
6908:20170228:114749.718 [INFO] [JASERVER000004] server #7 started [job trapper #4]
6911:20170228:114749.718 [INFO] [JASERVER000004] server #10 started [jobnet boot #1]
6903:20170228:114749.720 [INFO] [JASERVER000004] server #2 started [start the job #1]
6910:20170228:114749.721 [INFO] [JASERVER000004] server #9 started [job loader #1]

デバックでのログも、念の為添付しております。

考えられる原因及び対応策をご教示願います。
以上です。宜しくお願い致します。


ファイル

デバックログ.txt (233 KB) デバックログ.txt 匿名ユーザー, 2017/02/28 13:24
ジョブネット画面.png (40.8 KB) ジョブネット画面.png 匿名ユーザー, 2017/03/02 10:49
ジョブネット詳細画面.png (26.4 KB) ジョブネット詳細画面.png 匿名ユーザー, 2017/03/02 10:49
jobarg_server.log (17.7 MB) jobarg_server.log 匿名ユーザー, 2017/03/02 14:43

保守サポート 担当 さんが7年以上前に更新

  • ステータス新規登録 から 受付完了 に変更

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

このリスタートは、ジョブサーバの1つの子プロセスが停止したために起きています。
6873:20170228:114747.424 [CRIT] One child process died (PID:6880,exitcode/signal:11). Exiting ...

デバッグログでは、0228:1250の起動以後で起きていませんが、再現性はありますか?
また、このリスタート時に動いたジョブに関連するジョブネットを見せて頂けますか?
ジョブネットフローと当該ジョブの詳細(設定画面)をエクセルへの張り付けファイルなどでOKです。

速やかな返信のためにサポート契約をご検討頂ければ幸甚です。
宜しくお願い致します。

匿名ユーザー さんが7年以上前に更新

お世話になっております。

デバッグログでは、0228:1250の起動以後で起きていませんが、再現性はありますか?

該当するジョブを実行すると常に再現されます。

また、このリスタート時に動いたジョブに関連するジョブネットを見せて頂けますか?
ジョブネットフローと当該ジョブの詳細(設定画面)をエクセルへの張り付けファイルなどでOKです。

画面を添付します。

下記のエラーログも表示しています
s*** stack smashing detected ***: /usr/sbin/jobarg_server terminated
49835:20170228:003308.983 [CRIT] Got signal [signal:11(SIGSEGV),reason:128,refaddr:(nil)].@ 49835:20170228:003308.983 [CRIT] Got signal [signal:11(SIGSEGV),reason:128,refaddr:(nil)].. Crashing ...
49835:20170228:003308.984 [CRIT] ====== Fatal information: ======

49835:20170228:003308.984 [CRIT] Program counter: 0x7f3890e22128
49835:20170228:003308.984 [CRIT] === Registers: ===
49835:20170228:003308.984 [CRIT] r8 =0 =0 = 049835:20170228:003308.984 [CRIT] r9 = 7f3890570d80 = 139880916520320 = 13988091652032049835:20170228:003308.984 [CRIT] r10 = 7f3890577878 = 139880916547704 = 139880916547704
49835:20170228:003308.984 [CRIT] r11 =0 =0 =@
49835:20170228:003308.984 [CRIT] r11 = 0 = 0 = 049835:20170228:003308.984 [CRIT] r12 = 7ffdacd2e550 = 140727502955856 = 140727502955856
49835:20170228:003308.984 [CRIT] r13 = 7ffdacd2e460 = 140727502955616 = 140727502955616
49835:20170228:003308.984 [CRIT] r14     =     7ffdacd2e710 =      140727502956304 =       14072750295630449835:20170228:003308.984 [CRIT] r15     =0 =0 =        0
49835:20170228:003308.984 [CRIT] rdi = 7f3893bb4930 = 139880973420848 =
49835:20170228:003308.984 [CRIT] rdi = 7f3893bb4930 = 139880973420848 = 13988097342084849835:20170228:003308.984 [CRIT] rsi =0 =0 = 049835:20170228:003308.984 [CRIT] rbp = 7ffdacd2e700 = 140727502956288 = 14072750295628849835:20170228:003308.983 [CRIT] Got signal [signal:11(SIGSEGV),reason:128,refaddr:(nil)].. Crashing ...*** stack smashing detected ***: /usr/sbin/jobarg_server terminated

以上です。宜しくお願い致します。

保守サポート 担当 さんが7年以上前に更新

  • ステータス受付完了 から 回答中 に変更

Job Arranger のサーバlogを添付して頂けますか?

匿名ユーザー さんが7年以上前に更新

お世話になっております。
Job Arranger のサーバlogを添付致します。
ご確認の程宜しくお願い致します。

匿名ユーザー さんが7年以上前に更新

お世話になっております。
サポート契約のない中で申し訳ないですが、対処可能かの見込みだけでもいただくことはできないでしょう。
解析、本回答にお時間かかるようであれば、一旦、別案等で対応を考えようと思っております。

誠に勝手なお願いではございますが、ご協力いただけると幸いです。

保守サポート 担当 さんが7年以上前に更新

返信遅くなりまして恐縮です。

頂いたserver.logを見ますと連続してOne child process died のエラーと再起動が発生しています。

該当するジョブを実行すると常に再現されます。

このジョブを実行するためのデータが問題を引き起こしている可能性があります。

①先ず連続しているエラー再起動を停止するには下記テーブルをクリア(全データ削除)してください。
ja_run_jobnet_table

②One child process diedのプロセスの特定
logよりJob Arranger Server開始~ Arranger Serverのエラーstop の一例を抜き出しました。
停止の原因となった One child process died (PID:3274 はServer起動時のログの[job trapper #4]です。★印
Server起動時はいくつかの子プロセスを起動しますが、そのうちのtrapperプロセス(5個ある)の一つが問題となっています。
これは、AgentからServerに送られる通信を受け取るプロセスですので、その通知データに問題があると思われます。

  3267:20170202:020044.034 [INFO] [JASERVER000001] Starting Job Arranger Server. Job Arranger 3.0.0 (revision 7065).
  3268:20170202:020044.035 [INFO] [JASERVER000004] server #1 started [start and check the jobnet #1]
  3269:20170202:020044.035 [INFO] [JASERVER000004] server #2 started [start the job #1]
省略
  3267:20170202:020044.036 [INFO] [JASERVER000003] server #0 started [main process]
★3274:20170202:020044.036 [INFO] [JASERVER000004] server #7 started [job trapper #4] 
省略
  3273:20170202:020248.725 [INFO] [JAJOBNETRUN000001] In ja_set_runerr() job execution error. inner_job_id: 11402582 status is RUNERR jobnet_id: JBN_SRV_051, job_id: JBN_SRV_051/JB_SRV_051_001, user_name: production, job_exit_cd: 99, icon_status: 1
info from server: "processed: 1; failed: 0; total: 1; seconds spent: 0.000041" 
sent: 1; skipped: 0; total: 1
  3277:20170202:020500.283 [INFO] [JABOOT000001] skipped the start of jobnet: inner jobnet id[1304980] jobnet id[JBN_BYD_048] scheduled time[201702020205]
*** stack smashing detected ***: /usr/sbin/jobarg_server terminated
  3274:20170202:020936.282 [CRIT] Got signal [signal:11(SIGSEGV),reason:128,refaddr:(nil)]. Crashing ...
  3274:20170202:020936.282 [CRIT] ====== Fatal information: ======
  3274:20170202:020936.282 [CRIT] Program counter: 0x7f8e259c4128
  3274:20170202:020936.282 [CRIT] === Registers: ===
  3274:20170202:020936.282 [CRIT] r8      =                0 =                    0 =                    0     
省略                 0
  3274:20170202:020936.282 [CRIT] === Backtrace: ===
★3267:20170202:020936.283 [CRIT] One child process died (PID:3274,exitcode/signal:11). Exiting ...
pkill: killing pid 3132 failed: 荐怨・&・娯 ・>・・>繿坂サ懌 с☆
  3267:20170202:020938.306 [INFO] [JASERVER000002] Job Arranger Server stopped. Job Arranger 3.0.0 (revision 7065).

③対応としましては...
ログ上で文字化けしています。なにかAgentからServerに送られる通信内容で文字コードがおかしいものがあるかもしれません。
job_id: JBN_SRV_051 で問題が起きていることが明確ですから、他のうまく行くジョブとの違いを突きとめてください。

もしhost ci01 で実行するジョブが同じようにエラーとなるなら、
そのサーバのJobAgentやその他設定を他のうまくいっているサーバのものと比較してみてください。

以上宜しくお願いいたします。

匿名ユーザー さんが7年以上前に更新

ご回答いただきありがとうございます。

①先ず連続しているエラー再起動を停止するには下記テーブルをクリア(全データ削除)してください。
ja_run_jobnet_table

こちらについては、実行ジョブに影響があると思われますので、停止調整中です。調整でき次第実施確認いたします。

②One child process diedのプロセスの特定
これは、AgentからServerに送られる通信を受け取るプロセスですので、その通知データに問題があると思われます。

通知データの不正なパターンや同事象の過去事例などを提供いただくことは難しいでしょうか。

③対応としましては...
ログ上で文字化けしています。なにかAgentからServerに送られる通信内容で文字コードがおかしいものがあるかもしれません。

ログの文字化けしている内容ですが、正しい文字コード(UTF−8)に変換したところ以下のようになりました。(こちら変換して送付すべきでした。。。)
pkill: killing pid 3132 failed: 荐怨・&・娯 ・>・・>繿坂サ懌 с☆

pkill: killing pid 3132 failed: 許可されていない操作です
AgentからServerへの通知データのログでしょうか。
(内容から子プロセスが停止できなかったようなログにも見えます。)

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

匿名ユーザー さんが7年以上前に更新

たまにくる人間です。

2.1では問題なかったjobが3.0ではエラーでしょうか?

Agentからくる文字コードがUTF8ではなさそうに見られます。
/var/lib/jobarrangerにある
jobarg_agentd.db を確認してください。
文字コードが難しいならteeを使わないほうがよいでは

以上です。

匿名ユーザー さんが7年以上前に更新

保守サポート 担当様
たまにくる人間様

Job arrangerで実行しているシェルスクリプトの出力を止めると問題なくジョブネットの実行できました。
ご指摘いただいた通りAgentから送付されるデータの問題であったかと思います。
文字コードの変更等での検証まで実施できておりませんが、ジョブネットの運用はできそうです。

ご協力いただきありがとうございます。大変助かりました。

取り急ぎ、お礼とご報告まで。

保守サポート 担当 さんが7年以上前に更新

  • ステータス回答中 から 終了 に変更

他の形式にエクスポート: Atom PDF