<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv=Content-Type content="text/html; charset=iso-8859-1">
<meta name=Generator content="Microsoft Word 12 (filtered medium)">
<style>
<!--
/* Font Definitions */
@font-face
{font-family:Wingdings;
panose-1:5 0 0 0 0 0 0 0 0 0;}
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:blue;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:purple;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri","sans-serif";
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;}
@page Section1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.Section1
{page:Section1;}
-->
</style>
<!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang=EN-US link=blue vlink=purple>
<div class=Section1>
<p class=MsoNormal>I have been operating a busy twisted TCP server for quite
some time (1 year+).<o:p></o:p></p>
<p class=MsoNormal>Yesterday, it strangely crashed under peak load for that day
(it has been under more load in the past). <o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal># grep segfault /var/log/messages<o:p></o:p></p>
<p class=MsoNormal>Mar 20 19:12:15 serv2 kernel: [17687209.144548]
twistd[10701]: segfault at 8 rip 41eccf rsp 7fff33675270 error 6<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>I cannot understand the reason of the crash, except that it’s
some very rare race condition.<o:p></o:p></p>
<p class=MsoNormal>While the code is quite cumbersome, here are some general
details:<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>8 min before the crash, the server started giving repeated error
on clients disconnect, that I have never seen before in the last year.<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>It first produced this twice:<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>2009/03/20 19:04 -0700 [ClientProtocol,318930,70.132.227.150]
Unhandled Error<o:p></o:p></p>
<p class=MsoNormal> Traceback (most recent call last):<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/application/app.py",
line 113, in runReactorWithLogging<o:p></o:p></p>
<p class=MsoNormal> reactor.run()<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/posixbase.py",
line 220, in run<o:p></o:p></p>
<p class=MsoNormal> self.mainLoop()<o:p></o:p></p>
<p class=MsoNormal> File "/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/posixbase.py",
line 231, in mainLoop<o:p></o:p></p>
<p class=MsoNormal> self.doIteration(t)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/epollreactor.py",
line 181, in doPoll<o:p></o:p></p>
<p class=MsoNormal> log.callWithLogger(selectable, _drdw,
selectable, fd, event)<o:p></o:p></p>
<p class=MsoNormal> --- <exception caught here> ---<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/python/log.py",
line 48, in callWithLogger<o:p></o:p></p>
<p class=MsoNormal> return callWithContext({"system": lp},
func, *args, **kw)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/python/log.py",
line 33, in callWithContext<o:p></o:p></p>
<p class=MsoNormal> return context.call({ILogContext: newCtx}, func,
*args, **kw)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/python/context.py",
line 59, in callWithContext<o:p></o:p></p>
<p class=MsoNormal> return
self.currentContext().callWithContext(ctx, func, *args, **kw)<o:p></o:p></p>
<p class=MsoNormal> File "/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/python/context.py",
line 37, in callWithContext<o:p></o:p></p>
<p class=MsoNormal> return func(*args,**kw)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/epollreactor.py",
line 212, in _doReadOrWrite<o:p></o:p></p>
<p class=MsoNormal> self._disconnectSelectable(selectable, why,
inRead)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/posixbase.py",
line 252, in _disconnectSelectable<o:p></o:p></p>
<p class=MsoNormal> selectable.readConnectionLost(f)<o:p></o:p></p>
<p class=MsoNormal> File "/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/tcp.py",
line 405, in readConnectionLost<o:p></o:p></p>
<p class=MsoNormal> self.connectionLost(reason)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/tcp.py",
line 416, in connectionLost<o:p></o:p></p>
<p class=MsoNormal> protocol.connectionLost(reason)<o:p></o:p></p>
<p class=MsoNormal> File "/nail/live/im/myserv/protocols.py",
line 170, in connectionLost<o:p></o:p></p>
<p class=MsoNormal> self.session.logout()<o:p></o:p></p>
<p class=MsoNormal> File "/nail/live/im/myserv/service.py",
line 1199, in logout<o:p></o:p></p>
<p class=MsoNormal> if self.nick in session.sellers:<o:p></o:p></p>
<p class=MsoNormal> exceptions.AttributeError: Deferred instance has no
attribute 'sellers'<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>and then a different error in the same line with the same
call stack, that was repeated about 1000 times for different logging out clients:<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>2009/03/20 19:04 -0700 [ClientProtocol,326158,99.245.246.187]
Unhandled Error<o:p></o:p></p>
<p class=MsoNormal> Traceback (most recent call last):<o:p></o:p></p>
<p class=MsoNormal> File "/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/application/app.py",
line 113, in runReactorWithLogging<o:p></o:p></p>
<p class=MsoNormal> reactor.run()<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/posixbase.py",
line 220, in run<o:p></o:p></p>
<p class=MsoNormal> self.mainLoop()<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/posixbase.py",
line 231, in mainLoop<o:p></o:p></p>
<p class=MsoNormal> self.doIteration(t)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/epollreactor.py",
line 181, in doPoll<o:p></o:p></p>
<p class=MsoNormal> log.callWithLogger(selectable, _drdw,
selectable, fd, event)<o:p></o:p></p>
<p class=MsoNormal> --- <exception caught here> ---<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/python/log.py",
line 48, in callWithLogger<o:p></o:p></p>
<p class=MsoNormal> return callWithContext({"system": lp},
func, *args, **kw)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/python/log.py",
line 33, in callWithContext<o:p></o:p></p>
<p class=MsoNormal> return context.call({ILogContext: newCtx}, func,
*args, **kw)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/python/context.py",
line 59, in callWithContext<o:p></o:p></p>
<p class=MsoNormal> return self.currentContext().callWithContext(ctx,
func, *args, **kw)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/python/context.py",
line 37, in callWithContext<o:p></o:p></p>
<p class=MsoNormal> return func(*args,**kw)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/epollreactor.py",
line 212, in _doReadOrWrite<o:p></o:p></p>
<p class=MsoNormal> self._disconnectSelectable(selectable, why,
inRead)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/posixbase.py",
line 252, in _disconnectSelectable<o:p></o:p></p>
<p class=MsoNormal> selectable.readConnectionLost(f)<o:p></o:p></p>
<p class=MsoNormal> File
"/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/tcp.py",
line 405, in readConnectionLost<o:p></o:p></p>
<p class=MsoNormal> self.connectionLost(reason)<o:p></o:p></p>
<p class=MsoNormal> File "/nail/encap/Twisted-2.5.0/lib/python2.4/site-packages/twisted/internet/tcp.py",
line 416, in connectionLost<o:p></o:p></p>
<p class=MsoNormal> protocol.connectionLost(reason)<o:p></o:p></p>
<p class=MsoNormal> File "/nail/live/im/myserv/protocols.py",
line 170, in connectionLost<o:p></o:p></p>
<p class=MsoNormal> self.session.logout()<o:p></o:p></p>
<p class=MsoNormal> File "/nail/live/im/myserv/service.py",
line 1199, in logout<o:p></o:p></p>
<p class=MsoNormal> if self.nick in session.sellers:<o:p></o:p></p>
<p class=MsoNormal> exceptions.AttributeError: WLResultSet instance has
no attribute 'sellers'<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>This last error repeated about 1000 times for different
clients, after which the segfault occurred.<o:p></o:p></p>
<p class=MsoNormal>The problem is, that “session” is an instance of
a Session class that is defined in the code, it is NEITHER a Deferred NOR an
instance of WLResultSet class- these are completely different classes, and
there’s no possible way in the code for variable session to become an
instance of Deferred.<o:p></o:p></p>
<p class=MsoNormal>The code is approximately like this:<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>def logout(self):<o:p></o:p></p>
<p class=MsoNormal style='text-indent:.5in'>self.on_logout(self.do_logout) <o:p></o:p></p>
<p class=MsoNormal style='text-indent:.5in'>for session in
self.service.client_sessions: <span style='font-family:Wingdings'>ß</span> self.service.client_sessions
is a dictionary of custom Session class instances<o:p></o:p></p>
<p class=MsoNormal style='margin-left:.5in;text-indent:.5in'>if self.nick in
session.sellers: <span style='font-family:Wingdings'>ß</span> error here, it
claims that session is a Deferred or sometimes an instance of a completely
unrelated class<o:p></o:p></p>
<p class=MsoNormal> #Some
statements <o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>The function self.on_logout sometimes (rarely) dispatches a
deferred (it has maybeDeferred in it), such that its argument self.on_logout is
called when that deferred returns (otherwise it’s called synchronously).<o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>My question is, is it possible to muck up deferred in such a
way, that after dispatching a deferred chain inside self.on_logout(self.do_logout)
, the remaining statements would be executed in some unexpected local scope,
such that I would see these weird errors where my for loop iterator would
suddenly go over Deferred instances, instead of the dictionary of Session
instances that I define in the code ?? <o:p></o:p></p>
<p class=MsoNormal><o:p> </o:p></p>
<p class=MsoNormal>Also, why did these errors lead to segfault of the whole
twisted process after 8 minutes?<o:p></o:p></p>
<p class=MsoNormal> <o:p></o:p></p>
</div>
</body>
</html>