aboutsummaryrefslogtreecommitdiffstats
path: root/kernel/printk.c
diff options
context:
space:
mode:
Diffstat (limited to 'kernel/printk.c')
-rw-r--r--kernel/printk.c1768
1 files changed, 1331 insertions, 437 deletions
diff --git a/kernel/printk.c b/kernel/printk.c
index b663c2c95d39..177fa49357a5 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -41,6 +41,7 @@
41#include <linux/cpu.h> 41#include <linux/cpu.h>
42#include <linux/notifier.h> 42#include <linux/notifier.h>
43#include <linux/rculist.h> 43#include <linux/rculist.h>
44#include <linux/poll.h>
44 45
45#include <asm/uaccess.h> 46#include <asm/uaccess.h>
46 47
@@ -54,8 +55,6 @@ void asmlinkage __attribute__((weak)) early_printk(const char *fmt, ...)
54{ 55{
55} 56}
56 57
57#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
58
59/* printk's without a loglevel use this.. */ 58/* printk's without a loglevel use this.. */
60#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL 59#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL
61 60
@@ -99,24 +98,6 @@ EXPORT_SYMBOL_GPL(console_drivers);
99static int console_locked, console_suspended; 98static int console_locked, console_suspended;
100 99
101/* 100/*
102 * logbuf_lock protects log_buf, log_start, log_end, con_start and logged_chars
103 * It is also used in interesting ways to provide interlocking in
104 * console_unlock();.
105 */
106static DEFINE_RAW_SPINLOCK(logbuf_lock);
107
108#define LOG_BUF_MASK (log_buf_len-1)
109#define LOG_BUF(idx) (log_buf[(idx) & LOG_BUF_MASK])
110
111/*
112 * The indices into log_buf are not constrained to log_buf_len - they
113 * must be masked before subscripting
114 */
115static unsigned log_start; /* Index into log_buf: next char to be read by syslog() */
116static unsigned con_start; /* Index into log_buf: next char to be sent to consoles */
117static unsigned log_end; /* Index into log_buf: most-recently-written-char + 1 */
118
119/*
120 * If exclusive_console is non-NULL then only this console is to be printed to. 101 * If exclusive_console is non-NULL then only this console is to be printed to.
121 */ 102 */
122static struct console *exclusive_console; 103static struct console *exclusive_console;
@@ -145,13 +126,510 @@ EXPORT_SYMBOL(console_set_on_cmdline);
145/* Flag: console code may call schedule() */ 126/* Flag: console code may call schedule() */
146static int console_may_schedule; 127static int console_may_schedule;
147 128
129/*
130 * The printk log buffer consists of a chain of concatenated variable
131 * length records. Every record starts with a record header, containing
132 * the overall length of the record.
133 *
134 * The heads to the first and last entry in the buffer, as well as the
135 * sequence numbers of these both entries are maintained when messages
136 * are stored..
137 *
138 * If the heads indicate available messages, the length in the header
139 * tells the start next message. A length == 0 for the next message
140 * indicates a wrap-around to the beginning of the buffer.
141 *
142 * Every record carries the monotonic timestamp in microseconds, as well as
143 * the standard userspace syslog level and syslog facility. The usual
144 * kernel messages use LOG_KERN; userspace-injected messages always carry
145 * a matching syslog facility, by default LOG_USER. The origin of every
146 * message can be reliably determined that way.
147 *
148 * The human readable log message directly follows the message header. The
149 * length of the message text is stored in the header, the stored message
150 * is not terminated.
151 *
152 * Optionally, a message can carry a dictionary of properties (key/value pairs),
153 * to provide userspace with a machine-readable message context.
154 *
155 * Examples for well-defined, commonly used property names are:
156 * DEVICE=b12:8 device identifier
157 * b12:8 block dev_t
158 * c127:3 char dev_t
159 * n8 netdev ifindex
160 * +sound:card0 subsystem:devname
161 * SUBSYSTEM=pci driver-core subsystem name
162 *
163 * Valid characters in property names are [a-zA-Z0-9.-_]. The plain text value
164 * follows directly after a '=' character. Every property is terminated by
165 * a '\0' character. The last property is not terminated.
166 *
167 * Example of a message structure:
168 * 0000 ff 8f 00 00 00 00 00 00 monotonic time in nsec
169 * 0008 34 00 record is 52 bytes long
170 * 000a 0b 00 text is 11 bytes long
171 * 000c 1f 00 dictionary is 23 bytes long
172 * 000e 03 00 LOG_KERN (facility) LOG_ERR (level)
173 * 0010 69 74 27 73 20 61 20 6c "it's a l"
174 * 69 6e 65 "ine"
175 * 001b 44 45 56 49 43 "DEVIC"
176 * 45 3d 62 38 3a 32 00 44 "E=b8:2\0D"
177 * 52 49 56 45 52 3d 62 75 "RIVER=bu"
178 * 67 "g"
179 * 0032 00 00 00 padding to next message header
180 *
181 * The 'struct log' buffer header must never be directly exported to
182 * userspace, it is a kernel-private implementation detail that might
183 * need to be changed in the future, when the requirements change.
184 *
185 * /dev/kmsg exports the structured data in the following line format:
186 * "level,sequnum,timestamp;<message text>\n"
187 *
188 * The optional key/value pairs are attached as continuation lines starting
189 * with a space character and terminated by a newline. All possible
190 * non-prinatable characters are escaped in the "\xff" notation.
191 *
192 * Users of the export format should ignore possible additional values
193 * separated by ',', and find the message after the ';' character.
194 */
195
196enum log_flags {
197 LOG_NOCONS = 1, /* already flushed, do not print to console */
198 LOG_NEWLINE = 2, /* text ended with a newline */
199 LOG_PREFIX = 4, /* text started with a prefix */
200 LOG_CONT = 8, /* text is a fragment of a continuation line */
201};
202
203struct log {
204 u64 ts_nsec; /* timestamp in nanoseconds */
205 u16 len; /* length of entire record */
206 u16 text_len; /* length of text buffer */
207 u16 dict_len; /* length of dictionary buffer */
208 u8 facility; /* syslog facility */
209 u8 flags:5; /* internal record flags */
210 u8 level:3; /* syslog level */
211};
212
213/*
214 * The logbuf_lock protects kmsg buffer, indices, counters. It is also
215 * used in interesting ways to provide interlocking in console_unlock();
216 */
217static DEFINE_RAW_SPINLOCK(logbuf_lock);
218
219/* the next printk record to read by syslog(READ) or /proc/kmsg */
220static u64 syslog_seq;
221static u32 syslog_idx;
222static enum log_flags syslog_prev;
223static size_t syslog_partial;
224
225/* index and sequence number of the first record stored in the buffer */
226static u64 log_first_seq;
227static u32 log_first_idx;
228
229/* index and sequence number of the next record to store in the buffer */
230static u64 log_next_seq;
148#ifdef CONFIG_PRINTK 231#ifdef CONFIG_PRINTK
232static u32 log_next_idx;
233
234/* the next printk record to read after the last 'clear' command */
235static u64 clear_seq;
236static u32 clear_idx;
149 237
150static char __log_buf[__LOG_BUF_LEN]; 238#define LOG_LINE_MAX 1024
239
240/* record buffer */
241#if defined(CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS)
242#define LOG_ALIGN 4
243#else
244#define LOG_ALIGN __alignof__(struct log)
245#endif
246#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
247static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
151static char *log_buf = __log_buf; 248static char *log_buf = __log_buf;
152static int log_buf_len = __LOG_BUF_LEN; 249static u32 log_buf_len = __LOG_BUF_LEN;
153static unsigned logged_chars; /* Number of chars produced since last read+clear operation */ 250
154static int saved_console_loglevel = -1; 251/* cpu currently holding logbuf_lock */
252static volatile unsigned int logbuf_cpu = UINT_MAX;
253
254/* human readable text of the record */
255static char *log_text(const struct log *msg)
256{
257 return (char *)msg + sizeof(struct log);
258}
259
260/* optional key/value pair dictionary attached to the record */
261static char *log_dict(const struct log *msg)
262{
263 return (char *)msg + sizeof(struct log) + msg->text_len;
264}
265
266/* get record by index; idx must point to valid msg */
267static struct log *log_from_idx(u32 idx)
268{
269 struct log *msg = (struct log *)(log_buf + idx);
270
271 /*
272 * A length == 0 record is the end of buffer marker. Wrap around and
273 * read the message at the start of the buffer.
274 */
275 if (!msg->len)
276 return (struct log *)log_buf;
277 return msg;
278}
279
280/* get next record; idx must point to valid msg */
281static u32 log_next(u32 idx)
282{
283 struct log *msg = (struct log *)(log_buf + idx);
284
285 /* length == 0 indicates the end of the buffer; wrap */
286 /*
287 * A length == 0 record is the end of buffer marker. Wrap around and
288 * read the message at the start of the buffer as *this* one, and
289 * return the one after that.
290 */
291 if (!msg->len) {
292 msg = (struct log *)log_buf;
293 return msg->len;
294 }
295 return idx + msg->len;
296}
297
298/* insert record into the buffer, discard old ones, update heads */
299static void log_store(int facility, int level,
300 enum log_flags flags, u64 ts_nsec,
301 const char *dict, u16 dict_len,
302 const char *text, u16 text_len)
303{
304 struct log *msg;
305 u32 size, pad_len;
306
307 /* number of '\0' padding bytes to next message */
308 size = sizeof(struct log) + text_len + dict_len;
309 pad_len = (-size) & (LOG_ALIGN - 1);
310 size += pad_len;
311
312 while (log_first_seq < log_next_seq) {
313 u32 free;
314
315 if (log_next_idx > log_first_idx)
316 free = max(log_buf_len - log_next_idx, log_first_idx);
317 else
318 free = log_first_idx - log_next_idx;
319
320 if (free > size + sizeof(struct log))
321 break;
322
323 /* drop old messages until we have enough contiuous space */
324 log_first_idx = log_next(log_first_idx);
325 log_first_seq++;
326 }
327
328 if (log_next_idx + size + sizeof(struct log) >= log_buf_len) {
329 /*
330 * This message + an additional empty header does not fit
331 * at the end of the buffer. Add an empty header with len == 0
332 * to signify a wrap around.
333 */
334 memset(log_buf + log_next_idx, 0, sizeof(struct log));
335 log_next_idx = 0;
336 }
337
338 /* fill message */
339 msg = (struct log *)(log_buf + log_next_idx);
340 memcpy(log_text(msg), text, text_len);
341 msg->text_len = text_len;
342 memcpy(log_dict(msg), dict, dict_len);
343 msg->dict_len = dict_len;
344 msg->facility = facility;
345 msg->level = level & 7;
346 msg->flags = flags & 0x1f;
347 if (ts_nsec > 0)
348 msg->ts_nsec = ts_nsec;
349 else
350 msg->ts_nsec = local_clock();
351 memset(log_dict(msg) + dict_len, 0, pad_len);
352 msg->len = sizeof(struct log) + text_len + dict_len + pad_len;
353
354 /* insert message */
355 log_next_idx += msg->len;
356 log_next_seq++;
357}
358
359/* /dev/kmsg - userspace message inject/listen interface */
360struct devkmsg_user {
361 u64 seq;
362 u32 idx;
363 struct mutex lock;
364 char buf[8192];
365};
366
367static ssize_t devkmsg_writev(struct kiocb *iocb, const struct iovec *iv,
368 unsigned long count, loff_t pos)
369{
370 char *buf, *line;
371 int i;
372 int level = default_message_loglevel;
373 int facility = 1; /* LOG_USER */
374 size_t len = iov_length(iv, count);
375 ssize_t ret = len;
376
377 if (len > LOG_LINE_MAX)
378 return -EINVAL;
379 buf = kmalloc(len+1, GFP_KERNEL);
380 if (buf == NULL)
381 return -ENOMEM;
382
383 line = buf;
384 for (i = 0; i < count; i++) {
385 if (copy_from_user(line, iv[i].iov_base, iv[i].iov_len))
386 goto out;
387 line += iv[i].iov_len;
388 }
389
390 /*
391 * Extract and skip the syslog prefix <[0-9]*>. Coming from userspace
392 * the decimal value represents 32bit, the lower 3 bit are the log
393 * level, the rest are the log facility.
394 *
395 * If no prefix or no userspace facility is specified, we
396 * enforce LOG_USER, to be able to reliably distinguish
397 * kernel-generated messages from userspace-injected ones.
398 */
399 line = buf;
400 if (line[0] == '<') {
401 char *endp = NULL;
402
403 i = simple_strtoul(line+1, &endp, 10);
404 if (endp && endp[0] == '>') {
405 level = i & 7;
406 if (i >> 3)
407 facility = i >> 3;
408 endp++;
409 len -= endp - line;
410 line = endp;
411 }
412 }
413 line[len] = '\0';
414
415 printk_emit(facility, level, NULL, 0, "%s", line);
416out:
417 kfree(buf);
418 return ret;
419}
420
421static ssize_t devkmsg_read(struct file *file, char __user *buf,
422 size_t count, loff_t *ppos)
423{
424 struct devkmsg_user *user = file->private_data;
425 struct log *msg;
426 u64 ts_usec;
427 size_t i;
428 size_t len;
429 ssize_t ret;
430
431 if (!user)
432 return -EBADF;
433
434 ret = mutex_lock_interruptible(&user->lock);
435 if (ret)
436 return ret;
437 raw_spin_lock_irq(&logbuf_lock);
438 while (user->seq == log_next_seq) {
439 if (file->f_flags & O_NONBLOCK) {
440 ret = -EAGAIN;
441 raw_spin_unlock_irq(&logbuf_lock);
442 goto out;
443 }
444
445 raw_spin_unlock_irq(&logbuf_lock);
446 ret = wait_event_interruptible(log_wait,
447 user->seq != log_next_seq);
448 if (ret)
449 goto out;
450 raw_spin_lock_irq(&logbuf_lock);
451 }
452
453 if (user->seq < log_first_seq) {
454 /* our last seen message is gone, return error and reset */
455 user->idx = log_first_idx;
456 user->seq = log_first_seq;
457 ret = -EPIPE;
458 raw_spin_unlock_irq(&logbuf_lock);
459 goto out;
460 }
461
462 msg = log_from_idx(user->idx);
463 ts_usec = msg->ts_nsec;
464 do_div(ts_usec, 1000);
465 len = sprintf(user->buf, "%u,%llu,%llu;",
466 (msg->facility << 3) | msg->level, user->seq, ts_usec);
467
468 /* escape non-printable characters */
469 for (i = 0; i < msg->text_len; i++) {
470 unsigned char c = log_text(msg)[i];
471
472 if (c < ' ' || c >= 127 || c == '\\')
473 len += sprintf(user->buf + len, "\\x%02x", c);
474 else
475 user->buf[len++] = c;
476 }
477 user->buf[len++] = '\n';
478
479 if (msg->dict_len) {
480 bool line = true;
481
482 for (i = 0; i < msg->dict_len; i++) {
483 unsigned char c = log_dict(msg)[i];
484
485 if (line) {
486 user->buf[len++] = ' ';
487 line = false;
488 }
489
490 if (c == '\0') {
491 user->buf[len++] = '\n';
492 line = true;
493 continue;
494 }
495
496 if (c < ' ' || c >= 127 || c == '\\') {
497 len += sprintf(user->buf + len, "\\x%02x", c);
498 continue;
499 }
500
501 user->buf[len++] = c;
502 }
503 user->buf[len++] = '\n';
504 }
505
506 user->idx = log_next(user->idx);
507 user->seq++;
508 raw_spin_unlock_irq(&logbuf_lock);
509
510 if (len > count) {
511 ret = -EINVAL;
512 goto out;
513 }
514
515 if (copy_to_user(buf, user->buf, len)) {
516 ret = -EFAULT;
517 goto out;
518 }
519 ret = len;
520out:
521 mutex_unlock(&user->lock);
522 return ret;
523}
524
525static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
526{
527 struct devkmsg_user *user = file->private_data;
528 loff_t ret = 0;
529
530 if (!user)
531 return -EBADF;
532 if (offset)
533 return -ESPIPE;
534
535 raw_spin_lock_irq(&logbuf_lock);
536 switch (whence) {
537 case SEEK_SET:
538 /* the first record */
539 user->idx = log_first_idx;
540 user->seq = log_first_seq;
541 break;
542 case SEEK_DATA:
543 /*
544 * The first record after the last SYSLOG_ACTION_CLEAR,
545 * like issued by 'dmesg -c'. Reading /dev/kmsg itself
546 * changes no global state, and does not clear anything.
547 */
548 user->idx = clear_idx;
549 user->seq = clear_seq;
550 break;
551 case SEEK_END:
552 /* after the last record */
553 user->idx = log_next_idx;
554 user->seq = log_next_seq;
555 break;
556 default:
557 ret = -EINVAL;
558 }
559 raw_spin_unlock_irq(&logbuf_lock);
560 return ret;
561}
562
563static unsigned int devkmsg_poll(struct file *file, poll_table *wait)
564{
565 struct devkmsg_user *user = file->private_data;
566 int ret = 0;
567
568 if (!user)
569 return POLLERR|POLLNVAL;
570
571 poll_wait(file, &log_wait, wait);
572
573 raw_spin_lock_irq(&logbuf_lock);
574 if (user->seq < log_next_seq) {
575 /* return error when data has vanished underneath us */
576 if (user->seq < log_first_seq)
577 ret = POLLIN|POLLRDNORM|POLLERR|POLLPRI;
578 ret = POLLIN|POLLRDNORM;
579 }
580 raw_spin_unlock_irq(&logbuf_lock);
581
582 return ret;
583}
584
585static int devkmsg_open(struct inode *inode, struct file *file)
586{
587 struct devkmsg_user *user;
588 int err;
589
590 /* write-only does not need any file context */
591 if ((file->f_flags & O_ACCMODE) == O_WRONLY)
592 return 0;
593
594 err = security_syslog(SYSLOG_ACTION_READ_ALL);
595 if (err)
596 return err;
597
598 user = kmalloc(sizeof(struct devkmsg_user), GFP_KERNEL);
599 if (!user)
600 return -ENOMEM;
601
602 mutex_init(&user->lock);
603
604 raw_spin_lock_irq(&logbuf_lock);
605 user->idx = log_first_idx;
606 user->seq = log_first_seq;
607 raw_spin_unlock_irq(&logbuf_lock);
608
609 file->private_data = user;
610 return 0;
611}
612
613static int devkmsg_release(struct inode *inode, struct file *file)
614{
615 struct devkmsg_user *user = file->private_data;
616
617 if (!user)
618 return 0;
619
620 mutex_destroy(&user->lock);
621 kfree(user);
622 return 0;
623}
624
625const struct file_operations kmsg_fops = {
626 .open = devkmsg_open,
627 .read = devkmsg_read,
628 .aio_write = devkmsg_writev,
629 .llseek = devkmsg_llseek,
630 .poll = devkmsg_poll,
631 .release = devkmsg_release,
632};
155 633
156#ifdef CONFIG_KEXEC 634#ifdef CONFIG_KEXEC
157/* 635/*
@@ -165,9 +643,9 @@ static int saved_console_loglevel = -1;
165void log_buf_kexec_setup(void) 643void log_buf_kexec_setup(void)
166{ 644{
167 VMCOREINFO_SYMBOL(log_buf); 645 VMCOREINFO_SYMBOL(log_buf);
168 VMCOREINFO_SYMBOL(log_end);
169 VMCOREINFO_SYMBOL(log_buf_len); 646 VMCOREINFO_SYMBOL(log_buf_len);
170 VMCOREINFO_SYMBOL(logged_chars); 647 VMCOREINFO_SYMBOL(log_first_idx);
648 VMCOREINFO_SYMBOL(log_next_idx);
171} 649}
172#endif 650#endif
173 651
@@ -191,7 +669,6 @@ early_param("log_buf_len", log_buf_len_setup);
191void __init setup_log_buf(int early) 669void __init setup_log_buf(int early)
192{ 670{
193 unsigned long flags; 671 unsigned long flags;
194 unsigned start, dest_idx, offset;
195 char *new_log_buf; 672 char *new_log_buf;
196 int free; 673 int free;
197 674
@@ -219,20 +696,8 @@ void __init setup_log_buf(int early)
219 log_buf_len = new_log_buf_len; 696 log_buf_len = new_log_buf_len;
220 log_buf = new_log_buf; 697 log_buf = new_log_buf;
221 new_log_buf_len = 0; 698 new_log_buf_len = 0;
222 free = __LOG_BUF_LEN - log_end; 699 free = __LOG_BUF_LEN - log_next_idx;
223 700 memcpy(log_buf, __log_buf, __LOG_BUF_LEN);
224 offset = start = min(con_start, log_start);
225 dest_idx = 0;
226 while (start != log_end) {
227 unsigned log_idx_mask = start & (__LOG_BUF_LEN - 1);
228
229 log_buf[dest_idx] = __log_buf[log_idx_mask];
230 start++;
231 dest_idx++;
232 }
233 log_start -= offset;
234 con_start -= offset;
235 log_end -= offset;
236 raw_spin_unlock_irqrestore(&logbuf_lock, flags); 701 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
237 702
238 pr_info("log_buf_len: %d\n", log_buf_len); 703 pr_info("log_buf_len: %d\n", log_buf_len);
@@ -332,11 +797,270 @@ static int check_syslog_permissions(int type, bool from_file)
332 return 0; 797 return 0;
333} 798}
334 799
800#if defined(CONFIG_PRINTK_TIME)
801static bool printk_time = 1;
802#else
803static bool printk_time;
804#endif
805module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
806
807static size_t print_time(u64 ts, char *buf)
808{
809 unsigned long rem_nsec;
810
811 if (!printk_time)
812 return 0;
813
814 if (!buf)
815 return 15;
816
817 rem_nsec = do_div(ts, 1000000000);
818 return sprintf(buf, "[%5lu.%06lu] ",
819 (unsigned long)ts, rem_nsec / 1000);
820}
821
822static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
823{
824 size_t len = 0;
825 unsigned int prefix = (msg->facility << 3) | msg->level;
826
827 if (syslog) {
828 if (buf) {
829 len += sprintf(buf, "<%u>", prefix);
830 } else {
831 len += 3;
832 if (prefix > 999)
833 len += 3;
834 else if (prefix > 99)
835 len += 2;
836 else if (prefix > 9)
837 len++;
838 }
839 }
840
841 len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
842 return len;
843}
844
845static size_t msg_print_text(const struct log *msg, enum log_flags prev,
846 bool syslog, char *buf, size_t size)
847{
848 const char *text = log_text(msg);
849 size_t text_size = msg->text_len;
850 bool prefix = true;
851 bool newline = true;
852 size_t len = 0;
853
854 if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
855 prefix = false;
856
857 if (msg->flags & LOG_CONT) {
858 if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
859 prefix = false;
860
861 if (!(msg->flags & LOG_NEWLINE))
862 newline = false;
863 }
864
865 do {
866 const char *next = memchr(text, '\n', text_size);
867 size_t text_len;
868
869 if (next) {
870 text_len = next - text;
871 next++;
872 text_size -= next - text;
873 } else {
874 text_len = text_size;
875 }
876
877 if (buf) {
878 if (print_prefix(msg, syslog, NULL) +
879 text_len + 1>= size - len)
880 break;
881
882 if (prefix)
883 len += print_prefix(msg, syslog, buf + len);
884 memcpy(buf + len, text, text_len);
885 len += text_len;
886 if (next || newline)
887 buf[len++] = '\n';
888 } else {
889 /* SYSLOG_ACTION_* buffer size only calculation */
890 if (prefix)
891 len += print_prefix(msg, syslog, NULL);
892 len += text_len;
893 if (next || newline)
894 len++;
895 }
896
897 prefix = true;
898 text = next;
899 } while (text);
900
901 return len;
902}
903
904static int syslog_print(char __user *buf, int size)
905{
906 char *text;
907 struct log *msg;
908 int len = 0;
909
910 text = kmalloc(LOG_LINE_MAX, GFP_KERNEL);
911 if (!text)
912 return -ENOMEM;
913
914 while (size > 0) {
915 size_t n;
916 size_t skip;
917
918 raw_spin_lock_irq(&logbuf_lock);
919 if (syslog_seq < log_first_seq) {
920 /* messages are gone, move to first one */
921 syslog_seq = log_first_seq;
922 syslog_idx = log_first_idx;
923 syslog_prev = 0;
924 syslog_partial = 0;
925 }
926 if (syslog_seq == log_next_seq) {
927 raw_spin_unlock_irq(&logbuf_lock);
928 break;
929 }
930
931 skip = syslog_partial;
932 msg = log_from_idx(syslog_idx);
933 n = msg_print_text(msg, syslog_prev, true, text, LOG_LINE_MAX);
934 if (n - syslog_partial <= size) {
935 /* message fits into buffer, move forward */
936 syslog_idx = log_next(syslog_idx);
937 syslog_seq++;
938 syslog_prev = msg->flags;
939 n -= syslog_partial;
940 syslog_partial = 0;
941 } else if (!len){
942 /* partial read(), remember position */
943 n = size;
944 syslog_partial += n;
945 } else
946 n = 0;
947 raw_spin_unlock_irq(&logbuf_lock);
948
949 if (!n)
950 break;
951
952 if (copy_to_user(buf, text + skip, n)) {
953 if (!len)
954 len = -EFAULT;
955 break;
956 }
957
958 len += n;
959 size -= n;
960 buf += n;
961 }
962
963 kfree(text);
964 return len;
965}
966
967static int syslog_print_all(char __user *buf, int size, bool clear)
968{
969 char *text;
970 int len = 0;
971
972 text = kmalloc(LOG_LINE_MAX, GFP_KERNEL);
973 if (!text)
974 return -ENOMEM;
975
976 raw_spin_lock_irq(&logbuf_lock);
977 if (buf) {
978 u64 next_seq;
979 u64 seq;
980 u32 idx;
981 enum log_flags prev;
982
983 if (clear_seq < log_first_seq) {
984 /* messages are gone, move to first available one */
985 clear_seq = log_first_seq;
986 clear_idx = log_first_idx;
987 }
988
989 /*
990 * Find first record that fits, including all following records,
991 * into the user-provided buffer for this dump.
992 */
993 seq = clear_seq;
994 idx = clear_idx;
995 prev = 0;
996 while (seq < log_next_seq) {
997 struct log *msg = log_from_idx(idx);
998
999 len += msg_print_text(msg, prev, true, NULL, 0);
1000 idx = log_next(idx);
1001 seq++;
1002 }
1003
1004 /* move first record forward until length fits into the buffer */
1005 seq = clear_seq;
1006 idx = clear_idx;
1007 prev = 0;
1008 while (len > size && seq < log_next_seq) {
1009 struct log *msg = log_from_idx(idx);
1010
1011 len -= msg_print_text(msg, prev, true, NULL, 0);
1012 idx = log_next(idx);
1013 seq++;
1014 }
1015
1016 /* last message fitting into this dump */
1017 next_seq = log_next_seq;
1018
1019 len = 0;
1020 prev = 0;
1021 while (len >= 0 && seq < next_seq) {
1022 struct log *msg = log_from_idx(idx);
1023 int textlen;
1024
1025 textlen = msg_print_text(msg, prev, true, text, LOG_LINE_MAX);
1026 if (textlen < 0) {
1027 len = textlen;
1028 break;
1029 }
1030 idx = log_next(idx);
1031 seq++;
1032 prev = msg->flags;
1033
1034 raw_spin_unlock_irq(&logbuf_lock);
1035 if (copy_to_user(buf + len, text, textlen))
1036 len = -EFAULT;
1037 else
1038 len += textlen;
1039 raw_spin_lock_irq(&logbuf_lock);
1040
1041 if (seq < log_first_seq) {
1042 /* messages are gone, move to next one */
1043 seq = log_first_seq;
1044 idx = log_first_idx;
1045 prev = 0;
1046 }
1047 }
1048 }
1049
1050 if (clear) {
1051 clear_seq = log_next_seq;
1052 clear_idx = log_next_idx;
1053 }
1054 raw_spin_unlock_irq(&logbuf_lock);
1055
1056 kfree(text);
1057 return len;
1058}
1059
335int do_syslog(int type, char __user *buf, int len, bool from_file) 1060int do_syslog(int type, char __user *buf, int len, bool from_file)
336{ 1061{
337 unsigned i, j, limit, count; 1062 bool clear = false;
338 int do_clear = 0; 1063 static int saved_console_loglevel = -1;
339 char c;
340 int error; 1064 int error;
341 1065
342 error = check_syslog_permissions(type, from_file); 1066 error = check_syslog_permissions(type, from_file);
@@ -364,28 +1088,14 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
364 goto out; 1088 goto out;
365 } 1089 }
366 error = wait_event_interruptible(log_wait, 1090 error = wait_event_interruptible(log_wait,
367 (log_start - log_end)); 1091 syslog_seq != log_next_seq);
368 if (error) 1092 if (error)
369 goto out; 1093 goto out;
370 i = 0; 1094 error = syslog_print(buf, len);
371 raw_spin_lock_irq(&logbuf_lock);
372 while (!error && (log_start != log_end) && i < len) {
373 c = LOG_BUF(log_start);
374 log_start++;
375 raw_spin_unlock_irq(&logbuf_lock);
376 error = __put_user(c,buf);
377 buf++;
378 i++;
379 cond_resched();
380 raw_spin_lock_irq(&logbuf_lock);
381 }
382 raw_spin_unlock_irq(&logbuf_lock);
383 if (!error)
384 error = i;
385 break; 1095 break;
386 /* Read/clear last kernel messages */ 1096 /* Read/clear last kernel messages */
387 case SYSLOG_ACTION_READ_CLEAR: 1097 case SYSLOG_ACTION_READ_CLEAR:
388 do_clear = 1; 1098 clear = true;
389 /* FALL THRU */ 1099 /* FALL THRU */
390 /* Read last kernel messages */ 1100 /* Read last kernel messages */
391 case SYSLOG_ACTION_READ_ALL: 1101 case SYSLOG_ACTION_READ_ALL:
@@ -399,51 +1109,11 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
399 error = -EFAULT; 1109 error = -EFAULT;
400 goto out; 1110 goto out;
401 } 1111 }
402 count = len; 1112 error = syslog_print_all(buf, len, clear);
403 if (count > log_buf_len)
404 count = log_buf_len;
405 raw_spin_lock_irq(&logbuf_lock);
406 if (count > logged_chars)
407 count = logged_chars;
408 if (do_clear)
409 logged_chars = 0;
410 limit = log_end;
411 /*
412 * __put_user() could sleep, and while we sleep
413 * printk() could overwrite the messages
414 * we try to copy to user space. Therefore
415 * the messages are copied in reverse. <manfreds>
416 */
417 for (i = 0; i < count && !error; i++) {
418 j = limit-1-i;
419 if (j + log_buf_len < log_end)
420 break;
421 c = LOG_BUF(j);
422 raw_spin_unlock_irq(&logbuf_lock);
423 error = __put_user(c,&buf[count-1-i]);
424 cond_resched();
425 raw_spin_lock_irq(&logbuf_lock);
426 }
427 raw_spin_unlock_irq(&logbuf_lock);
428 if (error)
429 break;
430 error = i;
431 if (i != count) {
432 int offset = count-error;
433 /* buffer overflow during copy, correct user buffer. */
434 for (i = 0; i < error; i++) {
435 if (__get_user(c,&buf[i+offset]) ||
436 __put_user(c,&buf[i])) {
437 error = -EFAULT;
438 break;
439 }
440 cond_resched();
441 }
442 }
443 break; 1113 break;
444 /* Clear ring buffer */ 1114 /* Clear ring buffer */
445 case SYSLOG_ACTION_CLEAR: 1115 case SYSLOG_ACTION_CLEAR:
446 logged_chars = 0; 1116 syslog_print_all(NULL, 0, true);
447 break; 1117 break;
448 /* Disable logging to console */ 1118 /* Disable logging to console */
449 case SYSLOG_ACTION_CONSOLE_OFF: 1119 case SYSLOG_ACTION_CONSOLE_OFF:
@@ -472,7 +1142,38 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
472 break; 1142 break;
473 /* Number of chars in the log buffer */ 1143 /* Number of chars in the log buffer */
474 case SYSLOG_ACTION_SIZE_UNREAD: 1144 case SYSLOG_ACTION_SIZE_UNREAD:
475 error = log_end - log_start; 1145 raw_spin_lock_irq(&logbuf_lock);
1146 if (syslog_seq < log_first_seq) {
1147 /* messages are gone, move to first one */
1148 syslog_seq = log_first_seq;
1149 syslog_idx = log_first_idx;
1150 syslog_prev = 0;
1151 syslog_partial = 0;
1152 }
1153 if (from_file) {
1154 /*
1155 * Short-cut for poll(/"proc/kmsg") which simply checks
1156 * for pending data, not the size; return the count of
1157 * records, not the length.
1158 */
1159 error = log_next_idx - syslog_idx;
1160 } else {
1161 u64 seq = syslog_seq;
1162 u32 idx = syslog_idx;
1163 enum log_flags prev = syslog_prev;
1164
1165 error = 0;
1166 while (seq < log_next_seq) {
1167 struct log *msg = log_from_idx(idx);
1168
1169 error += msg_print_text(msg, prev, true, NULL, 0);
1170 idx = log_next(idx);
1171 seq++;
1172 prev = msg->flags;
1173 }
1174 error -= syslog_partial;
1175 }
1176 raw_spin_unlock_irq(&logbuf_lock);
476 break; 1177 break;
477 /* Size of the log buffer */ 1178 /* Size of the log buffer */
478 case SYSLOG_ACTION_SIZE_BUFFER: 1179 case SYSLOG_ACTION_SIZE_BUFFER:
@@ -501,29 +1202,11 @@ void kdb_syslog_data(char *syslog_data[4])
501{ 1202{
502 syslog_data[0] = log_buf; 1203 syslog_data[0] = log_buf;
503 syslog_data[1] = log_buf + log_buf_len; 1204 syslog_data[1] = log_buf + log_buf_len;
504 syslog_data[2] = log_buf + log_end - 1205 syslog_data[2] = log_buf + log_first_idx;
505 (logged_chars < log_buf_len ? logged_chars : log_buf_len); 1206 syslog_data[3] = log_buf + log_next_idx;
506 syslog_data[3] = log_buf + log_end;
507} 1207}
508#endif /* CONFIG_KGDB_KDB */ 1208#endif /* CONFIG_KGDB_KDB */
509 1209
510/*
511 * Call the console drivers on a range of log_buf
512 */
513static void __call_console_drivers(unsigned start, unsigned end)
514{
515 struct console *con;
516
517 for_each_console(con) {
518 if (exclusive_console && con != exclusive_console)
519 continue;
520 if ((con->flags & CON_ENABLED) && con->write &&
521 (cpu_online(smp_processor_id()) ||
522 (con->flags & CON_ANYTIME)))
523 con->write(con, &LOG_BUF(start), end - start);
524 }
525}
526
527static bool __read_mostly ignore_loglevel; 1210static bool __read_mostly ignore_loglevel;
528 1211
529static int __init ignore_loglevel_setup(char *str) 1212static int __init ignore_loglevel_setup(char *str)
@@ -540,142 +1223,33 @@ MODULE_PARM_DESC(ignore_loglevel, "ignore loglevel setting, to"
540 "print all kernel messages to the console."); 1223 "print all kernel messages to the console.");
541 1224
542/* 1225/*
543 * Write out chars from start to end - 1 inclusive
544 */
545static void _call_console_drivers(unsigned start,
546 unsigned end, int msg_log_level)
547{
548 trace_console(&LOG_BUF(0), start, end, log_buf_len);
549
550 if ((msg_log_level < console_loglevel || ignore_loglevel) &&
551 console_drivers && start != end) {
552 if ((start & LOG_BUF_MASK) > (end & LOG_BUF_MASK)) {
553 /* wrapped write */
554 __call_console_drivers(start & LOG_BUF_MASK,
555 log_buf_len);
556 __call_console_drivers(0, end & LOG_BUF_MASK);
557 } else {
558 __call_console_drivers(start, end);
559 }
560 }
561}
562
563/*
564 * Parse the syslog header <[0-9]*>. The decimal value represents 32bit, the
565 * lower 3 bit are the log level, the rest are the log facility. In case
566 * userspace passes usual userspace syslog messages to /dev/kmsg or
567 * /dev/ttyprintk, the log prefix might contain the facility. Printk needs
568 * to extract the correct log level for in-kernel processing, and not mangle
569 * the original value.
570 *
571 * If a prefix is found, the length of the prefix is returned. If 'level' is
572 * passed, it will be filled in with the log level without a possible facility
573 * value. If 'special' is passed, the special printk prefix chars are accepted
574 * and returned. If no valid header is found, 0 is returned and the passed
575 * variables are not touched.
576 */
577static size_t log_prefix(const char *p, unsigned int *level, char *special)
578{
579 unsigned int lev = 0;
580 char sp = '\0';
581 size_t len;
582
583 if (p[0] != '<' || !p[1])
584 return 0;
585 if (p[2] == '>') {
586 /* usual single digit level number or special char */
587 switch (p[1]) {
588 case '0' ... '7':
589 lev = p[1] - '0';
590 break;
591 case 'c': /* KERN_CONT */
592 case 'd': /* KERN_DEFAULT */
593 sp = p[1];
594 break;
595 default:
596 return 0;
597 }
598 len = 3;
599 } else {
600 /* multi digit including the level and facility number */
601 char *endp = NULL;
602
603 lev = (simple_strtoul(&p[1], &endp, 10) & 7);
604 if (endp == NULL || endp[0] != '>')
605 return 0;
606 len = (endp + 1) - p;
607 }
608
609 /* do not accept special char if not asked for */
610 if (sp && !special)
611 return 0;
612
613 if (special) {
614 *special = sp;
615 /* return special char, do not touch level */
616 if (sp)
617 return len;
618 }
619
620 if (level)
621 *level = lev;
622 return len;
623}
624
625/*
626 * Call the console drivers, asking them to write out 1226 * Call the console drivers, asking them to write out
627 * log_buf[start] to log_buf[end - 1]. 1227 * log_buf[start] to log_buf[end - 1].
628 * The console_lock must be held. 1228 * The console_lock must be held.
629 */ 1229 */
630static void call_console_drivers(unsigned start, unsigned end) 1230static void call_console_drivers(int level, const char *text, size_t len)
631{ 1231{
632 unsigned cur_index, start_print; 1232 struct console *con;
633 static int msg_level = -1;
634 1233
635 BUG_ON(((int)(start - end)) > 0); 1234 trace_console(text, 0, len, len);
636 1235
637 cur_index = start; 1236 if (level >= console_loglevel && !ignore_loglevel)
638 start_print = start; 1237 return;
639 while (cur_index != end) { 1238 if (!console_drivers)
640 if (msg_level < 0 && ((end - cur_index) > 2)) { 1239 return;
641 /* strip log prefix */
642 cur_index += log_prefix(&LOG_BUF(cur_index), &msg_level, NULL);
643 start_print = cur_index;
644 }
645 while (cur_index != end) {
646 char c = LOG_BUF(cur_index);
647
648 cur_index++;
649 if (c == '\n') {
650 if (msg_level < 0) {
651 /*
652 * printk() has already given us loglevel tags in
653 * the buffer. This code is here in case the
654 * log buffer has wrapped right round and scribbled
655 * on those tags
656 */
657 msg_level = default_message_loglevel;
658 }
659 _call_console_drivers(start_print, cur_index, msg_level);
660 msg_level = -1;
661 start_print = cur_index;
662 break;
663 }
664 }
665 }
666 _call_console_drivers(start_print, end, msg_level);
667}
668 1240
669static void emit_log_char(char c) 1241 for_each_console(con) {
670{ 1242 if (exclusive_console && con != exclusive_console)
671 LOG_BUF(log_end) = c; 1243 continue;
672 log_end++; 1244 if (!(con->flags & CON_ENABLED))
673 if (log_end - log_start > log_buf_len) 1245 continue;
674 log_start = log_end - log_buf_len; 1246 if (!con->write)
675 if (log_end - con_start > log_buf_len) 1247 continue;
676 con_start = log_end - log_buf_len; 1248 if (!cpu_online(smp_processor_id()) &&
677 if (logged_chars < log_buf_len) 1249 !(con->flags & CON_ANYTIME))
678 logged_chars++; 1250 continue;
1251 con->write(con, text, len);
1252 }
679} 1253}
680 1254
681/* 1255/*
@@ -700,16 +1274,6 @@ static void zap_locks(void)
700 sema_init(&console_sem, 1); 1274 sema_init(&console_sem, 1);
701} 1275}
702 1276
703#if defined(CONFIG_PRINTK_TIME)
704static bool printk_time = 1;
705#else
706static bool printk_time = 0;
707#endif
708module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
709
710static bool always_kmsg_dump;
711module_param_named(always_kmsg_dump, always_kmsg_dump, bool, S_IRUGO | S_IWUSR);
712
713/* Check if we have any console registered that can be called early in boot. */ 1277/* Check if we have any console registered that can be called early in boot. */
714static int have_callable_console(void) 1278static int have_callable_console(void)
715{ 1279{
@@ -722,51 +1286,6 @@ static int have_callable_console(void)
722 return 0; 1286 return 0;
723} 1287}
724 1288
725/**
726 * printk - print a kernel message
727 * @fmt: format string
728 *
729 * This is printk(). It can be called from any context. We want it to work.
730 *
731 * We try to grab the console_lock. If we succeed, it's easy - we log the output and
732 * call the console drivers. If we fail to get the semaphore we place the output
733 * into the log buffer and return. The current holder of the console_sem will
734 * notice the new output in console_unlock(); and will send it to the
735 * consoles before releasing the lock.
736 *
737 * One effect of this deferred printing is that code which calls printk() and
738 * then changes console_loglevel may break. This is because console_loglevel
739 * is inspected when the actual printing occurs.
740 *
741 * See also:
742 * printf(3)
743 *
744 * See the vsnprintf() documentation for format string extensions over C99.
745 */
746
747asmlinkage int printk(const char *fmt, ...)
748{
749 va_list args;
750 int r;
751
752#ifdef CONFIG_KGDB_KDB
753 if (unlikely(kdb_trap_printk)) {
754 va_start(args, fmt);
755 r = vkdb_printf(fmt, args);
756 va_end(args);
757 return r;
758 }
759#endif
760 va_start(args, fmt);
761 r = vprintk(fmt, args);
762 va_end(args);
763
764 return r;
765}
766
767/* cpu currently holding logbuf_lock */
768static volatile unsigned int printk_cpu = UINT_MAX;
769
770/* 1289/*
771 * Can we actually use the console at this time on this cpu? 1290 * Can we actually use the console at this time on this cpu?
772 * 1291 *
@@ -810,17 +1329,12 @@ static int console_trylock_for_printk(unsigned int cpu)
810 retval = 0; 1329 retval = 0;
811 } 1330 }
812 } 1331 }
813 printk_cpu = UINT_MAX; 1332 logbuf_cpu = UINT_MAX;
814 if (wake) 1333 if (wake)
815 up(&console_sem); 1334 up(&console_sem);
816 raw_spin_unlock(&logbuf_lock); 1335 raw_spin_unlock(&logbuf_lock);
817 return retval; 1336 return retval;
818} 1337}
819static const char recursion_bug_msg [] =
820 KERN_CRIT "BUG: recent printk recursion!\n";
821static int recursion_bug;
822static int new_text_line = 1;
823static char printk_buf[1024];
824 1338
825int printk_delay_msec __read_mostly; 1339int printk_delay_msec __read_mostly;
826 1340
@@ -836,15 +1350,99 @@ static inline void printk_delay(void)
836 } 1350 }
837} 1351}
838 1352
839asmlinkage int vprintk(const char *fmt, va_list args) 1353/*
1354 * Continuation lines are buffered, and not committed to the record buffer
1355 * until the line is complete, or a race forces it. The line fragments
1356 * though, are printed immediately to the consoles to ensure everything has
1357 * reached the console in case of a kernel crash.
1358 */
1359static struct cont {
1360 char buf[LOG_LINE_MAX];
1361 size_t len; /* length == 0 means unused buffer */
1362 size_t cons; /* bytes written to console */
1363 struct task_struct *owner; /* task of first print*/
1364 u64 ts_nsec; /* time of first print */
1365 u8 level; /* log level of first message */
1366 u8 facility; /* log level of first message */
1367 bool flushed:1; /* buffer sealed and committed */
1368} cont;
1369
1370static void cont_flush(void)
840{ 1371{
841 int printed_len = 0; 1372 if (cont.flushed)
842 int current_log_level = default_message_loglevel; 1373 return;
1374 if (cont.len == 0)
1375 return;
1376
1377 log_store(cont.facility, cont.level, LOG_NOCONS, cont.ts_nsec,
1378 NULL, 0, cont.buf, cont.len);
1379
1380 cont.flushed = true;
1381}
1382
1383static bool cont_add(int facility, int level, const char *text, size_t len)
1384{
1385 if (cont.len && cont.flushed)
1386 return false;
1387
1388 if (cont.len + len > sizeof(cont.buf)) {
1389 cont_flush();
1390 return false;
1391 }
1392
1393 if (!cont.len) {
1394 cont.facility = facility;
1395 cont.level = level;
1396 cont.owner = current;
1397 cont.ts_nsec = local_clock();
1398 cont.cons = 0;
1399 cont.flushed = false;
1400 }
1401
1402 memcpy(cont.buf + cont.len, text, len);
1403 cont.len += len;
1404 return true;
1405}
1406
1407static size_t cont_print_text(char *text, size_t size)
1408{
1409 size_t textlen = 0;
1410 size_t len;
1411
1412 if (cont.cons == 0) {
1413 textlen += print_time(cont.ts_nsec, text);
1414 size -= textlen;
1415 }
1416
1417 len = cont.len - cont.cons;
1418 if (len > 0) {
1419 if (len+1 > size)
1420 len = size-1;
1421 memcpy(text + textlen, cont.buf + cont.cons, len);
1422 textlen += len;
1423 cont.cons = cont.len;
1424 }
1425
1426 if (cont.flushed) {
1427 text[textlen++] = '\n';
1428 /* got everything, release buffer */
1429 cont.len = 0;
1430 }
1431 return textlen;
1432}
1433
1434asmlinkage int vprintk_emit(int facility, int level,
1435 const char *dict, size_t dictlen,
1436 const char *fmt, va_list args)
1437{
1438 static int recursion_bug;
1439 static char textbuf[LOG_LINE_MAX];
1440 char *text = textbuf;
1441 size_t text_len;
1442 enum log_flags lflags = 0;
843 unsigned long flags; 1443 unsigned long flags;
844 int this_cpu; 1444 int this_cpu;
845 char *p; 1445 int printed_len = 0;
846 size_t plen;
847 char special;
848 1446
849 boot_delay_msec(); 1447 boot_delay_msec();
850 printk_delay(); 1448 printk_delay();
@@ -856,7 +1454,7 @@ asmlinkage int vprintk(const char *fmt, va_list args)
856 /* 1454 /*
857 * Ouch, printk recursed into itself! 1455 * Ouch, printk recursed into itself!
858 */ 1456 */
859 if (unlikely(printk_cpu == this_cpu)) { 1457 if (unlikely(logbuf_cpu == this_cpu)) {
860 /* 1458 /*
861 * If a crash is occurring during printk() on this CPU, 1459 * If a crash is occurring during printk() on this CPU,
862 * then try to get the crash message out but make sure 1460 * then try to get the crash message out but make sure
@@ -873,97 +1471,91 @@ asmlinkage int vprintk(const char *fmt, va_list args)
873 1471
874 lockdep_off(); 1472 lockdep_off();
875 raw_spin_lock(&logbuf_lock); 1473 raw_spin_lock(&logbuf_lock);
876 printk_cpu = this_cpu; 1474 logbuf_cpu = this_cpu;
877 1475
878 if (recursion_bug) { 1476 if (recursion_bug) {
1477 static const char recursion_msg[] =
1478 "BUG: recent printk recursion!";
1479
879 recursion_bug = 0; 1480 recursion_bug = 0;
880 strcpy(printk_buf, recursion_bug_msg); 1481 printed_len += strlen(recursion_msg);
881 printed_len = strlen(recursion_bug_msg); 1482 /* emit KERN_CRIT message */
1483 log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
1484 NULL, 0, recursion_msg, printed_len);
882 } 1485 }
883 /* Emit the output into the temporary buffer */
884 printed_len += vscnprintf(printk_buf + printed_len,
885 sizeof(printk_buf) - printed_len, fmt, args);
886 1486
887 p = printk_buf; 1487 /*
1488 * The printf needs to come first; we need the syslog
1489 * prefix which might be passed-in as a parameter.
1490 */
1491 text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
888 1492
889 /* Read log level and handle special printk prefix */ 1493 /* mark and strip a trailing newline */
890 plen = log_prefix(p, &current_log_level, &special); 1494 if (text_len && text[text_len-1] == '\n') {
891 if (plen) { 1495 text_len--;
892 p += plen; 1496 lflags |= LOG_NEWLINE;
1497 }
893 1498
894 switch (special) { 1499 /* strip syslog prefix and extract log level or control flags */
895 case 'c': /* Strip <c> KERN_CONT, continue line */ 1500 if (text[0] == '<' && text[1] && text[2] == '>') {
896 plen = 0; 1501 switch (text[1]) {
897 break; 1502 case '0' ... '7':
898 case 'd': /* Strip <d> KERN_DEFAULT, start new line */ 1503 if (level == -1)
899 plen = 0; 1504 level = text[1] - '0';
900 default: 1505 case 'd': /* KERN_DEFAULT */
901 if (!new_text_line) { 1506 lflags |= LOG_PREFIX;
902 emit_log_char('\n'); 1507 case 'c': /* KERN_CONT */
903 new_text_line = 1; 1508 text += 3;
904 } 1509 text_len -= 3;
905 } 1510 }
906 } 1511 }
907 1512
908 /* 1513 if (level == -1)
909 * Copy the output into log_buf. If the caller didn't provide 1514 level = default_message_loglevel;
910 * the appropriate log prefix, we insert them here
911 */
912 for (; *p; p++) {
913 if (new_text_line) {
914 new_text_line = 0;
915
916 if (plen) {
917 /* Copy original log prefix */
918 int i;
919
920 for (i = 0; i < plen; i++)
921 emit_log_char(printk_buf[i]);
922 printed_len += plen;
923 } else {
924 /* Add log prefix */
925 emit_log_char('<');
926 emit_log_char(current_log_level + '0');
927 emit_log_char('>');
928 printed_len += 3;
929 }
930 1515
931 if (printk_time) { 1516 if (dict)
932 /* Add the current time stamp */ 1517 lflags |= LOG_PREFIX|LOG_NEWLINE;
933 char tbuf[50], *tp;
934 unsigned tlen;
935 unsigned long long t;
936 unsigned long nanosec_rem;
937
938 t = cpu_clock(printk_cpu);
939 nanosec_rem = do_div(t, 1000000000);
940 tlen = sprintf(tbuf, "[%5lu.%06lu] ",
941 (unsigned long) t,
942 nanosec_rem / 1000);
943
944 for (tp = tbuf; tp < tbuf + tlen; tp++)
945 emit_log_char(*tp);
946 printed_len += tlen;
947 }
948 1518
949 if (!*p) 1519 if (!(lflags & LOG_NEWLINE)) {
950 break; 1520 /*
1521 * Flush the conflicting buffer. An earlier newline was missing,
1522 * or another task also prints continuation lines.
1523 */
1524 if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
1525 cont_flush();
1526
1527 /* buffer line if possible, otherwise store it right away */
1528 if (!cont_add(facility, level, text, text_len))
1529 log_store(facility, level, lflags | LOG_CONT, 0,
1530 dict, dictlen, text, text_len);
1531 } else {
1532 bool stored = false;
1533
1534 /*
1535 * If an earlier newline was missing and it was the same task,
1536 * either merge it with the current buffer and flush, or if
1537 * there was a race with interrupts (prefix == true) then just
1538 * flush it out and store this line separately.
1539 */
1540 if (cont.len && cont.owner == current) {
1541 if (!(lflags & LOG_PREFIX))
1542 stored = cont_add(facility, level, text, text_len);
1543 cont_flush();
951 } 1544 }
952 1545
953 emit_log_char(*p); 1546 if (!stored)
954 if (*p == '\n') 1547 log_store(facility, level, lflags, 0,
955 new_text_line = 1; 1548 dict, dictlen, text, text_len);
956 } 1549 }
1550 printed_len += text_len;
957 1551
958 /* 1552 /*
959 * Try to acquire and then immediately release the 1553 * Try to acquire and then immediately release the console semaphore.
960 * console semaphore. The release will do all the 1554 * The release will print out buffers and wake up /dev/kmsg and syslog()
961 * actual magic (print out buffers, wake up klogd, 1555 * users.
962 * etc).
963 * 1556 *
964 * The console_trylock_for_printk() function 1557 * The console_trylock_for_printk() function will release 'logbuf_lock'
965 * will release 'logbuf_lock' regardless of whether it 1558 * regardless of whether it actually gets the console semaphore or not.
966 * actually gets the semaphore or not.
967 */ 1559 */
968 if (console_trylock_for_printk(this_cpu)) 1560 if (console_trylock_for_printk(this_cpu))
969 console_unlock(); 1561 console_unlock();
@@ -974,16 +1566,88 @@ out_restore_irqs:
974 1566
975 return printed_len; 1567 return printed_len;
976} 1568}
977EXPORT_SYMBOL(printk); 1569EXPORT_SYMBOL(vprintk_emit);
978EXPORT_SYMBOL(vprintk);
979 1570
980#else 1571asmlinkage int vprintk(const char *fmt, va_list args)
1572{
1573 return vprintk_emit(0, -1, NULL, 0, fmt, args);
1574}
1575EXPORT_SYMBOL(vprintk);
981 1576
982static void call_console_drivers(unsigned start, unsigned end) 1577asmlinkage int printk_emit(int facility, int level,
1578 const char *dict, size_t dictlen,
1579 const char *fmt, ...)
983{ 1580{
1581 va_list args;
1582 int r;
1583
1584 va_start(args, fmt);
1585 r = vprintk_emit(facility, level, dict, dictlen, fmt, args);
1586 va_end(args);
1587
1588 return r;
984} 1589}
1590EXPORT_SYMBOL(printk_emit);
985 1591
1592/**
1593 * printk - print a kernel message
1594 * @fmt: format string
1595 *
1596 * This is printk(). It can be called from any context. We want it to work.
1597 *
1598 * We try to grab the console_lock. If we succeed, it's easy - we log the
1599 * output and call the console drivers. If we fail to get the semaphore, we
1600 * place the output into the log buffer and return. The current holder of
1601 * the console_sem will notice the new output in console_unlock(); and will
1602 * send it to the consoles before releasing the lock.
1603 *
1604 * One effect of this deferred printing is that code which calls printk() and
1605 * then changes console_loglevel may break. This is because console_loglevel
1606 * is inspected when the actual printing occurs.
1607 *
1608 * See also:
1609 * printf(3)
1610 *
1611 * See the vsnprintf() documentation for format string extensions over C99.
1612 */
1613asmlinkage int printk(const char *fmt, ...)
1614{
1615 va_list args;
1616 int r;
1617
1618#ifdef CONFIG_KGDB_KDB
1619 if (unlikely(kdb_trap_printk)) {
1620 va_start(args, fmt);
1621 r = vkdb_printf(fmt, args);
1622 va_end(args);
1623 return r;
1624 }
986#endif 1625#endif
1626 va_start(args, fmt);
1627 r = vprintk_emit(0, -1, NULL, 0, fmt, args);
1628 va_end(args);
1629
1630 return r;
1631}
1632EXPORT_SYMBOL(printk);
1633
1634#else
1635
1636#define LOG_LINE_MAX 0
1637static struct cont {
1638 size_t len;
1639 size_t cons;
1640 u8 level;
1641 bool flushed:1;
1642} cont;
1643static struct log *log_from_idx(u32 idx) { return NULL; }
1644static u32 log_next(u32 idx) { return 0; }
1645static void call_console_drivers(int level, const char *text, size_t len) {}
1646static size_t msg_print_text(const struct log *msg, enum log_flags prev,
1647 bool syslog, char *buf, size_t size) { return 0; }
1648static size_t cont_print_text(char *text, size_t size) { return 0; }
1649
1650#endif /* CONFIG_PRINTK */
987 1651
988static int __add_preferred_console(char *name, int idx, char *options, 1652static int __add_preferred_console(char *name, int idx, char *options,
989 char *brl_options) 1653 char *brl_options)
@@ -1217,7 +1881,7 @@ int is_console_locked(void)
1217} 1881}
1218 1882
1219/* 1883/*
1220 * Delayed printk facility, for scheduler-internal messages: 1884 * Delayed printk version, for scheduler-internal messages:
1221 */ 1885 */
1222#define PRINTK_BUF_SIZE 512 1886#define PRINTK_BUF_SIZE 512
1223 1887
@@ -1253,6 +1917,11 @@ void wake_up_klogd(void)
1253 this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP); 1917 this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
1254} 1918}
1255 1919
1920/* the next printk record to write to the console */
1921static u64 console_seq;
1922static u32 console_idx;
1923static enum log_flags console_prev;
1924
1256/** 1925/**
1257 * console_unlock - unlock the console system 1926 * console_unlock - unlock the console system
1258 * 1927 *
@@ -1263,15 +1932,17 @@ void wake_up_klogd(void)
1263 * by printk(). If this is the case, console_unlock(); emits 1932 * by printk(). If this is the case, console_unlock(); emits
1264 * the output prior to releasing the lock. 1933 * the output prior to releasing the lock.
1265 * 1934 *
1266 * If there is output waiting for klogd, we wake it up. 1935 * If there is output waiting, we wake /dev/kmsg and syslog() users.
1267 * 1936 *
1268 * console_unlock(); may be called from any context. 1937 * console_unlock(); may be called from any context.
1269 */ 1938 */
1270void console_unlock(void) 1939void console_unlock(void)
1271{ 1940{
1941 static char text[LOG_LINE_MAX];
1942 static u64 seen_seq;
1272 unsigned long flags; 1943 unsigned long flags;
1273 unsigned _con_start, _log_end; 1944 bool wake_klogd = false;
1274 unsigned wake_klogd = 0, retry = 0; 1945 bool retry;
1275 1946
1276 if (console_suspended) { 1947 if (console_suspended) {
1277 up(&console_sem); 1948 up(&console_sem);
@@ -1280,18 +1951,69 @@ void console_unlock(void)
1280 1951
1281 console_may_schedule = 0; 1952 console_may_schedule = 0;
1282 1953
1954 /* flush buffered message fragment immediately to console */
1955 raw_spin_lock_irqsave(&logbuf_lock, flags);
1956 if (cont.len && (cont.cons < cont.len || cont.flushed)) {
1957 size_t len;
1958
1959 len = cont_print_text(text, sizeof(text));
1960 raw_spin_unlock(&logbuf_lock);
1961 stop_critical_timings();
1962 call_console_drivers(cont.level, text, len);
1963 start_critical_timings();
1964 local_irq_restore(flags);
1965 } else
1966 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
1967
1283again: 1968again:
1284 for ( ; ; ) { 1969 for (;;) {
1970 struct log *msg;
1971 size_t len;
1972 int level;
1973
1285 raw_spin_lock_irqsave(&logbuf_lock, flags); 1974 raw_spin_lock_irqsave(&logbuf_lock, flags);
1286 wake_klogd |= log_start - log_end; 1975 if (seen_seq != log_next_seq) {
1287 if (con_start == log_end) 1976 wake_klogd = true;
1288 break; /* Nothing to print */ 1977 seen_seq = log_next_seq;
1289 _con_start = con_start; 1978 }
1290 _log_end = log_end; 1979
1291 con_start = log_end; /* Flush */ 1980 if (console_seq < log_first_seq) {
1981 /* messages are gone, move to first one */
1982 console_seq = log_first_seq;
1983 console_idx = log_first_idx;
1984 console_prev = 0;
1985 }
1986skip:
1987 if (console_seq == log_next_seq)
1988 break;
1989
1990 msg = log_from_idx(console_idx);
1991 if (msg->flags & LOG_NOCONS) {
1992 /*
1993 * Skip record we have buffered and already printed
1994 * directly to the console when we received it.
1995 */
1996 console_idx = log_next(console_idx);
1997 console_seq++;
1998 /*
1999 * We will get here again when we register a new
2000 * CON_PRINTBUFFER console. Clear the flag so we
2001 * will properly dump everything later.
2002 */
2003 msg->flags &= ~LOG_NOCONS;
2004 goto skip;
2005 }
2006
2007 level = msg->level;
2008 len = msg_print_text(msg, console_prev, false,
2009 text, sizeof(text));
2010 console_idx = log_next(console_idx);
2011 console_seq++;
2012 console_prev = msg->flags;
1292 raw_spin_unlock(&logbuf_lock); 2013 raw_spin_unlock(&logbuf_lock);
2014
1293 stop_critical_timings(); /* don't trace print latency */ 2015 stop_critical_timings(); /* don't trace print latency */
1294 call_console_drivers(_con_start, _log_end); 2016 call_console_drivers(level, text, len);
1295 start_critical_timings(); 2017 start_critical_timings();
1296 local_irq_restore(flags); 2018 local_irq_restore(flags);
1297 } 2019 }
@@ -1312,8 +2034,7 @@ again:
1312 * flush, no worries. 2034 * flush, no worries.
1313 */ 2035 */
1314 raw_spin_lock(&logbuf_lock); 2036 raw_spin_lock(&logbuf_lock);
1315 if (con_start != log_end) 2037 retry = console_seq != log_next_seq;
1316 retry = 1;
1317 raw_spin_unlock_irqrestore(&logbuf_lock, flags); 2038 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
1318 2039
1319 if (retry && console_trylock()) 2040 if (retry && console_trylock())
@@ -1549,7 +2270,9 @@ void register_console(struct console *newcon)
1549 * for us. 2270 * for us.
1550 */ 2271 */
1551 raw_spin_lock_irqsave(&logbuf_lock, flags); 2272 raw_spin_lock_irqsave(&logbuf_lock, flags);
1552 con_start = log_start; 2273 console_seq = syslog_seq;
2274 console_idx = syslog_idx;
2275 console_prev = syslog_prev;
1553 raw_spin_unlock_irqrestore(&logbuf_lock, flags); 2276 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
1554 /* 2277 /*
1555 * We're about to replay the log buffer. Only do this to the 2278 * We're about to replay the log buffer. Only do this to the
@@ -1758,50 +2481,221 @@ int kmsg_dump_unregister(struct kmsg_dumper *dumper)
1758} 2481}
1759EXPORT_SYMBOL_GPL(kmsg_dump_unregister); 2482EXPORT_SYMBOL_GPL(kmsg_dump_unregister);
1760 2483
2484static bool always_kmsg_dump;
2485module_param_named(always_kmsg_dump, always_kmsg_dump, bool, S_IRUGO | S_IWUSR);
2486
1761/** 2487/**
1762 * kmsg_dump - dump kernel log to kernel message dumpers. 2488 * kmsg_dump - dump kernel log to kernel message dumpers.
1763 * @reason: the reason (oops, panic etc) for dumping 2489 * @reason: the reason (oops, panic etc) for dumping
1764 * 2490 *
1765 * Iterate through each of the dump devices and call the oops/panic 2491 * Call each of the registered dumper's dump() callback, which can
1766 * callbacks with the log buffer. 2492 * retrieve the kmsg records with kmsg_dump_get_line() or
2493 * kmsg_dump_get_buffer().
1767 */ 2494 */
1768void kmsg_dump(enum kmsg_dump_reason reason) 2495void kmsg_dump(enum kmsg_dump_reason reason)
1769{ 2496{
1770 unsigned long end;
1771 unsigned chars;
1772 struct kmsg_dumper *dumper; 2497 struct kmsg_dumper *dumper;
1773 const char *s1, *s2;
1774 unsigned long l1, l2;
1775 unsigned long flags; 2498 unsigned long flags;
1776 2499
1777 if ((reason > KMSG_DUMP_OOPS) && !always_kmsg_dump) 2500 if ((reason > KMSG_DUMP_OOPS) && !always_kmsg_dump)
1778 return; 2501 return;
1779 2502
1780 /* Theoretically, the log could move on after we do this, but 2503 rcu_read_lock();
1781 there's not a lot we can do about that. The new messages 2504 list_for_each_entry_rcu(dumper, &dump_list, list) {
1782 will overwrite the start of what we dump. */ 2505 if (dumper->max_reason && reason > dumper->max_reason)
2506 continue;
2507
2508 /* initialize iterator with data about the stored records */
2509 dumper->active = true;
2510
2511 raw_spin_lock_irqsave(&logbuf_lock, flags);
2512 dumper->cur_seq = clear_seq;
2513 dumper->cur_idx = clear_idx;
2514 dumper->next_seq = log_next_seq;
2515 dumper->next_idx = log_next_idx;
2516 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
2517
2518 /* invoke dumper which will iterate over records */
2519 dumper->dump(dumper, reason);
2520
2521 /* reset iterator */
2522 dumper->active = false;
2523 }
2524 rcu_read_unlock();
2525}
2526
2527/**
2528 * kmsg_dump_get_line - retrieve one kmsg log line
2529 * @dumper: registered kmsg dumper
2530 * @syslog: include the "<4>" prefixes
2531 * @line: buffer to copy the line to
2532 * @size: maximum size of the buffer
2533 * @len: length of line placed into buffer
2534 *
2535 * Start at the beginning of the kmsg buffer, with the oldest kmsg
2536 * record, and copy one record into the provided buffer.
2537 *
2538 * Consecutive calls will return the next available record moving
2539 * towards the end of the buffer with the youngest messages.
2540 *
2541 * A return value of FALSE indicates that there are no more records to
2542 * read.
2543 */
2544bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
2545 char *line, size_t size, size_t *len)
2546{
2547 unsigned long flags;
2548 struct log *msg;
2549 size_t l = 0;
2550 bool ret = false;
2551
2552 if (!dumper->active)
2553 goto out;
2554
1783 raw_spin_lock_irqsave(&logbuf_lock, flags); 2555 raw_spin_lock_irqsave(&logbuf_lock, flags);
1784 end = log_end & LOG_BUF_MASK; 2556 if (dumper->cur_seq < log_first_seq) {
1785 chars = logged_chars; 2557 /* messages are gone, move to first available one */
2558 dumper->cur_seq = log_first_seq;
2559 dumper->cur_idx = log_first_idx;
2560 }
2561
2562 /* last entry */
2563 if (dumper->cur_seq >= log_next_seq) {
2564 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
2565 goto out;
2566 }
2567
2568 msg = log_from_idx(dumper->cur_idx);
2569 l = msg_print_text(msg, 0, syslog, line, size);
2570
2571 dumper->cur_idx = log_next(dumper->cur_idx);
2572 dumper->cur_seq++;
2573 ret = true;
1786 raw_spin_unlock_irqrestore(&logbuf_lock, flags); 2574 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
2575out:
2576 if (len)
2577 *len = l;
2578 return ret;
2579}
2580EXPORT_SYMBOL_GPL(kmsg_dump_get_line);
2581
2582/**
2583 * kmsg_dump_get_buffer - copy kmsg log lines
2584 * @dumper: registered kmsg dumper
2585 * @syslog: include the "<4>" prefixes
2586 * @buf: buffer to copy the line to
2587 * @size: maximum size of the buffer
2588 * @len: length of line placed into buffer
2589 *
2590 * Start at the end of the kmsg buffer and fill the provided buffer
2591 * with as many of the the *youngest* kmsg records that fit into it.
2592 * If the buffer is large enough, all available kmsg records will be
2593 * copied with a single call.
2594 *
2595 * Consecutive calls will fill the buffer with the next block of
2596 * available older records, not including the earlier retrieved ones.
2597 *
2598 * A return value of FALSE indicates that there are no more records to
2599 * read.
2600 */
2601bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
2602 char *buf, size_t size, size_t *len)
2603{
2604 unsigned long flags;
2605 u64 seq;
2606 u32 idx;
2607 u64 next_seq;
2608 u32 next_idx;
2609 enum log_flags prev;
2610 size_t l = 0;
2611 bool ret = false;
2612
2613 if (!dumper->active)
2614 goto out;
1787 2615
1788 if (chars > end) { 2616 raw_spin_lock_irqsave(&logbuf_lock, flags);
1789 s1 = log_buf + log_buf_len - chars + end; 2617 if (dumper->cur_seq < log_first_seq) {
1790 l1 = chars - end; 2618 /* messages are gone, move to first available one */
2619 dumper->cur_seq = log_first_seq;
2620 dumper->cur_idx = log_first_idx;
2621 }
1791 2622
1792 s2 = log_buf; 2623 /* last entry */
1793 l2 = end; 2624 if (dumper->cur_seq >= dumper->next_seq) {
1794 } else { 2625 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
1795 s1 = ""; 2626 goto out;
1796 l1 = 0; 2627 }
1797 2628
1798 s2 = log_buf + end - chars; 2629 /* calculate length of entire buffer */
1799 l2 = chars; 2630 seq = dumper->cur_seq;
2631 idx = dumper->cur_idx;
2632 prev = 0;
2633 while (seq < dumper->next_seq) {
2634 struct log *msg = log_from_idx(idx);
2635
2636 l += msg_print_text(msg, prev, true, NULL, 0);
2637 idx = log_next(idx);
2638 seq++;
2639 prev = msg->flags;
1800 } 2640 }
1801 2641
1802 rcu_read_lock(); 2642 /* move first record forward until length fits into the buffer */
1803 list_for_each_entry_rcu(dumper, &dump_list, list) 2643 seq = dumper->cur_seq;
1804 dumper->dump(dumper, reason, s1, l1, s2, l2); 2644 idx = dumper->cur_idx;
1805 rcu_read_unlock(); 2645 prev = 0;
2646 while (l > size && seq < dumper->next_seq) {
2647 struct log *msg = log_from_idx(idx);
2648
2649 l -= msg_print_text(msg, prev, true, NULL, 0);
2650 idx = log_next(idx);
2651 seq++;
2652 prev = msg->flags;
2653 }
2654
2655 /* last message in next interation */
2656 next_seq = seq;
2657 next_idx = idx;
2658
2659 l = 0;
2660 prev = 0;
2661 while (seq < dumper->next_seq) {
2662 struct log *msg = log_from_idx(idx);
2663
2664 l += msg_print_text(msg, prev, syslog, buf + l, size - l);
2665 idx = log_next(idx);
2666 seq++;
2667 prev = msg->flags;
2668 }
2669
2670 dumper->next_seq = next_seq;
2671 dumper->next_idx = next_idx;
2672 ret = true;
2673 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
2674out:
2675 if (len)
2676 *len = l;
2677 return ret;
2678}
2679EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
2680
2681/**
2682 * kmsg_dump_rewind - reset the interator
2683 * @dumper: registered kmsg dumper
2684 *
2685 * Reset the dumper's iterator so that kmsg_dump_get_line() and
2686 * kmsg_dump_get_buffer() can be called again and used multiple
2687 * times within the same dumper.dump() callback.
2688 */
2689void kmsg_dump_rewind(struct kmsg_dumper *dumper)
2690{
2691 unsigned long flags;
2692
2693 raw_spin_lock_irqsave(&logbuf_lock, flags);
2694 dumper->cur_seq = clear_seq;
2695 dumper->cur_idx = clear_idx;
2696 dumper->next_seq = log_next_seq;
2697 dumper->next_idx = log_next_idx;
2698 raw_spin_unlock_irqrestore(&logbuf_lock, flags);
1806} 2699}
2700EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
1807#endif 2701#endif