vsprintf: Fix %ps on non symbols when using kallsyms

Using %ps in a printk format will sometimes fail silently and print the empty string if the address passed in does not match a symbol that kallsyms knows about. But using %pS will fall back to printing the full address if kallsyms can't find the symbol. Make %ps act the same as %pS by falling back to printing the address.

While we're here also make %ps print the module that a symbol comes from so that it matches what %pS already does. Take this simple function for example (in a module):

	static void test_printk(void)
	{
		int test;
		pr_info("with pS: %pS\n", &test);
		pr_info("with ps: %ps\n", &test);
	}

Before this patch:

with pS: 0xdff7df44
with ps:

After this patch:

with pS: 0xdff7df44
with ps: 0xdff7df44

---

The name is admittedly bad. Please suggest alternatives.

 include/linux/kallsyms.h |    7 +++++++
 kernel/kallsyms.c        |   32 ++++++++++++++++++++++++--------
 lib/vsprintf.c           |    2 +-
 3 files changed, 32 insertions(+), 9 deletions(-)

index 3875719..6883e19 100644
@@ -36,6 +36,7 @@ const char *kallsyms_lookup(unsigned long addr,
 
 /* Look up a kernel symbol and return it in a text buffer. */
 extern int sprint_symbol(char *buffer, unsigned long address);
+extern int sprint_symbol_no_offset(char *buffer, unsigned long address);
 extern int sprint_backtrace(char *buffer, unsigned long address);
 
 /* Look up a kernel symbol and print it to the kernel messages. */

@@ -80,6 +81,12 @@ static inline int sprint_symbol(char *buffer, unsigned long addr)
 	return 0;
 }
 
