r199 - in /debtorrent/trunk: ./ DebTorrent/ DebTorrent/BT1/

camrdale-guest at users.alioth.debian.org camrdale-guest at users.alioth.debian.org
Mon Aug 6 00:50:01 UTC 2007


Author: camrdale-guest
Date: Mon Aug  6 00:50:01 2007
New Revision: 199

URL: http://svn.debian.org/wsvn/debtorrent/?sc=1&rev=199
Log:
Add lots more log messages.

Modified:
    debtorrent/trunk/DebTorrent/BT1/AptListener.py
    debtorrent/trunk/DebTorrent/BT1/Connecter.py
    debtorrent/trunk/DebTorrent/BT1/Downloader.py
    debtorrent/trunk/DebTorrent/BT1/Encrypter.py
    debtorrent/trunk/DebTorrent/BT1/HTTPDownloader.py
    debtorrent/trunk/DebTorrent/BT1/NatCheck.py
    debtorrent/trunk/DebTorrent/BT1/PiecePicker.py
    debtorrent/trunk/DebTorrent/BT1/Rerequester.py
    debtorrent/trunk/DebTorrent/BT1/Storage.py
    debtorrent/trunk/DebTorrent/BT1/StorageWrapper.py
    debtorrent/trunk/DebTorrent/BT1/StreamCheck.py
    debtorrent/trunk/DebTorrent/BT1/Uploader.py
    debtorrent/trunk/DebTorrent/BT1/btformats.py
    debtorrent/trunk/DebTorrent/BT1/makemetafile.py
    debtorrent/trunk/DebTorrent/BT1/track.py
    debtorrent/trunk/DebTorrent/HTTPCache.py
    debtorrent/trunk/DebTorrent/HTTPHandler.py
    debtorrent/trunk/DebTorrent/RawServer.py
    debtorrent/trunk/DebTorrent/ServerPortHandler.py
    debtorrent/trunk/DebTorrent/SocketHandler.py
    debtorrent/trunk/DebTorrent/__init__.py
    debtorrent/trunk/DebTorrent/bencode.py
    debtorrent/trunk/DebTorrent/download_bt1.py
    debtorrent/trunk/DebTorrent/launchmanycore.py
    debtorrent/trunk/TODO

Modified: debtorrent/trunk/DebTorrent/BT1/AptListener.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/AptListener.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/AptListener.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/AptListener.py Mon Aug  6 00:50:01 2007
@@ -180,6 +180,7 @@
             # Check for a closed connection
             if c.closed:
                 closed_conns.append(c)
+                logger.warning('connection closed while request queued for file '+str(v[1]))
                 continue
                 
             # Remove the downloaded pieces from the list of needed ones
@@ -343,6 +344,7 @@
             if path[-1] in ('Packages', 'Packages.gz', 'Packages.bz2'):
                 if r[0] == 304:
                     # Oops, we do need the cached file after all to start the torrent
+                    logger.info('retrieving the cached Packages file to start the torrent')
                     r2 = self.Cache.cache_get(path)
                     self.got_Packages(path, r2[3])
                 else:
@@ -351,6 +353,7 @@
             return r
         
         except IOError, e:
+            logger.exception('While retrieving cache file: ' + '/'.join(path))
             try:
                 (msg, status) = e
             except:
@@ -382,6 +385,7 @@
         for connection in connections:
             # Check to make sure the requester is still waiting
             if connection.closed:
+                logger.warning('Retrieved the file, but the requester is gone: '+'/'.join(path))
                 continue
             
             connection.answer(r)
@@ -403,6 +407,7 @@
         d, f = self.handler.find_file(path[0], path[1:])
         
         if d is None:
+            logger.warning('Unable to find the file in any torrents: '+'/'.join(path))
             return (404, 'Not Found', {'Server': VERSION, 'Content-Type': 'text/plain', 'Pragma': 'no-cache'}, alas)
 
         # Check if the file has already been downloaded
@@ -420,6 +425,7 @@
 
         # Check if the torrent is running/not paused
         if d.doneflag.isSet():
+            logger.error('The needed torrent is not running')
             return (404, 'Not Found', {'Server': VERSION, 'Content-Type': 'text/plain', 'Pragma': 'no-cache'}, alas)
         
         if not d.unpauseflag.isSet():
@@ -493,7 +499,7 @@
             assert data[:8] == "Package:"
             h = data.split('\n')
         except:
-            logger.warning('Packages file could not be converted to a torrent')
+            logger.warning('Packages file is not in the correct format')
             return 
 
         sub_pieces = getsubpieces('_'.join(path))
@@ -548,6 +554,7 @@
         setkey('announce-list')
         a['metainfo'] = response
         
+        logger.info('Adding torrent '+name+': '+b2a_hex(infohash))
         self.handler.add(infohash, a)
         
 
@@ -563,11 +570,13 @@
         """
         
         if not self.allow_get:
+            logger.warning('Unauthorized request for torrent file: '+b2a_hex(hash))
             return (400, 'Not Authorized', {'Server': VERSION, 
                                             'Content-Type': 'text/plain', 
                                             'Pragma': 'no-cache'},
                     'get function is not available with this tracker.')
         if hash not in self.handler.torrent_cache:
+            logger.warning('Request for unknown torrent file: '+b2a_hex(hash))
             return (404, 'Not Found', {'Server': VERSION, 
                                        'Content-Type': 'text/plain', 
                                        'Pragma': 'no-cache'}, 
@@ -575,6 +584,7 @@
         fname = self.handler.torrent_cache[hash]['file'] + '.dtorrent'
         response = self.handler.configdir.getTorrentFile(hash)
         if not response:
+            logger.warning('Could not retrieve torrent file: '+b2a_hex(hash))
             return (404, 'Not Found', {'Server': VERSION, 
                                        'Content-Type': 'text/plain', 
                                        'Pragma': 'no-cache'}, 
@@ -603,7 +613,6 @@
         
         """
         
-#        return (404, 'Not Found', {'Content-Type': 'text/plain', 'Pragma': 'no-cache'}, alas)
         real_ip = connection.get_ip()
         ip = real_ip
         if not is_ipv4(ip):
@@ -614,6 +623,7 @@
 
         if ( (self.allowed_IPs and not self.allowed_IPs.includes(ip))
              or (self.banned_IPs and self.banned_IPs.includes(ip)) ):
+            logger.warning('Unauthorized request from '+ip+' for: '+path)
             return (400, 'Not Authorized', {'Server': VERSION, 'Content-Type': 'text/plain', 'Pragma': 'no-cache'},
                 bencode({'failure reason':
                 'your IP is not allowed on this proxy'}))
@@ -672,6 +682,7 @@
             return self.get_cached(connection, path, headers)
             
         except ValueError, e:
+            logger.exception('Bad request from: '+ip)
             return (400, 'Bad Request', {'Server': VERSION, 'Content-Type': 'text/plain'}, 
                 'you sent me garbage - ' + str(e))
 
@@ -687,7 +698,7 @@
                 self.allowed_IPs.read_fieldlist(f)
                 self.allowed_ip_mtime = os.path.getmtime(f)
             except (IOError, OSError):
-                logger.warning('unable to read allowed_IP list')
+                logger.exception('unable to read allowed_IP list')
                 
         f = self.config['banned_ips']
         if f and self.banned_ip_mtime != os.path.getmtime(f):
@@ -696,7 +707,7 @@
                 self.banned_IPs.read_rangelist(f)
                 self.banned_ip_mtime = os.path.getmtime(f)
             except (IOError, OSError):
-                logger.warning('unable to read banned_IP list')
+                logger.exception('unable to read banned_IP list')
                 
 
 def size_format(s):

Modified: debtorrent/trunk/DebTorrent/BT1/Connecter.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/Connecter.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/Connecter.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/Connecter.py Mon Aug  6 00:50:01 2007
@@ -81,7 +81,7 @@
 class Connection:
     """A connection to an individual peer.
     
-    @type connection: L{DebTorrent.SocketHandler.SingleSocket}
+    @type connection: L{Encrypter.Connection}
     @ivar connection: the connection
     @type connecter: L{Connecter}
     @ivar connecter: the collection of all connections
@@ -89,7 +89,7 @@
     @ivar ccount: the number of the connection
     @type got_anything: C{boolean}
     @ivar got_anything: whether a message has ever been received on the connection
-    @type next_upload: L{DebTorrent.SocketHandler.SingleSocket}
+    @type next_upload: L{Encrypter.Connection}
     @ivar next_upload: the connection that will next be allowed to upload
     @type outqueue: C{list}
     @ivar outqueue: the queue of messages to send on the connection that are
@@ -110,7 +110,7 @@
     def __init__(self, connection, connecter, ccount):
         """Initialize the class.
         
