futility: updater: Revise output messages for debug logsfactory-grunt-11164.Bfactory-grunt-11164.135.Bfactory-11164.135.B

In auto update and recovery, the firmware updater was executed with both
stdout and stderr logged. However, the logs usually comes with all stderr
first then all stdout. This makes it harder to debug because the
messages logged in out of order.

TO solve that, few macros are introduced:
 INFO: for useful information.
 STATUS: the most common information, usually comes with a prefix code.

And all messages should now go to stderr except the final execution
result (and those output commands, for example --manifest).

BUG=chromium:875551
TEST=TEST=make futil; tests/futility/run_test_scripts.sh $(pwd)/build/futility
CQ-DEPEND=CL:1345250
BRANCH=None

Change-Id: Ie0dc6594ece10e7e15caf9c36353e2b3ec8754c5
Signed-off-by: Hung-Te Lin <hungte@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/1345611
Reviewed-by: Youcheng Syu <youcheng@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/vboot_reference/+/1694203
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/vboot_reference/+/2306633
Reviewed-by: Cheng-Han Yang <chenghan@chromium.org>
Commit-Queue: Cheng-Han Yang <chenghan@chromium.org>
Tested-by: Cheng-Han Yang <chenghan@chromium.org>

5 files changed, 52 insertions, 48 deletions

diff --git a/futility/cmd_update.c b/futility/cmd_update.c
index 1b202c0f..89a105b0 100644
--- a/futility/cmd_update.c
+++ b/futility/cmd_update.c
@@ -85,7 +85,6 @@ static int do_update(int argc, char *argv[])
 	struct updater_config_arguments args = {0};
 	int i, errorcnt = 0, do_update = 1;
 
-	fprintf(stderr, ">> Firmware updater started.\n");
 	cfg = updater_new_config();
 	assert(cfg);
 
@@ -182,16 +181,19 @@ static int do_update(int argc, char *argv[])
 	if (!errorcnt)
 		errorcnt += updater_setup_config(cfg, &args, &do_update);
 	if (!errorcnt && do_update) {
-		int r = update_firmware(cfg);
+		int r;
+		STATUS("Starting firmware updater.");
+		r = update_firmware(cfg);
 		if (r != UPDATE_ERR_DONE) {
 			r = Min(r, UPDATE_ERR_UNKNOWN);
 			Error("%s\n", updater_error_messages[r]);
 			errorcnt++;
 		}
+		/* Use stdout for the final result. */
+		printf(">> %s: Firmware updater %s.\n",
+			errorcnt ? "FAILED": "DONE",
+			errorcnt ? "aborted" : "exits successfully");
 	}
-	fprintf(stderr, ">> %s: Firmware updater %s.\n",
-		errorcnt ? "FAILED": "DONE",
-		errorcnt ? "stopped due to error" : "exited successfully");
 
 	updater_delete_config(cfg);
 	return !!errorcnt;
diff --git a/futility/updater.c b/futility/updater.c
index acc390b8..7bdac37d 100644
--- a/futility/updater.c
+++ b/futility/updater.c
@@ -297,7 +297,7 @@ static int host_flashrom(enum flashrom_ops op, const char *image_path,
 		 postfix);
 
 	if (verbose)
