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=-7.2 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI, SPF_HELO_NONE,SPF_PASS,USER_AGENT_SANE_1 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 30D03C433DB for ; Sat, 6 Feb 2021 03:11:55 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id F2CF964FA8 for ; Sat, 6 Feb 2021 03:11:54 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S232086AbhBFDLC (ORCPT ); Fri, 5 Feb 2021 22:11:02 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:38830 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231250AbhBFCiZ (ORCPT ); Fri, 5 Feb 2021 21:38:25 -0500 Received: from mail-ej1-x62d.google.com (mail-ej1-x62d.google.com [IPv6:2a00:1450:4864:20::62d]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id D59F0C0698C5 for ; Fri, 5 Feb 2021 14:25:08 -0800 (PST) Received: by mail-ej1-x62d.google.com with SMTP id a9so14567971ejr.2 for ; Fri, 05 Feb 2021 14:25:08 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=chrisdown.name; s=google; h=date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to:user-agent; bh=YrUiRYPqSoGiONt4v52Rv4dRTvj5+zwYfGfPMtX2fW8=; b=qWuHXWS9WZ2Rlrw6nvL0zLQ3kbQ//jj3uRRygrRkQncrRDmTGFdWvpWNaexf3hBsjp 7fEsIoFBmG9ttxCQUHMbf7rp0KmTHTZv7S5bDvN7K2b8Jd2EFu1aEsJ7lNhCUIKsZWVZ /frepM3qEu/o0yEoIIY5WZV4JlPxDnHQiqxI4= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to:user-agent; bh=YrUiRYPqSoGiONt4v52Rv4dRTvj5+zwYfGfPMtX2fW8=; b=GSV1Ee3E3ghKsYMsQp1pKLIT7/ukB9fsBX3oNseJhxQnCFGeiykAPBTn+165lArZc5 +ROgU3olFjcZZDIhuyZuvwC/k+W+mgLFqgHzZLnoFIxK5zc9qmGL6alxuFgrBnsFq9+h 27A8/SeBj6rQxTaN36QcjX56PfG7Gu5VpOC4cu070GtexhgzTZUZsHjB6vf0zZFLrprm jTHPP5b6Bnb2fWaO5ECPu5yyzuUAvyk7MHZsyyaYx1tHLJfNcsafIe5oHKlXvYOPD6o0 c6YLIuInJlYqADNeaJh43oLINtwJ/heKJpzc+SZInQU7ZjbgRIwuze5Uf1QAfHPk0hi+ 06rw== X-Gm-Message-State: AOAM5318xLeWseI4u9sqIa4XzIipX4Ld2wO7OYHb/vfghXKq+17k1Fnw SwKipYrAlSpDxC23fGNCIze/6F/41aOLAFrK X-Google-Smtp-Source: ABdhPJxZFkkecXefURAUd4+eGWoHN9EKiuW85AUEMPCTo7SxpAdnPI7eAEU4qJk52s210NU0lUPmxA== X-Received: by 2002:a17:906:fc4:: with SMTP id c4mr6233854ejk.143.1612563907514; Fri, 05 Feb 2021 14:25:07 -0800 (PST) Received: from localhost ([2620:10d:c093:400::4:66bb]) by smtp.gmail.com with ESMTPSA id u5sm4862228edc.29.2021.02.05.14.25.07 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 05 Feb 2021 14:25:07 -0800 (PST) Date: Fri, 5 Feb 2021 22:25:06 +0000 From: Chris Down To: Petr Mladek Cc: linux-kernel@vger.kernel.org, Sergey Senozhatsky , John Ogness , Johannes Weiner , Andrew Morton , kernel-team@fb.com, Steven Rostedt , Alexey Dobriyan , Greg Kroah-Hartman , Jason Baron , Kees Cook , linux-api@vger.kernel.org Subject: Re: [PATCH] printk: Userspace format enumeration support Message-ID: References: MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii; format=flowed Content-Disposition: inline In-Reply-To: User-Agent: Mutt/2.0.5 (da5e3282) (2021-01-21) Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hi Petr, Thanks for looking over the patch. :-) Petr Mladek writes: >> Most production issues come from unexpected phenomena, and as such >> usually the code in question doesn't have easily usable tracepoints or >> other counters available for the specific problem being mitigated. We >> have a number of lines of monitoring defence against problems in >> production (host metrics, process metrics, service metrics, etc), and >> where it's not feasible to reliably monitor at another level, this kind >> of pragmatic netconsole monitoring is essential. >> >> As you'd expect, monitoring using printk is rather brittle for a number >> of reasons -- most notably that the message might disappear entirely in >> a new version of the kernel, or that the message may change in some way >> that the regex or other classification methods start to silently fail. > >Another is that printk() is not reliable on its own. Messages might >get lost. The size of the log buffer is limited. Deamon reading >/dev/kmsg need not be scheduled in time or often enough. Console >might be slow. The messages are filtered on the console by console_loglevel. This is of course true. We don't use kmsg as the last line of defence for monitoring or remediation, of course, but it would be unwise to not have infrastructure capable of monitoring it. We often need to act quickly when production incidents happen, and often kmsg is the place where those "unexpected" issues are surfaced. It's often much more likely that there is some kmsg log which we can act on in those scenarios than anything else, and even if it's not ideal, in reality, it's typically reliable enough to at least mitigate the problem when dealing with a large fleet of machines :-) >> # Format: ,\0 >> $ perl -p -e 's/\n/\\n/g;s/\0/\n/g' /proc/printk_formats | shuf -n 5 >> vmlinux,6Disabling APIC timer\n >> intel_rapl_common,3intel_rapl_common: Cannot find matching power limit for constraint %d\n >> dm_crypt,3device-mapper: crypt: %s: INTEGRITY AEAD ERROR, sector %llu\n >> mac80211,6%s: AP bug: HT capability missing from AssocResp\n >> vmlinux,3zpool: couldn't create zpool - out of memory\n > >The facility and log level are not well separated from the format string. > >Also this is yet another style how the format is displayed. We already have > > + console/syslog: formated by record_print_text() > + /dev/kmsg: formatted by info_print_ext_header(), msg_print_ext_body(). > + /sys/kernel/debug/dynamic_debug/control > + /sys/kernel/debug/tracing/printk_formats > >We should get some inspiration from the existing interfaces. Sure, I'm not super bound to the format, as long as we have something that can aid those maintaining these systems which monitor printk in identifying that a format was mutated or removed. The module is more or less optional -- it's just intended as a hint about where to look. >But we first should decide what information might be useful: > > + 'facility' should not be needed. All messages should be from > kernel. That's fair enough, it can be omitted. I just didn't want to stray too far from the netconsole format, since we already mostly have it in this format there. My intention is to _not_ deviate from existing interfaces, really, so I'll be happy with any suggested format that will achieve this patch's stated goals, since this kind of data is sorely needed :-) > + is already optinaly added by pr_fmt() to the printed strings > as: pr_fmt(): ... pr_fmts are not consistently used across the kernel, and sometimes differ from the module itself. Many modules don't use it at all, and we also don't have it for pr_cont. Just picking some random examples: % grep -av vmlinux /proc/printk_formats | shuf -n 10 mac80211,6%s: mesh STA %pM switches to channel requiring DFS (%d MHz, width:%d, CF1/2: %d/%d MHz), aborting thinkpad_acpi,c N/Athinkpad_acpi,c %dthinkpad_acpi,5thinkpad_acpi: temperatures (Celsius):thinkpad_acpi,3thinkpad_acpi: Out of memory for LED data i915,6drm/i915 developers can then reassign to the right component if it's not a kernel issue. video,4[Firmware Bug]: _BCQ is used instead of _BQC i915,3gvt: requesting SMI service are MMIO SPTEs. i915,3gvt: invalid tiling mode: %x video,3ACPI: Create sysfs link cec,6cec-%s: duplicate logical address type soundwire_bus,3%s: %s: inconsistent state state %d >> +static int proc_pf_show(struct seq_file *s, void *v) >> +{ >> + const struct printk_fmt_sec *ps = NULL; >> + const char **fptr = NULL; >> + >> + mutex_lock(&printk_fmts_mutex); >> + >> + list_for_each_entry(ps, &printk_fmts_list, list) { >> + const char *mod_name = ps_get_module_name(ps); >> + >> + for (fptr = ps->start; fptr < ps->end; fptr++) { >> + seq_puts(s, mod_name); >> + seq_putc(s, ','); >> + seq_puts(s, *fptr); >> + seq_putc(s, '\0'); >> + } > >You probably should get inspiration from t_show() in trace_printk.c. >It handles newlines, ... > >Or by ddebug_proc_show(). It uses seq_escape(). > >Anyway, there is something wrong at the moment. The output looks fine >with cat. But "less" says that it is a binary format and the output >is a bit messy: Hmm, why should that be a problem? It's intentional that this pretty much just directly replicates the format string passed to printk, since it's easy to write a parser for it: 1. Go up to the comma, take the module 2. Take the facility and level 3. Take the rest up to a \0 as the format 4. Go to 1 I don't mind to have it escaped, but I'm not immediately seeing the benefit. We also don't escape `\0` in (for example) `/proc/pid/cmdline`, since it serves as a good natural delimiter. Thanks for taking the time to review :-) Chris