Merge pull request #980 from dcabib/fix/log-sampling-random-generation-951

fix(logging): Fix sampling when log level is above Debug

Author: hjgraca

docs/core/logging.md

@@ -778,12 +778,16 @@ custom keys can be persisted across invocations. If you want all custom keys to
 
 ## Sampling debug logs
 
-You can dynamically set a percentage of your logs to **DEBUG** level via env var `POWERTOOLS_LOGGER_SAMPLE_RATE` or
-via `SamplingRate` parameter on attribute.
+Use sampling when you want to dynamically change your log level to **DEBUG** based on a **percentage of the Lambda function invocations**.
 
-!!! info
-    Configuration on environment variable is given precedence over sampling rate configuration on attribute, provided it's
-    in valid value range.
+You can use values ranging from `0.0` to `1` (100%) when setting `POWERTOOLS_LOGGER_SAMPLE_RATE` env var, or `SamplingRate` parameter in Logger.
+
+???+ tip "Tip: When is this useful?"
+    Log sampling allows you to capture debug information for a fraction of your requests, helping you diagnose rare or intermittent issues without increasing the overall verbosity of your logs.
+
+    Example: Imagine an e-commerce checkout process where you want to understand rare payment gateway errors. With 10% sampling, you'll log detailed information for a small subset of transactions, making troubleshooting easier without generating excessive logs.
+
+The sampling decision happens automatically with each invocation when using `Logger` decorator.  When not using the decorator, you're in charge of refreshing it via `RefreshSampleRateCalculation` method. Skipping both may lead to unexpected sampling results.
 
 === "Sampling via attribute parameter"
 
@@ -802,6 +806,30 @@ via `SamplingRate` parameter on attribute.
     }
     ```
 
+=== "Sampling Logger.Configure"
+
+    ```c# hl_lines="5-10 16"
+    public class Function
+    {
+        public Function()
+        {
+            Logger.Configure(options =>
+            {
+                options.MinimumLogLevel = LogLevel.Information;
+                options.LoggerOutputCase = LoggerOutputCase.CamelCase;
+                options.SamplingRate = 0.1; // 10% sampling
+            });
+        }
+
+        public async Task<APIGatewayProxyResponse> FunctionHandler
+            (APIGatewayProxyRequest apigProxyEvent, ILambdaContext context)
+        {
+            Logger.RefreshSampleRateCalculation();            
+            ...
+        }
+    }
+    ```
+
 === "Sampling via environment variable"
 
     ```yaml hl_lines="8"

libraries/src/AWS.Lambda.Powertools.Logging/Internal/Helpers/LoggerFactoryHelper.cs

@@ -21,6 +21,7 @@ internal static ILoggerFactory CreateAndConfigureFactory(PowertoolsLoggerConfigu
                 config.Service = configuration.Service;
                 config.TimestampFormat = configuration.TimestampFormat;
                 config.MinimumLogLevel = configuration.MinimumLogLevel;
+                config.InitialLogLevel = configuration.InitialLogLevel;
                 config.SamplingRate = configuration.SamplingRate;
                 config.LoggerOutputCase = configuration.LoggerOutputCase;
                 config.LogLevelKey = configuration.LogLevelKey;
@@ -32,8 +33,14 @@ internal static ILoggerFactory CreateAndConfigureFactory(PowertoolsLoggerConfigu
                 config.LogEvent = configuration.LogEvent;
             });
 
