futility: updater: Revise output messages for debug logs
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
diff --git a/futility/cmd_update.c b/futility/cmd_update.c
index e665b74..9b19435 100644
--- a/futility/cmd_update.c
+++ b/futility/cmd_update.c
@@ -99,7 +99,6 @@
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);
@@ -204,16 +203,19 @@
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 7771c57..4714ff9 100644
--- a/futility/updater.c
+++ b/futility/updater.c
@@ -297,7 +297,7 @@
postfix);
if (verbose)
- printf("Executing: %s\n", command);
+ INFO("Executing: %s", command);
if (op != FLASHROM_WP_STATUS) {
r = system(command);
@@ -720,8 +720,8 @@
}
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;
}
@@ -813,10 +813,10 @@
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);
@@ -875,8 +875,8 @@
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));
@@ -1228,17 +1228,16 @@
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;
}
@@ -1352,7 +1351,7 @@
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;
}
@@ -1392,7 +1391,7 @@
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))
@@ -1405,7 +1404,7 @@
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);
@@ -1416,8 +1415,7 @@
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;
@@ -1432,12 +1430,12 @@
/* 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;
}
@@ -1452,11 +1450,11 @@
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))
@@ -1483,7 +1481,7 @@
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;
@@ -1501,13 +1499,13 @@
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) {
@@ -1518,7 +1516,7 @@
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. "
@@ -1553,9 +1551,9 @@
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;
@@ -1565,11 +1563,11 @@
* 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);
@@ -1577,7 +1575,7 @@
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));
@@ -1600,7 +1598,7 @@
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)
@@ -1674,7 +1672,7 @@
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);
@@ -1737,7 +1735,7 @@
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 5698f9e..3645b61 100644
--- a/futility/updater.h
+++ b/futility/updater.h
@@ -17,6 +17,10 @@
"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 14ebacb..49beb6f 100644
--- a/futility/updater_archive.c
+++ b/futility/updater_archive.c
@@ -452,7 +452,7 @@
uint8_t *data;
int r;
- printf("Copying: %s\n", path);
+ INFO("Copying: %s", path);
if (archive_read_file(arg->from, path, &data, &size)) {
ERROR("Failed reading: %s", path);
return 1;
@@ -894,7 +894,7 @@
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 8c924a3..c170f25 100644
--- a/futility/updater_quirks.c
+++ b/futility/updater_quirks.c
@@ -124,7 +124,7 @@
* 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;
@@ -182,8 +182,8 @@
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);
