futility: updater: Revise verbosity and error messages

`futility` used to print debug messages to stdout, but there is a side
effect that stdout may be buffered and then flush later than stderr.
For example, when calling futility via ssh, we will see flashrom
messages before any of futility's own messages.

Also, many people want to get flashrom verbose messages (-V).

With this change, when calling ERROR and DEBUG, we will always output to
stderr. This also enables better parameter type checking.
`-d` and `-v` both contribute to verbosity, that will be converted to
-V's when calling flashrom.

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

Change-Id: I1d22a8054fc43cdc5e6c7415e131cc9826fbff0c
Signed-off-by: Hung-Te Lin <hungte@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/1251145

5 files changed, 46 insertions, 21 deletions

diff --git a/futility/cmd_update.c b/futility/cmd_update.c
index c944724a..d220988e 100644
--- a/futility/cmd_update.c
+++ b/futility/cmd_update.c
@@ -78,7 +78,8 @@ static int do_update(int argc, char *argv[])
 		   *opt_emulation = NULL,
 		   *opt_sys_props = NULL,
 		   *opt_write_protection = NULL;
-	int opt_is_factory = 0, opt_try_update = 0, opt_force_update = 0;
+	int opt_is_factory = 0, opt_try_update = 0, opt_force_update = 0,
+	    opt_verbosity = 0;
 	int i, errorcnt = 0;
 	struct updater_config *cfg;
 
@@ -129,11 +130,11 @@ static int do_update(int argc, char *argv[])
 			opt_sys_props = optarg;
 			break;
 		case 'v':
-			/* TODO(hungte) Change to better verbosity control. */
-			debugging_enabled = 1;
+			opt_verbosity++;
 			break;
 		case 'd':
 			debugging_enabled = 1;
+			opt_verbosity++;
 			break;
 
 		case 'h':
@@ -164,7 +165,8 @@ static int do_update(int argc, char *argv[])
 				opt_quirks, opt_mode, opt_programmer,
 				opt_emulation, opt_sys_props,
 				opt_write_protection, opt_is_factory,
-				opt_try_update, opt_force_update);
+				opt_try_update, opt_force_update,
+				opt_verbosity);
 	if (!errorcnt) {
 		int r = update_firmware(cfg);
 		if (r != UPDATE_ERR_DONE) {
diff --git a/futility/updater.c b/futility/updater.c
index 7541cdf1..e1ae0769 100644
--- a/futility/updater.c
+++ b/futility/updater.c
@@ -15,6 +15,7 @@
 
 #include "2rsa.h"
 #include "crossystem.h"
+#include "futility.h"
 #include "host_misc.h"
 #include "updater.h"
 #include "utility.h"
@@ -234,11 +235,22 @@ static int host_flashrom(enum flashrom_ops op, const char *image_path,
 	const char *op_cmd, *dash_i = "-i", *postfix = "", *ignore_lock = "";
 	int r;
 
-	if (debugging_enabled)
-		verbose = 1;
-
-	if (!verbose)
+	switch (verbose) {
+	case 0:
 		postfix = " >/dev/null 2>&1";
+		break;
+	case 1:
+		break;
+	case 2:
+		postfix = "-V";
+		break;
+	case 3:
+		postfix = "-V -V";
+		break;
+	default:
+		postfix = "-V -V -V";
+		break;
+	}
 
 	if (!section_name || !*section_name) {
 		dash_i = "";
@@ -405,7 +417,7 @@ static void override_properties_from_list(const char *override_list,
 		}
 		v = strtol(s, &e, 0);
 		s = e - 1;
-		DEBUG("property[%d].value = %d", i, v);
+		DEBUG("property[%d].value = %ld", i, v);
 		override_system_property((enum system_property_type)i, cfg, v);
 		wait_comma = 1;
 		i++;
@@ -624,7 +636,8 @@ int load_system_image(struct updater_config *cfg, struct firmware_image *image)
 	if (!tmp_file)
 		return -1;
 	RETURN_ON_FAILURE(host_flashrom(
-			FLASHROM_READ, tmp_file, image->programmer, 0, NULL));
+			FLASHROM_READ, tmp_file, image->programmer,
+			cfg->verbosity, NULL));
 	return load_image(tmp_file, image);
 }
 
@@ -759,7 +772,7 @@ static int emulate_write_firmware(const char *filename,
 		size_t to_write = Min(to.size, from.size);
 
 		assert(from.data && to.data);
-		DEBUG("Writing %d bytes", to_write);
+		DEBUG("Writing %zu bytes", to_write);
 		memcpy(to.data, from.data, to_write);
 	}
 
@@ -802,8 +815,8 @@ static int write_firmware(struct updater_config *cfg,
 		ERROR("Cannot write temporary file for output: %s", tmp_file);
 		return -1;
 	}
-	return host_flashrom(FLASHROM_WRITE, tmp_file, programmer, 1,
-			     section_name);
+	return host_flashrom(FLASHROM_WRITE, tmp_file, programmer,
+			     cfg->verbosity + 1, section_name);
 }
 
 /*
@@ -1630,12 +1643,15 @@ int updater_setup_config(struct updater_config *cfg,
 			 const char *write_protection,
 			 int is_factory,
 			 int try_update,
-			 int force_update)
+			 int force_update,
+			 int verbosity)
 {
 	int errorcnt = 0;
 	int check_single_image = 0, check_wp_disabled = 0;
 	const char *default_quirks = NULL;
 
+	cfg->verbosity = verbosity;
+
 	if (try_update)
 		cfg->try_update = 1;
 	if (force_update)
diff --git a/futility/updater.h b/futility/updater.h
index 58445a1c..3993f073 100644
--- a/futility/updater.h
+++ b/futility/updater.h
@@ -8,11 +8,15 @@
 #ifndef VBOOT_REFERENCE_FUTILITY_UPDATER_H_
 #define VBOOT_REFERENCE_FUTILITY_UPDATER_H_
 
+#include <stdio.h>
+
 #include "fmap.h"
-#include "futility.h"
 
-#define DEBUG(format, ...) Debug("%s: " format "\n", __FUNCTION__,##__VA_ARGS__)
-#define ERROR(format, ...) Error("%s: " format "\n", __FUNCTION__,##__VA_ARGS__)
+extern int debugging_enabled;
+#define DEBUG(format, ...) do { if (debugging_enabled) fprintf(stderr, \
+	"DEBUG: %s: " format "\n", __FUNCTION__, ##__VA_ARGS__); } while (0)
+#define ERROR(format, ...) fprintf(stderr, \
+	"ERROR: %s: " format "\n", __FUNCTION__, ##__VA_ARGS__)
 
 /* FMAP section names. */
 static const char * const FMAP_RO_FRID = "RO_FRID",
