From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-2.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS autolearn=no autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 22BABC433DB for ; Mon, 29 Mar 2021 02:46:51 +0000 (UTC) Received: from kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by mail.kernel.org (Postfix) with ESMTP id 645C461938 for ; Mon, 29 Mar 2021 02:46:50 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 645C461938 Authentication-Results: mail.kernel.org; dmarc=fail (p=none dis=none) header.from=gmail.com Authentication-Results: mail.kernel.org; spf=pass smtp.mailfrom=owner-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix) id 6369B6B006C; Sun, 28 Mar 2021 22:46:49 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id 5E79A6B006E; Sun, 28 Mar 2021 22:46:49 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id 460796B0070; Sun, 28 Mar 2021 22:46:49 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from forelay.hostedemail.com (smtprelay0082.hostedemail.com [216.40.44.82]) by kanga.kvack.org (Postfix) with ESMTP id 2A6F86B006C for ; Sun, 28 Mar 2021 22:46:49 -0400 (EDT) Received: from smtpin31.hostedemail.com (10.5.19.251.rfc1918.com [10.5.19.251]) by forelay03.hostedemail.com (Postfix) with ESMTP id D84938249980 for ; Mon, 29 Mar 2021 02:46:48 +0000 (UTC) X-FDA: 77971374096.31.A1ACA28 Received: from mail-il1-f171.google.com (mail-il1-f171.google.com [209.85.166.171]) by imf28.hostedemail.com (Postfix) with ESMTP id 2C6972000244 for ; Mon, 29 Mar 2021 02:46:48 +0000 (UTC) Received: by mail-il1-f171.google.com with SMTP id d2so10016074ilm.10 for ; Sun, 28 Mar 2021 19:46:48 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=2mMCjLRbIjMiUSToAvmZJzIfnIV25RQ2WsQmT7UZYZU=; b=QOMWHgd2QrWw7jiMAnI/xdmwpXQN1T5eU38h3H1fzTbID7W0mjd14mTdNW5r5fEW9P jZQ3viFABq+K91BFW8yCOI2PFIv2AWX8Hz6qDozShpGSt3mbhYSEALAg595qJDWP3l9O Po3cBn4i4Uxi4Bk8c4a2ID36rQv9n+APgx3CJUDa0B0tSBIYQT00Pqiin8i+sGqOhDpy GpO6iy6ExksRuVUhrccykuraaT+nK/4h996zXxvtTKBankpDlj0PW6RPc6Pbi5fd12KR ZAI3GISSVPEerJijFMLdGHiu0s2ct1d33EXac2s7wckG/GViWk5L+qbM2I7e6N2FGVOM hE7g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=2mMCjLRbIjMiUSToAvmZJzIfnIV25RQ2WsQmT7UZYZU=; b=FrY/5gK1nWEq9LcGsLqpXa+F0ROEICWW186GxIKUnzFVU2n3DuMQXrw5C6XS764eKj ybTBH+eKOQHzGSz9tQ8WJdQbuiaUeA8idw6/iwB4w/wU+AtASWr3Yvk/uc2Rf7JsT5ci p6qkIuBvtYebPktisI1BcpSTgOMMs0Y7qyiqihsk2j3Mn7q5lT5EemJaBsarHWyw7ik5 AZfTIn8bGMepnVAD8qxAUM7RkAgQ5qiFklUxkbpkauXuz6H3PDVpbaCR293tJvMCKY4W ysZnhHeoP9r3n4q8uJqLkGdbAztCtzf47zgSOsX8P39mBW9x8ys3n2YAUI9vYN4smP+i rgQQ== X-Gm-Message-State: AOAM532MZ6AuG7BumiL8Lsn38OxrxH/xayv2+iJF0sgJLqIqIdXicnxt 6ob9v7FrwhKhMQp2D98TKLXJQukKiMNvco5MqPY= X-Google-Smtp-Source: ABdhPJz5iVWuJngtZQd1nTkw9/ta5qlvbGiWhBQE+Kw7sLtJVUTusR+2Vyb9eADCOVBwe83aZ5iwojG17zaHNb3ftSw= X-Received: by 2002:a05:6e02:104b:: with SMTP id p11mr12438494ilj.77.1616986007664; Sun, 28 Mar 2021 19:46:47 -0700 (PDT) MIME-Version: 1.0 References: In-Reply-To: From: Ilya Lipnitskiy Date: Sun, 28 Mar 2021 19:46:36 -0700 Message-ID: Subject: Re: exec error: BUG: Bad rss-counter To: "Eric W. Biederman" Cc: Linux-MM , Linux Kernel Mailing List , linux-fsdevel , Kees Cook , Christoph Hellwig , Linus Torvalds Content-Type: text/plain; charset="UTF-8" X-Stat-Signature: xe551sg7to8kuwzan3bmtwnjq7bkafbo X-Rspamd-Server: rspam04 X-Rspamd-Queue-Id: 2C6972000244 Received-SPF: none (gmail.com>: No applicable sender policy available) receiver=imf28; identity=mailfrom; envelope-from=""; helo=mail-il1-f171.google.com; client-ip=209.85.166.171 X-HE-DKIM-Result: pass/pass X-HE-Tag: 1616986008-73770 X-Bogosity: Ham, tests=bogofilter, spamicity=0.000000, version=1.2.4 Sender: owner-linux-mm@kvack.org Precedence: bulk X-Loop: owner-majordomo@kvack.org List-ID: On Wed, Mar 3, 2021 at 7:50 AM Eric W. Biederman wrote: > > Ilya Lipnitskiy writes: > > > On Tue, Mar 2, 2021 at 11:37 AM Eric W. Biederman wrote: > >> > >> Ilya Lipnitskiy writes: > >> > >> > On Mon, Mar 1, 2021 at 12:43 PM Eric W. Biederman wrote: > >> >> > >> >> Ilya Lipnitskiy writes: > >> >> > >> >> > Eric, All, > >> >> > > >> >> > The following error appears when running Linux 5.10.18 on an embedded > >> >> > MIPS mt7621 target: > >> >> > [ 0.301219] BUG: Bad rss-counter state mm:(ptrval) type:MM_ANONPAGES val:1 > >> >> > > >> >> > Being a very generic error, I started digging and added a stack dump > >> >> > before the BUG: > >> >> > Call Trace: > >> >> > [<80008094>] show_stack+0x30/0x100 > >> >> > [<8033b238>] dump_stack+0xac/0xe8 > >> >> > [<800285e8>] __mmdrop+0x98/0x1d0 > >> >> > [<801a6de8>] free_bprm+0x44/0x118 > >> >> > [<801a86a8>] kernel_execve+0x160/0x1d8 > >> >> > [<800420f4>] call_usermodehelper_exec_async+0x114/0x194 > >> >> > [<80003198>] ret_from_kernel_thread+0x14/0x1c > >> >> > > >> >> > So that's how I got to looking at fs/exec.c and noticed quite a few > >> >> > changes last year. Turns out this message only occurs once very early > >> >> > at boot during the very first call to kernel_execve. current->mm is > >> >> > NULL at this stage, so acct_arg_size() is effectively a no-op. > >> >> > >> >> If you believe this is a new error you could bisect the kernel > >> >> to see which change introduced the behavior you are seeing. > >> >> > >> >> > More digging, and I traced the RSS counter increment to: > >> >> > [<8015adb4>] add_mm_counter_fast+0xb4/0xc0 > >> >> > [<80160d58>] handle_mm_fault+0x6e4/0xea0 > >> >> > [<80158aa4>] __get_user_pages.part.78+0x190/0x37c > >> >> > [<8015992c>] __get_user_pages_remote+0x128/0x360 > >> >> > [<801a6d9c>] get_arg_page+0x34/0xa0 > >> >> > [<801a7394>] copy_string_kernel+0x194/0x2a4 > >> >> > [<801a880c>] kernel_execve+0x11c/0x298 > >> >> > [<800420f4>] call_usermodehelper_exec_async+0x114/0x194 > >> >> > [<80003198>] ret_from_kernel_thread+0x14/0x1c > >> >> > > >> >> > In fact, I also checked vma_pages(bprm->vma) and lo and behold it is set to 1. > >> >> > > >> >> > How is fs/exec.c supposed to handle implied RSS increments that happen > >> >> > due to page faults when discarding the bprm structure? In this case, > >> >> > the bug-generating kernel_execve call never succeeded, it returned -2, > >> >> > but I didn't trace exactly what failed. > >> >> > >> >> Unless I am mistaken any left over pages should be purged by exit_mmap > >> >> which is called by mmput before mmput calls mmdrop. > >> > Good to know. Some more digging and I can say that we hit this error > >> > when trying to unmap PFN 0 (is_zero_pfn(pfn) returns TRUE, > >> > vm_normal_page returns NULL, zap_pte_range does not decrement > >> > MM_ANONPAGES RSS counter). Is my understanding correct that PFN 0 is > >> > usable, but special? Or am I totally off the mark here? > >> > >> It would be good to know if that is the page that get_user_pages_remote > >> returned to copy_string_kernel. The zero page that is always zero, > >> should never be returned when a writable mapping is desired. > > > > Indeed, pfn 0 is returned from get_arg_page: (page is 0x809cf000, > > page_to_pfn(page) is 0) and it is the same page that is being freed and not > > refcounted in mmput/zap_pte_range. Confirmed with good old printk. Also, > > ZERO_PAGE(0)==0x809fc000 -> PFN 5120. > > > > I think I have found the problem though, after much digging and thanks to all > > the information provided. init_zero_pfn() gets called too late (after > > the call to > > is_zero_pfn(0) from mmput returns true), until then zero_pfn == 0, and after, > > zero_pfn == 5120. Boom. > > > > So PFN 0 is special, but only for a little bit, enough for something > > on my system > > to call kernel_execve :) > > > > Question: is my system not supposed to be calling kernel_execve this > > early or does > > init_zero_pfn() need to happen earlier? init_zero_pfn is currently a > > core_initcall. > > Looking quickly it seems that init_zero_pfn() is in mm/memory.c and is > common for both mips and x86. Further it appears init_zero_pfn() has > been that was since 2009 a13ea5b75964 ("mm: reinstate ZERO_PAGE"). > > Given the testing that x86 gets and that nothing like this has been > reported it looks like whatever driver is triggering the kernel_execve > is doing something wrong. > > Because honestly. If the zero page isn't working there is not a chance > that anything in userspace is working so it is clearly much too early. > > I suspect there is some driver that is initialized very early that is > doing something that looks innocuous (like triggering a hotplug event) > and that happens to cause a call_usermode_helper which then calls > kernel_execve. Here is the data that's passed into the very first kernel_execve call: kernel_filename: /sbin/hotplug argv: [/sbin/hotplug, bus] envp: [ACTION=add, DEVPATH=/bus/workqueue, SUBSYSTEM=bus, SEQNUM=4, HOME=/, PATH=/sbin:/bin:/usr/sbin:/usr/bin] It comes from kobject_uevent_env() calling call_usermodehelper_exec() with UMH_NO_WAIT. Trace: [<80340dc8>] kobject_uevent_env+0x7e4/0x7ec [<8033f8b8>] kset_register+0x68/0x88 [<803cf824>] bus_register+0xdc/0x34c [<803cfac8>] subsys_virtual_register+0x34/0x78 [<8086afb0>] wq_sysfs_init+0x1c/0x4c [<80001648>] do_one_initcall+0x50/0x1a8 [<8086503c>] kernel_init_freeable+0x230/0x2c8 [<8066bca0>] kernel_init+0x10/0x100 [<80003038>] ret_from_kernel_thread+0x14/0x1c A bunch of other bus devices are initialized at the same time, but SEQNUM=4 gets to go first for some reason: [ 0.420497] smp: Brought up 1 node, 4 CPUs [ 0.431204] ACTION:add DEVPATH:/bus/platform SUBSYSTEM:bus SEQNUM: 1 [ 0.431249] ACTION:add DEVPATH:/bus/cpu SUBSYSTEM:bus SEQNUM: 2 [ 0.440594] ACTION:add DEVPATH:/bus/container SUBSYSTEM:bus SEQNUM: 3 [ 0.449994] ACTION:add DEVPATH:/bus/workqueue SUBSYSTEM:bus SEQNUM: 4 Since both wq_sysfs_init() and init_zero_pfn() are annotated with core_initcall() is there a race? Maybe there is still an argument for moving init_zero_pfn() to early_initcall()? According to the comment above init_zero_pfn(), "CONFIG_MMU architectures set up ZERO_PAGE in their paging_init()". paging_init() gets called in setup_arch(), which is way before do_pre_smp_initcalls(), so it should work, right? Obviously something that needs to be tested, but are my assumptions correct? FWIW I tested it on my MIPS device and it boots fine and the BUG message is gone. I still don't know why it started appearing on 5.10+, maybe some core_initcalls got added that made the race worse? Ilya