Skip to contentSkip to conversation

Question on debugging use-after-free memory issues.

DISCUSSION Ben Greear 3 participants 4 messages Jun 27, 2011 – Jun 29, 2011

Subsystems (3)
Networking NFS client NFS server
lore
Share & tools
lore

Ben Greear

author
#0 lore raw

I have a case where deleted memory is being passed into an RPC callback. I enabled SLUB memory poisoning and verified that the data pointed to has 0x6b...6b value.

Unfortunately, the rpc code is a giant maze of callbacks and I'm having a difficult time figuring out where this data could be erroneously deleted at.

So first question:

Given a pointer to memory, and with SLUB memory debuging on (and/or other debugging options if applicable), is there a way to get any info about where the memory was last deleted?

Second: Any other suggestions for how to go about debugging this?

I hit this problem under load after multiple hours, so just adding printks in random places may not be feasible...

Thanks,
Ben

Signature · 2 lines
Ben Greear <[email protected]>
Candela Technologies Inc  http://www.candelatech.com
#1 lore raw
Quoted 10 lines · Ben Greear

I have a case where deleted memory is being passed into an RPC callback. I enabled SLUB memory poisoning and verified that the data pointed to has 0x6b...6b value.

Unfortunately, the rpc code is a giant maze of callbacks and I'm having a difficult time figuring out where this data could be erroneously deleted at.

So first question:

Quoted 8 lines

Given a pointer to memory, and with SLUB memory debuging on (and/or other debugging options if applicable), is there a way to get any info about where the memory was last deleted?

Second: Any other suggestions for how to go about debugging this?

I hit this problem under load after multiple hours, so just adding printks in random places may not be feasible...

First, this is not really a proper list for such questions. I'd propose kernel newbies community next time.

Anyway, I'd propose to start with kmemcheck (see Documentation/kmemcheck.txt). It could pin-point the problemtic spot immediately (or it might not).

Signature · 2 lines
Jiri Kosina
SUSE Labs
#2 lore raw
Quoted 16 lines · Jiri Kosina
Quoted 14 lines · Ben Greear

I have a case where deleted memory is being passed into an RPC callback. I enabled SLUB memory poisoning and verified that the data pointed to has 0x6b...6b value.

Unfortunately, the rpc code is a giant maze of callbacks and I'm having a difficult time figuring out where this data could be erroneously deleted at.

So first question:

Given a pointer to memory, and with SLUB memory debuging on (and/or other debugging options if applicable), is there a way to get any info about where the memory was last deleted?

Quoted 8 lines
Quoted 4 lines

Second: Any other suggestions for how to go about debugging this?

I hit this problem under load after multiple hours, so just adding printks in random places may not be feasible...

First, this is not really a proper list for such questions. I'd propose kernel newbies community next time.

LKML is definitely a place for such questions.

Quoted 4 lines

Anyway, I'd propose to start with kmemcheck (see Documentation/kmemcheck.txt). It could pin-point the problemtic spot immediately (or it might not).

kmemcheck is fine if problem is not coming from an SMP bug only. Also kmemcheck is so slow it makes a rare bug becoming very hard to trigger.

Ben, given that you know that RPC might have a problem on a given small object (struct rpcbind_args ), you could afford changing the kmalloc()/kfree() used to allocate/free such objects by calls to page allocator, and dont free the page but unmap it from kernel mapping so that any further read/write access triggers a fault. You can then have a more precise idea of what's happening, without slowing down whole kernel. Of course there is a mem leak for each "struct rpcbind_args" allocated, so this is a debugging aid only.

DEBUG_PAGEALLOC might be too expensive, so try this patch (untested, you might need to complete it)

net/sunrpc/rpcb_clnt.c +2 -2
index 9a80a92..9b4dbaf 100644
@@ -158,7 +158,7 @@ static void rpcb_map_release(void *data)
 	rpcb_wake_rpcbind_waiters(map->r_xprt, map->r_status);
 	xprt_put(map->r_xprt);
 	kfree(map->r_addr);
