2lib: add VB2_DEBUG_RAW() to print without function name

Currently, VB2_DEBUG() will print the function name as a prefix to the
debug output.  Add VB2_DEBUG_RAW() to print without that, so that it's
possible to print little bits of debug output.  Use this in ec_sync to
hex dump the hashes.

And then clean up all of the debug calls which explicitly did things like:
    VB2_DEBUG("%s: foo", __func__);
to just:
    VB2_DEBUG("foo");
so they don't double-print the function name

BUG=chromium:683391
BRANCH=none
TEST=build_packages --board=reef chromeos-firmware &&
     DEBUG=1 make -j runtests
CQ-DEPEND=CL:430978,CL:431111

Change-Id: I0c35519d2e670d55d65d01eaa60d61f3e3edf419
Signed-off-by: Randall Spangler <rspangler@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/431171
Reviewed-by: Julius Werner <jwerner@chromium.org>

firmware/2lib/2stub.c

@@ -16,6 +16,7 @@ void vb2ex_printf(const char *func, const char *fmt, ...)
 {
 	va_list ap;
 	va_start(ap, fmt);
+	if (func)
 		fprintf(stderr, "%s: ", func);
 	vfprintf(stderr, fmt, ap);
 	va_end(ap);

firmware/2lib/include/2api.h

@@ -628,6 +628,18 @@ int vb2ex_read_resource(struct vb2_context *ctx,
 			void *buf,
 			uint32_t size);
 
+/**
+ * Print debug output
+ *
+ * This should work like printf().  If func!=NULL, it will be a string with
+ * the current function name; that can be used to generate prettier debug
+ * output.  If func==NULL, don't print any extra header/trailer so that this
+ * can be used to composite a bigger output string from several calls - for
+ * example, when doing a hex dump.
+ *
+ * @param func		Function name generating output, or NULL.
+ * @param fmt		Printf format string
+ */
 void vb2ex_printf(const char *func, const char *fmt, ...);
 
 /**

firmware/2lib/include/2common.h

@@ -32,12 +32,18 @@ struct vb2_public_key;
 #if defined(VBOOT_DEBUG)
 #  if defined(FOR_TEST)
 #    include <stdio.h>
-#    define VB2_DEBUG(format, args...) printf(format, ## args)
+#    define VB2_DEBUG(format, args...)		do {	\
+	printf("%s", __func__);				\
+	printf(format, ## args);			\
+	} while(0)
+#    define VB2_DEBUG_RAW(format, args...) printf(format, ## args)
 #  else
 #    define VB2_DEBUG(format, args...) vb2ex_printf(__func__, format, ## args)
+#    define VB2_DEBUG_RAW(format, args...) vb2ex_printf(NULL, format, ## args)
 #  endif
 #else
 #  define VB2_DEBUG(format, args...)
+#  define VB2_DEBUG_RAW(format, args...)
 #endif
 
 /*

firmware/lib/ec_sync.c

@@ -68,8 +68,8 @@ static void print_hash(const uint8_t *hash, uint32_t hash_size,
 
 	VB2_DEBUG("%s hash: ", desc);
 	for (i = 0; i < hash_size; i++)
-		VB2_DEBUG("%02x", hash[i]);
+		VB2_DEBUG_RAW("%02x", hash[i]);
-	VB2_DEBUG("\n");
+	VB2_DEBUG_RAW("\n");
 }
 
 /**
@@ -90,7 +90,7 @@ static int check_ec_hash(struct vb2_context *ctx, int devidx,
 	int ec_hash_size;
 	int rv = VbExEcHashImage(devidx, select, &ec_hash, &ec_hash_size);
 	if (rv) {
-		VB2_DEBUG("%s: VbExEcHashImage() returned %d\n", __func__, rv);
+		VB2_DEBUG("VbExEcHashImage() returned %d\n", rv);
 		request_recovery(ctx, VB2_RECOVERY_EC_HASH_FAILED);
 		return VB2_ERROR_EC_HASH_IMAGE;
 	}
@@ -102,14 +102,13 @@ static int check_ec_hash(struct vb2_context *ctx, int devidx,
 	int hash_size;
 	rv = VbExEcGetExpectedImageHash(devidx, select, &hash, &hash_size);
 	if (rv) {
-		VB2_DEBUG("%s: VbExEcGetExpectedImageHash() returned %d\n",
+		VB2_DEBUG("VbExEcGetExpectedImageHash() returned %d\n", rv);
-			  __func__, rv);
 		request_recovery(ctx, VB2_RECOVERY_EC_EXPECTED_HASH);
 		return VB2_ERROR_EC_HASH_EXPECTED;
 	}
 	if (ec_hash_size != hash_size) {
-		VB2_DEBUG("%s: EC uses %d-byte hash, but AP-RW contains %d "
+		VB2_DEBUG("EC uses %d-byte hash, but AP-RW contains %d bytes\n",
-			  "bytes\n", __func__, ec_hash_size, hash_size);
+			  ec_hash_size, hash_size);
 		request_recovery(ctx, VB2_RECOVERY_EC_HASH_SIZE);
 		return VB2_ERROR_EC_HASH_SIZE;
 	}
@@ -135,7 +134,7 @@ static VbError_t update_ec(struct vb2_context *ctx, int devidx,
 {
 	struct vb2_shared_data *sd = vb2_get_sd(ctx);
 
-	VB2_DEBUG("%s: updating %s...\n", __func__,
+	VB2_DEBUG("updating %s...\n",
 		  select == VB_SELECT_FIRMWARE_READONLY ? "RO" : "RW");
 
 	/* Get expected EC image */
@@ -143,17 +142,15 @@ static VbError_t update_ec(struct vb2_context *ctx, int devidx,
 	int want_size;
 	int rv = VbExEcGetExpectedImage(devidx, select, &want, &want_size);
 	if (rv) {
-		VB2_DEBUG("%s: VbExEcGetExpectedImage() returned %d\n",
+		VB2_DEBUG("VbExEcGetExpectedImage() returned %d\n", rv);
-			  __func__, rv);
 		request_recovery(ctx, VB2_RECOVERY_EC_EXPECTED_IMAGE);
 		return rv;
 	}
-	VB2_DEBUG("%s: image len = %d\n", __func__, want_size);
+	VB2_DEBUG("image len = %d\n", want_size);
 
 	rv = VbExEcUpdateImage(devidx, select, want, want_size);
 	if (rv != VBERROR_SUCCESS) {
-		VB2_DEBUG("%s: VbExEcUpdateImage() returned %d\n",
+		VB2_DEBUG("VbExEcUpdateImage() returned %d\n", rv);
-			  __func__, rv);
 
 		/*
 		 * The EC may know it needs a reboot.  It may need to
@@ -175,7 +172,7 @@ static VbError_t update_ec(struct vb2_context *ctx, int devidx,
 	if (check_ec_hash(ctx, devidx, select) != VB2_SUCCESS)
 		return VBERROR_EC_REBOOT_TO_RO_REQUIRED;
 	if (sd->flags & WHICH_EC(devidx, select)) {
-		VB2_DEBUG("%s: Failed to update\n", __func__);
+		VB2_DEBUG("Failed to update\n");
 		request_recovery(ctx, VB2_RECOVERY_EC_UPDATE);
 		return VBERROR_EC_REBOOT_TO_RO_REQUIRED;
 	}
@@ -217,13 +214,12 @@ static VbError_t check_ec_active(struct vb2_context *ctx, int devidx)
 			 * had some way to track that we'd already rebooted for
 			 * this reason, we could retry only once.
 			 */
-			VB2_DEBUG("%s: want recovery but got EC-RW\n",
+			VB2_DEBUG("want recovery but got EC-RW\n");
-				  __func__);
 			request_recovery(ctx, sd->recovery_reason);
 			return VBERROR_EC_REBOOT_TO_RO_REQUIRED;
 		}
 
-		VB2_DEBUG("%s: in recovery; EC-RO\n", __func__);
+		VB2_DEBUG("in recovery; EC-RO\n");
 		return VBERROR_SUCCESS;
 	}
 
@@ -232,7 +228,7 @@ static VbError_t check_ec_active(struct vb2_context *ctx, int devidx)
 	 * reboot to recovery.
 	 */
 	if (rv != VBERROR_SUCCESS) {
-		VB2_DEBUG("%s: VbExEcRunningRW() returned %d\n", __func__, rv);
+		VB2_DEBUG("VbExEcRunningRW() returned %d\n", rv);
 		request_recovery(ctx, VB2_RECOVERY_EC_UNKNOWN_IMAGE);
 		return VBERROR_EC_REBOOT_TO_RO_REQUIRED;
 	}
@@ -260,7 +256,7 @@ static VbError_t sync_one_ec(struct vb2_context *ctx, int devidx,
 		VB_SELECT_FIRMWARE_A;
 	int rv;
 
-	VB2_DEBUG("%s: devidx=%d\n", __func__, devidx);
+	VB2_DEBUG("devidx=%d\n", devidx);
 
 	/* Update the RW Image */
 	if (sd->flags & VB2_SD_FLAG_ECSYNC_RW) {
@@ -270,11 +266,10 @@ static VbError_t sync_one_ec(struct vb2_context *ctx, int devidx,
 
 	/* Tell EC to jump to its RW image */
 	if (!(sd->flags & IN_RW(devidx))) {
-		VB2_DEBUG("%s: jumping to EC-RW\n", __func__);
+		VB2_DEBUG("jumping to EC-RW\n");
 		rv = VbExEcJumpToRW(devidx);
 		if (rv != VBERROR_SUCCESS) {
-			VB2_DEBUG("%s: VbExEcJumpToRW() returned %x\n",
+			VB2_DEBUG("VbExEcJumpToRW() returned %x\n", rv);
-				  __func__, rv);
 
 			/*
 			 * If a previous AP boot has called VbExEcStayInRO(),
@@ -292,7 +287,7 @@ static VbError_t sync_one_ec(struct vb2_context *ctx, int devidx,
 
 	/* Might need to update EC-RO (but not PD-RO) */
 	if (sd->flags & VB2_SD_FLAG_ECSYNC_EC_RO) {
-		VB2_DEBUG("%s: RO Software Sync\n", __func__);
+		VB2_DEBUG("RO Software Sync\n");
 
 		/* Reset RO Software Sync NV flag */
 		vb2_nv_set(ctx, VB2_NV_TRY_RO_SYNC, 0);
@@ -338,8 +333,7 @@ static VbError_t sync_one_ec(struct vb2_context *ctx, int devidx,
 
 	rv = VbExEcDisableJump(devidx);
 	if (rv != VBERROR_SUCCESS) {
-		VB2_DEBUG("%s: VbExEcDisableJump() returned %d\n",
+		VB2_DEBUG("VbExEcDisableJump() returned %d\n", rv);
-			  __func__, rv);
 		request_recovery(ctx, VB2_RECOVERY_EC_SOFTWARE_SYNC);
 		return VBERROR_EC_REBOOT_TO_RO_REQUIRED;
 	}

firmware/lib/ec_sync_all.c

@@ -37,7 +37,7 @@ VbError_t ec_sync_all(struct vb2_context *ctx, struct VbCommonParams *cparams)
 				shared->flags & VBSD_OPROM_MATTERS &&
 				!(shared->flags & VBSD_OPROM_LOADED));
 	if (reboot_for_oprom) {
-		VB2_DEBUG("%s: Reboot to load VGA Option ROM\n", __func__);
+		VB2_DEBUG("Reboot to load VGA Option ROM\n");
 		vb2_nv_set(ctx, VB2_NV_OPROM_NEEDED, 1);
 	}
 
@@ -49,7 +49,7 @@ VbError_t ec_sync_all(struct vb2_context *ctx, struct VbCommonParams *cparams)
 
 	/* Display the wait screen if we need it */
 	if (need_wait_screen) {
-		VB2_DEBUG("%s: EC is slow. Show WAIT screen.\n", __func__);
+		VB2_DEBUG("EC is slow. Show WAIT screen.\n");
 		VbDisplayScreen(ctx, cparams, VB_SCREEN_WAIT, 0);
 	}
 
@@ -72,7 +72,7 @@ VbError_t ec_sync_all(struct vb2_context *ctx, struct VbCommonParams *cparams)
 	    (shared->flags & VBSD_OPROM_MATTERS) &&
 	    (shared->flags & VBSD_OPROM_LOADED) &&
 	    !(shared->flags & VBSD_BOOT_DEV_SWITCH_ON)) {
-		VB2_DEBUG("%s: Reboot to unload VGA Option ROM\n", __func__);
+		VB2_DEBUG("Reboot to unload VGA Option ROM\n");
 		vb2_nv_set(ctx, VB2_NV_OPROM_NEEDED, 0);
 		return VBERROR_VGA_OPROM_MISMATCH;
 	}

firmware/lib/rollback_index.c

@@ -105,10 +105,10 @@ uint32_t ReadSpaceFirmware(RollbackSpaceFirmware *rsf)
 				      offsetof(RollbackSpaceFirmware, crc8)))
 			return TPM_SUCCESS;
 
-		VB2_DEBUG("TPM: %s() - bad CRC\n", __func__);
+		VB2_DEBUG("TPM: bad CRC\n");
 	}
 
-	VB2_DEBUG("TPM: %s() - too many bad CRCs, giving up\n", __func__);
+	VB2_DEBUG("TPM: too many bad CRCs, giving up\n");
 	return TPM_E_CORRUPTED_STATE;
 }
 
@@ -135,11 +135,11 @@ uint32_t WriteSpaceFirmware(RollbackSpaceFirmware *rsf)
 		if (r == TPM_SUCCESS)
 			return r;
 
-		VB2_DEBUG("TPM: %s() - bad CRC\n", __func__);
+		VB2_DEBUG("TPM: bad CRC\n");
 		/* Try writing it again. Maybe it was garbled on the way out. */
 	}
 
-	VB2_DEBUG("TPM: %s() - too many bad CRCs, giving up\n", __func__);
+	VB2_DEBUG("TPM: too many bad CRCs, giving up\n");
 	return TPM_E_CORRUPTED_STATE;
 }
 
