search

tomerfiliba / plumbum

Plumbum: Shell Combinators
https://plumbum.readthedocs.io
MIT License
2.81k stars 183 forks source link

plumbum remote file stat, EOFError and ShellSessionError errors #187

Open vodik opened 9 years ago

vodik commented 9 years ago

Hi, I'm currently using python2-plumbum 1.4.2 on python 2.7.9.

We're using plumbum internally as part of a testing tool and I'm seeing some curious and spurious failures with plumbum's remote path, specifically the stat call. The test run takes around 5 hours to complete and every few runs I encounter this particilar problem:

I have a remote file, I call stat on it. Every once and a while, this triggers and EOFError exception. In my log, I see this:

Mar 25 11:20:40 [DEBUG] plumbum.shell session.py:207 : Running "stat -c '%F,%f,%i,%d,%h,%u,%g,%s,%X,%Y,%Z' /var/log/<some log file> ; echo $? ; echo '-
Mar 25 11:20:40 [INFO] paramiko.transport transport.py:1430 : Disconnect (code 2): Received ieof for nonexistent channel 3.

At this point I get an EOFError, which is fitting. Then, after this first failure, every single following stat call raises a "ShellSessionError: Each shell may start only one process at a time".

Looking through my log, I can see that channel 3 was created, used, and then closed to service a different command:

Mar 25 11:04:36 [DEBUG] plumbum.paramiko paramiko_machine.py:212 : cd /root && /usr/bin/<some binary>
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] Max packet in: 32768 bytes
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] Max packet out: 32768 bytes
Mar 25 11:04:36 [DEBUG] paramiko.transport transport.py:1430 : Secsh channel 3 opened.
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] Sesch channel 3 request ok
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] EOF received (3)
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] EOF sent (3)

However, the weird thing is that immediately after this command, stat calls still continue to work. Here again a snippet of my log with some additional context of working stat commands.

Mar 25 11:04:36 [DEBUG] plumbum.paramiko paramiko_machine.py:212 : cd /root && /usr/bin/<some binary>
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] Max packet in: 32768 bytes
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] Max packet out: 32768 bytes
Mar 25 11:04:36 [DEBUG] paramiko.transport transport.py:1430 : Secsh channel 3 opened.
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] Sesch channel 3 request ok
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] EOF received (3)
Mar 25 11:04:36 [DEBUG] paramiko.transport channel.py:1072 : [chan 3] EOF sent (3)
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:207 : Running "stat -c '%F,%f,%i,%d,%h,%u,%g,%s,%X,%Y,%Z' /var/log/<some log file> ; echo $? ; echo '-
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 2> ''
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> 'regular file,81a4,130852,2305,1,0,0,570,1427283548,1427295827,1427295827\n'
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> '0\n'
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> ''
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:207 : Running "stat -c '%F,%f,%i,%d,%h,%u,%g,%s,%X,%Y,%Z' /var/log/mediamon.log.1 ; echo $? ; echo 
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 2> "stat: cannot stat `/var/log/<some log file>': No such file or directory\n"
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> '1\n'
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 2> ''
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> ''
Mar 25 11:04:36 [INFO] sangoma.controllers.base.Nsc.dut-001 nsc.py:881 : Truncating log /var/log/<some log file>
Mar 25 11:04:36 [DEBUG] paramiko.transport.sftp sftp.py:129 : [chan 1] open('/var/log/<some log file>', 'wb')
Mar 25 11:04:36 [DEBUG] paramiko.transport.sftp sftp.py:129 : [chan 1] open('/var/log/<some log file>', 'wb') -> 00000000
Mar 25 11:04:36 [DEBUG] paramiko.transport.sftp sftp.py:129 : [chan 1] close(00000000)
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:207 : Running "stat -c '%F,%f,%i,%d,%h,%u,%g,%s,%X,%Y,%Z' /var/log/<some log file> ; echo $? ; echo '--.EN
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 2> ''
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> 'regular file,8180,130860,2305,1,0,0,27782,1427283548,1427295845,1427295845\n'
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> '0\n'
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> ''
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:207 : Running "stat -c '%F,%f,%i,%d,%h,%u,%g,%s,%X,%Y,%Z' /var/log/<some log file> ; echo $? ; echo '--.
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 2> "stat: cannot stat `/var/log/<some log file>': No such file or directory\n"
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> '1\n'
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 2> ''
Mar 25 11:04:36 [DEBUG] plumbum.shell session.py:93 : 1> ''

So it seems like it takes some time for this failure to appear? I'm at a loss. The full log is available, if you feel like you need it. I will try deploying a git build to see if you've already solved this problem, I've found similar issues in the tracker.

