Merge 8cacf33 into 48c7211

Sentry.xcodeproj/project.pbxproj

@@ -1399,6 +1399,7 @@
 		844DA81F28246DE300E6B62E /* scripts */ = {isa = PBXFileReference; lastKnownFileType = folder; path = scripts; sourceTree = "<group>"; };
 		8453421128BE855D00C22EEC /* SentrySampleDecision.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentrySampleDecision.m; sourceTree = "<group>"; };
 		8453421528BE8A9500C22EEC /* SentrySpanStatus.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = SentrySpanStatus.m; sourceTree = "<group>"; };
+		84732A6D2928BD4B00790372 /* SentryProfiler+SwiftTest.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = "SentryProfiler+SwiftTest.h"; sourceTree = "<group>"; };
 		84A888FC28D9B11700C51DFD /* SentryProfiler+Test.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; name = "SentryProfiler+Test.h"; path = "Sources/Sentry/include/SentryProfiler+Test.h"; sourceTree = SOURCE_ROOT; };
 		84A8891A28DBD28900C51DFD /* SentryDevice.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = SentryDevice.h; path = include/SentryDevice.h; sourceTree = "<group>"; };
 		84A8891B28DBD28900C51DFD /* SentryDevice.mm */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.objcpp; path = SentryDevice.mm; sourceTree = "<group>"; };
@@ -2771,6 +2772,7 @@
 				03F84D1B27DD414C008FE43F /* SentryMachLogging.hpp */,
 				03F84D2C27DD4191008FE43F /* SentryMachLogging.cpp */,
 				03F84D1127DD414C008FE43F /* SentryProfiler.h */,
+				84732A6D2928BD4B00790372 /* SentryProfiler+SwiftTest.h */,
 				84A888FC28D9B11700C51DFD /* SentryProfiler+Test.h */,
 				03F84D2B27DD4191008FE43F /* SentryProfiler.mm */,
 				03BCC38D27E2A377003232C7 /* SentryProfilingConditionals.h */,

Sources/Sentry/Profiling/SentryProfiler+SwiftTest.h

@@ -0,0 +1 @@
+FOUNDATION_EXPORT NSTimeInterval kSentryProfilerTimeoutInterval;

Sources/Sentry/SentryFileManager.m

@@ -196,7 +196,7 @@ - (void)deleteOldEnvelopesFromAllSentryPaths
         NSDictionary *dict = [[NSFileManager defaultManager] attributesOfItemAtPath:fullPath
                                                                               error:nil];
         if (!dict || dict[NSFileType] != NSFileTypeDirectory) {
-            SENTRY_LOG_DEBUG(@"Could not get NSFileTypeDirectory from %@", fullPath);
+            SENTRY_LOG_WARN(@"Could not get NSFileTypeDirectory from %@", fullPath);
             continue;
         }
 
@@ -214,7 +214,7 @@ - (void)deleteOldEnvelopesFromPath:(NSString *)envelopesPath
         NSDictionary *dict = [[NSFileManager defaultManager] attributesOfItemAtPath:fullPath
                                                                               error:nil];
         if (!dict || !dict[NSFileCreationDate]) {
-            SENTRY_LOG_DEBUG(@"Could not get NSFileCreationDate from %@", fullPath);
+            SENTRY_LOG_WARN(@"Could not get NSFileCreationDate from %@", fullPath);
             continue;
         }
 
