Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ansible pipelining breaks with tlog #349

Open
roth-wine opened this issue Sep 7, 2022 · 4 comments
Open

Ansible pipelining breaks with tlog #349

roth-wine opened this issue Sep 7, 2022 · 4 comments

Comments

@roth-wine
Copy link

Hi !
I've encountered an issue with Ansible in combination with Tlog on multiple Ubuntu 20.04 hosts. We need to delegate some tasks in several playbooks to other hosts. If the option pipelining=True is set and we try to perform a task with the delegate_to option on a host, which uses the tlog-rec-session shell, the task will fail. If we set the option pipelining=False the task will proceed as expected.
The behavior in relation to the pipelining option will also only happen, when the task get performed via delegate_to.
If the same task, get's processed without delegate_to, but on the same host and the option pipelining=True, everything will proceed as expected.

We manage the server with Ansible version 2.12.7 and option pipelining=True

~ ansible --version
ansible [core 2.12.7]
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/home/phil/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /home/phil/.local/lib/python3.10/site-packages/ansible
  ansible collection location = /home/phil/.ansible/collections:/usr/share/ansible/collections
  executable location = /usr/local/bin/ansible
  python version = 3.10.6 (main, Aug  2 2022, 00:00:00) [GCC 12.1.1 20220507 (Red Hat 12.1.1-1)]
  jinja version = 3.0.3
  libyaml = True

The Playbook for testing is the following:

➜  ~ cat test.yml
---
- hosts: "{{ servers }}"
  tasks:
    - name: Hello World
      ansible.builtin.shell: >
        echo "Hello World"
      delegate_to: "{{ peer }}"

To test and reproduce the issue we have set up two hosts with Tlog v12.1, which has been build from the master branch.
The playbook will then get started as the following:

ansible-playbook test5_play.yml -e servers=test2.domain.tld -e peer=test1.domain.tld -vvvv

The error message is the following:

