Repository: Azure/WALinuxAgent (python)

Issue:
CGroups error in Ubuntu 14.04
```
2018/07/31 11:41:06.400633 ERROR ExtHandler monitor: Exception tracking wrapper and agent: 'Hierarchy memory is not mounted' [Traceback (most recent call last):
  File "bin/WALinuxAgent-2.2.30-py2.7.egg/azurelinuxagent/ga/monitor.py", line 397, in init_cgroups
    CGroupsTelemetry.track_cgroup(CGroups.for_extension(""))
  File "bin/WALinuxAgent-2.2.30-py2.7.egg/azurelinuxagent/common/cgroups.py", line 360, in for_extension
    return CGroups(name, CGroups._construct_custom_path_for_hierarchy)
  File "bin/WALinuxAgent-2.2.30-py2.7.egg/azurelinuxagent/common/cgroups.py", line 401, in __init__
    raise CGroupsException("Hierarchy {0} is not mounted".format(hierarchy))
azurelinuxagent.common.cgroups.CGroupsException: 'Hierarchy memory is not mounted'
]
```

Pull request:
Improve cgroups logging
## Description

- if cgroups cannot be initialized we should not log an error
- closes #1282 

---

### 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.
- [ ] 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/ga/monitor.py b/azurelinuxagent/ga/monitor.py
index c1215806..d6b66921 100644
--- a/azurelinuxagent/ga/monitor.py
+++ b/azurelinuxagent/ga/monitor.py
@@ -406,7 +406,11 @@ class MonitorHandler(object):
             CGroupsTelemetry.track_cgroup(CGroups.for_extension(""))
             CGroupsTelemetry.track_agent()
         except Exception as e:
-            logger.error("monitor: Exception tracking wrapper and agent: {0} [{1}]", e, traceback.format_exc())
+            # when a hierarchy is not mounted, we raise an exception
+            # and we should therefore only issue a warning, since this
+            # is not unexpected
+            logger.warn("Monitor: cgroups not initialized: {0}", ustr(e))
+            logger.verbose(traceback.format_exc())
 
     def send_cgroup_telemetry(self):
         if self.last_cgroup_telemetry is None:
@@ -419,13 +423,15 @@ class MonitorHandler(object):
                         if value > 0:
                             report_metric(metric_group, metric_name, cgroup_name, value)
             except Exception as e:
-                logger.warn("Failed to collect performance metrics: {0} [{1}]", e, traceback.format_exc())
+                logger.warn("Monitor: failed to collect cgroups performance metrics: {0}", ustr(e))
+                logger.verbose(traceback.format_exc())
 
             # Look for extension cgroups we're not already tracking and track them
             try:
                 CGroupsTelemetry.update_tracked(self.protocol.client.get_current_handlers())
             except Exception as e:
-                logger.warn("Monitor: updating tracked extensions raised {0}: {1}", e, traceback.format_exc())
+                logger.warn("Monitor: failed to update cgroups tracked extensions: {0}", ustr(e))
+                logger.verbose(traceback.format_exc())
 
             self.last_cgroup_telemetry = datetime.datetime.utcnow()
 
diff --git a/azurelinuxagent/pa/provision/cloudinit.py b/azurelinuxagent/pa/provision/cloudinit.py
index 9609d7da..3f3cdb04 100644
--- a/azurelinuxagent/pa/provision/cloudinit.py
+++ b/azurelinuxagent/pa/provision/cloudinit.py
@@ -69,9 +69,10 @@ class CloudInitProvisionHandler(ProvisionHandler):
                 duration=elapsed_milliseconds(utc_start))
 
         except ProvisionError as e:
-            logger.error("Provisioning failed: {0}", ustr(e))
+            msg = "Provisioning with cloud-init failed: {0} ({1}s)".format(ustr(e), self._get_uptime_seconds())
+            logger.error(msg)
             self.report_not_ready("ProvisioningFailed", ustr(e))
-            self.report_event(ustr(e))
+            self.report_event(msg)
             return
 
     def wait_for_ovfenv(self, max_retry=1800, sleep_time=1):
diff --git a/azurelinuxagent/pa/provision/default.py b/azurelinuxagent/pa/provision/default.py
index a6e50824..0eb0823c 100644
--- a/azurelinuxagent/pa/provision/default.py
+++ b/azurelinuxagent/pa/provision/default.py
@@ -98,9 +98,10 @@ class ProvisionHandler(object):
             logger.info("Provisioning complete")
 
         except (ProtocolError, ProvisionError) as e:
+            msg = "Provisioning failed: {0} ({1}s)".format(ustr(e), self._get_uptime_seconds())
+            logger.error(msg)
             self.report_not_ready("ProvisioningFailed", ustr(e))
-            self.report_event(ustr(e), is_success=False)
-            logger.error("Provisioning failed: {0}", ustr(e))
+            self.report_event(msg, is_success=False)
             return
 
     @staticmethod


Test patch:
diff --git a/tests/pa/test_provision.py b/tests/pa/test_provision.py
index 0335bc9c..27f75266 100644
--- a/tests/pa/test_provision.py
+++ b/tests/pa/test_provision.py
@@ -268,8 +268,8 @@ class TestProvision(AgentTestCase):
         fileutil.write_file(ovfenv_file, ovfenv_data)
 
         ph.run()
-        ph.report_event.assert_called_once_with(
-            '[ProvisionError] --unit-test--', is_success=False)
+        positional_args, kw_args = ph.report_event.call_args_list[0]
+        self.assertTrue(re.match(r'Provisioning failed: \[ProvisionError\] --unit-test-- \(\d+\.\d+s\)', positional_args[0]) is not None)
 
     @patch('azurelinuxagent.pa.provision.default.ProvisionHandler.write_agent_disabled')
     @distros()