Crash with kfree(null) on MacBook? kobject_set_name_vargs

Crash with kfree(null) on MacBook? kobject_set_name_vargs

[Rafał Miłecki]

I'm writing new axi bus driver and one of the early testers reported
it crashing for him. Andy is using MacBook and backtrace+debugging
pretty clearly point to kfree being called on null string.

The most interesting part of code is:
axi_info("[axi_register_cores][%d] current name: %s\n", i, core->dev.kobj.name);
axi_info("[axi_register_cores][%d] calling dev_set_name with %d, %d
for 0x%03X\n", i, 0/*bus->busnumber*/, dev_id, core->id.id);
err = dev_set_name(&core->dev, "axi%d:%d", 0/*bus->busnumber*/, dev_id);
axi_info("[axi_register_cores][%d] dev_set_name result: %d\n", i, err);

The result is:
[axi_register_cores][1] current name: (null)
[axi_register_cores][1] calling dev_set_name with 0, 0 for 0x812
BUG: unable to handle kernel paging request at ffffeba400000000
IP: [<ffffffff8108c4d4>] kfree+0x2a/0x8a

Whole code: http://pastie.org/1779473
Whole result: http://pastie.org/1779416

Can you help me with this issue, please? On my machine everything goes fine:
[axi_register_cores][1] current name: (null)
[axi_register_cores][1] calling dev_set_name with 0, 0 for 0x812
[axi_register_cores][1] dev_set_name result: 0
[axi_register_cores][1] Register dev for core 0x812

bcopeland on #linux-wireless suggested turning on SLAB or SLUB. Is
this going to provide some interesting info?

-- 
Rafał

Re: Crash with kfree(null) on MacBook? kobject_set_name_vargs

[Rafał Miłecki]

W dniu 10 kwietnia 2011 19:14 użytkownik Rafał Miłecki
<zajec5@gmail.com> napisał:
> I'm writing new axi bus driver and one of the early testers reported
> it crashing for him. Andy is using MacBook and backtrace+debugging
> pretty clearly point to kfree being called on null string.
>
> The most interesting part of code is:
> axi_info("[axi_register_cores][%d] current name: %s\n", i, core->dev.kobj.name);
> axi_info("[axi_register_cores][%d] calling dev_set_name with %d, %d
> for 0x%03X\n", i, 0/*bus->busnumber*/, dev_id, core->id.id);
> err = dev_set_name(&core->dev, "axi%d:%d", 0/*bus->busnumber*/, dev_id);
> axi_info("[axi_register_cores][%d] dev_set_name result: %d\n", i, err);
>
> The result is:
> [axi_register_cores][1] current name: (null)
> [axi_register_cores][1] calling dev_set_name with 0, 0 for 0x812
> BUG: unable to handle kernel paging request at ffffeba400000000
> IP: [<ffffffff8108c4d4>] kfree+0x2a/0x8a
>
> Whole code: http://pastie.org/1779473
> Whole result: http://pastie.org/1779416
>
> Can you help me with this issue, please? On my machine everything goes fine:
> [axi_register_cores][1] current name: (null)
> [axi_register_cores][1] calling dev_set_name with 0, 0 for 0x812
> [axi_register_cores][1] dev_set_name result: 0
> [axi_register_cores][1] Register dev for core 0x812
>
> bcopeland on #linux-wireless suggested turning on SLAB or SLUB. Is
> this going to provide some interesting info?

Link to kobject_set_name_vargs for lazy ;)
http://lxr.free-electrons.com/source/lib/kobject.c#L215

-- 
Rafał

Re: Crash with kfree(null) on MacBook? kobject_set_name_vargs

[Bob Copeland]

2011/4/10 Rafał Miłecki <zajec5@gmail.com>:
> I'm writing new axi bus driver and one of the early testers reported
> it crashing for him. Andy is using MacBook and backtrace+debugging
> pretty clearly point to kfree being called on null string.

> bcopeland on #linux-wireless suggested turning on SLAB or SLUB. Is
> this going to provide some interesting info?

To be precise, I said slab or slub _debugging_.  The reason I said
this is that often a crash on kfree() is due to memory corruption.
Many places in the kernel rely on kfree(NULL) being a safe operation,
so it's likely something more than that.  SL?B debugging adds
poisoning and corresponding checks that detect several kinds of
corruption like buffer overruns, use-after-free, etc.

The other thing you can do is get the disassembly of the Code portion
for your oops and match it up with specific C code, look at the
register file in the oops and match that up with variable names, and
work backwards to figure out which pointers are broken.  Sometimes
this can be enlightening, like if a pointer has ascii values, or is a
small number (0 + some struct offset).
-- 
Bob Copeland %% www.bobcopeland.com

Re: Crash with kfree(null) on MacBook? kobject_set_name_vargs

[Rafał Miłecki]

I just got report from Arend that he's hitting the same issue. I've no
idea what's wrong with my dev_set_name call. Should I pre-init struct
dev somehow? Before calling dev_set_name on it?

W dniu 10 kwietnia 2011 23:28 użytkownik Bob Copeland
<me@bobcopeland.com> napisał:
> 2011/4/10 Rafał Miłecki <zajec5@gmail.com>:
>> I'm writing new axi bus driver and one of the early testers reported
>> it crashing for him. Andy is using MacBook and backtrace+debugging
>> pretty clearly point to kfree being called on null string.
>
>> bcopeland on #linux-wireless suggested turning on SLAB or SLUB. Is
>> this going to provide some interesting info?
>
> To be precise, I said slab or slub _debugging_.  The reason I said
> this is that often a crash on kfree() is due to memory corruption.
> Many places in the kernel rely on kfree(NULL) being a safe operation,
> so it's likely something more than that.  SL?B debugging adds
> poisoning and corresponding checks that detect several kinds of
> corruption like buffer overruns, use-after-free, etc.
>
> The other thing you can do is get the disassembly of the Code portion
> for your oops and match it up with specific C code, look at the
> register file in the oops and match that up with variable names, and
> work backwards to figure out which pointers are broken.  Sometimes
> this can be enlightening, like if a pointer has ascii values, or is a
> small number (0 + some struct offset).

Andy, Arend: I'm not sure if someone will have straight idea whats
wrong with my code. Could you try this SL?B debugging maybe?

-- 
Rafał

Re: Crash with kfree(null) on MacBook? kobject_set_name_vargs

[Linus Torvalds]

2011/4/10 Rafał Miłecki <zajec5@gmail.com>:
> I'm writing new axi bus driver and one of the early testers reported
> it crashing for him. Andy is using MacBook and backtrace+debugging
> pretty clearly point to kfree being called on null string.
>
> The most interesting part of code is:
> axi_info("[axi_register_cores][%d] current name: %s\n", i, core->dev.kobj.name);
> axi_info("[axi_register_cores][%d] calling dev_set_name with %d, %d
> for 0x%03X\n", i, 0/*bus->busnumber*/, dev_id, core->id.id);
> err = dev_set_name(&core->dev, "axi%d:%d", 0/*bus->busnumber*/, dev_id);
> axi_info("[axi_register_cores][%d] dev_set_name result: %d\n", i, err);
>
> The result is:
> [axi_register_cores][1] current name: (null)
> [axi_register_cores][1] calling dev_set_name with 0, 0 for 0x812
> BUG: unable to handle kernel paging request at ffffeba400000000
> IP: [<ffffffff8108c4d4>] kfree+0x2a/0x8a
>
> Whole code: http://pastie.org/1779473
> Whole result: http://pastie.org/1779416
>
> Can you help me with this issue, please? On my machine everything goes fine:
> [axi_register_cores][1] current name: (null)
> [axi_register_cores][1] calling dev_set_name with 0, 0 for 0x812
> [axi_register_cores][1] dev_set_name result: 0
> [axi_register_cores][1] Register dev for core 0x812
>
> bcopeland on #linux-wireless suggested turning on SLAB or SLUB. Is
> this going to provide some interesting info?

The disassembly of the oopsing code (kfree()) is:

   0:	41 54                	push   %r12
   2:	48 83 ff 10          	cmp    $0x10,%rdi
   6:	55                   	push   %rbp
   7:	53                   	push   %rbx
   8:	48 89 fb             	mov    %rdi,%rbx
   b:	76 78                	jbe    0x85
   d:	9c                   	pushfq
   e:	5d                   	pop    %rbp
   f:	fa                   	cli
  10:	e8 85 21 f9 ff       	callq  0xfffffffffff9219a
  15:	48 ba 00 00 00 00 00 	movabs $0xffffea0000000000,%rdx
  1c:	ea ff ff
  1f:	48 c1 e8 0c          	shr    $0xc,%rax
  23:	48 6b c0 38          	imul   $0x38,%rax,%rax
  27:	48 01 d0             	add    %rdx,%rax
  2a:*	48 8b 10             	mov    (%rax),%rdx     <-- trapping instruction
  2d:	66 85 d2             	test   %dx,%dx
  30:	79 04                	jns    0x36

and from that you can see that the parameter that was passed in to
kfree (which was originally in %rdi) is now in %rbx.

That, in turn, is 0x202.

So it's not NULL. The fact that

  axi_info("[axi_register_cores][%d] current name: %s\n", i,
core->dev.kobj.name);

prints out NULL is because the string printout code does this:

        if ((unsigned long)s < PAGE_SIZE)
                s = "(null)";


which admittedly is not very helpful in this case (but it's usually
nicer than just oopsing).

So code->dev.kobj.name is corrupt even before.

Where that corruption comes from, I have no idea, but there is no
point in blaming kfree() or dev_set_name().

                           Linus

Re: Crash with kfree(null) on MacBook? kobject_set_name_vargs

[Linus Torvalds]

[-- Attachment #1: Type: text/plain, Size: 853 bytes --]

2011/4/11 Linus Torvalds <torvalds@linux-foundation.org>:
>
> prints out NULL is because the string printout code does this:
>
>        if ((unsigned long)s < PAGE_SIZE)
>                s = "(null)";
>
> which admittedly is not very helpful in this case (but it's usually
> nicer than just oopsing).

You could try this (UNTESTED!) patch to avoid this particular issue.
It will (well, unless I screwed up) print non-NULL pointers as the hex
value they have. So you should see "0x202" instead of "(null)" in that
case.

Of course, it sounds like _you_ don't actually see the bug at all,
because for you it probably really _is_ NULL. The people who see the
bug have some random non-null value, probably because of the field
just not being initialized properly, and containing some crud.

                                       Linus

[-- Attachment #2: patch.diff --]
[-- Type: text/x-patch, Size: 577 bytes --]

 lib/vsprintf.c |    8 +++++++-
 1 files changed, 7 insertions(+), 1 deletions(-)

diff --git a/lib/vsprintf.c b/lib/vsprintf.c
index bc0ac6b333dc..dabc310684bf 100644
--- a/lib/vsprintf.c
+++ b/lib/vsprintf.c
@@ -400,8 +400,14 @@ char *string(char *buf, char *end, const char *s, struct printf_spec spec)
 {
 	int len, i;
 
-	if ((unsigned long)s < PAGE_SIZE)
+	if ((unsigned long)s < PAGE_SIZE) {
+		if (s) {
+			spec.base = 16;
+			spec.flags |= SPECIAL;
+			return number(buf, end, (unsigned long)s, spec);
+		}
 		s = "(null)";
+	}
 
 	len = strnlen(s, spec.precision);
 

Re: Crash with kfree(null) on MacBook? kobject_set_name_vargs

[Rafał Miłecki]

W dniu 11 kwietnia 2011 19:41 użytkownik Linus Torvalds
<torvalds@linux-foundation.org> napisał:
> 2011/4/10 Rafał Miłecki <zajec5@gmail.com>:
>> I'm writing new axi bus driver and one of the early testers reported
>> it crashing for him. Andy is using MacBook and backtrace+debugging
>> pretty clearly point to kfree being called on null string.
>>
>> The most interesting part of code is:
>> axi_info("[axi_register_cores][%d] current name: %s\n", i, core->dev.kobj.name);
>> axi_info("[axi_register_cores][%d] calling dev_set_name with %d, %d
>> for 0x%03X\n", i, 0/*bus->busnumber*/, dev_id, core->id.id);
>> err = dev_set_name(&core->dev, "axi%d:%d", 0/*bus->busnumber*/, dev_id);
>> axi_info("[axi_register_cores][%d] dev_set_name result: %d\n", i, err);
>>
>> The result is:
>> [axi_register_cores][1] current name: (null)
>> [axi_register_cores][1] calling dev_set_name with 0, 0 for 0x812
>> BUG: unable to handle kernel paging request at ffffeba400000000
>> IP: [<ffffffff8108c4d4>] kfree+0x2a/0x8a
>>
>> Whole code: http://pastie.org/1779473
>> Whole result: http://pastie.org/1779416
>>
>> Can you help me with this issue, please? On my machine everything goes fine:
>> [axi_register_cores][1] current name: (null)
>> [axi_register_cores][1] calling dev_set_name with 0, 0 for 0x812
>> [axi_register_cores][1] dev_set_name result: 0
>> [axi_register_cores][1] Register dev for core 0x812
>>
>> bcopeland on #linux-wireless suggested turning on SLAB or SLUB. Is
>> this going to provide some interesting info?
>
> The disassembly of the oopsing code (kfree()) is:
>
>   0:   41 54                   push   %r12
>   2:   48 83 ff 10             cmp    $0x10,%rdi
>   6:   55                      push   %rbp
>   7:   53                      push   %rbx
>   8:   48 89 fb                mov    %rdi,%rbx
>   b:   76 78                   jbe    0x85
>   d:   9c                      pushfq
>   e:   5d                      pop    %rbp
>   f:   fa                      cli
>  10:   e8 85 21 f9 ff          callq  0xfffffffffff9219a
>  15:   48 ba 00 00 00 00 00    movabs $0xffffea0000000000,%rdx
>  1c:   ea ff ff
>  1f:   48 c1 e8 0c             shr    $0xc,%rax
>  23:   48 6b c0 38             imul   $0x38,%rax,%rax
>  27:   48 01 d0                add    %rdx,%rax
>  2a:*  48 8b 10                mov    (%rax),%rdx     <-- trapping instruction
>  2d:   66 85 d2                test   %dx,%dx
>  30:   79 04                   jns    0x36
>
> and from that you can see that the parameter that was passed in to
> kfree (which was originally in %rdi) is now in %rbx.
>
> That, in turn, is 0x202.
>
> So it's not NULL. The fact that
>
>  axi_info("[axi_register_cores][%d] current name: %s\n", i,
> core->dev.kobj.name);
>
> prints out NULL is because the string printout code does this:
>
>        if ((unsigned long)s < PAGE_SIZE)
>                s = "(null)";
>
>
> which admittedly is not very helpful in this case (but it's usually
> nicer than just oopsing).
>
> So code->dev.kobj.name is corrupt even before.
>
> Where that corruption comes from, I have no idea, but there is no
> point in blaming kfree() or dev_set_name().

Thank you Linus, now when you made it clear to me that NULL ~!= NULL,
I realized I didn't zeroed struct which contains struct dev.

struct axi_device core;
vs.
struct axi_device core = { };

-- 
Rafał

Re: Crash with kfree(null) on MacBook? kobject_set_name_vargs

[Steven Rostedt]

On Mon, Apr 11, 2011 at 09:38:02PM +0200, Rafa?? Mi??ecki wrote:
> Thank you Linus, now when you made it clear to me that NULL ~!= NULL,
> I realized I didn't zeroed struct which contains struct dev.
> 
> struct axi_device core;
> vs.
> struct axi_device core = { };

The two are identical. If they are declared as globals or static. As
globals and static variables are initialized to zero at start up.

Is this on the stack or global? If on the stack, you need the
initializer, if it is global you do not.

IOW:

struct axi_device core;
static struct axi_device core;

void func(void)
{
	static struct axi_device core;
[...]

All the above is OK with no initializer.

void func(void)
{
	struct axi_device core = {};


This does need an initializer, but gcc should complain if you use core
without initializing.

-- Steve