Camera2: Clean up corner case error handling

- If a session is closed, and a new session is created immediately
afterwards, but then fails to be configured, the first session sees an
onUnconfigured call which it wasn't expecting, and throws an
exception on an internal thread, leading to app death.
Add a guard against this case.

- If the lower levels skip a frame (illegal per design), be slightly more
robust to that by accepting any successful result as the latest completed
frame, instead of just incrementing the completed frame count. This will
lead to missing results, but should allow shutdown, etc, to complete
cleanly.

- Convert TIMED_OUT error codes to CAMERA_ERROR CameraAccessExceptions.
This is a common error code returned by waitUntilIdle.

Also, improve debug logging to log a session ID with verbose logging,
and add a few verbose logs.

Bug: 16899526
Change-Id: I7a31f0a12effc2611e1f9c2408224ee82c37c912
diff --git a/core/java/android/hardware/camera2/impl/CameraCaptureSessionImpl.java b/core/java/android/hardware/camera2/impl/CameraCaptureSessionImpl.java
index 0057f61..b9507d7 100644
--- a/core/java/android/hardware/camera2/impl/CameraCaptureSessionImpl.java
+++ b/core/java/android/hardware/camera2/impl/CameraCaptureSessionImpl.java
@@ -42,6 +42,10 @@
     private static final String TAG = "CameraCaptureSession";
     private static final boolean VERBOSE = Log.isLoggable(TAG, Log.VERBOSE);
 
+    /** Simple integer ID for session for debugging */
+    private final int mId;
+    private final String mIdString;
+
     /** User-specified set of surfaces used as the configuration outputs */
     private final List<Surface> mOutputs;
     /**
@@ -83,7 +87,7 @@
      * There must be no pending actions
      * (e.g. no pending captures, no repeating requests, no flush).</p>
      */
-    CameraCaptureSessionImpl(List<Surface> outputs,
+    CameraCaptureSessionImpl(int id, List<Surface> outputs,
             CameraCaptureSession.StateCallback callback, Handler stateHandler,
             android.hardware.camera2.impl.CameraDeviceImpl deviceImpl,
             Handler deviceStateHandler, boolean configureSuccess) {
@@ -93,6 +97,9 @@
             throw new IllegalArgumentException("callback must not be null");
         }
 
+        mId = id;
+        mIdString = String.format("Session %d: ", mId);
+
         // TODO: extra verification of outputs
         mOutputs = outputs;
         mStateHandler = checkHandler(stateHandler);
@@ -120,12 +127,12 @@
 
         if (configureSuccess) {
             mStateCallback.onConfigured(this);
-            if (VERBOSE) Log.v(TAG, "ctor - Created session successfully");
+            if (VERBOSE) Log.v(TAG, mIdString + "Created session successfully");
             mConfigureSuccess = true;
         } else {
             mStateCallback.onConfigureFailed(this);
             mClosed = true; // do not fire any other callbacks, do not allow any other work
-            Log.e(TAG, "Failed to create capture session; configuration failed");
+            Log.e(TAG, mIdString + "Failed to create capture session; configuration failed");
             mConfigureSuccess = false;
         }
     }
