Clean up debug output

Should print with [%T prefix

BUG=none
TEST=if it boots, it works

Change-Id: I035c081ae3e8ad0088daf0bba404118e1a1f9b41
Signed-off-by: Randall Spangler <rspangler@chromium.org>
Reviewed-on: https://gerrit.chromium.org/gerrit/29480
Reviewed-by: Bill Richardson <wfrichar@chromium.org>

5 files changed, 41 insertions, 34 deletions

diff --git a/common/charge_state.c b/common/charge_state.c
index d43e5a9fa5..b2d535c8ee 100644
--- a/common/charge_state.c
+++ b/common/charge_state.c
@@ -459,7 +459,7 @@ static enum power_state state_error(struct power_state_context *ctx)
 
 	/* Debug output */
 	if (ctx->curr.error != logged_error) {
-		CPRINTF("[Charge error: flag[%08b -> %08b], ac %d, "
+		CPRINTF("[%T Charge error: flag[%08b -> %08b], ac %d, "
 			" charger %s, battery %s\n",
 			logged_error, ctx->curr.error, ctx->curr.ac,
 			(ctx->curr.error & F_CHARGER_MASK) ?
@@ -484,7 +484,7 @@ static void charging_progress(struct power_state_context *ctx)
 		else
 			battery_time_to_empty(&minutes);
 
-		CPRINTF("[Battery %3d%% / %dh:%d]\n",
+		CPRINTF("[%T Battery %3d%% / %dh:%d]\n",
 			ctx->curr.batt.state_of_charge,
 			minutes / 60, minutes % 60);
 		return;
@@ -500,7 +500,7 @@ static void charging_progress(struct power_state_context *ctx)
 		seconds = (int)(get_time().val -
 				ctx->trickle_charging_time.val) / (int)SECOND;
 		minutes = seconds / 60;
-		CPRINTF("[Precharge CHG(%dmV) BATT(%dmV %dmA) "
+		CPRINTF("[%T Precharge CHG(%dmV) BATT(%dmV %dmA) "
 			"%dh:%d]\n", ctx->curr.charging_voltage,
 			ctx->curr.batt.voltage, ctx->curr.batt.current,
 			minutes / 60, minutes % 60);
@@ -590,7 +590,7 @@ void charge_state_machine_task(void)
 			new_state = state_error(ctx);
 			break;
 		default:
-			CPRINTF("[Undefined charging state %d]\n",
+			CPRINTF("[%T Charge state %d undefined]\n",
 				ctx->curr.state);
 			ctx->curr.state = PWR_STATE_ERROR;
 			new_state = PWR_STATE_ERROR;
@@ -603,7 +603,7 @@ void charge_state_machine_task(void)
 
 		if (new_state) {
 			ctx->curr.state = new_state;
-			CPRINTF("[Charge state %s -> %s]\n",
+			CPRINTF("[%T Charge state %s -> %s]\n",
 				state_name[ctx->prev.state],
 				state_name[new_state]);
 		}
diff --git a/common/ir357x.c b/common/ir357x.c
index d82a39c53c..1dd6c481f9 100644
--- a/common/ir357x.c
+++ b/common/ir357x.c
@@ -13,6 +13,10 @@
 #include "uart.h"
 #include "util.h"
 
+/* Console output macros */
+#define CPUTS(outstr) cputs(CC_CHIPSET, outstr)
+#define CPRINTF(format, args...) cprintf(CC_CHIPSET, format, ## args)
+
 /* 8-bit I2C address */
 #define IR357x_I2C_ADDR (0x8 << 1)
 
@@ -109,10 +113,10 @@ static void ir357x_write(uint8_t reg, uint8_t val)
 
 	res = i2c_write8(I2C_PORT_REGULATOR, IR357x_I2C_ADDR, reg, val);
 	if (res)
-		ccprintf("I2C write failed\n");
+		CPRINTF("[%T IR I2C write failed]\n");
 }
 
-int ir357x_get_version(void)
+static int ir357x_get_version(void)
 {
 	/* IR3571 on Link EVT */
 	if ((ir357x_read(0xfc) == 'I') && (ir357x_read(0xfd) == 'R') &&
@@ -139,7 +143,7 @@ struct ir_setting *ir357x_get_settings(void)
 		return NULL;
 }
 
-void ir357x_prog(void)
+static void ir357x_prog(void)
 {
 	struct ir_setting *settings = ir357x_get_settings();
 
@@ -147,15 +151,15 @@ void ir357x_prog(void)
 		for (; settings->reg; settings++)
 			ir357x_write(settings->reg, settings->value);
 	} else {
-		ccprintf("Unsupported chip IR %d. Skip writing settings !\n",
-			 ir357x_get_version());
+		CPRINTF("[%T IR%d chip unsupported. Skip writing settings!\n",
+			ir357x_get_version());
 		return;
 	}
 
-	ccprintf("IR%d registers UPDATED.\n", ir357x_get_version());
+	CPRINTF("[%T IR%d registers UPDATED]\n", ir357x_get_version());
 }
 
-void ir357x_dump(void)
+static void ir357x_dump(void)
 {
 	int i;
 
@@ -169,7 +173,7 @@ void ir357x_dump(void)
 	ccprintf("\n");
 }
 
-int ir357x_check(void)
+static int ir357x_check(void)
 {
 	uint8_t val;
 	int diff = 0;
diff --git a/common/keyboard.c b/common/keyboard.c
index 49b9a01397..16b7ad3bc8 100644
--- a/common/keyboard.c
+++ b/common/keyboard.c
@@ -203,12 +203,12 @@ static enum ec_error_list matrix_callback(int8_t row, int8_t col,
 		break;
 
 	default:
-		CPRINTF("[Scancode set %d unsupported]\n", code_set);
+		CPRINTF("[%T KB scancode set %d unsupported]\n", code_set);
 		return EC_ERROR_UNIMPLEMENTED;
 	}
 
 	if (!make_code) {
-		CPRINTF("[Scancode %d:%d missing]\n", row, col);
+		CPRINTF("[%T KB scancode %d:%d missing]\n", row, col);
 		return EC_ERROR_UNIMPLEMENTED;
 	}
 
@@ -282,7 +282,7 @@ void keyboard_state_changed(int row, int col, int is_pressed)
 	int32_t len;
 	enum ec_error_list ret;
 
-	CPRINTF5("[%s(): row=%d col=%d is_pressed=%d]\n",
+	CPRINTF5("[%T KB %s(): row=%d col=%d is_pressed=%d]\n",
 		 __func__, row, col, is_pressed);
 
 	ret = matrix_callback(row, col, is_pressed, scancode_set, scan_code,
@@ -339,7 +339,7 @@ static void update_ctl_ram(uint8_t addr, uint8_t data)
 
 	orig = controller_ram[addr];
 	controller_ram[addr] = data;
-	CPRINTF5("[Set CTR_RAM(0x%02x)=0x%02x (old:0x%02x)]\n",
+	CPRINTF5("[%T KB set CTR_RAM(0x%02x)=0x%02x (old:0x%02x)]\n",
 		 addr, data, orig);
 
 	if (addr == 0x00) {  /* the controller RAM */
@@ -377,55 +377,56 @@ int handle_keyboard_data(uint8_t data, uint8_t *output)
 	int save_for_resend = 1;
 	int i;
 
-	CPRINTF5("[KB recv data: 0x%02x]\n", data);
+	CPRINTF5("[%T KB recv data: 0x%02x]\n", data);
 	kblog_put('d', data);
 
 	switch (data_port_state) {
 	case STATE_SCANCODE:
-		CPRINTF5("[Eaten by STATE_SCANCODE: 0x%02x]\n", data);
+		CPRINTF5("[%T KB eaten by STATE_SCANCODE: 0x%02x]\n", data);
 		if (data == SCANCODE_GET_SET) {
 			output[out_len++] = I8042_RET_ACK;
 			output[out_len++] = scancode_set;
 		} else {
 			scancode_set = data;
-			CPRINTF("[Scancode set to %d]\n", scancode_set);
+			CPRINTF("[%T KB scancode set to %d]\n", scancode_set);
 			output[out_len++] = I8042_RET_ACK;
 		}
 		data_port_state = STATE_NORMAL;
 		break;
 
 	case STATE_SETLEDS:
-		CPUTS5("[Eaten by STATE_SETLEDS]\n");
+		CPUTS5("[%T KB eaten by STATE_SETLEDS]\n");
 		output[out_len++] = I8042_RET_ACK;
 		data_port_state = STATE_NORMAL;
 		break;
 
 	case STATE_EX_SETLEDS_1:
-		CPUTS5("[Eaten by STATE_EX_SETLEDS_1]\n");
+		CPUTS5("[%T KB eaten by STATE_EX_SETLEDS_1]\n");
 		output[out_len++] = I8042_RET_ACK;
 		data_port_state = STATE_EX_SETLEDS_2;
 		break;
 
 	case STATE_EX_SETLEDS_2:
-		CPUTS5("[Eaten by STATE_EX_SETLEDS_2]\n");
+		CPUTS5("[%T KB eaten by STATE_EX_SETLEDS_2]\n");
 		output[out_len++] = I8042_RET_ACK;
 		data_port_state = STATE_NORMAL;
 		break;
 
 	case STATE_WRITE_CMD_BYTE:
-		CPRINTF5("[Eaten by STATE_WRITE_CMD_BYTE: 0x%02x]\n", data);
+		CPRINTF5("[%T KB eaten by STATE_WRITE_CMD_BYTE: 0x%02x]\n",
+			 data);
 		update_ctl_ram(controller_ram_address, data);
 		data_port_state = STATE_NORMAL;
 		break;
 
 	case STATE_ECHO_MOUSE:
-		CPRINTF5("[Eaten by STATE_ECHO_MOUSE: 0x%02x]\n", data);
+		CPRINTF5("[%T KB eaten by STATE_ECHO_MOUSE: 0x%02x]\n", data);
 		output[out_len++] = data;
 		data_port_state = STATE_NORMAL;
 		break;
 
 	case STATE_SETREP:
-		CPRINTF5("[Eaten by STATE_SETREP: 0x%02x]\n", data);
+		CPRINTF5("[%T KB eaten by STATE_SETREP: 0x%02x]\n", data);
 		typematic_value_from_host = data;
 		refill_first_delay =
 			(((typematic_value_from_host & 0x60) >> 5) + 1) * 250;
@@ -439,7 +440,8 @@ int handle_keyboard_data(uint8_t data, uint8_t *output)
 		break;
 
 	case STATE_SEND_TO_MOUSE:
-		CPRINTF5("[Eaten by STATE_SEND_TO_MOUSE: 0x%02x]\n", data);
+		CPRINTF5("[%T KB eaten by STATE_SEND_TO_MOUSE: 0x%02x]\n",
+			 data);
 		data_port_state = STATE_NORMAL;
 		break;
 
@@ -523,7 +525,8 @@ int handle_keyboard_data(uint8_t data, uint8_t *output)
 		case I8042_CMD_EX_ENABLE:
 		default:
 			output[out_len++] = I8042_RET_NAK;
-			CPRINTF("[Unsupported i8042 data 0x%02x]\n", data);
+			CPRINTF("[%T KB Unsupported i8042 data 0x%02x]\n",
+				data);
 			break;
 		}
 	}
@@ -545,7 +548,7 @@ int handle_keyboard_command(uint8_t command, uint8_t *output)
 {
 	int out_len = 0;
 
-	CPRINTF5("[KB recv cmd: 0x%02x]\n", command);
+	CPRINTF5("[%T KB recv cmd: 0x%02x]\n", command);
 	kblog_put('c', command);
 
 	switch (command) {
@@ -612,7 +615,7 @@ int handle_keyboard_command(uint8_t command, uint8_t *output)
 			   command <= I8042_PULSE_END) {
 			/* Pulse Output Bit. Not implemented. Ignore it. */
 		} else {
-			CPRINTF("[Unsupported cmd: 0x%02x]\n", command);
+			CPRINTF("[%T KB unsupported cmd: 0x%02x]\n", command);
 			reset_rate_and_delay();
 			keyboard_clear_underlying_buffer();
 			output[out_len++] = I8042_RET_NAK;
diff --git a/common/usb_charge_commands.c b/common/usb_charge_commands.c
index af22b12366..0915ab064d 100644
--- a/common/usb_charge_commands.c
+++ b/common/usb_charge_commands.c
@@ -20,7 +20,7 @@ static int usb_charge_command_set_mode(struct host_cmd_handler_args *args)
 	const struct ec_params_usb_charge_set_mode *p = args->params;
 	int rv;
 
-	CPRINTF("[Setting USB port %d to mode %d]\n",
+	CPRINTF("[%T USB setting port %d to mode %d]\n",
 		p->usb_port_id, p->mode);
 
 	rv = usb_charge_set_mode(p->usb_port_id, p->mode);
diff --git a/common/x86_power.c b/common/x86_power.c
index 28592a8383..655826418b 100644
--- a/common/x86_power.c
+++ b/common/x86_power.c
@@ -169,7 +169,7 @@ static int wait_in_signals(uint32_t want)
 	while ((in_signals & in_want) != in_want) {
 		if (task_wait_event(DEFAULT_TIMEOUT) == TASK_EVENT_TIMER) {
 			update_in_signals();
-			CPRINTF("[x86 power timeout on input; "
+			CPRINTF("[%T x86 power timeout on input; "
 				"wanted 0x%04x, got 0x%04x]\n",
 				in_want, in_signals & in_want);
 			return EC_ERROR_TIMEOUT;
@@ -378,11 +378,11 @@ static int x86_power_init(void)
 	 */
 	if (system_jumped_to_this_image()) {
 		if ((in_signals & IN_ALL_S0) == IN_ALL_S0) {
-			CPUTS("[x86 already in S0]\n");
+			CPRINTF("[%T x86 already in S0]\n");
 			state = X86_S0;
 		} else {
 			/* Force all signals to their G3 states */
-			CPUTS("[x86 forcing G3]\n");
+			CPRINTF("[%T x86 forcing G3]\n");
 			gpio_set_level(GPIO_PCH_PWROK, 0);
 			gpio_set_level(GPIO_ENABLE_VCORE, 0);
 			gpio_set_level(GPIO_ENABLE_VS, 0);