Timeout frame capturing.

It has been observed on some of the MS camera devices, that device may got stuck on something
that would alwais return EAGAIN when queried for the next video frame. This requires us to
timeout the loop that repeats attempts to acquire first frame from the device. Also added
detection and reporting of I/O errors occurred during frame capturing.

Also, this CL contains some cosmetick changes to error and warning reporting.

Change-Id: I81edaf5ff8bfe147dbe4510e1446e77a87817f37

6 files changed, 64 insertions, 24 deletions

diff --git a/android/camera/camera-capture-linux.c b/android/camera/camera-capture-linux.c
index 0975f0e..8a96c0c 100644
--- a/android/camera/camera-capture-linux.c
+++ b/android/camera/camera-capture-linux.c
@@ -26,9 +26,9 @@
 #include "android/camera/camera-capture.h"
 #include "android/camera/camera-format-converters.h"
 
+#define  E(...)    derror(__VA_ARGS__)
+#define  W(...)    dwarning(__VA_ARGS__)
 #define  D(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  W(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  E(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
 #define  D_ACTIVE  VERBOSE_CHECK(camera)
 
 /* the T(...) macro is used to dump traffic */
@@ -498,8 +498,6 @@ _camera_device_open(LinuxCameraDevice* cd)
     struct stat st;
 
     if (stat(cd->device_name, &st)) {
-        E("%s: Cannot identify camera device '%s': %s",
-          __FUNCTION__, cd->device_name, strerror(errno));
         return -1;
     }
 
diff --git a/android/camera/camera-capture-mac.c b/android/camera/camera-capture-mac.c
index 8a793c1..764a055 100644
--- a/android/camera/camera-capture-mac.c
+++ b/android/camera/camera-capture-mac.c
@@ -21,9 +21,9 @@
 
 #include "android/camera/camera-capture.h"
 
+#define  E(...)    derror(__VA_ARGS__)
+#define  W(...)    dwarning(__VA_ARGS__)
 #define  D(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  W(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  E(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
 #define  D_ACTIVE  VERBOSE_CHECK(camera)
 
 /* the T(...) macro is used to dump traffic */
diff --git a/android/camera/camera-capture-windows.c b/android/camera/camera-capture-windows.c
index fff078e..28820a8 100755
--- a/android/camera/camera-capture-windows.c
+++ b/android/camera/camera-capture-windows.c
@@ -23,9 +23,9 @@
 #include "android/camera/camera-capture.h"
 #include "android/camera/camera-format-converters.h"
 
+#define  E(...)    derror(__VA_ARGS__)
+#define  W(...)    dwarning(__VA_ARGS__)
 #define  D(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  W(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  E(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
 #define  D_ACTIVE  VERBOSE_CHECK(camera)
 
 /* the T(...) macro is used to dump traffic */
