Repository: Azure/WALinuxAgent
Pull request #991 (2018-01-04 23:20:34)

ship warning and errors logs to Geneva
Upload logs as telemetry events to Geneva.
Appease the PEP gods on a few things.  


Patch:
diff --git a/azurelinuxagent/agent.py b/azurelinuxagent/agent.py
index 87ab3c14..4ab7aa01 100644
--- a/azurelinuxagent/agent.py
+++ b/azurelinuxagent/agent.py
@@ -63,6 +63,9 @@ class Agent(object):
                                  path="/var/log/waagent.log")
         logger.add_logger_appender(logger.AppenderType.CONSOLE, level,
                                  path="/dev/console")
+        logger.add_logger_appender(logger.AppenderType.TELEMETRY,
+                                   logger.LogLevel.WARNING,
+                                   path=event.add_log_event)
 
         ext_log_dir = conf.get_ext_log_dir()
         try:
diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py
index ef8fdfcc..ac39bc1a 100644
--- a/azurelinuxagent/common/event.py
+++ b/azurelinuxagent/common/event.py
@@ -60,6 +60,7 @@ class WALAEventOperation:
     HttpErrors = "HttpErrors"
     Install = "Install"
     InitializeHostPlugin = "InitializeHostPlugin"
+    Log = "Log"
     Partition = "Partition"
     ProcessGoalState = "ProcessGoalState"
     Provision = "Provision"
@@ -77,7 +78,7 @@ class WALAEventOperation:
 class EventStatus(object):
     EVENT_STATUS_FILE = "event_status.json"
 
-    def __init__(self, status_dir=conf.get_lib_dir()):
+    def __init__(self):
         self._path = None
         self._status = {}
 
@@ -92,7 +93,7 @@ class EventStatus(object):
         event = self._event_name(name, version, op)
         if event not in self._status:
             return True
-        return self._status[event] == True
+        return self._status[event] is True
 
     def initialize(self, status_dir=conf.get_lib_dir()):
         self._path = os.path.join(status_dir, EventStatus.EVENT_STATUS_FILE)
@@ -100,7 +101,7 @@ class EventStatus(object):
 
     def mark_event_status(self, name, version, op, status):
         event = self._event_name(name, version, op)
-        self._status[event] = (status == True)
+        self._status[event] = (status is True)
         self._save()
 
     def _event_name(self, name, version, op):
@@ -123,6 +124,7 @@ class EventStatus(object):
         except Exception as e:
             logger.warn("Exception occurred saving event status: {0}".format(e))
 
