その他問い合わせ #1947
完了ジョブエージェントが突然停止します
説明
jobArrangerでシステムの運用を行っておりますが突然エージェントのプロセスが消えることがあります。
消えた時間帯のログを確認するとクリティカルエラーが発生し、その後にエージェントが停止しています。
原因を調べたところ、Sqliteにジョブ情報を書き込む処理がうまくいっていないように見えます。
また、エージェントが停止する直前で『the database is busy』の警告が出ており、データベースファイルを複数のプロセスが使用しています。
エージェントが停止した時間には２つのジョブがちょうど同じ時間にスケジューリングしておりました。
これが原因でエージェントが停止してしまったのでしょうか。
jobarrangerの設定などでこれを回避する方法はないでしょうか。
■エージェントが停止する直前のログ
Jul 30 14:00:01 Batch 1820:20150730:140001.867 [INFO] In ja_agent_begin() jobid: 672713, method: 0
Jul 30 14:00:01 Batch 1820:20150730:140001.868 [WARN] In ja_jobdb_get_status() can not find jobid: 672713
Jul 30 14:00:01 Batch 1820:20150730:140001.868 [INFO] In ja_jobdb_insert() jobid: 672713 is created
Jul 30 14:00:01 Batch 1820:20150730:140001.876 [INFO] jobid: 672713, method: 0 is begin
Jul 30 14:00:01 Batch 1819:20150730:140001.879 [INFO] In ja_job_object_list_executive () jobid: 672713, type: command, status: BEGIN
Jul 30 14:00:01 Batch 1819:20150730:140001.879 [INFO] jobid: 672713, status: 0
Jul 30 14:00:01 Batch 1820:20150730:140001.882 [INFO] In ja_agent_begin() jobid: 672747, method: 0
Jul 30 14:00:01 Batch 1820:20150730:140001.883 [WARN] the database is busy.
Jul 30 14:00:02 Batch 1820:20150730:140002.883 [WARN] In ja_jobdb_get_status() can not find jobid: 672747
Jul 30 14:00:02 Batch 1820:20150730:140002.884 [INFO] In ja_jobdb_insert() jobid: 672747 is created
Jul 30 14:00:02 Batch 1820:20150730:140002.892 [INFO] jobid: 672747, method: 0 is begin
Jul 30 14:00:02 Batch 1820:20150730:140002.892 [INFO] In ja_agent_begin() jobid: 672732, method: 0
Jul 30 14:00:02 Batch 1819:20150730:140002.892 [WARN] query failed: [ select * from jobs where status = 0] error [database disk image is malformed]
Jul 30 14:00:02 Batch 1819:20150730:140002.892 [CRIT] Got signal [signal:11(SIGSEGV),reason:1,refaddr:(nil)]. Crashing ...
Jul 30 14:00:02 Batch 1820:20150730:140002.892 [WARN] In ja_jobdb_get_status() can not find jobid: 672732
Jul 30 14:00:02 Batch 1819:20150730:140002.892 [CRIT] ====== Fatal information: ======
Jul 30 14:00:02 Batch 1819:20150730:140002.892 [CRIT] Program counter: 0x410e20
Jul 30 14:00:02 Batch 1819:20150730:140002.892 [CRIT] === Registers: ===
Jul 30 14:00:02 Batch 1819:20150730:140002.892 [CRIT] r8 = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] r9 = 71b = 1819 = 1819
Jul 30 14:00:02 Batch 1820:20150730:140002.893 [INFO] In ja_jobdb_insert() jobid: 672732 is created
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] r10 = 7ff8b7867700 = 140706207659776 = 140706207659776
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] r11 = 206 = 518 = 518
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] r12 = d0fef0 = 13696752 = 13696752
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] r13 = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] r14 = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] r15 = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rdi = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rsi = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rbp = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rbx = d0fef0 = 13696752 = 13696752
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rdx = 6dc2e8 = 7193320 = 7193320
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rax = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rcx = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rsp = 7fff3fbbd488 = 140734262662280 = 140734262662280
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] rip = 410e20 = 4263456 = 4263456
Jul 30 14:00:02 Batch 1819:20150730:140002.893 [CRIT] efl = 10206 = 66054 = 66054
Jul 30 14:00:02 Batch 1819:20150730:140002.894 [CRIT] csgsfs = 3b9a00000000e033 = 4294745194651246643 = 4294745194651246643
Jul 30 14:00:02 Batch 1819:20150730:140002.894 [CRIT] err = 4 = 4 = 4
Jul 30 14:00:02 Batch 1819:20150730:140002.894 [CRIT] trapno = e = 14 = 14
Jul 30 14:00:02 Batch 1819:20150730:140002.894 [CRIT] oldmask = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.894 [CRIT] cr2 = 0 = 0 = 0
Jul 30 14:00:02 Batch 1819:20150730:140002.894 [CRIT] === Backtrace: ===
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 12: /usr/sbin/jobarg_agentd(print_fatal_info+0xae) [0x4181ee]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 11: /usr/sbin/jobarg_agentd() [0x417b3f]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 10: /lib64/libpthread.so.0(+0xf5b0) [0x7ff8b72445b0]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 9: /usr/sbin/jobarg_agentd(ja_db_fetch+0) [0x410e20]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 8: /usr/sbin/jobarg_agentd(ja_job_object_list_add+0x68) [0x40d648]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 7: /usr/sbin/jobarg_agentd(ja_job_object_list_executive+0x3c) [0x40d78c]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 6: /usr/sbin/jobarg_agentd(executive_thread+0x83) [0x40d503]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 5: /usr/sbin/jobarg_agentd(zbx_thread_start+0x62) [0x4170a2]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 4: /usr/sbin/jobarg_agentd(MAIN_ZABBIX_ENTRY+0x143) [0x40c923]
Jul 30 14:00:02 Batch 1819:20150730:140002.900 [CRIT] 3: /usr/sbin/jobarg_agentd(daemon_start+0x25a) [0x41786a]
Jul 30 14:00:02 Batch 1819:20150730:140002.901 [CRIT] 2: /usr/sbin/jobarg_agentd(main+0xc8) [0x40d178]
Jul 30 14:00:02 Batch 1819:20150730:140002.901 [CRIT] 1: /lib64/libc.so.6(__libc_start_main+0xf5) [0x7ff8b67947d5]
Jul 30 14:00:02 Batch 1819:20150730:140002.901 [CRIT] 0: /usr/sbin/jobarg_agentd() [0x40c609]
Jul 30 14:00:02 Batch 1819:20150730:140002.901 [CRIT] === Memory map: ===
Jul 30 14:00:02 Batch 1819:20150730:140002.901 [CRIT] 00400000-004d5000 r-xp 00000000 ca:01 4874 /usr/sbin/jobarg_agentd
Jul 30 14:00:02 Batch 1819:20150730:140002.903 [CRIT] 006d4000-006d7000 rw-p 000d4000 ca:01 4874 /usr/sbin/jobarg_agentd
Jul 30 14:00:02 Batch 1819:20150730:140002.903 [CRIT] 006d7000-006df000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.903 [CRIT] 00cf9000-00d1a000 rw-p 00000000 00:00 0 [heap]
Jul 30 14:00:02 Batch 1819:20150730:140002.903 [CRIT] 00d1a000-00e8f000 rw-p 00000000 00:00 0 [heap]
Jul 30 14:00:02 Batch 1819:20150730:140002.903 [CRIT] 00e8f000-00f2b000 rw-p 00000000 00:00 0 [heap]
Jul 30 14:00:02 Batch 1819:20150730:140002.903 [CRIT] 7ff8b655e000-7ff8b6573000 r-xp 00000000 ca:01 402 /lib64/libgcc_s-4.7.2-20121109.so.1
Jul 30 14:00:02 Batch 1819:20150730:140002.903 [CRIT] 7ff8b6573000-7ff8b6772000 ---p 00015000 ca:01 402 /lib64/libgcc_s-4.7.2-20121109.so.1
Jul 30 14:00:02 Batch 1820:20150730:140002.904 [INFO] jobid: 672732, method: 0 is begin
Jul 30 14:00:02 Batch 1819:20150730:140002.904 [CRIT] 7ff8b6772000-7ff8b6773000 rw-p 00014000 ca:01 402 /lib64/libgcc_s-4.7.2-20121109.so.1
Jul 30 14:00:02 Batch 1819:20150730:140002.904 [CRIT] 7ff8b6773000-7ff8b690e000 r-xp 00000000 ca:01 3024 /lib64/libc-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.905 [CRIT] 7ff8b690e000-7ff8b6b0e000 ---p 0019b000 ca:01 3024 /lib64/libc-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.905 [CRIT] 7ff8b6b0e000-7ff8b6b12000 r--p 0019b000 ca:01 3024 /lib64/libc-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.905 [CRIT] 7ff8b6b12000-7ff8b6b14000 rw-p 0019f000 ca:01 3024 /lib64/libc-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.905 [CRIT] 7ff8b6b14000-7ff8b6b18000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.905 [CRIT] 7ff8b6b18000-7ff8b6b2b000 r-xp 00000000 ca:01 6107 /lib64/libresolv-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.905 [CRIT] 7ff8b6b2b000-7ff8b6d2b000 ---p 00013000 ca:01 6107 /lib64/libresolv-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.905 [CRIT] 7ff8b6d2b000-7ff8b6d2c000 r--p 00013000 ca:01 6107 /lib64/libresolv-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.905 [CRIT] 7ff8b6d2c000-7ff8b6d2d000 rw-p 00014000 ca:01 6107 /lib64/libresolv-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b6d2d000-7ff8b6d2f000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b6d2f000-7ff8b6d36000 r-xp 00000000 ca:01 6116 /lib64/librt-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b6d36000-7ff8b6f35000 ---p 00007000 ca:01 6116 /lib64/librt-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b6f35000-7ff8b6f36000 r--p 00006000 ca:01 6116 /lib64/librt-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b6f36000-7ff8b6f37000 rw-p 00007000 ca:01 6116 /lib64/librt-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b6f37000-7ff8b7034000 r-xp 00000000 ca:01 5175 /lib64/libm-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b7034000-7ff8b7233000 ---p 000fd000 ca:01 5175 /lib64/libm-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b7233000-7ff8b7234000 r--p 000fc000 ca:01 5175 /lib64/libm-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b7234000-7ff8b7235000 rw-p 000fd000 ca:01 5175 /lib64/libm-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b7235000-7ff8b724c000 r-xp 00000000 ca:01 3048 /lib64/libpthread-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b724c000-7ff8b744b000 ---p 00017000 ca:01 3048 /lib64/libpthread-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b744b000-7ff8b744c000 r--p 00016000 ca:01 3048 /lib64/libpthread-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b744c000-7ff8b744d000 rw-p 00017000 ca:01 3048 /lib64/libpthread-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b744d000-7ff8b7451000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b7451000-7ff8b7454000 r-xp 00000000 ca:01 5173 /lib64/libdl-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.906 [CRIT] 7ff8b7454000-7ff8b7653000 ---p 00003000 ca:01 5173 /lib64/libdl-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7653000-7ff8b7654000 r--p 00002000 ca:01 5173 /lib64/libdl-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7654000-7ff8b7655000 rw-p 00003000 ca:01 5173 /lib64/libdl-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7655000-7ff8b7674000 r-xp 00000000 ca:01 3426 /lib64/ld-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7866000-7ff8b786b000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7870000-7ff8b7871000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7871000-7ff8b7872000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7872000-7ff8b7873000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7873000-7ff8b7874000 r--p 0001e000 ca:01 3426 /lib64/ld-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7874000-7ff8b7875000 rw-p 0001f000 ca:01 3426 /lib64/ld-2.17.so
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7ff8b7875000-7ff8b7876000 rw-p 00000000 00:00 0
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7fff3fbaa000-7fff3fbe3000 rw-p 00000000 00:00 0 [stack]
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] 7fff3fbfe000-7fff3fc00000 r-xp 00000000 00:00 0 [vdso]
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0 [vsyscall]
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] ================================
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] Please consider attaching a disassembly listing to your bug report.
Jul 30 14:00:02 Batch 1819:20150730:140002.907 [CRIT] This listing can be produced with, e.g., objdump -DSswx jobarg_agentd.
Jul 30 14:00:02 Batch 1819:20150730:140002.908 [CRIT] ================================
Jul 30 14:00:02 Batch 1620:20150730:140002.909 [CRIT] One child process died (PID:1819,exitcode/signal:255). Exiting ...
Jul 30 14:00:04 Batch 1620:20150730:140004.909 [INFO] Job Arranger Agent stopped. Job Arranger 2.1.0 (revision 6777).
park S.Y さんがほぼ9年前に更新
- ステータス を 受付完了 から 回答中 に変更
ジョブアレンジャーのご利用ありがとうございます。
上記のエラーはSqliteのクラシューによるエラーになります。
この原因を調べるためにはお客様の情報が必要になります。
CPU:メーカー情報とプロセッサ情報
HDD:メーカー情報と型番
OS:OS情報
Job Arranger:rpmまたはinstall方法
提供頂きたいファイルは
/var/lib/jobarranger以下にある
jobarg_agentd.dbと
jobarg_agentd.db.backupと
jobarg_agentd.db.jajournalファイル
になります。(rpmインストールの場合)
お客様のServerは不良セクタ・不良ブロックの検査は完了でしょうか？
速やかな返信のためにサポート契約をご検討頂ければ幸甚です。
宜しくお願い致します。
匿名ユーザー さんがほぼ9年前に更新
早速の回答ありがとうございます。
障害発生時の情報は次の通りです。
＞この原因を調べるためにはお客様の情報が必要になります。
＞CPU:メーカー情報とプロセッサ情報
＞HDD:メーカー情報と型番
＞OS:OS情報
AWSのEC2上に構築したサーバーとなります。
OSはAmazonLinuxです。
＞Job Arranger:rpmまたはinstall方法
rpmを使用してインストールを実施しました。
＞提供頂きたいファイルは
＞/var/lib/jobarranger以下にある
＞jobarg_agentd.dbと
＞jobarg_agentd.db.backupと
＞jobarg_agentd.db.jajournalファイル
これらのファイルは既にローテートが行われており残っておりません。
Sqliteがクラッシュとなる原因として考えられるのは何がありますでしょうか。
どのようにすれば対処することが可能でしょうか、ご回答お願い致します。
park S.Y さんがほぼ9年前に更新
ご回答ありがとうございます。
エージェントが停止した時間には２つのジョブがちょうど同じ時間にスケジューリングしておりました。
弊社ではジョブアレンジャーの安定テストを実施しています。内容は同じAgentに並列で10個のジョブを実行するジョブネットを100回繰り返すテストです。
そのテストでsqliteがクラッシュすることはまだございません。
弊社ではsqliteの速度より安定を優先してsynchronousの値もFULLにしています。
sqliteがクラッシュする原因を解明するためにはお客様の環境(OSの全rpm調査とH/W調査など)を調査する必要があります。
すみませんがもし、同じ現象が発生したらAgentのlog、jobarg_agentd.db、jobarg_agentd.db.backup、jobarg_agentd.db.jajournalファイル、OSの全rpm情報を頂けますでしょうか？
ジョブアレンジャーのご利用ありがとうございます。
今後とも、宜しくお願い致します。
匿名ユーザー さんがほぼ9年前に更新
回答ありがとうございます。
＞弊社ではジョブアレンジャーの安定テストを実施しています。内容は同じAgentに並列で10個のジョブを実行するジョブネットを100回繰り返すテストです。
＞そのテストでsqliteがクラッシュすることはまだございません。
３ヶ月ほどシステムを運用しており、何度も同時にジョブネットが実行されていますが発生したのは１回のみ、再現性はかなり低いと考えられます。
こちらでも再現しようと並列にジョブを走らせましたが再現はできませんでした。
ちなみに安定テストですが、ジョブの並列実行でなくジョブネットを並列に実行した場合は挙動が変わるのでしょうか。
発生した状況としましてはジョブネットが同時に複数実行されておりました。
言葉足らずで申し訳ありません。
＞弊社ではsqliteの速度より安定を優先してsynchronousの値もFULLにしています。
このパラメーターはjobarrangerの設定で変更できるのでしょうか。
それとも運用者が意識せず常にFULLとなっているのでしょうか。
＞sqliteがクラッシュする原因を解明するためにはお客様の環境(OSの全rpm調査とH/W調査など)を調査する必要があります。
＞すみませんがもし、同じ現象が発生したらAgentのlog、jobarg_agentd.db、jobarg_agentd.db.backup、jobarg_agentd.db.jajournalファイル、OSの全rpm情報を頂けますでしょうか？
再現した場合に情報をお送り致します。