Skip to content

Fix filtering of analytic events on Unix platforms. #6086

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
daxian-dbw merged 4 commits into from
Feb 2, 2018
Merged

Fix filtering of analytic events on Unix platforms. #6086

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
de681d3
Remove operational and analytic from keywords
dantraMSFT Jan 31, 2018
dd7c46f
Fix PSChannel on Linux to use a bitmask
Feb 1, 2018
7f6c89b
Update PSChannel comment
Feb 1, 2018
15bb676
Address PR feedback.
Feb 1, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 2 additions & 7 deletions src/System.Management.Automation/engine/PSConfiguration.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -247,8 +247,6 @@ internal PSLevel GetLogLevel()
/// </summary>
const string LogDefaultValue = "default";

const PSChannel DefaultChannels = PSChannel.Operational;

/// <summary>
/// Gets the bitmask of the PSChannel values to log.
/// </summary>
Expand Down Expand Up @@ -282,15 +280,12 @@ internal PSChannel GetLogChannels()

if (result == 0)
{
result = DefaultChannels;
result = System.Management.Automation.Tracing.PSSysLogProvider.DefaultChannels;
}

return result;
}

// by default, do not include analytic events.
const PSKeyword DefaultKeywords = (PSKeyword) (0xFFFFFFFFFFFFFFFF & ~(ulong)PSKeyword.UseAlwaysAnalytic);

/// <summary>
/// Gets the bitmask of keywords to log.
/// </summary>
Expand Down Expand Up @@ -324,7 +319,7 @@ internal PSKeyword GetLogKeywords()

if (result == 0)
{
result = DefaultKeywords;
result = System.Management.Automation.Tracing.PSSysLogProvider.DefaultKeywords;
}

return result;
Expand Down
14 changes: 14 additions & 0 deletions src/System.Management.Automation/engine/remoting/common/PSETWTracer.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -195,12 +195,26 @@ internal enum PSEventId : int
/// <summary>
/// Defines enumerations for channels
/// </summary>
/// <remarks>
/// On Windows, PSChannel is the numeric channel id value.
/// On Non-Windows, PSChannel is used to filter events and
/// the underlying channel bitmask values are used instead.
/// The bit values are the same as used on Windows.
/// </remarks>
#if UNIX
[Flags]
Copy link
Member

@daxian-dbw daxian-dbw Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The enum is actually not a flags enum on Windows ...

Copy link
Contributor Author

@dantraMSFT dantraMSFT Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

internal enum PSChannel : byte
{
Operational = 0x80,
Analytic = 0x40
}
#else
internal enum PSChannel : byte
{
Operational = 0x10,
Analytic = 0x11
}
#endif

