その他問い合わせ #3613
closedJob Arrager Serverのログ出力先をsyslogに設定すると一部のログしか出力されなくなる
Description
お世話になっております。
Job Arranger Serverのログ出力先をsyslogに設定すると、一部のログしか出力されなくなるという事象が発生しております。
jobarg_server.confのログ出力先は、下記のようにコメントアウトしており、
#JaLogFile=/var/log/jobarranger/jobarg_server.log
下記のようなログはsyslogでも出力が確認できるのですが、
Oct 22 16:51:08 vmfsppjb006 journal22685: Job Arranger Server22685: [JAJOBNET000001] In jajobnet_kill() jobnet was forced to stop. inner_jobnet_id: 1500000000000000138, jobnet_id: JOBNET_2, user_name: Admin
ログ出力先をsyslogではなく/var/log/jobarranger/jobarg_server.logに設定していた時には出力されていた、下記のようなメッセージは出力されなくなりました。
また、メッセージIDが[JASERVER000003]や[JASESSION300004]で始まるようなほとんどのログが出力されていないように見受けられます。
21263:20211022:133423.910 [ERROR] [JASESSION300004] The job return code '1' is range of the stop code '1' inner_job_id: 776
下記ファイルの、該当メッセージのログタイプや通知設定などを変更してみましたが、出力されませんでした。
/etc/jobarranger/locale/logmessage_64BIT.txt
また、Job Arranger monitorについても、jobarg_monitor.conf内で下記の通りログ出力先の項目をコメントアウトすることによりsyslog出力されるよう設定しておりますが、
#JaLogFile=/var/log/jobarranger/jobarg_monitor.log
こちらについては下記のようにメッセージがsyslogに出力されることを確認しております。
Oct 22 09:36:16 vmfsppjb006 journal6894: Job Arranger Monitor6894: [JAMONITOR200002] In ja_sender() jobnet_id 'JOBNET_1' can not be not run on schedule time '202110220935'. calendar_id: CALENDAR_1, schedule_id: SCHEDULE_1, user_name: Admin
Oct 22 09:36:16 vmfsppjb006 journal6894: Job Arranger Monitor6894: In ja_sender() cmd: /etc/jobarranger/monitor/jasender_monitor.sh '2' 'CALENDAR_1' 'SCHEDULE_1' 'JOBNET_1' 'Admin' '2021/10/22 09:35' '0'
以上を踏まえ、ご質問したいことは2点ございます。
①ログ出力先をsyslogに設定した場合でも、ジョブリターンコード1のメッセージを出力するにはどうしたらよいでしょうか。
②Job Arranger monitorのログメッセージ定義ファイル（Job Arranger Serverにとっての/etc/jobarranger/locale/logmessage_64BIT.txt）はあるのでしょうか。
あれば場所をお教えいただきたいです。
お忙しいところ大変恐れ入りますが、ご回答のほど、よろしくお願いいたします。
Files
Updated by Anonymous almost 3 years ago
すみません。
また、メッセージIDが[JASERVER000003]や[JASESSION300004]で始まるようなほとんどのログが出力されていないように見受けられます。
と書きましたが、[JASERVER00000x]については通常通り出力されているようでした。
特定のメッセージが出力されなくなるようです。
Updated by 保守サポート 担当 almost 3 years ago
- Status changed from 新規登録 to 回答中
ジョブアレンジャーのご利用有難うございます。
本事象発生環境の詳細情報(各種バージョン)、各種設定ファイル、ログファイル(ファイルのまま、圧縮可)等をご開示頂ければ幸甚です。
速やかな返信・対応のためにサポート契約をご検討頂ければ幸甚です。
宜しくお願い致します。
Updated by Anonymous almost 3 years ago
- File 設定ファイル.zip 設定ファイル.zip added
- File messages.zip messages.zip added
お世話になっております。
ご回答いただき誠にありがとうございます。
以下に環境情報を記載いたします。
【OS】RHEL 8.2
【Job Arranger Server】5.0.1
【Zabbix server】5.0.15
【MySQL】8.0.26
【Apache HTTP Server】2.4.37
【php】7.2.24
また、設定ファイル・ログファイルを添付しますので、ご確認のほどよろしくお願いいたします。
Updated by Anonymous almost 3 years ago
お世話になっております。
当該チケットについて、その後調査はいかがでしょうか。
サポート契約者優先であることについて重々承知の上ですが、何卒よろしくお願いいたします。
Updated by 保守サポート 担当 almost 3 years ago
資料のご提供有難うございました。
回答遅くなりまして恐縮です。
こちらでも同じJob Arranger 5.0.1 (revision 7557)で、以下の通り同様にジョブServerのログをコメントアウトし、messageを確認しました。
#JaLogFile=/var/log/jobarranger/jobarg_server.log
以下が頂きましたmessagesと弊社テストの messages での"Job Arranger Server"キーワードを含む行の抽出比較です。
御社のmessagesでは、スタート時の一連のメッセージと、ジョブネットを強制終了したときの[JAJOBNET000001]のみ以外、ジョブネット実行関連が出ていないようです。
こちらで確認しますとジョブがjob_exit_cd: 1でエラーになった時の[JAJOBNETRUN000001] やjob_timeoutの[JAJOBICONJOB300001] も出ております。
そちらでは[JAJOBNETRUN000001] や[JAJOBICONJOB300001] が全く出ないという事ですと、conf設定以外の何かの環境の違いに依ると考えられます。
★[JAJOBNETRUN000001] や[JAJOBICONJOB300001] が全く出ないという事で間違いないでしょうか？
因みにjobarg_server.conf設定で以下をお試しください。
LogType=system (# LogType=fileとなっています)
本来はLogType=systemが syslog指定になるものです。
弊社側では#LogTypeコメントアウト＋JaLogFileのコメントアウトで下記出力でしたので、JaLogFileのコメントアウトのみでLogType=systemの認識になるようですが念のため...
◆頂きました messages より最後部の "Job Arranger Server" 含む行の抽出
Oct 28 09:06:53 vmfsppjb006 journal[6353]: Job Arranger Server[6353]: [JASERVER000001] Starting Job Arranger Server. Job Arranger 5.0.1 (revision 7557). Oct 28 09:06:53 vmfsppjb006 journal[6353]: Job Arranger Server[6353]: [JASERVER000003] server #0 started [main process] Oct 28 09:06:53 vmfsppjb006 journal[6361]: Job Arranger Server[6361]: [JASERVER000004] server #6 started [job trapper #3] Oct 28 09:06:53 vmfsppjb006 journal[6363]: Job Arranger Server[6363]: [JASERVER000004] server #8 started [job trapper #5] Oct 28 09:06:53 vmfsppjb006 journal[6364]: Job Arranger Server[6364]: [JASERVER000004] server #9 started [job loader #1] Oct 28 09:06:53 vmfsppjb006 journal[6366]: Job Arranger Server[6366]: [JASERVER000004] server #11 started [message send #1] Oct 28 09:06:53 vmfsppjb006 journal[6362]: Job Arranger Server[6362]: [JASERVER000004] server #7 started [job trapper #4] Oct 28 09:06:53 vmfsppjb006 journal[6359]: Job Arranger Server[6359]: [JASERVER000004] server #4 started [job trapper #1] Oct 28 09:06:53 vmfsppjb006 journal[6356]: Job Arranger Server[6356]: [JASERVER000004] server #1 started [start and check the jobnet #1] Oct 28 09:06:53 vmfsppjb006 journal[6357]: Job Arranger Server[6357]: [JASERVER000004] server #2 started [start the job #1] Oct 28 09:06:53 vmfsppjb006 journal[6358]: Job Arranger Server[6358]: [JASERVER000004] server #3 started [check the running job #1] Oct 28 09:06:53 vmfsppjb006 journal[6360]: Job Arranger Server[6360]: [JASERVER000004] server #5 started [job trapper #2] Oct 28 09:06:53 vmfsppjb006 journal[6365]: Job Arranger Server[6365]: [JASERVER000004] server #10 started [jobnet boot #1] Oct 28 09:06:53 vmfsppjb006 journal[6367]: Job Arranger Server[6367]: [JASERVER000004] server #12 started [self-monitoring #1] Oct 28 16:07:46 vmfsppjb006 journal[6356]: Job Arranger Server[6356]: [JAJOBNET000001] In jajobnet_kill() jobnet was forced to stop. inner_jobnet_id: 1500000000000000152, jobnet_id: JOBNET_2, user_name: Admin Oct 28 16:09:18 vmfsppjb006 journal[6356]: Job Arranger Server[6356]: [JAJOBNET000001] In jajobnet_kill() jobnet was forced to stop. inner_jobnet_id: 1500000000000000153, jobnet_id: JOBNET_2, user_name: Admin
◆弊社テストの messages より "Job Arranger Server" 含む行の抽出
Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24069]: [JASERVER000001] Starting Job Arranger Server. Job Arranger 5.0.1 (revision 7557). Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24069]: [JASERVER000003] server #0 started [main process] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24081]: [JASERVER000004] server #12 started [self-monitoring #1] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24078]: [JASERVER000004] server #9 started [job loader #1] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24073]: [JASERVER000004] server #4 started [job trapper #1] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24074]: [JASERVER000004] server #5 started [job trapper #2] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24070]: [JASERVER000004] server #1 started [start and check the jobnet #1] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24071]: [JASERVER000004] server #2 started [start the job #1] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24075]: [JASERVER000004] server #6 started [job trapper #3] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24076]: [JASERVER000004] server #7 started [job trapper #4] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24077]: [JASERVER000004] server #8 started [job trapper #5] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24080]: [JASERVER000004] server #11 started [message send #1] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24072]: [JASERVER000004] server #3 started [check the running job #1] Nov 10 18:39:12 [localhost] journal: Job Arranger Server[24079]: [JASERVER000004] server #10 started [jobnet boot #1] Nov 10 18:42:47 [localhost] journal: Job Arranger Server[24070]: [JAJOBNET000001] In jajobnet_kill() jobnet was forced to stop. inner_jobnet_id: 1500000000000000605, jobnet_id: RUN_JOB_1500000000000000605, user_name: Admin Nov 10 18:43:33 [localhost] journal: Job Arranger Server[24077]: [JAJOBNETRUN000001] In ja_set_runerr() job execution error. inner_job_id: 220023 status is RUNERR jobnet_id: RUN_JOB_1500000000000000606, job_id: RUN_JOB_1500000000000000606/JOB-1, user_name: Admin, job_exit_cd: 1, icon_status: 1 Nov 10 18:48:12 [localhost] journal: Job Arranger Server[24070]: [JAJOBNET000001] In jajobnet_kill() jobnet was forced to stop. inner_jobnet_id: 1500000000000000606, jobnet_id: RUN_JOB_1500000000000000606, user_name: Admin Nov 10 18:50:04 [localhost] journal: Job Arranger Server[24072]: [JAJOBICONJOB300001] In jajob_icon_job_timeout() timeout occurrence. inner_job_id: 220026, timeout: 1, start_time: 20211110184841, jobnet_id: RUN_JOB_1500000000000000607, job_id: RUN_JOB_1500000000000000607/JOB-1, user_name: Admin Nov 10 18:50:11 [localhost] journal: Job Arranger Server[24077]: [JAJOBNETRUN000001] In ja_set_runerr() job execution error. inner_job_id: 220026 status is RUNERR jobnet_id: RUN_JOB_1500000000000000607, job_id: RUN_JOB_1500000000000000607/JOB-1, user_name: Admin, job_exit_cd: 1, icon_status: 1
②Job Arranger monitorのログメッセージ定義ファイルはございません。
以上ご確認よろしくお願いいたします。
Updated by Anonymous almost 3 years ago
お世話になっております。
ご回答いただき誠にありがとうございます。
★[JAJOBNETRUN000001] や[JAJOBICONJOB300001] が全く出ないという事で間違いないでしょうか？
間違いありません。
因みにjobarg_server.conf設定で以下をお試しください。
LogType=system (# LogType=fileとなっています)
LogType=system にして試してみましたが、出力結果に違いはありませんでした。
以上、よろしくお願い致します。
Updated by Anonymous almost 3 years ago
重ねて失礼します。
[JAJOBICONLESS300001]については、出力が確認できました。
Nov 11 14:25:37 vmfsppjb006 journal16888: Job Arranger Server16888: [JAJOBICONLESS300001] In jajob_icon_less_timeout() timeout occurrence. inner_job_id: 893, timeout: 1, start_time: 20211111142428, jobnet_id: JOBNET_00, job_id: JOBNET_00/LESS-1, user_name: Admin
これまではタイムアウト警告を0に設定していたため、出力されていませんでした。
よろしくお願い致します。
Updated by Anonymous almost 3 years ago
たびたび申し訳ありません。
出力できている[JASERVER000001]や[JAJOBICONLESS300001]等と、
出力できない[JAJOBNETRUN000001]等とでは、ログレベルに差があるのでしょうか？
ご教示いただけますと幸いです。
よろしくお願い致します。
Updated by 保守サポート 担当 almost 3 years ago
ご確認有難うございました。
出力できている[JASERVER000001]や[JAJOBICONLESS300001]等と、
出力できない[JAJOBNETRUN000001]等とでは、ログレベルに差があるのでしょうか？
ログレベルがINFOやERROR、WARNを意図されていましたらそれは logmessage_64BIT.txt の設定に依ります。
以下はjobarg_server.log で出力した例ですが、JAJOBNETRUN000001を logmessage_64BIT.txt でINFOに設定しています。
syslog(messages)に出力されますと、このログレベル情報が出ません。ですので推奨はいたしません。
因みになぜJaLogFile=のログ指定でなく、syslogに出力されているか、理由を訓えて頂けませんでしょうか？
◆弊社テストのjobarg_server.log での出力例
14242:20211111:164927.696 [INFO] [JASERVER000001] Starting Job Arranger Server. Job Arranger 5.0.1 (revision 7557). 14242:20211111:164927.698 [INFO] [JASERVER000003] server #0 started [main process] 14254:20211111:164927.704 [INFO] [JASERVER000004] server #12 started [self-monitoring #1] 14251:20211111:164927.704 [INFO] [JASERVER000004] server #9 started [job loader #1] 14246:20211111:164927.705 [INFO] [JASERVER000004] server #4 started [job trapper #1] 14247:20211111:164927.705 [INFO] [JASERVER000004] server #5 started [job trapper #2] 14243:20211111:164927.706 [INFO] [JASERVER000004] server #1 started [start and check the jobnet #1] 14244:20211111:164927.706 [INFO] [JASERVER000004] server #2 started [start the job #1] 14248:20211111:164927.707 [INFO] [JASERVER000004] server #6 started [job trapper #3] 14249:20211111:164927.707 [INFO] [JASERVER000004] server #7 started [job trapper #4] 14250:20211111:164927.707 [INFO] [JASERVER000004] server #8 started [job trapper #5] 14253:20211111:164927.708 [INFO] [JASERVER000004] server #11 started [message send #1] 14245:20211111:164927.708 [INFO] [JASERVER000004] server #3 started [check the running job #1] 14252:20211111:164927.709 [INFO] [JASERVER000004] server #10 started [jobnet boot #1] 14250:20211111:165106.262 [INFO] [JAJOBNETRUN000001] In ja_set_runerr() job execution error. inner_job_id: 220049 status is RUNERR jobnet_id: RUN_JOB_1500000000000000612, job_id: RUN_JOB_1500000000000000612/JOB-1, user_name: Admin, job_exit_cd: 1, icon_status: 1 14243:20211111:165119.792 [INFO] [JAJOBNET000001] In jajobnet_kill() jobnet was forced to stop. inner_jobnet_id: 1500000000000000612, jobnet_id: RUN_JOB_1500000000000000612, user_name: Admin 14245:20211111:165304.869 [WARN] [JAJOBICONJOB300001] In jajob_icon_job_timeout() timeout occurrence. inner_job_id: 220052, timeout: 1, start_time: 20211111165142, jobnet_id: RUN_JOB_1500000000000000613, job_id: RUN_JOB_1500000000000000613/JOB-1, user_name: Admin
また[JAJOBICONLESS300001]が出たという事ですが、
[JAJOBICONJOB300001]～ジョブアイコンのtimeout～は出ますでしょうか？
何がjobarg_server.logとsyslog(messages)両方に出て、何がjobarg_server.logにのみ出るのかを数種類のエラーを両ケースで発生させ上記
◆弊社テストのjobarg_server.log での出力例
◆弊社テストの messages より "Job Arranger Server" 含む行の抽出
のイメージで両方のログの出力結果を比較してみたいですね。何か傾向があるのではないでしょうか？
messagesは"Job Arranger Server" 含む行でgrepしてください。
実行プロセスとファイル権限も気になります。ジョブサーバで以下の2つのコマンド結果を拝見できますか？
# ps -ef | grep job # ls -l /var/log/messages
よろしくお願いいたします。
Updated by Anonymous almost 3 years ago
お世話になっております。
syslogに出力する理由は、監視をZabbixではなくAzure monitorで実施するためです。
Azure monitorのログ監視ではログのフォーマットに制約があるため、Job Arrangerのログもsyslogに出力してもらう必要があります。
また[JAJOBICONLESS300001]が出たという事ですが、
[JAJOBICONJOB300001]～ジョブアイコンのtimeout～は出ますでしょうか？ --
当方ではAgentを使用しない想定なので[JAJOBICONLESS300001]の出力を確認しておりました。
[JAJOBICONJOB300001]については、後日確認致したいと思います。
以下実行プロセスとsyslogのファイル権限確認結果です。
【実行プロセス】
zabbix 1102 1 0 09:50 ? 00:00:00 /usr/sbin/jobarg_agentd -c /etc/jobarranger/jobarg_agentd.conf
zabbix 1147 1102 0 09:50 ? 00:00:00 /usr/sbin/jobarg_agentd -c /etc/jobarranger/jobarg_agentd.conf
zabbix 1148 1102 0 09:50 ? 00:00:00 /usr/sbin/jobarg_agentd -c /etc/jobarranger/jobarg_agentd.conf
zabbix 1149 1102 0 09:50 ? 00:00:00 /usr/sbin/jobarg_agentd -c /etc/jobarranger/jobarg_agentd.conf
zabbix 6372 1 0 09:51 ? 00:00:00 /usr/sbin/jobarg_monitor -c /etc/jobarranger/jobarg_monitor.conf
zabbix 6373 1 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6374 6372 0 09:51 ? 00:00:00 /usr/sbin/jobarg_monitor -c /etc/jobarranger/jobarg_monitor.conf
zabbix 6380 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6381 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6382 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6383 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6384 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6385 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6386 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6387 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6388 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6389 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6390 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
zabbix 6391 6373 0 09:51 ? 00:00:00 /usr/sbin/jobarg_server -c /etc/jobarranger/jobarg_server.conf
【ファイル権限】
'-rw-r-----. 1 root zabbix 2358854 Nov 19 10:18 /var/log/messages
以上、よろしくお願いいたします。