-            // Use current filter level or level from config
-            if (configuration.MinimumLogLevel != LogLevel.None)
+            // When sampling is enabled, set the factory minimum level to Debug
+            // so that all logs can reach our PowertoolsLogger for dynamic filtering
+            if (configuration.SamplingRate > 0)
+            {
+                builder.AddFilter(null, LogLevel.Debug);
+                builder.SetMinimumLevel(LogLevel.Debug);
+            }
+            else if (configuration.MinimumLogLevel != LogLevel.None)
             {
                 builder.AddFilter(null, configuration.MinimumLogLevel);
                 builder.SetMinimumLevel(configuration.MinimumLogLevel);

libraries/src/AWS.Lambda.Powertools.Logging/Internal/PowertoolsLogger.cs

@@ -80,7 +80,18 @@ internal void EndScope()
     public bool IsEnabled(LogLevel logLevel)
     {
         var config = _currentConfig();
+        return IsEnabledForConfig(logLevel, config);
+    }
 
+    /// <summary>
+    ///     Determines whether the specified log level is enabled for a specific configuration.
+    /// </summary>
+    /// <param name="logLevel">The log level.</param>
+    /// <param name="config">The configuration to check against.</param>
+    /// <returns>bool.</returns>
+    [MethodImpl(MethodImplOptions.AggressiveInlining)]
+    private bool IsEnabledForConfig(LogLevel logLevel, PowertoolsLoggerConfiguration config)
+    {
         //if Buffering is enabled and the log level is below the buffer threshold, skip logging only if bellow error
         if (logLevel <= config.LogBuffering?.BufferAtLogLevel
             && config.LogBuffering?.BufferAtLogLevel != LogLevel.Error
@@ -116,19 +127,38 @@ public bool IsEnabled(LogLevel logLevel)
     public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception,
         Func<TState, Exception, string> formatter)
     {
-        if (!IsEnabled(logLevel))
+        var config = _currentConfig();
+        if (config.SamplingRate > 0)
+        {
+            var samplingActivated = config.RefreshSampleRateCalculation(out double samplerValue);
+            if (samplingActivated)
+            {
+                config.LogOutput.WriteLine($"Changed log level to DEBUG based on Sampling configuration. Sampling Rate: {config.SamplingRate}, Sampler Value: {samplerValue}.");
+            }
+        }
+
+        // Use the same config reference for IsEnabled check to ensure we see the updated MinimumLogLevel
+        if (!IsEnabledForConfig(logLevel, config))
         {
             return;
         }
 
-        _currentConfig().LogOutput.WriteLine(LogEntryString(logLevel, state, exception, formatter));
+        config.LogOutput.WriteLine(LogEntryString(logLevel, state, exception, formatter));
     }
 
     internal void LogLine(string message)
     {
         _currentConfig().LogOutput.WriteLine(message);
     }
 
+    private void LogDebug(string message)
+    {
+        if (IsEnabled(LogLevel.Debug))
+        {
+            Log(LogLevel.Debug, new EventId(), message, null, (msg, ex) => msg);
+        }
+    }
+
     internal string LogEntryString<TState>(LogLevel logLevel, TState state, Exception exception,
         Func<TState, Exception, string> formatter)
     {
@@ -662,4 +692,4 @@ private string ExtractParameterName(string key)
             ? nameWithPossibleFormat.Substring(0, colonIndex)
             : nameWithPossibleFormat;
     }
-}
+}

libraries/src/AWS.Lambda.Powertools.Logging/Internal/PowertoolsLoggerProvider.cs

@@ -24,10 +24,10 @@ public PowertoolsLoggerProvider(
     {
         _powertoolsConfigurations = powertoolsConfigurations;
         _currentConfig = config;
-        
+
         // Set execution environment
         _powertoolsConfigurations.SetExecutionEnvironment(this);
-        
+
         // Apply environment configurations if available
         ConfigureFromEnvironment();
     }
@@ -58,47 +58,41 @@ public void ConfigureFromEnvironment()
             _currentConfig.LoggerOutputCase = loggerOutputCase;
         }
 
-        // Set log level from environment ONLY if not explicitly set
         var minLogLevel = lambdaLogLevelEnabled ? lambdaLogLevel : logLevel;
