printk_safe.c 10.6 KB
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414
// SPDX-License-Identifier: GPL-2.0-or-later
/*
 * printk_safe.c - Safe printk for printk-deadlock-prone contexts
 */

#include <linux/preempt.h>
#include <linux/spinlock.h>
#include <linux/debug_locks.h>
#include <linux/kdb.h>
#include <linux/smp.h>
#include <linux/cpumask.h>
#include <linux/irq_work.h>
#include <linux/printk.h>
#include <linux/kprobes.h>

#include "internal.h"

/*
 * printk() could not take logbuf_lock in NMI context. Instead,
 * it uses an alternative implementation that temporary stores
 * the strings into a per-CPU buffer. The content of the buffer
 * is later flushed into the main ring buffer via IRQ work.
 *
 * The alternative implementation is chosen transparently
 * by examining current printk() context mask stored in @printk_context
 * per-CPU variable.
 *
 * The implementation allows to flush the strings also from another CPU.
 * There are situations when we want to make sure that all buffers
 * were handled or when IRQs are blocked.
 */

#define SAFE_LOG_BUF_LEN ((1 << CONFIG_PRINTK_SAFE_LOG_BUF_SHIFT) -	\
				sizeof(atomic_t) -			\
				sizeof(atomic_t) -			\
				sizeof(struct irq_work))

struct printk_safe_seq_buf {
	atomic_t		len;	/* length of written data */
	atomic_t		message_lost;
	struct irq_work		work;	/* IRQ work that flushes the buffer */
	unsigned char		buffer[SAFE_LOG_BUF_LEN];
};

static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq);
static DEFINE_PER_CPU(int, printk_context);

#ifdef CONFIG_PRINTK_NMI
static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
#endif

/* Get flushed in a more safe context. */
static void queue_flush_work(struct printk_safe_seq_buf *s)
{
	if (printk_percpu_data_ready())
		irq_work_queue(&s->work);
}

/*
 * Add a message to per-CPU context-dependent buffer. NMI and printk-safe
 * have dedicated buffers, because otherwise printk-safe preempted by
 * NMI-printk would have overwritten the NMI messages.
 *
 * The messages are flushed from irq work (or from panic()), possibly,
 * from other CPU, concurrently with printk_safe_log_store(). Should this
 * happen, printk_safe_log_store() will notice the buffer->len mismatch
 * and repeat the write.
 */
static __printf(2, 0) int printk_safe_log_store(struct printk_safe_seq_buf *s,
						const char *fmt, va_list args)
{
	int add;
	size_t len;
	va_list ap;

again:
	len = atomic_read(&s->len);

	/* The trailing '\0' is not counted into len. */
	if (len >= sizeof(s->buffer) - 1) {
		atomic_inc(&s->message_lost);
		queue_flush_work(s);
		return 0;
	}

	/*
	 * Make sure that all old data have been read before the buffer
	 * was reset. This is not needed when we just append data.
	 */
	if (!len)
		smp_rmb();

	va_copy(ap, args);
	add = vscnprintf(s->buffer + len, sizeof(s->buffer) - len, fmt, ap);
	va_end(ap);
	if (!add)
		return 0;

	/*
	 * Do it once again if the buffer has been flushed in the meantime.
	 * Note that atomic_cmpxchg() is an implicit memory barrier that
	 * makes sure that the data were written before updating s->len.
	 */
	if (atomic_cmpxchg(&s->len, len, len + add) != len)
		goto again;

	queue_flush_work(s);
	return add;
}

static inline void printk_safe_flush_line(const char *text, int len)
{
	/*
	 * Avoid any console drivers calls from here, because we may be
	 * in NMI or printk_safe context (when in panic). The messages
	 * must go only into the ring buffer at this stage.  Consoles will
	 * get explicitly called later when a crashdump is not generated.
	 */
	printk_deferred("%.*s", len, text);
}

