Fixing xpc client retry/timeout

MPMessagePack.podspec

@@ -1,7 +1,7 @@
 Pod::Spec.new do |s|
 
   s.name         = "MPMessagePack"
-  s.version      = "1.3.10"
+  s.version      = "1.3.11"
   s.summary      = "Library for MessagePack"
   s.homepage     = "https://github.com/gabriel/MPMessagePack"
   s.license      = { :type => "MIT" }

MPMessagePack.xcodeproj/project.pbxproj

@@ -26,6 +26,8 @@
 		0013923A1B041AD30082DEA8 /* MPXPCClient.m in Sources */ = {isa = PBXBuildFile; fileRef = 002A2C131AF98AB1006DFB51 /* MPXPCClient.m */; };
 		0013923B1B041AD30082DEA8 /* MPXPCProtocol.h in Headers */ = {isa = PBXBuildFile; fileRef = 002A2C161AF98BB6006DFB51 /* MPXPCProtocol.h */; settings = {ATTRIBUTES = (Public, ); }; };
 		0013923C1B041AD30082DEA8 /* MPXPCProtocol.m in Sources */ = {isa = PBXBuildFile; fileRef = 002A2C171AF98BB6006DFB51 /* MPXPCProtocol.m */; };
+		003378A31D78F4DB00888BFA /* MPLog.h in Headers */ = {isa = PBXBuildFile; fileRef = 003378A11D78F4DB00888BFA /* MPLog.h */; settings = {ATTRIBUTES = (Public, ); }; };
+		003378A41D78F4DB00888BFA /* MPLog.h in Headers */ = {isa = PBXBuildFile; fileRef = 003378A11D78F4DB00888BFA /* MPLog.h */; settings = {ATTRIBUTES = (Public, ); }; };
 		004270D11B14E74C006F17C7 /* MPMessagePack.h in Headers */ = {isa = PBXBuildFile; fileRef = 006555AF19662E3000288AE7 /* MPMessagePack.h */; settings = {ATTRIBUTES = (Public, ); }; };
 		004CF22E1B9393EF002BE5A4 /* MPMessagePackClient.h in Headers */ = {isa = PBXBuildFile; fileRef = 004CF22A1B9393EF002BE5A4 /* MPMessagePackClient.h */; settings = {ATTRIBUTES = (Public, ); }; };
 		004CF22F1B9393EF002BE5A4 /* MPMessagePackClient.m in Sources */ = {isa = PBXBuildFile; fileRef = 004CF22B1B9393EF002BE5A4 /* MPMessagePackClient.m */; };
@@ -88,6 +90,7 @@
 		002A2C131AF98AB1006DFB51 /* MPXPCClient.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = MPXPCClient.m; sourceTree = "<group>"; };
 		002A2C161AF98BB6006DFB51 /* MPXPCProtocol.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MPXPCProtocol.h; sourceTree = "<group>"; };
 		002A2C171AF98BB6006DFB51 /* MPXPCProtocol.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = MPXPCProtocol.m; sourceTree = "<group>"; };
+		003378A11D78F4DB00888BFA /* MPLog.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MPLog.h; sourceTree = "<group>"; };
 		004CF22A1B9393EF002BE5A4 /* MPMessagePackClient.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MPMessagePackClient.h; sourceTree = "<group>"; };
 		004CF22B1B9393EF002BE5A4 /* MPMessagePackClient.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = MPMessagePackClient.m; sourceTree = "<group>"; };
 		004CF22C1B9393EF002BE5A4 /* MPMessagePackServer.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MPMessagePackServer.h; sourceTree = "<group>"; };
@@ -248,6 +251,7 @@
 				004D14A11A3D1D210083888D /* MPDefines.h */,
 				007110B11A5B68DB005DF8D1 /* NSData+MPMessagePack.h */,
 				007110B21A5B68DB005DF8D1 /* NSData+MPMessagePack.m */,
+				003378A11D78F4DB00888BFA /* MPLog.h */,
 			);
 			path = MPMessagePack;
 			sourceTree = "<group>";
