Merge 57388ae into 06d0821

docs/changelog.rst

@@ -20,6 +20,10 @@ Bug fix release.
 - Network: Close connection following an exception in the protocol handler.
   (Fixes: :issue:`1762`, PR: :issue:`1765`)
 
+- Network: Log client's connection details instead of server's. This fixed a
+  regression introduced as part of PR: :issue:`1629`. (Fixes: :issue:`1788`,
+  PR: :issue:`1792`)
+
 
 v2.2.3 (2019-06-20)
 ===================

mopidy/internal/network.py

@@ -24,6 +24,14 @@ def is_unix_socket(sock):
     return False
 
 
+def get_socket_address(host, port):
+    unix_socket_path = path.get_unix_socket_path(host)
+    if unix_socket_path is not None:
+        return (unix_socket_path, None)
+    else:
+        return (host, port)
+
+
 class ShouldRetrySocketCall(Exception):
 
     """Indicate that attempted socket call should be retried"""
@@ -70,12 +78,13 @@ def create_unix_socket():
     return socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
 
 
-def format_socket_name(sock):
-    """Format the connection string for the given socket"""
-    if is_unix_socket(sock):
-        return '%s' % sock.getsockname()
+def format_address(address):
+    """Format socket address for display."""
+    host, port = address[:2]
+    if port is not None:
+        return '[%s]:%s' % (host, port)
     else:
-        return '[%s]:%s' % sock.getsockname()[:2]
+        return '[%s]' % host
 
 
 def format_hostname(hostname):
@@ -96,6 +105,7 @@ def __init__(self, host, port, protocol, protocol_kwargs=None,
         self.max_connections = max_connections
         self.timeout = timeout
         self.server_socket = self.create_server_socket(host, port)
+        self.address = get_socket_address(host, port)
 
         self.watcher = self.register_server_socket(self.server_socket.fileno())
 
@@ -166,9 +176,7 @@ def number_of_connections(self):
 
     def reject_connection(self, sock, addr):
         # FIXME provide more context in logging?
-        logger.warning(
-            'Rejected connection from %s',
-            format_socket_name(sock))
+        logger.warning('Rejected connection from %s', format_address(addr))
         try:
             sock.close()
         except socket.error:
@@ -356,7 +364,7 @@ def timeout_callback(self):
         return False
 
     def __str__(self):
-        return format_socket_name(self._sock)
+        return format_address((self.host, self.port))
 
 
 class LineProtocol(pykka.ThreadingActor):

mopidy/mpd/actor.py

@@ -61,8 +61,7 @@ def _setup_server(self, config, core):
                 encoding.locale_decode(error))
 
         logger.info(
-            'MPD server running at %s',
-            network.format_socket_name(server.server_socket))
+            'MPD server running at %s', network.format_address(server.address))
 
         return server
 

mopidy/mpd/session.py

@@ -29,14 +29,14 @@ def on_start(self):
         self.send_lines(['OK MPD %s' % protocol.VERSION])
 
     def on_line_received(self, line):
-        logger.debug('Request from [%s]: %s', self.connection, line)
+        logger.debug('Request from %s: %s', self.connection, line)
 
         response = self.dispatcher.handle_request(line)
         if not response:
             return
 
         logger.debug(
-            'Response to [%s]: %s',
+            'Response to %s: %s',
             self.connection,
             formatting.indent(self.terminator.join(response)))
 

tests/internal/network/test_connection.py

@@ -557,3 +557,15 @@ def test_timeout_callback(self):
 
         self.assertFalse(network.Connection.timeout_callback(self.mock))
         self.mock.stop.assert_called_once_with(any_unicode)
+
+    def test_str(self):
+        self.mock.host = 'foo'
+        self.mock.port = 999
+
+        self.assertEqual('[foo]:999', network.Connection.__str__(self.mock))
+
+    def test_str_without_port(self):
+        self.mock.host = 'foo'
+        self.mock.port = None
+
+        self.assertEqual('[foo]', network.Connection.__str__(self.mock))

tests/internal/network/test_server.py

@@ -19,13 +19,24 @@ class ServerTest(unittest.TestCase):
     def setUp(self):  # noqa: N802
         self.mock = Mock(spec=network.Server)
 
+    @patch.object(network, 'get_socket_address', new=Mock())
     def test_init_calls_create_server_socket(self):
         network.Server.__init__(
             self.mock, sentinel.host, sentinel.port, sentinel.protocol)
         self.mock.create_server_socket.assert_called_once_with(
             sentinel.host, sentinel.port)
         self.mock.stop()
 
+    @patch.object(network, 'get_socket_address', new=Mock())
+    def test_init_calls_get_socket_address(self):
+        network.Server.__init__(
+            self.mock, sentinel.host, sentinel.port, sentinel.protocol)
+        self.mock.create_server_socket.return_value = None
+        network.get_socket_address.assert_called_once_with(
+            sentinel.host, sentinel.port)
+        self.mock.stop()
+
+    @patch.object(network, 'get_socket_address', new=Mock())
     def test_init_calls_register_server(self):
         sock = Mock(spec=socket.SocketType)
         sock.fileno.return_value = sentinel.fileno
@@ -36,6 +47,7 @@ def test_init_calls_register_server(self):
         self.mock.register_server_socket.assert_called_once_with(
             sentinel.fileno)
 
+    @patch.object(network, 'get_socket_address', new=Mock())
     def test_init_fails_on_fileno_call(self):
         sock = Mock(spec=socket.SocketType)
         sock.fileno.side_effect = socket.error
