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=-8.4 required=3.0 tests=DKIMWL_WL_MED,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI, SPF_HELO_NONE,SPF_PASS,USER_IN_DEF_DKIM_WL 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 A5042CA9EC0 for ; Mon, 28 Oct 2019 13:09:44 +0000 (UTC) Received: from kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by mail.kernel.org (Postfix) with ESMTP id 57DD920717 for ; Mon, 28 Oct 2019 13:09:44 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=google.com header.i=@google.com header.b="O8sywFJb" DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 57DD920717 Authentication-Results: mail.kernel.org; dmarc=fail (p=reject dis=none) header.from=google.com Authentication-Results: mail.kernel.org; spf=pass smtp.mailfrom=owner-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix) id 02F116B0006; Mon, 28 Oct 2019 09:09:44 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id F211C6B0007; Mon, 28 Oct 2019 09:09:43 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id DE87F6B0008; Mon, 28 Oct 2019 09:09:43 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from forelay.hostedemail.com (smtprelay0057.hostedemail.com [216.40.44.57]) by kanga.kvack.org (Postfix) with ESMTP id BE12E6B0006 for ; Mon, 28 Oct 2019 09:09:43 -0400 (EDT) Received: from smtpin21.hostedemail.com (10.5.19.251.rfc1918.com [10.5.19.251]) by forelay02.hostedemail.com (Postfix) with SMTP id 5B5E67593 for ; Mon, 28 Oct 2019 13:09:43 +0000 (UTC) X-FDA: 76093225446.21.worm86_1a9be5d80ec43 X-HE-Tag: worm86_1a9be5d80ec43 X-Filterd-Recvd-Size: 6734 Received: from mail-wm1-f66.google.com (mail-wm1-f66.google.com [209.85.128.66]) by imf36.hostedemail.com (Postfix) with ESMTP for ; Mon, 28 Oct 2019 13:09:42 +0000 (UTC) Received: by mail-wm1-f66.google.com with SMTP id g7so9388701wmk.4 for ; Mon, 28 Oct 2019 06:09:42 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc:content-transfer-encoding; bh=igTiXIWwLXbwVzyX9UCFvoOrxjA3I8j0lJag9+efkI0=; b=O8sywFJbnp4qey5rqeCAHRBDBoING8v6zU1C8Fn1RARxBAhvqVNBve094USgNcPZuG afjWZZ1xLACaZ+YrbCcN0Ci0XHc1mR3i3FwCoK6spR0GNH0jWL5Uxzzxy/lekyGpzsyn K/Tjy06cXwiViUQL6WgmbQ8SprR8RpZK70xYLYa2FHV9t5s7MSN69QpHI3wcn4+UgIJf NhSXspkakDBPO0lqjUmWtEoZ+JHUBBbilcurqgucinHcxl1+oGqfw24YR6KGWY35kUNH 8SGiv3ERt7qwMZDDpkb/32fJ1sd7XZzWJXvYF44jDkwxLoiFn/fto63uNJpgLwl1rARD XVhA== 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:content-transfer-encoding; bh=igTiXIWwLXbwVzyX9UCFvoOrxjA3I8j0lJag9+efkI0=; b=gxG2IX8bXRXlzxRBt8TbjDjsQ1k/fIqId+aZsxnWScBGRp2PQLNN2m14FBZ1HzJ9h+ wC344U9M/h4D8zZi89FIzNENgLSHNVNO6vxDBCORrMB2COmeQWhKrfG80ctwEMTOsgpZ lTNQnaMSCKb0q3A7TET0+mudEu/9ynjsjoRpLB4AH54TrCytsFbFw77zGeq7hb7A3LWk IQyndrJl4Xv2zG5BFbn6RgHjkmqCuP2/kJmKsN6iIoiAXWIhQmV6BEpovq+QYZ9n7WYb LqFMTbZDPCRcXcjpYlCqUdyLXpi1ZvxO/A05o+yRB/2K0ChAXRXazAPguCi5r0F/M/kT 6A6A== X-Gm-Message-State: APjAAAXuqF1M0YAu0RUC39Rp4TuurejMzjiF1Rtlo0CkDzv1hPZTimwQ B3ZCC+5lcTj+Iz0kPXJEiNJfK2fCE5Eecz7fxKna2w== X-Google-Smtp-Source: APXvYqw/bhmGlrElkXWLzNfTWIcG2mj2QKbLLmUweFv5mruGNPkqqF+jSDoo/dxvyPzO0RP4mADtce7/We4+/XEQ1iY= X-Received: by 2002:a1c:1f03:: with SMTP id f3mr15570611wmf.131.1572268181068; Mon, 28 Oct 2019 06:09:41 -0700 (PDT) MIME-Version: 1.0 References: <20191018094304.37056-1-glider@google.com> <20191018094304.37056-6-glider@google.com> <20191021090925.3dcqukovauqsyw5w@pathway.suse.cz> <20191024124634.hzsn74l7q4nl4mti@pathway.suse.cz> In-Reply-To: <20191024124634.hzsn74l7q4nl4mti@pathway.suse.cz> From: Alexander Potapenko Date: Mon, 28 Oct 2019 14:09:29 +0100 Message-ID: Subject: Re: [PATCH RFC v1 05/26] printk_safe: externalize printk_context To: Petr Mladek Cc: Vegard Nossum , Sergey Senozhatsky , Steven Rostedt , Dmitry Vyukov , Linux Memory Management List Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable 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 Thu, Oct 24, 2019 at 2:46 PM Petr Mladek wrote: > > On Wed 2019-10-23 19:57:39, Alexander Potapenko wrote: > > On Mon, Oct 21, 2019 at 11:09 AM Petr Mladek wrote: > > > > > > On Fri 2019-10-18 11:42:43, glider@google.com wrote: > > > > Petr Mladek suggested we use > > > > this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK > > > > instead of checking the spinlock status in kmsan_pr_err() > > > > > > I would like to understand why the check is needed. > > > > > > My guess is that it prevents a infinite recursion. > > > Is this the case? It might be possible to debug this using > > > trace_printk(). > > This indeed used to prevent infinite recursion, however looks like the > > check isn't needed anymore. > > When I remove it, KMSAN doesn't hang, probably because printk is doing > > a better job at deadlock prevention. > > Great. > > > What I'm seeing now is that e.g. in the following case: > > ptr =3D kmalloc(sizeof(int), GFP_KERNEL); > > if (ptr) > > pr_info("true\n"); > > else > > pr_info("false\n"); > > > > KMSAN detects errors within pr_info(), namely in vprintk_store(). > > If I understand correctly, printing from that point causes printk to > > use the per-cpu buffer, which is flushed once we're done with the > > original printing: > > > > [ 58.984971][ T8390] BUG: KMSAN: uninit-value in > > kmsan_handle_vprintk+0xa0/0xf0 > > ... > > [ 59.061976][ C0] BUG: KMSAN: uninit-value in vsnprintf+0x3276/0x3= 2b0 > > ... > > [ 59.062457][ C0] BUG: KMSAN: uninit-value in format_decode+0x17f/= 0x1900 > > ... > > [ 59.062961][ C0] BUG: KMSAN: uninit-value in format_decode+0x17f/= 0x1900 > > Please, do you have an explanation where the uninitialized values come > from? Is it a false positive? Or is there really a bug how the > printk() parameters are passed? I believe these are true bugs. The problem is, when we pass an uninitialized argument into printk(), KMSAN will report an error every time this uninitialized argument is used. E.g. for an uninitialized format string there'll be at least strlen(fmt) reports in format_decode(), followed by several reports in vsnprintf(). Although these reports seem to be real, printing only the first of them should be more than enough. In the future we'll actually want KMSAN to check every printk() argument (which will require parsing the format string to figure out the arguments' lengths), but disable reports within printk. > > ... > > [ 59.063338][ C0] Lost 6207 message(s)! > > This message comes from report_message_lost(). It means that many > recursive messages did not fit into the limited per-CPU buffers. > > > So it turns out we'd better disable reporting under logbuf_lock, > > otherwise these lost messages will confuse the developers. > > Because the first pr_info() isn't called by KMSAN itself, the tool > > still needs a way to know it's running inside printk. > > OK. Well, I still would like to understand why the recursive messages > are printed at all. Is it a bug in the printk() code or a false positive? > > There should be no recursive messages if we fix the bug or make > some annotations to prevent the false positives. > > That said, I am not completely against disabling the recursive > messages. But it would be pity to hide some real bugs. > > Best Regards, > Petr -- Alexander Potapenko Software Engineer Google Germany GmbH Erika-Mann-Stra=C3=9Fe, 33 80636 M=C3=BCnchen Gesch=C3=A4ftsf=C3=BChrer: Paul Manicle, Halimah DeLaine Prado Registergericht und -nummer: Hamburg, HRB 86891 Sitz der Gesellschaft: Hamburg