meta: debug logging (#3557)

Sources/Sentry/SentryOptions.m

@@ -17,6 +17,8 @@
 #import "SentryScope.h"
 #import "SentrySwiftAsyncIntegration.h"
 
+#import <objc/runtime.h>
+
 #if SENTRY_HAS_UIKIT
 #    import "SentryAppStartTrackingIntegration.h"
 #    import "SentryFramesTrackingIntegration.h"
@@ -199,6 +201,7 @@ - (instancetype)init
     return self;
 }
 
+/** Only exposed via `SentryOptions+HybridSDKs.h`. */
 - (_Nullable instancetype)initWithDict:(NSDictionary<NSString *, id> *)options
                       didFailWithError:(NSError *_Nullable *_Nullable)error
 {
@@ -708,4 +711,28 @@ - (void)setEnablePreWarmedAppStartTracing:(BOOL)enablePreWarmedAppStartTracing
 
 #endif // SENTRY_UIKIT_AVAILABLE
 
+#if defined(DEBUG) || defined(TEST) || defined(TESTCI)
+- (NSString *)debugDescription
+{
+    NSMutableString *propertiesDescription = [NSMutableString string];
+    @autoreleasepool {
+        unsigned int outCount, i;
+        objc_property_t *properties = class_copyPropertyList([self class], &outCount);
+        for (i = 0; i < outCount; i++) {
+            objc_property_t property = properties[i];
+            const char *propName = property_getName(property);
+            if (propName) {
+                NSString *propertyName = [NSString stringWithUTF8String:propName];
+                NSString *propertyValue = [[self valueForKey:propertyName] description];
+                [propertiesDescription appendFormat:@"  %@: %@\n", propertyName, propertyValue];
+            } else {
+                SENTRY_LOG_DEBUG(@"Failed to get a property name.");
+            }
+        }
+        free(properties);
+    }
+    return [NSString stringWithFormat:@"<%@: {\n%@\n}>", self, propertiesDescription];
+}
+#endif // defined(DEBUG) || defined(TEST) || defined(TESTCI)
+
 @end

Sources/Sentry/SentrySDK.m

@@ -162,6 +162,10 @@ + (void)startWithOptions:(SentryOptions *)options
     // thread could lead to deadlocks.
     SENTRY_LOG_DEBUG(@"Starting SDK...");
 
+#if defined(DEBUG) || defined(TEST) || defined(TESTCI)
+    SENTRY_LOG_DEBUG(@"Configured options: %@", options.debugDescription);
+#endif // defined(DEBUG) || defined(TEST) || defined(TESTCI)
+
     startInvocations++;
     startTimestamp = [SentryDependencyContainer.sharedInstance.dateProvider date];
 

Sources/Sentry/SentryTimeToDisplayTracker.m

@@ -4,6 +4,7 @@
 
 #    import "SentryDependencyContainer.h"
 #    import "SentryFramesTracker.h"
+#    import "SentryLog.h"
 #    import "SentryMeasurementValue.h"
 #    import "SentrySpan.h"
 #    import "SentrySpanContext.h"
@@ -44,12 +45,14 @@ - (instancetype)initForController:(UIViewController *)controller
 
 - (void)startForTracer:(SentryTracer *)tracer
 {
+    SENTRY_LOG_DEBUG(@"Starting initial display span");
     self.initialDisplaySpan = [tracer
         startChildWithOperation:SentrySpanOperationUILoadInitialDisplay
                     description:[NSString stringWithFormat:@"%@ initial display", _controllerName]];
     self.initialDisplaySpan.origin = SentryTraceOriginAutoUITimeToDisplay;
 
     if (self.waitForFullDisplay) {
+        SENTRY_LOG_DEBUG(@"Starting full display span");
         self.fullDisplaySpan =
             [tracer startChildWithOperation:SentrySpanOperationUILoadFullDisplay
                                 description:[NSString stringWithFormat:@"%@ full display",
@@ -120,18 +123,17 @@ - (void)framesTrackerHasNewFrame:(NSDate *)newFrameDate
     // takes to the content of the screen to change.
     // Thats why we need to wait for the next frame to be drawn.
     if (_initialDisplayReported && self.initialDisplaySpan.isFinished == NO) {
+        SENTRY_LOG_DEBUG(@"Finishing initial display span");
         self.initialDisplaySpan.timestamp = newFrameDate;
-
         [self.initialDisplaySpan finish];
-
         if (!_waitForFullDisplay) {
             [SentryDependencyContainer.sharedInstance.framesTracker removeListener:self];
         }
     }
     if (_waitForFullDisplay && _fullyDisplayedReported && self.fullDisplaySpan.isFinished == NO
         && self.initialDisplaySpan.isFinished == YES) {
+        SENTRY_LOG_DEBUG(@"Finishing full display span");
         self.fullDisplaySpan.timestamp = newFrameDate;
-
         [self.fullDisplaySpan finish];
     }
 

Sources/Sentry/SentryTracer.m

@@ -426,8 +426,8 @@ - (void)finish
 
 - (void)finishWithStatus:(SentrySpanStatus)status
 {
-    SENTRY_LOG_DEBUG(@"Finished trace with traceID: %@ and status: %@", self.traceId.sentryIdString,
-        nameForSentrySpanStatus(status));
+    SENTRY_LOG_DEBUG(@"Finished trace with traceID: %@ and status: %@",
+        self.internalID.sentryIdString, nameForSentrySpanStatus(status));
     @synchronized(self) {
         self.wasFinishCalled = YES;
     }
@@ -594,7 +594,8 @@ - (void)captureTransactionWithProfile:(SentryTransaction *)transaction
         return;
     }
 
-    SENTRY_LOG_DEBUG(@"Capturing transaction with profiling data attached.");
+    SENTRY_LOG_DEBUG(@"Capturing transaction with profiling data attached for tracer id %@.",
+        self.internalID.sentryIdString);
     [_hub captureTransaction:transaction
                       withScope:_hub.scope
         additionalEnvelopeItems:@[ profileEnvelopeItem ]];
@@ -694,27 +695,35 @@ - (nullable SentryAppStartMeasurement *)getAppStartMeasurement
     // Only send app start measurement for transactions generated by auto performance
     // instrumentation.
     if (![self.operation isEqualToString:SentrySpanOperationUILoad]) {
+        SENTRY_LOG_DEBUG(
+            @"Not returning app start measurements because it's not a ui.load operation.");
         return nil;
     }
 
     // Hybrid SDKs send the app start measurement themselves.
     if (PrivateSentrySDKOnly.appStartMeasurementHybridSDKMode) {
+        SENTRY_LOG_DEBUG(@"Not returning app start measurements because hybrid SDK will do it in "
+                         @"its own routine.");
         return nil;
     }
 
     // Double-Checked Locking to avoid acquiring unnecessary locks.
     if (appStartMeasurementRead == YES) {
+        SENTRY_LOG_DEBUG(@"Not returning app start measurements because it was already reported.");
         return nil;
     }
 
     SentryAppStartMeasurement *measurement = nil;
     @synchronized(appStartMeasurementLock) {
         if (appStartMeasurementRead == YES) {
+            SENTRY_LOG_DEBUG(@"Not returning app start measurements because it was already "
+                             @"reported concurrently.");
             return nil;
         }
 
         measurement = [SentrySDK getAppStartMeasurement];
         if (measurement == nil) {
+            SENTRY_LOG_DEBUG(@"No app start measurement available.");
             return nil;
         }
 
@@ -731,9 +740,12 @@ - (nullable SentryAppStartMeasurement *)getAppStartMeasurement
     // sequence and the start of the transaction. This makes transactions too long.
     if (difference > SENTRY_APP_START_MEASUREMENT_DIFFERENCE
         || difference < -SENTRY_APP_START_MEASUREMENT_DIFFERENCE) {
+        SENTRY_LOG_DEBUG(@"Not returning app start measurements because too much time elapsed.");
         return nil;
     }
 
+    SENTRY_LOG_DEBUG(
+        @"Returning app start measurements for trace id %@", self.internalID.sentryIdString);
     return measurement;
 }
 

Tests/SentryTests/SentryOptionsTest.m

@@ -1233,6 +1233,21 @@ - (void)testInitialSwiftAsyncStacktracesYes
     XCTAssertTrue(options.swiftAsyncStacktraces);
 }
 
+- (void)testOptionsDebugDescription
+{
+    NSNumber *_Nullable (^tracesSampler)(void) = ^NSNumber *_Nullable { return nil; };
+    SentryOptions *options = [self getValidOptions:@{
+        @"tracesSampler" : tracesSampler,
+        @"sampleRate" : @0.123,
+    }];
+    NSString *debugDescription = options.debugDescription;
+    XCTAssertNotNil(debugDescription);
+    XCTAssert([debugDescription containsString:@"sampleRate: 0.123"]);
+    XCTAssert([debugDescription containsString:@"tracesSampler: <__NSGlobalBlock__: "]);
+}
+
+#pragma mark - Private
+
 - (void)assertArrayEquals:(NSArray<NSString *> *)expected actual:(NSArray<NSString *> *)actual
 {
     XCTAssertEqualObjects([expected sortedArrayUsingSelector:@selector(compare:)],