@@ -278,6 +282,7 @@
 			files = (
 				001392301B0418EF0082DEA8 /* NSData+MPMessagePack.h in Headers */,
 				001392271B0418EF0082DEA8 /* NSDictionary+MPMessagePack.h in Headers */,
+				003378A31D78F4DB00888BFA /* MPLog.h in Headers */,
 				009D441C1BCEF7560030DD7E /* MPDispatchRequest.h in Headers */,
 				001392371B041AD30082DEA8 /* MPXPCService.h in Headers */,
 				004CF22E1B9393EF002BE5A4 /* MPMessagePackClient.h in Headers */,
@@ -307,6 +312,7 @@
 				33220B2B1CFF954B00F3C3DA /* NSData+MPMessagePack.h in Headers */,
 				33220B2A1CFF954B00F3C3DA /* MPDefines.h in Headers */,
 				33220B2D1CFF954F00F3C3DA /* MPMessagePackClient.h in Headers */,
+				003378A41D78F4DB00888BFA /* MPLog.h in Headers */,
 				33220B221CFF954B00F3C3DA /* MPMessagePackWriter.h in Headers */,
 				33220B241CFF954B00F3C3DA /* MPMessagePackReader.h in Headers */,
 				33220B211CFF954B00F3C3DA /* cmp.h in Headers */,
@@ -778,6 +784,7 @@
 				33220B1D1CFF952F00F3C3DA /* Release */,
 			);
 			defaultConfigurationIsVisible = 0;
+			defaultConfigurationName = Release;
 		};
 /* End XCConfigurationList section */
 	};

MPMessagePack/MPLog.h

@@ -0,0 +1,22 @@
+//
+//  MPLog.h
+//  MPMessagePack
+//
+//  Created by Gabriel on 9/1/16.
+//  Copyright © 2016 Gabriel Handford. All rights reserved.
+//
+
+#import <Foundation/Foundation.h>
+
+typedef NS_ENUM (NSInteger, MPLogLevel) {
+  MPLogLevelDefault = 0,
+  MPLogLevelVerbose = 20,
+  MPLogLevelDebug = 20,
+  MPLogLevelInfo = 30,
+  MPLogLevelWarn = 40,
+  MPLogLevelError = 50,
+};
+
+@protocol MPLog <NSObject>
+- (void)log:(MPLogLevel)level format:(NSString *)format, ...;
+@end

MPMessagePack/MPMessagePack.h

@@ -20,6 +20,7 @@ FOUNDATION_EXPORT const unsigned char MPMessagePackVersionString[];
 #import <MPMessagePack/MPMessagePackWriter.h>
 #import <MPMessagePack/MPMessagePackReader.h>
 
+#import <MPMessagePack/MPLog.h>
 #import <MPMessagePack/MPMessagePackClient.h>
 #import <MPMessagePack/MPMessagePackServer.h>
 #import <MPMessagePack/MPRPCProtocol.h>

XPC/MPXPCClient.h

@@ -9,13 +9,17 @@
 #import <Foundation/Foundation.h>
 
 #import "MPMessagePackReader.h"
+#import "MPLog.h"
 
 @interface MPXPCClient : NSObject
 
 @property (readonly) NSString *serviceName;
 @property (readonly) BOOL privileged;
 @property (readonly) MPMessagePackReaderOptions readOptions;
 @property NSTimeInterval timeout;
+@property BOOL retryMaxAttempts;
+@property NSTimeInterval retryDelay;
+@property (weak) id<MPLog> logDelegate;
 
 - (instancetype)initWithServiceName:(NSString *)serviceName privileged:(BOOL)privileged;
 - (instancetype)initWithServiceName:(NSString *)serviceName privileged:(BOOL)privileged readOptions:(MPMessagePackReaderOptions)readOptions ;
@@ -24,8 +28,6 @@
 
 - (void)sendRequest:(NSString *)method params:(NSArray *)params completion:(void (^)(NSError *error, id value))completion;
 
-- (void)sendRequest:(NSString *)method params:(NSArray *)params maxAttempts:(NSInteger)maxAttempts retryDelay:(NSTimeInterval)retryDelay completion:(void (^)(NSError *error, id value))completion;
-
 - (void)close;
 
 @end