vodik commented 9 years ago

I can verify that this still happens on the current HEAD. I'm using #188 in the meanwhile as a workaround for this problem.

vodik commented 9 years ago

Actually, patch #188 made things more resiliant (took a lot longer to trigger) but doesn't work around the problem:

Mar 25 17:15:31 [DEBUG] paramiko.transport.sftp sftp.py:129 : [chan 1] stat('/var/log/<logfile>')
Mar 25 17:15:31 [INFO] paramiko.transport transport.py:1430 : Disconnect (code 2): Received ieof for nonexistent channel 3.

This is interesting because now I don't know where channel 3 comes from here. Channel 3 is used in this log exactly as how it was in the original report.

henryiii commented 9 years ago

I'm setting up MacOS travis builds, and this seems to show up occasionally (at least once). This is the output:

======================================================================
ERROR: test_env (test_remote.TestParamikoMachine)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/travis/build/henryiii/plumbum/tests/test_remote.py", line 131, in test_env
    out = rem.python("-c", "import os;print(os.environ['FOOBAR72'])")
  File "/usr/local/lib/python2.7/site-packages/plumbum/commands/base.py", line 89, in __call__
    return self.run(args, **kwargs)[1]
  File "/usr/local/lib/python2.7/site-packages/plumbum/commands/base.py", line 218, in run
    with self.bgrun(args, **kwargs) as p:
  File "/usr/local/Cellar/python/2.7.10_2/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/usr/local/lib/python2.7/site-packages/plumbum/commands/base.py", line 174, in bgrun
    p = self.popen(args, **kwargs)
  File "/usr/local/lib/python2.7/site-packages/plumbum/machines/remote.py", line 115, in popen
    return self.remote.popen(self[args], **kwargs)
  File "/usr/local/lib/python2.7/site-packages/plumbum/machines/paramiko_machine.py", line 236, in popen
    si, so, se = streams = self._client.exec_command(cmdline, 1)
  File "/usr/local/lib/python2.7/site-packages/paramiko/client.py", line 341, in exec_command
    chan = self._transport.open_session()
  File "/usr/local/lib/python2.7/site-packages/paramiko/transport.py", line 615, in open_session
    max_packet_size=max_packet_size)
  File "/usr/local/lib/python2.7/site-packages/paramiko/transport.py", line 731, in open_channel
    raise e
