Ansible Tips: shellモジュールで長時間かかる処理を行う際に、途中経過ログを確認できるようにする

以下の改定
https://qiita.com/hiroyuki_onodera/items/b283e1a30fb91ac1ebf9

あまり作り込みし過ぎとはしたくないが、プロンプトを求められているようなケースで状態を確認できる様にしたい。

環境

• Fedora Linux 36 (Workstation Edition)
• ansible [core 2.11.6]
• ansible.cfg
  [defaults]
  verbosity = 1
  stdout_callback = ansible.posix.debug

実装例

tasks

    - name: long_process (logfile is /tmp/ansible_shell-yyyy-mmdd-hhmm-ss.log)
      shell: |-
        exec &> >(tee "/tmp/ansible_shell-$(date +%Y-%m%d-%H%M-%S).log")  # stdout,stderrを合わせて、ログにも分割して出力。
        set -xe 
        # 長時間かかる処理
        sleep 180
        echo END
      async: 1800                 # タイムアウト 30分
      poll: 0                     # 非同期実行
      register: long_process

    - name: wait 30 times every 60 seconds
      ansible.builtin.async_status:
        jid: "{{ long_process.ansible_job_id }}"
      register: r                                                             
      until: r is finished
      retries: 30                 # 待ちを行う回数
      delay: 60                   # 待ちを行う間隔

shellモジュールにおけるstdout, stderrを、リアルタイムで、対象ノードの/tmp/ansible_shell-yyyy-mmdd-hhmm-ss.logにログ出力。
1分毎に、非同期処理が終わっていないというログを出力。

追記

プロセス置換の箇所で、bashなどを明示指定しないとエラーとなるケースがあった。
その場合、以下にて回避可能。

tasks

    - name: long_process (logfile is /tmp/ansible_shell-yyyy-mmdd-hhmm-ss.log)
      shell:
        executable: /bin/bash
        cmd: |
          exec &> >(tee "/tmp/ansible_shell-$(date +%Y-%m%d-%H%M-%S).log")  # stdout,stderrを合わせて、ログにも分割して出力。        set -xe 
          # 長時間かかる処理
          sleep 180
          echo END
      async: 1800                 # タイムアウト 30分
      poll: 0                     # 非同期実行
      register: long_process

実行結果

TASK [long_process (logfile is /tmp/ansible_shell-yyyy-mmdd-hhmm-ss.log)] ********************************************************************************************************************
changed: [localhost] => {
    "ansible_job_id": "345271991923.700076",
    "changed": true,
    "finished": 0,
    "results_file": "/home/hiroyukionodera/.ansible_async/345271991923.700076",
    "started": 1
}

TASK [wait 30 times every 60 seconds] ********************************************************************************************************************************************************
FAILED - RETRYING: wait 30 times every 60 seconds (30 retries left).
FAILED - RETRYING: wait 30 times every 60 seconds (29 retries left).
FAILED - RETRYING: wait 30 times every 60 seconds (28 retries left).
changed: [localhost] => {
    "ansible_job_id": "345271991923.700076",
    "attempts": 4,
    "changed": true,
    "cmd": "exec &> >(tee \"/tmp/ansible_shell-$(date +%Y-%m%d-%H%M-%S).log\")\nset -xe\n# 長時間かかる処理\nsleep 180",
    "delta": "0:03:00.005839",
    "end": "2022-09-07 17:32:16.920473",
    "finished": 1,
    "rc": 0,
    "start": "2022-09-07 17:29:16.914634"
}

STDOUT:

+ sleep 180
+ echo END
END

非同期で実行されたstdoutも出力されている。
ログ分割の過程でstderrもstdout側に合流。
"delta": "0:03:00.005839" により3分かかっていることがわかる。

途中経過

対象ノードにおいて、書き出しているログを確認

$ ls -t /tmp/ansible_shell-* | head -1 
/tmp/ansible_shell-2022-0907-1729-16.log

$ fuser $(ls -t /tmp/ansible_shell-* | head -1)
/tmp/ansible_shell-2022-0907-1729-16.log: 707586

$ tail -f $( ls -t /tmp/ansible_shell-* | head -1 ) 
+ sleep 180
+ echo END
END
^C

$ fuser $(ls -t /tmp/ansible_shell-* | head -1)

Ansible側だけでなく、分割してログファイルにもログを出力できている。
tail -fによりリアルタイムで追記されるログ内容を表示可能。
fuserコマンドを用いると、実行中には対象ファイルをopenしているteeコマンドのプロセスidを確認可能。