XPC/MPXPCClient.m

@@ -34,13 +34,14 @@ - (instancetype)initWithServiceName:(NSString *)serviceName privileged:(BOOL)pri
   if ((self = [super init])) {
     _serviceName = serviceName;
     _privileged = privileged;
-    _timeout = 2.0;
+    _retryMaxAttempts = 1; // No retry by default (only 1 attempt is made)
     _readOptions = readOptions;
   }
   return self;
 }
 
 - (BOOL)connect:(NSError **)error {
+  [self.logDelegate log:MPLogLevelInfo format:@"Connecting to %@ (privileged=%@)", _serviceName, @(_privileged)];
   _connection = xpc_connection_create_mach_service([_serviceName UTF8String], NULL, _privileged ? XPC_CONNECTION_MACH_SERVICE_PRIVILEGED : 0);
 
   if (!_connection) {
@@ -54,10 +55,13 @@ - (BOOL)connect:(NSError **)error {
     if (type == XPC_TYPE_ERROR) {
       if (event == XPC_ERROR_CONNECTION_INTERRUPTED) {
         // Interrupted
+        [wself.logDelegate log:MPLogLevelWarn format:@"Connection interrupted"];
       } else if (event == XPC_ERROR_CONNECTION_INVALID) {
+        [wself.logDelegate log:MPLogLevelWarn format:@"Connection invalid, clearing connection"];
         if (wself.connection) {
           dispatch_async(dispatch_get_main_queue(), ^{
             wself.connection = nil;
+            [wself.logDelegate log:MPLogLevelWarn format:@"Cleared connection"];
           });
         }
       } else {
@@ -69,30 +73,62 @@ - (BOOL)connect:(NSError **)error {
   });
 
   xpc_connection_resume(_connection);
+  [self.logDelegate log:MPLogLevelInfo format:@"Connected"];
   return YES;
 }
 
 - (void)close {
+  [self.logDelegate log:MPLogLevelInfo format:@"Closing connection"];
   if (_connection) {
     xpc_connection_cancel(_connection);
     _connection = nil;
   }
 }
 
 - (void)sendRequest:(NSString *)method params:(NSArray *)params completion:(void (^)(NSError *error, id value))completion {
-  [self sendRequest:method params:params attempt:1 maxAttempts:2 retryDelay:0 completion:completion];
-}
+  __block BOOL replied = NO;
+  static NSInteger requestId = 0;
+  if (_timeout > 0) {
+    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, _timeout * NSEC_PER_SEC), dispatch_get_main_queue(), ^{
+      if (!replied) {
+        replied = YES;
+        completion(MPMakeError(MPXPCErrorCodeTimeout, @"Timeout"), nil);
+      }
+    });
+  }
+  NSUInteger rid = requestId++;
+  //[self.logDelegate log:MPLogLevelVerbose format:@"Request start (%@)", @(rid)];
+  [self _sendRequest:method params:params attempt:1 maxAttempts:_retryMaxAttempts retryDelay:_retryDelay requestId:rid completion:^(NSError *error, id value) {
+    if (replied) {
+      //[self.logDelegate log:MPLogLevelVerbose format:@"Ignoring event, we already completed (%@)", @(requestId)];
+      return;
+    }
 
-- (void)sendRequest:(NSString *)method params:(NSArray *)params maxAttempts:(NSInteger)maxAttempts retryDelay:(NSTimeInterval)retryDelay completion:(void (^)(NSError *error, id value))completion {
-  [self sendRequest:method params:params attempt:1 maxAttempts:maxAttempts retryDelay:retryDelay completion:completion];
+    replied = YES;
+    //[self.logDelegate log:MPLogLevelVerbose format:@"Request completion (%@)", @(rid)];
+    completion(error, value);
+  }];
 }
 
-- (void)sendRequest:(NSString *)method params:(NSArray *)params attempt:(NSInteger)attempt maxAttempts:(NSInteger)maxAttempts retryDelay:(NSTimeInterval)retryDelay completion:(void (^)(NSError *error, id value))completion {
+- (void)_sendRequest:(NSString *)method params:(NSArray *)params attempt:(NSInteger)attempt maxAttempts:(NSInteger)maxAttempts retryDelay:(NSTimeInterval)retryDelay requestId:(NSUInteger)requestId completion:(void (^)(NSError *error, id value))completion {
+
+  if (attempt < 1) {
+    completion(MPMakeError(-1, @"Invalid attempt number"), nil);
+    return;
+  }
+
   if (!_connection) {
     NSError *error = nil;
     if (![self connect:&error]) {
-      completion(error, nil);
-      return;
+      if (attempt >= maxAttempts) {
+        completion(error, nil);
+        return;
+      } else {
+        [self.logDelegate log:MPLogLevelError format:@"Retrying connect after XPC connect (requestId=%@) error: %@", @(requestId), error];
+        dispatch_after(dispatch_time(DISPATCH_TIME_NOW, retryDelay * NSEC_PER_SEC), dispatch_get_main_queue(), ^{
+          [self _sendRequest:method params:params attempt:attempt+1 maxAttempts:maxAttempts retryDelay:retryDelay requestId:requestId completion:completion];
+        });
+      }
     }
   }
 
@@ -103,36 +139,27 @@ - (void)sendRequest:(NSString *)method params:(NSArray *)params attempt:(NSInteg
     return;
   }
 
-  // For timeout (TODO cancelable block?)
-  __block BOOL replied = NO;
-  if (_timeout > 0) {
-    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, _timeout * NSEC_PER_SEC), dispatch_get_main_queue(), ^{
-      if (!replied) {
-        completion(MPMakeError(MPXPCErrorCodeTimeout, @"Timeout"), nil);
-      }
-    });
-  }
-
   if (!_connection) {
     completion(MPMakeError(MPXPCErrorCodeInvalidConnection, @"No connection"), nil);
     return;
   }
 
+  //[self.logDelegate log:MPLogLevelVerbose format:@"Sending request (%@)", @(requestId)];
   xpc_connection_send_message_with_reply(_connection, message, dispatch_get_main_queue(), ^(xpc_object_t event) {
     if (xpc_get_type(event) == XPC_TYPE_ERROR) {
-      // If we failed on retry, return error, otherwise retry
-      if (attempt == maxAttempts) {
-        replied = YES;
-        const char *description = xpc_dictionary_get_string(event, "XPCErrorDescription");
-        NSString *errorMessage = [NSString stringWithCString:description encoding:NSUTF8StringEncoding];
-        completion(MPMakeError(MPXPCErrorCodeInvalidConnection, @"XPC Error: %@", errorMessage), nil);
+      const char *description = xpc_dictionary_get_string(event, "XPCErrorDescription");
+      NSString *errorMessage = [NSString stringWithCString:description encoding:NSUTF8StringEncoding];
+      NSError *xpcError = MPMakeError(MPXPCErrorCodeInvalidConnection, @"XPC Error: %@", errorMessage);
+      if (attempt >= maxAttempts) {
+        [self.logDelegate log:MPLogLevelError format:@"Max attempts reached (%@ >= %@)", @(attempt), @(maxAttempts)];
+        completion(xpcError, nil);
       } else {
+        [self.logDelegate log:MPLogLevelError format:@"Retrying (attempt=%@, requestId=%@) after XPC error: %@", @(attempt), @(requestId), xpcError];
         dispatch_after(dispatch_time(DISPATCH_TIME_NOW, retryDelay * NSEC_PER_SEC), dispatch_get_main_queue(), ^{
-          [self sendRequest:method params:params attempt:attempt+1 maxAttempts:maxAttempts retryDelay:retryDelay completion:completion];
+          [self _sendRequest:method params:params attempt:attempt+1 maxAttempts:maxAttempts retryDelay:retryDelay requestId:requestId completion:completion];
         });
       }
     } else if (xpc_get_type(event) == XPC_TYPE_DICTIONARY) {
-      replied = YES;
       NSError *error = nil;
       size_t length = 0;
       const void *buffer = xpc_dictionary_get_data(event, "data", &length);