osv.dev icon indicating copy to clipboard operation
osv.dev copied to clipboard

[WIP] Errors in running test suite

Open lumjjb opened this issue 3 years ago • 4 comments

I followed the instructions in the CONTRIBUTING.md and ran into some issues with running the test suite. I am documenting what I'm running into in this issue (and will update it as I make progress, and i'll create some PRs to help address what I can fix):

WIP

Error 3: ?

cd docker/worker && ./run_tests.sh
+ export GOOGLE_CLOUD_PROJECT=fake-project123
+ GOOGLE_CLOUD_PROJECT=fake-project123
+ pipenv sync
Installing dependencies from Pipfile.lock (92a85e)...
  🐍   ▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉ 0/0 — 00:00:00
All dependencies are now up-to-date!
+ pipenv run python worker_test.py
Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp14ryjwjy/oss-fuzz'...
remote: Enumerating objects: 49666, done.
remote: Counting objects: 100% (49666/49666), done.
remote: Compressing objects: 100% (15251/15251), done.
remote: Total 49666 (delta 33888), reused 49536 (delta 33822), pack-reused 0
Receiving objects: 100% (49666/49666), 34.90 MiB | 27.01 MiB/s, done.
Resolving deltas: 100% (33888/33888), done.
.ERROR:root:Failed to walk repo with invalid commit: 949f182716f037e25394bbb98d39b3295d230a29
FERROR:root:Failed to walk repo with invalid commit: 949f182716f037e25394bbb98d39b3295d230a29
.ERROR:root:Failed to walk repo with invalid commit: b1fa81a5d59e9b4d6e276d82fc17058f3cf139d9
FERROR:root:Failed to walk repo with invalid commit: 00514d6f244f696e750a37083163992c6a50cfd3
F.ERROR:root:Failed to walk repo with invalid commit: b587c21c36a84e16cfc6b39eb68578d43b5281ad
EWARNING:root:Missing FixResult for oss-fuzz:123
F........Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpkkcdrhyu/sources/source'...
remote: Enumerating objects: 12, done.
remote: Counting objects: 100% (12/12), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 12 (delta 6), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (6/6), done.
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/tempfile.py:821: ResourceWarning: Implicitly cleaning up <TemporaryDirectory '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpicjv2yl6'>
  _warnings.warn(warn_message, ResourceWarning)
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmphgaysgio/sources/source'...
remote: Enumerating objects: 12, done.
remote: Counting objects: 100% (12/12), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 12 (delta 6), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (6/6), done.
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/tempfile.py:821: ResourceWarning: Implicitly cleaning up <TemporaryDirectory '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp8qkxj8ji'>
  _warnings.warn(warn_message, ResourceWarning)
../usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/inspect.py:3007: ResourceWarning: unclosed <ssl.SSLSocket fd=16, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.0.207', 57541), raddr=('142.251.40.176', 443)>
  arg_val = kwargs.pop(param_name)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp8dft3bqq/sources/source'...
remote: Enumerating objects: 12, done.
remote: Counting objects: 100% (12/12), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 12 (delta 6), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (6/6), done.
WARNING:root:sha256sum of BLAH-123.yaml no longer matches (expected=invalid vs current=4482d534343fa6e1ab575d2d803ec2e2d53a38993e720cbff98b44c910e5c52a).
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpyhwv0m4b/sources/source'...
remote: Enumerating objects: 12, done.
remote: Counting objects: 100% (12/12), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 12 (delta 6), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (6/6), done.
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/tempfile.py:821: ResourceWarning: Implicitly cleaning up <TemporaryDirectory '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpvt4zmv3o'>
  _warnings.warn(warn_message, ResourceWarning)