-		printf("Executing: %s\n", command);
+		INFO("Executing: %s", command);
 
 	if (op != FLASHROM_WP_STATUS) {
 		r = system(command);
@@ -727,8 +727,8 @@ static int set_try_cookies(struct updater_config *cfg, const char *target,
 	}
 
 	if (cfg->emulation) {
-		printf("(emulation) Setting try_next to %s, try_count to %d.\n",
-		       slot, tries);
+		INFO("(emulation) Setting try_next to %s, try_count to %d.",
+		     slot, tries);
 		return 0;
 	}
 
@@ -820,10 +820,10 @@ static int write_firmware(struct updater_config *cfg,
 		return -1;
 
 	if (cfg->emulation) {
-		printf("%s: (emulation) Writing %s from %s to %s (emu=%s).\n",
-		       __FUNCTION__,
-		       section_name ? section_name : "whole image",
-		       image->file_name, programmer, cfg->emulation);
+		INFO("%s: (emulation) Writing %s from %s to %s (emu=%s).",
+		     __FUNCTION__,
+		     section_name ? section_name : "whole image",
+		     image->file_name, programmer, cfg->emulation);
 
 		return emulate_write_firmware(
 				cfg->emulation, image, section_name);
@@ -882,8 +882,8 @@ int preserve_firmware_section(const struct firmware_image *image_from,
 		return -1;
 	}
 	if (from.size > to.size) {
-		printf("WARNING: %s: Section %s is truncated after updated.\n",
-		       __FUNCTION__, section_name);
+		WARN("%s: Section %s is truncated after updated.",
+		     __FUNCTION__, section_name);
 	}
 	/* Use memmove in case if we need to deal with sections that overlap. */
 	memmove(to.data, from.data, Min(from.size, to.size));
@@ -1235,17 +1235,16 @@ static enum rootkey_compat_result check_compatible_root_key(
 				   ROOTKEY_HASH_DEV) == 0)
 				to_dev = 1;
 		}
-		printf("Current (RO) image root key is %s, ",
-		       packed_key_sha1_string(rootkey));
-
+		INFO("Current (RO) firmware image has root key: %s",
+		     packed_key_sha1_string(rootkey));
 		if (is_same_key) {
-			printf("same with target (RW) image. "
-			       "Maybe RW corrupted?\n");
+			ERROR("Rootkey is same as target (RW) image. "
+			      "Maybe RW corrupted?");
 			return ROOTKEY_COMPAT_ERROR;
 		}
-		printf("target (RW) image is signed with rootkey %s.\n",
-		       rootkey_rw ? packed_key_sha1_string(rootkey_rw) :
-		       "<invalid>");
+		WARN("Target (RW) image is signed by rootkey: %s.",
+		     rootkey_rw ? packed_key_sha1_string(rootkey_rw) :
+		     "<invalid>");
 		return to_dev ? ROOTKEY_COMPAT_REKEY_TO_DEV :
 				ROOTKEY_COMPAT_REKEY;
 	}
@@ -1359,7 +1358,7 @@ static int check_compatible_tpm_keys(struct updater_config *cfg,
 		ERROR("Add --force if you want to waive TPM checks.");
 		return r;
 	}
-	printf("TPM KEYS CHECK IS WAIVED BY --force. YOU ARE ON YOUR OWN.\n");
+	WARN("TPM KEYS CHECK IS WAIVED BY --force. YOU ARE ON YOUR OWN.");
 	return 0;
 }
 
@@ -1399,7 +1398,7 @@ static enum updater_error_codes update_try_rw_firmware(
 			image_from, image_to, FMAP_RO_SECTION))
 		return UPDATE_ERR_NEED_RO_UPDATE;
 
-	printf("Checking compatibility...\n");
+	INFO("Checking compatibility...");
 	if (check_compatible_root_key(image_from, image_to))
 		return UPDATE_ERR_ROOT_KEY;
 	if (check_compatible_tpm_keys(cfg, image_to))
@@ -1412,7 +1411,7 @@ static enum updater_error_codes update_try_rw_firmware(
 		return UPDATE_ERR_TARGET;
 	}
 
