tests: improve diagnostic output on failure

cmd/tools/modules/testing/common.v

@@ -50,6 +50,7 @@ pub fn new_test_session(_vargs string) TestSession {
 		skip_files: skip_files
 		vargs: vargs
 		show_ok_tests: !_vargs.contains('-silent')
+		message_handler: 0
 	}
 }
 

vlib/builtin/builtin.v

@@ -32,26 +32,31 @@ pub fn print_backtrace() {
 
 // replaces panic when -debug arg is passed
 fn panic_debug(line_no int, file, mod, fn_name, s string) {
-	println('================ V panic ================')
-	println('   module: $mod')
-	println(' function: ${fn_name}()')
-	println('     file: $file')
-	println('     line: ' + line_no.str())
-	println('  message: $s')
-	println('=========================================')
+	// NB: the order here is important for a stabler test output
+	// module is less likely to change than function, etc...
+	// During edits, the line number will change most frequently,
+	// so it is last
+	eprintln('================ V panic ================')
+	eprintln('   module: $mod')
+	eprintln(' function: ${fn_name}()')
+	eprintln('  message: $s')
+	eprintln('     file: $file')
+	eprintln('     line: ' + line_no.str())
+	eprintln('=========================================')
 	print_backtrace_skipping_top_frames(1)
 	C.exit(1)
 }
 
 pub fn panic(s string) {
-	println('V panic: $s')
+	eprintln('V panic: $s')
 	print_backtrace()
 	C.exit(1)
 }
 
 pub fn eprintln(s string) {
+	// eprintln is used in panics, so it should not fail at all
 	if s.str == 0 {
-		panic('eprintln(NIL)')
+		eprintln('eprintln(NIL)')
 	}
 	$if !windows {
 		C.fflush(C.stdout)
@@ -66,7 +71,7 @@ pub fn eprintln(s string) {
 
 pub fn eprint(s string) {
 	if s.str == 0 {
-		panic('eprint(NIL)')
+		eprintln('eprint(NIL)')
 	}
 	$if !windows {
 		C.fflush(C.stdout)

vlib/builtin/builtin_nix.c.v

@@ -65,7 +65,7 @@ fn print_backtrace_skipping_top_frames_mac(skipframes int) bool {
 	$if macos {
 		buffer := [100]byteptr
 		nr_ptrs := backtrace(buffer, 100)
-		backtrace_symbols_fd(&buffer[skipframes], nr_ptrs - skipframes, 1)
+		backtrace_symbols_fd(&buffer[skipframes], nr_ptrs - skipframes, 2)
 	}
 	return true
 }
@@ -74,7 +74,7 @@ fn print_backtrace_skipping_top_frames_freebsd(skipframes int) bool {
 	$if freebsd {
 		buffer := [100]byteptr
 		nr_ptrs := backtrace(buffer, 100)
-		backtrace_symbols_fd(&buffer[skipframes], nr_ptrs - skipframes, 1)
+		backtrace_symbols_fd(&buffer[skipframes], nr_ptrs - skipframes, 2)
 	}
 	return true
 }
@@ -104,7 +104,7 @@ fn print_backtrace_skipping_top_frames_linux(skipframes int) bool {
 				// taken from os, to avoid depending on the os module inside builtin.v
 				f := C.popen(cmd.str, 'r')
 				if isnil(f) {
-					println(sframe)
+					eprintln(sframe)
 					continue
 				}
 				buf := [1000]byte
@@ -114,7 +114,7 @@ fn print_backtrace_skipping_top_frames_linux(skipframes int) bool {
 				}
 				output = output.trim_space() + ':'
 				if C.pclose(f) != 0 {
-					println(sframe)
+					eprintln(sframe)
 					continue
 				}
 				if output in ['??:0:', '??:?:'] {
@@ -124,13 +124,13 @@ fn print_backtrace_skipping_top_frames_linux(skipframes int) bool {
 				// NB: it is shortened here to just d. , just so that it fits, and so
 				// that the common error file:lineno: line format is enforced.
 				output = output.replace(' (discriminator', ': (d.')
-				println('${output:-46s} | ${addr:14s} | $beforeaddr')
+				eprintln('${output:-46s} | ${addr:14s} | $beforeaddr')
 			}
 			// backtrace_symbols_fd(*voidptr(&buffer[skipframes]), nr_actual_frames, 1)
 			return true
 		} $else {
-			println('backtrace_symbols_fd is missing, so printing backtraces is not available.\n')
-			println('Some libc implementations like musl simply do not provide it.')
+			eprintln('backtrace_symbols_fd is missing, so printing backtraces is not available.\n')
+			eprintln('Some libc implementations like musl simply do not provide it.')
 		}
 	}
 	return false

vlib/builtin/builtin_windows.c.v

@@ -69,12 +69,11 @@ fn builtin_init() {
 fn print_backtrace_skipping_top_frames(skipframes int) bool {
 	$if msvc {
 		return print_backtrace_skipping_top_frames_msvc(skipframes)
-
 	}
 	$if mingw {
 		return print_backtrace_skipping_top_frames_mingw(skipframes)
 	}
-	println('print_backtrace_skipping_top_frames is not implemented')
+	eprintln('print_backtrace_skipping_top_frames is not implemented')
 	return false
 }
 
@@ -97,7 +96,7 @@ $if msvc {
 
 	syminitok := C.SymInitialize( handle, 0, 1)
 	if syminitok != 1 {
-		println('Failed getting process: Aborting backtrace.\n')
+		eprintln('Failed getting process: Aborting backtrace.\n')
 		return true
 	}
 
@@ -115,27 +114,29 @@ $if msvc {
 				lineinfo = '?? : address = 0x${&frame_addr:x}'
 			}
 			sfunc := tos3(fname)
-			println('${nframe:-2d}: ${sfunc:-25s}  $lineinfo')
+			eprintln('${nframe:-2d}: ${sfunc:-25s}  $lineinfo')
 		} else {
 			// https://docs.microsoft.com/en-us/windows/win32/debug/system-error-codes
 			cerr := int(C.GetLastError())
 			if cerr == 87 {
-				println('SymFromAddr failure: $cerr = The parameter is incorrect)')
+				eprintln('SymFromAddr failure: $cerr = The parameter is incorrect)')
 			} else if cerr == 487 {
 				// probably caused because the .pdb isn't in the executable folder
-				println('SymFromAddr failure: $cerr = Attempt to access invalid address (Verify that you have the .pdb file in the right folder.)')
+				eprintln('SymFromAddr failure: $cerr = Attempt to access invalid address (Verify that you have the .pdb file in the right folder.)')
 			} else {
-				println('SymFromAddr failure: $cerr (see https://docs.microsoft.com/en-us/windows/win32/debug/system-error-codes)')
+				eprintln('SymFromAddr failure: $cerr (see https://docs.microsoft.com/en-us/windows/win32/debug/system-error-codes)')
 			}
 		}
 	}
 	return true
 } $else {
+	eprintln('print_backtrace_skipping_top_frames_msvc must be called only when the compiler is msvc')
 	return false
 }
 }
 
 fn print_backtrace_skipping_top_frames_mingw(skipframes int) bool {
+	eprintln('print_backtrace_skipping_top_frames_mingw is not implemented')
 	return false
 }
 

vlib/builtin/js/builtin.v

@@ -14,7 +14,7 @@ pub fn isnil(v voidptr) bool {
 }
 
 pub fn panic(s string) {
-	println('V panic: ' + s)
+	eprintln('V panic: ' + s)
 	exit(1)
 }
 

vlib/os/os_windows.c.v

@@ -308,7 +308,7 @@ pub fn exec(cmd string) ?Result {
 	create_process_ok := C.CreateProcessW(0, command_line, 0, 0, C.TRUE, 0, 0, 0, voidptr(&start_info), voidptr(&proc_info))
 	if !create_process_ok {
 		error_msg := get_error_msg(int(C.GetLastError()))
-		return error('exec failed (CreateProcess): $error_msg')
+		return error('exec failed (CreateProcess): $error_msg cmd: $cmd')
 	}
 	C.CloseHandle(child_stdin)
 	C.CloseHandle(child_stdout_write)

vlib/v/gen/fn.v

@@ -470,7 +470,7 @@ fn (mut g Gen) fn_call(node ast.CallExpr) {
 			}
 			g.write('))')
 		}
-	} else if g.pref.is_debug && node.name == 'panic' && g.fn_decl.name != '__as_cast' {
+	} else if g.pref.is_debug && node.name == 'panic' {
 		paline := node.pos.line_nr + 1
 		pafile := g.fn_decl.file.replace('\\', '/')
 		pafn := g.fn_decl.name.after('.')

vlib/v/tests/inout/bad_st_as.out

@@ -1,2 +1,5 @@
 Foo
-V panic: as cast: cannot cast
+================ V panic ================
+   module: __as_cast
+ function: __as_cast()
+  message: as cast: cannot cast

vlib/v/tests/inout/compiler_test.v

@@ -1,9 +1,12 @@
 import os
 import term
+import v.util
 
 fn test_all() {
 	mut total_errors := 0
 	vexe := os.getenv('VEXE')
+	vroot := os.dir(vexe)
+	diff_cmd := util.find_working_diff_command() or { '' }
 	dir := 'vlib/v/tests/inout'
 	files := os.ls(dir) or {
 		panic(err)
@@ -20,9 +23,12 @@ fn test_all() {
 		os.cp(path, program) or {
 			panic(err)
 		}
-		_ := os.exec('$vexe -o exe -cflags "-w" -cg $program') or {
+		compilation := os.exec('$vexe -o exe -cflags "-w" -cg $program') or {
 			panic(err)
 		}
+		if compilation.exit_code != 0 {
+			panic('compilation failed: $compilation.output')
+		}
 		// os.rm(program)
 		res := os.exec('./exe') or {
 			println('nope')
@@ -32,29 +38,40 @@ fn test_all() {
 		// println('============')
 		// println(res.output)
 		// println('============')
+		mut found := res.output.trim_space().trim('\n').replace('\r\n', '\n')
 		mut expected := os.read_file(program.replace('.v', '') + '.out') or {
 			panic(err)
 		}
 		expected = expected.trim_space().trim('\n').replace('\r\n', '\n')
-		found := res.output.trim_space().trim('\n').replace('\r\n', '\n')
-		if expected.contains('V panic:') {
-			// panic include backtraces, so can't do char by char comparison
-			panic_msg := expected.find_between('V panic:', '\n').trim_space()
-			if found.contains('V panic:') && found.contains(panic_msg) {
-				println(term.green('OK (panic)'))
-				continue
+		if expected.contains('================ V panic ================') {
+			// panic include backtraces and absolute file paths, so can't do char by char comparison
+			n_found := normalize_panic_message( found, vroot )
+			n_expected := normalize_panic_message( expected, vroot )
+			if found.contains('================ V panic ================') {
+				if n_found.contains(n_expected) {
+					println(term.green('OK (panic)'))
+					continue
+				} else {
+					// Both have panics, but there was a difference...
+					// Pass the normalized strings for further reporting.
+					// There is no point in comparing the backtraces too.
+					found = n_found
+					expected = n_expected
+				}
 			}
 		}
 		if expected != found {
 			println(term.red('FAIL'))
-			// println(x.output.limit(30))
-			println('============')
-			println('expected:')
+			println(term.header('expected:','-'))
 			println(expected)
-			println('============')
-			println('found:')
+			println(term.header('found:','-'))
 			println(found)
-			println('============\n')
+			if diff_cmd != '' {
+				println(term.header('difference:','-'))
+				println(util.color_compare_strings(diff_cmd, expected, found))
+			} else {
+				println(term.h_divider('-'))
+			}
 			total_errors++
 		} else {
 			println(term.green('OK'))
@@ -62,3 +79,10 @@ fn test_all() {
 	}
 	assert total_errors == 0
 }
+
+fn normalize_panic_message(message string, vroot string) string {
+	mut msg := message.all_before('=========================================')
+	msg = msg.replace(vroot + os.path_separator, '')
+	msg = msg.trim_space()
+	return msg
+}

vlib/v/util/errors.v

@@ -6,6 +6,7 @@ module util
 import os
 import term
 import v.token
+import time
 
 // The filepath:line:col: format is the default C compiler error output format.
 // It allows editors and IDE's like emacs to quickly find the errors in the
@@ -184,3 +185,16 @@ pub fn color_compare_files(diff_cmd, file1, file2 string) string {
     }
     return ''
 }
+
+fn color_compare_strings(diff_cmd string, expected string, found string) string {
+	cdir := os.cache_dir()
+	ctime := time.sys_mono_now()
+	e_file := os.join_path(cdir, '${ctime}.expected.txt')
+	f_file := os.join_path(cdir, '${ctime}.found.txt')
+	os.write_file( e_file, expected)
+	os.write_file( f_file, found)
+	res := util.color_compare_files(diff_cmd, e_file, f_file)
+	os.rm( e_file )
+	os.rm( f_file )
+	return res
+}