Include the process PID in the log lines

This will help debugging the crazy double-Blender-running we're seeing
in the studio.

CHANGELOG.md

@@ -24,6 +24,7 @@ changed functionality, fixed bugs).
   status `error` and sleep for 10 minutes before trying again.
 - Subprocess commands now write the spawned process PID in a text file, and refuse to run if there
   already is such a file with an alive PID.
+- Log lines produced by subprocesses are now prefixed with 'PID=nnn'.
 
 
 ## Version 2.1.0 (2018-01-04)

flamenco_worker/commands.py

@@ -517,7 +517,7 @@ class AbstractSubprocessCommand(AbstractCommand):
     async def process_line(self, line: str) -> typing.Optional[str]:
         """Processes the line, returning None to ignore it."""
 
-        return '> %s' % line
+        return 'PID=%d > %s' % (self.proc.pid, line)
 
     async def abort(self):
         """Aborts the command by killing the subprocess."""

tests/test_runner.py

@@ -86,14 +86,15 @@ class ExecCommandTest(AbstractCommandTest):
             0.6
         ))
         self.assertTrue(ok)
+        pid = cmd.proc.pid
 
         # Check that both lines have been reported.
         self.fworker.register_log.assert_has_calls([
             call('exec: Starting'),
             call('Executing %s',
                  '%s -c \'print("hello, this is two lines\\nYes, really.")\'' % sys.executable),
-            call('> hello, this is two lines'),  # note the logged line doesn't end in a newline
-            call('> Yes, really.'),  # note the logged line doesn't end in a newline
+            call('PID=%d > hello, this is two lines' % pid),
+            call('PID=%d > Yes, really.' % pid),  # note the logged line doesn't end in a newline
             call('exec: Finished'),
         ])
 
@@ -151,13 +152,14 @@ class ExecCommandTest(AbstractCommandTest):
             0.6
         ))
         self.assertFalse(ok)
+        pid = cmd.proc.pid
 
         # Check that the execution error has been reported.
         self.fworker.register_log.assert_has_calls([
             call('exec: Starting'),
             call('Executing %s',
                  '%s -c \'raise SystemExit("¡FAIL!")\'' % sys.executable),
-            call('> ¡FAIL!'),  # note the logged line doesn't end in a newline
+            call('PID=%d > ¡FAIL!' % pid),  # note the logged line doesn't end in a newline
             call('exec.(task_id=12345, command_idx=0): Error executing: '
                  'Command failed with status 1')
         ])