Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On 2020/05/29 11:04, Sergey Senozhatsky wrote: > You are not going to add pr_debug() all over the kernel, are you? Of course, I'm not planning to add pr_debug() all over the kernel. When I need to print something to consoles, I will use one-time patch (like https://syzkaller.appspot.com/text?tag=Patch=135f254a10 ) for adding custom printk() and turning on some switches for making existing printk() calls work.
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On (20/05/25 19:43), Tetsuo Handa wrote:
> >> On Sun 2020-05-24 23:50:34, Tetsuo Handa wrote:
> >>> syzbot found a NULL pointer dereference bug inside mptcp_recvmsg() due to
> >>> ssock == NULL, but this bug manifested inside selinux_socket_recvmsg()
> >>> because pr_debug() was no-op [1].
> >>>
> >>> pr_debug("fallback-read subflow=%p",
> >>>mptcp_subflow_ctx(ssock->sk));
> >>> copied = sock_recvmsg(ssock, msg, flags);
> >>
> >> The NULL pointer deference was found even without this patch.
> >> This patch would just cause that it will manifest itself on another
> >> place. What is the benefit, please?
>
> It would help localizing the bug in this specific case.
>
> It's not only about %p, even %d can crash kernel or leak sensitive
> info (if it happens after-free/out-of-bounds/uninit). Overall it
> increases code coverage and allows to catch more bugs earlier.
I don't know. Relying on random pr_debug()-s that can be added or
removed any time. oops backtrace should help with that. You are
not going to add pr_debug() all over the kernel, are you?
-ss
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Thu, 2020-05-28 at 14:14 +0200, Petr Mladek wrote:
> On Thu 2020-05-28 20:33:10, Tetsuo Handa wrote:
> > On 2020/05/28 19:59, Petr Mladek wrote:
> > > 2. Add twist into vprintk_store(). In the current, implementation
> > >it would do:
> > >
> > > #if TWIST
> > > return text_len;
> > > #endif
> > >
> > > return log_output(facility, level, lflags,
> > > dict, dictlen, text, text_len);
> >
> > This part could be possible. But
> >
> > > 1. Add twist into ddebug_add_module() and enable all newly added
> > >entries by default. For example, by calling
> > >ddebug_exec_query("*:+p", const char *modname) or what is the syntax.
> > >
> > >This will cause that any pr_devel() variant will always get called.
> >
> > how to handle
> >
> > > > #define no_printk(fmt, ...) \
> > > > ({ \
> > > > if (0) \
> > > > printk(fmt, ##__VA_ARGS__); \
> > > > 0; \
> > > > })
> >
> > part used by e.g. pr_devel() ? Since this macro is not using dynamic debug
> > interface, vprintk_store() will not be called from the beginning. Are you
> > suggesting that we should convert no_printk() to use dynamic debug
> > interface ?
>
> OK, this is one more path that would need special handling. Two paths
> are much better than 15.
A few more:
$ grep-2.5.4 --include=*.[ch] -rP '\if\s*\(\s*0\s*\)\s*\{?\s*\\?\s*no_printk' *
drivers/platform/x86/thinkpad_acpi.c: do { if (0) no_printk(format, ##arg); }
while (0)
fs/ntfs/debug.h:if (0)
\
no_printk(fmt, ##__VA_ARGS__); \
include/linux/net.h:if (0)
\
no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); \
kernel/cred.c: if (0)
\
no_printk("[%-5.5s%5u] " FMT "\n", \
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On 2020/05/28 21:14, Petr Mladek wrote:
>> how to handle
>>
#define no_printk(fmt, ...) \
({ \
if (0) \
printk(fmt, ##__VA_ARGS__); \
0; \
})
>>
>> part used by e.g. pr_devel() ? Since this macro is not using dynamic debug
>> interface, vprintk_store() will not be called from the beginning. Are you
>> suggesting that we should convert no_printk() to use dynamic debug interface
>> ?
>
> OK, this is one more path that would need special handling. Two paths
> are much better than 15.
OK. That can avoid needlessly increasing dynamic debug locations.
But I believe that your suggestion is much worse than 15. ;-(
Let's go back to "Add twist into vprintk_store().". The condition is not as
simple as
#if TWIST
return text_len;
#endif
because we need to check whether the caller wants to print this message or not.
Since we need to print all messages that the caller asked to print, the
condition
needs to be
#if TWIST
if (!this_message_should_be_stored_into_logbuf(arg))
return text_len;
#endif
and where does the "arg" come? It is not as simple as loglevel. Like you said
It might get more complicated if you would actually want to see
pr_debug() messages for a selected module in the fuzzer.
, we want to conditionally store KERN_DEBUG messages into logbuf.
We sometimes don't want to store into logbuf due to ratelimit, due to
dynamic debug. But we DO want to evaluate arguments passed to printk().
Oh, if we try to add twist into vprintk_store(), we will have to modify
all printk() callers in order to pass "arg" only for telling whether we
want to store that messages into logbuf. What a nightmare!
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Thu 2020-05-28 20:33:10, Tetsuo Handa wrote:
> On 2020/05/28 19:59, Petr Mladek wrote:
> > 2. Add twist into vprintk_store(). In the current, implementation
> >it would do:
> >
> > #if TWIST
> > return text_len;
> > #endif
> >
> > return log_output(facility, level, lflags,
> > dict, dictlen, text, text_len);
>
> This part could be possible. But
>
> > 1. Add twist into ddebug_add_module() and enable all newly added
> >entries by default. For example, by calling
> >ddebug_exec_query("*:+p", const char *modname) or what is the syntax.
> >
> >This will cause that any pr_devel() variant will always get called.
>
> how to handle
>
> >> #define no_printk(fmt, ...) \
> >> ({ \
> >> if (0) \
> >> printk(fmt, ##__VA_ARGS__); \
> >> 0; \
> >> })
>
> part used by e.g. pr_devel() ? Since this macro is not using dynamic debug
> interface, vprintk_store() will not be called from the beginning. Are you
> suggesting that we should convert no_printk() to use dynamic debug interface ?
OK, this is one more path that would need special handling. Two paths
are much better than 15.
> I don't know whether enabling only in linux-next makes sense. Since not all
> tests
> are equally done on each git tree, available only in linux-next will not be
> able
> to cover all callers. Just using
> CONFIG_TWIST_ALWAYS_EVALUATE_PRINTK_ARGUMENTS=y
> and CONFIG_DYNAMIC_DEBUG=n is the simplest.
I hope that tests done on linux-next would be enough to trigger some
bugs. If you do not see problems in linux-next then this twist
probably is not worth the effort and code complications.
Best Regards,
Petr
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On 2020/05/28 19:59, Petr Mladek wrote:
> 2. Add twist into vprintk_store(). In the current, implementation
>it would do:
>
> #if TWIST
> return text_len;
> #endif
>
> return log_output(facility, level, lflags,
> dict, dictlen, text, text_len);
This part could be possible. But
> 1. Add twist into ddebug_add_module() and enable all newly added
>entries by default. For example, by calling
>ddebug_exec_query("*:+p", const char *modname) or what is the syntax.
>
>This will cause that any pr_devel() variant will always get called.
how to handle
>> #define no_printk(fmt, ...) \
>> ({ \
>> if (0) \
>> printk(fmt, ##__VA_ARGS__); \
>> 0; \
>> })
part used by e.g. pr_devel() ? Since this macro is not using dynamic debug
interface, vprintk_store() will not be called from the beginning. Are you
suggesting that we should convert no_printk() to use dynamic debug interface ?
I don't know whether enabling only in linux-next makes sense. Since not all
tests
are equally done on each git tree, available only in linux-next will not be able
to cover all callers. Just using CONFIG_TWIST_ALWAYS_EVALUATE_PRINTK_ARGUMENTS=y
and CONFIG_DYNAMIC_DEBUG=n is the simplest.
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Thu 2020-05-28 08:33:37, Tetsuo Handa wrote:
> On 2020/05/28 0:55, Petr Mladek wrote:
> >>> Well, it would be possible to call vsprintf() with NULL buffer. It is
> >>> normally used to calculate the length of the message before it is
> >>> printed. But it also does all the accesses without printing anything.
> >>
> >> OK. I think that redirecting pr_debug() to vsnprintf(NULL, 0) will be
> >> better than modifying dynamic_debug path, for
> >
> > It might get more complicated if you would actually want to see
> > pr_debug() messages for a selected module in the fuzzer.
>
> I don't expect that automated testing can afford selectively enabling
> DYNAMIC_DEBUG_BRANCH(id) conditions. But we could evaluate all arguments
> by calling snprintf(NULL, 0) if the condition to call printk() is false.
>
> > vsprintf(NULL, ) can be called for pr_debug() messages in
> > vprintk_store(). It will be again only a single place for
> > all printk() wrappers.
>
> I couldn't catch what you mean. The problem of pr_debug() is that
> vprintk_store() might not be called because of
>
> #define no_printk(fmt, ...) \
> ({ \
> if (0) \
> printk(fmt, ##__VA_ARGS__); \
> 0; \
> })
>
> #define pr_debug(fmt, ...) \
> no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>
> or
>
> #define __dynamic_func_call(id, fmt, func, ...) do {\
> DEFINE_DYNAMIC_DEBUG_METADATA(id, fmt); \
> if (DYNAMIC_DEBUG_BRANCH(id)) \
> func(, ##__VA_ARGS__); \
> } while (0)
>
> #define _dynamic_func_call(fmt, func, ...) \
> __dynamic_func_call(__UNIQUE_ID(ddebug), fmt, func, ##__VA_ARGS__)
>
> #define dynamic_pr_debug(fmt, ...) \
> _dynamic_func_call(fmt, __dynamic_pr_debug, \
> pr_fmt(fmt), ##__VA_ARGS__)
>
> #define pr_debug(fmt, ...) \
> dynamic_pr_debug(fmt, ##__VA_ARGS__)
That is exactly the problem. Your current patch [1] adds checks
for the CONFIG_TWIST into 15 different locations.
This is perfectly fine for testing in linux-next whether this twist
is worth the effort. But I do not like this as a long term solution.
If the testing shows that it was really helpful and you would want
to get this into Linus' tree. Then I would like to do the twist at different
level:
1. Add twist into ddebug_add_module() and enable all newly added
entries by default. For example, by calling
ddebug_exec_query("*:+p", const char *modname) or what is the syntax.
This will cause that any pr_devel() variant will always get called.
2. Add twist into vprintk_store(). In the current, implementation
it would do:
#if TWIST
return text_len;
#endif
return log_output(facility, level, lflags,
dict, dictlen, text, text_len);
Something similar would need to be done also in printk_safe().
Hot you could ignore this because it would be used only in
very few scenarios.
In the lock_less variant, we would need to format the message
into small buffer on stack to detect the log level from the first
few bytes.
The approach will cause that pr_devel() message will never get really
printed when this TWIST is enabled. But you mention that automatic
testing would not do so anyway.
[1]
https://lore.kernel.org/r/20200528065603.3596-1-penguin-ker...@i-love.sakura.ne.jp
Best Regards,
Petr
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On 2020/05/28 0:55, Petr Mladek wrote:
>>> Well, it would be possible to call vsprintf() with NULL buffer. It is
>>> normally used to calculate the length of the message before it is
>>> printed. But it also does all the accesses without printing anything.
>>
>> OK. I think that redirecting pr_debug() to vsnprintf(NULL, 0) will be
>> better than modifying dynamic_debug path, for
>
> It might get more complicated if you would actually want to see
> pr_debug() messages for a selected module in the fuzzer.
I don't expect that automated testing can afford selectively enabling
DYNAMIC_DEBUG_BRANCH(id) conditions. But we could evaluate all arguments
by calling snprintf(NULL, 0) if the condition to call printk() is false.
> vsprintf(NULL, ) can be called for pr_debug() messages in
> vprintk_store(). It will be again only a single place for
> all printk() wrappers.
I couldn't catch what you mean. The problem of pr_debug() is that
vprintk_store() might not be called because of
#define no_printk(fmt, ...) \
({ \
if (0) \
printk(fmt, ##__VA_ARGS__); \
0; \
})
#define pr_debug(fmt, ...) \
no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
or
#define __dynamic_func_call(id, fmt, func, ...) do {\
DEFINE_DYNAMIC_DEBUG_METADATA(id, fmt); \
if (DYNAMIC_DEBUG_BRANCH(id)) \
func(, ##__VA_ARGS__); \
} while (0)
#define _dynamic_func_call(fmt, func, ...) \
__dynamic_func_call(__UNIQUE_ID(ddebug), fmt, func, ##__VA_ARGS__)
#define dynamic_pr_debug(fmt, ...) \
_dynamic_func_call(fmt, __dynamic_pr_debug, \
pr_fmt(fmt), ##__VA_ARGS__)
#define pr_debug(fmt, ...) \
dynamic_pr_debug(fmt, ##__VA_ARGS__)
. Maybe we can append
else if (IS_BUILTIN(CONFIG_TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK)) \
snprintf(NULL, 0, fmt, ##__VA_ARGS__); \
to no_printk() and __dynamic_func_call().
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Wed 2020-05-27 19:13:38, Tetsuo Handa wrote: > On 2020/05/27 17:37, Petr Mladek wrote: > > On Mon 2020-05-25 19:43:04, Tetsuo Handa wrote: > >> On 2020/05/25 17:42, Petr Mladek wrote: > >>> I see few drawbacks with this patch: > >>> > >>> 1. It will cause adding much more messages into the logbuffer even > >>>though they are not flushed to the console. It might cause that > >>>more important messages will get overridden before they reach > >>>console. They might also make hard to read the full log. > >> > >> Since the user of this twist option will select console loglevel in a way > >> KERN_DEBUG messages are not printed to consoles, KERN_DEBUG messages will > >> be immediately processed (and space for future messages will be reclaimed). > >> Therefore, I don't think that more important messages will get overridden. > > > > This is not fully true. More important messages will still be printed > > to the console. The debug messages will not be skipped before the > > older messages are proceed. > > > > I mean that many debug messages might cause losing more important ones > > before the old important messages are proceed. > > Then, this reasoning will be also applicable to > > [PATCH] printk: Add loglevel for "do not print to consoles". > > in a sense that "don't try to quickly queue a lot of messages" rule. This > concern > cannot be solved even if asynchronous printk() and per console loglevel are > supported someday, and oom_dump_tasks() is not allowed to count on these for > solving the stall problem caused by reporting all OOM victim candidates at > once. Good point. Even the "do_not_print_to_consoles" flag might cause loosing other important messages on consoles. It is because all consoles are handled in a single loop. The asynchronous consoles would use one kthread per console. It would allow to see all messages at least by fast consoles and userspace. The OOM problem will also be solvable with a bigger log buffer. It would all to keep the entire dump until it can be seen on consoles or stored by userspace. The asynchronous consoles will prevent blocking OOM killer which is the primary problem. > >> This twist option might increase possibility of mixing KERN_DEBUG messages > >> and non-KERN_DEBUG messages due to KERN_CONT case. > >> > >> But if these concerns turn out to be a real problem, we can redirect > >> pr_devel()/pr_debug() to simple snprintf() which evaluates arguments > >> but discards the result without storing into the logbuffer. > >> > >>> > >>> 2. Crash inside printk() causes recursive messages. They are currently > >>>printed into the printk_safe() buffers and there is a bigger risk > >>>that they will not reach the console. > >> > >> Currently "static char textbuf[LOG_LINE_MAX];" is "static" because it is > >> used > >> under logbuf_lock. If we remove "static", we can use "char > >> textbuf[LOG_LINE_MAX];" > >> without logbuf_lock. Then, we can bring potentially dangerous-and-slow > >> vscnprintf() > >> in vprintk_store() to earlier stage (and vprintk_store() will need to do > >> simple > >> copy) so that oops in printk() will happen before entering printk-safe > >> context. > >> I think that this change follows a direction which lockless logbuf will > >> want. > > > > No, LOG_LINE_MAX is too big to be allocated on stack. > > We could assign per task_struct buffers and per CPU interrupt context buffers > (like we discussed about how to handle KERN_CONT problem). But managing these > off stack buffers is out of scope for this patch. This is much more complicated than the vsprintf(NULL) approach. > > Well, it would be possible to call vsprintf() with NULL buffer. It is > > normally used to calculate the length of the message before it is > > printed. But it also does all the accesses without printing anything. > > OK. I think that redirecting pr_debug() to vsnprintf(NULL, 0) will be > better than modifying dynamic_debug path, for It might get more complicated if you would actually want to see pr_debug() messages for a selected module in the fuzzer. > >>> Have you tested this patch by the syzcaller with many runs, please? > >>> Did it helped to actually discover more bugs? > >>> Did it really made things easier? > >> > >> syzbot can't test with custom patches. The only way to test this patch is > >> to send to e.g. linux-next.git which syzbot is testing. > > > > OK, we could try this via some test branch that will go into > > linux-next but it would not be scheduled for the next merge window. > > > > For the testing, this patch might be good enough. > > > > For eventual upstreaming, I would prefer to handle this in > > lib/dynamic_debug.c by enabling all entries by default. This > > would solve all DYNAMIC_DEBUG_BRANCH() users at one place. > > since "enabling all entries by default" will redirect pr_debug() calls to > printk(KERN_DEBUG), the "don't try to quickly queue too much messages" above > remains (i.e. it is essentially same
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
>From 3406a1853564618f167a5d0a815f174d2fb295f5 Mon Sep 17 00:00:00 2001 From: Tetsuo Handa Date: Wed, 27 May 2020 22:34:50 +0900 Subject: [PATCH] dev_printk: Explicitly include dynamic_debug.h While printk.h included dynamic_debug.h before pr_debug(), dev_printk.h did not include it before dynamic_dev_dbg(). Include it in dev_printk.h in case future patch touches CONFIG_DYNAMIC_DEBUG case in printk.h . Reported-by: kbuild test robot Signed-off-by: Tetsuo Handa --- include/linux/dev_printk.h | 1 + 1 file changed, 1 insertion(+) diff --git a/include/linux/dev_printk.h b/include/linux/dev_printk.h index 5aad06b4ca7b..69f0b3708eaf 100644 --- a/include/linux/dev_printk.h +++ b/include/linux/dev_printk.h @@ -110,6 +110,7 @@ void _dev_info(const struct device *dev, const char *fmt, ...) _dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__) #if defined(CONFIG_DYNAMIC_DEBUG) +#include #define dev_dbg(dev, fmt, ...) \ dynamic_dev_dbg(dev, dev_fmt(fmt), ##__VA_ARGS__) #elif defined(DEBUG) -- 2.18.2
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
Hi Tetsuo,
I love your patch! Perhaps something to improve:
[auto build test WARNING on next-20200519]
[cannot apply to linus/master linux/master pmladek/for-next v5.7-rc6 v5.7-rc5
v5.7-rc4 v5.7-rc7]
[if your patch is applied to the wrong git tree, please drop us a note to help
improve the system. BTW, we also suggest to use '--base' option to specify the
base tree in git format-patch, please see https://stackoverflow.com/a/37406982]
url:
https://github.com/0day-ci/linux/commits/Tetsuo-Handa/twist-allow-converting-pr_devel-pr_debug-into-printk-KERN_DEBUG/20200524-225318
base:fb57b1fabcb28f358901b2df90abd2b48abc1ca8
config: riscv-allyesconfig (attached as .config)
compiler: riscv64-linux-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
wget
https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O
~/bin/make.cross
chmod +x ~/bin/make.cross
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross
ARCH=riscv
If you fix the issue, kindly add following tag as appropriate
Reported-by: kbuild test robot
All warnings (new ones prefixed by >>, old ones prefixed by <<):
In file included from include/linux/device.h:15,
from include/linux/dmaengine.h:8,
from drivers/i2c/busses/i2c-tegra.c:12:
drivers/i2c/busses/i2c-tegra.c: In function 'tegra_i2c_dma_submit':
include/linux/dev_printk.h:115:2: error: implicit declaration of function
'dynamic_dev_dbg' [-Werror=implicit-function-declaration]
115 | dynamic_dev_dbg(dev, dev_fmt(fmt), ##__VA_ARGS__)
| ^~~
>> drivers/i2c/busses/i2c-tegra.c:377:2: note: in expansion of macro 'dev_dbg'
377 | dev_dbg(i2c_dev->dev, "starting DMA for length: %zun", len);
| ^~~
cc1: some warnings being treated as errors
vim +/dev_dbg +377 drivers/i2c/busses/i2c-tegra.c
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 370
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 371 static int
tegra_i2c_dma_submit(struct tegra_i2c_dev *i2c_dev, size_t len)
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 372 {
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 373 struct
dma_async_tx_descriptor *dma_desc;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 374 enum
dma_transfer_direction dir;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 375 struct dma_chan *chan;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 376
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 @377 dev_dbg(i2c_dev->dev,
"starting DMA for length: %zu\n", len);
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 378
reinit_completion(_dev->dma_complete);
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 379 dir = i2c_dev->msg_read
? DMA_DEV_TO_MEM : DMA_MEM_TO_DEV;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 380 chan =
i2c_dev->msg_read ? i2c_dev->rx_dma_chan : i2c_dev->tx_dma_chan;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 381 dma_desc =
dmaengine_prep_slave_single(chan, i2c_dev->dma_phys,
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 382
len, dir, DMA_PREP_INTERRUPT |
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 383
DMA_CTRL_ACK);
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 384 if (!dma_desc) {
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 385
dev_err(i2c_dev->dev, "failed to get DMA descriptor\n");
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 386 return -EINVAL;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 387 }
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 388
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 389 dma_desc->callback =
tegra_i2c_dma_complete;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 390
dma_desc->callback_param = i2c_dev;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 391
dmaengine_submit(dma_desc);
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 392
dma_async_issue_pending(chan);
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 393 return 0;
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 394 }
86c92b9965ff175 Sowjanya Komatineni 2019-02-12 395
:: The code at line 377 was first introduced by commit
:: 86c92b9965ff1758952cd0d6c5f19f291eea i2c: tegra: Add DMA support
:: TO: Sowjanya Komatineni
:: CC: Wolfram Sang
---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-...@lists.01.org
.config.gz
Description: application/gzip
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On 2020/05/27 17:37, Petr Mladek wrote: > On Mon 2020-05-25 19:43:04, Tetsuo Handa wrote: >> On 2020/05/25 17:42, Petr Mladek wrote: >>> I see few drawbacks with this patch: >>> >>> 1. It will cause adding much more messages into the logbuffer even >>>though they are not flushed to the console. It might cause that >>>more important messages will get overridden before they reach >>>console. They might also make hard to read the full log. >> >> Since the user of this twist option will select console loglevel in a way >> KERN_DEBUG messages are not printed to consoles, KERN_DEBUG messages will >> be immediately processed (and space for future messages will be reclaimed). >> Therefore, I don't think that more important messages will get overridden. > > This is not fully true. More important messages will still be printed > to the console. The debug messages will not be skipped before the > older messages are proceed. > > I mean that many debug messages might cause losing more important ones > before the old important messages are proceed. Then, this reasoning will be also applicable to [PATCH] printk: Add loglevel for "do not print to consoles". in a sense that "don't try to quickly queue a lot of messages" rule. This concern cannot be solved even if asynchronous printk() and per console loglevel are supported someday, and oom_dump_tasks() is not allowed to count on these for solving the stall problem caused by reporting all OOM victim candidates at once. > > >> This twist option might increase possibility of mixing KERN_DEBUG messages >> and non-KERN_DEBUG messages due to KERN_CONT case. >> >> But if these concerns turn out to be a real problem, we can redirect >> pr_devel()/pr_debug() to simple snprintf() which evaluates arguments >> but discards the result without storing into the logbuffer. >> >>> >>> 2. Crash inside printk() causes recursive messages. They are currently >>>printed into the printk_safe() buffers and there is a bigger risk >>>that they will not reach the console. >> >> Currently "static char textbuf[LOG_LINE_MAX];" is "static" because it is used >> under logbuf_lock. If we remove "static", we can use "char >> textbuf[LOG_LINE_MAX];" >> without logbuf_lock. Then, we can bring potentially dangerous-and-slow >> vscnprintf() >> in vprintk_store() to earlier stage (and vprintk_store() will need to do >> simple >> copy) so that oops in printk() will happen before entering printk-safe >> context. >> I think that this change follows a direction which lockless logbuf will want. > > No, LOG_LINE_MAX is too big to be allocated on stack. We could assign per task_struct buffers and per CPU interrupt context buffers (like we discussed about how to handle KERN_CONT problem). But managing these off stack buffers is out of scope for this patch. > > Well, it would be possible to call vsprintf() with NULL buffer. It is > normally used to calculate the length of the message before it is > printed. But it also does all the accesses without printing anything. OK. I think that redirecting pr_debug() to vsnprintf(NULL, 0) will be better than modifying dynamic_debug path, for > > >>> Have you tested this patch by the syzcaller with many runs, please? >>> Did it helped to actually discover more bugs? >>> Did it really made things easier? >> >> syzbot can't test with custom patches. The only way to test this patch is >> to send to e.g. linux-next.git which syzbot is testing. > > OK, we could try this via some test branch that will go into > linux-next but it would not be scheduled for the next merge window. > > For the testing, this patch might be good enough. > > For eventual upstreaming, I would prefer to handle this in > lib/dynamic_debug.c by enabling all entries by default. This > would solve all DYNAMIC_DEBUG_BRANCH() users at one place. since "enabling all entries by default" will redirect pr_debug() calls to printk(KERN_DEBUG), the "don't try to quickly queue too much messages" above remains (i.e. it is essentially same with what this patch is doing). > > Anyway, I would like to see a proof that it really helped to find > some bugs an easier way before upstreaming. > > Best Regards, > Petr >
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
Hi Tetsuo,
I love your patch! Perhaps something to improve:
[auto build test WARNING on next-20200519]
[cannot apply to linus/master linux/master pmladek/for-next v5.7-rc6 v5.7-rc5
v5.7-rc4 v5.7-rc7]
[if your patch is applied to the wrong git tree, please drop us a note to help
improve the system. BTW, we also suggest to use '--base' option to specify the
base tree in git format-patch, please see https://stackoverflow.com/a/37406982]
url:
https://github.com/0day-ci/linux/commits/Tetsuo-Handa/twist-allow-converting-pr_devel-pr_debug-into-printk-KERN_DEBUG/20200524-225318
base:fb57b1fabcb28f358901b2df90abd2b48abc1ca8
config: powerpc-allmodconfig (attached as .config)
compiler: powerpc64-linux-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
wget
https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O
~/bin/make.cross
chmod +x ~/bin/make.cross
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross
ARCH=powerpc
If you fix the issue, kindly add following tag as appropriate
Reported-by: kbuild test robot
All warnings (new ones prefixed by >>, old ones prefixed by <<):
In file included from include/linux/device.h:15,
from include/linux/acpi.h:15,
from include/linux/i2c.h:13,
from drivers/iio/adc/ina2xx-adc.c:24:
drivers/iio/adc/ina2xx-adc.c: In function 'ina2xx_buffer_enable':
include/linux/dev_printk.h:115:2: error: implicit declaration of function
'dynamic_dev_dbg' [-Werror=implicit-function-declaration]
115 | dynamic_dev_dbg(dev, dev_fmt(fmt), ##__VA_ARGS__)
| ^~~
>> drivers/iio/adc/ina2xx-adc.c:834:2: note: in expansion of macro 'dev_dbg'
834 | dev_dbg(_dev->dev, "Enabling buffer w/ scan_mask %02x, freq = %d,
avg =%un",
| ^~~
cc1: some warnings being treated as errors
vim +/dev_dbg +834 drivers/iio/adc/ina2xx-adc.c
c43a102e67db99c Marc Titinger 2015-12-07 827
c43a102e67db99c Marc Titinger 2015-12-07 828 static int
ina2xx_buffer_enable(struct iio_dev *indio_dev)
c43a102e67db99c Marc Titinger 2015-12-07 829 {
c43a102e67db99c Marc Titinger 2015-12-07 830 struct ina2xx_chip_info
*chip = iio_priv(indio_dev);
c43a102e67db99c Marc Titinger 2015-12-07 831 unsigned int
sampling_us = SAMPLING_PERIOD(chip);
7d6cd21d82bacab Akinobu Mita2018-06-25 832 struct task_struct
*task;
c43a102e67db99c Marc Titinger 2015-12-07 833
1961bce76452938 Andrew F. Davis 2016-02-24 @834
dev_dbg(_dev->dev, "Enabling buffer w/ scan_mask %02x, freq = %d, avg
=%u\n",
c43a102e67db99c Marc Titinger 2015-12-07 835 (unsigned
int)(*indio_dev->active_scan_mask),
c43a102e67db99c Marc Titinger 2015-12-07 836 100 /
sampling_us, chip->avg);
c43a102e67db99c Marc Titinger 2015-12-07 837
1961bce76452938 Andrew F. Davis 2016-02-24 838
dev_dbg(_dev->dev, "Expected work period: %u us\n", sampling_us);
1961bce76452938 Andrew F. Davis 2016-02-24 839
dev_dbg(_dev->dev, "Async readout mode: %d\n",
1961bce76452938 Andrew F. Davis 2016-02-24 840
chip->allow_async_readout);
c43a102e67db99c Marc Titinger 2015-12-07 841
7d6cd21d82bacab Akinobu Mita2018-06-25 842 task =
kthread_create(ina2xx_capture_thread, (void *)indio_dev,
46294cd948d530d Marc Titinger 2015-12-11 843
"%s:%d-%uus", indio_dev->name, indio_dev->id,
46294cd948d530d Marc Titinger 2015-12-11 844
sampling_us);
7d6cd21d82bacab Akinobu Mita2018-06-25 845 if (IS_ERR(task))
7d6cd21d82bacab Akinobu Mita2018-06-25 846 return
PTR_ERR(task);
7d6cd21d82bacab Akinobu Mita2018-06-25 847
7d6cd21d82bacab Akinobu Mita2018-06-25 848 get_task_struct(task);
7d6cd21d82bacab Akinobu Mita2018-06-25 849 wake_up_process(task);
7d6cd21d82bacab Akinobu Mita2018-06-25 850 chip->task = task;
c43a102e67db99c Marc Titinger 2015-12-07 851
7d6cd21d82bacab Akinobu Mita2018-06-25 852 return 0;
c43a102e67db99c Marc Titinger 2015-12-07 853 }
c43a102e67db99c Marc Titinger 2015-12-07 854
:: The code at line 834 was first introduced by commit
:: 1961bce76452938eed8f797b7d96ab5f3c611525 iio: ina2xx: Remove
trace_printk debug statments
:: TO: Andrew F. Davis
:: CC: Jonathan Cameron
---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-...@lists.01.org
.config.gz
Description: application/gzip
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Mon 2020-05-25 19:43:04, Tetsuo Handa wrote: > On 2020/05/25 17:42, Petr Mladek wrote: > > I see few drawbacks with this patch: > > > > 1. It will cause adding much more messages into the logbuffer even > >though they are not flushed to the console. It might cause that > >more important messages will get overridden before they reach > >console. They might also make hard to read the full log. > > Since the user of this twist option will select console loglevel in a way > KERN_DEBUG messages are not printed to consoles, KERN_DEBUG messages will > be immediately processed (and space for future messages will be reclaimed). > Therefore, I don't think that more important messages will get overridden. This is not fully true. More important messages will still be printed to the console. The debug messages will not be skipped before the older messages are proceed. I mean that many debug messages might cause losing more important ones before the old important messages are proceed. > This twist option might increase possibility of mixing KERN_DEBUG messages > and non-KERN_DEBUG messages due to KERN_CONT case. > > But if these concerns turn out to be a real problem, we can redirect > pr_devel()/pr_debug() to simple snprintf() which evaluates arguments > but discards the result without storing into the logbuffer. > > > > > 2. Crash inside printk() causes recursive messages. They are currently > >printed into the printk_safe() buffers and there is a bigger risk > >that they will not reach the console. > > Currently "static char textbuf[LOG_LINE_MAX];" is "static" because it is used > under logbuf_lock. If we remove "static", we can use "char > textbuf[LOG_LINE_MAX];" > without logbuf_lock. Then, we can bring potentially dangerous-and-slow > vscnprintf() > in vprintk_store() to earlier stage (and vprintk_store() will need to do > simple > copy) so that oops in printk() will happen before entering printk-safe > context. > I think that this change follows a direction which lockless logbuf will want. No, LOG_LINE_MAX is too big to be allocated on stack. Well, it would be possible to call vsprintf() with NULL buffer. It is normally used to calculate the length of the message before it is printed. But it also does all the accesses without printing anything. > > Have you tested this patch by the syzcaller with many runs, please? > > Did it helped to actually discover more bugs? > > Did it really made things easier? > > syzbot can't test with custom patches. The only way to test this patch is > to send to e.g. linux-next.git which syzbot is testing. OK, we could try this via some test branch that will go into linux-next but it would not be scheduled for the next merge window. For the testing, this patch might be good enough. For eventual upstreaming, I would prefer to handle this in lib/dynamic_debug.c by enabling all entries by default. This would solve all DYNAMIC_DEBUG_BRANCH() users at one place. Anyway, I would like to see a proof that it really helped to find some bugs an easier way before upstreaming. Best Regards, Petr
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On 2020/05/25 17:42, Petr Mladek wrote:
> I see few drawbacks with this patch:
>
> 1. It will cause adding much more messages into the logbuffer even
>though they are not flushed to the console. It might cause that
>more important messages will get overridden before they reach
>console. They might also make hard to read the full log.
Since the user of this twist option will select console loglevel in a way
KERN_DEBUG messages are not printed to consoles, KERN_DEBUG messages will
be immediately processed (and space for future messages will be reclaimed).
Therefore, I don't think that more important messages will get overridden.
This twist option might increase possibility of mixing KERN_DEBUG messages
and non-KERN_DEBUG messages due to KERN_CONT case.
But if these concerns turn out to be a real problem, we can redirect
pr_devel()/pr_debug() to simple snprintf() which evaluates arguments
but discards the result without storing into the logbuffer.
>
> 2. Crash inside printk() causes recursive messages. They are currently
>printed into the printk_safe() buffers and there is a bigger risk
>that they will not reach the console.
Currently "static char textbuf[LOG_LINE_MAX];" is "static" because it is used
under logbuf_lock. If we remove "static", we can use "char
textbuf[LOG_LINE_MAX];"
without logbuf_lock. Then, we can bring potentially dangerous-and-slow
vscnprintf()
in vprintk_store() to earlier stage (and vprintk_store() will need to do simple
copy) so that oops in printk() will happen before entering printk-safe context.
I think that this change follows a direction which lockless logbuf will want.
>
> 3. pr_debug() messages are not printed by default. It is possible that
>nobody used them for ages. You might get many errors in less
>maintained code instead in the really used one. I mean that you
>will get more noise with less gain.
Given that potentially dangerous-and-slow vscnprintf() is done outside of
printk-safe context, we can get more test coverage without difficult things.
>
>
> Have you tested this patch by the syzcaller with many runs, please?
> Did it helped to actually discover more bugs?
> Did it really made things easier?
syzbot can't test with custom patches. The only way to test this patch is
to send to e.g. linux-next.git which syzbot is testing.
>
> I am not able to judge usefulness without more data. My intuition
> tells me that we should keep the number of syzcaller-related twists
> as small as possible. Otherwise, syscaller will diverge more and
> more from reality.
The twist options are not specific to syzkaller. Anyone can selectively
enable the twist options.
On 2020/05/25 18:11, Sergey Senozhatsky wrote:
> On (20/05/25 10:42), Petr Mladek wrote:
>> On Sun 2020-05-24 23:50:34, Tetsuo Handa wrote:
>>> syzbot found a NULL pointer dereference bug inside mptcp_recvmsg() due to
>>> ssock == NULL, but this bug manifested inside selinux_socket_recvmsg()
>>> because pr_debug() was no-op [1].
>>>
>>> pr_debug("fallback-read subflow=%p",
>>>mptcp_subflow_ctx(ssock->sk));
>>> copied = sock_recvmsg(ssock, msg, flags);
>>
>> The NULL pointer deference was found even without this patch.
>> This patch would just cause that it will manifest itself on another
>> place. What is the benefit, please?
It would help localizing the bug in this specific case.
It's not only about %p, even %d can crash kernel or leak sensitive
info (if it happens after-free/out-of-bounds/uninit). Overall it
increases code coverage and allows to catch more bugs earlier.
>
> Right, I don't get this patch. A NULL-deref is still a NULL pointer deref.
> pr_debug() will fault reading one byte from the address and print something
> like "fallback-read subflow=(efault)" to printk-safe buffer, but then
> sock_recvmsg() is still going to do its thing.
Since this NULL pointer dereference already happens before calling pr_debug(),
we won't store "fallback-read subflow=(efault)" to printk-safe buffer.
Just evaluating pr_devel()/pr_debug() arguments would help finding some bugs.
Again, we can change this twist option to redirect pr_devel()/pr_debug() to
simple snprintf() which evaluates arguments but discards the result without
storing into the logbuffer.
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On (20/05/25 10:42), Petr Mladek wrote:
> On Sun 2020-05-24 23:50:34, Tetsuo Handa wrote:
> > syzbot found a NULL pointer dereference bug inside mptcp_recvmsg() due to
> > ssock == NULL, but this bug manifested inside selinux_socket_recvmsg()
> > because pr_debug() was no-op [1].
> >
> > pr_debug("fallback-read subflow=%p",
> >mptcp_subflow_ctx(ssock->sk));
> > copied = sock_recvmsg(ssock, msg, flags);
>
> The NULL pointer deference was found even without this patch.
> This patch would just cause that it will manifest itself on another
> place. What is the benefit, please?
Right, I don't get this patch. A NULL-deref is still a NULL pointer deref.
pr_debug() will fault reading one byte from the address and print something
like "fallback-read subflow=(efault)" to printk-safe buffer, but then
sock_recvmsg() is still going to do its thing.
-ss
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Sun 2020-05-24 23:50:34, Tetsuo Handa wrote:
> syzbot found a NULL pointer dereference bug inside mptcp_recvmsg() due to
> ssock == NULL, but this bug manifested inside selinux_socket_recvmsg()
> because pr_debug() was no-op [1].
>
> pr_debug("fallback-read subflow=%p",
>mptcp_subflow_ctx(ssock->sk));
> copied = sock_recvmsg(ssock, msg, flags);
The NULL pointer deference was found even without this patch.
This patch would just cause that it will manifest itself on another
place. What is the benefit, please?
> Since console loglevel used by syzkaller will not print KERN_DEBUG
> messages to consoles, always evaluating pr_devel()/pr_debug() messages
> will not cause too much console output. Thus, let's allow fuzzers to
> always evaluate pr_devel()/pr_debug() messages.
I see few drawbacks with this patch:
1. It will cause adding much more messages into the logbuffer even
though they are not flushed to the console. It might cause that
more important messages will get overridden before they reach
console. They might also make hard to read the full log.
2. Crash inside printk() causes recursive messages. They are currently
printed into the printk_safe() buffers and there is a bigger risk
that they will not reach the console.
3. pr_debug() messages are not printed by default. It is possible that
nobody used them for ages. You might get many errors in less
maintained code instead in the really used one. I mean that you
will get more noise with less gain.
Have you tested this patch by the syzcaller with many runs, please?
Did it helped to actually discover more bugs?
Did it really made things easier?
I am not able to judge usefulness without more data. My intuition
tells me that we should keep the number of syzcaller-related twists
as small as possible. Otherwise, syscaller will diverge more and
more from reality.
Best Regards,
Petr
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Mon, May 25, 2020 at 8:07 AM Joe Perches wrote: > > On Mon, 2020-05-25 at 14:03 +0900, Tetsuo Handa wrote: > > On 2020/05/25 4:18, Ondrej Mosnacek wrote: > > > I'm also not sure if this is really worth it... It would help localize > > > the bug in this specific case, but there is nothing systematic about > > > it. Are there that many debug print statements that dereference > > > pointers that are later passed to functions, but not dereferenced > > > otherwise? Maybe yes, but it seems to be quite an optimistic > > > assumption... I don't consider it such a big problem that a bug in > > > function X only manifests itself deeper in the callchain. There will > > > always be such bugs, no matter how many moles you whack. > > > > There are about 1400 pr_debug() callers. About 1000 pr_debug() callers seem > > to pass plain '%p' (which is now likely useless for debugging purpose due to > > default ptr_to_id() conversion inside pointer()), and about 400 pr_debug() > > callers seem to pass '%p[a-zA-Z]' (which does some kind of dereference > > inside > > pointer()). Thus, we might find some bugs by evaluating '%p[a-zA-Z]'. > > > > > > > > On Sun, May 24, 2020 at 7:38 PM Joe Perches wrote: > > > While I think this is rather unnecessary, > > > what about dev_dbg/netdev_dbg/netif_dbg et al ? > > > > Maybe a good idea, for there are about 24000 *dev_dbg() callers, and > > 479 callers pass '%p[a-zA-Z]'. But we can defer to another patch, in > > case this patch finds crashes before fuzz testing process starts. > > There are a bunch more than that. > Some use other macros, some are functions. I think this is a good idea overall and I don't mind enabling it on syzbot. It's not only about %p, even %d can crash kernel or leak sensitive info (if it happens after-free/out-of-bounds/uninit). Overall it increases code coverage and allows to catch more bugs earlier. That was the reason for enabling dynamic debug, but I wasn't aware that debug level is not included.
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Mon, 2020-05-25 at 14:03 +0900, Tetsuo Handa wrote:
> On 2020/05/25 4:18, Ondrej Mosnacek wrote:
> > I'm also not sure if this is really worth it... It would help localize
> > the bug in this specific case, but there is nothing systematic about
> > it. Are there that many debug print statements that dereference
> > pointers that are later passed to functions, but not dereferenced
> > otherwise? Maybe yes, but it seems to be quite an optimistic
> > assumption... I don't consider it such a big problem that a bug in
> > function X only manifests itself deeper in the callchain. There will
> > always be such bugs, no matter how many moles you whack.
>
> There are about 1400 pr_debug() callers. About 1000 pr_debug() callers seem
> to pass plain '%p' (which is now likely useless for debugging purpose due to
> default ptr_to_id() conversion inside pointer()), and about 400 pr_debug()
> callers seem to pass '%p[a-zA-Z]' (which does some kind of dereference inside
> pointer()). Thus, we might find some bugs by evaluating '%p[a-zA-Z]'.
>
>
>
> On Sun, May 24, 2020 at 7:38 PM Joe Perches wrote:
> > While I think this is rather unnecessary,
> > what about dev_dbg/netdev_dbg/netif_dbg et al ?
>
> Maybe a good idea, for there are about 24000 *dev_dbg() callers, and
> 479 callers pass '%p[a-zA-Z]'. But we can defer to another patch, in
> case this patch finds crashes before fuzz testing process starts.
There are a bunch more than that.
Some use other macros, some are functions.
$ grep-2.5.4 --include=*.[ch] -n -rP
'\w+_dbg\s*\((?:[^,"]+,){0,3}\s*"[^"]+%p\w+\b[^"]*"' * | \
perl -e 'local $/; while (<>) { s/\n\s+/ /g; print; }' | \
grep -o -P '\w+_dbg' | \
sort | uniq -c | sort -rn
415 dev_dbg
116 netdev_dbg
100 batadv_dbg
80 ath10k_dbg
53 mwifiex_dbg
49 ath11k_dbg
29 brcmf_dbg
28 ath_dbg
26 ht_dbg
20 ath6kl_dbg
17 wcn36xx_dbg
15 netif_dbg
15 cifs_dbg
14 tdls_dbg
13 ibss_dbg
11 mpl_dbg
10 memblock_dbg
10 bt_dev_dbg
9 ps_dbg
8 wiphy_dbg
8 mps_dbg
8 mlme_dbg
8 mhwmp_dbg
8 ipoib_dbg
7 sta_dbg
7 slave_dbg
7 pci_dbg
7 ibdev_dbg
6 mpath_dbg
6 en_dbg
6 drm_dbg
5 usnic_dbg
5 mlx5_core_dbg
4 vin_dbg
4 msync_dbg
3 rsi_dbg
3 cal_dbg
2 v4l2_dbg
2 siw_dbg
2 sdata_dbg
2 ocb_dbg
2 musb_dbg
2 hw_dbg
2 eeh_edev_dbg
2 cifs_server_dbg
2 at76_dbg
1 rt2x00_eeprom_dbg
1 pnp_dbg
1 mthca_dbg
1 mlx5_ib_dbg
1 mlx4_dbg
1 isp_dbg
1 gfs2_print_dbg
1 erofs_dbg
1 dynamic_drbd_dbg
1 ctx_dbg
1 cs89_dbg
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On 2020/05/25 4:18, Ondrej Mosnacek wrote: > I'm also not sure if this is really worth it... It would help localize > the bug in this specific case, but there is nothing systematic about > it. Are there that many debug print statements that dereference > pointers that are later passed to functions, but not dereferenced > otherwise? Maybe yes, but it seems to be quite an optimistic > assumption... I don't consider it such a big problem that a bug in > function X only manifests itself deeper in the callchain. There will > always be such bugs, no matter how many moles you whack. There are about 1400 pr_debug() callers. About 1000 pr_debug() callers seem to pass plain '%p' (which is now likely useless for debugging purpose due to default ptr_to_id() conversion inside pointer()), and about 400 pr_debug() callers seem to pass '%p[a-zA-Z]' (which does some kind of dereference inside pointer()). Thus, we might find some bugs by evaluating '%p[a-zA-Z]'. On Sun, May 24, 2020 at 7:38 PM Joe Perches wrote: > While I think this is rather unnecessary, > what about dev_dbg/netdev_dbg/netif_dbg et al ? Maybe a good idea, for there are about 24000 *dev_dbg() callers, and 479 callers pass '%p[a-zA-Z]'. But we can defer to another patch, in case this patch finds crashes before fuzz testing process starts.
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Sun, May 24, 2020 at 7:38 PM Joe Perches wrote:
> On Sun, 2020-05-24 at 23:50 +0900, Tetsuo Handa wrote:
> > syzbot found a NULL pointer dereference bug inside mptcp_recvmsg() due to
> > ssock == NULL, but this bug manifested inside selinux_socket_recvmsg()
> > because pr_debug() was no-op [1].
> >
> > pr_debug("fallback-read subflow=%p",
> >mptcp_subflow_ctx(ssock->sk));
> > copied = sock_recvmsg(ssock, msg, flags);
>
> > Since console loglevel used by syzkaller will not print KERN_DEBUG
> > messages to consoles, always evaluating pr_devel()/pr_debug() messages
> > will not cause too much console output. Thus, let's allow fuzzers to
> > always evaluate pr_devel()/pr_debug() messages.
>
> While I think this is rather unnecessary,
> what about dev_dbg/netdev_dbg/netif_dbg et al ?
I'm also not sure if this is really worth it... It would help localize
the bug in this specific case, but there is nothing systematic about
it. Are there that many debug print statements that dereference
pointers that are later passed to functions, but not dereferenced
otherwise? Maybe yes, but it seems to be quite an optimistic
assumption... I don't consider it such a big problem that a bug in
function X only manifests itself deeper in the callchain. There will
always be such bugs, no matter how many moles you whack.
That said, I'm not strongly opposed to the change either, I just
wanted to state my opinion in case my reply to the syzbot report [1]
gave the impression that I considered the "misattribution" as
something that needs to be fixed :)
[1]
https://lore.kernel.org/selinux/CAFqZXNvf+oJs9u4H97u7=jtl2wo_hkf4nzdzjld7tnc_j0k...@mail.gmail.com/
--
Ondrej Mosnacek
Software Engineer, Security Technologies
Red Hat, Inc.
Re: [PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
On Sun, 2020-05-24 at 23:50 +0900, Tetsuo Handa wrote:
> syzbot found a NULL pointer dereference bug inside mptcp_recvmsg() due to
> ssock == NULL, but this bug manifested inside selinux_socket_recvmsg()
> because pr_debug() was no-op [1].
>
> pr_debug("fallback-read subflow=%p",
>mptcp_subflow_ctx(ssock->sk));
> copied = sock_recvmsg(ssock, msg, flags);
> Since console loglevel used by syzkaller will not print KERN_DEBUG
> messages to consoles, always evaluating pr_devel()/pr_debug() messages
> will not cause too much console output. Thus, let's allow fuzzers to
> always evaluate pr_devel()/pr_debug() messages.
While I think this is rather unnecessary,
what about dev_dbg/netdev_dbg/netif_dbg et al ?
[PATCH] twist: allow converting pr_devel()/pr_debug() into printk(KERN_DEBUG)
syzbot found a NULL pointer dereference bug inside mptcp_recvmsg() due to
ssock == NULL, but this bug manifested inside selinux_socket_recvmsg()
because pr_debug() was no-op [1].
pr_debug("fallback-read subflow=%p",
mptcp_subflow_ctx(ssock->sk));
copied = sock_recvmsg(ssock, msg, flags);
Since console loglevel used by syzkaller will not print KERN_DEBUG
messages to consoles, always evaluating pr_devel()/pr_debug() messages
will not cause too much console output. Thus, let's allow fuzzers to
always evaluate pr_devel()/pr_debug() messages.
[1]
https://syzkaller.appspot.com/bug?id=12be9aa373be9d8727cdd172f190de39528a413a
Signed-off-by: Tetsuo Handa
Cc: Petr Mladek
Cc: Sergey Senozhatsky
Cc: Steven Rostedt
Cc: Ondrej Mosnacek
Cc: Dmitry Vyukov
---
include/linux/printk.h | 25 ++---
lib/Kconfig.twist | 10 ++
2 files changed, 28 insertions(+), 7 deletions(-)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 38beb97e7018..2562ffb438ed 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -389,7 +389,7 @@ extern int kptr_restrict;
*
* It uses pr_fmt() to generate the format string.
*/
-#ifdef DEBUG
+#if defined(DEBUG) || defined(CONFIG_TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK)
#define pr_devel(fmt, ...) \
printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
@@ -399,7 +399,10 @@ extern int kptr_restrict;
/* If you are writing a driver, please use dev_dbg instead */
-#if defined(CONFIG_DYNAMIC_DEBUG) || \
+#if defined(CONFIG_TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK)
+#define pr_debug(fmt, ...) \
+ printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
+#elif defined(CONFIG_DYNAMIC_DEBUG) || \
(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
#include
@@ -476,7 +479,7 @@ extern int kptr_restrict;
#define pr_cont_once(fmt, ...) \
printk_once(KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
-#if defined(DEBUG)
+#if defined(DEBUG) || defined(CONFIG_TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK)
#define pr_devel_once(fmt, ...)\
printk_once(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
@@ -485,7 +488,7 @@ extern int kptr_restrict;
#endif
/* If you are writing a driver, please use dev_dbg instead */
-#if defined(DEBUG)
+#if defined(DEBUG) || defined(CONFIG_TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK)
#define pr_debug_once(fmt, ...)\
printk_once(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
@@ -528,7 +531,7 @@ extern int kptr_restrict;
printk_ratelimited(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
/* no pr_cont_ratelimited, don't do that... */
-#if defined(DEBUG)
+#if defined(DEBUG) || defined(CONFIG_TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK)
#define pr_devel_ratelimited(fmt, ...) \
printk_ratelimited(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
@@ -537,7 +540,10 @@ extern int kptr_restrict;
#endif
/* If you are writing a driver, please use dev_dbg instead */
-#if defined(CONFIG_DYNAMIC_DEBUG) || \
+#if defined(CONFIG_TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK)
+#define pr_debug_ratelimited(fmt, ...) \
+ printk_ratelimited(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
+#elif defined(CONFIG_DYNAMIC_DEBUG) || \
(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
/* descriptor check is first to prevent flooding with "callbacks suppressed" */
#define pr_debug_ratelimited(fmt, ...) \
@@ -585,7 +591,12 @@ static inline void print_hex_dump_bytes(const char
*prefix_str, int prefix_type,
#endif
-#if defined(CONFIG_DYNAMIC_DEBUG) || \
+#if defined(CONFIG_TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK)
+#define print_hex_dump_debug(prefix_str, prefix_type, rowsize, \
+groupsize, buf, len, ascii)\
+ print_hex_dump(KERN_DEBUG, prefix_str, prefix_type, rowsize,\
+ groupsize, buf, len, ascii)
+#elif defined(CONFIG_DYNAMIC_DEBUG) || \
(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
#define print_hex_dump_debug(prefix_str, prefix_type, rowsize, \
groupsize, buf, len, ascii)\
diff --git a/lib/Kconfig.twist b/lib/Kconfig.twist
index f20e0d003581..710202f4b15d 100644
--- a/lib/Kconfig.twist
+++ b/lib/Kconfig.twist
@@ -12,10 +12,20 @@ if TWIST_KERNEL_BEHAVIOR
config TWIST_FOR_SYZKALLER_TESTING
bool "Select all twist options suitable for syzkaller testing"
+ select TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK
select TWIST_DISABLE_KBD_K_SPEC_HANDLER
help
Say N unless you are building kernels for syzkaller's testing.
+config TWIST_ALWAYS_EVALUATE_DEBUG_PRINTK
+ bool "Always evaluate pr_devel() and pr_debug()"
+ help
+When pr_devel()/pr_debug() are no-op, only format string is checked
+