-        _currentConfig.MinimumLogLevel = minLogLevel != LogLevel.None ? minLogLevel : LoggingConstants.DefaultLogLevel;
+        var effectiveLogLevel = minLogLevel != LogLevel.None ? minLogLevel : LoggingConstants.DefaultLogLevel;
+
+        // Only set InitialLogLevel if it hasn't been explicitly configured
+        if (_currentConfig.InitialLogLevel == LogLevel.Information)
+        {
+            _currentConfig.InitialLogLevel = effectiveLogLevel;
+        }
+
+        _currentConfig.MinimumLogLevel = effectiveLogLevel;
+
         _currentConfig.XRayTraceId = _powertoolsConfigurations.XRayTraceId;
         _currentConfig.LogEvent = _powertoolsConfigurations.LoggerLogEvent;
-        
+
         // Configure the log level key based on output case
         _currentConfig.LogLevelKey = _powertoolsConfigurations.LambdaLogLevelEnabled() &&
                                      _currentConfig.LoggerOutputCase == LoggerOutputCase.PascalCase
             ? "LogLevel"
             : LoggingConstants.KeyLogLevel;
-            
+
         ProcessSamplingRate(_currentConfig, _powertoolsConfigurations);
         _environmentConfigured = true;
     }
-    
+
     /// <summary>
     /// Process sampling rate configuration
     /// </summary>
     private void ProcessSamplingRate(PowertoolsLoggerConfiguration config, IPowertoolsConfigurations configurations)
     {
-        var samplingRate = config.SamplingRate > 0 
-            ? config.SamplingRate 
+        var samplingRate = config.SamplingRate > 0
+            ? config.SamplingRate
             : configurations.LoggerSampleRate;
-            
+
         samplingRate = ValidateSamplingRate(samplingRate, config);
         config.SamplingRate = samplingRate;
-
-        // Only notify if sampling is configured
-        if (samplingRate > 0)
-        {
-            double sample = config.GetRandom();
-            
-            // Instead of changing log level, just indicate sampling status
-            if (sample <= samplingRate)
-            {
-                config.LogOutput.WriteLine(
-                    $"Changed log level to DEBUG based on Sampling configuration. Sampling Rate: {samplingRate}, Sampler Value: {sample}.");
-                config.MinimumLogLevel = LogLevel.Debug;
-            }
-        }
     }
 
     /// <summary>
@@ -129,18 +123,27 @@ public virtual ILogger CreateLogger(string categoryName)
     }
 
     internal PowertoolsLoggerConfiguration GetCurrentConfig() => _currentConfig;
-    
+
     public void UpdateConfiguration(PowertoolsLoggerConfiguration config)
     {
         _currentConfig = config;
-        
+
         // Apply environment configurations if available
         if (_powertoolsConfigurations != null && !_environmentConfigured)
         {
             ConfigureFromEnvironment();
         }
     }
 
