Added new logging to the RKRequestQueue for inspecting what is happening. Eliminated use of copy during iteration of the request queue to avoid issues with re-entrant invocations of the queue resulting in the queue becoming starved. Fixed a number of flaky tests by making the RKSpec helpers stub out network availability. closes #164

Code/Network/RKReachabilityObserver.m

@@ -17,7 +17,7 @@
 
 // Set Logging Component
 #undef RKLogComponent
-#define RKLogComponent lcl_cRestKitNetwork
+#define RKLogComponent lcl_cRestKitNetworkReachability
 
 // Constants
 NSString* const RKReachabilityStateChangedNotification = @"RKReachabilityStateChangedNotification";

Code/Network/RKRequest.m

@@ -263,7 +263,7 @@
     [[NSNotificationCenter defaultCenter] postNotificationName:RKRequestSentNotification object:self userInfo:nil];
 }
 
-- (BOOL)shouldDispatchRequest {
+- (BOOL)shouldDispatchRequest {    
     return [RKClient sharedClient] == nil || [[RKClient sharedClient] isNetworkAvailable];
 }
 
@@ -279,7 +279,7 @@
         }
     }
     
-	if ([self shouldDispatchRequest]) {
+	if ([self shouldDispatchRequest]) {        
 #if TARGET_OS_IPHONE
         // Background Request Policy support
         UIApplication* app = [UIApplication sharedApplication];
@@ -316,6 +316,8 @@
         [self fireAsynchronousRequest];
 #endif
 	} else {
+        RKLogTrace(@"Declined to dispatch request %@: shared client reported the network is not available.", self);
+        
 	    if (_cachePolicy & RKRequestCachePolicyLoadIfOffline &&
 			[self.cache hasResponseForRequest:self]) {
 
@@ -323,6 +325,7 @@
 			[self didFinishLoad:[self.cache responseForRequest:self]];
 
 		} else {
+            RKLogCritical(@"SharedClient = %@ and network availability = %d", [RKClient sharedClient], [[RKClient sharedClient] isNetworkAvailable]);
             NSString* errorMessage = [NSString stringWithFormat:@"The client is unable to contact the resource at %@", [[self URL] absoluteString]];
     		NSDictionary *userInfo = [NSDictionary dictionaryWithObjectsAndKeys:
     								  errorMessage, NSLocalizedDescriptionKey,

Code/Network/RKRequestQueue.m

@@ -14,11 +14,16 @@
 #import "RKResponse.h"
 #import "RKNotifications.h"
 #import "RKClient.h"
+#import "../Support/RKLog.h"
 
 static RKRequestQueue* gSharedQueue = nil;
 
 static const NSTimeInterval kFlushDelay = 0.3;
 
+// Set Logging Component
+#undef RKLogComponent
+#define RKLogComponent lcl_cRestKitNetworkQueue
+
 @interface RKRequestQueue (Private)
 
 // Declare the loading count read-write
@@ -41,14 +46,16 @@ static const NSTimeInterval kFlushDelay = 0.3;
 	if (!gSharedQueue) {
 		gSharedQueue = [[RKRequestQueue alloc] init];
 		gSharedQueue.suspended = NO;
+        RKLogDebug(@"Shared queue initialized: %@", gSharedQueue);
 	}
 	return gSharedQueue;
 }
 
 + (void)setSharedQueue:(RKRequestQueue*)requestQueue {
 	if (gSharedQueue != requestQueue) {
+        RKLogDebug(@"Shared queue instance changed from %@ to %@", gSharedQueue, requestQueue);
 		[gSharedQueue release];
-		gSharedQueue = [requestQueue retain];
+		gSharedQueue = [requestQueue retain];        
 	}
 }
 
@@ -87,13 +94,14 @@ static const NSTimeInterval kFlushDelay = 0.3;
 }
 
 - (void)dealloc {
-  [[NSNotificationCenter defaultCenter] removeObserver:self];
+    RKLogDebug(@"Queue instance is being deallocated: %@", self);
+    [[NSNotificationCenter defaultCenter] removeObserver:self];
 
-	[_queueTimer invalidate];
-	[_requests release];
-	_requests = nil;
+    [_queueTimer invalidate];
+    [_requests release];
+    _requests = nil;
 
-	[super dealloc];
+    [super dealloc];
 }
 
 - (NSUInteger)count {
@@ -102,6 +110,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
 
 - (void)setLoadingCount:(NSUInteger)count {
     if (_loadingCount == 0 && count > 0) {
+        RKLogTrace(@"Loading count increasing from 0 to %d. Firing requestQueueDidBeginLoading", count);
+        
         // Transitioning from empty to processing
         if ([_delegate respondsToSelector:@selector(requestQueueDidBeginLoading:)]) {
             [_delegate requestQueueDidBeginLoading:self];
@@ -113,6 +123,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
         }
 #endif
     } else if (_loadingCount > 0 && count == 0) {
+        RKLogTrace(@"Loading count decreasing from %d to 0. Firing requestQueueDidFinishLoading", _loadingCount);
+        
         // Transition from processing to empty
         if ([_delegate respondsToSelector:@selector(requestQueueDidFinishLoading:)]) {
             [_delegate requestQueueDidFinishLoading:self];
@@ -125,6 +137,7 @@ static const NSTimeInterval kFlushDelay = 0.3;
 #endif
     }
     
+    RKLogTrace(@"Loading count set to %d for queue %@", count, self);
     _loadingCount = count;
 }
 
@@ -135,6 +148,7 @@ static const NSTimeInterval kFlushDelay = 0.3;
 													 selector:@selector(loadNextInQueue)
 													 userInfo:nil
 													  repeats:NO];
+        RKLogDebug(@"Timer initialized with delay %f for queue %@", kFlushDelay, self);
 	}
 }
 
@@ -144,6 +158,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
         self.suspended) {
 		_queueTimer = nil;
 		[self loadNextInQueueDelayed];
+        
+        RKLogTrace(@"Deferring queue loading because of %@", self.suspended ? @"queue suspension" : @"indeterminate network condition");
 		return;
 	}
 