fatal: [test1.domain.tld -> test2.domain.tld(OBFUSCATED)]: FAILED! => {
    "changed": false,
    "module_stderr": "
OpenSSH_8.8p1, OpenSSL 3.0.5 5 Jul 2022
debug1: Reading configuration data /home/phil/.ssh/config
debug1: /home/phil/.ssh/config line 31: Applying options for *
debug1: Reading configuration data /etc/ssh/ssh_config
debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/50-redhat.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/50-redhat.conf
debug2: checking match for 'final all' host OBFUSCATED originally OBFUSCATED
debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 3: not matched 'final'
debug2: match not found
debug3: /etc/ssh/ssh_config.d/50-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-]
debug3: kex names ok: [curve25519-sha256,curve25519-sha256@libssh.org,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]
debug1: configuration requests final Match pass
debug2: resolve_canonicalize: hostname OBFUSCATED is address
debug1: re-parsing configuration
debug1: Reading configuration data /home/phil/.ssh/config
debug1: /home/phil/.ssh/config line 31: Applying options for *
debug1: Reading configuration data /etc/ssh/ssh_config
debug3: /etc/ssh/ssh_config line 55: Including file /etc/ssh/ssh_config.d/50-redhat.conf depth 0
debug1: Reading configuration data /etc/ssh/ssh_config.d/50-redhat.conf
debug2: checking match for 'final all' host OBFUSCATED originally OBFUSCATED
debug3: /etc/ssh/ssh_config.d/50-redhat.conf line 3: matched 'final'
debug2: match found
debug3: /etc/ssh/ssh_config.d/50-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-]
debug3: kex names ok: [curve25519-sha256,curve25519-sha256@libssh.org,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]
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/home/phil/.ssh/known_hosts'
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/home/phil/.ssh/known_hosts2'
debug1: auto-mux: Trying existing master
debug1: Control socket "/tmp/ansible-ssh-OBFUSCATED-222-root" does not exist
debug3: ssh_connect_direct: entering
debug1: Connecting to OBFUSCATED [OBFUSCATED] port 222.
debug3: set_sock_tos: set socket 3 IP_TOS 0x48
debug2: fd 3 setting O_NONBLOCK
debug1: fd 3 clearing O_NONBLOCK
debug1: Connection established.
debug3: timeout: 9997 ms remain after connect
debug1: identity file /home/phil/.ssh/id_rsa type -1
debug1: identity file /home/phil/.ssh/id_rsa-cert type -1
debug1: identity file /home/phil/.ssh/id_dsa type -1
debug1: identity file /home/phil/.ssh/id_dsa-cert type -1
debug1: identity file /home/phil/.ssh/id_ecdsa type -1
debug1: identity file /home/phil/.ssh/id_ecdsa-cert type -1
debug1: identity file /home/phil/.ssh/id_ecdsa_sk type -1
debug1: identity file /home/phil/.ssh/id_ecdsa_sk-cert type -1
debug1: identity file /home/phil/.ssh/id_ed25519 type 3
debug1: identity file /home/phil/.ssh/id_ed25519-cert type 7
debug1: identity file /home/phil/.ssh/id_ed25519_sk type -1
debug1: identity file /home/phil/.ssh/id_ed25519_sk-cert type -1
debug1: identity file /home/phil/.ssh/id_xmss type -1
debug1: identity file /home/phil/.ssh/id_xmss-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_8.8
debug1: Remote protocol version 2.0, remote software version OpenSSH_8.2p1 Ubuntu-4ubuntu0.5
debug1: compat_banner: match: OpenSSH_8.2p1 Ubuntu-4ubuntu0.5 pat OpenSSH* compat 0x04000000
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to OBFUSCATED:222 as 'root'
debug3: put_host_port: [OBFUSCATED]:222
debug3: record_hostkey: found key type ED25519 in file /home/phil/.ssh/known_hosts:3
debug3: record_hostkey: found key type RSA in file /home/phil/.ssh/known_hosts:5
debug3: load_hostkeys_file: loaded 2 keys from [OBFUSCATED]:222
debug1: load_hostkeys: fopen /home/phil/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug3: order_hostkeyalgs: have matching best-preference key type ssh-ed25519-cert-v01@openssh.com, using HostkeyAlgorithms verbatim
debug3: send packet: type 20
debug1: SSH2_MSG_KEXINIT sent
debug3: receive packet: type 20
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,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,ext-info-c
debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,sk-ssh-ed25519-cert-v01@openssh.com,sk-ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ssh-ed25519@openssh.com,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-512,rsa-sha2-256
debug2: ciphers ctos: aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes256-ctr,aes128-gcm@openssh.com,aes128-ctr
debug2: ciphers stoc: aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes256-ctr,aes128-gcm@openssh.com,aes128-ctr
debug2: MACs ctos: hmac-sha2-256-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha2-256,hmac-sha1,umac-128@openssh.com,hmac-sha2-512
debug2: MACs stoc: hmac-sha2-256-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha2-256,hmac-sha1,umac-128@openssh.com,hmac-sha2-512
debug2: compression ctos: zlib@openssh.com,zlib,none
debug2: compression stoc: zlib@openssh.com,zlib,none
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug2: peer server KEXINIT proposal
debug2: KEX algorithms: curve25519-sha256@libssh.org,curve25519-sha256,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512
debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-ed25519,ssh-ed25519-cert-v01@openssh.com
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes256-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-gcm@openssh.com,aes128-ctr
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes256-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-gcm@openssh.com,aes128-ctr
debug2: MACs ctos: hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512,hmac-sha2-256
debug2: MACs stoc: hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512,hmac-sha2-256
debug2: compression ctos: none,zlib@openssh.com
debug2: compression stoc: none,zlib@openssh.com
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: ssh-ed25519-cert-v01@openssh.com
debug1: kex: server->client cipher: aes256-gcm@openssh.com MAC: <implicit> compression: zlib@openssh.com
debug1: kex: client->server cipher: aes256-gcm@openssh.com MAC: <implicit> compression: zlib@openssh.com
debug1: kex: curve25519-sha256 need=32 dh_need=32
debug1: kex: curve25519-sha256 need=32 dh_need=32
debug3: send packet: type 30
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug3: receive packet: type 31
debug1: SSH2_MSG_KEX_ECDH_REPLY received
debug1: Server host certificate: ssh-ed25519-cert-v01@openssh.com SHA256:Q/huYLPc08AF/9dZuBdZjRX82LmkijFs7ZiyR8CRBBw, serial 0 ID "test1.domain.tld" CA ssh-ed25519 SHA256:J+tg5lDLgVQmREJvdZdP+REyeDfVJeOlcPB16WenQcw valid from 2022-09-02T12:31:59 to 2027-08-07T12:36:59
debug2: Server host certificate hostname: test1.domain.tld
debug2: Server host certificate hostname: test1.domain.tld
debug3: put_host_port: [OBFUSCATED]:222
debug3: put_host_port: [OBFUSCATED]:222
debug3: record_hostkey: found key type ED25519 in file /home/phil/.ssh/known_hosts:3
debug3: record_hostkey: found key type RSA in file /home/phil/.ssh/known_hosts:5
debug3: load_hostkeys_file: loaded 2 keys from [OBFUSCATED]:222
debug1: load_hostkeys: fopen /home/phil/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug1: checking without port identifier
debug1: load_hostkeys: fopen /home/phil/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug1: No matching CA found. Retry with plain key
debug1: No matching CA found. Retry with plain key
debug1: Host '[OBFUSCATED]:222' is known and matches the ED25519 host key.
debug1: Found key in /home/phil/.ssh/known_hosts:3
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey out after 4294967296 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug1: SSH2_MSG_NEWKEYS received
debug2: set_newkeys: mode 0
debug1: rekey in after 4294967296 blocks
debug1: Will attempt key: /home/phil/.ssh/id_ed25519 ED25519 SHA256:WOJEuNDIg+F1MGTEJy0LitDbJAopa/205gPed0goyaM agent
debug1: Will attempt key: personal ECDSA SHA256:uusB+m3btbU8hMpckUuEXzVmtq8+YyNCp+6HHhCfO7E agent
debug1: Will attempt key: /home/phil/.ssh/id_rsa 
debug1: Will attempt key: /home/phil/.ssh/id_dsa 
debug1: Will attempt key: /home/phil/.ssh/id_ecdsa 
debug1: Will attempt key: /home/phil/.ssh/id_ecdsa_sk 
debug1: Will attempt key: /home/phil/.ssh/id_ed25519 ED25519-CERT SHA256:WOJEuNDIg+F1MGTEJy0LitDbJAopa/205gPed0goyaM
debug1: Will attempt key: /home/phil/.ssh/id_ed25519_sk 
debug1: Will attempt key: /home/phil/.ssh/id_xmss 
debug2: pubkey_prepare: done
debug3: send packet: type 5
debug3: receive packet: type 7
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<ssh-ed25519,sk-ssh-ed25519@openssh.com,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ecdsa-sha2-nistp256@openssh.com>
debug3: receive packet: type 6
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug3: send packet: type 50
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey
debug3: start over, passed a different list publickey
debug3: preferred gssapi-with-mic,gssapi-keyex,hostbased,publickey
debug3: authmethod_lookup publickey
debug3: remaining preferred: ,gssapi-keyex,hostbased,publickey
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering public key: /home/phil/.ssh/id_ed25519 ED25519 SHA256:WOJEuNDIg+F1MGTEJy0LitDbJAopa/205gPed0goyaM agent
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey
debug1: Offering public key: personal ECDSA SHA256:uusB+m3btbU8hMpckUuEXzVmtq8+YyNCp+6HHhCfO7E agent
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey
debug1: Trying private key: /home/phil/.ssh/id_rsa
debug3: no such identity: /home/phil/.ssh/id_rsa: No such file or directory
debug1: Trying private key: /home/phil/.ssh/id_dsa
debug3: no such identity: /home/phil/.ssh/id_dsa: No such file or directory
debug1: Trying private key: /home/phil/.ssh/id_ecdsa
debug3: no such identity: /home/phil/.ssh/id_ecdsa: No such file or directory
debug1: Trying private key: /home/phil/.ssh/id_ecdsa_sk
debug3: no such identity: /home/phil/.ssh/id_ecdsa_sk: No such file or directory
debug1: Offering public key: /home/phil/.ssh/id_ed25519 ED25519-CERT SHA256:WOJEuNDIg+F1MGTEJy0LitDbJAopa/205gPed0goyaM
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 60
debug1: Server accepts key: /home/phil/.ssh/id_ed25519 ED25519-CERT SHA256:WOJEuNDIg+F1MGTEJy0LitDbJAopa/205gPed0goyaM
debug3: sign_and_send_pubkey: ED25519-CERT SHA256:WOJEuNDIg+F1MGTEJy0LitDbJAopa/205gPed0goyaM
debug2: sign_and_send_pubkey: using private key "/home/phil/.ssh/id_ed25519" from agent for certificate
debug3: sign_and_send_pubkey: signing using ssh-ed25519-cert-v01@openssh.com SHA256:WOJEuNDIg+F1MGTEJy0LitDbJAopa/205gPed0goyaM
debug3: send packet: type 50
debug3: receive packet: type 52
debug1: Enabling compression at level 6.
Authenticated to OBFUSCATED ([OBFUSCATED]:222) using "publickey".
debug1: pkcs11_del_provider: called, provider_id = (null)
debug1: setting up multiplex master socket
debug3: muxserver_listen: temporary control path /tmp/ansible-ssh-OBFUSCATED-222-root.AJs5j752XM5WvyoA
debug2: fd 4 setting O_NONBLOCK
debug3: fd 4 is O_NONBLOCK
debug3: fd 4 is O_NONBLOCK
debug1: channel 0: new [/tmp/ansible-ssh-OBFUSCATED-222-root]
debug3: muxserver_listen: mux listener channel 0 fd 4
debug2: fd 3 setting TCP_NODELAY
debug3: set_sock_tos: set socket 3 IP_TOS 0x20
debug1: control_persist_detach: backgrounding master process
debug2: control_persist_detach: background process is 25360
debug2: fd 4 setting O_NONBLOCK
debug1: forking to background
debug1: Entering interactive session.
debug1: pledge: id
debug2: set_control_persist_exit_time: schedule exit in 60 seconds
debug1: multiplexing control connection
debug2: fd 5 setting O_NONBLOCK
debug3: fd 5 is O_NONBLOCK
debug1: channel 1: new [mux-control]
debug3: channel_post_mux_listener: new mux channel 1 fd 5
debug3: mux_master_read_cb: channel 1: hello sent
debug2: set_control_persist_exit_time: cancel scheduled exit
debug3: mux_master_read_cb: channel 1 packet type 0x00000001 len 4
debug2: mux_master_process_hello: channel 1 client version 4
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_master_read_cb: channel 1 packet type 0x10000004 len 4
debug2: mux_master_process_alive_check: channel 1: alive check
debug3: mux_client_request_alive: done pid = 25362
debug3: mux_client_request_session: session request sent
debug3: mux_master_read_cb: channel 1 packet type 0x10000002 len 132
debug2: mux_master_process_new_session: channel 1: request tty 0, X 0, agent 0, subsys 0, term "xterm-256color", cmd "/bin/sh -c '/usr/bin/python3 && sleep 0'", env 2
debug3: mux_master_process_new_session: got fds stdin 6, stdout 7, stderr 8
debug2: fd 6 setting O_NONBLOCK
debug1: channel 2: new [client-session]
debug2: mux_master_process_new_session: channel_new: 2 linked to control channel 1
debug2: channel 2: send open
debug3: send packet: type 90
debug3: receive packet: type 80
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug3: client_input_hostkeys: received RSA key SHA256:sfHSKdE0oxgTyH+Erm5F1E4LZj8jWJFAtp1j9jqz9mo
debug3: client_input_hostkeys: received ED25519 key SHA256:Q/huYLPc08AF/9dZuBdZjRX82LmkijFs7ZiyR8CRBBw
debug3: put_host_port: [OBFUSCATED]:222
debug1: client_input_hostkeys: searching /home/phil/.ssh/known_hosts for [OBFUSCATED]:222 / (none)
debug3: hostkeys_foreach: reading file "/home/phil/.ssh/known_hosts"
debug3: hostkeys_find: found ssh-ed25519 key at /home/phil/.ssh/known_hosts:3
debug3: hostkeys_find: found ssh-rsa key at /home/phil/.ssh/known_hosts:5
debug1: client_input_hostkeys: searching /home/phil/.ssh/known_hosts2 for [OBFUSCATED]:222 / (none)
debug1: client_input_hostkeys: hostkeys file /home/phil/.ssh/known_hosts2 does not exist
debug3: client_input_hostkeys: 2 server keys: 0 new, 2 retained, 0 incomplete match. 0 to remove
debug1: client_input_hostkeys: no new or deprecated keys from server
debug3: receive packet: type 4
debug1: Remote: cert: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug3: receive packet: type 4
debug1: Remote: principals: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug3: receive packet: type 4
debug1: Remote: cert: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug3: receive packet: type 4
debug1: Remote: principals: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug3: receive packet: type 91
debug2: channel_input_open_confirmation: channel 2: callback start
debug2: client_session2_setup: id 2
debug1: Sending environment.
debug1: channel 2: setting env LANG = "de_DE.utf8"
debug2: channel 2: request env confirm 0
debug3: send packet: type 98
debug1: channel 2: setting env XMODIFIERS = "@im=none"
debug2: channel 2: request env confirm 0
debug3: send packet: type 98
debug1: Sending command: /bin/sh -c '/usr/bin/python3 && sleep 0'
debug2: channel 2: request exec confirm 1
debug3: send packet: type 98
debug3: mux_session_confirm: sending success reply
debug2: channel_input_open_confirmation: channel 2: callback done
debug2: channel 2: open confirm rwindow 0 rmax 32768
debug1: mux_client_request_session: master session id: 2
debug2: channel 2: rcvd adjust 2097152
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 2
debug2: exec request accepted on channel 2
debug2: channel 2: read<=0 rfd 6 len 0
debug2: channel 2: read failed
debug2: chan_shutdown_read: channel 2: (i0 o0 sock -1 wfd 6 efd 8 [write])
debug2: channel 2: input open -> drain
debug2: channel 2: ibuf empty
debug2: channel 2: send eof
debug3: send packet: type 96
debug2: channel 2: input drain -> closed
debug2: channel 2: rcvd adjust 65536
debug3: receive packet: type 96
debug2: channel 2: rcvd eof
debug2: channel 2: output open -> drain
debug2: channel 2: obuf empty
debug2: chan_shutdown_write: channel 2: (i3 o1 sock -1 wfd 7 efd 8 [write])
debug2: channel 2: output drain -> closed
debug3: receive packet: type 98
debug1: client_input_channel_req: channel 2 rtype exit-status reply 0
debug3: mux_exit_message: channel 2: exit message, exitval 0
debug3: receive packet: type 97
debug2: channel 2: rcvd close
debug3: channel 2: will not send data after close
debug2: channel 2: send close
debug3: send packet: type 97
debug2: channel 2: is dead
debug2: channel 2: gc: notify user
debug3: mux_master_session_cleanup_cb: entering for channel 2
debug2: channel 1: rcvd close
debug2: channel 1: output open -> drain
debug2: chan_shutdown_read: channel 1: (i0 o1 sock 5 wfd 5 efd -1 [closed])
debug2: channel 1: input open -> closed
debug2: channel 2: gc: user detached
debug2: channel 2: is dead
debug2: channel 2: garbage collecting
debug1: channel 2: free: client-session, nchannels 3
debug3: channel 2: status: The following connections are open:
  #1 mux-control (t16 nr0 i3/0 o1/16 e[closed]/0 fd 5/5/-1 sock 5 cc -1)
  #2 client-session (t4 r0 i3/0 o3/0 e[write]/0 fd -1/-1/8 sock -1 cc -1)

