testing: support new events in the output modules of v test: .cmd_begin sent right before a _test.v execution, and .cmd_end sent right after a _test.v execution

cmd/tools/modules/testing/common.v

@@ -109,10 +109,22 @@ pub fn (mut ts TestSession) session_stop(message string) {
 }
 
 pub fn (mut ts TestSession) print_messages() {
+	mut test_idx := 0
 	mut print_msg_time := time.new_stopwatch()
 	for {
 		// get a message from the channel of messages to be printed:
 		mut rmessage := <-ts.nmessages
+		ts.nmessage_idx++
+
+		// first sent *all events* to the output reporter, so it can then process them however it wants:
+		ts.reporter.report(ts.nmessage_idx, rmessage)
+
+		if rmessage.kind in [.cmd_begin, .cmd_end] {
+			// The following events, are sent before the test framework has determined,
+			// what the full completion status is. They can also be repeated multiple times,
+			// for tests that are flaky and need repeating.
+			continue
+		}
 		if rmessage.kind == .sentinel {
 			// a sentinel for stopping the printing thread
 			if !ts.silent_mode && ts.progress_mode {
@@ -121,19 +133,19 @@ pub fn (mut ts TestSession) print_messages() {
 			return
 		}
 		if rmessage.kind != .info {
-			ts.nmessage_idx++
+			// info events can also be repeated, and should be ignored when determining
+			// the total order of the current test file, in the following replacements:
+			test_idx++
 		}
-		//
-		ts.reporter.report(ts.nmessage_idx, rmessage)
 		msg := rmessage.message.replace_each([
 			'TMP1',
-			'${ts.nmessage_idx:1d}',
+			'${test_idx:1d}',
 			'TMP2',
-			'${ts.nmessage_idx:2d}',
+			'${test_idx:2d}',
 			'TMP3',
-			'${ts.nmessage_idx:3d}',
+			'${test_idx:3d}',
 			'TMP4',
-			'${ts.nmessage_idx:4d}',
+			'${test_idx:4d}',
 		])
 		is_ok := rmessage.kind == .ok
 		//
@@ -343,7 +355,7 @@ pub fn (mut ts TestSession) test() {
 	pool_of_test_runners.work_on_pointers(unsafe { remaining_files.pointers() })
 	//
 	ts.benchmark.stop()
-	ts.append_message(.sentinel, '', MessageThreadContext{ flow_id: sync.thread_id().str() }) // send the sentinel
+	ts.append_message(.sentinel, '', MessageThreadContext{ flow_id: '-1' }) // send the sentinel
 	printing_thread.wait()
 	ts.reporter.worker_threads_finish(mut ts)
 	ts.reporter.divider()
@@ -436,7 +448,13 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 	}
 	if ts.show_stats {
 		ts.reporter.divider()
+
+		ts.append_message(.cmd_begin, cmd, mtc)
+		d_cmd := time.new_stopwatch()
 		mut status := os.system(cmd)
+		mut cmd_duration := d_cmd.elapsed()
+		ts.append_message_with_duration(.cmd_end, '', cmd_duration, mtc)
+
 		if status != 0 {
 			details := get_test_details(file)
 			os.setenv('VTEST_RETRY_MAX', '${details.retry}', true)
@@ -444,7 +462,13 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 				ts.append_message(.info, '  [stats]        retrying ${retry}/${details.retry} of ${relative_file} ; known flaky: ${details.flaky} ...',
 					mtc)
 				os.setenv('VTEST_RETRY', '${retry}', true)
+
+				ts.append_message(.cmd_begin, cmd, mtc)
+				d_cmd_2 := time.new_stopwatch()
 				status = os.system(cmd)
+				cmd_duration = d_cmd_2.elapsed()
+				ts.append_message_with_duration(.cmd_end, '', cmd_duration, mtc)
+
 				if status == 0 {
 					unsafe {
 						goto test_passed_system
@@ -473,9 +497,12 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 			ts.append_message(.info, '                 starting ${relative_file} ...',
 				mtc)
 		}
+		ts.append_message(.cmd_begin, cmd, mtc)
 		d_cmd := time.new_stopwatch()
 		mut r := os.execute(cmd)
-		cmd_duration := d_cmd.elapsed()
+		mut cmd_duration := d_cmd.elapsed()
+		ts.append_message_with_duration(.cmd_end, r.output, cmd_duration, mtc)
+
 		if r.exit_code < 0 {
 			ts.benchmark.fail()
 			tls_bench.fail()
@@ -491,7 +518,13 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 				ts.append_message(.info, '                 retrying ${retry}/${details.retry} of ${relative_file} ; known flaky: ${details.flaky} ...',
 					mtc)
 				os.setenv('VTEST_RETRY', '${retry}', true)
+
+				ts.append_message(.cmd_begin, cmd, mtc)
+				d_cmd_2 := time.new_stopwatch()
 				r = os.execute(cmd)
+				cmd_duration = d_cmd_2.elapsed()
+				ts.append_message_with_duration(.cmd_end, r.output, cmd_duration, mtc)
+
 				if r.exit_code == 0 {
 					unsafe {
 						goto test_passed_execute

cmd/tools/modules/testing/output.v

@@ -3,21 +3,25 @@ module testing
 import time
 
 pub enum MessageKind {
-	ok
+	cmd_begin // sent right before *each* _test.v file execution, the resulting status is not known yet, but the _test.v file itself is
-	fail
+	cmd_end // sent right after *each* _test.v file execution, the message contains the output of that execution
-	skip
+	//
-	info
+	ok // success of a _test.v file
-	sentinel
+	fail // failed _test.v file, one or more assertions failed
+	skip // the _test.v file was skipped for some reason
+	info // a generic information message, detailing the actions of the `v test` program (some tests could be repeated for example, and the details are sent with an .info status)
+	//
+	sentinel // send just once after all executions are done; it signals that the reporting/printing thread should stop the loop and exit
 }
 
 pub struct LogMessage {
 pub:
-	flow_id string        // the messages of each thread, producing LogMessage, will have all the same unique flowid. Messages by other threads will have other flowid. If you use VJOBS=1 to serialise the execution, then all messages will have the same flowid.
+	kind    MessageKind   // see the MessageKind declaration above
 	file    string        // the _test.v file that the message is about
-	message string        // the actual message text; the result of the event, that the message describes; most reporters could ignore this, since it could be reconstructed by the other fields
-	kind    MessageKind   // see the MessageKind declaration
 	when    time.Time     // when was the message sent (messages are sent by the execution threads at the *end* of each event)
+	flow_id string        // the messages of each thread, producing LogMessage, will have all the same unique flowid. Messages by other threads will have other flowid. If you use VJOBS=1 to serialise the execution, then all messages will have the same flowid.
 	took    time.Duration // the duration of the event, that this message describes
+	message string        // the actual message text; the result of the event, that the message describes; most reporters could ignore this, since it could be reconstructed by the other fields
 }
 
 pub interface Reporter {