Skip to content

Commit c8dc245

Browse files
committed
Adding Write-PnPTraceLog cmdlet
1 parent bdb5ab8 commit c8dc245

File tree

5 files changed

+231
-13
lines changed

5 files changed

+231
-13
lines changed

.vscode/launch.json

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,23 @@
3737
"program": "pwsh.exe"
3838
}
3939
},
40+
{
41+
"name": "Debug with local copy of PnP Framework",
42+
"type": "coreclr",
43+
"request": "launch",
44+
"preLaunchTask": "Build with local copy of PnP Framework",
45+
"args": [],
46+
"cwd": "${workspaceFolder}",
47+
"stopAtEntry": false,
48+
"console": "externalTerminal",
49+
"program": "pwsh",
50+
"osx": {
51+
"program": "pwsh",
52+
},
53+
"windows": {
54+
"program": "pwsh.exe"
55+
}
56+
},
4057
{
4158
"preLaunchTask": "Build with nugets",
4259
"name": ".NET Core Attach",

documentation/Write-PnPTraceLog.md

Lines changed: 152 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,152 @@
1+
---
2+
Module Name: PnP.PowerShell
3+
title: Write-PnPTraceLog
4+
schema: 2.0.0
5+
applicable: SharePoint Online
6+
external help file: PnP.PowerShell.dll-Help.xml
7+
online version: https://pnp.github.io/powershell/cmdlets/Write-PnPTraceLog.html
8+
---
9+
10+
# Write-PnPTraceLog
11+
12+
## SYNOPSIS
13+
Allows logging your own messages during the execution of PnP PowerShell cmdlets
14+
15+
## SYNTAX
16+
17+
### Log from file
18+
19+
```powershell
20+
Write-PnPTraceLog -Path <string> [-Verbose]
21+
```
22+
### Log from log stream
23+
24+
```powershell
25+
Write-PnPTraceLog [-Verbose]
26+
```
27+
28+
## DESCRIPTION
29+
This cmdlet allows logging of your own messages in line with the PnPTraceLog cmdlets that allow logging what happens behind the scenes of the execution of PnP PowerShell cmdlets. This allows you to inject your own custom logging along with the built in logging to get a complete and chronoligal log of the execution of the cmdlets in your scripts.
30+
31+
Look at [Start-PnPTraceLog](Start-PnPTraceLog.md) to see how to start logging to a file and/or to an in memory stream.
32+
You can use [Get-PnPTraceLog](Get-PnPTraceLog.md) to read from the log file or the in memory stream.
33+
34+
## EXAMPLES
35+
36+
### EXAMPLE 1
37+
```powershell
38+
Write-PnPTraceLog "Hello World"
39+
```
40+
41+
This logs the message "Hello World" as an informational message to the built in logging.
42+
43+
### EXAMPLE 2
44+
```powershell
45+
Write-PnPTraceLog "Hello World" -Level Warning
46+
```
47+
48+
This logs the message "Hello World" as an warning message to the built in logging.
49+
50+
### EXAMPLE 3
51+
```powershell
52+
Write-PnPTraceLog "Hello World" -Level Error -Source "MyScript"
53+
```
54+
55+
This logs the message "Hello World" as an error message to the built in logging with a source of "MyScript". The source is used to identify the cmdlet that was executed when the log was created. This is useful to identify which part of your script was executing when the log was created.
56+
57+
### EXAMPLE 4
58+
```powershell
59+
Write-PnPTraceLog "Hello World" -Level Debug -Source "MyScript" -CorrelationId "5a6206a0-6c83-4446-9d1b-38c14f93cb60" -EllapsedMilliseconds 1000
60+
```
61+
62+
This is the most complete example. It logs the message "Hello World" as a debug message to the built in logging with a source of "MyScript", a correlation id of "5a6206a0-6c83-4446-9d1b-38c14f93cb60" and an ellapsed time of 1000 milliseconds. The correlation id is used to identify the set of operations that were executed when the log was created. The ellapsed time is used to identify how long the operation took to complete. You can provide your own measurements to define this value. If you omit the ellapsed time, the cmdlet will try to define the execution time based on the last logged entry.
63+
64+
## PARAMETERS
65+
66+
### -CorrelationId
67+
An optional GUID as an unique identifier for the cmdlet execution. This is useful to identify which part of your script was executing when the log was created. If not provided, it will leave the value empty.
68+
69+
```yaml
70+
Type: Guid
71+
Parameter Sets: (All)
72+
73+
Required: False
74+
Position: Named
75+
Default value: None
76+
Accept pipeline input: False
77+
Accept wildcard characters: False
78+
```
79+
80+
### -EllapsedMilliseconds
81+
You can optionaly provide the ellapsed time in milliseconds. This is the time that was taken to execute the operation. If you omit this parameter, the cmdlet will try to define the execution time based on the last logged entry.
82+
83+
```yaml
84+
Type: Long
85+
Parameter Sets: (All)
86+
87+
Required: False
88+
Position: Named
89+
Default value: None
90+
Accept pipeline input: False
91+
Accept wildcard characters: False
92+
```
93+
94+
### -Level
95+
The level to log your message under. Options are: Verbose, Information, Warning, Error and Debug. It will log it both to the default PowerShell its logging equivallent such as Write-Warning, Write-Error, Write-Verbose, and to the PnPTraceLog logging. If not provided, it will default to Information.
96+
97+
```yaml
98+
Type: Framework.Diagnostics.LogLevel
99+
Parameter Sets: (All)
100+
101+
Required: False
102+
Position: Named
103+
Default value: Information
104+
Accept pipeline input: False
105+
Accept wildcard characters: False
106+
```
107+
108+
### -Message
109+
The message to log. This is the message that will be logged to the log file or the in memory stream.
110+
111+
```yaml
112+
Type: String
113+
Parameter Sets: (All)
114+
115+
Required: True
116+
Position: Named
117+
Default value: None
118+
Accept pipeline input: True
119+
Accept wildcard characters: False
120+
```
121+
122+
### -Source
123+
The source of the log. This is the source that will be logged to the log file or the in memory stream. This is useful to identify which part of your script was executing when the log was created.
124+
125+
```yaml
126+
Type: String
127+
Parameter Sets: (All)
128+
129+
Required: False
130+
Position: Named
131+
Default value: None
132+
Accept pipeline input: False
133+
Accept wildcard characters: False
134+
```
135+
136+
### -Verbose
137+
When provided, additional debug statements will be shown while executing the cmdlet.
138+
139+
```yaml
140+
Type: SwitchParameter
141+
Parameter Sets: (All)
142+
143+
Required: False
144+
Position: Named
145+
Default value: None
146+
Accept pipeline input: False
147+
Accept wildcard characters: False
148+
```
149+
150+
## RELATED LINKS
151+
152+
[Microsoft 365 Patterns and Practices](https://aka.ms/m365pnp)

src/Commands/Base/BasePSCmdlet.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@ public class BasePSCmdlet : PSCmdlet
1212
/// <summary>
1313
/// Generate a new correlation id for each cmdlet execution. This is used to correlate log entries in the PnP PowerShell log stream.
1414
/// </summary>
15-
internal Guid? CorrelationId { get; } = Guid.NewGuid();
15+
public virtual Guid? CorrelationId { get; protected set; } = Guid.NewGuid();
1616

1717
#region Cmdlet execution
1818

@@ -98,7 +98,7 @@ protected string ErrorActionSetting
9898
/// </summary>
9999
private void CheckForDeprecationAttributes()
100100
{
101-
if (MyInvocation.MyCommand.Name.ToLower() != MyInvocation.InvocationName.ToLower())
101+
if (!MyInvocation.MyCommand.Name.Equals(MyInvocation.InvocationName, StringComparison.CurrentCultureIgnoreCase))
102102
{
103103
var attribute = Attribute.GetCustomAttribute(GetType(), typeof(WriteAliasWarningAttribute));
104104
if (attribute != null)

src/Commands/Base/WriteTraceLog.cs

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
using System;
2+
using System.Management.Automation;
3+
4+
namespace PnP.PowerShell.Commands.Base
5+
{
6+
[Cmdlet(VerbsCommunications.Write, "PnPTraceLog")]
7+
[OutputType(typeof(void))]
8+
public class WriteTraceLog : BasePSCmdlet
9+
{
10+
[Parameter(Mandatory = true, Position = 0, ValueFromPipeline = true)]
11+
public string Message;
12+
13+
[Parameter(Mandatory = false)]
14+
public string Source;
15+
16+
[Parameter(Mandatory = false)]
17+
public long? EllapsedMilliseconds;
18+
19+
[Parameter(Mandatory = false)]
20+
public override Guid? CorrelationId { get; protected set; } = null;
21+
22+
[Parameter(Mandatory = false)]
23+
public Framework.Diagnostics.LogLevel Level = Framework.Diagnostics.LogLevel.Information;
24+
25+
protected override void ProcessRecord()
26+
{
27+
switch (Level)
28+
{
29+
case Framework.Diagnostics.LogLevel.Debug:
30+
Utilities.Logging.LoggingUtility.Debug(this, Message, Source, CorrelationId, EllapsedMilliseconds);
31+
break;
32+
case Framework.Diagnostics.LogLevel.Warning:
33+
Utilities.Logging.LoggingUtility.Warning(this, Message, Source, CorrelationId, EllapsedMilliseconds);
34+
break;
35+
case Framework.Diagnostics.LogLevel.Information:
36+
Utilities.Logging.LoggingUtility.Info(this, Message, Source, CorrelationId, EllapsedMilliseconds);
37+
break;
38+
case Framework.Diagnostics.LogLevel.Error:
39+
Utilities.Logging.LoggingUtility.Error(this, Message, Source, CorrelationId, EllapsedMilliseconds);
40+
break;
41+
}
42+
}
43+
}
44+
}

src/Commands/Utilities/Logging/LoggingUtility.cs

Lines changed: 16 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -28,9 +28,10 @@ internal static class LoggingUtility
2828
/// <param name="message">The message to log</param>
2929
/// <param name="source">The source from where is being logged. Leave NULL to have it use the cmdlet name automatically.</param>
3030
/// <param name="correlationId">The correlation of the cmdlet execution</param>
31-
public static void Debug(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null)
31+
/// <param name="ellapsedMilliseconds">The elapsed milliseconds since the last log entry. Leave NULL to try to calculate it automatically.</param>
32+
public static void Debug(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null, long? ellapsedMilliseconds = null)
3233
{
33-
Log.Debug(ComposeLogEntry(cmdlet, message, source, correlationId));
34+
Log.Debug(ComposeLogEntry(cmdlet, message, source, correlationId, ellapsedMilliseconds));
3435
cmdlet?.WriteVerbose(message);
3536
}
3637

@@ -41,9 +42,10 @@ public static void Debug(Cmdlet cmdlet, string message, string source = null, Gu
4142
/// <param name="message">The message to log</param>
4243
/// <param name="source">The source from where is being logged. Leave NULL to have it use the cmdlet name automatically.</param>
4344
/// <param name="correlationId">The correlation of the cmdlet execution</param>
44-
public static void Warning(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null)
45+
/// <param name="ellapsedMilliseconds">The elapsed milliseconds since the last log entry. Leave NULL to try to calculate it automatically.</param>
46+
public static void Warning(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null, long? ellapsedMilliseconds = null)
4547
{
46-
Log.Warning(ComposeLogEntry(cmdlet, message, source, correlationId));
48+
Log.Warning(ComposeLogEntry(cmdlet, message, source, correlationId, ellapsedMilliseconds));
4749
cmdlet?.WriteWarning(message);
4850
}
4951

@@ -54,9 +56,10 @@ public static void Warning(Cmdlet cmdlet, string message, string source = null,
5456
/// <param name="message">The message to log</param>
5557
/// <param name="source">The source from where is being logged. Leave NULL to have it use the cmdlet name automatically.</param>
5658
/// <param name="correlationId">The correlation of the cmdlet execution</param>
57-
public static void Info(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null)
59+
/// <param name="ellapsedMilliseconds">The elapsed milliseconds since the last log entry. Leave NULL to try to calculate it automatically.</param>
60+
public static void Info(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null, long? ellapsedMilliseconds = null)
5861
{
59-
Log.Info(ComposeLogEntry(cmdlet, message, source, correlationId));
62+
Log.Info(ComposeLogEntry(cmdlet, message, source, correlationId, ellapsedMilliseconds));
6063
cmdlet?.WriteInformation(new InformationRecord(message, DefineCmdletName(cmdlet)));
6164
}
6265

@@ -67,9 +70,10 @@ public static void Info(Cmdlet cmdlet, string message, string source = null, Gui
6770
/// <param name="message">The message to log</param>
6871
/// <param name="source">The source from where is being logged. Leave NULL to have it use the cmdlet name automatically.</param>
6972
/// <param name="correlationId">The correlation of the cmdlet execution</param>
70-
public static void Error(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null)
73+
/// <param name="ellapsedMilliseconds">The elapsed milliseconds since the last log entry. Leave NULL to try to calculate it automatically.</param>
74+
public static void Error(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null, long? ellapsedMilliseconds = null)
7175
{
72-
Log.Error(ComposeLogEntry(cmdlet, message, source, correlationId));
76+
Log.Error(ComposeLogEntry(cmdlet, message, source, correlationId, ellapsedMilliseconds));
7377
cmdlet?.WriteError(new ErrorRecord(new Exception(message), source, ErrorCategory.NotSpecified, null));
7478
}
7579

@@ -102,10 +106,11 @@ private static string DefineCmdletName(Cmdlet cmdlet)
102106
/// <param name="message">The message to log</param>
103107
/// <param name="source">The source from where is being logged. Leave NULL to have it use the cmdlet name automatically.</param>
104108
/// <param name="correlationId">The correlation of the cmdlet execution</param>
109+
/// <param name="ellapsedMilliseconds">The elapsed milliseconds since the last log entry. Leave NULL to try to calculate it automatically.</param>
105110
/// <returns></returns>
106-
private static LogEntry ComposeLogEntry(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null)
111+
private static LogEntry ComposeLogEntry(Cmdlet cmdlet, string message, string source = null, Guid? correlationId = null, long? ellapsedMilliseconds = null)
107112
{
108-
if (_lastCorrelationId != correlationId)
113+
if (_lastCorrelationId != correlationId && correlationId.HasValue)
109114
{
110115
// New cmdlet execution, reset the last log time
111116
_lastLogTime = null;
@@ -116,7 +121,7 @@ private static LogEntry ComposeLogEntry(Cmdlet cmdlet, string message, string so
116121
{
117122
Message = message,
118123
CorrelationId = correlationId ?? Guid.Empty,
119-
EllapsedMilliseconds = _lastLogTime.HasValue ? (long)DateTime.UtcNow.Subtract(_lastLogTime.Value).TotalMilliseconds : 0,
124+
EllapsedMilliseconds = ellapsedMilliseconds ?? (_lastLogTime.HasValue ? (long)DateTime.UtcNow.Subtract(_lastLogTime.Value).TotalMilliseconds : 0),
120125
Source = source ?? DefineCmdletName(cmdlet),
121126
ThreadId = Environment.CurrentManagedThreadId
122127
};

0 commit comments

Comments
 (0)