diff src/plugins/plugin_xep_0065.py @ 993:301b342c697a

core: use of the new core.log module: /!\ this is a massive refactoring and was largely automated, it probably did bring some bugs /!\
author Goffi <goffi@goffi.org>
date Sat, 19 Apr 2014 19:19:19 +0200
parents 132de9d487ac
children 9a85836f0d45
line wrap: on
line diff
--- a/src/plugins/plugin_xep_0065.py	Sat Apr 19 16:48:26 2014 +0200
+++ b/src/plugins/plugin_xep_0065.py	Sat Apr 19 19:19:19 2014 +0200
@@ -55,9 +55,10 @@
 # THE SOFTWARE.
 
 from sat.core.i18n import _
-from logging import debug, info, warning, error
+from sat.core.log import getLogger
+log = getLogger(__name__)
 from twisted.internet import protocol, reactor
-from twisted.internet import error as jab_error
+from twisted.internet import error
 from twisted.words.protocols.jabber import jid, client as jabber_client
 from twisted.protocols.basic import FileSender
 from twisted.words.xish import domish
@@ -139,7 +140,7 @@
 
 class SOCKSv5(protocol.Protocol, FileSender):
     def __init__(self):
-        debug(_("Protocol init"))
+        log.debug(_("Protocol init"))
         self.state = STATE_INITIAL
         self.buf = ""
         self.supportedAuthMechs = [AUTHMECH_ANON]
@@ -150,12 +151,12 @@
         self.requestType = 0
 
     def _startNegotiation(self):
-        debug("_startNegotiation")
+        log.debug("_startNegotiation")
         self.state = STATE_TARGET_AUTH
         self.transport.write(struct.pack('!3B', SOCKS5_VER, 1, AUTHMECH_ANON))
 
     def _parseNegotiation(self):
-        debug("_parseNegotiation")
+        log.debug("_parseNegotiation")
         try:
             # Parse out data
             ver, nmethod = struct.unpack('!BB', self.buf[:2])
@@ -189,7 +190,7 @@
             pass
 
     def _parseUserPass(self):
-        debug("_parseUserPass")
+        log.debug("_parseUserPass")
         try:
             # Parse out data
             ver, ulen = struct.unpack('BB', self.buf[:2])
@@ -211,14 +212,14 @@
             pass
 
     def sendErrorReply(self, errorcode):
-        debug("sendErrorReply")
+        log.debug("sendErrorReply")
         # Any other address types are not supported
         result = struct.pack('!BBBBIH', SOCKS5_VER, errorcode, 0, 1, 0, 0)
         self.transport.write(result)
         self.transport.loseConnection()
 
     def _parseRequest(self):
-        debug("_parseRequest")
+        log.debug("_parseRequest")
         try:
             # Parse out data and trim buffer accordingly
             ver, cmd, rsvd, self.addressType = struct.unpack('!BBBB', self.buf[:4])
@@ -260,14 +261,14 @@
             return None
 
     def _makeRequest(self):
-        debug("_makeRequest")
+        log.debug("_makeRequest")
         self.state = STATE_TARGET_REQUEST
         sha1 = calculateHash(self.data["from"], self.data["to"], self.sid)
         request = struct.pack('!5B%dsH' % len(sha1), SOCKS5_VER, CMD_CONNECT, 0, ADDR_DOMAINNAME, len(sha1), sha1, 0)
         self.transport.write(request)
 
     def _parseRequestReply(self):
-        debug("_parseRequestReply")
+        log.debug("_parseRequestReply")
         try:
             ver, rep, rsvd, self.addressType = struct.unpack('!BBBB', self.buf[:4])
             # Ensure we actually support the requested address type
@@ -304,7 +305,7 @@
             return None
 
     def connectionMade(self):
-        debug("connectionMade (mode = %s)" % "requester" if isinstance(self.factory, Socks5ServerFactory) else "target")
+        log.debug("connectionMade (mode = %s)" % "requester" if isinstance(self.factory, Socks5ServerFactory) else "target")
 
         if isinstance(self.factory, Socks5ClientFactory):
             self.sid = self.factory.sid