-        @type connection: L{DebTorrent.SocketHandler.SingleSocket}
+        @type connection: L{Encrypter.Connection}
         @param connection: the connection
         @type connecter: L{Connecter}
         @param connecter: the collection of all connections
@@ -208,7 +208,7 @@
         """Send the L{UNCHOKE} message."""
         if self.send_choke_queued:
             self.send_choke_queued = False
-            logger.info(self.get_ip()+': CHOKE SUPPRESSED')
+            logger.info(self.get_ip()+': UNCHOKE SUPPRESSED')
         else:
             self._send_message(UNCHOKE)
             if ( self.partial_message or self.just_unchoked is None
@@ -231,7 +231,7 @@
         
         self._send_message(REQUEST + tobinary(index) + 
             tobinary(begin) + tobinary(length))
-        logger.debug(self.get_ip()+': sent request '+str(index)+', '+str(begin)+', '+str(begin+length))
+        logger.debug(self.get_ip()+': sent request '+str(index)+', '+str(begin)+'-'+str(begin+length))
 
     def send_cancel(self, index, begin, length):
         """Send the L{CANCEL} message.
@@ -249,7 +249,7 @@
         
         self._send_message(CANCEL + tobinary(index) + 
             tobinary(begin) + tobinary(length))
-        logger.debug(self.get_ip()+': sent cancel '+str(index)+', '+str(begin)+', '+str(begin+length))
+        logger.debug(self.get_ip()+': sent cancel '+str(index)+', '+str(begin)+'-'+str(begin+length))
 
     def send_bitfield(self, bitfield):
         """Send the L{BITFIELD} message.
@@ -313,7 +313,7 @@
             self.partial_message = ''.join((
                             tobinary(len(piece) + 9), PIECE,
                             tobinary(index), tobinary(begin), piece.tostring() ))
-            logger.debug(self.get_ip()+': sending chunk '+str(index)+', '+str(begin)+', '+str(begin+len(piece)))
+            logger.debug(self.get_ip()+': sending chunk '+str(index)+', '+str(begin)+'-'+str(begin+len(piece)))
 
         if bytes < len(self.partial_message):
             self.connection.send_message_raw(self.partial_message[:bytes])
@@ -385,6 +385,7 @@
         
         """
         
+        logger.debug(self.get_ip()+': got request '+str(i)+', '+str(p)+'-'+str(p+l))
         self.upload.got_request(i, p, l)
         if self.just_unchoked:
             self.connecter.ratelimiter.ping(clock() - self.just_unchoked)
@@ -474,7 +475,7 @@
     def connection_made(self, connection):
         """Make a new connection.
         
-        @type connection: L{DebTorrent.SocketHandler.SingleSocket}
+        @type connection: L{Encrypter.Connection}
         @param connection: the new connection to make
         @rtype: L{Connection}
         @return: the new connection
@@ -493,13 +494,13 @@
     def connection_lost(self, connection):
         """Process a lost connection.
         
-        @type connection: L{DebTorrent.SocketHandler.SingleSocket}
+        @type connection: L{Encrypter.Connection}
         @param connection: the connection that was lost
         
         """
         
         c = self.connections[connection]
-        logger.debug(c.get_ip()+': connection closed')
+        logger.debug(c.get_ip()+': connection lost')
         del self.connections[connection]
         if c.download:
             c.download.disconnected()
@@ -508,7 +509,7 @@
     def connection_flushed(self, connection):
         """Process a flushed connection.
         
-        @type connection: L{DebTorrent.SocketHandler.SingleSocket}
+        @type connection: L{Encrypter.Connection}
         @param connection: the connection that was flushed
         
         """
@@ -532,7 +533,7 @@
     def got_message(self, connection, message):
         """Process a received message on a connection.
         
-        @type connection: L{DebTorrent.SocketHandler.SingleSocket}
+        @type connection: L{Encrypter.Connection}
         @param connection: the connection that the message was received on
         @type message: C{string}
         @param message: the message that was received
@@ -541,15 +542,15 @@
         
         c = self.connections[connection]
         t = message[0]
-        logger.debug(c.get_ip()+': message received '+str(ord(t)))
+        logger.debug(c.get_ip()+': message received '+str(ord(t))+' ('+str(len(message))+')')
         if t == BITFIELD and c.got_anything:
-            logger.info(c.get_ip()+': misplaced bitfield, closing connection')
+            logger.warning(c.get_ip()+': misplaced bitfield, closing connection')
             connection.close()
             return
         c.got_anything = True
         if (t in [CHOKE, UNCHOKE, INTERESTED, NOT_INTERESTED] and 
                 len(message) != 1):
-            logger.debug(c.get_ip()+': bad message length, closing connection')
+            logger.warning(c.get_ip()+': bad message length, closing connection')
             connection.close()
             return
         if t == CHOKE:
@@ -563,12 +564,12 @@
             c.upload.got_not_interested()
         elif t == HAVE:
             if len(message) != 5:
-                logger.debug(c.get_ip()+': bad message length, closing connection')
+                logger.warning(c.get_ip()+': bad message length, closing connection')
                 connection.close()
                 return
             i = toint(message[1:])
             if i >= self.numpieces:
-                logger.debug(c.get_ip()+': bad piece number, closing connection')
+                logger.warning(c.get_ip()+': bad piece number, closing connection')
                 connection.close()
                 return
             if c.download.got_have(i):
@@ -577,47 +578,47 @@
             try:
                 b = Bitfield(self.numpieces, message[1:])
             except ValueError:
-                logger.debug(c.get_ip()+': bad bitfield, closing connection')
+                logger.warning(c.get_ip()+': bad bitfield, closing connection')
                 connection.close()
                 return
             if c.download.got_have_bitfield(b):
                 c.upload.got_not_interested()
         elif t == REQUEST:
             if len(message) != 13:
-                logger.debug(c.get_ip()+': bad message length, closing connection')
+                logger.warning(c.get_ip()+': bad message length, closing connection')
                 connection.close()
                 return
             i = toint(message[1:5])
             if i >= self.numpieces:
-                logger.debug(c.get_ip()+': bad piece number, closing connection')
+                logger.warning(c.get_ip()+': bad piece number, closing connection')
                 connection.close()
                 return
             c.got_request(i, toint(message[5:9]), 
                 toint(message[9:]))
         elif t == CANCEL:
             if len(message) != 13:
-                logger.debug(c.get_ip()+': bad message length, closing connection')
+                logger.warning(c.get_ip()+': bad message length, closing connection')
                 connection.close()
                 return
             i = toint(message[1:5])
             if i >= self.numpieces:
-                logger.debug(c.get_ip()+': bad piece number, closing connection')
+                logger.warning(c.get_ip()+': bad piece number, closing connection')
                 connection.close()
                 return
             c.upload.got_cancel(i, toint(message[5:9]), 
                 toint(message[9:]))
         elif t == PIECE:
             if len(message) <= 9:
-                logger.debug(c.get_ip()+': bad message length, closing connection')
+                logger.warning(c.get_ip()+': bad message length, closing connection')
                 connection.close()
                 return
             i = toint(message[1:5])
             if i >= self.numpieces:
-                logger.debug(c.get_ip()+': bad piece number, closing connection')
+                logger.warning(c.get_ip()+': bad piece number, closing connection')
                 connection.close()
                 return
             if c.download.got_piece(i, toint(message[5:9]), message[9:]):
                 self.got_piece(i)
         else:
-            logger.debug(c.get_ip()+': unknown message type, closing connection')
+            logger.warning(c.get_ip()+': unknown message type, closing connection')
             connection.close()

Modified: debtorrent/trunk/DebTorrent/BT1/Downloader.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/Downloader.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/Downloader.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/Downloader.py Mon Aug  6 00:50:01 2007
@@ -6,6 +6,8 @@
 
 """Download pieces from remote peers.
 
+ at type logger: C{logging.Logger}
+ at var logger: the logger to send all log messages to for this module
 @type EXPIRE_TIME: C{int}
 @var EXPIRE_TIME: number of seconds after which disconnected seeds are expired
 
@@ -15,11 +17,14 @@
 from DebTorrent.bitfield import Bitfield
 from random import shuffle
 from DebTorrent.clock import clock
+import logging
 try:
     True
 except:
     True = 1
     False = 0
+
+logger = logging.getLogger('DebTorrent.BT1.Downloader')
 
 EXPIRE_TIME = 60 * 60
 
@@ -255,7 +260,7 @@
             self._letgo()
 
     def got_unchoke(self):
-        """Update the status and request any needed pieces."""
+        """Update the choked status and request any needed pieces."""
         if self.choked:
             self.choked = False
             if self.interested:
@@ -317,6 +322,8 @@
         try:
             self.active_requests.remove((index, begin, length))
         except ValueError:
+            logger.warning('received an unrequested piece from '+self.ip+': '+
+                           str(index)+', '+str(begin)+'-'+str(begin+len(piece)))
             self.downloader.discarded += length
             return False
         if self.downloader.endgamemode:
@@ -870,6 +877,7 @@
             id = download.connection.get_readable_id()
             self.kicked[ip] = id
             self.perip[ip].peerid = id
+            logger.warning('kicking peer '+ip+' ('+id+')')
             self.kickfunc(download.connection)
         
     def try_ban(self, ip):
@@ -881,6 +889,7 @@
         """
         
         if self._check_kicks_ok():
+            logger.warning('banning peer IP '+ip)
             self.banfunc(ip)
             self.banned[ip] = self.perip[ip].peerid
             if self.kicked.has_key(ip):
@@ -998,6 +1007,7 @@
     def start_endgame(self):
         """Switch to endgame mode."""
         assert not self.endgamemode
+        logger.info('Switching to endgame mode')
         self.endgamemode = True
         assert not self.all_requests
         for d in self.downloads:

Modified: debtorrent/trunk/DebTorrent/BT1/Encrypter.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/Encrypter.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/Encrypter.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/Encrypter.py Mon Aug  6 00:50:01 2007
@@ -40,6 +40,8 @@
     bool = lambda x: not not x
 
 logger = logging.getLogger('DebTorrent.BT1.Encrypter')
+
+DEBUG = False
 
 MAX_INCOMPLETE = 8
 
@@ -251,10 +253,12 @@
         if self.locally_initiated:
             incompletecounter.increment()
             if encrypted:
+                logger.info('Initiating an encrypted connection to '+self.readable_id)
                 self.encrypted = True
                 self.encrypter = Crypto(True)
                 self.write(self.encrypter.pubkey+self.encrypter.padding())
             else:
+                logger.info('Initiating an unencrypted connection to '+self.readable_id)
                 self.encrypted = False
                 self.write(chr(len(protocol_name)) + protocol_name + 
                     option_pattern + self.Encoder.download_id )
@@ -262,17 +266,20 @@
         elif ext_handshake:
             self.Encoder.connecter.external_connection_made += 1
             if encrypted:   # passed an already running encrypter
+                logger.info('Received an external encrypted connection from '+self.readable_id)
                 self.encrypter = encrypted
                 self.encrypted = True
                 self._start_crypto()
                 self.next_len, self.next_func = 14, self.read_crypto_block3c
             else:
+                logger.info('Received an external unencrypted connection from '+self.readable_id)
                 self.encrypted = False
                 self.options = options
                 self.write(chr(len(protocol_name)) + protocol_name + 
                            option_pattern + self.Encoder.download_id + self.Encoder.my_id)
                 self.next_len, self.next_func = 20, self.read_peer_id
         else:
+            logger.info('Received an unknown connection from '+self.readable_id)
             self.encrypted = None       # don't know yet
             self.next_len, self.next_func = 1+len(protocol_name), self.read_header
         self.Encoder.raw_server.add_task(self._auto_close, 30)
@@ -398,11 +405,14 @@
         
         if self._read_header(s):
             if self.encrypted or self.Encoder.config['crypto_stealth']:
+                logger.info('Dropped the connection as it was unencrypted: '+self.readable_id)
                 return None
             return 8, self.read_options
         if self.locally_initiated and not self.encrypted:
+            logger.info('Got a bad protocol name: '+self.readable_id)
             return None
         elif not self.Encoder.config['crypto_allowed']:
+            logger.info('Dropped the connection as it was encrypted: '+self.readable_id)
             return None
         if not self.encrypted:
             self.encrypted = True
@@ -511,6 +521,7 @@
         """
         
         if s != self.encrypter.block3b:
+            logger.info('Dropped the encrypted connection due to a bad block3b: '+self.readable_id)
             return None
         self.Encoder.connecter.external_connection_made += 1
         self._start_crypto()
@@ -528,15 +539,19 @@
         """
         
         if s[:8] != ('\x00'*8):             # check VC
+            logger.info('Dropped the encrypted connection due to a bad VC: '+self.readable_id)
             return None
         self.cryptmode = toint(s[8:12]) % 4
         if self.cryptmode == 0:
+            logger.info('Dropped the encrypted connection due to a bad crypt mode: '+self.readable_id)
             return None                     # no encryption selected
         if ( self.cryptmode == 1            # only header encryption
              and self.Encoder.config['crypto_only'] ):
+            logger.info('Dropped the header-only encrypted connection: '+self.readable_id)
             return None
         padlen = (ord(s[12])<<8)+ord(s[13])
         if padlen > 512:
+            logger.info('Dropped the encrypted connection due to bad padding: '+self.readable_id)
             return None
         return padlen+2, self.read_crypto_pad3
 
@@ -554,6 +569,7 @@
         s = s[-2:]
         ialen = (ord(s[0])<<8)+ord(s[1])
         if ialen > 65535:
+            logger.info('Dropped the encrypted connection due to very long padding: '+self.readable_id)
             return None
         if self.cryptmode == 1:
             cryptmode = '\x00\x00\x00\x01'    # header only encryption
@@ -639,11 +655,14 @@
         self.cryptmode = toint(s[:4]) % 4
         if self.cryptmode == 1:             # only header encryption
             if self.Encoder.config['crypto_only']:
+                logger.info('Dropped the header-only encrypted connection: '+self.readable_id)
                 return None
         elif self.cryptmode != 2:
+            logger.info('Dropped the encrypted connection due to an unknown crypt mode: '+self.readable_id)
             return None                     # unknown encryption
         padlen = (ord(s[4])<<8)+ord(s[5])
         if padlen > 512:
+            logger.info('Dropped the encrypted connection due to bad padding: '+self.readable_id)
             return None
         if padlen:
             return padlen, self.read_crypto_pad4
@@ -676,6 +695,7 @@
             self._log_start()
         if self.cryptmode == 1:     # only handshake encryption
             if not self.buffer:  # oops; check for exceptions to this
+                logger.info('Dropped the encrypted connection due to a lack of buffer: '+self.readable_id)
                 return None
             self._end_crypto()
         self.write(chr(len(protocol_name)) + protocol_name + 
@@ -726,6 +746,7 @@
         
         if ( s != self.Encoder.download_id
              or not self.Encoder.check_ip(ip=self.get_ip()) ):
+            logger.warning('IPs or torrent info hashes do not match: '+self.readable_id)
             return None
         if not self.locally_initiated:
             if not self.encrypted:
@@ -746,6 +767,7 @@
         """
         
         if not self.encrypted and self.Encoder.config['crypto_only']:
+            logger.info('Dropped the unencrypted connection: '+self.readable_id)
             return None     # allows older trackers to ping,
                             # but won't proceed w/ connections
         if not self.id:
@@ -753,14 +775,17 @@
             self.readable_id = make_readable(s)
         else:
             if s != self.id:
+                logger.info('Peer ID does not match: '+self.readable_id)
                 return None
         self.complete = self.Encoder.got_id(self)
         if not self.complete:
+            logger.warning('Connection disallowed for security: '+self.readable_id)
             return None
         if self.locally_initiated:
             self.write(self.Encoder.my_id)
             incompletecounter.decrement()
         self._switch_to_read2()
+        logger.info('Handshake complete: '+self.readable_id)
         c = self.Encoder.connecter.connection_made(self)
         self.keepalive = c.send_keepalive
         return 4, self.read_len
@@ -778,6 +803,7 @@
         
         l = toint(s)
         if l > self.Encoder.max_len:
+            logger.warning('Dropped the connection due to bad length message: '+self.readable_id)
             return None
         return l, self.read_message
 
@@ -811,6 +837,7 @@
     def _auto_close(self):
         """Close the connection if the handshake is not yet complete."""
         if not self.complete:
+            logger.warning('Connection dropped due to handshake taking too long: '+self.readable_id)
             self.close()
 
     def close(self):
@@ -904,6 +931,7 @@
             try:
                 x = self.next_func(m)
             except:
+                logger.exception('Dropped connection due to exception: '+self.readable_id)
                 self.next_len, self.next_func = 1, self.read_dead
                 raise
             if x is None:
@@ -975,6 +1003,7 @@
             try:
                 x = self.next_func(m)
             except:
+                logger.exception('Dropped connection due to exception: '+self.readable_id)
                 self.next_len, self.next_func = 1, self.read_dead
                 raise
             if x is None:
@@ -1114,6 +1143,7 @@
         self.schedulefunc(self.send_keepalives, self.keepalive_delay)
         if self.paused:
             return
+        logger.debug('Sending keepalive messages to all connected peers')
         for c in self.connections.values():
             c.keepalive()
 
@@ -1162,23 +1192,33 @@
        
         """
         
-        if ( self.paused
-             or len(self.connections) >= self.max_connections
-             or id == self.my_id
-             or not self.check_ip(ip=dns[0]) ):
+        if self.paused:
+            logger.info('Not connecting due to being paused')
+            return True
+        if len(self.connections) >= self.max_connections:
+            logger.info('Not connecting due to too many connections: '+str(len(self.connections))+' >= '+str(self.max_connections))
+            return True
+        if id == self.my_id:
+            logger.info('Not connecting due to it being my ID: '+id)
+            return True
+        if not self.check_ip(ip=dns[0]):
+            logger.info('Not connecting due to the IP being banned: '+dns[0])
             return True
         if self.config['crypto_only']:
             if encrypted is None or encrypted:  # fails on encrypted = 0
                 encrypted = True
             else:
+                logger.info('Not connecting due to not being encrypted: '+dns[0])
                 return True
         for v in self.connections.values():
             if v is None:
                 continue
             if id and v.id == id:
+                logger.info('Not connecting due to a matching peer ID: '+id)
                 return True
             ip = v.get_ip(True)
             if self.config['security'] and ip != 'unknown' and ip == dns[0]:
+                logger.info('Not connecting due to a matching IP: '+ip)
                 return True
         try:
             logger.debug('initiating connection to: '+str(dns)+', '+str(id)+', '+str(encrypted))
@@ -1245,16 +1285,20 @@
         
         if connection.id == self.my_id:
             self.connecter.external_connection_made -= 1
+            logger.debug('New connection matches our peer ID')
             return False
         ip = connection.get_ip(True)
         for v in self.connections.values():
             if connection is not v:
                 if connection.id == v.id:
                     if ip == v.get_ip(True):
+                        logger.debug('Closing an old connection to the same peer')
                         v.close()
                     else:
+                        logger.debug('New peer ID is already connected')
                         return False
                 if self.config['security'] and ip != 'unknown' and ip == v.get_ip(True):
+                    logger.debug('Closing an old connection to the same IP')
                     v.close()
         return True
 
@@ -1269,6 +1313,11 @@
         """
         
         if self.paused or len(self.connections) >= self.max_connections:
+            if self.paused:
+                logger.info('Not allowing connection due to being paused')
+            else:
+                logger.info('Not allowing connection due to too many connections: '+
+                            str(len(self.connections))+' >= '+str(self.max_connections))
             connection.close()
             return False
         con = Connection(self, connection, None)
@@ -1295,9 +1344,17 @@
         
         """
         
-        if ( self.paused
-             or len(self.connections) >= self.max_connections
-             or not self.check_ip(connection=connection) ):
+        if self.paused:
+            logger.info('Not allowing external connection due to being paused')
+            connection.close()
+            return False
+        if len(self.connections) >= self.max_connections:
+            logger.info('Not allowing external connection due to too many connections: '+
+                        str(len(self.connections))+' >= '+str(self.max_connections))
+            connection.close()
+            return False
+        if not self.check_ip(connection=connection):
+            logger.info('Not allowing external connection due to the IP being banned: '+dns[0])
             connection.close()
             return False
         con = Connection(self, connection, None,
@@ -1322,6 +1379,7 @@
         
         """
         
+        logger.info('Banned: '+ip)
         self.banned[ip] = 1
 
     def pause(self, flag):

Modified: debtorrent/trunk/DebTorrent/BT1/HTTPDownloader.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/HTTPDownloader.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/HTTPDownloader.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/HTTPDownloader.py Mon Aug  6 00:50:01 2007
@@ -214,7 +214,7 @@
             self.endflag = True
             self.resched()
         else:
-            logger.debug('HTTPDownloader: downloading piece '+str(self.index))
+            logger.info('downloading piece '+str(self.index))
             (start, end, length, file) = self.downloader.storage.storage.get_file_range(self.index)
             filename = self.downloader.filenamefunc()
             if len(filename) > 0 and file.startswith(filename):
@@ -244,7 +244,7 @@
         self.error = None
         self.received_data = None
         try:
-            logger.debug('HTTPDownloader: sending request: GET '+self.url+' '+str(self.headers))
+            logger.debug('sending request: GET '+self.url+' '+str(self.headers))
             self.connection.request('GET',self.url, None, self.headers)
             
             # Check for closed persistent connection due to server timeout
@@ -257,7 +257,7 @@
                 self.connection.request('GET',self.url, None, self.headers)
                 r = self.connection.getresponse()
                 
-            logger.debug('HTTPDownloader: got response: '+str(r.status)+', '+r.reason+', '+str(r.getheaders()))
+            logger.debug('got response: '+str(r.status)+', '+r.reason+', '+str(r.getheaders()))
             self.connection_status = r.status
             self.received_data = r.read()
         except Exception, e:
@@ -306,12 +306,13 @@
         """
         
         if self.connection_status not in [200, 206]:
+            logger.warning('bad status from http seed: '+str(self.connection_status))
             self.errorcount += 1
             return False
         self._retry_period = 1
         if len(self.received_data) != self.request_size:
             if self.goodseed:
-                logger.warning('corrupt data from http seed - redownloading')
+                logger.warning('corrupt data from http seed')
                 self.downloader.errorfunc('corrupt data from http seed - redownloading')
             return False
         self.measure.update_rate(len(self.received_data))
@@ -353,6 +354,7 @@
             begin, length = self.requests.pop(0)
             if not self.downloader.storage.piece_came_in(self.index, begin,
                             self.received_data[start:start+length]):
+                logger.warning('piece failed hash check')
                 success = False
                 break
             start += length

Modified: debtorrent/trunk/DebTorrent/BT1/NatCheck.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/NatCheck.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/NatCheck.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/NatCheck.py Mon Aug  6 00:50:01 2007
@@ -15,6 +15,7 @@
 from socket import error as socketerror
 from DebTorrent.BTcrypto import Crypto, CRYPTO_OK
 from DebTorrent.__init__ import protocol_name
+from binascii import b2a_hex
 
 try:
     True
@@ -92,6 +93,8 @@
         self.resultfunc = resultfunc
         self.downloadid = downloadid
         self.peerid = peerid
+        self.readable_id = b2a_hex(peerid)
+        logger.info('Starting a NAT check for '+self.readable_id)
         self.ip = ip
         self.port = port
         self.encrypted = encrypted
@@ -102,16 +105,18 @@
         try:
             self.connection = rawserver.start_connection((ip, port), self)
             if encrypted:
+                logger.info('Initiating an encrypted connection to '+self.readable_id)
                 self._dc = not(CRYPTO_OK and CHECK_PEER_ID_ENCRYPTED)
                 self.encrypter = Crypto(True, disable_crypto = self._dc)
                 self.write(self.encrypter.pubkey+self.encrypter.padding())
             else:
+                logger.info('Initiating an unencrypted connection to '+self.readable_id)
                 self.encrypter = None
                 self.write(chr(len(protocol_name)) + protocol_name +
                     (chr(0) * 8) + downloadid)
-        except socketerror:
-            self.answer(False)
-        except IOError:
+        except (socketerror, IOError):
+            logger.exception('Could not initiate a connection to %s:%d for %s', 
+                             ip, port, self.readable_id)
             self.answer(False)
         self.next_len, self.next_func = 1+len(protocol_name), self.read_header
 
@@ -128,6 +133,7 @@
             self.connection.close()
         except AttributeError:
             pass
+        logger.info('Result was '+str(result)+' for: '+self.readable_id)
         self.resultfunc(result, self.downloadid, self.peerid, self.ip, self.port)
 
     def _read_header(self, s):
@@ -158,9 +164,11 @@
         
         if self._read_header(s):
             if self.encrypted:
+                logger.info('Dropped the connection as it was unencrypted: '+self.readable_id)
                 return None
             return 8, self.read_options
         if not self.encrypted:
+            logger.info('Got a bad protocol name: '+self.readable_id)
             return None
         self._write_buffer(s)
         return self.encrypter.keylength, self.read_crypto_header
@@ -259,9 +267,11 @@
         
         self.cryptmode = toint(s[:4]) % 4
         if self.cryptmode != 2:
+            logger.info('Dropped the encrypted connection due to an unknown crypt mode: '+self.readable_id)
             return None                     # unknown encryption
         padlen = (ord(s[4])<<8)+ord(s[5])
         if padlen > 512:
+            logger.info('Dropped the encrypted connection due to bad padding: '+self.readable_id)
             return None
         if padlen:
             return padlen, self.read_crypto_pad4
@@ -292,6 +302,7 @@
         
         if self.cryptmode == 1:     # only handshake encryption
             if not self.buffer:  # oops; check for exceptions to this
+                logger.info('Dropped the encrypted connection due to a lack of buffer: '+self.readable_id)
                 return None
             self._end_crypto()
         self.write(chr(len(protocol_name)) + protocol_name + 
@@ -340,6 +351,7 @@
         """
         
         if s != self.downloadid:
+            logger.warning('Torrent info hash does not match: '+self.readable_id)
             return None
         return 20, self.read_peer_id
 
@@ -354,6 +366,7 @@
         """
         
         if s != self.peerid:
+            logger.info('Peer ID does not match: '+self.readable_id)
             return None
         self.answer(True)
         return None
@@ -418,6 +431,7 @@
             try:
                 x = self.next_func(m)
             except:
+                logger.exception('Dropped connection due to exception: '+self.readable_id)
                 if not self.closed:
                     self.answer(False)
                 return
@@ -438,6 +452,7 @@
         """
         
         if not self.closed:
+            logger.warning('Connection was dropped externally: '+self.readable_id)
             self.closed = True
             self.resultfunc(False, self.downloadid, self.peerid, self.ip, self.port)
 

Modified: debtorrent/trunk/DebTorrent/BT1/PiecePicker.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/PiecePicker.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/PiecePicker.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/PiecePicker.py Mon Aug  6 00:50:01 2007
@@ -4,15 +4,23 @@
 #
 # $Id$
 
-"""Choose pieces to download."""
+"""Choose pieces to download.
+
+ at type logger: C{logging.Logger}
+ at var logger: the logger to send all log messages to for this module
+
+"""
 
 from random import randrange, shuffle
 from DebTorrent.clock import clock
+import logging
 try:
     True
 except:
     True = 1
     False = 0
+
+logger = logging.getLogger('DebTorrent.BT1.Rerequester')
 
 class PiecePicker:
     """Choose pieces to download.
@@ -326,6 +334,8 @@
         @type complete_first: C{boolean}
         @param complete_first: whether to complete a partially dowloaded piece
             before requsting a new one (optional, defaults to False)
+        @rtype: C{int}
+        @return: the index of the piece to download
         
         """
         
@@ -340,6 +350,7 @@
                     bestnum = self.level_in_interests[i]
         if best is not None:
             if complete_first or (cutoff and len(self.interests) > self.cutoff):
+                logger.info('Next piece to download/request: '+str(best))
                 return best
         if haves.complete():
             r = [ (0, min(bestnum,len(self.interests))) ]
@@ -352,8 +363,10 @@
             for i in xrange(lo,hi):
                 for j in self.interests[i]:
                     if haves[j] and wantfunc(j):
+                        logger.info('Next piece to download/request: '+str(j))
                         return j
         if best is not None:
+            logger.info('Next piece to download/request: '+str(best))
             return best
         return None
 

Modified: debtorrent/trunk/DebTorrent/BT1/Rerequester.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/Rerequester.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/Rerequester.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/Rerequester.py Mon Aug  6 00:50:01 2007
@@ -441,6 +441,7 @@
                 self.rerequest(s, callback)
             self.sched(retry,5)         # retry in 5 seconds
             return
+        logger.info('Sending request: '+s)
         self.lock.reset()
         rq = Thread(target = self._rerequest, args = [s, callback],
                     name = 'Rerequester._rerequest')
@@ -471,15 +472,19 @@
                 for t in range(len(self.trackerlist)):
                     for tr in range(len(self.trackerlist[t])):
                         tracker  = self.trackerlist[t][tr]
+                        logger.debug('Trying tracker: '+tracker)
                         if self.rerequest_single(tracker, s, callback):
                             if not self.last_failed and tr != 0:
                                 del self.trackerlist[t][tr]
                                 self.trackerlist[t] = [tracker] + self.trackerlist[t]
+                            logger.info('Succesful with tracker: '+tracker)
                             return
             else:
                 tracker = self.special
                 self.special = None
+                logger.debug('Trying special tracker: '+tracker)
                 if self.rerequest_single(tracker, s, callback):
+                    logger.info('Succesful with special tracker: '+tracker)
                     return
             # no success from any tracker
             self.externalsched(fail)
@@ -673,7 +678,7 @@
                 x = p[i]
                 peers.append(((x['ip'].strip(), x['port']),
                               x.get('peer id',0), cflags[i]))
-        logger.debug('received from tracker: '+str(peers))
+        logger.info('received from tracker: '+str(peers))
         ps = len(peers) + self.howmany()
         if ps < self.maxpeers:
             if self.doneflag.isSet():

Modified: debtorrent/trunk/DebTorrent/BT1/Storage.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/Storage.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/Storage.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/Storage.py Mon Aug  6 00:50:01 2007
@@ -521,8 +521,8 @@
         for l in self.working_ranges:
             self.ranges.extend(l)
         self.begins = [i[0] for i in self.ranges]
-        logger.debug('file ranges: '+str(self.ranges))
-        logger.debug('file begins: '+str(self.begins))
+        logger.debug('new file ranges: '+str(self.ranges))
+        logger.debug('new file begins: '+str(self.begins))
 
     def get_file_range(self, index):
         """Get the file name and range that corresponds to this piece.
@@ -635,6 +635,7 @@
         
         file = split(file)[0]
         if file != '' and not exists(file):
+            logger.debug('creating directories: '+file)
             makedirs(file)
 
     def top_off(self):

Modified: debtorrent/trunk/DebTorrent/BT1/StorageWrapper.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/StorageWrapper.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/StorageWrapper.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/StorageWrapper.py Mon Aug  6 00:50:01 2007
@@ -512,6 +512,7 @@
                 logger.info('StorageWrapper initialize complete')
                 return
             msg, done, init, next = self.initialize_tasks.pop(0)
+            logger.debug('Starting initialization task: %s', msg)
             if init():
                 self.statusfunc(activity = msg, fractionDone = done)
                 self.initialize_next = next
@@ -580,7 +581,7 @@
         
         """
         
-        logger.debug(str(piece)+' at '+str(pos))
+        logger.debug('Marking '+str(piece)+' at '+str(pos)+' as complete')
         self.places[piece] = pos
         self.have[piece] = True
         len = self._piecelen(piece)

Modified: debtorrent/trunk/DebTorrent/BT1/StreamCheck.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/StreamCheck.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/StreamCheck.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/StreamCheck.py Mon Aug  6 00:50:01 2007
@@ -71,12 +71,12 @@
 
     def read_header_len(self, s):
         if ord(s) != len(protocol_name):
-            logger.warn(str(self.no)+' BAD HEADER LENGTH')
+            logger.warning(str(self.no)+' BAD HEADER LENGTH')
         return len(protocol_name), self.read_header
 
     def read_header(self, s):
         if s != protocol_name:
-            logger.warn(str(self.no)+' BAD HEADER')
+            logger.warning(str(self.no)+' BAD HEADER')
         return 8, self.read_reserved
 
     def read_reserved(self, s):
@@ -93,7 +93,7 @@
     def read_len(self, s):
         l = toint(s)
         if l > 2 ** 23:
-            logger.warn(str(self.no)+' BAD LENGTH: '+str(l)+' ('+s+')')
+            logger.warning(str(self.no)+' BAD LENGTH: '+str(l)+' ('+s+')')
         return l, self.read_message
 
     def read_message(self, s):
@@ -101,10 +101,10 @@
             return 4, self.read_len
         m = s[0]
         if ord(m) > 8:
-            logger.warn(str(self.no)+' BAD MESSAGE: '+str(ord(m)))
+            logger.warning(str(self.no)+' BAD MESSAGE: '+str(ord(m)))
         if m == Connecter.REQUEST:
             if len(s) != 13:
-                logger.warn(str(self.no)+' BAD REQUEST SIZE: '+str(len(s)))
+                logger.warning(str(self.no)+' BAD REQUEST SIZE: '+str(len(s)))
                 return 4, self.read_len
             index = toint(s[1:5])
             begin = toint(s[5:9])
@@ -112,7 +112,7 @@
             logger.info(str(self.no)+' Request: '+str(index)+': '+str(begin)+'-'+str(begin)+'+'+str(length))
         elif m == Connecter.CANCEL:
             if len(s) != 13:
-                logger.warn(str(self.no)+' BAD CANCEL SIZE: '+str(len(s)))
+                logger.warning(str(self.no)+' BAD CANCEL SIZE: '+str(len(s)))
                 return 4, self.read_len
             index = toint(s[1:5])
             begin = toint(s[5:9])

Modified: debtorrent/trunk/DebTorrent/BT1/Uploader.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/Uploader.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/Uploader.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/Uploader.py Mon Aug  6 00:50:01 2007
@@ -17,7 +17,7 @@
 class Upload:
     """Manage uploading to a single peer.
     
-    @type connection: L{DebTorrent.SocketHandler.SingleSocket}
+    @type connection: L{Connecter.Connection}
     @ivar connection: the connection to the peer
     @type ratelimiter: L{RateLimiter.RateLimiter}
     @ivar ratelimiter: the RateLimiter instance to use
@@ -66,7 +66,7 @@
                  picker, config):
         """Initialize the instance and send the initial bitfield.
         
-        @type connection: L{DebTorrent.SocketHandler.SingleSocket}
+        @type connection: L{Connecter.Connection}
         @param connection: the connection to the peer
         @type ratelimiter: L{RateLimiter.RateLimiter}
         @param ratelimiter: the RateLimiter instance to use

Modified: debtorrent/trunk/DebTorrent/BT1/btformats.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/btformats.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/btformats.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/btformats.py Mon Aug  6 00:50:01 2007
@@ -43,7 +43,7 @@
         raise ValueError, 'bad metainfo - bad pieces key'
     piecelengths = info.get('piece lengths')
     if type(piecelengths) != ListType:
-        raise ValueError
+        raise ValueError, 'bad metainfo - bad piece lengths list'
     total_length = 0L
     piece_bounds = [0L]
     for length in piecelengths:
@@ -55,7 +55,7 @@
         raise ValueError, 'single/multiple file mix'
     files = info.get('files')
     if type(files) != ListType:
-        raise ValueError
+        raise ValueError, 'bad metainfo - bad files list'
     total_length = 0L
     for f in files:
         if type(f) != DictType:
@@ -93,13 +93,13 @@
     """
     
     if type(message) != DictType:
-        raise ValueError
+        raise ValueError, 'bad dictionary'
     check_info(message.get('info'))
     if type(message.get('announce')) != StringType:
-        raise ValueError
+        raise ValueError, 'bad announce'
     name = message.get('name')
     if type(name) != StringType:
-        raise ValueError, 'bad metainfo - bad name'
+        raise ValueError, 'bad name'
     if not reg.match(name):
         raise ValueError, 'name %s disallowed for security reasons' % name
 
@@ -116,41 +116,41 @@
     """
     
     if type(message) != DictType:
-        raise ValueError
+        raise ValueError, 'bad dictionary'
     if message.has_key('failure reason'):
         if type(message['failure reason']) != StringType:
-            raise ValueError
+            raise ValueError, 'bad failure reason'
         return
     peers = message.get('peers')
     if type(peers) == ListType:
         for p in peers:
             if type(p) != DictType:
-                raise ValueError
+                raise ValueError, 'bad peers - bad dictionary'
             if type(p.get('ip')) != StringType:
-                raise ValueError
+                raise ValueError, 'bad peers - bad ip'
             port = p.get('port')
             if type(port) not in ints or p <= 0:
-                raise ValueError
+                raise ValueError, 'bad peers - bad port'
             if p.has_key('peer id'):
                 id = p['peer id']
                 if type(id) != StringType or len(id) != 20:
-                    raise ValueError
+                    raise ValueError, 'bad peers - bad peer ID'
     elif type(peers) != StringType or len(peers) % 6 != 0:
-        raise ValueError
+        raise ValueError, 'bad compact peers'
     interval = message.get('interval', 1)
     if type(interval) not in ints or interval <= 0:
-        raise ValueError
+        raise ValueError, 'bad interval'
     minint = message.get('min interval', 1)
     if type(minint) not in ints or minint <= 0:
-        raise ValueError
+        raise ValueError, 'bad min interval'
     if type(message.get('tracker id', '')) != StringType:
-        raise ValueError
+        raise ValueError, 'bad tracker id'
     npeers = message.get('num peers', 0)
     if type(npeers) not in ints or npeers < 0:
-        raise ValueError
+        raise ValueError, 'bad num peers'
     dpeers = message.get('done peers', 0)
     if type(dpeers) not in ints or dpeers < 0:
-        raise ValueError
+        raise ValueError, 'bad done peers'
     last = message.get('last', 0)
     if type(last) not in ints or last < 0:
-        raise ValueError
+        raise ValueError, 'bad last'

Modified: debtorrent/trunk/DebTorrent/BT1/makemetafile.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/makemetafile.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/makemetafile.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/makemetafile.py Mon Aug  6 00:50:01 2007
@@ -284,11 +284,13 @@
     
     pieces = {}
     packages = 0
-
+    piece_url = ''
+    
     if pieces_file:
         try:
             f = open(pieces_file)
         except:
+            logger.exception('sub-pieces file not found: '+pieces_file)
             return {}
     elif 'dists' in file.split('_'):
         try:
@@ -320,8 +322,10 @@
                 pass
             f = piece_data.split('\n')
         except:
+            logger.exception('sub-pieces URL not working: '+piece_url)
             return {}
     else:
+        logger.warning('unable to find sub-pieces data')
         return {}
 
     p = [None, [], []]
@@ -350,6 +354,8 @@
     except:
         pass
 
+    logger.info('successfully retrieved sub-piece data for '+str(len(pieces))+' files')
+
     return pieces
 
 def getpieces(f, encoding = None, progress = lambda x: None, separate_all = 0, sub_pieces = {}):
@@ -428,8 +434,12 @@
 
     if packages[0] > 0:
         info = {'pieces': ''.join(pieces[0]), 'piece lengths': lengths[0], 'files': fs[0]}
+        logger.info('got metainfo for torrent of '+str(len(pieces[0]))+
+                    ' pieces for '+str(len(fs[0]))+' files')
     if packages[1] > 0:
         info_all = {'pieces': ''.join(pieces[1]), 'piece lengths': lengths[1], 'files': fs[1]}
+        logger.info('got metainfo for torrent of '+str(len(pieces[0]))+
+                    ' pieces for '+str(len(fs[0]))+' files')
 
     return (info, info_all)
 
@@ -458,8 +468,6 @@
 
     sub_pieces = getsubpieces(file, pieces_file)
 
-    logger.warning('WARNING: Pieces file could not be found, not using sub-package pieces.')
-        
     file = abspath(file)
     f = open(file)
     (info, info_all) = getpieces(f, encoding, progress, separate_all = separate_all, sub_pieces = sub_pieces)

Modified: debtorrent/trunk/DebTorrent/BT1/track.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/BT1/track.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/BT1/track.py (original)
+++ debtorrent/trunk/DebTorrent/BT1/track.py Mon Aug  6 00:50:01 2007
@@ -769,9 +769,11 @@
         """
         
         if not self.allow_get:
+            logger.warning('Unauthorized request for torrent file: '+b2a_hex(hash))
             return (400, 'Not Authorized', {'Content-Type': 'text/plain', 'Pragma': 'no-cache'},
                 'get function is not available with this tracker.')
         if not self.allowed.has_key(hash):
+            logger.warning('Request for unknown torrent file: '+b2a_hex(hash))
             return (404, 'Not Found', {'Content-Type': 'text/plain', 'Pragma': 'no-cache'}, alas)
         fname = self.allowed[hash]['file']
         fpath = self.allowed[hash]['path']
@@ -1154,6 +1156,7 @@
 
         if ( (self.allowed_IPs and not self.allowed_IPs.includes(ip))
              or (self.banned_IPs and self.banned_IPs.includes(ip)) ):
+            logger.warning('Unauthorized request from '+ip+' for: '+path)
             return (400, 'Not Authorized', {'Content-Type': 'text/plain', 'Pragma': 'no-cache'},
                 bencode({'failure reason':
                 'your IP is not allowed on this tracker'}))
@@ -1235,6 +1238,7 @@
             rsize = self.add_data(infohash, event, ip, paramslist)
 
         except ValueError, e:
+            logger.exception('Bad request from: '+ip)
             return (400, 'Bad Request', {'Content-Type': 'text/plain'}, 
                 'you sent me garbage - ' + str(e))
 
@@ -1385,7 +1389,7 @@
                 (self.allowed, added, garbage2) = r
                 self.state['allowed_list'] = self.allowed
             except (IOError, OSError):
-                logger.warning('unable to read allowed torrent list')
+                logger.exception('unable to read allowed torrent list')
                 return
             self.allowed_list_mtime = os.path.getmtime(f)
 
@@ -1406,7 +1410,7 @@
                 self.allowed_IPs.read_fieldlist(f)
                 self.allowed_ip_mtime = os.path.getmtime(f)
             except (IOError, OSError):
-                logger.warning('unable to read allowed_IP list')
+                logger.exception('unable to read allowed_IP list')
                 
         f = self.config['banned_ips']
         if f and self.banned_ip_mtime != os.path.getmtime(f):
@@ -1415,7 +1419,7 @@
                 self.banned_IPs.read_rangelist(f)
                 self.banned_ip_mtime = os.path.getmtime(f)
             except (IOError, OSError):
-                logger.warning('unable to read banned_IP list')
+                logger.exception('unable to read banned_IP list')
                 
 
     def delete_peer(self, infohash, peerid):

Modified: debtorrent/trunk/DebTorrent/HTTPCache.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/HTTPCache.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/HTTPCache.py (original)
+++ debtorrent/trunk/DebTorrent/HTTPCache.py Mon Aug  6 00:50:01 2007
@@ -85,12 +85,12 @@
         try:
             self.connection = HTTPConnection(self.server)
         except:
-            logger.error('cannot connect to http seed: '+self.server)
+            logger.exception('cannot connect to http seed: '+self.server)
             return
         
         self.headers = {'User-Agent': VERSION}
         self.active = False
-        logger.info('CacheRequest: downloading '+self.url)
+        logger.debug('starting thread to download '+self.url)
         rq = Thread(target = self._request, name = 'HTTPCache.CacheRequest._request')
         rq.setDaemon(False)
         rq.start()
@@ -103,12 +103,12 @@
         import encodings.idna
         
         try:
-            logger.debug('CacheRequest: sending request GET '+self.url+', '+str(self.headers))
+            logger.debug('sending request GET '+self.url+', '+str(self.headers))
             self.connection.request('GET',self.url, None, self.headers)
             
             r = self.connection.getresponse()
                 
-            logger.debug('CacheRequest: got response '+str(r.status)+', '+r.reason+', '+str(r.getheaders()))
+            logger.debug('got response '+str(r.status)+', '+r.reason+', '+str(r.getheaders()))
             self.connection_status = r.status
             self.connection_response = r.reason
             self.headers = dict(r.getheaders())
@@ -166,7 +166,7 @@
         
         """
         
-        logger.info('Starting a HttpCache downloader for: http://'+'/'.join(path))
+        logger.info('Starting a downloader for: http://'+'/'.join(path))
         self.downloads.append(CacheRequest(self, path, func))
 
     def download_complete(self, d, path, func, r):
@@ -187,7 +187,7 @@
         
         """
         
-        logger.info('HttpCache download completed for: http://'+'/'.join(path))
+        logger.info('download completed for: http://'+'/'.join(path))
         self.downloads.remove(d)
 
         if r[0] in (200, 206):
@@ -247,6 +247,7 @@
             
         # Check if the file isn't in the cache
         if not exists(file):
+            logger.info('cache miss: '+file)
             return (404, 'Not Found', {'Server': VERSION, 'Content-Type': 'text/plain', 'Pragma': 'no-cache'}, alas)
         
         if uptodate:
@@ -259,10 +260,12 @@
 
             # Check if the cached data is stale
             if self.check_mtime(last_modified, file = file) > 0:
+                logger.info('cache out of date: '+file)
                 return (405, 'Method Not Allowed', {'Server': VERSION, 'Content-Type': 'text/plain', 'Pragma': 'no-cache'}, alas)
 
         # Check if the request needs the data
         if if_modified_time and self.check_mtime(if_modified_time, file = file) >= 0:
+            logger.info('cache up to date and so is request: '+file)
             return (304, 'Not Modified', {'Server': VERSION, 'Pragma': 'no-cache'}, '')
             
         # Read in the file and return the data
@@ -271,6 +274,7 @@
         f.close()
         mtime_string = strftime(time_format+' GMT', gmtime(getmtime(file)))
         
+        logger.info('cache hit: '+file)
         return (200, 'OK', {'Server': VERSION, 'Content-Type': 'text/plain', 'Last-Modified': mtime_string}, data)
 
     def get_filename(self, path):

Modified: debtorrent/trunk/DebTorrent/HTTPHandler.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/HTTPHandler.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/HTTPHandler.py (original)
+++ debtorrent/trunk/DebTorrent/HTTPHandler.py Mon Aug  6 00:50:01 2007
@@ -157,10 +157,13 @@
             self.command, self.path = words
             self.pre1 = True
             if self.command != 'GET':
+                logger.warning('connection closed, improper command: '+self.command)
                 return None
         else:
+            logger.warning('connection closed, corrupt header line: '+data)
             return None
         if self.command not in ('HEAD', 'GET'):
+            logger.warning('connection closed, improper command: '+self.command)
             return None
         self.headers = {}
         return self.read_header
@@ -189,6 +192,7 @@
         try:
             i = data.index(':')
         except ValueError:
+            logger.warning('connection closed, corrupt header: '+data)
             return None
         self.headers[data[:i].strip().lower()] = data[i+1:].strip()
         logger.debug(data[:i].strip() + ": " + data[i+1:].strip())
@@ -209,6 +213,7 @@
         """
         
         if self.closed:
+            logger.warning('connection closed before anwswer, dropping data')
             return
         if self.encoding == 'gzip':
             compressed = StringIO()
@@ -233,6 +238,8 @@
                                 self.headers.get('referer','-'),
                                 self.headers.get('user-agent','-') )
         self.done = True
