diff --git a/src/common/xmpp/client_nb.py b/src/common/xmpp/client_nb.py index cf8fa67be..314f0a232 100644 --- a/src/common/xmpp/client_nb.py +++ b/src/common/xmpp/client_nb.py @@ -123,8 +123,12 @@ class NBCommonClient(CommonClient): self.on_connect_failure(retry) def _on_connected(self): - # connect succeded, so no need of this callback anymore - self.on_connect_failure = None + # FIXME: why was this needed? Please note that we're working + # in nonblocking mode, and this handler is actually called + # as soon as connection is initiated, NOT when connection + # succeeds, as the name suggests. + # # connect succeeded, so no need of this callback anymore + # self.on_connect_failure = None self.connected = 'tcp' if self._Ssl: transports_nb.NonBlockingTLS().PlugIn(self, now=1) diff --git a/src/common/xmpp/dispatcher_nb.py b/src/common/xmpp/dispatcher_nb.py index 30eb811b0..9f05282f1 100644 --- a/src/common/xmpp/dispatcher_nb.py +++ b/src/common/xmpp/dispatcher_nb.py @@ -135,7 +135,6 @@ class Dispatcher(PlugIn): self._owner.Connection.disconnect() return 0 except ExpatError: - sys.exc_clear() self.DEBUG('Invalid XML received from server. Forcing disconnect.', 'error') self._owner.Connection.pollend() return 0 diff --git a/src/common/xmpp/transports_nb.py b/src/common/xmpp/transports_nb.py index 4c656b4c0..adf2602ec 100644 --- a/src/common/xmpp/transports_nb.py +++ b/src/common/xmpp/transports_nb.py @@ -24,6 +24,34 @@ from transports import * import sys import os import errno +import time + +import traceback +import thread + +import logging +h = logging.StreamHandler() +f = logging.Formatter('%(asctime)s %(name)s: %(levelname)s: %(message)s') +h.setFormatter(f) +log = logging.getLogger('Gajim.transports') +log.addHandler(h) +log.setLevel(logging.DEBUG) +log.propagate = False +del h, f + +USE_PYOPENSSL = False + +try: + #raise ImportError("Manually disabled PyOpenSSL") + import OpenSSL.SSL + import OpenSSL.crypto + USE_PYOPENSSL = True + log.info("PyOpenSSL loaded") +except ImportError: + # FIXME: Remove these prints before release, replace with a warning dialog. + print >> sys.stderr, "=" * 79 + print >> sys.stderr, "PyOpenSSL not found, falling back to Python builtin SSL objects (insecure)." + print >> sys.stderr, "=" * 79 # timeout to connect to the server socket, it doesn't include auth CONNECT_TIMEOUT_SECONDS = 30 @@ -33,7 +61,178 @@ DISCONNECT_TIMEOUT_SECONDS = 10 # size of the buffer which reads data from server # if lower, more stanzas will be fragmented and processed twice -RECV_BUFSIZE = 1048576 +RECV_BUFSIZE = 32768 # 2x maximum size of ssl packet, should be plenty +#RECV_BUFSIZE = 16 # FIXME: (#2634) gajim breaks with this setting: it's inefficient but should work. + +def torf(cond, tv, fv): + if cond: return tv + return fv + +def gattr(obj, attr, default=None): + try: + return getattr(obj, attr) + except: + return default + +class SSLWrapper: + class Error(IOError): + def __init__(self, sock=None, exc=None, errno=None, strerror=None, peer=None): + self.parent = IOError + + errno = errno or gattr(exc, 'errno') + strerror = strerror or gattr(exc, 'strerror') or gattr(exc, 'args') + if not isinstance(strerror, basestring): strerror = repr(strerror) + + self.sock = sock + self.exc = exc + self.peer = peer + self.exc_name = None + self.exc_args = None + self.exc_str = None + self.exc_repr = None + + if self.exc is not None: + self.exc_name = str(self.exc.__class__) + self.exc_args = gattr(self.exc, 'args') + self.exc_str = str(self.exc) + self.exc_repr = repr(self.exc) + if not errno: + try: + if isinstance(exc, OpenSSL.SSL.SysCallError): + if self.exc_args[0] > 0: + errno = self.exc_args[0] + strerror = self.exc_args[1] + except: pass + + self.parent.__init__(self, errno, strerror) + + if self.peer is None and sock is not None: + try: + ppeer = self.sock.getpeername() + if len(ppeer) == 2 and isinstance(ppeer[0], basestring) \ + and isinstance(ppeer[1], int): + self.peer = ppeer + except: pass + + def __str__(self): + s = str(self.__class__) + if self.peer: s += " for %s:%d" % self.peer + if self.errno is not None: s += ": [Errno: %d]" % self.errno + if self.strerror: s += " (%s)" % self.strerror + if self.exc_name: + s += ", Caused by %s" % self.exc_name + if self.exc_str: + if self.strerror: s += "(%s)" % self.exc_str + else: s += "(%s)" % str(self.exc_args) + return s + + def __init__(self, sslobj, sock=None): + self.sslobj = sslobj + self.sock = sock + log.debug("%s.__init__ called with %s", self.__class__, sslobj) + + def recv(self, data, flags=None): + """ Receive wrapper for SSL object + + We can return None out of this function to signal that no data is + available right now. Better than an exception, which differs + depending on which SSL lib we're using. Unfortunately returning '' + can indicate that the socket has been closed, so to be sure, we avoid + this by returning None. """ + + raise NotImplementedException() + + def send(self, data, flags=None): + raise NotImplementedException() + +class PyOpenSSLWrapper(SSLWrapper): + '''Wrapper class for PyOpenSSL's recv() and send() methods''' + + def __init__(self, *args): + self.parent = SSLWrapper + self.parent.__init__(self, *args) + + def is_numtoolarge(self, e): + t = ('asn1 encoding routines', 'a2d_ASN1_OBJECT', 'first num too large') + return isinstance(e.args, (list, tuple)) and len(e.args) == 1 and \ + isinstance(e.args[0], (list, tuple)) and len(e.args[0]) == 2 and \ + e.args[0][0] == e.args[0][1] == t + + def recv(self, bufsize, flags=None): + retval = None + try: + if flags is None: retval = self.sslobj.recv(bufsize) + else: retval = self.sslobj.recv(bufsize, flags) + except (OpenSSL.SSL.WantReadError, OpenSSL.SSL.WantWriteError), e: + pass + # log.debug("Recv: " + repr(e)) + except OpenSSL.SSL.SysCallError, e: + log.error("Recv: Got OpenSSL.SSL.SysCallError: " + repr(e), exc_info=True) + #traceback.print_exc() + raise SSLWrapper.Error(self.sock or self.sslobj, e) + except OpenSSL.SSL.Error, e: + if self.is_numtoolarge(e): + # warn, but ignore this exception + log.warning("Recv: OpenSSL: asn1enc: first num too large (ignored)") + else: + log.error("Recv: Caught OpenSSL.SSL.Error:", exc_info=True) + #traceback.print_exc() + #print "Current Stack:" + #traceback.print_stack() + raise SSLWrapper.Error(self.sock or self.sslobj, e) + return retval + + def send(self, data, flags=None): + try: + if flags is None: return self.sslobj.send(data) + else: return self.sslobj.send(data, flags) + except (OpenSSL.SSL.WantReadError, OpenSSL.SSL.WantWriteError), e: + #log.debug("Send: " + repr(e)) + time.sleep(0.1) # prevent 100% CPU usage + except OpenSSL.SSL.SysCallError, e: + log.error("Send: Got OpenSSL.SSL.SysCallError: " + repr(e), exc_info=True) + #traceback.print_exc() + raise SSLWrapper.Error(self.sock or self.sslobj, e) + except OpenSSL.SSL.Error, e: + if self.is_numtoolarge(e): + # warn, but ignore this exception + log.warning("Send: OpenSSL: asn1enc: first num too large (ignored)") + else: + log.error("Send: Caught OpenSSL.SSL.Error:", exc_info=True) + #traceback.print_exc() + #print "Current Stack:" + #traceback.print_stack() + raise SSLWrapper.Error(self.sock or self.sslobj, e) + return 0 + +class StdlibSSLWrapper(SSLWrapper): + '''Wrapper class for Python's socket.ssl read() and write() methods''' + + def __init__(self, *args): + self.parent = SSLWrapper + self.parent.__init__(self, *args) + + def recv(self, bufsize, flags=None): + # we simply ignore flags since ssl object doesn't support it + try: + return self.sslobj.read(bufsize) + except socket.sslerror, e: + log.debug("Recv: Caught socket.sslerror:", exc_info=True) + #traceback.print_exc() + if e.args[0] not in (socket.SSL_ERROR_WANT_READ, socket.SSL_ERROR_WANT_WRITE): + raise SSLWrapper.Error(self.sock or self.sslobj, e) + return None + + def send(self, data, flags=None): + # we simply ignore flags since ssl object doesn't support it + try: + return self.sslobj.write(data) + except socket.sslerror, e: + log.debug("Send: Caught socket.sslerror:", exc_info=True) + #traceback.print_exc() + if e.args[0] not in (socket.SSL_ERROR_WANT_READ, socket.SSL_ERROR_WANT_WRITE): + raise SSLWrapper.Error(self.sock or self.sslobj, e) + return 0 class NonBlockingTcp(PlugIn, IdleObject): ''' This class can be used instead of transports.Tcp in threadless implementations ''' @@ -53,6 +252,7 @@ class NonBlockingTcp(PlugIn, IdleObject): self.on_connect_failure = on_connect_failure self.on_receive = None self.on_disconnect = None + self.printed_error = False # 0 - not connected # 1 - connected @@ -82,6 +282,7 @@ class NonBlockingTcp(PlugIn, IdleObject): Also registers self.disconnected method in the owner's dispatcher. Called internally. ''' self.idlequeue = owner.idlequeue + self.printed_error = False if not self._server: self._server=(self._owner.Server,5222) if self.connect(self._server) is False: @@ -104,6 +305,7 @@ class NonBlockingTcp(PlugIn, IdleObject): server=self._server else: self._server = server + self.printed_error = False self.state = 0 try: for ai in socket.getaddrinfo(server[0],server[1],socket.AF_UNSPEC,socket.SOCK_STREAM): @@ -118,7 +320,8 @@ class NonBlockingTcp(PlugIn, IdleObject): #for all errors, we try other addresses continue except: - sys.exc_clear() + log.error("Exception trying to connect to %s:", self.getName(), exc_info=True) + #traceback.print_exc() if self.on_connect_failure: self.on_connect_failure() return False @@ -152,7 +355,11 @@ class NonBlockingTcp(PlugIn, IdleObject): def pollin(self): self._do_receive() - def pollend(self, retry = False): + def pollend(self, retry=False): + if not self.printed_error: + self.printed_error = True + try: self._do_receive(errors_only=True) + except: log.error("pollend: Got exception from _do_receive:", exc_info=True) conn_failure_cb = self.on_connect_failure self.disconnect() if conn_failure_cb: @@ -168,10 +375,11 @@ class NonBlockingTcp(PlugIn, IdleObject): self.idlequeue.unplug_idle(self.fd) try: self._sock.shutdown(socket.SHUT_RDWR) - self._sock.close() - except: - # socket is already closed - sys.exc_clear() + except socket.error, e: + if e[0] != errno.ENOTCONN: + log.error("Error shutting down socket for %s:", self.getName(), exc_info=True) + try: self._sock.close() + except: log.error("Error closing socket for %s:", self.getName(), exc_info=True) # socket descriptor cannot be (un)plugged anymore self.fd = -1 if self.on_disconnect: @@ -211,40 +419,62 @@ class NonBlockingTcp(PlugIn, IdleObject): if not recv_handler(None) and _tmp == self.on_receive: self.on_receive = recv_handler - def _do_receive(self): + def _do_receive(self, errors_only=False): ''' Reads all pending incoming data. Calls owner's disconnected() method if appropriate.''' - received = '' + ERR_DISCONN = -2 # Misc error signifying that we got disconnected + ERR_OTHER = -1 # Other error + received = None errnum = 0 + errtxt = 'No Error Set' try: # get as many bites, as possible, but not more than RECV_BUFSIZE received = self._recv(RECV_BUFSIZE) - except Exception, e: - if len(e.args) > 0 and isinstance(e.args[0], int): - errnum = e[0] - sys.exc_clear() - # "received" will be empty anyhow - if errnum == socket.SSL_ERROR_WANT_READ: - pass - elif errnum == errno.ECONNRESET: - self.pollend(True) - # don't proccess result, caus it will raise error + except (socket.error, socket.herror, socket.gaierror), e: + log.error("_do_receive: got %s:", e.__class__, exc_info=True) + #traceback.print_exc() + #print "Current Stack:" + #traceback.print_stack() + errnum = e[0] + errtxt = str(errnum) + ':' + e[1] + except socket.sslerror, e: + log.error("_do_receive: got unknown %s:", e.__class__, exc_info=True) + #traceback.print_exc() + #print "Current Stack:" + #traceback.print_stack() + errnum = ERR_OTHER + errtxt = repr("socket.sslerror: " + e.args) + except SSLWrapper.Error, e: + log.debug("Caught: %s", str(e)) + errnum = gattr(e, 'errno', ERR_OTHER) + if not errnum: errnum = ERR_OTHER # unset, but we must put a status + errtxt = gattr(e, 'strerror') or repr(e.args) + + if received == '': + errnum = ERR_DISCONN + errtxt = "Connection closed unexpectedly" + + if errnum in (ERR_DISCONN, errno.ECONNRESET, errno.ENOTCONN, errno.ESHUTDOWN): + self.DEBUG(errtxt, 'error') + log.error("Connection to %s lost: %s [%d]", self.getName(), errtxt, errnum) + self.printed_error = True + if not errors_only: + self.pollend(retry=(errnum in (ERR_DISCONN, errno.ECONNRESET))) + # don't process result, because it will raise an error return - elif errnum in [errno.ENOTCONN, errno.ESHUTDOWN]: - self.pollend() - # don't proccess result, caus it will raise error + + if received is None: + if errnum != 0: + self.DEBUG(errtxt, 'error') + log.error("Connection to %s lost: %s [%d]", self.getName(), errtxt, errnum) + self.printed_error = True + if not errors_only and self.state >= 0: + self.pollend(retry=True) + return + received = '' + + if errors_only or self.state < 0: return - elif not received : - if errnum != socket.SSL_ERROR_EOF: - # 8 EOF occurred in violation of protocol - self.DEBUG('Socket error while receiving data', 'error') - self.pollend(True) - if self.state >= 0: - self.disconnect() - return - - if self.state < 0: - return - + # we have received some bites, stop the timeout! self.renew_send_timeout() if self.on_receive: @@ -281,9 +511,10 @@ class NonBlockingTcp(PlugIn, IdleObject): self._plug_idle() self._on_send() except socket.error, e: - sys.exc_clear() if e[0] == socket.SSL_ERROR_WANT_WRITE: return True + log.error("_do_send:", exc_info=True) + #traceback.print_exc() if self.state < 0: self.disconnect() return @@ -296,12 +527,16 @@ class NonBlockingTcp(PlugIn, IdleObject): if self.state != 0: return self._sock.setblocking(False) + self._send = self._sock.send + self._recv = self._sock.recv errnum = 0 try: self._sock.connect(self._server) except socket.error, e: errnum = e[0] - sys.exc_clear() + if errnum != errno.EINPROGRESS: + log.error("_do_connect:", exc_info=True) + #traceback.print_exc() # in progress, or would block if errnum in (errno.EINPROGRESS, errno.EALREADY, errno.EWOULDBLOCK): return @@ -317,8 +552,6 @@ class NonBlockingTcp(PlugIn, IdleObject): self.state = 1 self._sock.setblocking(False) - self._send = self._sock.send - self._recv = self._sock.recv self._plug_idle() if self.on_connect: self.on_connect() @@ -367,13 +600,28 @@ class NonBlockingTcp(PlugIn, IdleObject): def getHost(self): ''' Return the 'host' value that is connection is [will be] made to.''' return self._server[0] - + + def getName(self): + ''' Return the server's name, or 'getHost()' if not available.''' + retval = None + retval = gattr(self._owner, 'name') + if retval: return retval + return self.getHost() + def getPort(self): ''' Return the 'port' value that is connection is [will be] made to.''' return self._server[1] class NonBlockingTLS(PlugIn): ''' TLS connection used to encrypts already estabilished tcp connection.''' + + # from ssl.h (partial extract) + ssl_h_bits = { "SSL_ST_CONNECT": 0x1000, "SSL_ST_ACCEPT": 0x2000, + "SSL_CB_LOOP": 0x01, "SSL_CB_EXIT": 0x02, + "SSL_CB_READ": 0x04, "SSL_CB_WRITE": 0x08, + "SSL_CB_ALERT": 0x4000, + "SSL_CB_HANDSHAKE_START": 0x10, "SSL_CB_HANDSHAKE_DONE": 0x20} + def PlugIn(self, owner, now=0, on_tls_start = None): ''' If the 'now' argument is true then starts using encryption immidiatedly. If 'now' in false then starts encryption as soon as TLS feature is @@ -388,6 +636,8 @@ class NonBlockingTLS(PlugIn): try: res = self._startSSL() except Exception, e: + log.error("PlugIn: while trying _startSSL():", exc_info=True) + #traceback.print_exc() self._owner.socket.pollend() return self.tls_start() @@ -429,18 +679,126 @@ class NonBlockingTLS(PlugIn): self.tls_start() raise NodeProcessed + def _dumpX509(self, cert, stream=sys.stderr): + print >> stream, "Digest (SHA-1):", cert.digest("sha1") + print >> stream, "Digest (MD5):", cert.digest("md5") + print >> stream, "Serial #:", cert.get_serial_number() + print >> stream, "Version:", cert.get_version() + print >> stream, "Expired:", torf(cert.has_expired(), "Yes", "No") + print >> stream, "Subject:" + self._dumpX509Name(cert.get_subject(), stream) + print >> stream, "Issuer:" + self._dumpX509Name(cert.get_issuer(), stream) + self._dumpPKey(cert.get_pubkey(), stream) + + def _dumpX509Name(self, name, stream=sys.stderr): + print >> stream, "X509Name:", str(name) + + def _dumpPKey(self, pkey, stream=sys.stderr): + typedict = {OpenSSL.crypto.TYPE_RSA: "RSA", OpenSSL.crypto.TYPE_DSA: "DSA"} + print >> stream, "PKey bits:", pkey.bits() + print >> stream, "PKey type: %s (%d)" % (typedict.get(pkey.type(), "Unknown"), pkey.type()) + def _startSSL(self): ''' Immidiatedly switch socket to TLS mode. Used internally.''' + log.debug("_startSSL called") + if USE_PYOPENSSL: return self._startSSL_pyOpenSSL() + return self._startSSL_stdlib() + + def _startSSL_pyOpenSSL(self): + #log.debug("_startSSL_pyOpenSSL called, thread id: %s", str(thread.get_ident())) + log.debug("_startSSL_pyOpenSSL called") + tcpsock = self._owner.Connection + # FIXME: should method be configurable? + #tcpsock._sslContext = OpenSSL.SSL.Context(OpenSSL.SSL.TLSv1_METHOD) + tcpsock._sslContext = OpenSSL.SSL.Context(OpenSSL.SSL.SSLv23_METHOD) + tcpsock._sslContext.set_info_callback(self._ssl_info_callback) + tcpsock._sslObj = OpenSSL.SSL.Connection(tcpsock._sslContext, tcpsock._sock) + tcpsock._sslObj.set_connect_state() # set to client mode + + wrapper = PyOpenSSLWrapper(tcpsock._sslObj) + tcpsock._recv = wrapper.recv + tcpsock._send = wrapper.send + + log.debug("Initiating handshake...") + #tcpsock._sslObj.setblocking(True) + try: + self.starttls='in progress' + tcpsock._sslObj.do_handshake() + except (OpenSSL.SSL.WantReadError, OpenSSL.SSL.WantWriteError), e: + pass + #tcpsock._sslObj.setblocking(False) + #print "Done handshake" + log.debug("Async handshake started...") + + # fake it, for now + self.starttls='success' + + def _on_ssl_handshake_done(self): + log.debug("Handshake done!") + #self.starttls='success' + + tcpsock = self._owner.Connection + cert = tcpsock._sslObj.get_peer_certificate() + peer = cert.get_subject() + issuer = cert.get_issuer() + tcpsock._sslIssuer = unicode(issuer) + tcpsock._sslServer = unicode(peer) + + # FIXME: remove debug prints + peercert = tcpsock._sslObj.get_peer_certificate() + ciphers = tcpsock._sslObj.get_cipher_list() + + print >> sys.stderr, "Ciphers:", ciphers + print >> sys.stderr, "Peer cert:", peercert + self._dumpX509(peercert) + + print >> sys.stderr, OpenSSL.crypto.dump_certificate(OpenSSL.crypto.FILETYPE_PEM, peercert) + + def _startSSL_stdlib(self): + log.debug("_startSSL_stdlib called") tcpsock=self._owner.Connection tcpsock._sock.setblocking(True) tcpsock._sslObj = socket.ssl(tcpsock._sock, None, None) tcpsock._sock.setblocking(False) tcpsock._sslIssuer = tcpsock._sslObj.issuer() tcpsock._sslServer = tcpsock._sslObj.server() - tcpsock._recv = tcpsock._sslObj.read - tcpsock._send = tcpsock._sslObj.write + wrapper = StdlibSSLWrapper(tcpsock._sslObj, tcpsock._sock) + tcpsock._recv = wrapper.recv + tcpsock._send = wrapper.send self.starttls='success' + def _ssl_info_callback(self, sslconn, type, st): + # Exceptions can't propagate up through this callback, so print them here. + try: + self._ssl_info_callback_guarded(sslconn, type, st) + except: + log.error("Exception caught in _ssl_info_callback:", exc_info=True) + traceback.print_exc() # Make sure something is printed, even if log is disabled. + + def _ssl_info_callback_guarded(self, sslconn, type, st): + b = self.ssl_h_bits + + #if type & b['SSL_CB_LOOP']: + # if type & SSL_ST_CONNECT: tls_state = "connect" + # elif type & SSL_ST_ACCEPT: tls_state = "accept" + # else: tls_state = "undefined" + # print "tls_state: %s: %s" % (tls_state, sslconn.state_string()) + + #if type & b['SSL_CB_ALERT']: + # if type & SSL_CB_READ: rdwr = "read" + # elif type & SSL_CB_WRITE: rdwr = "write" + # else: rdwr = "unknown" + # print "tls_alert: %s:%d: %s" % (rdwr, st, sslconn.state_string()) + + #mask = "" + #for k, v in b.iteritems(): + # if type & v: mask += " " + k + #print "mask:", mask, st + + if type & b['SSL_CB_HANDSHAKE_DONE']: + self._on_ssl_handshake_done() + def StartTLSHandler(self, conn, starttls): ''' Handle server reply if TLS is allowed to process. Behaves accordingly. Used internally.''' @@ -454,6 +812,8 @@ class NonBlockingTLS(PlugIn): try: self._startSSL() except Exception, e: + log.error("StartTLSHandler:", exc_info=True) + #traceback.print_exc() self._owner.socket.pollend() return self._owner.Dispatcher.PlugOut() @@ -512,6 +872,8 @@ class NBHTTPPROXYsocket(NonBlockingTcp): try: proto, code, desc = reply.split('\n')[0].split(' ', 2) except: + log.error("_on_headers_sent:", exc_info=True) + #traceback.print_exc() raise error('Invalid proxy reply') if code <> '200': self.DEBUG('Invalid proxy reply: %s %s %s' % (proto, code, desc),'error') diff --git a/src/common/zeroconf/client_zeroconf.py b/src/common/zeroconf/client_zeroconf.py index 8614acbf4..bd0872126 100644 --- a/src/common/zeroconf/client_zeroconf.py +++ b/src/common/zeroconf/client_zeroconf.py @@ -376,7 +376,6 @@ class P2PConnection(IdleObject, PlugIn): except Exception, e: if len(e.args) > 0 and isinstance(e.args[0], int): errnum = e[0] - sys.exc_clear() # "received" will be empty anyhow if errnum == socket.SSL_ERROR_WANT_READ: pass @@ -456,7 +455,6 @@ class P2PConnection(IdleObject, PlugIn): self._on_send() except socket.error, e: - sys.exc_clear() if e[0] == socket.SSL_ERROR_WANT_WRITE: return True if self.state < 0: diff --git a/src/gajim-remote.py b/src/gajim-remote.py index 6673ad9eb..5aab4110f 100755 --- a/src/gajim-remote.py +++ b/src/gajim-remote.py @@ -27,7 +27,6 @@ from common import i18n try: PREFERRED_ENCODING = locale.getpreferredencoding() except: - sys.exc_clear() PREFERRED_ENCODING = 'UTF-8' def send_error(error_message):