Repository: Azure/WALinuxAgent
Pull request #1300 (2018-08-16 21:17:16)

Remove call to Process.terminate
## Description

Issue #1293

We received several reports of issues regarding custom script 2.0. Logs and the state of files on disk indicate that custom script process was crashing while running, triggered by a change in the agent. The reports were of inconsistent failures, ranging between 2-50% of deployments affected. 

There was a change added to capture process output, which was the most likely candidate for the root cause. Calling `Process.terminate()` is known to corrupt the pipe [1] and this seems to result in the custom script extension crashing. Since it is not necessary for us to terminate the process which is attempting to collect process output, this was removed.

[1] From https://docs.python.org/2/library/multiprocessing.html:

> _Avoid terminating processes_
>
> _Using the Process.terminate method to stop a process is liable to cause any shared resources (such as locks, semaphores, pipes and queues) currently being used by the process to become broken or unavailable to other processes._
>
> _Therefore it is probably best to only consider using Process.terminate on processes which never use any shared resources._

---

### PR information
- [x] The title of the PR is clear and informative.
- [x] There are a small number of commits, each of which has an informative message. This means that previously merged commits do not appear in the history of the PR. For information on cleaning up the commits in your pull request, [see this page](https://github.com/Azure/azure-powershell/blob/master/documentation/development-docs/cleaning-up-commits.md).
- [x] Except for special cases involving multiple contributors, the PR is started from a fork of the main repository, not a branch.
- [x] If applicable, the PR references the bug/issue that it fixes in the description.
- [x] New Unit tests were added for the changes made and Travis.CI is passing.

### Quality of Code and Contribution Guidelines
- [x] I have read the [contribution guidelines](https://github.com/Azure/WALinuxAgent/blob/master/.github/CONTRIBUTING.md).


Patch:
diff --git a/azurelinuxagent/common/protocol/hostplugin.py b/azurelinuxagent/common/protocol/hostplugin.py
index 295d6aa7..7333e378 100644
--- a/azurelinuxagent/common/protocol/hostplugin.py
+++ b/azurelinuxagent/common/protocol/hostplugin.py
@@ -118,6 +118,7 @@ class HostPluginProtocol(object):
             if restutil.request_failed(response):
                 error_response = restutil.read_response_error(response)
                 logger.error("HostGAPlugin: Failed Get API versions: {0}".format(error_response))
+                is_healthy = not restutil.request_failed_at_hostplugin(response)
             else:
                 return_val = ustr(remove_bom(response.read()), encoding='utf-8')
                 is_healthy = True
diff --git a/azurelinuxagent/common/utils/processutil.py b/azurelinuxagent/common/utils/processutil.py
index b6f30ee7..d1d8e08a 100644
--- a/azurelinuxagent/common/utils/processutil.py
+++ b/azurelinuxagent/common/utils/processutil.py
@@ -25,6 +25,7 @@ import signal
 from errno import ESRCH
 from multiprocessing import Process
 
+import azurelinuxagent.common.logger as logger
 from azurelinuxagent.common.exception import ExtensionError
 from azurelinuxagent.common.future import ustr
 
@@ -102,7 +103,8 @@ def _destroy_process(process, signal_to_send=signal.SIGKILL):
 
 def capture_from_process_poll(process, cmd, timeout, code):
     """
-    If the process forks, we cannot capture anything we block until the process tree completes
+    Capture output from the process if it does not fork, or forks
+    and completes quickly.
     """
     retry = timeout
     while retry > 0 and process.poll() is None:
@@ -143,11 +145,9 @@ def capture_from_process_poll(process, cmd, timeout, code):
         # allow 1s to capture output
         cproc.join(1)
 
-        if cproc.is_alive():
-            cproc.terminate()
-
-        stdout = ret_dict[0]
-        stderr = ret_dict[1]
+        if len(ret_dict) == 2:
+            stdout = ret_dict[0]
+            stderr = ret_dict[1]
 
     except Exception:
         pass
diff --git a/azurelinuxagent/common/utils/restutil.py b/azurelinuxagent/common/utils/restutil.py
index dee51e0e..1a246333 100644
--- a/azurelinuxagent/common/utils/restutil.py
+++ b/azurelinuxagent/common/utils/restutil.py
@@ -86,6 +86,7 @@ HTTP_PROXY_ENV = "http_proxy"
 HTTPS_PROXY_ENV = "https_proxy"
 HTTP_USER_AGENT = "{0}/{1}".format(AGENT_NAME, GOAL_STATE_AGENT_VERSION)
 HTTP_USER_AGENT_HEALTH = "{0}+health".format(HTTP_USER_AGENT)
+INVALID_CONTAINER_CONFIGURATION = "InvalidContainerConfiguration"
 
 DEFAULT_PROTOCOL_ENDPOINT = '168.63.129.16'
 HOST_PLUGIN_PORT = 32526
@@ -130,15 +131,27 @@ def _compute_delay(retry_attempt=1, delay=DELAY_IN_SECONDS):
         fib = (fib[1], fib[0]+fib[1])
     return delay*fib[1]
 
+
 def _is_retry_status(status, retry_codes=RETRY_CODES):
     return status in retry_codes
 
+
 def _is_retry_exception(e):
     return len([x for x in RETRY_EXCEPTIONS if isinstance(e, x)]) > 0
 
+
 def _is_throttle_status(status):
     return status in THROTTLE_CODES
 
+
+def _is_invalid_container_configuration(response):
+    result = False
+    if response is not None and response.status == httpclient.BAD_REQUEST:
+        error_detail = read_response_error(response)
+        result = INVALID_CONTAINER_CONFIGURATION in error_detail
+    return result
+
+
 def _parse_url(url):
     o = urlparse(url)
     rel_uri = o.path
@@ -320,6 +333,13 @@ def http_request(method,
             if resp.status in RESOURCE_GONE_CODES:
                 raise ResourceGoneError()
 
+            # Map invalid container configuration errors to resource gone in
+            # order to force a goal state refresh, which in turn updates the
+            # container-id header passed to HostGAPlugin.
+            # See #1294.
+            if _is_invalid_container_configuration(resp):
+                raise ResourceGoneError()
+
             return resp
 
         except httpclient.HTTPException as e:


Test patch:
diff --git a/tests/ga/test_extension.py b/tests/ga/test_extension.py
index 6fc6b8c1..3f220f57 100644
--- a/tests/ga/test_extension.py
+++ b/tests/ga/test_extension.py
@@ -552,6 +552,19 @@ class TestExtension(AgentTestCase):
         self.assertTrue("Failed to report vm agent status" in kw['message'])
         self.assertEquals("ReportStatusExtended", kw['op'])
 
+    @patch('azurelinuxagent.ga.exthandlers.add_event')
+    def test_ext_handler_report_status_resource_gone(self, mock_add_event, *args):
+        test_data = WireProtocolData(DATA_FILE)
+        exthandlers_handler, protocol = self._create_mock(test_data, *args)
+        protocol.report_vm_status = Mock(side_effect=ResourceGoneError)
+
+        exthandlers_handler.run()
+        self.assertEquals(4, mock_add_event.call_count)
+        args, kw = mock_add_event.call_args
+        self.assertEquals(False, kw['is_success'])
+        self.assertTrue("ResourceGoneError" in kw['message'])
+        self.assertEquals("ExtensionProcessing", kw['op'])
+
     @patch('azurelinuxagent.common.errorstate.ErrorState.is_triggered')
     @patch('azurelinuxagent.common.event.add_event')
     def test_ext_handler_download_failure_permanent(self, mock_add_event, mock_error_state, *args):
diff --git a/tests/protocol/test_healthservice.py b/tests/protocol/test_healthservice.py
index e9646c01..c0a028d6 100644
--- a/tests/protocol/test_healthservice.py
+++ b/tests/protocol/test_healthservice.py
@@ -201,6 +201,7 @@ class TestHealthService(AgentTestCase):
         self.assert_status_code(status_code=200, expected_healthy=True)
         self.assert_status_code(status_code=201, expected_healthy=True)
         self.assert_status_code(status_code=302, expected_healthy=True)
+        self.assert_status_code(status_code=400, expected_healthy=True)
         self.assert_status_code(status_code=416, expected_healthy=True)
         self.assert_status_code(status_code=419, expected_healthy=True)
         self.assert_status_code(status_code=429, expected_healthy=True)
diff --git a/tests/protocol/test_hostplugin.py b/tests/protocol/test_hostplugin.py
index a1b91acd..6d28f80e 100644
--- a/tests/protocol/test_hostplugin.py
+++ b/tests/protocol/test_hostplugin.py
@@ -26,6 +26,7 @@ import azurelinuxagent.common.protocol.hostplugin as hostplugin
 from azurelinuxagent.common.errorstate import ErrorState
 
 from azurelinuxagent.common.exception import HttpError, ResourceGoneError
+from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.protocol.hostplugin import API_VERSION
 from azurelinuxagent.common.utils import restutil
 from tests.protocol.mockwiredata import WireProtocolData, DATA_FILE
@@ -129,6 +130,76 @@ class TestHostPlugin(AgentTestCase):
         self.assertEqual(headers['x-ms-containerid'], goal_state.container_id)
         self.assertEqual(headers['x-ms-host-config-name'], goal_state.role_config_name)
 
+    @patch("azurelinuxagent.common.protocol.healthservice.HealthService.report_host_plugin_versions")
+    @patch("azurelinuxagent.ga.update.restutil.http_get")
+    @patch("azurelinuxagent.common.event.report_event")
+    def assert_ensure_initialized(self, patch_event, patch_http_get, patch_report_health,
+                                  response_body,
+                                  response_status_code,
+                                  should_initialize,
+                                  should_report_healthy):
+
+        host = hostplugin.HostPluginProtocol(endpoint='ws', container_id='cid', role_config_name='rcf')
+
+        host.is_initialized = False
+        patch_http_get.return_value = MockResponse(body=response_body,
+                                                   reason='reason',
+                                                   status_code=response_status_code)
+        return_value = host.ensure_initialized()
+
+        self.assertEqual(return_value, host.is_available)
+        self.assertEqual(should_initialize, host.is_initialized)
+
+        self.assertEqual(1, patch_event.call_count)
+        self.assertEqual('InitializeHostPlugin', patch_event.call_args[0][0])
+
+        self.assertEqual(should_initialize, patch_event.call_args[1]['is_success'])
+        self.assertEqual(1, patch_report_health.call_count)
+
+        self.assertEqual(should_report_healthy, patch_report_health.call_args[1]['is_healthy'])
+
+        actual_response = patch_report_health.call_args[1]['response']
+        if should_initialize:
+            self.assertEqual('', actual_response)
+        else:
+            self.assertTrue('HTTP Failed' in actual_response)
+            self.assertTrue(response_body in actual_response)
+            self.assertTrue(ustr(response_status_code) in actual_response)
+
+    def test_ensure_initialized(self):
+        """
+        Test calls to ensure_initialized
+        """
+        self.assert_ensure_initialized(response_body=api_versions,
+                                       response_status_code=200,
+                                       should_initialize=True,
+                                       should_report_healthy=True)
+
+        self.assert_ensure_initialized(response_body='invalid ip',
+                                       response_status_code=400,
+                                       should_initialize=False,
+                                       should_report_healthy=True)
+
+        self.assert_ensure_initialized(response_body='generic bad request',
+                                       response_status_code=400,
+                                       should_initialize=False,
+                                       should_report_healthy=True)
+
+        self.assert_ensure_initialized(response_body='resource gone',
+                                       response_status_code=410,
+                                       should_initialize=False,
+                                       should_report_healthy=True)
+
+        self.assert_ensure_initialized(response_body='generic error',
+                                       response_status_code=500,
+                                       should_initialize=False,
+                                       should_report_healthy=False)
+
+        self.assert_ensure_initialized(response_body='upstream error',
+                                       response_status_code=502,
+                                       should_initialize=False,
+                                       should_report_healthy=True)
+
     @patch("azurelinuxagent.common.protocol.hostplugin.HostPluginProtocol.ensure_initialized", return_value=True)
     @patch("azurelinuxagent.common.protocol.wire.StatusBlob.upload", return_value=False)
     @patch("azurelinuxagent.common.protocol.hostplugin.HostPluginProtocol._put_page_blob_status")
@@ -523,7 +594,8 @@ class TestHostPlugin(AgentTestCase):
         result = host_plugin.get_health()
         self.assertFalse(result)
 
-    @patch("azurelinuxagent.common.utils.restutil.http_get")
+    @patch("azurelinuxagent.common.utils.restutil.http_get",
+           return_value=MockResponse(status_code=200, body=b''))
     @patch("azurelinuxagent.common.protocol.healthservice.HealthService.report_host_plugin_versions")
     def test_ensure_health_service_called(self, patch_http_get, patch_report_versions):
         host_plugin = self._init_host()
@@ -735,9 +807,10 @@ class TestHostPlugin(AgentTestCase):
 
 
 class MockResponse:
-    def __init__(self, body, status_code):
+    def __init__(self, body, status_code, reason=''):
         self.body = body
         self.status = status_code
+        self.reason = reason
 
     def read(self):
         return self.body if sys.version_info[0] == 2 else bytes(self.body, encoding='utf-8')
diff --git a/tests/utils/test_rest_util.py b/tests/utils/test_rest_util.py
index 76b79479..6f8518ee 100644
--- a/tests/utils/test_rest_util.py
+++ b/tests/utils/test_rest_util.py
@@ -25,6 +25,7 @@ from azurelinuxagent.common.future import httpclient, ustr
 
 from tests.tools import *
 
+
 class TestIOErrorCounter(AgentTestCase):
     def test_increment_hostplugin(self):
         restutil.IOErrorCounter.reset()
@@ -459,6 +460,19 @@ class TestHttpOperations(AgentTestCase):
         self.assertRaises(ResourceGoneError, restutil.http_get, "https://foo.bar")
         self.assertEqual(1, _http_request.call_count)
 
+    @patch("time.sleep")
+    @patch("azurelinuxagent.common.utils.restutil._http_request")
+    def test_http_request_raises_for_invalid_container_configuration(self, _http_request, _sleep):
+        def read():
+            return b'{ "errorCode": "InvalidContainerConfiguration", "message": "Invalid request." }'
+
+        _http_request.side_effect = [
+            Mock(status=httpclient.BAD_REQUEST, reason='Bad Request', read=read)
+        ]
+
+        self.assertRaises(ResourceGoneError, restutil.http_get, "https://foo.bar")
+        self.assertEqual(1, _http_request.call_count)
+
     @patch("time.sleep")
     @patch("azurelinuxagent.common.utils.restutil._http_request")
     def test_http_request_retries_exceptions(self, _http_request, _sleep):