diff --git a/CHANGELOG.md b/CHANGELOG.md index 4ebc0839f..435f04582 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,8 +2,9 @@ ## Unreleased -### Fixes +### Fixes +- Structured logs now have the `origin` and `sdk` attributes correctly set ([#2390](https://github.com/getsentry/sentry-unity/pull/2390)) - Resolved possible startup crashes on Android VR platforms like the Oculus Quest. The SDK no longer natively subscribes to interaction hooks for automatic tracing and breadcrumb creation. ([#2393](https://github.com/getsentry/sentry-unity/pull/2393)) ### Dependencies diff --git a/src/Sentry.Unity/Integrations/UnityApplicationLoggingIntegration.cs b/src/Sentry.Unity/Integrations/UnityApplicationLoggingIntegration.cs index 10d329003..674e089df 100644 --- a/src/Sentry.Unity/Integrations/UnityApplicationLoggingIntegration.cs +++ b/src/Sentry.Unity/Integrations/UnityApplicationLoggingIntegration.cs @@ -1,5 +1,6 @@ using System; using Sentry.Extensibility; +using Sentry.Infrastructure; using Sentry.Integrations; using UnityEngine; @@ -12,26 +13,28 @@ namespace Sentry.Unity.Integrations; /// internal class UnityApplicationLoggingIntegration : ISdkIntegration { - private readonly IApplication _application; private readonly bool _captureExceptions; + private readonly IApplication _application; + private readonly ISystemClock _clock; private ErrorTimeDebounce _errorTimeDebounce = null!; // Set in Register private LogTimeDebounce _logTimeDebounce = null!; // Set in Register private WarningTimeDebounce _warningTimeDebounce = null!; // Set in Register - private IHub? _hub; + private IHub _hub = null!; // Set in Register private SentryUnityOptions _options = null!; // Set in Register - internal UnityApplicationLoggingIntegration(bool captureExceptions = false, IApplication? application = null) + internal UnityApplicationLoggingIntegration(bool captureExceptions = false, IApplication? application = null, ISystemClock? clock = null) { _captureExceptions = captureExceptions; _application = application ?? ApplicationAdapter.Instance; + _clock = clock ?? SystemClock.Clock; } public void Register(IHub hub, SentryOptions sentryOptions) { - _hub = hub; - // This should never throw + // These should never throw but in case they do... + _hub = hub ?? throw new ArgumentException("Hub is null."); _options = sentryOptions as SentryUnityOptions ?? throw new ArgumentException("Options is not of type 'SentryUnityOptions'."); _logTimeDebounce = new LogTimeDebounce(_options.DebounceTimeLog); @@ -44,11 +47,6 @@ public void Register(IHub hub, SentryOptions sentryOptions) internal void OnLogMessageReceived(string message, string stacktrace, LogType logType) { - if (_hub is null) - { - return; - } - // We're not capturing the SDK's own logs if (message.StartsWith(UnityLogger.LogTag)) { @@ -64,6 +62,7 @@ internal void OnLogMessageReceived(string message, string stacktrace, LogType lo ProcessException(message, stacktrace, logType); ProcessError(message, stacktrace, logType); ProcessBreadcrumbs(message, logType); + ProcessStructuredLog(message, logType); } private bool IsGettingDebounced(LogType logType) @@ -92,7 +91,7 @@ private void ProcessException(string message, string stacktrace, LogType logType _options.LogDebug("Exception capture has been enabled. Capturing exception through '{0}'.", nameof(UnityApplicationLoggingIntegration)); var evt = UnityLogEventFactory.CreateExceptionEvent(message, stacktrace, false, _options); - _hub?.CaptureEvent(evt); + _hub.CaptureEvent(evt); } } @@ -108,11 +107,11 @@ private void ProcessError(string message, string stacktrace, LogType logType) if (_options.AttachStacktrace && !string.IsNullOrEmpty(stacktrace)) { var evt = UnityLogEventFactory.CreateMessageEvent(message, stacktrace, SentryLevel.Error, _options); - _hub?.CaptureEvent(evt); + _hub.CaptureEvent(evt); } else { - _hub?.CaptureMessage(message, level: SentryLevel.Error); + _hub.CaptureMessage(message, level: SentryLevel.Error); } } @@ -133,8 +132,26 @@ private void ProcessBreadcrumbs(string message, LogType logType) if (_options.AddBreadcrumbsForLogType.TryGetValue(logType, out var value) && value) { _options.LogDebug("Adding breadcrumb for log message of type: {0}", logType); - _hub?.AddBreadcrumb(message: message, category: "unity.logger", level: ToBreadcrumbLevel(logType)); + _hub.AddBreadcrumb(message: message, category: "unity.logger", level: ToBreadcrumbLevel(logType)); + } + } + + private void ProcessStructuredLog(string message, LogType logType) + { + if (!_options.Experimental.EnableLogs || !_options.Experimental.CaptureStructuredLogsForLogType.TryGetValue(logType, out var captureLog) || !captureLog) + { + return; } + + _options.LogDebug("Capturing structured log message of type '{0}'.", logType); + + SentryLog.GetTraceIdAndSpanId(_hub, out var traceId, out var spanId); + SentryLog log = new(_clock.GetUtcNow(), traceId, ToLogLevel(logType), message) { ParentSpanId = spanId }; + + log.SetDefaultAttributes(_options, UnitySdkInfo.Sdk); + log.SetOrigin("auto.log.unity"); + + _hub.Logger.CaptureLog(log); } private void OnQuitting() => _application.LogMessageReceived -= OnLogMessageReceived; @@ -149,4 +166,15 @@ private static BreadcrumbLevel ToBreadcrumbLevel(LogType logType) LogType.Warning => BreadcrumbLevel.Warning, _ => BreadcrumbLevel.Info }; + + private static SentryLogLevel ToLogLevel(LogType logType) + => logType switch + { + LogType.Assert => SentryLogLevel.Error, + LogType.Error => SentryLogLevel.Error, + LogType.Exception => SentryLogLevel.Error, + LogType.Log => SentryLogLevel.Info, + LogType.Warning => SentryLogLevel.Warning, + _ => SentryLogLevel.Info + }; } diff --git a/src/Sentry.Unity/Integrations/UnityLogHandlerIntegration.cs b/src/Sentry.Unity/Integrations/UnityLogHandlerIntegration.cs index 90f8b9a7f..51c2a535e 100644 --- a/src/Sentry.Unity/Integrations/UnityLogHandlerIntegration.cs +++ b/src/Sentry.Unity/Integrations/UnityLogHandlerIntegration.cs @@ -12,24 +12,15 @@ namespace Sentry.Unity.Integrations; /// internal sealed class UnityLogHandlerIntegration : ISdkIntegration, ILogHandler { - private readonly Func? _loggerFactory; private IHub? _hub; private SentryUnityOptions _options = null!; // Set during register private ILogHandler _unityLogHandler = null!; // Set during register - private SentryStructuredLogger _structuredLogger = null!; // Set during register - - // For testing: allows injecting a custom logger factory - internal UnityLogHandlerIntegration(Func? loggerFactory = null) - { - _loggerFactory = loggerFactory; - } public void Register(IHub hub, SentryOptions sentryOptions) { _hub = hub; // This should never happen, but if it does... _options = sentryOptions as SentryUnityOptions ?? throw new ArgumentException("Options is not of type 'SentryUnityOptions'."); - _structuredLogger = _loggerFactory?.Invoke() ?? _hub.Logger; // If called twice (i.e. init with the same options object) the integration will reference itself as the // original handler loghandler and endlessly forward to itself @@ -70,66 +61,13 @@ internal void ProcessException(Exception exception, UnityEngine.Object? context) // https://docs.sentry.io/platforms/unity/troubleshooting/#unhandled-exceptions---debuglogexception exception.SetSentryMechanism("Unity.LogException", handled: false, terminal: false); _ = _hub.CaptureException(exception); - - if (_options.Experimental.CaptureStructuredLogsForLogType.TryGetValue(LogType.Exception, out var captureException) && captureException) - { - _options.LogDebug("Capturing structured log message of type '{0}'.", LogType.Exception); - _structuredLogger.LogError(exception.Message); - } } public void LogFormat(LogType logType, UnityEngine.Object? context, string format, params object[] args) { - try - { - ProcessLog(logType, context, format, args); - } - finally - { - // Always pass the log back to Unity - // Capturing of `Debug`, `Warning`, and `Error` happens in the Application Logging Integration. - // The LogHandler does not have access to the stacktrace information required - _unityLogHandler.LogFormat(logType, context, format, args); - } - } - - private void ProcessLog(LogType logType, UnityEngine.Object? context, string format, params object[] args) - { - if (_hub?.IsEnabled is not true || !_options.Experimental.EnableLogs) - { - return; - } - - // We're not capturing the SDK's own logs. - if (args.Length > 1 && Equals(args[0], UnityLogger.LogTag)) - { - return; - } - - ProcessStructuredLog(logType, format, args); - } - - private void ProcessStructuredLog(LogType logType, string format, params object[] args) - { - if (!_options.Experimental.CaptureStructuredLogsForLogType.TryGetValue(logType, out var captureLog) || !captureLog) - { - return; - } - - _options.LogDebug("Capturing structured log message of type '{0}'.", logType); - - switch (logType) - { - case LogType.Log: - _structuredLogger.LogInfo(format, args); - break; - case LogType.Warning: - _structuredLogger.LogWarning(format, args); - break; - case LogType.Assert: - case LogType.Error: - _structuredLogger.LogError(format, args); - break; - } + // Always pass the log back to Unity + // Capturing of `Debug`, `Warning`, and `Error` happens in the Application Logging Integration. + // The LogHandler does not have access to the stacktrace information required + _unityLogHandler.LogFormat(logType, context, format, args); } } diff --git a/src/Sentry.Unity/Integrations/UnityScopeIntegration.cs b/src/Sentry.Unity/Integrations/UnityScopeIntegration.cs index 61ec5e774..0bbeedbef 100644 --- a/src/Sentry.Unity/Integrations/UnityScopeIntegration.cs +++ b/src/Sentry.Unity/Integrations/UnityScopeIntegration.cs @@ -13,6 +13,8 @@ internal static class UnitySdkInfo public static string Version { get; } = typeof(UnitySdkInfo).Assembly.GetNameAndVersion().Version ?? "0.0.0"; public const string Name = "sentry.dotnet.unity"; public const string PackageName = "upm:sentry.unity"; + + public static readonly SdkVersion Sdk = new() { Name = Name, Version = Version }; } internal class UnityScopeIntegration : ISdkIntegration diff --git a/test/Sentry.Unity.Tests/Stubs/TestHub.cs b/test/Sentry.Unity.Tests/Stubs/TestHub.cs index 7515f010e..306ac3ce6 100644 --- a/test/Sentry.Unity.Tests/Stubs/TestHub.cs +++ b/test/Sentry.Unity.Tests/Stubs/TestHub.cs @@ -16,12 +16,10 @@ internal sealed class TestHub : IHub public IReadOnlyList CapturedTransactions => _capturedTransactions; public IReadOnlyList> ConfigureScopeCalls => _configureScopeCalls; - public TestHub(bool isEnabled = true) + public TestHub(bool isEnabled = true, SentryStructuredLogger? logger = null) { -#pragma warning disable SENTRY0001 - Logger = null!; -#pragma warning restore SENTRY0001 IsEnabled = isEnabled; + Logger = logger ?? new TestStructuredLogger(); } public bool IsEnabled { get; } @@ -134,10 +132,7 @@ public void BindException(Exception exception, ISpan span) throw new NotImplementedException(); } - ISpan? IHub.GetSpan() - { - throw new NotImplementedException(); - } + ISpan? IHub.GetSpan() => null; public SentryTraceHeader? GetTraceHeader() { diff --git a/test/Sentry.Unity.Tests/Stubs/TestStructuredLogger.cs b/test/Sentry.Unity.Tests/Stubs/TestStructuredLogger.cs index 52b5c10ba..d242eaea4 100644 --- a/test/Sentry.Unity.Tests/Stubs/TestStructuredLogger.cs +++ b/test/Sentry.Unity.Tests/Stubs/TestStructuredLogger.cs @@ -6,13 +6,14 @@ namespace Sentry.Unity.Tests.Stubs; internal sealed class TestStructuredLogger : SentryStructuredLogger { public List<(string level, string message, object[] args)> LogCalls { get; } = new(); + public List CapturedLogs { get; } = new(); private protected override void CaptureLog(SentryLogLevel level, string template, object[]? parameters, Action? configureLog) => LogCalls.Add((level.ToString(), template, parameters ?? [])); protected internal override void CaptureLog(SentryLog log) { - // Not needed for our tests + CapturedLogs.Add(log); } protected internal override void Flush() @@ -20,5 +21,9 @@ protected internal override void Flush() // Not needed for our tests } - public void Clear() => LogCalls.Clear(); + public void Clear() + { + LogCalls.Clear(); + CapturedLogs.Clear(); + } } diff --git a/test/Sentry.Unity.Tests/UnityApplicationLoggingIntegrationTests.cs b/test/Sentry.Unity.Tests/UnityApplicationLoggingIntegrationTests.cs index 4f6ba8460..90827320e 100644 --- a/test/Sentry.Unity.Tests/UnityApplicationLoggingIntegrationTests.cs +++ b/test/Sentry.Unity.Tests/UnityApplicationLoggingIntegrationTests.cs @@ -18,7 +18,7 @@ private class Fixture public UnityApplicationLoggingIntegration GetSut() { var application = new TestApplication(); - var integration = new UnityApplicationLoggingIntegration(CaptureExceptions, application); + var integration = new UnityApplicationLoggingIntegration(CaptureExceptions, application, clock: null); integration.Register(Hub, SentryOptions); return integration; } @@ -190,7 +190,13 @@ public void OnLogMessageReceived_ExperimentalLogsEnabledWithAttachBreadcrumbsFal sut.OnLogMessageReceived(message, string.Empty, unityLogType); - Assert.AreEqual(0, _fixture.Hub.ConfigureScopeCalls.Count); + var scope = new Scope(_fixture.SentryOptions); + foreach (var configureScopeCall in _fixture.Hub.ConfigureScopeCalls) + { + configureScopeCall.Invoke(scope); + } + + Assert.AreEqual(0, scope.Breadcrumbs.Count); } [Test] @@ -208,11 +214,14 @@ public void OnLogMessageReceived_ExperimentalLogsEnabledWithAttachBreadcrumbsTru sut.OnLogMessageReceived(message, string.Empty, unityLogType); var scope = new Scope(_fixture.SentryOptions); - _fixture.Hub.ConfigureScopeCalls.Single().Invoke(scope); - var breadcrumb = scope.Breadcrumbs.Single(); + foreach (var configureScopeCall in _fixture.Hub.ConfigureScopeCalls) + { + configureScopeCall.Invoke(scope); + } - Assert.AreEqual(message, breadcrumb.Message); - Assert.AreEqual("unity.logger", breadcrumb.Category); + Assert.AreEqual(1, scope.Breadcrumbs.Count); + Assert.AreEqual(message, scope.Breadcrumbs.Single().Message); + Assert.AreEqual("unity.logger", scope.Breadcrumbs.Single().Category); } [Test] @@ -290,5 +299,98 @@ public void OnLogMessageReceived_LogErrorAttachStackTraceFalse_CaptureMessageWit Assert.IsEmpty(capturedEvent.SentryExceptions); Assert.IsEmpty(capturedEvent.SentryThreads); } + + [Test] + public void OnLogMessageReceived_ExperimentalCaptureEnabled_CapturesStructuredLog() + { + _fixture.SentryOptions.Experimental.EnableLogs = true; + _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[LogType.Exception] = true; + _fixture.CaptureExceptions = true; + var sut = _fixture.GetSut(); + var message = TestContext.CurrentContext.Test.Name; + + sut.OnLogMessageReceived(message, string.Empty, LogType.Exception); + + var logger = (TestStructuredLogger)_fixture.Hub.Logger; + Assert.AreEqual(1, logger.CapturedLogs.Count); + var log = logger.CapturedLogs[0]; + Assert.AreEqual(SentryLogLevel.Error, log.Level); + Assert.AreEqual(message, log.Message); + } + + [Test] + public void OnLogMessageReceived_ExperimentalCaptureDisabled_DoesNotCaptureStructuredLog() + { + _fixture.SentryOptions.Experimental.EnableLogs = true; + _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[LogType.Exception] = false; + _fixture.CaptureExceptions = true; + var sut = _fixture.GetSut(); + var message = TestContext.CurrentContext.Test.Name; + + sut.OnLogMessageReceived(message, string.Empty, LogType.Exception); + + var logger = (TestStructuredLogger)_fixture.Hub.Logger; + Assert.AreEqual(0, logger.CapturedLogs.Count); + } + + [Test] + public void OnLogMessageReceived_WithSentryLogTag_DoesNotCaptureStructuredLog() + { + _fixture.SentryOptions.Experimental.EnableLogs = true; + _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[LogType.Error] = true; + var sut = _fixture.GetSut(); + var message = $"{UnityLogger.LogTag}: Test message"; + + sut.OnLogMessageReceived(message, string.Empty, LogType.Error); + + var logger = (TestStructuredLogger)_fixture.Hub.Logger; + Assert.AreEqual(0, logger.CapturedLogs.Count); + } + + [Test] + public void OnLogMessageReceived_WithEnableLogsFalse_DoesNotCaptureStructuredLog() + { + _fixture.SentryOptions.Experimental.EnableLogs = false; + _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[LogType.Error] = true; + var sut = _fixture.GetSut(); + var message = TestContext.CurrentContext.Test.Name; + + sut.OnLogMessageReceived(message, string.Empty, LogType.Error); + + var logger = (TestStructuredLogger)_fixture.Hub.Logger; + Assert.AreEqual(0, logger.CapturedLogs.Count); + } + + [Test] + [TestCase(LogType.Log, SentryLogLevel.Info, true)] + [TestCase(LogType.Log, SentryLogLevel.Info, false)] + [TestCase(LogType.Warning, SentryLogLevel.Warning, true)] + [TestCase(LogType.Warning, SentryLogLevel.Warning, false)] + [TestCase(LogType.Error, SentryLogLevel.Error, true)] + [TestCase(LogType.Error, SentryLogLevel.Error, false)] + [TestCase(LogType.Assert, SentryLogLevel.Error, true)] + [TestCase(LogType.Assert, SentryLogLevel.Error, false)] + public void OnLogMessageReceived_WithExperimentalFlag_CapturesStructuredLogWhenEnabled(LogType logType, SentryLogLevel expectedLevel, bool captureEnabled) + { + _fixture.SentryOptions.Experimental.EnableLogs = true; + _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[logType] = captureEnabled; + var sut = _fixture.GetSut(); + var message = TestContext.CurrentContext.Test.Name; + + sut.OnLogMessageReceived(message, string.Empty, logType); + + var logger = (TestStructuredLogger)_fixture.Hub.Logger; + if (captureEnabled) + { + Assert.AreEqual(1, logger.CapturedLogs.Count); + var log = logger.CapturedLogs[0]; + Assert.AreEqual(expectedLevel, log.Level); + Assert.AreEqual(message, log.Message); + } + else + { + Assert.AreEqual(0, logger.CapturedLogs.Count); + } + } } } diff --git a/test/Sentry.Unity.Tests/UnityLogHandlerIntegrationTests.cs b/test/Sentry.Unity.Tests/UnityLogHandlerIntegrationTests.cs index 143591080..5fc8822cf 100644 --- a/test/Sentry.Unity.Tests/UnityLogHandlerIntegrationTests.cs +++ b/test/Sentry.Unity.Tests/UnityLogHandlerIntegrationTests.cs @@ -17,13 +17,10 @@ private class Fixture { public TestHub Hub { get; set; } = null!; public SentryUnityOptions SentryOptions { get; set; } = null!; - public TestStructuredLogger? StructuredLogger { get; set; } public UnityLogHandlerIntegration GetSut() { - var integration = StructuredLogger != null - ? new UnityLogHandlerIntegration(() => StructuredLogger) - : new UnityLogHandlerIntegration(() => DisabledSentryStructuredLogger.Instance); + var integration = new UnityLogHandlerIntegration(); integration.Register(Hub, SentryOptions); return integration; } @@ -82,101 +79,4 @@ public void Register_RegisteredASecondTime_LogsWarningAndReturns() log.logLevel == SentryLevel.Warning && log.message.Contains("UnityLogHandlerIntegration has already been registered."))); } - - [Test] - public void ProcessException_ExperimentalCaptureEnabled_CapturesStructuredLog() - { - _fixture.SentryOptions.Experimental.EnableLogs = true; - _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[LogType.Exception] = true; - _fixture.StructuredLogger = new TestStructuredLogger(); - var sut = _fixture.GetSut(); - var message = TestContext.CurrentContext.Test.Name; - - sut.ProcessException(new Exception(message), null); - - Assert.AreEqual(1, _fixture.StructuredLogger.LogCalls.Count); - var logCall = _fixture.StructuredLogger.LogCalls.Single(); - Assert.AreEqual("Error", logCall.level); - Assert.AreEqual(message, logCall.message); - } - - [Test] - public void ProcessException_ExperimentalCaptureDisabled_DoesNotCaptureStructuredLog() - { - _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[LogType.Exception] = false; - _fixture.StructuredLogger = new TestStructuredLogger(); - var sut = _fixture.GetSut(); - var message = TestContext.CurrentContext.Test.Name; - - sut.ProcessException(new Exception(message), null); - - Assert.AreEqual(0, _fixture.StructuredLogger.LogCalls.Count); - } - - [Test] - public void LogFormat_WithSentryLogTag_DoesNotCaptureStructuredLog() - { - _fixture.SentryOptions.Experimental.EnableLogs = true; - _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[LogType.Error] = true; - _fixture.StructuredLogger = new TestStructuredLogger(); - var sut = _fixture.GetSut(); - - const string? format = "{0}: {1}"; - const string? message = "Test message"; - LogAssert.Expect(LogType.Error, string.Format(format, UnityLogger.LogTag, message)); - - sut.LogFormat(LogType.Error, null, format, UnityLogger.LogTag, message); - - Assert.AreEqual(0, _fixture.StructuredLogger.LogCalls.Count); - } - - [Test] - public void LogFormat_WithEnableLogsFalse_DoesNotCaptureStructuredLog() - { - _fixture.SentryOptions.Experimental.EnableLogs = false; - _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[LogType.Error] = true; - _fixture.StructuredLogger = new TestStructuredLogger(); - var sut = _fixture.GetSut(); - var message = TestContext.CurrentContext.Test.Name; - - LogAssert.Expect(LogType.Error, message); - - sut.LogFormat(LogType.Error, null, message); - - Assert.AreEqual(0, _fixture.StructuredLogger.LogCalls.Count); - } - - [Test] - [TestCase(LogType.Log, "Info", true)] - [TestCase(LogType.Log, "Info", false)] - [TestCase(LogType.Warning, "Warning", true)] - [TestCase(LogType.Warning, "Warning", false)] - [TestCase(LogType.Error, "Error", true)] - [TestCase(LogType.Error, "Error", false)] - [TestCase(LogType.Assert, "Error", true)] - [TestCase(LogType.Assert, "Error", false)] - public void LogFormat_WithExperimentalFlag_CapturesStructuredLogWhenEnabled(LogType logType, string expectedLevel, bool captureEnabled) - { - _fixture.SentryOptions.Experimental.EnableLogs = true; - _fixture.SentryOptions.Experimental.CaptureStructuredLogsForLogType[logType] = captureEnabled; - _fixture.StructuredLogger = new TestStructuredLogger(); - var sut = _fixture.GetSut(); - var message = TestContext.CurrentContext.Test.Name; - - LogAssert.Expect(logType, message); - - sut.LogFormat(logType, null, message); - - if (captureEnabled) - { - Assert.AreEqual(1, _fixture.StructuredLogger.LogCalls.Count); - var logCall = _fixture.StructuredLogger.LogCalls.Single(); - Assert.AreEqual(expectedLevel, logCall.level); - Assert.AreEqual(message, logCall.message); - } - else - { - Assert.AreEqual(0, _fixture.StructuredLogger.LogCalls.Count); - } - } }