make test broken in latest master

[eloquence]

@kushaldas reported, and @conorsch confirmed, the following errors with make test in #127 (comment):

Detailed output

$ make test
python -m unittest discover tests
EF
.
.
.
.
./bin/cat: /usr/local/bin/do-not-open-here: No such file or directory
E/bin/cat: /usr/local/bin/move-to-svs: No such file or directory
E/bin/cat: /usr/local/bin/sd-process-display: No such file or directory
E/bin/cat: /usr/local/bin/sd-process-download: No such file or directory
E/bin/cat: /usr/local/bin/sd-process-feedback: No such file or directory
E...........
.
.
.
.
======================================================================
ERROR: test_dispvm (unittest.loader.ModuleImportFailure)
----------------------------------------------------------------------
ImportError: Failed to import test module: test_dispvm
Traceback (most recent call last):
File "/usr/lib64/python2.7/unittest/loader.py", line 254, in _find_tests
module = self._get_module_from_name(name)
File "/usr/lib64/python2.7/unittest/loader.py", line 232, in _get_module_from_name
__import__(name)
File "/home/kdas/securedrop-workstation/tests/test_dispvm.py", line 9, in <module>
import qubes.tests
ImportError: No module named qubes.tests


======================================================================
ERROR: test_do_not_open_here (test_journalist_vm.SD_Journalist_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/kdas/securedrop-workstation/tests/test_journalist_vm.py", line 21, in test_do_not_open_here
"sd-journalist/do-not-open-here")
File "/home/kdas/securedrop-workstation/tests/base.py", line 55, in assertFilesMatch
remote_content = self._get_file_contents(remote_path)
File "/home/kdas/securedrop-workstation/tests/base.py", line 51, in _get_file_contents
"/bin/cat {}".format(path)])
File "/usr/lib64/python2.7/subprocess.py", line 219, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command '['qvm-run', '-p', 'sd-journalist', '/bin/cat /usr/local/bin/do-not-open-here']' returned non-zero exit status 1

======================================================================
ERROR: test_move_to_svs (test_journalist_vm.SD_Journalist_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/kdas/securedrop-workstation/tests/test_journalist_vm.py", line 13, in test_move_to_svs
"sd-journalist/move-to-svs")
File "/home/kdas/securedrop-workstation/tests/base.py", line 55, in assertFilesMatch
remote_content = self._get_file_contents(remote_path)
File "/home/kdas/securedrop-workstation/tests/base.py", line 51, in _get_file_contents
"/bin/cat {}".format(path)])
File "/usr/lib64/python2.7/subprocess.py", line 219, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command '['qvm-run', '-p', 'sd-journalist', '/bin/cat /usr/local/bin/move-to-svs']' returned non-zero exit status 1

======================================================================
ERROR: test_sd_process_display (test_journalist_vm.SD_Journalist_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/kdas/securedrop-workstation/tests/test_journalist_vm.py", line 29, in test_sd_process_display
"sd-journalist/sd-process-display")
File "/home/kdas/securedrop-workstation/tests/base.py", line 55, in assertFilesMatch
remote_content = self._get_file_contents(remote_path)
File "/home/kdas/securedrop-workstation/tests/base.py", line 51, in _get_file_contents
"/bin/cat {}".format(path)])
File "/usr/lib64/python2.7/subprocess.py", line 219, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command '['qvm-run', '-p', 'sd-journalist', '/bin/cat /usr/local/bin/sd-process-display']' returned non-zero exit status 1

======================================================================
ERROR: test_sd_process_download (test_journalist_vm.SD_Journalist_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/kdas/securedrop-workstation/tests/test_journalist_vm.py", line 17, in test_sd_process_download
"sd-journalist/sd-process-download")
File "/home/kdas/securedrop-workstation/tests/base.py", line 55, in assertFilesMatch
remote_content = self._get_file_contents(remote_path)
File "/home/kdas/securedrop-workstation/tests/base.py", line 51, in _get_file_contents
"/bin/cat {}".format(path)])
File "/usr/lib64/python2.7/subprocess.py", line 219, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command '['qvm-run', '-p', 'sd-journalist', '/bin/cat /usr/local/bin/sd-process-download']' returned non-zero exit status 1

======================================================================
ERROR: test_sd_process_feedback (test_journalist_vm.SD_Journalist_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/kdas/securedrop-workstation/tests/test_journalist_vm.py", line 25, in test_sd_process_feedback
"sd-journalist/sd-process-feedback")
File "/home/kdas/securedrop-workstation/tests/base.py", line 55, in assertFilesMatch
remote_content = self._get_file_contents(remote_path)
File "/home/kdas/securedrop-workstation/tests/base.py", line 51, in _get_file_contents
"/bin/cat {}".format(path)])
File "/usr/lib64/python2.7/subprocess.py", line 219, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command '['qvm-run', '-p', 'sd-journalist', '/bin/cat /usr/local/bin/sd-process-feedback']' returned non-zero exit status 1