+static inline int sprint_symbol_no_offset(char *buffer, unsigned long addr)
+{
+	*buffer = '\0';
+	return 0;
+}
+
 static inline int sprint_backtrace(char *buffer, unsigned long addr)
 {
 	*buffer = '\0';

index 079f1d3..2169fee 100644
@@ -343,7 +343,7 @@ int lookup_symbol_attrs(unsigned long addr, unsigned long *size,
 
 /* Look up a kernel symbol and return it in a text buffer. */
 static int __sprint_symbol(char *buffer, unsigned long address,
-			   int symbol_offset)
+			   int symbol_offset, int add_offset)
 {
 	char *modname;
 	const char *name;

@@ -358,13 +358,13 @@ static int __sprint_symbol(char *buffer, unsigned long address,
 	if (name != buffer)
 		strcpy(buffer, name);
 	len = strlen(buffer);
-	buffer += len;
 	offset -= symbol_offset;
 
+	if (add_offset)
+		len += sprintf(buffer + len, "+%#lx/%#lx", offset, size);
+
 	if (modname)
-		len += sprintf(buffer, "+%#lx/%#lx [%s]", offset, size, modname);
-	else
-		len += sprintf(buffer, "+%#lx/%#lx", offset, size);
+		len += sprintf(buffer + len, " [%s]", modname);
 
 	return len;
 }

@@ -382,12 +382,28 @@ static int __sprint_symbol(char *buffer, unsigned long address,
  */
 int sprint_symbol(char *buffer, unsigned long address)
 {
-	return __sprint_symbol(buffer, address, 0);
+	return __sprint_symbol(buffer, address, 0, 1);
 }
-
 EXPORT_SYMBOL_GPL(sprint_symbol);
 
 /**
+ * sprint_symbol_no_offset - Look up a kernel symbol and return it in a text buffer
+ * @buffer: buffer to be stored
+ * @address: address to lookup
+ *
+ * This function looks up a kernel symbol with @address and stores its name
+ * and module name to @buffer if possible. If no symbol was found, just saves
+ * its @address as is.
+ *
+ * This function returns the number of bytes stored in @buffer.
+ */
+int sprint_symbol_no_offset(char *buffer, unsigned long address)
+{
+	return __sprint_symbol(buffer, address, 0, 0);
+}
+EXPORT_SYMBOL_GPL(sprint_symbol_no_offset);
+
+/**
  * sprint_backtrace - Look up a backtrace symbol and return it in a text buffer
  * @buffer: buffer to be stored
  * @address: address to lookup

@@ -403,7 +419,7 @@ EXPORT_SYMBOL_GPL(sprint_symbol);
  */
 int sprint_backtrace(char *buffer, unsigned long address)
 {
-	return __sprint_symbol(buffer, address, -1);
+	return __sprint_symbol(buffer, address, -1, 1);
 }
 
 /* Look up a kernel symbol and print it to the kernel messages. */

index ba7bb1b..0b56d43 100644
@@ -535,7 +535,7 @@ char *symbol_string(char *buf, char *end, void *ptr,
 	else if (ext != 'f' && ext != 's')
 		sprint_symbol(sym, value);
 	else
-		kallsyms_lookup(value, NULL, NULL, NULL, sym);
+		sprint_symbol_no_offset(sym, value);
 
 	return string(buf, end, sym, spec);
 #else

Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.

When a spinlock warning is printed we usually get

 BUG: spinlock bad magic on CPU#0, modprobe/111
  lock: 0xdff09f38, .magic: 00000000, .owner: /0, .owner_cpu: 0

but it's nicer to print the symbol for the lock if we have it so that we can avoid 'grep dff09f38 /proc/kallsyms' to find out which lock it was. Use kallsyms to print the symbol name so we get something a bit easier to read

 BUG: spinlock bad magic on CPU#0, modprobe/112
  lock: test_lock, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0

If the lock is not in kallsyms %ps will fall back to printing the address directly.

---
 lib/spinlock_debug.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 525d160..d0ec4f3 100644
@@ -58,7 +58,7 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
 		msg, raw_smp_processor_id(),
 		current->comm, task_pid_nr(current));
-	printk(KERN_EMERG " lock: %p, .magic: %08x, .owner: %s/%d, "
+	printk(KERN_EMERG " lock: %ps, .magic: %08x, .owner: %s/%d, "
 			".owner_cpu: %d\n",
 		lock, lock->magic,
 		owner ? owner->comm : "<none>",

Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.

hm. Is this true? From my reading of kallsyms_lookup(), it will fall into module_address_lookup() whcih is a no-op if !CONFIG_MODULES.

Agreed. It catches the really stupid stuff and that's about it. I was thinking we could get more information about dynamic allocated locks by adding some code to slab to find the slab that a pointer is allocated in. Does that sound possible?

With stacktrace support in slub we could even find the caller who allocated the storage for the spinlock. It might be useful but one could argue the stacktrace from this function is already pretty useful for tracking down which spinlock it is.

Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.

Well lockdep knows lots of things about the lock, including numerous stack backtraces which can be used to identify the lock. Making spinlock_debug use lockdep infrastructure seems a good fit.

I was thinking about this more. In the case of spinlock bad magic I want to find out who freed this region of memory last because that code most likely stomped all over my lock and corrupted the magic. With lockdep I can't find that. I can only find out that the allocator of a lock did a lock/unlock after a kfree() and I believe lockdep already checks to make sure live locks are not being freed.

Enabling slub debugging might help, but I would have to get lucky and allocate the lock after the previous user corrupted it. So I really want a way to query slab/slub about who last allocated and free this memory so I can find them when I detect magic corruption.

Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.

Oh. The stupid mails came in reverse order.

Hi Andrew,

A coworker pointed out that the second patch in this series now prints the symbol closest to the address passed in if kallsyms sees the address is between two symbols. So if I have a pointer to some member of a structure %ps prints the symbol for the containing structure, which is not really helpful.

For example

struct test {
int i;
int j;
} my_test;

printk("%ps\n", &my_test.j)

would print out "my_test" instead of "0xc4523400".

This is especially bad for the spinlock debugging case where there could be two locks embedded in some static structure. I think it would be a good idea to apply this patch so we get a good middle ground by printing the name and the offset. Or we can revert the patch and I'll add more info by printing lockdep information about the lock.

-----8<------

From: Stephen Boyd <[email protected]>
Subject: [PATCH] spinlock_debug: Print offset in addition to symbol name

If there are two spinlocks embedded in a structure that kallsyms knows about and one of the spinlocks locks up we will print the name of the containing structure instead of the address of the lock. This is quite bad, so let's use %pS instead of %ps so we get an offset in addition to the symbol so we can determine which particular lock is having problems.

---
 lib/spinlock_debug.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index e91fbc2..eb10578 100644
@@ -58,7 +58,7 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
 		msg, raw_smp_processor_id(),
 		current->comm, task_pid_nr(current));
-	printk(KERN_EMERG " lock: %ps, .magic: %08x, .owner: %s/%d, "
+	printk(KERN_EMERG " lock: %pS, .magic: %08x, .owner: %s/%d, "
 			".owner_cpu: %d\n",
 		lock, lock->magic,
 		owner ? owner->comm : "<none>",

Sent by an employee of the Qualcomm Innovation Center, Inc.
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum.