Azure-pipelines-tasks: Bash 'task.setvariable' adds unexpected ' as trailing symbol

[nuclear0wl]

Type: Bug

Task Name: Bash

Environment

• Server - Azure Pipelines

• Agent - Private:

  • OS: Red Hat Enterprise Linux Server release 7.4 (Maipo)
  • Agent version: 2.141.1

Issue Description

When echo "##vso[task.setvariable variable=variable]$value" is used as a part of script in Bash task type some unexpected trailing ' may appear in the value of variable. Appearance of trailing ' is a fully random process, but I usually get them in the part of my variables.

To produce and show appearance of trailing ' in value of variables I set two variables: build.producedArtifactName and build.producedArtifactPath, as could be seen below, I work with this variables in the same style: use some bash commands to set values and expose them using ###vso set.variable, in next Tasks I echo this variables and use them as an input for Task, as could be seen on screenshots, trailing ' appeared in value of variable build.producedArtifactName and didn't for build.producedArtifactPath that makes me think that problem came from the side of Bash V3 module.

Here simple bash script sets two variables and uses ###vso for variables setting:

As it could be seen in log, set variables don't have any ' symbols:

Next, it's used simple bash script to echo variables which were set via ###vso:

As a result output for first variable absolutely normal, but in second variable trailing ' appeared:

If variable set via ###vso is used in other types of tasks like Publish Build Artifacts same behaviour is faced:

As a result drop artifact also has trailing ' in it's name:

[thereallukl]

I'm experiencing same issue, basically I have to manually remove this character from all my pipelines. So instead using dedicated tasks for my pipelines, I have to use bash task everywhere and run for each variable

VARIABLE=`echo $(variable) | tr -d "'"`

[i0pr1m3]

Have you tried using echo ##vso[task.setvariable variable=variable]$value instead of echo "##vso[task.setvariable variable=variable]$value"?

[damccorm]

Hm, I'm not able to get a repro. Does your variable have any special characters in it? Wondering if there's a weird escaping bug here.

Also, have you tried not quoting the command like @i0pr1m3 suggested? Just trying to rule out possibilities

[tomtung]

For reference I also have the same problem and need to do the same workaround: https://github.com/tomtung/omikuji/blob/83f33e8c62694f0ec58d28d306a59246849701bb/.ci/azure-python-build.yml#L67

Unless it's already fixed, removing this line (and maybe all such lines in the file) should help repro the problem.

[sweekarpinto]

This seems to be an issue with set -x: https://developercommunity.visualstudio.com/content/problem/375679/pipeline-variable-incorrectly-inserts-single-quote.html

[Cseverance]

Hi I would like to just add in that I am also seeing this issue, but not consistently. It shows up in about 1 in 10-15 releases, and then I can't reproduce it for a few days, which makes troubleshooting it very difficult.

[germaino]

I have the same issue of quote in bash script, this is very annoying

[kentcb]

Arrived here with the same annoying problem. Changing my set -ex call to set -e does indeed work around the issue.

[dg0yt]

Okay, -x might explain the problem when it occurs - but it happens just in 10% of the runs in my setup.

[nuclear0wl]

Hello, @damccorm. As participants above absolutely truly mentioned, this issue occurs only when you set set -x in bash tasks. Also probability to reproduce issue is very random. For some tasks it occurs every run, for another it may not be occurred at all. Various experiments with quoting haven't gave any result at all.
In our case we had to remove all mentions of set -x from our bash tasks, it's very sad, because Azure Pipelines has very poor diagnostic of runtime execution of bash scripts. As I can see, since my last visit demand on this issue grown so mush, so I hope that bugfix will be released someday.

_Just a little bit of information for future visitors of this issue:_ As we recognised in the process of our internal investigation, Azure Pipelines just scans output of all commands in bash script and if sees special command like ##vso, then executes it immediately even if it's just an output of an -x option (you may notice that if your echo or set -x output has ##vso command it won't be shown at logging screen at all).
As set -x option may add some extra single quotes to debugging output (starting with + symbol) , Azure Pipelines identifies this extra quotes as a part of variable that should be set. Also task.setvariable may set value of variable only once, so when echo command provide clear output without any quotes to stdout it won't change value which was already set using output from set -x option.
As a workaround set +x may be added before calls of ##vso functions, it may help if you need to have output of set -x options for some parts of your code but such output for ##vso functions may be suppressed.

[damccorm]

;tldr - I think the Bash task is actually behaving correctly here - @nuclear0wl's most recent comment of set +x before ## commands is probably the right thing to do.

@nuclear0wl @dg0yt @kentcb @germaino @Cseverance @sweekarpinto @tomtung @i0pr1m3 @lleszczu - thank you for your comments and sorry for the slow response. This was a hard problem to track down, they all helped. I think a lot of comments are getting at the issue here, but I want to share what is causing this.

Basically, the issue is that when Bash has set -x turned on, it responds to any commands it processed with an extra line saying that it processed the command. So if you have the script:

set -x
echo foo

it will print:

Processed: foo
[... things happening ...]
Processed: + echo 'foo'

So in the case of ## commands,

set -x
echo ##vso[task.setvariable variable=foo;]bar

will print

Processed: ##vso[task.setvariable variable=foo;]bar
[... things happening ...]
Processed: + echo '##vso[task.setvariable variable=foo;]bar'

