Add option to clear TriggeredBuilds Variable after Build awaited and improve logging

[cbaxter]

Extension working great; thanks again for all your hard work!

I have been using a combination of the Trigger/Wait tasks within a single build definition to conditionally queue up a batch of builds and subsequently wait for any queued build(s) to complete before proceeding on to the next batch of builds to be queued. Basically, the use case arises when creating multiple builds from a single GIT repo, and conditionally triggering builds only if changes are detected.

Example

Build A (optional)
Build B (optional)
Wait for A and/or B (optional)
Build C (optional)
Wait for C (optional)
Build D 
...
...

I appreciate that there is no actual need to clear out the variable as the next wait will see the builds as completed; I find the extra noise in the log distracting. I can reset the TriggeredBuildIds myself via PowerShell, although I thought it might be nice if the Trigger/Wait tasks cleared out the TriggeredBuildIds variable once finished so that the TriggeredBuildIds is empty at the start of the next batch. Thoughts?

Guessing something along the lines of:
this.taskLibrary.setVariable(taskConstants.TriggeredBuildIdsEnvironmentVariableName, "");

After the while loop exits:

TfsExtensions/BuildTasks/waitforbuildtask/taskrunner.ts

Line 56 in f46b570

---

Although the following could be captured as a separate suggestion, I would also appreciate suppressing the following two console messages to reduce build log noise while waiting for longer builds to complete...

1. Sleeping for ${ms / 1000} seconds...
   

   TfsExtensions/BuildTasks/waitforbuildtask/generalfunctions.ts

   Line 13 in f46b570

   console.log(`Sleeping for ${ms / 1000} seconds...`);

2. Build ${queuedBuildId} has not yet completed
   https://github.com/huserben/TfsRestService/blob/0d7d8ebe6f2262e513bd923c6f0f4692ac15be87/index.ts#L280

   NOTE: Would not impact: Build ${queuedBuildId} has completed logging (that is always useful).

Perhaps both messages are only shown when system.debug is True? That would be a minor change in current behavior but at least would not require a new task configuration option...

Again, the tasks work great and I am glad they exist, just minor suggestions based on my usage.

[huserben]

Hi @cbaxter

thanks for your input and the very detailed explanation.

I think both your suggestions make sense. I'm wondering if "clearing the TriggeredBuildIds" should be configurable via the options. I'm thinking the default shall be to clear, however if it's needed for something else (like some custom script or something) I don't want to break anything, with this backwards compatability would be given.

The second suggestion definetly makes sense, I think I initially put it in during development/debuggin on the server but I think it's not even needed when system.debug is set to true. So I'll probably drop it completly. I'm not really impacted by the "noise" as all my test-builds usually point to an already finished build so I don't really see those lines ;-)

I will include those changes in the next version of the task.
Note: I'm not sure when I will be able to provide this version as I will be not able to work on the code during the whole next week, so if it's not there by Sunday evening you will need to wait till next week

[huserben]

