Project

General

Profile

その他問い合わせ #2475

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

Added by Anonymous about 2 years ago. Updated about 2 years ago.

Status:
終了
Priority:
急いで
Assignee:
-
Start date:
02/28/2017
Due date:
% Done:

0%

Estimated time:

Description

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

・説明
下記の環境で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 Anonymous, 02/28/2017 01:24 PM
ジョブネット画面.png (40.8 KB) ジョブネット画面.png Anonymous, 03/02/2017 10:49 AM
ジョブネット詳細画面.png (26.4 KB) ジョブネット詳細画面.png Anonymous, 03/02/2017 10:49 AM
jobarg_server.log (17.7 MB) jobarg_server.log Anonymous, 03/02/2017 02:43 PM

History

#1 Updated by 保守サポート 担当 about 2 years ago

  • Status changed from 新規登録 to 受付完了

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

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

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

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

#2 Updated by Anonymous about 2 years ago

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

デバッグログでは、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

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

#3 Updated by 保守サポート 担当 about 2 years ago

  • Status changed from 受付完了 to 回答中

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

#4 Updated by Anonymous about 2 years ago

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

#5 Updated by Anonymous about 2 years ago

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

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

#6 Updated by 保守サポート 担当 about 2 years ago

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

頂いた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 Updated by Anonymous about 2 years ago

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

①先ず連続しているエラー再起動を停止するには下記テーブルをクリア(全データ削除)してください。
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への通知データのログでしょうか。
(内容から子プロセスが停止できなかったようなログにも見えます。)

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

#8 Updated by Anonymous about 2 years ago

たまにくる人間です。

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

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

以上です。

#9 Updated by Anonymous about 2 years ago

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

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

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

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

#10 Updated by 保守サポート 担当 about 2 years ago

  • Status changed from 回答中 to 終了

Also available in: Atom PDF