@@ -252,8 +252,6 @@ camera_device_start_capturing(CameraDevice* cd,
 
     /* Connect capture window to the video capture driver. */
     if (!capDriverConnect(wcd->cap_window, wcd->input_channel)) {
-        E("%s: Unable to connect to the video capturing driver #%d: %d",
-          __FUNCTION__, wcd->input_channel, GetLastError());
         return -1;
     }
 
diff --git a/android/camera/camera-common.h b/android/camera/camera-common.h
index 126b3ed..37bdef4 100755
--- a/android/camera/camera-common.h
+++ b/android/camera/camera-common.h
@@ -176,5 +176,31 @@ typedef struct CameraDevice {
     /* Opaque pointer used by the camera capturing API. */
     void*       opaque;
 } CameraDevice;
+
+/* Returns current time in microseconds. */
+static __inline__ uint64_t
+_get_timestamp(void)
+{
+    struct timeval t;
+    t.tv_sec = t.tv_usec = 0;
+    gettimeofday(&t, NULL);
+    return (uint64_t)t.tv_sec * 1000000LL + t.tv_usec;
+}
+
+/* Sleeps for the given amount of milliseconds */
+static __inline__ void
+_sleep(int millisec)
+{
+    struct timeval t;
+    const uint64_t wake_at = _get_timestamp() + (uint64_t)millisec * 1000;
+    do {
+        const uint64_t stamp = _get_timestamp();
+        if ((stamp / 1000) >= (wake_at / 1000)) {
+            break;
+        }
+        t.tv_sec = (wake_at - stamp) / 1000000;
+        t.tv_usec = (wake_at - stamp) - (uint64_t)t.tv_sec * 1000000;
+    } while (select(0, NULL, NULL, NULL, &t) < 0 && errno == EINTR);
+}
 

 #endif  /* ANDROID_CAMERA_CAMERA_COMMON_H_ */
diff --git a/android/camera/camera-format-converters.c b/android/camera/camera-format-converters.c
index c675f15..3366a44 100755
--- a/android/camera/camera-format-converters.c
+++ b/android/camera/camera-format-converters.c
@@ -24,9 +24,10 @@
 #endif
 #include "android/camera/camera-format-converters.h"

 
+#define  E(...)    derror(__VA_ARGS__)
+#define  W(...)    dwarning(__VA_ARGS__)
 #define  D(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  W(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  E(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
+#define  D_ACTIVE  VERBOSE_CHECK(camera)
 
  /*
  * NOTE: RGB and big/little endian considerations. Wherewer in this code RGB
diff --git a/android/camera/camera-service.c b/android/camera/camera-service.c
index 282acb4..088039f 100644
--- a/android/camera/camera-service.c
+++ b/android/camera/camera-service.c
@@ -28,9 +28,9 @@
 #include "android/camera/camera-format-converters.h"
 #include "android/camera/camera-service.h"
 
+#define  E(...)    derror(__VA_ARGS__)
+#define  W(...)    dwarning(__VA_ARGS__)
 #define  D(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  W(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
-#define  E(...)    VERBOSE_PRINT(camera,__VA_ARGS__)
 #define  D_ACTIVE  VERBOSE_CHECK(camera)
 
 /* the T(...) macro is used to dump traffic */
@@ -497,9 +497,9 @@ _camera_service_init(CameraServiceDesc* csd)
             csd->camera_count++;
             memset(found, 0, sizeof(CameraInfo));
         } else {
-            dwarning("Camera name '%s' is not found in the list of connected cameras.\n"
-                     "Use -webcam-list emulator option to obtain the list of connected camera names\n\n",
-                     disp_name);
+            W("Camera name '%s' is not found in the list of connected cameras.\n"
+              "Use -webcam-list emulator option to obtain the list of connected camera names",
+              disp_name);
         }
     }
 }
@@ -1164,6 +1164,7 @@ _camera_client_query_frame(CameraClient* cc, QemudClient* qc, const char* param)
     ClientFrameBuffer fbs[2];
     int fbs_num = 0;
     size_t payload_size;
+    uint64_t tick;
 
     /* Sanity check. */
     if (cc->video_frame == NULL) {
@@ -1212,25 +1213,41 @@ _camera_client_query_frame(CameraClient* cc, QemudClient* qc, const char* param)
     }
 
     /* Capture new frame. */
+    tick = _get_timestamp();
     repeat = camera_device_read_frame(cc->camera, fbs, fbs_num);
 
     /* Note that there is no (known) way how to wait on next frame being
-     * available, so we dequeue frame buffer from the device only when we know
-     * it's available. Instead we're shooting in the dark, and quite often
+     * available, so we could dequeue frame buffer from the device only when we
+     * know it's available. Instead we're shooting in the dark, and quite often
      * device will response with EAGAIN, indicating that it doesn't have frame
      * ready. In turn, it means that the last frame we have obtained from the
      * device is still good, and we can reply with the cached frames. The only
      * case when we need to keep trying to obtain a new frame is when frame cache
-     * is empty. */
-    while (repeat == 1 && !cc->frames_cached) {
+     * is empty. To prevent ourselves from an indefinite loop in case device got
+     * stuck on something (observed with some Microsoft devices) we will limit
+     * the loop by 2 second time period (which is more than enough to obtain
+     * something from the device) */
+    while (repeat == 1 && !cc->frames_cached &&
+           (_get_timestamp() - tick) < 2000000LL) {
+        /* Sleep for 10 millisec before repeating the attempt. */
+        _sleep(10);
         repeat = camera_device_read_frame(cc->camera, fbs, fbs_num);
     }
-    if (repeat < 0) {
-        E("%s: Unable to obtain video frame from the camera '%s': %s",
-          __FUNCTION__, cc->device_name, strerror(errno));
+    if (repeat == 1 && !cc->frames_cached) {
+        /* Waited too long for the first frame. */
+        E("%s: Unable to obtain first video frame from the camera '%s' in %d milliseconds: %s.",
+          __FUNCTION__, cc->device_name,
+          (uint32_t)(_get_timestamp() - tick) / 1000, strerror(errno));
         _qemu_client_reply_ko(qc, "Unable to obtain video frame from the camera");
         return;
+    } else if (repeat < 0) {
+        /* An I/O error. */
+        E("%s: Unable to obtain video frame from the camera '%s': %s.",
+          __FUNCTION__, cc->device_name, strerror(errno));
+        _qemu_client_reply_ko(qc, strerror(errno));
+        return;
     }
+
     /* We have cached something... */
     cc->frames_cached = 1;