@@ -314,7 +315,7 @@
             self._startNegotiation()
 
     def connectRequested(self, addr, port):
-        debug("connectRequested")
+        log.debug("connectRequested")
 
         # Check that this session is expected
         if addr not in self.factory.hash_sid_map:
@@ -333,12 +334,12 @@
         d.addCallback(self.fileTransfered)
 
     def fileTransfered(self, d):
-        info(_("File transfer completed, closing connection"))
+        log.info(_("File transfer completed, closing connection"))
         self.transport.loseConnection()
         self.factory.finishedCb(self.sid, True, self.profile)
 
     def connectCompleted(self, remotehost, remoteport):
-        debug("connectCompleted")
+        log.debug("connectCompleted")
         if self.addressType == ADDR_IPV4:
             result = struct.pack('!BBBBIH', SOCKS5_VER, REPLY_SUCCESS, 0, 1, remotehost, remoteport)
         elif self.addressType == ADDR_DOMAINNAME:
@@ -351,7 +352,7 @@
         pass
 
     def authenticateUserPass(self, user, passwd):
-        debug("User/pass: %s/%s", user, passwd)
+        log.debug("User/pass: %s/%s", user, passwd)
         return True
 
     def dataReceived(self, buf):
@@ -377,11 +378,11 @@
             self._parseRequestReply()
 
     def clientConnectionLost(self, reason):
-        debug("clientConnectionLost")
+        log.debug("clientConnectionLost")
         self.transport.loseConnection()
 
     def connectionLost(self, reason):
-        debug("connectionLost")
+        log.debug("connectionLost")
         if self.state != STATE_CONNECT_PENDING:
             self.transport.unregisterProducer()
             if self.peersock is not None:
@@ -399,10 +400,10 @@
         self.finishedCb = finishedCb
 
     def startedConnecting(self, connector):
-        debug(_("Socks 5 server connection started"))
+        log.debug(_("Socks 5 server connection started"))
 
     def clientConnectionLost(self, connector, reason):
-        debug(_("Socks 5 server connection lost (reason: %s)"), reason)
+        log.debug(_("Socks 5 server connection lost (reason: %s)"), reason)
 
 
 class Socks5ClientFactory(protocol.ClientFactory):
@@ -427,11 +428,11 @@
         self.profile = profile
 
     def startedConnecting(self, connector):
-        debug(_("Socks 5 client connection started"))
+        log.debug(_("Socks 5 client connection started"))
 
     def clientConnectionLost(self, connector, reason):
-        debug(_("Socks 5 client connection lost (reason: %s)"), reason)
-        self.finishedCb(self.sid, reason.type == jab_error.ConnectionDone, self.profile)  # TODO: really check if the state is actually successful
+        log.debug(_("Socks 5 client connection lost (reason: %s)"), reason)
+        self.finishedCb(self.sid, reason.type == error.ConnectionDone, self.profile)  # TODO: really check if the state is actually successful
 
 
 class XEP_0065(object):