debug2: channel 1: obuf empty
debug2: chan_shutdown_write: channel 1: (i3 o1 sock 5 wfd 5 efd -1 [closed])
debug2: channel 1: output drain -> closed
debug2: channel 1: is dead (local)
debug2: channel 1: gc: notify user
debug3: mux_master_control_cleanup_cb: entering for channel 1
debug2: channel 1: gc: user detached
debug2: channel 1: is dead (local)
debug2: channel 1: garbage collecting
debug3: mux_client_read_packet: read header failed: Broken pipe
debug1: channel 1: free: mux-control, nchannels 2
debug3: channel 1: status: The following connections are open:
  #1 mux-control (t16 nr0 i3/0 o3/0 e[closed]/0 fd 5/5/-1 sock 5 cc -1)

debug2: Received exit status from master 0
debug2: set_control_persist_exit_time: schedule exit in 60 seconds
",
    "module_stdout": "",
    "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error",
    "rc": 0
}

When setting pipelining to False, the playbook will proceed as expected.

changed: [test2.domain.tld -> test1.domain.tld(OBFUSCATED)] => {
   "changed": true,
   "cmd": "echo \"Hello World\"\n",
   "delta": "0:00:00.006459",
   "end": "2022-09-07 12:07:58.716469",
   "invocation": {
       "module_args": {
           "_raw_params": "echo \"Hello World\"\n",
           "_uses_shell": true,
           "argv": null,
           "chdir": null,
           "creates": null,
           "executable": null,
           "removes": null,
           "stdin": null,
           "stdin_add_newline": true,
           "strip_empty_ends": true,
           "warn": false
       }
   },
   "msg": "",
   "rc": 0,
   "start": "2022-09-07 12:07:58.710010",
   "stderr": "",
   "stderr_lines": [],
   "stdout": "Hello World",
   "stdout_lines": [
       "Hello World"
   ]
}
@justin-stephenson
Copy link
Collaborator

