Red Hat Bugzilla – Bug 595397
GFS2: stuck in inode wait, no glocks stuck
Last modified: 2011-11-02 16:25:59 EDT
This request was evaluated by Red Hat Product Management for inclusion in a Red Hat Enterprise Linux maintenance release. Product Management has requested further review of this request by Red Hat Engineering, for potential inclusion in a Red Hat Enterprise Linux Update release for currently deployed products. This request is not yet committed for inclusion in an Update release.
Time for an update on this problem. I back-ported the RHEL6 patches to RHEL5.6 and, given enough pressure, I can recreate various problems that did not appear in RHEL6.0. The main problem seems to occur in the gfs2-minrg coherency test. The symptom is this: Unable to handle kernel NULL pointer dereference at 0000000000000000 RIP: [<0000000000000000>] _stext+0x7ffff000/0x1000 PGD 2041d8067 PUD 20a010067 PMD 0 Oops: 0010 [1] SMP last sysfs file: /devices/pci0000:00/0000:00:1c.5/0000:06:00.0/irq CPU 1 Modules linked in: md5 sctp lock_dlm gfs2(U) dlm configfs autofs4 hidp rfcomm l2cap bluetooth dm_log_clustered(U) lockd sunrpc be2iscsi ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp bnx2i cnic ipv6 xfrm_nalgo crypto_api uio cxgb3i cxgb3 8021q libiscsi_tcp libiscsi2 scsi_transport_iscsi2 scsi_transport_iscsi dm_multipath scsi_dh video backlight sbs power_meter hwmon i2c_ec dell_wmi wmi button battery asus_acpi acpi_memhotplug ac parport_pc lp parport sr_mod joydev tg3 ide_cd serio_raw pata_sil680 i3000_edac i2c_i801 shpchp cdrom i2c_core edac_mc sg pcspkr dm_raid45 dm_message dm_region_hash dm_mem_cache dm_snapshot dm_zero dm_mirror dm_log dm_mod qla2xxx scsi_transport_fc ata_piix libata sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd Pid: 3191, comm: dlm_astd Tainted: G 2.6.18-200.el5 #1 RIP: 0010:[<0000000000000000>] [<0000000000000000>] _stext+0x7ffff000/0x1000 RSP: 0018:ffff8102314bfeb8 EFLAGS: 00010247 RAX: 0000000000000000 RBX: ffff8101fbeec4d8 RCX: 0000000000000001 RDX: ffff810208b63188 RSI: 0000000000000101 RDI: 0000000000200200 RBP: 0000000000000005 R08: ffff8102314be000 R09: ffff810232b75280 R10: 0000000000000003 R11: 0000000000000000 R12: ffffffff888212c1 R13: 0000000000000002 R14: ffff81023149fca8 R15: ffffffff800a07e7 FS: 0000000000000000(0000) GS:ffff8101fffb77c0(0000) knlGS:0000000000000000 CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b CR2: 0000000000000000 CR3: 0000000204270000 CR4: 00000000000006e0 Process dlm_astd (pid: 3191, threadinfo ffff8102314be000, task ffff810231462080) Stack: ffffffff88775238 ffff81023149fcb8 0000000000000000 ffffffff88775137 ffff81023149fcb8 0000000000000282 ffffffff80032880 0000000000000000 ffff810231462080 ffffffffffffffff ffffffffffffffff ffffffffffffffff Call Trace: [<ffffffff88775238>] :dlm:dlm_astd+0x101/0x14f [<ffffffff88775137>] :dlm:dlm_astd+0x0/0x14f [<ffffffff80032880>] kthread+0xfe/0x132 [<ffffffff8005dfb1>] child_rip+0xa/0x11 [<ffffffff800a07e7>] keventd_create_kthread+0x0/0xc4 In other words, dlm sends GFS2 a glock callback and that apparently has a bad pointer. I've backtracked the problem to the fact that gfs2 has deleted the lock_dlm lock structure before the dlm is done using it. This is _always_ on an iopen glock by the way. The reason, it turns out, is because function gfs2_clear_inode was called, destroying the inode and subsequently its i_open glock, so it's clearly a use-after-free error and the corrupt pointer is due to the memory of the lock_dlm lock structure being reused. Today I backtracked some more and, as I feared, the problem seems due to the sequence of events when dealing with reclaiming unlinked dinodes. Today's instrumentation makes me believe very strongly that we have a race. One unknown process holds the inode's i_open glock. Another is trying to allocate blocks in the same rgrp and finds the block is unlinked and needs to be reclaimed. When the second process calls my new function gfs2_process_unlinked_inode, the function does a LM_FLAG_TRY trylock on the i_open glock, but when that fails with TRY_FAILED, function gfs2_glock_nq_init, having found an error, calls uninit on the holder. The problem is, the gfs2_holder is common to all users of the ip, also known as ip->i_iopen_gh. The first process blocks in the dlm. The second one's TRY_FAILED attempt nukes the holder being waited on by the first one's attempt. When dlm responds with its callback, the memory has been destroyed. It almost seems like there are two scenarios happening here but they both stem from this re-use of the i_open holder. I've written about this concern before. The reason this does not happen in RHEL6 is because in RHEL6 the lock_dlm has been integrated with the glock layer, so the lock_dlm locking structure isn't relied upon, and the glock will still exist. Today I attempted another solution, but that failed and I know why. I'll craft another solution tomorrow or Monday. When done, whatever solution I come up with should be ported back to RHEL6.
Why does the solution require a RHEL6 backport if RHEL6 doesn't have the problem?
The trace in comment #2 has an RIP value of 0. That suggests that this is a call to a NULL function pointer. However, in the dlm ast code, there is a check for that occurring on the two ast/bast functions. In addition, the gfs2 code only ever uses constant values for those functions for all glocks. This suggests that something else might be wrong, or that this trace isn't giving us all the details. If the functions were NULL then the code in astd should have picked that up and not called the callbacks. It would be worth adding a check to the astd loop to check that the ref count on the lkbs is correct. That should catch any use-after-free problems. The same check could also be added into dlm_add_ast in case we can catch it earlier. I guess we should also add a check for NULL parameters being provided to the ast/bast functions too. If you get any better/different stack traces, please upload those to the bz too.
Yesterday, for a while, I thought the problem was due to the fact that the i_iopen_gh holder was being used half of the time without the TRY flag, via gfs2_inode_lookup and half of the time with the TRY flag by gfs2_process_unlinked_inode. The TRY bit is getting turned on and off while multiple glock operations were taking place. As an experiment, I changed the lock in gfs2_process_unlinked_inode to not have the TRY flag. The failing scenario ran successfully about eight times (each run being about 10 to 15 minutes), but then it failed with the same error. So the problem isn't the TRY flag. I added instrumentation to dlm to see if it was perhaps using a pointer after it was done with it, but dlm passed the test with flying colors: the same corruption occurred with the dlm having apparently done nothing wrong (that I could tell with that instrumentation). Basically, I made the dlm completely destroy its lkb pointer whenever it was freed, so accesses to it after the lkb was freed should have triggered a gpf or something. This was a complex, pervasive patch that yielded no results, but at least it told me what's _not_ happening. This is similar to a patch I did a couple weeks ago where I added checks to the dlm to make sure lvbs were not overwritten. That ended the same way: dlm seems innocent. Before that patch, I had another that verified in the dlm that everything was set properly in the lkb. Then a similar one in gfs2 that made sure the glock was proper before submitting the request to dlm. Then another in lock_dlm that made sure the bast address had not changed from its original address in various places (it only was different just before the failing bast call), and Dave did a similar patch for the dlm. So the big question is: why would dlm make a call to the bast function for a freed gdlm_lock? Instrumentation has all but proven the gdlm_lock associated with the call was set correctly, locked correctly, unlocked correctly and then freed properly. I can even tell you the path by which it was freed: gfs2_clear_inode gfs2_glock_dq_uninit(&ip->i_iopen_gh); gfs2_glock_put glock_free gfs2_lm_put_lock lm_put_lock gdlm_put_lock kfree the lock_dlm structure This seems to be a case of memory corruption, because the gdlm_lock structure getting the bast call indicates (via instrumentation) the memory was already freed. The corruption is always in the gdlm_lock structure for an i_iopen inode. All attempts to detect corruption before the dlm call have yielded no results.
We do have some other clues though, in that it might be the same thing as that reported in bug #568102 comment #14. I've been trying to figure out what possible problems might cause that symptom and whether it might be the same problem as we are seeing here. Looking at the above call graph, I'd suggest that the bug might simply be not waiting for the reply to the dlm demote request before freeing the lock_dlm structure. At least I can't see where we wait for that here. In RHEL6 at least we know that we don't free the glock until the final reply from the DLM telling us that the lock is ready to be freed. I'd suggest poisoning the structure when its freed so that it will be obvious if it is a freed structure thats being dereferenced. The slab debugging code should be able to do that for you, or just memset it to some obvious value.
Using some more complex and creative instrumentation, I might have made a breakthrough here. I set a mousetrap looking for places where we delete a gdlm_lock while there's still something queued on its lkb's lkb_astqueue. It took a long time to recreate and there were a lot of false positives, but finally I got a failure. Right before the failure, I got what seemed to be a positive. The "failing" call trace looked like this: Call Trace: [<ffffffff8869f695>] :lock_dlm:gdlm_delete_lp+0x118/0x136 [<ffffffff88624410>] :gfs2:glock_free+0x20/0x3f [<ffffffff886247f2>] :gfs2:gfs2_glock_put+0xe5/0x111 [<ffffffff80022e20>] clear_inode+0xd2/0x123 [<ffffffff80039d99>] generic_drop_inode+0x146/0x15a [<ffffffff886283d7>] :gfs2:gfs2_process_unlinked_inode+0x1be/0x1c7 [<ffffffff88623e76>] :gfs2:gfs2_glock_schedule_for_reclaim+0x5d/0x9a [<ffffffff8863902e>] :gfs2:gfs2_inplace_reserve_i+0x663/0x6f4 [<ffffffff8012b77b>] selinux_capable+0x15/0x2a [<ffffffff8862ff6e>] :gfs2:gfs2_page_mkwrite+0x13e/0x2dd [<ffffffff8000aadf>] get_page_from_freelist+0x378/0x43a [<ffffffff8862fe90>] :gfs2:gfs2_page_mkwrite+0x60/0x2dd [<ffffffff80008b59>] __handle_mm_fault+0x3f6/0xfaa [<ffffffff886251bb>] :gfs2:run_queue+0xad/0x18a [<ffffffff88623e76>] :gfs2:gfs2_glock_schedule_for_reclaim+0x5d/0x9a [<ffffffff80066b55>] do_page_fault+0x4cb/0x874 [<ffffffff8001cd14>] vma_link+0xd0/0xfd [<ffffffff8000e129>] do_mmap_pgoff+0x615/0x780 [<ffffffff8005dde9>] error_exit+0x0/0x84 [<ffffffff8004d7eb>] run_workqueue+0x99/0xf6 [<ffffffff8004a021>] worker_thread+0x0/0x122 [<ffffffff800a0ac1>] keventd_create_kthread+0x0/0xc4 [<ffffffff8004a111>] worker_thread+0xf0/0x122 [<ffffffff8008cf9f>] default_wake_function+0x0/0xe [<ffffffff800a0ac1>] keventd_create_kthread+0x0/0xc4 lock_dlm: fatal assertion failed "lp->gdlm_magic == GDLM_MAGIC" lock_dlm: gdlm_lock hosed 7e1df400 1,736c lp=ffff81007519c1c0 lkb=ffff81005d52de78 Using objdump, I isolated the eip to this statement in function gfs2_process_unlinked_inode: error = gfs2_glock_nq_init(ip->i_gl, LM_ST_EXCLUSIVE, LM_FLAG_TRY, &gh); So here's my latest theory: 1. Function gfs2_process_unlinked_inode queues up a TRY lock request for an inode's i_iopen glock. 2. Next, it queues up a TRY lock for the i_gl glock. 3. The second glock fails with -EAGAIN (TRYFAILED), which causes the gfs2_glock_nq_init to dequeue the holder for the i_iopen glock immediately. 4. The holder is freed while there's still a bast queued on dlm's queue for the lkb. 5. The memory is reused by some process, thus overwriting the memory with trash (and it has the right to do so). 6. The dlm takes the bast off its queue and tries to call the bast function, but now the memory for the valid lkb points to the freed memory, and thus the bast address is hosed, so it chokes. I don't know all the ins and outs of dlm's flags and how this combination is supposed to work. According to Chrissie's dlm user's guide: If the lock manager cannot grant your lock request, it normally adds your request to the end of the wait queue, along with all other blocked lock requests on the lock resource. However, you can specify that the lock manager not queue your request if it cannot be granted immediately by specifying the LKF_NOQUEUE flag as an argument to the lock routine. If your lock request cannot be granted immediately, the dlm_lock routine returns the status 0 and the AST is queued with the status EAGAIN in the status field of the lock status block. And according to the comments in one of the header files: * DLM_LKF_NOQUEUEBAST * * Send blocking AST's before returning -EAGAIN to the caller. It is only * used along with the NOQUEUE flag. Blocking AST's are not sent for failed * NOQUEUE requests otherwise. Based on these findings I've made a patch that changes the glock call in function gfs2_process_unlinked_inode from LM_FLAG_TRY to LM_FLAG_TRY_1CB. So far I haven't hit any failures. I need to do more investigation because I'm not sure if this is the "right thing to do." I need to understand the nuances of the dlm and TRY locks better before I'll feel comfortable with this. Tomorrow I may just make this change to the uninstrumented version of gfs2 and see if the problem goes away, but in the mean time I need to speak with Steve Whitehouse and Dave Teigland about how this is "supposed" to work. Adding Dave to the cc list.
I think there is probably some confusion in comment #7. The trace shows generic_drop_inode calling clear_inode. There is no suggestion that I can see which might point to there being a call to delete_inode. It probably doesn't make a lot of difference whether there was or not though, since we'd land up in clear inode anyway. From the traces I've seen to far, the problem has been in the ast not the bast so I think that #4 in your "So here's my latest theory:" is wrong unless there is some other evidence. If we have a problem with using memory which has been freed, then we need to ensure that we don't free that memory until after whatever is using it has finished. Although adding the _1CB might be harmless in this case, it won't actually do anything other than change the timing. I've not seen any evidence that my theory of comment #6 (2nd pg) is wrong so far, so I still think that is the best bet.
Regarding comment #8: The problem is, in fact, detected on a bast, not an ast. The evidence you're looking for is this: The corrupt gdlm_lock is first noticed by instrumentation I added to function gdlm_bast and not by any other function's instrumentation. And gdlm_bast is called only when dlm calls from the loop where it processes things on its lkb_astqueue, which includes both ast and bast locks. A few days ago, I took the suggestion given in comment #6 and memsetted the entire gdlm_lock to 0x66 just before freeing it. There were absolutely no references to the gdlm_lock by either lock_dlm or gfs2 after it was freed, or it would have segfaulted. The code I'm running has numerous calls to a "check_integrity" function that verifies the gdlm_lock is not corrupt any time something significant happens to it, and none of these triggers. The very first report of the corruption comes from function gdlm_bast and it reports that, when it was called by dlm, the structure is now filled with 0x66. That can only mean the dlm has called it for an lkb that's still left on its lkb_astqueue for which the gdlm_lock has been freed. Before this memset was added, the check_integrity function reported the gdlm_lock's lock numbers, and they normally started with "5," meaning that before it was freed, it used to correspond to a i_open glock. The most suspicious thing I've found in the code is the fact that dlm protects its lkb_astqueue with a spinlock called ast_queue_lock, and yet other functions mess with the queue without that spinlock held, but with proc->asts_spin held instead. Not with the queue directly, because it's a global variable declared in ast.c, but with some asts lkb_astqueue. This may be nothing. But for example, dlm function dlm_user_add_ast and others mess with some lkb's lkb_astqueue and hopefully the lkbs in question are not queued on the lkb_astqueue when they do. So I stand by my comments in comment #7.
Then it is very much starting to sound like you've simply run into the same dlm bug as we had in RHEL6 (now fixed) with reordering and which has yet to be back ported to RHEL5. Perhaps we should have been a bit more proactive in pushing for that backport :( The two different locks are due to different locking schemes according to whether the (b)ast is being delivered to userland or to the kernel. I think the locking is ok on the kernel side, but I've not been though the userland side of things in any detail.
The cast/bast ordering problems were done in rhel6 bug 568102. And Steve is correct, the proc->asts_spin locking is only used for userland locks, and wouldn't be a factor for gfs locks.
Created attachment 423982 [details] Latest patch from 14 June 2010 I figured out what the problem was, at least the one I was stuck on. The problem was related to the fact that the new function, gfs2_process_unlinked_inode, was using a TRY lock to try to hold the i_open and i_gl glocks for an unlinked dinode to be reclaimed. In the failing case, the try lock was succeeding for the i_open glock but failing for the i_gl glock. The error code path ended up calling function gfs2_glock_put twice for the i_open glock: Once for the normal put and once for the error-exit put. This is still the case (and can be seen) in today's function gfs2_inode_lookup, but since it doesn't use try locks, the glock is a lot less likely to error out. We may still want to fix it. So here is my latest patch, which includes a better error path for gfs2_process_unlinked_inode (but gfs2_inode_lookup still has the issue. We may want to change it, and I'd like to discuss that with Steve Whitehouse.) This patch doesn't include some of my other code changes, for example, the one to protect the i_open glock from being reinitialized by a failed glock_nq_init. It has some of my changes though. I'd like Steve and possibly others to review the patch to see which changes they deem unwanted/unnecessary. I've run this version a few times without error, and it should have failed if the problem was still there. I did, however, get other errors, which are known problems. Another problem is that one of my nodes reported hardware errors: looks like I may have a bad hard disk to complicate matters.
Yes, I think we should fix gfs2_inode_lookup as well. Anyway, that sounds good and I can't see any issues with the patch. If it is working ok, then lets go with that and get this one posted.
*** Bug 582359 has been marked as a duplicate of this bug. ***
Created attachment 429927 [details] Latest patch from 06 Jul 2010 This patch fixes three bugs having to do with the reclaiming of unlinked dinodes. The three were discovered during RHEL6 testing and reported as these bugzilla numbers: bug #570182 - GFS2: glock held by ended process bug #583737 - GFS2: stuck in inode wait, no glocks stuck bug #604244 - GFS2: kernel NULL pointer dereference from dlm_astd This patch is a combined version of three patches that already appear upstream in the -nmw git repository and in the RHEL6 kernel. Due to the serious nature of the problems, the patches were back-ported to RHEL5 for inclusion in the RHEL5.6 kernel under the bugzilla bug #595397. The first bug #570182 was caused by GFS2 not following its documented lock ordering rules while reclaiming unlinked dinodes. The fix was to split the gfs2_inode_lookup function into a separate function just for reclaim: gfs2_process_unlinked_inode. The new function follows the lock ordering rules properly by doing two things: First, by using a "try" lock during the lookup. Second, by returning the dinode block number to a higher-level function that can deal with the inode outside the locks that were causing deadlock, (rather than to try to do the locking while the other locks were held). The second bug #583737 was caused by a problem with the patch for the first bug #570182. This is the combined patch. Basically, the timing window was nearly closed in the first patch, but there was still a case where it could hang. The third bug #604244 was due to a problem with the second patch. Basically, if the "try" lock failed due to lock contention, the glock was improperly released twice, which caused dlm_astd to reference a pointer to freed storage. Now we set the freed pointer to NULL so that it's not unlocked a second time. This patch was tested and found to be correct on the roth-0{1,2,3} cluster using the brawl test. I posted it to rhkernel-list for inclusion into the 5.6 kernel.
Is this patch available for testing in RHEL 5.5 x86_64? If so, how may I obtain it?
I put a compiled x86_64 version for RHEL5.x on my people page if you want to try it. This has not undergone our rigorous file system testing process, so there are absolutely no guarantees: http://people.redhat.com/rpeterso/Experimental/RHEL5.x/gfs2/gfs2.ko
in kernel-2.6.18-206.el5 You can download this test kernel from http://people.redhat.com/jwilson/el5 Detailed testing feedback is always welcomed.
Adding James to the cc list. There's really no reason this bz needs to be private; I think maybe that's the default. James: comment #15 should be of particular interest to you.
*** Bug 645563 has been marked as a duplicate of this bug. ***
An advisory has been issued which should help the problem described in this bug report. This report is therefore being closed with a resolution of ERRATA. For more information on therefore solution and/or where to find the updated files, please follow the link below. You may reopen this bug report if the solution does not work for you. http://rhn.redhat.com/errata/RHSA-2011-0017.html