Log the number of work items when adding/removing to MTRAsyncWorkQueu…

…e. (#32832)

We used to have logging for this, but it seems to have gotten lost.  Would be
useful to know how many work items are in the queue after one is added.

Also makes ContextSnapshot assert the relevant lock is not held, and cleans up
some manual lock/unlock to use the auto helper.

src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm

@@ -33,20 +33,6 @@ typedef NS_ENUM(NSInteger, MTRAsyncWorkItemState) {
     MTRAsyncWorkItemRetryCountBase = MTRAsyncWorkItemRunning, // values >= MTRAsyncWorkItemRunning encode retryCount
 };
 
-// A helper struct that facilitates access to _context while
-//  - only reading the _context weak reference once and retaining a strong
-//    reference for the duration of a particular queue method call
-//  - avoiding calls to `[context description]` under our lock
-struct ContextSnapshot {
-    id _Nullable reference;
-    NSString * _Nullable description;
-    ContextSnapshot(id _Nullable context)
-    {
-        reference = context;
-        description = [context description];
-    }
-};
-
 MTR_DIRECT_MEMBERS
 @implementation MTRAsyncWorkItem {
     dispatch_queue_t _queue;
@@ -214,6 +200,21 @@ @implementation MTRAsyncWorkQueue {
     NSInteger _runningWorkItemCount;
 }
 
+// A helper struct that facilitates access to _context while
+//  - only reading the _context weak reference once and retaining a strong
+//    reference for the duration of a particular queue method call
+//  - avoiding calls to `[context description]` under our lock
+struct ContextSnapshot {
+    id _Nullable reference;
+    NSString * _Nullable description;
+    ContextSnapshot(MTRAsyncWorkQueue * queue)
+    {
+        os_unfair_lock_assert_not_owner(&queue->_lock);
+        reference = queue->_context;
+        description = [reference description];
+    }
+};
+
 - (instancetype)initWithContext:(id)context
 {
     NSParameterAssert(context);
@@ -224,13 +225,18 @@ - (instancetype)initWithContext:(id)context
     return self;
 }
 
+- (NSString *)_lockedSelfDescription:(const ContextSnapshot &)context
+{
+    os_unfair_lock_assert_owner(&_lock);
+
+    return [NSString stringWithFormat:@"%@, items count: %tu", context.description, _items.count];
+}
+
 - (NSString *)description
 {
-    NSUInteger itemsCount;
-    os_unfair_lock_lock(&_lock);
-    itemsCount = _items.count;
-    os_unfair_lock_unlock(&_lock);
-    return [NSString stringWithFormat:@"<%@ context: %@ items count: %tu>", self.class, _context, itemsCount];
+    ContextSnapshot context(self);
+    std::lock_guard lock(_lock);
+    return [NSString stringWithFormat:@"<%@ context: %@>", self.class, [self _lockedSelfDescription:context]];
 }
 
 - (void)enqueueWorkItem:(MTRAsyncWorkItem *)item
@@ -251,29 +257,28 @@ - (void)enqueueWorkItem:(MTRAsyncWorkItem *)item
             description:(nullable NSString *)description
 {
     NSParameterAssert(item);
-    ContextSnapshot context(_context); // outside of lock
+    ContextSnapshot context(self); // outside of lock
     NSAssert(context.reference, @"context has been lost");
 
-    os_unfair_lock_lock(&_lock);
+    std::lock_guard lock(_lock);
     [item markEnqueued];
     [_items addObject:item];
 
     if (description) {
         // Logging the description once is enough because other log messages
         // related to the work item (execution, completion etc) can easily be
         // correlated using the unique id.
-        MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> enqueued work item [%llu]: %@", context.description, item.uniqueID, description);
+        MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> enqueued work item [%llu]: %@", [self _lockedSelfDescription:context], item.uniqueID, description);
     } else {
-        MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> enqueued work item [%llu]", context.description, item.uniqueID);
+        MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> enqueued work item [%llu]", [self _lockedSelfDescription:context], item.uniqueID);
     }
 
     [self _callNextReadyWorkItemWithContext:context];
-    os_unfair_lock_unlock(&_lock);
 }
 
 - (void)invalidate
 {
-    ContextSnapshot context(_context); // outside of lock
+    ContextSnapshot context(self); // outside of lock
     std::lock_guard lock(_lock);
     MTR_LOG_INFO("MTRAsyncWorkQueue<%@> invalidate %tu items", context.description, _items.count);
     for (MTRAsyncWorkItem * item in _items) {
@@ -299,7 +304,7 @@ - (void)_postProcessWorkItem:(MTRAsyncWorkItem *)workItem
     } else {
         [workItem markComplete];
         [_items removeObjectAtIndex:0];
-        MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> completed work item [%llu]", context.description, workItem.uniqueID);
+        MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> completed work item [%llu]", [self _lockedSelfDescription:context], workItem.uniqueID);
     }
 
     // when "concurrency width" is implemented this will be decremented instead
@@ -362,13 +367,12 @@ - (void)_callNextReadyWorkItemWithContext:(ContextSnapshot const &)context
         mtr_strongify(self);
         BOOL handled = NO;
         if (self) {
-            ContextSnapshot context(self->_context); // re-acquire a new snapshot
-            os_unfair_lock_lock(&self->_lock);
+            ContextSnapshot context(self); // re-acquire a new snapshot
+            std::lock_guard lock(self->_lock);
             if (!workItem.isComplete) {
                 [self _postProcessWorkItem:workItem context:context retry:(outcome == MTRAsyncWorkNeedsRetry)];
                 handled = YES;
             }
-            os_unfair_lock_unlock(&self->_lock);
         }
         return handled;
     }];