WARNING:root:Failed to push: cannot push because a reference that you are trying to update on the remote contains commits that are not present locally.
WARNING:root:Upstream hash for /private/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpyhwv0m4b/sources/source/BLAH-123.yaml changed (expected=4482d534343fa6e1ab575d2d803ec2e2d53a38993e720cbff98b44c910e5c52a vs current=d67e2e944994496c8d8ec76eed0cf9f09679448d584b532bebf941852a37f5ed)
WARNING:root:Discarding changes for BLAH-123 due to conflicts.
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp7nlivts6/sources/source'...
remote: Enumerating objects: 15, done.
remote: Counting objects: 100% (15/15), done.
remote: Compressing objects: 100% (14/14), done.
remote: Total 15 (delta 7), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (15/15), done.
Resolving deltas: 100% (7/7), done.
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpkiamqe26/sources/source'...
remote: Enumerating objects: 14, done.
remote: Counting objects: 100% (14/14), done.
remote: Compressing objects: 100% (13/13), done.
remote: Total 14 (delta 7), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (14/14), done.
Resolving deltas: 100% (7/7), done.
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpc2q_x7iz/sources/source'...
remote: Enumerating objects: 12, done.
remote: Counting objects: 100% (12/12), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 12 (delta 6), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (6/6), done.
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/tempfile.py:821: ResourceWarning: Implicitly cleaning up <TemporaryDirectory '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpekw93j6h'>
  _warnings.warn(warn_message, ResourceWarning)
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/json/decoder.py:353: ResourceWarning: unclosed <ssl.SSLSocket fd=11, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.0.207', 57546), raddr=('142.250.65.240', 443)>
  obj, end = self.scan_once(s, idx)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpholjl4yp/sources/source'...
remote: Enumerating objects: 15, done.
remote: Counting objects: 100% (15/15), done.
remote: Compressing objects: 100% (14/14), done.
remote: Total 15 (delta 7), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (15/15), done.
Resolving deltas: 100% (7/7), done.
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpcggqqheq/sources/source'...
remote: Enumerating objects: 15, done.
remote: Counting objects: 100% (15/15), done.
remote: Compressing objects: 100% (14/14), done.
remote: Total 15 (delta 8), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (15/15), done.
Resolving deltas: 100% (8/8), done.
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/tempfile.py:821: ResourceWarning: Implicitly cleaning up <TemporaryDirectory '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpci76unk7'>
  _warnings.warn(warn_message, ResourceWarning)
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpujpyyxdn/sources/source'...
remote: Enumerating objects: 12, done.
remote: Counting objects: 100% (12/12), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 12 (delta 6), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (6/6), done.
.Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp979i3823/sources/source'...
remote: Enumerating objects: 12, done.
remote: Counting objects: 100% (12/12), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 12 (delta 6), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (6/6), done.
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/tempfile.py:821: ResourceWarning: Implicitly cleaning up <TemporaryDirectory '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpenf82hsw'>
  _warnings.warn(warn_message, ResourceWarning)
FCloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp87e4zj4f/sources/source'...
remote: Enumerating objects: 15, done.
remote: Counting objects: 100% (15/15), done.
remote: Compressing objects: 100% (14/14), done.
remote: Total 15 (delta 8), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (15/15), done.
Resolving deltas: 100% (8/8), done.
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/tempfile.py:821: ResourceWarning: Implicitly cleaning up <TemporaryDirectory '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp_3kc5wnc'>
  _warnings.warn(warn_message, ResourceWarning)