@@ -151,15 +167,25 @@ static const NSTimeInterval kFlushDelay = 0.3;
 
 	_queueTimer = nil;
 
-	NSArray* requestsCopy = [NSArray arrayWithArray:_requests];
-	for (RKRequest* request in requestsCopy) {
-		if (![request isLoading] && ![request isLoaded] && self.loadingCount < _concurrentRequestsLimit) {            
+    NSUInteger count = [_requests count];
+    for (NSUInteger index = 0; index < count; index++) {
+        RKRequest* request = [_requests objectAtIndex:index];
+        RKLogTrace(@"Processing request %@ in queue %@", request, self);
+        
+		if ([request isLoading]) {
+            RKLogTrace(@"Skipping request %@: currently loading.", request);
+        } else if ([request isLoaded]) {
+            RKLogTrace(@"Skipping request %@: already loaded.", request);
+        } else if (self.loadingCount > _concurrentRequestsLimit) {
+            RKLogTrace(@"Skipping request %@: Maximum concurrent request limit of %d is reached", request, self.loadingCount);
+        } else {
             if ([_delegate respondsToSelector:@selector(requestQueue:willSendRequest:)]) {
                 [_delegate requestQueue:self willSendRequest:request];
             }
             
             self.loadingCount = self.loadingCount + 1;
             [request sendAsynchronously];
+            RKLogDebug(@"Sent request %@ from top of queue %@. Loading count = %d", request, self, self.loadingCount);
 
             if ([_delegate respondsToSelector:@selector(requestQueue:didSendRequest:)]) {
                 [_delegate requestQueue:self didSendRequest:request];
@@ -177,11 +203,15 @@ static const NSTimeInterval kFlushDelay = 0.3;
 - (void)setSuspended:(BOOL)isSuspended {    
     if (_suspended != isSuspended) {
         if (isSuspended) {
+            RKLogDebug(@"Queue %@ has been suspended", self);
+            
             // Becoming suspended
             if ([_delegate respondsToSelector:@selector(requestQueueWasSuspended:)]) {
                 [_delegate requestQueueWasSuspended:self];
             }
         } else {
+            RKLogDebug(@"Queue %@ has been unsuspended", self);
+            
             // Becoming unsupended
             if ([_delegate respondsToSelector:@selector(requestQueueWasUnsuspended:)]) {
                 [_delegate requestQueueWasUnsuspended:self];
@@ -200,6 +230,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
 }
 
 - (void)addRequest:(RKRequest*)request {
+    RKLogTrace(@"Request %@ added to queue %@", request, self);
+    
 	[_requests addObject:request];
 	[self loadNextInQueue];
 }
@@ -210,6 +242,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
 
 - (void)cancelRequest:(RKRequest*)request loadNext:(BOOL)loadNext {
     if (![request isLoading]) {
+        RKLogDebug(@"Canceled undispatched request %@ and removed from queue %@", request, self);
+        
         [_requests removeObject:request];
         request.delegate = nil;
         
@@ -217,6 +251,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
             [_delegate requestQueue:self didCancelRequest:request];
         }
     } else if ([_requests containsObject:request] && ![request isLoaded]) {
+        RKLogDebug(@"Canceled loading request %@ and removed from queue %@", request, self);
+        
 		[request cancel];
 		request.delegate = nil;
         
@@ -238,6 +274,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
 }
 
 - (void)cancelRequestsWithDelegate:(NSObject<RKRequestDelegate>*)delegate {
+    RKLogDebug(@"Cancelling all request in queue %@ with delegate %@", self, delegate);
+    
 	NSAutoreleasePool* pool = [[NSAutoreleasePool alloc] init];
 	NSArray* requestsCopy = [NSArray arrayWithArray:_requests];
 	for (RKRequest* request in requestsCopy) {
@@ -249,6 +287,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
 }
 
 - (void)cancelAllRequests {
+    RKLogDebug(@"Cancelling all request in queue %@", self);
+    
 	NSAutoreleasePool* pool = [[NSAutoreleasePool alloc] init];
 	NSArray* requestsCopy = [NSArray arrayWithArray:_requests];
 	for (RKRequest* request in requestsCopy) {
@@ -258,6 +298,7 @@ static const NSTimeInterval kFlushDelay = 0.3;
 }
 
 - (void)start {
+    RKLogDebug(@"Started queue %@", self);
     [self setSuspended:NO];
 }
 
@@ -279,6 +320,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
 		// Our RKRequest completed and we're notified with an RKResponse object
         if (request != nil && [self containsRequest:request]) { 
             if ([notification.object isKindOfClass:[RKResponse class]]) {
+                RKLogTrace(@"Received response for request %@, removing from queue.", request);
+                
                 [_requests removeObject:request];
                 self.loadingCount = self.loadingCount - 1;
                 
@@ -288,6 +331,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
 				
 				// Our RKRequest failed and we're notified with the original RKRequest object
             } else if ([notification.object isKindOfClass:[RKRequest class]]) {
+                RKLogTrace(@"Received failure notification for request %@, removing from queue.", request);
+                
                 [_requests removeObject:request];
                 self.loadingCount = self.loadingCount - 1;
                 
@@ -295,6 +340,7 @@ static const NSTimeInterval kFlushDelay = 0.3;
                 NSError* error = nil;
                 if (userInfo) {
                     error = [userInfo objectForKey:@"error"];
+                    RKLogDebug(@"Request %@ failed loading in queue %@ with error: %@", request, self, [error localizedDescription]);
                 }
                 
                 if ([_delegate respondsToSelector:@selector(requestQueue:didFailRequest:withError:)]) {
@@ -303,6 +349,8 @@ static const NSTimeInterval kFlushDelay = 0.3;
             }
 			
             [self loadNextInQueue];
+        } else {
+            RKLogWarning(@"Request queue %@ received unexpected lifecycle notification for request %@: Request not found in queue.", self, request);
         }
 	}
 }
@@ -310,11 +358,15 @@ static const NSTimeInterval kFlushDelay = 0.3;
 #pragma mark - Background Request Support
 
 - (void)willTransitionToBackground {
+    RKLogDebug(@"App is transitioning into background, suspending queue");
+    
     // Suspend the queue so background requests do not trigger additional requests on state changes
     self.suspended = YES;
 }
 
 - (void)willTransitionToForeground {
+    RKLogDebug(@"App returned from background, unsuspending queue");
+    
     self.suspended = NO;
 }
 

Code/Support/lcl_config_components.h

@@ -37,8 +37,10 @@
 // RestKit Logging Components
 //
 
-_lcl_component(RestKit,                 "restkit",                  "RestKit")
-_lcl_component(RestKitNetwork,          "restkit.network",          "RestKit/Network")
-_lcl_component(RestKitNetworkCache,     "restkit.network.cache",    "RestKit/Network/Cache")
-_lcl_component(RestKitObjectMapping,    "restkit.object_mapping",   "RestKit/ObjectMapping")
-_lcl_component(RestKitCoreData,         "restkit.core_data",        "RestKit/CoreData")
+_lcl_component(RestKit,                     "restkit",                      "RestKit")
+_lcl_component(RestKitNetwork,              "restkit.network",              "RestKit/Network")
+_lcl_component(RestKitNetworkCache,         "restkit.network.cache",        "RestKit/Network/Cache")
+_lcl_component(RestKitNetworkQueue,         "restkit.network.queue",        "RestKit/Network/Queue")
+_lcl_component(RestKitNetworkReachability,  "restkit.network.reachability", "RestKit/Network/Reachability")
+_lcl_component(RestKitObjectMapping,        "restkit.object_mapping",       "RestKit/ObjectMapping")
+_lcl_component(RestKitCoreData,             "restkit.core_data",            "RestKit/CoreData")

RestKit.xcodeproj/xcshareddata/xcschemes/UISpec.xcscheme

@@ -87,8 +87,8 @@
          </EnvironmentVariable>
          <EnvironmentVariable
             key = "UISPEC_SPEC"
-            value = "RKManagedObjectMappingSpec"
-            isEnabled = "YES">
+            value = "RKObjectManagerSpec"
+            isEnabled = "NO">
          </EnvironmentVariable>
          <EnvironmentVariable
             key = "UISPEC_EXAMPLE"

Specs/Network/RKRequestSpec.m

@@ -30,6 +30,7 @@
 - (void)itShouldSendMultiPartRequests {
 	NSString* URLString = [NSString stringWithFormat:@"http://127.0.0.1:4567/photo"];
 	NSURL* URL = [NSURL URLWithString:URLString];
+    RKSpecStubNetworkAvailability(YES);
 	RKRequest* request = [[RKRequest alloc] initWithURL:URL];
 	RKParams* params = [[RKParams params] retain];
 	NSString* filePath = [[NSBundle mainBundle] pathForResource:@"blake" ofType:@"png"];
@@ -184,7 +185,6 @@
 }
 
 - (void)itShouldCacheTheRequestHeadersAndBodyIncludingOurOwnCustomTimestampHeader {
-    RKLogConfigureByName("RestKit/Network/Cache", RKLogLevelTrace);
     NSString* baseURL = RKSpecGetBaseURL();
     NSString* cacheDirForClient = [NSString stringWithFormat:@"RKClientRequestCache-%@",
 								   [[NSURL URLWithString:baseURL] host]];
@@ -410,7 +410,10 @@
     [params setValue: @"password" forParam:@"password"];
     
     RKClient* client = RKSpecNewClient();
+    client.cachePolicy = RKRequestCachePolicyNone;
+    RKSpecStubNetworkAvailability(YES);
     RKSpecResponseLoader* loader = [RKSpecResponseLoader responseLoader];
+    loader.timeout = 20;
     [client post:@"/echo_params" params:params delegate:loader];
     [loader waitForResponse];
     assertThat([loader.response bodyAsString], is(equalTo(@"{\"username\":\"hello\",\"password\":\"password\"}")));

Specs/Network/RKResponseSpec.m

@@ -211,7 +211,7 @@
     RKResponse* response = [[[RKResponse alloc] init] autorelease];
 	id mock = [OCMockObject partialMockForObject:response];
 	[[[mock stub] andReturn:@"sad;sdvjnk;"] bodyAsString];
-    [[[mock stub] andReturn:@"application/json"] contentType];
+    [[[mock stub] andReturn:@"application/json"] MIMEType];
     NSError* error = nil;
     id object = [mock parsedBody:&error];
     assertThat(object, is(nilValue()));

Specs/ObjectMapping/RKObjectManagerSpec.m

@@ -66,6 +66,8 @@
     RKObjectRouter* router = [[[RKObjectRouter alloc] init] autorelease];
     [router routeClass:[RKHuman class] toResourcePath:@"/humans" forMethod:RKRequestMethodPOST];
     _objectManager.router = router;
+    
+    RKSpecStubNetworkAvailability(YES);
 }
 
 - (void)itShouldSetTheAcceptHeaderAppropriatelyForTheFormat {
@@ -109,9 +111,9 @@
 
 // TODO: Move to Core Data specific spec file...
 - (void)itShouldLoadAHuman {
-    RKSpecResponseLoader* loader = [RKSpecResponseLoader responseLoader];
+    assertThatBool([RKClient sharedClient].isNetworkAvailable, is(equalToBool(YES)));
+    RKSpecResponseLoader* loader = [RKSpecResponseLoader responseLoader];    
 	[_objectManager loadObjectsAtResourcePath:@"/JSON/humans/1.json" delegate:loader];
-    loader.timeout = 200;
 	[loader waitForResponse];
     [expectThat(loader.failureError) should:be(nil)];
     assertThat(loader.objects, isNot(empty()));
@@ -140,6 +142,9 @@
 
 - (void)itShouldPOSTAnObject {
     RKObjectManager* manager = RKSpecNewObjectManager();
+    RKSpecStubNetworkAvailability(YES);
+    assertThatBool([RKClient sharedClient].isNetworkAvailable, is(equalToBool(YES)));
+    
     RKObjectRouter* router = [[RKObjectRouter new] autorelease];
     [router routeClass:[RKObjectMapperSpecModel class] toResourcePath:@"/humans" forMethod:RKRequestMethodPOST];
     manager.router = router;

Specs/ObjectMapping/RKObjectMappingNextGenSpec.m

@@ -409,7 +409,6 @@
 }
 
 - (void)itShouldMapACollectionOfObjectsWithDynamicKeys {
-    RKLogConfigureByName("RestKit/*", RKLogLevelTrace);
     RKObjectMapping* mapping = [RKObjectMapping mappingForClass:[RKExampleUser class]];
     mapping.forceCollectionMapping = YES;
     [mapping mapKeyOfNestedDictionaryToAttribute:@"name"];    
@@ -433,7 +432,6 @@
 }
 
 - (void)itShouldMapACollectionOfObjectsWithDynamicKeysAndRelationships {
-    RKLogConfigureByName("RestKit/*", RKLogLevelTrace);
     RKObjectMapping* mapping = [RKObjectMapping mappingForClass:[RKExampleUser class]];
     mapping.forceCollectionMapping = YES;
     [mapping mapKeyOfNestedDictionaryToAttribute:@"name"];
@@ -1246,9 +1244,9 @@
 
 #pragma mark - RKObjectMappingProvider
 
-- (void)itShouldRegisterRailsIdiomaticObjects {
-    RKSpecStubNetworkAvailability(YES);
+- (void)itShouldRegisterRailsIdiomaticObjects {    
     RKObjectManager* objectManager = RKSpecNewObjectManager();
+    RKSpecStubNetworkAvailability(YES);
     RKObjectMapping* mapping = [RKObjectMapping mappingForClass:[RKExampleUser class]];
     [mapping mapAttributes:@"name", @"website", nil];
     [mapping mapKeyPath:@"id" toAttribute:@"userID"];

Specs/ObjectMapping/RKObjectMappingOperationSpec.m

@@ -51,7 +51,6 @@
 }
 
 - (void)itShouldSuccessfullyMapBoolsToStrings {
-    RKLogConfigureByName("*", RKLogLevelTrace);
     RKObjectMapping* mapping = [RKObjectMapping mappingForClass:[TestMappable class]];
     [mapping mapAttributes:@"boolString", nil];
     TestMappable* object = [[[TestMappable alloc] init] autorelease];

Specs/Runner/RKSpecEnvironment.m

@@ -28,9 +28,12 @@ void RKSpecStubNetworkAvailability(BOOL isNetworkAvailable) {
 
 RKClient* RKSpecNewClient() {
     RKClient* client = [RKClient clientWithBaseURL:RKSpecGetBaseURL()];
-    [RKClient setSharedClient:client];
+    [RKClient setSharedClient:client];    
     [client release];
     
+    RKSpecNewRequestQueue();
+    RKSpecStubNetworkAvailability(YES);
+    
     return client;
 }
 
@@ -47,10 +50,12 @@ RKObjectManager* RKSpecNewObjectManager() {
     RKObjectManager* objectManager = [RKObjectManager objectManagerWithBaseURL:RKSpecGetBaseURL()];
     [RKObjectManager setSharedManager:objectManager];
     [RKClient setSharedClient:objectManager.client];
+    
     RKSpecNewRequestQueue();
+    RKSpecStubNetworkAvailability(YES);
     
     // This allows the manager to determine state.
-    [[NSRunLoop currentRunLoop] runUntilDate:[NSDate dateWithTimeIntervalSinceNow:0.01]];
+    [[NSRunLoop currentRunLoop] runUntilDate:[NSDate dateWithTimeIntervalSinceNow:0.2]];
     
     return objectManager;
 }