More info, with some debug data...
Today it happened again, DH got stuck and the log shows the lines we
have been seeing:
2008-06-06 06:41:57,022 - denyhosts : INFO new denied hosts:
['189.19.193.190']
2008-06-06 07:18:07,646 - denyhosts : INFO new denied hosts:
['66.77.218.75']
2008-06-06 07:38:57,823 - denyfileutil: INFO purging entries older
than: Wed Jun 4 07:38:57 2008
2008-06-06 07:38:57,921 - loginattempt: INFO purging_hosts:
['83.13.44.90','213.23.74.130', '203.200.23.8', '200.24.193.42',
'82.63.214.81', '195.161.32.6']
2008-06-06 07:38:58,147 - denyfileutil: INFO num entries purged: 6
2008-06-06 07:42:07,428 - sync : ERROR (110, 'Connection timed
out')
Traceback (most recent call last):
File "/usr/lib64/python2.5/site-packages/DenyHosts/sync.py", line
100, in __send_new_hosts
self.__server.add_hosts(hosts)
File "/usr/lib64/python2.5/xmlrpclib.py", line 1147, in __call__
return self.__send(self.__name, args)
File "/usr/lib64/python2.5/xmlrpclib.py", line 1437, in __request
verbose=self.__verbose
File "/usr/lib64/python2.5/xmlrpclib.py", line 1183, in request
self.send_content(h, request_body)
File "/usr/lib64/python2.5/xmlrpclib.py", line 1297, in send_content
connection.endheaders()
File "/usr/lib64/python2.5/httplib.py", line 856, in endheaders
self._send_output()
File "/usr/lib64/python2.5/httplib.py", line 728, in _send_output
self.send(msg)
File "/usr/lib64/python2.5/httplib.py", line 695, in send
self.connect()
File "/usr/lib64/python2.5/httplib.py", line 679, in connect
raise socket.error, msg
error: (110, 'Connection timed out')
2008-06-06 07:42:07,429 - sync : INFO sent 2 new hosts
Then nothing.
I logged in in the afternoon and first thing I did was run gdb on the
process, this is where it was stuck (sorry don't know how to get python
lines and files from gdb, anyone knows a python debugger that can attach
to a process? pydb doesn't seem to be able to do that):
# gdb /usr/bin/python 29275
GNU gdb 6.7.1
... lots of libraries loaded
(gdb) where
#0 0x00002af7aff67fb5 in recv () from /lib/libpthread.so.0
#1 0x00002af7b13a0b71 in ?? ()
from /usr/lib64/python2.5/lib-dynload/_socket.so
#2 0x00002af7b13a0cfb in ?? ()
from /usr/lib64/python2.5/lib-dynload/_socket.so
#3 0x00002af7afcb434a in PyEval_EvalFrameEx ()
from /usr/lib/libpython2.5.so.1.0
#4 0x00002af7afcb551f in PyEval_EvalCodeEx ()
from /usr/lib/libpython2.5.so.1.0
#5 0x00002af7afcb3ef1 in PyEval_EvalFrameEx ()
from /usr/lib/libpython2.5.so.1.0
#6 0x00002af7afcb424d in PyEval_EvalFrameEx ()
from /usr/lib/libpython2.5.so.1.0
#7 0x00002af7afcb551f in PyEval_EvalCodeEx ()
from /usr/lib/libpython2.5.so.1.0
...
(gdb) quit
Then I toggled logging to debug mode (pkill -USR1 denyhosts) and the
process woke up:
2008-06-06 19:23:52,138 - denyhosts : INFO setting debug level to:
DEBUG
2008-06-06 19:23:52,138 - sync : ERROR (4, 'Interrupted system
call')
Traceback (most recent call last):
File "/usr/lib64/python2.5/site-packages/DenyHosts/sync.py", line
117, in receive_new_hosts
self.__prefs.get("SYNC_DOWNLOAD_RESILIENCY"))
File "/usr/lib64/python2.5/xmlrpclib.py", line 1147, in __call__
return self.__send(self.__name, args)
File "/usr/lib64/python2.5/xmlrpclib.py", line 1437, in __request
verbose=self.__verbose
File "/usr/lib64/python2.5/xmlrpclib.py", line 1185, in request
errcode, errmsg, headers = h.getreply()
File "/usr/lib64/python2.5/httplib.py", line 1195, in getreply
response = self._conn.getresponse()
File "/usr/lib64/python2.5/httplib.py", line 924, in getresponse
response.begin()
File "/usr/lib64/python2.5/httplib.py", line 414, in begin
self.msg = HTTPMessage(self.fp, 0)
File "/usr/lib64/python2.5/mimetools.py", line 16, in __init__
rfc822.Message.__init__(self, fp, seekable)
File "/usr/lib64/python2.5/rfc822.py", line 104, in __init__
self.readheaders()
File "/usr/lib64/python2.5/httplib.py", line 270, in readheaders
line = self.fp.readline()
File "/usr/lib64/python2.5/socket.py", line 331, in readline
data = recv(1)
error: (4, 'Interrupted system call')
2008-06-06 19:23:52,213 - denyhosts : DEBUG /var/log/messages has
additional data
2008-06-06 19:23:52,291 - denyhosts : DEBUG user: - host:
200.168.86.209 - success: 0 - invalid: 1
2008-06-06 19:23:52,292 - denyhosts : DEBUG user: root - host:
200.168.86.209 - success: 0 - invalid: 1
... repeats 28 times (time stamp)
... and so on, looks like normal operation
2008-06-06 19:23:52,503 - denyhosts : DEBUG user: root - host:
mail2.ek-pooltje.nl - success: 0 - invalid: 1
2008-06-06 19:23:52,503 - denyhosts : DEBUG user: - host:
66.120.114.50 - success: 0 - invalid: 1
2008-06-06 19:23:52,504 - denyhosts : DEBUG user: - host:
66.120.114.50 - success: 0 - invalid: 1
2008-06-06 19:23:52,504 - denyhosts : DEBUG user: rberber - host:
189.146.59.117 - success: 1 - invalid: 0
2008-06-06 19:23:52,505 - loginattempt: INFO resetting count for:
189.146.59.117
2008-06-06 19:23:52,522 - denyhosts : DEBUG new hosts:
['200.168.86.209', 'mail2.ek-pooltje.nl']
2008-06-06 19:23:52,522 - report : DEBUG get_host:
200.168.86.209 (200-168-86-209.websolute.com.br)
2008-06-06 19:23:52,522 - report : DEBUG get_host:
mail2.ek-pooltje.nl
2008-06-06 19:23:52,543 - denyhosts : INFO new denied hosts:
['200.168.86.209', 'mail2.ek-pooltje.nl']
2008-06-06 19:23:52,543 - denyhosts : DEBUG no new suspicious logins
2008-06-06 19:24:02,545 - denyhosts : DEBUG /var/log/messages has
additional data
2008-06-06 19:24:02,597 - denyhosts : DEBUG new hosts: []
2008-06-06 19:24:02,597 - denyhosts : DEBUG no new denied hosts
2008-06-06 19:24:02,597 - denyhosts : DEBUG no new suspicious logins
That's as far as I have gone. Anyone with good ideas on how to continue
debugging this?
--
René Berber
-------------------------------------------------------------------------
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://sourceforge.net/services/buy/index.php
_______________________________________________
Denyhosts-user mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/denyhosts-user