======================================================================
FAIL: test_accept_sd_xfer_extracted_file (test_sd_whonix.SD_Whonix_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/kdas/securedrop-workstation/tests/test_sd_whonix.py", line 20, in test_accept_sd_xfer_extracted_file
self.assertFileHasLine("/usr/local/etc/torrc.d/50_user.conf", line)
File "/home/kdas/securedrop-workstation/tests/base.py", line 72, in assertFileHasLine
raise AssertionError(msg)
AssertionError: File /usr/local/etc/torrc.d/50_user.conf does not contain expected line HidServAuth avgfxawdn6c3coe3.onion Il8Xas7uf6rjtc0LxYwhrx

----------------------------------------------------------------------
Ran 27 tests in 78.106s

FAILED (failures=1, errors=6)
Makefile:100: recipe for target 'test' failed
make: *** [test] Error 1

@conorsch also notes:

I'll note also that during salt provisioning runs against e.g. sd-journalist, a temporary management VM spins up, i.e. disp-mgmt-sd-journalist. That should only happen when the target vm is a TemplateVM, but sd-journalist VM is an AppVM. (See #131 for using TemplateVMs across the board.) @joshuathayer has not yet been able to reproduce this failure, so I suspect there's a bit of dev env drift somewhere that we need to investigate.

[conorsch]

During a brief debugging session just now, @joshuathayer pointed me to dom0:/var/log/qubes/mgmt-sd-journalist.log, which showed a stack trace on salt calls during. Snippet:

Trackback for Salt concurrent.futures error

2018-09-05 14:09:38,262 calling 'state.highstate'...
2018-09-05 14:10:57,149 output: sd-journalist:
2018-09-05 14:10:57,150 output:     ----------
2018-09-05 14:10:57,150 output:     _error:
2018-09-05 14:10:57,151 output:         Failed to return clean data
2018-09-05 14:10:57,151 output:     retcode:
2018-09-05 14:10:57,151 output:         0
2018-09-05 14:10:57,151 output:     stderr:
2018-09-05 14:10:57,152 output:         Traceback (most recent call last):
2018-09-05 14:10:57,152 output:           File "/var/tmp/.root_62a99a_salt/salt-call", line 15, in <module>
2018-09-05 14:10:57,152 output:             salt_call()
2018-09-05 14:10:57,152 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/scripts.py", line 395, in salt_call
2018-09-05 14:10:57,152 output:             import salt.cli.call
2018-09-05 14:10:57,152 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/cli/call.py", line 5, in <module>
2018-09-05 14:10:57,153 output:             import salt.utils.parsers
2018-09-05 14:10:57,153 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/utils/parsers.py", line 27, in <module>
2018-09-05 14:10:57,153 output:             import salt.config as config
2018-09-05 14:10:57,153 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/config/__init__.py", line 98, in <module>
2018-09-05 14:10:57,153 output:             _DFLT_IPC_WBUFFER = _gather_buffer_space() * .5
2018-09-05 14:10:57,153 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/config/__init__.py", line 88, in _gather_buffer_space
2018-09-05 14:10:57,154 output:             import salt.grains.core
2018-09-05 14:10:57,154 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/grains/core.py", line 44, in <module>
2018-09-05 14:10:57,154 output:             import salt.utils.dns
2018-09-05 14:10:57,154 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/utils/dns.py", line 32, in <module>
2018-09-05 14:10:57,154 output:             import salt.modules.cmdmod
2018-09-05 14:10:57,155 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/modules/cmdmod.py", line 34, in <module>
2018-09-05 14:10:57,155 output:             import salt.utils.templates
2018-09-05 14:10:57,156 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/utils/templates.py", line 32, in <module>
2018-09-05 14:10:57,156 output:             import salt.utils.http
2018-09-05 14:10:57,156 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/utils/http.py", line 41, in <module>
2018-09-05 14:10:57,156 output:             import salt.loader
2018-09-05 14:10:57,157 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/loader.py", line 28, in <module>
2018-09-05 14:10:57,157 output:             import salt.utils.event
2018-09-05 14:10:57,157 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/utils/event.py", line 85, in <module>
2018-09-05 14:10:57,157 output:             import salt.transport.ipc
2018-09-05 14:10:57,158 output:           File "/var/tmp/.root_62a99a_salt/py2/salt/transport/ipc.py", line 21, in <module>
2018-09-05 14:10:57,160 output:             from tornado.locks import Semaphore
2018-09-05 14:10:57,160 output:           File "/var/tmp/.root_62a99a_salt/py2/tornado/locks.py", line 18, in <module>
2018-09-05 14:10:57,160 output:             from concurrent.futures import CancelledError
2018-09-05 14:10:57,161 output:         ImportError: No module named concurrent.futures
2018-09-05 14:10:57,161 output:     stdout:
2018-09-05 14:10:57,161 exit code: 0

That at least gives us something to debug. I've seen that error before when passing the --show-output flag to qubesctl, so will try to sort out the import problems.

[conorsch]

Finally found a report of this bug upstream: QubesOS/qubes-issues#4272 Long story short, as a temporary workaround:

1. Open terminal in whonix-ws-14 TemplateVM.
2. Run sudo apt install -y python-futures. (N.B. python-futures is a virtual package, pointing to python-concurrent.futures.)
3. Shut down TemplateVM.

Salt then works again against AppVMs based on whonix-ws-14.

[conorsch]

Note that we cannot install this package via salt in the VM, because the package is required to run salt in the VM. 🙂 As a stopgap, we should be able to leverage the salt config targeting dom0 to run an ad-hoc apt-get command to force the package presence that way. Will test that locally before opening a slim PR.

[redshiftzero]

Done via #143

[kushaldas]

My sd-whonix-template is missing the same Python package today.