Ansible の SSH の通信をデバッグする

レッドハットの杉村です。Ansible のテクニカルサポートをしています。

今回は以前のお問い合わせいただいた事例から、SSH (Secure Shell Protocol) について一つ紹介しようと思います。Ansible は Linux サーバを制御対象とするときは SSH で接続して処理を実行しますので、SSH の通信についてのトラブルは問題に直結します。

RHEL 8.6 + Ansible Core 2.13 で確認しています。

Ansible の基本的な動作原理

まずは Ansible はどうやって動いているのかというのを軽く振り返ってみます。

Ansible が動作するサーバをコントロールノード、制御対象をマネージドノードと呼びます。流れを大まかに説明しますと、この図のようになります。

• â‘  YAMLで書かれたプレイブックからタスクごとに小さなプログラムを生成する
• â‘¡ ①で生成した小さなプログラムをマネージドノードに送り込む
• â‘¢ マネージドノードで適切なインタプリタを検出して、それを使って処理を実行する
• â‘£ 処理結果を JSON 形式で返す

このマネージドノードはコントロールノード自身になることもあります。たとえばクラウドやネットワーク機器を制御したい場合には、③の処理で REST API を呼び出したり、機器に対して対話的な処理を行ったりします。

マネージドノードへの接続方式や実行環境については、標準設定ではこちらの表に従います。今回の記事では、Linux サーバに対して SSH で接続するときのお話をします。

マネージドノード	接続方式	検出する実行環境
コントロールノード自身	local	Python
Linuxサーバ	SSH	Python
Windowsサーバ	WinRM	PowerShell

Ansible での主なトラブル

上記の図で説明しました①〜④がきちんと動作しないと Ansible は自動化の処理を実行できないため、プレイブックが動かないというときにはそれぞれに確認するポイントがあります。

問い合わせを受けたときは例えばこのようなものを確認します。問題によってはこの他にも確認するものはあります。

① コントロールノードの問題

• Ansible がインストールされていない
• YAML の文法が間違っている
• コレクションが参照できない
• 変数や認証情報が参照できない
• Python の実行環境が正しく設定されていない
• 暗号化データを取り扱うことや実行可能なスクリプトを生成することがウイルススキャンサービスによって阻害されている

② SSH でのマネージドノードへの接続の問題

• ファイアウォールで通信が許可されていない (通常は 22/tcp)
• 名前解決ができない
• マネージドノードへのルーティングがない
• マネージドノードで SSH のサービスが起動していない
• コントロールノードから直接接続できないときに踏み台等を経由する設定が正しくない
• 認証ができない
  • ユーザ名とパスワードの組み合わせが正しくない
  • パスワードの入力待ちになっている
  • 公開鍵と秘密鍵の組み合わせが正しくない
  • StrictHostKeyChecking が有効になっていてホスト鍵の確認を求められる
  • 暗号化スイートが双方で適合するものがない (強いのを要求されるのに弱いのしかないなど)
  • 他の認証の仕組みとの連携に問題がある (Kerberos ã‚„ SSO (Single Sign On) など)
• 接続ユーザにホームディレクトリがなく、ファイルが書き込めない
• 22/tcp は許可されているものの、必要な通信を中継機器で遮断している

③ マネージドノードでの動作の問題

• Python インタプリタがインストールされていない
• Python インタプリタを検出できない
• 検出された Python インタプリタに必要なライブラリがインストールされていない
• 接続したユーザにスクリプトを実行する権限がない
• 外から送り込まれた実行可能なスクリプトの実行がウイルススキャンサービスによって阻害されている
• 処理に時間がかかりすぎて接続がタイムアウトする
• 大量にデータを生成してディスクがあふれる

④ マネージドノードから結果を受け取るときの問題

• 処理結果が膨大すぎて接続がタイムアウトする
• 大量にデータを受け取ってコントロールノード側のディスクがあふれる (fact を使うときなど)
• 処理結果が文字化けしている

Ansible のデバッグレベル

ansible-playbook コマンドでは、-v (--verbose) でデバッグレベルを指定します。現在のバージョン (Ansible Core 2.13) では、-vvvvvv (v が6つ) まで指定できます。多いほどより詳細なログが出力されます。主に使うのは -vvvv (v が4つ) です。Windows のときは5つ指定した情報を取得します。

docs.ansible.com

vの数	意味合い
(指定しない)	通常の出力
v	verbose
vv	more verbose
vvv	debug
vvvv	connection debug
vvvvv	WinRM debug
vvvvvv	(下記リンク先のコードでしか使われてなさそうです)

github.com

その他、ANSIBLE_DEBUG 変数を true にすることで、Python の処理に深く切り込んでいくことができます。

実際の例

このような簡単なプレイブックを用意してみました。

---
- hosts: all
  gather_facts: false

  tasks:
    - name: ping
      ansible.builtin.ping:

インベントリファイルも用意しておきます。

[RHEL8]
192.168.0.130
192.168.0.131
192.168.0.132

[RHEL8:vars]
ansible_user=sugimura
ansible_password=XXXXXXXX

実行します。

$ ansible-playbook -i inventory ping.yml 

PLAY [all] **********************************************************************************************************************************************************************************

TASK [ping] *********************************************************************************************************************************************************************************
ok: [192.168.0.131]
ok: [192.168.0.132]
ok: [192.168.0.130]

PLAY RECAP **********************************************************************************************************************************************************************************
192.168.0.130              : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   
192.168.0.131              : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   
192.168.0.132              : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   

これを -vvvv (vが4つ) で実行すると、このようにさまざまな情報が出力されます。

$ ansible-playbook -i inventory ping.yml -vvvv
ansible-playbook [core 2.13.0]
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/home/sugimura/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python3.9/site-packages/ansible
  ansible collection location = /home/sugimura/.ansible/collections:/usr/share/ansible/collections
  executable location = /usr/bin/ansible-playbook
  python version = 3.9.7 (default, Sep 13 2021, 08:18:39) [GCC 8.5.0 20210514 (Red Hat 8.5.0-3)]
  jinja version = 3.0.3
  libyaml = True