@@ -147,7 +147,7 @@ uint32_t SetVirtualDevMode(int val)
 {
 	RollbackSpaceFirmware rsf;
 
-	VB2_DEBUG("TPM: Entering %s()\n", __func__);
+	VB2_DEBUG("TPM: Entering");
 	if (TPM_SUCCESS != ReadSpaceFirmware(&rsf))
 		return VBERROR_TPM_FIRMWARE_SETUP;
 
@@ -165,7 +165,7 @@ uint32_t SetVirtualDevMode(int val)
 	if (TPM_SUCCESS != WriteSpaceFirmware(&rsf))
 		return VBERROR_TPM_SET_BOOT_MODE_STATE;
 
-	VB2_DEBUG("TPM: Leaving %s()\n", __func__);
+	VB2_DEBUG("TPM: Leaving\n");
 	return VBERROR_SUCCESS;
 }
 
@@ -201,10 +201,10 @@ uint32_t ReadSpaceKernel(RollbackSpaceKernel *rsk)
 		    vb2_crc8(rsk, offsetof(RollbackSpaceKernel, crc8)))
 			return TPM_SUCCESS;
 
-		VB2_DEBUG("TPM: %s() - bad CRC\n", __func__);
+		VB2_DEBUG("TPM: bad CRC\n");
 	}
 
