Repository navigation
Powershell 6.0.0-1.debian.9 logging to /var/log/syslog is too verbose... #6032
Description
Activity
Dan Travison (@dantraMSFT) what is the default logging level supposed to be?
Thank you for looking into this, wanted to say that this behavior persists in 6.0.1-1.debian.9. I see a pending pull request related to this but thought I'd let you know anyway.
Informational is the default logging level but I'll dig into it; perhaps I have a filtering problem or new log items have been added.
I suggest using
/var/log/powershell/{debug.log,information.log,warning.log,error.log}respectively, instead of/var/log/syslog, with the exception of errors which can be sent to both their own log and/var/log/syslog.I currently have a single 98 line powershell script running on a server right now that generates 32 lines a minute to
/var/log/syslog... each line is then read, parsed and filtered, sent over the network, parsed again, tagged, sorted, stored... and then retrieved and filtered out repeatedly forever after.I've got a consistent repro; analytic events are not being filtered.
This appears to be a regression of #5791.Dan Travison (@dantraMSFT) This should be related to this if block added in #5791.
The script block execution logging uses
PSKeyword.UseAlwaysAnalytic, and the default keyword filter caused those loggings to be filtered out even if the script block logging was enabled.The
UseAlwaysAnalyticevent is able to be written into ETW on Windows (see the code here). So, that change was made to work around the default keyword filtering on Unix. Looking back at that change, it's not well thought through as it basically cancels the default keyword filtering.I think the root problems are:
- what level of parity should the logging on Unix has compared with on Windows? For example, an event with the keyword
UseAlwaysAnalyticcan be written to ETW by default. Does that make sense? Should the logging on Unix be able to do that by default as well? - we need to review the code that issues events. Are they using the correct keyword and channel? For example, I see calls like
PSEtwLog.LogOperationalVerbose(..., PSKeyword.UseAlwaysAnalytic, ...)where operational channel is used but the pass-in keyword is "PSKeyword.UseAlwaysAnalytic".
- what level of parity should the logging on Unix has compared with on Windows? For example, an event with the keyword
The windows implementation is based on a misunderstanding of how channels and keywords are used. Under the hood, channels and keywords are simply bits in a larger bit set and enabling/disabling a given bit does not cause the event to be written. What causes it to be written is one or more listeners that have compatible bit set for the given event. If no listeners have requested events with the analytic bit set, they are dropped on the floor.
Normally, this is handled completely transparently to the component raising the events, the underlying event descriptor indicates what keywords are defined for each event and has a bit set for the target channel.
Problems occur when attempting to customize this behavior. In this case, stripping the analytic bit from all events mean all analytic events get logged.
As far as #2 above, that code really doesn't make sense from an ETW standpoint. Events are expected to target a single channel, not changed on the fly and in your example, under the hood it is targeting multiple channels since both operational and analytic are marked (one via LogOperationAlVerbose and a second via PSKeyword.UseAlwaysAnalytic).
An alternative solution would be to log 'required' script block events to operational (perhaps as warning) and leave the remaining marked as analytic and don't attempt to mix and match keywords and channels on the fly; it usually ends up causing unexpected results.
I've reopened #5695 and will revisit the script block events for an alternative approach.
the underlying event descriptor indicates what keywords are defined for each event
Does this mean the caller shouldn't specify a keyword when writing an ETW event?
On windows, the only thing the caller 'should' be providing is the event id and payload. All other values, including keywords, channel, opcode, task and level are embedded in the event descriptor. It's not clear to me why the original PowerShell code base decided to also pass these values as explicit parameters. At best, it's passing redundant values, at worse, the events that are logged do not always match the definition in the manifest.
PowerShell usually gets away with it more as a side-effect of how consuming code usually decodes events but it also means cases where precise queries are needed may not return the complete results since the logged events do not match the events declared in the manifest. However, if the consuming code uses the manifest as the authority, events may be presented incorrectly. For example, if the manifest indicates an event has an Informational level but the event was logged as Error level, the event would be presented as Informational.
If we end up doing the work to decouple PowerShell's logging from ETW, this will have to be refactored out of the callers and will like require an updated, and simpler, ETW manifest when used on Windows.
Dan Travison (@dantraMSFT) Thanks for the clarification! I like the idea that all events are defined in the manifest and the caller just provides event id and payload to write an event. But would this also work for syslog and apple log (no manifest on Unix platforms)?
This would work on Linux and MacOS; in fact, the manifest is currently being used to generate the resx file containing the event messages that are logged to syslog/os_log. Take a look at tools\ResxGen\Resxgen.psm1. It currently extracts this information from the manifest in anticipation of changes to our logging.
For example, it's straight forward to use this to generate a C# class like mc.exe does then insert the platform specific 'logger' interface underneath it.
Bradd (@k1rb): This should now be fixed with PR #6086
Reacted by Bradd
Hi there,
Opening
/usr/bin/pwsh, typing in"hello world."and pressing enter yields 43 (+4 on exit) events to /var/log/syslog. This isn't the case with all of my servers but it is for all of my servers runningPowershell 6.0.0-1.debian.9.Here is the first log generated, as an example:
17 lines later it's telling me that the console is ready for use:
And then finally, 47 lines later it's done with:
As you can imagine, running even a simple script would cause flooding of syslog and then worse for log servers downstream.
Is this "normal" now, is there a way to disable this behavior or at least redirect logging to another source, for instance to one that isn't sent off for parsing by log servers?
Thanks!