test_pull_missing_blob spuriously crashes
Summary
I observed this test case fail in the strangest way today, it appears to have crashed in assertions after having decided to build the same element a second time.
Steps to reproduce
Not sure, it happened to me once while running detox today, since then I've been running the following:
while true; do
if ! detox -- tests/frontend/pull.py::test_pull_missing_blob; then
echo "We failed !"
break
fi
doneAnd it hasn't turned up again yet.
Relevant logs and/or screenshots
Note the few interesting lines leading up to the BUG message:
[00:00:00][5fd3fc52][build:target.bst ] SUCCESS test/target/5fd3fc52-build.25694.log
[--:--:--][ac5452b8][ push:compose-all.bst ] START test/compose-all/ac5452b8-push.25693.log
[--:--:--][ac5452b8][ push:compose-all.bst ] STATUS Pushing artifact ac5452b8 -> http://localhost:34682
[--:--:--][ac5452b8][ push:compose-all.bst ] INFO Pushed artifact ac5452b8 -> http://localhost:34682
[00:00:00][ac5452b8][ push:compose-all.bst ] SUCCESS test/compose-all/ac5452b8-push.25693.log
[--:--:--][5fd3fc52][build:target.bst ] START test/target/5fd3fc52-build.25728.logHere is the interesting log of the failure run:
=================================== FAILURES ===================================
____________________________ test_pull_missing_blob ____________________________
cli = <tests.testutils.runcli.Cli object at 0x7f8ddc1ea470>
tmpdir = local('/codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0')
datafiles = local('/codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0')
@pytest.mark.datafiles(DATA_DIR)
def test_pull_missing_blob(cli, tmpdir, datafiles):
project = os.path.join(datafiles.dirname, datafiles.basename)
with create_artifact_share(os.path.join(str(tmpdir), 'artifactshare')) as share:
# First build the target element and push to the remote.
cli.configure({
'artifacts': {'url': share.repo, 'push': True}
})
result = cli.run(project=project, args=['build', 'target.bst'])
> result.assert_success()
tests/frontend/pull.py:312:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self = <tests.testutils.runcli.Result object at 0x7f8ddc163a90>
fail_message = ''
def assert_success(self, fail_message=''):
> assert self.exit_code == 0, fail_message
E AssertionError:
E assert -1 == 0
E + where -1 = <tests.testutils.runcli.Result object at 0x7f8ddc163a90>.exit_code
tests/testutils/runcli.py:82: AssertionError
----------------------------- Captured stdout call -----------------------------
BuildStream exited with code -1 for invocation:
bst --no-colors --config /codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0/cache/buildstream.conf --directory /codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0 build target.bst
Program stderr was:
[--:--:--][][] START Build
[--:--:--][][] START Loading elements
[00:00:00][][] SUCCESS Loading elements
[--:--:--][][] START Resolving elements
[00:00:00][][] SUCCESS Resolving elements
[--:--:--][][] START Initializing remote caches
Coverage.py warning: No data was collected. (no-data-collected)
[00:00:00][][] SUCCESS Initializing remote caches
[--:--:--][][] START Resolving cached state
[00:00:00][][] SUCCESS Resolving cached state
[--:--:--][][] START Checking sources
[00:00:00][][] SUCCESS Checking sources
BuildStream Version 1.3.0+1230.gd983f231
Session Start: Friday, 11-01-2019 at 12:29:55
Project: test (/codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0)
Targets: target.bst
User Configuration
Configuration File: /codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0/cache/buildstream.conf
Log Files: /codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0/cache/logs
Source Mirrors: /codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0/cache/sources
Build Area: /codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0/cache/build
Artifact Cache: /codethink/GNOME/buildstream/.tox/py36/tmp/test_pull_missing_blob0/cache/artifacts
Strict Build Plan: Yes
Maximum Fetch Tasks: 10
Maximum Build Tasks: 4
Maximum Push Tasks: 4
Maximum Network Retries: 2
Pipeline
waiting 20e5e72ce0a7efebb431012ecd66f188ce2ea23a4ca1d69aa60c4683acc8e3ca import-bin.bst
waiting d01beb58148f1b95e136199b63d0ccdd24f0dbe4953013c12b33d99c5db08bf3 import-dev.bst
waiting ac5452b80c852872f1e3dc6ef0839c0c2a435ec4a92186f5415c8559f0f2af0e compose-all.bst
waiting 5fd3fc525a4a4151b8e1db73ccf2315d362fc2496eb4c4223ad31acd390b730e target.bst
===============================================================================
[--:--:--][20e5e72c][ pull:import-bin.bst ] START test/import-bin/20e5e72c-pull.25485.log
[--:--:--][20e5e72c][ pull:import-bin.bst ] STATUS Pulling artifact 20e5e72c <- http://localhost:34682
[--:--:--][5fd3fc52][ pull:target.bst ] START test/target/5fd3fc52-pull.25487.log
[--:--:--][5fd3fc52][ pull:target.bst ] STATUS Pulling artifact 5fd3fc52 <- http://localhost:34682
[--:--:--][20e5e72c][ pull:import-bin.bst ] INFO Remote (http://localhost:34682) does not have 20e5e72c cached
[00:00:00][20e5e72c][ pull:import-bin.bst ] SKIPPED Pull
[--:--:--][5fd3fc52][ pull:target.bst ] INFO Remote (http://localhost:34682) does not have 5fd3fc52 cached
[00:00:00][5fd3fc52][ pull:target.bst ] SKIPPED Pull
Coverage.py warning: No data was collected. (no-data-collected)
Coverage.py warning: No data was collected. (no-data-collected)
[--:--:--][20e5e72c][build:import-bin.bst ] START test/import-bin/20e5e72c-build.25516.log
[--:--:--][ac5452b8][ pull:compose-all.bst ] START test/compose-all/ac5452b8-pull.25515.log
[--:--:--][ac5452b8][ pull:compose-all.bst ] STATUS Pulling artifact ac5452b8 <- http://localhost:34682
[--:--:--][20e5e72c][build:import-bin.bst ] START Staging sources
[00:00:00][20e5e72c][build:import-bin.bst ] SUCCESS Staging sources
[--:--:--][20e5e72c][build:import-bin.bst ] START Caching artifact
[--:--:--][ac5452b8][ pull:compose-all.bst ] INFO Remote (http://localhost:34682) does not have ac5452b8 cached
[00:00:00][ac5452b8][ pull:compose-all.bst ] SKIPPED Pull
[00:00:00][20e5e72c][build:import-bin.bst ] SUCCESS Caching artifact
[00:00:00][20e5e72c][build:import-bin.bst ] SUCCESS test/import-bin/20e5e72c-build.25516.log
Coverage.py warning: No data was collected. (no-data-collected)
Coverage.py warning: No data was collected. (no-data-collected)
[--:--:--][d01beb58][ pull:import-dev.bst ] START test/import-dev/d01beb58-pull.25546.log
[--:--:--][d01beb58][ pull:import-dev.bst ] STATUS Pulling artifact d01beb58 <- http://localhost:34682
[--:--:--][20e5e72c][ push:import-bin.bst ] START test/import-bin/20e5e72c-push.25556.log
[--:--:--][20e5e72c][ push:import-bin.bst ] STATUS Pushing artifact 20e5e72c -> http://localhost:34682
[--:--:--][d01beb58][ pull:import-dev.bst ] INFO Remote (http://localhost:34682) does not have d01beb58 cached
[00:00:00][d01beb58][ pull:import-dev.bst ] SKIPPED Pull
[--:--:--][20e5e72c][ push:import-bin.bst ] INFO Pushed artifact 20e5e72c -> http://localhost:34682
[00:00:00][20e5e72c][ push:import-bin.bst ] SUCCESS test/import-bin/20e5e72c-push.25556.log
Coverage.py warning: No data was collected. (no-data-collected)
Coverage.py warning: No data was collected. (no-data-collected)
[--:--:--][d01beb58][build:import-dev.bst ] START test/import-dev/d01beb58-build.25628.log
[--:--:--][d01beb58][build:import-dev.bst ] START Staging sources
[00:00:00][d01beb58][build:import-dev.bst ] SUCCESS Staging sources
[--:--:--][d01beb58][build:import-dev.bst ] START Caching artifact
[00:00:00][d01beb58][build:import-dev.bst ] SUCCESS Caching artifact
[00:00:00][d01beb58][build:import-dev.bst ] SUCCESS test/import-dev/d01beb58-build.25628.log
Coverage.py warning: No data was collected. (no-data-collected)
[--:--:--][d01beb58][ push:import-dev.bst ] START test/import-dev/d01beb58-push.25674.log
[--:--:--][ac5452b8][build:compose-all.bst ] START test/compose-all/ac5452b8-build.25675.log
[--:--:--][d01beb58][ push:import-dev.bst ] STATUS Pushing artifact d01beb58 -> http://localhost:34682
[--:--:--][ac5452b8][build:compose-all.bst ] START Staging dependencies
[00:00:00][ac5452b8][build:compose-all.bst ] SUCCESS Staging dependencies
[--:--:--][d01beb58][ push:import-dev.bst ] INFO Pushed artifact d01beb58 -> http://localhost:34682
[00:00:00][d01beb58][ push:import-dev.bst ] SUCCESS test/import-dev/d01beb58-push.25674.log
[--:--:--][ac5452b8][build:compose-all.bst ] START Caching artifact
[00:00:00][ac5452b8][build:compose-all.bst ] SUCCESS Caching artifact
[00:00:00][ac5452b8][build:compose-all.bst ] SUCCESS test/compose-all/ac5452b8-build.25675.log
Coverage.py warning: No data was collected. (no-data-collected)
[--:--:--][5fd3fc52][build:target.bst ] START test/target/5fd3fc52-build.25694.log
[--:--:--][5fd3fc52][build:target.bst ] START Caching artifact
[00:00:00][5fd3fc52][build:target.bst ] SUCCESS Caching artifact
[00:00:00][5fd3fc52][build:target.bst ] SUCCESS test/target/5fd3fc52-build.25694.log
[--:--:--][ac5452b8][ push:compose-all.bst ] START test/compose-all/ac5452b8-push.25693.log
[--:--:--][ac5452b8][ push:compose-all.bst ] STATUS Pushing artifact ac5452b8 -> http://localhost:34682
[--:--:--][ac5452b8][ push:compose-all.bst ] INFO Pushed artifact ac5452b8 -> http://localhost:34682
[00:00:00][ac5452b8][ push:compose-all.bst ] SUCCESS test/compose-all/ac5452b8-push.25693.log
Coverage.py warning: No data was collected. (no-data-collected)
[--:--:--][5fd3fc52][build:target.bst ] START test/target/5fd3fc52-build.25728.log
[00:00:00][5fd3fc52][build:target.bst ] BUG Build
An unhandled exception occured:
Traceback (most recent call last):
File "/codethink/GNOME/buildstream/buildstream/_scheduler/jobs/job.py", line 411, in _child_action
result = self.child_process() # pylint: disable=assignment-from-no-return
File "/codethink/GNOME/buildstream/buildstream/_scheduler/jobs/elementjob.py", line 94, in child_process
return self._action_cb(self._element)
File "/codethink/GNOME/buildstream/buildstream/_scheduler/queues/buildqueue.py", line 71, in process
return element._assemble()
File "/codethink/GNOME/buildstream/buildstream/element.py", line 1552, in _assemble
assert not self._cached_success()
AssertionError
[--:--:--][5fd3fc52][ push:target.bst ] START test/target/5fd3fc52-push.25729.log
Coverage.py warning: No data was collected. (no-data-collected)
[--:--:--][5fd3fc52][ main:target.bst ] BUG Unhandled exception in post processing
Traceback (most recent call last):
File "/codethink/GNOME/buildstream/buildstream/_scheduler/queues/queue.py", line 303, in _job_done
self.done(job, element, result, status)
File "/codethink/GNOME/buildstream/buildstream/_scheduler/queues/buildqueue.py", line 110, in done
element._assemble_done()
File "/codethink/GNOME/buildstream/buildstream/element.py", line 1498, in _assemble_done
assert self.__assemble_scheduled
AssertionError
[--:--:--][5fd3fc52][ push:target.bst ] STATUS Pushing artifact 5fd3fc52 -> http://localhost:34682
[--:--:--][5fd3fc52][ push:target.bst ] INFO Pushed artifact 5fd3fc52 -> http://localhost:34682
[00:00:00][5fd3fc52][ push:target.bst ] SUCCESS test/target/5fd3fc52-push.25729.log
Coverage.py warning: No data was collected. (no-data-collected)
[00:00:01][][] FAILURE Build
Failure Summary
target.bst:
[00:00:00][5fd3fc52][build:target.bst ] BUG Build
An unhandled exception occured:
Traceback (most recent call last):
File "/codethink/GNOME/buildstream/buildstream/_scheduler/jobs/job.py", line 411, in _child_action
result = self.child_process() # pylint: disable=assignment-from-no-return
File "/codethink/GNOME/buildstream/buildstream/_scheduler/jobs/elementjob.py", line 94, in child_process
return self._action_cb(self._element)
File "/codethink/GNOME/buildstream/buildstream/_scheduler/queues/buildqueue.py", line 71, in process
return element._assemble()
File "/codethink/GNOME/buildstream/buildstream/element.py", line 1552, in _assemble
assert not self._cached_success()
AssertionError
[--:--:--][5fd3fc52][ main:target.bst ] BUG Unhandled exception in post processing
Traceback (most recent call last):
File "/codethink/GNOME/buildstream/buildstream/_scheduler/queues/queue.py", line 303, in _job_done
self.done(job, element, result, status)
File "/codethink/GNOME/buildstream/buildstream/_scheduler/queues/buildqueue.py", line 110, in done
element._assemble_done()
File "/codethink/GNOME/buildstream/buildstream/element.py", line 1498, in _assemble_done
assert self.__assemble_scheduled
AssertionError
Pipeline Summary
Total: 4
Session: 4
Pull Queue: processed 0, skipped 4, failed 0
Fetch Queue: processed 0, skipped 4, failed 0
Build Queue: processed 4, skipped 0, failed 1
Push Queue: processed 4, skipped 0, failed 0
----------------------------- Captured stderr call -----------------------------
Coverage.py warning: No data was collected. (no-data-collected)
------------------------------ Captured log call -------------------------------
base_events.py 1285 ERROR Unknown exception in SIGCHLD handler
Traceback (most recent call last):
File "/usr/local/lib/python3.6/asyncio/unix_events.py", line 819, in _sig_chld
self._do_waitpid_all()
File "/usr/local/lib/python3.6/asyncio/unix_events.py", line 885, in _do_waitpid_all
self._do_waitpid(pid)
File "/usr/local/lib/python3.6/asyncio/unix_events.py", line 919, in _do_waitpid
callback(pid, returncode, *args)
File "/codethink/GNOME/buildstream/buildstream/_scheduler/jobs/job.py", line 584, in _parent_child_completed
self._scheduler.job_completed(self, status)
File "/codethink/GNOME/buildstream/buildstream/_scheduler/scheduler.py", line 249, in job_completed
self._sched()
File "/codethink/GNOME/buildstream/buildstream/_scheduler/scheduler.py", line 287, in _sched
job.spawn()
File "/codethink/GNOME/buildstream/buildstream/_scheduler/jobs/job.py", line 187, in spawn
self._watcher.add_child_handler(self._process.pid, self._parent_child_completed)
File "/usr/local/lib/python3.6/asyncio/unix_events.py", line 873, in add_child_handler
self._do_waitpid(pid)
File "/usr/local/lib/python3.6/asyncio/unix_events.py", line 919, in _do_waitpid
callback(pid, returncode, *args)
File "/codethink/GNOME/buildstream/buildstream/_scheduler/jobs/job.py", line 584, in _parent_child_completed
self._scheduler.job_completed(self, status)
File "/codethink/GNOME/buildstream/buildstream/_scheduler/scheduler.py", line 244, in job_completed
self.active_jobs.remove(job)
ValueError: list.remove(x): x not in listEdited by Tristan Van Berkom