.
======================================================================
ERROR: test_fixed_range_too_long (__main__.ImpactTest)
Test fixed range that's too long.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/lumb/git/osv.dev/osv/impact.py", line 274, in get_commit_and_tag_list
    walker = repo.walk(end_commit,
KeyError: 'object not found - no match for id (b587c21c36a84e16cfc6b39eb68578d43b5281ad)'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/lumb/git/osv.dev/docker/worker/worker_test.py", line 282, in test_fixed_range_too_long
    oss_fuzz.process_impact_task('oss-fuzz:123', message)
  File "/Users/lumb/git/osv.dev/docker/worker/oss_fuzz.py", line 330, in process_impact_task
    regress_commits, fix_commits = _get_commits(repo, regress_result.commit,
  File "/Users/lumb/git/osv.dev/docker/worker/oss_fuzz.py", line 260, in _get_commits
    fix_commits = _get_commit_range(repo, fix_commit_or_range)
  File "/Users/lumb/git/osv.dev/docker/worker/oss_fuzz.py", line 250, in _get_commit_range
    commits, _ = osv.get_commit_and_tag_list(repo, start_commit, end_commit)
  File "/Users/lumb/git/osv.dev/osv/impact.py", line 277, in get_commit_and_tag_list
    raise ImpactError('Invalid commit.') from e
osv.impact.ImpactError: Invalid commit.

======================================================================
FAIL: test_has_issue_id (__main__.FindOssFuzzFixViaCommitTest)
Test identifying the commit that has the issue ID.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/lumb/git/osv.dev/docker/worker/worker_test.py", line 486, in test_has_issue_id
    self.assertEqual('57e58a5d7c2bb3ce0f04f17ec0648b92ee82531f', commit)
AssertionError: '57e58a5d7c2bb3ce0f04f17ec0648b92ee82531f' != None

======================================================================
FAIL: test_has_oss_fuzz_reference (__main__.FindOssFuzzFixViaCommitTest)
Test identifying the commit that has the testcase ID.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/lumb/git/osv.dev/docker/worker/worker_test.py", line 510, in test_has_oss_fuzz_reference
    self.assertEqual('3c5dcf6a5bec14baab3b247d369a7270232e1b83', commit)
AssertionError: '3c5dcf6a5bec14baab3b247d369a7270232e1b83' != None

======================================================================
FAIL: test_has_testcase_id (__main__.FindOssFuzzFixViaCommitTest)
Test identifying the commit that has the testcase ID.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/lumb/git/osv.dev/docker/worker/worker_test.py", line 501, in test_has_testcase_id
    self.assertEqual('90aa4127295b2c37b5f7fcf6a9772b12c99a5212', commit)
AssertionError: '90aa4127295b2c37b5f7fcf6a9772b12c99a5212' != None

======================================================================
FAIL: test_not_fixed (__main__.ImpactTest)
Test not fixed bug.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/lumb/git/osv.dev/docker/worker/worker_test.py", line 410, in test_not_fixed
    self.assertCountEqual([
AssertionError: Element counts were not equal:
First has 1, Second has 0:  'b587c21c36a84e16cfc6b39eb68578d43b5281ad'
First has 1, Second has 0:  '88e5ae3c40c85b702ba89a34c29f233048abb12b'
First has 1, Second has 0:  '3ea6feea9bb853596c727abab309476cc07d1505'

======================================================================
FAIL: test_update_no_introduced (__main__.UpdateTest)
Test update vulnerability with no introduced commit.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/lumb/git/osv.dev/docker/worker/worker_test.py", line 756, in test_update_no_introduced
    self.assertCountEqual([
AssertionError: Element counts were not equal:
First has 1, Second has 0:  '00514d6f244f696e750a37083163992c6a50cfd3'
First has 1, Second has 0:  '25147a74d8aeb27b43665530ee121a2a1b19dc58'
First has 1, Second has 0:  '3c5dcf6a5bec14baab3b247d369a7270232e1b83'
First has 1, Second has 0:  '57e58a5d7c2bb3ce0f04f17ec0648b92ee82531f'
First has 1, Second has 0:  '90aa4127295b2c37b5f7fcf6a9772b12c99a5212'
First has 1, Second has 0:  '949f182716f037e25394bbb98d39b3295d230a29'
First has 1, Second has 0:  'b1fa81a5d59e9b4d6e276d82fc17058f3cf139d9'
First has 1, Second has 0:  'f0cc40d8c3dabb27c2cfe26f1764305abc91a0b9'

----------------------------------------------------------------------
Ran 30 tests in 24.950s

FAILED (failures=5, errors=1)
make: *** [worker-tests] Error 1

Fixed

Error 1: datastore emulator

(osv.dev) ➜  osv.dev git:(master) ✗ make all-tests
...
cd docker/worker && ./run_tests.sh
+ export GOOGLE_CLOUD_PROJECT=fake-project123
[core]
+ GOOGLE_CLOUD_PROJECT=fake-project123
+ pipenv sync
Installing dependencies from Pipfile.lock (92a85e)...
  🐍   ▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉▉ 0/0 — 00:00:00
All dependencies are now up-to-date!
+ pipenv run python worker_test.py
Traceback (most recent call last):
  File "/Users/lumb/git/osv.dev/docker/worker/worker_test.py", line 1061, in <module>
    ds_emulator = tests.start_datastore_emulator()
  File "/Users/lumb/git/osv.dev/osv/tests.py", line 113, in start_datastore_emulator
    _wait_for_emulator_ready(proc, 'datastore', _DATASTORE_READY_INDICATOR)
  File "/Users/lumb/git/osv.dev/osv/tests.py", line 142, in _wait_for_emulator_ready
    raise RuntimeError(
RuntimeError: datastore emulator did not get ready in time.
make: *** [worker-tests] Error 1

This seemed to have been because the command failed to run. Doing the following addressed that error message.

gcloud components install beta cloud-datastore-emulator

Fixed by: https://github.com/google/osv.dev/pull/550

Error 2: Repository not found at osv-test

Log:

Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp6t9lryqa/oss-fuzz'...
remote: Enumerating objects: 49560, done.
remote: Counting objects: 100% (357/357), done.
remote: Compressing objects: 100% (223/223), done.
remote: Total 49560 (delta 182), reused 273 (delta 131), pack-reused 49203
Receiving objects: 100% (49560/49560), 34.93 MiB | 25.87 MiB/s, done.
Resolving deltas: 100% (33700/33700), done.
.EEEEEEEEEE.....Cloning into '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmp_hlyn1gv/sources/source'...
remote: Enumerating objects: 12, done.
remote: Counting objects: 100% (12/12), done.
remote: Compressing objects: 100% (11/11), done.
remote: Total 12 (delta 6), reused 0 (delta 0), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (6/6), done.
/usr/local/Cellar/[email protected]/3.9.13_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/tempfile.py:821: ResourceWarning: Implicitly cleaning up <TemporaryDirectory '/var/folders/7r/3c1qxmkj57x67ddbb7lwtqwc009k_d/T/tmpa3o3w3if'>
  _warnings.warn(warn_message, ResourceWarning)
ERROR:root:Clone failed: Repository not found at osv-test
ERROR:root:Clone failed: Repository not found at osv-test
ERROR:root:Clone failed: Repository not found at osv-test

Seems like osv/repos.py:clone_with_retries is being called with git_url=''

Fixed by: https://github.com/google/osv.dev/pull/550

lumjjb avatar Jul 21 '22 01:07 lumjjb

Thank you for trying these instructions! They're definitely a little rough and I'll address them. @andrewpollock FYI.

oliverchang avatar Jul 21 '22 01:07 oliverchang

Thanks again @lumjjb. Let us know if you run into more issues here!

oliverchang avatar Jul 22 '22 04:07 oliverchang

Awesome - thanks @oliverchang , i pasted a new log for the most recent errors. Only worker-tests having issues, the rest are all good.

I think it may be from .ERROR:root:Failed to walk repo with invalid commit: 949f182716f037e25394bbb98d39b3295d230a29

lumjjb avatar Jul 22 '22 20:07 lumjjb

Thanks @lumjjb ! Those issues should be fixed with https://github.com/google/osv.dev/pull/562

oliverchang avatar Jul 29 '22 18:07 oliverchang

Worker tests look pretty good as of today. There's some GCP auth dependencies (GCS bucket related) that we need to remove, possibly by making them public.

andrewpollock avatar Oct 18 '22 01:10 andrewpollock