+
 __event_status__ = EventStatus()
 __event_status_operations__ = [
         WALAEventOperation.AutoUpdate,
@@ -225,6 +227,20 @@ class EventLogger(object):
         except EventError as e:
             logger.error("{0}", e)
 
+    def add_log_event(self, level, message):
+        event = TelemetryEvent(7, "FFF0196F-EE4C-4EAF-9AA5-776F622DEB4F")
+        event.parameters.append(TelemetryEventParam('EventName', WALAEventOperation.Log))
+        event.parameters.append(TelemetryEventParam('CapabilityUsed', logger.LogLevel.STRINGS[level]))
+        event.parameters.append(TelemetryEventParam('Context1', ''))
+        event.parameters.append(TelemetryEventParam('Context2', str(CURRENT_AGENT)))
+        event.parameters.append(TelemetryEventParam('Context3', str(message)))
+
+        data = get_properties(event)
+        try:
+            self.save_event(json.dumps(data))
+        except EventError:
+            pass
+
 
 __event_logger__ = EventLogger()
 
@@ -234,6 +250,7 @@ def elapsed_milliseconds(utc_start):
     return int(((d.days * 24 * 60 * 60 + d.seconds) * 1000) + \
                     (d.microseconds / 1000.0))
 
+
 def report_event(op, is_success=True, message=''):
     from azurelinuxagent.common.version import AGENT_NAME, CURRENT_VERSION
     add_event(AGENT_NAME,
@@ -242,6 +259,7 @@ def report_event(op, is_success=True, message=''):
               message=message,
               op=op)
 
+
 def report_periodic(delta, op, is_success=True, message=''):
     from azurelinuxagent.common.version import AGENT_NAME, CURRENT_VERSION
     add_periodic(delta, AGENT_NAME,
@@ -250,6 +268,7 @@ def report_periodic(delta, op, is_success=True, message=''):
               message=message,
               op=op)
 
+
 def add_event(name, op=WALAEventOperation.Unknown, is_success=True, duration=0,
               version=CURRENT_VERSION,
               message="", evt_type="", is_internal=False, log_event=True,
@@ -266,6 +285,14 @@ def add_event(name, op=WALAEventOperation.Unknown, is_success=True, duration=0,
             version=str(version), message=message, evt_type=evt_type,
             is_internal=is_internal, log_event=log_event)
 
+
+def add_log_event(level, message, reporter=__event_logger__):
+    if reporter.event_dir is None:
+        return
+
+    reporter.add_log_event(level, message)
+
+
 def add_periodic(
     delta, name, op=WALAEventOperation.Unknown, is_success=True, duration=0,
     version=CURRENT_VERSION,
@@ -281,10 +308,12 @@ def add_periodic(
         version=str(version), message=message, evt_type=evt_type,
         is_internal=is_internal, log_event=log_event, force=force)
 
+
 def mark_event_status(name, version, op, status):
     if op in __event_status_operations__:
         __event_status__.mark_event_status(name, version, op, status)
 
+
 def should_emit_event(name, version, op, status):
     return \
         op not in __event_status_operations__ or \
@@ -292,12 +321,15 @@ def should_emit_event(name, version, op, status):
         not __event_status__.event_marked(name, version, op) or \
         __event_status__.event_succeeded(name, version, op) != status
 
+
 def init_event_logger(event_dir):
     __event_logger__.event_dir = event_dir
 
+
 def init_event_status(status_dir):
     __event_status__.initialize(status_dir)
 
+
 def dump_unhandled_err(name):
     if hasattr(sys, 'last_type') and hasattr(sys, 'last_value') and \
             hasattr(sys, 'last_traceback'):
diff --git a/azurelinuxagent/common/exception.py b/azurelinuxagent/common/exception.py
index 51411935..bb8ab109 100644
--- a/azurelinuxagent/common/exception.py
+++ b/azurelinuxagent/common/exception.py
@@ -44,7 +44,7 @@ class AgentConfigError(AgentError):
 
 class AgentNetworkError(AgentError):
     """
-    When network is not avaiable.
+    When network is not available\.
     """
 
     def __init__(self, msg=None, inner=None):
@@ -86,6 +86,7 @@ class DhcpError(AgentError):
     def __init__(self, msg=None, inner=None):
         super(DhcpError, self).__init__(msg, inner)
 
+
 class OSUtilError(AgentError):
     """
     Failed to perform operation to OS configuration
diff --git a/azurelinuxagent/common/logger.py b/azurelinuxagent/common/logger.py
index bfdc73aa..0a90718d 100644
--- a/azurelinuxagent/common/logger.py
+++ b/azurelinuxagent/common/logger.py
@@ -17,8 +17,8 @@
 """
 Log utils
 """
-import os
 import sys
+
 from azurelinuxagent.common.future import ustr
 from datetime import datetime, timedelta
 
@@ -28,6 +28,7 @@ EVERY_HOUR = timedelta(hours=1)
 EVERY_HALF_HOUR = timedelta(minutes=30)
 EVERY_FIFTEEN_MINUTES = timedelta(minutes=15)
 
+
 class Logger(object):
     """
     Logger class
@@ -92,6 +93,7 @@ class Logger(object):
         appender = _create_logger_appender(appender_type, level, path)
         self.appenders.append(appender)
 
+
 class ConsoleAppender(object):
     def __init__(self, level, path):
         self.level = level
@@ -105,6 +107,7 @@ class ConsoleAppender(object):
             except IOError:
                 pass
 
+
 class FileAppender(object):
     def __init__(self, level, path):
         self.level = level
@@ -118,6 +121,7 @@ class FileAppender(object):
             except IOError:
                 pass
 
+
 class StdoutAppender(object):
     def __init__(self, level):
         self.level = level
@@ -129,9 +133,24 @@ class StdoutAppender(object):
             except IOError:
                 pass
 
+
+class TelemetryAppender(object):
+    def __init__(self, level, event_func):
+        self.level = level
+        self.event_func = event_func
+
+    def write(self, level, msg):
+        if self.level <= level:
+            try:
+                self.event_func(level, msg)
+            except IOError:
+                pass
+
+
 #Initialize logger instance
 DEFAULT_LOGGER = Logger()
 
+
 class LogLevel(object):
     VERBOSE = 0
     INFO = 1
@@ -144,35 +163,46 @@ class LogLevel(object):
         "ERROR"
     ]
 
+
 class AppenderType(object):
     FILE = 0
     CONSOLE = 1
     STDOUT = 2
+    TELEMETRY = 3
+
 
 def add_logger_appender(appender_type, level=LogLevel.INFO, path=None):
     DEFAULT_LOGGER.add_appender(appender_type, level, path)
 
+
 def reset_periodic():
     DEFAULT_LOGGER.reset_periodic()
 
+
 def periodic(delta, msg_format, *args):
     DEFAULT_LOGGER.periodic(delta, msg_format, *args)
 
+
 def verbose(msg_format, *args):
     DEFAULT_LOGGER.verbose(msg_format, *args)
 
+
 def info(msg_format, *args):
     DEFAULT_LOGGER.info(msg_format, *args)
 
+
 def warn(msg_format, *args):
     DEFAULT_LOGGER.warn(msg_format, *args)
 
+
 def error(msg_format, *args):
     DEFAULT_LOGGER.error(msg_format, *args)
 
+
 def log(level, msg_format, *args):
     DEFAULT_LOGGER.log(level, msg_format, args)
 
+
 def _create_logger_appender(appender_type, level=LogLevel.INFO, path=None):
     if appender_type == AppenderType.CONSOLE:
         return ConsoleAppender(level, path)
@@ -180,6 +210,8 @@ def _create_logger_appender(appender_type, level=LogLevel.INFO, path=None):
         return FileAppender(level, path)
     elif appender_type == AppenderType.STDOUT:
         return StdoutAppender(level)
+    elif appender_type == AppenderType.TELEMETRY:
+        return TelemetryAppender(level, path)
     else:
         raise ValueError("Unknown appender type")
 
diff --git a/azurelinuxagent/common/utils/fileutil.py b/azurelinuxagent/common/utils/fileutil.py
index 7846506a..1f0c7ac4 100644
--- a/azurelinuxagent/common/utils/fileutil.py
+++ b/azurelinuxagent/common/utils/fileutil.py
@@ -27,7 +27,6 @@ import os
 import pwd
 import re
 import shutil
-import string
 
 import azurelinuxagent.common.logger as logger
 import azurelinuxagent.common.utils.textutil as textutil
diff --git a/azurelinuxagent/common/version.py b/azurelinuxagent/common/version.py
index f97e7f99..71f982b2 100644
--- a/azurelinuxagent/common/version.py
+++ b/azurelinuxagent/common/version.py
@@ -161,14 +161,17 @@ def set_current_agent():
         version = AGENT_VERSION
     return agent, FlexibleVersion(version)
 
+
 def is_agent_package(path):
     path = os.path.basename(path)
     return not re.match(AGENT_PKG_PATTERN, path) is None
 
+
 def is_agent_path(path):
     path = os.path.basename(path)
     return not re.match(AGENT_NAME_PATTERN, path) is None
 
+
 CURRENT_AGENT, CURRENT_VERSION = set_current_agent()
 
 
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index b6414913..67e6c329 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -50,7 +50,7 @@ from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.osutil import get_osutil
 from azurelinuxagent.common.protocol import get_protocol_util
 from azurelinuxagent.common.protocol.hostplugin import HostPluginProtocol
-from azurelinuxagent.common.protocol.wire import WireProtocol, RestartError
+from azurelinuxagent.common.protocol.wire import WireProtocol
 from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
 from azurelinuxagent.common.version import AGENT_NAME, AGENT_VERSION, AGENT_LONG_VERSION, \
                                             AGENT_DIR_GLOB, AGENT_PKG_GLOB, \
@@ -284,10 +284,7 @@ class UpdateHandler(object):
                 utc_start = datetime.utcnow()
 
                 last_etag = exthandlers_handler.last_etag
-                try:
-                    exthandlers_handler.run()
-                except RestartError:
-                    continue
+                exthandlers_handler.run()
 
                 if last_etag != exthandlers_handler.last_etag:
                     self._ensure_readonly_files()
@@ -299,7 +296,7 @@ class UpdateHandler(object):
                         duration=elapsed_milliseconds(utc_start),
                         message="Incarnation {0}".format(
                                             exthandlers_handler.last_etag),
-                        log_event=exthandlers_handler.log_process)
+                        log_event=True)
 
                 time.sleep(GOAL_STATE_INTERVAL)
 