@@ -147,8 +154,8 @@
         handler = checkHandler(handler, callback);
 
         if (VERBOSE) {
-            Log.v(TAG, "capture - request " + request + ", callback " + callback + " handler" +
-                    " " + handler);
+            Log.v(TAG, mIdString + "capture - request " + request + ", callback " + callback +
+                    " handler " + handler);
         }
 
         return addPendingSequence(mDeviceImpl.capture(request,
@@ -170,8 +177,8 @@
 
         if (VERBOSE) {
             CaptureRequest[] requestArray = requests.toArray(new CaptureRequest[0]);
-            Log.v(TAG, "captureBurst - requests " + Arrays.toString(requestArray) + ", callback " +
-                    callback + " handler" + "" + handler);
+            Log.v(TAG, mIdString + "captureBurst - requests " + Arrays.toString(requestArray) +
+                    ", callback " + callback + " handler " + handler);
         }
 
         return addPendingSequence(mDeviceImpl.captureBurst(requests,
@@ -190,8 +197,8 @@
         handler = checkHandler(handler, callback);
 
         if (VERBOSE) {
-            Log.v(TAG, "setRepeatingRequest - request " + request + ", callback " + callback +
-                    " handler" + " " + handler);
+            Log.v(TAG, mIdString + "setRepeatingRequest - request " + request + ", callback " +
+                    callback + " handler" + " " + handler);
         }
 
         return addPendingSequence(mDeviceImpl.setRepeatingRequest(request,
@@ -213,7 +220,7 @@
 
         if (VERBOSE) {
             CaptureRequest[] requestArray = requests.toArray(new CaptureRequest[0]);
-            Log.v(TAG, "setRepeatingBurst - requests " + Arrays.toString(requestArray) +
+            Log.v(TAG, mIdString + "setRepeatingBurst - requests " + Arrays.toString(requestArray) +
                     ", callback " + callback + " handler" + "" + handler);
         }
 
@@ -226,7 +233,7 @@
         checkNotClosed();
 
         if (VERBOSE) {
-            Log.v(TAG, "stopRepeating");
+            Log.v(TAG, mIdString + "stopRepeating");
         }
 
         mDeviceImpl.stopRepeating();
@@ -237,11 +244,11 @@
         checkNotClosed();
 
         if (VERBOSE) {
-            Log.v(TAG, "abortCaptures");
+            Log.v(TAG, mIdString + "abortCaptures");
         }
 
         if (mAborting) {
-            Log.w(TAG, "abortCaptures - Session is already aborting; doing nothing");
+            Log.w(TAG, mIdString + "abortCaptures - Session is already aborting; doing nothing");
             return;
         }
 
@@ -279,7 +286,7 @@
          * but this would introduce nondeterministic behavior.
          */
 
-        if (VERBOSE) Log.v(TAG, "replaceSessionClose");
+        if (VERBOSE) Log.v(TAG, mIdString + "replaceSessionClose");
 
         // Set up fast shutdown. Possible alternative paths:
         // - This session is active, so close() below starts the shutdown drain
@@ -299,11 +306,11 @@
     public synchronized void close() {
 
         if (mClosed) {
-            if (VERBOSE) Log.v(TAG, "close - reentering");
+            if (VERBOSE) Log.v(TAG, mIdString + "close - reentering");
             return;
         }
 
-        if (VERBOSE) Log.v(TAG, "close - first time");
+        if (VERBOSE) Log.v(TAG, mIdString + "close - first time");
 
         mClosed = true;
 
@@ -321,7 +328,7 @@
             mDeviceImpl.stopRepeating();
         } catch (IllegalStateException e) {
             // OK: Camera device may already be closed, nothing else to do
-            Log.w(TAG, "The camera device was already closed: ", e);
+            Log.w(TAG, mIdString + "The camera device was already closed: ", e);
 
             // TODO: Fire onClosed anytime we get the device onClosed or the ISE?
             // or just suppress the ISE only and rely onClosed.
@@ -332,7 +339,7 @@
             return;
         } catch (CameraAccessException e) {
             // OK: close does not throw checked exceptions.
-            Log.e(TAG, "Exception while stopping repeating: ", e);
+            Log.e(TAG, mIdString + "Exception while stopping repeating: ", e);
 
             // TODO: call onError instead of onClosed if this happens
         }
@@ -453,13 +460,14 @@
 
             @Override
             public void onDisconnected(CameraDevice camera) {
+                if (VERBOSE) Log.v(TAG, mIdString + "onDisconnected");
                 close();
             }
 
             @Override
             public void onError(CameraDevice camera, int error) {
-                // TODO: Handle errors somehow.
-                Log.wtf(TAG, "Got device error " + error);
+                // Should not be reached, handled by device code
+                Log.wtf(TAG, mIdString + "Got device error " + error);
             }
 
             @Override
@@ -467,12 +475,15 @@
                 mIdleDrainer.taskStarted();
                 mActive = true;
 
+                if (VERBOSE) Log.v(TAG, mIdString + "onActive");
                 mStateCallback.onActive(session);
             }
 
             @Override
             public void onIdle(CameraDevice camera) {
                 boolean isAborting;
+                if (VERBOSE) Log.v(TAG, mIdString + "onIdle");
+
                 synchronized (session) {
                     isAborting = mAborting;
                 }
@@ -513,14 +524,29 @@
                 // TODO: Queue captures during abort instead of failing them
                 // since the app won't be able to distinguish the two actives
                 // Don't signal the application since there's no clean mapping here
-                Log.w(TAG, "Device is now busy; do not submit new captures (TODO: allow this)");
+                if (VERBOSE) Log.v(TAG, mIdString + "onBusy");
             }
 
             @Override
             public void onUnconfigured(CameraDevice camera) {
+                if (VERBOSE) Log.v(TAG, mIdString + "onUnconfigured");
                 synchronized (session) {
-                    // Ignore #onUnconfigured before #close is called
-                    if (mClosed && mConfigureSuccess) {
+                    // Ignore #onUnconfigured before #close is called.
+                    //
+                    // Normally, this is reached when this session is closed and no immediate other
+                    // activity happens for the camera, in which case the camera is configured to
+                    // null streams by this session and the UnconfigureDrainer task is started.
+                    // However, we can also end up here if
+                    //
+                    // 1) Session is closed
+                    // 2) New session is created before this session finishes closing, setting
+                    //    mSkipUnconfigure and therefore this session does not configure null or
+                    //    start the UnconfigureDrainer task.
+                    // 3) And then the new session fails to be created, so onUnconfigured fires
+                    //    _anyway_.
+                    // In this second case, need to not finish a task that was never started, so
+                    // guard with mSkipUnconfigure
+                    if (mClosed && mConfigureSuccess && !mSkipUnconfigure) {
                         mUnconfigureDrainer.taskFinished();
                     }
                 }
@@ -580,6 +606,7 @@
              * If the camera is already "IDLE" and no aborts are pending,
              * then the drain immediately finishes.
              */
+            if (VERBOSE) Log.v(TAG, mIdString + "onSequenceDrained");
             mAbortDrainer.beginDrain();
         }
     }
@@ -587,6 +614,7 @@
     private class AbortDrainListener implements TaskDrainer.DrainListener {
         @Override
         public void onDrained() {
+            if (VERBOSE) Log.v(TAG, mIdString + "onAbortDrained");
             synchronized (CameraCaptureSessionImpl.this) {
                 /*
                  * Any queued aborts have now completed.
@@ -604,6 +632,7 @@
     private class IdleDrainListener implements TaskDrainer.DrainListener {
         @Override
         public void onDrained() {
+            if (VERBOSE) Log.v(TAG, mIdString + "onIdleDrained");
             synchronized (CameraCaptureSessionImpl.this) {
                 /*
                  * The device is now IDLE, and has settled. It will not transition to
@@ -613,7 +642,7 @@
                  *
                  * This operation is idempotent; a session will not be closed twice.
                  */
-                if (VERBOSE) Log.v(TAG, "Session drain complete, skip unconfigure: " +
+                if (VERBOSE) Log.v(TAG, mIdString + "Session drain complete, skip unconfigure: " +
                         mSkipUnconfigure);
 
                 // Fast path: A new capture session has replaced this one; don't unconfigure.
@@ -629,7 +658,7 @@
                     mDeviceImpl.configureOutputsChecked(null); // begin transition to unconfigured
                 } catch (CameraAccessException e) {
                     // OK: do not throw checked exceptions.
-                    Log.e(TAG, "Exception while configuring outputs: ", e);
+                    Log.e(TAG, mIdString + "Exception while configuring outputs: ", e);
 
                     // TODO: call onError instead of onClosed if this happens
                 }
@@ -641,7 +670,9 @@
 
     private class UnconfigureDrainListener implements TaskDrainer.DrainListener {
         @Override
+
         public void onDrained() {
+            if (VERBOSE) Log.v(TAG, mIdString + "onUnconfigureDrained");
             synchronized (CameraCaptureSessionImpl.this) {
                 // The device has finished unconfiguring. It's now fully closed.
                 mStateCallback.onClosed(CameraCaptureSessionImpl.this);
diff --git a/core/java/android/hardware/camera2/impl/CameraDeviceImpl.java b/core/java/android/hardware/camera2/impl/CameraDeviceImpl.java
index f011d60..f917fdc 100644
--- a/core/java/android/hardware/camera2/impl/CameraDeviceImpl.java
+++ b/core/java/android/hardware/camera2/impl/CameraDeviceImpl.java
@@ -99,6 +99,7 @@
     private final FrameNumberTracker mFrameNumberTracker = new FrameNumberTracker();
 
     private CameraCaptureSessionImpl mCurrentSession;
+    private int mNextSessionId = 0;
 
     // Runnables for all state transitions, except error, which needs the
     // error code argument
@@ -445,7 +446,8 @@
 
             // Fire onConfigured if configureOutputs succeeded, fire onConfigureFailed otherwise.
             CameraCaptureSessionImpl newSession =
-                    new CameraCaptureSessionImpl(outputs, callback, handler, this, mDeviceHandler,
+                    new CameraCaptureSessionImpl(mNextSessionId++,
+                            outputs, callback, handler, this, mDeviceHandler,
                             configureSuccess);
 
             // TODO: wait until current session closes, then create the new session
@@ -1003,8 +1005,10 @@
                     Log.e(TAG, String.format(
                             "result frame number %d comes out of order, should be %d + 1",
                             frameNumber, mCompletedFrameNumber));
+                    // Continue on to set the completed frame number to this frame anyway,
+                    // to be robust to lower-level errors and allow for clean shutdowns.
                 }
-                mCompletedFrameNumber++;
+                mCompletedFrameNumber = frameNumber;
             }
             update();
         }
diff --git a/core/java/android/hardware/camera2/utils/CameraBinderDecorator.java b/core/java/android/hardware/camera2/utils/CameraBinderDecorator.java
index 83ebadd..d461bca 100644
--- a/core/java/android/hardware/camera2/utils/CameraBinderDecorator.java
+++ b/core/java/android/hardware/camera2/utils/CameraBinderDecorator.java
@@ -19,6 +19,7 @@
 import static android.hardware.camera2.CameraAccessException.CAMERA_DISABLED;
 import static android.hardware.camera2.CameraAccessException.CAMERA_DISCONNECTED;
 import static android.hardware.camera2.CameraAccessException.CAMERA_IN_USE;
+import static android.hardware.camera2.CameraAccessException.CAMERA_ERROR;
 import static android.hardware.camera2.CameraAccessException.MAX_CAMERAS_IN_USE;
 import static android.hardware.camera2.CameraAccessException.CAMERA_DEPRECATED_HAL;
 
@@ -41,6 +42,7 @@
     public static final int BAD_VALUE = -22;
     public static final int DEAD_OBJECT = -32;
     public static final int INVALID_OPERATION = -38;
+    public static final int TIMED_OUT = -110;
 
     /**
      * TODO: add as error codes in Errors.h
@@ -112,6 +114,9 @@
                 throw new IllegalArgumentException("Bad argument passed to camera service");
             case DEAD_OBJECT:
                 throw new CameraRuntimeException(CAMERA_DISCONNECTED);
+            case TIMED_OUT:
+                throw new CameraRuntimeException(CAMERA_ERROR,
+                        "Operation timed out in camera service");
             case EACCES:
                 throw new CameraRuntimeException(CAMERA_DISABLED);
             case EBUSY:
@@ -123,7 +128,7 @@
             case EOPNOTSUPP:
                 throw new CameraRuntimeException(CAMERA_DEPRECATED_HAL);
             case INVALID_OPERATION:
-                throw new IllegalStateException(
+                throw new CameraRuntimeException(CAMERA_ERROR,
                         "Illegal state encountered in camera service.");
         }