Missing cache key in log messages (workspace open)

Summary

During bst workspace open, various messages do not contain the associated elements cache key.

Steps to reproduce

Open a workspace, observe output.

What is the current bug behavior?

Messages are produced without any cache key

What is the expected correct behavior?

All messages associated with the operation triggered for the element should contain its cache key.

Relevant logs and/or screenshots

[--:--:--][651aa7ef][ main:5G.bst                        ] START   Staging sources to /home/joshsmith/buildstream/doc/examples/CAS-interaction/wspdir
[--:--:--][        ][ main:5G.bst-0                      ] STATUS  Running host command

    /usr/bin/git show 72b5902157316e173de2eec5b3a2772283eec3c7:.gitmodules

[--:--:--][        ][ main:5G.bst-0                      ] START   Setting up workspace "/home/joshsmith/.cache/buildstream/build/workspace-5Gr52jkhma"
[00:00:00][        ][ main:5G.bst-0                      ] SUCCESS Setting up workspace "/home/joshsmith/.cache/buildstream/build/workspace-5Gr52jkhma"
[00:00:00][651aa7ef][ main:5G.bst                        ] SUCCESS Staging sources to /home/joshsmith/buildstream/doc/examples/CAS-interaction/wspdir
[--:--:--][][] INFO    Saved workspace configuration

Other relevant information

• BuildStream version affected: master @ 7dd74b01

---

Yes this is a bug.

Some clarifications:

• Log messages which are not associated to a specific element, e.g. the main messages at startup, will of course not have a cache key
• Log messages which are associated to an element, do not always have a cache key
  • If the cache key is not discovered yet (because of non-strict mode and artifact pulling, or because of workspaces, or because of bst build --track-all), then it will be shown as ????????

So the above clearly appears to be a bug.

This is due to the message being produced by a source (The workspaced element main:5G.bst-0) and message.task_id is unset.

changed milestone to %BuildStream_v1.4

added Important To Do labels

Update, this is still a bug.

Tried today with fdsdk and today's master:

[--:--:--][        ][    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 bootstrap/stripper.bst
[--:--:--][238a62d7][    main:bootstrap/stripper.bst        ] START   Staging sources to /home/tristan/work/freedesktop-sdk/TEMP
[--:--:--][        ][    main:bootstrap/stripper.bst        ] START   Staging local files into CAS
[00:00:00][        ][    main:bootstrap/stripper.bst        ] SUCCESS Staging local files into CAS
[00:00:00][238a62d7][    main:bootstrap/stripper.bst        ] SUCCESS Staging sources to /home/tristan/work/freedesktop-sdk/TEMP
[--:--:--][        ][    main:core activity                 ] INFO    Created a workspace for element: bootstrap/stripper.bst

I can explain why this is happening:

• When you open a workspace, there is no scheduler or subprocessing happening, messages are not stamped with the "task element" in the normal way, because there is no "task element"
  • This means that we are falling back to printing the issuing plugin in the log lines, not the task element
• The "Staging local files to CAS" messages are issued by the workspace source, and the workspace source is not the workspaced element itself, as such those messages do not bare any cache key.

It is questionable whether this is worth fixing, if so; one way to fix this would be to have element sources derive their "cache key for logging purposes" from their owning elements... another way would be to change how the name is displayed, instead of showing the element name in the UI, it should be clear that we are logging a specific source belonging to that element.