'bst build <elem>' does not assemble all required elements in some circumstances

Summary

There seems to be a problem with how the build pipeline is constructed when a workspace is open on a depedency of the element I requested a build for. bst build seems to just build up to the workspace element and stops there (exiting with 0 too). It's a little hard to explain - see 'Steps to reproduce'. I've tested this with v1.2.3 and current head of master (1.3.0).

Steps to reproduce

I've set up a project that demonstrates the issue here: https://gitlab.com/matthew-yates/bst-workspace-issue

$ bst workspace open elem1.bst
$ bst build elem3.bst

This should build elem1.bst and elem3.bst, but only elem1.bst is built and elem3.bst is left in a 'waiting' state.

What is the current bug behavior?

[myates@myates-uk-rdlabs-hpecorp-net workspace_issue]$ bst --version
1.3.0+1559.gef85e3b2                                                    
[myates@myates-uk-rdlabs-hpecorp-net workspace_issue]$ bst workspace open elem1.bst
[--:--:--][        ][ main:core activity                 ] START   Loading elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Loading elements
[--:--:--][        ][ main:core activity                 ] START   Resolving elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving elements
[--:--:--][        ][ main:core activity                 ] START   Resolving cached state
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving cached state
[--:--:--][        ][ main:core activity                 ] START   Checking sources
[00:00:00][        ][ main:core activity                 ] SUCCESS Checking sources
[--:--:--][        ][ main:core activity                 ] INFO    Creating workspace for element elem1.bst
[--:--:--][e8ed8241][ main:elem1.bst                     ] START   Staging sources to /var/home/myates/workspace_issue/elem1
[--:--:--][        ][ main:elem1.bst-0                   ] START   Staging local files at files/file1
[00:00:00][        ][ main:elem1.bst-0                   ] SUCCESS Staging local files at files/file1
[00:00:00][e8ed8241][ main:elem1.bst                     ] SUCCESS Staging sources to /var/home/myates/workspace_issue/elem1
[--:--:--][        ][ main:core activity                 ] INFO    Created a workspace for element: elem1.bst
[myates@myates-uk-rdlabs-hpecorp-net workspace_issue]$ bst build elem3.bst
[--:--:--][        ][ main:core activity                 ] START   Build
[--:--:--][        ][ main:core activity                 ] START   Loading elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Loading elements
[--:--:--][        ][ main:core activity                 ] START   Resolving elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving elements
[--:--:--][        ][ main:core activity                 ] START   Resolving cached state
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving cached state
[--:--:--][        ][ main:core activity                 ] START   Checking sources
[00:00:00][        ][ main:core activity                 ] SUCCESS Checking sources

BuildStream Version 1.3.0+1559.gef85e3b2
  Session Start: Monday, 18-02-2019 at 12:57:26
  Project:       workspace_issue_test (/var/home/myates/workspace_issue)
  Targets:       elem3.bst
  Cache Usage:   11.2G / infinity (6%)

User Configuration
  Configuration File:      Default Configuration
  Log Files:               /home/myates/.cache/buildstream/logs
  Source Mirrors:          /home/myates/.cache/buildstream/sources
  Build Area:              /home/myates/.cache/buildstream/build
  Artifact Cache:          /home/myates/.cache/buildstream/artifacts
  Strict Build Plan:       Yes
  Maximum Fetch Tasks:     10
  Maximum Build Tasks:     4
  Maximum Push Tasks:      4
  Maximum Network Retries: 2

Pipeline
   buildable ???????????????????????????????????????????????????????????????? elem1.bst Workspace: /var/home/myates/workspace_issue/elem1
      cached 0b26d694fcb7affb69ae8a1ff181978fcfcf089623b4065835c64b952a69e1c8 elem2.bst 
     waiting ???????????????????????????????????????????????????????????????? stack.bst 
     waiting ???????????????????????????????????????????????????????????????? elem3.bst 
===============================================================================
[--:--:--][????????][build:elem1.bst                     ] START   workspace_issue_test/elem1/????????-build.19601.log
[--:--:--][????????][build:elem1.bst                     ] START   Staging sources
[00:00:00][????????][build:elem1.bst                     ] SUCCESS Staging sources
[--:--:--][????????][build:elem1.bst                     ] START   Caching artifact
[00:00:00][????????][build:elem1.bst                     ] SUCCESS Caching artifact
[00:00:00][????????][build:elem1.bst                     ] SUCCESS workspace_issue_test/elem1/????????-build.19601.log
[00:00:00][        ][ main:core activity                 ] SUCCESS Build

