emit-crash-char: Allow diversion of printk output for crash logging

Allow diversion of characters generated through printk so that they can be logged separately. The printk_time variables is made externally visible so that functions processing the diverted characters can parse off the time added if CONFIG_PRINTK_TIME is enabled.

---
I apologize for the crufty disclaimer Cisco adds. It is on a long list on things that make us awkward open source community members but things change slowly at many large companies.

Rationale for this patch: The ability to divert characters is useful for embedded systems when a panic occurs. It is frequently the case that there is insufficient storage to hold a crash dump and too little, if any, upstream network bandwith to upload a dump if one could be stored. Instead, we rely upon the report written to the console for most of our debugging. The ability to capture that report and either store it or send it upstream is a fundamental part of our ability to support our systems in the lab and in the field.

include/linux/kernel.h | 5 ++++
kernel/printk.c | 56 ++++++++++++++++++++++++++++++++++++++++++++++-

2 files changed, 59 insertions(+), 2 deletions(-)

index aaa998f..1848260 100644
@@ -200,6 +200,8 @@ extern struct ratelimit_state printk_ratelimit_state;

extern int printk_ratelimit(void);
extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,

				   unsigned int interval_msec);

+extern void register_emit_crash_char(void (*fn)(char c)); +extern void unregister_emit_crash_char(void); #else
static inline int vprintk(const char *s, va_list args)

	__attribute__ ((format (printf, 1, 0)));
@@ -211,6 +213,8 @@ static inline int printk_ratelimit(void) { return 0; }
static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies, \
					  unsigned int interval_msec)	\
		{ return false; }

+static inline void register_emit_crash_char(void (*fn)(char c)) {} +static inline void unregister_emit_crash_char() {} #endif

extern void asmlinkage __attribute__((format(printf, 1, 2))) @@ -229,6 +233,7 @@ static inline void console_verbose(void)

		console_loglevel = 15;
}

+extern int printk_time;
extern void bust_spinlocks(int yes);
extern void wake_up_klogd(void);
extern int oops_in_progress; /* If set, an oops, panic(), BUG() or die() is in progress */