@@ -251,6 +251,7 @@ - (BOOL)removeFileAtPath:(NSString *)path
     NSFileManager *fileManager = [NSFileManager defaultManager];
     NSError *error = nil;
     @synchronized(self) {
+        SENTRY_LOG_DEBUG(@"Deleting %@", path);
         [fileManager removeItemAtPath:path error:&error];
 
         if (nil != error) {

Sources/Sentry/SentryProfiler.mm

@@ -40,6 +40,7 @@
 
 const int kSentryProfilerFrequencyHz = 101;
 NSString *const kTestStringConst = @"test";
+NSTimeInterval kSentryProfilerTimeoutInterval = 30;
 
 using namespace sentry::profiling;
 
@@ -208,19 +209,6 @@ - (instancetype)init
 
 + (void)startForSpanID:(SentrySpanId *)spanID hub:(SentryHub *)hub
 {
-#    if SENTRY_TARGET_PROFILING_SUPPORTED
-    NSTimeInterval timeoutInterval = 30;
-#        if defined(TEST) || defined(TESTCI)
-    timeoutInterval = 1;
-#        endif
-    [self startForSpanID:spanID hub:hub timeoutInterval:timeoutInterval];
-#    endif
-}
-
-+ (void)startForSpanID:(SentrySpanId *)spanID
-                   hub:(SentryHub *)hub
-       timeoutInterval:(NSTimeInterval)timeoutInterval
-{
 #    if SENTRY_TARGET_PROFILING_SUPPORTED
     std::lock_guard<std::mutex> l(_gProfilerLock);
 
@@ -235,7 +223,7 @@ + (void)startForSpanID:(SentrySpanId *)spanID
 #        endif // SENTRY_HAS_UIKIT
         [_gCurrentProfiler start];
         _gCurrentProfiler->_timeoutTimer =
-            [NSTimer scheduledTimerWithTimeInterval:timeoutInterval
+            [NSTimer scheduledTimerWithTimeInterval:kSentryProfilerTimeoutInterval
                                              target:self
                                            selector:@selector(timeoutAbort)
                                            userInfo:nil
@@ -276,19 +264,18 @@ + (void)stopProfilingSpan:(id<SentrySpan>)span
 #    endif // SENTRY_TARGET_PROFILING_SUPPORTED
 }
 
-+ (void)dropTransaction:(SentryTransaction *)transaction
++ (void)dropTransactionWithID:(SentrySpanId *)transactionID
 {
 #    if SENTRY_TARGET_PROFILING_SUPPORTED
     std::lock_guard<std::mutex> l(_gProfilerLock);
 
-    const auto spanID = transaction.trace.context.spanId;
-    const auto profiler = _gProfilersPerSpanID[spanID];
+    const auto profiler = _gProfilersPerSpanID[transactionID];
     if (profiler == nil) {
-        SENTRY_LOG_DEBUG(@"No profiler tracking span with id %@", spanID.sentrySpanIdString);
+        SENTRY_LOG_DEBUG(@"No profiler tracking span with id %@", transactionID.sentrySpanIdString);
         return;
     }
 
-    [self captureEnvelopeIfFinished:profiler spanID:spanID];
+    [self captureEnvelopeIfFinished:profiler spanID:transactionID];
 #    endif // SENTRY_TARGET_PROFILING_SUPPORTED
 }
 
@@ -329,8 +316,10 @@ + (void)captureEnvelopeIfFinished:(SentryProfiler *)profiler spanID:(SentrySpanI
     if (profiler->_spansInFlight.count == 0) {
         [profiler captureEnvelope];
         [profiler->_transactions removeAllObjects];
+        SENTRY_LOG_DEBUG(@"Span %@ was last being tracked.", spanID.sentrySpanIdString);
     } else {
-        SENTRY_LOG_DEBUG(@"Profiler %@ is waiting for more spans to complete.", profiler);
+        SENTRY_LOG_DEBUG(@"Profiler %@ is waiting for more spans to complete: %@.", profiler,
+            profiler->_spansInFlight);
     }
 }
 
@@ -345,6 +334,7 @@ + (void)timeoutAbort
 
     SENTRY_LOG_DEBUG(@"Stopping profiler %@ due to timeout.", _gCurrentProfiler);
     [self stopProfilerForReason:SentryProfilerTruncationReasonTimeout];
+    [_gCurrentProfiler captureEnvelope];
 }
 
 + (void)backgroundAbort
@@ -358,6 +348,7 @@ + (void)backgroundAbort
 
     SENTRY_LOG_DEBUG(@"Stopping profiler %@ due to timeout.", _gCurrentProfiler);
     [self stopProfilerForReason:SentryProfilerTruncationReasonAppMovedToBackground];
+    [_gCurrentProfiler captureEnvelope];
 }
 
 + (void)stopProfilerForReason:(SentryProfilerTruncationReason)reason
@@ -497,6 +488,11 @@ - (void)stop
 
 - (void)captureEnvelope
 {
+    if (_transactions.count == 0) {
+        SENTRY_LOG_DEBUG(@"No linked transactions, won't send profile.");
+        return;
+    }
+
     NSMutableDictionary<NSString *, id> *profile = nil;
     @synchronized(self) {
         profile = [_profile mutableCopy];

Sources/Sentry/SentrySpan.m

@@ -119,6 +119,7 @@ - (BOOL)isFinished
 
 - (void)finish
 {
+    SENTRY_LOG_DEBUG(@"Attempting to finish span with id %@", _context.spanId.sentrySpanIdString);
     [self finishWithStatus:kSentrySpanStatusOk];
 }
 
@@ -131,9 +132,12 @@ - (void)finishWithStatus:(SentrySpanStatus)status
         SENTRY_LOG_DEBUG(@"Setting span timestamp: %@ at system time %llu", self.timestamp,
             (unsigned long long)getAbsoluteTime());
     }
-    if (self.tracer != nil) {
-        [self.tracer spanFinished:self];
+    if (self.tracer == nil) {
+        SENTRY_LOG_DEBUG(
+            @"No tracer associated with span with id %@", _context.spanId.sentrySpanIdString);
+        return;
     }
+    [self.tracer spanFinished:self];
 }
 
 - (SentryTraceHeader *)toTraceHeader

Sources/Sentry/SentrySpanContext.m

@@ -1,5 +1,6 @@
 #import "SentrySpanContext.h"
 #import "SentryId.h"
+#import "SentryLog.h"
 #import "SentrySpanId.h"
 
 NS_ASSUME_NONNULL_BEGIN
@@ -41,6 +42,10 @@ - (instancetype)initWithTraceId:(SentryId *)traceId
         self.operation = operation;
         self.status = kSentrySpanStatusUndefined;
         _tags = [[NSMutableDictionary alloc] init];
+        SENTRY_LOG_DEBUG(
+            @"Created span context with trace ID %@; span ID %@; parent span ID %@; operation %@",
+            traceId.sentryIdString, spanId.sentrySpanIdString, parentId.sentrySpanIdString,
+            operation);
     }
     return self;
 }

Sources/Sentry/SentrySwizzleWrapper.m

@@ -1,4 +1,5 @@
 #import "SentrySwizzleWrapper.h"
+#import "SentryLog.h"
 #import "SentrySwizzle.h"
 
 NS_ASSUME_NONNULL_BEGIN
@@ -32,6 +33,7 @@ - (void)swizzleSendAction:(SentrySwizzleSendActionCallback)callback forKey:(NSSt
 {
     // We need to make a copy of the block to avoid ARC of autoreleasing it.
     sentrySwizzleSendActionCallbacks[key] = [callback copy];
+    SENTRY_LOG_DEBUG(@"Swizzling sendAction for %@", key);
 
     if (sentrySwizzleSendActionCallbacks.count != 1) {
         return;

Sources/Sentry/SentryTracer.m

@@ -145,7 +145,9 @@ - (instancetype)initWithTransactionContext:(SentryTransactionContext *)transacti
 {
     if (self = [super init]) {
         SENTRY_LOG_DEBUG(
-            @"Starting transaction at system time %llu", (unsigned long long)getAbsoluteTime());
+            @"Starting transaction ID %@ and name %@ for span ID %@ at system time %llu",
+            transactionContext.traceId.sentryIdString, transactionContext.name,
+            transactionContext.spanId.sentrySpanIdString, (unsigned long long)getAbsoluteTime());
         self.rootSpan = [[SentrySpan alloc] initWithTracer:self context:transactionContext];
         self.transactionContext = transactionContext;
         _children = [[NSMutableArray alloc] init];
@@ -264,8 +266,9 @@ - (void)cancelIdleTimeout
                                            sampled:_rootSpan.context.sampled];
     context.spanDescription = description;
 
-    SENTRY_LOG_DEBUG(@"Starting child span under %@", parentId.sentrySpanIdString);
     SentrySpan *child = [[SentrySpan alloc] initWithTracer:self context:context];
+    SENTRY_LOG_DEBUG(@"Started child span %@ under %@", child.context.spanId.sentrySpanIdString,
+        parentId.sentrySpanIdString);
     @synchronized(_children) {
         [_children addObject:child];
     }
@@ -275,11 +278,15 @@ - (void)cancelIdleTimeout
 
 - (void)spanFinished:(id<SentrySpan>)finishedSpan
 {
+    SENTRY_LOG_DEBUG(@"Finished span %@", finishedSpan.context.spanId.sentrySpanIdString);
     // Calling canBeFinished on the rootSpan would end up in an endless loop because canBeFinished
     // calls finish on the rootSpan.
-    if (finishedSpan != self.rootSpan) {
-        [self canBeFinished];
+    if (finishedSpan == self.rootSpan) {
+        SENTRY_LOG_DEBUG(@"Cannot call finish on root span with id %@",
+            finishedSpan.context.spanId.sentrySpanIdString);
+        return;
     }
+    [self canBeFinished];
 }
 
 - (SentrySpanContext *)context
@@ -409,9 +416,9 @@ - (void)finish
 
 - (void)finishWithStatus:(SentrySpanStatus)status
 {
+    SENTRY_LOG_DEBUG(@"Finished trace %@", self.traceContext.traceId.sentryIdString);
     self.wasFinishCalled = YES;
     _finishStatus = status;
-
     [self cancelIdleTimeout];
     [self canBeFinished];
 }
@@ -421,17 +428,26 @@ - (void)canBeFinished
     // Transaction already finished and captured.
     // Sending another transaction and spans with
     // the same SentryId would be an error.
-    if (self.rootSpan.isFinished)
+    if (self.rootSpan.isFinished) {
+        SENTRY_LOG_DEBUG(@"Root span with id %@ is already finished",
+            self.rootSpan.context.spanId.sentrySpanIdString);
         return;
+    }
 
     BOOL hasUnfinishedChildSpansToWaitFor = [self hasUnfinishedChildSpansToWaitFor];
     if (!self.wasFinishCalled && !hasUnfinishedChildSpansToWaitFor && [self hasIdleTimeout]) {
+        SENTRY_LOG_DEBUG(
+            @"Root span with id %@ isn't waiting on children and needs idle timeout dispatched.",
+            self.rootSpan.context.spanId.sentrySpanIdString);
         [self dispatchIdleTimeout];
         return;
     }
 
-    if (!self.wasFinishCalled || hasUnfinishedChildSpansToWaitFor)
+    if (!self.wasFinishCalled || hasUnfinishedChildSpansToWaitFor) {
+        SENTRY_LOG_DEBUG(@"Root span with id %@ has children but isn't waiting for them right now.",
+            self.rootSpan.context.spanId.sentrySpanIdString);
         return;
+    }
 
     [self finishInternal];
 }
@@ -475,6 +491,13 @@ - (void)finishInternal
 
     @synchronized(_children) {
         if (self.idleTimeout > 0.0 && _children.count == 0) {
+            SENTRY_LOG_DEBUG(@"Was waiting for timeout for UI event trace but it had no children, "
+                             @"will not keep transaction.");
+
+#if SENTRY_TARGET_PROFILING_SUPPORTED
+            [SentryProfiler stopProfilingSpan:self.rootSpan];
+            [SentryProfiler dropTransactionWithID:self.transactionContext.spanId];
+#endif // SENTRY_TARGET_PROFILING_SUPPORTED
             return;
         }
 
@@ -499,17 +522,20 @@ - (void)finishInternal
 
     SentryTransaction *transaction = [self toTransaction];
 
-    // Prewarming can execute code up to viewDidLoad of a UIViewController, and keep the app in the
-    // background. This can lead to auto-generated transactions lasting for minutes or event hours.
-    // Therefore, we drop transactions lasting longer than SENTRY_AUTO_TRANSACTION_MAX_DURATION.
+    /**
+     * Prewarming can execute code up to viewDidLoad of a UIViewController, and keep the app in the
+     * background, leading to auto-generated transactions lasting for minutes or event hours. It
+     * could be that other circumstances could lead to long-lasting transactions as well. Therefore,
+     * as a safety measure for all auto-generated transactions, we drop transactions lasting longer
+     * than SENTRY_AUTO_TRANSACTION_MAX_DURATION.  */
     NSTimeInterval transactionDuration = [self.timestamp timeIntervalSinceDate:self.startTimestamp];
     if ([self isAutoGeneratedTransaction]
         && transactionDuration >= SENTRY_AUTO_TRANSACTION_MAX_DURATION) {
         SENTRY_LOG_INFO(@"Auto generated transaction exceeded the max duration of %f seconds. Not "
                         @"capturing transaction.",
             SENTRY_AUTO_TRANSACTION_MAX_DURATION);
 #if SENTRY_TARGET_PROFILING_SUPPORTED
-        [SentryProfiler dropTransaction:transaction];
+        [SentryProfiler dropTransactionWithID:self.transactionContext.spanId];
 #endif // SENTRY_TARGET_PROFILING_SUPPORTED
         return;
     }

Sources/Sentry/SentryTransactionContext.mm

@@ -1,4 +1,5 @@
 #import "SentryTransactionContext.h"
+#import "SentryLog.h"
 #include "SentryProfilingConditionals.h"
 #import "SentryThread.h"
 #include "SentryThreadHandle.hpp"
@@ -31,10 +32,7 @@ - (instancetype)initWithName:(NSString *)name
                    operation:(NSString *)operation
 {
     if (self = [super initWithOperation:operation]) {
-        _name = [NSString stringWithString:name];
-        _nameSource = source;
-        self.parentSampled = kSentryDefaultSamplingDecision;
-        [self getThreadInfo];
+        [self commonInitWithName:name source:source parentSampled:kSentryDefaultSamplingDecision];
     }
     return self;
 }
@@ -55,10 +53,7 @@ - (instancetype)initWithName:(NSString *)name
                      sampled:(SentrySampleDecision)sampled
 {
     if (self = [super initWithOperation:operation sampled:sampled]) {
-        _name = [NSString stringWithString:name];
-        _nameSource = source;
-        self.parentSampled = kSentryDefaultSamplingDecision;
-        [self getThreadInfo];
+        [self commonInitWithName:name source:source parentSampled:kSentryDefaultSamplingDecision];
     }
     return self;
 }
@@ -92,10 +87,7 @@ - (instancetype)initWithName:(NSString *)name
                              parentId:parentSpanId
                             operation:operation
                               sampled:kSentryDefaultSamplingDecision]) {
-        _name = [NSString stringWithString:name];
-        _nameSource = source;
-        self.parentSampled = parentSampled;
-        [self getThreadInfo];
+        [self commonInitWithName:name source:source parentSampled:parentSampled];
     }
     return self;
 }
@@ -115,6 +107,17 @@ - (SentryThread *)sentry_threadInfo
 }
 #endif
 
+- (void)commonInitWithName:(NSString *)name
+                    source:(SentryTransactionNameSource)source
+             parentSampled:(SentrySampleDecision)parentSampled
+{
+    _name = [NSString stringWithString:name];
+    _nameSource = source;
+    self.parentSampled = parentSampled;
+    [self getThreadInfo];
+    SENTRY_LOG_DEBUG(@"Created transaction context with name %@", name);
+}
+
 @end
 
 NS_ASSUME_NONNULL_END