Merge branch 'sam/distbuild-logging-improvements'

Reviewed-By: Richard Ipsum <richard.ipsum@codethink.co.uk>
Reviewed-By: Lars Wirzenius <lars.wirzenius@codethink.co.uk>

13 files changed, 125 insertions, 47 deletions

diff --git a/distbuild-helper b/distbuild-helper
index 7399fb59..08e30f10 100755
--- a/distbuild-helper
+++ b/distbuild-helper
@@ -309,7 +309,7 @@ class DistributedBuildHelper(cliapp.Application):
 
         addr = self.settings['parent-address']
         port = self.settings['parent-port']
-        conn = socket.socket()
+        conn = distbuild.create_socket()
         conn.connect((addr, port))
         helper = HelperMachine(conn)
         helper.debug_messages = self.settings['debug-messages']
diff --git a/distbuild/__init__.py b/distbuild/__init__.py
index 3e60d5ee..57aaccaf 100644
--- a/distbuild/__init__.py
+++ b/distbuild/__init__.py
@@ -58,4 +58,6 @@ from protocol import message
 from crashpoint import (crash_point, add_crash_condition, add_crash_conditions,
                         clear_crash_conditions)
 
+from distbuild_socket import create_socket
+
 __all__ = locals()
diff --git a/distbuild/build_controller.py b/distbuild/build_controller.py
index b00344f9..ce8fced5 100644
--- a/distbuild/build_controller.py
+++ b/distbuild/build_controller.py
@@ -158,7 +158,11 @@ class BuildController(distbuild.StateMachine):
         self._artifact_cache_server = artifact_cache_server
         self._morph_instance = morph_instance
         self._helper_id = None
-        self.debug_transitions = True
+        self.debug_transitions = False
+
+    def __repr__(self):
+        return '<BuildController at 0x%x, request-id %s>' % (id(self),
+                self._request['id'])
 
     def setup(self):
         distbuild.crash_point()
diff --git a/distbuild/connection_machine.py b/distbuild/connection_machine.py
index 3d4e8d04..2f768f0b 100644
--- a/distbuild/connection_machine.py
+++ b/distbuild/connection_machine.py
@@ -97,7 +97,7 @@ class ConnectionMachine(distbuild.StateMachine):
         logging.debug(
             'ConnectionMachine: connecting to %s:%s' % 
                 (self._addr, self._port))
-        self._socket = socket.socket()
+        self._socket = distbuild.create_socket()
         distbuild.set_nonblocking(self._socket)
         try:
             self._socket.connect((self._addr, self._port))
diff --git a/distbuild/distbuild_socket.py b/distbuild/distbuild_socket.py
new file mode 100644
index 00000000..0408a2c1
--- /dev/null
+++ b/distbuild/distbuild_socket.py
@@ -0,0 +1,63 @@
+# distbuild/distbuild_socket.py -- wrapper around Python 'socket' module.
+#
+# Copyright (C) 2014  Codethink Limited
+#
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; version 2 of the License.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License along
+# with this program; if not, write to the Free Software Foundation, Inc.,
+# 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA..
+
+
+import socket
+
+
+class DistbuildSocket(object):
+    '''Wraps socket.SocketType with a few helper functions.'''
+
+    def __init__(self, real_socket):
+        self.real_socket = real_socket
+
+    def __getattr__(self, name):
+        return getattr(self.real_socket, name)
+
+    def __repr__(self):
+        return '<DistbuildSocket at 0x%x: %s>' % (id(self), str(self))
+
+    def __str__(self):
+        localname = self.localname() or '(closed)'
+        remotename = self.remotename()
+        if remotename is None:
+            return '%s' % self.localname()
+        else:
+            return '%s -> %s' % (self.localname(), remotename)
+
+    def accept(self, *args):
+        result = self.real_socket.accept(*args)
+        return DistbuildSocket(result[0]), result[1:]
+
+    def localname(self):
+        '''Get local end of socket connection as a string.'''
+        try:
+            return '%s:%s' % self.getsockname()
+        except socket.error:
+            # If the socket is in destruction we may get EBADF here.
+            return None
+
+    def remotename(self):
+        '''Get remote end of socket connection as a string.'''
+        try:
+            return '%s:%s' % self.getpeername()
+        except socket.error:
+            return None
+
+
+def create_socket(*args):
+    return DistbuildSocket(socket.socket(*args))
diff --git a/distbuild/initiator.py b/distbuild/initiator.py
index e4d4975f..069578d2 100644
--- a/distbuild/initiator.py
+++ b/distbuild/initiator.py
@@ -48,7 +48,7 @@ class Initiator(distbuild.StateMachine):
         self._morphology = morphology
         self._steps = None
         self._step_outputs = {}
