Merge lp:~mwhudson/lava-scheduler/do-not-drop-monitor-output into lp:lava-scheduler

[Michael Hudson-Doyle]

I'm cautiously optimistic that this branch will help debugging bug 1043059.

[Andy Doan (doanac)]

this change would have helped me debug a similar type problem in the past, so I'm +1

review: Approve

=== modified file 'fake-dispatcher'
--- fake-dispatcher	2012-03-27 21:30:51 +0000
+++ fake-dispatcher	2012-08-30 04:00:24 +0000
@@ -11,15 +11,8 @@
 
 echo starting processing $1
 echo error >&2
-for i in `seq 100`; do
+for i in `seq 10`; do
 echo p $i
-cat $1
-echo
-done
-for i in `seq 300`; do
 sleep 1
-echo $i
-cat $1
-echo
 done
 echo dashboard-put-result: http://disney.com >&3

=== modified file 'lava_scheduler_daemon/board.py'
--- lava_scheduler_daemon/board.py	2012-07-10 22:45:19 +0000
+++ lava_scheduler_daemon/board.py	2012-08-30 04:00:24 +0000
@@ -5,7 +5,7 @@
 import tempfile
 import logging
 
-from twisted.internet.error import ProcessExitedAlready
+from twisted.internet.error import ProcessDone, ProcessExitedAlready
 from twisted.internet.protocol import ProcessProtocol
 from twisted.internet import defer, task
 from twisted.protocols.basic import LineReceiver
@@ -64,7 +64,13 @@
                 self.job.cancel("exceeded log size limit")
         self.log_file.flush()
 
+    def processExited(self, reason):
+        self.logger.info("processExited for %s: %s",
+            self.job.board_name, reason.value)
+
     def processEnded(self, reason):
+        self.logger.info("processEnded for %s: %s",
+            self.job.board_name, reason.value)
         self.log_file.close()
         self.deferred.callback(reason.value.exitCode)
 
@@ -170,10 +176,23 @@
             lambda r:exit_code)
 
 
-class SimplePP(ProcessProtocol):
-    def __init__(self, d):
+class SchedulerMonitorPP(ProcessProtocol):
+
+    def __init__(self, d, board_name):
         self.d = d
+        self.board_name = board_name
+        self.logger = logging.getLogger(__name__ + '.SchedulerMonitorPP')
+
+    def childDataReceived(self, childFD, data):
+        self.logger.warning(
+            "scheduler monitor for %s produced output: %r on fd %s",
+            self.board_name, data, childFD)
+
     def processEnded(self, reason):
+        if not reason.check(ProcessDone):
+            self.logger.error(
+                "scheduler monitor for %s crashed: %s",
+                self.board_name, reason)
         self.d.callback(None)
 
 
@@ -199,6 +218,7 @@
         with os.fdopen(fd, 'wb') as f:
             json.dump(json_data, f)
 
+        childFDs = {0:0, 1:1, 2:2}
         if self.use_celery:
             args = [
                 'setsid', 'lava', 'celery-schedulermonitor',
@@ -210,10 +230,11 @@
                 '-l', self.daemon_options['LOG_LEVEL']]
             if self.daemon_options['LOG_FILE_PATH']:
                 args.extend(['-f', self.daemon_options['LOG_FILE_PATH']])
+                childFDs = None
         self.logger.info('executing "%s"', ' '.join(args))
         self.reactor.spawnProcess(
-            SimplePP(d), 'setsid', childFDs={0:0, 1:1, 2:2},
-            env=None, args=args)
+            SchedulerMonitorPP(d, self.board_name), 'setsid',
+            childFDs=childFDs, env=None, args=args)
         d.addBoth(self._exited)
         return d