Hi,

Thanks for reporting this issue and providing the simple reproducer.

We tried to fix this problem already in RHEL, we validated the fix was working in RHEL/Fedora environments. I need to investigate further what is different in your environment compared to the RHEL environment for the ansible pipelining=True problem.

@justin-stephenson
Copy link
Collaborator

@roth-wine does this issue happen only when using delegate_to , or can it be reproduced simply with pipelining=True ?

@roth-wine
Copy link
Author

Hello @justin-stephenson,
this issue only happens when using delegate_to in combination with pipelining=True. If you use the Playbook above without delegate_to everything will work as expected.

@roth-wine
Copy link
Author

@justin-stephenson
I have created the following Dockerfile to reproduce the Issue more easily without ansible.

FROM ubuntu:jammy
ARG ARCH

RUN apt-get update && \
  apt-get install -y build-essential pkg-config vim \
  libjson-c-dev libsystemd-dev libcurl4-openssl-dev \
  libutempter-dev autoconf automake libtool openssh-server \
  whois

RUN useradd -ms /bin/bash tloguser
RUN mkdir -p /var/log/tlog && mkdir -p /var/run/tlog
RUN touch /var/log/tlog/session.log
RUN chown tloguser:tloguser /var/log/tlog/session.log
RUN chown -R tloguser:tloguser /var/run/tlog