Using /etc/ansible/ansible.cfg as config file
setting up inventory plugins
host_list declined parsing /home/sugimura/inventory as it did not pass its verify_file() method
script declined parsing /home/sugimura/inventory as it did not pass its verify_file() method
auto declined parsing /home/sugimura/inventory as it did not pass its verify_file() method
Parsed /home/sugimura/inventory inventory source with ini plugin
Loading callback plugin default of type stdout, v2.0 from /usr/lib/python3.9/site-packages/ansible/plugins/callback/default.py
Skipping callback 'default', as we already have a stdout callback.
Skipping callback 'minimal', as we already have a stdout callback.
Skipping callback 'oneline', as we already have a stdout callback.

PLAYBOOK: ping.yml **************************************************************************************************************************************************************************
Positional arguments: ping.yml
verbosity: 4
connection: smart
timeout: 10
become_method: sudo
tags: ('all',)
inventory: ('/home/sugimura/inventory',)
forks: 5
1 plays in ping.yml

PLAY [all] **********************************************************************************************************************************************************************************
META: ran handlers

TASK [ping] *********************************************************************************************************************************************************************************
task path: /home/sugimura/ping.yml:6
<192.168.0.130> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.131> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.130> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/72daa41b21"' 192.168.0.130 '/bin/sh -c '"'"'echo ~sugimura && sleep 0'"'"''
<192.168.0.131> SSH: EXEC sshpass -d12 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/1f1a06c0f9"' 192.168.0.131 '/bin/sh -c '"'"'echo ~sugimura && sleep 0'"'"''
<192.168.0.132> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.132> SSH: EXEC sshpass -d14 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' 192.168.0.132 '/bin/sh -c '"'"'echo ~sugimura && sleep 0'"'"''

...

さらに、ANSIBLE_DEBUG=true もつけるとさらに詳しい情報が出てきます。実行に取り掛かる前にも設定ファイルの解釈やモジュールの読み込み、実行時刻など、さまざまな情報が取得できます。

$ ANSIBLE_DEBUG=true ansible-playbook -i inventory ping.yml -vvvv
1522811 1664675100.64203: starting run
ansible-playbook [core 2.13.0]
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/home/sugimura/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python3.9/site-packages/ansible
  ansible collection location = /home/sugimura/.ansible/collections:/usr/share/ansible/collections
  executable location = /usr/bin/ansible-playbook
  python version = 3.9.7 (default, Sep 13 2021, 08:18:39) [GCC 8.5.0 20210514 (Red Hat 8.5.0-3)]
  jinja version = 3.0.3
  libyaml = True
Using /etc/ansible/ansible.cfg as config file
1522811 1664675100.64446: Added group all to inventory
1522811 1664675100.64449: Added group ungrouped to inventory
1522811 1664675100.64453: Group all now contains ungrouped
1522811 1664675100.64456: Examining possible inventory source: /home/sugimura/inventory
setting up inventory plugins
1522811 1664675100.64552: trying /usr/share/ansible/plugins/cache
1522811 1664675100.64557: trying /usr/lib/python3.9/site-packages/ansible/plugins/cache
1522811 1664675100.64591: Loading CacheModule 'memory' from /usr/lib/python3.9/site-packages/ansible/plugins/cache/memory.py (searched paths: /usr/lib/python3.9/site-packages/ansible/plugins/cache:/usr/share/ansible/plugins/cache)
1522811 1664675100.64606: trying /usr/share/ansible/plugins/inventory
1522811 1664675100.64609: trying /usr/lib/python3.9/site-packages/ansible/plugins/inventory
1522811 1664675100.64649: Loading InventoryModule 'host_list' from /usr/lib/python3.9/site-packages/ansible/plugins/inventory/host_list.py (searched paths: /usr/lib/python3.9/site-packages/ansible/plugins/inventory:/usr/share/ansible/plugins/inventory)
1522811 1664675100.64698: Loaded config def from plugin (inventory/script)
1522811 1664675100.64701: Loading InventoryModule 'script' from /usr/lib/python3.9/site-packages/ansible/plugins/inventory/script.py (searched paths: /usr/lib/python3.9/site-packages/ansible/plugins/inventory:/usr/share/ansible/plugins/inventory)
1522811 1664675100.64727: Loading InventoryModule 'auto' from /usr/lib/python3.9/site-packages/ansible/plugins/inventory/auto.py (searched paths: /usr/lib/python3.9/site-packages/ansible/plugins/inventory:/usr/share/ansible/plugins/inventory)
1522811 1664675100.64767: Loaded config def from plugin (inventory/yaml)
...
PLAYBOOK: ping.yml **************************************************************************************************************************************************************************
Positional arguments: ping.yml
verbosity: 4
connection: smart
timeout: 10
become_method: sudo
tags: ('all',)
inventory: ('/home/sugimura/inventory',)
forks: 5
1 plays in ping.yml

...
1522816 1664675100.74991: _low_level_execute_command(): starting
1522816 1664675100.74996: _low_level_execute_command(): executing: /bin/sh -c 'echo ~sugimura && sleep 0'
<192.168.0.131> ESTABLISH SSH CONNECTION FOR USER: sugimura
1522818 1664675100.75114: running TaskExecutor() for 192.168.0.132/TASK: ping
1522818 1664675100.75153: in run() - task 00505699-f612-50dd-9ea3-00000000000a
1522818 1664675100.75163: variable 'ansible_search_path' from source: unknown
1522818 1664675100.75179: calling self._execute()
1522818 1664675100.75206: variable 'ansible_user' from source: group vars, precedence entry 'groups_inventory'
1522818 1664675100.75209: variable 'ansible_password' from source: group vars, precedence entry 'groups_inventory'
1522818 1664675100.75214: variable 'omit' from source: magic vars
1522818 1664675100.75264: variable 'omit' from source: magic vars
<192.168.0.130> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/72daa41b21"' 192.168.0.130 '/bin/sh -c '"'"'echo ~sugimura && sleep 0'"'"''
1522818 1664675100.75279: variable 'omit' from source: magic vars
1522818 1664675100.75313: trying /usr/share/ansible/plugins/connection
1522818 1664675100.75324: trying /usr/lib/python3.9/site-packages/ansible/plugins/connection
1522818 1664675100.75355: Loading Connection 'ssh' from /usr/lib/python3.9/site-packages/ansible/plugins/connection/ssh.py (searched paths: /usr/share/ansible/plugins/connection:/usr/lib/python3.9/site-packages/ansible/plugins/connection) (found_in_cache=True, class_only=False)
...

SSH の通信をデバッグする

