Re: [PATCH] printk/console: Check consistent sequence number when handling race in console_unlock()

From: kernel test robot
Date: Tue Jun 29 2021 - 15:44:33 EST

Hi Petr,

I love your patch! Perhaps something to improve:

[auto build test WARNING on linus/master]
[also build test WARNING on v5.13 next-20210629]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]

url: https://github.com/0day-ci/linux/commits/Petr-Mladek/printk-console-Check-consistent-sequence-number-when-handling-race-in-console_unlock/20210629-223408
base: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git c54b245d011855ea91c5beff07f1db74143ce614
config: x86_64-buildonly-randconfig-r006-20210629 (attached as .config)
compiler: gcc-9 (Debian 9.3.0-22) 9.3.0
reproduce (this is a W=1 build):
# https://github.com/0day-ci/linux/commit/24c9c4e757be2efe5bb225e443b3502338abf64c
git remote add linux-review https://github.com/0day-ci/linux
git fetch --no-tags linux-review Petr-Mladek/printk-console-Check-consistent-sequence-number-when-handling-race-in-console_unlock/20210629-223408
git checkout 24c9c4e757be2efe5bb225e443b3502338abf64c
# save the attached .config to linux build tree
make W=1 ARCH=x86_64

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <lkp@xxxxxxxxx>

All warnings (new ones prefixed by >>):

kernel/printk/printk.c:175:5: warning: no previous prototype for 'devkmsg_sysctl_set_loglvl' [-Wmissing-prototypes]
175 | int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write,
| ^~~~~~~~~~~~~~~~~~~~~~~~~
kernel/printk/printk.c: In function 'console_unlock':
>> kernel/printk/printk.c:2548:6: warning: variable 'next_seq' set but not used [-Wunused-but-set-variable]
2548 | u64 next_seq;
| ^~~~~~~~


vim +/next_seq +2548 kernel/printk/printk.c

2525
2526 /**
2527 * console_unlock - unlock the console system
2528 *
2529 * Releases the console_lock which the caller holds on the console system
2530 * and the console driver list.
2531 *
2532 * While the console_lock was held, console output may have been buffered
2533 * by printk(). If this is the case, console_unlock(); emits
2534 * the output prior to releasing the lock.
2535 *
2536 * If there is output waiting, we wake /dev/kmsg and syslog() users.
2537 *
2538 * console_unlock(); may be called from any context.
2539 */
2540 void console_unlock(void)
2541 {
2542 static char ext_text[CONSOLE_EXT_LOG_MAX];
2543 static char text[CONSOLE_LOG_MAX];
2544 unsigned long flags;
2545 bool do_cond_resched, retry;
2546 struct printk_info info;
2547 struct printk_record r;
> 2548 u64 next_seq;
2549
2550 if (console_suspended) {
2551 up_console_sem();
2552 return;
2553 }
2554
2555 prb_rec_init_rd(&r, &info, text, sizeof(text));
2556
2557 /*
2558 * Console drivers are called with interrupts disabled, so
2559 * @console_may_schedule should be cleared before; however, we may
2560 * end up dumping a lot of lines, for example, if called from
2561 * console registration path, and should invoke cond_resched()
2562 * between lines if allowable. Not doing so can cause a very long
2563 * scheduling stall on a slow console leading to RCU stall and
2564 * softlockup warnings which exacerbate the issue with more
2565 * messages practically incapacitating the system.
2566 *
2567 * console_trylock() is not able to detect the preemptive
2568 * context reliably. Therefore the value must be stored before
2569 * and cleared after the "again" goto label.
2570 */
2571 do_cond_resched = console_may_schedule;
2572 again:
2573 console_may_schedule = 0;
2574
2575 /*
2576 * We released the console_sem lock, so we need to recheck if
2577 * cpu is online and (if not) is there at least one CON_ANYTIME
2578 * console.
2579 */
2580 if (!can_use_console()) {
2581 console_locked = 0;
2582 up_console_sem();
2583 return;
2584 }
2585
2586 for (;;) {
2587 size_t ext_len = 0;
2588 size_t len;
2589
2590 printk_safe_enter_irqsave(flags);
2591 skip:
2592 if (!prb_read_valid(prb, console_seq, &r))
2593 break;
2594
2595 if (console_seq != r.info->seq) {
2596 console_dropped += r.info->seq - console_seq;
2597 console_seq = r.info->seq;
2598 }
2599
2600 if (suppress_message_printing(r.info->level)) {
2601 /*
2602 * Skip record we have buffered and already printed
2603 * directly to the console when we received it, and
2604 * record that has level above the console loglevel.
2605 */
2606 console_seq++;
2607 goto skip;
2608 }
2609
2610 /* Output to all consoles once old messages replayed. */
2611 if (unlikely(exclusive_console &&
2612 console_seq >= exclusive_console_stop_seq)) {
2613 exclusive_console = NULL;
2614 }
2615
2616 /*
2617 * Handle extended console text first because later
2618 * record_print_text() will modify the record buffer in-place.
2619 */
2620 if (nr_ext_console_drivers) {
2621 ext_len = info_print_ext_header(ext_text,
2622 sizeof(ext_text),
2623 r.info);
2624 ext_len += msg_print_ext_body(ext_text + ext_len,
2625 sizeof(ext_text) - ext_len,
2626 &r.text_buf[0],
2627 r.info->text_len,
2628 &r.info->dev_info);
2629 }
2630 len = record_print_text(&r,
2631 console_msg_format & MSG_FORMAT_SYSLOG,
2632 printk_time);
2633 console_seq++;
2634
2635 /*
2636 * While actively printing out messages, if another printk()
2637 * were to occur on another CPU, it may wait for this one to
2638 * finish. This task can not be preempted if there is a
2639 * waiter waiting to take over.
2640 */
2641 console_lock_spinning_enable();
2642
2643 stop_critical_timings(); /* don't trace print latency */
2644 call_console_drivers(ext_text, ext_len, text, len);
2645 start_critical_timings();
2646
2647 if (console_lock_spinning_disable_and_check()) {
2648 printk_safe_exit_irqrestore(flags);
2649 return;
2650 }
2651
2652 printk_safe_exit_irqrestore(flags);
2653
2654 if (do_cond_resched)
2655 cond_resched();
2656 }
2657
2658 /* Get consistent value of the next-to-be-used sequence number. */
2659 next_seq = console_seq;
2660
2661 console_locked = 0;
2662 up_console_sem();
2663
2664 /*
2665 * Someone could have filled up the buffer again, so re-check if there's
2666 * something to flush. In case we cannot trylock the console_sem again,
2667 * there's a new owner and the console_unlock() from them will do the
2668 * flush, no worries.
2669 */
2670 retry = prb_read_valid(prb, next_seq, NULL);
2671 printk_safe_exit_irqrestore(flags);
2672
2673 if (retry && console_trylock())
2674 goto again;
2675 }
2676 EXPORT_SYMBOL(console_unlock);
2677

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all@xxxxxxxxxxxx

Attachment: .config.gz
Description: application/gzip