I was doing some debugging recently and noticed that my pointers were
being hashed while slub_debug was on the kernel commandline. Let's make
the prints in here meaningful in that case by pushing %px throughout.
Alternatively, we could force on no_hash_pointers if slub_debug is on
the commandline. Maybe that would be better?
The final patch is just something else I noticed while looking at the
code. The message argument is never used so the debugging messages are
not as clear as they could be.
Stephen Boyd (3):
lib/hexdump: Add a raw pointer printing format for slub debugging
slub: Print raw pointer addresses when debugging
slub: Actually use 'message' in restore_bytes()
include/linux/printk.h | 1 +
lib/hexdump.c | 12 ++++++++++--
mm/slub.c | 24 ++++++++++++------------
3 files changed, 23 insertions(+), 14 deletions(-)
base-commit: 6efb943b8616ec53a5e444193dccf1af9ad627b5
--
https://chromeos.dev
The message argument isn't used here. Let's pass the string to the
printk message so that the developer can figure out what's happening,
instead of guessing that a redzone is being restored, etc.
Signed-off-by: Stephen Boyd <[email protected]>
---
mm/slub.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/mm/slub.c b/mm/slub.c
index 87eeeed1f369..16e8e8f8dc0c 100644
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -777,7 +777,7 @@ static void init_object(struct kmem_cache *s, void *object, u8 val)
static void restore_bytes(struct kmem_cache *s, char *message, u8 data,
void *from, void *to)
{
- slab_fix(s, "Restoring 0x%px-0x%px=0x%x\n", from, to - 1, data);
+ slab_fix(s, "Restoring %s 0x%px-0x%px=0x%x\n", message, from, to - 1, data);
memset(from, data, to - from);
}
--
https://chromeos.dev
We want to get actual pointer addresses when we're looking at slub
debugging reports. Add another prefix format specifier that says we want
raw pointer addresses, i.e. %px, in the printk format.
Signed-off-by: Stephen Boyd <[email protected]>
---
include/linux/printk.h | 1 +
lib/hexdump.c | 12 ++++++++++--
2 files changed, 11 insertions(+), 2 deletions(-)
diff --git a/include/linux/printk.h b/include/linux/printk.h
index fe7eb2351610..a7b0b620982d 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -567,6 +567,7 @@ extern const struct file_operations kmsg_fops;
enum {
DUMP_PREFIX_NONE,
DUMP_PREFIX_ADDRESS,
+ DUMP_PREFIX_RAW_ADDRESS,
DUMP_PREFIX_OFFSET
};
extern int hex_dump_to_buffer(const void *buf, size_t len, int rowsize,
diff --git a/lib/hexdump.c b/lib/hexdump.c
index 9301578f98e8..87af5755563f 100644
--- a/lib/hexdump.c
+++ b/lib/hexdump.c
@@ -211,8 +211,12 @@ EXPORT_SYMBOL(hex_dump_to_buffer);
* @level: kernel log level (e.g. KERN_DEBUG)
* @prefix_str: string to prefix each line with;
* caller supplies trailing spaces for alignment if desired
- * @prefix_type: controls whether prefix of an offset, address, or none
- * is printed (%DUMP_PREFIX_OFFSET, %DUMP_PREFIX_ADDRESS, %DUMP_PREFIX_NONE)
+ * @prefix_type: controls how prefix is printed
+ * %DUMP_PREFIX_OFFSET - offset prefix
+ * %DUMP_PREFIX_ADDRESS - hashed address prefix
+ * %DUMP_PREFIX_RAW_ADDRESS - non-hashed address prefix
+ * %DUMP_PREFIX_NONE - no prefix
+ *
* @rowsize: number of bytes to print per line; must be 16 or 32
* @groupsize: number of bytes to print at a time (1, 2, 4, 8; default = 1)
* @buf: data blob to dump
@@ -260,6 +264,10 @@ void print_hex_dump(const char *level, const char *prefix_str, int prefix_type,
printk("%s%s%p: %s\n",
level, prefix_str, ptr + i, linebuf);
break;
+ case DUMP_PREFIX_RAW_ADDRESS:
+ printk("%s%s%px: %s\n",
+ level, prefix_str, ptr + i, linebuf);
+ break;
case DUMP_PREFIX_OFFSET:
printk("%s%s%.8x: %s\n", level, prefix_str, i, linebuf);
break;
--
https://chromeos.dev
Obscuring the pointers that slub shows when debugging makes for some
confusing slub debug messages:
Padding overwritten. 0x0000000079f0674a-0x000000000d4dce17
Those addresses are hashed for kernel security reasons. If we're trying
to be secure with slub_debug on the commandline we have some big
problems given that we dump whole chunks of kernel memory to the kernel
logs. Let's use %px here and dump buffers with the actual address for
the buffer instead of the hashed version so that the logs are
meaningful. This also helps if a kernel address is in some slub debug
report so we can figure out that the object is referencing itself.
Signed-off-by: Stephen Boyd <[email protected]>
---
mm/slub.c | 24 ++++++++++++------------
1 file changed, 12 insertions(+), 12 deletions(-)
diff --git a/mm/slub.c b/mm/slub.c
index feda53ae62ba..87eeeed1f369 100644
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -549,7 +549,7 @@ static void print_section(char *level, char *text, u8 *addr,
unsigned int length)
{
metadata_access_enable();
- print_hex_dump(level, kasan_reset_tag(text), DUMP_PREFIX_ADDRESS,
+ print_hex_dump(level, kasan_reset_tag(text), DUMP_PREFIX_RAW_ADDRESS,
16, 1, addr, length, 1);
metadata_access_disable();
}
@@ -650,7 +650,7 @@ void print_tracking(struct kmem_cache *s, void *object)
static void print_page_info(struct page *page)
{
- pr_err("Slab 0x%p objects=%u used=%u fp=0x%p flags=%#lx(%pGp)\n",
+ pr_err("Slab 0x%px objects=%u used=%u fp=0x%px flags=%#lx(%pGp)\n",
page, page->objects, page->inuse, page->freelist,
page->flags, &page->flags);
@@ -707,7 +707,7 @@ static void print_trailer(struct kmem_cache *s, struct page *page, u8 *p)
print_page_info(page);
- pr_err("Object 0x%p @offset=%tu fp=0x%p\n\n",
+ pr_err("Object 0x%px @offset=%tu fp=0x%px\n\n",
p, p - addr, get_freepointer(s, p));
if (s->flags & SLAB_RED_ZONE)
@@ -777,7 +777,7 @@ static void init_object(struct kmem_cache *s, void *object, u8 val)
static void restore_bytes(struct kmem_cache *s, char *message, u8 data,
void *from, void *to)
{
- slab_fix(s, "Restoring 0x%p-0x%p=0x%x\n", from, to - 1, data);
+ slab_fix(s, "Restoring 0x%px-0x%px=0x%x\n", from, to - 1, data);
memset(from, data, to - from);
}
@@ -800,7 +800,7 @@ static int check_bytes_and_report(struct kmem_cache *s, struct page *page,
end--;
slab_bug(s, "%s overwritten", what);
- pr_err("0x%p-0x%p @offset=%tu. First byte 0x%x instead of 0x%x\n",
+ pr_err("0x%px-0x%px @offset=%tu. First byte 0x%x instead of 0x%x\n",
fault, end - 1, fault - addr,
fault[0], value);
print_trailer(s, page, object);
@@ -893,7 +893,7 @@ static int slab_pad_check(struct kmem_cache *s, struct page *page)
while (end > fault && end[-1] == POISON_INUSE)
end--;
- slab_err(s, page, "Padding overwritten. 0x%p-0x%p @offset=%tu",
+ slab_err(s, page, "Padding overwritten. 0x%px-0x%px @offset=%tu",
fault, end - 1, fault - start);
print_section(KERN_ERR, "Padding ", pad, remainder);
@@ -1041,7 +1041,7 @@ static void trace(struct kmem_cache *s, struct page *page, void *object,
int alloc)
{
if (s->flags & SLAB_TRACE) {
- pr_info("TRACE %s %s 0x%p inuse=%d fp=0x%p\n",
+ pr_info("TRACE %s %s 0x%px inuse=%d fp=0x%px\n",
s->name,
alloc ? "alloc" : "free",
object, page->inuse,
@@ -1186,7 +1186,7 @@ static inline int free_consistency_checks(struct kmem_cache *s,
struct page *page, void *object, unsigned long addr)
{
if (!check_valid_pointer(s, page, object)) {
- slab_err(s, page, "Invalid object pointer 0x%p", object);
+ slab_err(s, page, "Invalid object pointer 0x%px", object);
return 0;
}
@@ -1200,10 +1200,10 @@ static inline int free_consistency_checks(struct kmem_cache *s,
if (unlikely(s != page->slab_cache)) {
if (!PageSlab(page)) {
- slab_err(s, page, "Attempt to free object(0x%p) outside of slab",
+ slab_err(s, page, "Attempt to free object(0x%px) outside of slab",
object);
} else if (!page->slab_cache) {
- pr_err("SLUB <none>: no slab for object 0x%p.\n",
+ pr_err("SLUB <none>: no slab for object 0x%px.\n",
object);
dump_stack();
} else
@@ -1263,7 +1263,7 @@ static noinline int free_debug_processing(
slab_unlock(page);
spin_unlock_irqrestore(&n->list_lock, flags);
if (!ret)
- slab_fix(s, "Object at 0x%p not freed", object);
+ slab_fix(s, "Object at 0x%px not freed", object);
return ret;
}
@@ -3908,7 +3908,7 @@ static void list_slab_objects(struct kmem_cache *s, struct page *page,
for_each_object(p, s, addr, page->objects) {
if (!test_bit(__obj_to_index(s, addr, p), map)) {
- pr_err("Object 0x%p @offset=%tu\n", p, p - addr);
+ pr_err("Object 0x%px @offset=%tu\n", p, p - addr);
print_tracking(s, p);
}
}
--
https://chromeos.dev
+CC folks from the no_hash_pointers debate
Full thread with patches here:
https://lore.kernel.org/linux-mm/[email protected]/
On 5/20/21 3:35 AM, Stephen Boyd wrote:
> I was doing some debugging recently and noticed that my pointers were
> being hashed while slub_debug was on the kernel commandline. Let's make
> the prints in here meaningful in that case by pushing %px throughout.
But we actually added no_hash_pointers exactly so that we don't push %px in
hexdump and others. So I don't think this will be accepted.
> Alternatively, we could force on no_hash_pointers if slub_debug is on
> the commandline. Maybe that would be better?
That would certainly be more acceptable, but maybe still too much, dunno. I'm
neutral on this approach, let's see what others think.
> The final patch is just something else I noticed while looking at the
> code. The message argument is never used so the debugging messages are
> not as clear as they could be.
>
> Stephen Boyd (3):
> lib/hexdump: Add a raw pointer printing format for slub debugging
> slub: Print raw pointer addresses when debugging
> slub: Actually use 'message' in restore_bytes()
>
> include/linux/printk.h | 1 +
> lib/hexdump.c | 12 ++++++++++--
> mm/slub.c | 24 ++++++++++++------------
> 3 files changed, 23 insertions(+), 14 deletions(-)
>
>
> base-commit: 6efb943b8616ec53a5e444193dccf1af9ad627b5
>
On 5/20/21 3:35 AM, Stephen Boyd wrote:
> The message argument isn't used here. Let's pass the string to the
> printk message so that the developer can figure out what's happening,
> instead of guessing that a redzone is being restored, etc.
>
> Signed-off-by: Stephen Boyd <[email protected]>
Reviewed-by: Vlastimil Babka <[email protected]>
> ---
> mm/slub.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/mm/slub.c b/mm/slub.c
> index 87eeeed1f369..16e8e8f8dc0c 100644
> --- a/mm/slub.c
> +++ b/mm/slub.c
> @@ -777,7 +777,7 @@ static void init_object(struct kmem_cache *s, void *object, u8 val)
> static void restore_bytes(struct kmem_cache *s, char *message, u8 data,
> void *from, void *to)
> {
> - slab_fix(s, "Restoring 0x%px-0x%px=0x%x\n", from, to - 1, data);
> + slab_fix(s, "Restoring %s 0x%px-0x%px=0x%x\n", message, from, to - 1, data);
> memset(from, data, to - from);
> }
>
>
On Wed, 19 May 2021, Stephen Boyd wrote:
> We want to get actual pointer addresses when we're looking at slub
> debugging reports. Add another prefix format specifier that says we want
> raw pointer addresses, i.e. %px, in the printk format.
>
> Signed-off-by: Stephen Boyd <[email protected]>
Acked-by: David Rientjes <[email protected]>
On Wed, 19 May 2021, Stephen Boyd wrote:
> The message argument isn't used here. Let's pass the string to the
> printk message so that the developer can figure out what's happening,
> instead of guessing that a redzone is being restored, etc.
>
> Signed-off-by: Stephen Boyd <[email protected]>
Acked-by: David Rientjes <[email protected]>
On Wed 2021-05-19 18:35:38, Stephen Boyd wrote:
> Obscuring the pointers that slub shows when debugging makes for some
> confusing slub debug messages:
>
> Padding overwritten. 0x0000000079f0674a-0x000000000d4dce17
>
> Those addresses are hashed for kernel security reasons. If we're trying
> to be secure with slub_debug on the commandline we have some big
> problems given that we dump whole chunks of kernel memory to the kernel
> logs. Let's use %px here and dump buffers with the actual address for
> the buffer instead of the hashed version so that the logs are
> meaningful. This also helps if a kernel address is in some slub debug
> report so we can figure out that the object is referencing itself.
Please, do not do this!
Use "no_hash_pointers" commandling option when you want to see
raw pointers. It will make it clear when the kernel logs are save
and when not.
If "slub_debug" is useless with hashed pointers then it might enable
"no_hash_pointers". But make sure that it prints the fat warning.
This patch is the worst approach. We have to keep the number of "%px"
callers at minimum to keep it maintainable. The only safe use-case is
when the system is in panic() [*]. If the pointers might be printed
at any time then users should be warned by the fat message printed
by "no_hash_pointers".
[*] Raw pointers are currently printed also by Oops/WARN messages.
It is from historic reasons. Anyway, they are fat warnings
on its own. The system often need to get reported anyway.
Best Regards,
Petr
On Wed 2021-05-19 18:35:37, Stephen Boyd wrote:
> We want to get actual pointer addresses when we're looking at slub
> debugging reports. Add another prefix format specifier that says we want
> raw pointer addresses, i.e. %px, in the printk format.
This patch makes sense only with the 2nd patch.
Please, do not do this! Raw pointers might be printed safely
only in panic(). Users should be warned by the fat warning
triggered by "no_hash_pointers" in other use-cases. And
this patch is not needed when "no_hash_pointers" are enabled.
Best Regards,
Petr
Quoting Petr Mladek (2021-05-24 04:32:13)
> On Wed 2021-05-19 18:35:38, Stephen Boyd wrote:
> > Obscuring the pointers that slub shows when debugging makes for some
> > confusing slub debug messages:
> >
> > Padding overwritten. 0x0000000079f0674a-0x000000000d4dce17
> >
> > Those addresses are hashed for kernel security reasons. If we're trying
> > to be secure with slub_debug on the commandline we have some big
> > problems given that we dump whole chunks of kernel memory to the kernel
> > logs. Let's use %px here and dump buffers with the actual address for
> > the buffer instead of the hashed version so that the logs are
> > meaningful. This also helps if a kernel address is in some slub debug
> > report so we can figure out that the object is referencing itself.
>
> Please, do not do this!
>
> Use "no_hash_pointers" commandling option when you want to see
> raw pointers. It will make it clear when the kernel logs are save
> and when not.
>
> If "slub_debug" is useless with hashed pointers then it might enable
> "no_hash_pointers". But make sure that it prints the fat warning.
Ok I'll try to make slub_debug force on no_hash_pointers.
>
> This patch is the worst approach. We have to keep the number of "%px"
> callers at minimum to keep it maintainable. The only safe use-case is
> when the system is in panic() [*]. If the pointers might be printed
> at any time then users should be warned by the fat message printed
> by "no_hash_pointers".
>
>
> [*] Raw pointers are currently printed also by Oops/WARN messages.
> It is from historic reasons. Anyway, they are fat warnings
> on its own. The system often need to get reported anyway.
>
Got it. The slub debug messages are usually followed by stuff blowing up
and the system crashing but it's possible that the automatic fixup code
will save us. When you have things scribbling all over the place it
doesn't end well.
On Sun, 2021-05-23 at 22:12 -0700, David Rientjes wrote:
> On Wed, 19 May 2021, Stephen Boyd wrote:
>
> > The message argument isn't used here. Let's pass the string to the
> > printk message so that the developer can figure out what's happening,
> > instead of guessing that a redzone is being restored, etc.
> >
> > Signed-off-by: Stephen Boyd <[email protected]>
>
> Acked-by: David Rientjes <[email protected]>
Ideally, the slab_fix function would be marked with __printf and the
format here would not use \n as that's emitted by the slab_fix.
---
mm/slub.c | 8 +++++---
1 file changed, 5 insertions(+), 3 deletions(-)
diff --git a/mm/slub.c b/mm/slub.c
index ee51857d8e9bc..46f9b043089b6 100644
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -702,6 +702,7 @@ static void slab_bug(struct kmem_cache *s, char *fmt, ...)
va_end(args);
}
+__printf(2, 3)
static void slab_fix(struct kmem_cache *s, char *fmt, ...)
{
struct va_format vaf;
@@ -816,7 +817,8 @@ static void init_object(struct kmem_cache *s, void *object, u8 val)
static void restore_bytes(struct kmem_cache *s, char *message, u8 data,
void *from, void *to)
{
- slab_fix(s, "Restoring %s 0x%px-0x%px=0x%x\n", message, from, to - 1, data);
+ slab_fix(s, "Restoring %s 0x%px-0x%px=0x%x",
+ message, from, to - 1, data);
memset(from, data, to - from);
}
@@ -1069,13 +1071,13 @@ static int on_freelist(struct kmem_cache *s, struct page *page, void *search)
slab_err(s, page, "Wrong number of objects. Found %d but should be %d",
page->objects, max_objects);
page->objects = max_objects;
- slab_fix(s, "Number of objects adjusted.");
+ slab_fix(s, "Number of objects adjusted");
}
if (page->inuse != page->objects - nr) {
slab_err(s, page, "Wrong object count. Counter is %d but counted were %d",
page->inuse, page->objects - nr);
page->inuse = page->objects - nr;
- slab_fix(s, "Object count adjusted.");
+ slab_fix(s, "Object count adjusted");
}
return search == NULL;
}
Quoting Joe Perches (2021-05-25 00:37:45)
> On Sun, 2021-05-23 at 22:12 -0700, David Rientjes wrote:
> > On Wed, 19 May 2021, Stephen Boyd wrote:
> >
> > > The message argument isn't used here. Let's pass the string to the
> > > printk message so that the developer can figure out what's happening,
> > > instead of guessing that a redzone is being restored, etc.
> > >
> > > Signed-off-by: Stephen Boyd <[email protected]>
> >
> > Acked-by: David Rientjes <[email protected]>
>
> Ideally, the slab_fix function would be marked with __printf and the
> format here would not use \n as that's emitted by the slab_fix.
Thanks. I can make this into a proper patch and author it from you. Can
you provide a signed-off-by? The restore_bytes() hunk is slightly
different but I can fix that up.
> ---
> mm/slub.c | 8 +++++---
> 1 file changed, 5 insertions(+), 3 deletions(-)
>
> diff --git a/mm/slub.c b/mm/slub.c
> index ee51857d8e9bc..46f9b043089b6 100644
> --- a/mm/slub.c
> +++ b/mm/slub.c
> @@ -702,6 +702,7 @@ static void slab_bug(struct kmem_cache *s, char *fmt, ...)
> va_end(args);
> }
>
> +__printf(2, 3)
> static void slab_fix(struct kmem_cache *s, char *fmt, ...)
> {
> struct va_format vaf;
> @@ -816,7 +817,8 @@ static void init_object(struct kmem_cache *s, void *object, u8 val)
> static void restore_bytes(struct kmem_cache *s, char *message, u8 data,
> void *from, void *to)
> {
> - slab_fix(s, "Restoring %s 0x%px-0x%px=0x%x\n", message, from, to - 1, data);
> + slab_fix(s, "Restoring %s 0x%px-0x%px=0x%x",
> + message, from, to - 1, data);
> memset(from, data, to - from);
> }
>
> @@ -1069,13 +1071,13 @@ static int on_freelist(struct kmem_cache *s, struct page *page, void *search)
> slab_err(s, page, "Wrong number of objects. Found %d but should be %d",
> page->objects, max_objects);
> page->objects = max_objects;
> - slab_fix(s, "Number of objects adjusted.");
> + slab_fix(s, "Number of objects adjusted");
> }
> if (page->inuse != page->objects - nr) {
> slab_err(s, page, "Wrong object count. Counter is %d but counted were %d",
> page->inuse, page->objects - nr);
> page->inuse = page->objects - nr;
> - slab_fix(s, "Object count adjusted.");
> + slab_fix(s, "Object count adjusted");
> }
> return search == NULL;
> }
>
>
On Tue, 2021-05-25 at 22:32 -0400, Stephen Boyd wrote:
> Quoting Joe Perches (2021-05-25 00:37:45)
> > On Sun, 2021-05-23 at 22:12 -0700, David Rientjes wrote:
> > > On Wed, 19 May 2021, Stephen Boyd wrote:
> > >
> > > > The message argument isn't used here. Let's pass the string to the
> > > > printk message so that the developer can figure out what's happening,
> > > > instead of guessing that a redzone is being restored, etc.
> > > >
> > > > Signed-off-by: Stephen Boyd <[email protected]>
> > >
> > > Acked-by: David Rientjes <[email protected]>
> >
> > Ideally, the slab_fix function would be marked with __printf and the
> > format here would not use \n as that's emitted by the slab_fix.
>
> Thanks. I can make this into a proper patch and author it from you. Can
> you provide a signed-off-by? The restore_bytes() hunk is slightly
> different but I can fix that up.
If you want...
Signed-off-by: Joe Perches <[email protected]>
>
> > ---
> > ?mm/slub.c | 8 +++++---
> > ?1 file changed, 5 insertions(+), 3 deletions(-)
> >
> > diff --git a/mm/slub.c b/mm/slub.c
> > index ee51857d8e9bc..46f9b043089b6 100644
> > --- a/mm/slub.c
> > +++ b/mm/slub.c
> > @@ -702,6 +702,7 @@ static void slab_bug(struct kmem_cache *s, char *fmt, ...)
> > ????????va_end(args);
> > ?}
> >
> > +__printf(2, 3)
> > ?static void slab_fix(struct kmem_cache *s, char *fmt, ...)
> > ?{
> > ????????struct va_format vaf;
> > @@ -816,7 +817,8 @@ static void init_object(struct kmem_cache *s, void *object, u8 val)
> > ?static void restore_bytes(struct kmem_cache *s, char *message, u8 data,
> > ????????????????????????????????????????????????void *from, void *to)
> > ?{
> > - slab_fix(s, "Restoring %s 0x%px-0x%px=0x%x\n", message, from, to - 1, data);
> > + slab_fix(s, "Restoring %s 0x%px-0x%px=0x%x",
> > + message, from, to - 1, data);
> > ????????memset(from, data, to - from);
> > ?}
> >
> > @@ -1069,13 +1071,13 @@ static int on_freelist(struct kmem_cache *s, struct page *page, void *search)
> > ????????????????slab_err(s, page, "Wrong number of objects. Found %d but should be %d",
> > ?????????????????????????page->objects, max_objects);
> > ????????????????page->objects = max_objects;
> > - slab_fix(s, "Number of objects adjusted.");
> > + slab_fix(s, "Number of objects adjusted");
> > ????????}
> > ????????if (page->inuse != page->objects - nr) {
> > ????????????????slab_err(s, page, "Wrong object count. Counter is %d but counted were %d",
> > ?????????????????????????page->inuse, page->objects - nr);
> > ????????????????page->inuse = page->objects - nr;
> > - slab_fix(s, "Object count adjusted.");
> > + slab_fix(s, "Object count adjusted");
> > ????????}
> > ????????return search == NULL;
> > ?}
> >
> >