-        self.debug_transitions = True
+        self.debug_transitions = False
 
     def setup(self):
         distbuild.crash_point()
diff --git a/distbuild/initiator_connection.py b/distbuild/initiator_connection.py
index 48d083e4..d48d4698 100644
--- a/distbuild/initiator_connection.py
+++ b/distbuild/initiator_connection.py
@@ -51,6 +51,11 @@ class InitiatorConnection(distbuild.StateMachine):
         self.conn = conn
         self.artifact_cache_server = artifact_cache_server
         self.morph_instance = morph_instance
+        self.initiator_name = conn.remotename()
+
+    def __repr__(self):
+        return '<InitiatorConnection at 0x%x: remote %s>' % (id(self),
+                self.initiator_name)
 
     def setup(self):
         self.jm = distbuild.JsonMachine(self.conn)
@@ -84,10 +89,10 @@ class InitiatorConnection(distbuild.StateMachine):
         
     def _handle_msg(self, event_source, event):
         '''Handle message from initiator.'''
-        
-        logging.debug(
-            'InitiatorConnection: from initiator: %s', repr(event.msg))
-            
+
+        logging.debug('InitiatorConnection: from %s: %r', self.initiator_name,
+                event.msg)
+
         if event.msg['type'] == 'build-request':
             new_id = self._idgen.next()
             self.our_ids.add(new_id)
@@ -99,16 +104,16 @@ class InitiatorConnection(distbuild.StateMachine):
 
     def _disconnect(self, event_source, event):
         for id in self.our_ids:
-            logging.debug('InitiatorConnection: InitiatorDisconnect(%s)'
-                          % str(id))
+            logging.debug('InitiatorConnection: %s: InitiatorDisconnect(%s)',
+                    self.initiator_name, str(id))
             self.mainloop.queue_event(InitiatorConnection,
                                       InitiatorDisconnect(id))
         # TODO should this clear our_ids?
         self.mainloop.queue_event(self, _Close(event_source))
 
     def _close(self, event_source, event):
-        logging.debug('InitiatorConnection: closing: %s',
-                      repr(event.event_source))
+        logging.debug('InitiatorConnection: %s: closing: %s',
+                      self.initiator_name, repr(event.event_source))
 
         event.event_source.close()
 
@@ -120,6 +125,10 @@ class InitiatorConnection(distbuild.StateMachine):
                 'InitiatorConnection: received result: %s', repr(event.msg))
             self.jm.send(event.msg)
 
+    def _log_send(self, msg):
+        logging.debug(
+            'InitiatorConnection: sent to %s: %r', self.initiator_name, msg)
+
     def _send_build_finished_message(self, event_source, event):
         if event.id in self.our_ids:
             msg = distbuild.message('build-finished',
@@ -128,8 +137,7 @@ class InitiatorConnection(distbuild.StateMachine):
             self._route_map.remove(event.id)
             self.our_ids.remove(event.id)
             self.jm.send(msg)
-            logging.debug(
-                'InitiatorConnection: sent to initiator: %s', repr(msg))
+            self._log_send(msg)
 
     def _send_build_failed_message(self, event_source, event):
         if event.id in self.our_ids:
@@ -139,8 +147,7 @@ class InitiatorConnection(distbuild.StateMachine):
             self._route_map.remove(event.id)
             self.our_ids.remove(event.id)
             self.jm.send(msg)
-            logging.debug(
-                'InitiatorConnection: sent to initiator: %s', repr(msg))
+            self._log_send(msg)
 
     def _send_build_progress_message(self, event_source, event):
         if event.id in self.our_ids:
@@ -148,8 +155,7 @@ class InitiatorConnection(distbuild.StateMachine):
                 id=self._route_map.get_incoming_id(event.id),
                 message=event.message_text)
             self.jm.send(msg)
-            logging.debug(
-                'InitiatorConnection: sent to initiator: %s', repr(msg))
+            self._log_send(msg)
 
     def _send_build_steps_message(self, event_source, event):
     
@@ -169,8 +175,7 @@ class InitiatorConnection(distbuild.StateMachine):
                 id=self._route_map.get_incoming_id(event.id),
                 steps=step_names)
             self.jm.send(msg)