/// <summary>
/// Defines enumerations for tasks
Expand Down
14 changes: 7 additions & 7 deletions src/System.Management.Automation/engine/runtime/CompiledScriptBlock.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1321,7 +1321,7 @@ private static bool WriteScriptBlockToLog(ScriptBlock scriptBlock, int segment,
// they can just wait on the compromised box and see the sensitive data eventually anyways.

string errorMessage = StringUtil.Format(SecuritySupportStrings.CouldNotEncryptContent, textToLog, error.ToString());
PSEtwLog.LogOperationalError(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysAnalytic,
PSEtwLog.LogOperationalError(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysOperational,
0, 0, errorMessage, scriptBlock.Id.ToString(), scriptBlock.File ?? String.Empty);
}
else
Expand All @@ -1334,12 +1334,12 @@ private static bool WriteScriptBlockToLog(ScriptBlock scriptBlock, int segment,

if (scriptBlock._scriptBlockData.HasSuspiciousContent)
{
PSEtwLog.LogOperationalWarning(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysAnalytic,
PSEtwLog.LogOperationalWarning(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysOperational,
segment + 1, segments, textToLog, scriptBlock.Id.ToString(), scriptBlock.File ?? String.Empty);
}
else
{
PSEtwLog.LogOperationalVerbose(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysAnalytic,
PSEtwLog.LogOperationalVerbose(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysOperational,
Copy link
Member

@daxian-dbw daxian-dbw Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are 4 more instances of LogOperationalXX(..., PSKeyword.UseAlwaysAnalytic) in CompiledScriptBlock.cs. They are:

Can you please correct them all?

Copy link
Contributor Author

@dantraMSFT dantraMSFT Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

Copy link
Contributor

@PaulHigin PaulHigin Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Script block logging moves from Analytic to Operational, which is different from Windows PowerShell. Is this considered a breaking change that needs to be communicated to Windows platform users?

Copy link
Member

@daxian-dbw daxian-dbw Feb 1, 2018 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The methods PSEtwLog.LogOperationalXXX are actually writing events into the operational channel on Windows ETW, and the keywords PSKeyword.UseAlwaysAnalytic and PSKeyword.UseAlwaysOperational are actually ignored in PSETWLogProvider.WriteEvent. So this is not a breaking change on Windows.

That piece of code is weird. I don't understand why those two keywords are simply ignored on Windows. Maybe it's just a misunderstanding when implementing PSETWLogProvider. @dantraMSFT may have more insight.

Copy link
Contributor

@PaulHigin PaulHigin Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That does look weird ... how do we know it defaults to operational? It would be good to add a comment in the code, if we understand why.

Copy link
Member

@daxian-dbw daxian-dbw Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It does not default to operational. The passed-in argument for PSChannel channel is PSChannel.Operational from PSEtwLog.LogOperationalXXX methods.

segment + 1, segments, textToLog, scriptBlock.Id.ToString(), scriptBlock.File ?? String.Empty);
}

Expand Down Expand Up @@ -1405,7 +1405,7 @@ private static bool GetAndValidateEncryptionRecipients(ScriptBlock scriptBlock,
// attacker seeing potentially sensitive data. Because if they aren't detected, then
// they can just wait on the compromised box and see the sensitive data eventually anyways.
string errorMessage = StringUtil.Format(SecuritySupportStrings.CouldNotUseCertificate, error.ToString());
PSEtwLog.LogOperationalError(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysAnalytic,
PSEtwLog.LogOperationalError(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysOperational,
0, 0, errorMessage, scriptBlock.Id.ToString(), scriptBlock.File ?? String.Empty);

return true;
Expand All @@ -1430,7 +1430,7 @@ private static bool GetAndValidateEncryptionRecipients(ScriptBlock scriptBlock,
}

string errorMessage = StringUtil.Format(SecuritySupportStrings.CertificateContainsPrivateKey, certificateForLog);
PSEtwLog.LogOperationalError(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysAnalytic,
PSEtwLog.LogOperationalError(PSEventId.ScriptBlock_Compile_Detail, PSOpcode.Create, PSTask.ExecuteCommand, PSKeyword.UseAlwaysOperational,
0, 0, errorMessage, scriptBlock.Id.ToString(), scriptBlock.File ?? String.Empty);
}
}
Expand Down Expand Up @@ -1794,7 +1794,7 @@ internal static void LogScriptBlockStart(ScriptBlock scriptBlock, Guid runspaceI

if (GetScriptBlockLoggingSetting()?.EnableScriptBlockInvocationLogging == true)
{
PSEtwLog.LogOperationalVerbose(PSEventId.ScriptBlock_Invoke_Start_Detail, PSOpcode.Create, PSTask.CommandStart, PSKeyword.UseAlwaysAnalytic,
PSEtwLog.LogOperationalVerbose(PSEventId.ScriptBlock_Invoke_Start_Detail, PSOpcode.Create, PSTask.CommandStart, PSKeyword.UseAlwaysOperational,
scriptBlock.Id.ToString(), runspaceId.ToString());
}
}
Expand All @@ -1803,7 +1803,7 @@ internal static void LogScriptBlockEnd(ScriptBlock scriptBlock, Guid runspaceId)
{
if (GetScriptBlockLoggingSetting()?.EnableScriptBlockInvocationLogging == true)
{
PSEtwLog.LogOperationalVerbose(PSEventId.ScriptBlock_Invoke_Complete_Detail, PSOpcode.Create, PSTask.CommandStop, PSKeyword.UseAlwaysAnalytic,
PSEtwLog.LogOperationalVerbose(PSEventId.ScriptBlock_Invoke_Complete_Detail, PSOpcode.Create, PSTask.CommandStop, PSKeyword.UseAlwaysOperational,
scriptBlock.Id.ToString(), runspaceId.ToString());
}
}
Expand Down
7 changes: 5 additions & 2 deletions src/System.Management.Automation/utils/tracing/PSSysLogProvider.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,8 +17,11 @@ internal class PSSysLogProvider : LogProvider
{
private static SysLogProvider s_provider;

// by default, do not include analytic events
internal const PSKeyword DefaultKeywords = (PSKeyword) (0xFFFFFFFFFFFFFFFF & ~(ulong)PSKeyword.UseAlwaysAnalytic);
// by default, do not include channel bits
internal const PSKeyword DefaultKeywords = (PSKeyword) (0x00FFFFFFFFFFFFFF);
Copy link
Member

@daxian-dbw daxian-dbw Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The default keyword should be 0x0FFFFFFFFFFFFFFF. The diff bit for UseAlwaysOperational and UseAlwaysAnalytic is only in the first 4 bits.

UseAlwaysOperational = 0x8000000000000000,
UseAlwaysAnalytic    = 0x4000000000000000,

Copy link
Contributor Author

@dantraMSFT dantraMSFT Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's as intended; channel bits use the high order byte.

Copy link
Member

@daxian-dbw daxian-dbw Feb 1, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Got it. Closed.


// the default enabled channel(s)
internal const PSChannel DefaultChannels = PSChannel.Operational;

/// <summary>
/// Class constructor.
Expand Down
15 changes: 8 additions & 7 deletions src/System.Management.Automation/utils/tracing/SysLogProvider.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -102,6 +102,14 @@ public SysLogProvider(string applicationId, PSLevel level, PSKeyword keywords, P
_keywordFilter = (ulong)keywords;
_levelFilter = (byte) level;
_channelFilter = (byte) channels;
if ((_channelFilter & (ulong) PSChannel.Operational) != 0)
{
_keywordFilter |= (ulong) PSKeyword.UseAlwaysOperational;
}
if ((_channelFilter & (ulong) PSChannel.Analytic) != 0)
{
_keywordFilter |= (ulong) PSKeyword.UseAlwaysAnalytic;
}
}

/// <summary>
Expand Down Expand Up @@ -313,13 +321,6 @@ public void SetActivity(Guid activity)
/// <param name="args">The payload for the log message.</param>
public void Log(PSEventId eventId, PSChannel channel, PSTask task, PSOpcode opcode, PSLevel level, PSKeyword keyword, params object[] args)
{
if (keyword == PSKeyword.UseAlwaysAnalytic)
{
// Use the 'DefaultKeywords' to work around the default keyword filter.
// Note that the PSKeyword argument is not really used in writing SysLog.
keyword = PSSysLogProvider.DefaultKeywords;
}

if (ShouldLog(level, keyword, channel))
{
int threadId = Thread.CurrentThread.ManagedThreadId;
Expand Down