SSHException: Unable to open channel.
-------------------- >> begin captured logging << --------------------
paramiko.transport: DEBUG: starting thread (client mode): 0xe015d50L
paramiko.transport: INFO: Connected (version 2.0, client OpenSSH_6.2)
paramiko.transport: DEBUG: kex algos:[u'diffie-hellman-group-exchange-sha256', u'diffie-hellman-group-exchange-sha1', u'diffie-hellman-group14-sha1', u'diffie-hellman-group1-sha1'] server key:[u'ssh-rsa', u'ssh-dss'] client encrypt:[u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'arcfour256', u'arcfour128', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com', u'aes128-cbc', u'3des-cbc', u'blowfish-cbc', u'cast128-cbc', u'aes192-cbc', u'aes256-cbc', u'arcfour', u'rijndael-cbc@lysator.liu.se'] server encrypt:[u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'arcfour256', u'arcfour128', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com', u'aes128-cbc', u'3des-cbc', u'blowfish-cbc', u'cast128-cbc', u'aes192-cbc', u'aes256-cbc', u'arcfour', u'rijndael-cbc@lysator.liu.se'] client mac:[u'hmac-md5-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-ripemd160-etm@openssh.com', u'hmac-sha1-96-etm@openssh.com', u'hmac-md5-96-etm@openssh.com', u'hmac-md5', u'hmac-sha1', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-ripemd160', u'hmac-ripemd160@openssh.com', u'hmac-sha1-96', u'hmac-md5-96'] server mac:[u'hmac-md5-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-ripemd160-etm@openssh.com', u'hmac-sha1-96-etm@openssh.com', u'hmac-md5-96-etm@openssh.com', u'hmac-md5', u'hmac-sha1', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-ripemd160', u'hmac-ripemd160@openssh.com', u'hmac-sha1-96', u'hmac-md5-96'] client compress:[u'none', u'zlib@openssh.com'] server compress:[u'none', u'zlib@openssh.com'] client lang:[u''] server lang:[u''] kex follows?False
paramiko.transport: DEBUG: Ciphers agreed: local=aes128-ctr, remote=aes128-ctr
paramiko.transport: DEBUG: using kex diffie-hellman-group14-sha1; server key type ssh-rsa; cipher: local aes128-ctr, remote aes128-ctr; mac: local hmac-sha1, remote hmac-sha1; compression: local none, remote none
paramiko.transport: DEBUG: Switch to new keys ...
paramiko.transport: DEBUG: Adding ssh-rsa host key for 127.0.0.1: 68201825117859b5826681716c8e9bbf
paramiko.transport: DEBUG: Trying discovered key 402c989b09c7a5f519c2c43be20850b2 in /Users/travis/.ssh/id_rsa
paramiko.transport: DEBUG: userauth is OK
paramiko.transport: INFO: Authentication (publickey) successful!
paramiko.transport: DEBUG: [chan 0] Max packet in: 32768 bytes
paramiko.transport: DEBUG: [chan 0] Max packet out: 32768 bytes
paramiko.transport: DEBUG: Secsh channel 0 opened.
paramiko.transport: DEBUG: [chan 0] Sesch channel 0 request ok
plumbum.shell: DEBUG: Running "true ; echo $? ; echo '--.END1265905233.63.--' ; echo '--.END1265905233.63.--' 1>&2"
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running "uname ; echo $? ; echo '--.END328101115.133.--' ; echo '--.END328101115.133.--' 1>&2"
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> 'Darwin\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running "pwd ; echo $? ; echo '--.END1392287188.26.--' ; echo '--.END1392287188.26.--' 1>&2"
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '/Users/travis\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running "env -0; echo ; echo $? ; echo '--.END1336529777.73.--' ; echo '--.END1336529777.73.--' 1>&2"
plumbum.shell: DEBUG: 2> 'env: illegal option -- 0\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 2> 'usage: env [-i] [name=value ...] [utility [argument ...]]\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running "env; echo ; echo $? ; echo '--.END334645697.144.--' ; echo '--.END334645697.144.--' 1>&2"
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> 'SHELL=/bin/bash\n'
plumbum.shell: DEBUG: 1> 'TMPDIR=/var/folders/gw/_2jq29095y7b__wtby9dg_5h0000gn/T/\n'
plumbum.shell: DEBUG: 1> 'SSH_CLIENT=127.0.0.1 49254 22\n'
plumbum.shell: DEBUG: 1> 'USER=travis\n'
plumbum.shell: DEBUG: 1> 'MAIL=/var/mail/travis\n'
plumbum.shell: DEBUG: 1> 'PATH=/usr/bin:/bin:/usr/sbin:/sbin\n'
plumbum.shell: DEBUG: 1> 'PWD=/Users/travis\n'
plumbum.shell: DEBUG: 1> 'SHLVL=1\n'
plumbum.shell: DEBUG: 1> 'HOME=/Users/travis\n'
plumbum.shell: DEBUG: 1> 'LOGNAME=travis\n'
plumbum.shell: DEBUG: 1> 'SSH_CONNECTION=127.0.0.1 49254 127.0.0.1 22\n'
plumbum.shell: DEBUG: 1> '_=/usr/bin/env\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "SHELL"; echo ; echo $? ; echo \'--.END1058202168.23.--\' ; echo \'--.END1058202168.23.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '/bin/bash\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "TMPDIR"; echo ; echo $? ; echo \'--.END103304655.542.--\' ; echo \'--.END103304655.542.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '/var/folders/gw/_2jq29095y7b__wtby9dg_5h0000gn/T/\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "SSH_CLIENT"; echo ; echo $? ; echo \'--.END850997837.142.--\' ; echo \'--.END850997837.142.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '127.0.0.1 49254 22\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "USER"; echo ; echo $? ; echo \'--.END992406113.899.--\' ; echo \'--.END992406113.899.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> 'travis\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "MAIL"; echo ; echo $? ; echo \'--.END874557901.106.--\' ; echo \'--.END874557901.106.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '/var/mail/travis\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "PATH"; echo ; echo $? ; echo \'--.END883244575.79.--\' ; echo \'--.END883244575.79.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '/usr/bin:/bin:/usr/sbin:/sbin\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "PWD"; echo ; echo $? ; echo \'--.END842993231.294.--\' ; echo \'--.END842993231.294.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '/Users/travis\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "SHLVL"; echo ; echo $? ; echo \'--.END488146695.281.--\' ; echo \'--.END488146695.281.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '1\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "HOME"; echo ; echo $? ; echo \'--.END1323730064.86.--\' ; echo \'--.END1323730064.86.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '/Users/travis\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "LOGNAME"; echo ; echo $? ; echo \'--.END1398164427.45.--\' ; echo \'--.END1398164427.45.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> 'travis\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "SSH_CONNECTION"; echo ; echo $? ; echo \'--.END981915824.956.--\' ; echo \'--.END981915824.956.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '127.0.0.1 49254 127.0.0.1 22\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running 'printenv "_"; echo ; echo $? ; echo \'--.END176870540.607.--\' ; echo \'--.END176870540.607.--\' 1>&2'
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '/usr/bin/printenv\n'
plumbum.shell: DEBUG: 1> '\n'
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
paramiko.transport: DEBUG: [chan 1] Max packet in: 32768 bytes
paramiko.transport: DEBUG: [chan 1] Max packet out: 32768 bytes
paramiko.transport: DEBUG: Secsh channel 1 opened.
paramiko.transport: DEBUG: [chan 1] Sesch channel 1 request ok
paramiko.transport.sftp: INFO: [chan 1] Opened sftp connection (server version 3)
paramiko.transport.sftp: DEBUG: [chan 1] stat('/usr/bin/python')
plumbum.paramiko: DEBUG: cd /Users/travis && /usr/bin/python -c "import os;os.environ['FOOBAR72']"
paramiko.transport: DEBUG: [chan 2] Max packet in: 32768 bytes
paramiko.transport: DEBUG: [chan 2] Max packet out: 32768 bytes
paramiko.transport: DEBUG: Secsh channel 2 opened.
paramiko.transport: DEBUG: [chan 2] Sesch channel 2 request ok
paramiko.transport: DEBUG: [chan 2] EOF received (2)
paramiko.transport: DEBUG: [chan 2] EOF sent (2)
plumbum.shell: DEBUG: Running "export FOOBAR72=lala SHELL=/bin/bash SHLVL=1 SSH_CLIENT='127.0.0.1 49254 22' TMPDIR=/var/folders/gw/_2jq29095y7b__wtby9dg_5h0000gn/T/ PWD=/Users/travis LOGNAME=travis USER=travis MAIL=/var/mail/travis PATH=/usr/bin:/bin:/usr/sbin:/sbin SSH_CONNECTION='127.0.0.1 49254 127.0.0.1 22' HOME=/Users/travis _=/usr/bin/printenv ; echo $? ; echo '--.END928959680.009.--' ; echo '--.END928959680.009.--' 1>&2"
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.shell: DEBUG: Running "export FOOBAR72=baba SHELL=/bin/bash SHLVL=1 SSH_CLIENT='127.0.0.1 49254 22' TMPDIR=/var/folders/gw/_2jq29095y7b__wtby9dg_5h0000gn/T/ PWD=/Users/travis LOGNAME=travis USER=travis MAIL=/var/mail/travis PATH=/usr/bin:/bin:/usr/sbin:/sbin SSH_CONNECTION='127.0.0.1 49254 127.0.0.1 22' HOME=/Users/travis _=/usr/bin/printenv ; echo $? ; echo '--.END726563402.299.--' ; echo '--.END726563402.299.--' 1>&2"
plumbum.shell: DEBUG: 2> ''
plumbum.shell: DEBUG: 1> '0\n'
plumbum.shell: DEBUG: 1> ''
plumbum.paramiko: DEBUG: cd /Users/travis && env FOOBAR72=baba /usr/bin/python -c "import os;print(os.environ['FOOBAR72'])"
paramiko.transport: DEBUG: [chan 3] Max packet in: 32768 bytes
paramiko.transport: DEBUG: [chan 3] Max packet out: 32768 bytes
paramiko.transport: DEBUG: Secsh channel 3 opened.
paramiko.transport: DEBUG: [chan 3] Sesch channel 3 request ok
paramiko.transport: DEBUG: [chan 3] EOF received (3)
paramiko.transport: DEBUG: [chan 3] EOF sent (3)
plumbum.paramiko: DEBUG: cd /Users/travis && env FOOBAR72=lala /usr/bin/python -c "import os;print(os.environ['FOOBAR72'])"
paramiko.transport: DEBUG: [chan 4] Max packet in: 32768 bytes
paramiko.transport: INFO: Disconnect (code 2): Received ieof for nonexistent channel 2.
paramiko.transport: DEBUG: [chan 0] EOF sent (0)
paramiko.transport: DEBUG: Dropping user packet because connection is dead.
--------------------- >> end captured logging << ---------------------

Simple forcing a rebuild clears the issue. So it does seem to be random.

I've tried running just this test 100 times on my Mac, in Python 2.7, and it's fine. I do use conda instead of brew on my Mac, otherwise it should be the same as the Travis build.