Issue with Remote Execution / Pending because of tee not receiving EOF

Hello,

I had a problem with Foreman 1.18.1 release and Remote Execution. All the command I tried to execute on Linux servers (tested Ubuntu 16.0.4 and Centos 7) were in pending state for unlimited time.

After some long research, it seems that tee is executed on the remote host so that commands are stored in a temporary file, and then the file is executed. Problem is that tee is never closing because it never receives the “EOF” signal.

I modified the file /usr/lib/ruby/vendor_ruby/foreman_remote_execution_core/script_runner.rb and changed the “run_sync” function : after “ch.send_data(stdin) unless stdin.nil?”, I added “ch.eof! unless stdin.nil?”.

Now it works, but as I’m not a developper I’m not sure this is the right way to solve this issue.

I even don’t know if it is the right place for this, but I give it a try…

Please help us on this.

Regards,

Thomas

We’ve not seen this issue so far with that release as far as I know. Any info on the reproducer: what command was run, how ssh -i /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy -vvvv root@remote-host, does it happen on every command - would be good to check with something simple like echo hello.

Hello,

SSH connection is correctly working :

root@srv-msc-foreman:/usr/lib/ruby/vendor_ruby# ssh -i /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy -vvvv root@10.254.251.120
OpenSSH_7.2p2 Ubuntu-4ubuntu2.4, OpenSSL 1.0.2g  1 Mar 2016
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: Applying options for *
debug3: kex names ok: [diffie-hellman-group1-sha1]
debug2: resolving "10.254.251.120" port 22
debug2: ssh_connect_direct: needpriv 0
debug1: Connecting to 10.254.251.120 [10.254.251.120] port 22.
debug1: Connection established.
debug1: permanently_set_uid: 0/0
debug1: identity file /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy type 1
debug1: key_load_public: No such file or directory
debug1: identity file /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu2.4
debug1: Remote protocol version 2.0, remote software version OpenSSH_7.4
debug1: match: OpenSSH_7.4 pat OpenSSH* compat 0x04000000
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to 10.254.251.120:22 as 'root'
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
debug3: record_hostkey: found key type ECDSA in file /root/.ssh/known_hosts:2
debug3: load_hostkeys: loaded 1 keys from 10.254.251.120
debug3: order_hostkeyalgs: prefer hostkeyalgs: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
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@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,ext-info-c
debug2: host key algorithms: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zlib@openssh.com,zlib
debug2: compression stoc: none,zlib@openssh.com,zlib
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug2: peer server 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-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,cast128-cbc,3des-cbc
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,cast128-cbc,3des-cbc
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
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@libssh.org
debug1: kex: host key algorithm: ecdsa-sha2-nistp256
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug3: send packet: type 30
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug3: receive packet: type 31
debug1: Server host key: ecdsa-sha2-nistp256 SHA256:ZJ+QGGjzIRVolpakYRjDT7/fUYvjEy+LUaGVixJI4Oc
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
debug3: record_hostkey: found key type ECDSA in file /root/.ssh/known_hosts:2
debug3: load_hostkeys: loaded 1 keys from 10.254.251.120
debug1: Host '10.254.251.120' is known and matches the ECDSA host key.
debug1: Found key in /root/.ssh/known_hosts:2
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug2: set_newkeys: mode 0
debug1: rekey after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS received
debug2: key: /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy (0x561980447b80), explicit
debug3: send packet: type 5
debug3: receive packet: type 7
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<rsa-sha2-256,rsa-sha2-512>
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,gssapi-keyex,gssapi-with-mic,password
debug3: start over, passed a different list publickey,gssapi-keyex,gssapi-with-mic,password
debug3: preferred gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup gssapi-keyex
debug3: remaining preferred: gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-keyex
debug1: Next authentication method: gssapi-keyex
debug1: No valid Key exchange context
debug2: we did not send a packet, disable method
debug3: authmethod_lookup gssapi-with-mic
debug3: remaining preferred: publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-with-mic
debug1: Next authentication method: gssapi-with-mic
debug1: Unspecified GSS failure.  Minor code may provide more information
Server not found in Kerberos database

debug1: Unspecified GSS failure.  Minor code may provide more information
Server not found in Kerberos database

debug1: Unspecified GSS failure.  Minor code may provide more information