@@ -97,6 +101,7 @@ struct updater_config {
 	int try_update;
 	int force_update;
 	int legacy_update;
+	int verbosity;
 	const char *emulation;
 };
 
@@ -153,7 +158,8 @@ int updater_setup_config(struct updater_config *cfg,
 			  const char *write_protection,
 			  int is_factory,
 			  int try_update,
-			  int force_update);
+			  int force_update,
+			  int verbosity);
 
 /* Prints the name and description from all supported quirks. */
 void updater_list_config_quirks(const struct updater_config *cfg);
diff --git a/futility/updater_quirks.c b/futility/updater_quirks.c
index c1d937af..f3989e78 100644
--- a/futility/updater_quirks.c
+++ b/futility/updater_quirks.c
@@ -12,8 +12,9 @@
 #include <sys/types.h>
 #include <sys/stat.h>
 
-#include "updater.h"
+#include "futility.h"
 #include "host_misc.h"
+#include "updater.h"
 
 struct quirks_record {
 	const char * const match;
diff --git a/tests/futility/test_update.sh b/tests/futility/test_update.sh
index 655d17dc..b7f0e738 100755
--- a/tests/futility/test_update.sh
+++ b/tests/futility/test_update.sh
@@ -8,7 +8,7 @@ TMP="$me.tmp"
 
 # Test --sys_props (primitive test needed for future updating tests).
 test_sys_props() {
-	! "${FUTILITY}" --debug update --sys_props "$*" |
+	! "${FUTILITY}" --debug update --sys_props "$*" 2>&1 |
 		sed -n 's/.*property\[\(.*\)].value = \(.*\)/\1,\2,/p' |
 		tr '\n' ' '
 }
@@ -20,7 +20,7 @@ test "$(test_sys_props "   1,, 2")" = "0,1, 2,2, "
 test "$(test_sys_props " , 4,")" = "1,4, "
 
 test_quirks() {
-	! "${FUTILITY}" --debug update --quirks "$*" |
+	! "${FUTILITY}" --debug update --quirks "$*" 2>&1 |
 		sed -n 's/.*Set quirk \(.*\) to \(.*\)./\1,\2/p' |
 		tr '\n' ' '
 }