Resolved key Summary
      cached eef33afd91c11513ced818c07952b816a5bf1c51654e3b64819133a688c2c181 elem1.bst Workspace: /var/home/myates/workspace_issue/elem1
     waiting 413a90aa56674ed5567274a37c1c85a09278322809715c070077f7b2e9cfe054 elem3.bst 
   buildable ec34b50b61fccf50eb9f4115a2db0bf1e59f8ec68c4f3f73f48cd7490b643520 stack.bst 

Pipeline Summary
  Total:       4
  Session:     3
  Fetch Queue: processed 0, skipped 1, failed 0 
  Build Queue: processed 1, skipped 0, failed 0 
[myates@myates-uk-rdlabs-hpecorp-net workspace_issue]$ bst show elem3.bst
[--:--:--][        ][ main:core activity                 ] START   Loading elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Loading elements
[--:--:--][        ][ main:core activity                 ] START   Resolving elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving elements
[--:--:--][        ][ main:core activity                 ] START   Resolving cached state
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving cached state
      cached eef33afd91c11513ced818c07952b816a5bf1c51654e3b64819133a688c2c181 elem1.bst Workspace: /var/home/myates/workspace_issue/elem1
      cached 0b26d694fcb7affb69ae8a1ff181978fcfcf089623b4065835c64b952a69e1c8 elem2.bst 
   buildable ec34b50b61fccf50eb9f4115a2db0bf1e59f8ec68c4f3f73f48cd7490b643520 stack.bst 
     waiting 413a90aa56674ed5567274a37c1c85a09278322809715c070077f7b2e9cfe054 elem3.bst

So despite asking elem3.bst to be built, it's still not built. But if i call bst build elem3.bst again, it is built. Presumably because the strong cache key for elem1.bst is now resolved.

[myates@myates-uk-rdlabs-hpecorp-net workspace_issue]$ bst build elem3.bst
[--:--:--][        ][ main:core activity                 ] START   Build
[--:--:--][        ][ main:core activity                 ] START   Loading elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Loading elements
[--:--:--][        ][ main:core activity                 ] START   Resolving elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving elements
[--:--:--][        ][ main:core activity                 ] START   Resolving cached state
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving cached state
[--:--:--][        ][ main:core activity                 ] START   Checking sources
[00:00:00][        ][ main:core activity                 ] SUCCESS Checking sources

BuildStream Version 1.3.0+1559.gef85e3b2
  Session Start: Monday, 18-02-2019 at 13:03:07
  Project:       workspace_issue_test (/var/home/myates/workspace_issue)
  Targets:       elem3.bst
  Cache Usage:   11.2G / infinity (6%)

User Configuration
  Configuration File:      Default Configuration
  Log Files:               /home/myates/.cache/buildstream/logs
  Source Mirrors:          /home/myates/.cache/buildstream/sources
  Build Area:     [myates@myates-uk-rdlabs-hpecorp-net workspace_issue]$ bst build elem3.bst
[--:--:--][        ][ main:core activity                 ] START   Build
[--:--:--][        ][ main:core activity                 ] START   Loading elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Loading elements
[--:--:--][        ][ main:core activity                 ] START   Resolving elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving elements
[--:--:--][        ][ main:core activity                 ] START   Resolving cached state
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving cached state
[--:--:--][        ][ main:core activity                 ] START   Checking sources
[00:00:00][        ][ main:core activity                 ] SUCCESS Checking sources

BuildStream Version 1.3.0+1559.gef85e3b2
  Session Start: Monday, 18-02-2019 at 13:03:07
  Project:       workspace_issue_test (/var/home/myates/workspace_issue)
  Targets:       elem3.bst
  Cache Usage:   11.2G / infinity (6%)

User Configuration[myates@myates-uk-rdlabs-hpecorp-net workspace_issue]$ bst build elem3.bst
[--:--:--][        ][ main:core activity                 ] START   Build
[--:--:--][        ][ main:core activity                 ] START   Loading elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Loading elements
[--:--:--][        ][ main:core activity                 ] START   Resolving elements
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving elements
[--:--:--][        ][ main:core activity                 ] START   Resolving cached state
[00:00:00][        ][ main:core activity                 ] SUCCESS Resolving cached state
[--:--:--][        ][ main:core activity                 ] START   Checking sources
[00:00:00][        ][ main:core activity                 ] SUCCESS Checking sources