ようやく今回の本題です。このデバッグ情報を元にして、どのように通信を追いかけていくのかを紹介します。

ここではこのような問題を考えます。

• RHEL のターミナルから ssh コマンドを使ってマネージドノードに接続して、コマンドの実行はできるものの、プレイブックを実行すると結果が返らずタイムアウトとなる。
• コントロールノードとマネージドノードの間には VPN 機器がある。
• 通常のトラブルシューティングを行った結果、SSH の通信内容が怪しいと思われるところまでは絞り込んだ。(ここまでがまた大変ではありましたが)

そこで、ANSIBLE_DEBUG=true での詳細情報から、SSH での接続を読み解いていきます。上から順に追いかけます。

1. ssh で接続することを設定する

本当に ssh を使おうとしているのか、どのようなパラメータが設定されているかを確認します。いまの Ansible の実装では、接続部分はプラグインに切り離されています。コードを追いかけるときにはどのプラグインが使われているかを把握することが必要です。

1523091 1664675304.99557: trying /usr/share/ansible/plugins/connection
1523091 1664675304.99562: trying /usr/lib/python3.9/site-packages/ansible/plugins/connection
1523091 1664675304.99579: Loading Connection 'ssh' from /usr/lib/python3.9/site-packages/ansible/plugins/connection/ssh.py (searched paths: /usr/share/ansible/plugins/connection:/usr/lib/python3.9/site-packages/ansible/plugins/connection) (found_in_cache=True, class_only=False)
1523091 1664675304.99589: trying /usr/lib/python3.9/site-packages/ansible/plugins/shell
1523091 1664675304.99597: Loading ShellModule 'sh' from /usr/lib/python3.9/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
1523091 1664675304.99603: Loading ShellModule 'sh' from /usr/lib/python3.9/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
1523091 1664675304.99619: variable 'inventory_hostname' from source: host vars for '192.168.0.132'
1523091 1664675304.99621: variable 'ansible_password' from source: group vars, precedence entry 'groups_inventory'
1523091 1664675304.99623: variable 'ansible_user' from source: group vars, precedence entry 'groups_inventory'
1523091 1664675304.99692: Set connection var ansible_module_compression to ZIP_DEFLATED
1523091 1664675304.99697: Set connection var ansible_timeout to 10
1523091 1664675304.99699: Set connection var ansible_shell_executable to /bin/sh
1523091 1664675304.99703: Set connection var ansible_pipelining to False
1523091 1664675304.99705: Set connection var ansible_shell_type to sh
1523091 1664675304.99707: Set connection var ansible_connection to ssh
1523091 1664675304.99709: Set connection var ansible_host to 192.168.0.132
...

2. ssh コマンドで接続確認用のコマンドを発行する

実行しているコマンドがログに記録されています。sshpass -d10 ssh -vvv ... のところです。ホームディレクトリがあることを確認しています。

1523091 1664675304.99812: _low_level_execute_command(): starting
1523091 1664675304.99819: _low_level_execute_command(): executing: /bin/sh -c 'echo ~sugimura && sleep 0'
<192.168.0.132> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.132> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' 192.168.0.132 '/bin/sh -c '"'"'echo ~sugimura && sleep 0'"'"''

さらに、ssh コマンドのデバッグログ ssh -vvv が出力されてきます。パケットの気持ちになって、それぞれ処理を読み解いていきます。

• 設定ファイル /home/sugimura/.ssh/config, /etc/ssh/ssh_config, そこから include されているファイル
• 提案する鍵交換アルゴリズム (ここでは diffie-hellman-group-exchange-sha1) が RHEL の crypto policy に合致しているか
• 通信のための socket が確立されたか
• リクエストを送信できたか (<<<)
• レスポンスが得られたか (>>>)

