diff --git a/mopidy/utils/network.py b/mopidy/utils/network.py index c56690a3..26565577 100644 --- a/mopidy/utils/network.py +++ b/mopidy/utils/network.py @@ -10,6 +10,7 @@ from pykka.registry import ActorRegistry from mopidy.utils.log import indent +# FIXME setup logger with extra={...} logger = logging.getLogger('mopidy.utils.server') class ShouldRetrySocketCall(Exception): @@ -134,11 +135,14 @@ class Connection(object): self.enable_recv() self.enable_timeout() - def stop(self): + def stop(self, reason, level=logging.DEBUG): + logger.log(level, reason) + self.actor_ref.stop() self.disable_timeout() self.disable_recv() self.disable_send() + try: self.sock.close() except socket.error: @@ -188,18 +192,18 @@ class Connection(object): def recv_callback(self, fd, flags): if flags & (gobject.IO_ERR | gobject.IO_HUP): - self.stop() + self.stop(u'Bad client flags: %s' % flags) return True try: data = self.sock.recv(4096) except socket.error as e: if e.errno not in (errno.EWOULDBLOCK, errno.EINTR): - self.stop() + self.stop(u'Unexpected client error: %s' % e) return True if not data: - self.stop() + self.stop(u'Client most likely disconnected.') else: self.actor_ref.send_one_way({'received': data}) return True @@ -217,16 +221,14 @@ class Connection(object): self.disable_send() except socket.error as e: if e.errno not in (errno.EWOULDBLOCK, errno.EINTR): - #self.log_error(e) # FIXME log error - self.stop() + self.stop(u'Unexpected client error: %s' % e) finally: self.send_lock.release() return True def timeout_callback(self): - #self.log_timeout() # FIXME log this - return self.stop() + return self.stop(u'Client timeout out after %s seconds' % self.timeout) class LineProtocol(ThreadingActor): diff --git a/tests/utils/network_test.py b/tests/utils/network_test.py index f280c0d3..e4dcec70 100644 --- a/tests/utils/network_test.py +++ b/tests/utils/network_test.py @@ -2,6 +2,7 @@ import errno import gobject import socket import unittest +import logging from mock import patch, sentinel, Mock from mopidy.utils import network @@ -244,7 +245,7 @@ class ConnectionTest(unittest.TestCase): self.mock.actor_ref = Mock() self.mock.sock = Mock(spec=socket.SocketType) - network.Connection.stop(self.mock) + network.Connection.stop(self.mock, sentinel.reason) self.mock.disable_timeout.assert_called_once_with() self.mock.disable_recv.assert_called_once_with() self.mock.disable_timeout.assert_called_once_with() @@ -253,7 +254,7 @@ class ConnectionTest(unittest.TestCase): self.mock.actor_ref = Mock() self.mock.sock = Mock(spec=socket.SocketType) - network.Connection.stop(self.mock) + network.Connection.stop(self.mock, sentinel.reason) self.mock.sock.close.assert_called_once_with() def test_stop_closes_socket_error(self): @@ -261,16 +262,35 @@ class ConnectionTest(unittest.TestCase): self.mock.sock = Mock(spec=socket.SocketType) self.mock.sock.close.side_effect = socket.error() - network.Connection.stop(self.mock) + network.Connection.stop(self.mock, sentinel.reason) self.mock.sock.close.assert_called_once_with() def test_stop_stops_actor(self): self.mock.actor_ref = Mock() self.mock.sock = Mock(spec=socket.SocketType) - network.Connection.stop(self.mock) + network.Connection.stop(self.mock, sentinel.reason) self.mock.actor_ref.stop.assert_called_once_with() + @patch.object(network.logger, 'log', new=Mock()) + def test_stop_logs_reason(self): + self.mock.actor_ref = Mock() + self.mock.sock = Mock(spec=socket.SocketType) + + network.Connection.stop(self.mock, sentinel.reason) + network.logger.log.assert_called_once_with( + logging.DEBUG, sentinel.reason) + + @patch.object(network.logger, 'log', new=Mock()) + def test_stop_logs_reason_with_level(self): + self.mock.actor_ref = Mock() + self.mock.sock = Mock(spec=socket.SocketType) + + network.Connection.stop(self.mock, sentinel.reason, + level=sentinel.level) + network.logger.log.assert_called_once_with( + sentinel.level, sentinel.reason) + @patch.object(gobject, 'io_add_watch', new=Mock()) def test_enable_recv_registers_with_gobject(self): self.mock.recv_id = None @@ -421,17 +441,17 @@ class ConnectionTest(unittest.TestCase): def test_recv_callback_respects_io_err(self): self.assertTrue(network.Connection.recv_callback(self.mock, sentinel.fd, gobject.IO_IN | gobject.IO_ERR)) - self.mock.stop.assert_called_once_with() + self.assertEqual(1, self.mock.stop.call_count) def test_recv_callback_respects_io_hup(self): self.assertTrue(network.Connection.recv_callback(self.mock, sentinel.fd, gobject.IO_IN | gobject.IO_HUP)) - self.mock.stop.assert_called_once_with() + self.assertEqual(1, self.mock.stop.call_count) def test_recv_callback_respects_io_hup_and_io_err(self): self.assertTrue(network.Connection.recv_callback(self.mock, sentinel.fd, gobject.IO_IN | gobject.IO_HUP | gobject.IO_ERR)) - self.mock.stop.assert_called_once_with() + self.assertEqual(1, self.mock.stop.call_count) def test_recv_callback_gets_data(self): self.mock.sock = Mock(spec=socket.SocketType) @@ -449,7 +469,7 @@ class ConnectionTest(unittest.TestCase): self.assertTrue(network.Connection.recv_callback( self.mock, sentinel.fd, gobject.IO_IN)) - self.mock.stop.assert_called_once_with() + self.assertEqual(1, self.mock.stop.call_count) def test_recv_callback_recoverable_error(self): self.mock.sock = Mock(spec=socket.SocketType) @@ -465,7 +485,7 @@ class ConnectionTest(unittest.TestCase): self.assertTrue(network.Connection.recv_callback( self.mock, sentinel.fd, gobject.IO_IN)) - self.mock.stop.assert_called_once_with() + self.assertEqual(1, self.mock.stop.call_count) @SkipTest def test_send_callback_respects_flags(self): @@ -537,8 +557,10 @@ class ConnectionTest(unittest.TestCase): self.mock.sock.send.side_effect = socket.error() self.assertTrue(network.Connection.send_callback( self.mock, sentinel.fd, gobject.IO_IN)) - self.mock.stop.assert_called_once_with() + self.assertEqual(1, self.mock.stop.call_count) def test_timeout_callback(self): + self.mock.timeout = 10 + network.Connection.timeout_callback(self.mock) - self.mock.stop.assert_called_once_with() + self.assertEqual(1, self.mock.stop.call_count)