BuildStream Version 1.3.0+1559.gef85e3b2
  Session Start: Monday, 18-02-2019 at 13:03:07
  Project:       workspace_issue_test (/var/home/myates/workspace_issue)
  Targets:       elem3.bst
  Cache Usage:   11.2G / infinity (6%)

User Configuration
  Configuration File:      Default Configuration
  Log Files:               /home/myates/.cache/buildstream/logs
  Source Mirrors:          /home/myates/.cache/buildstream/sources
  Build Area:              /home/myates/.cache/buildstream/build
  Artifact Cache:          /home/myates/.cache/buildstream/artifacts
  Strict Build Plan:       Yes
  Maximum Fetch Tasks:     10
  Maximum Build Tasks:     4
  Maximum Push Tasks:      4
  Maximum Network Retries: 2

Pipeline
      cached eef33afd91c11513ced818c07952b816a5bf1c51654e3b64819133a688c2c181 elem1.bst Workspace: /var/home/myates/workspace_issue/elem1
      cached 0b26d694fcb7affb69ae8a1ff181978fcfcf089623b4065835c64b952a69e1c8 elem2.bst 
      cached ec34b50b61fccf50eb9f4115a2db0bf1e59f8ec68c4f3f73f48cd7490b643520 stack.bst 
      cached 413a90aa56674ed5567274a37c1c85a09278322809715c070077f7b2e9cfe054 elem3.bst 
===============================================================================
[00:00:00][        ][ main:core activity                 ] SUCCESS Build

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

  Configuration File:      Default Configuration
  Log Files:               /home/myates/.cache/buildstream/logs
  Source Mirrors:          /home/myates/.cache/buildstream/sources
  Build Area:              /home/myates/.cache/buildstream/build
  Artifact Cache:          /home/myates/.cache/buildstream/artifacts
  Strict Build Plan:       Yes
  Maximum Fetch Tasks:     10
  Maximum Build Tasks:     4
  Maximum Push Tasks:      4
  Maximum Network Retries: 2

Pipeline
      cached eef33afd91c11513ced818c07952b816a5bf1c51654e3b64819133a688c2c181 elem1.bst Workspace: /var/home/myates/workspace_issue/elem1
      cached 0b26d694fcb7affb69ae8a1ff181978fcfcf089623b4065835c64b952a69e1c8 elem2.bst 
      cached ec34b50b61fccf50eb9f4115a2db0bf1e59f8ec68c4f3f73f48cd7490b643520 stack.bst 
      cached 413a90aa56674ed5567274a37c1c85a09278322809715c070077f7b2e9cfe054 elem3.bst 
===============================================================================
[00:00:00][        ][ main:core activity                 ] SUCCESS Build

Pipeline Summary
  Total:       4
  Session:     0
  Fetch Queue: processed 0, skipped 0, failed 0 
         /home/myates/.cache/buildstream/build
  Artifact Cache:          /home/myates/.cache/buildstream/artifacts
  Strict Build Plan:       Yes
  Maximum Fetch Tasks:     10
  Maximum Build Tasks:     4
  Maximum Push Tasks:      4
  Maximum Network Retries: 2

Pipeline
      cached eef33afd91c11513ced818c07952b816a5bf1c51654e3b64819133a688c2c181 elem1.bst Workspace: /var/home/myates/workspace_issue/elem1
      cached 0b26d694fcb7affb69ae8a1ff181978fcfcf089623b4065835c64b952a69e1c8 elem2.bst 
      cached ec34b50b61fccf50eb9f4115a2db0bf1e59f8ec68c4f3f73f48cd7490b643520 stack.bst 
      cached 413a90aa56674ed5567274a37c1c85a09278322809715c070077f7b2e9cfe054 elem3.bst 
===============================================================================
[00:00:00][        ][ main:core activity                 ] SUCCESS Build

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

What is the expected correct behavior?

That I only have to invoke 'bst build elem3.bst' once.

Relevant logs and/or screenshots

See above.

Possible fixes

No idea - Element._update_state() looks suspicious though.

Other relevant information

BuildStream version affected: /milestone %BuildStream_v1.2.3

Edited Feb 18, 2019 by Matthew Yates

To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information