-	kfree(map);
+	kernel_map_pages(virt_to_page(map), 1, 0);
 }
 
 /*

@@ -668,7 +668,7 @@ void rpcb_getport_async(struct rpc_task *task)
 		goto bailout_nofree;
 	}
 
-	map = kzalloc(sizeof(struct rpcbind_args), GFP_ATOMIC);
+	map = (struct rpcbind_args *)__get_free_page(GFP_ATOMIC | __GFP_ZERO);
 	if (!map) {
 		status = -ENOMEM;
 		dprintk("RPC: %5u %s: no memory available\n",
author
#3 lore raw
Quoted 10 lines · Eric Dumazet
Quoted 6 lines · Jiri Kosina

On Mon, 27 Jun 2011, Ben Greear wrote:

Anyway, I'd propose to start with kmemcheck (see Documentation/kmemcheck.txt). It could pin-point the problemtic spot immediately (or it might not).

kmemcheck is fine if problem is not coming from an SMP bug only. Also kmemcheck is so slow it makes a rare bug becoming very hard to trigger.

I think I've pretty much verified that deleted memory is passed down a certain call path with the slub patches I posted.
What I can't figure out is how that came to be.

Quoted 27 lines

Ben, given that you know that RPC might have a problem on a given small object (struct rpcbind_args ), you could afford changing the kmalloc()/kfree() used to allocate/free such objects by calls to page allocator, and dont free the page but unmap it from kernel mapping so that any further read/write access triggers a fault. You can then have a more precise idea of what's happening, without slowing down whole kernel. Of course there is a mem leak for each "struct rpcbind_args" allocated, so this is a debugging aid only.

DEBUG_PAGEALLOC might be too expensive, so try this patch (untested, you might need to complete it)

net/sunrpc/rpcb_clnt.c +1 -1
index 9a80a92..9b4dbaf 100644
@@ -158,7 +158,7 @@ static void rpcb_map_release(void *data)
  	rpcb_wake_rpcbind_waiters(map->r_xprt, map->r_status);
  	xprt_put(map->r_xprt);
  	kfree(map->r_addr);
-	kfree(map);
+	kernel_map_pages(virt_to_page(map), 1, 0);
  }
 
  /*

net/sunrpc/rpcb_clnt.c void rpcb_getport_async(struct rpc_task *task) · line 674

Quoted 8 lines
net/sunrpc/rpcb_clnt.c +1 -1
@@ -668,7 +668,7 @@ void rpcb_getport_async(struct rpc_task *task)
  		goto bailout_nofree;
  	}
 
-	map = kzalloc(sizeof(struct rpcbind_args), GFP_ATOMIC);
+	map = (struct rpcbind_args *)__get_free_page(GFP_ATOMIC | __GFP_ZERO);
  	if (!map) {
  		status = -ENOMEM;
  		dprintk("RPC: %5u %s: no memory available\n",

It takes possibly hours of heavy load to hit the problem, so I think I cannot afford to leak that much memory.

Interestingly, I added this code below, and haven't hit the problem since. I'm not sure if it just changed the timing, or what...or maybe I'll hit it overnight...

I tried setting this (below) to 0x6b instead of 0x0 (mempool doesn't really kmalloc/free too often, so the slub poisoning doesn't help), but never did hit the bug again.

I suspect that somehow the task object is still on the work-queue, when it is deleted, but since the 0x6b and 0x0 poisoning didn't cause any funny crashes, I could easily be wrong about that.

net/sunrpc/sched.c +6 -0
index 17c3e3a..d94f009 100644
@@ -859,6 +859,12 @@ static void rpc_free_task(struct rpc_task *task)
 
        if (task->tk_flags & RPC_TASK_DYNAMIC) {
                dprintk("RPC: %5u freeing task\n", task->tk_pid);
+               /* HACK:  Have been seeing use-after-free of calldata.  Zero this memory
+                * so that it cannot happen here.  Seems to have fixed the problem
+                * in 3.0 kernel, but maybe it just adjusted timing..either way,
+                * it's not a real fix. --Ben
+                */
+               memset(task, 0, sizeof(*task));
                mempool_free(task, rpc_task_mempool);
        }
        rpc_release_calldata(tk_ops, calldata);

Thanks,
Ben

Signature · 2 lines
Ben Greear <[email protected]>
Candela Technologies Inc  http://www.candelatech.com