-            logging.debug(
-                'InitiatorConnection: sent to initiator: %s', repr(msg))
+            self._log_send(msg)
 
     def _send_build_step_started_message(self, event_source, event):
         if event.id in self.our_ids:
@@ -179,8 +184,7 @@ class InitiatorConnection(distbuild.StateMachine):
                 step_name=event.step_name,
                 worker_name=event.worker_name)
             self.jm.send(msg)
-            logging.debug(
-                'InitiatorConnection: sent to initiator: %s', repr(msg))
+            self._log_send(msg)
 
     def _send_build_output_message(self, event_source, event):
         logging.debug('InitiatorConnection: build_output: '
@@ -193,8 +197,7 @@ class InitiatorConnection(distbuild.StateMachine):
                 stdout=event.stdout,
                 stderr=event.stderr)
             self.jm.send(msg)
-            logging.debug(
-                'InitiatorConnection: sent to initiator: %s', repr(msg))
+            self._log_send(msg)
 
     def _send_build_step_finished_message(self, event_source, event):
         if event.id in self.our_ids:
@@ -202,8 +205,7 @@ class InitiatorConnection(distbuild.StateMachine):
                 id=self._route_map.get_incoming_id(event.id),
                 step_name=event.step_name)
             self.jm.send(msg)
-            logging.debug(
-                'InitiatorConnection: sent to initiator: %s', repr(msg))
+            self._log_send(msg)
 
     def _send_build_step_failed_message(self, event_source, event):
         if event.id in self.our_ids:
@@ -211,6 +213,5 @@ class InitiatorConnection(distbuild.StateMachine):
                 id=self._route_map.get_incoming_id(event.id),
                 step_name=event.step_name)
             self.jm.send(msg)
-            logging.debug(
-                'InitiatorConnection: sent to initiator: %s', repr(msg))
+            self._log_send(msg)
 
diff --git a/distbuild/jm.py b/distbuild/jm.py
index ae222c00..bb86adc4 100644
--- a/distbuild/jm.py
+++ b/distbuild/jm.py
@@ -43,7 +43,11 @@ class JsonMachine(StateMachine):
         StateMachine.__init__(self, 'rw')
         self.conn = conn
         self.debug_json = False
-        
+
+    def __repr__(self):
+	    return '<JsonMachine at 0x%x: socket %s, max_buffer %s>' % (id(self),
+		    self.conn, self.max_buffer)
+
     def setup(self):
         sockbuf = self.sockbuf = SocketBuffer(self.conn, self.max_buffer)
         self.mainloop.add_state_machine(sockbuf)
diff --git a/distbuild/serialise.py b/distbuild/serialise.py
index cd871042..44d96eee 100644
--- a/distbuild/serialise.py
+++ b/distbuild/serialise.py
@@ -75,9 +75,6 @@ def serialise_artifact(artifact):
         else:
             arch = artifact.arch
 
