Bug report: Running CLI on Azure Function throws errors because of Spinner output

[martinlingstuyl]

Description

When running the CLI 6.3 and above on an Azure Function, the following vague exceptions are thrown. This is probably caused by the Spinner trying to pipe output to the console, while the Azure Function may not be allowing this type of writing output.

[2023-03-29T11:56:41.954Z] Result: ERROR: - Running command...
[2023-03-29T11:56:41.955Z]
[2023-03-29T11:56:41.956Z] Exception             :
[2023-03-29T11:56:41.957Z]     Type        : System.Management.Automation.RemoteException
[2023-03-29T11:56:41.958Z]     ErrorRecord :
[2023-03-29T11:56:41.959Z]         Exception             :
[2023-03-29T11:56:41.960Z]             Type    : System.Management.Automation.ParentContainsErrorRecordException
[2023-03-29T11:56:41.960Z]             Message : - Running command...
[2023-03-29T11:56:41.961Z]             HResult : -2146233087
[2023-03-29T11:56:41.962Z]         CategoryInfo          : NotSpecified: (:) [], ParentContainsErrorRecordException
[2023-03-29T11:56:41.963Z]         FullyQualifiedErrorId : RuntimeException
[2023-03-29T11:56:41.965Z]     Message     : - Running command...
[2023-03-29T11:56:41.966Z]     HResult     : -2146233087
[2023-03-29T11:56:41.967Z] TargetObject          : - Running command...
[2023-03-29T11:56:41.968Z] CategoryInfo          : NotSpecified: (- Running command...:String) [], RemoteException
[2023-03-29T11:56:41.969Z] FullyQualifiedErrorId : NativeCommandError
[2023-03-29T11:56:41.970Z] InvocationInfo        :
[2023-03-29T11:56:41.971Z]     MyCommand        : node.exe
[2023-03-29T11:56:41.972Z]     ScriptLineNumber : 24
[2023-03-29T11:56:41.974Z]     OffsetInLine     : 5
[2023-03-29T11:56:41.975Z]     HistoryId        : -1
[2023-03-29T11:56:41.976Z]     ScriptName       : C:\Users\MartinLingstuyl\AppData\Roaming\npm\m365.ps1
[2023-03-29T11:56:41.977Z]     Line             :     & "node$exe"  "$basedir/node_modules/@pnp/cli-microsoft365/dist/index.js" $args
[2023-03-29T11:56:41.978Z]
[2023-03-29T11:56:41.978Z]     PositionMessage  : At C:\Users\MartinLingstuyl\AppData\Roaming\npm\m365.ps1:24 char:5
[2023-03-29T11:56:41.981Z]                        +     & "node$exe"  "$basedir/node_modules/@pnp/cli-microsoft365/dist/i .
[2023-03-29T11:56:41.983Z]                        +     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[2023-03-29T11:56:41.984Z]     PSScriptRoot     : C:\Users\MartinLingstuyl\AppData\Roaming\npm
[2023-03-29T11:56:42.065Z]     PSCommandPath    : C:\Users\MartinLingstuyl\AppData\Roaming\npm\m365.ps1
[2023-03-29T11:56:42.067Z]     InvocationName   : &
[2023-03-29T11:56:42.069Z]     CommandOrigin    : Internal
[2023-03-29T11:56:42.084Z] ScriptStackTrace      : at <ScriptBlock>, C:\Users\MartinLingstuyl\AppData\Roaming\npm\m365.ps1: line 24

Steps to reproduce

Create a new VS Code project with PowerShell, use a CLI command and press F5

CLI for Microsoft 365 version

6.4 (beta)

nodejs version

16.15.0

Operating system (environment)

Windows, Azure Function

Shell

PowerShell

Additional Info

If we would be able to hide the spinner with a config key, this may be avoided. Also, we should add this config key to the settings that will be added when running the new m365 setup command that is being created in #4216.

Implementation

We agreed on adding a config key showSpinner with the default value true. If it's false the spinner should not be rendered.

[waldekmastykarz]

Ouch, that's annoying. Would you mind elaborating the repro steps a bit? What's a "VS Code project with PowerShell" exactly?