Adding the following improvement proposal to this issue as it goes in the same direction and is about cleaning/chaning logging behavior of awaited builds (original proposal from @jfinnegan3 in #47 (comment)):

In my setup, when I'm using the Await Build Task, and the build I'm waiting for fails, I fail the whole build. A couple of the developers on my team have suggested that if that Await Build Task fails as a result of the triggered build failing, could the link to the failed build(s) console be provided in that step? This would allow for easy navigation, so the devs can see what went wrong.

Current Proposal:
Just add the full link to the build that has failed to the console.
@jfinnegan3: Please confirm that this is what you expect

Edit: Another option could be to directly link to the logs as described in the docs. However I'm not sure if this would bring any benefit, as you would end up with just a plain log file, while if you go via the regular build output you would at least have some color indication etc.

[cbaxter]

@huserben A new option to support backward compatibility makes perfect sense; thank you. I also like the suggestion from #47 regarding easy navigation to a failed build; a few of our developers have asked for that as well... if you have access to the build definition name; that would be useful as well (over build ID).

[huserben]

Ok, I could try to see what it would mean to include the name of the build definition name next to the ID and include a link to the build itself after completion (I guess I can log this in any case, not only when it failed).

So something along the line of this:
Build 1234 (MyBuildDefiniton) has completed
https://myInstance.visualstudio.com/TeamProject/_build/index?buildId=1234&_a=summary

[jfinnegan3]

What I'm proposing is along the lines of either :

Will wait for queued builds to be finished - Refresh time is set to x seconds
Build XXXXX, <def_name> has not yet completed
Sleeping for x seconds...
Build XXXXX, <def_name> has not yet completed
Sleeping for x seconds...
Build XXXXX, <def_name> has completed
##[error]Build XXXXX, <def_name>, <build_url>, was not successful - failing task.

OR, something at the beginning of the task like:

Following Builds are awaited: XXXXX - <def_name>, <build_url>
Using current Team Project URL
...
(keeping everything else mostly the same)

This makes it easier to use this task because all a dev needs to do is go to the failed task, ctrl + click the link to navigate to build and see what went wrong. This is as opposed to going to failed task, finding build number of failed build, going to trigger task, and then ctrl clicking on the link to failed build.

Thanks for looking into it!

[huserben]

Ok I think this is a good compromise.
As suggested by @jfinnegan3 I would list all the awaited builds in the beginning together with the Build Definition name and the link to it.
Instead of completly removing the "Sleeping for x seconds..." I changed it so that everytime we check again I append a "." to the current line. This is because during testing I realized it's good to know that there is still progress, just to be sure something is still happening (and not some issue with the browser, refresh of the console is wrong etc.).

This will lead to an output somewhat similar to:

Queued new Build for definition CI Test: https://myInstance.visualstudio.com/DefaultCollection/Build Test/_build/index?buildId=1801
Will wait for queued build to be finished - Refresh time is set to 10 seconds
Following Builds will be awaited:
Build 1801 (CI Test): https://myInstance.visualstudio.com/DefaultCollection/_permalink/_build/index?collectionId=12d83491-05ec-4d25-9701-6ee9a0e83256&projectId=df832ba4-a0a1-4ab9-b417-7958a933c508&buildId=1801
Waiting for builds to finish............All builds are finished

In case of a failed build and we want to fail the Task, the error itself would contain again the information:

2018-03-11T09:46:42.4430959Z ##[error]Build 1767 (CI Test) was not successful - failing task.
                    See following link for more info: https://myInstance.visualstudio.com/_permalink/_build/index?collectionId=12d83491-05ec-4d25-9701-6ee9a0e83256&projectId=df832ba4-a0a1-4ab9-b417-7958a933c508&buildId=1767

This might seem like a "duplicate info" as we list it in the beginning anyways, however it helps in a way as the error will appear on the build summary page. So with this you will see already there what failed and the link to the build without the need of navigating to the logs:

Note: I think this link is not clickable though.

I implemented it more or less like this now, however it would require some cleanup. As I'm not available during the next week I would finish it end of next week and publish it then, as I could not provide any "hotfix" in case something goes wrong with the new relesae.
I hope you can live with the current task for another week.

What do you guys think, would this be fine with both you? I think we have then a good compromise between not polluting the log with unnecessary info while we have more meaningful info for the devs to figure out more quickly why/what went wrong.

[cbaxter]

@huserben Seems like a reasonable compromise to me; achieves reduced log noise but still contains all required information to troubleshoot any build failures. Thanks!

Is an option to reset TriggeredBuildIds still in scope?

[huserben]

@cbaxter Yes, sorry I missed to mention that. I will add an option for the WaitForBuild Task to clear the Variable after the task was run. The default will be set to true.

For the TriggerBuildTask everything will be as before, as this option does not really make sense there I believe.

[jfinnegan3]

Yes, looks good - thank you!

[huserben]

Hi @cbaxter and @jfinnegan3

I just uploaded version 2.7.0 which includes both changes, the new option to clear the variable in the waitforbuild task and the improved logging when awaiting builds.

Please have a look and let me know whether its working ok or if it needs any adjustements.

Thanks for the feedback both of you provided to help improve the tasks and please do not hesitate to add other issues if new things pop up.

[cbaxter]

@huserben Excellent, thank you! I will update our builds either tomorrow or Monday and review.

[JeffRausch]

I love the idea of appending a period to the current line for "Waiting for builds to finish"... but it doesn't seem to work as expected in the VSTS console. I don't know if that uses the newline character to trigger refreshing the console or what but I don't see "Waiting for the builds to finish" until after that triggered build finishes and it moves to the next task.
This is what I see while it's building:

Will wait for queued build to be finished - Refresh time is set to 5 seconds
Following Builds will be awaited:
Build 4487 (BUILDNAME): https://COMPANY.visualstudio.com/_permalink/_build/index?collectionId=XXXXXXX&projectId=XXXXXXXXXX&buildId=4487

Then after it's finished and moves to the next task I see this:

Waiting for builds to finish.....All builds are finished

[cbaxter]

@huserben As a thought, if you wanted to be "fancy", you could pull back the current build's currentOperation (and/or percentComplete) for a build using the following URL to grab the build details...

GET https://{instance}/DefaultCollection/{project}/_apis/build/builds/{buildId}/timeline?api-version={version}

You could then display the current build operation for each queued build rather than "Waiting..." and filter the results down to only update the console with new messages when the build status has changed from the previous interval? Has the added bonus of giving a little context as to where the build stands without having to go look.

[huserben]

Oh yes, now that you mention it, it seems that this really won't work as expected in the web console. Due to the lack of multiple agents on my test environment and for simplicity reasons I usually run the task on my local machine where it used to work.
Problem seems to be when logs are written via process.stdout.write instead of console.log.

@cbaxter Hmm that sounds like a valid proposal, I need however some time to look into it and see how to properly do it. I never checked out the timeline so far and I need to see what info I can get and how to properly use it (e.g. it seems that a failed build will have "null" as percentComplete).
Edit: Seems like this is always null, maybe we just display the task currently executed...

So your idea would be to log a log a line for every build that is awaited after it was checked stating in which state it is (like you mentioned with either currentOperation or percentage or both). And only display this if it has changed since the last check (to reduce the amount of log messages?)

@JeffRausch
Would this as well for you be a viable solution. And could you live with the current "faulty" state that won't display the dots while waiting? I'm not sure if it's even possible to append dots in the webconsole if the current implementation won't work...

Example of a possible log:

Following Builds will be awaited:
Build 1234 (MyBuild): https://instance.visualstudio.com/_permalink/_build/index?collectionId=42&projectId=12&buildId=1234
Build 1234 has not yet finished (Build Solution)
Build 1234 has not yet finished (Test Assemblies)
All awaited builds have finished

[cbaxter]

@huserben The task currently executed would work... I liked the ... idea; however as that does not appear to be possible based on the feedback from @JeffRausch ; my thought is that the status messages could be used to convey where in the build we are waiting and provide valuable context. Just a thought...

[cbaxter]

@huserben

Small bug unfortunately...

2018-03-19T12:12:26.5369327Z Following value is already stored in the variable: ''
2018-03-19T12:12:26.5369327Z New Value of variable: ',4989'

Note the leading , ... subsequent wait task will results in...

2018-03-19T12:12:27.6150446Z Following Builds will be awaited:
2018-03-19T12:12:28.3650553Z ##[error]Cannot read property 'name' of undefined

[JeffRausch]

That's fine with me. It's not often I sit and watch the builds as they're processing so not seeing it in real time isn't a big deal.
Thanks again for all your work on this!

[huserben]

@cbaxter
You wrote

my thought is that the status messages could be used to convey where in the build we are waiting and provide valuable context

From what I see, this was included in the sample log messages I put, for example Build Solution or Test Assemblies would be the name of the task in the build script that is currently executed. What else would you have in mind to log for the user if not that? At least I could not figure out any other info that could be used.

Regarding your issue, in what scenario did this happen? After the variable was cleaned in the next instance of the trigger build task?

Edit: Ok regarding the Issue I think I located the problem and I would be able to provide a fix rather soon.
Edit2: Version 2.7.1 should the fix the issue you had @cbaxter

[cbaxter]

@huserben Thanks, I will confirm tomorrow... the issue was on the subsequent wait...

1. Build (OK)
2. Wait (OK)
3. Build (appended , ####)
4. Wait (Failed due to ,)

[cbaxter]

@huserben Appears to be working as expected now, thanks!

[huserben]

@cbaxter
Regarding the log statements examples I made in the comment above, you said

... that the status messages could be used to convey where in the build we are waiting and provide valuable context

Just that I don't implement something that is not needed anyway, how would provide this information. As far as I could see the only meaningful value I got back was the Step the build is currently in (what i put in the brackes in my sample log).
I'm open to any kind of proposal :-)

[cbaxter]

@huserben To be honest, I like the suppressed output in the current version; the suggestion for showing where in the build came from the fact that it was sounding like there may continue to be "progress" output... if that is off the table for now (i.e., the ... don't show until the end), then this isn't required in my opinion. If the wait task goes back to having some form of interval output, then we can discuss further?

[huserben]

Ah ok, now I see.

I'll continue to look a bit into this and see what is possible in that direction. For example I saw now that for each build we await an entry in the Build Timeline could be created. I will also check again a bit into the direction of updating the console logs on the fly.

Anyways in case I see something worth pursuing I would create a new Issue so I can close this one, as I think the main topic of it was cleaning out the logs and adding the Clear Variable option which is solved.

Thanks both of you for your inputs.