usbc: fix flaky tests

Change waits in USBC tests to 1 MSEC. When we wait and don't care, wait
for much longer.

We also need to ensure that the lower priority task actually ran when we
are trying to cycle the state machine. If the entire process is starved
then we have to do some manual checking.

Added more prints statements to help debug failing tests.

BRANCH=none
BUG=none
TEST=repeat all tests 100 times without failure

Change-Id: I12e0f0fa5247a24c87a4ff457e2be684991f0cad
Signed-off-by: Jett Rink <jettrink@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/ec/+/1837995
Commit-Queue: Denis Brockus <dbrockus@chromium.org>
Reviewed-by: Edward Hill <ecgh@chromium.org>
Reviewed-by: Denis Brockus <dbrockus@chromium.org>

3 files changed, 145 insertions, 90 deletions

diff --git a/core/host/task.c b/core/host/task.c
index d004698ed7..b6ab778b60 100644
--- a/core/host/task.c
+++ b/core/host/task.c
@@ -206,6 +206,11 @@ uint32_t task_set_event(task_id_t tskid, uint32_t event, int wait)
 	return 0;
 }
 
+uint32_t *task_get_event_bitmap(task_id_t tskid)
+{
+	return &tasks[tskid].event;
+}
+
 uint32_t task_wait_event(int timeout_us)
 {
 	int tid = task_get_current();
diff --git a/test/usb_prl.c b/test/usb_prl.c
index d1cbaf5a94..308117493b 100644
--- a/test/usb_prl.c
+++ b/test/usb_prl.c
@@ -122,6 +122,11 @@ static void init_port(int port, int rev)
 	tcpm_set_rx_enable(port, 0);
 }
 
+static inline uint32_t pending_pd_task_events(int port)
+{
+	return *task_get_event_bitmap(PD_PORT_TO_TASK_ID(port));
+}
+
 void inc_tx_id(int port)
 {
 	pd_port[port].msg_tx_id = (pd_port[port].msg_tx_id + 1) & 7;
@@ -179,6 +184,12 @@ static void cycle_through_state_machine(int port, uint32_t num, uint32_t time)
 	for (i = 0; i < num; i++) {
 		task_wake(PD_PORT_TO_TASK_ID(port));
 		task_wait_event(time);
+		/*
+		 * Ensure that the PD task actually ran otherwise loop again.
+		 * This can happen for slow/overloaded cpus (e.g. cq machine).
+		 */
+		if (TASK_EVENT_WAKE & pending_pd_task_events(port))
+			--i;
 	}
 }
 
@@ -255,21 +266,32 @@ static int verify_chunk_data_reception(int port, uint16_t header, int len)
 	int i;
 	uint8_t *td = (uint8_t *)test_data;
 
-	if (pd_port[port].mock_got_soft_reset)
+	if (pd_port[port].mock_got_soft_reset) {
+		ccprintf("Got mock soft reset\n");
 		return 0;
+	}
 
-	if (!pd_port[port].mock_pe_message_received)
+	if (!pd_port[port].mock_pe_message_received) {
+		ccprintf("No mock pe msg received\n");
 		return 0;
+	}
 
-	if (pd_port[port].mock_pe_error >= 0)
+	if (pd_port[port].mock_pe_error >= 0) {
+		ccprintf("Mock pe error (%d)\n", pd_port[port].mock_pe_error);
 		return 0;
+	}
 
-	if (emsg[port].len != len)
+	if (emsg[port].len != len) {
+		ccprintf("emsg len (%d) != 0\n", emsg[port].len);
 		return 0;
+	}
 
-	for (i = 0; i < len; i++)
-		if (emsg[port].buf[i] != td[i])
+	for (i = 0; i < len; i++) {
+		if (emsg[port].buf[i] != td[i]) {
+			ccprintf("emsg buf[%d] != td\n", i);
 			return 0;
+		}
+	}
 
 	return 1;
 }