@@ -457,13 +458,13 @@
     """
 
     def __init__(self, host):
-        info(_("Plugin XEP_0065 initialization"))
+        log.info(_("Plugin XEP_0065 initialization"))
 
         #session data
         self.hash_sid_map = {}  # key: hash of the transfer session, value: (session id, profile)
 
         self.host = host
-        debug(_("registering"))
+        log.debug(_("registering"))
         self.server_factory = Socks5ServerFactory(host, self.hash_sid_map, lambda sid, success, profile: self._killId(sid, success, profile=profile))
 
         #parameters
@@ -471,7 +472,7 @@
         host.memory.setDefault("IP", "File Transfer", self.getExternalIP)
         port = int(self.host.memory.getParamA("Port", "File Transfer"))
 
-        info(_("Launching Socks5 Stream server on port %d"), port)
+        log.info(_("Launching Socks5 Stream server on port %d") % port)
         reactor.listenTCP(port, self.server_factory)
 
     def getHandler(self, profile):
@@ -498,7 +499,7 @@
     def _timeOut(self, sid, profile):
         """Delecte current_stream id, called after timeout
         @param id: id of client.xep_0065_current_stream"""
-        info(_("Socks5 Bytestream: TimeOut reached for id %(sid)s [%(profile)s]")
+        log.info(_("Socks5 Bytestream: TimeOut reached for id %(sid)s [%(profile)s]")
              % {"sid": sid, "profile": profile})
         self._killId(sid, False, "TIMEOUT", profile)
 
@@ -508,7 +509,7 @@
         assert(profile)
         client = self.host.getClient(profile)
         if sid not in client.xep_0065_current_stream:
-            warning(_("kill id called on a non existant id"))
+            log.warning(_("kill id called on a non existant id"))
             return
         if "observer_cb" in client.xep_0065_current_stream[sid]:
             xmlstream = client.xep_0065_current_stream[sid]["xmlstream"]
@@ -546,7 +547,7 @@
         client = self.host.getClient(profile)
 
         if length is not None:
-            error(_('stream length not managed yet'))
+            log.error(_('stream length not managed yet'))
             return
 
         profile_jid = client.jid
@@ -589,7 +590,7 @@
     def iqResult(self, sid, profile, iq_elt):
         """Called when the result of open iq is received"""
         if iq_elt["type"] == "error":
-            warning(_("Transfer failed"))
+            log.warning(_("Transfer failed"))
             return
         client = self.host.getClient(profile)
         try:
@@ -597,7 +598,7 @@
             file_obj = data["file_obj"]
             timer = data["timer"]
         except KeyError:
-            error(_("Internal error, can't do transfer"))
+            log.error(_("Internal error, can't do transfer"))
             return
 
         if timer.active():
@@ -607,17 +608,17 @@
         query_elt = iq_elt.firstChildElement()
         streamhost_elts = filter(lambda elt: elt.name == 'streamhost-used', query_elt.elements())
         if not streamhost_elts:
-            warning(_("No streamhost found in stream query"))
+            log.warning(_("No streamhost found in stream query"))
             return
 
         streamhost_jid = streamhost_elts[0]['jid']
         if streamhost_jid != profile_jid.full():
-            debug(_("A proxy server is used"))
+            log.debug(_("A proxy server is used"))
             proxy_host = self.host.memory.getParamA("Proxy host", "File Transfer", profile_key=profile)
             proxy_port = self.host.memory.getParamA("Proxy port", "File Transfer", profile_key=profile)
             proxy_jid = self.host.memory.getParamA("Proxy", "File Transfer", profile_key=profile)
             if proxy_jid != streamhost_jid:
-                warning(_("Proxy jid is not the same as in parameters, this should not happen"))
+                log.warning(_("Proxy jid is not the same as in parameters, this should not happen"))
                 return
             factory = Socks5ClientFactory(client.xep_0065_current_stream, sid, None, self.activateProxyStream, lambda sid, success, profile: self._killId(sid, success, profile=profile), True, profile)
             reactor.connectTCP(proxy_host, int(proxy_port), factory)
@@ -625,7 +626,7 @@
             data["start_transfer_cb"](file_obj)  # We now activate the stream
 
     def activateProxyStream(self, sid, iq_id, start_transfer_cb, profile):
-        debug(_("activating stream"))
+        log.debug(_("activating stream"))
         client = self.host.getClient(profile)
         data = client.xep_0065_current_stream[sid]
         profile_jid, xmlstream = self.host.getJidNStream(profile)
@@ -641,7 +642,7 @@
 
     def proxyResult(self, sid, start_transfer_cb, file_obj, iq_elt):
         if iq_elt['type'] == 'error':
-            warning(_("Can't activate the proxy stream"))
+            log.warning(_("Can't activate the proxy stream"))
             return
         else:
             start_transfer_cb(file_obj)
@@ -669,7 +670,7 @@
 
     def streamQuery(self, iq_elt, profile):
         """Get file using byte stream"""
-        debug(_("BS stream query"))
+        log.debug(_("BS stream query"))
         client = self.host.getClient(profile)
 
         if not client:
@@ -683,7 +684,7 @@
         streamhost_elts = filter(lambda elt: elt.name == 'streamhost', query_elt.elements())
 
         if not sid in client.xep_0065_current_stream:
-            warning(_("Ignoring unexpected BS transfer: %s" % sid))
+            log.warning(_("Ignoring unexpected BS transfer: %s" % sid))
             self.sendNotAcceptableError(iq_elt['id'], iq_elt['from'], xmlstream)
             return
 
@@ -692,7 +693,7 @@
         client.xep_0065_current_stream[sid]["xmlstream"] = xmlstream
 
         if not streamhost_elts:
-            warning(_("No streamhost found in stream query %s" % sid))
+            log.warning(_("No streamhost found in stream query %s" % sid))
             self.sendBadRequestError(iq_elt['id'], iq_elt['from'], xmlstream)
             return
 
@@ -701,19 +702,19 @@
         sh_port = streamhost_elt.getAttribute("port")
         sh_jid = streamhost_elt.getAttribute("jid")
         if not sh_host or not sh_port or not sh_jid:
-            warning(_("incomplete streamhost element"))
+            log.warning(_("incomplete streamhost element"))
             self.sendBadRequestError(iq_elt['id'], iq_elt['from'], xmlstream)
             return
 
         client.xep_0065_current_stream[sid]["streamhost"] = (sh_host, sh_port, sh_jid)
 
-        info(_("Stream proposed: host=[%(host)s] port=[%(port)s]") % {'host': sh_host, 'port': sh_port})
+        log.info(_("Stream proposed: host=[%(host)s] port=[%(port)s]") % {'host': sh_host, 'port': sh_port})
         factory = Socks5ClientFactory(client.xep_0065_current_stream, sid, iq_elt["id"], self.activateStream, lambda sid, success, profile: self._killId(sid, success, profile=profile), profile=profile)
         reactor.connectTCP(sh_host, int(sh_port), factory)
 
     def activateStream(self, sid, iq_id, profile):
         client = self.host.getClient(profile)
-        debug(_("activating stream"))
+        log.debug(_("activating stream"))
         result = domish.Element((None, 'iq'))
         data = client.xep_0065_current_stream[sid]
         result['type'] = 'result'
@@ -766,18 +767,18 @@
         """Called with the informations about proxy according to XEP-0065 #4
         Params should be filled with these infos"""
         if iq_elt["type"] == "error":
-            warning(_("Can't determine proxy informations"))
+            log.warning(_("Can't determine proxy informations"))
             return
         query_elt = iq_elt.firstChildElement()
         if query_elt.name != "query":
-            warning(_("Bad answer received from proxy"))
+            log.warning(_("Bad answer received from proxy"))
             return
         streamhost_elts = filter(lambda elt: elt.name == 'streamhost', query_elt.elements())
         if not streamhost_elts:
-            warning(_("No streamhost found in stream query"))
+            log.warning(_("No streamhost found in stream query"))
             return
         if len(streamhost_elts) != 1:
-            warning(_("Multiple streamhost elements in proxy not managed, keeping only the first one"))
+            log.warning(_("Multiple streamhost elements in proxy not managed, keeping only the first one"))
         streamhost_elt = streamhost_elts[0]
         self.host.memory.setParam("Proxy", streamhost_elt.getAttribute("jid", ""),
                                   "File Transfer", profile_key=self.parent.profile)
@@ -795,7 +796,7 @@
                     try:
                         proxy_ent = entities.pop()
                     except KeyError:
-                        info(_("No proxy found on this server"))
+                        log.info(_("No proxy found on this server"))
                         return
                     iq_elt = jabber_client.IQ(self.parent.xmlstream, 'get')
                     iq_elt["to"] = proxy_ent.full()