index b51b156..35a4d81 100644
@@ -67,6 +67,9 @@ int console_printk[4] = {

int oops_in_progress;
EXPORT_SYMBOL(oops_in_progress);

+static void (*emit_crash_char_fn)(char c);
+static bool recursive_emit_crash_char;
+
/*
* console_sem protects the console_drivers list, and also
* provides serialisation for access to the entire console
@@ -520,8 +523,35 @@ static void call_console_drivers(unsigned start, unsigned end)

	_call_console_drivers(start_print, end, msg_level);
}

+/*
+ * This emits a character intended for a crash log. We take special care
+ * to avoid recursive use so that we don't end up in an crash reporting loop.
+ */
+static void emit_crash_char(char c)
+{
+ static bool in_call;
+
+ if (emit_crash_char_fn != NULL) {
+ /* Detect recursive calls and ignore them. This could happen
+ * if the function we use to emit the character to the crash
+ * log failed and called printk. Though we ignore the output,
+ * we remember that we had a recursive call so that we can
+ * report it later. */
+ if (in_call)
+ recursive_emit_crash_char = true;
+
+ else {
+ in_call = true;
+ emit_crash_char_fn(c);
+ in_call = false;
+ }
+ }
+}
+
static void emit_log_char(char c)
{
+ emit_crash_char(c);
+

	LOG_BUF(log_end) = c;
	log_end++;
	if (log_end - log_start > log_buf_len)

@@ -533,6 +563,28 @@ static void emit_log_char(char c) }

/*
+ * Register a function to emit a crash character
+ * @fn: Function to register
+ */
+void register_emit_crash_char(void (*fn)(char c))
+{
+ emit_crash_char_fn = fn;
+}
+
+/*
+ * Unregister a function emiting a crash character
+ */
+void unregister_emit_crash_char()
+{
+ emit_crash_char_fn = NULL;
+
+ if (recursive_emit_crash_char) {
+ pr_err("emit_crash_char was called recursively!\n");
+ recursive_emit_crash_char = false;
+ }
+}
+
+/*
* Zap console related locks when oopsing. Only zap at most once
* every 10 seconds, to leave time for slow consoles to print a
* full oops.
@@ -554,9 +606,9 @@ static void zap_locks(void)
}

#if defined(CONFIG_PRINTK_TIME)
-static int printk_time = 1;
+int printk_time = 1;
#else
-static int printk_time = 0;
+int printk_time;
#endif
module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);

- - - - - Cisco - - - - -
This e-mail and any attachments may contain information which is confidential, proprietary, privileged or otherwise protected by law. The information is solely intended for the named addressee (or a person responsible for delivering it to the addressee). If you are not the intended recipient of this message, you are not authorized to read, print, retain, copy or disseminate this message or any part of it. If you have received this e-mail in error, please notify the sender immediately by return e-mail and delete it from your computer.

i really doubt that. lack of existing tangible users makes it a harder case, but it certainly is not a "never" case. there is plenty of examples in the tree where things were merged without any users and the commit wouldnt be immediately leveraged.
-mike

Well, I did say "usually" .. I invite you to give some of the "plenty of examples in the tree", you might surprise me..

Daniel

you said "usually people submit new interfaces", not "it is usually not accepted without at least one user".

look at all the new syscalls added without any userspace code in place (still) to use it. or Linus' recent printk modifier extension. or my printk extensions for extracting portions of the kernel log buffer. people usually submit interfaces with backend extesions, or the intent to use it is obvious.
-mike

Well, usually people do submit the users, and if they don't it's usually not accepted..

Syscalls and Userspace are unrelated .. You clearly can't add userspace code to the kernel .. If you add a _kernel_ interface like David has done you need at least one user of the interface.. Otherwise it's just plain bloat inside the kernel which no one wants.

Your changes for extracting part of the kernel log buffer (commit 0b15d04af3dd996035d8fa81fc849d049171f9c3),

with:
text data bss dec hex filename
4322000 386760 2592768 7301528 6f6998 vmlinux
without:
text data bss dec hex filename
4321876 386760 2592768 7301404 6f691c vmlinux

Adds roughly 120bytes of bloat to my kernel, since 2007 .. What's the point? I grepped for users , and there are none ..

Daniel

same sort of things as the point of David's code. early/crash scenarios for people to safely extract portions of the kernel log buffer for transmission/storage elsewhere. as was explained in the original thread behind the commit.
-mike

How is that code suppose to help anyone if you aren't calling it from anyplace in the kernel? Clearly your using it, right? Where is the code your calling these functions from?

Daniel

Not that it was in the patch, but netconsole would be an obvious potential user. It would be most useful in board specific startup code such as arch/ppc/platforms, where a particular board might have a place to put information like this for later retrieval. One would hope that such board specific file would be forthcoming, rather than be maintained out-of-tree.

In the thread where this code was created it was assumed that the blackfin architecture would use the functions .. However, blackfin doesn't appear to use it .. Not sure where that code went, but it hasn't materialized in almost a year.

It basically all comes back to my original point which is don't submit code that isn't used .. If you have a specific user for the code you can tailor ifdefs. Then for instance it doesn't bloat non-blackfin architectures, or non-netconsole users .. Or if it's used only during init you can flag it with __init and it will be freed after the system boots. When it's enable and exists it's possible for it to get called and serve some useful purpose ..

Daniel

Yes, you could, but this seems *so much* more straight-forward. Another option I considered was changing things so that the first level interface would simply output a character, possibly also passing some sort of context pointer. Then whatever was called by that interface could call a console driver, if appropriate. Even though I think this is really a cleaner way to do this, it also involves many more changes than I think are warranted just to get this little piece of functionality.

A highly valid criticism. I actually quoted your message to my management in order to underscore how important it is that Cisco becomes a good open source citizen. Personally, I view it as an absolute must.

I'm not thrilled with this patch. It seems so much more straight forward in your special case, but it comes at the expense of making the code path more complex in every other case.

I would much rather see this be done using the existing console driver interface. The only possible reason I could see wanting to do things this way is if you don't trust the console code to call your console driver, which I think is a pretty unlikely case.

g.

--
Grant Likely, B.Sc., P.Eng.
Secret Lab Technologies Ltd.

I'll buy that reasoning.

Regardless of implementation, it seems to me that it could be of use for some other embedded platforms. Any suggestions as to where it should go in the tree? drivers/char? drivers/misc?

--
David VomLehn

Depends on what you're storing to. Can you send more details about the specific use case that you will use this interface for?

g.

The system I'm working on is a settop box. It is in an environment where it is connected to a central server. The settop box doesn't have enough space to hold core dumps and the upstream connection to the server has too little bandwidth to upload them if we did store them. We have found that we can usually diagnose and fix problems with much less information than a core dump however, so we want to be able to capture that information and send it upstream.

Our use case is:
1. We register a panic handler
2. The kernel panics and calls our panic handler
3. We register a function to log printk output
4. We print registers, stack, memory, and various other pieces of information using standard kernel functions, which all use printk
5. As printk output is generated, we store it in memory
6. We unregister the printk logging function
7. The panic handler exits
8. The kernel does the rest of its usual panic handling

I'm not proposing storing the data in a specific place; that will be up to the platform. We will be storing in a piece of memory set aside for this purpose, but storing it in NOR flash makes a lot of sense, too, or using NAND flash or possibly even disk. All I'm proposing is a small framework that will allow plugging in a logging function when needed and removing it when done. I'll do the common piece that looks like a fake console and we, and other people, can use the simpler interface it provides.

--
David VomLehn

I'm not sure exactly what triggers the transition from step 5 to 6 in your steps above. That is, how do you know when to unregister the printk logging function?

But, taking a step back, instead of storing the information somewhere else, why not just use the log buffer as the storage medium, and transfer that all-at-once when you've collected the information you want? That is, change your steps to:

1. Register a panic handler
2. The kernel panics and calls our panic handler
3. Record the current position of the log buffer insertion point
4. Print registers, stack, memory, and various other pieces of information using standard kernel functions, which all use printk
5. As printk output is generated - it is stored by the kernel in the log buffer (no change to printk code is needed).
** (not sure what the trigger is to stop, here) **
6. Record the current position of the log buffer, and transfer data logged between steps 3 and 6 to wherever you like. That is, copy it directly from the log buffer.
7. The panic handler exits
8. The kernel does the rest of its usual panic handling

This reduces your intrusion to just your trigger points, and grabbing the log buffer position. (Side Note - the way the log buffer position is stored is a bit funky. It is an absolute value that monotonically increases, and is masked when used to refer to the buffer. This is why the log buffer size is constrained to a power of two).
-- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum Senior Staff Engineer, Sony Corporation of America
=============================

...

The printk logging function is unregistered when we are done printing everything we're interested in.

An interesting suggestion, but we've seen cases where the logging itself causes subsequent faults. In such cases, you would get nothing at all if you waited to store information until you've collected everything. A partial report, particularly if you've tried to print the most useful things first, is better than none at all. In addition, there is the risk that, for a particularly long report, you might wrap the log buffer and lose the first part of your output. --
David VomLehn