/* printk part of the temporary buffer line by line */
static int printk_safe_flush_buffer(const char *start, size_t len)
{
	const char *c, *end;
	bool header;

	c = start;
	end = start + len;
	header = true;

	/* Print line by line. */
	while (c < end) {
		if (*c == '\n') {
			printk_safe_flush_line(start, c - start + 1);
			start = ++c;
			header = true;
			continue;
		}

		/* Handle continuous lines or missing new line. */
		if ((c + 1 < end) && printk_get_level(c)) {
			if (header) {
				c = printk_skip_level(c);
				continue;
			}

			printk_safe_flush_line(start, c - start);
			start = c++;
			header = true;
			continue;
		}

		header = false;
		c++;
	}

	/* Check if there was a partial line. Ignore pure header. */
	if (start < end && !header) {
		static const char newline[] = KERN_CONT "\n";

		printk_safe_flush_line(start, end - start);
		printk_safe_flush_line(newline, strlen(newline));
	}

	return len;
}

static void report_message_lost(struct printk_safe_seq_buf *s)
{
	int lost = atomic_xchg(&s->message_lost, 0);

	if (lost)
		printk_deferred("Lost %d message(s)!\n", lost);
}

/*
 * Flush data from the associated per-CPU buffer. The function
 * can be called either via IRQ work or independently.
 */
static void __printk_safe_flush(struct irq_work *work)
{
	static raw_spinlock_t read_lock =
		__RAW_SPIN_LOCK_INITIALIZER(read_lock);
	struct printk_safe_seq_buf *s =
		container_of(work, struct printk_safe_seq_buf, work);
	unsigned long flags;
	size_t len;
	int i;

	/*
	 * The lock has two functions. First, one reader has to flush all
	 * available message to make the lockless synchronization with
	 * writers easier. Second, we do not want to mix messages from
	 * different CPUs. This is especially important when printing
	 * a backtrace.
	 */
	raw_spin_lock_irqsave(&read_lock, flags);

	i = 0;
more:
	len = atomic_read(&s->len);

	/*
	 * This is just a paranoid check that nobody has manipulated
	 * the buffer an unexpected way. If we printed something then
	 * @len must only increase. Also it should never overflow the
	 * buffer size.
	 */
	if ((i && i >= len) || len > sizeof(s->buffer)) {
		const char *msg = "printk_safe_flush: internal error\n";

		printk_safe_flush_line(msg, strlen(msg));
		len = 0;
	}

	if (!len)
		goto out; /* Someone else has already flushed the buffer. */

	/* Make sure that data has been written up to the @len */
	smp_rmb();
	i += printk_safe_flush_buffer(s->buffer + i, len - i);

	/*
	 * Check that nothing has got added in the meantime and truncate
	 * the buffer. Note that atomic_cmpxchg() is an implicit memory
	 * barrier that makes sure that the data were copied before
	 * updating s->len.
	 */
	if (atomic_cmpxchg(&s->len, len, 0) != len)
		goto more;

out:
	report_message_lost(s);
	raw_spin_unlock_irqrestore(&read_lock, flags);
}

/**
 * printk_safe_flush - flush all per-cpu nmi buffers.
 *
 * The buffers are flushed automatically via IRQ work. This function
 * is useful only when someone wants to be sure that all buffers have
 * been flushed at some point.
 */
void printk_safe_flush(void)
{
	int cpu;

	for_each_possible_cpu(cpu) {
#ifdef CONFIG_PRINTK_NMI
		__printk_safe_flush(&per_cpu(nmi_print_seq, cpu).work);
#endif
		__printk_safe_flush(&per_cpu(safe_print_seq, cpu).work);
	}
}

/**
 * printk_safe_flush_on_panic - flush all per-cpu nmi buffers when the system
 *	goes down.
 *
 * Similar to printk_safe_flush() but it can be called even in NMI context when
 * the system goes down. It does the best effort to get NMI messages into
 * the main ring buffer.
 *
 * Note that it could try harder when there is only one CPU online.
 */
