[Issue] Cannot troubleshoot script hooks - no output

[heaths]

Output from azd version azd version 1.0.2 (commit 145e046b1ea9394bd4e1b1d539eb32e860d692fb)

Describe the bug There is no way to troubleshoot script hooks because output does't appear to be available even if running azd up --debug. No log file, nothing.

To Reproduce Add a hook like https://github.com/heaths/azcrypto/blob/553f98cbb9dedd76534778050ad06eea4818b135/azure.yaml#L9. Run it with necessary parameters, and notice that - even when passed --debug - all you see is something like this:

Executing postprovision hook => /tmp/azd-postprovision-3919396641.sh
2023/06/16 14:14:25 hooks_runner.go:148: Executing script '/tmp/azd-postprovision-3919396641.sh'
2023/06/16 14:17:34 command_runner.go:132: Run exec: ' /tmp/azd-postprovision-3919396641.sh' , exit code: 0

That said, at the very end - not during - anything written to stderr was shown.

Expected behavior stdout and stderr should be redirected to azd's own stdout and stderr - at least when passing --debug or, perhaps better, a --verbose (I don't need to see tons of polling messages for resources like Managed HSM that take a very long time to provision.

Or at least write those to a log and tell me the log path before you execute so I can tail it.

[heaths]

For posterity, though we have a thread going internally, I was made aware of:

https://github.com/Azure/azure-dev/blob/1280db447de17ab96db05fb390d836f41c4ed283/cli/azd/pkg/ext/models.go#L65

However, how much information a user wants to see is a user's (caller's) choice - not the dev/maintainer. Does a repo admin get to configure the equivalent of git -vv for every git command issued? I don't even think it's possible, but would be presumptive to use.

At the very least, binding stdout, stdin when --debug is passed makes more sense. If a dev/maintainer does need to prompt, interactive: true does make sense - it's hard to ask for input on stdin without writing to stdout/stderr.

Alternatively - or even in addition to - you could support something like a AZD_DEBUG env var where if it's defined, you get debug output. You could even support debug levels like 1..2 for verbose (-v) vs. very verbose (debug, -vv) like git. git and gh have these as well e.g., GIT_DEBUG and GH_DEBUG, respectively.

[rajeshkamal5050]

@savannahostrowski @ellismg

should we at a minimum make the script hooks output appear in the --debug logs?

[savannahostrowski]

That seems reasonable to me

[weikanglim]

Currently, the script hooks output does appear in --debug. But as @heaths points out, if a hook has Interactive:false, the log output is buffered and written to log file only after the script exits. If the script hangs, the log isn't written.

If you set Interactive: true, all the output goes to stdout/stderr and stdin is also allowed to be bounded to the running script.

[weikanglim]

Both --debug and the way the logging (w/ buffering) serves azd well but doesn't play well with hooks.

One way we could eliminate the complexity here is maybe think about what Interactive should really mean? It seems like if I wrote a script that wants to use stdin/stdout, and forgot to set Interactive:true that ends up hiding expected output and hanging indefinitely.

What is the core idea behind Interactive:false? I could see this as a reasonable way for script authors to not have to think about whether they explicitly suppressed output. But if so, is Quiet the configuration we should define instead?

[heaths]

But when a caller needs to troubleshoot their hooks, they decide to pass --debug. This shouldn't be a script author's decision. If they need to attach to a TTY via stdin to prompt for input, certainly - and in that case, stdout and/or stderr is needed to print context and what the caller is being prompted for, but just emitting stdout and stderr is a caller choice - no different than calling git -vv ... or the like.

In my case, I couldn't tell if commands I was running were hung or not, and because they are verbose I certainly don't want callers seeing them by default.

I think the fundamental consideration here is what @vhvb1989 and I were discussing internally: there doesn't seem to be much consideration for repos that provide azd templates for use by contributors. Frankly, I thought that was a major use case. Would-be contribs could pop into a repo, make a few changes, run azd up, and test those changes. Or even if they don't look to change code and want to try a sample repo e.g., a Cosmos DB Todo app, they clone and run azd up.

Why, as a repo maintainer, would I want to force verbose output on would-be contribs or dev interested in learning from a sample? That seems rather frustrating.

[weikanglim]

I was mostly wondering if the Interactive property is something that ends up making authoring and debugging slightly more difficult. Suppose that Interactive wasn't a configuration property, I'd imagine that you'd get a more natural output, when you'd write your script, handle stdout/stderr as you would want to, and observe the expected output in console. From an authoring perspective, there isn't an additional azd consideration when writing scripts.

Short of that, I agree that we should make:

1. --debug make scripts behave as-if Interactive:true? Or stdout/stderr visible as you pointed out? The behavior personally is harder for me to reason about as an end user (why does CLI debug affect my script hooks output), but perhaps the mental model of "let's just re-run with --debug to debug additional output" fits the use case.
2. AZD_HOOKS_DEBUG as a env var way of just enabling the debug output for scripts? This would align better with your CI scenarios as you suggested. I also think that promoting AZD_DEBUG as a env-sourced debug flag also makes sense. We can readjust the internal usage of this variable.

[heaths]

why does CLI debug affect my script hooks output

If you consider that the hooks are part of your "template", I find it more odd that showing hook command output isn't included in --debug. That typically means, "show me everything". Aren't hooks part of that? Afterall, your template probably won't work correctly if you don't run those hooks.

Overall, I think --debug working like interactive: true makes sense, but maybe not hooking up stdin. That could alter the behavior of hooks.

The main point is that showing debug output is a caller choice. Could an author, for example, force request/response logging on a user via configuration? Why should command output be any different? Just because the commands worked for the author initially, maybe they don't subsequently or for another user. Consider, for example, if they assume that the user is logged into az because the author was at the time. The script would hopefully just fail. But why? The user can pass --debug to find out.