RUN passroot=$(echo date +%s | sha256sum | base64 | head -c 32) && \
    echo "root:${passroot}" | chpasswd && echo "root: ${passroot}" > /passroot
RUN passtloguser=$(echo date +%s | sha256sum | base64 | head -c 32) && \
    echo "tloguser:${passtloguser}" | chpasswd && echo "tloguser: ${passtloguser}" > /passtloguser

RUN sed -i 's/#Port 22/Port 2222/g' /etc/ssh/sshd_config
RUN sed -i 's/#ListenAddress 0.0.0.0/ListenAddress 127.0.0.1/g' /etc/ssh/sshd_config
RUN sed -i '/AcceptEnv\ LANG\ LC_\*/d' /etc/ssh/sshd_config
RUN service ssh start

RUN git clone https://github.com/Scribery/tlog.git
WORKDIR /tlog
RUN git checkout main
RUN autoreconf -i -f
RUN ./configure --prefix=/usr --sysconfdir=/etc --localstatedir=/var && make
RUN make install

RUN sed -i 's/\/\/."path".:.""/"path"\ :\ "\/var\/log\/tlog\/session.log"/g' /etc/tlog/tlog-rec-session.conf
RUN sed -i 's/\/\/."writer".:."journal"/"writer"\ :\ "file"/g' /etc/tlog/tlog-rec-session.conf
RUN sed -i 's/\/\/."window".:.true/"window"\ :\ false/g' /etc/tlog/tlog-rec-session.conf
RUN sed -i 's/\/\/."input".:.false/"input"\ :\ true/g' /etc/tlog/tlog-rec-session.conf
RUN sed -i 's/\/\/."output".:.true/"output"\ :\ true/g' /etc/tlog/tlog-rec-session.conf
RUN usermod -s /usr/bin/tlog-rec-session tloguser
ENTRYPOINT cat /passroot && cat /passtloguser && service ssh restart && tail -f /var/log/tlog/session.log
EXPOSE 2222
WORKDIR /root