[waldekmastykarz]

Could you also share the code for how you reference the CLI?

[waldekmastykarz]

Before we decide to disable the spinner as the solution, let's see if we can understand why this is happening exactly.

[waldekmastykarz]

I can indeed confirm that commenting out spinner start removes the error. Let's see if there's a way for us to detect it reliably.

[martinlingstuyl]

So you were able to reproduce it with the short description I gave? 😂

Yeah, so for progeny: Azure Functions project, npm install cli locally and update the path, basically this setup:

https://www.blimped.nl/how-to-run-the-cli-for-microsoft365-on-an-azure-function/

I'm not sure if there is something to detect... aside from maybe checking certain env variables?

I'd say it would be nice if we had a few optimizations for usage in automation scenarios. We could configure these using m365 setup, and expose them using config keys. Disabling dynamic User Interface things like spinners and (disambiguation) prompts for example.

[waldekmastykarz]

Yup, I was able to repro it. So far I've seen, that Ora (which we use for showing spinners) has built in detection of non-interactive streams. Calling .start() seems to be working as expected, and I suspect it's failing either in stop or when other logic sends something to output.

I agree that we should make it configurable but also the defaults should work too.

[waldekmastykarz]

So it seems, that the issue is caused by PowerShell treating anything logged to stderr (which is where the spinner goes) as an exception. You can verify this by adding anywhere inside CLI console.error('foo') and seeing the same (or similar) result.

We can go about it two ways:

1. Ignore stderr:

$version = m365 version 2>$null

2. Allow configuring CLI

Allow configuring CLI for non-interactive use and disabling spinners, prompts, etc. We'd need to find a way how users would run m365 setup in a non-interactive way though.

[martinlingstuyl]

So it seems, that the issue is caused by PowerShell treating anything logged to stderr (which is where the spinner goes) as an exception.

Interesting!
Though that does not occur in my local PowerShell 7.x sessions. It's only doing this within the context of Azure Function as far as I've currently seen.

As yo the solutions:

1. Feels more like a workaround. If you have a large script, it's not really feasible to have this on every line.

2. +1 on this.

3. Let me try if m365 cli config set --key errorOutput --value stdout works as well.

[waldekmastykarz]

1. Feels more like a workaround.

Yes and no. Like you said: it's Functions' PowerShell runtime that decides to treat stderr, which is a legitimate output stream for non-error messages, like exception. Ideally, that's something that should be configurable on Functions runtime. In this case we'd work around Functions runtime settings, rather than CLI using stderr to output messages. You'd have the same issue when you'd choose to run CLI in verbose or debug mode.

If you have a large script, it's not really feasible to have this on every line.

Correct. This is why we already offer the ability to redirect all output to stdout. This wouldn't be feasible for spinners though, because it would cause CLI output would become useless. So the only way really is to suppress spinners altogether.

[martinlingstuyl]

Yes and no. Like you said: it's Functions' PowerShell runtime that decides to treat stderr, which is a legitimate output stream for non-error messages, like exception. Ideally, that's something that should be configurable on Functions runtime. In this case we'd work around Functions runtime settings, rather than CLI using stderr to output messages. You'd have the same issue when you'd choose to run CLI in verbose or debug mode.

Ah, that sounds logical indeed, we're working around Functions' runtime settings.

Let me try if m365 cli config set --key errorOutput --value stdout works as well.

I tried this out btw, but it does not seem to have effect whatsoever. I still get the spinner errors.

[waldekmastykarz]

Right now, our setting doesn't affect spinner settings which still outputs to stderr and which is why you keep getting the error. While we could change the spinner to log to stdout as well, I don't think it would make sense.

Do you think it would make more sense to have a separate setting that controls the spinner or do we suppress it when we redirect stderr to stdout using the errorOutput setting?

[martinlingstuyl]

If the spinner is not affected there we should definitely add an extra configuration key. Something like showSpinner, default true. You may have a scenario where you don't want to redirect the output but still disable the spinner.

[waldekmastykarz]

Makes sense. Let's make that a config setting