@@ -51,12 +63,14 @@ def test_init_stores_values_in_attributes(self):
         self.mock.create_server_socket.return_value = sock
 
         network.Server.__init__(
-            self.mock, sentinel.host, sentinel.port, sentinel.protocol,
+            self.mock, str(sentinel.host), sentinel.port, sentinel.protocol,
             max_connections=sentinel.max_connections, timeout=sentinel.timeout)
         self.assertEqual(sentinel.protocol, self.mock.protocol)
         self.assertEqual(sentinel.max_connections, self.mock.max_connections)
         self.assertEqual(sentinel.timeout, self.mock.timeout)
         self.assertEqual(sock, self.mock.server_socket)
+        self.assertEqual(
+            (str(sentinel.host), sentinel.port), self.mock.address)
 
     def test_create_server_socket_no_port(self):
         with self.assertRaises(exceptions.ValidationError):
@@ -257,15 +271,26 @@ def test_init_connection(self):
             sentinel.protocol, {}, sentinel.sock, sentinel.addr,
             sentinel.timeout)
 
-    @patch.object(network, 'format_socket_name', new=Mock())
     def test_reject_connection(self):
         sock = Mock(spec=socket.SocketType)
 
         network.Server.reject_connection(
             self.mock, sock, (sentinel.host, sentinel.port))
         sock.close.assert_called_once_with()
 
-    @patch.object(network, 'format_socket_name', new=Mock())
+    @patch.object(network, 'format_address', new=Mock())
+    @patch.object(network.logger, 'warning', new=Mock())
+    def test_reject_connection_message(self):
+        sock = Mock(spec=socket.SocketType)
+        network.format_address.return_value = sentinel.formatted
+
+        network.Server.reject_connection(
+            self.mock, sock, (sentinel.host, sentinel.port))
+        network.format_address.assert_called_once_with(
+            (sentinel.host, sentinel.port))
+        network.logger.warning.assert_called_once_with(
+            'Rejected connection from %s', sentinel.formatted)
+
     def test_reject_connection_error(self):
         sock = Mock(spec=socket.SocketType)
         sock.close.side_effect = socket.error

tests/internal/network/test_utils.py

@@ -22,23 +22,40 @@ def test_format_hostname_does_nothing_when_only_ipv4_available(self):
         self.assertEqual(network.format_hostname('0.0.0.0'), '0.0.0.0')
 
 
-class FormatSocketConnectionTest(unittest.TestCase):
+class FormatAddressTest(unittest.TestCase):
 
-    def test_format_socket_name(self):
-        sock = Mock(spec=socket.SocketType)
-        sock.family = socket.AF_INET
-        sock.getsockname.return_value = (sentinel.ip, sentinel.port)
+    def test_format_address_ipv4(self):
+        address = (sentinel.host, sentinel.port)
         self.assertEqual(
-            network.format_socket_name(sock),
-            '[%s]:%s' % (sentinel.ip, sentinel.port))
+            network.format_address(address),
+            '[%s]:%s' % (sentinel.host, sentinel.port))
 
-    def test_format_socket_name_unix(self):
-        sock = Mock(spec=socket.SocketType)
-        sock.family = socket.AF_UNIX
-        sock.getsockname.return_value = sentinel.sockname
+    def test_format_address_ipv6(self):
+        address = (sentinel.host, sentinel.port, sentinel.flow, sentinel.scope)
         self.assertEqual(
-            network.format_socket_name(sock),
-            str(sentinel.sockname))
+            network.format_address(address),
+            '[%s]:%s' % (sentinel.host, sentinel.port))
+
+    def test_format_address_unix(self):
+        address = (sentinel.path, None)
+        self.assertEqual(
+            network.format_address(address),
+            '[%s]' % (sentinel.path))
+
+
+class GetSocketAddress(unittest.TestCase):
+
+    def test_get_socket_address(self):
+        host = str(sentinel.host)
+        port = sentinel.port
+        self.assertEqual(
+            network.get_socket_address(host, port), (host, port))
+
+    def test_get_socket_address_unix(self):
+        host = str(sentinel.host)
+        port = sentinel.port
+        self.assertEqual(
+            network.get_socket_address('unix:' + host, port), (host, None))
 
 
 class TryIPv6SocketTest(unittest.TestCase):

tests/mpd/test_session.py

@@ -0,0 +1,30 @@
+from __future__ import unicode_literals
+
+import logging
+
+from mock import Mock, sentinel
+
+from mopidy.internal import network
+from mopidy.mpd import dispatcher, session
+
+
+def test_on_start_logged(caplog):
+    caplog.set_level(logging.INFO)
+    connection = Mock(spec=network.Connection)
+
+    session.MpdSession(connection).on_start()
+
+    assert 'New MPD connection from %s' % connection in caplog.text
+
+
+def test_on_line_received_logged(caplog):
+    caplog.set_level(logging.DEBUG)
+    connection = Mock(spec=network.Connection)
+    mpd_session = session.MpdSession(connection)
+    mpd_session.dispatcher = Mock(spec=dispatcher.MpdDispatcher)
+    mpd_session.dispatcher.handle_request.return_value = ['foo']
+
+    mpd_session.on_line_received(sentinel.line)
+
+    assert 'Request from %s: %s' % (connection, sentinel.line) in caplog.text
+    assert 'Response to %s: %s\n' % (connection, 'foo') in caplog.text