azure-functions-powershell-worker
azure-functions-powershell-worker copied to clipboard
Azure
Add `Write-AzFuncLog` cmdlet to the helper module to allow writing Azure Function user logs in an explicit way.
This is a feedback from the tech review within PowerShell team.
Currently PowerShell built-in Write-* cmdlets are redirected to the Azure Function log in the following mapping:
| Write-* cmdlet (the target stream) | Log level |
|---|---|
| Write-Verbose (verbose stream) | Trace |
| Write-Progress (progress stream) | Trace |
| Write-Debug (debug stream) | Debug |
| Write-Information (information stream) | Information |
| Write-Host (information stream) | Information |
| Write-Warning (warning stream) | Warning |
| Write-Error (error stream) | Error |
| Write-Output (output stream) | Information |
The log level Critical doesn't have a corresponding mapping, and for Verbose, Progress, Host, and Output, it's not obvious for users to tell what log levels they are mapped to.
So the feedback is to provide another cmdlet to allow writing Azure Function user logs in an explicit way.
The proposal is Write-AzFuncLog, with the following syntax:
Write-AzFuncLog [-Message] <string> [-Level] <string> [<CommonParameters>]
As for the implementation, probably it should just call Write-Information -Tag internally with the log level as the tag.
As for the implementation, probably it should just call
Write-Information -Taginternally with the log level as the tag
So for this cmdlet, we will not honor the Azure Functions log streams?
So for this cmdlet, we will not honor the Azure Functions log streams?
Today, we already handle information stream differently depending on the tag -- if the tag is __output__, then we prepend OUTPUT: to the message. Otherwise, we prepend INFORMATION:.
We can do similar things for Write-AzFuncLog, for example, Write-AzFuncLog blah -Level critical maps to Write-Information blah -Tag __critical__.
Downside of this implementation is that, user can write Write-Information -Tag __critical__ directly in script ... which would be annoying. But I think that's OK if they want to confuse themselves 😆
Well the downside to it as well is that, if they do:
Write-AzFuncLog blah -Level trace
It will show up in the logs as:
TRACE: blah
Regardless of the trace level you set in the host.json.
So if you set your host.json to exclude trace/Verbose level logs and just have information and error logs, these logs will still show up since you're always writing to the information stream.
No, you missed my points. We will have to change the even handler for the information stream. When the tag is __trace__, we don't write the message to the information level log, but to the trace level log. Same to other tags like __warning__ and etc.
Is there a reason for Write-Information -Tag __trace__ when we can do Write-Verbose under the hood?
as in...
Write-AzFuncLog blah -Level Trace
# just calls
Write-Verbose blah -Verbose
Ideally, that would be better. But we don't have an existing cmdlet mapping to Critical, so we still need to do something as I mention above.
Also, for Write-Verbose, we add Verbose: prefix to the message in the stream handler, which we don't want if the user is using Write-AzFuncLog -Level Trace. Same to the other existing cmdlets.
I see. That makes sense. I agree It would be nice to cover all of the Azure Functions log levels.
I guess my biggest question is... Do we know customers want this? Or will the normal write-* cmdlets suffice?
I remember @dfinke and a couple others mentioning that they want an environment variable to test for so that they can share code between an Azure Function and just running a script with pwsh.exe.
In that case, a Write-AzFuncLog wouldn't be too useful.
Our programming model today is very close (exception: Push-OutputBinding) to regular pwsh.exe.
We should discuss if we want to diverge from that, or keep to that.
I know you're not suggesting to remove Write-* but I remember @joeyaiello mentioning we should only be additive when requested 😊
Do we know customers want this? Or will the normal write-* cmdlets suffice?
This was brought up by Jim in the review dry run. There are two concerns:
- User cannot write
criticallevel log. - User has to do extra configuration to see
verbose/debugmessages written from the script, because, IIRC, theinformationand above levels are enabled by default.
For 1, I agree that critical level should be supported for completeness.
For 2, a proposal was: make all built-in write-* cmdlets write messages to the information level log, and using prefix like VERBOSE:, PROGRESS: to differentiate them, so all of them will be visible by default just like in pwsh. I think this option also makes sense, but not super sure we should change to that.
Sure, we should discuss with @joeyaiello before implementation.
Another one of those "Functions is different than PowerShell" issues 😄
For number 1 on your list, I think it would be better to fill that gap a different way with a Write-Critical cmdlet that does what the others do. That way it's consistent with what's already in PowerShell. I don't think it's really... critical... personally though. Hence the request for feedback.
Also for number 2... I think it's a shift in mindset from someone writing a script interactively vs creating an application and deploying it. We've been hitting this "PowerShell ecosystem doesn't fit perfectly in the application model" pain in a few places like the "module dependency" issue for example. This is another pain point.
Do you bombard someone with logs that can't really be filtered like any other Function App? Or do we tell our customers that they should follow the docs on configuring logging?
Hard to tell what the best way forward is... but I think feedback can help us answer it.
I don't think it's really... critical... personally though. Hence the request for feedback.
I think the critical concept in logging is determined by the business logic of a Function implementation. Maybe it's not an error in script running, but the state of something makes a critical log necessary.
For number 2, the way I'm thinking is that, when I'm using Write-Verbose -Verbose in my script, I don't necessarily mean to have my verbose message written to the trace level log. Instead, most of time, I just want to see them displayed to me truly as verbose messages. That's why I think that proposal also makes sense to me. But, for Write-Error, Write-Information, Write-Debug and Write-Warning, their names match the log level so well that it would be confusing if they don't really write to the corresponding logs. Hence, like I said, I'm not super sure about it.
Do you bombard someone with logs that can't really be filtered like any other Function App?
Haven't heard a user complaint yet, but we don't have much usage today anyways.
Per our discussion, we should talk to the Functions team about how critical is used in another languages.
/cc @asavaritayal @fabiocav
At the very least, just allow the option to expose the TelemetryClient as a powershell variable, then we can call it directly to write whatever custom logs we want, in addition to the existing "native" powershell stream interface by way of the iLogger
If telemetryclient is available then I can write critical there, and the community can write powershell functions for Write-Critical, or whatever, that leverage that interface, in addition to the wide variety of stuff I might want to do like track an Event in application insights, etc.
EDIT: For reference, the javascript worker exposes it as applicationInsights.defaultClient, so there is precedence for this sort of thing. https://docs.microsoft.com/en-us/azure/azure-monitor/app/api-custom-events-metrics#get-a-telemetryclient-instance
Workaround
Turns out the TelemetryClient works just fine inside the powershell worker:
using namespace Microsoft.ApplicationInsights
function Write-Critical ([String]$message) {
$tc = [TelemetryClient]::New($env:APPINSIGHTS_INSTRUMENTATIONKEY)
$tc.TrackTrace($message,4, $null)
}
Write-Critical 'My New Test Critical Message'
The only caveat I see so far is it doesn't support live metrics stream realistically as far as I can tell with limited testing, so exposing the defaultclient object is still a "good idea"
As far as the native integration, I agree that using Write-Information tags makes the most sense to keep it "Powershell-y"
If I do write information with a tag, it should add that to the prefix (e.g. INFORMATION-MYEXCEPTIONEXTRAINFO for write-information -tags MYEXCEPTIONEXTRAINFO), or use the logging scopes function of iLogger since that comes through to application insights per: https://github.com/microsoft/ApplicationInsights-dotnet-logging/pull/239/files
"Special" tags to allow certain functionality (like writing to critical, etc.) are OK, but again if people need that advanced functionality it's better to provide a way to expose the iLogger or telemetryClient directly for those "power users" (like me) to develop community functions that can be imported via powershell modules for these purposes, no need to burden the team with them.
What would be the best way to write custom properties to the log in order to query for them with Kusto? Now I have to strip the "INFORMATION" prefix from the message first:
traces
| where timestamp > ago(24h) | where message startswith "INFORMATION: " | extend props = parse_json(substring(message, 12)) | where props["prop1"] == "value1"
| order by timestamp desc
I use the following PowerShell:
$dictionary = New-Object 'System.Collections.Generic.Dictionary[String,String]'
$customProperties = @{ "prop1" = "value1" }
$customProperties | ForEach-Object { $dictionary.Add($_, $customProperties.Item($_)) }
$dictionary.Add("InvocationId", $TriggerMetadata.InvocationId)
$config = [Microsoft.ApplicationInsights.Extensibility.TelemetryConfiguration]::Active
$client = [Microsoft.ApplicationInsights.TelemetryClient]::new($config)
$client.TrackTrace("Request body", $dictionary)
Write-Information -MessageData ($dictionary | ConvertTo-Json) -InformationAction Continue
Unfortunately the TrackTrace invocation does not get correlated with the actual request as @justingrote already confirmed. For now I believe the only way to find the related OperationId is through the InvocationId as per https://github.com/Azure/azure-functions-host/issues/5014
@cveld Pretty much what you did (use your own telemetry client) was going to be my suggestion.