@@ -708,13 +705,13 @@ class GuestAgent(object):
         version = None
         if path is not None:
             m = AGENT_DIR_PATTERN.match(path)
-            if m is None:
+            if m == None:
                 raise UpdateError(u"Illegal agent directory: {0}".format(path))
             version = m.group(1)
         elif self.pkg is not None:
             version = pkg.version
 
-        if version is None:
+        if version == None:
             raise UpdateError(u"Illegal agent version: {0}".format(version))
         self.version = FlexibleVersion(version)
 


Test patch:
diff --git a/tests/common/test_event.py b/tests/common/test_event.py
index d52d3e64..01bcd7b9 100644
--- a/tests/common/test_event.py
+++ b/tests/common/test_event.py
@@ -49,8 +49,7 @@ class TestEvent(AgentTestCase):
         self.assertTrue(es.event_succeeded("Foo", "1.2", "FauxOperation"))
 
     def test_event_status_records_status(self):
-        d = tempfile.mkdtemp()
-        es = event.EventStatus(tempfile.mkdtemp())
+        es = event.EventStatus()
 
         es.mark_event_status("Foo", "1.2", "FauxOperation", True)
         self.assertTrue(es.event_succeeded("Foo", "1.2", "FauxOperation"))
@@ -70,7 +69,7 @@ class TestEvent(AgentTestCase):
         self.assertFalse(es.event_succeeded("Foo", "1.2", "FauxOperation"))
 
     def test_should_emit_event_ignores_unknown_operations(self):