debug3: send packet: type 50
debug2: we sent a gssapi-with-mic packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug2: we did not send a packet, disable method
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy
debug3: send_pubkey_test
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 60
debug1: Server accepts key: pkalg rsa-sha2-512 blen 279
debug2: input_userauth_pk_ok: fp SHA256:A9RDqpjHsGPyg0RIsjGJ8HbrTk3uFOJciCYNM1LtmxU
debug3: sign_and_send_pubkey: RSA SHA256:A9RDqpjHsGPyg0RIsjGJ8HbrTk3uFOJciCYNM1LtmxU
debug3: send packet: type 50
debug3: receive packet: type 52
debug1: Authentication succeeded (publickey).
Authenticated to 10.254.251.120 ([10.254.251.120]:22).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Requesting no-more-sessions@openssh.com
debug3: send packet: type 80
debug1: Entering interactive session.
debug1: pledge: network
debug3: receive packet: type 80
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug3: receive packet: type 91
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: ssh_packet_set_tos: set IP_TOS 0x10
debug2: client_session2_setup: id 0
debug2: channel 0: request pty-req confirm 1
debug3: send packet: type 98
debug1: Sending environment.
debug3: Ignored env SHELL
debug3: Ignored env TERM
debug3: Ignored env USER
debug3: Ignored env LS_COLORS
debug3: Ignored env SUDO_USER
debug3: Ignored env SUDO_UID
debug3: Ignored env USERNAME
debug3: Ignored env MAIL
debug3: Ignored env PATH
debug3: Ignored env PWD
debug1: Sending env LANG = en_US.UTF-8
debug2: channel 0: request env confirm 0
debug3: send packet: type 98
debug3: Ignored env KRB5CCNAME
debug3: Ignored env SHLVL
debug3: Ignored env SUDO_COMMAND
debug3: Ignored env HOME
debug3: Ignored env LOGNAME
debug3: Ignored env LESSOPEN
debug3: Ignored env SUDO_GID
debug3: Ignored env LESSCLOSE
debug3: Ignored env OLDPWD
debug3: Ignored env _
debug2: channel 0: request shell confirm 1
debug3: send packet: type 98
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: PTY allocation request accepted on channel 0
debug2: channel 0: rcvd adjust 2097152
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: shell request accepted on channel 0
Last login: Tue Sep  4 11:20:04 2018 from srv-msc-foreman.msc.so

When I try to execute the command « uname –a » on this Centos7 server through the standard « Run Command – SSH Default » Job, it results in an indefinite pending state.
On the Centos7 server, I can see that those process are running :

root     23816 20546  0 10:55 ?        00:00:00 sshd: root@notty
root     23826 23816  0 10:55 ?        00:00:00 bash -c tee '/var/tmp/foreman-ssh-cmd-86fcb648-01a4-418d-bee6-dcc04c40624a/script' && chmod '555' '/var/tmp/foreman-ssh-cmd-86fcb648-01a4-418d-bee6-dcc04c40624a/script'
root     23833 23826  0 10:55 ?        00:00:00 tee /var/tmp/foreman-ssh-cmd-86fcb648-01a4-418d-bee6-dcc04c40624a/script

the proxy log in debug mode shows this :

