Tuf: Problems running tuf unit tests against local version of securesyslib

[MVrachev]

Description of issue or feature request:
While I was working on issue https://github.com/secure-systems-lab/securesystemslib/issues/220 I wanted to approach it that way:

1. create and use editable venv in tuf
2. install the development dependencies
3. make the necessary changes in securesyslib
4. adapt tuf with the changes made in securesyslib
5. submit a pr to securesyslib
6. submit a pr to tuf

On step 4 I ran the tests with the tox command I received ConnectionRefusedError: [Errno 111] Connection refused errors when running the unit tests.
Then I stepped back, stashed all my changes and ran all of the tests again and the same happened.
I will paste more details from the logs below.

This error doesn't encounter when running the tests with tox -e py37 for example.
It seems to me that I am missing something when creating my editable venv.

Steps to reproduce the error:

1. Clone securesyslib when the top of the master branch is: https://github.com/secure-systems-lab/securesystemslib/commit/caf029ea61339dc5fa9beedf230ca1d026129169
2. Clone tuf when the top of the master branch is: https://github.com/theupdateframework/tuf/commit/e095112be7d57b26406469b767b7ef8561a8f6a9
3. In the tuf folder run:

$ python3.6 -m venv . .editable_venv
$ source .editable_venv/bin/activate

1. From the securesyslib folder run pip3.6 install -r requirements-dev.txt
2. From the tuf folder run pip3.6 install -r requirements-dev.txt
3. Finally, from the tuf directory, without changing the source code of securesyslib or tuf, run:

(.editable_venv) $ cd ./tests
(.editable_venv) $ python3.6 aggregate_tests.py

and then you will see the following errors:

