On Tue, Oct 12, 2021 at 01:57:09PM +0200, Rasmus Villemoes wrote: > On 12/10/2021 13.32, Matthew Wilcox wrote: > > On Tue, Oct 12, 2021 at 11:55:50AM +0200, Rasmus Villemoes wrote: > >> ...default_flag_spec has '.flags = SPECIAL | SMALL,', i.e. what one > >> would get from %#x . I'm guessing that's what upsets 0-day. > >> > >> Geez it would be nice if 0day actually reported the "Expected foo, but > >> bar was emitted to the buffer". > > > > It's there; you just have to dive into the dmesg.xz to get it: > > > > [ 48.607787][ T1214] test_printf: vsnprintf(buf, 256, "%pGp", ...) returned 33, expected 29 > > [ 48.616106][ T1214] test_printf: vsnprintf(buf, 18, "%pGp", ...) returned 33, expected 29 > > [ 48.624292][ T1214] test_printf: vsnprintf(buf, 0, "%pGp", ...) returned 33, expected 29 > > [ 48.632403][ T1214] test_printf: kvasprintf(..., "%pGp", ...) returned '0x0(node=0|zone=0|lastcpupid=0x0)', expected 'node=0|zone=0|lastcpupid=0x0)' > > [ 48.645741][ T1214] test_printf: vsnprintf(buf, 256, "%pGp", ...) returned 33, expected 29 > > [ 48.654023][ T1214] test_printf: vsnprintf(buf, 23, "%pGp", ...) returned 33, expected 29 > > [ 48.662218][ T1214] test_printf: vsnprintf(buf, 0, "%pGp", ...) returned 33, expected 29 > > [ 48.670327][ T1214] test_printf: kvasprintf(..., "%pGp", ...) returned '0x0(node=0|zone=0|lastcpupid=0x0)', expected 'node=0|zone=0|lastcpupid=0x0)' > > [ 48.683670][ T1214] test_printf: vsnprintf(buf, 256, "%pGp", ...) returned 88, expected 71 > > [ 48.691937][ T1214] test_printf: vsnprintf(buf, 64, "%pGp", ...) returned 88, expected 71 > > [ 48.700128][ T1214] test_printf: vsnprintf(buf, 0, "%pGp", ...) returned 88, expected 71 > > [ 48.708249][ T1214] test_printf: kvasprintf(..., "%pGp", ...) returned '0x4fffffc008003c(uptodate|dirty|lru|active|swapbacked|node=1|zone=1|lastcpupid=0x1fffff)', expected 'uptodate|dirty|lru|active|swapbacked|node=1|zone=1|lastcpupid=0x1fffff)' > > [ 48.730275][ T1214] test_printf: failed 12 out of 420 tests > > > > So you're right, it's missing the 0x, > > Ah, it's actually missing the whole '0xfoo(' because you're not updating > 'size' after the first > > + snprintf(cmp_buf + size, BUF_SIZE - size, "%x(", flags); > > so the next write to cmp_buf overwrites whatever you wrote here. > > > but I still don't know how to run this self-test. > > Neither do I, when I created test_printf.c I made sure it ran on boot if > built-in, and that's certainly how I've been testing vsprintf.c patches > in the past. Maybe the kstm crowd can explain how to get that to work as > expected. Got it. It was running; just wasn't being captured by the kernel messages output on my test system. If I ssh in to the test system and examine dmesg, it's there. Now, this isn't quite enough; - snprintf(cmp_buf + size, BUF_SIZE - size, "%x(", flags); + snprintf(cmp_buf + size, BUF_SIZE - size, "%#x(", flags); + size = strlen(cmp_buf); The problem is that the test suite doesn't pass in a full flags. It passes in some pageflags and then ORs in the zone, nid, etc after printing some of the flags. So I had to restructure the test a bit to print the full hex number. What do you think? +++ b/lib/test_printf.c @@ -610,11 +610,15 @@ page_flags_test(int section, int node, int zone, int last_cpupid, { unsigned long values[] = {section, node, zone, last_cpupid, kasan_tag}; unsigned long page_flags = 0; + unsigned long test_flags = flags & PAGEFLAGS_MASK; unsigned long size = 0; bool append = false; int i; - snprintf(cmp_buf + size, BUF_SIZE - size, "%x(", flags); + for (i = 0; i < ARRAY_SIZE(values); i++) + test_flags |= (values[i] & pft[i].mask) << pft[i].shift; + snprintf(cmp_buf + size, BUF_SIZE - size, "%#lx(", test_flags); + size = strlen(cmp_buf); flags &= PAGEFLAGS_MASK; if (flags) { page_flags |= flags; It's a bit duplicative of what's below, and I'm far from sure about the testing of bits that fall outside PAGEFLAGS_MASK. It doesn't feel like a great test in that it's not testing how pGp would get used. Maybe that points to a small defect in pGp -- shouldn't it print something for unknown bits being set?