Capture and log pip install error output (#7200)

Add an optional extended description…

homeassistant/util/package.py

@@ -1,9 +1,9 @@
 """Helpers to install PyPi packages."""
 import logging
 import os
-import subprocess
 import sys
 import threading
+from subprocess import Popen, PIPE
 from urllib.parse import urlparse
 
 from typing import Optional
@@ -36,12 +36,15 @@ def install_package(package: str, upgrade: bool=True,
         if constraints is not None:
             args += ['--constraint', constraints]
 
-        try:
+        process = Popen(args, stdin=PIPE, stdout=PIPE, stderr=PIPE)
-            return subprocess.call(args) == 0
+        _, stderr = process.communicate()
-        except subprocess.SubprocessError:
+        if process.returncode != 0:
-            _LOGGER.exception('Unable to install package %s', package)
+            _LOGGER.error('Unable to install package %s: %s',
+                          package, stderr.decode('utf-8').lstrip().strip())
             return False
 
+        return True
+
 
 def check_package_exists(package: str, lib_dir: str) -> bool:
     """Check if a package is installed globally or in lib_dir.

tests/util/test_package.py

@@ -1,11 +1,11 @@
 """Test Home Assistant package util methods."""
 import os
 import pkg_resources
-import subprocess
 import unittest
 
+from subprocess import PIPE
 from distutils.sysconfig import get_python_lib
-from unittest.mock import call, patch
+from unittest.mock import call, patch, Mock
 
 import homeassistant.util.package as package
 
@@ -18,13 +18,20 @@ TEST_ZIP_REQ = 'file://{}#{}' \
     .format(os.path.join(RESOURCE_DIR, 'pyhelloworld3.zip'), TEST_NEW_REQ)
 
 
-@patch('homeassistant.util.package.subprocess.call')
+@patch('homeassistant.util.package.Popen')
 @patch('homeassistant.util.package.check_package_exists')
 class TestPackageUtilInstallPackage(unittest.TestCase):
     """Test for homeassistant.util.package module."""
 
-    def test_install_existing_package(self, mock_exists, mock_subprocess):
+    def setUp(self):
+        """Setup the tests."""
+        self.mock_process = Mock()
+        self.mock_process.communicate.return_value = (b'message', b'error')
+        self.mock_process.returncode = 0
+
+    def test_install_existing_package(self, mock_exists, mock_popen):
         """Test an install attempt on an existing package."""
+        mock_popen.return_value = self.mock_process
         mock_exists.return_value = True
 
         self.assertTrue(package.install_package(TEST_EXIST_REQ))
@@ -32,52 +39,54 @@ class TestPackageUtilInstallPackage(unittest.TestCase):
         self.assertEqual(mock_exists.call_count, 1)
         self.assertEqual(mock_exists.call_args, call(TEST_EXIST_REQ, None))
 
-        self.assertEqual(mock_subprocess.call_count, 0)
+        self.assertEqual(self.mock_process.communicate.call_count, 0)
 
     @patch('homeassistant.util.package.sys')
-    def test_install(self, mock_sys, mock_exists, mock_subprocess):
+    def test_install(self, mock_sys, mock_exists, mock_popen):
         """Test an install attempt on a package that doesn't exist."""
         mock_exists.return_value = False
-        mock_subprocess.return_value = 0
+        mock_popen.return_value = self.mock_process
 
         self.assertTrue(package.install_package(TEST_NEW_REQ, False))
 
         self.assertEqual(mock_exists.call_count, 1)
 
-        self.assertEqual(mock_subprocess.call_count, 1)
+        self.assertEqual(self.mock_process.communicate.call_count, 1)
+        self.assertEqual(mock_popen.call_count, 1)
         self.assertEqual(
-            mock_subprocess.call_args,
+            mock_popen.call_args,
             call([
                 mock_sys.executable, '-m', 'pip', 'install', '--quiet',
                 TEST_NEW_REQ
-            ])
+            ], stdin=PIPE, stdout=PIPE, stderr=PIPE)
         )
 
     @patch('homeassistant.util.package.sys')
-    def test_install_upgrade(self, mock_sys, mock_exists, mock_subprocess):
+    def test_install_upgrade(self, mock_sys, mock_exists, mock_popen):
         """Test an upgrade attempt on a package."""
         mock_exists.return_value = False
-        mock_subprocess.return_value = 0
+        mock_popen.return_value = self.mock_process
 
         self.assertTrue(package.install_package(TEST_NEW_REQ))
 
         self.assertEqual(mock_exists.call_count, 1)
 
-        self.assertEqual(mock_subprocess.call_count, 1)
+        self.assertEqual(self.mock_process.communicate.call_count, 1)
+        self.assertEqual(mock_popen.call_count, 1)
         self.assertEqual(
-            mock_subprocess.call_args,
+            mock_popen.call_args,
             call([
                 mock_sys.executable, '-m', 'pip', 'install', '--quiet',
                 TEST_NEW_REQ, '--upgrade'
-            ])
+            ], stdin=PIPE, stdout=PIPE, stderr=PIPE)
         )
 
     @patch('homeassistant.util.package.sys')
-    def test_install_target(self, mock_sys, mock_exists, mock_subprocess):
+    def test_install_target(self, mock_sys, mock_exists, mock_popen):
         """Test an install with a target."""
         target = 'target_folder'
         mock_exists.return_value = False
-        mock_subprocess.return_value = 0
+        mock_popen.return_value = self.mock_process
 
         self.assertTrue(
             package.install_package(TEST_NEW_REQ, False, target=target)
@@ -85,26 +94,28 @@ class TestPackageUtilInstallPackage(unittest.TestCase):
 
         self.assertEqual(mock_exists.call_count, 1)
 
-        self.assertEqual(mock_subprocess.call_count, 1)
+        self.assertEqual(self.mock_process.communicate.call_count, 1)
+        self.assertEqual(mock_popen.call_count, 1)
         self.assertEqual(
-            mock_subprocess.call_args,
+            mock_popen.call_args,
             call([
                 mock_sys.executable, '-m', 'pip', 'install', '--quiet',
                 TEST_NEW_REQ, '--target', os.path.abspath(target)
-            ])
+            ], stdin=PIPE, stdout=PIPE, stderr=PIPE)
         )
 
     @patch('homeassistant.util.package._LOGGER')
     @patch('homeassistant.util.package.sys')
     def test_install_error(self, mock_sys, mock_logger, mock_exists,
-                           mock_subprocess):
+                           mock_popen):
         """Test an install with a target."""
         mock_exists.return_value = False
-        mock_subprocess.side_effect = [subprocess.SubprocessError]
+        mock_popen.return_value = self.mock_process
+        self.mock_process.returncode = 1
 
         self.assertFalse(package.install_package(TEST_NEW_REQ))
 
-        self.assertEqual(mock_logger.exception.call_count, 1)
+        self.assertEqual(mock_logger.error.call_count, 1)
 
 
 class TestPackageUtilCheckPackageExists(unittest.TestCase):