..................x..............................................................................E
Stderr:
DEBUG:tuf.client.updater:Adding roles delegated from 'targets'.
DEBUG:tuf.client.updater:Adding delegated role: role1.
DEBUG:tuf.client.updater:Adding roles delegated from 'targets'.
DEBUG:tuf.client.updater:Adding delegated role: role1.
DEBUG:tuf.client.updater:Interrogating repository: 'test_repository1'
DEBUG:tuf.client.updater:Interrogating repository: 'test_repository1'
DEBUG:tuf.client.updater:Found local directory for 'test_repository1'
DEBUG:tuf.client.updater:Interrogating repository: 'test_repository1'
DEBUG:tuf.client.updater:Found local directory for 'test_repository1'
DEBUG:tuf.client.updater:Found local Root file at '/home/mvrachev/src/tuf/tests/tmpi_0e23e9/TestMultiRepoUpdater_lys9irpf/test_repository1/metadata/current/root.json'
DEBUG:tuf.client.updater:Interrogating repository: 'test_repository2'
DEBUG:tuf.client.updater:Found local directory for 'test_repository2'
DEBUG:tuf.client.updater:Found local Root file at '/home/mvrachev/src/tuf/tests/tmpi_0e23e9/TestMultiRepoUpdater_lys9irpf/test_repository2/metadata/current/root.json'
DEBUG:tuf.client.updater:Interrogating mappings..{'paths': ['*1.txt'], 'repositories': ['test_repository1', 'test_repository2'], 'terminating': False, 'threshold': 1}
DEBUG:tuf.client.updater:Interrogating pattern '*1.txt'for target: 'non-existent.txt'
DEBUG:tuf.client.updater:Continue searching for relevant paths.
DEBUG:tuf.client.updater:None of the paths are relevant.
DEBUG:tuf.client.updater:Interrogating mappings..{'paths': ['*3.txt'], 'repositories': ['test_repository2'], 'terminating': True, 'threshold': 1}
DEBUG:tuf.client.updater:Interrogating pattern '*3.txt'for target: 'non-existent.txt'
DEBUG:tuf.client.updater:Continue searching for relevant paths.
DEBUG:tuf.client.updater:None of the paths are relevant.
DEBUG:tuf.client.updater:Did not find valid targetinfo for 'non-existent.txt'
DEBUG:tuf.client.updater:Interrogating repository: 'test_repository1'
DEBUG:tuf.client.updater:Found local directory for 'test_repository1'
DEBUG:tuf.client.updater:Found local Root file at '/home/mvrachev/src/tuf/tests/tmpi_0e23e9/TestMultiRepoUpdater_lys9irpf/test_repository1/metadata/current/root.json'
DEBUG:tuf.client.updater:Interrogating repository: 'test_repository2'
DEBUG:tuf.client.updater:Found local directory for 'test_repository2'
DEBUG:tuf.client.updater:Found local Root file at '/home/mvrachev/src/tuf/tests/tmpi_0e23e9/TestMultiRepoUpdater_lys9irpf/test_repository2/metadata/current/root.json'
DEBUG:tuf.client.updater:Interrogating mappings..{'paths': ['*1.txt'], 'repositories': ['test_repository1', 'test_repository2'], 'terminating': False, 'threshold': 1}
DEBUG:tuf.client.updater:Interrogating pattern '*1.txt'for target: 'non-existent.txt'
DEBUG:tuf.client.updater:Continue searching for relevant paths.
DEBUG:tuf.client.updater:None of the paths are relevant.
DEBUG:tuf.client.updater:Interrogating mappings..{'paths': ['*3.txt'], 'repositories': ['test_repository2'], 'terminating': False, 'threshold': 1}
DEBUG:tuf.client.updater:Interrogating pattern '*3.txt'for target: 'non-existent.txt'
DEBUG:tuf.client.updater:Continue searching for relevant paths.
DEBUG:tuf.client.updater:None of the paths are relevant.
DEBUG:tuf.client.updater:Did not find valid targetinfo for 'non-existent.txt'
DEBUG:tuf.client.updater:Interrogating repository: 'test_repository1'
DEBUG:tuf.client.updater:Found local directory for 'test_repository1'
DEBUG:tuf.client.updater:Found local Root file at '/home/mvrachev/src/tuf/tests/tmpi_0e23e9/TestMultiRepoUpdater_lys9irpf/test_repository1/metadata/current/root.json'
DEBUG:tuf.client.updater:Interrogating repository: 'test_repository2'
DEBUG:tuf.client.updater:Found local directory for 'test_repository2'
DEBUG:tuf.client.updater:Found local Root file at '/home/mvrachev/src/tuf/tests/tmpi_0e23e9/TestMultiRepoUpdater_lys9irpf/test_repository2/metadata/current/root.json'
DEBUG:tuf.client.updater:Interrogating mappings..{'paths': ['*1.txt'], 'repositories': ['test_repository1', 'test_repository2'], 'terminating': True, 'threshold': 1}
DEBUG:tuf.client.updater:Interrogating pattern '*1.txt'for target: 'bad3.txt'
DEBUG:tuf.client.updater:Continue searching for relevant paths.
DEBUG:tuf.client.updater:None of the paths are relevant.
DEBUG:tuf.client.updater:Interrogating mappings..{'paths': ['*3.txt'], 'repositories': ['test_repository2'], 'terminating': True, 'threshold': 1}
DEBUG:tuf.client.updater:Interrogating pattern '*3.txt'for target: 'bad3.txt'
DEBUG:tuf.client.updater:Found a match for 'bad3.txt'
DEBUG:tuf.client.updater:Retrieving targetinfo for 'bad3.txt' from repository...
DEBUG:tuf.client.updater:Adding updater for 'test_repository2'
DEBUG:tuf.client.updater:Adding roles delegated from 'targets'.
DEBUG:tuf.client.updater:Adding delegated role: role1.
INFO:tuf.download:Downloading: 'http://localhost:30002/metadata/2.root.json'
DEBUG:tuf.download:url: http://localhost:30002/metadata/2.root.json
DEBUG:tuf.download:session index: http+localhost
DEBUG:tuf.download:Reusing session for http+localhost
ERROR:tuf.download:Could not download URL: 'http://localhost:30002/metadata/2.root.json'
Traceback (most recent call last):
  File "/home/mvrachev/src/tuf/.editable_venv/lib/python3.6/site-packages/urllib3/connection.py", line 157, in _new_conn
    (self._dns_host, self.port), self.timeout, **extra_kw
  File "/home/mvrachev/src/tuf/.editable_venv/lib/python3.6/site-packages/urllib3/util/connection.py", line 84, in create_connection
    raise err
  File "/home/mvrachev/src/tuf/.editable_venv/lib/python3.6/site-packages/urllib3/util/connection.py", line 74, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