+    /// <summary>
+    ///   Refresh the sampling calculation and update the minimum log level if needed
+    /// </summary>
+    /// <returns>True if debug sampling was enabled, false otherwise</returns>
+    internal bool RefreshSampleRateCalculation()
+    {
+        return _currentConfig.RefreshSampleRateCalculation();
+    }
+
     public virtual void Dispose()
     {
         _loggers.Clear();

libraries/src/AWS.Lambda.Powertools.Logging/Logger.Sampling.cs

@@ -0,0 +1,13 @@
+namespace AWS.Lambda.Powertools.Logging;
+
+public static partial class Logger
+{
+    /// <summary>
+    ///   Refresh the sampling calculation and update the minimum log level if needed
+    /// </summary>
+    /// <returns>True if debug sampling was enabled, false otherwise</returns>
+    public static bool RefreshSampleRateCalculation()
+    {
+        return _config.RefreshSampleRateCalculation();
+    }
+}

libraries/src/AWS.Lambda.Powertools.Logging/Logger.cs

@@ -12,6 +12,7 @@ namespace AWS.Lambda.Powertools.Logging;
 /// </summary>
 public static partial class Logger
 {
+    private static PowertoolsLoggerConfiguration _config;
     private static ILogger _loggerInstance;
     private static readonly object Lock = new object();
 
@@ -58,9 +59,9 @@ public static void Configure(Action<PowertoolsLoggerConfiguration> configure)
     {
         lock (Lock)
         {
-            var config = new PowertoolsLoggerConfiguration();
-            configure(config);
-            _loggerInstance = LoggerFactoryHelper.CreateAndConfigureFactory(config).CreatePowertoolsLogger();
+            _config = new PowertoolsLoggerConfiguration();
+            configure(_config);
+            _loggerInstance = LoggerFactoryHelper.CreateAndConfigureFactory(_config).CreatePowertoolsLogger();
         }
     }
 

libraries/src/AWS.Lambda.Powertools.Logging/PowertoolsLoggerConfiguration.cs

@@ -313,22 +313,84 @@ private PowertoolsLoggingSerializer InitializeSerializer()
     internal string XRayTraceId { get; set; }
     internal bool LogEvent { get; set; }
 
-    internal double Random { get; set; } = GetSafeRandom();
+    internal int SamplingRefreshCount { get; set; } = 0;
+    internal LogLevel InitialLogLevel { get; set; } = LogLevel.Information;
 
     /// <summary>
     ///     Gets random number
     /// </summary>
     /// <returns>System.Double.</returns>
     internal virtual double GetRandom()
     {
-        return Random;
+        return GetSafeRandom();
     }
-    
+
+    /// <summary>
+    ///   Refresh the sampling calculation and update the minimum log level if needed
+    /// </summary>
+    /// <returns>True if debug sampling was enabled, false otherwise</returns>
+    internal bool RefreshSampleRateCalculation()
+    {
+        return RefreshSampleRateCalculation(out _);
+    }
+
+    /// <summary>
+    ///   Refresh the sampling calculation and update the minimum log level if needed
+    /// </summary>
+    /// <param name="samplerValue"></param>
+    /// <returns>True if debug sampling was enabled, false otherwise</returns>
+    internal bool RefreshSampleRateCalculation(out double samplerValue)
+    {
+        samplerValue = 0.0;
+
+        if (SamplingRate <= 0)
+            return false;
+
+        // Increment counter at the beginning for proper cold start protection
+        SamplingRefreshCount++;
+
+        // Skip first call for cold start protection
+        if (SamplingRefreshCount == 1)
+        {
+            return false;
+        }
+
+        var shouldEnableDebugSampling = ShouldEnableDebugSampling(out samplerValue);
+
+        if (shouldEnableDebugSampling && MinimumLogLevel > LogLevel.Debug)
+        {
+            MinimumLogLevel = LogLevel.Debug;
+            return true;
+        }
+        else if (!shouldEnableDebugSampling)
+        {
+            MinimumLogLevel = InitialLogLevel;
+        }
+
+        return shouldEnableDebugSampling;
+    }
+
+
+    internal bool ShouldEnableDebugSampling()
+    {
+        return ShouldEnableDebugSampling(out _);
+    }
+
+    internal bool ShouldEnableDebugSampling(out double samplerValue)
+    {
+        samplerValue = 0.0;
+        if (SamplingRate <= 0) return false;
+
+        samplerValue = GetRandom();
+        return samplerValue <= SamplingRate;
+    }
+
     internal static double GetSafeRandom()
     {
         var randomGenerator = RandomNumberGenerator.Create();
-        byte[] data = new byte[16];
+        byte[] data = new byte[4];
         randomGenerator.GetBytes(data);
-        return BitConverter.ToDouble(data);
+        uint randomUInt = BitConverter.ToUInt32(data, 0);
+        return (double)randomUInt / uint.MaxValue;
     }
 }

libraries/src/AWS.Lambda.Powertools.Logging/PowertoolsLoggerExtensions.cs

@@ -257,4 +257,13 @@ public static void ClearBuffer(this ILogger logger)
         // Direct call to the buffer manager to avoid any recursion
         LogBufferManager.ClearCurrentBuffer();
     }
+    
+    /// <summary>
+    ///   Refresh the sampling calculation and update the minimum log level if needed
+    /// </summary>
+    /// <returns></returns>
+    public static bool RefreshSampleRateCalculation(this ILogger logger)
+    {
+        return Logger.RefreshSampleRateCalculation();
+    }
 }