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

Group
 
 

bug #39092: NSLock deadlock even in trivial GSWeb application

Submitter:  Graham Lee <leeg>
Submitted:  Tue 28 May 2013 06:19:08 AM UTC
   
 
Category:  gsweb Severity:  3 - Normal
Item Group:  Bug Status:  Fixed
Privacy:  Public Assigned to:  buzzdee
Open/Closed:  Closed
* Mandatory Fields

Add a New Comment Rich Markup
   

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>
Group Member
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>
Group Member
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>
Group Member
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>
Group 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>

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #28209:  fix-NSLocking-gsweb.diff added by buzzdee (2KiB - text/x-patch)
file #28195:  gsweb-session-timeout-deadlock.patch added by leeg (2KiB - 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 (1KiB - application/x-bzip2)

 

Depends on the following items: None found

Items that depend on this one: None found

 

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

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only logged-in users can vote.

     

    Follow 7 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2013-12-20 buzzdee Open/ClosedOpen Closed
    2013-05-31 buzzdee StatusNeed Info Fixed
    2013-05-30 buzzdee Attached File- Added fix-NSLocking-gsweb.diff, #28209
        StatusNone Need Info
        Assigned toNone buzzdee
    2013-05-28 leeg Attached File- Added gsweb-session-timeout-deadlock.patch, #28195
    2013-05-28 leeg Attached File- Added EmptyApp.tar.bz2, #28194

    Back to the top

    Powered by Savane 3.13-4448.
    Corresponding source code