I have a intermittent issue with execute remote operations using Paramiko.
if channel.active:
contents = io.StringIO()
error = io.StringIO()
try:
LOG.info('{} - Executing script {} - as {} user '.format(self.target_host, script, self.targetvmuser))
channel.exec_command(script)
while not channel.exit_status_ready():
if channel.recv_ready():
data = channel.recv(1024)
LOG.debug(data.decode())
while data:
contents.write(data.decode())
data = channel.recv(1024)
LOG.debug(data.decode())
if channel.recv_stderr_ready():
error_buff = channel.recv_stderr(1024)
LOG.debug(error_buff.decode())
while error_buff:
error.write(error_buff.decode())
error_buff = channel.recv_stderr(1024)
LOG.debug(error_buff.decode())
exit_status = channel.recv_exit_status()
Below are the debug logs of 2 executions. I am not able to figure out why the output below is returned on one VM but not on another VM.
2022-03-17 12:14:42 [DEBUG] - -rw-rw-r--. 1 test test 1702 Mar 17 12:14 /tmp/testfile
2022-03-17 12:14:42 [DEBUG] -
Linux VM with Paramiko 2.7.2 - intermittent Bad run.
2022-03-17 12:14:20 [DEBUG][chan 0] Max packet out: 32768 bytes
2022-03-17 12:14:20 [DEBUG] - Secsh channel 0 opened.
2022-03-17 12:14:20 [DEBUG] - [chan 1] Max packet in: 32768 bytes
2022-03-17 12:14:20 [DEBUG] - [chan 1] Max packet out: 32768 bytes
2022-03-17 12:14:20 [DEBUG] - Secsh channel 1 opened.
2022-03-17 12:14:20 [DEBUG] - [chan 1] Sesch channel 1 request ok
2022-03-17 12:14:20 [INFO ] - [chan 1] Opened sftp connection (server version 3)
2022-03-17 12:14:20 [DEBUG] - [chan 1] open(b'/tmp/testfile', 'wb')
2022-03-17 12:14:20 [DEBUG] - Sending global request "keepalive@lag.net"
2022-03-17 12:14:20 [DEBUG] - [chan 1] open(b'/tmp/testfile', 'wb') -> 00000000
2022-03-17 12:14:20 [DEBUG] - [chan 1] close(00000000)
2022-03-17 12:14:20 [DEBUG] - [chan 1] stat(b'/tmp/testfile')
2022-03-17 12:14:20 [DEBUG] - [chan 2] Max packet in: 32768 bytes
2022-03-17 12:14:20 [DEBUG] - [chan 2] Max packet out: 32768 bytes
2022-03-17 12:14:20 [DEBUG] - Secsh channel 2 opened.
2022-03-17 12:14:20 [INFO ] - 10.9.59.11 - Executing script ls -ltr /tmp/testfile - as opc user
2022-03-17 12:14:20 [DEBUG] - [chan 2] Sesch channel 2 request ok
2022-03-17 12:14:20 [DEBUG] - Sending global request "keepalive@lag.net"
2022-03-17 12:14:20 [DEBUG] - Sending global request "keepalive@lag.net"
2022-03-17 12:14:20 [DEBUG] - [chan 2] EOF received (2)
2022-03-17 12:14:20 [DEBUG] - [chan 2] EOF sent (2)
2022-03-17 12:14:20 [INFO ] - 10.9.59.11 -script ls -ltr /tmp/testfile 0 - exit code is 0
2022-03-17 12:14:20 [INFO ] - [chan 1] sftp session closed.
2022-03-17 12:14:20 [DEBUG] - [chan 1] EOF sent (1)
2022-03-17 12:14:20 [DEBUG] - [chan 0] EOF sent (0)
2022-03-17 12:14:20 [DEBUG] - [chan 0] EOF sent (0)
2022-03-17 12:14:20 [DEBUG] - EOF in transport thread
Linux VM with Paramiko 2.9.2 & Windows – Paramiko 2.7.2 – No issues – Always Good Run.
2022-03-17 12:14:42 [DEBUG] - [chan 0] Max packet out: 32768 bytes
2022-03-17 12:14:42 [DEBUG] - Secsh channel 0 opened.
2022-03-17 12:14:42 [DEBUG] - [chan 1] Max packet in: 32768 bytes
2022-03-17 12:14:42 [DEBUG] - [chan 1] Max packet out: 32768 bytes
2022-03-17 12:14:42 [DEBUG] - Secsh channel 1 opened.
2022-03-17 12:14:42 [DEBUG] - [chan 1] Sesch channel 1 request ok
2022-03-17 12:14:42 [DEBUG] - Sending global request "keepalive@lag.net"
2022-03-17 12:14:42 [INFO ] - [chan 1] Opened sftp connection (server version 3)
2022-03-17 12:14:42 [DEBUG] - [chan 1] open(b'/tmp/testfile', 'wb')
2022-03-17 12:14:42 [DEBUG] - [chan 1] open(b'/tmp/testfile', 'wb') -> 00000000
2022-03-17 12:14:42 [DEBUG] - [chan 1] close(00000000)
2022-03-17 12:14:42 [DEBUG] - Sending global request "keepalive@lag.net"
2022-03-17 12:14:42 [DEBUG] - [chan 1] stat(b'/tmp/testfile')
2022-03-17 12:14:42 [DEBUG] - [chan 2] Max packet in: 32768 bytes
2022-03-17 12:14:42 [DEBUG] - Sending global request "keepalive@lag.net"
2022-03-17 12:14:42 [DEBUG] - [chan 2] Max packet out: 32768 bytes
2022-03-17 12:14:42 [DEBUG] - Secsh channel 2 opened.
2022-03-17 12:14:42 [INFO ] - 10.9.59.11 - Executing script ls -ltr /tmp/testfile - as test user
2022-03-17 12:14:42 [DEBUG] - Sending global request "keepalive@lag.net"
2022-03-17 12:14:42 [DEBUG] - [chan 2] Sesch channel 2 request ok
2022-03-17 12:14:42 [DEBUG] - [chan 2] EOF received (2)
2022-03-17 12:14:42 [DEBUG] - [chan 2] EOF sent (2)
2022-03-17 12:14:42 [DEBUG] - -rw-rw-r--. 1 test test 1702 Mar 17 12:14 /tmp/testfile
2022-03-17 12:14:42 [DEBUG] -
2022-03-17 12:14:42 [INFO ] - 10.9.59.11 -script ls -ltr /tmp/testfile 0 - exit code is 0
2022-03-17 12:14:42 [INFO ] - [chan 1] sftp session closed.
2022-03-17 12:14:42 [DEBUG] - [chan 1] EOF sent (1)
2022-03-17 12:14:42 [DEBUG] - [chan 0] EOF sent (0)
2022-03-17 12:14:42 [DEBUG] - [chan 0] EOF sent (0)
2022-03-17 12:14:42 [DEBUG] - EOF in transport thread
It's probably a race condition. The exit_status_ready can return true if the command has finished, even if you have not read its complete output yet.
The correct code is like:
while True:
exited = channel.exit_status_ready()
if channel.recv_ready():
data = channel.recv(1024)
LOG.debug(data.decode())
while data:
contents.write(data.decode())
data = channel.recv(1024)
LOG.debug(data.decode())
if channel.recv_stderr_ready():
error_buff = channel.recv_stderr(1024)
LOG.debug(error_buff.decode())
while error_buff:
error.write(error_buff.decode())
error_buff = channel.recv_stderr(1024)
LOG.debug(error_buff.decode())
if exited:
break
I.e. to check exit_status_ready before reading the output, but act upon it only afterwards.