1523091 1664675305.00773: stderr chunk (state=2):
>>>OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021
debug1: Reading configuration data /home/sugimura/.ssh/config
debug3: kex names ok: [diffie-hellman-group-exchange-sha1]
debug1: Reading configuration data /etc/ssh/ssh_config
debug3: /etc/ssh/ssh_config line 54: Including file /etc/ssh/ssh_config.d/05-redhat.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/05-redhat.conf
<<<
1523091 1664675305.00791: stderr chunk (state=3):
>>>debug2: checking match for 'final all' host 192.168.0.132 originally 192.168.0.132
debug3: /etc/ssh/ssh_config.d/05-redhat.conf line 3: not matched 'final'
debug2: match not found
debug3: /etc/ssh/ssh_config.d/05-redhat.conf line 5: Including file /etc/crypto-policies/back-ends/openssh.config depth 1 (parse only)
debug1: Reading configuration data /etc/crypto-policies/back-ends/openssh.config
debug3: gss kex names ok: [gss-curve25519-sha256-,gss-nistp256-sha256-,gss-group14-sha256-,gss-group16-sha512-,gss-gex-sha1-,gss-group14-sha1-]
debug3: kex names ok: [curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1]
debug1: configuration requests final Match pass
debug2: resolve_canonicalize: hostname 192.168.0.132 is address
debug1: re-parsing configuration
debug1: Reading configuration data /home/sugimura/.ssh/config
debug3: kex names ok: [diffie-hellman-group-exchange-sha1]
debug1: Reading configuration data /etc/ssh/ssh_config
debug3: /etc/ssh/ssh_config line 54: Including file /etc/ssh/ssh_config.d/05-redhat.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/05-redhat.conf
debug2: checking match for 'final all' host 192.168.0.132 originally 192.168.0.132
debug3: /etc/ssh/ssh_config.d/05-redhat.conf line 3: matched 'final'
debug2: match found
debug3: /etc/ssh/ssh_config.d/05-redhat.conf line 5: Including file /etc/crypto-policies/back-ends/openssh.config depth 1
debug1: Reading configuration data /etc/crypto-policies/back-ends/openssh.config
debug3: gss kex names ok: [gss-curve25519-sha256-,gss-nistp256-sha256-,gss-group14-sha256-,gss-group16-sha512-,gss-gex-sha1-,gss-group14-sha1-]
debug3: kex names ok: [curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1]
<<<
1523091 1664675305.00803: stderr chunk (state=3):
>>>debug1: auto-mux: Trying existing master
debug2: fd 4 setting O_NONBLOCK
<<<
1523091 1664675305.00820: stderr chunk (state=3):
>>>debug2: mux_client_hello_exchange: master version 4
debug3: mux_client_forwards: request forwardings: 0 local, 0 remote
debug3: mux_client_request_session: entering
debug3: mux_client_request_alive: entering
debug3: mux_client_request_alive: done pid = 1523069
debug3: mux_client_request_session: session request sent
<<<
1523091 1664675305.03130: stdout chunk (state=3):
>>>/home/sugimura
<<<
1523091 1664675305.03203: stderr chunk (state=3):
>>>debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
<<<
1523091 1664675305.03270: stderr chunk (state=3):
>>><<<
1523091 1664675305.03278: stdout chunk (state=3):
>>><<<
<192.168.0.132> (0, b'/home/sugimura\n', b"OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021\r\ndebug1: Reading configuration data /home/sugimura/.ssh/config\r\ndebug3: kex names ok: [diffie-hellman-group-exchange-sha1]\r\ndebug1:
...

3. Python のプログラムを送信する準備をする

ホームディレクトリがあることが確認できたので、SSH の通信セッションを使って Python のプログラムを送り込むためのディレクトリを作成する処理を見ていきます。

ここでも同様に入出力を見ます。

• リクエストを送信できたか (<<<)
• レスポンスが得られたか (>>>)
• 正常終了したか (rc=0)

もし失敗すると、他の /tmp 等のディレクトリに作成できないかを試みたりすることがあります。パーミッションの問題があるときはシェルに設定されている umask の値や、/etc/login.defs などに定義されているシステムワイドでの umask を確認します。ファイルシステムの mount オプションを疑うこともあります。

1523091 1664675305.03317: _low_level_execute_command(): starting
1523091 1664675305.03323: _low_level_execute_command(): executing: /bin/sh -c '( umask 77 && mkdir -p "` echo /home/sugimura/.ansible/tmp `"&& mkdir "` echo /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486 `" && echo ansible-tmp-1664675305.0331209-1523091-142821774396486="` echo /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486 `" ) && sleep 0'
<192.168.0.132> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.132> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' 192.168.0.132 '/bin/sh -c '"'"'( umask 77 && mkdir -p "` echo /home/sugimura/.ansible/tmp `"&& mkdir "` echo /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486 `" && echo ansible-tmp-1664675305.0331209-1523091-142821774396486="` echo /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486 `" ) && sleep 0'"'"''
1523091 1664675305.03972: stderr chunk (state=2):
>>>OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021
...
debug1: auto-mux: Trying existing master
debug2: fd 4 setting O_NONBLOCK
<<<
1523091 1664675305.28372: stderr chunk (state=3):
>>>debug2: mux_client_hello_exchange: master version 4
debug3: mux_client_forwards: request forwardings: 0 local, 0 remote
debug3: mux_client_request_session: entering
debug3: mux_client_request_alive: entering
<<<
1523091 1664675305.28381: stderr chunk (state=3):
>>>debug3: mux_client_request_alive: done pid = 1523069
debug3: mux_client_request_session: session request sent
<<<
1523091 1664675305.30525: stderr chunk (state=3):
>>>debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
<<<
1523091 1664675305.30614: stderr chunk (state=3):
>>><<<
1523091 1664675305.30624: stdout chunk (state=3):
>>><<<
<192.168.0.132> (0, b'', b"OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021\r\ndebug1: Reading configuration data /home/sugimura/.ssh/config\r\ndebug3: kex names ok: [diffie-hellman-group-exchange-sha1]\r\ndebug1: Reading 
...
1523091 1664675305.06308: _low_level_execute_command() done: rc=0, stdout=ansible-tmp-1664675305.0331209-1523091-142821774396486=/home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486
, stderr=OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021
...

4. マネージドノードの Python インタプリタを検出する

ping モジュールからは Python の小さなプログラムを生成したため、それをマネージドノードで実行するために利用できるものがあるかどうかを探します。 モジュールによっては debug モジュールのように Python インタプリタを必要としないものもあるため、モジュールを解釈しなければこの処理に入りません。

Python インタプリタの検出について、外側から見た大まかな概要についてはこちらの記事もご覧ください。

rheb.hatenablog.com

1523091 1664675305.06391: ANSIBALLZ: Using lock for ansible.builtin.ping
1523091 1664675305.06394: ANSIBALLZ: Acquiring lock
1523091 1664675305.06397: ANSIBALLZ: Lock acquired: 139933950381504
1523091 1664675305.06399: ANSIBALLZ: Creating module
1523091 1664675305.15378: ANSIBALLZ: Writing module into payload
1523091 1664675305.15434: ANSIBALLZ: Writing module
1523091 1664675305.15450: ANSIBALLZ: Renaming module
1523091 1664675305.15454: ANSIBALLZ: Done creating module
1523091 1664675305.15472: variable 'ansible_facts' from source: unknown
1523091 1664675305.15476: variable 'inventory_hostname' from source: host vars for '192.168.0.132'
<192.168.0.132> Attempting python interpreter discovery
1523091 1664675305.15485: _low_level_execute_command(): starting
1523091 1664675305.15490: _low_level_execute_command(): executing: /bin/sh -c 'echo PLATFORM; uname; echo FOUND; command -v '"'"'python3.10'"'"'; command -v '"'"'python3.9'"'"'; command -v '"'"'python3.8'"'"'; command -v '"'"'python3.7'"'"'; command -v '"'"'python3.6'"'"'; command -v '"'"'python3.5'"'"'; command -v '"'"'/usr/bin/python3'"'"'; command -v '"'"'/usr/libexec/platform-python'"'"'; command -v '"'"'python2.7'"'"'; command -v '"'"'/usr/bin/python'"'"'; command -v '"'"'python'"'"'; echo ENDFOUND && sleep 0'
<192.168.0.132> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.132> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' 192.168.0.132 '/bin/sh -c '"'"'echo PLATFORM; uname; echo FOUND; command -v '"'"'"'"'"'"'"'"'python3.10'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'python3.9'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'python3.8'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'python3.7'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'python3.6'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'python3.5'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'/usr/bin/python3'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'/usr/libexec/platform-python'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'python2.7'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'/usr/bin/python'"'"'"'"'"'"'"'"'; command -v '"'"'"'"'"'"'"'"'python'"'"'"'"'"'"'"'"'; echo ENDFOUND && sleep 0'"'"''
1523091 1664675305.16121: stderr chunk (state=2):
>>>OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021
...
<<<
1523091 1664675305.18538: stdout chunk (state=3):
>>>PLATFORM
<<<
1523091 1664675305.18587: stdout chunk (state=3):
>>>Linux
<<<
1523091 1664675305.18621: stdout chunk (state=3):
>>>FOUND
/usr/bin/python3.9
/usr/bin/python3
/usr/libexec/platform-python
ENDFOUND
<<<
1523091 1664675305.18779: stderr chunk (state=3):
>>>debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
<<<
1523091 1664675305.18796: stderr chunk (state=3):
>>><<<
1523091 1664675305.18801: stdout chunk (state=3):
>>><<<
...
1523091 1664675305.18826: _low_level_execute_command() done: rc=0, stdout=PLATFORM
Linux
FOUND
/usr/bin/python3.9
/usr/bin/python3
/usr/libexec/platform-python
ENDFOUND
, stderr=OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021
...
1523091 1664675305.18836 [192.168.0.132]: found interpreters: ['/usr/bin/python3.9', '/usr/bin/python3', '/usr/libexec/platform-python']

5. 検出した Python インタプリタを調べる

Python インタプリタを実際に実行して、結果を得ることができるかを確認しています。1234 bytes の何か小さなデータを送っていることはわかりますが、その内容はログには出てきていませんでした。OS についての情報を収集して結果が JSON で返されていることがわかります。

ここでも入出力と rc=0 (正常終了) であることを確認します。

1523091 1664675305.18877: _low_level_execute_command(): starting
1523091 1664675305.18885: _low_level_execute_command(): executing: /bin/sh -c '/usr/bin/python3.9 && sleep 0'
<192.168.0.132> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.132> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' 192.168.0.132 '/bin/sh -c '"'"'/usr/bin/python3.9 && sleep 0'"'"''
1523091 1664675305.19179: Sending initial data
1523091 1664675305.19195: Sent initial data (1234 bytes)
...
<<<
1523091 1664675305.19553: stderr chunk (state=3):
>>>debug3: mux_client_request_alive: done pid = 1523069
debug3: mux_client_request_session: session request sent
<<<
1523091 1664675305.23304: stdout chunk (state=3):
>>>{"platform_dist_result": [], "osrelease_content": "NAME=\"Red Hat Enterprise Linux\"\nVERSION=\"8.6 (Ootpa)\"\nID=\"rhel\"\nID_LIKE=\"fedora\"\nVERSION_ID=\"8.6\"\nPLATFORM_ID=\"platform:el8\"\nPRETTY_NAME=\"Red Hat Enterprise Linux 8.6 (Ootpa)\"\nANSI_COLOR=\"0;31\"\nCPE_NAME=\"cpe:/o:redhat:enterprise_linux:8::baseos\"\nHOME_URL=\"https://www.redhat.com/\"\nDOCUMENTATION_URL=\"https://access.redhat.com/documentation/red_hat_enterprise_linux/8/\"\nBUG_REPORT_URL=\"https://bugzilla.redhat.com/\"\n\nREDHAT_BUGZILLA_PRODUCT=\"Red Hat Enterprise Linux 8\"\nREDHAT_BUGZILLA_PRODUCT_VERSION=8.6\nREDHAT_SUPPORT_PRODUCT=\"Red Hat Enterprise Linux\"\nREDHAT_SUPPORT_PRODUCT_VERSION=\"8.6\"\n"}
<<<
1523091 1664675305.23927: stderr chunk (state=3):
>>>debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
<<<
1523091 1664675305.23952: stderr chunk (state=3):
>>><<<
1523091 1664675305.23955: stdout chunk (state=3):
>>><<<
...
1523091 1664675305.23973: _low_level_execute_command() done: rc=0, stdout={"platform_dist_result": [], "osrelease_content": "NAME=\"Red Hat Enterprise Linux\"\nVERSION=\"8.6 (Ootpa)\"\nID=\"rhel\"\nID_LIKE=\"fedora\"\nVERSION_ID=\"8.6\"\nPLATFORM_ID=\"platform:el8\"\nPRETTY_NAME=\"Red Hat Enterprise Linux 8.6 (Ootpa)\"\nANSI_COLOR=\"0;31\"\nCPE_NAME=\"cpe:/o:redhat:enterprise_linux:8::baseos\"\nHOME_URL=\"https://www.redhat.com/\"\nDOCUMENTATION_URL=\"https://access.redhat.com/documentation/red_hat_enterprise_linux/8/\"\nBUG_REPORT_URL=\"https://bugzilla.redhat.com/\"\n\nREDHAT_BUGZILLA_PRODUCT=\"Red Hat Enterprise Linux 8\"\nREDHAT_BUGZILLA_PRODUCT_VERSION=8.6\nREDHAT_SUPPORT_PRODUCT=\"Red Hat Enterprise Linux\"\nREDHAT_SUPPORT_PRODUCT_VERSION=\"8.6\"\n"}
, stderr=OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021

6. ping モジュールから生成された Python のプログラムを送信する

ここまで来てやっと、ping モジュールから生成した Python のプログラムを送信します。ping.py を元にして AnsiballZ_ping.py を生成し、sftp で送信しています。

ファイルを送信して相手先に書き込むというのはこれまでのコマンドの実行と比べるとそれなりに複雑なため、注意深く見ていく必要があります。

1523091 1664675305.24066: variable 'ansible_facts' from source: unknown
1523091 1664675305.24071: variable 'ansible_facts' from source: unknown
1523091 1664675305.24098: ANSIBALLZ: using cached module: /home/sugimura/.ansible/tmp/ansible-local-1523087yurgsn13/ansiballz_cache/ansible.modules.ping-ZIP_DEFLATED
1523091 1664675305.24123: variable 'ansible_facts' from source: unknown
Using module file /usr/lib/python3.9/site-packages/ansible/modules/ping.py
1523091 1664675305.24179: transferring module to remote /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/AnsiballZ_ping.py
<192.168.0.132> PUT /home/sugimura/.ansible/tmp/ansible-local-1523087yurgsn13/tmpl67x1t1y TO /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/AnsiballZ_ping.py
<192.168.0.132> SSH: EXEC sshpass -d10 sftp -o BatchMode=no -b - -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' '[192.168.0.132]'
1523091 1664675305.24611: Sending initial data
1523091 1664675305.24627: Sent initial data (175 bytes)
1523091 1664675305.25089: stderr chunk (state=3):
>>>OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021
...
debug3: kex names ok: [curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1]
<<<
1523091 1664675305.25115: stderr chunk (state=3):
>>>debug1: auto-mux: Trying existing master
debug2: fd 4 setting O_NONBLOCK
<<<
1523091 1664675305.25134: stderr chunk (state=3):
>>>debug2: mux_client_hello_exchange: master version 4
debug3: mux_client_forwards: request forwardings: 0 local, 0 remote
debug3: mux_client_request_session: entering
debug3: mux_client_request_alive: entering
debug3: mux_client_request_alive: done pid = 1523069
<<<
1523091 1664675305.25140: stderr chunk (state=3):
>>>debug3: mux_client_request_session: session request sent
<<<
1523091 1664675305.26885: stderr chunk (state=3):
>>>debug2: Remote version: 3
debug2: Server supports extension "[email protected]" revision 1
debug2: Server supports extension "[email protected]" revision 2
debug2: Server supports extension "[email protected]" revision 2
debug2: Server supports extension "[email protected]" revision 1
debug2: Server supports extension "[email protected]" revision 1
debug2: Server supports extension "[email protected]" revision 1
debug3: Sent message fd 3 T:16 I:1
<<<
1523091 1664675305.26918: stderr chunk (state=3):
>>>debug3: SSH_FXP_REALPATH . -> /home/sugimura size 0
debug3: Looking up /home/sugimura/.ansible/tmp/ansible-local-1523087yurgsn13/tmpl67x1t1y
debug3: Sent message fd 3 T:17 I:2
<<<
1523091 1664675305.26927: stdout chunk (state=3):
>>>sftp> put /home/sugimura/.ansible/tmp/ansible-local-1523087yurgsn13/tmpl67x1t1y /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/AnsiballZ_ping.py
<<<
1523091 1664675305.26938: stderr chunk (state=3):
>>>debug3: Received stat reply T:101 I:2
debug1: Couldn't stat remote file: No such file or directory
debug3: Sent message SSH2_FXP_OPEN I:3 P:/home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/AnsiballZ_ping.py
<<<
1523091 1664675305.26968: stderr chunk (state=3):
>>>debug3: Sent message SSH2_FXP_WRITE I:4 O:0 S:32768
<<<
1523091 1664675305.27142: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
debug3: In write loop, ack for 4 32768 bytes at 0
debug3: Sent message SSH2_FXP_WRITE I:5 O:32768 S:32768
debug3: Sent message SSH2_FXP_WRITE I:6 O:65536 S:32768
debug3: Sent message SSH2_FXP_WRITE I:7 O:98304 S:28929
<<<
1523091 1664675305.27425: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
debug3: In write loop, ack for 5 32768 bytes at 32768
<<<
1523091 1664675305.27454: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
debug3: In write loop, ack for 6 32768 bytes at 65536
<<<
1523091 1664675305.27470: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
debug3: In write loop, ack for 7 28929 bytes at 98304
debug3: Sent message SSH2_FXP_CLOSE I:4
<<<
1523091 1664675305.27488: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
<<<
1523091 1664675305.27539: stderr chunk (state=3):
>>>debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
<<<
1523091 1664675305.27634: stderr chunk (state=3):
>>><<<
1523091 1664675305.27645: stdout chunk (state=3):
>>><<<
...
1523091 1664675305.27677: done transferring module to remote

7. ping モジュールから生成された Python のプログラムに実行権限を付与する

無事 AnsiballZ_ping.py を送りつけたら、実行権限を付与します。chmod u+x コマンドを実行しています。

こういうコマンドでもマネージドノード上の設定によっては何らかの理由で失敗する場合があるので、注意深く見ていく必要があります。chmod の失敗はファイルシステム (LVM や NFS など) の設定が疑わしいことがあります。

1523091 1664675305.27690: _low_level_execute_command(): starting
1523091 1664675305.27695: _low_level_execute_command(): executing: /bin/sh -c 'chmod u+x /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/ /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/AnsiballZ_ping.py && sleep 0'
<192.168.0.132> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.132> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' 192.168.0.132 '/bin/sh -c '"'"'chmod u+x /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/ /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/AnsiballZ_ping.py && sleep 0'"'"''
1523091 1664675305.28351: stderr chunk (state=2):
...
1523091 1664675305.30648: _low_level_execute_command() done: rc=0, stdout=, stderr=OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021

8. ping モジュールから生成された Python のプログラムを実行する

ようやくモジュールを実行します。4. では ['/usr/bin/python3.9', '/usr/bin/python3', '/usr/libexec/platform-python'] の Python インタプリタを検出して 5. では最初の /usr/bin/python3.9 で実行していましたが、5. の処理結果からはマネージドノードの OS は RHEL 8 であることが判断できたので、INTERPRETER_PYTHON_DISTRO_MAP の定義から RHEL 8 を探して /usr/libexec/platform-python を使って実行します。この定義は ansible-config dump で確認できます。

$ ansible-config dump | grep INTERPRETER
INTERPRETER_PYTHON(default) = auto
INTERPRETER_PYTHON_DISTRO_MAP(default) = {'redhat': {'6': '/usr/bin/python', '8': '/usr/libexec/platform-python', '9': '/usr/bin/python3'}, 'debian': {'8': '/usr/bin/python', '10': '/usr/bin/python3'}, 'fedora': {'23': '/usr/bin/python3'}, 'ubuntu': {'14': '/usr/bin/python', '16': '/usr/bin/python3'}}
INTERPRETER_PYTHON_FALLBACK(default) = ['python3.10', 'python3.9', 'python3.8', 'python3.7', 'python3.6', 'python3.5', '/usr/bin/python3', '/usr/libexec/platform-python', 'python2.7', '/usr/bin/python', 'python']

このように /usr/libexec/platform-python で AnsiballZ_ping.py を実行しています。>>> のレスポンスを見ると ”pong” が返されていることがわかります。Ansible のモジュールは JSON 形式で結果を返す約束になっています。

正常終了 (rc=0) も見ておきます。

1523091 1664675305.30654: _low_level_execute_command(): starting
1523091 1664675305.30659: _low_level_execute_command(): executing: /bin/sh -c '/usr/libexec/platform-python /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/AnsiballZ_ping.py && sleep 0'
<192.168.0.132> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.132> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' -tt 192.168.0.132 '/bin/sh -c '"'"'/usr/libexec/platform-python /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/AnsiballZ_ping.py && sleep 0'"'"''
1523091 1664675305.31222: stderr chunk (state=2):
>>>OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021
...
<<<
1523091 1664675305.31286: stderr chunk (state=3):
>>>debug3: mux_client_request_alive: done pid = 1523069
debug3: mux_client_request_session: session request sent
<<<
1523091 1664675305.43192: stdout chunk (state=3):
>>>
{"ping": "pong", "invocation": {"module_args": {"data": "pong"}}}
<<<
1523091 1664675305.44110: stderr chunk (state=3):
>>>debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
Shared connection to 192.168.0.132 closed.
<<<
1523091 1664675305.44191: stderr chunk (state=3):
>>><<<
1523091 1664675305.44199: stdout chunk (state=3):
>>><<<

...
1523091 1664675305.44222: _low_level_execute_command() done: rc=0, stdout=
{"ping": "pong", "invocation": {"module_args": {"data": "pong"}}}
, stderr=OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021
...
debug2: fd 4 setting O_NONBLOCK
debug2: mux_client_hello_exchange: master version 4
debug3: mux_client_forwards: request forwardings: 0 local, 0 remote
debug3: mux_client_request_session: entering
debug3: mux_client_request_alive: entering
debug3: mux_client_request_alive: done pid = 1523069
debug3: mux_client_request_session: session request sent
debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
Shared connection to 192.168.0.132 closed.
1523091 1664675305.44261: done with _execute_module (ansible.builtin.ping, {'_ansible_check_mode': False, '_ansible_no_log': False, '_ansible_debug': True, '_ansible_diff': False, '_ansible_verbosity': 4, '_ansible_version': '2.13.0', '_ansible_module_name': 'ansible.builtin.ping', '_ansible_syslog_facility': 'LOG_USER', '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p', 'vfat'], '_ansible_string_conversion_action': 'warn', '_ansible_socket': None, '_ansible_shell_executable': '/bin/sh', '_ansible_keep_remote_files': False, '_ansible_tmpdir': '/home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/', '_ansible_remote_tmp': '~/.ansible/tmp'})

もし ping モジュールではなく他のモジュールでライブラリが足りないためにエラーとなるというようなことがあれば、ここのあたりを詳しく見ていくと Python のエラーが見つかることがあります。

9. ping モジュールから生成された Python のプログラムを削除する

モジュールの実行が終わったら、送りつけたプログラムをディレクトリごと削除します。3. で実行した mkdir コマンドに対応して、rm -f -r コマンドを実行しています。

1523091 1664675305.44269: _low_level_execute_command(): starting
1523091 1664675305.44273: _low_level_execute_command(): executing: /bin/sh -c 'rm -f -r /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/ > /dev/null 2>&1 && sleep 0'
<192.168.0.132> ESTABLISH SSH CONNECTION FOR USER: sugimura
<192.168.0.132> SSH: EXEC sshpass -d10 ssh -vvv -C -o ControlMaster=auto -o ControlPersist=60s -o 'User="sugimura"' -o ConnectTimeout=10 -o 'ControlPath="/home/sugimura/.ansible/cp/8577d474f2"' 192.168.0.132 '/bin/sh -c '"'"'rm -f -r /home/sugimura/.ansible/tmp/ansible-tmp-1664675305.0331209-1523091-142821774396486/ > /dev/null 2>&1 && sleep 0'"'"''
1523091 1664675305.44857: stderr chunk (state=2):
...
1523091 1664675305.47347: _low_level_execute_command() done: rc=0, stdout=, stderr=OpenSSH_8.0p1, OpenSSL 1.1.1k  FIPS 25 Mar 2021

10. モジュール実行の後処理

タスクの実行が終わったら、返されたデータの整形や後処理をします。

1523091 1664675305.47359: handler run complete
1523091 1664675305.47371: variable 'ansible_facts' from source: unknown
1523091 1664675305.47436: variable 'ansible_facts' from source: unknown
1523091 1664675305.47461: attempt loop complete, returning result
1523091 1664675305.47465: _execute() done
1523091 1664675305.47467: dumping result to json
1523091 1664675305.47469: done dumping result, returning
1523091 1664675305.47477: done running TaskExecutor() for 192.168.0.132/TASK: ping [00505699-f612-c152-b54d-000000000008]
1523091 1664675305.47480: sending task result for task 00505699-f612-c152-b54d-000000000008
1523091 1664675305.47527: done sending task result for task 00505699-f612-c152-b54d-000000000008
1523091 1664675305.47531: WORKER PROCESS EXITING
ok: [192.168.0.132] => {
    "ansible_facts": {
        "discovered_interpreter_python": "/usr/libexec/platform-python"
    },
    "changed": false,
    "invocation": {
        "module_args": {
            "data": "pong"
        }
    },
    "ping": "pong"
}
1523087 1664675305.47873: no more pending results, returning what we have

異常なとき

先ほど上で見たのは正常に動作している流れを追ってみたものです。

ANSIBLE_DEBUG=true で Ansible から見た処理としては意図通り流れている場合、より下のレイヤの SSH を追いかける必要があることがあります。

マネージドノードの /etc/ssh/sshd_config ファイルで LogLevel DEBUG3 として、sshd サービスを再起動します。

$ sudo su -
# systemctl restart sshd

そして再度 ansible-playbook -vvvv ... を実行して、マネージドノード側の /var/log/secure を見ます。例えば Python インタプリタを検出するあたりでは、このようなログが出ていました。

Oct  2 11:51:00 rhel86 sshd[24024]: debug3: receive packet: type 90
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: server_input_channel_open: ctype session rchan 2 win 2097152 max 32768
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: input_session_request
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: channel 0: new [server-session]
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_new: session 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_open: channel 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_open: session 0: link with channel 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: server_input_channel_open: confirm session
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: send packet: type 91
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: receive packet: type 98
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: server_input_channel_req: channel 0 request env reply 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_by_channel: session 0 channel 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_input_channel_req: session 0 req env
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: Setting env 0: LANG=ja_JP.UTF-8
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: receive packet: type 98
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: server_input_channel_req: channel 0 request exec reply 1
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_by_channel: session 0 channel 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_input_channel_req: session 0 req exec
Oct  2 11:51:00 rhel86 sshd[24024]: Starting session: command for sugimura from 192.168.0.130 port 35746 id 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: mm_audit_run_command entering command /bin/sh -c 'echo PLATFORM; uname; echo FOUND; command -v '"'"'python3.10'"'"'; command -v '"'"'python3.9'"'"'; command -v '"'"'python3.8'"'"'; command -v '"'"'python3.7'"'"'; command -v '"'"'python3.6'"'"'; command -v '"'"'python3.5'"'"'; command -v '"'"'/usr/bin/python3'"'"'; command -v '"'"'/usr/libexec/platform-python'"'"'; command -v '"'"'python2.7'"'"'; command -v '"'"'/usr/bin/python'"'"'; command -v '"'"'python'"'"'; echo ENDFOUND && sleep 0'
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: mm_request_send entering: type 114
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: mm_request_receive_expect entering: type 115
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: mm_request_receive entering
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: fd 17 setting O_NONBLOCK
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: fd 16 setting O_NONBLOCK
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: fd 19 setting O_NONBLOCK
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: mm_forward_audit_messages: entering
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: send packet: type 99
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: Received SIGCHLD.
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_by_pid: pid 24065
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_exit_message: session 0 channel 0 pid 24065
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: request exit-status confirm 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: send packet: type 98
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_exit_message: release channel 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: write failed
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: chan_shutdown_write (i0 o0 sock -1 wfd 16 efd 19 [read])
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: send eow
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: send packet: type 98
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: output open -> closed
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: read<=0 rfd 17 len 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: read failed
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: chan_shutdown_read (i0 o3 sock -1 wfd 17 efd 19 [read])
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: input open -> drain
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: read 0 from efd 19
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: closing read-efd 19
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: ibuf empty
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: send eof
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: send packet: type 96
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: input drain -> closed
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: send close
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: send packet: type 97
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: notify_done: reading
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: channel 0: will not send data after close
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: receive packet: type 97
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: rcvd close
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: channel 0: will not send data after close
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: is dead
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: gc: notify user
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_by_channel: session 0 channel 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: session_close_by_channel: channel 0 child 0
Oct  2 11:51:00 rhel86 sshd[24024]: Close session: user sugimura from 192.168.0.130 port 35746 id 0
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: mm_audit_end_command entering command /bin/sh -c 'echo PLATFORM; uname; echo FOUND; command -v '"'"'python3.10'"'"'; command -v '"'"'python3.9'"'"'; command -v '"'"'python3.8'"'"'; command -v '"'"'python3.7'"'"'; command -v '"'"'python3.6'"'"'; command -v '"'"'python3.5'"'"'; command -v '"'"'/usr/bin/python3'"'"'; command -v '"'"'/usr/libexec/platform-python'"'"'; command -v '"'"'python2.7'"'"'; command -v '"'"'/usr/bin/python'"'"'; command -v '"'"'python'"'"'; echo ENDFOUND && sleep 0'
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: mm_request_send entering: type 116
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: session_unused: session id 0 unused
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: gc: user detached
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: is dead
Oct  2 11:51:00 rhel86 sshd[24024]: debug2: channel 0: garbage collecting
Oct  2 11:51:00 rhel86 sshd[24024]: debug1: channel 0: free: server-session, nchannels 1
Oct  2 11:51:00 rhel86 sshd[24024]: debug3: channel 0: status: The following connections are open:\r\n  #0 server-session (t4 r2 i3/0 o3/0 e[closed]/0 fd -1/-1/-1 sock -1 cc -1)\r\n

このときに着目するのは主にこのようなものを見ていきます。

• SSH の type
• channel の open と close
• 送信と受信 (read, write)

SSH の type は、RFC 4250 に Message Numbers として定義されています。channel ではこのあたりを追いかけます。

• SSH_MSG_CHANNEL_OPEN 90
• SSH_MSG_CHANNEL_EOF 96
• SSH_MSG_CHANNEL_CLOSE 97
• SSH_MSG_CHANNEL_REQUEST 98
• SSH_MSG_CHANNEL_SUCCESS 99

datatracker.ietf.org

channel については RFC 4254 も同様に見ていきます。キーボードの入出力以外にも複数のやりとりを見えないところでできるようになっています。

datatracker.ietf.org

上のログからはこのような形で読み解いていきます。

• type 90 の要求に基づいて channel 0 を開く
• クライアントと channel 0 を使うことを合意
• mm_audit_run_command によるコマンド要求を受け付け
• channel 0 上で読み書き
• 終わったら session_close_by_channel で channel 0 を閉じる
• mm_audit_end_command でコマンド実行を終了

実際に問い合わせのあった事例だと、この type 90 のパケットは受信したもののネゴシエーションに至らず、channel が確立できなかったために Ansible のモジュール実行の入出力が正しく受け渡しできなかったことにより、コントロールノード側ではデータの受け取り待ちになってタイムアウトしたということがありました。

ssh コマンドでログインしただけですと新しく channel を確立することがないため、当初は問題に気がつくことはありませんでした。その後例えば vim コマンドでファイルを作成したりするとターミナル上で見えている画面の書き換えのために同様に新しく channel を確立する処理が実行されることがわかり、問題の特定や再現に役に立ったのを覚えています。

これが冒頭の例に挙げた「22/tcp は許可されているものの、必要な通信を中継機器で遮断している」によって発生したもので、VPN 装置側で全ての SSH の通信パケットを通していなかったことが疑わしいということで問題解消となりました。

まとめ

最も簡単な ping モジュールでの処理について、一通り何が行われているかを紹介しました。

SSH で接続してファイルを送受信したりコマンドの実行結果を受け取るということでも、これだけの深い内容があります。さらに認証や鍵交換なども含めるとそれぞれ掘り下げることがあります。

実際の数千以上あるモジュールではそれぞれ何らかの自動化の処理を実行しますので、トラブルの内容によってはその中身も追いかけることがあります。ここまでパケットのレベルまで見ていくことはあまり頻度は多くありませんが、問題によってさまざまな方法を試しています。

Ansible Automation Platform の評価ライセンスリクエストはこちらからご利用いただけます。60日間利用できます。

www.redhat.com

Happy Automation!