Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

BuildGrid tests failing #1582

Closed
gtristan opened this issue Feb 4, 2022 · 10 comments · Fixed by #1612
Closed

BuildGrid tests failing #1582

gtristan opened this issue Feb 4, 2022 · 10 comments · Fixed by #1612
Labels
bug Something isn't working critical The tool is unusable in a certain scenario, or causes data loss remote execution Related to remote execution

Comments

@gtristan
Copy link
Contributor

gtristan commented Feb 4, 2022

While trying to merge #1570 I came across a few problems:

  • The github runners are utter garbage again, so CI just wont run completely, timing out after a mere 30/40 minutes and citing that "this will happen when there is resource starvation on the runner", indicating to me that these runners just dont make the cut.
  • Running CI locally works except I noticed the buildgrid test now fails, but reports a successful error code
    • This might likely happen if ever the buildbarn test were to fail too

To reproduce this, run the following locally in a BuildStream checkout:

./.github/run-ci.sh -s buildgrid
echo $?

Notice there are various failures in the buildgrid test, but the return status of the script is 0

Some relevant snips from the log:

...
tests/remoteexecution/buildfail.py::test_build_remote_failure PASSED                                                                                                                   [ 83%]
tests/remoteexecution/buildtree.py::test_buildtree_remote PASSED                                                                                                                       [ 83%]
tests/remoteexecution/junction.py::test_junction_build_remote PASSED                                                                                                                   [ 83%]
tests/remoteexecution/remotecache.py::test_remote_autotools_build FAILED                                                                                                               [ 83%]
tests/remoteexecution/simple.py::test_remote_autotools_build PASSED                                                                                                                    [ 83%]
tests/remoteexecution/simple.py::test_remote_autotools_run PASSED                                                                                                                      [ 83%]
tests/remoteexecution/workspace.py::test_workspace_build[content] PASSED                                                                                                               [ 83%]
tests/remoteexecution/workspace.py::test_workspace_build[content] ERROR                                                                                                                [ 83%]
tests/remoteexecution/workspace.py::test_workspace_build[time] ERROR                                                                                                                   [ 83%]
...
tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[git-strict] PASSED                                     [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[git-strict] ERROR                                      [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[git-non-strict] ERROR                                  [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[bzr-strict] ERROR                                      [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[bzr-non-strict] ERROR                                  [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[tar-strict] ERROR                                      [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[tar-non-strict] ERROR                                  [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[zip-strict] ERROR                                      [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/build_checkout.py::test_fetch_build_checkout[zip-non-strict] ERROR                                  [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch[git] ERROR                                                                     [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch[bzr] ERROR                                                                     [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch[tar] ERROR                                                                     [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch[zip] ERROR                                                                     [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch_cross_junction[git-inline] ERROR                                               [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch_cross_junction[git-project.refs] ERROR                                         [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch_cross_junction[bzr-inline] ERROR                                               [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch_cross_junction[bzr-project.refs] ERROR                                         [ 93%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch_cross_junction[tar-inline] ERROR                                               [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch_cross_junction[tar-project.refs] ERROR                                         [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch_cross_junction[zip-inline] ERROR                                               [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/fetch.py::test_fetch_cross_junction[zip-project.refs] ERROR                                         [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_fetch[git] ERROR                                                             [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_fetch[bzr] ERROR                                                             [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_fetch[tar] ERROR                                                             [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_fetch[zip] ERROR                                                             [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_fetch_upstream_absent[git] ERROR                                             [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_fetch_upstream_absent[bzr] ERROR                                             [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_fetch_upstream_absent[tar] ERROR                                             [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_fetch_upstream_absent[zip] ERROR                                             [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_from_includes[git] ERROR                                                     [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_from_includes[bzr] ERROR                                                     [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_from_includes[tar] ERROR                                                     [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_from_includes[zip] ERROR                                                     [ 94%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_junction_from_includes[git] ERROR                                            [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_junction_from_includes[bzr] ERROR                                            [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_junction_from_includes[tar] ERROR                                            [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_junction_from_includes[zip] ERROR                                            [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_track_upstream_present[git] ERROR                                            [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_track_upstream_present[bzr] ERROR                                            [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_track_upstream_present[tar] ERROR                                            [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_track_upstream_present[zip] ERROR                                            [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_track_upstream_absent[git] ERROR                                             [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_track_upstream_absent[bzr] ERROR                                             [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_track_upstream_absent[tar] ERROR                                             [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/mirror.py::test_mirror_track_upstream_absent[zip] ERROR                                             [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/source_determinism.py::test_deterministic_source_umask[git] ERROR                                   [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/source_determinism.py::test_deterministic_source_umask[bzr] ERROR                                   [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/source_determinism.py::test_deterministic_source_umask[tar] ERROR                                   [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/source_determinism.py::test_deterministic_source_umask[zip] ERROR                                   [ 95%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track[git-inline] ERROR                                                              [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track[git-project.refs] ERROR                                                        [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track[bzr-inline] ERROR                                                              [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track[bzr-project.refs] ERROR                                                        [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track[tar-inline] ERROR                                                              [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track[tar-project.refs] ERROR                                                        [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track[zip-inline] ERROR                                                              [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track[zip-project.refs] ERROR                                                        [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse[git-1] ERROR                                                           [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse[git-10] ERROR                                                          [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse[bzr-1] ERROR                                                           [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse[bzr-10] ERROR                                                          [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse[tar-1] ERROR                                                           [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse[tar-10] ERROR                                                          [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse[zip-1] ERROR                                                           [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse[zip-10] ERROR                                                          [ 96%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse_except[git] ERROR                                                      [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse_except[bzr] ERROR                                                      [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse_except[tar] ERROR                                                      [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_recurse_except[zip] ERROR                                                      [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_cross_junction[git-inline] ERROR                                                     [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_cross_junction[git-project.refs] ERROR                                               [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_cross_junction[bzr-inline] ERROR                                                     [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_cross_junction[bzr-project.refs] ERROR                                               [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_cross_junction[tar-inline] ERROR                                                     [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_cross_junction[tar-project.refs] ERROR                                               [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_cross_junction[zip-inline] ERROR                                                     [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_cross_junction[zip-project.refs] ERROR                                               [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include[git-inline] ERROR                                                      [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include[git-project.refs] ERROR                                                [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include[bzr-inline] ERROR                                                      [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include[bzr-project.refs] ERROR                                                [ 97%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include[tar-inline] ERROR                                                      [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include[tar-project.refs] ERROR                                                [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include[zip-inline] ERROR                                                      [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include[zip-project.refs] ERROR                                                [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include_junction[git-inline] ERROR                                             [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include_junction[git-project.refs] ERROR                                       [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include_junction[bzr-inline] ERROR                                             [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include_junction[bzr-project.refs] ERROR                                       [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include_junction[tar-inline] ERROR                                             [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include_junction[tar-project.refs] ERROR                                       [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include_junction[zip-inline] ERROR                                             [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_include_junction[zip-project.refs] ERROR                                       [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_junction_included[git-inline] ERROR                                            [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_junction_included[git-project.refs] ERROR                                      [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_junction_included[bzr-inline] ERROR                                            [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_junction_included[bzr-project.refs] ERROR                                      [ 98%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_junction_included[tar-inline] ERROR                                            [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_junction_included[tar-project.refs] ERROR                                      [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_junction_included[zip-inline] ERROR                                            [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track.py::test_track_junction_included[zip-project.refs] ERROR                                      [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track_cross_junction.py::test_cross_junction_multiple_projects[git] ERROR                           [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track_cross_junction.py::test_cross_junction_multiple_projects[bzr] ERROR                           [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track_cross_junction.py::test_cross_junction_multiple_projects[tar] ERROR                           [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track_cross_junction.py::test_cross_junction_multiple_projects[zip] ERROR                           [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track_cross_junction.py::test_track_exceptions[git] ERROR                                           [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track_cross_junction.py::test_track_exceptions[bzr] ERROR                                           [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track_cross_junction.py::test_track_exceptions[tar] ERROR                                           [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/track_cross_junction.py::test_track_exceptions[zip] ERROR                                           [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/workspace.py::test_open[git] ERROR                                                                  [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/workspace.py::test_open[bzr] ERROR                                                                  [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/workspace.py::test_open[tar] ERROR                                                                  [ 99%]
.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_sourcetests/workspace.py::test_open[zip] ERROR                                                                  [100%]

=========================================================================================== ERRORS ===========================================================================================
_____________________________________________________________________ ERROR at teardown of test_workspace_build[content] _____________________________________________________________________

default_thread_number = 1

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
        assert has_no_unexpected_background_threads(default_thread_number)
        yield
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:53: AssertionError
------------------------------------------------------------------------------------ Captured stdout call ------------------------------------------------------------------------------------
BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 workspace open --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/workspace autotools/amhello.bst
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][        ][    main:core activity                 ] START   Checking sources
[00:00:00][        ][    main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][    main:core activity                 ] START   Preparing work plan
[00:00:00][        ][    main:core activity                 ] SUCCESS Preparing work plan

    1 of 1 subtasks processed

[--:--:--][c9c40f65][   fetch:autotools/amhello.bst         ] START   test/autotools-amhello/c9c40f65-fetch.99.log
[--:--:--][c9c40f65][   fetch:autotools/amhello.bst         ] START   Fetching file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/files/amhello.tar.gz
[00:00:00][c9c40f65][   fetch:autotools/amhello.bst         ] SUCCESS Fetching file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/files/amhello.tar.gz
[00:00:00][c9c40f65][   fetch:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/c9c40f65-fetch.99.log
[--:--:--][        ][    main:core activity                 ] INFO    Creating workspace for element autotools/amhello.bst
[--:--:--][c9c40f65][    main:autotools/amhello.bst         ] START   Staging sources to /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/workspace
[00:00:00][c9c40f65][    main:autotools/amhello.bst         ] SUCCESS Staging sources to /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/workspace
[--:--:--][        ][    main:core activity                 ] INFO    Created a workspace for element: autotools/amhello.bst

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 --cache-buildtrees always build autotools/amhello.bst
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Build
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Checking sources
[00:00:00][        ][    main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][        ][    main:core activity                 ] START   Preparing work plan
[00:00:00][        ][    main:core activity                 ] SUCCESS Preparing work plan

    3 of 3 subtasks processed


BuildStream Version 1.93.6+222.gebab0cb40
    Session Start: Friday, 04-02-2022 at 02:20:09
    Project:       test (/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0)
    Targets:       autotools/amhello.bst

User Configuration
    Configuration File:      /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf
    Cache Directory:         /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache
    Log Files:               /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/logs
    Source Mirrors:          /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/sources
    Build Area:              /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/build
    Strict Build Plan:       Yes
    Maximum Fetch Tasks:     10
    Maximum Build Tasks:     4
    Maximum Push Tasks:      4
    Maximum Network Retries: 2

Remote Execution Configuration
    Execution Service:    http://localhost:50051
    Storage Service:      http://localhost:50051
    Action Cache Service: http://localhost:50051

Project: test

    Project Options
        arch:  x86-64
        linux: 1

    Element Plugins
        autotools: core plugin
        stack:     core plugin
        import:    core plugin

    Source Plugins
        workspace: core plugin
        tar:       core plugin

Pipeline
fetch needed 456b61e83c339afb408d03df9db50efdeb0962ffea3cce6a2291a89a89248443 base/base-alpine.bst 
     waiting 7a43f178642961ce8afe6aa7dfe9b0978aecc69b0f6b367a690b90e3bc335cfb base.bst 
     waiting 3da737a54d46131d5d5b2173ea258526fef43ccbc2dc1b8226bc23fec7d49c8e autotools/amhello.bst Workspace: /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/workspace
===============================================================================
[--:--:--][3da737a5][   fetch:autotools/amhello.bst         ] START   test/autotools-amhello/3da737a5-fetch.99.log
[--:--:--][7a43f178][   fetch:base.bst                      ] START   test/base/7a43f178-fetch.99.log
[--:--:--][456b61e8][   fetch:base/base-alpine.bst          ] START   test/base-base-alpine/456b61e8-fetch.99.log
[--:--:--][456b61e8][   fetch:base/base-alpine.bst          ] START   Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
[00:00:00][7a43f178][   fetch:base.bst                      ] SUCCESS test/base/7a43f178-fetch.99.log
[00:00:00][3da737a5][   fetch:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/3da737a5-fetch.99.log
[00:00:07][456b61e8][   fetch:base/base-alpine.bst          ] SUCCESS Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
[00:00:13][456b61e8][   fetch:base/base-alpine.bst          ] SUCCESS test/base-base-alpine/456b61e8-fetch.99.log
[--:--:--][456b61e8][   build:base/base-alpine.bst          ] START   test/base-base-alpine/456b61e8-build.99.log
[--:--:--][456b61e8][   build:base/base-alpine.bst          ] INFO    Using a remote sandbox for artifact base/base-alpine.bst with directory '/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/build/base-base-alpine-pkavag3r'
[--:--:--][456b61e8][   build:base/base-alpine.bst          ] START   Staging sources
[00:00:00][456b61e8][   build:base/base-alpine.bst          ] SUCCESS Staging sources
[--:--:--][456b61e8][   build:base/base-alpine.bst          ] START   Caching artifact
[00:00:00][456b61e8][   build:base/base-alpine.bst          ] SUCCESS Caching artifact
[00:00:00][456b61e8][   build:base/base-alpine.bst          ] SUCCESS test/base-base-alpine/456b61e8-build.99.log
[--:--:--][7a43f178][   build:base.bst                      ] START   test/base/7a43f178-build.99.log
[--:--:--][7a43f178][   build:base.bst                      ] INFO    Using a remote sandbox for artifact base.bst with directory '/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/build/base-ukfln963'
[--:--:--][7a43f178][   build:base.bst                      ] START   Caching artifact
[00:00:00][7a43f178][   build:base.bst                      ] SUCCESS Caching artifact
[00:00:00][7a43f178][   build:base.bst                      ] SUCCESS test/base/7a43f178-build.99.log
[--:--:--][3da737a5][   build:autotools/amhello.bst         ] START   test/autotools-amhello/3da737a5-build.99.log
[--:--:--][3da737a5][   build:autotools/amhello.bst         ] INFO    Using a remote sandbox for artifact autotools/amhello.bst with directory '/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/build/autotools-amhello-pwviha9i'
[--:--:--][3da737a5][   build:autotools/amhello.bst         ] START   Staging dependencies at: /
[00:00:00][3da737a5][   build:autotools/amhello.bst         ] SUCCESS Staging dependencies at: /
[--:--:--][3da737a5][   build:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][3da737a5][   build:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][3da737a5][   build:autotools/amhello.bst         ] START   Staging sources
[00:00:00][3da737a5][   build:autotools/amhello.bst         ] SUCCESS Staging sources
[--:--:--][3da737a5][   build:autotools/amhello.bst         ] START   Running commands

    export NOCONFIGURE=1;
    
    if [ -x ./configure ]; then true;
    elif [ -x ./autogen ]; then ./autogen;
    elif [ -x ./autogen.sh ]; then ./autogen.sh;
    elif [ -x ./bootstrap ]; then ./bootstrap;
    elif [ -x ./bootstrap.sh ]; then ./bootstrap.sh;
    else autoreconf -ivf .;
    fi
    ./configure --prefix=/usr \
    --exec-prefix=/usr \
    --bindir=/usr/bin \
    --sbindir=/usr/sbin \
    --sysconfdir=/etc \
    --datadir=/usr/share \
    --includedir=/usr/include \
    --libdir=/usr/lib \
    --libexecdir=/usr/libexec \
    --localstatedir=/var \
    --sharedstatedir=/usr/com \
    Message contains 25 additional lines

[--:--:--][3da737a5][   build:autotools/amhello.bst         ] START   Uploading input root
[00:00:00][3da737a5][   build:autotools/amhello.bst         ] SUCCESS Uploading input root
[--:--:--][3da737a5][   build:autotools/amhello.bst         ] START   Waiting for the remote build to complete
[00:00:08][3da737a5][   build:autotools/amhello.bst         ] SUCCESS Waiting for the remote build to complete
[00:00:08][3da737a5][   build:autotools/amhello.bst         ] SUCCESS Running commands
[--:--:--][3da737a5][   build:autotools/amhello.bst         ] START   Caching artifact
[00:00:00][3da737a5][   build:autotools/amhello.bst         ] SUCCESS Caching artifact
[00:00:08][3da737a5][   build:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/3da737a5-build.99.log
[00:00:22][        ][    main:core activity                 ] SUCCESS Build

Pipeline Summary
    Total:       3
    Session:     3
    Fetch Queue: processed 3, skipped 0, failed 0 
    Build Queue: processed 3, skipped 0, failed 0 

BuildStream exited with code 0 for invocation:
	bst --no-colors --no-verbose --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 show --deps none --format %{state} autotools/amhello.bst
Program output was:
cached

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache

BuildStream exited with code 0 for invocation:
	bst --no-colors --no-verbose --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 show --deps none --format %{full-key} autotools/amhello.bst
Program output was:
3da737a54d46131d5d5b2173ea258526fef43ccbc2dc1b8226bc23fec7d49c8e

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 shell --build autotools/amhello.bst --use-buildtree -- find . -mindepth 1 -exec stat -c %n::%Y {} ;
Program output was:
./.bst-prepared::1643941228
./.bstproject.yaml::1643941209
./Makefile::1643941228
./Makefile.am::1419947381
./Makefile.in::1643941227
./README::1419976385
./aclocal.m4::1643941226
./autom4te.cache::1321009871
./autom4te.cache/output.0::1643941226
./autom4te.cache/output.1::1643941227
./autom4te.cache/requests::1643941228
./autom4te.cache/traces.0::1643941226
./autom4te.cache/traces.1::1643941227
./build-time::1643941228
./compile::1643941227
./config-time::1643941228
./config.h::1643941228
./config.h.in::1643941228
./config.log::1643941228
./config.status::1643941228
./configure::1643941226
./configure.ac::1419947381
./configure.lineno::1643941227
./depcomp::1643941227
./install-sh::1643941227
./missing::1643941227
./newfile.cfg::1643941209
./src::1321009871
./src/.deps::1321009871
./src/.deps/main.Po::1643941228
./src/Makefile::1643941228
./src/Makefile.am::1419947381
./src/Makefile.in::1643941227
./src/hello::1643941228
./src/main.c::1419947381
./src/main.o::1643941228
./stamp-h1::1643941228

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging dependencies at: /
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging dependencies at: /
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging sources
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging sources
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] STATUS  Running command

    find . -mindepth 1 -exec stat -c %n::%Y {} ;

2022-02-04T02:20:33.213+0000 [895:139874675320896] [buildboxcommon_casclient.cpp:95] [INFO] Setting d_maxBatchTotalSizeBytes = 4128768 bytes by default

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 shell --build autotools/amhello.bst --use-buildtree -- cat build-time
Program output was:
1643941228

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging dependencies at: /
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging dependencies at: /
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging sources
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging sources
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] STATUS  Running command

    cat build-time

2022-02-04T02:20:34.900+0000 [970:140252684687424] [buildboxcommon_casclient.cpp:95] [INFO] Setting d_maxBatchTotalSizeBytes = 4128768 bytes by default

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 artifact checkout autotools/amhello.bst --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/checkout
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging dependencies
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging dependencies
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Checking out files in '/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/checkout'
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Checking out files in '/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/checkout'

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 --cache-buildtrees always build autotools/amhello.bst
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Build
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Checking sources
[00:00:00][        ][    main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][        ][    main:core activity                 ] START   Preparing work plan
[00:00:00][        ][    main:core activity                 ] SUCCESS Preparing work plan

    3 of 3 subtasks processed


BuildStream Version 1.93.6+222.gebab0cb40
    Session Start: Friday, 04-02-2022 at 02:20:37
    Project:       test (/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0)
    Targets:       autotools/amhello.bst

User Configuration
    Configuration File:      /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf
    Cache Directory:         /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache
    Log Files:               /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/logs
    Source Mirrors:          /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/sources
    Build Area:              /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/build
    Strict Build Plan:       Yes
    Maximum Fetch Tasks:     10
    Maximum Build Tasks:     4
    Maximum Push Tasks:      4
    Maximum Network Retries: 2

Remote Execution Configuration
    Execution Service:    http://localhost:50051
    Storage Service:      http://localhost:50051
    Action Cache Service: http://localhost:50051

Project: test

    Project Options
        arch:  x86-64
        linux: 1

    Element Plugins
        autotools: core plugin
        stack:     core plugin
        import:    core plugin

    Source Plugins
        workspace: core plugin
        tar:       core plugin

Pipeline
      cached 456b61e83c339afb408d03df9db50efdeb0962ffea3cce6a2291a89a89248443 base/base-alpine.bst 
      cached 7a43f178642961ce8afe6aa7dfe9b0978aecc69b0f6b367a690b90e3bc335cfb base.bst 
      cached 3da737a54d46131d5d5b2173ea258526fef43ccbc2dc1b8226bc23fec7d49c8e autotools/amhello.bst Workspace: /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/workspace
===============================================================================
[00:00:00][        ][    main:core activity                 ] SUCCESS Build

Pipeline Summary
    Total:       3
    Session:     3
    Fetch Queue: processed 0, skipped 3, failed 0 
    Build Queue: processed 0, skipped 3, failed 0 

BuildStream exited with code 0 for invocation:
	bst --no-colors --no-verbose --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 show --deps none --format %{state} autotools/amhello.bst
Program output was:
cached

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache

BuildStream exited with code 0 for invocation:
	bst --no-colors --no-verbose --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 show --deps none --format %{full-key} autotools/amhello.bst
Program output was:
3da737a54d46131d5d5b2173ea258526fef43ccbc2dc1b8226bc23fec7d49c8e

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 shell --build autotools/amhello.bst --use-buildtree -- find . -mindepth 1 -exec stat -c %n::%Y {} ;
Program output was:
./.bst-prepared::1643941228
./.bstproject.yaml::1643941209
./Makefile::1643941228
./Makefile.am::1419947381
./Makefile.in::1643941227
./README::1419976385
./aclocal.m4::1643941226
./autom4te.cache::1321009871
./autom4te.cache/output.0::1643941226
./autom4te.cache/output.1::1643941227
./autom4te.cache/requests::1643941228
./autom4te.cache/traces.0::1643941226
./autom4te.cache/traces.1::1643941227
./build-time::1643941228
./compile::1643941227
./config-time::1643941228
./config.h::1643941228
./config.h.in::1643941228
./config.log::1643941228
./config.status::1643941228
./configure::1643941226
./configure.ac::1419947381
./configure.lineno::1643941227
./depcomp::1643941227
./install-sh::1643941227
./missing::1643941227
./newfile.cfg::1643941209
./src::1321009871
./src/.deps::1321009871
./src/.deps/main.Po::1643941228
./src/Makefile::1643941228
./src/Makefile.am::1419947381
./src/Makefile.in::1643941227
./src/hello::1643941228
./src/main.c::1419947381
./src/main.o::1643941228
./stamp-h1::1643941228

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging dependencies at: /
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging dependencies at: /
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging sources
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging sources
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] STATUS  Running command

    find . -mindepth 1 -exec stat -c %n::%Y {} ;

2022-02-04T02:20:38.449+0000 [1110:140453338896448] [buildboxcommon_casclient.cpp:95] [INFO] Setting d_maxBatchTotalSizeBytes = 4128768 bytes by default

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 shell --build autotools/amhello.bst --use-buildtree -- cat build-time
Program output was:
1643941228

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging dependencies at: /
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging dependencies at: /
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] START   Staging sources
[00:00:00][3da737a5][    main:autotools/amhello.bst         ] SUCCESS Staging sources
[--:--:--][3da737a5][    main:autotools/amhello.bst         ] STATUS  Running command

    cat build-time

2022-02-04T02:20:40.117+0000 [1185:140236168775744] [buildboxcommon_casclient.cpp:95] [INFO] Setting d_maxBatchTotalSizeBytes = 4128768 bytes by default

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 --cache-buildtrees always build autotools/amhello.bst
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Build
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Checking sources
[00:00:00][        ][    main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][        ][    main:core activity                 ] START   Preparing work plan
[00:00:00][        ][    main:core activity                 ] SUCCESS Preparing work plan

    3 of 3 subtasks processed


BuildStream Version 1.93.6+222.gebab0cb40
    Session Start: Friday, 04-02-2022 at 02:20:41
    Project:       test (/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0)
    Targets:       autotools/amhello.bst

User Configuration
    Configuration File:      /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf
    Cache Directory:         /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache
    Log Files:               /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/logs
    Source Mirrors:          /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/sources
    Build Area:              /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/build
    Strict Build Plan:       Yes
    Maximum Fetch Tasks:     10
    Maximum Build Tasks:     4
    Maximum Push Tasks:      4
    Maximum Network Retries: 2

Remote Execution Configuration
    Execution Service:    http://localhost:50051
    Storage Service:      http://localhost:50051
    Action Cache Service: http://localhost:50051

Project: test

    Project Options
        arch:  x86-64
        linux: 1

    Element Plugins
        autotools: core plugin
        stack:     core plugin
        import:    core plugin

    Source Plugins
        workspace: core plugin
        tar:       core plugin

Pipeline
      cached 456b61e83c339afb408d03df9db50efdeb0962ffea3cce6a2291a89a89248443 base/base-alpine.bst 
      cached 7a43f178642961ce8afe6aa7dfe9b0978aecc69b0f6b367a690b90e3bc335cfb base.bst 
   buildable 5ddd4cd54319df305e4b04e060e75116d544a2dfeeecddcdde732fc7328bc67f autotools/amhello.bst Workspace: /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/workspace
===============================================================================
[--:--:--][5ddd4cd5][   fetch:autotools/amhello.bst         ] START   test/autotools-amhello/5ddd4cd5-fetch.99.log
[00:00:00][5ddd4cd5][   fetch:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/5ddd4cd5-fetch.99.log
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] START   test/autotools-amhello/5ddd4cd5-build.99.log
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] INFO    Using a remote sandbox for artifact autotools/amhello.bst with directory '/home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/build/autotools-amhello-6tlco71f'
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] START   Staging dependencies at: /
[00:00:00][5ddd4cd5][   build:autotools/amhello.bst         ] SUCCESS Staging dependencies at: /
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][5ddd4cd5][   build:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] START   Staging sources
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] INFO    Incremental build
[00:00:00][5ddd4cd5][   build:autotools/amhello.bst         ] SUCCESS Staging sources
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] START   Running commands

    make
    date +%s > build-time
    make -j1 DESTDIR="/buildstream-install" install
    if false || false; then
      find "/buildstream-install" -name "*.la" -print0 | while read -d '' -r file; do
        if grep '^shouldnotlink=yes$' "${file}" &>/dev/null; then
          if false; then
            echo "Removing ${file}."
            rm "${file}"
          else
            echo "Not removing ${file}."
          fi
        else
          if false; then
            echo "Removing ${file}."
            rm "${file}"
          else
            echo "Not removing ${file}."
          fi
        fi
    Message contains 2 additional lines

[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] START   Uploading input root
[00:00:00][5ddd4cd5][   build:autotools/amhello.bst         ] SUCCESS Uploading input root
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] START   Waiting for the remote build to complete
[00:00:03][5ddd4cd5][   build:autotools/amhello.bst         ] SUCCESS Waiting for the remote build to complete
[00:00:04][5ddd4cd5][   build:autotools/amhello.bst         ] SUCCESS Running commands
[--:--:--][5ddd4cd5][   build:autotools/amhello.bst         ] START   Caching artifact
[00:00:00][5ddd4cd5][   build:autotools/amhello.bst         ] SUCCESS Caching artifact
[00:00:04][5ddd4cd5][   build:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/5ddd4cd5-build.99.log
[00:00:04][        ][    main:core activity                 ] SUCCESS Build

Pipeline Summary
    Total:       3
    Session:     3
    Fetch Queue: processed 1, skipped 2, failed 0 
    Build Queue: processed 1, skipped 2, failed 0 

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 shell --build autotools/amhello.bst --use-buildtree -- find . -mindepth 1 -exec stat -c %n::%Y {} ;
Program output was:
./.bst-prepared::1643941228
./.bstproject.yaml::1643941209
./Makefile::1643941228
./Makefile.am::1419947381
./Makefile.in::1643941227
./README::1419976385
./aclocal.m4::1643941226
./autom4te.cache::1321009871
./autom4te.cache/output.0::1643941226
./autom4te.cache/output.1::1643941227
./autom4te.cache/requests::1643941228
./autom4te.cache/traces.0::1643941226
./autom4te.cache/traces.1::1643941227
./build-time::1643941243
./compile::1643941227
./config-time::1643941228
./config.h::1643941228
./config.h.in::1643941228
./config.log::1643941228
./config.status::1643941228
./configure::1643941226
./configure.ac::1419947381
./configure.lineno::1643941227
./depcomp::1643941227
./install-sh::1643941227
./missing::1643941227
./newfile.cfg::1643941209
./src::1321009871
./src/.deps::1321009871
./src/.deps/main.Po::1643941243
./src/Makefile::1643941228
./src/Makefile.am::1419947381
./src/Makefile.in::1643941227
./src/hello::1643941243
./src/main.c::1643941241
./src/main.o::1643941243
./stamp-h1::1643941228

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][5ddd4cd5][    main:autotools/amhello.bst         ] START   Staging dependencies at: /
[00:00:00][5ddd4cd5][    main:autotools/amhello.bst         ] SUCCESS Staging dependencies at: /
[--:--:--][5ddd4cd5][    main:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][5ddd4cd5][    main:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][5ddd4cd5][    main:autotools/amhello.bst         ] START   Staging sources
[00:00:00][5ddd4cd5][    main:autotools/amhello.bst         ] SUCCESS Staging sources
[--:--:--][5ddd4cd5][    main:autotools/amhello.bst         ] STATUS  Running command

    find . -mindepth 1 -exec stat -c %n::%Y {} ;

2022-02-04T02:20:46.438+0000 [1254:140234959738944] [buildboxcommon_casclient.cpp:95] [INFO] Setting d_maxBatchTotalSizeBytes = 4128768 bytes by default

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_workspace_build_content_0 shell --build autotools/amhello.bst --use-buildtree -- cat build-time
Program output was:
1643941243

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:autotools/amhello.bst         ] START   Staging local files
[00:00:00][        ][    main:autotools/amhello.bst         ] SUCCESS Staging local files
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][5ddd4cd5][    main:autotools/amhello.bst         ] START   Staging dependencies at: /
[00:00:00][5ddd4cd5][    main:autotools/amhello.bst         ] SUCCESS Staging dependencies at: /
[--:--:--][5ddd4cd5][    main:autotools/amhello.bst         ] START   Integrating sandbox
[00:00:00][5ddd4cd5][    main:autotools/amhello.bst         ] SUCCESS Integrating sandbox
[--:--:--][5ddd4cd5][    main:autotools/amhello.bst         ] START   Staging sources
[00:00:00][5ddd4cd5][    main:autotools/amhello.bst         ] SUCCESS Staging sources
[--:--:--][5ddd4cd5][    main:autotools/amhello.bst         ] STATUS  Running command

    cat build-time

2022-02-04T02:20:48.230+0000 [1329:140367466801216] [buildboxcommon_casclient.cpp:95] [INFO] Setting d_maxBatchTotalSizeBytes = 4128768 bytes by default

________________________________________________________________________ ERROR at setup of test_workspace_build[time] ________________________________________________________________________

default_thread_number = 1

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at teardown of test_fetch_build_checkout[git-strict] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
        assert has_no_unexpected_background_threads(default_thread_number)
        yield
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:53: AssertionError
------------------------------------------------------------------------------------ Captured stdout call ------------------------------------------------------------------------------------
Initialized empty Git repository in /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo/.git/
[master (root-commit) 2abde3f] Initial commit
 1 file changed, 12 insertions(+)
 create mode 100644 usr/include/pony.h
BuildStream exited with code 0 for invocation:
	bst --no-colors --no-verbose --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0 show --deps none --format %{state} build-test-git.bst
Program output was:
fetch needed

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    1 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:build-test-git.bst            ] WARNING [unaliased-url]: git source at build-test-git.bst [line 3 column 2]: Use of unaliased source download URL: file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    1 of 1 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0 build build-test-git.bst
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Build
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    1 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:build-test-git.bst            ] WARNING [unaliased-url]: git source at build-test-git.bst [line 3 column 2]: Use of unaliased source download URL: file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[--:--:--][        ][    main:build-test-git.bst            ] STATUS  Running host command

    /usr/bin/git --version

[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    1 of 1 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Checking sources
[00:00:00][        ][    main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][        ][    main:core activity                 ] START   Preparing work plan
[00:00:00][        ][    main:core activity                 ] SUCCESS Preparing work plan

    1 of 1 subtasks processed


BuildStream Version 1.93.6+222.gebab0cb40
    Session Start: Friday, 04-02-2022 at 02:21:00
    Project:       test (/home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0)
    Targets:       build-test-git.bst

User Configuration
    Configuration File:      /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/buildstream.conf
    Cache Directory:         /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache
    Log Files:               /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/logs
    Source Mirrors:          /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/sources
    Build Area:              /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/build
    Strict Build Plan:       Yes
    Maximum Fetch Tasks:     10
    Maximum Build Tasks:     4
    Maximum Push Tasks:      4
    Maximum Network Retries: 2

Project: test

    Project Options
        arch:  x86-64
        linux: 1

    Element Plugins
        import: core plugin

    Source Plugins
        git: core plugin

Pipeline
fetch needed 29139f2488505d248ac32f22b7558d6a4e400b1b8ff378e39ea205ea8f2c5732 build-test-git.bst 
===============================================================================
[--:--:--][29139f24][   fetch:build-test-git.bst            ] START   test/build-test-git/29139f24-fetch.99.log
[--:--:--][29139f24][   fetch:build-test-git.bst            ] WARNING [unaliased-url]: git source at build-test-git.bst [line 3 column 2]: Use of unaliased source download URL: file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[--:--:--][29139f24][   fetch:build-test-git.bst            ] START   Fetching from file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[00:00:00][29139f24][   fetch:build-test-git.bst            ] SUCCESS Fetching from file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[--:--:--][29139f24][   fetch:build-test-git.bst            ] STATUS  Running host command

    /usr/bin/git show 2abde3f5dd1611de18c48ad51dc16457f5c47f55:.gitmodules

[--:--:--][29139f24][   fetch:build-test-git.bst            ] STATUS  Running host command

    /usr/bin/git branch --list master --contains 2abde3f5dd1611de18c48ad51dc16457f5c47f55

[--:--:--][29139f24][   fetch:build-test-git.bst            ] START   Staging file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[00:00:00][29139f24][   fetch:build-test-git.bst            ] SUCCESS Staging file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[00:00:00][29139f24][   fetch:build-test-git.bst            ] SUCCESS test/build-test-git/29139f24-fetch.99.log
[--:--:--][29139f24][   build:build-test-git.bst            ] START   test/build-test-git/29139f24-build.99.log
[--:--:--][29139f24][   build:build-test-git.bst            ] START   Staging sources
[00:00:00][29139f24][   build:build-test-git.bst            ] SUCCESS Staging sources
[--:--:--][29139f24][   build:build-test-git.bst            ] START   Caching artifact
[00:00:00][29139f24][   build:build-test-git.bst            ] SUCCESS Caching artifact
[00:00:00][29139f24][   build:build-test-git.bst            ] SUCCESS test/build-test-git/29139f24-build.99.log
[00:00:00][        ][    main:core activity                 ] SUCCESS Build

Pipeline Summary
    Total:       1
    Session:     1
    Fetch Queue: processed 1, skipped 0, failed 0 
    Build Queue: processed 1, skipped 0, failed 0 

BuildStream exited with code 0 for invocation:
	bst --no-colors --no-verbose --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0 show --deps none --format %{state} build-test-git.bst
Program output was:
cached

Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    1 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:build-test-git.bst            ] WARNING [unaliased-url]: git source at build-test-git.bst [line 3 column 2]: Use of unaliased source download URL: file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    1 of 1 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache

BuildStream exited with code 0 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0 artifact checkout build-test-git.bst --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/checkout
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    1 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[--:--:--][        ][    main:build-test-git.bst            ] WARNING [unaliased-url]: git source at build-test-git.bst [line 3 column 2]: Use of unaliased source download URL: file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/repo
[--:--:--][        ][    main:build-test-git.bst            ] STATUS  Running host command

    /usr/bin/git --version

[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    1 of 1 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Query cache
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][29139f24][    main:build-test-git.bst            ] START   Staging dependencies
[00:00:00][29139f24][    main:build-test-git.bst            ] SUCCESS Staging dependencies
[--:--:--][29139f24][    main:build-test-git.bst            ] START   Integrating sandbox
[00:00:00][29139f24][    main:build-test-git.bst            ] SUCCESS Integrating sandbox
[--:--:--][29139f24][    main:build-test-git.bst            ] START   Checking out files in '/home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/checkout'
[00:00:00][29139f24][    main:build-test-git.bst            ] SUCCESS Checking out files in '/home/testuser/buildstream/.tox/py310-nocover/tmp/test_fetch_build_checkout_git_0/cache/checkout'

------------------------------------------------------------------------------------ Captured stderr call ------------------------------------------------------------------------------------
hint: Using 'master' as the name for the initial branch. This default branch name
hint: is subject to change. To configure the initial branch name to use in all
hint: of your new repositories, which will suppress this warning, call:
hint: 
hint: 	git config --global init.defaultBranch <name>
hint: 
hint: Names commonly chosen instead of 'master' are 'main', 'trunk' and
hint: 'development'. The just-created branch can be renamed via this command:
hint: 
hint: 	git branch -m <name>
________________________________________________________________ ERROR at setup of test_fetch_build_checkout[git-non-strict] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_fetch_build_checkout[bzr-strict] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________ ERROR at setup of test_fetch_build_checkout[bzr-non-strict] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_fetch_build_checkout[tar-strict] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________ ERROR at setup of test_fetch_build_checkout[tar-non-strict] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_fetch_build_checkout[zip-strict] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________ ERROR at setup of test_fetch_build_checkout[zip-non-strict] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_____________________________________________________________________________ ERROR at setup of test_fetch[git] ______________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_____________________________________________________________________________ ERROR at setup of test_fetch[bzr] ______________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_____________________________________________________________________________ ERROR at setup of test_fetch[tar] ______________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_____________________________________________________________________________ ERROR at setup of test_fetch[zip] ______________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_fetch_cross_junction[git-inline] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_______________________________________________________________ ERROR at setup of test_fetch_cross_junction[git-project.refs] ________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_fetch_cross_junction[bzr-inline] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_______________________________________________________________ ERROR at setup of test_fetch_cross_junction[bzr-project.refs] ________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_fetch_cross_junction[tar-inline] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_______________________________________________________________ ERROR at setup of test_fetch_cross_junction[tar-project.refs] ________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_fetch_cross_junction[zip-inline] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_______________________________________________________________ ERROR at setup of test_fetch_cross_junction[zip-project.refs] ________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________________ ERROR at setup of test_mirror_fetch[git] __________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________________ ERROR at setup of test_mirror_fetch[bzr] __________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________________ ERROR at setup of test_mirror_fetch[tar] __________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________________ ERROR at setup of test_mirror_fetch[zip] __________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_mirror_fetch_upstream_absent[git] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_mirror_fetch_upstream_absent[bzr] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_mirror_fetch_upstream_absent[tar] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_mirror_fetch_upstream_absent[zip] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_mirror_from_includes[git] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_mirror_from_includes[bzr] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_mirror_from_includes[tar] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_mirror_from_includes[zip] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_mirror_junction_from_includes[git] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_mirror_junction_from_includes[bzr] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_mirror_junction_from_includes[tar] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_mirror_junction_from_includes[zip] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_mirror_track_upstream_present[git] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_mirror_track_upstream_present[bzr] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_mirror_track_upstream_present[tar] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_mirror_track_upstream_present[zip] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_mirror_track_upstream_absent[git] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_mirror_track_upstream_absent[bzr] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_mirror_track_upstream_absent[tar] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_mirror_track_upstream_absent[zip] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
___________________________________________________________________ ERROR at setup of test_deterministic_source_umask[git] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
___________________________________________________________________ ERROR at setup of test_deterministic_source_umask[bzr] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
___________________________________________________________________ ERROR at setup of test_deterministic_source_umask[tar] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
___________________________________________________________________ ERROR at setup of test_deterministic_source_umask[zip] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________________ ERROR at setup of test_track[git-inline] __________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_______________________________________________________________________ ERROR at setup of test_track[git-project.refs] _______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________________ ERROR at setup of test_track[bzr-inline] __________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_______________________________________________________________________ ERROR at setup of test_track[bzr-project.refs] _______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________________ ERROR at setup of test_track[tar-inline] __________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_______________________________________________________________________ ERROR at setup of test_track[tar-project.refs] _______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________________ ERROR at setup of test_track[zip-inline] __________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_______________________________________________________________________ ERROR at setup of test_track[zip-project.refs] _______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_recurse[git-1] _________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_recurse[git-10] ________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_recurse[bzr-1] _________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_recurse[bzr-10] ________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_recurse[tar-1] _________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_recurse[tar-10] ________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_recurse[zip-1] _________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_recurse[zip-10] ________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_track_recurse_except[git] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_track_recurse_except[bzr] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_track_recurse_except[tar] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_track_recurse_except[zip] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_____________________________________________________________________ ERROR at setup of test_cross_junction[git-inline] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_cross_junction[git-project.refs] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_____________________________________________________________________ ERROR at setup of test_cross_junction[bzr-inline] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_cross_junction[bzr-project.refs] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_____________________________________________________________________ ERROR at setup of test_cross_junction[tar-inline] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_cross_junction[tar-project.refs] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_____________________________________________________________________ ERROR at setup of test_cross_junction[zip-inline] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
__________________________________________________________________ ERROR at setup of test_cross_junction[zip-project.refs] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_track_include[git-inline] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
___________________________________________________________________ ERROR at setup of test_track_include[git-project.refs] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_track_include[bzr-inline] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
___________________________________________________________________ ERROR at setup of test_track_include[bzr-project.refs] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_track_include[tar-inline] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
___________________________________________________________________ ERROR at setup of test_track_include[tar-project.refs] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________ ERROR at setup of test_track_include[zip-inline] ______________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
___________________________________________________________________ ERROR at setup of test_track_include[zip-project.refs] ___________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_track_include_junction[git-inline] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________ ERROR at setup of test_track_include_junction[git-project.refs] _______________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_track_include_junction[bzr-inline] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________ ERROR at setup of test_track_include_junction[bzr-project.refs] _______________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_track_include_junction[tar-inline] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________ ERROR at setup of test_track_include_junction[tar-project.refs] _______________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_track_include_junction[zip-inline] __________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________ ERROR at setup of test_track_include_junction[zip-project.refs] _______________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_track_junction_included[git-inline] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________ ERROR at setup of test_track_junction_included[git-project.refs] ______________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_track_junction_included[bzr-inline] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________ ERROR at setup of test_track_junction_included[bzr-project.refs] ______________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_track_junction_included[tar-inline] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________ ERROR at setup of test_track_junction_included[tar-project.refs] ______________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
_________________________________________________________________ ERROR at setup of test_track_junction_included[zip-inline] _________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________ ERROR at setup of test_track_junction_included[zip-project.refs] ______________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________ ERROR at setup of test_cross_junction_multiple_projects[git] ________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________ ERROR at setup of test_cross_junction_multiple_projects[bzr] ________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________ ERROR at setup of test_cross_junction_multiple_projects[tar] ________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________ ERROR at setup of test_cross_junction_multiple_projects[zip] ________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_exceptions[git] ________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_exceptions[bzr] ________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_exceptions[tar] ________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
________________________________________________________________________ ERROR at setup of test_track_exceptions[zip] ________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________________ ERROR at setup of test_open[git] ______________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________________ ERROR at setup of test_open[bzr] ______________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________________ ERROR at setup of test_open[tar] ______________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
______________________________________________________________________________ ERROR at setup of test_open[zip] ______________________________________________________________________________

default_thread_number = 5

    @pytest.fixture(autouse=True)
    def thread_check(default_thread_number):
>       assert has_no_unexpected_background_threads(default_thread_number)
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/_fixtures.py:51: AssertionError
========================================================================================== FAILURES ==========================================================================================
________________________________________________________________________________ test_remote_autotools_build _________________________________________________________________________________

cli = <buildstream.testing.runcli.CliRemote object at 0x7f9931eb9330>, datafiles = local('/home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0')
remote_services = <tests.conftest.RemoteServices object at 0x7f9943129630>

    @pytest.mark.datafiles(DATA_DIR)
    def test_remote_autotools_build(cli, datafiles, remote_services):
        project = str(datafiles)
        checkout = os.path.join(cli.directory, "checkout")
        element_name = "autotools/amhello.bst"
    
        services = cli.ensure_services()
        assert set(services) == set(["action-cache", "execution", "storage"])
    
        # Enable remote cache and remove explicit remote execution CAS configuration.
        config_without_remote_cache = copy.deepcopy(cli.config)
        cli.configure({"cache": {"storage-service": {"url": remote_services.storage_service}}})
        del cli.config["remote-execution"]["storage-service"]
        config_with_remote_cache = cli.config
    
        # Build element with remote execution.
        result = cli.run(project=project, args=["build", element_name])
>       result.assert_success()

tests/remoteexecution/remotecache.py:37: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <buildstream.testing.runcli.Result object at 0x7f99400aa2c0>, fail_message = ''

    def assert_success(self, fail_message=""):
>       assert self.exit_code == 0, fail_message
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/testing/runcli.py:107: AssertionError
------------------------------------------------------------------------------------ Captured stdout call ------------------------------------------------------------------------------------
BuildStream exited with code -1 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0 build autotools/amhello.bst
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Build
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Checking sources
[00:00:00][        ][    main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][    main:core activity                 ] START   Query cache
[--:--:--][456b61e8][cache-query:base/base-alpine.bst          ] START   test/base-base-alpine/456b61e8-cache-query.99.log
[00:00:00][456b61e8][cache-query:base/base-alpine.bst          ] SUCCESS test/base-base-alpine/456b61e8-cache-query.99.log
[--:--:--][7a43f178][cache-query:base.bst                      ] START   test/base/7a43f178-cache-query.99.log
[00:00:00][7a43f178][cache-query:base.bst                      ] SUCCESS test/base/7a43f178-cache-query.99.log
[--:--:--][c9c40f65][cache-query:autotools/amhello.bst         ] START   test/autotools-amhello/c9c40f65-cache-query.99.log
[00:00:00][c9c40f65][cache-query:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/c9c40f65-cache-query.99.log
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][        ][    main:core activity                 ] START   Preparing work plan
[00:00:00][        ][    main:core activity                 ] SUCCESS Preparing work plan

    3 of 3 subtasks processed


BuildStream Version 1.93.6+222.gebab0cb40
    Session Start: Friday, 04-02-2022 at 02:18:58
    Project:       test (/home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0)
    Targets:       autotools/amhello.bst

User Configuration
    Configuration File:      /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/buildstream.conf
    Cache Directory:         /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache
    Log Files:               /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/logs
    Source Mirrors:          /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/sources
    Build Area:              /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/build
    Strict Build Plan:       Yes
    Maximum Fetch Tasks:     10
    Maximum Build Tasks:     4
    Maximum Push Tasks:      4
    Maximum Network Retries: 2
    Cache Storage Service:   http://localhost:50051

Remote Execution Configuration
    Execution Service:    http://localhost:50051
    Storage Service:      http://localhost:50051
    Action Cache Service: http://localhost:50051

Project: test

    Project Options
        arch:  x86-64
        linux: 1

    Element Plugins
        autotools: core plugin
        stack:     core plugin
        import:    core plugin

    Source Plugins
        tar: core plugin

Pipeline
fetch needed 456b61e83c339afb408d03df9db50efdeb0962ffea3cce6a2291a89a89248443 base/base-alpine.bst 
     waiting 7a43f178642961ce8afe6aa7dfe9b0978aecc69b0f6b367a690b90e3bc335cfb base.bst 
fetch needed c9c40f6563b468bce646b1398df1cc5e1fb1d90a179f8da42728819d04293412 autotools/amhello.bst 
===============================================================================
[--:--:--][456b61e8][   fetch:base/base-alpine.bst          ] START   test/base-base-alpine/456b61e8-fetch.99.log
[--:--:--][7a43f178][   fetch:base.bst                      ] START   test/base/7a43f178-fetch.99.log
[--:--:--][c9c40f65][   fetch:autotools/amhello.bst         ] START   test/autotools-amhello/c9c40f65-fetch.99.log
[--:--:--][456b61e8][   fetch:base/base-alpine.bst          ] START   Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
[--:--:--][c9c40f65][   fetch:autotools/amhello.bst         ] START   Fetching file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/files/amhello.tar.gz
[00:00:00][7a43f178][   fetch:base.bst                      ] SUCCESS test/base/7a43f178-fetch.99.log
[00:00:00][c9c40f65][   fetch:autotools/amhello.bst         ] SUCCESS Fetching file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/files/amhello.tar.gz
[00:00:00][c9c40f65][   fetch:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/c9c40f65-fetch.99.log
[00:00:11][456b61e8][   fetch:base/base-alpine.bst          ] SUCCESS Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
[00:00:17][456b61e8][   fetch:base/base-alpine.bst          ] BUG     Fetch

    An unhandled exception occured:
    
    Traceback (most recent call last):
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/jobs/job.py", line 441, in child_action
        result = self.child_process()  # pylint: disable=assignment-from-no-return
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/jobs/elementjob.py", line 92, in child_process
        return self._action_cb(self._element)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/queues/fetchqueue.py", line 77, in _fetch_not_original
        element._fetch(fetch_original=False)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/element.py", line 2182, in _fetch
        self.__sources.fetch()
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 225, in fetch
        self.fetch_sources()
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 254, in fetch_sources
        self._fetch_source(source)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 438, in _fetch_source
        self._sourcecache.commit(source)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_sourcecache.py", line 80, in commit
        vdir.import_files(tmpdir, can_link=True)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/storage/_casbaseddirectory.py", line 535, in import_files
        digest = self.cas_cache.import_directory(external_pathspec, properties=properties)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_cas/cascache.py", line 426, in import_directory
        response = local_cas.CaptureTree(request)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/grpc/_channel.py", line 946, in __call__
        return _end_unary_response_blocking(state, call, False, None)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/grpc/_channel.py", line 849, in _end_unary_response_blocking
        raise _InactiveRpcError(state)
    grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
    	status = StatusCode.UNKNOWN
    	details = "Unexpected error in RPC handling"
    	debug_error_string = "{"created":"@1643941156.370521100","description":"Error received from peer unix:/tmp/buildstreamwqzlncyy/cas/casserver-pq3n8f70.sock","file":"src/core/lib/surface/call.cc","file_line":1066,"grpc_message":"Unexpected error in RPC handling","grpc_status":2}"
    >

[00:00:17][        ][    main:core activity                 ] FAILURE Build

Failure Summary
    base/base-alpine.bst:
    [00:00:17][456b61e8][   fetch:base/base-alpine.bst          ] BUG     Fetch

        An unhandled exception occured:
    
        Traceback (most recent call last):
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/jobs/job.py", line 441, in child_action
            result = self.child_process()  # pylint: disable=assignment-from-no-return
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/jobs/elementjob.py", line 92, in child_process
            return self._action_cb(self._element)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/queues/fetchqueue.py", line 77, in _fetch_not_original
            element._fetch(fetch_original=False)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/element.py", line 2182, in _fetch
            self.__sources.fetch()
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 225, in fetch
            self.fetch_sources()
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 254, in fetch_sources
            self._fetch_source(source)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 438, in _fetch_source
            self._sourcecache.commit(source)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_sourcecache.py", line 80, in commit
            vdir.import_files(tmpdir, can_link=True)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/storage/_casbaseddirectory.py", line 535, in import_files
            digest = self.cas_cache.import_directory(external_pathspec, properties=properties)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_cas/cascache.py", line 426, in import_directory
            response = local_cas.CaptureTree(request)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/grpc/_channel.py", line 946, in __call__
            return _end_unary_response_blocking(state, call, False, None)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/grpc/_channel.py", line 849, in _end_unary_response_blocking
            raise _InactiveRpcError(state)
        grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
        	status = StatusCode.UNKNOWN
        	details = "Unexpected error in RPC handling"
        	debug_error_string = "{"created":"@1643941156.370521100","description":"Error received from peer unix:/tmp/buildstreamwqzlncyy/cas/casserver-pq3n8f70.sock","file":"src/core/lib/surface/call.cc","file_line":1066,"grpc_message":"Unexpected error in RPC handling","grpc_status":2}"
        >

Pipeline Summary
    Total:       3
    Session:     3
    Fetch Queue: processed 2, skipped 0, failed 1 
    Build Queue: processed 0, skipped 0, failed 0 



====================================================================================== warnings summary ======================================================================================
@gtristan gtristan added this to the BuildStream 2.0 milestone Feb 4, 2022
@gtristan
Copy link
Contributor Author

gtristan commented Feb 4, 2022

Making this block 2.0 as we have to have functional remote execution at least with BuildGrid.

@gtristan gtristan added bug Something isn't working critical The tool is unusable in a certain scenario, or causes data loss remote execution Related to remote execution labels Feb 4, 2022
@abderrahim
Copy link
Contributor

Looks like this is as easy as

diff --git a/.github/run-ci.sh b/.github/run-ci.sh
index a860be708..dde7102da 100755
--- a/.github/run-ci.sh
+++ b/.github/run-ci.sh
@@ -97,7 +97,7 @@ function runServiceTest() {
 
 # Lazily ensure that the script exits when a command fails
 #
-set -x
+set -e
 
 if [ -z "${test_names}" ]; then
     runTest "lint"

(i.e. someone mixed up the arguments)

@abderrahim
Copy link
Contributor

Regarding the actual failure, what is happening is that buildgrid returns an error and buildstream crashes loudly (AssertionError) when that happens. Yeah, it shouldn't happen in the testsuite but bst shouldn't crash that loudly when it happens.

In testing with a real build the error returned has a status code 13 (INTERNAL according to https://github.com/grpc/grpc/blob/master/doc/statuscodes.md), and looking at the bgd logs I see "blob not found" errors.

The "default" buildgrid configuration we use has a 2G in-memory CAS, so I wouldn't be surprised it isn't enough (especially if it is pruned agressively). I don't think that would happen with the testsuite, but I guess it may happen.

@gtristan
Copy link
Contributor Author

Looks like this is as easy as

diff --git a/.github/run-ci.sh b/.github/run-ci.sh
index a860be708..dde7102da 100755
--- a/.github/run-ci.sh
+++ b/.github/run-ci.sh
@@ -97,7 +97,7 @@ function runServiceTest() {
 
 # Lazily ensure that the script exits when a command fails
 #
-set -x
+set -e
 
 if [ -z "${test_names}" ]; then
     runTest "lint"

(i.e. someone mixed up the arguments)

Thanks, I'm going to apply this fix to both master and bst-1 right away, and I'll keep this open to track the failing buildgrid test in master.

@gtristan gtristan changed the title BuildGrid tests silently failing BuildGrid tests failing Feb 24, 2022
@gtristan
Copy link
Contributor Author

gtristan commented Feb 24, 2022

Note that tests/remoteexecution/remotecache.py::test_remote_autotools_build fails first, and subsequently tests are failing due to an errant background thread.

This leads me to suspect that something about this failing test is causing a background thread to be left behind. (This was disproven, see below)

The exception appears to be raised by the following line in CasCache.import_directory():

response = local_cas.CaptureTree(request)

Which does not expect to receive an exception (there is no try/except here).

Testing the individual test can be done like this:

  • Start the RE cluster and observe output:
docker-compose --env-file .github/common.env \
    --file .github/compose/ci.buildgrid.yml \
    up \
    --renew-anon-volumes --remove-orphans
  • Run the test which is failing in the overall run (in a separate terminal):
ARTIFACT_CACHE_SERVICE=http://localhost:50052 \
    SOURCE_CACHE_SERVICE=http://localhost:50052 \
    REMOTE_EXECUTION_SERVICE=http://localhost:50051 \
    tox -- --remote-execution \
    tests/remoteexecution/remotecache.py::test_remote_autotools_build

And the test passes - running the test multiple times here is now futile (always passes), observing the buildgrid container output shows that no new builds are performed - which is expected since the build was already successful and stored in CAS.

Errors without failures

Running locally, when running all of the RE tests in tests/remoteexecution/ (rather than only the one test known to fail), I can observe the background thread assertion errors are raising even if no failure occurs.

Interesting different error from same test

After running the tests multiple times whilst keeping the RE cluster up and running, I was able to cause test_remote_autotools_build to fail in a new way, with the following output with no stack trace:

________________________________________________________________________________ test_remote_autotools_build _________________________________________________________________________________

cli = <buildstream._testing.runcli.CliRemote object at 0x7fb85059ef10>, datafiles = local('/home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0')
remote_services = <tests.conftest.RemoteServices object at 0x7fb861ca6730>

    @pytest.mark.datafiles(DATA_DIR)
    def test_remote_autotools_build(cli, datafiles, remote_services):
        project = str(datafiles)
        checkout = os.path.join(cli.directory, "checkout")
        element_name = "autotools/amhello.bst"
    
        services = cli.ensure_services()
        assert set(services) == set(["action-cache", "execution", "storage"])
    
        # Enable remote cache and remove explicit remote execution CAS configuration.
        config_without_remote_cache = copy.deepcopy(cli.config)
        cli.configure({"cache": {"storage-service": {"url": remote_services.storage_service}}})
        del cli.config["remote-execution"]["storage-service"]
        config_with_remote_cache = cli.config
    
        # Build element with remote execution.
        result = cli.run(project=project, args=["build", element_name])
>       result.assert_success()

tests/remoteexecution/remotecache.py:37: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <buildstream._testing.runcli.Result object at 0x7fb850df8370>, fail_message = ''

    def assert_success(self, fail_message=""):
>       assert self.exit_code == 0, fail_message
E       AssertionError

.tox/py39-nocover/lib/python3.9/site-packages/buildstream/_testing/runcli.py:107: AssertionError
------------------------------------------------------------------------------------ Captured stdout call ------------------------------------------------------------------------------------
BuildStream exited with code -1 for invocation:
	bst --no-colors --config /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/buildstream.conf --directory /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0 build autotools/amhello.bst
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Build
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Checking sources
[00:00:00][        ][    main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][    main:core activity                 ] START   Query cache
[--:--:--][a1e46db9][cache-query:base/base-alpine.bst          ] START   test/base-base-alpine/a1e46db9-cache-query.628644.log
[00:00:00][a1e46db9][cache-query:base/base-alpine.bst          ] SUCCESS test/base-base-alpine/a1e46db9-cache-query.628644.log
[--:--:--][378a7f2d][cache-query:base.bst                      ] START   test/base/378a7f2d-cache-query.628644.log
[--:--:--][a72e1ca8][cache-query:autotools/amhello.bst         ] START   test/autotools-amhello/a72e1ca8-cache-query.628644.log
[00:00:00][378a7f2d][cache-query:base.bst                      ] SUCCESS test/base/378a7f2d-cache-query.628644.log
[00:00:00][a72e1ca8][cache-query:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/a72e1ca8-cache-query.628644.log
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][        ][    main:core activity                 ] START   Preparing work plan
[00:00:00][        ][    main:core activity                 ] SUCCESS Preparing work plan

    3 of 3 subtasks processed


BuildStream Version 1.93.6+244.g16654a068.dirty
    Session Start: Thursday, 24-02-2022 at 16:59:50
    Project:       test (/home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0)
    Targets:       autotools/amhello.bst

User Configuration
    Configuration File:      /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/buildstream.conf
    Cache Directory:         /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache
    Log Files:               /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/logs
    Source Mirrors:          /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/sources
    Build Area:              /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/build
    Strict Build Plan:       Yes
    Maximum Fetch Tasks:     10
    Maximum Build Tasks:     4
    Maximum Push Tasks:      4
    Maximum Network Retries: 2
    Cache Storage Service:   http://localhost:50051

Remote Execution Configuration
    Execution Service:    http://localhost:50051
    Storage Service:      http://localhost:50051
    Action Cache Service: http://localhost:50051

Project: test

    Project Options
        arch:  x86-64
        linux: 1

    Element Plugins
        autotools: core plugin
        stack:     core plugin
        import:    core plugin

    Source Plugins
        tar: core plugin

Pipeline
fetch needed a1e46db9db777559a74aca850f6f58c5745ce36b61ed75a26e8056d4a0b967b1 base/base-alpine.bst 
     waiting 378a7f2d90b64643bb42bc3f3c6252f0304c3d73ce78cf1a9af9a01ec47fc5d8 base.bst 
fetch needed a72e1ca8ea2ac7a5584f260983f9e940a75c842ea25399fd545dbbd60e0d9306 autotools/amhello.bst 
===============================================================================
[--:--:--][378a7f2d][   fetch:base.bst                      ] START   test/base/378a7f2d-fetch.628644.log
[--:--:--][a72e1ca8][   fetch:autotools/amhello.bst         ] START   test/autotools-amhello/a72e1ca8-fetch.628644.log
[--:--:--][a1e46db9][   fetch:base/base-alpine.bst          ] START   test/base-base-alpine/a1e46db9-fetch.628644.log
[--:--:--][a72e1ca8][   fetch:autotools/amhello.bst         ] START   Fetching file:///home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/files/amhello.tar.gz
[--:--:--][a1e46db9][   fetch:base/base-alpine.bst          ] START   Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
[00:00:00][378a7f2d][   fetch:base.bst                      ] SUCCESS test/base/378a7f2d-fetch.628644.log
[00:00:00][a72e1ca8][   fetch:autotools/amhello.bst         ] SUCCESS Fetching file:///home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/files/amhello.tar.gz
[00:00:00][a72e1ca8][   fetch:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/a72e1ca8-fetch.628644.log
[00:00:41][a1e46db9][   fetch:base/base-alpine.bst          ] SUCCESS Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
[00:00:48][a1e46db9][   fetch:base/base-alpine.bst          ] FAILURE Failed to capture tree /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6: code: 13
message: "Runtime error uploading and storing path \"/home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6\": std::runtime_error exception thrown at [buildboxcasd_localcasproxyinstance.cpp:767], errMsg = \"Unable to upload 1 blobs to remote CAS\""


    Printing the last 20 lines from log file:
    /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/logs/test/base-base-alpine/a1e46db9-fetch.628644.log
    ======================================================================
    [--:--:--] START   [a1e46db9] base/base-alpine.bst: Fetch
    [--:--:--] START   base/base-alpine.bst: Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
    [00:00:41] SUCCESS base/base-alpine.bst: Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
    [00:00:48] FAILURE [a1e46db9] base/base-alpine.bst: Failed to capture tree /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6: code: 13
    message: "Runtime error uploading and storing path \"/home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6\": std::runtime_error exception thrown at [buildboxcasd_localcasproxyinstance.cpp:767], errMsg = \"Unable to upload 1 blobs to remote CAS\""
    ======================================================================

[00:00:48][        ][    main:core activity                 ] FAILURE Build

Failure Summary
    base/base-alpine.bst:
    [00:00:48][a1e46db9][   fetch:base/base-alpine.bst          ] FAILURE Failed to capture tree /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6: code: 13
    message: "Runtime error uploading and storing path \"/home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6\": std::runtime_error exception thrown at [buildboxcasd_localcasproxyinstance.cpp:767], errMsg = \"Unable to upload 1 blobs to remote CAS\""


        Printing the last 20 lines from log file:
        /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/logs/test/base-base-alpine/a1e46db9-fetch.628644.log
        ======================================================================
        [--:--:--] START   [a1e46db9] base/base-alpine.bst: Fetch
        [--:--:--] START   base/base-alpine.bst: Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
        [00:00:41] SUCCESS base/base-alpine.bst: Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
        [00:00:48] FAILURE [a1e46db9] base/base-alpine.bst: Failed to capture tree /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6: code: 13
        message: "Runtime error uploading and storing path \"/home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6\": std::runtime_error exception thrown at [buildboxcasd_localcasproxyinstance.cpp:767], errMsg = \"Unable to upload 1 blobs to remote CAS\""
        ======================================================================

Pipeline Summary
    Total:       3
    Session:     3
    Fetch Queue: processed 2, skipped 0, failed 1 
    Build Queue: processed 0, skipped 0, failed 0 

This one seems to have stray stdout/stderr being inappropriately interspersed (instead of observed by buildstream/logged through buildstream) from some other process, presumably we're not properly capturing the stdout/stderr of buildbox-casd:

message: "Runtime error uploading and storing path \"/home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6\": std::runtime_error exception thrown at [buildboxcasd_localcasproxyinstance.cpp:767], errMsg = \"Unable to upload 1 blobs to remote CAS\""

This stray error message shows up after the (properly logged) error:

[00:00:48] FAILURE [a1e46db9] base/base-alpine.bst: Failed to capture tree /home/tristan/work/buildstream/.tox/py39-nocover/tmp/test_remote_autotools_build0/cache/tmp/staging-temp3bo8v3j6: code: 13

Which is raised by cascache.py in CasCache.import_directory() only a few lines after where the aforementioned unhandled exception is occurring (causing the stack trace in the cases where it normally fails).

Reproducible error

It seems that the following test consistently causes there to be a leaked background thread:

tests/remoteexecution/workspace.py::test_workspace_build[content]

Even if the RE cluster has been up and running and built everything... every time we run the above test we get the following output in the RE cluster, and this seems unexpected since we should have already built this content in previous runs:

bot_1         | 2022-02-25T01:15:23.254+0000 [8:139665901813568] [buildboxworker_worker.cpp:571] [DEBUG] Processing pending lease: state: PENDING
bot_1         | status {
bot_1         | }
bot_1         | id: "5cb25238-383b-417e-be5f-877bd8a32e40"
bot_1         | payload {
bot_1         |   [type.googleapis.com/build.bazel.remote.execution.v2.Action] {
bot_1         |     command_digest {
bot_1         |       hash: "222cdfebc6e802bbd3d0560eaa03aadb32bd025b2b25f26a5e77bf65d90e5a65"
bot_1         |       size_bytes: 3479
bot_1         |     }
bot_1         |     input_root_digest {
bot_1         |       hash: "caf5b427f5ad4de2a3074fcd3606b1919c8275e9232048c4da8e98b677d5bc1e"
bot_1         |       size_bytes: 1438
bot_1         |     }
bot_1         |   }
bot_1         | }
bot_1         | result {
bot_1         | }
bot_1         | 2022-02-25T01:15:23.279+0000 [8:139665901813568] [buildboxworker_worker.cpp:605] [DEBUG] Processing active lease: state: ACTIVE
bot_1         | status {
bot_1         | }
bot_1         | id: "5cb25238-383b-417e-be5f-877bd8a32e40"
bot_1         | payload {
bot_1         |   [type.googleapis.com/build.bazel.remote.execution.v2.Action] {
bot_1         |     command_digest {
bot_1         |       hash: "222cdfebc6e802bbd3d0560eaa03aadb32bd025b2b25f26a5e77bf65d90e5a65"
bot_1         |       size_bytes: 3479
bot_1         |     }
bot_1         |     input_root_digest {
bot_1         |       hash: "caf5b427f5ad4de2a3074fcd3606b1919c8275e9232048c4da8e98b677d5bc1e"
bot_1         |       size_bytes: 1438
bot_1         |     }
bot_1         |   }
bot_1         | }
bot_1         | result {
bot_1         | }
bot_1         | 2022-02-25T01:15:23.279+0000 [8:139665867962112] [buildboxworker_worker.cpp:355] [DEBUG] Starting worker thread for leaseId 5cb25238-383b-417e-be5f-877bd8a32e40
bot_1         | 2022-02-25T01:15:23.288+0000 [8:139665867962112] [buildboxworker_worker.cpp:437] [DEBUG] Saving Action to [/tmp/buildboxBruSCj]
bot_1         | 2022-02-25T01:15:23.288+0000 [8:139665867962112] [buildboxworker_actionutils.cpp:148] [DEBUG] Launching runner process: /usr/local/bin/buildbox-run-bubblewrap --remote=unix:/var/lib/buildgrid/cache/casd.sock --instance= --retry-limit=4 --retry-delay=1000 --action=/tmp/buildboxBruSCj --action-result=/tmp/buildboxhj6iUP --log-level=info --stdout-file=/tmp/buildboxjd0smN --stderr-file=/tmp/buildboxeNK35g
bot_1         | 2022-02-25T01:15:23.289+0000 [9885:139665867962112] [buildboxworker_actionutils.cpp:110] [DEBUG] I am the runner process: pid [9885], group-pid [9885]
bot_1         | 2022-02-25T01:15:23.294+0000 [9885:139798200909632] [buildboxcommon_client.cpp:98] [INFO] Setting d_maxBatchTotalSizeBytes = 4128768 bytes by default
bot_1         | 2022-02-25T01:15:30.438+0000 [8:139665867962112] [buildboxworker_actionutils.cpp:181] [INFO] Worker exited with code 0
bot_1         | 2022-02-25T01:15:30.438+0000 [8:139665867962112] [buildboxworker_worker.cpp:348] [DEBUG] ActionResult output_directories {
bot_1         |   path: "."
bot_1         |   tree_digest {
bot_1         |     hash: "1de7be94bb604c0dc72457538f769e599aa05a0c70af7d617fadffb2c965b118"
bot_1         |     size_bytes: 3654
bot_1         |   }
bot_1         | }
bot_1         | output_directories {
bot_1         |   path: "../../../../buildstream-install"
bot_1         |   tree_digest {
bot_1         |     hash: "0899c4c9e4dd10f030ca03780b503ee2036cfb0f559e95e0936d3b35c965fdad"
bot_1         |     size_bytes: 599
bot_1         |   }
bot_1         | }
bot_1         | output_directories {
bot_1         |   path: "../../../.."
bot_1         |   tree_digest {
bot_1         |     hash: "4955e4d60c91f0f01f1eef854fa4e19d3a13faf4706120f146e702d5f2c99aba"
bot_1         |     size_bytes: 1105507
bot_1         |   }
bot_1         | }
bot_1         | stdout_digest {
bot_1         |   hash: "b63a67e177e3e59d90db057e908212c79e91e299e281d9b874595396d5c1309a"
bot_1         |   size_bytes: 2767
bot_1         | }
bot_1         | stderr_digest {
bot_1         |   hash: "b8cfc7fec9972a76de187df6f770019e8b2f535c6cf4969c0789ad3251378701"
bot_1         |   size_bytes: 1621
bot_1         | }
bot_1         | execution_metadata {
bot_1         |   worker_start_timestamp {
bot_1         |     seconds: 1645751723
bot_1         |     nanos: 294036000
bot_1         |   }
bot_1         |   worker_completed_timestamp {
bot_1         |     seconds: 1645751730
bot_1         |     nanos: 437214000
bot_1         |   }
bot_1         |   execution_start_timestamp {
bot_1         |     seconds: 1645751723
bot_1         |     nanos: 350534000
bot_1         |   }
bot_1         |   execution_completed_timestamp {
bot_1         |     seconds: 1645751726
bot_1         |     nanos: 884455000
bot_1         |   }
bot_1         |   auxiliary_metadata {
bot_1         |     [type.googleapis.com/build.buildbox.ExecutionStatistics] {
bot_1         |       command_rusage {
bot_1         |         utime {
bot_1         |           nanos: 1328000
bot_1         |         }
bot_1         |         stime {
bot_1         |         }
bot_1         |         maxrss: 2884
bot_1         |         minflt: 162
bot_1         |         nvcsw: 2
bot_1         |       }
bot_1         |     }
bot_1         |   }
bot_1         | }
bot_1         | 2022-02-25T01:15:39.723+0000 [8:139665901813568] [buildboxworker_worker.cpp:571] [DEBUG] Processing pending lease: state: PENDING
bot_1         | status {
bot_1         | }
bot_1         | id: "d524b851-698e-477e-be9c-bdb1a0a50e94"
bot_1         | payload {
bot_1         |   [type.googleapis.com/build.bazel.remote.execution.v2.Action] {
bot_1         |     command_digest {
bot_1         |       hash: "d1c006ae8ee5434bd5e374ece5f8492f09e003017ee4b052d2870607c966bf7a"
bot_1         |       size_bytes: 1988
bot_1         |     }
bot_1         |     input_root_digest {
bot_1         |       hash: "191573002495f791fa82d1c0a3f9e68d681028f43d91eb1c67cd8ff2b843a3d7"
bot_1         |       size_bytes: 1438
bot_1         |     }
bot_1         |   }
bot_1         | }
bot_1         | result {
bot_1         | }
bot_1         | 2022-02-25T01:15:39.761+0000 [8:139665901813568] [buildboxworker_worker.cpp:605] [DEBUG] Processing active lease: state: ACTIVE
bot_1         | status {
bot_1         | }
bot_1         | id: "d524b851-698e-477e-be9c-bdb1a0a50e94"
bot_1         | payload {
bot_1         |   [type.googleapis.com/build.bazel.remote.execution.v2.Action] {
bot_1         |     command_digest {
bot_1         |       hash: "d1c006ae8ee5434bd5e374ece5f8492f09e003017ee4b052d2870607c966bf7a"
bot_1         |       size_bytes: 1988
bot_1         |     }
bot_1         |     input_root_digest {
bot_1         |       hash: "191573002495f791fa82d1c0a3f9e68d681028f43d91eb1c67cd8ff2b843a3d7"
bot_1         |       size_bytes: 1438
bot_1         |     }
bot_1         |   }
bot_1         | }
bot_1         | result {
bot_1         | }
bot_1         | 2022-02-25T01:15:39.761+0000 [8:139665867962112] [buildboxworker_worker.cpp:355] [DEBUG] Starting worker thread for leaseId d524b851-698e-477e-be9c-bdb1a0a50e94
bot_1         | 2022-02-25T01:15:39.775+0000 [8:139665867962112] [buildboxworker_worker.cpp:437] [DEBUG] Saving Action to [/tmp/buildboxmCRuoa]
bot_1         | 2022-02-25T01:15:39.775+0000 [8:139665867962112] [buildboxworker_actionutils.cpp:148] [DEBUG] Launching runner process: /usr/local/bin/buildbox-run-bubblewrap --remote=unix:/var/lib/buildgrid/cache/casd.sock --instance= --retry-limit=4 --retry-delay=1000 --action=/tmp/buildboxmCRuoa --action-result=/tmp/buildboxFxOgKd --log-level=info --stdout-file=/tmp/buildboxOnKe46 --stderr-file=/tmp/buildboxwoUYJ3
bot_1         | 2022-02-25T01:15:39.776+0000 [10863:139665867962112] [buildboxworker_actionutils.cpp:110] [DEBUG] I am the runner process: pid [10863], group-pid [10863]
bot_1         | 2022-02-25T01:15:39.781+0000 [10863:140694966566720] [buildboxcommon_client.cpp:98] [INFO] Setting d_maxBatchTotalSizeBytes = 4128768 bytes by default
bot_1         | 2022-02-25T01:15:42.436+0000 [8:139665867962112] [buildboxworker_actionutils.cpp:181] [INFO] Worker exited with code 0
bot_1         | 2022-02-25T01:15:42.436+0000 [8:139665867962112] [buildboxworker_worker.cpp:348] [DEBUG] ActionResult output_directories {
bot_1         |   path: "."
bot_1         |   tree_digest {
bot_1         |     hash: "d9db94ff25e7d40c47624dd1988f99ec5f5bf25da40afb9141db7c457331c812"
bot_1         |     size_bytes: 3660
bot_1         |   }
bot_1         | }
bot_1         | output_directories {
bot_1         |   path: "../../../../buildstream-install"
bot_1         |   tree_digest {
bot_1         |     hash: "c7911d9241cf3b093493018c74ed7b3093cd1a6b11e5e64a205e890594f13363"
bot_1         |     size_bytes: 599
bot_1         |   }
bot_1         | }
bot_1         | output_directories {
bot_1         |   path: "../../../.."
bot_1         |   tree_digest {
bot_1         |     hash: "cf978d16cee899094cce215fd4057c65525a75b309252e50dc70eea13d46d08e"
bot_1         |     size_bytes: 1105513
bot_1         |   }
bot_1         | }
bot_1         | stdout_digest {
bot_1         |   hash: "9d5d236e1c24bb93bb51c2345e3497f9b51f5cee0cec4df00261fb81c8b180f7"
bot_1         |   size_bytes: 1590
bot_1         | }
bot_1         | stderr_digest {
bot_1         |   hash: "a22a02f980d2cfa237793915db0051bb2942d627d2df44982baa632997f11e2b"
bot_1         |   size_bytes: 594
bot_1         | }
bot_1         | execution_metadata {
bot_1         |   worker_start_timestamp {
bot_1         |     seconds: 1645751739
bot_1         |     nanos: 781105000
bot_1         |   }
bot_1         |   worker_completed_timestamp {
bot_1         |     seconds: 1645751742
bot_1         |     nanos: 414431000
bot_1         |   }
bot_1         |   execution_start_timestamp {
bot_1         |     seconds: 1645751739
bot_1         |     nanos: 838875000
bot_1         |   }
bot_1         |   execution_completed_timestamp {
bot_1         |     seconds: 1645751739
bot_1         |     nanos: 878631000
bot_1         |   }
bot_1         |   auxiliary_metadata {
bot_1         |     [type.googleapis.com/build.buildbox.ExecutionStatistics] {
bot_1         |       command_rusage {
bot_1         |         utime {
bot_1         |           nanos: 1724000
bot_1         |         }
bot_1         |         stime {
bot_1         |         }
bot_1         |         maxrss: 4884
bot_1         |         minflt: 163
bot_1         |         nvcsw: 2
bot_1         |       }
bot_1         |     }
bot_1         |   }
bot_1         | }

Bisection result

Using the tests/remoteexecution/workspace.py::test_workspace_build[content] test, I was able to pinpoint the errors down to commit e97d16b, which is extremely confusing to me. I've repeatedly tested this but commits before this consistently pass and tests from this commit onwards consistently produce the error of having errant background threads. Testing one commit before the offending commit, the entire remote execution test runs flawlessly.

Further, I can confirm that reverting e97d16b (which reverts cleanly at this time) from master, causes the remote execution tests to pass cleanly again.

By reverting the patch and undoing the revert to _stream.py, I can confirm that the portion of the patch which changes _stream.py introduces the breaking change.

Digging a bit deeper:

  • The changes to Stream._expand_and_classify_targets() are somehow responsible for causing background native threads to be left behind in the tests/remoteexecution/workspace.py::test_workspace_build[content] test
  • Debugging in buildstream/_testing/_fixtures.py shows me that there are 5 total threads instead of the expected 1 thread
    • The additional 4 threads are not python threads, these are presumably leaked gRPC threads
  • Adding time.sleep() statements of variable length in Stream._expand_and_classify_targets() does not affect test results
  • Ensuring that ArtifactCache.list_artifacts() gets called does not affect test results
  • Using lists instead of dictionaries for the element_names, artifact_names, etc local variables in this function does not affect test results

One working theory is that there is something about this change to Stream._expand_and_classify_targets() which introduces some kind of circular object reference cycle which causes the Stream object, and consequently the gRPC channel objects to not be garbage collected, which may be responsible.

@gtristan
Copy link
Contributor Author

I cannot explain why the commit in question happens to introduce this test failure, however I was able to get down to the root of the problem and fix this in #1605

@gtristan
Copy link
Contributor Author

gtristan commented Feb 28, 2022

The errors occurring due to leaked gRPC threads are now fixed with #1605, but we still have the following failure:

________________________________________________________________________________ test_remote_autotools_build _________________________________________________________________________________

cli = <buildstream._testing.runcli.CliRemote object at 0x7f85183c51b0>, datafiles = local('/home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0')
remote_services = <tests.conftest.RemoteServices object at 0x7f85210cf820>

    @pytest.mark.datafiles(DATA_DIR)
    def test_remote_autotools_build(cli, datafiles, remote_services):
        project = str(datafiles)
        checkout = os.path.join(cli.directory, "checkout")
        element_name = "autotools/amhello.bst"
    
        services = cli.ensure_services()
        assert set(services) == set(["action-cache", "execution", "storage"])
    
        # Enable remote cache and remove explicit remote execution CAS configuration.
        config_without_remote_cache = copy.deepcopy(cli.config)
        cli.configure({"cache": {"storage-service": {"url": remote_services.storage_service}}})
        del cli.config["remote-execution"]["storage-service"]
        config_with_remote_cache = cli.config
    
        # Build element with remote execution.
        result = cli.run(project=project, args=["build", element_name])
>       result.assert_success()

tests/remoteexecution/remotecache.py:37: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <buildstream._testing.runcli.Result object at 0x7f8518344430>, fail_message = ''

    def assert_success(self, fail_message=""):
>       assert self.exit_code == 0, fail_message
E       AssertionError

.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_testing/runcli.py:107: AssertionError
------------------------------------------------------------------------------------ Captured stdout call ------------------------------------------------------------------------------------
BuildStream exited with code -1 for invocation:
	bst --no-colors --config /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/buildstream.conf --directory /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0 build autotools/amhello.bst
Program stderr was:
[--:--:--][        ][    main:core activity                 ] START   Build
[--:--:--][        ][    main:core activity                 ] START   Loading elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Loading elements

    3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Resolving elements
[00:00:00][        ][    main:core activity                 ] SUCCESS Resolving elements

    3 of 3 subtasks processed

[--:--:--][        ][    main:core activity                 ] START   Initializing remote caches
[00:00:00][        ][    main:core activity                 ] SUCCESS Initializing remote caches
[--:--:--][        ][    main:core activity                 ] START   Checking sources
[00:00:00][        ][    main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][    main:core activity                 ] START   Query cache
[--:--:--][a72e1ca8][cache-query:autotools/amhello.bst         ] START   test/autotools-amhello/a72e1ca8-cache-query.3476.log
[00:00:00][a72e1ca8][cache-query:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/a72e1ca8-cache-query.3476.log
[--:--:--][378a7f2d][cache-query:base.bst                      ] START   test/base/378a7f2d-cache-query.3476.log
[00:00:00][378a7f2d][cache-query:base.bst                      ] SUCCESS test/base/378a7f2d-cache-query.3476.log
[--:--:--][a1e46db9][cache-query:base/base-alpine.bst          ] START   test/base-base-alpine/a1e46db9-cache-query.3476.log
[00:00:00][a1e46db9][cache-query:base/base-alpine.bst          ] SUCCESS test/base-base-alpine/a1e46db9-cache-query.3476.log
[00:00:00][        ][    main:core activity                 ] SUCCESS Query cache
[--:--:--][        ][    main:core activity                 ] START   Preparing work plan
[00:00:00][        ][    main:core activity                 ] SUCCESS Preparing work plan

    3 of 3 subtasks processed


BuildStream Version 1.93.6+248.g02f6a13de
    Session Start: Monday, 28-02-2022 at 08:49:08
    Project:       test (/home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0)
    Targets:       autotools/amhello.bst

User Configuration
    Configuration File:      /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/buildstream.conf
    Cache Directory:         /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache
    Log Files:               /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/logs
    Source Mirrors:          /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/sources
    Build Area:              /home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/cache/build
    Strict Build Plan:       Yes
    Maximum Fetch Tasks:     10
    Maximum Build Tasks:     4
    Maximum Push Tasks:      4
    Maximum Network Retries: 2
    Cache Storage Service:   http://localhost:50051

Remote Execution Configuration
    Execution Service:    http://localhost:50051
    Storage Service:      http://localhost:50051
    Action Cache Service: http://localhost:50051

Project: test

    Project Options
        arch:  x86-64
        linux: 1

    Element Plugins
        autotools: core plugin
        stack:     core plugin
        import:    core plugin

    Source Plugins
        tar: core plugin

Pipeline
fetch needed a1e46db9db777559a74aca850f6f58c5745ce36b61ed75a26e8056d4a0b967b1 base/base-alpine.bst 
     waiting 378a7f2d90b64643bb42bc3f3c6252f0304c3d73ce78cf1a9af9a01ec47fc5d8 base.bst 
fetch needed a72e1ca8ea2ac7a5584f260983f9e940a75c842ea25399fd545dbbd60e0d9306 autotools/amhello.bst 
===============================================================================
[--:--:--][a1e46db9][   fetch:base/base-alpine.bst          ] START   test/base-base-alpine/a1e46db9-fetch.3476.log
[--:--:--][378a7f2d][   fetch:base.bst                      ] START   test/base/378a7f2d-fetch.3476.log
[--:--:--][a1e46db9][   fetch:base/base-alpine.bst          ] START   Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
[--:--:--][a72e1ca8][   fetch:autotools/amhello.bst         ] START   test/autotools-amhello/a72e1ca8-fetch.3476.log
[--:--:--][a72e1ca8][   fetch:autotools/amhello.bst         ] START   Fetching file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/files/amhello.tar.gz
[00:00:00][378a7f2d][   fetch:base.bst                      ] SUCCESS test/base/378a7f2d-fetch.3476.log
[00:00:00][a72e1ca8][   fetch:autotools/amhello.bst         ] SUCCESS Fetching file:///home/testuser/buildstream/.tox/py310-nocover/tmp/test_remote_autotools_build0/files/amhello.tar.gz
[00:00:00][a72e1ca8][   fetch:autotools/amhello.bst         ] SUCCESS test/autotools-amhello/a72e1ca8-fetch.3476.log
[00:00:42][a1e46db9][   fetch:base/base-alpine.bst          ] SUCCESS Fetching https://bst-integration-test-images.ams3.cdn.digitaloceanspaces.com/integration-tests-base.v1.x86_64.tar.xz
[00:00:49][a1e46db9][   fetch:base/base-alpine.bst          ] BUG     Fetch

    An unhandled exception occured:
    
    Traceback (most recent call last):
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/jobs/job.py", line 441, in child_action
        result = self.child_process()  # pylint: disable=assignment-from-no-return
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/jobs/elementjob.py", line 92, in child_process
        return self._action_cb(self._element)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/queues/fetchqueue.py", line 77, in _fetch_not_original
        element._fetch(fetch_original=False)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/element.py", line 2185, in _fetch
        self.__sources.fetch()
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 225, in fetch
        self.fetch_sources()
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 254, in fetch_sources
        self._fetch_source(source)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 438, in _fetch_source
        self._sourcecache.commit(source)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_sourcecache.py", line 80, in commit
        vdir.import_files(tmpdir, can_link=True)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/storage/_casbaseddirectory.py", line 535, in import_files
        digest = self.cas_cache.import_directory(external_pathspec, properties=properties)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_cas/cascache.py", line 426, in import_directory
        response = local_cas.CaptureTree(request)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/grpc/_channel.py", line 946, in __call__
        return _end_unary_response_blocking(state, call, False, None)
      File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/grpc/_channel.py", line 849, in _end_unary_response_blocking
        raise _InactiveRpcError(state)
    grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
    	status = StatusCode.UNKNOWN
    	details = "Unexpected error in RPC handling"
    	debug_error_string = "{"created":"@1646038197.387303231","description":"Error received from peer unix:/tmp/buildstreameftucrvd/cas/casserver-h467901b.sock","file":"src/core/lib/surface/call.cc","file_line":1066,"grpc_message":"Unexpected error in RPC handling","grpc_status":2}"
    >

[00:00:49][        ][    main:core activity                 ] FAILURE Build

Failure Summary
    base/base-alpine.bst:
    [00:00:49][a1e46db9][   fetch:base/base-alpine.bst          ] BUG     Fetch

        An unhandled exception occured:
    
        Traceback (most recent call last):
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/jobs/job.py", line 441, in child_action
            result = self.child_process()  # pylint: disable=assignment-from-no-return
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/jobs/elementjob.py", line 92, in child_process
            return self._action_cb(self._element)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_scheduler/queues/fetchqueue.py", line 77, in _fetch_not_original
            element._fetch(fetch_original=False)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/element.py", line 2185, in _fetch
            self.__sources.fetch()
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 225, in fetch
            self.fetch_sources()
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 254, in fetch_sources
            self._fetch_source(source)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_elementsources.py", line 438, in _fetch_source
            self._sourcecache.commit(source)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_sourcecache.py", line 80, in commit
            vdir.import_files(tmpdir, can_link=True)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/storage/_casbaseddirectory.py", line 535, in import_files
            digest = self.cas_cache.import_directory(external_pathspec, properties=properties)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/buildstream/_cas/cascache.py", line 426, in import_directory
            response = local_cas.CaptureTree(request)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/grpc/_channel.py", line 946, in __call__
            return _end_unary_response_blocking(state, call, False, None)
          File "/home/testuser/buildstream/.tox/py310-nocover/lib64/python3.10/site-packages/grpc/_channel.py", line 849, in _end_unary_response_blocking
            raise _InactiveRpcError(state)
        grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
        	status = StatusCode.UNKNOWN
        	details = "Unexpected error in RPC handling"
        	debug_error_string = "{"created":"@1646038197.387303231","description":"Error received from peer unix:/tmp/buildstreameftucrvd/cas/casserver-h467901b.sock","file":"src/core/lib/surface/call.cc","file_line":1066,"grpc_message":"Unexpected error in RPC handling","grpc_status":2}"
        >

Pipeline Summary
    Total:       3
    Session:     3
    Fetch Queue: processed 2, skipped 0, failed 1 
    Build Queue: processed 0, skipped 0, failed 0 

Bisection results

I've managed to isolate the breakage to the commit 220dc78, which essentially updates the docker images, which supports @abderrahim's observation below (#1582 (comment)) that this only happens on certain platforms.

  • Upgrading to the latest grpc version does not fix this
  • Upgrading to the latest grpc version and regenerating the proto handling python code also does not fix this

Debugging buildbox-casd

Looking at the gRPC error and gRPC source code, I was suspecting that this was being caused by a client side exception being raised by gRPC internal code, as the string "Unexpected error in RPC handling" we are seeing only appears here in grpc.

However @juergbi suspected it was a server side error instead, and as usual... he was right !

Using a surgical strike to reproduce the error under the fedora docker image and running buildbox-casd I was able to observe the stack trace of the thrown exception which causes grpc to return this unexpected error:

#0  0x00007f4887f7a392 in __cxxabiv1::__cxa_throw (obj=0x7f4860532880, tinfo=0x7a5ad8 <typeinfo for std::logic_error@GLIBCXX_3.4>, dest=0x415a10 <std::logic_error::~logic_error()@plt>)
    at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:78
#1  0x00000000004e1617 in buildboxcommon::CASClient::upload(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, build::bazel::remote::execution::v2::Digest const&, buildboxcommon::GrpcClient::RequestStats*) ()
#2  0x00000000004e2d96 in buildboxcommon::CASClient::uploadRequest(buildboxcommon::CASClient::UploadRequest const&, buildboxcommon::GrpcClient::RequestStats*) ()
#3  0x00000000004e3143 in buildboxcommon::CASClient::uploadBlobs(std::vector<buildboxcommon::CASClient::UploadRequest, std::allocator<buildboxcommon::CASClient::UploadRequest> > const&, bool, buildboxcommon::GrpcClient::RequestStats*) ()
#4  0x00000000004e2e2c in buildboxcommon::CASClient::uploadBlobs(std::vector<buildboxcommon::CASClient::UploadRequest, std::allocator<buildboxcommon::CASClient::UploadRequest> > const&, buildboxcommon::GrpcClient::RequestStats*) ()
#5  0x00000000004b9f74 in buildboxcasd::LocalCasProxyInstance::UploadAndStore(int, std::unordered_map<build::bazel::remote::execution::v2::Digest, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::hash<build::bazel::remote::execution::v2::Digest>, std::equal_to<build::bazel::remote::execution::v2::Digest>, std::allocator<std::pair<build::bazel::remote::execution::v2::Digest const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > > const&, build::bazel::remote::execution::v2::Tree const*, bool, bool) ()
#6  0x00000000004abaf6 in buildboxcasd::LocalCasInstance::captureDirectory(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&, bool, bool) ()
#7  0x00000000004ab493 in buildboxcasd::LocalCasInstance::CaptureTree(build::buildgrid::CaptureTreeRequest const&, build::buildgrid::CaptureTreeResponse*) ()
#8  0x0000000000456134 in buildboxcasd::LocalCasServicer::CaptureTree(grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*) ()
#9  0x000000000060f1fd in build::buildgrid::LocalContentAddressableStorage::Service::Service()::{lambda(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*)#6}::operator()(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*) const ()
#10 0x0000000000613138 in grpc::Status std::__invoke_impl<grpc::Status, build::buildgrid::LocalContentAddressableStorage::Service::Service()::{lambda(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*)#6}&, build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*>(std::__invoke_other, build::buildgrid::LocalContentAddressableStorage::Service::Service()::{lambda(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*)#6}&, build::buildgrid::LocalContentAddressableStorage::Service*&&, grpc::ServerContext*&&, build::buildgrid::CaptureTreeRequest const*&&, build::buildgrid::CaptureTreeResponse*&&) ()
#11 0x0000000000612180 in std::enable_if<std::__and_<std::__not_<std::is_void<grpc::Status> >, std::is_convertible<std::__invoke_result<build::buildgrid::LocalContentAddressableStorage::Service::Service()::{lambda(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*)#6}&, build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*>::type, grpc::Status> >::value, grpc::Status>::type std::__invoke_r<grpc::Status, build::buildgrid::LocalContentAddressableStorage::Service::Service()::{lambda(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*)#6}&, build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*>(build::buildgrid::LocalContentAddressableStorage::Service::Service()::{lambda(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*)#6}&, build::buildgrid::LocalContentAddressableStorage::Service*&&, grpc::ServerContext*&&, build::buildgrid::CaptureTreeRequest const*&&, build::buildgrid::CaptureTreeResponse*&&) ()
#12 0x0000000000611093 in std::_Function_handler<grpc::Status (build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*), build::buildgrid::LocalContentAddressableStorage::Service::CaptureTreeResponse()::{lambda(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*)#6}>::_M_invoke(std::_Any_data const&, build::buildgrid::LocalContentAddressableStorage::Service*&&, grpc::ServerContext*&&, build::buildgrid::CaptureTreeRequest const*&&, build::buildgrid::CaptureTreeResponse*&&) ()
#13 0x0000000000621b16 in std::function<grpc::Status (build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*)>::operator()(build::buildgrid::LocalContentAddressableStorage::Service*, grpc::ServerContext*, build::buildgrid::CaptureTreeRequest const*, build::buildgrid::CaptureTreeResponse*) const ()
#14 0x000000000061cf52 in grpc::internal::RpcMethodHandler<build::buildgrid::LocalContentAddressableStorage::Service, build::buildgrid::CaptureTreeRequest, build::buildgrid::CaptureTreeResponse, google::protobuf::MessageLite, google::protobuf::MessageLite>::RunHandler(grpc::internal::MethodHandler::HandlerParameter const&)::{lambda()#1}::operator()() const ()
#15 0x0000000000621b4b in grpc::Status grpc::internal::CatchingFunctionHandler<grpc::internal::RpcMethodHandler<build::buildgrid::LocalContentAddressableStorage::Service, build::buildgrid::CaptureTreeRequest, build::buildgrid::CaptureTreeResponse, google::protobuf::MessageLite, google::protobuf::MessageLite>::RunHandler(grpc::internal::MethodHandler::HandlerParameter const&)::{lambda()#1}>(grpc::internal::RpcMethodHandler<build::buildgrid::LocalContentAddressableStorage::Service, build::buildgrid::CaptureTreeRequest, build::buildgrid::CaptureTreeResponse, google::protobuf::MessageLite, google::protobuf::MessageLite>::RunHandler(grpc::internal::MethodHandler::HandlerParameter const&)::{lambda()#1}&&) ()
#16 0x000000000061cfe5 in grpc::internal::RpcMethodHandler<build::buildgrid::LocalContentAddressableStorage::Service, build::buildgrid::CaptureTreeRequest, build::buildgrid::CaptureTreeResponse, google::protobuf::MessageLite, google::protobuf::MessageLite>::RunHandler(grpc::internal::MethodHandler::HandlerParameter const&) ()
#17 0x00007f4888e50568 in grpc::Server::SyncRequest::ContinueRunAfterInterception (this=0x7f4870010a90) at /usr/include/c++/11/bits/move.h:196
#18 0x00007f4888e56a1c in grpc::ThreadManager::MainWorkLoop (this=0x1288120) at /usr/src/debug/grpc-1.39.1-12.fc35.x86_64/src/cpp/thread_manager/thread_manager.cc:213
#19 0x00007f4888e56b50 in grpc::ThreadManager::WorkerThread::Run (this=0x7f4870002780) at /usr/src/debug/grpc-1.39.1-12.fc35.x86_64/src/cpp/thread_manager/thread_manager.cc:43
#20 0x00007f48885c4011 in operator() (__closure=0x0, v=<optimized out>) at /usr/src/debug/grpc-1.39.1-12.fc35.x86_64/src/core/lib/gprpp/thd_posix.cc:140
#21 _FUN () at /usr/src/debug/grpc-1.39.1-12.fc35.x86_64/src/core/lib/gprpp/thd_posix.cc:145
#22 0x00007f4887c59a87 in start_thread (arg=<optimized out>) at pthread_create.c:435
#23 0x00007f4887cde640 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

The original exception has to be one of the two exceptions which can be thrown from CASClient::upload, in the depths of buildbox-common.

The exception is later caught in grpc core, the stack looks like this:

#0  __cxxabiv1::__cxa_begin_catch (exc_obj_in=0x7f4860532860) at ../../../../libstdc++-v3/libsupc++/eh_catch.cc:84
#1  0x0000000000621b58 in grpc::Status grpc::internal::CatchingFunctionHandler<grpc::internal::RpcMethodHandler<build::buildgrid::LocalContentAddressableStorage::Service, build::buildgrid::CaptureTreeRequest, build::buildgrid::CaptureTreeResponse, google::protobuf::MessageLite, google::protobuf::MessageLite>::RunHandler(grpc::internal::MethodHandler::HandlerParameter const&)::{lambda()#1}>(grpc::internal::RpcMethodHandler<build::buildgrid::LocalContentAddressableStorage::Service, build::buildgrid::CaptureTreeRequest, build::buildgrid::CaptureTreeResponse, google::protobuf::MessageLite, google::protobuf::MessageLite>::RunHandler(grpc::internal::MethodHandler::HandlerParameter const&)::{lambda()#1}&&) ()
#2  0x000000000061cfe5 in grpc::internal::RpcMethodHandler<build::buildgrid::LocalContentAddressableStorage::Service, build::buildgrid::CaptureTreeRequest, build::buildgrid::CaptureTreeResponse, google::protobuf::MessageLite, google::protobuf::MessageLite>::RunHandler(grpc::internal::MethodHandler::HandlerParameter const&) ()
#3  0x00007f4888e50568 in grpc::Server::SyncRequest::ContinueRunAfterInterception (this=0x7f4870010a90) at /usr/include/c++/11/bits/move.h:196
#4  0x00007f4888e56a1c in grpc::ThreadManager::MainWorkLoop (this=0x1288120) at /usr/src/debug/grpc-1.39.1-12.fc35.x86_64/src/cpp/thread_manager/thread_manager.cc:213
#5  0x00007f4888e56b50 in grpc::ThreadManager::WorkerThread::Run (this=0x7f4870002780) at /usr/src/debug/grpc-1.39.1-12.fc35.x86_64/src/cpp/thread_manager/thread_manager.cc:43
#6  0x00007f48885c4011 in operator() (__closure=0x0, v=<optimized out>) at /usr/src/debug/grpc-1.39.1-12.fc35.x86_64/src/core/lib/gprpp/thd_posix.cc:140
#7  _FUN () at /usr/src/debug/grpc-1.39.1-12.fc35.x86_64/src/core/lib/gprpp/thd_posix.cc:145
#8  0x00007f4887c59a87 in start_thread (arg=<optimized out>) at pthread_create.c:435
#9  0x00007f4887cde640 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

In order to observe the actual exception, I recompiled buildbox common/casd and added BUILDBOX_LOG_TRACE and ran the test with a higher log level for buildbox... it turns out to be the first of the two exceptions being raised, and the message is:

Digest length of 9336394 bytes for 5180d0ae8d2038aa36f6592b97f0db4e5cd4822079121e7fc870dccb71b2f872 does not match string length of 14 bytes

@gtristan gtristan reopened this Feb 28, 2022
@abderrahim
Copy link
Contributor

FTR, this failure was there for some time. I've only ever seen it happen on fedora, but couldn't reproduce it locally. It is mostly triggered by test_track_recurse.

@juergbi
Copy link
Contributor

juergbi commented Mar 5, 2022

This should be fixed by https://gitlab.com/BuildGrid/buildbox/buildbox-casd/-/merge_requests/265 (and https://gitlab.com/BuildGrid/buildgrid/-/merge_requests/771). I've validated this locally but not yet in CI. This will require an update of buildbox-casd in the BuildStream docker images (when the fix is merged).

@juergbi
Copy link
Contributor

juergbi commented Mar 9, 2022

The BuildBox MRs have been merged. There will likely be new git tags later today or tomorrow.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working critical The tool is unusable in a certain scenario, or causes data loss remote execution Related to remote execution
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants