Re: BUG: Bad rss-counter state (4)

Re: BUG: Bad rss-counter state (4)

[Dmitry Vyukov]

On Mon, May 18, 2020 at 9:27 AM syzbot
<syzbot+347e2331d03d06ab0224@syzkaller.appspotmail.com> wrote:
>
> Hello,
>
> syzbot found the following crash on:
>
> HEAD commit:    ac935d22 Add linux-next specific files for 20200415
> git tree:       linux-next
> console output: https://syzkaller.appspot.com/x/log.txt?x=14b66e6e100000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=bc498783097e9019
> dashboard link: https://syzkaller.appspot.com/bug?extid=347e2331d03d06ab0224
> compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=12d18e6e100000
> C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=104170d6100000
>
> IMPORTANT: if you fix the bug, please add the following tag to the commit:
> Reported-by: syzbot+347e2331d03d06ab0224@syzkaller.appspotmail.com

This seems to be related to the mmap/mremap calls, +mm/mmap.c maintainers.

> BUG: Bad rss-counter state mm:00000000a67744c9 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000f49d6d70 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:0000000006212dd2 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000b6ae35d3 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000d44d5c2e type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:0000000023502204 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:000000001a912a5c type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:0000000072bd9e23 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:0000000053ee80f7 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:000000003cc0aff9 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:000000005a4ef043 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000fe0ab895 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000863004ed type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:0000000064449491 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000f6a209ff type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:000000008100dc4b type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000f80eb0e8 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000475e50a5 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000f2f5edcf type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000bf721456 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000d8d29ec3 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:00000000b5dff60e type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:000000001f0fe928 type:MM_ANONPAGES val:1
> BUG: Bad rss-counter state mm:000000006fc01973 type:MM_ANONPAGES val:1
>
>
> ---
> This bug is generated by a bot. It may contain errors.
> See https://goo.gl/tpsmEJ for more information about syzbot.
> syzbot engineers can be reached at syzkaller@googlegroups.com.
>
> syzbot will keep track of this bug report. See:
> https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
> syzbot can test patches for this bug, for details see:
> https://goo.gl/tpsmEJ#testing-patches
>
> --
> You received this message because you are subscribed to the Google Groups "syzkaller-bugs" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to syzkaller-bugs+unsubscribe@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/syzkaller-bugs/000000000000ada39605a5e71711%40google.com.

Re: BUG: Bad rss-counter state (4)

[syzbot]

syzbot has bisected this bug to:

commit 0d8dd67be013727ae57645ecd3ea2c36365d7da8
Author: Song Liu <songliubraving@fb.com>
Date:   Wed Dec 6 22:45:14 2017 +0000

    perf/headers: Sync new perf_event.h with the tools/include/uapi version

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=13240a02100000
start commit:   ac935d22 Add linux-next specific files for 20200415
git tree:       linux-next
final crash:    https://syzkaller.appspot.com/x/report.txt?x=10a40a02100000
console output: https://syzkaller.appspot.com/x/log.txt?x=17240a02100000
kernel config:  https://syzkaller.appspot.com/x/.config?x=bc498783097e9019
dashboard link: https://syzkaller.appspot.com/bug?extid=347e2331d03d06ab0224
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=12d18e6e100000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=104170d6100000

Reported-by: syzbot+347e2331d03d06ab0224@syzkaller.appspotmail.com
Fixes: 0d8dd67be013 ("perf/headers: Sync new perf_event.h with the tools/include/uapi version")

For information about bisection process see: https://goo.gl/tpsmEJ#bisection

Re: Re: BUG: Bad rss-counter state (4)

[Vegard Nossum]

(trimmed off the batman/bpf Ccs)

On 2020-05-18 14:28, syzbot wrote:
> syzbot has bisected this bug to:
> 
> commit 0d8dd67be013727ae57645ecd3ea2c36365d7da8
> Author: Song Liu <songliubraving@fb.com>
> Date:   Wed Dec 6 22:45:14 2017 +0000
> 
>      perf/headers: Sync new perf_event.h with the tools/include/uapi version
> 
> bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=13240a02100000
> start commit:   ac935d22 Add linux-next specific files for 20200415
> git tree:       linux-next
> final crash:    https://syzkaller.appspot.com/x/report.txt?x=10a40a02100000
> console output: https://syzkaller.appspot.com/x/log.txt?x=17240a02100000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=bc498783097e9019
> dashboard link: https://syzkaller.appspot.com/bug?extid=347e2331d03d06ab0224
> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=12d18e6e100000
> C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=104170d6100000
> 
> Reported-by: syzbot+347e2331d03d06ab0224@syzkaller.appspotmail.com
> Fixes: 0d8dd67be013 ("perf/headers: Sync new perf_event.h with the tools/include/uapi version")
> 
> For information about bisection process see: https://goo.gl/tpsmEJ#bisection
> 

FWIW here's a nicer reproducer that more clearly shows what's really
going on:

#define _GNU_SOURCE
#include <sys/mman.h>
#include <linux/perf_event.h>
#include <linux/hw_breakpoint.h>

#include <fcntl.h>
#include <stdio.h>
#include <stdint.h>
#include <string.h>
#include <syscall.h>
#include <unistd.h>

// for compat with older perf headers
#define uprobe_path config1

int main(int argc, char *argv[])
{
         // Find out what type id we need for uprobes
         int perf_type_pmu_uprobe;
         {
                 FILE *fp = 
fopen("/sys/bus/event_source/devices/uprobe/type", "r");
                 fscanf(fp, "%d", &perf_type_pmu_uprobe);
                 fclose(fp);
         }

         const char *filename = "./bus";

         int fd = open(filename, O_RDWR|O_CREAT, 0600);
         write(fd, "x", 1);

         void *addr = mmap(NULL, 4096,
                 PROT_READ | PROT_WRITE | PROT_EXEC,
                 MAP_PRIVATE | MAP_ANONYMOUS, -1, 0);

         // Register a perf uprobe on "./bus"
         struct perf_event_attr attr = {};
         attr.type = perf_type_pmu_uprobe;
         attr.uprobe_path = (unsigned long) filename;
         syscall(__NR_perf_event_open, &attr, 0, 0, -1, 0);

         void *addr2 = mmap(NULL, 2 * 4096,
                 PROT_NONE,
                 MAP_PRIVATE, fd, 0);
         void *addr3 = mremap((void *) addr2, 4096, 2 * 4096, 
MREMAP_MAYMOVE);
         mremap(addr3, 4096, 4096, MREMAP_MAYMOVE | MREMAP_FIXED, (void 
*) addr2);

         return 0;
}

this instantly reproduces this output on current mainline for me:

BUG: Bad rss-counter state mm:(____ptrval____) type:MM_ANONPAGES val:1

AFAICT the worst thing about this bug is that it shows up on anything
that parses logs for "BUG"; it doesn't seem to have any ill effects
other than messing up the rss counters. Although maybe it points to some
underlying problem in uprobes/mm interaction.

If I enable the "rss_stat" tracepoint and set ftrace_dump_on_oops=1, I
see a trace roughly like this:

perf_event_open()

mmap(2 * 4096):
  - uprobe_mmap()
     - install_breakpoint()
        - __replace_page()
           - rss_stat: mm_id=0 curr=1 member=1 size=53248B

mremap(4096 => 2 * 4096):
  - install_breakpoint()
     - __replace_page()
        - rss_stat: mm_id=0 curr=1 member=1 size=57344B
  - unmap_page_range()
     - rss_stat: mm_id=0 curr=1 member=1 size=53248B

mremap(4096 => 4096):
  - move_vma()
     - copy_vma()
        - vma_merge()
           - install_breakpoint()
              - __replace_page()
                 - rss_stat: mm_id=0 curr=1 member=1 size=57344B
  - do_munmap()
     - install_breakpoint():
        - __replace_page()
           - rss_stat: mm_id=0 curr=1 member=1 size=61440B
     - unmap_page_range():
        - rss_stat: mm_id=0 curr=1 member=1 size=57344B

exit()
  - exit_mmap()
     - unmap_page_range():
        - rss_stat: mm_id=0 curr=0 member=1 size=45056B
     - unmap_page_range():
        - rss_stat: mm_id=0 curr=0 member=1 size=32768B
     - unmap_page_range():
        - rss_stat: mm_id=0 curr=0 member=1 size=20480B
     - unmap_page_range():
        - rss_stat: mm_id=0 curr=0 member=1 size=16384B
     - unmap_page_range():
        - rss_stat: mm_id=0 curr=0 member=1 size=4096B

What strikes me here is that at the end of the first mremap(), we have
size 53248B (13 pages), but at the end of the second mremap(), we have
size 57344B (14 pages), even though the second mremap() is only moving 1
page. So the second mremap() is bumping it up twice, but then only
bumping down once.


Vegard