Re: [PATCH v3 0/5] Add printf and formatted asserts in the guest

[Sean Christopherson <seanjc@google.com>]

On Wed, Jun 07, 2023, Aaron Lewis wrote:
> Extend the ucall framework to offer GUEST_PRINTF() and GUEST_ASSERT_FMT()
> in selftests.  This will allow for better and easier guest debugging.

This. Is.  Awesome.  Seriously, this is amazing!

I have one or two nits, but theyre so minor I already forgot what they were.

The one thing I think we should change is the final output of the assert.  Rather
than report the host TEST_FAIL as the assert:

  # ./svm_nested_soft_inject_test
  Running soft int test
  ==== Test Assertion Failure ====
    x86_64/svm_nested_soft_inject_test.c:191: false
    pid=169827 tid=169827 errno=4 - Interrupted system call
       1	0x0000000000401b52: run_test at svm_nested_soft_inject_test.c:191
       2	0x00000000004017d2: main at svm_nested_soft_inject_test.c:212
       3	0x00000000004159d3: __libc_start_call_main at libc-start.o:?
       4	0x000000000041701f: __libc_start_main_impl at ??:?
       5	0x0000000000401660: _start at ??:?
    Failed guest assert: regs->rip != (unsigned long)l2_guest_code_int at x86_64/svm_nested_soft_inject_test.c:39
    Expected IRQ at RIP 0x401e80, received IRQ at 0x401e80

show the guest assert as the primary assert.

  Running soft int test
  ==== Test Assertion Failure ====
    x86_64/svm_nested_soft_inject_test.c:39: regs->rip != (unsigned long)l2_guest_code_int
    pid=214104 tid=214104 errno=4 - Interrupted system call
       1	0x0000000000401b35: run_test at svm_nested_soft_inject_test.c:191
       2	0x00000000004017d2: main at svm_nested_soft_inject_test.c:212
       3	0x0000000000415b03: __libc_start_call_main at libc-start.o:?
       4	0x000000000041714f: __libc_start_main_impl at ??:?
       5	0x0000000000401660: _start at ??:?
    Expected IRQ at RIP 0x401e50, received IRQ at 0x401e50

That way users don't have to manually find the "real" assert.  Ditto for any kind
of automated reporting.  The site of the test_fail() invocation in the host is
still captured in the stack trace (though that too could be something to fix over
time), so unless I'm missing something, there's no information lost.

The easiest thing I can think of is to add a second buffer to hold the exp+file+line.
Then, test_assert() just needs to skip that particular line of formatting.

If you don't object, I'll post a v4 with the below folded in somewhere (after
more testing), and put this on the fast track for 6.6.

Side topic, if anyone lurking out there wants an easy (but tedious and boring)
starter project, we should convert all tests to the newfangled formatting and
drop GUEST_ASSERT_N entirely.  Once all tests are converted, GUEST_ASSERT_FMT()
and REPORT_GUEST_ASSERT_FMT can drop the "FMT" postfix.

---
 .../selftests/kvm/include/ucall_common.h      | 19 ++++++++---------
 tools/testing/selftests/kvm/lib/assert.c      | 13 +++++++-----
 .../testing/selftests/kvm/lib/ucall_common.c  | 21 +++++++++++++++++++
 3 files changed, 38 insertions(+), 15 deletions(-)

