diff --git a/README.md b/README.md index 94be064..9766267 100644 --- a/README.md +++ b/README.md @@ -97,6 +97,23 @@ Get-Command -Module containers-toolkit Install-Containerd -Version "1.7.7" -InstallPath 'C:\Test\Path\Containerd' ``` +### Logging + +The module uses a static logger designed for use across module files within the **Containers Toolkit**. It supports configurable log levels, console output, optional log file writing, and integration with the **Windows Event Log**. +The logger supports the following log levels: + +- `DEBUG` +- `INFO` +- `WARNING` +- `ERROR` +- `FATAL` + +For more details on the logger, please refer to the [Logger documentation](./docs/LOGGER.md). + +#### Logging Environment Variables + +See [Logger documentation](./docs/LOGGER.md#environment-variables) for more details on the environment variables used to control logging. + ## Important Notes 1. Requires elevated PowerShell to run some commands. diff --git a/containers-toolkit/Private/logger.psm1 b/containers-toolkit/Private/logger.psm1 new file mode 100644 index 0000000..5dc2603 --- /dev/null +++ b/containers-toolkit/Private/logger.psm1 @@ -0,0 +1,263 @@ +class Logger { + static [string] $EventSource = "Containers-Toolkit" + static [string] $EventLogName = "Application" + static [hashtable] $LogLevelRank = @{ + "DEBUG" = 1 + "INFO" = 2 + "WARNING" = 3 + "ERROR" = 4 + "FATAL" = 5 + } + + # Set minimum log level from environment variable: CTK_LOG_LEVEL or DebugPreference + static [string] GetMinLevel() { + try { + $DebugPref = Get-Variable -Name DebugPreference -Scope Global -ValueOnly + if ($DebugPref -ne "SilentlyContinue") { + return "DEBUG" + } + elseif ($env:CTK_LOG_LEVEL) { + return $env:CTK_LOG_LEVEL.ToUpper() + } + else { + return "INFO" + } + } + catch { + return "INFO" + } + } + + # Set log file path from environment variable: CTK_LOG_FILE + static [string] GetLogFile() { + try { + $fileName = $env:CTK_LOG_FILE + } + catch { + $fileName = $null + } + return $fileName + } + + # Set quiet mode from environment variable: SKIP_CTK_LOGGING + # User-defined environment variable to skip logging. Equivalent to --quiet. + # If set, only DEBUG messages are logged to the terminal. + # If not set, all messages are logged to the terminal and to the event log. + static [bool] GetQuiet() { + $defaultQuiet = $false + try { + $quietValue = $env:SKIP_CTK_LOGGING + if ($quietValue) { return [bool]::Parse($quietValue) } + } + catch { + # return defaultQuiet + } + return $defaultQuiet + } + + # Set format log from environment variable: CTK_FORMAT_LOG + # Use to determine if the logs displayed in the terminal should be formatted. + # If set to true, the logs will be formatted. If not set, the logs will not be formatted. + static [bool] ShouldFormat() { + $defaultFormat = $false + try { + $formatValue = $env:CTK_FORMAT_LOG + if ($formatValue) { return [bool]::Parse($formatValue) } + } + catch { + # return defaultFormat + } + + return $defaultFormat + } + + # Check if the log level is greater than or equal to the minimum log level + static [bool] ShouldLog([string] $Level) { + return [Logger]::LogLevelRank[$Level.ToUpper()] -ge [Logger]::LogLevelRank[[Logger]::GetMinLevel()] + } + + # Format the message for logging + static [string] FormatMessage([object] $message) { + if ($null -eq $message) { + return "[null]" + } + + if ($message -is [string]) { + return $message + } + + try { + return $message | ConvertTo-Json -Depth 5 -Compress + } + catch { + return $message.ToString() + # $Message = $Message | Out-String + } + } + + # Retrieve the function in the call stack that triggered the log + static [pscustomobject] GetCallerFunction($CallStack) { + $i = 3 + $CallerFunction = $CallStack[$i] + + while ((-not $CallerFunction.Command) -and ($i -lt $CallStack.Count - 1)) { + $i++ + $CallerFunction = $CallStack[$i] + } + + return $CallerFunction + } + + # Generate a parsed log message from the log level and message + static [string] GetLogMessage([string] $Level, [string] $Message) { + $CallStack = Get-PSCallStack + $Caller = [Logger]::GetCallerFunction($CallStack) + + $timestamp = (Get-Date).ToUniversalTime().ToString("yyyy-MM-ddTHH:mm:ss.fffffffK") + $cmd = $Caller.InvocationInfo.MyCommand + $line = $Caller.ScriptLineNumber + + # Add padding to the message based on the difference between the longest level name and the current level + $padding = ([Logger]::LogLevelRank.Keys | Measure-Object -Maximum Length).Maximum - $Level.Length + + return "$($Level.ToUpper()):$(" " * $padding)[$timestamp] [${cmd}:${line}]: $Message" + } + + # Write log messages to the Windows Event Log + static [void] WriteToEventLog([string] $Level, [string] $Message) { + # Create the event log source if it doesn't exist + if (-not [System.Diagnostics.EventLog]::SourceExists($([Logger]::EventLogName))) { + Write-Debug "Creating event log source: { LogName: $([Logger]::EventLogName), Source: $([Logger]::EventSource) }" + New-EventLog -LogName $([Logger]::EventLogName) -Source $([Logger]::EventSource) + } + + $entryType = switch ($Level) { + "INFO" { [System.Diagnostics.EventLogEntryType]::Information } + "WARNING" { [System.Diagnostics.EventLogEntryType]::Warning } + "ERROR" { [System.Diagnostics.EventLogEntryType]::Error } + "FATAL" { [System.Diagnostics.EventLogEntryType]::Error } + default { throw [System.NotImplementedException]("Invalid log level: $Level") } + } + + $eventId = switch ($Level) { + "INFO" { 1000 } + "WARNING" { 4000 } + "ERROR" { 5000 } + "FATAL" { 6000 } + default { throw [System.NotImplementedException]("Invalid log level: $Level") } + } + + try { + Write-EventLog -LogName $([Logger]::EventLogName) ` + -Source $([Logger]::EventSource) ` + -EntryType $entryType ` + -EventId $eventId ` + -Message $Message + } + catch { + # Fallback: write warning but continue + Write-Warning "Failed to write to event log: $_" + } + } + + # Write log messages to a file + static [void] WriteToFile([string] $Message) { + $LogFilePath = [Logger]::GetLogFile() + if (-not $LogFilePath) { + return + } + + try { + Add-Content -Path $LogFilePath -Value $Message + } + catch { + Write-Warning "Failed to write to log file: $_" + } + } + + # Write log messages to the console + static [void] WriteToConsole([string] $Level, [string] $Message, [string] $parsedMessage) { + if ([Logger]::ShouldFormat()) { + switch ($Level) { + "FATAL" { + [Console]::Error.WriteLine($parsedMessage) + Write-Error "FATAL: $message" -ErrorAction Stop + } + "ERROR" { + # HACK: We still use Write-Error for users who may need to access the error using $Error or Get-Error. + # This is a workaround because we want to use a custom log format. + # Write-Error prefixes the message with "Write-Error" which is not neat and consistent with other log levels. + # SilentlyContinue is used to avoid writing to the console. + Write-Error $message -ErrorAction SilentlyContinue + [Console]::Error.WriteLine($parsedMessage) + } + default { [Console]::WriteLine($parsedMessage) } + } + return + } + + # Write unformatted messages to the console + switch ($Level) { + "FATAL" { + # `-ErrorAction Stop` to make it a terminating error + # This will stop the script execution and throw an exception, + # even when a command is called with -ErrorAction SilentlyContinue. + # Needs to be handled by the caller with a try-catch block. + Write-Error "FATAL: $message" -ErrorAction Stop + } + "ERROR" { + Write-Error $message -ErrorAction Continue + } + "WARNING" { + Write-Warning $message + } + "INFO" { + Write-Information $message -InformationAction Continue + } + "DEBUG" { + Write-Debug $message + } + } + } + + # Write log messages to the console and/or event log (or file) + # This is the main logging function that handles all log levels + static [void] Write([string] $Level, [object] $Message) { + $Level = $Level.ToUpper() + + # Minimum log level filtering: Only log messages that are at least as severe as the minimum level + if (-not [Logger]::ShouldLog($Level)) { + return + } + + # Convert the message to a string + $formatedMessage = [Logger]::FormatMessage($message) + + # Generate the log message + $parsedMessage = [Logger]::GetLogMessage($Level, $formatedMessage) + + # Default: Log to event log (non-DEBUG messages) + if ($Level -ne "DEBUG") { + [Logger]::WriteToEventLog($Level, $parsedMessage) + } + + # Log to file if CTK_LOG_FILE is set + [Logger]::WriteToFile($parsedMessage) + + # If true, only DEBUG messages are logged to the terminal + # else, all messages are logged to the terminal and to the event log. + if ([Logger]::GetQuiet() -and $Level -ne "DEBUG") { + return + } + + # Console output + [Logger]::WriteToConsole($Level, $formatedMessage, $parsedMessage) + } + + static [void] Fatal([object] $Message) { [Logger]::Write("FATAL", $Message) } + static [void] Error([object] $Message) { [Logger]::Write("ERROR", $Message) } + static [void] Warning([object] $Message) { [Logger]::Write("WARNING", $Message) } + static [void] Info([object] $Message) { [Logger]::Write("INFO", $Message) } + static [void] Debug([object] $Message) { [Logger]::Write("DEBUG", $Message) } + static [void] Log([string] $Level = "INFO", [string] $Message) { [Logger]::Write($Level, $Message) } +} diff --git a/containers-toolkit/containers-toolkit.psd1 b/containers-toolkit/containers-toolkit.psd1 index b6ded73..0177683 100644 --- a/containers-toolkit/containers-toolkit.psd1 +++ b/containers-toolkit/containers-toolkit.psd1 @@ -68,6 +68,7 @@ Note that the HostNetworkingService module is available only when the Hyper-V Wi # Modules to import as nested modules of the module specified in RootModule/ModuleToProcess NestedModules = @( 'Private\CommonToolUtilities.psm1', + 'Private\Logger.psm1', 'Private\UpdateEnvironmentPath.psm1', 'Public\AllToolsUtilities.psm1', 'Public\BuildkitTools.psm1', @@ -124,6 +125,7 @@ Note that the HostNetworkingService module is available only when the Hyper-V Wi # List of all files packaged with this module FileList = @( './Private/CommonToolUtilities.psm1', + './Private/Logger.psm1', './Private/UpdateEnvironmentPath.psm1', './Public/AllToolsUtilities.psm1', './Public/BuildkitTools.psm1', diff --git a/docs/LOGGER.md b/docs/LOGGER.md new file mode 100644 index 0000000..b29d8e9 --- /dev/null +++ b/docs/LOGGER.md @@ -0,0 +1,93 @@ +# Containers Toolkit Logger + +A static PowerShell logger designed for use across module files within the **Containers Toolkit**. It supports configurable log levels, console output, optional log file writing, and integration with the **Windows Event Log**. + +## Key Features + +- Supports multiple log levels: `DEBUG`, `INFO`, `WARNING`, `ERROR`, `FATAL`. +- Logs messages to the **console**, **optional log file**, and the **Windows Event Log** (for applicable levels). +- Minimum log level is determined dynamically from the `CTK_LOG_LEVEL` environment variable or PowerShell’s `$DebugPreference`. +- Allows suppressing console output using the SKIP_CTK_LOGGING environment variable — similar to running in a quiet mode. + +## Debug Logging Behavior + +- `DEBUG` messages are only shown in the console if: + + - `$DebugPreference` is not `"SilentlyContinue"`, **or** + - the environment variable `CTK_LOG_LEVEL` is set to `"DEBUG"`. +- `DEBUG` messages are **not** written to the Windows Event Log. + +## Usage + +To use the logger, you need to import the module (if it is not already imported). + +```PowerShell +using using module "..\Private\logger.psm1" +``` + +### Log Levels + +The logger supports the following log levels: + +#### Info level + +```PowerShell +[Logger]::Log("This is a test message") # Defaults to INFO level +[Logger]::Log("This is a test message", "INFO") +[Logger]::Info("This is a test message") + +INFO: [2025-05-20T08:23:12Z] [Install-Nerdctl:42]: "This is a test message" +``` + +#### Debug level + +To enable `DEBUG` level logging, set the environment variable `CTK_LOG_LEVEL` to `"DEBUG"` or ensure `$DebugPreference` is not set to `"SilentlyContinue"`. + +```PowerShell +[Logger]::Log("This is a test message", "DEBUG") +[Logger]::Debug("This is a test message") + +DEBUG: [2025-05-20T08:23:12Z] [Install-Nerdctl:42]: "This is a test message" +``` + +#### Warning level + +```PowerShell +[Logger]::Log("This is a test message", "WARNING") +[Logger]::Warning("This is a test message") + +WARNING: [2025-05-20T08:23:12Z] [Install-Nerdctl:42]: "This is a test message" +``` + +#### Error level + +```PowerShell +[Logger]::Log("This is a test message", "ERROR") +[Logger]::Error("This is a test message") + +ERROR: [2025-05-20T08:23:12Z] [Install-Nerdctl:42]: "This is a test message" +``` + +#### Fatal level + +Throws a terminating error. + +```PowerShell +[Logger]::Log("This is a test message", "FATAL") +[Logger]::Fatal("This is a test message") + + +FATAL: [2025-05-20T08:23:12Z] [Install-Nerdctl:42]: "This is a test message" +Exception: Uncaught Critical message +``` + +## Environment Variables + +The logger uses the following environment variables to configure its behavior: + +| Variable | Type | Description | +| ---------------------- | ------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `CTK_LOG_LEVEL` | String | Sets the minimum log level. Accepted values are: `DEBUG`, `INFO`, `WARNING`, `ERROR`, and `FATAL`.
Defaults to `INFO` if not set. | +| `CTK_LOG_FILE` | String | Path to a file where logs should be written. If not set, logs will be written to the console and Windows Event Log (for applicable levels).
**Note:** The logger does not handle log file rotation or cleanup — use external tooling for that. | +| `SKIP_CTK_LOGGING` | Boolean | If set to `"true"`, suppresses console output for all log levels except `DEBUG` (when `$DebugPreference` is not `"SilentlyContinue"`).
Logging to file (if set) and to the Windows Event Log (excluding `DEBUG`) still occurs. | +| `CTK_FORMAT_LOG` | Boolean | If set to `"true"`, formats the log message with a timestamp and the calling function name. This is useful for debugging and tracking the source of log messages. |