void printk_safe_flush_on_panic(void)
{
	/*
	 * Make sure that we could access the main ring buffer.
	 * Do not risk a double release when more CPUs are up.
	 */
	if (raw_spin_is_locked(&logbuf_lock)) {
		if (num_online_cpus() > 1)
			return;

		debug_locks_off();
		raw_spin_lock_init(&logbuf_lock);
	}

	printk_safe_flush();
}

#ifdef CONFIG_PRINTK_NMI
/*
 * Safe printk() for NMI context. It uses a per-CPU buffer to
 * store the message. NMIs are not nested, so there is always only
 * one writer running. But the buffer might get flushed from another
 * CPU, so we need to be careful.
 */
static __printf(1, 0) int vprintk_nmi(const char *fmt, va_list args)
{
	struct printk_safe_seq_buf *s = this_cpu_ptr(&nmi_print_seq);

	return printk_safe_log_store(s, fmt, args);
}

void noinstr printk_nmi_enter(void)
{
	this_cpu_add(printk_context, PRINTK_NMI_CONTEXT_OFFSET);
}

void noinstr printk_nmi_exit(void)
{
	this_cpu_sub(printk_context, PRINTK_NMI_CONTEXT_OFFSET);
}

/*
 * Marks a code that might produce many messages in NMI context
 * and the risk of losing them is more critical than eventual
 * reordering.
 *
 * It has effect only when called in NMI context. Then printk()
 * will try to store the messages into the main logbuf directly
 * and use the per-CPU buffers only as a fallback when the lock
 * is not available.
 */
void printk_nmi_direct_enter(void)
{
	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
		this_cpu_or(printk_context, PRINTK_NMI_DIRECT_CONTEXT_MASK);
}

void printk_nmi_direct_exit(void)
{
	this_cpu_and(printk_context, ~PRINTK_NMI_DIRECT_CONTEXT_MASK);
}

#else

static __printf(1, 0) int vprintk_nmi(const char *fmt, va_list args)
{
	return 0;
}

#endif /* CONFIG_PRINTK_NMI */

/*
 * Lock-less printk(), to avoid deadlocks should the printk() recurse
 * into itself. It uses a per-CPU buffer to store the message, just like
 * NMI.
 */
static __printf(1, 0) int vprintk_safe(const char *fmt, va_list args)
{
	struct printk_safe_seq_buf *s = this_cpu_ptr(&safe_print_seq);

	return printk_safe_log_store(s, fmt, args);
}

/* Can be preempted by NMI. */
void __printk_safe_enter(void)
{
	this_cpu_inc(printk_context);
}

/* Can be preempted by NMI. */
void __printk_safe_exit(void)
{
	this_cpu_dec(printk_context);
}

__printf(1, 0) int vprintk_func(const char *fmt, va_list args)
{
#ifdef CONFIG_KGDB_KDB
	/* Allow to pass printk() to kdb but avoid a recursion. */
	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0))
		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
#endif

	/*
	 * Try to use the main logbuf even in NMI. But avoid calling console
	 * drivers that might have their own locks.
	 */
	if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK) &&
	    raw_spin_trylock(&logbuf_lock)) {
		int len;

		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
		raw_spin_unlock(&logbuf_lock);
		defer_console_output();
		return len;
	}

	/* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */
	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
		return vprintk_nmi(fmt, args);

	/* Use extra buffer to prevent a recursion deadlock in safe mode. */
	if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK)
		return vprintk_safe(fmt, args);

	/* No obstacles. */
	return vprintk_default(fmt, args);
}

void __init printk_safe_init(void)
{
	int cpu;

	for_each_possible_cpu(cpu) {
		struct printk_safe_seq_buf *s;

		s = &per_cpu(safe_print_seq, cpu);
		init_irq_work(&s->work, __printk_safe_flush);

#ifdef CONFIG_PRINTK_NMI
		s = &per_cpu(nmi_print_seq, cpu);
		init_irq_work(&s->work, __printk_safe_flush);
#endif
	}

	/* Flush pending messages that did not have scheduled IRQ works. */
	printk_safe_flush();
}