diff --git a/tools/testing/selftests/kvm/include/ucall_common.h b/tools/testing/selftests/kvm/include/ucall_common.h
index b4f4c88e8d84..3bc4e62bec1b 100644
--- a/tools/testing/selftests/kvm/include/ucall_common.h
+++ b/tools/testing/selftests/kvm/include/ucall_common.h
@@ -25,6 +25,7 @@ struct ucall {
 	uint64_t cmd;
 	uint64_t args[UCALL_MAX_ARGS];
 	char buffer[UCALL_BUFFER_LEN];
+	char aux_buffer[UCALL_BUFFER_LEN];
 
 	/* Host virtual address of this struct. */
 	struct ucall *hva;
@@ -36,6 +37,8 @@ void *ucall_arch_get_ucall(struct kvm_vcpu *vcpu);
 
 void ucall(uint64_t cmd, int nargs, ...);
 void ucall_fmt(uint64_t cmd, const char *fmt, ...);
+void ucall_assert(uint64_t cmd, const char *exp, const char *file,
+		  unsigned int line, const char *fmt, ...);
 uint64_t get_ucall(struct kvm_vcpu *vcpu, struct ucall *uc);
 void ucall_init(struct kvm_vm *vm, vm_paddr_t mmio_gpa);
 int ucall_nr_pages_required(uint64_t page_size);
@@ -63,15 +66,10 @@ enum guest_assert_builtin_args {
 	GUEST_ASSERT_BUILTIN_NARGS
 };
 
-#define __GUEST_ASSERT_FMT(_condition, _str, _fmt, _args...)			\
-do {										\
-	char fmt[UCALL_BUFFER_LEN];						\
-										\
-	if (!(_condition)) {							\
-		guest_snprintf(fmt, sizeof(fmt), "%s\n  %s",			\
-			     "Failed guest assert: " _str " at %s:%ld", _fmt);	\
-		ucall_fmt(UCALL_ABORT, fmt, __FILE__, __LINE__, ##_args);	\
-	}									\
+#define __GUEST_ASSERT_FMT(_condition, _str, _fmt, _args...)				\
+do {											\
+	if (!(_condition)) 								\
+		ucall_assert(UCALL_ABORT, _str, __FILE__, __LINE__, _fmt, ##_args);	\
 } while (0)
 
 #define GUEST_ASSERT_FMT(_condition, _fmt, _args...)	\
@@ -102,7 +100,8 @@ do {									\
 
 #define GUEST_ASSERT_EQ(a, b) __GUEST_ASSERT((a) == (b), #a " == " #b, 2, a, b)
 
-#define REPORT_GUEST_ASSERT_FMT(_ucall) TEST_FAIL("%s", _ucall.buffer)
+#define REPORT_GUEST_ASSERT_FMT(ucall)					\
+	test_assert(false, (ucall).aux_buffer, NULL, 0, "%s", (ucall).buffer);
 
 #define __REPORT_GUEST_ASSERT(_ucall, fmt, _args...)			\
 	TEST_FAIL("%s at %s:%ld\n" fmt,					\
diff --git a/tools/testing/selftests/kvm/lib/assert.c b/tools/testing/selftests/kvm/lib/assert.c
index 2bd25b191d15..74d94a34cf1a 100644
--- a/tools/testing/selftests/kvm/lib/assert.c
+++ b/tools/testing/selftests/kvm/lib/assert.c
@@ -75,11 +75,14 @@ test_assert(bool exp, const char *exp_str,
 	if (!(exp)) {
 		va_start(ap, fmt);
 
-		fprintf(stderr, "==== Test Assertion Failure ====\n"
-			"  %s:%u: %s\n"
-			"  pid=%d tid=%d errno=%d - %s\n",
-			file, line, exp_str, getpid(), _gettid(),
-			errno, strerror(errno));
+		fprintf(stderr, "==== Test Assertion Failure ====\n");
+		/* If @file is NULL, @exp_str contains a preformatted string. */
+		if (file)
+			fprintf(stderr, "  %s:%u: %s\n", file, line, exp_str);
+		else
+			fprintf(stderr, "  %s\n", exp_str);
+		fprintf(stderr, "  pid=%d tid=%d errno=%d - %s\n",
+			getpid(), _gettid(), errno, strerror(errno));
 		test_dump_stack();
 		if (fmt) {
 			fputs("  ", stderr);
diff --git a/tools/testing/selftests/kvm/lib/ucall_common.c b/tools/testing/selftests/kvm/lib/ucall_common.c
index b507db91139b..e7741aadf2ce 100644
--- a/tools/testing/selftests/kvm/lib/ucall_common.c
+++ b/tools/testing/selftests/kvm/lib/ucall_common.c
@@ -75,6 +75,27 @@ static void ucall_free(struct ucall *uc)
 	clear_bit(uc - ucall_pool->ucalls, ucall_pool->in_use);
 }
 
+void ucall_assert(uint64_t cmd, const char *exp, const char *file,
+		  unsigned int line, const char *fmt, ...)
+{
+	struct ucall *uc;
+	va_list va;
+
+	uc = ucall_alloc();
+	uc->cmd = cmd;
+
+	guest_snprintf(uc->aux_buffer, sizeof(uc->aux_buffer),
+		       "%s:%u: %s", file, line, exp);
+
+	va_start(va, fmt);
+	guest_vsnprintf(uc->buffer, UCALL_BUFFER_LEN, fmt, va);
+	va_end(va);
+
+	ucall_arch_do_ucall((vm_vaddr_t)uc->hva);
+
+	ucall_free(uc);
+}
+
 void ucall_fmt(uint64_t cmd, const char *fmt, ...)
 {
 	struct ucall *uc;

base-commit: 8dc29dfc010293957c5ca24271748a3c8f047a76
--