@@ -322,7 +344,6 @@ static int simulate_receive_extended_data(int port,
 	int data_offset = 0;
 	uint8_t *expected_data = (uint8_t *)test_data;
 	uint16_t header;
-	int req_timeout;
 
 	pd_port[port].mock_pe_error = -1;
 	pd_port[port].mock_pe_message_received = 0;
@@ -331,10 +352,10 @@ static int simulate_receive_extended_data(int port,
 	memset(emsg[port].buf, 0, 260);
 
 	dsize = len;
-
-	cycle_through_state_machine(port, 2, 40 * MSEC);
-
 	for (j = 0; j < 10; j++) {
+		/* Let state machine settle before starting another round */
+		cycle_through_state_machine(port, 10, MSEC);
+
 		byte_len = len;
 		if (byte_len > 26)
 			byte_len = 26;
@@ -352,26 +373,33 @@ static int simulate_receive_extended_data(int port,
 			pd_port[port].data_role, pd_port[port].msg_rx_id,
 			nw, pd_port[port].rev, 1);
 
-		cycle_through_state_machine(port, 2, 40 * MSEC);
-
-		if (pd_port[port].mock_pe_error >= 0)
+		if (pd_port[port].mock_pe_error >= 0) {
+			ccprintf("Mock pe error (%d) iteration (%d)\n",
+				pd_port[port].mock_pe_error, j);
 			return 0;
+		}
 
-		if (pd_port[port].mock_pe_message_received)
+		if (pd_port[port].mock_pe_message_received) {
+			ccprintf("Mock pe msg received iteration (%d)\n", j);
 			return 0;
+		}
 
-		if (emsg[port].len != 0)
+		if (emsg[port].len != 0) {
+			ccprintf("emsg len (%d) != 0 iteration (%d)\n",
+				emsg[port].len, j);
 			return 0;
+		}
 
 		simulate_rx_msg(port, header, nw, (uint32_t *)td);
-		task_wait_event(40 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 
 		if (!verify_goodcrc(port, pd_port[port].data_role,
-						pd_port[port].msg_rx_id))
+						pd_port[port].msg_rx_id)) {
+			ccprintf("Verify goodcrc bad iteration (%d)\n", j);
 			return 0;
+		}
 
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(40);
+		cycle_through_state_machine(port, 1, MSEC);
 		inc_rx_id(port);
 
 		/*
@@ -381,52 +409,58 @@ static int simulate_receive_extended_data(int port,
 			break;
 
 		/*
-		 * Wait for request chunk message
+		 * We need to ensure that the TX event has been set, which may
+		 * require an extra cycle through the state machine
 		 */
-		req_timeout = 0;
-		while (rch_get_state(port) != RCH_REQUESTING_CHUNK &&
-							req_timeout < 5) {
-			req_timeout++;
-			msleep(2);
-		}
+		if (!(PD_EVENT_TX & pending_pd_task_events(port)))
+			cycle_through_state_machine(port, 1, MSEC);
 
 		chunk_num++;
 
 		/* Test Request next chunk packet */
-		if (!pd_test_tx_msg_verify_sop(port))
+		if (!pd_test_tx_msg_verify_sop(port)) {
+			ccprintf("Verify sop bad iteration (%d)\n", j);
 			return 0;
+		}
 
 		if (!pd_test_tx_msg_verify_short(port,
 				PD_HEADER(msg_type,
 				pd_port[port].power_role,
 				pd_port[port].data_role,
 				pd_port[port].msg_tx_id,
-				1, pd_port[port].rev, 1)))
+				1, pd_port[port].rev, 1))) {
+			ccprintf("Verify msg short bad iteration (%d)\n", j);
 			return 0;
+		}
 
 		if (!pd_test_tx_msg_verify_word(port,
-				PD_EXT_HEADER(chunk_num, 1, 0)))
+				PD_EXT_HEADER(chunk_num, 1, 0))) {
+			ccprintf("Verify msg word bad iteration (%d)\n", j);
 			return 0;
+		}
 
-		if (!pd_test_tx_msg_verify_crc(port))
+		if (!pd_test_tx_msg_verify_crc(port)) {
+			ccprintf("Verify msg crc bad iteration (%d)\n", j);
 			return 0;
+		}
 
-		if (!pd_test_tx_msg_verify_eop(port))
+		if (!pd_test_tx_msg_verify_eop(port)) {
+			ccprintf("Verify msg eop bad iteration (%d)\n", j);
 			return 0;
+		}
 
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(30 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 
 		/* Request next chunk packet was good. Send GoodCRC */
 		simulate_goodcrc(port, pd_port[port].power_role,
 					pd_port[port].msg_tx_id);
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(40 * MSEC);
+
+		cycle_through_state_machine(port, 1, MSEC);
+
 		inc_tx_id(port);
 	}
 
-	task_wake(PD_PORT_TO_TASK_ID(port));
-	task_wait_event(20 * MSEC);
+	cycle_through_state_machine(port, 1, MSEC);
 
 	return verify_chunk_data_reception(port, header, dsize);
 }