+        logger.info('sending response: '+str(responsecode)+' '+responsestring+
+                    ' ('+str(len(data))+' bytes)')
         r = StringIO()
         r.write('HTTP/1.0 ' + str(responsecode) + ' ' + 
             responsestring + '\r\n')

Modified: debtorrent/trunk/DebTorrent/RawServer.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/RawServer.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/RawServer.py (original)
+++ debtorrent/trunk/DebTorrent/RawServer.py Mon Aug  6 00:50:01 2007
@@ -334,7 +334,7 @@
                             return
                         except KeyboardInterrupt:
                             signal(SIGINT, SIG_DFL)
-#                            self.exception(True)
+                            self.exception(True)
                             return
                         except:
                             self.exception()
@@ -351,7 +351,7 @@
                         return
                 except KeyboardInterrupt:
                     signal(SIGINT, SIG_DFL)
-#                    self.exception(True)
+                    self.exception(True)
                     return
                 except:
                     self.exception()

Modified: debtorrent/trunk/DebTorrent/ServerPortHandler.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/ServerPortHandler.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/ServerPortHandler.py (original)
+++ debtorrent/trunk/DebTorrent/ServerPortHandler.py Mon Aug  6 00:50:01 2007
@@ -6,6 +6,8 @@
 
 """Wrappers to handle multiple torrent downloads.
 
+ at type logger: C{logging.Logger}
+ at var logger: the logger to send all log messages to for this module
 @type default_task_id: C{mutable}
 @var default_task_id: the default task ID to use for scheduling all unspecified tasks
 
@@ -14,6 +16,8 @@
 from cStringIO import StringIO
 #from RawServer import RawServer
 from BTcrypto import Crypto
+from binascii import b2a_hex
+import logging
 try:
     True
 except:
@@ -21,6 +25,8 @@
     False = 0
 
 from BT1.Encrypter import protocol_name
+
+logger = logging.getLogger('DebTorrent.ServerPortHandler')
 
 default_task_id = []
 
@@ -252,6 +258,7 @@
     def _auto_close(self):
         """Automatically close the connection if it is not fully connected."""
         if not self.complete:
+            logger.warning('Connection dropped due to handshake taking too long')
             self.close()
         
     def close(self):
@@ -291,9 +298,11 @@
         
         if self._read_header(s):
             if self.multihandler.config['crypto_only']:
+                logger.info('Dropped the connection as it was unencrypted')
                 return None
             return 8, self.read_options
         if not self.multihandler.config['crypto_allowed']:
+            logger.info('Dropped the connection as it was encrypted')
             return None
         self.encrypted = True
         self.encrypter = Crypto(False)
@@ -370,7 +379,9 @@
                 self.multihandler.singlerawservers[k]._external_connection_made(
                         self.connection, None, self.buffer,
                         encrypted = self.encrypter )
+                logger.info('Found the encrypted download ID: '+b2a_hex(k))
                 return True
+        logger.info('Dropped the encrypted connection to an unknown torrent')
         return None
 
     def read_options(self, s):
@@ -402,7 +413,9 @@
             if self.multihandler.singlerawservers[s].protocol == self.protocol:
                 self.multihandler.singlerawservers[s]._external_connection_made(
                         self.connection, self.options, self.buffer)
+                logger.info('Found the unencrypted download ID: '+b2a_hex(s))
                 return True
+        logger.info('Dropped the unencrypted connection to an unknown torrent: '+b2a_hex(s))
         return None
 
 
@@ -475,6 +488,7 @@
             try:
                 x = self.next_func(m)
             except:
+                logger.exception('Dropped connection due to exception')
                 self.next_len, self.next_func = 1, self.read_dead
                 raise
             if x is None:

Modified: debtorrent/trunk/DebTorrent/SocketHandler.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/SocketHandler.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/SocketHandler.py (original)
+++ debtorrent/trunk/DebTorrent/SocketHandler.py Mon Aug  6 00:50:01 2007
@@ -192,6 +192,7 @@
             if self.skipped >= 3:
                 dead = True
             if dead:
+                logger.debug('Socket is dead from write: '+self.ip)
                 self.socket_handler.dead_from_write.append(self)
                 return
         if self.buffer:
@@ -258,7 +259,6 @@
         self.ipv6_enable = ipv6_enable
         self.readsize = readsize
         self.poll = poll()
-        # {socket: SingleSocket}
         self.single_sockets = {}
         self.dead_from_write = []
         self.max_connects = 1000
@@ -351,6 +351,7 @@
             self.servers[key] = value
         for item in newinterfaces:
             self.interfaces.append(item)
+        logger.info('Successfully bound to port '+str(port))
 
     def find_and_bind(self, minport, maxport, bind = '', reuse = False,
                       ipv6_socket_style = 1, randomizer = False):

Modified: debtorrent/trunk/DebTorrent/__init__.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/__init__.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/__init__.py (original)
+++ debtorrent/trunk/DebTorrent/__init__.py Mon Aug  6 00:50:01 2007
@@ -8,6 +8,8 @@
 This package, and it's subpackage L{BT1}, contains all the modules needed
 to implement the DebTorrent protocol.
 
+ at type logger: C{logging.Logger}
+ at var logger: the logger to send all log messages to for this module
 @type product_name: C{string}
 @var product_name: the name given for the package
 @type version_short: C{string}
@@ -28,11 +30,15 @@
 from types import StringType
 from sha import sha
 from time import time, clock
+from binascii import b2a_hex
+import logging
 try:
     from os import getpid
 except ImportError:
     def getpid():
         return 1
+
+logger = logging.getLogger('DebTorrent')
 
 protocol_name = product_name+'/'+'.'.join(version_short[2:].split('.')[:2])
 
@@ -57,6 +63,7 @@
     except:
         x = ''
 
+    logger.info('Resetting the peer ID generation')
     l1 = 0
     t = clock()
     while t == clock():
@@ -95,4 +102,5 @@
     
     assert type(ins) is StringType
     assert len(ins) == 3
+    logger.info('New peer ID: '+b2a_hex(_idprefix + ins + _idrandom[0]))
     return _idprefix + ins + _idrandom[0]

Modified: debtorrent/trunk/DebTorrent/bencode.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/bencode.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/bencode.py (original)
+++ debtorrent/trunk/DebTorrent/bencode.py Mon Aug  6 00:50:01 2007
@@ -476,7 +476,7 @@
     try:
         encode_func[type(x)](x, r)
     except:
-        logger.error('could not encode type '+str(type(x))+' (value: '+str(x)+')')
+        logger.exception('could not encode type '+str(type(x))+' (value: '+str(x)+')')
         assert 0
     return ''.join(r)
 

Modified: debtorrent/trunk/DebTorrent/download_bt1.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/download_bt1.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/download_bt1.py (original)
+++ debtorrent/trunk/DebTorrent/download_bt1.py Mon Aug  6 00:50:01 2007
@@ -852,8 +852,10 @@
                 self.config, self.unpauseflag)
             
         except ValueError, e:
+            logger.exception('bad data')
             self._failed('bad data - ' + str(e))
         except IOError, e:
+            logger.exception('IOError')
             self._failed('IOError - ' + str(e))
         if self.doneflag.isSet():
             return None
@@ -1177,6 +1179,7 @@
         
         """
         