-        logging.debug('encode_single_artifact dependencies: %s'
-            % str([('id: %s' % str(id(d)), d.name) for d in a.dependencies]))
-
         return {
             'source_id': source_id,
             'name': a.name,
@@ -104,13 +101,10 @@ def serialise_artifact(artifact):
     encoded_sources = {}
 
     for a in traverse(artifact):
-        logging.debug('traversing artifacts at %s' % a.name)
-
         if id(a.source) not in encoded_sources:
             if a.source.morphology['kind'] == 'chunk':
                 for (_, sa) in a.source.artifacts.iteritems():
                     if id(sa) not in artifacts:
-                        logging.debug('encoding source artifact %s' % sa.name)
                         artifacts[id(sa)] = sa
                         encoded_artifacts[id(sa)] = encode_single_artifact(sa,
                             artifacts, id(a.source))
@@ -130,7 +124,6 @@ def serialise_artifact(artifact):
 
         if id(a) not in artifacts:
             artifacts[id(a)] = a
-            logging.debug('encoding artifact %s' % a.name)
             encoded_artifacts[id(a)] = encode_single_artifact(a, artifacts,
                 id(a.source))
 
diff --git a/distbuild/sockbuf.py b/distbuild/sockbuf.py
index a7fe339a..6803bfb5 100644
--- a/distbuild/sockbuf.py
+++ b/distbuild/sockbuf.py
@@ -77,6 +77,10 @@ class SocketBuffer(StateMachine):
         self._sock = sock
         self._max_buffer = max_buffer
 
+    def __repr__(self):
+        return '<SocketBuffer at 0x%x: socket %s max_buffer %i>' % (
+                id(self), self._sock, self._max_buffer)
+
     def setup(self):        
         src = self._src = SocketEventSource(self._sock)
         src.stop_writing() # We'll start writing when we need to.
diff --git a/distbuild/socketsrc.py b/distbuild/socketsrc.py
index 78486f0e..14adc74d 100644
--- a/distbuild/socketsrc.py
+++ b/distbuild/socketsrc.py
@@ -9,6 +9,8 @@ import logging
 import os
 import socket
 
+import distbuild
+
 from eventsrc import EventSource
 
 
@@ -48,13 +50,13 @@ class ListeningSocketEventSource(EventSource):
     '''An event source for a socket that listens for connections.'''
 
     def __init__(self, addr, port):
-        self.sock = socket.socket()
+        self.sock = distbuild.create_socket()
         self.sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
         self.sock.bind((addr, port))
         self.sock.listen(5)
         self._accepting = True
-        logging.info('Listening at %s' % repr(self.sock.getsockname()))
-        
+        logging.info('Listening at %s' % self.sock.remotename())
+
     def get_select_params(self):
         r = [self.sock.fileno()] if self._accepting else []
         return r, [], [], None
@@ -117,7 +119,10 @@ class SocketEventSource(EventSource):
         self._writing = True
 
         set_nonblocking(sock)
-        
+
+    def __repr__(self):
+        return '<SocketEventSource at %x: socket %s>' % (id(self), self.sock)
+
     def get_select_params(self):
         r = [self.sock.fileno()] if self._reading else []
         w = [self.sock.fileno()] if self._writing else []
diff --git a/distbuild/sockserv.py b/distbuild/sockserv.py
index 6d8f216e..dc313d06 100644
--- a/distbuild/sockserv.py
+++ b/distbuild/sockserv.py
@@ -34,7 +34,7 @@ class ListenServer(StateMachine):
     def new_conn(self, event_source, event):
         logging.debug(
             'ListenServer: Creating new %s using %s and %s' %
-                (repr(self._machine),
+                (self._machine,
                  repr(event.connection),
                  repr(self._extra_args)))
         m = self._machine(event.connection, *self._extra_args)
diff --git a/distbuild/worker_build_scheduler.py b/distbuild/worker_build_scheduler.py
index 315d3094..5ec7c9aa 100644
--- a/distbuild/worker_build_scheduler.py
+++ b/distbuild/worker_build_scheduler.py
@@ -193,11 +193,13 @@ class WorkerConnection(distbuild.StateMachine):
         self._worker_cache_server_port = worker_cache_server_port
         self._morph_instance = morph_instance
         self._helper_id = None
-        
-    def name(self):
+
         addr, port = self._conn.getpeername()
         name = socket.getfqdn(addr)
-        return '%s:%s' % (name, port)
+        self._worker_name = '%s:%s' % (name, port)
+
+    def name(self):
+        return self._worker_name
 
     def setup(self):
         distbuild.crash_point()
@@ -231,7 +233,7 @@ class WorkerConnection(distbuild.StateMachine):
         self._request_job(None, None)
 
     def _maybe_cancel(self, event_source, build_cancel):
-        logging.debug('WC: BuildController requested a cancel')
+        logging.debug('WC: BuildController %r requested a cancel' % event_source)
         if build_cancel.id == self._initiator_id:
             distbuild.crash_point()
 
@@ -265,7 +267,7 @@ class WorkerConnection(distbuild.StateMachine):
             stdin_contents=distbuild.serialise_artifact(self._artifact),
         )
         self._jm.send(msg)
-        logging.debug('WC: sent to worker: %s' % repr(msg))
+        logging.debug('WC: sent to worker %s: %r' % (self._worker_name, msg))
         self._route_map.add(self._initiator_id, msg['id'])
         self._initiator_request_map[self._initiator_id].add(msg['id'])
         logging.debug(
@@ -281,7 +283,7 @@ class WorkerConnection(distbuild.StateMachine):
 
         distbuild.crash_point()
 
-        logging.debug('WC: from worker: %s' % repr(event.msg))
+        logging.debug('WC: from worker %s: %r' % (self._worker_name, event.msg))
 
         handlers = {
             'exec-output': self._handle_exec_output,