should work

flash_air_music/convert/discover.py

@@ -15,7 +15,8 @@ class Song(object):
 
     :ivar str source: Source file path (usually FLAC file).
     :ivar str target: Target file path (mp3 file).
-    :ivar dict stored_metadata: Previously recorded metadata of source and target files stored in target file ID3 tag.
+    :ivar dict previous_metadata: Previously recorded metadata of source and target files stored in target file ID3 tag.
+    :ivar dict current_metadata: Current metadata of soruce and target files.
     """
 
     def __init__(self, source, source_dir, target_dir):

flash_air_music/convert/transcode.py

@@ -5,7 +5,6 @@
 import os
 import signal
 import time
-from subprocess import DEVNULL, Popen
 
 from flash_air_music.configuration import GLOBAL_MUTABLE_CONFIG
 from flash_air_music.convert.id3_flac_tags import write_stored_metadata
@@ -14,10 +13,36 @@
 TIMEOUT = 5 * 60  # Seconds.
 
 
+class Protocol(asyncio.SubprocessProtocol):
+    """Handles process output."""
+
+    def __init__(self, exit_future):
+        """Constructor."""
+        self.exit_future = exit_future
+        self.stdout = bytearray()
+        self.stderr = bytearray()
+
+    def pipe_data_received(self, fd, data):
+        """Receive program's output.
+
+        :param int fd: File descriptor sending data.
+        :param bytearray data: Data sent.
+        """
+        if fd == 2:
+            self.stderr.extend(data)
+        else:
+            self.stdout.extend(data)
+
+    def process_exited(self):
+        """Called when process exits."""
+        self.exit_future.set_result(True)
+
+
 @asyncio.coroutine
-def convert_file(song):
+def convert_file(loop, song):
     """Convert one file to mp3. Store metadata in ID3 comment tag.
 
+    :param loop: AsyncIO event loop object.
     :param flash_air_music.convert.discover.Song song: Song instance.
 
     :return: Same Song instance, command, and exit status of command.
@@ -37,18 +62,31 @@ def convert_file(song):
         song.target,
     ]
 
+    # Start process.
     log.info('Converting %s', os.path.basename(song.source))
-    with Popen(command, stdin=DEVNULL, stdout=DEVNULL, stderr=DEVNULL) as process:
-        log.debug('Process %d started with command %s with timeout %d.', process.pid, str(command), TIMEOUT)
-        while process.poll() is None:
-            log.debug('Process %d still running...', process.pid)
-            if time.time() - start_time > TIMEOUT and timeout_signals:
-                send_signal = timeout_signals.pop()
-                log.warning('Timeout exceeded, sending signal %d to pid %d.', send_signal, process.pid)
-                process.send_signal(send_signal)
-            yield from asyncio.sleep(SLEEP_FOR)
-        exit_status = process.poll()
-        log.debug('Process %d exited %d', process.pid, exit_status)
+    exit_future = asyncio.Future(loop=loop)
+    transport, protocol = yield from loop.subprocess_exec(lambda: Protocol(exit_future), *command, stdin=None)
+    pid = transport.get_pid()
+
+    # Wait for process to finish.
+    log.debug('Process %d started with command %s with timeout %d.', pid, str(command), TIMEOUT)
+    while not exit_future.done():
+        log.debug('Process %d still running...', pid)
+        if time.time() - start_time > TIMEOUT and timeout_signals:
+            send_signal = timeout_signals.pop()
+            log.warning('Timeout exceeded, sending signal %d to pid %d.', send_signal, pid)
+            transport.send_signal(send_signal)
+        yield from asyncio.sleep(SLEEP_FOR)
+    yield from exit_future
+
+    # Get results.
+    transport.close()
+    exit_status = transport.get_returncode()
+    stdout = bytes(protocol.stdout)
+    stderr = bytes(protocol.stderr)
+    log.debug('Process %d exited %d', pid, exit_status)
+    log.debug('Process %d stdout: %s', pid, stdout.decode('utf-8'))
+    log.debug('Process %d stderr: %s', pid, stderr.decode('utf-8'))
 
     if not exit_status:
         log.debug('Storing metadata in %s', os.path.basename(song.target))

tests/test_convert/test_transcode.py

@@ -31,7 +31,7 @@ def test_convert_file_success(monkeypatch, tmpdir, caplog):
 
     # Run.
     loop = asyncio.get_event_loop()
-    command, exit_status = loop.run_until_complete(transcode.convert_file(song))[1:]
+    command, exit_status = loop.run_until_complete(transcode.convert_file(loop, song))[1:]
 
     # Verify.
     assert exit_status == 0
@@ -42,10 +42,11 @@ def test_convert_file_success(monkeypatch, tmpdir, caplog):
     messages = [r.message for r in caplog.records if r.name.startswith('flash_air_music')]
     assert messages[0] == 'Converting song1.mp3'
     assert str(command) in messages[1]
-    assert messages[-2].endswith('exited 0')
+    assert messages[-4].endswith('exited 0')
     assert messages[-1] == 'Storing metadata in song1.mp3'
 
 
+@pytest.mark.skipif(str(DEFAULT_FFMPEG_BINARY is None))
 def test_convert_file_deadlock(monkeypatch, tmpdir, caplog):
     """Test convert_file() with ffmpeg outputting a lot of data, filling up buffers.
 
@@ -56,21 +57,32 @@ def test_convert_file_deadlock(monkeypatch, tmpdir, caplog):
     ffmpeg = tmpdir.join('ffmpeg')
     ffmpeg.write(dedent("""\
     #!/bin/bash
-    for i in {1..1024000}; do echo -n Test$i; done
-    echo
+    ffmpeg $@
+    for i in {1..10240}; do echo -n test_stdout$i; done
+    for i in {1..10240}; do echo -n test_stderr$i >&2; done
     """))
     ffmpeg.chmod(0o0755)
     monkeypatch.setattr(transcode, 'GLOBAL_MUTABLE_CONFIG', {'--ffmpeg-bin': str(ffmpeg)})
-    monkeypatch.setattr(transcode, 'SLEEP_FOR', 0.1)
     source_dir = tmpdir.join('source').ensure_dir()
     target_dir = tmpdir.join('target').ensure_dir()
     HERE.join('1khz_sine.mp3').copy(source_dir.join('song1.mp3'))
-    HERE.join('1khz_sine.mp3').copy(target_dir.join('song1.mp3'))
     song = Song(str(source_dir.join('song1.mp3')), str(source_dir), str(target_dir))
 
     # Run.
     loop = asyncio.get_event_loop()
-    command, exit_status = loop.run_until_complete(transcode.convert_file(song))[1:]
+    command, exit_status = loop.run_until_complete(transcode.convert_file(loop, song))[1:]
 
     # Verify.
     assert exit_status == 0
+    assert target_dir.join('song1.mp3').check(file=True)
+    assert Song(str(source_dir.join('song1.mp3')), str(source_dir), str(target_dir)).needs_conversion is False
+
+    # Verify log.
+    messages = [r.message for r in caplog.records if r.name.startswith('flash_air_music')]
+    assert messages[0] == 'Converting song1.mp3'
+    assert str(command) in messages[1]
+    assert messages[2].endswith('still running...')
+    assert messages[-4].endswith('exited 0')
+    assert messages[-3].endswith('test_stdout10240')
+    assert messages[-2].endswith('test_stderr10240')
+    assert messages[-1] == 'Storing metadata in song1.mp3'