--log file object getting closed prematurely (Issue #219)

pip/basecommand.py

@@ -145,19 +145,19 @@ def main(self, args):
             logger.fatal('Exception:\n%s' % format_exc())
             store_log = True
             exit = UNKNOWN_ERROR
-        if log_fp is not None:
-            log_fp.close()
         if store_log:
-            log_fn = options.log_file
+            log_file_fn = options.log_file
             text = '\n'.join(complete_log)
             try:
-                log_fp = open_logfile(log_fn, 'w')
+                log_file_fp = open_logfile(log_file_fn, 'w')
             except IOError:
                 temp = tempfile.NamedTemporaryFile(delete=False)
-                log_fn = temp.name
-                log_fp = open_logfile(log_fn, 'w')
-            logger.fatal('Storing complete log in %s' % log_fn)
-            log_fp.write(text)
+                log_file_fn = temp.name
+                log_file_fp = open_logfile(log_file_fn, 'w')
+            logger.fatal('Storing complete log in %s' % log_file_fn)
+            log_file_fp.write(text)
+            log_file_fp.close()
+        if log_fp is not None:
             log_fp.close()
         return exit
 

tests/unit/test_basecommand.py

@@ -0,0 +1,63 @@
+import os
+from pip.basecommand import Command
+from pip.log import logger
+
+
+class FakeCommand(Command):
+    name = 'fake'
+    summary = name
+    def __init__(self, error=False):
+        self.error = error
+        super(FakeCommand, self).__init__()
+    def run(self, options, args):
+        logger.info("fake")
+        if self.error:
+            raise SystemExit(1)
+
+
+class Test_basecommand_logging(object):
+    """
+    Test `pip.basecommand.Command` setting up logging consumers based on options
+    """
+
+    def teardown(self):
+        logger.consumers = []
+
+    def test_log(self, tmpdir):
+        """
+        Test the --log option logs.
+        """
+        cmd = FakeCommand()
+        log_path = tmpdir.join('log')
+        cmd.main(['fake', '--log', log_path])
+        assert 'fake' == open(log_path).read().strip()[:4]
+
+    def test_log_file_success(self, tmpdir):
+        """
+        Test the --log-file option *doesn't* log when command succeeds.
+        (It's just the historical behavior? this just confirms it)
+        """
+        cmd = FakeCommand()
+        log_file_path = tmpdir.join('log_file')
+        cmd.main(['fake', '--log-file', log_file_path])
+        assert not os.path.exists(log_file_path)
+
+    def test_log_file_error(self, tmpdir):
+        """
+        Test the --log-file option logs (when there's an error).
+        """
+        cmd = FakeCommand(error=True)
+        log_file_path = tmpdir.join('log_file')
+        cmd.main(['fake', '--log-file', log_file_path])
+        assert 'fake' == open(log_file_path).read().strip()[:4]
+
+    def test_log_log_file(self, tmpdir):
+        """
+        Test the --log and --log-file options log together (when there's an error).
+        """
+        cmd = FakeCommand(error=True)
+        log_path = tmpdir.join('log')
+        log_file_path = tmpdir.join('log_file')
+        cmd.main(['fake', '--log', log_path, '--log-file', log_file_path])
+        assert 'fake' == open(log_path).read().strip()[:4]
+        assert 'fake' == open(log_file_path).read().strip()[:4]