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

[kernel test robot <lkp@intel.com>]

[-- Attachment #1: Type: text/plain, Size: 7441 bytes --]

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@intel.com>

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(a)lists.01.org

[-- Attachment #2: config.gz --]
[-- Type: application/gzip, Size: 35718 bytes --]