ref: add/improve logging (#2420)

Sources/Sentry/SentryFileManager.m

@@ -108,8 +108,13 @@ - (nullable instancetype)initWithOptions:(SentryOptions *)options
  self.currentFileCounter = 0;
  self.maxEnvelopes = options.maxCacheItems;
 
- [dispatchQueueWrapper dispatchAfter:10
- block:^{ [self deleteOldEnvelopesFromAllSentryPaths]; }];
+ SENTRY_LOG_DEBUG(@"Dispatching deletion of old envelopes from %@", self);
+ [dispatchQueueWrapper
+ dispatchAfter:10
+ block:^{
+ SENTRY_LOG_DEBUG(@"Dispatched deletion of old envelopes from %@", self);
+ [self deleteOldEnvelopesFromAllSentryPaths];
+ }];
  }
  return self;
 }
@@ -196,7 +201,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 +219,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 +256,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/SentryPerformanceTracker.m

@@ -68,12 +68,17 @@ - (SentrySpanId *)startSpanWithName:(NSString *)name
  BOOL bindToScope = true;
  if (span != nil) {
  if ([SentryUIEventTracker isUIEventOperation:span.context.operation]) {
+ SENTRY_LOG_DEBUG(@"Cancelling previous UI event span %@",
+ span.context.spanId.sentrySpanIdString);
  [span finishWithStatus:kSentrySpanStatusCancelled];
  } else {
+ SENTRY_LOG_DEBUG(@"Current scope span %@ is not tracking a UI event",
+ span.context.spanId.sentrySpanIdString);
  bindToScope = false;
  }
  }
 
+ SENTRY_LOG_DEBUG(@"Creating new transaction bound to scope: %d", bindToScope);
  newSpan = [SentrySDK.currentHub startTransactionWithContext:context
  bindToScope:bindToScope
  waitForChildren:YES
@@ -117,6 +122,8 @@ - (void)measureSpanWithDescription:(NSString *)description
  SentrySpanId *spanId = [self startSpanWithName:description
  nameSource:source
  operation:operation];
+ SENTRY_LOG_DEBUG(@"Measuring span %@; description %@; operation: %@", spanId.sentrySpanIdString,
+ description, operation);
  [self pushActiveSpan:spanId];
  block();
  [self popActiveSpan];
@@ -170,12 +177,14 @@ - (nullable SentrySpanId *)activeSpanId
 
 - (BOOL)pushActiveSpan:(SentrySpanId *)spanId
 {
+ SENTRY_LOG_DEBUG(@"Pushing active span %@", spanId.sentrySpanIdString);
  id<SentrySpan> toActiveSpan;
  @synchronized(self.spans) {
  toActiveSpan = self.spans[spanId];
  }
 
  if (toActiveSpan == nil) {
+ SENTRY_LOG_DEBUG(@"No span found with ID %@", spanId.sentrySpanIdString);
  return NO;
  }
 
@@ -194,6 +203,7 @@ - (void)popActiveSpan
 
 - (void)finishSpan:(SentrySpanId *)spanId
 {
+ SENTRY_LOG_DEBUG(@"Finishing performance span %@", spanId.sentrySpanIdString);
  [self finishSpan:spanId withStatus:kSentrySpanStatusOk];
 }
 

Sources/Sentry/SentryProfiler.mm

@@ -329,8 +329,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);
  }
 }
 

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,8 @@ - (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.");
  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

Sources/Sentry/SentryUIEventTracker.m

@@ -4,6 +4,7 @@
 #import <SentrySDK+Private.h>
 #import <SentrySDK.h>
 #import <SentryScope.h>
+#import <SentrySpanId.h>
 #import <SentrySpanOperations.h>
 #import <SentrySpanProtocol.h>
 #import <SentryTracer.h>
@@ -51,7 +52,17 @@ - (void)start
 {
  [self.swizzleWrapper
  swizzleSendAction:^(NSString *action, id target, id sender, UIEvent *event) {
- if (target == nil || sender == nil) {
+ if (target == nil) {
+ SENTRY_LOG_DEBUG(@"Target was nil for action %@; won't capture in transaction "
+ @"(sender: %@; event: %@)",
+ action, sender, event);
+ return;
+ }
+
+ if (sender == nil) {
+ SENTRY_LOG_DEBUG(@"Sender was nil for action %@; won't capture in transaction "
+ @"(target: %@; event: %@)",
+ action, sender, event);
  return;
  }
 
@@ -63,6 +74,7 @@ - (void)start
 
  NSString *targetClass = NSStringFromClass([target class]);
  if ([targetClass containsString:@"SwiftUI"]) {
+ SENTRY_LOG_DEBUG(@"Won't record transaction for SwiftUI target event.");
  return;
  }
 
@@ -79,18 +91,18 @@ - (void)start
  BOOL sameAction =
  [currentActiveTransaction.transactionContext.name isEqualToString:transactionName];
  if (sameAction) {
+ SENTRY_LOG_DEBUG(@"Dispatching idle timeout for transaction with span id %@",
+ currentActiveTransaction.context.spanId.sentrySpanIdString);
  [currentActiveTransaction dispatchIdleTimeout];
  return;
  }
 
  [currentActiveTransaction finish];
 
  if (currentActiveTransaction) {
- [SentryLog
- logWithMessage:
- [NSString stringWithFormat:@"SentryUIEventTracker finished transaction %@",
- currentActiveTransaction.transactionContext.name]
- andLevel:kSentryLevelDebug];
+ SENTRY_LOG_DEBUG(@"SentryUIEventTracker finished transaction %@ (span ID %@)",
+ currentActiveTransaction.transactionContext.name,
+ currentActiveTransaction.context.spanId.sentrySpanIdString);
  }
 
  NSString *operation = [self getOperation:sender];
@@ -116,12 +128,9 @@ - (void)start
  idleTimeout:self.idleTimeout
  dispatchQueueWrapper:self.dispatchQueueWrapper];
 
- [SentryLog
- logWithMessage:[NSString stringWithFormat:@"SentryUIEventTracker automatically "
- @"started a new transaction with "
- @"name: %@, bindToScope: %@",
- transactionName, bindToScope ? @"YES" : @"NO"]
- andLevel:kSentryLevelDebug];
+ SENTRY_LOG_DEBUG(@"SentryUIEventTracker automatically started a new transaction "
+ @"with name: %@, bindToScope: %@",
+ transactionName, bindToScope ? @"YES" : @"NO");
  }];
 
  if ([[sender class] isSubclassOfClass:[UIView class]]) {
@@ -135,9 +144,15 @@ - (void)start
  transaction.finishCallback = ^(SentryTracer *tracer) {
  @synchronized(self.activeTransactions) {
  [self.activeTransactions removeObject:tracer];
+ SENTRY_LOG_DEBUG(
+ @"Active transactions after removing tracer for span ID %@: %@",
+ tracer.context.spanId.sentrySpanIdString, self.activeTransactions);
  }
  };
  @synchronized(self.activeTransactions) {
+ SENTRY_LOG_DEBUG(
+ @"Adding transaction %@ to list of active transactions (currently %@)",
+ transaction.context.spanId.sentrySpanIdString, self.activeTransactions);
  [self.activeTransactions addObject:transaction];
  }
  }