If you turn on debug output, you'll probably be able to see this happening in your output.

By design, we pick up any instances of ##vso commands. This means that in the output above, we pick up the initial ##vso[task.setvariable variable=foo;]bar command, then we pick it up again from Processed: ##vso[task.setvariable variable=foo;]bar, and then finally we pick it up one last time from Processed: + echo '##vso[task.setvariable variable=foo;]bar'.

This is the problematic one, because we ignore everything before the ##vso. So what we receive here is ##vso[task.setvariable variable=foo;]bar' which correctly sets the variable to bar'.

This is weird, but I think we're actually doing the right thing here - our contract is that we parse all output from scripts. Part of our contract is also that we don't touch the actual contents of the script, so there's not a way for us to distinguish between valid ## commands and this.

All that to say, I think this is unfortunate, but I don't see a way around it. I'm open to suggestions, but as of now this looks like a no-op to me.

[dg0yt]

Any explanation why this happens only in some runs but not all of them?

[damccorm]

I haven't 100% figured that out yet, but my best guess is that I don't _think_ the ordering of the messages is guaranteed. So in the above example, the output of one run might be:

Processed: ##vso[task.setvariable variable=foo;]bar
Processed: + echo '##vso[task.setvariable variable=foo;]bar'

and in the next it could be:

Processed: + echo '##vso[task.setvariable variable=foo;]bar'
Processed: ##vso[task.setvariable variable=foo;]bar

The last one would win here

[tomtung]

Thanks for the clarification! I guess we made the (incorrect) assumption that ##vso has to appear at the beginning of a line to be processed

[dg0yt]

I guess we made the (incorrect) assumption that ##vso has to appear at the beginning of a line to be processed.

But isn't it a reasonable assumption?
a) Consistency: It picks up everything until the end of the line, so it should start at the beginning.
b) Consistency: If you parse bash output in the bash world, you would not see the Processed: prefix.
c) The documentation gives only examples which start at the beginning of the line.
d) Security: No string echoed to the console by some command should interfer with the environment too easily.

[damccorm]

@dg0yt

Consistency: It picks up everything until the end of the line, so it should start at the beginning.

I definitely get what you're saying here, and don't totally disagree. I think there are a fair amount of reasons people would want to have it begin in the middle (e.g. prefixing with description of what's happening, timestamp, etc...) and I can't speak to the history behind this decision, but at this point its somewhat moot - changing this would break a good amount of people so I don't think its really an option at this point.

Consistency: If you parse bash output in the bash world, you would not see the Processed: prefix.

Not sure I fully understand, but there's not much we can do here - we just parse stdout that the bash tool writes on our end, and that doesn't seem like a behavior we'd _want_ to change - in general we try to mess with the tools you use as little as possible because they tend to know their ecosystems better than we do.

The documentation gives only examples which start at the beginning of the line.

I think this makes sense - that's the mainline case - but we should probably also specifically call out that this behavior also works. Any docs you were looking at in particular? We can get those fixed up.

Security: No string echoed to the console by some command should interfer with the environment too easily.

I don't really see this one to be honest - regardless of what behavior we choose here, a tool _could_ alter the environment by pumping something to stdout. Note that tools can also set normal environment variables though, so I don't think this is hugely problematic. We're also working on features to let you lock down the ## commands, but as long as they exist in some capacity and tools have access to stdout, they will have access to those.

[damccorm]

I'm going to close since I think this is a no-op on our end. Please comment if you think it should be reopened

[HughDevlin]

Please re-open.

[damccorm]

Currently following up in the other issue (#10165). This is actually different than what you are experiencing there. Will follow up momentarily with guidance

[mjscosta]

May I ask @damccorm did you managed to reproduce the example I've provided in https://github.com/microsoft/azure-pipelines-tasks/issues/10165 ?

[damccorm]

@mjscosta I think its the same issue as this thread - did you try my guidance from #10165?

Hey @mjscosta - this looks like it might be the same issue as #10331
Could you try running set +x at the start of your script? If that doesn't work, could you try queuing a build with system diagnostics turned on and sharing the output?

[HughDevlin]

Hello Mario, good to hear from you.
I'm sorry this issue #10165 is closed as no issue found and also that it is blocked from further comment.
Thank you for contributing an example to the issue report. I have not reproduced the exact example you have provided. Others and I encountered an issue with the same symptom in conjunction with ##vso setvariable (not prependpath).

According to Microsoft, pipelines execute ##vso whenever it is encountered in a stdout stream, no matter the context. I feel this is too strong and the issue is best summarized as unexpected "extra" executions of ##vso in pipeline scripts. I remain convinced that an effective resolution of this issue is that ##vso should be coded so as to be sufficiently smart about its execution environment such that it does not execute (or "executes" but does nothing) in the context of being written to stdout due to happening to be the last command executed and included in a linux set command output.

Further, I submitted a vulnerability report VULN-013253 which was similarly closed with no action.

Hugh

[HughDevlin]

We know the setvariable and prependpath task commands within ##vso logging commands can exhibit this undesirable behavior, but we don't know how many other ##vso task commands are exposed to this undesirable behavior.

Further, we know the linux set bash command, used in a script in conjunction with ##vso can bring about the undesirable behavior, but we don't know how many other linux commands or Microsoft command line commands can also bring about the undesirable behavior.