@@ -459,10 +493,11 @@ static int simulate_send_ctrl_msg_request_from_pe(int port,
 	pd_port[port].mock_pe_error = -1;
 	pd_port[port].mock_pe_message_sent = 0;
 	prl_send_ctrl_msg(port, type, msg_type);
-	task_wait_event(40 * MSEC);
+	cycle_through_state_machine(port, 1, MSEC);
 
+	/* Soft reset takes another iteration through the state machine */
 	if (msg_type == PD_CTRL_SOFT_RESET)
-		cycle_through_state_machine(port, 1, 20 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 
 	return verify_ctrl_msg_transmission(port, msg_type);
 }
@@ -531,7 +566,7 @@ static int simulate_send_data_msg_request_from_pe(int port,
 	emsg[port].len = len;
 
 	prl_send_data_msg(port, type, msg_type);
-	task_wait_event(30 * MSEC);
+	cycle_through_state_machine(port, 1, MSEC);
 
 	return verify_data_msg_transmission(port, msg_type, len);
 }
@@ -558,15 +593,19 @@ static int verify_extended_data_msg_transmission(int port,
 
 		nw = (byte_len + 2 + 3) >> 2;
 
-		if (!pd_test_tx_msg_verify_sop(port))
+		if (!pd_test_tx_msg_verify_sop(port)) {
+			ccprintf("failed tx sop; iteration (%d)\n", j);
 			return 0;
+		}
 
 		if (!pd_test_tx_msg_verify_short(port,
 				PD_HEADER(msg_type, pd_port[port].power_role,
 				pd_port[port].data_role,
 				pd_port[port].msg_tx_id,
-				nw, pd_port[port].rev, 1)))
+				nw, pd_port[port].rev, 1))) {
+			ccprintf("failed tx short\n");
 			return 0;
+		}
 		td = PD_EXT_HEADER(chunk_number_to_send, 0, dsize);
 		td |= *(expected_data + data_offset++) << 16;
 		td |= *(expected_data + data_offset++) << 24;
@@ -574,8 +613,10 @@ static int verify_extended_data_msg_transmission(int port,
 		if (byte_len == 1)
 			td &= 0x00ffffff;
 
-		if (!pd_test_tx_msg_verify_word(port, td))
+		if (!pd_test_tx_msg_verify_word(port, td)) {
+			ccprintf("failed tx word\n");
 			return 0;
+		}
 
 		byte_len -= 2;
 
@@ -605,20 +646,22 @@ static int verify_extended_data_msg_transmission(int port,
 			}
 		}
 
-		if (!pd_test_tx_msg_verify_crc(port))
+		if (!pd_test_tx_msg_verify_crc(port)) {
+			ccprintf("failed tx crc\n");
 			return 0;
+		}
 