-	VB2_DEBUG("TPM: %s() - too many bad CRCs, giving up\n", __func__);
+	VB2_DEBUG("TPM: too many bad CRCs, giving up\n");
 	return TPM_E_CORRUPTED_STATE;
 }
 
@@ -231,11 +231,11 @@ uint32_t WriteSpaceKernel(RollbackSpaceKernel *rsk)
 		if (r == TPM_SUCCESS)
 			return r;
 
-		VB2_DEBUG("TPM: %s() - bad CRC\n", __func__);
+		VB2_DEBUG("TPM: bad CRC\n");
 		/* Try writing it again. Maybe it was garbled on the way out. */
 	}
 
-	VB2_DEBUG("TPM: %s() - too many bad CRCs, giving up\n", __func__);
+	VB2_DEBUG("TPM: too many bad CRCs, giving up\n");
 	return TPM_E_CORRUPTED_STATE;
 }
 
@@ -347,11 +347,10 @@ uint32_t RollbackFwmpRead(struct RollbackSpaceFwmp *fwmp)
 		r = TlclRead(FWMP_NV_INDEX, u.buf, sizeof(u.bf));
 		if (r == TPM_E_BADINDEX) {
 			/* Missing space is not an error; use defaults */
-			VB2_DEBUG("TPM: %s() - no FWMP space\n", __func__);
+			VB2_DEBUG("TPM: no FWMP space\n");
 			return TPM_SUCCESS;
 		} else if (r != TPM_SUCCESS) {
-			VB2_DEBUG("TPM: %s() - read returned 0x%x\n",
+			VB2_DEBUG("TPM: read returned 0x%x\n", r);
-				  __func__, r);
 			return r;
 		}
 
