lkml.org 
[lkml]   [2018]   [May]   [17]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
From
SubjectRe: [PATCH] printk: inject caller information into the body of message
On (05/17/18 20:21), Sergey Senozhatsky wrote:
> Dunno...
> For instance, can we store context tracking info as a extended record
> data? We have that dict/dict_len thing. So may we can store tracking
> info there? Extended records will appear on the serial console /* if
> console supports extended data */ or can be read in via devkmsg_read().

Those extended records are already there for exactly the same
reason - people want to attach a special context to printk() entries.
See dev_vprintk_emit() and create_syslog_header(). So we can add more
key/value data to that context. Sounds kinda-sorta reasonable.

So, for example, this output
cat /dev/kmsg

6,577,3156036,-;snd_hda_codec_generic hdaudioC1D0: autoconfig for Generic: line_outs=0 (0x0/0x0/0x0/0x0/0x0) type:line
SUBSYSTEM=hdaudio
DEVICE=+hdaudio:hdaudioC1D
6,578,3156807,-;snd_hda_codec_generic hdaudioC1D0: speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
SUBSYSTEM=hdaudio
DEVICE=+hdaudio:hdaudioC1D

Becomes this:
6,566,3033752,-;snd_hda_codec_realtek hdaudioC0D0: Front Mic=0x19
3/207: 0/0/0
SUBSYSTEM=hdaudio
DEVICE=+hdaudio:hdaudioC0D
6,567,3033754,-;snd_hda_codec_realtek hdaudioC0D0: Rear Mic=0x18
3/207: 0/0/0
SUBSYSTEM=hdaudio
DEVICE=+hdaudio:hdaudioC0D


"3/207: 0/0/0" is smp_processor_id/task_pid_nr and then masked
out bits of preempt count: hard irq, soft irq, nmi.

We definitely can change the format, etc. This is just a very quick and
dirty PoC.

Something as follows?
/* just to demonstrate the idea */

---

kernel/printk/printk.c | 22 +++++++++++++++++++++-
1 file changed, 21 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2f4af216bd6e..4a82d52a343d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -580,16 +580,33 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
}

+static size_t add_log_origin(char *buf, size_t buf_len)
+{
+ return snprintf(buf,
+ buf_len,
+ "%d/%d: %lu/%lu/%lu",
+ raw_smp_processor_id(),
+ task_pid_nr(current),
+ preempt_count() & HARDIRQ_MASK,
+ preempt_count() & SOFTIRQ_MASK,
+ preempt_count() & NMI_MASK);
+}
+
/* insert record into the buffer, discard old ones, update heads */
static int log_store(int facility, int level,
enum log_flags flags, u64 ts_nsec,
const char *dict, u16 dict_len,
const char *text, u16 text_len)
{
+ static char log_origin[64];
+ static size_t log_origin_len;
struct printk_log *msg;
u32 size, pad_len;
u16 trunc_msg_len = 0;

+ log_origin_len = add_log_origin(log_origin, sizeof(log_origin));
+ dict_len += log_origin_len;
+
/* number of '\0' padding bytes to next message */
size = msg_used_size(text_len, dict_len, &pad_len);

@@ -620,7 +637,10 @@ static int log_store(int facility, int level,
memcpy(log_text(msg) + text_len, trunc_msg, trunc_msg_len);
msg->text_len += trunc_msg_len;
}
- memcpy(log_dict(msg), dict, dict_len);
+ memcpy(log_dict(msg), log_origin, log_origin_len);
+ memcpy(log_dict(msg) + log_origin_len + 1,
+ dict,
+ dict_len - log_origin_len);
msg->dict_len = dict_len;
msg->facility = facility;
msg->level = level & 7;

\
 
 \ /
  Last update: 2018-05-17 13:53    [W:0.187 / U:0.276 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site