+        logger.info('Download shutdown')
         if self.checking or self.started:
             self.storagewrapper.sync()
             self.storage.close()
@@ -1429,6 +1432,7 @@
     def onPause(self):
         """Pause the download."""
         
+        logger.info('Download paused')
         self.whenpaused = clock()
         if not self.downloader:
             return
@@ -1443,6 +1447,7 @@
 
     def onUnpause(self):
         """Resume the download."""
+        logger.info('Download unpaused')
         if not self.downloader:
             return
         self.downloader.pause(False)

Modified: debtorrent/trunk/DebTorrent/launchmanycore.py
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/DebTorrent/launchmanycore.py?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/DebTorrent/launchmanycore.py (original)
+++ debtorrent/trunk/DebTorrent/launchmanycore.py Mon Aug  6 00:50:01 2007
@@ -233,6 +233,7 @@
         
         if self.closed:
             return
+        logger.info('Download shutdown')
         self.doneflag.set()
         self.rawserver.shutdown()
         if self.checking or self.working:
@@ -485,6 +486,7 @@
         
         """
         
+        logger.info('Removing torrent: '+str(binascii.b2a_hex(hash)))
         self.torrent_list.remove(hash)
         self.downloads[hash].shutdown()
         del self.downloads[hash]
@@ -543,6 +545,7 @@
             logger.error('Asked to start a torrent that is not in the cache')
             return
         
+        logger.info('Starting torrent: '+str(binascii.b2a_hex(hash)))
         c = self.counter
         self.counter += 1
         x = ''
@@ -620,7 +623,7 @@
         """
 
         file = '/'.join(path)
-        logger.debug('Trying to find file: '+file)
+        logger.info('Trying to find file: '+file)
         found_torrents = []
             
         # Check each torrent in the cache

Modified: debtorrent/trunk/TODO
URL: http://svn.debian.org/wsvn/debtorrent/debtorrent/trunk/TODO?rev=199&op=diff
==============================================================================
--- debtorrent/trunk/TODO (original)
+++ debtorrent/trunk/TODO Mon Aug  6 00:50:01 2007
@@ -78,13 +78,6 @@
 file are used, an allocation method could be used within a file.
 
 
-Comments
-
-Comments are needed, both for new code, and the original. Variable naming 
-could aslo be dramatically improved. This might break merging in new upstreams 
-though (but this might already be broken).
-
-
 Statistics for the swarm are incorrect
 
 The statistics for file completion in the swarm are incorrect. This is due to 




More information about the Debtorrent-commits mailing list