[bug #39092] NSLock deadlock even in trivial GSWeb application

[Graham Lee]

URL:
<http://savannah.gnu.org/bugs/?39092>

Summary: NSLock deadlock even in trivial GSWeb application
Project: GNUstep
Submitted by: leeg
Submitted on: Tue 28 May 2013 06:19:08 AM GMT
Category: gsweb
Severity: 3 - Normal
Item Group: Bug
Status: None
Privacy: Public
Assigned to: None
Open/Closed: Open
Discussion Lock: Any

_______________________________________________________

Details:

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




_______________________________________________________

File Attachments:


-------------------------------------------------------
Date: Tue 28 May 2013 06:19:08 AM GMT Name: EmptyApp.tar.bz2 Size: 1kB By:
leeg

<http://savannah.gnu.org/bugs/download.php?file_id=28194>

_______________________________________________________

Reply to this item at:

<http://savannah.gnu.org/bugs/?39092>

_______________________________________________
Message sent via/by Savannah
http://savannah.gnu.org/

[Graham Lee]

Follow-up Comment #1, bug #39092 (project gnustep):

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]

Additional Item Attachment, bug #39092 (project gnustep):

File name: gsweb-session-timeout-deadlock.patch Size:1 KB

[Graham Lee]

Follow-up Comment #2, bug #39092 (project gnustep):

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]

Follow-up Comment #3, bug #39092 (project gnustep):

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: (
0 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: (
0 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
)

[matt rice]

Follow-up Comment #4, bug #39092 (project gnustep):

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

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

[Sebastian Reitenbach]

Follow-up Comment #5, bug #39092 (project gnustep):

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]

Update of bug #39092 (project gnustep):

Status: None => Need Info
Assigned to: None => buzzdee

_______________________________________________________

Follow-up 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)
_______________________________________________________

Additional Item Attachment:

File name: fix-NSLocking-gsweb.diff Size:2 KB

[Graham Lee]

Follow-up Comment #7, bug #39092 (project gnustep):

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

[Sebastian Reitenbach]

Update of bug #39092 (project gnustep):

Status: Need Info => Fixed

_______________________________________________________

Follow-up Comment #8:

applied the patch in svn 36684.

thanks.

[Sebastian Reitenbach]

Update of bug #39092 (project gnustep):

Open/Closed: Open => Closed