diff --git a/arch/powerpc/kernel/nvram_64.c b/arch/powerpc/kernel/nvram_64.c index 532f226377831d89c592696df54794eaab311a8f..1ef55f4b389a2990ff3dc6edc8f86f43047b3ec8 100644 --- a/arch/powerpc/kernel/nvram_64.c +++ b/arch/powerpc/kernel/nvram_64.c @@ -73,7 +73,8 @@ static const char *nvram_os_partitions[] = { }; static void oops_to_nvram(struct kmsg_dumper *dumper, - enum kmsg_dump_reason reason); + enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter); static struct kmsg_dumper nvram_kmsg_dumper = { .dump = oops_to_nvram @@ -643,7 +644,8 @@ void __init nvram_init_oops_partition(int rtas_partition_exists) * partition. If that's too much, go back and capture uncompressed text. */ static void oops_to_nvram(struct kmsg_dumper *dumper, - enum kmsg_dump_reason reason) + enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter) { struct oops_log_info *oops_hdr = (struct oops_log_info *)oops_buf; static unsigned int oops_count = 0; @@ -681,13 +683,13 @@ static void oops_to_nvram(struct kmsg_dumper *dumper, return; if (big_oops_buf) { - kmsg_dump_get_buffer(dumper, false, + kmsg_dump_get_buffer(iter, false, big_oops_buf, big_oops_buf_sz, &text_len); rc = zip_oops(text_len); } if (rc != 0) { - kmsg_dump_rewind(dumper); - kmsg_dump_get_buffer(dumper, false, + kmsg_dump_rewind(iter); + kmsg_dump_get_buffer(iter, false, oops_data, oops_data_sz, &text_len); err_type = ERR_TYPE_KERNEL_PANIC; oops_hdr->version = cpu_to_be16(OOPS_HDR_VERSION); diff --git a/arch/powerpc/platforms/powernv/opal-kmsg.c b/arch/powerpc/platforms/powernv/opal-kmsg.c index 6c3bc4b4da9834966f7fd19eb28454ac33988b9e..ec862846bc82cbb1c2681f0ba3a7ef271c311878 100644 --- a/arch/powerpc/platforms/powernv/opal-kmsg.c +++ b/arch/powerpc/platforms/powernv/opal-kmsg.c @@ -20,7 +20,8 @@ * message, it just ensures that OPAL completely flushes the console buffer. */ static void kmsg_dump_opal_console_flush(struct kmsg_dumper *dumper, - enum kmsg_dump_reason reason) + enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter) { /* * Outside of a panic context the pollers will continue to run, diff --git a/arch/powerpc/xmon/xmon.c b/arch/powerpc/xmon/xmon.c index 5559edf36756c429cae207f58312ca85feced26b..b71690e8245b5998cd893e65bdfd8c8556612bdf 100644 --- a/arch/powerpc/xmon/xmon.c +++ b/arch/powerpc/xmon/xmon.c @@ -3005,7 +3005,7 @@ print_address(unsigned long addr) static void dump_log_buf(void) { - struct kmsg_dumper dumper = { .active = 1 }; + struct kmsg_dumper_iter iter = { .active = 1 }; unsigned char buf[128]; size_t len; @@ -3017,9 +3017,9 @@ dump_log_buf(void) catch_memory_errors = 1; sync(); - kmsg_dump_rewind_nolock(&dumper); + kmsg_dump_rewind_nolock(&iter); xmon_start_pagination(); - while (kmsg_dump_get_line_nolock(&dumper, false, buf, sizeof(buf), &len)) { + while (kmsg_dump_get_line_nolock(&iter, false, buf, sizeof(buf), &len)) { buf[len] = '\0'; printf("%s", buf); } diff --git a/arch/um/kernel/kmsg_dump.c b/arch/um/kernel/kmsg_dump.c index e4abac6c9727cc274647b47da116c1dfeae4e6d8..f38349ad00ead0693091d2768940859dbc8039e4 100644 --- a/arch/um/kernel/kmsg_dump.c +++ b/arch/um/kernel/kmsg_dump.c @@ -6,7 +6,8 @@ #include static void kmsg_dumper_stdout(struct kmsg_dumper *dumper, - enum kmsg_dump_reason reason) + enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter) { static char line[1024]; struct console *con; @@ -25,7 +26,7 @@ static void kmsg_dumper_stdout(struct kmsg_dumper *dumper, return; printf("kmsg_dump:\n"); - while (kmsg_dump_get_line(dumper, true, line, sizeof(line), &len)) { + while (kmsg_dump_get_line(iter, true, line, sizeof(line), &len)) { line[len] = '\0'; printf("%s", line); } diff --git a/drivers/hv/vmbus_drv.c b/drivers/hv/vmbus_drv.c index 5d820037e29183902361a5af893ed2b23eb74675..13d56054e3d2ace17ec69b4c1d4d3e85644195e9 100644 --- a/drivers/hv/vmbus_drv.c +++ b/drivers/hv/vmbus_drv.c @@ -1359,7 +1359,8 @@ static void vmbus_isr(void) * buffer and call into Hyper-V to transfer the data. */ static void hv_kmsg_dump(struct kmsg_dumper *dumper, - enum kmsg_dump_reason reason) + enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter) { size_t bytes_written; phys_addr_t panic_pa; @@ -1374,7 +1375,7 @@ static void hv_kmsg_dump(struct kmsg_dumper *dumper, * Write dump contents to the page. No need to synchronize; panic should * be single-threaded. */ - kmsg_dump_get_buffer(dumper, false, hv_panic_page, HV_HYP_PAGE_SIZE, + kmsg_dump_get_buffer(iter, false, hv_panic_page, HV_HYP_PAGE_SIZE, &bytes_written); if (bytes_written) hyperv_report_panic_msg(panic_pa, bytes_written); diff --git a/drivers/mtd/mtdoops.c b/drivers/mtd/mtdoops.c index 774970bfcf859621148347f5c453dcf41f3aa0be..6bc2c728adb73a4c8bf82916d027bb9a0b035552 100644 --- a/drivers/mtd/mtdoops.c +++ b/drivers/mtd/mtdoops.c @@ -267,7 +267,8 @@ static void find_next_position(struct mtdoops_context *cxt) } static void mtdoops_do_dump(struct kmsg_dumper *dumper, - enum kmsg_dump_reason reason) + enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter) { struct mtdoops_context *cxt = container_of(dumper, struct mtdoops_context, dump); @@ -276,7 +277,7 @@ static void mtdoops_do_dump(struct kmsg_dumper *dumper, if (reason == KMSG_DUMP_OOPS && !dump_oops) return; - kmsg_dump_get_buffer(dumper, true, cxt->oops_buf + MTDOOPS_HEADER_SIZE, + kmsg_dump_get_buffer(iter, true, cxt->oops_buf + MTDOOPS_HEADER_SIZE, record_size - MTDOOPS_HEADER_SIZE, NULL); if (reason != KMSG_DUMP_OOPS) { diff --git a/fs/pstore/platform.c b/fs/pstore/platform.c index 17d7bc27f41a37853404e8fa0ac6e607de419a1a..567decf3b53f00c2992f086fd1b083925fcdff3b 100644 --- a/fs/pstore/platform.c +++ b/fs/pstore/platform.c @@ -382,7 +382,8 @@ void pstore_record_init(struct pstore_record *record, * end of the buffer. */ static void pstore_do_dump(struct kmsg_dumper *dumper, - enum kmsg_dump_reason reason, struct pstore_info *psinfo, int pos) + enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter, struct pstore_info *psinfo, int pos) { unsigned long total = 0; const char *why; @@ -432,7 +433,7 @@ static void pstore_do_dump(struct kmsg_dumper *dumper, dst_size -= header_size; /* Write dump contents. */ - if (!kmsg_dump_get_buffer(dumper, true, dst + header_size, + if (!kmsg_dump_get_buffer(iter, true, dst + header_size, dst_size, &dump_size)) break; @@ -465,14 +466,15 @@ static void pstore_do_dump(struct kmsg_dumper *dumper, } static void pstore_dump(struct kmsg_dumper *dumper, - enum kmsg_dump_reason reason) + enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter) { struct pstore_info_list *entry; rcu_read_lock(); list_for_each_entry_rcu(entry, &psback->list_entry, list) if (entry->psi->flags & PSTORE_FLAGS_DMESG) - pstore_do_dump(dumper, reason, entry->psi, entry->index); + pstore_do_dump(dumper, reason, iter, entry->psi, entry->index); rcu_read_unlock(); } diff --git a/include/linux/kmsg_dump.h b/include/linux/kmsg_dump.h index 3378bcbe585eac4e76e93c768c287f6fd9c2eab8..2fdb10ab179948e57e5b82e9f36c42ccba8b61d0 100644 --- a/include/linux/kmsg_dump.h +++ b/include/linux/kmsg_dump.h @@ -29,6 +29,18 @@ enum kmsg_dump_reason { KMSG_DUMP_MAX }; +/** + * struct kmsg_dumper_iter - iterator for kernel crash message dumper + * @active: Flag that specifies if this is currently dumping + * @cur_seq: Points to the oldest message to dump (private) + * @next_seq: Points after the newest message to dump (private) + */ +struct kmsg_dumper_iter { + bool active; + u64 cur_seq; + u64 next_seq; +}; + /** * struct kmsg_dumper - kernel crash message dumper structure * @list: Entry in the dumper list (private) @@ -39,33 +51,27 @@ enum kmsg_dump_reason { */ struct kmsg_dumper { struct list_head list; - void (*dump)(struct kmsg_dumper *dumper, enum kmsg_dump_reason reason); + void (*dump)(struct kmsg_dumper *dumper, enum kmsg_dump_reason reason, + struct kmsg_dumper_iter *iter); enum kmsg_dump_reason max_reason; - bool active; bool registered; - - /* private state of the kmsg iterator */ - u32 cur_idx; - u32 next_idx; - u64 cur_seq; - u64 next_seq; }; #ifdef CONFIG_PRINTK void kmsg_dump(enum kmsg_dump_reason reason); -bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog, +bool kmsg_dump_get_line_nolock(struct kmsg_dumper_iter *iter, bool syslog, char *line, size_t size, size_t *len); -bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog, +bool kmsg_dump_get_line(struct kmsg_dumper_iter *iter, bool syslog, char *line, size_t size, size_t *len); -bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog, - char *buf, size_t size, size_t *len); +bool kmsg_dump_get_buffer(struct kmsg_dumper_iter *iter, bool syslog, + char *buf, size_t size, size_t *len_out); -void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper); +void kmsg_dump_rewind_nolock(struct kmsg_dumper_iter *iter); -void kmsg_dump_rewind(struct kmsg_dumper *dumper); +void kmsg_dump_rewind(struct kmsg_dumper_iter *dumper_iter); int kmsg_dump_register(struct kmsg_dumper *dumper); @@ -77,30 +83,30 @@ static inline void kmsg_dump(enum kmsg_dump_reason reason) { } -static inline bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, +static inline bool kmsg_dump_get_line_nolock(struct kmsg_dumper_iter *iter, bool syslog, const char *line, size_t size, size_t *len) { return false; } -static inline bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog, +static inline bool kmsg_dump_get_line(struct kmsg_dumper_iter *iter, bool syslog, const char *line, size_t size, size_t *len) { return false; } -static inline bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog, +static inline bool kmsg_dump_get_buffer(struct kmsg_dumper_iter *iter, bool syslog, char *buf, size_t size, size_t *len) { return false; } -static inline void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper) +static inline void kmsg_dump_rewind_nolock(struct kmsg_dumper_iter *iter) { } -static inline void kmsg_dump_rewind(struct kmsg_dumper *dumper) +static inline void kmsg_dump_rewind(struct kmsg_dumper_iter *iter) { } diff --git a/kernel/debug/kdb/kdb_main.c b/kernel/debug/kdb/kdb_main.c index 4e09fab52faf50beed7f4af7de696d4689c16d40..048baadd7a41c21af0f4c6037bf67eb6a298eb20 100644 --- a/kernel/debug/kdb/kdb_main.c +++ b/kernel/debug/kdb/kdb_main.c @@ -2157,7 +2157,7 @@ static int kdb_dmesg(int argc, const char **argv) int adjust = 0; int n = 0; int skip = 0; - struct kmsg_dumper dumper = { .active = 1 }; + struct kmsg_dumper_iter iter = { .active = 1 }; size_t len; char buf[201]; @@ -2182,8 +2182,8 @@ static int kdb_dmesg(int argc, const char **argv) kdb_set(2, setargs); } - kmsg_dump_rewind_nolock(&dumper); - while (kmsg_dump_get_line_nolock(&dumper, 1, NULL, 0, NULL)) + kmsg_dump_rewind_nolock(&iter); + while (kmsg_dump_get_line_nolock(&iter, 1, NULL, 0, NULL)) n++; if (lines < 0) { @@ -2215,8 +2215,8 @@ static int kdb_dmesg(int argc, const char **argv) if (skip >= n || skip < 0) return 0; - kmsg_dump_rewind_nolock(&dumper); - while (kmsg_dump_get_line_nolock(&dumper, 1, buf, sizeof(buf), &len)) { + kmsg_dump_rewind_nolock(&iter); + while (kmsg_dump_get_line_nolock(&iter, 1, buf, sizeof(buf), &len)) { if (skip) { skip--; continue; diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index dcb1354154cca953d0ffb9ec65095f359a6222a1..41acad5250c6d19fe07f05637ab30c38f577c5a4 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -403,8 +403,12 @@ DEFINE_RAW_SPINLOCK(logbuf_lock); printk_safe_exit_irqrestore(flags); \ } while (0) +/* syslog_lock protects syslog_* variables and write access to clear_seq. */ +static DEFINE_RAW_SPINLOCK(syslog_lock); + #ifdef CONFIG_PRINTK DECLARE_WAIT_QUEUE_HEAD(log_wait); +/* All 3 protected by @syslog_lock. */ /* the next printk record to read by syslog(READ) or /proc/kmsg */ static u64 syslog_seq; static size_t syslog_partial; @@ -415,16 +419,34 @@ static u64 console_seq; static u64 exclusive_console_stop_seq; static unsigned long console_dropped; -/* the next printk record to read after the last 'clear' command */ -static u64 clear_seq; +struct latched_seq { + seqcount_latch_t latch; + u64 val[2]; +}; + +/* + * The next printk record to read after the last 'clear' command. There are + * two copies (updated with seqcount_latch) so that reads can locklessly + * access a valid value. Writers are synchronized by @syslog_lock. + */ +static struct latched_seq clear_seq = { + .latch = SEQCNT_LATCH_ZERO(clear_seq.latch), + .val[0] = 0, + .val[1] = 0, +}; #ifdef CONFIG_PRINTK_CALLER #define PREFIX_MAX 48 #else #define PREFIX_MAX 32 #endif + +/* the maximum size allowed to be reserved for a record */ #define LOG_LINE_MAX (1024 - PREFIX_MAX) +/* the maximum size of a formatted record (i.e. with prefix added per line) */ +#define CONSOLE_LOG_MAX 4096 + #define LOG_LEVEL(v) ((v) & 0x07) #define LOG_FACILITY(v) ((v) >> 3 & 0xff) @@ -465,6 +487,31 @@ bool printk_percpu_data_ready(void) return __printk_percpu_data_ready; } +/* Must be called under syslog_lock. */ +static void latched_seq_write(struct latched_seq *ls, u64 val) +{ + raw_write_seqcount_latch(&ls->latch); + ls->val[0] = val; + raw_write_seqcount_latch(&ls->latch); + ls->val[1] = val; +} + +/* Can be called from any context. */ +static u64 latched_seq_read_nolock(struct latched_seq *ls) +{ + unsigned int seq; + unsigned int idx; + u64 val; + + do { + seq = raw_read_seqcount_latch(&ls->latch); + idx = seq & 0x1; + val = ls->val[idx]; + } while (read_seqcount_latch_retry(&ls->latch, seq)); + + return val; +} + /* Return log buffer address */ char *log_buf_addr_get(void) { @@ -504,52 +551,6 @@ static void truncate_msg(u16 *text_len, u16 *trunc_msg_len) *trunc_msg_len = 0; } -/* insert record into the buffer, discard old ones, update heads */ -static int log_store(u32 caller_id, int facility, int level, - enum log_flags flags, u64 ts_nsec, - const struct dev_printk_info *dev_info, - const char *text, u16 text_len) -{ - struct prb_reserved_entry e; - struct printk_record r; - u16 trunc_msg_len = 0; - - prb_rec_init_wr(&r, text_len); - - if (!prb_reserve(&e, prb, &r)) { - /* truncate the message if it is too long for empty buffer */ - truncate_msg(&text_len, &trunc_msg_len); - prb_rec_init_wr(&r, text_len + trunc_msg_len); - /* survive when the log buffer is too small for trunc_msg */ - if (!prb_reserve(&e, prb, &r)) - return 0; - } - - /* fill message */ - memcpy(&r.text_buf[0], text, text_len); - if (trunc_msg_len) - memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len); - r.info->text_len = text_len + trunc_msg_len; - r.info->facility = facility; - r.info->level = level & 7; - r.info->flags = flags & 0x1f; - if (ts_nsec > 0) - r.info->ts_nsec = ts_nsec; - else - r.info->ts_nsec = local_clock(); - r.info->caller_id = caller_id; - if (dev_info) - memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info)); - - /* A message without a trailing newline can be continued. */ - if (!(flags & LOG_NEWLINE)) - prb_commit(&e); - else - prb_final_commit(&e); - - return (text_len + trunc_msg_len); -} - int dmesg_restrict = IS_ENABLED(CONFIG_SECURITY_DMESG_RESTRICT); static int syslog_action_restricted(int type) @@ -678,7 +679,7 @@ static ssize_t msg_print_ext_body(char *buf, size_t size, /* /dev/kmsg - userspace message inject/listen interface */ struct devkmsg_user { - u64 seq; + atomic64_t seq; struct ratelimit_state rs; struct mutex lock; char buf[CONSOLE_EXT_LOG_MAX]; @@ -780,7 +781,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf, return ret; logbuf_lock_irq(); - if (!prb_read_valid(prb, user->seq, r)) { + if (!prb_read_valid(prb, atomic64_read(&user->seq), r)) { if (file->f_flags & O_NONBLOCK) { ret = -EAGAIN; logbuf_unlock_irq(); @@ -789,15 +790,15 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf, logbuf_unlock_irq(); ret = wait_event_interruptible(log_wait, - prb_read_valid(prb, user->seq, r)); + prb_read_valid(prb, atomic64_read(&user->seq), r)); if (ret) goto out; logbuf_lock_irq(); } - if (r->info->seq != user->seq) { + if (r->info->seq != atomic64_read(&user->seq)) { /* our last seen message is gone, return error and reset */ - user->seq = r->info->seq; + atomic64_set(&user->seq, r->info->seq); ret = -EPIPE; logbuf_unlock_irq(); goto out; @@ -808,7 +809,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf, &r->text_buf[0], r->info->text_len, &r->info->dev_info); - user->seq = r->info->seq + 1; + atomic64_set(&user->seq, r->info->seq + 1); logbuf_unlock_irq(); if (len > count) { @@ -848,7 +849,7 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence) switch (whence) { case SEEK_SET: /* the first record */ - user->seq = prb_first_valid_seq(prb); + atomic64_set(&user->seq, prb_first_valid_seq(prb)); break; case SEEK_DATA: /* @@ -856,11 +857,11 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence) * like issued by 'dmesg -c'. Reading /dev/kmsg itself * changes no global state, and does not clear anything. */ - user->seq = clear_seq; + atomic64_set(&user->seq, latched_seq_read_nolock(&clear_seq)); break; case SEEK_END: /* after the last record */ - user->seq = prb_next_seq(prb); + atomic64_set(&user->seq, prb_next_seq(prb)); break; default: ret = -EINVAL; @@ -883,7 +884,7 @@ static __poll_t devkmsg_poll(struct file *file, poll_table *wait) logbuf_lock_irq(); if (prb_read_valid_info(prb, user->seq, &info, NULL)) { /* return error when data has vanished underneath us */ - if (info.seq != user->seq) + if (info.seq != atomic64_read(&user->seq)) ret = EPOLLIN|EPOLLRDNORM|EPOLLERR|EPOLLPRI; else ret = EPOLLIN|EPOLLRDNORM; @@ -922,7 +923,7 @@ static int devkmsg_open(struct inode *inode, struct file *file) &user->text_buf[0], sizeof(user->text_buf)); logbuf_lock_irq(); - user->seq = prb_first_valid_seq(prb); + atomic64_set(&user->seq, prb_first_valid_seq(prb)); logbuf_unlock_irq(); file->private_data = user; @@ -1015,6 +1016,9 @@ void log_buf_vmcoreinfo_setup(void) VMCOREINFO_SIZE(atomic_long_t); VMCOREINFO_TYPE_OFFSET(atomic_long_t, counter); + + VMCOREINFO_STRUCT_SIZE(latched_seq); + VMCOREINFO_OFFSET(latched_seq, val); } #endif @@ -1186,7 +1190,7 @@ void __init setup_log_buf(int early) new_descs, ilog2(new_descs_count), new_infos); - logbuf_lock_irqsave(flags); + printk_safe_enter_irqsave(flags); log_buf_len = new_log_buf_len; log_buf = new_log_buf; @@ -1203,7 +1207,7 @@ void __init setup_log_buf(int early) */ prb = &printk_rb_dynamic; - logbuf_unlock_irqrestore(flags); + printk_safe_exit_irqrestore(flags); if (seq != prb_next_seq(&printk_rb_static)) { pr_err("dropped %llu messages\n", @@ -1481,6 +1485,50 @@ static size_t get_record_print_text_size(struct printk_info *info, return ((prefix_len * line_count) + info->text_len + 1); } +/* + * Beginning with @start_seq, find the first record where it and all following + * records up to (but not including) @max_seq fit into @size. + * + * @max_seq is simply an upper bound and does not need to exist. If the caller + * does not require an upper bound, -1 can be used for @max_seq. + */ +static u64 find_first_fitting_seq(u64 start_seq, u64 max_seq, size_t size, + bool syslog, bool time) +{ + struct printk_info info; + unsigned int line_count; + size_t len = 0; + u64 seq; + + /* Determine the size of the records up to @max_seq. */ + prb_for_each_info(start_seq, prb, seq, &info, &line_count) { + if (info.seq >= max_seq) + break; + len += get_record_print_text_size(&info, line_count, syslog, time); + } + + /* + * Adjust the upper bound for the next loop to avoid subtracting + * lengths that were never added. + */ + if (seq < max_seq) + max_seq = seq; + + /* + * Move first record forward until length fits into the buffer. Ignore + * newest messages that were not counted in the above cycle. Messages + * might appear and get lost in the meantime. This is a best effort + * that prevents an infinite loop that could occur with a retry. + */ + prb_for_each_info(start_seq, prb, seq, &info, &line_count) { + if (len <= size || info.seq >= max_seq) + break; + len -= get_record_print_text_size(&info, line_count, syslog, time); + } + + return seq; +} + static int syslog_print(char __user *buf, int size) { struct printk_info info; @@ -1488,18 +1536,20 @@ static int syslog_print(char __user *buf, int size) char *text; int len = 0; - text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL); + text = kmalloc(CONSOLE_LOG_MAX, GFP_KERNEL); if (!text) return -ENOMEM; - prb_rec_init_rd(&r, &info, text, LOG_LINE_MAX + PREFIX_MAX); + prb_rec_init_rd(&r, &info, text, CONSOLE_LOG_MAX); while (size > 0) { size_t n; size_t skip; logbuf_lock_irq(); + raw_spin_lock(&syslog_lock); if (!prb_read_valid(prb, syslog_seq, &r)) { + raw_spin_unlock(&syslog_lock); logbuf_unlock_irq(); break; } @@ -1529,6 +1579,7 @@ static int syslog_print(char __user *buf, int size) syslog_partial += n; } else n = 0; + raw_spin_unlock(&syslog_lock); logbuf_unlock_irq(); if (!n) @@ -1552,14 +1603,13 @@ static int syslog_print(char __user *buf, int size) static int syslog_print_all(char __user *buf, int size, bool clear) { struct printk_info info; - unsigned int line_count; struct printk_record r; char *text; int len = 0; u64 seq; bool time; - text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL); + text = kmalloc(CONSOLE_LOG_MAX, GFP_KERNEL); if (!text) return -ENOMEM; @@ -1569,17 +1619,10 @@ static int syslog_print_all(char __user *buf, int size, bool clear) * Find first record that fits, including all following records, * into the user-provided buffer for this dump. */ - prb_for_each_info(clear_seq, prb, seq, &info, &line_count) - len += get_record_print_text_size(&info, line_count, true, time); + seq = find_first_fitting_seq(latched_seq_read_nolock(&clear_seq), -1, + size, true, time); - /* move first record forward until length fits into the buffer */ - prb_for_each_info(clear_seq, prb, seq, &info, &line_count) { - if (len <= size) - break; - len -= get_record_print_text_size(&info, line_count, true, time); - } - - prb_rec_init_rd(&r, &info, text, LOG_LINE_MAX + PREFIX_MAX); + prb_rec_init_rd(&r, &info, text, CONSOLE_LOG_MAX); len = 0; prb_for_each_record(seq, prb, seq, &r) { @@ -1603,8 +1646,11 @@ static int syslog_print_all(char __user *buf, int size, bool clear) break; } - if (clear) - clear_seq = seq; + if (clear) { + raw_spin_lock(&syslog_lock); + latched_seq_write(&clear_seq, seq); + raw_spin_unlock(&syslog_lock); + } logbuf_unlock_irq(); kfree(text); @@ -1614,10 +1660,24 @@ static int syslog_print_all(char __user *buf, int size, bool clear) static void syslog_clear(void) { logbuf_lock_irq(); - clear_seq = prb_next_seq(prb); + raw_spin_lock(&syslog_lock); + latched_seq_write(&clear_seq, prb_next_seq(prb)); + raw_spin_unlock(&syslog_lock); logbuf_unlock_irq(); } +/* Return a consistent copy of @syslog_seq. */ +static u64 read_syslog_seq_irq(void) +{ + u64 seq; + + raw_spin_lock_irq(&syslog_lock); + seq = syslog_seq; + raw_spin_unlock_irq(&syslog_lock); + + return seq; +} + int do_syslog(int type, char __user *buf, int len, int source) { struct printk_info info; @@ -1641,8 +1701,9 @@ int do_syslog(int type, char __user *buf, int len, int source) return 0; if (!access_ok(buf, len)) return -EFAULT; + error = wait_event_interruptible(log_wait, - prb_read_valid(prb, syslog_seq, NULL)); + prb_read_valid(prb, read_syslog_seq_irq(), NULL)); if (error) return error; error = syslog_print(buf, len); @@ -1691,8 +1752,10 @@ int do_syslog(int type, char __user *buf, int len, int source) /* Number of chars in the log buffer */ case SYSLOG_ACTION_SIZE_UNREAD: logbuf_lock_irq(); + raw_spin_lock(&syslog_lock); if (!prb_read_valid_info(prb, syslog_seq, &info, NULL)) { /* No unread messages. */ + raw_spin_unlock(&syslog_lock); logbuf_unlock_irq(); return 0; } @@ -1721,6 +1784,7 @@ int do_syslog(int type, char __user *buf, int len, int source) } error -= syslog_partial; } + raw_spin_unlock(&syslog_lock); logbuf_unlock_irq(); break; /* Size of the log buffer */ @@ -1954,83 +2018,177 @@ static inline u32 printk_caller_id(void) 0x80000000 + raw_smp_processor_id(); } -static size_t log_output(int facility, int level, enum log_flags lflags, - const struct dev_printk_info *dev_info, - char *text, size_t text_len) +/** + * parse_prefix - Parse level and control flags. + * + * @text: The terminated text message. + * @level: A pointer to the current level value, will be updated. + * @lflags: A pointer to the current log flags, will be updated. + * + * @level may be NULL if the caller is not interested in the parsed value. + * Otherwise the variable pointed to by @level must be set to + * LOGLEVEL_DEFAULT in order to be updated with the parsed value. + * + * @lflags may be NULL if the caller is not interested in the parsed value. + * Otherwise the variable pointed to by @lflags will be OR'd with the parsed + * value. + * + * Return: The length of the parsed level and control flags. + */ +static u16 parse_prefix(char *text, int *level, enum log_flags *lflags) { - const u32 caller_id = printk_caller_id(); + u16 prefix_len = 0; + int kern_level; - if (lflags & LOG_CONT) { - struct prb_reserved_entry e; - struct printk_record r; + while (*text) { + kern_level = printk_get_level(text); + if (!kern_level) + break; - prb_rec_init_wr(&r, text_len); - if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) { - memcpy(&r.text_buf[r.info->text_len], text, text_len); - r.info->text_len += text_len; - if (lflags & LOG_NEWLINE) { - r.info->flags |= LOG_NEWLINE; - prb_final_commit(&e); - } else { - prb_commit(&e); - } - return text_len; + switch (kern_level) { + case '0' ... '7': + if (level && *level == LOGLEVEL_DEFAULT) + *level = kern_level - '0'; + break; + case 'c': /* KERN_CONT */ + if (lflags) + *lflags |= LOG_CONT; } + + prefix_len += 2; + text += 2; } - /* Store it in the record log */ - return log_store(caller_id, facility, level, lflags, 0, - dev_info, text, text_len); + return prefix_len; } -/* Must be called under logbuf_lock. */ +static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lflags, + const char *fmt, va_list args) +{ + u16 text_len; + + text_len = vscnprintf(text, size, fmt, args); + + /* Mark and strip a trailing newline. */ + if (text_len && text[text_len - 1] == '\n') { + text_len--; + *lflags |= LOG_NEWLINE; + } + + /* Strip log level and control flags. */ + if (facility == 0) { + u16 prefix_len; + + prefix_len = parse_prefix(text, NULL, NULL); + if (prefix_len) { + text_len -= prefix_len; + memmove(text, text + prefix_len, text_len); + } + } + + return text_len; +} + +__printf(4, 0) int vprintk_store(int facility, int level, const struct dev_printk_info *dev_info, const char *fmt, va_list args) { - static char textbuf[LOG_LINE_MAX]; - char *text = textbuf; - size_t text_len; + const u32 caller_id = printk_caller_id(); + struct prb_reserved_entry e; enum log_flags lflags = 0; + struct printk_record r; + u16 trunc_msg_len = 0; + char prefix_buf[8]; + u16 reserve_size; + va_list args2; + u16 text_len; + u64 ts_nsec; /* - * The printf needs to come first; we need the syslog - * prefix which might be passed-in as a parameter. + * Since the duration of printk() can vary depending on the message + * and state of the ringbuffer, grab the timestamp now so that it is + * close to the call of printk(). This provides a more deterministic + * timestamp with respect to the caller. */ - text_len = vscnprintf(text, sizeof(textbuf), fmt, args); + ts_nsec = local_clock(); - /* mark and strip a trailing newline */ - if (text_len && text[text_len-1] == '\n') { - text_len--; + /* + * The sprintf needs to come first since the syslog prefix might be + * passed in as a parameter. An extra byte must be reserved so that + * later the vscnprintf() into the reserved buffer has room for the + * terminating '\0', which is not counted by vsnprintf(). + */ + va_copy(args2, args); + reserve_size = vsnprintf(&prefix_buf[0], sizeof(prefix_buf), fmt, args2) + 1; + va_end(args2); + + if (reserve_size > LOG_LINE_MAX) + reserve_size = LOG_LINE_MAX; + + /* Extract log level or control flags. */ + if (facility == 0) + parse_prefix(&prefix_buf[0], &level, &lflags); + + if (level == LOGLEVEL_DEFAULT) + level = default_message_loglevel; + + if (dev_info) lflags |= LOG_NEWLINE; - } - /* strip kernel syslog prefix and extract log level or control flags */ - if (facility == 0) { - int kern_level; + if (lflags & LOG_CONT) { + prb_rec_init_wr(&r, reserve_size); + if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) { + text_len = printk_sprint(&r.text_buf[r.info->text_len], reserve_size, + facility, &lflags, fmt, args); + r.info->text_len += text_len; - while ((kern_level = printk_get_level(text)) != 0) { - switch (kern_level) { - case '0' ... '7': - if (level == LOGLEVEL_DEFAULT) - level = kern_level - '0'; - break; - case 'c': /* KERN_CONT */ - lflags |= LOG_CONT; + if (lflags & LOG_NEWLINE) { + r.info->flags |= LOG_NEWLINE; + prb_final_commit(&e); + } else { + prb_commit(&e); } - text_len -= 2; - text += 2; + return text_len; } } - if (level == LOGLEVEL_DEFAULT) - level = default_message_loglevel; + /* + * Explicitly initialize the record before every prb_reserve() call. + * prb_reserve_in_last() and prb_reserve() purposely invalidate the + * structure when they fail. + */ + prb_rec_init_wr(&r, reserve_size); + if (!prb_reserve(&e, prb, &r)) { + /* truncate the message if it is too long for empty buffer */ + truncate_msg(&reserve_size, &trunc_msg_len); + prb_rec_init_wr(&r, reserve_size + trunc_msg_len); + if (!prb_reserve(&e, prb, &r)) + return 0; + } + + /* fill message */ + text_len = printk_sprint(&r.text_buf[0], reserve_size, facility, &lflags, fmt, args); + if (trunc_msg_len) + memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len); + r.info->text_len = text_len + trunc_msg_len; + r.info->facility = facility; + r.info->level = level & 7; + r.info->flags = lflags & 0x1f; + r.info->ts_nsec = ts_nsec; + r.info->caller_id = caller_id; if (dev_info) - lflags |= LOG_NEWLINE; + memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info)); + + /* A message without a trailing newline can be continued. */ + if (!(lflags & LOG_NEWLINE)) + prb_commit(&e); + else + prb_final_commit(&e); - return log_output(facility, level, lflags, dev_info, text, text_len); + return (text_len + trunc_msg_len); } asmlinkage int vprintk_emit(int facility, int level, @@ -2059,10 +2217,9 @@ asmlinkage int vprintk_emit(int facility, int level, boot_delay_msec(level); printk_delay(); - /* This stops the holder of console_sem just where we want him */ - logbuf_lock_irqsave(flags); + printk_safe_enter_irqsave(flags); printed_len = vprintk_store(facility, level, dev_info, fmt, args); - logbuf_unlock_irqrestore(flags); + printk_safe_exit_irqrestore(flags); /* If called from the scheduler, we can not call up(). */ if (!in_sched) { @@ -2135,8 +2292,7 @@ EXPORT_SYMBOL(printk); #else /* CONFIG_PRINTK */ -#define LOG_LINE_MAX 0 -#define PREFIX_MAX 0 +#define CONSOLE_LOG_MAX 0 #define printk_time false #define prb_read_valid(rb, seq, r) false @@ -2473,7 +2629,7 @@ static inline int can_use_console(void) void console_unlock(void) { static char ext_text[CONSOLE_EXT_LOG_MAX]; - static char text[LOG_LINE_MAX + PREFIX_MAX]; + static char text[CONSOLE_LOG_MAX]; static int panic_console_dropped; unsigned long flags; bool do_cond_resched, retry; @@ -2923,7 +3079,12 @@ void register_console(struct console *newcon) */ exclusive_console = newcon; exclusive_console_stop_seq = console_seq; + + /* Get a consistent copy of @syslog_seq. */ + raw_spin_lock(&syslog_lock); console_seq = syslog_seq; + raw_spin_unlock(&syslog_lock); + logbuf_unlock_irqrestore(flags); } console_unlock(); @@ -3289,6 +3450,7 @@ EXPORT_SYMBOL_GPL(kmsg_dump_reason_str); */ void kmsg_dump(enum kmsg_dump_reason reason) { + struct kmsg_dumper_iter iter; struct kmsg_dumper *dumper; unsigned long flags; @@ -3308,25 +3470,21 @@ void kmsg_dump(enum kmsg_dump_reason reason) continue; /* initialize iterator with data about the stored records */ - dumper->active = true; - + iter.active = true; logbuf_lock_irqsave(flags); - dumper->cur_seq = clear_seq; - dumper->next_seq = prb_next_seq(prb); + iter.cur_seq = latched_seq_read_nolock(&clear_seq); + iter.next_seq = prb_next_seq(prb); logbuf_unlock_irqrestore(flags); /* invoke dumper which will iterate over records */ - dumper->dump(dumper, reason); - - /* reset iterator */ - dumper->active = false; + dumper->dump(dumper, reason, &iter); } rcu_read_unlock(); } /** * kmsg_dump_get_line_nolock - retrieve one kmsg log line (unlocked version) - * @dumper: registered kmsg dumper + * @iter: kmsg dumper iterator * @syslog: include the "<4>" prefixes * @line: buffer to copy the line to * @size: maximum size of the buffer @@ -3343,7 +3501,7 @@ void kmsg_dump(enum kmsg_dump_reason reason) * * The function is similar to kmsg_dump_get_line(), but grabs no locks. */ -bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog, +bool kmsg_dump_get_line_nolock(struct kmsg_dumper_iter *iter, bool syslog, char *line, size_t size, size_t *len) { struct printk_info info; @@ -3354,16 +3512,16 @@ bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog, prb_rec_init_rd(&r, &info, line, size); - if (!dumper->active) + if (!iter->active) goto out; /* Read text or count text lines? */ if (line) { - if (!prb_read_valid(prb, dumper->cur_seq, &r)) + if (!prb_read_valid(prb, iter->cur_seq, &r)) goto out; l = record_print_text(&r, syslog, printk_time); } else { - if (!prb_read_valid_info(prb, dumper->cur_seq, + if (!prb_read_valid_info(prb, iter->cur_seq, &info, &line_count)) { goto out; } @@ -3372,7 +3530,7 @@ bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog, } - dumper->cur_seq = r.info->seq + 1; + iter->cur_seq = r.info->seq + 1; ret = true; out: if (len) @@ -3382,7 +3540,7 @@ bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog, /** * kmsg_dump_get_line - retrieve one kmsg log line - * @dumper: registered kmsg dumper + * @iter: kmsg dumper iterator * @syslog: include the "<4>" prefixes * @line: buffer to copy the line to * @size: maximum size of the buffer @@ -3397,14 +3555,14 @@ bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog, * A return value of FALSE indicates that there are no more records to * read. */ -bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog, +bool kmsg_dump_get_line(struct kmsg_dumper_iter *iter, bool syslog, char *line, size_t size, size_t *len) { unsigned long flags; bool ret; logbuf_lock_irqsave(flags); - ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len); + ret = kmsg_dump_get_line_nolock(iter, syslog, line, size, len); logbuf_unlock_irqrestore(flags); return ret; @@ -3413,7 +3571,7 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_line); /** * kmsg_dump_get_buffer - copy kmsg log lines - * @dumper: registered kmsg dumper + * @iter: kmsg dumper iterator * @syslog: include the "<4>" prefixes * @buf: buffer to copy the line to * @size: maximum size of the buffer @@ -3430,87 +3588,76 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_line); * A return value of FALSE indicates that there are no more records to * read. */ -bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog, - char *buf, size_t size, size_t *len) +bool kmsg_dump_get_buffer(struct kmsg_dumper_iter *iter, bool syslog, + char *buf, size_t size, size_t *len_out) { struct printk_info info; - unsigned int line_count; struct printk_record r; unsigned long flags; u64 seq; u64 next_seq; - size_t l = 0; + size_t len = 0; bool ret = false; bool time = printk_time; - prb_rec_init_rd(&r, &info, buf, size); - - if (!dumper->active || !buf || !size) + if (!iter->active || !buf || !size) goto out; logbuf_lock_irqsave(flags); - if (prb_read_valid_info(prb, dumper->cur_seq, &info, NULL)) { - if (info.seq != dumper->cur_seq) { + if (prb_read_valid_info(prb, iter->cur_seq, &info, NULL)) { + if (info.seq != iter->cur_seq) { /* messages are gone, move to first available one */ - dumper->cur_seq = info.seq; + iter->cur_seq = info.seq; } } /* last entry */ - if (dumper->cur_seq >= dumper->next_seq) { + if (iter->cur_seq >= iter->next_seq) { logbuf_unlock_irqrestore(flags); goto out; } - /* calculate length of entire buffer */ - seq = dumper->cur_seq; - while (prb_read_valid_info(prb, seq, &info, &line_count)) { - if (r.info->seq >= dumper->next_seq) - break; - l += get_record_print_text_size(&info, line_count, syslog, time); - seq = r.info->seq + 1; - } - - /* move first record forward until length fits into the buffer */ - seq = dumper->cur_seq; - while (l >= size && prb_read_valid_info(prb, seq, - &info, &line_count)) { - if (r.info->seq >= dumper->next_seq) - break; - l -= get_record_print_text_size(&info, line_count, syslog, time); - seq = r.info->seq + 1; - } + /* + * Find first record that fits, including all following records, + * into the user-provided buffer for this dump. Pass in size-1 + * because this function (by way of record_print_text()) will + * not write more than size-1 bytes of text into @buf. + */ + seq = find_first_fitting_seq(iter->cur_seq, iter->next_seq, + size - 1, syslog, time); - /* last message in next interation */ + /* + * Next kmsg_dump_get_buffer() invocation will dump block of + * older records stored right before this one. + */ next_seq = seq; - /* actually read text into the buffer now */ - l = 0; - while (prb_read_valid(prb, seq, &r)) { - if (r.info->seq >= dumper->next_seq) - break; + prb_rec_init_rd(&r, &info, buf, size); - l += record_print_text(&r, syslog, time); + len = 0; + prb_for_each_record(seq, prb, seq, &r) { + if (r.info->seq >= iter->next_seq) + break; - /* adjust record to store to remaining buffer space */ - prb_rec_init_rd(&r, &info, buf + l, size - l); + len += record_print_text(&r, syslog, time); - seq = r.info->seq + 1; + /* Adjust record to store to remaining buffer space. */ + prb_rec_init_rd(&r, &info, buf + len, size - len); } - dumper->next_seq = next_seq; + iter->next_seq = next_seq; ret = true; logbuf_unlock_irqrestore(flags); out: - if (len) - *len = l; + if (len_out) + *len_out = len; return ret; } EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer); /** * kmsg_dump_rewind_nolock - reset the iterator (unlocked version) - * @dumper: registered kmsg dumper + * @iter: kmsg dumper iterator * * Reset the dumper's iterator so that kmsg_dump_get_line() and * kmsg_dump_get_buffer() can be called again and used multiple @@ -3518,26 +3665,26 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer); * * The function is similar to kmsg_dump_rewind(), but grabs no locks. */ -void kmsg_dump_rewind_nolock(struct kmsg_dumper *dumper) +void kmsg_dump_rewind_nolock(struct kmsg_dumper_iter *iter) { - dumper->cur_seq = clear_seq; - dumper->next_seq = prb_next_seq(prb); + iter->cur_seq = latched_seq_read_nolock(&clear_seq); + iter->next_seq = prb_next_seq(prb); } /** * kmsg_dump_rewind - reset the iterator - * @dumper: registered kmsg dumper + * @iter: kmsg dumper iterator * * Reset the dumper's iterator so that kmsg_dump_get_line() and * kmsg_dump_get_buffer() can be called again and used multiple * times within the same dumper.dump() callback. */ -void kmsg_dump_rewind(struct kmsg_dumper *dumper) +void kmsg_dump_rewind(struct kmsg_dumper_iter *iter) { unsigned long flags; logbuf_lock_irqsave(flags); - kmsg_dump_rewind_nolock(dumper); + kmsg_dump_rewind_nolock(iter); logbuf_unlock_irqrestore(flags); } EXPORT_SYMBOL_GPL(kmsg_dump_rewind);