-        event.__event_status__ = event.EventStatus(tempfile.mkdtemp())
+        event.__event_status__ = event.EventStatus()
 
         self.assertTrue(event.should_emit_event("Foo", "1.2", "FauxOperation", True))
         self.assertTrue(event.should_emit_event("Foo", "1.2", "FauxOperation", False))
@@ -83,7 +82,7 @@ class TestEvent(AgentTestCase):
 
 
     def test_should_emit_event_handles_known_operations(self):
-        event.__event_status__ = event.EventStatus(tempfile.mkdtemp())
+        event.__event_status__ = event.EventStatus()
 
         # Known operations always initially "fire"
         for op in event.__event_status_operations__:
diff --git a/tests/common/test_logger.py b/tests/common/test_logger.py
index 9e298b31..4727be61 100644
--- a/tests/common/test_logger.py
+++ b/tests/common/test_logger.py
@@ -15,17 +15,20 @@
 # Requires Python 2.4+ and Openssl 1.0+
 #
 
+import json
 from datetime import datetime
 
 import azurelinuxagent.common.logger as logger
+from azurelinuxagent.common.event import add_log_event
+from azurelinuxagent.common.version import CURRENT_AGENT, CURRENT_VERSION
 
 from tests.tools import *
 
 _MSG = "This is our test logging message {0} {1}"
 _DATA = ["arg1", "arg2"]
 
-class TestLogger(AgentTestCase):
 
+class TestLogger(AgentTestCase):
     @patch('azurelinuxagent.common.logger.Logger.info')
     def test_periodic_emits_if_not_previously_sent(self, mock_info):
         logger.reset_periodic()
@@ -64,3 +67,38 @@ class TestLogger(AgentTestCase):
 
         logger.periodic(logger.EVERY_DAY, _MSG, *_DATA)
         mock_info.assert_called_once_with(_MSG, *_DATA)
+
+    def test_telemetry_logger(self):
+        mock = MagicMock()
+        appender = logger.TelemetryAppender(logger.LogLevel.WARNING, mock)
+        appender.write(logger.LogLevel.WARNING, "--unit-test--")
+
+        mock.assert_called_once_with(logger.LogLevel.WARNING, "--unit-test--")
+
+    @patch('azurelinuxagent.common.event.EventLogger.save_event')
+    def test_telemetry_logger1(self, mock_save):
+        appender = logger.TelemetryAppender(logger.LogLevel.WARNING, add_log_event)
+        appender.write(logger.LogLevel.WARNING, "--unit-test--")
+
+        self.assertEqual(1, mock_save.call_count)
+        telemetry_json = json.loads(mock_save.call_args[0][0])
+
+        self.assertEqual('FFF0196F-EE4C-4EAF-9AA5-776F622DEB4F', telemetry_json['providerId'])
+        self.assertEqual(7, telemetry_json['eventId'])
+
+        self.assertEqual(5, len(telemetry_json['parameters']))
+        for x in telemetry_json['parameters']:
+            if x['name'] == 'EventName':
+                self.assertEqual('Log', x['value'])
+
+            elif x['name'] == 'CapabilityUsed':
+                self.assertEqual('WARNING', x['value'])
+
+            elif x['name'] == 'Context1':
+                self.assertEqual('', x['value'])
+
+            elif x['name'] == 'Context2':
+                self.assertEqual(CURRENT_AGENT, x['value'])
+
+            elif x['name'] == 'Context3':
+                self.assertEqual("--unit-test--", x['value'])
diff --git a/tests/ga/test_update.py b/tests/ga/test_update.py
index a40278c7..d9547446 100644
--- a/tests/ga/test_update.py
+++ b/tests/ga/test_update.py
@@ -17,17 +17,12 @@
 
 from __future__ import print_function
 
-from datetime import datetime
-
-import json
-import shutil
-import stat
-
 from azurelinuxagent.common.event import *
 from azurelinuxagent.common.protocol.hostplugin import *
 from azurelinuxagent.common.protocol.metadata import *
 from azurelinuxagent.common.protocol.wire import *
 from azurelinuxagent.common.utils.fileutil import *
+from azurelinuxagent.common.version import AGENT_PKG_GLOB, AGENT_DIR_GLOB
 from azurelinuxagent.ga.update import *
 
 from tests.tools import *