There are more exceptions after that, but this is the initial one.
Then the tests are failing with:

======================================================================
ERROR: test_13__get_file (test_updater.TestUpdater)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/mvrachev/src/tuf/tests/test_updater.py", line 1797, in test_13__get_file
    file_type, file_size, download_safely=True)
  File "/home/mvrachev/src/tuf/tuf/client/updater.py", line 1705, in _get_file
    raise tuf.exceptions.NoWorkingMirrorError(file_mirror_errors)
tuf.exceptions.NoWorkingMirrorError: No working mirror was found:
  'localhost:41481': ConnectionError(MaxRetryError("HTTPConnectionPool(host='localhost', port=41481): Max retries exceeded with url: /tmplmmecg9h/TestUpdater_1rv6zrui/repository/metadata/targets.json (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f8c2ff6ae48>: Failed to establish a new connection: [Errno 111] Connection refused',))",),)

Stderr:
DEBUG:tuf.client.updater:Adding roles delegated from 'targets'.
DEBUG:tuf.client.updater:Adding delegated role: role1.
INFO:tuf.download:Downloading: 'http://localhost:41481/tmplmmecg9h/TestUpdater_1rv6zrui/repository/metadata/targets.json'
DEBUG:tuf.download:url: http://localhost:41481/tmplmmecg9h/TestUpdater_1rv6zrui/repository/metadata/targets.json
DEBUG:tuf.download:session index: http+localhost
DEBUG:tuf.download:Reusing session for http+localhost
ERROR:tuf.download:Could not download URL: 'http://localhost:41481/tmplmmecg9h/TestUpdater_1rv6zrui/repository/metadata/targets.json'
Traceback (most recent call last):
  File "/home/mvrachev/src/tuf/.editable_venv/lib/python3.6/site-packages/urllib3/connection.py", line 157, in _new_conn
    (self._dns_host, self.port), self.timeout, **extra_kw
  File "/home/mvrachev/src/tuf/.editable_venv/lib/python3.6/site-packages/urllib3/util/connection.py", line 84, in create_connection
    raise err
  File "/home/mvrachev/src/tuf/.editable_venv/lib/python3.6/site-packages/urllib3/util/connection.py", line 74, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

Expected behavior:

I want to be able to run the tuf unit tests against my local version of securesyslib without any problems.

[MVrachev]

Also, there is one suspicious comment which could be conneted to the problem:

    # NOTE: Following error is raised if a delay is not long enough to allow
    # the server process to set up and start listening:
    #     <urlopen error [Errno 111] Connection refused>
    # or, on Windows:
    #     Failed to establish a new connection: [Errno 111] Connection refused'
    # While 0.3s has consistently worked on Travis and local builds, it led to
    # occasional failures in AppVeyor builds, so increasing this to 2s, sadly.
    time.sleep(2)

https://github.com/theupdateframework/tuf/blob/e095112be7d57b26406469b767b7ef8561a8f6a9/tests/test_updater.py#L1366

[lukpueh]

Thanks for posting this detailed issue report, @MVrachev! I have a feeling that the Connection refused is only the consequence of another error, so I'm not sure the code comment you discovered is actually related.

For background, tuf is not guaranteed to work with the master branch of securesystemslib at all times. We do try, though, to coordinate releases of securesystemslib with its two dependents , i.e. tuf and in-toto.
To keep track of breaking changes, we have a dedicated tox environment with-sslib-master in tuf (see tox.ini) that we also run on Travis but allow to fail. As you can see it currently fails there as well:
https://travis-ci.org/github/theupdateframework/tuf

May I suggest that you take a look when those particular travis builds started to fail and then look at code changes in securesystemslib?

(Btw. tox creates its own virtual environments, installing the requirements defined in tox.ini. For non-with-sslib-master we install the latest securesystemslib release from PyPI, that is why tox -e py37 works for you.)

[MVrachev]

After running git bisect I found that the commit that introduced the error is: 842f8432102b24f5c6a62f2521591a66c2052ca9.

I ran git bisect on tuf and with the current top of the master branch in secure-systems-lab/securesystemslib@caf029e.

Of course, it's possible that some of the latest securesystemslib commits together with the latest tuf commits were the problem.

[lukpueh]

Any news on this issue, @MVrachev?