D, [2018-09-04T16:33:42.880661 ] DEBUG -- : accept: 10.254.251.8:43026
D, [2018-09-04T16:33:42.885550 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
W, [2018-09-04T16:33:42.901499 #16447]  WARN -- : Could not open DB for dynflow at '', will keep data in memory. Restart will drop all dynflow data.
[2018-09-04 16:33:42.998 #16447]  INFO -- Execution plan cleaner removing 0 execution plans.
[2018-09-04 16:33:43.015 #16447]  INFO -- 10.254.251.8 - - [04/Sep/2018:16:33:43 +0200] "GET /dynflow/tasks/count?state=running HTTP/1.1" 200 29 0.0063

[2018-09-04 16:33:43.058 #16447] DEBUG -- close: 10.254.251.8:43026
[2018-09-04 16:33:43.472 #16447] DEBUG -- accept: 10.254.251.8:43028
[2018-09-04 16:33:43.488 #16447] DEBUG -- Rack::Handler::WEBrick is invoked.
[2018-09-04 16:33:43.492 #16447] DEBUG -- ExecutionPlan 00122fb3-2d19-4d4b-ba51-2f9ad36476f7      pending >>  planning
[2018-09-04 16:33:43.495 #16447] DEBUG --          Step 00122fb3-2d19-4d4b-ba51-2f9ad36476f7: 1   pending >>   running in phase     Plan ForemanRemoteExecutionCore::Actions::RunScript
[2018-09-04 16:33:43.497 #16447] DEBUG --          Step 00122fb3-2d19-4d4b-ba51-2f9ad36476f7: 4   pending >>   running in phase     Plan SmartProxyDynflowCore::Callback::Action
[2018-09-04 16:33:43.498 #16447] DEBUG --          Step 00122fb3-2d19-4d4b-ba51-2f9ad36476f7: 4   running >>   success in phase     Plan SmartProxyDynflowCore::Callback::Action
[2018-09-04 16:33:43.500 #16447] DEBUG --          Step 00122fb3-2d19-4d4b-ba51-2f9ad36476f7: 1   running >>   success in phase     Plan ForemanRemoteExecutionCore::Actions::RunScript
[2018-09-04 16:33:43.506 #16447] DEBUG -- ExecutionPlan 00122fb3-2d19-4d4b-ba51-2f9ad36476f7     planning >>   planned
[2018-09-04 16:33:43.517 #16447]  INFO -- 10.254.251.8 - - [04/Sep/2018:16:33:43 +0200] "POST /dynflow/tasks/ HTTP/1.1" 200 50 0.0274

[2018-09-04 16:33:43.526 #16447] DEBUG -- ExecutionPlan 00122fb3-2d19-4d4b-ba51-2f9ad36476f7      planned >>   running
[2018-09-04 16:33:43.530 #16447] DEBUG --          Step 00122fb3-2d19-4d4b-ba51-2f9ad36476f7: 2   pending >>   running in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
[2018-09-04 16:33:43.533 #16447] DEBUG --          Step 00122fb3-2d19-4d4b-ba51-2f9ad36476f7: 2   running >> suspended in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
[2018-09-04 16:33:43.534 #16447] DEBUG -- start runner 60429fd9-fbb8-4ae6-b6e0-1cc3490fed22
[2018-09-04 16:33:43.535 #16447] DEBUG -- opening session to root@10.254.251.120
[2018-09-04 16:33:43.557 #16447] DEBUG -- close: 10.254.251.8:43028
[2018-09-04 16:33:44.560 #16447] DEBUG -- Sending data to /var/tmp/foreman-ssh-cmd-60429fd9-fbb8-4ae6-b6e0-1cc3490fed22/script on remote host:
uname -a
[2018-09-04 16:33:57.980 #16447] DEBUG -- Executor heartbeat
[2018-09-04 16:33:57.980 #16447] DEBUG -- Executor heartbeat
[2018-09-04 16:33:57.980 #16447] DEBUG -- Executor heartbeat
[2018-09-04 16:33:57.980 #16447] DEBUG -- Executor heartbeat
[2018-09-04 16:33:57.980 #16447] DEBUG -- Executor heartbeat

… and so on.

As I told you, the « bash –c tee » process executed on the Centos is correctly receiving the date sent by the « ch.send_data(stdin) » command, but it waits forever for some more data, and so the « exit-status » signal is never sent back.
By adding the « ch.eof! unless stdin.nil? » just after, I can inform the process that the stdin is finished, and then everything works fine.

Regards,

Thomas Castelle
Responsable de la Direction Technique des Services Opérés
Direction des Opérations

T : +33 4 26 20 76 23 ― M : +33 6 27 27 28 57
Standard : +33 8 20 56 39 27 ― Fax : +33 4 72 43 00 67

Exaprobe
Agence de Lyon : 13 B avenue Albert Einstein - CS90217 - 69623 Villeurbanne Cedex
email : tcastelle@exaprobe.commailto:tcastelle@exaprobe.com
web : www.exaprobe.comhttp://www.exaprobe.com/ / www.econocom.comhttp://www.econocom.com/

[LOGO_EXAPROBE_BLUE_RVB_BD]
[cid:image003.gif@01CB0719.BB08BD00] Avant d’imprimer cet email, pensez à l’environnement