Repository: Azure/WALinuxAgent
Pull request #1558 (2019-06-14 22:15:21)

Prevents over-logging in known cases.
<!-- DO NOT DELETE THIS TEMPLATE -->

## Description
Prevents over-logging in known cases such as file not found (searching for file too soon), and tasks not present (cgroup got removed by systemd)

Issue # <!-- if any -->
<!--
Please add an informative description that covers that changes made by the pull request. 
This checklist is used to make sure that common issues in a pull request are addressed.
This will expedite the process of getting your pull request merged and avoid extra work on your part to fix issues discovered during the review process.
-->

---

### 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.
- [ ] 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).

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/azure/walinuxagent/1558)
<!-- Reviewable:end -->


codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558?src=pr&el=h1) Report
> :exclamation: No coverage uploaded for pull request base (`develop@9aae8a0`). [Click here to learn what that means](https://docs.codecov.io/docs/error-reference#section-missing-base-commit).
> The diff coverage is `85.71%`.

[![Impacted file tree graph](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558/graphs/tree.svg?width=650&token=ae90E2KYCw&height=150&src=pr)](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##             develop    #1558   +/-   ##
==========================================
  Coverage           ?   63.38%           
==========================================
  Files              ?       78           
  Lines              ?    11056           
  Branches           ?     1559           
==========================================
  Hits               ?     7008           
  Misses             ?     3709           
  Partials           ?      339
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/common/cgroupstelemetry.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9jZ3JvdXBzdGVsZW1ldHJ5LnB5) | `93.93% <100%> (ø)` | |
| [azurelinuxagent/common/cgroup.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9jZ3JvdXAucHk=) | `83.89% <80%> (ø)` | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558?src=pr&el=footer). Last update [9aae8a0...eb61933](https://codecov.io/gh/Azure/WALinuxAgent/pull/1558?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/azurelinuxagent/common/cgroup.py b/azurelinuxagent/common/cgroup.py
index 07913c48..5030b5f7 100644
--- a/azurelinuxagent/common/cgroup.py
+++ b/azurelinuxagent/common/cgroup.py
@@ -13,7 +13,7 @@
 # limitations under the License.
 #
 # Requires Python 2.6+ and Openssl 1.0+
-
+import errno
 import os
 import re
 
@@ -66,8 +66,7 @@ class CGroup(object):
         try:
             return fileutil.read_file(parameter_file)
         except Exception:
-            raise CGroupsException("Could not retrieve cgroup file {0}/{1}".
-                                   format(self.path, file_name))
+            raise
 
     def _get_parameters(self, parameter_name, first_line_only=False):
         """
@@ -87,9 +86,9 @@ class CGroup(object):
             parameter_filename = self._get_cgroup_file(parameter_name)
             logger.error("File {0} is empty but should not be".format(parameter_filename))
             raise CGroupsException("File {0} is empty but should not be".format(parameter_filename))
-        except CGroupsException:
-            raise
         except Exception as e:
+            if isinstance(e, (IOError, OSError)) and e.errno == errno.ENOENT:
+                raise e
             parameter_filename = self._get_cgroup_file(parameter_name)
             logger.error("Exception while attempting to read {0}: {1}".format(parameter_filename, ustr(e)))
             raise CGroupsException("Exception while attempting to read {0}".format(parameter_filename), e)
@@ -103,6 +102,14 @@ class CGroup(object):
             tasks = self._get_parameters("tasks")
             if tasks:
                 return len(tasks) != 0
+        except (IOError, OSError) as e:
+            if e.errno == errno.ENOENT:
+                # only suppressing file not found exceptions.
+                pass
+            else:
+                logger.periodic_warn(logger.EVERY_HALF_HOUR,
+                                     'Could not get list of tasks from "tasks" file in the cgroup: {0}.'
+                                     ' Internal error: {1}'.format(self.path, ustr(e)))
         except CGroupsException as e:
             logger.periodic_warn(logger.EVERY_HALF_HOUR,
                                  'Could not get list of tasks from "tasks" file in the cgroup: {0}.'
@@ -124,13 +131,6 @@ class CpuCgroup(CGroup):
 
         self._osutil = get_osutil()
         self._current_cpu_total = 0
-        try:
-            self._current_cpu_total = self._get_current_cpu_total()
-        except CGroupsException as e:
-            logger.periodic_warn(logger.EVERY_HALF_HOUR,
-                                 'Could not get current CPU total usage from cgroup: {0}. '
-                                 'Internal error :{1}'.format(self.path, ustr(e)))
-
         self._previous_cpu_total = 0
         self._current_system_cpu = self._osutil.get_total_cpu_ticks_since_boot()
         self._previous_system_cpu = 0
@@ -147,8 +147,14 @@ class CpuCgroup(CGroup):
         :return: int
         """
         cpu_total = 0
-        cpu_stat = self._get_file_contents('cpuacct.stat')
-        if cpu_stat is not None:
+        try:
+            cpu_stat = self._get_file_contents('cpuacct.stat')
+        except Exception as e:
+            if isinstance(e, (IOError, OSError)) and e.errno == errno.ENOENT:
+                raise e
+            raise CGroupsException("Exception while attempting to read {0}".format("cpuacct.stat"), e)
+
+        if cpu_stat:
             m = re_user_system_times.match(cpu_stat)
             if m:
                 cpu_total = int(m.groups()[0]) + int(m.groups()[1])
diff --git a/azurelinuxagent/common/cgroupstelemetry.py b/azurelinuxagent/common/cgroupstelemetry.py
index b323aec6..6384e88f 100644
--- a/azurelinuxagent/common/cgroupstelemetry.py
+++ b/azurelinuxagent/common/cgroupstelemetry.py
@@ -13,6 +13,7 @@
 # limitations under the License.
 #
 # Requires Python 2.6+ and Openssl 1.0+
+import errno
 import threading
 from datetime import datetime as dt
 
@@ -121,9 +122,12 @@ class CGroupsTelemetry(object):
                 try:
                     metric = cgroup.collect()
                 except Exception as e:
-                    logger.periodic_warn(logger.EVERY_HALF_HOUR,
-                                         'Could not collect the cgroup metrics for cgroup path {0}. '
-                                         'Internal error : {1}'.format(cgroup.path, ustr(e)))
+                    if isinstance(e, (IOError, OSError)) and e.errno == errno.ENOENT:
+                        pass
+                    else:
+                        logger.periodic_warn(logger.EVERY_HALF_HOUR,
+                                             'Could not collect the cgroup metrics for cgroup path {0}. '
+                                             'Internal error : {1}'.format(cgroup.path, ustr(e)))
                 if metric:
                     CGroupsTelemetry._cgroup_metrics[cgroup.name].add_new_data(cgroup.controller, metric)
 


Test patch:
diff --git a/tests/common/test_cgroupstelemetry.py b/tests/common/test_cgroupstelemetry.py
index 9fa9eabe..2841649f 100644
--- a/tests/common/test_cgroupstelemetry.py
+++ b/tests/common/test_cgroupstelemetry.py
@@ -14,10 +14,9 @@
 #
 # Requires Python 2.4+ and Openssl 1.0+
 #
-
+import errno
 import os
 import random
-import stat
 import time
 
 from mock import patch
@@ -256,6 +255,87 @@ class TestCGroupsTelemetry(AgentTestCase):
                             self.assertEqual(len(max_memory_levels._data), 0)
                             self.assertEqual(len(current_cpu_usage._data), 0)
 
+    @patch("azurelinuxagent.common.osutil.default.DefaultOSUtil._get_proc_stat")
+    @patch("azurelinuxagent.common.logger.periodic_warn")
+    @patch("azurelinuxagent.common.utils.fileutil.read_file")
+    def test_telemetry_polling_to_not_generate_transient_logs_ioerror_file_not_found(self, mock_read_file,
+                                                                                     patch_periodic_warn, *args):
+        num_extensions = 1
+        for i in range(num_extensions):
+            dummy_cpu_cgroup = CGroup.create("dummy_cpu_path_{0}".format(i), "cpu", "dummy_extension_{0}".format(i))
+            CGroupsTelemetry.track_cgroup(dummy_cpu_cgroup)
+
+            dummy_memory_cgroup = CGroup.create("dummy_memory_path_{0}".format(i), "memory",
+                                                "dummy_extension_{0}".format(i))
+            CGroupsTelemetry.track_cgroup(dummy_memory_cgroup)
+
+        self.assertEqual(0, patch_periodic_warn.call_count)
+
+        # Not expecting logs present for io_error with errno=errno.ENOENT
+        io_error_2 = IOError()
+        io_error_2.errno = errno.ENOENT
+        mock_read_file.side_effect = io_error_2
+
+        poll_count = 1
+        for data_count in range(poll_count, 10):
+            CGroupsTelemetry.poll_all_tracked()
+            self.assertEqual(0, patch_periodic_warn.call_count)
+
+    @patch("azurelinuxagent.common.osutil.default.DefaultOSUtil._get_proc_stat")
+    @patch("azurelinuxagent.common.logger.periodic_warn")
+    @patch("azurelinuxagent.common.utils.fileutil.read_file")
+    def test_telemetry_polling_to_generate_transient_logs_ioerror_permission_denied(self, mock_read_file,
+                                                                                    patch_periodic_warn, *args):
+        num_extensions = 1
+        num_controllers = 2
+        is_active_check_per_controller = 2
+
+        for i in range(num_extensions):
+            dummy_cpu_cgroup = CGroup.create("dummy_cpu_path_{0}".format(i), "cpu", "dummy_extension_{0}".format(i))
+            CGroupsTelemetry.track_cgroup(dummy_cpu_cgroup)
+
+            dummy_memory_cgroup = CGroup.create("dummy_memory_path_{0}".format(i), "memory",
+                                                "dummy_extension_{0}".format(i))
+            CGroupsTelemetry.track_cgroup(dummy_memory_cgroup)
+
+        self.assertEqual(0, patch_periodic_warn.call_count)
+
+        # Expecting logs to be present for different kind of errors
+        io_error_3 = IOError()
+        io_error_3.errno = errno.EPERM
+        mock_read_file.side_effect = io_error_3
+
+        poll_count = 1
+        expected_count_per_call = num_controllers + is_active_check_per_controller
+        # each collect per controller would generate a log statement, and each cgroup would invoke a
+        # is active check raising an exception
+
+        for data_count in range(poll_count, 10):
+            CGroupsTelemetry.poll_all_tracked()
+            self.assertEqual(poll_count * expected_count_per_call, patch_periodic_warn.call_count)
+
+    @patch("azurelinuxagent.common.osutil.default.DefaultOSUtil._get_proc_stat")
+    @patch("azurelinuxagent.common.utils.fileutil.read_file")
+    def test_telemetry_polling_to_generate_transient_logs_index_error(self, mock_read_file, *args):
+        num_extensions = 1
+        for i in range(num_extensions):
+            dummy_cpu_cgroup = CGroup.create("dummy_cpu_path_{0}".format(i), "cpu", "dummy_extension_{0}".format(i))
+            CGroupsTelemetry.track_cgroup(dummy_cpu_cgroup)
+
+            dummy_memory_cgroup = CGroup.create("dummy_memory_path_{0}".format(i), "memory",
+                                                "dummy_extension_{0}".format(i))
+            CGroupsTelemetry.track_cgroup(dummy_memory_cgroup)
+
+        # Generating a different kind of error (non-IOError) to check the logging.
+        # Trying to invoke IndexError during the getParameter call
+        mock_read_file.return_value = ''
+
+        with patch("azurelinuxagent.common.logger.periodic_warn") as patch_periodic_warn:
+            expected_call_count = 1  # called only once at start, and then gets removed from the tracked data.
+            for data_count in range(1, 10):
+                CGroupsTelemetry.poll_all_tracked()
+                self.assertEqual(expected_call_count, patch_periodic_warn.call_count)
+
     @patch("azurelinuxagent.common.osutil.default.DefaultOSUtil.get_total_cpu_ticks_since_boot")
     @patch("azurelinuxagent.common.cgroup.CpuCgroup._get_current_cpu_total")
     @patch("azurelinuxagent.common.cgroup.CpuCgroup._update_cpu_data")
@@ -407,7 +487,7 @@ class TestCGroupsTelemetry(AgentTestCase):
                 collected_metrics = {}
                 for name, cgroup_metrics in CGroupsTelemetry._cgroup_metrics.items():
                     collected_metrics[name] = CGroupsTelemetry._process_cgroup_metric(cgroup_metrics)
-                    self.assertEqual(collected_metrics[name], {})  #empty
+                    self.assertEqual(collected_metrics[name], {})  # empty
 
     @patch("azurelinuxagent.common.cgroup.CpuCgroup._get_current_cpu_total")
     @patch("azurelinuxagent.common.osutil.default.DefaultOSUtil.get_total_cpu_ticks_since_boot")