sessionブロック終了時のエラーについて

正式なコメント

服部健太

2023年12月05日 02:08

具体的な状況を確認させていただきたいのですが、以下の情報をご教示いただけますでしょうか？

セッションブロック接続対象のサーバのOSのバージョン
エラー発生時のジョブマネージャのログ（/var/log/kompira/kompira_jobmngrd.log）
セッションブロックの処理の内容（ジョブフロー）

以上、お手数をおかけしますが、どうぞよろしくお願いたします。

wata

2023年12月05日 07:40

ご確認ありがとうございます。ご質問いただいた内容は下記になります。

セッションブロック接続対象のサーバのOSのバージョン

　　　　Oracle Linux Server 8.5

エラー発生時のジョブマネージャのログ（/var/log/kompira/kompira_jobmngrd.log）

[2023-12-05 15:14:32,114:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:14:39,812:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received rpc message: OPEN_SESSION: corr_id=5d8f8139-c7fd-4650-816c-7223895de3fa
[2023-12-05 15:14:39,832:3992411:Worker-3:MainThread] INFO: [Worker-3] SessionJob(5d8f8139-c7fd-4650-816c-7223895de3fa,1624) started
[2023-12-05 15:14:39,840:3992411:Worker-3:MainThread] INFO: FabricDriver._create_connection: create FabricConnection[user@XXX.XXX.XXX.XXX:XXX]: 485e525944b009318c9103ece554c55cceeda3ff
[2023-12-05 15:14:39,848:3992411:Worker-3:MainThread] INFO: FabricDriver._create_connection: create FabricConnection[user@xxx.xxx.xxx.xxx:xxx]: c86512917d50dcb2453063645c5af6d7b4205094
[2023-12-05 15:14:39,991:3992411:Worker-3:MainThread] INFO: FabricRunner._setup: session_mode=True
[2023-12-05 15:14:40,094:3992411:Worker-3:MainThread] INFO: FabricRunner.start: use_pty: width=80, height=24
[2023-12-05 15:14:40,096:3992411:Worker-3:MainThread] INFO: FabricRunner.start: invoke_shell
[2023-12-05 15:14:40,098:3992411:Worker-3:MainThread] INFO: SessionJob: sent a reply for OPEN_SESSION
[2023-12-05 15:14:40,106:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received job message: SESSION_INPUT: corr_id=5d8f8139-c7fd-4650-816c-7223895de3fa
[2023-12-05 15:14:42,154:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:14:43,118:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received job message: SESSION_INPUT: corr_id=5d8f8139-c7fd-4650-816c-7223895de3fa
[2023-12-05 15:14:46,130:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received job message: SESSION_INPUT: corr_id=5d8f8139-c7fd-4650-816c-7223895de3fa
[2023-12-05 15:14:52,205:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:14:57,141:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received job message: CLOSE_SESSION: corr_id=5d8f8139-c7fd-4650-816c-7223895de3fa
[2023-12-05 15:14:57,143:3992411:Worker-3:handle_stdin] INFO: FabricRunner.close_proc_stdin: kill connection (session mode)
[2023-12-05 15:14:57,144:3992411:Worker-3:handle_stdin] INFO: FabricRunner.handle_stdin: program is finished
[2023-12-05 15:14:57,145:3992411:Worker-3:MainThread] WARNING: FabricDriver._prepare_connection: <CommandTimedOut: cmd='$SHELL' timeout=120>
[2023-12-05 15:14:57,145:3992411:Worker-3:MainThread] INFO: FabricDriver._cleanup_connection: set cache#0: FabricConnection[user@xxx.xxx.xxx.xxx:xxx]
[2023-12-05 15:14:57,145:3992411:Worker-3:MainThread] INFO: Connections.set: connection <c86512917d50dcb2453063645c5af6d7b4205094> set: FabricConnection[user@xxx.xxx.xxx.xxx:xxx] (expire=2023-12-05 15:19:57.145622)
[2023-12-05 15:14:57,145:3992411:Worker-3:MainThread] INFO: FabricDriver._cleanup_connection: set cache#1: FabricConnection[user@XXX.XXX.XXX.XXX:XXX]
[2023-12-05 15:14:57,145:3992411:Worker-3:MainThread] INFO: Connections.set: connection <485e525944b009318c9103ece554c55cceeda3ff> set: FabricConnection[user@XXX.XXX.XXX.XXX:XXX] (expire=2023-12-05 15:19:57.145727)
[2023-12-05 15:14:57,145:3992411:Worker-3:MainThread] ERROR: SessionJob(5d8f8139-c7fd-4650-816c-7223895de3fa,1624): CommandTimeoutError: <CommandTimedOut: cmd='$SHELL' timeout=120> (exc_info=False)
[2023-12-05 15:14:57,145:3992411:Worker-3:MainThread] INFO: [Worker-3] SessionJob(5d8f8139-c7fd-4650-816c-7223895de3fa,1624) finished
[2023-12-05 15:14:57,161:5400:kompira_jobmngrd:MainThread] INFO: SessionJob: sent a reply for CLOSE_SESSION
[2023-12-05 15:14:57,166:3992411:Worker-3:MainThread] INFO: [Worker-3] connections_cache_entries: ['c86512917d50dcb2453063645c5af6d7b4205094', '485e525944b009318c9103ece554c55cceeda3ff']
[2023-12-05 15:14:57,168:5400:kompira_jobmngrd:ReturnThread] INFO: [WorkerPool] SessionJob(5d8f8139-c7fd-4650-816c-7223895de3fa,1624) is done: <Worker(Worker-3, started)> has 2 cache_entries, and became idle.
[2023-12-05 15:14:57,268:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received rpc message: OPEN_SESSION: corr_id=c972428c-bacf-4f79-ae21-e687ff7e01c8
[2023-12-05 15:14:57,285:3992411:Worker-3:MainThread] INFO: [Worker-3] SessionJob(c972428c-bacf-4f79-ae21-e687ff7e01c8,1624) started
[2023-12-05 15:14:57,291:3992411:Worker-3:MainThread] INFO: Connections.get: connection <485e525944b009318c9103ece554c55cceeda3ff> is cached (reused=1)
[2023-12-05 15:14:57,291:3992411:Worker-3:MainThread] INFO: FabricDriver._create_connection: reuse FabricConnection[user@XXX.XXX.XXX.XXX:XXX]: 485e525944b009318c9103ece554c55cceeda3ff
[2023-12-05 15:14:57,297:3992411:Worker-3:MainThread] INFO: Connections.get: connection <c86512917d50dcb2453063645c5af6d7b4205094> is cached (reused=1)
[2023-12-05 15:14:57,298:3992411:Worker-3:MainThread] INFO: FabricDriver._create_connection: reuse FabricConnection[user@xxx.xxx.xxx.xxx:xxx]: c86512917d50dcb2453063645c5af6d7b4205094
[2023-12-05 15:14:57,298:3992411:Worker-3:MainThread] INFO: FabricRunner._setup: session_mode=True
[2023-12-05 15:14:57,301:3992411:Worker-3:MainThread] INFO: FabricRunner.start: use_pty: width=80, height=24
[2023-12-05 15:14:57,303:3992411:Worker-3:MainThread] INFO: FabricRunner.start: invoke_shell
[2023-12-05 15:14:57,305:3992411:Worker-3:MainThread] INFO: SessionJob: sent a reply for OPEN_SESSION
[2023-12-05 15:14:57,311:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received job message: SESSION_INPUT: corr_id=c972428c-bacf-4f79-ae21-e687ff7e01c8
[2023-12-05 15:15:00,323:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received job message: SESSION_INPUT: corr_id=c972428c-bacf-4f79-ae21-e687ff7e01c8
[2023-12-05 15:15:02,400:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:15:03,339:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received job message: SESSION_INPUT: corr_id=c972428c-bacf-4f79-ae21-e687ff7e01c8
[2023-12-05 15:15:07,175:5400:kompira_jobmngrd:ReturnThread] INFO: -------- cache entries[2]: updated 2023-12-05 15:14:57.168187 --------
485e525944b009318c9103ece554c55cceeda3ff | Worker-3 | 12/05 15:14:57 | 12/05 15:14:57 | 0 | FabricConnection[user@XXX.XXX.XXX.XXX:XXX]
c86512917d50dcb2453063645c5af6d7b4205094 | Worker-3 | 12/05 15:14:57 | 12/05 15:14:57 | 0 | FabricConnection[user@xxx.xxx.xxx.xxx:xxx]
[2023-12-05 15:15:12,418:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:15:14,349:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] received job message: CLOSE_SESSION: corr_id=c972428c-bacf-4f79-ae21-e687ff7e01c8
[2023-12-05 15:15:14,350:3992411:Worker-3:handle_stdin] INFO: FabricRunner.close_proc_stdin: kill connection (session mode)
[2023-12-05 15:15:14,353:3992411:Worker-3:handle_stdin] INFO: FabricRunner.handle_stdin: program is finished
[2023-12-05 15:15:14,353:3992411:Worker-3:MainThread] WARNING: FabricDriver._prepare_connection: <CommandTimedOut: cmd='$SHELL' timeout=120>
[2023-12-05 15:15:14,353:3992411:Worker-3:MainThread] INFO: FabricDriver._cleanup_connection: set cache#0: FabricConnection[user@xxx.xxx.xxx.xxx:xxx]
[2023-12-05 15:15:14,353:3992411:Worker-3:MainThread] INFO: Connections.set: connection <c86512917d50dcb2453063645c5af6d7b4205094> updated: FabricConnection[user@xxx.xxx.xxx.xxx:xxx] (expire=2023-12-05 15:19:57.145622)
[2023-12-05 15:15:14,354:3992411:Worker-3:MainThread] INFO: FabricDriver._cleanup_connection: set cache#1: FabricConnection[user@XXX.XXX.XXX.XXX:XXX]
[2023-12-05 15:15:14,354:3992411:Worker-3:MainThread] INFO: Connections.set: connection <485e525944b009318c9103ece554c55cceeda3ff> updated: FabricConnection[user@XXX.XXX.XXX.XXX:XXX] (expire=2023-12-05 15:19:57.145727)
[2023-12-05 15:15:14,354:3992411:Worker-3:MainThread] ERROR: SessionJob(c972428c-bacf-4f79-ae21-e687ff7e01c8,1624): CommandTimeoutError: <CommandTimedOut: cmd='$SHELL' timeout=120> (exc_info=False)
[2023-12-05 15:15:14,354:3992411:Worker-3:MainThread] INFO: [Worker-3] SessionJob(c972428c-bacf-4f79-ae21-e687ff7e01c8,1624) finished
[2023-12-05 15:15:14,373:5400:kompira_jobmngrd:MainThread] INFO: SessionJob: sent a reply for CLOSE_SESSION
[2023-12-05 15:15:14,378:3992411:Worker-3:MainThread] INFO: [Worker-3] connections_cache_entries: ['c86512917d50dcb2453063645c5af6d7b4205094', '485e525944b009318c9103ece554c55cceeda3ff']
[2023-12-05 15:15:14,379:5400:kompira_jobmngrd:ReturnThread] INFO: [WorkerPool] SessionJob(c972428c-bacf-4f79-ae21-e687ff7e01c8,1624) is done: <Worker(Worker-3, started)> has 2 cache_entries, and became idle.
[2023-12-05 15:15:23,121:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:15:24,382:5400:kompira_jobmngrd:ReturnThread] INFO: -------- cache entries[2]: updated 2023-12-05 15:15:14.379912 --------
485e525944b009318c9103ece554c55cceeda3ff | Worker-3 | 12/05 15:14:57 | 12/05 15:15:14 | 1 | FabricConnection[user@XXX.XXX.XXX.XXX:XXX]
c86512917d50dcb2453063645c5af6d7b4205094 | Worker-3 | 12/05 15:14:57 | 12/05 15:15:14 | 1 | FabricConnection[user@xxx.xxx.xxx.xxx:xxx]
[2023-12-05 15:15:33,123:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:15:43,125:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:15:53,127:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:
[2023-12-05 15:16:03,129:5400:kompira_jobmngrd:MainThread] INFO: [JobManager] multiprocessing manager debug info:

セッションブロックの処理の内容（ジョブフロー）

|status|
|id_array|
|job_name|
|caution_message|
|abnormal_message|
|error_num = 100|
[success_array = []] ->
[error_flg = 0] ->
[__timeout__ = 120] ->
[__use_pty__ = true] ->
[__node__ = xxx] ->
print("===================================") ->
print('$job_nameを実行します。') ->
{session s |
    [s.send:"stty rows 1000 cols 1000\n"] ->
    sleep(1) ->
    <s ?? g"*xxx*":2> ->
    [i = 0] ->
    {for id in id_array |
        { while $RESULT != null |
            <s: 2> =>
            {if $STATUS | break }
        } ->
        [s.send: 'curl -s -X GET -H "xxx"\n'] ->
        sleep(1) ->
        <s> ->
        <s> ->
        print($RESULT) ->
        {if $RESULT == "1\r\n" |
            then:[success_array = success_array + [[id,status[i]]]]
            else:[error_flg = 1] ->
            {if error_num == 1 |
                then:print(caution_message[i])
                elif error_num == 2:print(abnormal_message[i]) -> abort()
                else:print("想定外の事象")
            }
        } ->
        [i = i + 1]
    } ->
    sleep(1)
}

以上、調査の程お願いいたします。

0

Ichiro Takahashi

2023年12月06日 01:25

担当変わりまして、フィックスポイントの高橋と申します。

ジョブフローやログのご提供ありがとうございます。弊社内で確認をしたところ、セッションブロックの終了時に CommandTimeoutError のログが記録される事象が発生することは確認できました（ご提供いただいたジョブフローをそのまま走らせたわけではありません）。

まず確認になりますが、対象のリモートノードには SSH 踏み台でアクセスするように、ノード型オブジェクトに「プロキシ」ノードを設定されているのかと思いますが、こちらはその理解で合っておりますでしょうか？（その場合、プロキシノードも対象ノード同様に Oracle Linux になりますでしょうか？）

次に、ご報告にあるとおり「sessionブロック内の処理は正常に行われている」ことは再現しましたが、「その場合後続のジョブが実行されず異常終了してしまいます」の部分がまだ把握できておりません。たとえば同じジョブフローを同じノードに対して続けて実行しても、session ブロックの処理は成功しています。

この「後続のジョブが実行されず異常終了する」はおそらくこれとは別のジョブフローでの事かと推測しますが、具体的にどのような処理（どのようなジョブフロー）で、どのようなエラーが発生するか、といった情報について追加でご提供いただけますでしょうか。

お手数をおかけしますが、よろしくお願いいたします。

0

wata

2023年12月06日 05:55

ご確認いただきありがとうございます。

ご質問への回答は下記になります。

対象のリモートノードには SSH 踏み台でアクセスするように、ノード型オブジェクトに「プロキシ」ノードを設定されているのかと思いますが、こちらはその理解で合っておりますでしょうか？
>はい。その通りです。

その場合、プロキシノードも対象ノード同様に Oracle Linux になりますでしょうか？
>プロキシノードのOSは「CentOS Linux release 7.9.2009」を使用しております。

具体的にどのような処理（どのようなジョブフロー）で、どのようなエラーが発生するか、といった情報について追加でご提供いただけますでしょうか。
>セッションブロック終了時にエラーが発生しているため、後続のジョブフローを実行するための結合子「->」で異常終了しております。

以上、引き続き調査の程よろしくお願いいたします。

0

Ichiro Takahashi

2023年12月06日 08:59

セッションブロック終了時にエラーが発生しているため、後続のジョブフローを実行するための結合子「->」で異常終了しております。

とのことですが、セッションブロック終了時の CommandTimeoutError はセッションブロック自体のエラーにはなりません（セッション開始時の接続失敗はセッションブロックのエラーになります）。

弊社内での再現実験では以下のようにセッションブロックをループさせて、kompira_jobmngrd.log 上ではセッション終了時に CommandTimeoutError が記録されていても、ジョブフローとして毎回接続に成功してセッションとしてはエラーになりませんでした。

|__node__ = ...|
|loop = 100|
{ for n in loop |
    { session s |
        [s.send:"stty rows 1000 cols 1000\n"] ->
        sleep(1) ->
        ...
    }
}

セッションブロックを抜けた時点でエラーになっていて、後続の結合子でエラーになって異常終了している場合、プロセス詳細画面のコンソールにエラー情報が表示されていなかったでしょうか？

当該プロセスでエラー表示があったかご確認いただけますでしょうか。また異常終了した際の以下のログについてもご提供いただけますでしょうか。

/var/log/kompira/kompirad.log
/var/log/kompira/process.log

お手数をおかけしますが、よろしくお願いいたします。

0

wata

2023年12月20日 10:22
編集済み

ご確認いただきありがとうございます。

プロセス詳細画面のエラーは下記になります。
また、ジョブフローの41行目はセッションブロック終了の「}」と結合子「->」のみとなってますので、セッションブロック終了時にエラーになっていると考えております。

[ERROR] CommandTimeoutError: <CommandTimedOut: cmd='$SHELL' timeout=120>
aborted at line 41 in /kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: アサーション失敗: status code is non 0

異常終了した際のログは以下になります。

/var/log/kompira/kompirad.log

[2023-12-05 15:05:02,552:5290:kompirad:EngineServer] INFO: [EngineServer] execute jobflow "/kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test" by user "root"
[2023-12-05 15:05:02,579:5290:kompirad:EngineServer] INFO: Process(1623).start: started /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test (execute by user "root")
[2023-12-05 15:05:02,785:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: f435f89c-470b-497f-a194-be50d516c142: headers={'task': 'OPEN_SESSION', 'pid': 1623, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-05 15:05:02,802:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: f435f89c-470b-497f-a194-be50d516c142
[2023-12-05 15:05:03,095:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-05 15:05:03,099:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: f435f89c-470b-497f-a194-be50d516c142
[2023-12-05 15:05:03,100:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=f435f89c-470b-497f-a194-be50d516c142
[2023-12-05 15:05:03,104:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-stream, body[57]='Last login: Tue Dec  5 14:56:09 '...
[2023-12-05 15:05:03,145:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-stream, body[116]='stty rows 1000 cols 1000\r\n[kompi'...
[2023-12-05 15:05:06,110:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=f435f89c-470b-497f-a194-be50d516c142
[2023-12-05 15:05:06,118:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-05 15:05:06,175:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-05 15:05:06,177:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-05 15:05:09,123:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=f435f89c-470b-497f-a194-be50d516c142
[2023-12-05 15:05:09,129:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-05 15:05:09,189:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-stream, body[35]='0\r\n[kompira_user@stg-zabbix101 ~'...
[2023-12-05 15:05:20,133:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: f435f89c-470b-497f-a194-be50d516c142: headers={'task': 'CLOSE_SESSION', 'pid': 1623}, body[0]=''
[2023-12-05 15:05:20,156:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-05 15:05:20,156:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: f435f89c-470b-497f-a194-be50d516c142
[2023-12-05 15:05:20,158:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: f435f89c-470b-497f-a194-be50d516c142
[2023-12-05 15:05:20,172:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f435f89c-470b-497f-a194-be50d516c142, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-05 15:05:20,172:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: process(1623) has no session: f435f89c-470b-497f-a194-be50d516c142
[2023-12-05 15:05:20,268:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: d07e5158-a091-4970-a518-0c8487bbf6af: headers={'task': 'OPEN_SESSION', 'pid': 1623, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-05 15:05:20,284:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: d07e5158-a091-4970-a518-0c8487bbf6af
[2023-12-05 15:05:20,312:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-05 15:05:20,315:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: d07e5158-a091-4970-a518-0c8487bbf6af
[2023-12-05 15:05:20,316:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=d07e5158-a091-4970-a518-0c8487bbf6af
[2023-12-05 15:05:20,320:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-stream, body[57]='Last login: Tue Dec  5 15:05:03 '...
[2023-12-05 15:05:20,360:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-stream, body[116]='stty rows 1000 cols 1000\r\n[kompi'...
[2023-12-05 15:05:23,326:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=d07e5158-a091-4970-a518-0c8487bbf6af
[2023-12-05 15:05:23,332:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-05 15:05:23,391:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-05 15:05:23,391:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-05 15:05:26,339:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=d07e5158-a091-4970-a518-0c8487bbf6af
[2023-12-05 15:05:26,346:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-05 15:05:26,405:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-05 15:05:26,405:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-05 15:05:37,349:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: d07e5158-a091-4970-a518-0c8487bbf6af: headers={'task': 'CLOSE_SESSION', 'pid': 1623}, body[0]=''
[2023-12-05 15:05:37,366:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-05 15:05:37,366:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: d07e5158-a091-4970-a518-0c8487bbf6af
[2023-12-05 15:05:37,369:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: d07e5158-a091-4970-a518-0c8487bbf6af, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-05 15:05:37,369:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=-1: d07e5158-a091-4970-a518-0c8487bbf6af
[2023-12-05 15:05:37,371:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: d07e5158-a091-4970-a518-0c8487bbf6af
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] INFO: JobflowRuntime(1623).abort: aborted at line 41 in /kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: アサーション失敗: status code is non 0
[2023-12-05 15:05:37,379:5290:kompirad:MainThread] INFO: Process(1623).abort: finished /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test [ABORTED] elapsed=0:00:34.799691
[2023-12-05 15:05:37,383:5290:kompirad:MainThread] INFO: JobflowRuntime(1623).finish: process stats: cputime=0:00:00.485414, latency=0:00:00.009554, dispatch=17, preempt=0, interrupt=0

/var/log/kompira/process.log

[2023-12-05 15:05:02,644:5290:kompirad:MainThread] Process(1623): ===================================
[2023-12-05 15:05:02,645:5290:kompirad:MainThread] Process(1623): Zabbix_AP4_Chat_監視抑止事前確認を実行します。[2023-12-05 15:05:02,644:5290:kompirad:MainThread] Process(1623): ===================================
[2023-12-05 15:05:02,645:5290:kompirad:MainThread] Process(1623): Zabbix_AP4_Chat_監視抑止事前確認を実行します。
[2023-12-05 15:05:03,104:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: Last login: Tue Dec  5 14:56:09 2023 from XXX.XXX.XXX.XXX
[2023-12-05 15:05:03,145:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: stty rows 1000 cols 1000
[2023-12-05 15:05:03,145:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: [kompira_user@zabbix001 ~]$ stty rows 1000 cols 1000
[2023-12-05 15:05:06,118:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: [kompira_user@zabbix001 ~]$ curl -s -X GET -H "Content-Type:application/json-rpc" -d '{"jsonrpc": "2.0","method": "action.get","params": {"output": ["status"],"filter": {"eventsource": 0,"actionid": "55"}},"auth": "xxxxx","id": 1}' http://xxx.xxx.xxx.xxx/zabbix/api_jsonrpc.php | awk -F "," '{print $3}' | grep -c 1
[2023-12-05 15:05:06,176:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: 0
[2023-12-05 15:05:07,118:5290:kompirad:MainThread] Process(1623): 0
[2023-12-05 15:05:07,118:5290:kompirad:MainThread] Process(1623): 【警告】Zabbixのアクション「GoogleChat自動通知（APサーバ4号機_抑止）」の事前ステータス確認を行いましたが、既に「有効」でした。
[2023-12-05 15:05:09,129:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: [kompira_user@zabbix001 ~]$ curl -s -X GET -H "Content-Type:application/json-rpc" -d '{"jsonrpc": "2.0","method": "action.get","params": {"output": ["status"],"filter": {"eventsource": 0,"actionid": "54"}},"auth": "xxxxx","id": 1}' http://xxx.xxx.xxx.xxx/zabbix/api_jsonrpc.php | awk -F "," '{print $3}' | grep -c 0
[2023-12-05 15:05:09,190:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: 0
[2023-12-05 15:05:10,131:5290:kompirad:MainThread] Process(1623): 0
[2023-12-05 15:05:10,131:5290:kompirad:MainThread] Process(1623): 【警告】Zabbixのアクション「GoogleChat自動通知(TFO監視用)」の事前ステータス確認を行いましたが、既に「無効」でした。
[2023-12-05 15:05:20,171:5290:kompirad:MainThread] Process(1623): 0
[2023-12-05 15:05:20,171:5290:kompirad:MainThread] Process(1623): Zabbix_AP4_Chat_監視抑止事前確認:終了
[2023-12-05 15:05:20,177:5290:kompirad:MainThread] Process(1623): []
[2023-12-05 15:05:20,226:5290:kompirad:MainThread] Process(1623): ===================================
[2023-12-05 15:05:20,226:5290:kompirad:MainThread] Process(1623): Zabbix_AP4_アラート_監視抑止事前確認を実行します。
[2023-12-05 15:05:20,320:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: Last login: Tue Dec  5 15:05:03 2023 from XXX.XXX.XXX.XXX
[2023-12-05 15:05:20,360:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: stty rows 1000 cols 1000
[2023-12-05 15:05:20,360:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: [kompira_user@zabbix001 ~]$ stty rows 1000 cols 1000
[2023-12-05 15:05:23,333:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: [kompira_user@zabbix001 ~]$ curl -s -X GET -H "Content-Type:application/json-rpc" -d '{"jsonrpc": "2.0","method": "action.get","params": {"output": ["status"],"filter": {"eventsource": 0,"actionid": "58"}},"auth": "xxxxx","id": 1}' http://xxx.xxx.xxx.xxx/zabbix/api_jsonrpc.php | awk -F "," '{print $3}' | grep -c 1
[2023-12-05 15:05:23,391:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: 0
[2023-12-05 15:05:24,334:5290:kompirad:MainThread] Process(1623): 0
[2023-12-05 15:05:24,334:5290:kompirad:MainThread] Process(1623): 【警告】Zabbixのアクション「架電対象アラート発生（APサーバ4号機_架電抑止）」の事前ステータス確認を行いましたが、既に「有効」でした。
[2023-12-05 15:05:26,346:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: [kompira_user@zabbix001 ~]$ curl -s -X GET -H "Content-Type:application/json-rpc" -d '{"jsonrpc": "2.0","method": "action.get","params": {"output": ["status"],"filter": {"eventsource": 0,"actionid": "57"}},"auth": "xxxxx","id": 1}' http://xxx.xxx.xxx.xxx/zabbix/api_jsonrpc.php | awk -F "," '{print $3}' | grep -c 0
[2023-12-05 15:05:26,405:5290:kompirad:QueueManager] Process(1623): [xxx.xxx.xxx.xxx] session: 0
[2023-12-05 15:05:27,346:5290:kompirad:MainThread] Process(1623): 0
[2023-12-05 15:05:27,347:5290:kompirad:MainThread] Process(1623): 【警告】Zabbixのアクション「架電対象アラート発生」の事前ステータス確認を行いましたが、既に「無効」でした。
[2023-12-05 15:05:37,374:5290:kompirad:MainThread] Process(1623): [ERROR] CommandTimeoutError: <CommandTimedOut: cmd='$SHELL' timeout=120>
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623): aborted at line 41 in /kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: アサーション失敗: status code is non 0
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623): ------------------------------------------------------------
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623): <stack frames>
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):   [/kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test: 8]
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):     obj_name = '/kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test'
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):     success_Chat_actionid = []
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623): 
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):   [/kompira/_02_ジョブ本体/_01_LB切断接続/AP4号機/Zabbix/AP4号機監視抑止/Zabbix_AP4_アラート_監視抑止事前確認: 10]
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):     actionid_array = ['58', '57']
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):     env_dic = {'status_active': '0', 'status_inactive': '1', 'actionid_Chat_TFO': '54', 'actionid_Chat_AP4': '55', 'actionid_alert': '57', 'actionid_alert_AP4': '58'}
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):     error_message = ['【警告】Zabbixのアクション「架電対象アラート発生（APサーバ4号機_架電抑止）」の事前ステータス確認を行いましたが、既に「有効」でした。', '【警告】Zabbixのアクション「架電対象アラート発生」の事前ステータス確認を行いましたが、既に「無効」でした。']
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):     job_name = 'Zabbix_AP4_アラート_監視抑止事前確認'
[2023-12-05 15:05:37,377:5290:kompirad:MainThread] Process(1623):     status = ['1', '0']
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623): 
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):   [/kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: 41]
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     __node__ = /kompira/_00_共通設定/_03_ノード情報/ZABBIX
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     __timeout__ = 120
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     __use_pty__ = true
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     abnormal_message = ['想定外の事象', '想定外の事象']
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     actionid_array = ['58', '57']
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     caution_message = ['【警告】Zabbixのアクション「架電対象アラート発生（APサーバ4号機_架電抑止）」の事前ステータス確認を行いましたが、既に「有効」でした。', '【警告】Zabbixのアクション「架電対象アラート発生」の事前ステータス確認を行いましたが、既に「無効」でした。']
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     error_flg = 1
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     error_num = 1
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     i = 2
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     job_name = 'Zabbix_AP4_アラート_監視抑止事前確認'
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     status = ['1', '0']
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):     success_array = []
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623): 
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623): <special variables>
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):   $ENV = {}
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):   $ERROR = "CommandTimeoutError: <CommandTimedOut: cmd='$SHELL' timeout=120>"
[2023-12-05 15:05:37,378:5290:kompirad:MainThread] Process(1623):   $RESULT = <KompiraSessionChannel-ID: d07e5158-a091-4970-a518-0c8487bbf6af>
[2023-12-05 15:05:37,379:5290:kompirad:MainThread] Process(1623):   $STATUS = -1
[2023-12-05 15:05:37,379:5290:kompirad:MainThread] Process(1623): ------------------------------------------------------------

お手数をおかけしますが、引き続き調査の程よろしくお願いいたします。

0

Ichiro Takahashi

2023年12月07日 08:48

ログのご提供ありがとうございます。

いただいたログのうち kompirad.log に誤動作に関連する可能性のある不自然な記録が含まれていました。ログをもとに引き続き調査したいと思いますが、おそらく過去事例がないため少しお時間いただくかもしれません。

また、現象が単一であるのか確認したく、もう少し追加の情報を集められればと考えております。「体感5回に1回ぐらい」とのことでしたので、おそらく何度かぶんのログは残っているのかと思います。過去の分で結構ですので、kompirad.log について同様の箇所について数個程度でもいただけますでしょうか。

何度もご依頼させていただいて大変恐縮ですが、よろしくお願いいたします。

0

wata

2023年12月08日 01:15

調査いただきありがとうございます。

以下が過去5回分のエラー時のkompirad.logになります。
エラー発生個所の調査のために一部差異があると思いますが、そちらにつきましてはご了承ください。

[2023-12-04 15:53:21,923:5290:kompirad:EngineServer] INFO: [EngineServer] execute jobflow "/kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test" by user "root"
[2023-12-04 15:53:21,939:5290:kompirad:EngineServer] INFO: Process(1554).start: started /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test (execute by user "root")
[2023-12-04 15:53:22,105:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246: headers={'task': 'OPEN_SESSION', 'pid': 1554, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-04 15:53:22,134:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246
[2023-12-04 15:53:22,147:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-04 15:53:22,151:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246
[2023-12-04 15:53:22,186:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[89]='Last login: Mon Dec  4 15:53:11 '...
[2023-12-04 15:53:23,153:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=2dfdbaed-0748-4f4a-a3f6-a82fe722d246
[2023-12-04 15:53:23,160:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[26]='stty rows 1000 cols 1000\r\n'
[2023-12-04 15:53:23,161:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 15:53:26,163:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=2dfdbaed-0748-4f4a-a3f6-a82fe722d246
[2023-12-04 15:53:26,169:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 15:53:26,229:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[3]='1\r\n'
[2023-12-04 15:53:26,229:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 15:53:29,175:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=2dfdbaed-0748-4f4a-a3f6-a82fe722d246
[2023-12-04 15:53:29,182:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 15:53:29,243:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[3]='1\r\n'
[2023-12-04 15:53:29,243:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 15:53:30,184:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246: headers={'task': 'CLOSE_SESSION', 'pid': 1554}, body[0]=''
[2023-12-04 15:53:30,197:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-04 15:53:30,197:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246
[2023-12-04 15:53:30,200:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-04 15:53:30,200:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=-1: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246
[2023-12-04 15:53:30,202:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 2dfdbaed-0748-4f4a-a3f6-a82fe722d246
[2023-12-04 15:53:30,207:5290:kompirad:MainThread] INFO: JobflowRuntime(1554).abort: aborted at line 41 in /kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: アサーション失敗: status code is non 0
[2023-12-04 15:53:30,210:5290:kompirad:MainThread] INFO: Process(1554).abort: finished /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test [ABORTED] elapsed=0:00:08.270620
[2023-12-04 15:53:30,214:5290:kompirad:MainThread] INFO: JobflowRuntime(1554).finish: process stats: cputime=0:00:00.260294, latency=0:00:00.005099, dispatch=9, preempt=0, interrupt=0
==================================================================================================================================================================================================================================================================================================================================================================================================================================================================================-
[2023-12-04 16:01:02,176:5290:kompirad:EngineServer] INFO: [EngineServer] execute jobflow "/kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test" by user "root"
[2023-12-04 16:01:02,193:5290:kompirad:EngineServer] INFO: Process(1562).start: started /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test (execute by user "root")
[2023-12-04 16:01:02,352:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: f20b105f-0d11-48ee-b224-91224541bf24: headers={'task': 'OPEN_SESSION', 'pid': 1562, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-04 16:01:02,368:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: f20b105f-0d11-48ee-b224-91224541bf24
[2023-12-04 16:01:02,416:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-04 16:01:02,419:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: f20b105f-0d11-48ee-b224-91224541bf24
[2023-12-04 16:01:02,455:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[89]='Last login: Mon Dec  4 16:00:46 '...
[2023-12-04 16:01:03,421:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=f20b105f-0d11-48ee-b224-91224541bf24
[2023-12-04 16:01:03,428:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[26]='stty rows 1000 cols 1000\r\n'
[2023-12-04 16:01:03,429:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:01:06,431:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=f20b105f-0d11-48ee-b224-91224541bf24
[2023-12-04 16:01:06,436:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:01:06,497:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[3]='1\r\n'
[2023-12-04 16:01:06,498:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:01:09,443:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=f20b105f-0d11-48ee-b224-91224541bf24
[2023-12-04 16:01:09,450:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:01:09,511:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[3]='1\r\n'
[2023-12-04 16:01:09,512:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:01:10,452:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: f20b105f-0d11-48ee-b224-91224541bf24: headers={'task': 'CLOSE_SESSION', 'pid': 1562}, body[0]=''
[2023-12-04 16:01:10,471:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-04 16:01:10,471:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: f20b105f-0d11-48ee-b224-91224541bf24
[2023-12-04 16:01:10,474:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: f20b105f-0d11-48ee-b224-91224541bf24, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-04 16:01:10,474:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=-1: f20b105f-0d11-48ee-b224-91224541bf24
[2023-12-04 16:01:10,476:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: f20b105f-0d11-48ee-b224-91224541bf24
[2023-12-04 16:01:10,482:5290:kompirad:MainThread] INFO: JobflowRuntime(1562).abort: aborted at line 41 in /kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: アサーション失敗: status code is non 0
[2023-12-04 16:01:10,484:5290:kompirad:MainThread] INFO: Process(1562).abort: finished /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test [ABORTED] elapsed=0:00:08.291104
[2023-12-04 16:01:10,488:5290:kompirad:MainThread] INFO: JobflowRuntime(1562).finish: process stats: cputime=0:00:00.243900, latency=0:00:00.005074, dispatch=9, preempt=0, interrupt=0
==================================================================================================================================================================================================================================================================================================================================================================================================================================================================================-
[2023-12-04 16:19:32,890:5290:kompirad:EngineServer] INFO: [EngineServer] execute jobflow "/kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test" by user "root"
[2023-12-04 16:19:32,905:5290:kompirad:EngineServer] INFO: Process(1565).start: started /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test (execute by user "root")
[2023-12-04 16:19:33,088:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 87af3c01-1482-4925-8954-348816ebf495: headers={'task': 'OPEN_SESSION', 'pid': 1565, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-04 16:19:33,104:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 87af3c01-1482-4925-8954-348816ebf495
[2023-12-04 16:19:33,209:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-04 16:19:33,215:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 87af3c01-1482-4925-8954-348816ebf495
[2023-12-04 16:19:33,249:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[89]='Last login: Mon Dec  4 16:18:48 '...
[2023-12-04 16:19:34,218:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=87af3c01-1482-4925-8954-348816ebf495
[2023-12-04 16:19:34,229:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[26]='stty rows 1000 cols 1000\r\n'
[2023-12-04 16:19:34,231:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:19:37,227:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=87af3c01-1482-4925-8954-348816ebf495
[2023-12-04 16:19:37,233:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:19:37,292:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:19:37,292:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:19:40,240:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=87af3c01-1482-4925-8954-348816ebf495
[2023-12-04 16:19:40,246:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:19:40,304:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:19:40,305:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:19:41,249:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 87af3c01-1482-4925-8954-348816ebf495: headers={'task': 'CLOSE_SESSION', 'pid': 1565}, body[0]=''
[2023-12-04 16:19:41,256:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 87af3c01-1482-4925-8954-348816ebf495
[2023-12-04 16:19:41,256:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-04 16:19:41,270:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 87af3c01-1482-4925-8954-348816ebf495
[2023-12-04 16:19:41,270:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 87af3c01-1482-4925-8954-348816ebf495, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-04 16:19:41,270:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: process(1565) has no session: 87af3c01-1482-4925-8954-348816ebf495
[2023-12-04 16:19:41,376:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d: headers={'task': 'OPEN_SESSION', 'pid': 1565, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-04 16:19:41,406:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d
[2023-12-04 16:19:41,418:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-04 16:19:41,421:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d
[2023-12-04 16:19:41,456:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[89]='Last login: Mon Dec  4 16:19:33 '...
[2023-12-04 16:19:42,423:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d
[2023-12-04 16:19:42,430:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[26]='stty rows 1000 cols 1000\r\n'
[2023-12-04 16:19:42,432:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:19:45,433:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d
[2023-12-04 16:19:45,440:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:19:45,498:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:19:45,499:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:19:48,446:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d
[2023-12-04 16:19:48,455:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:19:48,512:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:19:48,512:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:19:49,455:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d: headers={'task': 'CLOSE_SESSION', 'pid': 1565}, body[0]=''
[2023-12-04 16:19:49,468:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-04 16:19:49,468:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d
[2023-12-04 16:19:49,471:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-04 16:19:49,471:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=-1: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d
[2023-12-04 16:19:49,474:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 8a6e63ca-b96f-4e42-87d9-7dfb6a0f291d
[2023-12-04 16:19:49,480:5290:kompirad:MainThread] INFO: JobflowRuntime(1565).abort: aborted at line 41 in /kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: アサーション失敗: status code is non 0
[2023-12-04 16:19:49,482:5290:kompirad:MainThread] INFO: Process(1565).abort: finished /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test [ABORTED] elapsed=0:00:16.577084
[2023-12-04 16:19:49,487:5290:kompirad:MainThread] INFO: JobflowRuntime(1565).finish: process stats: cputime=0:00:00.461174, latency=0:00:00.010264, dispatch=17, preempt=0, interrupt=0
==================================================================================================================================================================================================================================================================================================================================================================================================================================================================================-
[2023-12-04 16:33:41,387:5290:kompirad:EngineServer] INFO: [EngineServer] execute jobflow "/kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test" by user "root"
[2023-12-04 16:33:41,411:5290:kompirad:EngineServer] INFO: Process(1571).start: started /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test (execute by user "root")
[2023-12-04 16:33:41,582:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 04e70269-4893-4c2d-a48f-49c3a34b6d89: headers={'task': 'OPEN_SESSION', 'pid': 1571, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-04 16:33:41,602:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 04e70269-4893-4c2d-a48f-49c3a34b6d89
[2023-12-04 16:33:41,629:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-04 16:33:41,632:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 04e70269-4893-4c2d-a48f-49c3a34b6d89
[2023-12-04 16:33:41,669:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[89]='Last login: Mon Dec  4 16:33:10 '...
[2023-12-04 16:33:42,634:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=04e70269-4893-4c2d-a48f-49c3a34b6d89
[2023-12-04 16:33:42,641:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[26]='stty rows 1000 cols 1000\r\n'
[2023-12-04 16:33:42,643:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:33:45,645:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=04e70269-4893-4c2d-a48f-49c3a34b6d89
[2023-12-04 16:33:45,651:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:33:45,710:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:33:45,710:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:33:48,657:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=04e70269-4893-4c2d-a48f-49c3a34b6d89
[2023-12-04 16:33:48,664:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:33:48,722:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:33:48,723:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:33:50,667:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 04e70269-4893-4c2d-a48f-49c3a34b6d89: headers={'task': 'CLOSE_SESSION', 'pid': 1571}, body[0]=''
[2023-12-04 16:33:50,676:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-04 16:33:50,676:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 04e70269-4893-4c2d-a48f-49c3a34b6d89
[2023-12-04 16:33:50,678:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 04e70269-4893-4c2d-a48f-49c3a34b6d89
[2023-12-04 16:33:50,692:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 04e70269-4893-4c2d-a48f-49c3a34b6d89, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-04 16:33:50,692:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: process(1571) has no session: 04e70269-4893-4c2d-a48f-49c3a34b6d89
[2023-12-04 16:33:50,788:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98: headers={'task': 'OPEN_SESSION', 'pid': 1571, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-04 16:33:50,803:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98
[2023-12-04 16:33:50,828:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-04 16:33:50,830:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98
[2023-12-04 16:33:50,867:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[89]='Last login: Mon Dec  4 16:33:41 '...
[2023-12-04 16:33:51,832:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=6b5d4a18-f6ac-47ee-9ebf-6697657b2a98
[2023-12-04 16:33:51,839:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[26]='stty rows 1000 cols 1000\r\n'
[2023-12-04 16:33:51,841:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:33:54,843:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=6b5d4a18-f6ac-47ee-9ebf-6697657b2a98
[2023-12-04 16:33:54,850:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:33:54,911:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:33:54,911:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:33:57,858:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=6b5d4a18-f6ac-47ee-9ebf-6697657b2a98
[2023-12-04 16:33:57,864:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:33:57,924:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:33:57,924:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:33:59,868:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98: headers={'task': 'CLOSE_SESSION', 'pid': 1571}, body[0]=''
[2023-12-04 16:33:59,889:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-04 16:33:59,889:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98
[2023-12-04 16:33:59,889:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-04 16:33:59,889:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=-1: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98
[2023-12-04 16:33:59,892:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 6b5d4a18-f6ac-47ee-9ebf-6697657b2a98
[2023-12-04 16:33:59,897:5290:kompirad:MainThread] INFO: JobflowRuntime(1571).abort: aborted at line 42 in /kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: アサーション失敗: status code is non 0
[2023-12-04 16:33:59,900:5290:kompirad:MainThread] INFO: Process(1571).abort: finished /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test [ABORTED] elapsed=0:00:18.488071
[2023-12-04 16:33:59,904:5290:kompirad:MainThread] INFO: JobflowRuntime(1571).finish: process stats: cputime=0:00:00.447566, latency=0:00:00.011009, dispatch=19, preempt=0, interrupt=0
==================================================================================================================================================================================================================================================================================================================================================================================================================================================================================-
[2023-12-04 16:47:45,976:5290:kompirad:EngineServer] INFO: [EngineServer] execute jobflow "/kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test" by user "root"
[2023-12-04 16:47:45,991:5290:kompirad:EngineServer] INFO: Process(1573).start: started /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test (execute by user "root")
[2023-12-04 16:47:46,170:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 9f1627f4-18e0-4801-a534-1f00c79b5089: headers={'task': 'OPEN_SESSION', 'pid': 1573, '__port__': xxx, '__conntype__': 'ssh', '__shell__': '', '__use_shell__': False, '__host__': 'xxx.xxx.xxx.xxx', '__user__': 'kompira_user', '__passphrase__': '<secret>', '__keyfile__': '<secret>', '__proxy__': '<secret>', '__timeout__': 120, '__use_pty__': True}, body[0]=''
[2023-12-04 16:47:46,187:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 9f1627f4-18e0-4801-a534-1f00c79b5089
[2023-12-04 16:47:46,220:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-result, body[33]='default/stg-unyo-opt101/job_queu'...
[2023-12-04 16:47:46,225:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 9f1627f4-18e0-4801-a534-1f00c79b5089
[2023-12-04 16:47:46,226:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=9f1627f4-18e0-4801-a534-1f00c79b5089
[2023-12-04 16:47:46,230:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-stream, body[57]='Last login: Mon Dec  4 16:47:32 '...
[2023-12-04 16:47:46,271:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-stream, body[116]='stty rows 1000 cols 1000\r\n[kompi'...
[2023-12-04 16:47:49,241:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=9f1627f4-18e0-4801-a534-1f00c79b5089
[2023-12-04 16:47:49,247:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:47:49,305:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:47:49,305:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:47:52,253:5290:kompirad:QueueManager] INFO: [QueueManager] session input: session_id=9f1627f4-18e0-4801-a534-1f00c79b5089
[2023-12-04 16:47:52,263:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-stream, body[312]='curl -s -X GET -H "Content-Type:'...
[2023-12-04 16:47:52,319:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-stream, body[3]='0\r\n'
[2023-12-04 16:47:52,319:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-stream, body[32]='[kompira_user@stg-zabbix101 ~]$ '
[2023-12-04 16:47:54,263:5290:kompirad:QueueManager] INFO: [QueueManager] submit remote task: 9f1627f4-18e0-4801-a534-1f00c79b5089: headers={'task': 'CLOSE_SESSION', 'pid': 1573}, body[0]=''
[2023-12-04 16:47:54,278:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-result, body[0]=''
[2023-12-04 16:47:54,278:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=0: 9f1627f4-18e0-4801-a534-1f00c79b5089
[2023-12-04 16:47:54,281:5290:kompirad:QueueManager] INFO: [QueueManager] got message from return_queue: 9f1627f4-18e0-4801-a534-1f00c79b5089, content_type=application/x-kompira-job-result, body[43]=b'\x80\x03}q\x00(X\x06\x00\x00\x00stdou'...
[2023-12-04 16:47:54,281:5290:kompirad:QueueManager] INFO: [QueueManager] _on_job_result: notified result with status=-1: 9f1627f4-18e0-4801-a534-1f00c79b5089
[2023-12-04 16:47:54,284:5290:kompirad:QueueManager] INFO: [QueueManager] waiting command result: 9f1627f4-18e0-4801-a534-1f00c79b5089
[2023-12-04 16:47:54,290:5290:kompirad:MainThread] INFO: JobflowRuntime(1573).abort: aborted at line 41 in /kompira/_02_ジョブ本体/_00_テンプレート/_01_LB切断接続/Zabbix/Zabbix_ステータス確認_テンプレート: アサーション失敗: status code is non 0
[2023-12-04 16:47:54,292:5290:kompirad:MainThread] INFO: Process(1573).abort: finished /kompira/_02_ジョブ本体/_99_テスト用/xxx/jobnet_test [ABORTED] elapsed=0:00:08.300920
[2023-12-04 16:47:54,297:5290:kompirad:MainThread] INFO: JobflowRuntime(1573).finish: process stats: cputime=0:00:00.267130, latency=0:00:00.005045, dispatch=9, preempt=0, interrupt=0

0

Ichiro Takahashi

2023年12月08日 05:05

追加のログのご提供ありがとうございます。

いただいたログにはやはり共通的な部分があり調査の足掛かりとなるかもしれません。ただ、やはり弊社内では状況の再現が出来ておらず、調査には少し時間がかかるかもしれません。

ご迷惑をおかけして申し訳ございませんが、今しばらくお時間いただければ幸いです。

0

Ichiro Takahashi

2023年12月14日 06:40
編集済み

お待たせしてしまい、申し訳ございません。

社内で調査を継続したところ、やはり同様の状況の再現には至っておりませんが、原因と考えられる問題点が見えてきました。

改善案も検討しておりますが、社内で状況の再現ができていないために、改善効果の程度や別の問題を引き起こすことはないかといった検証が十分に出来ておりません。

そこで、ご相談になるのですが、御社に部分的な修正パッチをお送りして、問題が改善するかの動作検証にご協力いただくことは可能でしょうか？

先述のとおり十分検証できていないため、そのリスクを加味してご検討いただければと思います。もしご協力いただけるようであれば、修正パッチの準備を進めたいと思います。

0

wata

2023年12月15日 08:07

ご調査いただきありがとうございます。

>御社に部分的な修正パッチをお送りして、問題が改善するかの動作検証にご協力いただくことは可能でしょうか？
内部で確認いたしますが、前向きに進めていきたいと考えておりますので、修正パッチのご準備を進めていただけたらと思います。
それと、動作検証の際に別の問題が発生した時のための戻しのパッチも一緒にご用意していただける認識でよろしいでしょうか。

また、現在暫定策として、sessionブロック終了時の結合子を「->>」にし、if文で当該エラーのみ無視するといった方法を考えております。
当該エラー以外で「CommandTimeoutError」が発生することはございますでしょうか。
もし発生するとしたら、どのような状況で「CommandTimeoutError」が発生するのかご教示いただきたいです。

暫定策として考えているジョブフロー
{session s |
    ...
} ->>
{if $STATUS == -1 |
    {if $ERROR != "CommandTimeoutError: <CommandTimedOut: cmd='$SHELL' timeout=120>" | abort()}
} ->
...

以上、お手数ですがよろしくお願いいたします。

0

Ichiro Takahashi

2023年12月18日 09:55

内部で確認いたしますが、前向きに進めていきたいと考えておりますので、修正パッチのご準備を進めていただけたらと思います。
それと、動作検証の際に別の問題が発生した時のための戻しのパッチも一緒にご用意していただける認識でよろしいでしょうか。

KEサーバ上の既存のファイルをパッチを適用したファイルで置き換えていただいて、サービスを再起動して動作確認していただくことを想定しています。そのため、元のファイルを別の名前でコピーしておくことで、いざという時には元に戻していただくことが可能となる見込みです。

また、現在暫定策として、sessionブロック終了時の結合子を「->>」にし、if文で当該エラーのみ無視するといった方法を考えております。
当該エラー以外で「CommandTimeoutError」が発生することはございますでしょうか。

本来このエラーは、リモートコマンドやセッションブロックがタイムアウトしたときに発生するもので、今回はそれに該当しない場面であるにもかかわらず発生しているという状況です。そのため、実際にセッションブロック内部での処理がタイムアウトしたとしても、上記暫定策ではそれを無視してしまう可能性は考えられます。

以上、参考になさってみてください。

0

wata

2023年12月20日 10:13

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

パッチ適用について、内部で確認を行いました。
適用可否判断の為、以下内容について、確認させてください。
　・パッチの概要（例：問題発生個所に〇〇の処理を追加する。）
　・パッチ適用による影響有無
　　（例：影響なし：概要の通り、他処理へは影響はない）
　　（例：影響あり：〇〇の処理に影響を与える。パッチ適用中は〇〇の処理を行うことができない。）
　・影響がある場合の対策
　・万が一想定外の事態が発生した際の対応

また、現在「CommandTimeoutError」がどのような状況で発生するかの確認のため検証を行っているのですが、「CommandTimeoutError」を意図的に発生させることができずにいます。
具体的にはどのようなジョブフローで「CommandTimeoutError」が発生するのかご教示いただけないでしょうか。
以下が検証を行った内容と発生したエラーになります。

sleep(10) ->
[ERROR] session channel is closed

[s.send:"sleep 10\n"] ->
<s> ->
<s> ->
[ERROR] session channel is closed

[s.send:"sleep 10\n"] ->
<s:2> ->
<s:2> ->
アサーション失敗: status code is non 0

お手数をおかけしますが、ご確認お願いします。

0

Ichiro Takahashi

2023年12月21日 01:52

・パッチの概要（例：問題発生個所に〇〇の処理を追加する。）

まず、本件については、ジョブフローの実行を担う kompirad というプログラムと、セッションブロックなどリモート連携を担う kompira_jobmngrd という2つのプログラムが関連しています。

今回パッチ適用の対象となるのは kompira_jobmngrd 側を予定しており、パッチの概要としては以下のとおりです。

kompira_jobmngrd 内部で本来 CommandTimedOut エラーが発生すべきでない箇所を、エラーが発生しないように修正します。

・パッチ適用による影響有無

影響なし：他の処理への影響はない想定です。

・万が一想定外の事態が発生した際の対応

パッチの適用を中止して、元に戻していただくことを想定しています。

また、現在「CommandTimeoutError」がどのような状況で発生するかの確認のため検証を行っているのですが、「CommandTimeoutError」を意図的に発生させることができずにいます。
具体的にはどのようなジョブフローで「CommandTimeoutError」が発生するのかご教示いただけないでしょうか。

セッションブロックでは CommandTimeoutError を（kompira_jobmngrd の内部では発生していますが）ジョブフローレベルで見えるように意図的に起こすことはおそらく困難です。セッション終了時の内部処理において特定のタイミングで kompira_jobmngrd から kompirad に対して CommandTimeoutError に対応するエラーメッセージが送信された場合に、本現象が発生することは確認できています。CPUが高負荷状況の場合などに発生しうると推測はしていますが、弊社内では kompirad の内部処理の途中に意図的に処理遅延を生じさせることでようやく再現できました。

0

wata

2023年12月25日 09:28

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

度々申し訳ございませんが以下の点についてご教示いただけたらと思います。

　・パッチ完成の目途
　・パッチを当てる手順及び戻す手順

0

Ichiro Takahashi

2023年12月26日 02:25

お待たせしてしまい申し訳ございません。

以下に修正パッチとその適用手順について示した資料をご用意しました。

https://docbase.io/posts/3235598/sharing/59794b5d-36dd-4f8a-9444-b9108bf24089

パッチ適用と動作確認について、ご検討のほどよろしくお願いいたします。
ご不明点などございましたら、お問い合わせください。

0

wata

2023年12月26日 10:05

パッチ及び手順をご連携いただきありがとうございます。

パッチを連携いただいたばかりで申し訳ないのですが、現在別のバグの対応のためにKompiraのバージョンを最新の1.6.9にアップデートしております。

つきましては、バージョン1.6.9用のパッチもご用意していただけないでしょうか。

お手数をおかけしますが、ご対応よろしくお願いいたします。

また、パッチ適応につきましては、現在手順の確認を行っており、問題がなければパッチを適応する方向で進んでおります。

0

Ichiro Takahashi

2023年12月26日 13:26

さきほど共有させていただいた URL の資料を更新しました。

v1.6.9 用のパッチファイルとして、Python 3.8 用と Python 3.6用の2つを追加しました。
Python のバージョンに合わせてパッチ適用手順についても見直しました。

弊社内の環境で、CentOS Stream 8 上の v1.6.9 (python 3.8) 環境に、同パッチを適用して簡単な動作確認は実施しております。

0

wata

2024年01月16日 06:42

v1.6.9 用のパッチファイルをご連携いただきありがとうございます。

手順を確認した結果、問題ないと判断し、パッチを適用いたしました。

結果としましては、kompira_jobmngrd 内部で以前 CommandTimedOut エラーが発生していた箇所で、CommandTimedOut エラーが発生しなくなっていることを確認出来ました。

また、エラーが起きていたジョブフローを何回か実行し、エラーが起きなくなっていることも確認出来ました。

ご対応いただきありがとうございました。

0

コメント

お探しのものを見つけられませんでしたか？