diff --git a/Source/AudibleUtilities/Account.cs b/Source/AudibleUtilities/Account.cs index 2b9f18f1..2776e00c 100644 --- a/Source/AudibleUtilities/Account.cs +++ b/Source/AudibleUtilities/Account.cs @@ -1,13 +1,16 @@ using AudibleApi; using AudibleApi.Authorization; using Dinah.Core; +using Dinah.Core.Security; +using LibationFileManager; using Newtonsoft.Json; using System; -using System.Diagnostics.CodeAnalysis; +using System.Diagnostics; namespace AudibleUtilities; -public class Account : IUpdatable +[DebuggerDisplay("{AccountId,nq} - {Locale}")] +public class Account : IUpdatable, ILogMasked { public event EventHandler? Updated; private void update(object? sender = null, EventArgs? e = null) @@ -46,15 +49,18 @@ public class Account : IUpdatable } } - /// aka: activation bytes - [AllowNull] - public string? DecryptKey + /// + /// aka: activation bytes. A so that no reflective dump - Serilog's structured + /// logging, or Serilog.Exceptions walking a logged exception - can reach the value. Persists as the same + /// bare JSON string it always did. + /// + public SecretString DecryptKey { get => field; set { - var v = (value ?? "").Trim(); - if (v == field) + var v = (value.Reveal() ?? "").Trim(); + if (v == field.Reveal()) return; field = v; update(); @@ -88,7 +94,12 @@ public class Account : IUpdatable AccountId = ArgumentValidator.EnsureNotNullOrWhiteSpace(accountId, nameof(accountId)).Trim(); } - public override string ToString() => $"{AccountId} - {Locale?.Name ?? "[empty]"}"; + /// + /// Masked, because this is what interpolation and non-destructured logging reach for. Use + /// for dialogs shown to the account's owner, and see + /// the DebuggerDisplay above for the unmasked form while debugging. + /// + public override string ToString() => MaskedLogEntry; public string MaskedLogEntry => @$"AccountId={mask(AccountId)}|AccountName={mask(AccountName)}|Locale={Locale?.Name ?? "[empty]"}"; private static string mask(string? str) diff --git a/Source/AudibleUtilities/Mkb79Auth.cs b/Source/AudibleUtilities/Mkb79Auth.cs index 567782c9..4731a806 100644 --- a/Source/AudibleUtilities/Mkb79Auth.cs +++ b/Source/AudibleUtilities/Mkb79Auth.cs @@ -241,7 +241,7 @@ public partial class Mkb79Auth => new() { AccessToken = account.IdentityTokens?.ExistingAccessToken.Reveal(), - ActivationBytes = string.IsNullOrEmpty(account.DecryptKey) ? null : account.DecryptKey, + ActivationBytes = account.DecryptKey.HasValue ? account.DecryptKey.Reveal() : null, AdpToken = account.IdentityTokens?.AdpToken?.Reveal(), CustomerInfo = new CustomerInfo { diff --git a/Source/LibationFileManager/Configuration.Logging.cs b/Source/LibationFileManager/Configuration.Logging.cs index 0c39e014..d0c5cf9b 100644 --- a/Source/LibationFileManager/Configuration.Logging.cs +++ b/Source/LibationFileManager/Configuration.Logging.cs @@ -1,4 +1,5 @@ using Dinah.Core.Logging; +using Dinah.Core.Security; using FileManager; using Microsoft.Extensions.Configuration; using Newtonsoft.Json; @@ -162,6 +163,10 @@ public partial class Configuration .ReadFrom.Configuration(configuration, readerOptions) .Destructure.ByTransforming(lp => lp.Path) .Destructure.With() + // last lines of defense for structured logging: a masked identity instead of the object, and a + // secret that renders as its shape instead of its contents + .Destructure.With() + .Destructure.ByTransforming(secret => secret.ToString()) .CreateLogger(); SerilogInitialized = true; } diff --git a/Source/LibationFileManager/MaskedLogEntryPolicy.cs b/Source/LibationFileManager/MaskedLogEntryPolicy.cs new file mode 100644 index 00000000..2924adae --- /dev/null +++ b/Source/LibationFileManager/MaskedLogEntryPolicy.cs @@ -0,0 +1,37 @@ +using Serilog.Core; +using Serilog.Events; + +namespace LibationFileManager; + +/// +/// Implemented by types that identify something private, and so must appear in a log only in masked form. +/// +public interface ILogMasked +{ + /// The only form of this object that may reach a log file. + string MaskedLogEntry { get; } +} + +/// +/// Reduces any to its masked entry when Serilog destructures it, so that a structured +/// log call - {@Account}, or an anonymous {@DebugInfo} object holding one - cannot publish the +/// unmasked object by accident. +/// +/// This covers Serilog's own destructuring only. Serilog.Exceptions flattens a logged exception's properties +/// itself before Serilog sees them, so an exception must not carry one of these in the first place. +/// +/// +public class MaskedLogEntryPolicy : IDestructuringPolicy +{ + public bool TryDestructure(object value, ILogEventPropertyValueFactory propertyValueFactory, out LogEventPropertyValue result) + { + if (value is ILogMasked masked) + { + result = new ScalarValue(masked.MaskedLogEntry); + return true; + } + + result = null!; + return false; + } +} diff --git a/Source/_Tests/AudibleUtilities.Tests/AuthenticationRequiredExceptionLogSafetyTests.cs b/Source/_Tests/AudibleUtilities.Tests/AuthenticationRequiredExceptionLogSafetyTests.cs index 4d0d789e..f6a088b2 100644 --- a/Source/_Tests/AudibleUtilities.Tests/AuthenticationRequiredExceptionLogSafetyTests.cs +++ b/Source/_Tests/AudibleUtilities.Tests/AuthenticationRequiredExceptionLogSafetyTests.cs @@ -3,7 +3,10 @@ using AudibleApi.Authorization; using AudibleApi.Cryptography; using AudibleUtilities; using Dinah.Core.Security; +using LibationFileManager; using Microsoft.VisualStudio.TestTools.UnitTesting; +using Newtonsoft.Json; +using Newtonsoft.Json.Linq; using Serilog; using Serilog.Core; using Serilog.Events; @@ -128,6 +131,44 @@ public class AuthenticationRequiredExceptionLogSafety } } +/// +/// The paths that do not involve an exception at all: interpolating an account, and persisting its activation +/// bytes. +/// +[TestClass] +public class AccountMasking +{ + [TestMethod] + public void interpolating_an_account_is_masked() + { + var account = new Account("jade@example.com") { AccountName = "Jade" }; + + var interpolated = $"{account}"; + + Assert.AreEqual(account.MaskedLogEntry, interpolated); + Assert.IsFalse(interpolated.Contains("jade@example.com", StringComparison.Ordinal)); + Assert.IsFalse(interpolated.Contains("Jade", StringComparison.Ordinal)); + } + + [TestMethod] + public void an_account_declares_itself_maskable_for_serilog() + => Assert.IsInstanceOfType(new Account("jade@example.com")); + + /// + /// DecryptKey became a SecretString, which would serialize as an object and lose the value if the converter + /// were not doing its job. Existing settings files have to keep loading, and keep the shape they had. + /// + [TestMethod] + public void the_activation_bytes_still_persist_as_a_bare_string() + { + var json = JsonConvert.SerializeObject(new Account("jade@example.com") { DecryptKey = "1a2b3c4d" }); + + var decryptKey = JObject.Parse(json)["DecryptKey"]!; + Assert.AreEqual(JTokenType.String, decryptKey.Type); + Assert.AreEqual("1a2b3c4d", decryptKey.ToObject()); + } +} + /// /// A guard against the next exception type reintroducing this. Serilog.Exceptions walks the public property /// graph of whatever exception it is handed, to a default depth of 10, so no exception may be able to reach an @@ -154,7 +195,7 @@ public class ExceptionsCannotReachAnAccount var assemblies = new[] { typeof(Account).Assembly, - typeof(LibationFileManager.Configuration).Assembly, + typeof(Configuration).Assembly, typeof(FileManager.LongPath).Assembly }; diff --git a/Source/_Tests/LibationFileManager.Tests/MaskedLogEntryLoggingTests.cs b/Source/_Tests/LibationFileManager.Tests/MaskedLogEntryLoggingTests.cs new file mode 100644 index 00000000..64cc648a --- /dev/null +++ b/Source/_Tests/LibationFileManager.Tests/MaskedLogEntryLoggingTests.cs @@ -0,0 +1,109 @@ +using Dinah.Core.Security; +using LibationFileManager; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using Newtonsoft.Json.Linq; +using Serilog; +using System; +using System.IO; +using System.Linq; + +namespace SerilogConfigurationTests; + +/// +/// Builds the logger the way Libation does and writes through it, rather than testing the destructuring policy +/// on its own: the policy only protects anything if actually +/// registers it, and a missing registration is silent. +/// +[TestClass] +[DoNotParallelize] +public class MaskedLogEntryLoggingTests +{ + private const string Secret = "jade@example.com"; + private const string Masked = "AccountId=j[...]e|Locale=us"; + + private string tempDir = string.Empty; + private ILogger originalLogger = Serilog.Log.Logger; + + private class MaskedThing : ILogMasked + { + public string MaskedLogEntry => Masked; + public string Address => Secret; + public override string ToString() => Masked; + } + + [TestInitialize] + public void Initialize() + { + originalLogger = Serilog.Log.Logger; + tempDir = Path.Combine(Path.GetTempPath(), $"libation-masked-log-tests-{Guid.NewGuid():N}"); + Directory.CreateDirectory(tempDir); + } + + [TestCleanup] + public void Cleanup() + { + Serilog.Log.CloseAndFlush(); + Serilog.Log.Logger = originalLogger; + Configuration.RestoreSingletonInstance(); + + try + { + Directory.Delete(tempDir, recursive: true); + } + catch (IOException) + { + // A leftover temp directory is not worth failing a test over. + } + } + + private string LogThrough(Action write) + { + var config = Configuration.CreateMockInstance(); + config.EnsureSerilogConfig(); + + var args = (JObject)((JObject)config.GetObject("Serilog")!).SelectToken("$.WriteTo[0].Args")!; + args["path"] = Path.Combine(tempDir, "Log.log"); + args["outputTemplate"] = "{Message:lj} {Properties:j}{NewLine}"; + config.SetNonString((JObject)config.GetObject("Serilog")!, "Serilog"); + + config.ConfigureLogging(); + + write(Serilog.Log.Logger); + Serilog.Log.CloseAndFlush(); + + return string.Join("\n", Directory.GetFiles(tempDir, "Log*.log").Select(File.ReadAllText)); + } + + /// Destructured, so the policy is what has to catch it: without one, Address would be written. + [TestMethod] + public void a_destructured_masked_type_is_reduced_to_its_masked_entry() + { + var written = LogThrough(logger => logger.Information("scanning {@Account}", new MaskedThing())); + + StringAssert.Contains(written, Masked); + Assert.IsFalse(written.Contains(Secret, StringComparison.Ordinal), "the log contained the unmasked value"); + } + + /// The shape most of Libation's logging uses: an anonymous object holding the thing. + [TestMethod] + public void a_masked_type_nested_in_a_debug_object_is_reduced_too() + { + var written = LogThrough(logger => logger.Information("scanning {@DebugInfo}", new { Account = new MaskedThing(), Attempt = 2 })); + + StringAssert.Contains(written, Masked); + Assert.IsFalse(written.Contains(Secret, StringComparison.Ordinal), "the log contained the unmasked value"); + } + + /// + /// Destructured on purpose. Without the transform a secret renders as an empty structure - safe, but it says + /// nothing, and the shape is the whole point of the redaction. + /// + [TestMethod] + public void a_destructured_secret_is_written_as_its_shape() + { + var written = LogThrough(logger => logger.Information("key {@Key}", new SecretString(Secret))); + + StringAssert.Contains(written, $"[REDACTED length={Secret.Length}]"); + Assert.IsFalse(written.Contains(Secret, StringComparison.Ordinal), "the log contained the secret"); + } +} diff --git a/docs/development/contribute.md b/docs/development/contribute.md index 9e588067..a12999fd 100644 --- a/docs/development/contribute.md +++ b/docs/development/contribute.md @@ -20,6 +20,16 @@ We welcome contributions! Whether it's fixing bugs, adding features, or improvin - Ensure your code builds and runs without errors. - Clean up any unused dependencies or imports. +## Logging and secrets + +We ask people to attach `Log.log` to public issue reports, so treat everything written there as published. + +- Log `account.MaskedLogEntry`, never an account's id or name. `AccountCredentialStatus.FormatAccountLabel` gives the unmasked label and is for dialogs shown to the account's owner only. +- Never hang an `Account`, an `Identity`, or anything holding one off an exception. Serilog.Exceptions reflects over every public property of a logged exception and follows nested objects, so a live account on an exception publishes its address and activation bytes no matter what `ToString` says. Carry an `AccountSummary` instead. A test enforces this: see `ExceptionsCannotReachAnAccount`. +- Remember that an exception's `Message` gets logged too, so mask anything you interpolate into one. +- Wrap a new secret in `Dinah.Core.Security.SecretString`, which keeps the value behind `Reveal()` where reflection cannot find it and prints `[REDACTED length=N]` everywhere else. Implement `ILogMasked` on a type that needs a masked identity in logs. +- `Reveal()` at the point of use, and nowhere else. Interpolating a secret into a string is not a compile error, so a redaction can end up sent over the wire in place of the real value - cover any new call site with a test. + ## Submitting a Pull Request 1. **Commit your changes** with a clear message.