Files
natsnet/dotnet/tests/ZB.MOM.NatsNet.Server.Tests/Internal/ServerLoggerTests.cs

337 lines
15 KiB
C#

// Copyright 2012-2025 The NATS Authors
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
using Shouldly;
using System.Reflection;
using ZB.MOM.NatsNet.Server;
using ZB.MOM.NatsNet.Server.Internal;
namespace ZB.MOM.NatsNet.Server.Tests.Internal;
/// <summary>
/// Tests for server logging trace sanitization (RemovePassFromTrace, RemoveAuthTokenFromTrace).
/// Mirrors server/log_test.go — TestNoPasswordsFromConnectTrace, TestRemovePassFromTrace,
/// TestRemoveAuthTokenFromTrace.
/// </summary>
public class ServerLoggerTests
{
// ---------------------------------------------------------------------------
// T:2020 — TestNoPasswordsFromConnectTrace
// ---------------------------------------------------------------------------
/// <summary>
/// Mirrors TestNoPasswordsFromConnectTrace.
/// Verifies that a CONNECT trace with a password or auth_token does not
/// expose the secret value after sanitization.
/// </summary>
[Fact] // T:2020
public void NoPasswordsFromConnectTrace_ShouldSucceed()
{
const string connectWithPass =
"""CONNECT {"verbose":false,"pedantic":false,"user":"derek","pass":"s3cr3t","tls_required":false}""";
const string connectWithToken =
"""CONNECT {"verbose":false,"auth_token":"secret-token","tls_required":false}""";
ServerLogging.RemovePassFromTrace(connectWithPass).ShouldNotContain("s3cr3t");
ServerLogging.RemoveAuthTokenFromTrace(connectWithToken).ShouldNotContain("secret-token");
}
// ---------------------------------------------------------------------------
// T:2021 — TestRemovePassFromTrace
// ---------------------------------------------------------------------------
/// <summary>
/// Mirrors TestRemovePassFromTrace — covers all test vectors from log_test.go.
/// Each case verifies that RemovePassFromTrace redacts the first pass/password value
/// with [REDACTED] while leaving other fields intact.
/// </summary>
[Theory] // T:2021
[InlineData(
"user and pass",
"CONNECT {\"user\":\"derek\",\"pass\":\"s3cr3t\"}\r\n",
"CONNECT {\"user\":\"derek\",\"pass\":\"[REDACTED]\"}\r\n")]
[InlineData(
"user and pass extra space",
"CONNECT {\"user\":\"derek\",\"pass\": \"s3cr3t\"}\r\n",
"CONNECT {\"user\":\"derek\",\"pass\": \"[REDACTED]\"}\r\n")]
[InlineData(
"user and pass is empty",
"CONNECT {\"user\":\"derek\",\"pass\":\"\"}\r\n",
"CONNECT {\"user\":\"derek\",\"pass\":\"[REDACTED]\"}\r\n")]
[InlineData(
"user and pass is empty whitespace",
"CONNECT {\"user\":\"derek\",\"pass\":\" \"}\r\n",
"CONNECT {\"user\":\"derek\",\"pass\":\"[REDACTED]\"}\r\n")]
[InlineData(
"only pass",
"CONNECT {\"pass\":\"s3cr3t\",}\r\n",
"CONNECT {\"pass\":\"[REDACTED]\",}\r\n")]
[InlineData(
"complete connect",
"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"foo\",\"pass\":\"s3cr3t\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n",
"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"user\":\"foo\",\"pass\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n")]
[InlineData(
"user and pass are filtered",
"CONNECT {\"user\":\"s3cr3t\",\"pass\":\"s3cr3t\"}\r\n",
"CONNECT {\"user\":\"s3cr3t\",\"pass\":\"[REDACTED]\"}\r\n")]
[InlineData(
"single long password",
"CONNECT {\"pass\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\"}\r\n",
"CONNECT {\"pass\":\"[REDACTED]\"}\r\n")]
public void RemovePassFromTrace_ShouldSucceed(string name, string input, string expected)
{
_ = name; // used for test display only
ServerLogging.RemovePassFromTrace(input).ShouldBe(expected);
}
// ---------------------------------------------------------------------------
// T:2022 — TestRemoveAuthTokenFromTrace
// ---------------------------------------------------------------------------
/// <summary>
/// Mirrors TestRemoveAuthTokenFromTrace — covers representative test vectors
/// from log_test.go. Each case verifies that RemoveAuthTokenFromTrace redacts
/// the first auth_token value with [REDACTED].
/// </summary>
[Theory] // T:2022
[InlineData(
"user and auth_token",
"CONNECT {\"user\":\"derek\",\"auth_token\":\"s3cr3t\"}\r\n",
"CONNECT {\"user\":\"derek\",\"auth_token\":\"[REDACTED]\"}\r\n")]
[InlineData(
"user and auth_token extra space",
"CONNECT {\"user\":\"derek\",\"auth_token\": \"s3cr3t\"}\r\n",
"CONNECT {\"user\":\"derek\",\"auth_token\": \"[REDACTED]\"}\r\n")]
[InlineData(
"user and auth_token is empty",
"CONNECT {\"user\":\"derek\",\"auth_token\":\"\"}\r\n",
"CONNECT {\"user\":\"derek\",\"auth_token\":\"[REDACTED]\"}\r\n")]
[InlineData(
"only auth_token",
"CONNECT {\"auth_token\":\"s3cr3t\",}\r\n",
"CONNECT {\"auth_token\":\"[REDACTED]\",}\r\n")]
[InlineData(
"complete connect",
"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"auth_token\":\"s3cr3t\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n",
"CONNECT {\"echo\":true,\"verbose\":false,\"pedantic\":false,\"auth_token\":\"[REDACTED]\",\"tls_required\":false,\"name\":\"APM7JU94z77YzP6WTBEiuw\"}\r\n")]
[InlineData(
"user and token are filtered",
"CONNECT {\"user\":\"s3cr3t\",\"auth_token\":\"s3cr3t\"}\r\n",
"CONNECT {\"user\":\"s3cr3t\",\"auth_token\":\"[REDACTED]\"}\r\n")]
[InlineData(
"single long token",
"CONNECT {\"auth_token\":\"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA\"}\r\n",
"CONNECT {\"auth_token\":\"[REDACTED]\"}\r\n")]
public void RemoveAuthTokenFromTrace_ShouldSucceed(string name, string input, string expected)
{
_ = name; // used for test display only
ServerLogging.RemoveAuthTokenFromTrace(input).ShouldBe(expected);
}
[Fact]
public void SetLogger_SetLoggerV2AndConfigureLogger_ShouldApplyExpectedSemantics()
{
var (server, err) = NatsServer.NewServer(new ServerOptions());
err.ShouldBeNull();
server.ShouldNotBeNull();
var setLogger = GetRequiredServerMethod("SetLogger", typeof(INatsLogger), typeof(bool), typeof(bool));
var setLoggerV2 = GetRequiredServerMethod("SetLoggerV2", typeof(INatsLogger), typeof(bool), typeof(bool), typeof(bool));
var configureLogger = GetRequiredServerMethod("ConfigureLogger");
var executeLogCall = GetRequiredServerMethod("ExecuteLogCall", typeof(Action<INatsLogger>));
var first = new CapturingLogger();
setLogger.Invoke(server, [first, true, true]);
GetPrivateIntField(server!, "_debugEnabled").ShouldBe(1);
GetPrivateIntField(server!, "_traceEnabled").ShouldBe(1);
GetPrivateIntField(server!, "_traceSysAcc").ShouldBe(0);
var second = new CapturingLogger();
setLoggerV2.Invoke(server, [second, false, false, true]);
first.Disposed.ShouldBeTrue();
GetPrivateIntField(server!, "_debugEnabled").ShouldBe(0);
GetPrivateIntField(server!, "_traceEnabled").ShouldBe(0);
GetPrivateIntField(server!, "_traceSysAcc").ShouldBe(1);
var noLogOptions = server!.Options;
noLogOptions.NoLog = true;
configureLogger.Invoke(server, null);
InvokeNoticef(server, "no-log should keep existing logger");
second.Messages.ShouldContain(msg => msg.Contains("no-log should keep existing logger", StringComparison.Ordinal));
var calls = 0;
executeLogCall.Invoke(server, [(Action<INatsLogger>)(_ => calls++)]);
calls.ShouldBe(1);
}
[Fact]
public void ReOpenLogFile_ByLoggerMode_ShouldMatchExpectedBehavior()
{
var (server, err) = NatsServer.NewServer(new ServerOptions());
err.ShouldBeNull();
server.ShouldNotBeNull();
var setLogger = GetRequiredServerMethod("SetLogger", typeof(INatsLogger), typeof(bool), typeof(bool));
var configureLogger = GetRequiredServerMethod("ConfigureLogger");
var reOpenLogFile = GetRequiredServerMethod("ReOpenLogFile");
var executeLogCall = GetRequiredServerMethod("ExecuteLogCall", typeof(Action<INatsLogger>));
// Nil logger path: executeLogCall should no-op.
var called = false;
executeLogCall.Invoke(server, [(Action<INatsLogger>)(_ => called = true)]);
called.ShouldBeFalse();
// Non-file logger path.
var memoryLogger = new CapturingLogger();
setLogger.Invoke(server, [memoryLogger, false, false]);
reOpenLogFile.Invoke(server, null);
memoryLogger.Messages.ShouldContain(m => m.Contains("not a file logger", StringComparison.Ordinal));
// File logger path.
var logFile = Path.Combine(Path.GetTempPath(), $"{Guid.NewGuid():N}.log");
var opts = server!.Options;
opts.LogFile = logFile;
opts.NoLog = false;
opts.Debug = false;
opts.Trace = false;
opts.Logtime = false;
configureLogger.Invoke(server, null);
InvokeNoticef(server, "message-before-reopen");
reOpenLogFile.Invoke(server, null);
InvokeNoticef(server, "message-after-reopen");
File.Exists(logFile).ShouldBeTrue();
var content = File.ReadAllText(logFile);
content.ShouldContain("File log re-opened");
content.ShouldContain("message-after-reopen");
}
[Fact]
public void ErrorsVariants_ShouldUseExpectedFormatting()
{
var (server, err) = NatsServer.NewServer(new ServerOptions());
err.ShouldBeNull();
server.ShouldNotBeNull();
var setLogger = GetRequiredServerMethod("SetLogger", typeof(INatsLogger), typeof(bool), typeof(bool));
var errors = GetRequiredServerMethod("Errors", typeof(object), typeof(Exception));
var errorc = GetRequiredServerMethod("Errorc", typeof(string), typeof(Exception));
var errorsc = GetRequiredServerMethod("Errorsc", typeof(object), typeof(string), typeof(Exception));
var logger = new CapturingLogger();
setLogger.Invoke(server, [logger, false, false]);
var wrapped = ErrorContextHelper.NewErrorCtx(new Exception("connection reset"), "leaf reconnect");
errors.Invoke(server, ["client", wrapped]);
errorc.Invoke(server, ["tls", wrapped]);
errorsc.Invoke(server, ["route", "cluster", wrapped]);
logger.Messages.Count.ShouldBe(3);
logger.Messages[0].ShouldContain("client - connection reset: leaf reconnect");
logger.Messages[1].ShouldContain("tls: connection reset: leaf reconnect");
logger.Messages[2].ShouldContain("route - cluster: connection reset: leaf reconnect");
}
[Fact]
public void RateLimitHelpers_ShouldRespectDedupeSemanticsAndDebugFlag()
{
var (server, err) = NatsServer.NewServer(new ServerOptions());
err.ShouldBeNull();
server.ShouldNotBeNull();
var setLogger = GetRequiredServerMethod("SetLogger", typeof(INatsLogger), typeof(bool), typeof(bool));
var rateLimitFormatWarnf = GetRequiredServerMethod("RateLimitFormatWarnf", typeof(string), typeof(object[]));
var rateLimitWarnf = GetRequiredServerMethod("RateLimitWarnf", typeof(string), typeof(object[]));
var rateLimitDebugf = GetRequiredServerMethod("RateLimitDebugf", typeof(string), typeof(object[]));
var logger = new CapturingLogger();
setLogger.Invoke(server, [logger, false, false]);
// Dedupe by format string (same format, different args => single warning).
rateLimitFormatWarnf.Invoke(server, ["format {0}", new object[] { "one" }]);
rateLimitFormatWarnf.Invoke(server, ["format {0}", new object[] { "two" }]);
rateLimitFormatWarnf.Invoke(server, ["other {0}", new object[] { "three" }]);
logger.Messages.Count.ShouldBe(2);
logger.Messages.ShouldContain("format one");
logger.Messages.ShouldContain("other three");
// Dedupe by rendered statement.
logger.Messages.Clear();
rateLimitWarnf.Invoke(server, ["warn {0}", new object[] { "same" }]);
rateLimitWarnf.Invoke(server, ["warn {0}", new object[] { "same" }]);
rateLimitWarnf.Invoke(server, ["warn {0}", new object[] { "other" }]);
logger.Messages.Count.ShouldBe(2);
logger.Messages.ShouldContain("warn same");
logger.Messages.ShouldContain("warn other");
// Debug dedupe + debug-flag gating.
logger.Messages.Clear();
rateLimitDebugf.Invoke(server, ["debug {0}", new object[] { "suppressed" }]);
logger.Messages.ShouldBeEmpty();
setLogger.Invoke(server, [logger, true, false]);
rateLimitDebugf.Invoke(server, ["debug {0}", new object[] { "visible" }]);
rateLimitDebugf.Invoke(server, ["debug {0}", new object[] { "visible" }]);
logger.Messages.Count.ShouldBe(1);
logger.Messages[0].ShouldContain("debug visible");
}
private static int GetPrivateIntField(object target, string fieldName)
{
var field = target.GetType().GetField(fieldName, BindingFlags.Instance | BindingFlags.NonPublic);
field.ShouldNotBeNull();
return (int)field!.GetValue(target)!;
}
private static MethodInfo GetRequiredServerMethod(string name, params Type[] parameterTypes)
{
var method = typeof(NatsServer).GetMethod(
name,
BindingFlags.Instance | BindingFlags.Public | BindingFlags.NonPublic,
binder: null,
types: parameterTypes,
modifiers: null);
method.ShouldNotBeNull($"{name} should exist on NatsServer");
return method!;
}
private static void InvokeNoticef(NatsServer server, string message)
{
var noticeMethod = typeof(NatsServer).GetMethod(
"Noticef",
BindingFlags.Instance | BindingFlags.NonPublic);
noticeMethod.ShouldNotBeNull();
noticeMethod!.Invoke(server, ["{0}", new object?[] { message }]);
}
private sealed class CapturingLogger : INatsLogger, IDisposable
{
public List<string> Messages { get; } = [];
public bool Disposed { get; private set; }
public void Noticef(string format, params object[] args) => Messages.Add(string.Format(format, args));
public void Warnf(string format, params object[] args) => Messages.Add(string.Format(format, args));
public void Fatalf(string format, params object[] args) => Messages.Add(string.Format(format, args));
public void Errorf(string format, params object[] args) => Messages.Add(string.Format(format, args));
public void Debugf(string format, params object[] args) => Messages.Add(string.Format(format, args));
public void Tracef(string format, params object[] args) => Messages.Add(string.Format(format, args));
public void Dispose() => Disposed = true;
}
}