@@ -375,7 +374,7 @@ uint32_t RollbackFwmpRead(struct RollbackSpaceFwmp *fwmp)
 
 		/* Verify CRC */
 		if (u.bf.crc != vb2_crc8(u.buf + 2, u.bf.struct_size - 2)) {
-			VB2_DEBUG("TPM: %s() - bad CRC\n", __func__);
+			VB2_DEBUG("TPM: bad CRC\n");
 			continue;
 		}
 
@@ -397,7 +396,7 @@ uint32_t RollbackFwmpRead(struct RollbackSpaceFwmp *fwmp)
 		return TPM_SUCCESS;
 	}
 
-	VB2_DEBUG("TPM: %s() - too many bad CRCs, giving up\n", __func__);
+	VB2_DEBUG("TPM: too many bad CRCs, giving up\n");
 	return TPM_E_CORRUPTED_STATE;
 }
 

firmware/lib/tpm2_lite/marshaling.c

@@ -113,9 +113,8 @@ static void unmarshal_TPM2B_MAX_NV_BUFFER(void **buffer,
 {
 	nv_buffer->t.size = unmarshal_u16(buffer, size);
 	if (nv_buffer->t.size > *size) {
-		VB2_DEBUG("%s:%d - "
+		VB2_DEBUG("size mismatch: expected %d, remaining %d\n",
-			  "size mismatch: expected %d, remaining %d\n",
+			  nv_buffer->t.size, *size);
-			  __func__, __LINE__, nv_buffer->t.size, *size);
 		return;
 	}
 
@@ -133,9 +132,8 @@ static void unmarshal_authorization_section(void **buffer, int *size,
 	 * just confirm that this is the case and report any discrepancy.
 	 */
 	if (*size != 5)
-		VB2_DEBUG("%s:%d - unexpected authorisation section size %d "
+		VB2_DEBUG("unexpected authorisation section size %d for %s\n",
-			  "for %s\n",
+			  *size, cmd_name);
-			  __func__, __LINE__, *size, cmd_name);
 
 	*buffer = ((uint8_t *)(*buffer)) + *size;
 	*size = 0;
@@ -150,9 +148,8 @@ static void unmarshal_nv_read(void **buffer, int *size,
 
 	if (nvr->params_size !=
 	    (nvr->buffer.t.size + sizeof(nvr->buffer.t.size))) {
-		VB2_DEBUG("%s:%d - parameter/buffer %d/%d size mismatch",
+		VB2_DEBUG("parameter/buffer %d/%d size mismatch",
-			  __func__, __LINE__, nvr->params_size,
+			  nvr->params_size, nvr->buffer.t.size);
-			  nvr->buffer.t.size);
 		return;
 	}
 
@@ -168,9 +165,8 @@ static void unmarshal_TPM2B(void **buffer,
 {
 	tpm2b->size = unmarshal_u16(buffer, size);
 	if (tpm2b->size > *size) {
-		VB2_DEBUG("%s:%d - "
+		VB2_DEBUG("size mismatch: expected %d, remaining %d\n",
-			  "size mismatch: expected %d, remaining %d\n",
+			  tpm2b->size, *size);
-			  __func__, __LINE__, tpm2b->size, *size);
 		*size = -1;
 		return;
 	}
@@ -187,9 +183,8 @@ static void unmarshal_TPMS_NV_PUBLIC(void **buffer,
 {
 	int tpm2b_size = unmarshal_u16(buffer, size);
 	if (tpm2b_size > *size) {
-		VB2_DEBUG("%s:%d - "
+		VB2_DEBUG("size mismatch: expected %d, remaining %d\n",
-			  "size mismatch: expected %d, remaining %d\n",
+			  tpm2b_size, *size);
-			  __func__, __LINE__, tpm2b_size, *size);
 		*size = -1;
 		return;
 	}
@@ -202,9 +197,7 @@ static void unmarshal_TPMS_NV_PUBLIC(void **buffer,
 	pub->dataSize = unmarshal_u16(buffer, &tpm2b_size);
 
 	if (tpm2b_size != 0) {
-		VB2_DEBUG("%s:%d - "
+		VB2_DEBUG("TPMS_NV_PUBLIC size doesn't match size field\n");
-			  "TPMS_NV_PUBLIC size doesn't match the size field\n",
-			  __func__, __LINE__);
 		*size = -1;
 		return;
 	}
@@ -217,9 +210,7 @@ static void unmarshal_nv_read_public(void **buffer, int *size,
 	unmarshal_TPM2B(buffer, size, &nv_pub->nvName);
 
 	if (*size > 0) {
-		VB2_DEBUG("%s:%d - "
+		VB2_DEBUG("extra %d bytes after nvName\n", *size);
-			  "extra %d bytes after nvName\n",
-			  __func__, __LINE__, *size);
 		*size = -1;
 		return;
 	}
@@ -232,9 +223,9 @@ static void unmarshal_TPML_TAGGED_TPM_PROPERTY(void **buffer, int *size,
 
 	if (prop->count != 1) {
 		*size = -1;
-		VB2_DEBUG("%s:%d:Request to unmarshal unsupported "
+		VB2_DEBUG("Request to unmarshal unsupported "
 			  "number of properties: %u\n",
-			  __FILE__, __LINE__, prop->count);
+			  prop->count);
 		return;
 	}
 
@@ -257,9 +248,8 @@ static void unmarshal_TPMS_CAPABILITY_DATA(void **buffer, int *size,
 
 	default:
 		*size = -1;
-		VB2_DEBUG("%s:%d:Request to unmarshal unsupported "
+		VB2_DEBUG("Request to unmarshal unsupported capability %#x\n",
-			  "capability %#x\n",
+			  cap_data->capability);
-			  __FILE__, __LINE__, cap_data->capability);
 	}
 }
 
@@ -354,8 +344,7 @@ static void marshal_reserve_size_field(void **buffer,
 				       int *buffer_space)
 {
 	if (field_size != sizeof(uint32_t) && field_size != sizeof(uint16_t)) {
-		VB2_DEBUG("%s:%d:Unsupported size field size: %d\n",
+		VB2_DEBUG("Unsupported size field size: %d\n", field_size);
-			  __FILE__, __LINE__, field_size);
 		*buffer_space = -1;
 		return;
 	}
@@ -709,8 +698,8 @@ int tpm_marshal_command(TPM_CC command, void *tpm_command_body,
 
 	default:
 		body_size = -1;
-		VB2_DEBUG("%s:%d:Request to marshal unsupported command %#x\n",
+		VB2_DEBUG("Request to marshal unsupported command %#x\n",
-			  __FILE__, __LINE__, command);
+			  command);
 	}
 
 	if (body_size > 0) {
@@ -743,9 +732,8 @@ struct tpm2_response *tpm_unmarshal_response(TPM_CC command,
 
 	if (!cr_size) {
 		if (tpm2_resp.hdr.tpm_size != sizeof(tpm2_resp.hdr))
-			VB2_DEBUG("%s: "
+			VB2_DEBUG("size mismatch in response to command %#x\n",
-				  "size mismatch in response to command %#x\n",
+				  command);
-				  __func__, command);
 		return &tpm2_resp;
 	}
 
@@ -782,16 +770,15 @@ struct tpm2_response *tpm_unmarshal_response(TPM_CC command,
 		{
 			int i;
 
-			VB2_DEBUG("%s:%d:"
+			VB2_DEBUG("Request to unmarshal unexpected command %#x,"
-				  "Request to unmarshal unexpected command %#x,"
 				  " code %#x",
-				  __func__, __LINE__, command,
+				  command,
 				  tpm2_resp.hdr.tpm_code);
 
 			for (i = 0; i < cr_size; i++) {
 				if (!(i % 16))
-					VB2_DEBUG("\n");
+					VB2_DEBUG_RAW("\n");
-				VB2_DEBUG("%2.2x ",
+				VB2_DEBUG_RAW("%2.2x ",
 					      ((uint8_t *)response_body)[i]);
 			}
 		}
@@ -800,9 +787,9 @@ struct tpm2_response *tpm_unmarshal_response(TPM_CC command,
 	}
 
 	if (cr_size) {
-		VB2_DEBUG("%s:%d got %d bytes back in response to %#x,"
+		VB2_DEBUG("got %d bytes back in response to %#x,"
 			  " failed to parse (%d)\n",
-			  __func__, __LINE__, tpm2_resp.hdr.tpm_size,
+			  tpm2_resp.hdr.tpm_size,
 			  command, cr_size);
 		return NULL;
 	}

firmware/lib/tpm2_lite/tlcl.c

@@ -39,7 +39,7 @@ static struct tpm2_response *tpm_process_command(TPM_CC command,
 
 	response = tpm_unmarshal_response(command, cr_buffer, in_size);
 
-	VB2_DEBUG("%s: command %#x, return code %#x\n", __func__, command,
+	VB2_DEBUG("command %#x, return code %#x\n", command,
 		  response ? response->hdr.tpm_code : -1);
 
 	return response;
@@ -210,13 +210,13 @@ uint32_t TlclForceClear(void)
 
 uint32_t TlclSetDeactivated(uint8_t flag)
 {
-	VB2_DEBUG("%s called, NOT YET IMPLEMENTED\n", __func__);
+	VB2_DEBUG("NOT YET IMPLEMENTED\n");
 	return TPM_SUCCESS;
 }
 
 uint32_t TlclSetEnable(void)
 {
-	VB2_DEBUG("%s called, NOT YET IMPLEMENTED\n", __func__);
+	VB2_DEBUG("NOT YET IMPLEMENTED\n");
 	return TPM_SUCCESS;
 }
 
@@ -236,13 +236,13 @@ uint32_t TlclGetFlags(uint8_t* disable,
 
 int TlclIsOwned(void)
 {
-	VB2_DEBUG("%s called, NOT YET IMPLEMENTED\n", __func__);
+	VB2_DEBUG("NOT YET IMPLEMENTED\n");
 	return 0;
 }
 
 uint32_t TlclExtend(int pcr_num, const uint8_t *in_digest, uint8_t *out_digest)
 {
-	VB2_DEBUG("%s called, NOT YET IMPLEMENTED\n", __func__);
+	VB2_DEBUG("NOT YET IMPLEMENTED\n");
 	return TPM_SUCCESS;
 }
 
@@ -476,7 +476,7 @@ uint32_t TlclWrite(uint32_t index, const void *data, uint32_t length)
 
 uint32_t TlclPCRRead(uint32_t index, void *data, uint32_t length)
 {
-	VB2_DEBUG("%s called, NOT YET IMPLEMENTED\n", __func__);
+	VB2_DEBUG("NOT YET IMPLEMENTED\n");
 	return TPM_SUCCESS;
 }
 
@@ -519,6 +519,6 @@ uint32_t TlclReadLock(uint32_t index)
 uint32_t TlclGetRandom(uint8_t *data, uint32_t length, uint32_t *size)
 {
 	*size = 0;
-	VB2_DEBUG("%s called, NOT YET IMPLEMENTED\n", __func__);
+	VB2_DEBUG("NOT YET IMPLEMENTED\n");
 	return TPM_E_IOERROR;
 }

firmware/lib/vboot_api_kernel.c

@@ -190,7 +190,7 @@ VbError_t VbBootNormal(struct vb2_context *ctx, VbCommonParams *cparams)
 		(VbSharedDataHeader *)cparams->shared_data_blob;
 
 	/* Boot from fixed disk only */
-	VB2_DEBUG("Entering %s()\n", __func__);
+	VB2_DEBUG("Entering\n");
 
 	VbError_t rv = VbTryLoadKernel(ctx, cparams, VB_DISK_FLAG_FIXED);
 
@@ -278,7 +278,7 @@ static VbError_t vb2_kernel_setup(VbCommonParams *cparams,
 
 	unaligned_workbuf = ctx.workbuf = malloc(ctx.workbuf_size);
 	if (!unaligned_workbuf) {
-		VB2_DEBUG("%s: Can't allocate work buffer\n", __func__);
+		VB2_DEBUG("Can't allocate work buffer\n");
 		VbSetRecoveryRequest(&ctx, VB2_RECOVERY_RW_SHARED_DATA);
 		return VBERROR_INIT_SHARED_DATA;
 	}
@@ -286,13 +286,13 @@ static VbError_t vb2_kernel_setup(VbCommonParams *cparams,
 	if (VB2_SUCCESS != vb2_align(&ctx.workbuf, &ctx.workbuf_size,
 				     VB2_WORKBUF_ALIGN,
 				     VB2_KERNEL_WORKBUF_RECOMMENDED_SIZE)) {
-		VB2_DEBUG("%s: Can't align work buffer\n", __func__);
+		VB2_DEBUG("Can't align work buffer\n");
 		VbSetRecoveryRequest(&ctx, VB2_RECOVERY_RW_SHARED_DATA);
 		return VBERROR_INIT_SHARED_DATA;
 	}
 
 	if (VB2_SUCCESS != vb2_init_context(&ctx)) {
-		VB2_DEBUG("%s: Can't init vb2_context\n", __func__);
+		VB2_DEBUG("Can't init vb2_context\n");
 		free(unaligned_workbuf);
 		VbSetRecoveryRequest(&ctx, VB2_RECOVERY_RW_SHARED_DATA);
 		return VBERROR_INIT_SHARED_DATA;
@@ -453,7 +453,7 @@ VbError_t VbSelectAndLoadKernel(VbCommonParams *cparams,
 	vb2_kernel_cleanup(&ctx, cparams);
 
 	/* Pass through return value from boot path */
-	VB2_DEBUG("%s returning %d\n", __func__, (int)retval);
+	VB2_DEBUG("Returning %d\n", (int)retval);
 	return retval;
 }
 
@@ -635,12 +635,11 @@ fail:
 
 VbError_t VbUnlockDevice(void)
 {
-	VB2_DEBUG("%s() Enabling dev-mode...\n", __func__);
+	VB2_DEBUG("Enabling dev-mode...\n");
 	if (TPM_SUCCESS != SetVirtualDevMode(1))
 		return VBERROR_TPM_SET_BOOT_MODE_STATE;
 
-	VB2_DEBUG("%s() Mode change will take effect on next reboot.\n",
+	VB2_DEBUG("Mode change will take effect on next reboot.\n");
-		  __func__);
 	return VBERROR_SUCCESS;
 }
 
@@ -648,14 +647,12 @@ VbError_t VbLockDevice(void)
 {
 	VbNvLoad();
 
-	VB2_DEBUG("%s() - Storing request to leave dev-mode.\n",
+	VB2_DEBUG("Storing request to leave dev-mode.\n");
-		  __func__);
 	VbNvSet(&vnc, VBNV_DISABLE_DEV_REQUEST, 1);
 
 	VbNvCommit();
 
-	VB2_DEBUG("%s() Mode change will take effect on next reboot.\n",
+	VB2_DEBUG("Mode change will take effect on next reboot.\n");
-		  __func__);
 
 	return VBERROR_SUCCESS;
 }

firmware/lib/vboot_ui.c

@@ -29,7 +29,7 @@
 
 static void VbAllowUsbBoot(struct vb2_context *ctx)
 {
-	VB2_DEBUG("%s\n", __func__);
+	VB2_DEBUG(".");
 	vb2_nv_set(ctx, VB2_NV_DEV_BOOT_USB, 1);
 }
 
@@ -98,7 +98,7 @@ int VbUserConfirms(struct vb2_context *ctx, VbCommonParams *cparams,
         uint32_t button;
 	int rec_button_was_pressed = 0;
 
-	VB2_DEBUG("Entering %s(0x%x)\n", __func__, confirm_flags);
+	VB2_DEBUG("Entering(%x)\n", confirm_flags);
 
 	/* Await further instructions */
 	while (1) {
@@ -118,17 +118,17 @@ int VbUserConfirms(struct vb2_context *ctx, VbCommonParams *cparams,
 				break;
                         }
 
-			VB2_DEBUG("%s() - Yes (1)\n", __func__);
+			VB2_DEBUG("Yes (1)\n");
 			return 1;
 			break;
 		case ' ':
-			VB2_DEBUG("%s() - Space (%d)\n", __func__,
+			VB2_DEBUG("Space (%d)\n",
 				  confirm_flags & VB_CONFIRM_SPACE_MEANS_NO);
 			if (confirm_flags & VB_CONFIRM_SPACE_MEANS_NO)
 				return 0;
 			break;
 		case 0x1b:
-			VB2_DEBUG("%s() - No (0)\n", __func__);
+			VB2_DEBUG("No (0)\n");
 			return 0;
 			break;
 		default:
@@ -137,12 +137,10 @@ int VbUserConfirms(struct vb2_context *ctx, VbCommonParams *cparams,
 			 */
 			if (!(shared->flags & VBSD_BOOT_REC_SWITCH_VIRTUAL)) {
 				if (button) {
-					VB2_DEBUG("%s() - Rec button pressed\n",
+					VB2_DEBUG("Rec button pressed\n");
-						  __func__);
 	                                rec_button_was_pressed = 1;
 				} else if (rec_button_was_pressed) {
-					VB2_DEBUG("%s() - Rec button (1)\n",
+					VB2_DEBUG("Rec button (1)\n");
-						  __func__);
 					return 1;
 				}
 			}
@@ -173,7 +171,7 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 
 	VbAudioContext *audio = 0;
 
-	VB2_DEBUG("Entering %s()\n", __func__);
+	VB2_DEBUG("Entering\n");
 
 	/* Check if USB booting is allowed */
 	uint32_t allow_usb = vb2_nv_get(ctx, VB2_NV_DEV_BOOT_USB);
@@ -205,9 +203,8 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 		allow_legacy = 1;
 	if (fwmp_flags & FWMP_DEV_DISABLE_BOOT) {
 		if (gbb->flags & GBB_FLAG_FORCE_DEV_SWITCH_ON) {
-			VB2_DEBUG("%s() - FWMP_DEV_DISABLE_BOOT rejected by "
+			VB2_DEBUG("FWMP_DEV_DISABLE_BOOT rejected by "
-				  "FORCE_DEV_SWITCH_ON\n",
+				  "FORCE_DEV_SWITCH_ON\n");
-				  __func__);
 		} else {
 			disable_dev_boot = 1;
 		}
@@ -215,14 +212,14 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 
 	/* If dev mode is disabled, only allow TONORM */
 	while (disable_dev_boot) {
-		VB2_DEBUG("%s() - dev_disable_boot is set.\n", __func__);
+		VB2_DEBUG("dev_disable_boot is set\n");
 		VbDisplayScreen(ctx, cparams, VB_SCREEN_DEVELOPER_TO_NORM, 0);
 		VbExDisplayDebugInfo(dev_disable_msg);
 
 		/* Ignore space in VbUserConfirms()... */
 		switch (VbUserConfirms(ctx, cparams, 0)) {
 		case 1:
-			VB2_DEBUG("%s() - leaving dev-mode.\n", __func__);
+			VB2_DEBUG("leaving dev-mode\n");
 			vb2_nv_set(ctx, VB2_NV_DISABLE_DEV_REQUEST, 1);
 			VbDisplayScreen(ctx, cparams,
 					VB_SCREEN_TO_NORM_CONFIRMED,
@@ -230,11 +227,11 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 			VbExSleepMs(5000);
 			return VBERROR_REBOOT_REQUIRED;
 		case -1:
-			VB2_DEBUG("%s() - shutdown requested\n", __func__);
+			VB2_DEBUG("shutdown requested\n");
 			return VBERROR_SHUTDOWN_REQUESTED;
 		default:
 			/* Ignore user attempt to cancel */
-			VB2_DEBUG("%s() - ignore cancel TONORM\n", __func__);
+			VB2_DEBUG("ignore cancel TONORM\n");
 		}
 	}
 
@@ -265,8 +262,7 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 				break;
 		case ' ':
 			/* See if we should disable virtual dev-mode switch. */
-			VB2_DEBUG("%s shared->flags=0x%x\n",
+			VB2_DEBUG("shared->flags=0x%x\n", shared->flags);
-				  __func__, shared->flags);
 			if (shared->flags & VBSD_HONOR_VIRT_DEV_SWITCH &&
 			    shared->flags & VBSD_BOOT_DEV_SWITCH_ON) {
 				/* Stop the countdown while we go ask... */
@@ -276,9 +272,8 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 					 * TONORM won't work (only for
 					 * non-shipping devices).
 					 */
-					VB2_DEBUG("%s() - TONORM rejected by "
+					VB2_DEBUG("TONORM rejected by "
-						  "FORCE_DEV_SWITCH_ON\n",
+						  "FORCE_DEV_SWITCH_ON\n");
-						  __func__);
 					VbExDisplayDebugInfo(
 						"WARNING: TONORM prohibited by "
 						"GBB FORCE_DEV_SWITCH_ON.\n\n");
@@ -291,8 +286,7 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 				/* Ignore space in VbUserConfirms()... */
 				switch (VbUserConfirms(ctx, cparams, 0)) {
 				case 1:
-					VB2_DEBUG("%s() - leaving dev-mode.\n",
+					VB2_DEBUG("leaving dev-mode\n");
-						  __func__);
 					vb2_nv_set(ctx, VB2_NV_DISABLE_DEV_REQUEST,
 						1);
 					VbDisplayScreen(ctx,
@@ -302,13 +296,11 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 					VbExSleepMs(5000);
 					return VBERROR_REBOOT_REQUIRED;
 				case -1:
-					VB2_DEBUG("%s() - shutdown requested\n",
+					VB2_DEBUG("shutdown requested\n");
-						  __func__);
 					return VBERROR_SHUTDOWN_REQUESTED;
 				default:
 					/* Stay in dev-mode */
-					VB2_DEBUG("%s() - stay in dev-mode\n",
+					VB2_DEBUG("stay in dev-mode\n");
-						  __func__);
 					VbDisplayScreen(ctx,
 						cparams,
 						VB_SCREEN_DEVELOPER_WARNING,
@@ -321,8 +313,7 @@ VbError_t vb2_developer_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 				 * No virtual dev-mode switch, so go directly
 				 * to recovery mode.
 				 */
-				VB2_DEBUG("%s() - going to recovery\n",
+				VB2_DEBUG("going to recovery\n");
-					  __func__);
 				vb2_nv_set(ctx, VB2_NV_RECOVERY_REQUEST,
 					   VBNV_RECOVERY_RW_DEV_SCREEN);
 				VbAudioClose(audio);
@@ -520,8 +511,8 @@ VbError_t vb2_recovery_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 					 * any case we don't like this.  Beep
 					 * and ignore.
 					 */
-					VB2_DEBUG("%s() - ^D but rec switch "
+					VB2_DEBUG("^D but rec switch "
-						  "is pressed\n", __func__);
+						  "is pressed\n");
 					VbExBeep(120, 400);
 					continue;
 				}
@@ -537,23 +528,20 @@ VbError_t vb2_recovery_ui(struct vb2_context *ctx, VbCommonParams *cparams)
 				switch (VbUserConfirms(ctx, cparams,
 						       vbc_flags)) {
 				case 1:
-					VB2_DEBUG("%s() Enabling dev-mode...\n",
+					VB2_DEBUG("Enabling dev-mode...\n");
-						  __func__);
 					if (TPM_SUCCESS != SetVirtualDevMode(1))
 						return VBERROR_TPM_SET_BOOT_MODE_STATE;
-					VB2_DEBUG("%s() Reboot so it will take "
+					VB2_DEBUG("Reboot so it will take "
-						  "effect\n", __func__);
+						  "effect\n");
 					if (VbExGetSwitches
 					    (VB_INIT_FLAG_ALLOW_USB_BOOT))
 						VbAllowUsbBoot(ctx);
 					return VBERROR_REBOOT_REQUIRED;
 				case -1:
-					VB2_DEBUG("%s() - Shutdown requested\n",
+					VB2_DEBUG("Shutdown requested\n");
-						  __func__);
 					return VBERROR_SHUTDOWN_REQUESTED;
 				default: /* zero, actually */
-					VB2_DEBUG("%s() - Not enabling "
+					VB2_DEBUG("Not enabling dev-mode\n");
-						  "dev-mode\n", __func__);
 					/*
 					 * Jump out of the outer loop to
 					 * refresh the display quickly.

host/lib/host_key.c

@@ -32,7 +32,7 @@ int packed_key_looks_ok(const struct vb2_packed_key *key, uint32_t size)
 
 	if (key->key_version > VB2_MAX_KEY_VERSION) {
 		/* Currently, TPM only supports 16-bit version */
-		VB2_DEBUG("%s() - packed key invalid version\n", __func__);
+		fprintf(stderr, "%s() packed key invalid version\n", __func__);
 		return 0;
 	}
 

host/lib/host_signature2.c

@@ -125,7 +125,7 @@ struct vb2_signature *vb2_calculate_signature(
 	free(signature_digest);
 
 	if (-1 == rv) {
-		VB2_DEBUG("%s: RSA_private_encrypt() failed.\n", __func__);
+		fprintf(stderr, "%s: RSA_private_encrypt() failed\n", __func__);
 		free(sig);
 		return NULL;
 	}