-	printf("Checking %s contents...\n", target);
+	INFO("Checking %s contents...", target);
 	if (!firmware_section_exists(image_to, target)) {
 		ERROR("Cannot find section '%s' on firmware image: %s",
 		      target, image_to->file_name);
@@ -1423,8 +1422,7 @@ static enum updater_error_codes update_try_rw_firmware(
 
 	if (has_update) {
 		target = decide_rw_target(cfg, TARGET_UPDATE, is_vboot2);
-		printf(">> TRY-RW UPDATE: Updating %s to try on reboot.\n",
-		       target);
+		STATUS("TRY-RW UPDATE: Updating %s to try on reboot.", target);
 
 		if (write_firmware(cfg, image_to, target))
 			return UPDATE_ERR_WRITE_FIRMWARE;
@@ -1439,12 +1437,12 @@ static enum updater_error_codes update_try_rw_firmware(
 	/* Do not fail on updating legacy. */
 	if (legacy_needs_update(cfg)) {
 		has_update = 1;
-		printf(">> LEGACY UPDATE: Updating %s.\n", FMAP_RW_LEGACY);
+		STATUS("LEGACY UPDATE: Updating %s.", FMAP_RW_LEGACY);
 		write_firmware(cfg, image_to, FMAP_RW_LEGACY);
 	}
 
 	if (!has_update)
-		printf(">> No need to update.\n");
+		STATUS("NO UPDATE: No need to update.");
 
 	return UPDATE_ERR_DONE;
 }
@@ -1459,11 +1457,11 @@ static enum updater_error_codes update_rw_firmrware(
 		struct firmware_image *image_from,
 		struct firmware_image *image_to)
 {
-	printf(">> RW UPDATE: Updating RW sections (%s, %s, %s, and %s).\n",
+	STATUS("RW UPDATE: Updating RW sections (%s, %s, %s, and %s).",
 	       FMAP_RW_SECTION_A, FMAP_RW_SECTION_B, FMAP_RW_SHARED,
 	       FMAP_RW_LEGACY);
 
-	printf("Checking compatibility...\n");
+	INFO("Checking compatibility...");
 	if (check_compatible_root_key(image_from, image_to))
 		return UPDATE_ERR_ROOT_KEY;
 	if (check_compatible_tpm_keys(cfg, image_to))
@@ -1490,7 +1488,7 @@ static enum updater_error_codes update_legacy_firmware(
 		struct updater_config *cfg,
 		struct firmware_image *image_to)
 {
-	printf(">> LEGACY UPDATE: Updating firmware %s.\n", FMAP_RW_LEGACY);
+	STATUS("LEGACY UPDATE: Updating firmware %s.", FMAP_RW_LEGACY);
 
 	if (write_firmware(cfg, image_to, FMAP_RW_LEGACY))
 		return UPDATE_ERR_WRITE_FIRMWARE;
@@ -1508,13 +1506,13 @@ static enum updater_error_codes update_whole_firmware(
 		struct updater_config *cfg,
 		struct firmware_image *image_to)
 {
-	printf(">> FULL UPDATE: Updating whole firmware image(s), RO+RW.\n");
+	STATUS("FULL UPDATE: Updating whole firmware image(s), RO+RW.");
 
 	if (preserve_images(cfg))
 		DEBUG("Failed to preserve some sections - ignore.");
 
 
-	printf("Checking compatibility...\n");
+	INFO("Checking compatibility...");
 	if (check_compatible_tpm_keys(cfg, image_to))
 		return UPDATE_ERR_TPM_ROLLBACK;
 	if (!cfg->force_update) {
@@ -1525,7 +1523,7 @@ static enum updater_error_codes update_whole_firmware(
 		case ROOTKEY_COMPAT_OK:
 			break;
 		case ROOTKEY_COMPAT_REKEY:
-			printf("Will change firmware signing key.\n");
+			INFO("Will change firmware signing key.");
 			break;
 		case ROOTKEY_COMPAT_REKEY_TO_DEV:
 			ERROR("Re-key to DEV is not allowed. "
@@ -1560,9 +1558,9 @@ enum updater_error_codes update_firmware(struct updater_config *cfg)
 	if (try_apply_quirk(QUIRK_DAISY_SNOW_DUAL_MODEL, cfg))
 		return UPDATE_ERR_PLATFORM;
 
-	printf(">> Target image: %s (RO:%s, RW/A:%s, RW/B:%s).\n",
-	       image_to->file_name, image_to->ro_version,
-	       image_to->rw_version_a, image_to->rw_version_b);
+	STATUS("Target image: %s (RO:%s, RW/A:%s, RW/B:%s).",
+	     image_to->file_name, image_to->ro_version,
+	     image_to->rw_version_a, image_to->rw_version_b);
 
 	if (try_apply_quirk(QUIRK_MIN_PLATFORM_VERSION, cfg))
 		return UPDATE_ERR_PLATFORM;
@@ -1572,11 +1570,11 @@ enum updater_error_codes update_firmware(struct updater_config *cfg)
 		 * TODO(hungte) Read only RO_SECTION, VBLOCK_A, VBLOCK_B,
 		 * RO_VPD, RW_VPD, RW_NVRAM, RW_LEGACY.
 		 */
-		printf("Loading current system firmware...\n");
+		INFO("Loading current system firmware...");
 		if (load_system_firmware(cfg, image_from) != 0)
 			return UPDATE_ERR_SYSTEM_IMAGE;
 	}
-	printf(">> Current system: %s (RO:%s, RW/A:%s, RW/B:%s).\n",
+	STATUS("Current system: %s (RO:%s, RW/A:%s, RW/B:%s).",
 	       image_from->file_name, image_from->ro_version,
 	       image_from->rw_version_a, image_from->rw_version_b);
 
@@ -1584,7 +1582,7 @@ enum updater_error_codes update_firmware(struct updater_config *cfg)
 		return UPDATE_ERR_PLATFORM;
 
 	wp_enabled = is_write_protection_enabled(cfg);
-	printf(">> Write protection: %d (%s; HW=%d, SW=%d).\n", wp_enabled,
+	STATUS("Write protection: %d (%s; HW=%d, SW=%d).", wp_enabled,
 	       wp_enabled ? "enabled" : "disabled",
 	       get_system_property(SYS_PROP_WP_HW, cfg),
 	       get_system_property(SYS_PROP_WP_SW, cfg));
@@ -1607,7 +1605,7 @@ enum updater_error_codes update_firmware(struct updater_config *cfg)
 					   wp_enabled);
 		if (r != UPDATE_ERR_NEED_RO_UPDATE)
 			return r;
-		printf("Warning: %s\n", updater_error_messages[r]);
+		WARN("%s", updater_error_messages[r]);
 	}
 
 	if (wp_enabled)
@@ -1681,7 +1679,7 @@ static int updater_load_images(struct updater_config *cfg,
 
 	if (!cfg->image.data && image) {
 		if (image && strcmp(image, "-") == 0) {
-			fprintf(stderr, "Reading image from stdin...\n");
+			INFO("Reading image from stdin...");
 			image = updater_create_temp_file(cfg);
 			if (image)
 				errorcnt += !!save_from_stdin(image);
@@ -1744,7 +1742,7 @@ static int updater_apply_white_label(struct updater_config *cfg,
 				return 1;
 			}
 		} else {
-			printf("Loading system firmware for white label..\n");
+			INFO("Loading system firmware for white label...");
 			load_system_firmware(cfg, &cfg->image_current);
 			tmp_image = cfg->image_current.file_name;
 		}
diff --git a/futility/updater.h b/futility/updater.h
index 9c8502b1..c65e9a0a 100644
--- a/futility/updater.h
+++ b/futility/updater.h
@@ -17,6 +17,10 @@ extern int debugging_enabled;
 	"DEBUG: %s: " format "\n", __FUNCTION__, ##__VA_ARGS__); } while (0)
 #define ERROR(format, ...) fprintf(stderr, \
 	"ERROR: %s: " format "\n", __FUNCTION__, ##__VA_ARGS__)
+#define WARN(format, ...) fprintf(stderr, \
+	"WARNING: " format "\n", ##__VA_ARGS__)
+#define INFO(format, ...) fprintf(stderr, "INFO: " format "\n", ##__VA_ARGS__)
+#define STATUS(format, ...) fprintf(stderr, ">> " format "\n", ##__VA_ARGS__)
 #define ASPRINTF(strp, ...) do { if (asprintf(strp, __VA_ARGS__) >= 0) break; \
 	ERROR("Failed to allocate memory, abort."); exit(1); } while (0)
 
diff --git a/futility/updater_archive.c b/futility/updater_archive.c
index a209e242..87bab2f2 100644
--- a/futility/updater_archive.c
+++ b/futility/updater_archive.c
@@ -784,7 +784,7 @@ int model_apply_white_label(
 		ERROR("No keys found for signature_id: '%s'", signature_id);
 		r = 1;
 	} else {
-		printf("Applied for white label: %s\n", signature_id);
+		INFO("Applied for white label: %s", signature_id);
 	}
 	free(sig_id);
 	return r;
diff --git a/futility/updater_quirks.c b/futility/updater_quirks.c
index 5480d3c6..ca016d77 100644
--- a/futility/updater_quirks.c
+++ b/futility/updater_quirks.c
@@ -123,7 +123,7 @@ static int quirk_unlock_me_for_update(struct updater_config *cfg)
 	 * b/35568719: We should only update with unlocked ME and let
 	 * board-postinst lock it.
 	 */
-	printf("%s: Changed Flash Master Values to unlocked.\n", __FUNCTION__);
+	INFO("%s: Changed Flash Master Values to unlocked.", __FUNCTION__);
 	memcpy(section.data + flash_master_offset, flash_master,
 	       ARRAY_SIZE(flash_master));
 	return 0;
@@ -181,8 +181,8 @@ static int quirk_daisy_snow_dual_model(struct updater_config *cfg)
 		if (strcmp(x16_versions[i], platform_version) == 0)
 			is_x16 = 1;
 	}
-	printf("%s: Platform version: %s (original value: %s)\n", __FUNCTION__,
-	      is_x8 ? "x8" : is_x16 ? "x16": "unknown", platform_version);
+	INFO("%s: Platform version: %s (original value: %s)", __FUNCTION__,
+	     is_x8 ? "x8" : is_x16 ? "x16": "unknown", platform_version);
 	free(platform_version);
 
 	find_firmware_section(&a, &cfg->image, FMAP_RW_SECTION_A);