Merge pull request #163 from nextcloud/fix-api-not-responding

WIP: add more debugging output / destroy api when reconnect fails

Author: tobiasKaminsky

src/main/java/com/nextcloud/android/sso/api/AidlNetworkRequest.java

@@ -51,7 +51,7 @@ public class AidlNetworkRequest extends NetworkRequest {
      */
     private ServiceConnection mConnection = new ServiceConnection() {
         public void onServiceConnected(ComponentName className, IBinder service) {
-            Log.v(TAG, "Nextcloud Single sign-on: onServiceConnected [" + Thread.currentThread().getName() + "]");
+            Log.d(TAG, "[onServiceConnected] called from Thread: [" + Thread.currentThread().getName() + "] with IBinder [" + className.toString() + "]: " + service);
 
             mService = IInputStreamService.Stub.asInterface(service);
             mBound.set(true);
@@ -62,56 +62,75 @@ public void onServiceConnected(ComponentName className, IBinder service) {
         }
 
         public void onServiceDisconnected(ComponentName className) {
-            Log.e(TAG, "Nextcloud Single sign-on: ServiceDisconnected");
+            Log.w(TAG, "[onServiceDisconnected] [" + className.toString() + "]");
             // This is called when the connection with the service has been
-            // unexpectedly disconnected -- that is, its process crashed.
-            mService = null;
-            mBound.set(false);
+            // unexpectedly disconnected -- that is, its process crashed or the service was
+            // terminated due to an update (e.g. google play store)
 
             if (!mDestroyed) {
-                connectApiWithBackoff();
+                // In case we're currently not reconnecting
+                Log.d(TAG, "[onServiceDisconnected] Reconnecting lost service connection to component: [" + className.toString() + "]");
+                reconnect();
+            } else {
+                // API was destroyed on purpose
+                mService = null;
+                mBound.set(false);
             }
         }
     };
 
     public void connect(String type) {
-        if (mDestroyed) {
-            throw new IllegalStateException("API already stopped");
-        }
-
+        Log.d(TAG, "[connect] Binding to AccountManagerService for type [" + type + "]");
         super.connect(type);
 
         String componentName = Constants.PACKAGE_NAME_PROD;
         if (type.equals(Constants.ACCOUNT_TYPE_DEV)) {
             componentName = Constants.PACKAGE_NAME_DEV;
         }
 
+        Log.d(TAG, "[connect] Component name is: [" + componentName+ "]");
+
         try {
             Intent intentService = new Intent();
             intentService.setComponent(new ComponentName(componentName,
                                                          "com.owncloud.android.services.AccountManagerService"));
-            if (!mContext.bindService(intentService, mConnection, Context.BIND_AUTO_CREATE)) {
-                Log.d(TAG, "Binding to AccountManagerService returned false");
+            // https://developer.android.com/reference/android/content/Context#BIND_ABOVE_CLIENT
+            if (!mContext.bindService(intentService, mConnection, Context.BIND_AUTO_CREATE | Context.BIND_ABOVE_CLIENT)) {
+                Log.d(TAG, "[connect] Binding to AccountManagerService returned false");
                 throw new IllegalStateException("Binding to AccountManagerService returned false");
+            } else {
+                Log.d(TAG, "[connect] Bound to AccountManagerService successfully");
             }
         } catch (SecurityException e) {
-            Log.e(TAG, "can't bind to AccountManagerService, check permission in Manifest");
+            Log.e(TAG, "[connect] can't bind to AccountManagerService, check permission in Manifest");
             mCallback.onError(e);
         }
     }
 
+    public void reconnect() {
+        Log.d(TAG, "[reconnect] called");
+        unbindService();
+        connectApiWithBackoff();
+    }
+
     public void stop() {
         super.stop();
 
+        unbindService();
+        mContext = null;
+    }
+
+    private void unbindService() {
         // Unbind from the service
         if (mBound.get()) {
             if (mContext != null) {
+                Log.d(TAG, "[unbindService] Unbinding AccountManagerService");
                 mContext.unbindService(mConnection);
             } else {
-                Log.e(TAG, "Context was null, cannot unbind nextcloud single sign-on service connection!");
+                Log.e(TAG, "[unbindService] Context was null, cannot unbind nextcloud single sign-on service connection!");
             }
             mBound.set(false);
-            mContext = null;
+            mService = null;
         }
     }
 
@@ -123,7 +142,7 @@ private void waitForApi() throws NextcloudApiNotRespondingException {
                 try {
                     mBound.wait(10000); // wait up to 10 seconds
 
-                    // If api is still not bound after 10 seconds.. throw an exception
+                    // If api is still not bound after 10 seconds.. try reconnecting
                     if(!mBound.get()) {
                         throw new NextcloudApiNotRespondingException();
                     }
@@ -143,8 +162,6 @@ private void waitForApi() throws NextcloudApiNotRespondingException {
      * @throws Exception or SSOException
      */
     public Response performNetworkRequestV2(NextcloudRequest request, InputStream requestBodyInputStream) throws Exception {
-
-
         ParcelFileDescriptor output = performAidlNetworkRequestV2(request, requestBodyInputStream);
         InputStream os = new ParcelFileDescriptor.AutoCloseInputStream(output);
         ExceptionResponse response = deserializeObjectV2(os);
@@ -204,6 +221,10 @@ private ParcelFileDescriptor performAidlNetworkRequest(NextcloudRequest request,
             throw new NetworkOnMainThreadException();
         }
 
+        if(mDestroyed) {
+            throw new IllegalStateException("Nextcloud API already destroyed. Please report this issue.");
+        }
+
         // Wait for api to be initialized
         waitForApi();
 

src/main/java/com/nextcloud/android/sso/api/NetworkRequest.java

@@ -4,14 +4,14 @@
 import android.os.Looper;
 import android.util.Log;
 
+import androidx.annotation.NonNull;
+
 import com.nextcloud.android.sso.aidl.NextcloudRequest;
 import com.nextcloud.android.sso.helper.ExponentialBackoff;
 import com.nextcloud.android.sso.model.SingleSignOnAccount;
 
 import java.io.InputStream;
 
-import androidx.annotation.NonNull;
-
 public abstract class NetworkRequest {
 
     private static final String TAG = NetworkRequest.class.getCanonicalName();
@@ -30,7 +30,7 @@ protected NetworkRequest(@NonNull Context context, @NonNull SingleSignOnAccount
 
 
     protected void connect(String type) {
-        Log.v(TAG, "Nextcloud Single sign-on connect() called [" + Thread.currentThread().getName() + "] Account-Type: [" + type + "]");
+        Log.d(TAG, "[connect] connect() called [" + Thread.currentThread().getName() + "] Account-Type: [" + type + "]");
         if (mDestroyed) {
             throw new IllegalStateException("API already destroyed! You cannot reuse a stopped API instance");
         }
@@ -41,8 +41,13 @@ protected void connect(String type) {
     protected abstract Response performNetworkRequestV2(NextcloudRequest request, InputStream requestBodyInputStream) throws Exception;
 
     protected void connectApiWithBackoff() {
-        new ExponentialBackoff(1000, 10000, 2, 5, Looper.getMainLooper(), () -> {
+        Log.d(TAG, "[connectApiWithBackoff] connectApiWithBackoff() called from Thread: [" + Thread.currentThread().getName() + "]");
+        new ExponentialBackoff(1000, 5000, 2, 5, Looper.getMainLooper(), () -> {
+            Log.d(TAG, "[connectApiWithBackoff] trying to connect..");
             connect(mAccount.type);
+        }, () -> {
+            Log.e(TAG, "Unable to recover API");
+            stop();
         }).start();
     }
 

src/main/java/com/nextcloud/android/sso/helper/ExponentialBackoff.java

@@ -18,6 +18,8 @@
 
 import android.os.Handler;
 import android.os.Looper;
+import android.util.Log;
+
 import androidx.annotation.NonNull;
 import androidx.annotation.VisibleForTesting;
 
@@ -27,13 +29,16 @@
 /** The implementation of exponential backoff with jitter applied. */
 public class ExponentialBackoff {
 
+    private static final String TAG = ExponentialBackoff.class.getCanonicalName();
+
     private int mRetryCounter;
     private long mStartDelayMs;
     private long mMaximumDelayMs;
     private long mCurrentDelayMs;
     private int mMaxRetries;
     private int mMultiplier;
     private final Runnable mRunnable;
+    private final Runnable mFailedCallback;
     private final Handler mHandler;
 
     /**
@@ -64,8 +69,9 @@ public ExponentialBackoff(
             int multiplier,
             int maxRetries,
             @NonNull Looper looper,
-            @NonNull Runnable runnable) {
-        this(initialDelayMs, maximumDelayMs, multiplier, maxRetries, new Handler(looper), runnable);
+            @NonNull Runnable runnable,
+            @NonNull Runnable onErrorRunnable) {
+        this(initialDelayMs, maximumDelayMs, multiplier, maxRetries, new Handler(looper), runnable, onErrorRunnable);
     }
 
     private ExponentialBackoff(
@@ -74,14 +80,16 @@ private ExponentialBackoff(
             int multiplier,
             int maxRetries,
             @NonNull Handler handler,
-            @NonNull Runnable runnable) {
+            @NonNull Runnable runnable,
+            @NonNull Runnable onErrorRunnable) {
         mRetryCounter = 0;
         mStartDelayMs = initialDelayMs;
         mMaximumDelayMs = maximumDelayMs;
         mMultiplier = multiplier;
         mMaxRetries = maxRetries;
         mHandler = handler;
         mRunnable = new WrapperRunnable(runnable);
+        mFailedCallback = onErrorRunnable;
 
         if(initialDelayMs <= 0) {
             throw new InvalidParameterException("initialDelayMs should not be less or equal to 0");
@@ -99,17 +107,22 @@ public void start() {
     public void stop() {
         mRetryCounter = 0;
         mHandlerAdapter.removeCallbacks(mRunnable);
+
     }
 
     /** Should call when the retry action has failed and we want to retry after a longer delay. */
-    private void notifyFailed() {
+    private void notifyFailed(Exception ex) {
+        Log.d(TAG, "[notifyFailed] Error: [" + ex.getMessage() + "]");
         if(mRetryCounter > mMaxRetries) {
+            Log.d(TAG, "[notifyFailed] Retries exceeded, ending now");
             stop();
+            mFailedCallback.run();
         } else {
             mRetryCounter++;
             long temp = Math.min(
                     mMaximumDelayMs, (long) (mStartDelayMs * Math.pow(mMultiplier, mRetryCounter)));
             mCurrentDelayMs = (long) (((1 + Math.random()) / 2) * temp);
+            Log.d(TAG, "[notifyFailed] retrying in: [" + mCurrentDelayMs + "ms]");
             mHandlerAdapter.removeCallbacks(mRunnable);
             mHandlerAdapter.postDelayed(mRunnable, mCurrentDelayMs);
         }
@@ -128,7 +141,7 @@ public void run() {
             try {
                 runnable.run();
             } catch (Exception ex) {
-                notifyFailed();
+                notifyFailed(ex);
             }
         }
     }