When running multiple commands through the run() method of StartShell(), data is not always fully received from the buffer prior to returning got. This means that the output of the 2nd command in the list may be truncated or invalid if the commands are run in succession. I've tried a sleep time within my own code between commands, but it does not solve it.
Example code:
Commands:
- {Command: 'cprod -A <fpc> -c "show jnh 0 pool"'}
- {Command: 'cli -c "show version | display xml | no-more"'}
with StartShell(dev, timeout=30) as ss:
for command in commands:
_ret = ss.run(command['Command'])
<write _ret to file>
2018/08/22 11:03:23 __main__ 109 - INFO: Begin running collection script
2018/08/22 11:03:23 __main__ 111 - INFO: Opening `data.yml` file
2018/08/22 11:03:23 __main__ 129 - INFO: Looping through devices
2018/08/22 11:03:23 __main__ 131 - INFO: ----------------------------------------
2018/08/22 11:03:23 __main__ 132 - INFO: Begin collection from device: mx240
2018/08/22 11:03:23 __main__ 155 - INFO: Attempting connection to mx240
2018/08/22 11:03:23 ncclient.transport.ssh 1687 - INFO: Connected (version 2.0, client OpenSSH_6.6.1)
2018/08/22 11:03:23 ncclient.transport.ssh 1687 - INFO: Auth banner: b'\n--------------------------------------------\n| This is box is for dev and testing |\n| WARNING: UNAUTHORIZED USE OR TAMPERING |\n| IS PROHIBITED. ALL |\n| TRANSACTIONS ARE MONITORED. |\n--------------------------------------------\n'
2018/08/22 11:03:23 ncclient.transport.ssh 1687 - INFO: Authentication (publickey) failed.
2018/08/22 11:03:23 ncclient.transport.ssh 1687 - INFO: Authentication (password) successful!
2018/08/22 11:03:23 ncclient.transport.session 111 - INFO: initialized: session-id=83020 | server_capabilities=<dict_keyiterator object at 0x103b28cc8>
2018/08/22 11:03:23 __main__ 157 - INFO: Opened SSH connection to mx240
2018/08/22 11:03:23 __main__ 169 - INFO: Opening Shell on device mx240
2018/08/22 11:03:23 paramiko.transport 1687 - INFO: Connected (version 2.0, client OpenSSH_6.6.1)
2018/08/22 11:03:24 paramiko.transport 1687 - INFO: Auth banner: b'\n--------------------------------------------\n| This is box is for dev and testing |\n| WARNING: UNAUTHORIZED USE OR TAMPERING |\n| IS PROHIBITED. ALL |\n| TRANSACTIONS ARE MONITORED. |\n--------------------------------------------\n'
2018/08/22 11:03:24 paramiko.transport 1687 - INFO: Authentication (publickey) failed.
2018/08/22 11:03:24 paramiko.transport 1687 - INFO: Authentication (password) successful!
sleep None
recv data: b'Last login: Wed Aug 22 11:00:00 2018 from 192.168.1.1\r\r\n'
sleep None
recv data: b'--- JUNOS 15.1R5-S3.4 Kernel 64-bit JNPR-10.3-20160927.337663_build\r\n'
sleep None
recv data: b'myuser@mx240> '
send data: start shell
send data newline:
sleep None
recv data: b'st'
sleep None
recv data: b'art'
sleep None
recv data: b' s'
sleep None
recv data: b'hell'
sleep None
recv data: b' '
sleep None
recv data: b'\r\n'
sleep None
recv data: b'% '
2018/08/22 11:03:24 __main__ 173 - INFO: opening took 0.8582031726837158 secs
2018/08/22 11:03:24 __main__ 174 - INFO: Connection opened
send data: cprod -A fpc0 -c "show jnh 0 pool"
send data newline:
sleep 0
recv data: b'cpr'
sleep 0
recv data: b'od -A fpc0 -c "show jnh 0 pool"'
sleep 0
recv data: b'\r\r\n'
sleep 0
recv data: b'\r\nPFE 0 JNH Partition is using Cassis-Alloc.\r\nPFE 0 JNH Partition OK check is enabled, requests 3442779\r\n Name MemType Total Used (%) Free (%)\r\n'
sleep 0
recv data: b'\r\n Next Hop EDMEM 4194240 1454163 34% 2740077 66%\r\n\r\n Firewall EDMEM 2097152 41611 1% 2055541 99%\r\n\r\n Counters EDMEM 4194304 2251682 53% 1942622 47%\r\n\r\n LMEM LMEM 128 128 100% 0 0%\r\n\r\n HASH EDMEM 7044608 7044608 100% 0 0%\r\n OMEM 33202208 33202208 100% 0 0%\r\n\r\n ENCAPS EDMEM 4259840 4259840 100% 0 0%\r\n\r\n UEID_SPACE EDMEM 1048576 130 < 1% 1048446 >99%\r\n\r\n UEID_SHARED_SPACE EDMEM 65536 3 < 1% 65533 >99%\r\n'
send data: echo $?
send data newline:
sleep 0
recv data: b'% ' <<<<<<< HERE ISSUE IS FIRST SEEN - THIS IS THE LAST PART OF THE EXPECTED OUTPUT FROM ABOVE RECV CALL
2018/08/22 11:03:24 __main__ 179 - INFO: (False, 'cprod -A fpc0 -c "show jnh 0 pool"\r\r\n\r\nPFE 0 JNH Partition is using Cassis-Alloc.\r\nPFE 0 JNH Partition OK check is enabled, requests 3442779\r\n Name MemType Total Used (%) Free (%)\r\n\r\n Next Hop EDMEM 4194240 1454163 34% 2740077 66%\r\n\r\n Firewall EDMEM 2097152 41611 1% 2055541 99%\r\n\r\n Counters EDMEM 4194304 2251682 53% 1942622 47%\r\n\r\n LMEM LMEM 128 128 100% 0 0%\r\n\r\n HASH EDMEM 7044608 7044608 100% 0 0%\r\n OMEM 33202208 33202208 100% 0 0%\r\n\r\n ENCAPS EDMEM 4259840 4259840 100% 0 0%\r\n\r\n UEID_SPACE EDMEM 1048576 130 < 1% 1048446 >99%\r\n\r\n UEID_SHARED_SPACE EDMEM 65536 3 < 1% 65533 >99%\r\n')
cprod -A fpc0 -c "show jnh 0 pool"
PFE 0 JNH Partition is using Cassis-Alloc.
PFE 0 JNH Partition OK check is enabled, requests 3442779
Name MemType Total Used (%) Free (%)
Next Hop EDMEM 4194240 1454163 34% 2740077 66%
Firewall EDMEM 2097152 41611 1% 2055541 99%
Counters EDMEM 4194304 2251682 53% 1942622 47%
LMEM LMEM 128 128 100% 0 0%
HASH EDMEM 7044608 7044608 100% 0 0%
OMEM 33202208 33202208 100% 0 0%
ENCAPS EDMEM 4259840 4259840 100% 0 0%
UEID_SPACE EDMEM 1048576 130 < 1% 1048446 >99%
UEID_SHARED_SPACE EDMEM 65536 3 < 1% 65533 >99%
send data: cprod -A fpc1 -c "show jnh 0 pool"
send data newline:
sleep 0
recv data: b'ech'
sleep 0
recv data: b'o $?'
sleep 0
recv data: b'\r\r\n'
sleep 0
recv data: b'0\r\n'
sleep 0
recv data: b'% '
send data: echo $?
send data newline:
sleep 0
recv data: b'cprod -A fpc1 -c "show jnh 0 pool"\r\r\n'
sleep 0
recv data: b'\r\nPFE 0 JNH Partition is using Cassis-Alloc.\r\nPFE 0 JNH Partition OK check is enabled, requests 5083143\r\n Name MemType Total Used (%) Free (%)\r\n'
sleep 0
recv data: b'\r\n Next Hop EDMEM 5242816 1455923 27% 3786893 73%\r\n\r\n Firewall EDMEM 2097152 41611 1% 2055541 99%\r\n\r\n Counters EDMEM 4194304 2251770 53% 1942534 47%\r\n\r\n LMEM LMEM 128 128 100% 0 0%\r\n\r\n HASH EDMEM 7044608 7044608 100% 0 0%\r\n OMEM 33202208 33202208 100% 0 0%\r\n\r\n ENCAPS EDMEM 4259840 4259840 100% 0 0%\r\n\r\n UEID_SPACE EDMEM 1048576 129 < 1% 1048447 >99%\r\n\r\n UEID_SHARED_SPACE EDMEM 65536 2 < 1% 65534 >99%\r\n'
2018/08/22 11:03:25 __main__ 179 - INFO: (True, 'echo $?\r\r\n0\r\n% ')
echo $?
0
%
send data: cli -c "show version | display xml | no-more"
send data newline:
sleep 0
recv data: b'% '
send data: echo $?
send data newline:
sleep 0
recv data: b'ech'
sleep 0
recv data: b'o $?\r\r\n'
sleep 0
recv data: b'0\r\n'
sleep 0
recv data: b'% '
2018/08/22 11:03:25 __main__ 179 - INFO: (True, '% ')
%
2018/08/22 11:03:25 ncclient.operations.rpc 313 - INFO: Requesting 'CloseSession'
2018/08/22 11:03:25 __main__ 230 - INFO: Creating a Zip archive of outputs...
2018/08/22 11:03:25 __main__ 233 - INFO: Done
Process finished with exit code 0
Workaround
The only way I worked through this was to add a small sleep time within the StartShell()wait_for() method after trying to retrieve data from the channel. This few millisecond sleep was all it seemed to need to solve the problem. The sleep time I added was 0.05 or 50ms.
while timeout > datetime.datetime.now():
rd, wr, err = select([chan], [], [], _SELECT_WAIT)
if rd:
data = chan.recv(_RECVSZ)
if self.sleep: # <<<<<
time.sleep(self.sleep) # <<<<<
Sample new user code:
with StartShell(dev, timeout=30) as ss:
for command in commands:
_ret = ss.run(command['Command'], sleep=0.05)
<write _ret to file>
Issue
When running multiple commands through the
run()
method ofStartShell()
, data is not always fully received from the buffer prior to returninggot
. This means that the output of the 2nd command in the list may be truncated or invalid if the commands are run in succession. I've tried a sleep time within my own code between commands, but it does not solve it.Example code:
Sample current bad witnessed behavior
Log output during Issue
Workaround
The only way I worked through this was to add a small sleep time within the
StartShell()
wait_for()
method after trying to retrieve data from the channel. This few millisecond sleep was all it seemed to need to solve the problem. The sleep time I added was0.05
or 50ms.Sample new user code:
Workaround output now as expected
Log output from good output with workaround