ptp: tune EOS_FocusInfoEx, FocusInfo event related code

With the re-enabled FocusInfoEx, the 5Ds spams the log and the
--wait-event console output with a 64 entry long focus info list.
Assuming no tooling is dependent on the particular string format of the
FocusInfoEx value, since it seems to only ever contain a no-empty
set of selected AF-points at the beginning of the capture process, where
the event is 'swollowed' by the focus detection code. This changeset
strips it down to only contain the list of selected AF-points, meaning
without focus, we now get a simple "{}".

Furthermore, the olcmask 0x0100 (FocusInfo) data of the 5Ds, R8 and R5m2
has been analyzed and the in-focus detection code during trigger_capture
has been improved. See code comments for details.

Author: axxel

camlibs/ptp2/library.c

@@ -5989,7 +5989,6 @@ camera_trigger_canon_eos_capture (Camera *camera, GPContext *context)
 	PTPCanonEOSEvent	event;
 	int			back_off_wait = 0;
 	uint32_t		result;
-	struct timeval		focus_start;
 	PTPDevicePropDesc	dpd;
 
 	GP_LOG_D ("camera_trigger_canon_eos_capture");
@@ -6034,63 +6033,66 @@ camera_trigger_canon_eos_capture (Camera *camera, GPContext *context)
 		if (!is_canon_eos_m (params)) {
 			/* Regular EOS */
 			uint16_t	res;
-			int 		manualfocus = 0, foundfocusinfo = 0;
+			int 		manual_focus = 0, in_focus = 0;
 
 			/* are we in manual focus mode ... value would be 3 */
 			if (PTP_RC_OK == ptp_canon_eos_getdevicepropdesc (params, PTP_DPC_CANON_EOS_FocusMode, &dpd)) {
 				if ((dpd.DataType == PTP_DTC_UINT32) && (dpd.CurrentValue.u32 == 3)) {
-					manualfocus = 1;
+					manual_focus = 1;
 					/* will do 1 pass through the focusing loop for good measure */
 					GP_LOG_D("detected manual focus. skipping focus detection logic");
 				}
 			}
 			ret = GP_OK;
-			/* half press now - initiate focusing and wait for result */
+			/* half press now - initiate focusing (second param = 1 -> disabled AF) and wait for result */
 			C_PTP_REP_MSG (ptp_canon_eos_remotereleaseon (params, 1, 0), _("Canon EOS Half-Press failed"));
 
-			focus_start = time_now();
+			/* at this point, the focusing is complete and either succeded or failed. This has been verified with
+			 * a 5Dm2, 5Ds and R8. The RemoteReleaseOn call may take e.g. up to 8s on a 5Dm2 with a slow lens. */
+			struct timeval get_events_start = time_now();
 			do {
-				int foundevents = 0;
+				int received_events = 0;
 
 				C_PTP_REP_MSG (ptp_check_eos_events (params), _("Canon EOS Get Changes failed"));
 				while (ptp_get_one_eos_event (params, &event)) {
 					GP_LOG_D ("while focussing, processing event '%s'", ptp_get_eos_event_name(params, event.type));
-					foundevents = 1;
+					received_events = 1;
 					if (event.type == PTP_EOSEvent_FocusInfo) {
-						GP_LOG_D("focusinfo content: %s", event.u.info);
-						foundfocusinfo = 1;
-						if (strstr(event.u.info,"0000200")) {
-							gp_context_error (context, _("Canon EOS Capture failed to release: Perhaps no focus?"));
+						GP_LOG_D("FocusInfo content: %s", event.u.info);
+						if (strstr(event.u.info, "000000000101")) /* see OLCInfoChanged unpacking */
+							in_focus = 1;
+						else if (strstr(event.u.info, "000000000200") || strstr(event.u.info, "000000000000")) {
+							gp_context_error (context, _("Canon EOS Auto-Focus failed, could not capture."));
 							ret = GP_ERROR;
 						}
 					} else if ((event.type == PTP_EOSEvent_PropertyChanged) &&
 					           (event.u.propid == PTP_DPC_CANON_EOS_FocusInfoEx)
 					) {
 						if (PTP_RC_OK == ptp_canon_eos_getdevicepropdesc (params, PTP_DPC_CANON_EOS_FocusInfoEx, &dpd)) {
-							GP_LOG_D("focusinfo prop content: %s", dpd.CurrentValue.str);
-							if (!strstr(dpd.CurrentValue.str,"select={}")) /* select={} means "no focus yet" */
-								foundfocusinfo = 1;
+							GP_LOG_D("EOS_FocusInfoEx prop content: %s", dpd.CurrentValue.str);
+							if (strcmp(dpd.CurrentValue.str, "{}")) /* "{}" means "no focus points found" */
+								in_focus = 1;
 							ptp_free_devicepropdesc (&dpd);
 						}
 					}
 				}
 				/* We found focus information, so half way pressing has finished! */
-				if (foundfocusinfo)
+				if (in_focus)
 					break;
 				/* for manual focus, wait until we received an event or 0.1s passed */
-				if (manualfocus && (foundevents || time_since (focus_start) >= 100))
+				if (manual_focus && (received_events || time_since (get_events_start) >= 100))
 					break;
-			} while (waiting_for_timeout (&back_off_wait, focus_start, 2*1000)); /* wait 2 seconds for focus */
+			} while (waiting_for_timeout (&back_off_wait, get_events_start, 500)); /* wait up to 500ms for focus events */
 
-			if (!foundfocusinfo && !manualfocus) {
-				GP_LOG_E("no focus info?\n");
+			if (!in_focus && !manual_focus) {
+				GP_LOG_E("Auto-Focus failed\n");
 			}
 			if (ret != GP_OK) {
 				C_PTP_REP_MSG (ptp_canon_eos_remotereleaseoff (params, 1), _("Canon EOS Half-Release failed"));
 				return ret;
 			}
-			/* full press now */
 
+			/* full press now */
 			res = LOG_ON_PTP_E (ptp_canon_eos_remotereleaseon (params, 2, 0));
 			if (res != PTP_RC_OK) {
 				/* if the Full Press failed, try to roll back the release and do not exit Half-Pressed. */
@@ -6113,7 +6115,8 @@ camera_trigger_canon_eos_capture (Camera *camera, GPContext *context)
 			int button = 0, eos_m_focus_done = 0;
 
 			C_PTP_REP_MSG (ptp_canon_eos_remotereleaseon (params, 3, 0), _("Canon EOS M Full-Press failed"));
-			focus_start = time_now();
+
+			struct timeval focus_start = time_now(); /* This might be a misnomer, see EOS case above. */
 			/* check if the capture was successful (the result is reported as a set of OLCInfoChanged events) */
 			do {
 				ptp_check_eos_events (params);
@@ -6775,9 +6778,9 @@ camera_wait_for_event (Camera *camera, int timeout,
 					PTPDevicePropDesc	dpd;
 
 					*eventtype = GP_EVENT_UNKNOWN;
-					if (PTP_DPC_CANON_EOS_FocusInfoEx == event.u.propid) {
+					if (event.u.propid == PTP_DPC_CANON_EOS_FocusInfoEx) {
 						if (PTP_RC_OK == ptp_canon_eos_getdevicepropdesc (params, PTP_DPC_CANON_EOS_FocusInfoEx, &dpd)) {
-							*eventdata = aprintf("FocusInfo %s", dpd.CurrentValue.str);
+							*eventdata = aprintf("Focus Points %s", dpd.CurrentValue.str);
 							ptp_free_devicepropdesc (&dpd);
 							return GP_OK;
 						}

camlibs/ptp2/ptp-pack.c

@@ -1520,31 +1520,31 @@ ptp_pack_EOS_ImageFormat (PTPParams* params, unsigned char* data, uint16_t value
 		htod32a(data+=4, (value >> 0) & 0x7);
 	}
 
-#undef PACK_5DM3_SMALL_JPEG_SIZE
+#undef PACK_EOS_S123_JPEG_SIZE
 
 	return s;
 }
 
-/* 00: 32 bit size
- * 04: 16 bit subsize
- * 08: 16 bit version (?)
- * 0c: 16 bit focus_points_in_struct
- * 10: 16 bit focus_points_in_use
- * 14: variable arrays:
+/* 32 bit size
+ * 16 bit subsize
+ * 16 bit version (?)
+ * 16 bit focus_points_in_struct
+ * 16 bit focus_points_in_use
+ * variable arrays:
  * 	16 bit sizex, 16 bit sizey
  * 	16 bit othersizex, 16 bit othersizey
  * 	16 bit array height[focus_points_in_struct]
  * 	16 bit array width[focus_points_in_struct]
  * 	16 bit array offsetheight[focus_points_in_struct] middle is 0
  * 	16 bit array offsetwidth[focus_points_in_struct] middle is ?
  * bitfield of selected focus points, starting with 0 [size focus_points_in_struct in bits]
- * unknown stuff , likely which are active
+ * unknown stuff, likely which are active
  * 16 bit 0xffff
  *
  * size=NxN,size2=NxN,points={NxNxNxN,NxNxNxN,...},selected={0,1,2}
  */
 static inline char*
-ptp_unpack_EOS_FocusInfoEx (PTPParams* params, const unsigned char** data, uint32_t datasize )
+ptp_unpack_EOS_FocusInfoEx (PTPParams* params, const unsigned char** data, uint32_t datasize)
 {
 	uint32_t size 			= dtoh32a( *data );
 	uint32_t halfsize		= dtoh16a( (*data) + 4);
@@ -1569,11 +1569,6 @@ ptp_unpack_EOS_FocusInfoEx (PTPParams* params, const unsigned char** data, uint3
 		ptp_debug(params, "skipped FocusInfoEx data (zero filled)");
 		return strdup("no focus points returned by camera");
 	}
-
-	/* every focuspoint gets 4 (16 bit number possible "-" sign and a x) and a ,*/
-	/* initial things around lets say 100 chars at most.
-	 * FIXME: check selected when we decode it
-	 */
 	if (size < focus_points_in_struct*8) {
 		ptp_error(params, "focus_points_in_struct %d is too large vs size %d", focus_points_in_struct, size);
 		return strdup("bad size 2");
@@ -1582,54 +1577,48 @@ ptp_unpack_EOS_FocusInfoEx (PTPParams* params, const unsigned char** data, uint3
 		ptp_error(params, "focus_points_in_use %d is larger than focus_points_in_struct %d", focus_points_in_use, focus_points_in_struct);
 		return strdup("bad size 3");
 	}
-
-	maxlen = focus_points_in_use*32 + 100 + (size - focus_points_in_struct*8)*2;
 	if (halfsize != size-4) {
-		ptp_error(params, "halfsize %d is not expected %d", halfsize, size-4);
-		return strdup("bad size 4");
+		ptp_debug(params, "halfsize %d is not expected %d", halfsize, size-4);
 	}
+
 	if (20 + focus_points_in_struct*8 + (focus_points_in_struct+7)/8 > size) {
 		ptp_error(params, "size %d is too large for fp in struct %d", focus_points_in_struct*8 + 20 + (focus_points_in_struct+7)/8, size);
 		return strdup("bad size 5");
 	}
+
+	ptp_debug(params,"                prop d1d3 version is %d with %d focus points in struct and %d in use, size=%ux%u, size2=%ux%u",
+	          version, focus_points_in_struct, focus_points_in_use, sizeX, sizeY, size2X, size2Y);
 #if 0
-	ptp_debug(params,"d1d3 content:");
-	for (i=0;i<size;i+=2)
-		ptp_debug(params,"%d: %02x %02x", i, (*data)[i], (*data)[i+1]);
+	ptp_debug_data(params, *data, datasize);
 #endif
-	ptp_debug(params,"    version of d1d3 is %d with %d focus points in struct and %d in use",
-	          version, focus_points_in_struct, focus_points_in_use);
 
+	/* every selected focus_point gets an entry like "{N,N,N,N}," where N can be 5 chars long */
+	maxlen = 1 + focus_points_in_use * 26 + 2;
 	str = (char*)malloc( maxlen );
 	if (!str)
 		return NULL;
 	p = str;
 
-	p += sprintf(p,"eosversion=%u,size=%ux%u,size2=%ux%u,points={", version, sizeX, sizeY, size2X, size2Y);
+	/* output only the selected AF-points, so no AF means you get an empty list: "{}" */
+	p += sprintf(p,"{");
 	for (i=0;i<focus_points_in_use;i++) {
+		if (((1<<(i%8)) & (*data)[focus_points_in_struct*8+20+i/8]) == 0)
+			continue;
 		int16_t x = dtoh16a((*data) + focus_points_in_struct*4 + 20 + 2*i);
 		int16_t y = dtoh16a((*data) + focus_points_in_struct*6 + 20 + 2*i);
 		int16_t w = dtoh16a((*data) + focus_points_in_struct*2 + 20 + 2*i);
 		int16_t h = dtoh16a((*data) + focus_points_in_struct*0 + 20 + 2*i);
 
-		p += sprintf(p,"{%d,%d,%d,%d}",x,y,w,h);
-
-		if (i<focus_points_in_use-1)
-			p += sprintf(p,",");
-	}
-	p += sprintf(p,"},select={");
-	for (i=0;i<focus_points_in_use;i++) {
-		if ((1<<(i%8)) & ((*data)[focus_points_in_struct*8+20+i/8]))
-			p+=sprintf(p,"%u,", i);
-	}
-
-	p += sprintf(p,"},unknown={");
-	for (i=focus_points_in_struct*8+(focus_points_in_struct+7)/8+20;i<size;i++) {
-		if ((p-str) > maxlen - 4)
+		int n = snprintf(p, maxlen - (p - str), "{%d,%d,%d,%d},", x, y, w, h);
+		if (n < 0 || n > maxlen - (p - str)) {
+			ptp_error(params, "snprintf buffer overflow in %s", __func__);
 			break;
-		p+=sprintf(p,"%02x", (*data)[i]);
+		}
+		p += n;
 	}
-	p += sprintf(p,"}");
+	if (p[-1] == ',')
+		p--;
+	p += sprintf(p, "}");
 	return str;
 }
 
@@ -2408,6 +2397,16 @@ static unsigned int olcsizes[0x15][13] = {
 				case 0x0100: /* Focus Info */
 					/* mask 0x0100: 6 bytes, 00 00 00 00 00 00 (before focus) and
 					 *                       00 00 00 00 01 00 (on focus) observed */
+					/* a full trigger capture cycle on the 5Ds with enabled and acting auto-focus looks like this
+						0.098949  6 bytes: 00 00 00 00 00 00 (first GetEvent)
+						0.705762  6 bytes: 00 00 00 00 00 01 (first GetEvent after half-press-on, together with FocusInfoEx == {})
+						0.758275  6 bytes: 00 00 00 00 01 01 (second GetEvent after half-press-on, together with FocusInfoEx == {...})
+						0.962160  6 bytes: 00 00 00 00 01 00 (couple GetEvents later, together with 3x FocusInfoEx == {} and next line)
+						0.962300  6 bytes: 00 00 00 00 00 00
+					   On AF-failure, the 5Ds sequence is 0-1, 2-2, 2-0, 0-0.
+					   The R8 looks similar except another 00 byte is appended and on sucess it jumps directly from 1-1 to 0-0.
+					   On an AF-failure, it jumps from 0-1 to 0-0. The R5m2 has seen to fail with 0-1, 2-1, 2-0, 0-0.
+					*/
 					e[i].type = PTP_EOSEvent_FocusInfo;
 					PTP_CANON_SET_INFO(e[i], "%s", ptp_bytes2str(curdata + curoff, olcsizes[olcver][j], "%02x"));
 					break;