-		if (!pd_test_tx_msg_verify_eop(port))
+		if (!pd_test_tx_msg_verify_eop(port)) {
+			ccprintf("failed tx eop\n");
 			return 0;
+		}
 
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(10 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 
 		/* Send GoodCRC */
 		simulate_goodcrc(port, pd_port[port].power_role,
 						pd_port[port].msg_tx_id);
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(30 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 		inc_tx_id(port);
 
 		len -= 26;
@@ -626,13 +669,15 @@ static int verify_extended_data_msg_transmission(int port,
 			break;
 
 		chunk_number_to_send++;
-		cycle_through_state_machine(port, 4, 10 * MSEC);
+		/* Let state machine settle */
+		cycle_through_state_machine(port, 10, MSEC);
 		if (!simulate_request_chunk(port, msg_type,
-				chunk_number_to_send, dsize))
+				chunk_number_to_send, dsize)) {
+			ccprintf("failed request chunk\n");
 			return 0;
+		}
 
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(30 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 		inc_rx_id(port);
 	}
 
@@ -658,7 +703,7 @@ static int simulate_send_extended_data_msg(int port,
 		buf[i] = td[i];
 
 	prl_send_ext_data_msg(port, type, msg_type);
-	task_wait_event(30 * MSEC);
+	cycle_through_state_machine(port, 1, MSEC);
 
 	return verify_extended_data_msg_transmission(port, msg_type,
 							len);
@@ -673,11 +718,7 @@ static void enable_prl(int port, int en)
 	pd_port[port].msg_rx_id = 0;
 
 	/* Init PRL */
-	task_wake(PD_PORT_TO_TASK_ID(port));
-	task_wait_event(10 * MSEC);
-
-	task_wake(PD_PORT_TO_TASK_ID(port));
-	task_wait_event(10 * MSEC);
+	cycle_through_state_machine(port, 10, MSEC);
 
 	prl_set_rev(port, pd_port[port].rev);
 }
@@ -763,14 +804,14 @@ static int test_send_ctrl_msg(void)
 		TEST_ASSERT(simulate_send_ctrl_msg_request_from_pe(port,
 						TCPC_TX_SOP, PD_CTRL_ACCEPT));
 
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(30 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 
 		simulate_goodcrc(port, pd_port[port].power_role,
 						pd_port[port].msg_tx_id);
 		inc_tx_id(port);
 
-		cycle_through_state_machine(port, 3, 10 * MSEC);
+		/* Let statemachine settle */
+		cycle_through_state_machine(port, 10, MSEC);
 
 		TEST_ASSERT(!pd_port[port].mock_got_soft_reset);
 		TEST_ASSERT(pd_port[port].mock_pe_message_sent);
@@ -793,7 +834,7 @@ static int test_send_ctrl_msg_with_retry_and_fail(void)
 	 * TEST: Control message transmission fail with retry
 	 */
 	task_wake(PD_PORT_TO_TASK_ID(port));
-	task_wait_event(40 * MSEC);
+	task_wait_event(MSEC);
 
 	TEST_ASSERT(prl_tx_get_state(port) ==
 			PRL_TX_WAIT_FOR_MESSAGE_REQUEST);
@@ -801,34 +842,32 @@ static int test_send_ctrl_msg_with_retry_and_fail(void)
 	TEST_ASSERT(simulate_send_ctrl_msg_request_from_pe(port,
 					TCPC_TX_SOP, PD_CTRL_ACCEPT));
 
-	task_wake(PD_PORT_TO_TASK_ID(port));
-	task_wait_event(30 * MSEC);
+	cycle_through_state_machine(port, 1, MSEC);
 
 	simulate_goodcrc(port, pd_port[port].power_role,
 					pd_port[port].msg_tx_id);
 
 	/* Do not increment tx_id so phy layer will not transmit message */
 
-	cycle_through_state_machine(port, 3, 10 * MSEC);
+	/* Let statemachine settle */
+	cycle_through_state_machine(port, 10, MSEC);
 
 	TEST_ASSERT(!pd_port[port].mock_got_soft_reset);
 	TEST_ASSERT(pd_port[port].mock_pe_message_sent);
 
 	task_wake(PD_PORT_TO_TASK_ID(port));
-	task_wait_event(40 * MSEC);
+	task_wait_event(MSEC);
 
 	TEST_ASSERT(prl_tx_get_state(port) ==
 					PRL_TX_WAIT_FOR_MESSAGE_REQUEST);
 
 	pd_port[port].mock_pe_message_sent = 0;
 	prl_send_ctrl_msg(port, TCPC_TX_SOP, PD_CTRL_ACCEPT);
-	task_wait_event(30 * MSEC);
+	cycle_through_state_machine(port, 1, MSEC);
 
 	for (i = 0; i < N_RETRY_COUNT + 1; i++) {
-		cycle_through_state_machine(port, 10, 10 * MSEC);
-
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(PD_T_TCPC_TX_TIMEOUT);
+		/* Ensure that we have timed out */
+		cycle_through_state_machine(port, 10, 100 * MSEC);
 
 		TEST_ASSERT(!pd_port[port].mock_got_soft_reset);
 		TEST_ASSERT(pd_port[port].mock_pe_message_sent == 0);
@@ -854,8 +893,6 @@ static int test_send_ctrl_msg_with_retry_and_success(void)
 	/*
 	 * TEST: Control message transmission fail with retry
 	 */
-	task_wake(PD_PORT_TO_TASK_ID(port));
-	task_wait_event(40 * MSEC);
 
 	TEST_ASSERT(prl_tx_get_state(port) ==
 				PRL_TX_WAIT_FOR_MESSAGE_REQUEST);
@@ -929,8 +966,7 @@ static int test_send_data_msg(void)
 	 * TEST: Sending data  message with 1 to 28 bytes
 	 */
 	for (i = 1; i <= 28; i++) {
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(40 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 
 		TEST_ASSERT(prl_tx_get_state(port) ==
 					PRL_TX_WAIT_FOR_MESSAGE_REQUEST);
@@ -938,14 +974,13 @@ static int test_send_data_msg(void)
 		TEST_ASSERT(simulate_send_data_msg_request_from_pe(port,
 					TCPC_TX_SOP, PD_DATA_SOURCE_CAP, i));
 
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(30 * MSEC);
+		cycle_through_state_machine(port, 1, MSEC);
 
 		simulate_goodcrc(port, pd_port[port].power_role,
 						pd_port[port].msg_tx_id);
 		inc_tx_id(port);
 
-		cycle_through_state_machine(port, 3, 10 * MSEC);
+		cycle_through_state_machine(port, 10, MSEC);
 
 		TEST_ASSERT(!pd_port[port].mock_got_soft_reset);
 		TEST_ASSERT(pd_port[port].mock_pe_message_sent);
@@ -979,7 +1014,7 @@ static int test_send_data_msg_to_much_data(void)
 	task_wake(PD_PORT_TO_TASK_ID(port));
 	task_wait_event(30 * MSEC);
 
-	cycle_through_state_machine(port, 3, 10 * MSEC);
+	cycle_through_state_machine(port, 10, MSEC);
 
 	TEST_ASSERT(!pd_port[port].mock_got_soft_reset);
 	TEST_ASSERT(!pd_port[port].mock_pe_message_sent);
@@ -1004,11 +1039,12 @@ static int test_send_extended_data_msg(void)
 	pd_port[port].mock_got_soft_reset = 0;
 	pd_port[port].mock_pe_error = -1;
 
+	ccprintf("Iteration ");
 	for (i = 29; i <= 260; i++) {
+		ccprintf(".%d", i);
 		pd_port[port].mock_pe_message_sent = 0;
 
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(40 * MSEC);
+		cycle_through_state_machine(port, 10, MSEC);
 
 		TEST_ASSERT(prl_tx_get_state(port) ==
 					PRL_TX_WAIT_FOR_MESSAGE_REQUEST);
@@ -1016,10 +1052,7 @@ static int test_send_extended_data_msg(void)
 		TEST_ASSERT(simulate_send_extended_data_msg(
 			port, TCPC_TX_SOP, PD_EXT_MANUFACTURER_INFO, i));
 
-		task_wake(PD_PORT_TO_TASK_ID(port));
-		task_wait_event(30 * MSEC);
-
-		cycle_through_state_machine(port, 3, 10 * MSEC);
+		cycle_through_state_machine(port, 10, MSEC);
 
 		TEST_ASSERT(!pd_port[port].mock_got_soft_reset);
 		TEST_ASSERT(pd_port[port].mock_pe_message_sent);
@@ -1060,7 +1093,7 @@ static int test_receive_soft_reset_msg(void)
 	task_wake(PD_PORT_TO_TASK_ID(port));
 	task_wait_event(30 * MSEC);
 
-	cycle_through_state_machine(port, 3, 10 * MSEC);
+	cycle_through_state_machine(port, 10, MSEC);
 
 	TEST_ASSERT(pd_port[port].mock_got_soft_reset);
 	TEST_ASSERT(pd_port[port].mock_pe_error < 0);
@@ -1317,6 +1350,21 @@ int pd_task(void *u)
 	return EC_SUCCESS;
 }
 
+/* Reset the state machine between each test */
+void before_test(void)
+{
+	pd_port[PORT0].mock_pe_message_sent = 0;
+	pd_port[PORT0].mock_pe_error = -1;
+	pd_port[PORT0].mock_pe_hard_reset_sent = 0;
+	pd_port[PORT0].mock_pe_got_hard_reset = 0;
+	pd_port[PORT0].mock_pe_message_received = 0;
+	pd_port[PORT0].mock_got_soft_reset = 0;
+	pd_port[PORT0].pd_enable = false;
+	cycle_through_state_machine(PORT0, 10, MSEC);
+	pd_port[PORT0].pd_enable = true;
+	cycle_through_state_machine(PORT0, 10, MSEC);
+}
+
 void run_test(void)
 {
 	test_reset();
diff --git a/test/usb_typec_ctvpd.c b/test/usb_typec_ctvpd.c
index 8c8b5e3897..61fc64f9b9 100644
--- a/test/usb_typec_ctvpd.c
+++ b/test/usb_typec_ctvpd.c
@@ -76,8 +76,10 @@ uint64_t wait_for_state_change(int port, uint64_t timeout)
 
 	wait = get_time().val + timeout;
 	start = get_time().val;
-	while (get_state_tc(port) == state && get_time().val < wait)
+	while (get_state_tc(port) == state && get_time().val < wait) {
+		task_wake(PD_PORT_TO_TASK_ID(port));
 		task_wait_event(5 * MSEC);
+	}
 
 	return get_time().val - start;
 }
@@ -635,9 +637,9 @@ static int test_vpd_host_src_detection_message_reception(void)
 
 	host_connect_source(VBUS_0);
 
-	wait_for_state_change(port, 10 * MSEC);
+	wait_for_state_change(port, 100 * MSEC);
 
-	TEST_ASSERT(get_state_tc(port) == TC_UNATTACHED_SNK);
+	TEST_EQ(get_state_tc(port), TC_UNATTACHED_SNK, "%d");
 
 	host_disconnect_source();