[MVrachev]

Hi @lukpueh, unfortunately I can't work on that issue at the moment.
I wanted to give some directions to those who can invest time in it and that's why I ran git bisect.

[joshuagl]

I've seen this issue locally even with 842f843 reverted.

My first thought was that it might be some difference in the environment, but a quick eyeball comparison of the with-sslib-master and standard tox environments didn't show any obvious differences.

I did dig into the build history and saw that with-sslib-master tox environment first started failing with PR #988 on build 1747.
However, after a git revert -m 1 1cf085a360aaad739e1cc62fa19a2ece270bb693 locally I'm still seeing the same issue.
Build 1745 for PR #989 passed even for with-sslib-master.

Unfortunately it's hard to determine from the Travis logs what the time was at each of those builds and thus determine what the state of securesystemslib's master branch was at that time.

Needs some further investigation.

[lukpueh]

Unfortunately it's hard to determine from the Travis logs what the time was at each of those builds and thus determine what the state of securesystemslib's master branch was at that time.

sslib's master's HEAD is shown in the install log. Maybe that helps? E.g.
```
with-sslib-master installed: [...] ,-e git+http://github.com/secure-systems-lab/securesystemslib.git@4190a18b1b1b4b9bf5f4bd74e6381808621b8c83#egg=securesystemslib [...]
````

[joshuagl]

Unfortunately it's hard to determine from the Travis logs what the time was at each of those builds and thus determine what the state of securesystemslib's master branch was at that time.

sslib's master's HEAD is shown in the install log. Maybe that helps? E.g.

with-sslib-master installed: [...] ,-e git+http://github.com/secure-systems-lab/securesystemslib.git@4190a18b1b1b4b9bf5f4bd74e6381808621b8c83#egg=securesystemslib [...]

I looked for that and was sure I didn't see it 🤦‍♂ Thanks @lukpueh !

Both builds are using the same securesystemslib commit: fe918f866b131e802abe68798c6c03d3c28c9a66

[lukpueh]

Looks like https://github.com/theupdateframework/tuf/commit/842f8432102b24f5c6a62f2521591a66c2052ca9 indeed broke this (as bisected by @MVrachev 👍).

More specifically, running the test http server as python -m tests.simple_server might be a smart idea if the "tuf" directory is the only (or at least first) directory on the path that has a "tests" subdirectory. But this is not the case if we install securesystemslib in editable mode before you install tuf. 🤦

Moreover, passing a pipe to the subprocess, but not reading from it conceals helpful error messages like: No module named tests.simple_server.

-> And thus the http timeouts in the build logs that break the tests.

So, if we manage to actually start our test http server where needed, the tip of the tuf develop branch indeed works with the tip of the securesystemslib master branch.

A quick way to fix this would be to just run the script as python simple_server.py (which we already do in a few places). The downside is that it requires running the tests from within tests directory (which we already require).

A more flexible way would be assign the path to a tests wide-constant in __init__.py, e.g. as:

SIMPLE_SERVER = os.path.join(os.path.dirname(os.path.realpath(__file__)), "simple_server.py").

I'm curious what others think.

Regardless, I think we should remove the stderr PIPEs to better debug these problems in the future.

[joshuagl]

Yes please, let's remove the stderr PIPEs. I like the idea of a constant for the simple server, that gives us more explicit behaviour that should be easier to debug in future.

Thanks for your excellent work figuring out this issue @lukpueh

[MVrachev]

It's interesting that even without using the editable virtual environment and running
tox I had the same errors for python 3.6 and 3.7 (I don't have 3.5 installed), but the tests are passing for python 2.7.

That's with using the latest version of the develop branch: cf05221d88589abea7f8aebb9f7b100b15240b66

[joshuagl]

We can't assign the path of simple_server.py to a tests wide constant in tests/__init.py__ for the same reason that we can't run simple_server as a module -- when we have both securesystemslib and tuf installed in editable mode (as in the case of the with-sslib-master tox environment) we have two test directories in the path with securesystemslib first.

Instead @MVrachev resolved this issue by assigning the path of simple_server.py to a class variable and using it where invoking simple_server.py by name only does not work (i.e. in cases where subprocess.Popen() is called with a cwd kwarg).

[trishankatdatadog]

Good work, guys!