test_bicommand_environment_expansion currently fails

[Barry Price]

Running the "make test" target in an Ubuntu 20.04 amd64 environment results in one test failure:

lint run-test-pre: PYTHONHASHSEED='1519156813'
lint run-test: commands[0] | python -m flake8 --config=setup.cfg --max-complexity=30 mojo
check_formatting inst-nodeps: /home/ubuntu/mojo/.tox/.tmp/package/1/mojo-1.0.0.zip
check_formatting installed: appdirs==1.4.3,argcomplete==1.11.1,attrs==19.3.0,black==19.10b0,CacheControl==0.12.6,certifi==2019.11.28,cffi==1.14.0,chardet==3.0.4,click==7.1.2,colorama==0.4.3,contextlib2==0.6.0,cryptography==2.9.2,distlib==0.3.0,distro==1.4.0,distro-info==0.0.0,html5lib==1.0.1,idna==2.8,ipaddr==2.2.0,Jinja2==2.11.2,juju-deployer==0.11.0,jujuclient==0.54.0,lockfile==0.12.2,MarkupSafe==1.1.1,mojo==1.0.0,msgpack==0.6.2,packaging==20.3,pathspec==0.8.0,pbr==5.4.5,pep517==0.8.2,progress==1.5,pycparser==2.20,pylxd==2.2.11,pyparsing==2.4.6,python-codetree==1.2.0,python-dateutil==2.8.1,pytoml==0.1.21,PyYAML==5.3.1,regex==2020.6.8,requests==2.22.0,requests-toolbelt==0.9.1,requests-unixsocket==0.2.0,retrying==1.3.3,six==1.14.0,toml==0.10.1,typed-ast==1.4.1,urllib3==1.25.8,webencodings==0.5.1,websocket-client==0.57.0,ws4py==0.5.1
check_formatting run-test-pre: PYTHONHASHSEED='1519156813'
check_formatting run-test: commands[0] | python -m black --exclude=mojo/juju/wait.py --check mojo
All done! ✨ 🍰 ✨
34 files would be left unchanged.
py34 create: /home/ubuntu/mojo/.tox/py34
SKIPPED: InterpreterNotFound: python3.4
py35 create: /home/ubuntu/mojo/.tox/py35
SKIPPED: InterpreterNotFound: python3.5
py36 create: /home/ubuntu/mojo/.tox/py36
SKIPPED: InterpreterNotFound: python3.6
py38 inst-nodeps: /home/ubuntu/mojo/.tox/.tmp/package/1/mojo-1.0.0.zip
py38 installed: appdirs==1.4.3,argcomplete==1.11.1,CacheControl==0.12.6,certifi==2019.11.28,cffi==1.14.0,chardet==3.0.4,colorama==0.4.3,contextlib2==0.6.0,coverage==5.2,cryptography==2.9.2,distlib==0.3.0,distro==1.4.0,distro-info==0.0.0,html5lib==1.0.1,idna==2.8,ipaddr==2.2.0,Jinja2==2.11.2,juju-deployer==0.11.0,jujuclient==0.54.0,lockfile==0.12.2,MarkupSafe==1.1.1,mock==4.0.2,mojo==1.0.0,msgpack==0.6.2,nose==1.3.7,packaging==20.3,pbr==5.4.5,pep517==0.8.2,progress==1.5,pycparser==2.20,pylxd==2.2.11,pyparsing==2.4.6,python-codetree==1.2.0,python-dateutil==2.8.1,pytoml==0.1.21,PyYAML==5.3.1,requests==2.22.0,requests-toolbelt==0.9.1,requests-unixsocket==0.2.0,retrying==1.3.3,six==1.14.0,urllib3==1.25.8,webencodings==0.5.1,websocket-client==0.57.0,ws4py==0.5.1
py38 run-test-pre: PYTHONHASHSEED='1519156813'
py38 run-test: commands[0] | nosetests mojo/tests/
....../home/ubuntu/mojo/.tox/py38/lib/python3.8/site-packages/pylxd/models/operation.py:76: UserWarning: Attempted to set unknown attribute "location" on instance of "Operation"
  warnings.warn(
....................................................................F...........................................
======================================================================
FAIL: Environment variables in bicommand invocations are expanded.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/ubuntu/mojo/mojo/tests/test_mojo.py", line 261, in test_bicommand_environment_expansion
    self.assertEqual(output, response)
AssertionError: 'I' != "I've come to talk with you again."
- I
+ I've come to talk with you again.

[Tom Haddon (mthaddon)]

I don't see this failure - https://paste.ubuntu.com/p/TxXPG8G6KJ/.

Can you take a look at pdb and see if you can figure out why it might be failing for you?

[Barry Price (barryprice)]

Strange, I can reliably reproduce this in a completely fresh Focal VM, so I don't think it's my system - here's a step-by-step guide to reproduce on a fresh install:

https://paste.ubuntu.com/p/zbxJYhZh6g/

We're likely missing a dependency I guess, but I wonder what's on your local system that's making it work, that wouldn't result in an error message on systems where it's missing...

[Tom Haddon (mthaddon)]

I can confirm it's also failing for me inside a VM as created based on the pastebin above.

[Joel Sing (jsing)]

By default the bicommand() function runs subprocess.Popen() with stdin, stdout and stderr all being subprocess.PIPE (as an aside, it seems strange that stdin is subprocess.PIPE rather than subprocess.DEVNULL, when nothing writes to it - that could cause a process to block on read indefinitely). It then runs a select loop that reads stdout and stderr until it encounters EOF. The failing sequence is as follows:

1. stdout becomes ready and we read one byte (the default read length) from it.
2. stderr becomes ready and we read no bytes (EOF) from it.

We now exit the select loop since we encountered EOF, but that was on stderr and there is still more data available on stdout that we have not read.

I believe the fix will be to read until all file descriptors reach EOF.

[Haw Loeung (hloeung)]

Someone should feed the fixes upstream to https://gist.github.com/maw/1711614