Hi,
tonight I took the time to look at the tracebacks at SAPO pyMSNt
installation. I looked at three log files from three different
instances. They are running for about a month.
I recorded 4334 tracebacks in total, on 27 different code locations.
The distribution looks something like this:
1 0316ae573861d9470bc3af6c804a01a211be7510
1 08114afa91d9164f7779519be597c8ea0bd76fa5
1 2ad1e3f424234d0b4497c6cf5430a771324c8c74
1 9a69950d859490c91bb3b25aaacd79916a5ba6af
1 dab8fe318e484949da25f1612f59ab6db3e90bd4
1 e6a5956083d65103c50e515637be3c2f9699d990
2 fc01d467e407cbf438442d1c9fd7d9583e079174
4 21ff9cee0b39bb57cf873d9483b5ea1ed471a41e
5 aec4baa994423a94000f03904ee262f7efe5531f
6 28f6f8ceca4105c61b871a12956eb2ea82b5d11c
6 2a494a344262ad37ec7d3a204d4d85f8e9685c26
6 5ab6e230fe57c36695a2fd181d81665231c452a0
6 cf8310a008b86d17a8f0500276a60895b1ccc8e8
7 f04fedbd6cf09dc566a4fba5dbb1a4bbefedb981
8 4aed2e247e6d069382dd489bcb07698e6f61fc2c
8 698c8594e624e728382ab5d0f6a4a6696a7cc0be
10 8a85ca8336b28b1b962118e93d56f625dcb8bddd
17 6aefef6f915d0ac78e63c4490b15ffb77d03194c
22 8f3c05a4a64facb050c5d8a4f3b3e09e4812f0fe
22 96b437afd09613d5107e12500704ccf16d86df4c
73 057b263866549ada7cb6d972f075f8fa4abc2c82
84 33e0c784ca38672cb7d21cc133c7dc646ce35cb1
102 4512a2226871163fd661d65046ee0e4d34fcf32a
124 fc50c48ee1f2d92bcc41cac263aee45e793980fc
419 aca7dd13d5da178277927461e4544664b6e59440
763 e45c0498988401c3b84c5c3c35e089b740aad5d4
2634 d65b790c31b56ef8d73ed8fddee79473036380b8
The hash is a sha1 of filename, line number and function name.
I've created each file with the attached perl script. It assumes a
timestamp at the beginning of each line like the samples below. I did
the histogram with:
grep -c 'Traceback' * | perl -pe 's/(.+):(\d+)/$2\t$1/' | sort -n
#!/usr/bin/perl -w
#
# Extract Tracebacks from pyMSNt logs
#
use strict;
use Digest::SHA1 qw( sha1_hex );
my @tb;
while (my $line = <>) {
if (! @tb && $line =~ m/ Traceback \(most recent call last\):/) {
push @tb, $line;
}
elsif (@tb) {
push @tb, $line;
if ($line =~ m/\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d\.\d+\s+$/) {
check_tb(@tb);
@tb = ();
}
}
}
sub check_tb {
my @tb = @_;
foreach my $line (reverse @tb) {
if ($line =~ m/File "(.+?)", line (\d+), in (\S+)/) {
my ($file, $line, $func) = ($1, $2, $3);
$file =~ s/pymsnt\///i;
my $tb_id = sha1_hex( join(' ', $file, $line, $func));
if (open(my $dest, '>>', $tb_id)) {
print $dest ">>> $file $line $func\n", @tb, "\n\n";
close($dest);
}
last;
}
}
}
The top five tracebacks are:
d65b790c31b56ef8d73ed8fddee79473036380b8
2007-02-18 12:42:32.273434500 [2007-02-18 12:42:32] Traceback (most
recent call last):
2007-02-18 12:42:32.273438500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 1382, in handle_UUX
2007-02-18 12:42:32.273440500 self._fireCallback(id)
2007-02-18 12:42:32.273441500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 752, in _fireCallback
2007-02-18 12:42:32.273443500 self.ids[id][0].callback(args)
2007-02-18 12:42:32.273445500 File "/usr/lib/python2.4/site-
packages/twisted/internet/defer.py", line 229, in callback
2007-02-18 12:42:32.273473500 self._startRunCallbacks(result)
2007-02-18 12:42:32.273474500 File "/usr/lib/python2.4/site-
packages/twisted/internet/defer.py", line 294, in _startRunCallbacks
2007-02-18 12:42:32.273477500 self._runCallbacks()
2007-02-18 12:42:32.273478500 --- <exception caught here> ---
2007-02-18 12:42:32.273480500 File "/usr/lib/python2.4/site-
packages/twisted/internet/defer.py", line 307, in _runCallbacks
2007-02-18 12:42:32.273527500 self.result = callback
(self.result, *args, **kw)
2007-02-18 12:42:32.273529500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 1631, in _cb
2007-02-18 12:42:32.273531500 self.factory.status = r[0]
2007-02-18 12:42:32.273532500 exceptions.IndexError: tuple index
out of range
2007-02-18 12:42:32.273534500
I don't know enough of python for this one. It seems to me that the r
array is empty, so we should probably just test for that?
e45c0498988401c3b84c5c3c35e089b740aad5d4
2007-02-08 13:50:48.981360500 [2007-02-08 13:50:48] Traceback (most
recent call last):
2007-02-08 13:50:48.981364500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 356, in handleEndHeaders
2007-02-08 13:50:48.981367500 handler(info)
2007-02-08 13:50:48.981369500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 369, in login_failed
2007-02-08 13:50:48.981372500 self.deferred.callback
((LOGIN_FAILURE, unquote(info['cbtxt'])))
2007-02-08 13:50:48.981374500 File "/usr/lib/python2.4/site-
packages/twisted/internet/defer.py", line 229, in callback
2007-02-08 13:50:48.981416500 self._startRunCallbacks(result)
2007-02-08 13:50:48.981418500 File "/usr/lib/python2.4/site-
packages/twisted/internet/defer.py", line 294, in _startRunCallbacks
2007-02-08 13:50:48.981431500 self._runCallbacks()
2007-02-08 13:50:48.981433500 --- <exception caught here> ---
2007-02-08 13:50:48.981434500 File "/usr/lib/python2.4/site-
packages/twisted/internet/defer.py", line 307, in _runCallbacks
2007-02-08 13:50:48.981442500 self.result = callback
(self.result, *args, **kw)
2007-02-08 13:50:48.981444500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 1123, in _passportError
2007-02-08 13:50:48.981446500 self.loginFailure("Exception
while authenticating: %s" % failure)
2007-02-08 13:50:48.981448500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msnw.py", line 376, in loginFailure
2007-02-08 13:50:48.981453500 self.factory.msncon.loginFailed
(message)
2007-02-08 13:50:48.981466500 exceptions.AttributeError: 'NoneType'
object has no attribute 'loginFailed'
2007-02-08 13:50:48.981468500
I think we just need a
if not self.factory.msncon: return
at the beginning of function loginFailure at line 375 of src/legacy/
msn/msnw.py
aca7dd13d5da178277927461e4544664b6e59440
2007-02-08 11:06:13.792426500 [2007-02-08 11:06:13] Traceback (most
recent call last):
2007-02-08 11:06:13.792430500 File "/usr/lib/python2.4/site-
packages/twisted/python/log.py", line 53, in callWithLogger
2007-02-08 11:06:13.792432500 return callWithContext({"system":
lp}, func, *args, **kw)
2007-02-08 11:06:13.792434500 File "/usr/lib/python2.4/site-
packages/twisted/python/log.py", line 38, in callWithContext
2007-02-08 11:06:13.792436500 return context.call({ILogContext:
newCtx}, func, *args, **kw)
2007-02-08 11:06:13.792438500 File "/usr/lib/python2.4/site-
packages/twisted/python/context.py", line 59, in callWithContext
2007-02-08 11:06:13.792477500 return self.currentContext
().callWithContext(ctx, func, *args, **kw)
2007-02-08 11:06:13.792479500 File "/usr/lib/python2.4/site-
packages/twisted/python/context.py", line 37, in callWithContext
2007-02-08 11:06:13.792481500 return func(*args,**kw)
2007-02-08 11:06:13.792483500 --- <exception caught here> ---
2007-02-08 11:06:13.792484500 File "/usr/lib/python2.4/site-
packages/twisted/internet/epollreactor.py", line 199, in _doReadOrWrite
2007-02-08 11:06:13.792496500 why = selectable.doRead()
2007-02-08 11:06:13.792498500 File "/usr/lib/python2.4/site-
packages/twisted/internet/tcp.py", line 348, in doRead
2007-02-08 11:06:13.792500500 return self.protocol.dataReceived
(data)
2007-02-08 11:06:13.792501500 File "/usr/lib/python2.4/site-
packages/twisted/protocols/basic.py", line 240, in dataReceived
2007-02-08 11:06:13.792514500 return self.rawDataReceived(data)
2007-02-08 11:06:13.792515500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 848, in rawDataReceived
2007-02-08 11:06:13.792517500 self.gotMessage(m)
2007-02-08 11:06:13.792519500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msnw.py", line 744, in gotMessage
2007-02-08 11:06:13.792520500 self.msncon.gotMessage
(self.remoteUser, text)
2007-02-08 11:06:13.792526500 File "/servers/msn-transport/PyMSNt/
src/legacy/glue.py", line 430, in gotMessage
2007-02-08 11:06:13.792528500 self.session.sendMessage
(self.jabberID, fro=source, body=text, mtype="chat")
2007-02-08 11:06:13.792530500 exceptions.AttributeError: 'NoneType'
object has no attribute 'sendMessage'
2007-02-08 11:06:13.792532500
Same as the previous one, I think a
if not self.session: return
in the gotMessage at line 425 of src/legacy/glue.py should be enough.
fc50c48ee1f2d92bcc41cac263aee45e793980fc
2007-02-08 16:26:27.767256500 [2007-02-08 16:26:27] Traceback (most
recent call last):
2007-02-08 16:26:27.767259500 File "/usr/lib/python2.4/site-
packages/twisted/python/log.py", line 53, in callWithLogger
2007-02-08 16:26:27.767261500 return callWithContext({"system":
lp}, func, *args, **kw)
2007-02-08 16:26:27.767263500 File "/usr/lib/python2.4/site-
packages/twisted/python/log.py", line 38, in callWithContext
2007-02-08 16:26:27.767265500 return context.call({ILogContext:
newCtx}, func, *args, **kw)
2007-02-08 16:26:27.767267500 File "/usr/lib/python2.4/site-
packages/twisted/python/context.py", line 59, in callWithContext
2007-02-08 16:26:27.767298500 return self.currentContext
().callWithContext(ctx, func, *args, **kw)
2007-02-08 16:26:27.767300500 File "/usr/lib/python2.4/site-
packages/twisted/python/context.py", line 37, in callWithContext
2007-02-08 16:26:27.767302500 return func(*args,**kw)
2007-02-08 16:26:27.767304500 --- <exception caught here> ---
2007-02-08 16:26:27.767305500 File "/usr/lib/python2.4/site-
packages/twisted/internet/epollreactor.py", line 199, in _doReadOrWrite
2007-02-08 16:26:27.767313500 why = selectable.doRead()
2007-02-08 16:26:27.767315500 File "/usr/lib/python2.4/site-
packages/twisted/internet/tcp.py", line 348, in doRead
2007-02-08 16:26:27.767317500 return self.protocol.dataReceived
(data)
2007-02-08 16:26:27.767318500 File "/usr/lib/python2.4/site-
packages/twisted/protocols/basic.py", line 232, in dataReceived
2007-02-08 16:26:27.767336500 why = self.lineReceived(line)
2007-02-08 16:26:27.767337500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 819, in lineReceived
2007-02-08 16:26:27.767339500 try: handler(params.split(' '))
2007-02-08 16:26:27.767341500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 2220, in handle_ANS
2007-02-08 16:26:27.767342500 self.loggedIn()
2007-02-08 16:26:27.767348500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msnw.py", line 704, in loggedIn
2007-02-08 16:26:27.767350500 self._ready()
2007-02-08 16:26:27.767351500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msnw.py", line 671, in _ready
2007-02-08 16:26:27.767353500 self.userJoined(user)
2007-02-08 16:26:27.767354500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msnw.py", line 717, in userJoined
2007-02-08 16:26:27.767356500 self._switchToMulti(remoteUser)
2007-02-08 16:26:27.767361500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msnw.py", line 679, in _switchToMulti
2007-02-08 16:26:27.767363500 del
self.msncon.switchboardSessions[self.remoteUser]
2007-02-08 16:26:27.767365500 exceptions.KeyError:
'[EMAIL PROTECTED]'
2007-02-08 16:26:27.767366500
Don't know enough python on this one. It seems to me that the key is
no longer present in the map. Maybe we could just test for existance?
4512a2226871163fd661d65046ee0e4d34fcf32a
2007-02-27 00:58:02.785235500 [2007-02-27 00:58:02] Traceback (most
recent call last):
2007-02-27 00:58:02.785238500 File "/usr/lib/python2.4/site-
packages/twisted/python/log.py", line 53, in callWithLogger
2007-02-27 00:58:02.785240500 return callWithContext({"system":
lp}, func, *args, **kw)
2007-02-27 00:58:02.785242500 File "/usr/lib/python2.4/site-
packages/twisted/python/log.py", line 38, in callWithContext
2007-02-27 00:58:02.785244500 return context.call({ILogContext:
newCtx}, func, *args, **kw)
2007-02-27 00:58:02.785246500 File "/usr/lib/python2.4/site-
packages/twisted/python/context.py", line 59, in callWithContext
2007-02-27 00:58:02.785270500 return self.currentContext
().callWithContext(ctx, func, *args, **kw)
2007-02-27 00:58:02.785272500 File "/usr/lib/python2.4/site-
packages/twisted/python/context.py", line 37, in callWithContext
2007-02-27 00:58:02.785274500 return func(*args,**kw)
2007-02-27 00:58:02.785275500 --- <exception caught here> ---
2007-02-27 00:58:02.785277500 File "/usr/lib/python2.4/site-
packages/twisted/internet/epollreactor.py", line 199, in _doReadOrWrite
2007-02-27 00:58:02.785284500 why = selectable.doRead()
2007-02-27 00:58:02.785286500 File "/usr/lib/python2.4/site-
packages/twisted/internet/tcp.py", line 348, in doRead
2007-02-27 00:58:02.785288500 return self.protocol.dataReceived
(data)
2007-02-27 00:58:02.785290500 File "/usr/lib/python2.4/site-
packages/twisted/protocols/basic.py", line 240, in dataReceived
2007-02-27 00:58:02.785304500 return self.rawDataReceived(data)
2007-02-27 00:58:02.785310500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 849, in rawDataReceived
2007-02-27 00:58:02.785312500 self.setLineMode(extra)
2007-02-27 00:58:02.785313500 File "/usr/lib/python2.4/site-
packages/twisted/protocols/basic.py", line 255, in setLineMode
2007-02-27 00:58:02.785315500 return self.dataReceived(extra)
2007-02-27 00:58:02.785320500 File "/usr/lib/python2.4/site-
packages/twisted/protocols/basic.py", line 232, in dataReceived
2007-02-27 00:58:02.785322500 why = self.lineReceived(line)
2007-02-27 00:58:02.785324500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msn.py", line 805, in lineReceived
2007-02-27 00:58:02.785326500 if len(cmd) != 3: raise
MSNProtocolError, "Invalid Command, %s" % repr(cmd)
2007-02-27 00:58:02.785327500 legacy.msn.msn.MSNProtocolError:
Invalid Command, 'MIME-Version:'
2007-02-27 00:58:02.785353500
I think this one is more complicated... This needs more MSN protocol
knowledge than I have.
33e0c784ca38672cb7d21cc133c7dc646ce35cb1
2007-02-08 10:45:27.816178500 [2007-02-08 10:45:27] Traceback (most
recent call last):
2007-02-08 10:45:27.816182500 File "/servers/msn-transport/PyMSNt/
src/main.py", line 399, in main
2007-02-08 10:45:27.816184500 reactor.run()
2007-02-08 10:45:27.816185500 File "/usr/lib/python2.4/site-
packages/twisted/internet/posixbase.py", line 218, in run
2007-02-08 10:45:27.816188500 self.mainLoop()
2007-02-08 10:45:27.816189500 File "/usr/lib/python2.4/site-
packages/twisted/internet/posixbase.py", line 229, in mainLoop
2007-02-08 10:45:27.816191500 self.doIteration(t)
2007-02-08 10:45:27.816224500 File "/usr/lib/python2.4/site-
packages/twisted/internet/epollreactor.py", line 183, in doPoll
2007-02-08 10:45:27.816226500 log.callWithLogger(selectable,
_drdw, selectable, fd, event, log)
2007-02-08 10:45:27.816228500 --- <exception caught here> ---
2007-02-08 10:45:27.816230500 File "/usr/lib/python2.4/site-
packages/twisted/python/log.py", line 53, in callWithLogger
2007-02-08 10:45:27.816232500 return callWithContext({"system":
lp}, func, *args, **kw)
2007-02-08 10:45:27.816239500 File "/usr/lib/python2.4/site-
packages/twisted/python/log.py", line 38, in callWithContext
2007-02-08 10:45:27.816246500 return context.call({ILogContext:
newCtx}, func, *args, **kw)
2007-02-08 10:45:27.816248500 File "/usr/lib/python2.4/site-
packages/twisted/python/context.py", line 59, in callWithContext
2007-02-08 10:45:27.816250500 return self.currentContext
().callWithContext(ctx, func, *args, **kw)
2007-02-08 10:45:27.816261500 File "/usr/lib/python2.4/site-
packages/twisted/python/context.py", line 37, in callWithContext
2007-02-08 10:45:27.816263500 return func(*args,**kw)
2007-02-08 10:45:27.816264500 File "/usr/lib/python2.4/site-
packages/twisted/internet/epollreactor.py", line 211, in _doReadOrWrite
2007-02-08 10:45:27.816266500 self._disconnectSelectable
(selectable, why, inRead)
2007-02-08 10:45:27.816268500 File "/usr/lib/python2.4/site-
packages/twisted/internet/posixbase.py", line 253, in
_disconnectSelectable
2007-02-08 10:45:27.816304500 selectable.connectionLost(f)
2007-02-08 10:45:27.816305500 File "/usr/lib/python2.4/site-
packages/twisted/internet/tcp.py", line 554, in connectionLost
2007-02-08 10:45:27.816307500 Connection.connectionLost(self,
reason)
2007-02-08 10:45:27.816309500 File "/usr/lib/python2.4/site-
packages/twisted/internet/tcp.py", line 402, in connectionLost
2007-02-08 10:45:27.816310500 protocol.connectionLost(reason)
2007-02-08 10:45:27.816316500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msnw.py", line 658, in connectionLost
2007-02-08 10:45:27.816318500 self.failedMessage(message)
2007-02-08 10:45:27.816320500 File "/servers/msn-transport/PyMSNt/
src/legacy/msn/msnw.py", line 687, in failedMessage
2007-02-08 10:45:27.816321500 self.msncon.failedMessage
(self.remoteUser, text)
2007-02-08 10:45:27.816323500 File "/servers/msn-transport/PyMSNt/
src/legacy/glue.py", line 452, in failedMessage
2007-02-08 10:45:27.816334500
self.session.pytrans.statistics.stats["FailedMessageCount"] += 1
2007-02-08 10:45:27.816336500 exceptions.AttributeError: 'NoneType'
object has no attribute 'pytrans'
2007-02-08 10:45:27.816338500
A simple
if not self.session: return
at the top of failedMessage func at line 451 of src/legacy/glue.py
should be enough.
I'll send the others later on.
Best regards,
--
HIId: Pedro Melo
SMTP: [EMAIL PROTECTED]
XMPP: [EMAIL PROTECTED]
_______________________________________________
py-transports mailing list
[email protected]
http://lists.modevia.com/cgi-bin/mailman/listinfo/py-transports