You could build the Dockerfile docker build -t tlog-debug:main .
and then run the docker container afterwards docker run -it --network=host tlog-debug:main

Then the docker container will print the credentials for the root and tloguser and shows the output for the tlog session log:

root: ZDgzZjMyMGNiMWJiMDA3MWYxZjQzODJi
tloguser: ZDgzZjMyMGNiMWJiMDA3MWYxZjQzODJi
 * Restarting OpenBSD Secure Shell server sshd                                                                                                                                                                                                          [ OK ] 

Then i could start with the one-liner to reproduce issue:

➜ ssh tloguser@localhost -p2222 sh -c 'echo "Hello world"' 
tloguser@localhost's password: 
Locale charset is ANSI_X3.4-1968 (ASCII)
Assuming locale environment is lost and charset is UTF-8

ATTENTION! Your session is being recorded!

The stdout is empty, that's the reason why ansible breaks.

In the log file we could also see, that in_txt,in_bin,out_txt and out_bin is empty.

{"ver":"2.3","host":"thinkpad","rec":"de9598fe77594144b6a278887763d35d-37-11d189c","user":"tloguser","term":"","session":67,"id":1,"pos":0,"time":1667554409.541,"timing":">1","in_txt":"","in_bin":[],"out_txt":"\n","out_bin":[]}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants