bugGNUstep - Bugs: bug #39092, NSLock deadlock even in trivial...

 
 

You are not allowed to post comments on this tracker with your current authentification level.

bug #39092: NSLock deadlock even in trivial GSWeb application

Submitted by:  Graham Lee <leeg>
Submitted on:  Tue 28 May 2013 06:19:08 AM UTC  
 
Category: gswebSeverity: 3 - Normal
Item Group: BugStatus: Fixed
Privacy: PublicAssigned to: Sebastian Reitenbach <buzzdee>
Open/Closed: Closed

(Jump to the original submission Jump to the original submission)

Fri 31 May 2013 08:32:07 AM UTC, comment #8:

applied the patch in svn 36684.

thanks.

Sebastian Reitenbach <buzzdee>
Project MemberIn charge of this item.
Thu 30 May 2013 09:59:51 AM UTC, comment #7:

Yes it does; that's been my workaround since discovering this problem.

Graham Lee <leeg>
Thu 30 May 2013 09:34:15 AM UTC, comment #6:

Problem was obviously introduced by me.
Attached patch changes the lock into a recursive lock, but I don't know if this is the best idea, waiting on feedback from David.

Let me know if that works for you so far.

Sebastian

(file #28209)

Sebastian Reitenbach <buzzdee>
Project MemberIn charge of this item.
Wed 29 May 2013 08:58:29 PM UTC, comment #5:

I's on my list of things to look at in the next couple of days, just didn't got around it today.

Sebastian Reitenbach <buzzdee>
Project MemberIn charge of this item.
Wed 29 May 2013 08:31:37 PM UTC, comment #4:

this lock was a recursive lock until fairly recently,
hopefully sebastian chimes in.

https://github.com/gnustep/gnustep-gsweb/commit/3c4e7d11d74ab218118fe0995363c1a93db52b1a#GSWeb/GSWApplication.m

matt rice <ratmice>
Project Member
Wed 29 May 2013 06:49:47 PM UTC, comment #3:

Forgive me talking to myself, but I've made some progress on this. I wrote my own <NSLocking> class that both checks the pthread_mutex errors and stores the call stack at the point where it gets locked. If it gets deadlocked, it prints both the callstack where it was originally locked and the one where it deadlocked. So we now have this:

2013-05-29 19:40:59.228 EmptyApp[14545:3a07] Error locking GLLock<0x7f8372012120>: 11
2013-05-29 19:40:59.234 EmptyApp[14545:3a07] Was already locked here: (

  1. WebObjects 0x000000010b818c54 -[GLLock lockBeforeDate:] + 148

1 WebObjects 0x000000010b849f58 loggedLockBeforeDateFromFunctionInFileInLine + 88
2 WebObjects 0x000000010b819dc1 -[WOApplication lockRequestHandling] + 113
3 WebObjects 0x000000010b86387d -[GSWActionRequestHandler handleRequest:] + 141
4 WebObjects 0x000000010b81d2f0 -[WOApplication dispatchRequest:] + 224
5 WebObjects 0x000000010b876fe2 -[GSWWorkerThread runOnce] + 386
6 Foundation 0x00007fff8bc4ccd2 _NSThread__main_ + 1345
7 libsystem_c.dylib 0x00007fff965fd7a2 _pthread_start + 327
8 libsystem_c.dylib 0x00007fff965ea1e1 thread_start + 13
)
2013-05-29 19:40:59.250 EmptyApp[14545:3a07] And I want it here: (

  1. WebObjects 0x000000010b818ac4 -[GLLock lock] + 100

1 WebObjects 0x000000010b81c6fa -[WOApplication pageWithName:inContext:] + 90
2 WebObjects 0x000000010b8607d0 -[GSWAction pageWithName:] + 176
3 WebObjects 0x000000010b860efa -[WODirectAction defaultAction] + 26
4 WebObjects 0x000000010b860dd3 -[WODirectAction performActionNamed:] + 67
5 WebObjects 0x000000010b8641e9 -[GSWActionRequestHandler _handleRequest:] + 1257
6 WebObjects 0x000000010b86388d -[GSWActionRequestHandler handleRequest:] + 157
7 WebObjects 0x000000010b81d2f0 -[WOApplication dispatchRequest:] + 224
8 WebObjects 0x000000010b876fe2 -[GSWWorkerThread runOnce] + 386
9 Foundation 0x00007fff8bc4ccd2 _NSThread__main_ + 1345
10 libsystem_c.dylib 0x00007fff965fd7a2 _pthread_start + 327
11 libsystem_c.dylib 0x00007fff965ea1e1 thread_start + 13
)

Graham Lee <leeg>
Wed 29 May 2013 08:44:03 AM UTC, comment #2:

I have a little more information about the other deadlock condition I've seen; it doesn't help me understand it but hopefully it'll give you some clues :-). I added a DirectAction class to the empty app, set the default handler to the direct action handler, and now the app deadlocks when a browser connects to the direct connect URL:

#0 0x00007fff8bc09c07 in -[NSLock lock] ()
#1 0x000000010002996a in -[WOApplication pageWithName:inContext:] (self=0x101e14bd0, _cmd=<value temporarily unavailable, due to optimizations>, aName=0x0, aContext=0x101882b10) at GSWApplication.m:1826
#2 0x000000010006da40 in -[GSWAction pageWithName:] (self=<value temporarily unavailable, due to optimizations>, _cmd=<value temporarily unavailable, due to optimizations>, pageName=<value temporarily unavailable, due to optimizations>) at GSWAction.m:160
#3 0x000000010006e16a in -[WODirectAction defaultAction] (self=0x101e14db0, _cmd=<value temporarily unavailable, due to optimizations>) at GSWDirectAction.m:98
#4 0x000000010006e043 in -[WODirectAction performActionNamed:] (self=0x101e1d660, _cmd=0x1000a1236, actionName=0x1000f2b80) at GSWDirectAction.m:72
#5 0x0000000100071459 in -[GSWActionRequestHandler _handleRequest:] (self=0x101866a20, _cmd=0x1000a145c, aRequest=0x101e1c910) at GSWActionRequestHandler.m:363
#6 0x0000000100070afd in -[GSWActionRequestHandler handleRequest:] (self=0x101866a20, _cmd=<value temporarily unavailable, due to optimizations>, aRequest=0x101e1c910) at GSWActionRequestHandler.m:140
#7 0x000000010002a560 in -[WOApplication dispatchRequest:] (self=0x101e14bd0, _cmd=<value temporarily unavailable, due to optimizations>, aRequest=0x101e1c910) at GSWApplication.m:2210
#8 0x0000000100084252 in -[GSWWorkerThread runOnce] (self=0x101e18140, _cmd=<value temporarily unavailable, due to optimizations>) at GSWWorkerThread.m:183
#9 0x00007fff8bc4ccd2 in _NSThread__main_ ()
#10 0x00007fff965fd7a2 in _pthread_start ()
#11 0x00007fff965ea1e1 in thread_start ()
2013-05-29 07:43:15.807 EmptyApp[798:3707] *** -[NSLock lock]: deadlock (<NSLock: 0x101e14db0> '(null)')

As I understand it, NSLock will deadlock when a thread tries to acquire a lock that thread already has. I couldn't see in gdb where that was happening. I tried to supply my own lock class that checked for the same-thread condition in -lock and -tryLock, and while it still deadlocked my condition never triggered.

Switching the NSLock for an NSRecursiveLock does remove the deadlock, but I don't know why it's occurring :-(

Graham Lee <leeg>
Tue 28 May 2013 06:46:03 AM UTC, comment #1:

In this case, -[WOSessionTimeOutManager handleTimer:] locks the lock (via SYNCHRONIZED(GSWApp)), and then -[WOApplication _discountTerminatedSession] also tries to acquire the same lock.

I'm afraid I'm not familiar enough with the code to know what a good fix would be. I'd prefer to remove the locking code from _discountTerminatedSession, if it's truly an internal method and should always be called from within a locked context (it could test -tryLock if it needs that). Obviously a recursive lock also solves the problem but I'd be loathe to introduce that big a change.

Graham Lee <leeg>
Tue 28 May 2013 06:19:08 AM UTC, original submission:

I'm using gsweb from svn r36269, though with the patches in #39087 and #39088 applied so that it will build on my platform (apple-apple-apple, Mac OS X 10.8.3).

Even a blank app with empty Application and Session classes will deadlock. I've found that a reliable way to trigger the deadlock is on session timeout, so I've set that to five seconds in the attached project. Steps to reproduce:

1> build and launch app
2> navigate to direct connect URL in browser
3> wait for session timeout

The backtrace in this particular situation is reproduced below, though in other situations the deadlock is triggered elsewhere. In one example, the thread handling a direct action request deadlocks in -[WOApplication pageWithName:inContext:].

midgard:EmptyApp leeg$ gdb EmptyApp.gswa/Contents/MacOS/EmptyApp
GNU gdb 6.3.50-20050815 (Apple version gdb-1824) (Wed Feb 6 22:51:23 UTC 2013)
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "x86_64-apple-darwin"...Reading symbols for shared libraries .......... done

(gdb) break _NSLockError
Breakpoint 1 at 0x72b020c478740f
(gdb) run
Starting program: /Users/leeg/Documents/GNUstep/EmptyApp/EmptyApp.gswa/Contents/MacOS/EmptyApp
Reading symbols for shared libraries +++++++++............................................................................................................................................ done
Reading symbols for shared libraries . done
2013-05-28 07:07:53.402 EmptyApp[1090:f0b] host address '::1'
2013-05-28 07:07:53.404 EmptyApp[1090:f0b] cPortn '9001'
2013-05-28 07:07:53.405 EmptyApp[1090:f0b] Thread XX Waiting for connections on localhost:9001.
2013-05-28 07:07:53.407 EmptyApp[1090:f0b] Application running. To use direct connect enter
http://localhost:9001/WebObjects/EmptyApp.woa/0/
in your web Browser.
Please make sure that this port is only reachable in a trusted network.
2013-05-28 07:08:10.833 EmptyApp[1090:f0b] *** -[NSLock lock]: deadlock (<NSLock: 0x101c0d320> '(null)')

Breakpoint 1, 0x00007fff8931f40f in _NSLockError ()
(gdb) bt
#0 0x00007fff8931f40f in _NSLockError ()
#1 0x00007fff89242c86 in -[NSLock lock] ()
#2 0x0000000100027b85 in -[WOApplication _discountTerminatedSession] (self=0x101c0d170, _cmd=0x100098ae7) at GSWApplication.m:1314
#3 0x000000010004d646 in -[WOSession terminate] (self=0x101832c70, _cmd=<value temporarily unavailable, due to optimizations>) at GSWSession.m:523
#4 0x000000010001ee0c in -[WOSessionTimeOutManager handleTimer:] (self=0x101829640, _cmd=<value temporarily unavailable, due to optimizations>, aTimer=0xa1a1a1a1) at GSWSessionTimeOutManager.m:186
#5 0x00007fff89263af3 in __NSFireTimer ()
#6 0x00007fff88e41804 in _CFRUNLOOP_IS_CALLING_OUT_TO_A_TIMER_CALLBACK_FUNCTION_ ()
#7 0x00007fff88e4131d in __CFRunLoopDoTimer ()
#8 0x00007fff88e26ad9 in __CFRunLoopRun ()
#9 0x00007fff88e260e2 in CFRunLoopRunSpecific ()
#10 0x00007fff8928af5e in -[NSRunLoop(NSRunLoop) runMode:beforeDate:] ()
#11 0x0000000100028e38 in -[WOApplication run] (self=0x101c0d170, _cmd=<value temporarily unavailable, due to optimizations>) at GSWApplication.m:1977
#12 0x00000001000251c6 in GSWApplicationMainReal (applicationClassName=<value temporarily unavailable, due to optimizations>, argc=<value temporarily unavailable, due to optimizations>, argv=<value temporarily unavailable, due to optimizations>) at GSWApplication.m:208
#13 0x0000000100000e8a in main (argc=42057728, argv=0x7fff00000001) at EmptyApp_main.m:11

Graham Lee <leeg>

 

Attached Files
file #28209:  fix-NSLocking-gsweb.diff added by buzzdee (2kB - text/x-patch)
file #28195:  gsweb-session-timeout-deadlock.patch added by leeg (2kB - application/octet-stream - The deadlock can be avoided by locking the calling context in both places the affected method is called.)
file #28194:  EmptyApp.tar.bz2 added by leeg (1kB - application/x-bzip2)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -unavailable- added by buzzdee (Posted a comment)
  • -unavailable- added by ratmice (Posted a comment)
  • -unavailable- added by leeg (Submitted the item)
  •  

    Do you think this task is very important?
    If so, you can click here to add your encouragement to it.
    This task has 0 encouragements so far.

    Only logged-in users can vote.

     

    Please enter the title of George Orwell's famous dystopian book (it's a date):

     

     

    Follow 7 latest changes.

    Date Changed By Updated Field Previous Value => Replaced By
    Fri 20 Dec 2013 09:48:23 PM UTCbuzzdeeOpen/ClosedOpen=>Closed
    Fri 31 May 2013 08:32:07 AM UTCbuzzdeeStatusNeed Info=>Fixed
    Thu 30 May 2013 09:34:15 AM UTCbuzzdeeAttached File-=>Added fix-NSLocking-gsweb.diff, #28209
      StatusNone=>Need Info
      Assigned toNone=>buzzdee
    Tue 28 May 2013 07:05:18 AM UTCleegAttached File-=>Added gsweb-session-timeout-deadlock.patch, #28195
    Tue 28 May 2013 06:19:08 AM UTCleegAttached File-=>Added EmptyApp.tar.bz2, #28194

    Back to the top


    Powered by Savane 3.1-cleanup