From fca4fa78fb9c6473b2df35e808afc2b8698f2ea6 Mon Sep 17 00:00:00 2001 From: Brendan Dixon Date: Wed, 6 Jul 2016 14:58:21 -0700 Subject: [PATCH] Improved telemetry and enabled re-spawning of child process Signed-off-by: Brendan Dixon --- azurelinuxagent/common/event.py | 8 +- azurelinuxagent/common/version.py | 26 ++++ azurelinuxagent/ga/exthandlers.py | 11 +- azurelinuxagent/ga/update.py | 202 ++++++++++++++++++------------ tests/common/test_version.py | 65 ++++++++++ tests/ga/test_update.py | 40 +++--- 6 files changed, 243 insertions(+), 109 deletions(-) create mode 100644 tests/common/test_version.py diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py index 2ab2ef2..374b0e7 100644 --- a/azurelinuxagent/common/event.py +++ b/azurelinuxagent/common/event.py @@ -71,11 +71,11 @@ class EventLogger(object): except IOError as e: raise EventError("Failed to write events to file:{0}", e) - def add_event(self, name, op="", is_success=True, duration=0, version="1.0", + def add_event(self, name, op="", is_success=True, duration=0, version=AGENT_VERSION, message="", evt_type="", is_internal=False): event = TelemetryEvent(1, "69B669B9-4AF8-4C50-BDC4-6006FA76E975") event.parameters.append(TelemetryEventParam('Name', name)) - event.parameters.append(TelemetryEventParam('Version', version)) + event.parameters.append(TelemetryEventParam('Version', str(version))) event.parameters.append(TelemetryEventParam('IsInternal', is_internal)) event.parameters.append(TelemetryEventParam('Operation', op)) event.parameters.append(TelemetryEventParam('OperationSuccess', @@ -92,7 +92,7 @@ class EventLogger(object): __event_logger__ = EventLogger() -def add_event(name, op="", is_success=True, duration=0, version="1.0", +def add_event(name, op="", is_success=True, duration=0, version=AGENT_VERSION, message="", evt_type="", is_internal=False, reporter=__event_logger__): log = logger.info if is_success else logger.error @@ -102,7 +102,7 @@ def add_event(name, op="", is_success=True, duration=0, version="1.0", logger.warn("Event reporter is not initialized.") return reporter.add_event(name, op=op, is_success=is_success, duration=duration, - version=version, message=message, evt_type=evt_type, + version=str(version), message=message, evt_type=evt_type, is_internal=is_internal) def init_event_logger(event_dir, reporter=__event_logger__): diff --git a/azurelinuxagent/common/version.py b/azurelinuxagent/common/version.py index f578342..7a35d89 100644 --- a/azurelinuxagent/common/version.py +++ b/azurelinuxagent/common/version.py @@ -19,7 +19,10 @@ import os import re import platform import sys + +import azurelinuxagent.common.conf as conf import azurelinuxagent.common.utils.fileutil as fileutil +from azurelinuxagent.common.utils.flexible_version import FlexibleVersion from azurelinuxagent.common.future import ustr @@ -55,6 +58,29 @@ VMs in the Azure cloud. This package should be installed on Linux disk images that are built to run in the Azure environment. """ +AGENT_DIR_GLOB = "{0}-*".format(AGENT_NAME) +AGENT_PKG_GLOB = "{0}-*.zip".format(AGENT_NAME) + +AGENT_PATTERN = "{0}-(.*)".format(AGENT_NAME) +AGENT_NAME_PATTERN = re.compile(AGENT_PATTERN) +AGENT_DIR_PATTERN = re.compile(".*/{0}".format(AGENT_PATTERN)) + + +def set_current_agent(): + path = os.getcwd() + lib_dir = conf.get_lib_dir() + if lib_dir[-1] != os.path.sep: + lib_dir += os.path.sep + if path[:len(lib_dir)] != lib_dir: + agent = AGENT_LONG_VERSION + version = AGENT_VERSION + else: + agent = path[len(lib_dir):].split(os.path.sep)[0] + version = AGENT_NAME_PATTERN.match(agent).group(1) + return agent, FlexibleVersion(version) +CURRENT_AGENT, CURRENT_VERSION = set_current_agent() + + __distro__ = get_distro() DISTRO_NAME = __distro__[0] DISTRO_VERSION = __distro__[1] diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py index abed90e..1e6ca43 100644 --- a/azurelinuxagent/ga/exthandlers.py +++ b/azurelinuxagent/ga/exthandlers.py @@ -45,6 +45,7 @@ from azurelinuxagent.common.protocol.restapi import ExtHandlerStatus, \ from azurelinuxagent.common.utils.flexible_version import FlexibleVersion from azurelinuxagent.common.utils.textutil import Version from azurelinuxagent.common.protocol import get_protocol_util +from azurelinuxagent.common.version import AGENT_NAME, CURRENT_AGENT, CURRENT_VERSION #HandlerEnvironment.json schema version HANDLER_ENVIRONMENT_VERSION = 1.0 @@ -131,7 +132,7 @@ class ExtHandlersHandler(object): msg = u"Exception retrieving extension handlers: {0}".format( ustr(e)) logger.warn(msg) - add_event(name="WALA", is_success=False, message=msg) + add_event(AGENT_NAME, version=CURRENT_VERSION, is_success=False, message=msg) return if self.last_etag is not None and self.last_etag == etag: @@ -238,7 +239,11 @@ class ExtHandlersHandler(object): try: self.report_ext_handler_status(vm_status, ext_handler) except ExtensionError as e: - add_event(name="WALA", is_success=False, message=ustr(e)) + add_event( + AGENT_NAME, + version=CURRENT_VERSION, + is_success=False, + message=ustr(e)) logger.verbose("Report vm agent status") @@ -246,7 +251,7 @@ class ExtHandlersHandler(object): self.protocol.report_vm_status(vm_status) except ProtocolError as e: message = "Failed to report vm agent status: {0}".format(e) - add_event(name="WALA", is_success=False, message=message) + add_event(AGENT_NAME, version=CURRENT_VERSION, is_success=False, message=message) if self.log_report: logger.verbose("Successfully reported vm agent status") diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py index 151a74b..0d69f52 100644 --- a/azurelinuxagent/ga/update.py +++ b/azurelinuxagent/ga/update.py @@ -35,39 +35,23 @@ import azurelinuxagent.common.utils.fileutil as fileutil import azurelinuxagent.common.utils.restutil as restutil import azurelinuxagent.common.utils.textutil as textutil -from azurelinuxagent.common.event import add_event +from azurelinuxagent.common.event import add_event, WALAEventOperation from azurelinuxagent.common.exception import UpdateError, ProtocolError from azurelinuxagent.common.future import ustr from azurelinuxagent.common.osutil import get_osutil from azurelinuxagent.common.protocol import get_protocol_util from azurelinuxagent.common.utils.flexible_version import FlexibleVersion -from azurelinuxagent.common.version import AGENT_NAME, AGENT_VERSION +from azurelinuxagent.common.version import AGENT_NAME, AGENT_VERSION, AGENT_LONG_VERSION, \ + AGENT_DIR_GLOB, AGENT_PKG_GLOB, \ + AGENT_PATTERN, AGENT_NAME_PATTERN, AGENT_DIR_PATTERN, \ + CURRENT_AGENT, CURRENT_VERSION from azurelinuxagent.ga.exthandlers import HandlerManifest -AGENT_DIR_GLOB = "{0}-*".format(AGENT_NAME) -AGENT_PKG_GLOB = "{0}-*.zip".format(AGENT_NAME) - -AGENT_NAME_PATTERN = re.compile(".*/{0}-(.*)".format(AGENT_NAME)) - AGENT_ERROR_FILE = "error.json" # File name for agent error record AGENT_MANIFEST_FILE = "HandlerManifest.json" -EMPTY_MANIFEST = { - "name": "WALinuxAgent", - "version": 1.0, - "handlerManifest": { - "installCommand": "", - "uninstallCommand": "", - "updateCommand": "", - "enableCommand": "", - "disableCommand": "", - "rebootAfterInstall": False, - "reportHeartbeat": False - } -} - MAX_FAILURE = 3 # Max failure allowed for agent before blacklisted GOAL_STATE_INTERVAL = 25 @@ -98,24 +82,27 @@ class UpdateHandler(object): self.child_process = None self.signal_handler = None - - self.current_agent = self._extract_name() return def run_latest(self): """ This method is called from the daemon to find and launch the most current, downloaded agent. + + Note: + - Most events should be tagged to the launched agent (agent_version) """ latest_agent = self.get_latest_agent() if latest_agent == None: agent_cmd = "python -u {0} -run-exthandlers".format(sys.argv[0]) agent_dir = os.getcwd() - agent_name = "'Installed'" + agent_name = CURRENT_AGENT + agent_version = CURRENT_VERSION else: agent_cmd = latest_agent.get_agent_cmd() agent_dir = latest_agent.get_agent_dir() agent_name = latest_agent.name + agent_version = latest_agent.version if self.child_process is not None: raise Exception("Illegal attempt to launch multiple child processes") @@ -137,7 +124,7 @@ class UpdateHandler(object): msg = u"Agent {0} launched with command '{1}'".format(agent_name, agent_cmd) logger.info(msg) - add_event(u"WALA", is_success=True, message=msg) + add_event(AGENT_NAME, version=agent_version, message=msg) ret = self.child_process.wait() if ret == None: @@ -148,7 +135,12 @@ class UpdateHandler(object): agent_cmd, ret) logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + add_event( + AGENT_NAME, + version=agent_version, + op=WALAEventOperation.Enable, + is_success=False, + message=msg) if latest_agent is not None: latest_agent.mark_failure() else: @@ -156,18 +148,36 @@ class UpdateHandler(object): agent_name, agent_cmd) logger.info(msg) - add_event(u"WALA", is_success=True, message=msg) + add_event( + AGENT_NAME, + version=agent_version, + op=WALAEventOperation.Enable, + is_success=True, + message=msg) except Exception as e: msg = u"Agent {0} launch failed with command '{1}' failed with exception: {2}".format( agent_name, agent_cmd, ustr(e)) logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + add_event( + AGENT_NAME, + version=agent_version, + op=WALAEventOperation.Enable, + is_success=False, + message=msg) if latest_agent is not None: latest_agent.mark_failure(is_fatal=True) + msg = u"Agent {0} is blacklisted".format(agent_name) + logger.info(msg) + add_event( + AGENT_NAME, + version=agent_version, + op=WALAEventOperation.Enable, + is_success=False, + message=msg) - sys.exit(0) + self.child_process = None return def run(self): @@ -178,9 +188,9 @@ class UpdateHandler(object): exthandlers_handler = get_exthandlers_handler() msg = u"Agent {0} is running as the current agent".format( - self.current_agent) + CURRENT_AGENT) logger.info(msg) - add_event(u"WALA", is_success=True, message=msg) + add_event(AGENT_NAME, version=CURRENT_VERSION, is_success=True, message=msg) # TODO: Add means to stop running try: @@ -190,9 +200,13 @@ class UpdateHandler(object): # true), exit to allow the daemon to respawn using that agent. if self._ensure_latest_agent(): msg = u"Agent {0} discovered agent update and will exit".format( - self.current_agent) + CURRENT_AGENT) logger.info(msg) - add_event(u"WALA", is_success=True, message=msg) + add_event( + AGENT_NAME, + version=CURRENT_VERSION, + is_success=True, + message=msg) break # Process extensions @@ -201,9 +215,14 @@ class UpdateHandler(object): time.sleep(25) except Exception as e: - msg = u"Agent {0} failed with exception: {1}".format(self.current_agent, ustr(e)) + msg = u"Agent {0} failed with exception: {1}".format(CURRENT_AGENT, ustr(e)) logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + add_event( + AGENT_NAME, + version=CURRENT_VERSION, + op=WALAEventOperation.Enable, + is_success=False, + message=msg) sys.exit(1) sys.exit(0) return @@ -254,13 +273,17 @@ class UpdateHandler(object): except Exception as e: msg = u"Exception retrieving agent manifests: {0}".format(ustr(e)) logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + add_event( + AGENT_NAME, + version=CURRENT_VERSION, + is_success=False, + message=msg) return False if self.last_etag is not None and self.last_etag == etag: msg = u"Incarnation {0} has no agent updates".format(etag) logger.info(msg) - add_event(u"WALA", message=msg) + add_event(AGENT_NAME, version=CURRENT_VERSION, message=msg) return False logger.info("Check for agent updates") @@ -270,7 +293,7 @@ class UpdateHandler(object): if len(manifests) == 0: msg = u"Incarnation {0} has no agent family {1} updates".format(etag, family) logger.info(msg) - add_event(u"WALA", message=msg) + add_event(AGENT_NAME, version=CURRENT_VERSION, message=msg) return False try: @@ -280,7 +303,11 @@ class UpdateHandler(object): family, ustr(e)) logger.warn(msg) - add_event("WALA", is_success=False, message=msg) + add_event( + AGENT_NAME, + version=CURRENT_VERSION, + is_success=False, + message=msg) return False # Set the agents to those available for download at least as current as the existing agent @@ -298,15 +325,6 @@ class UpdateHandler(object): # Return True if agents more recent than the current are available return len(self.agents) > 0 and self.agents[0].version > current_version - def _extract_name(self): - path = os.getcwd() - lib_dir = conf.get_lib_dir() - if lib_dir[-1] != os.path.sep: - lib_dir += os.path.sep - if path[:len(lib_dir)] != lib_dir: - return "Installed" - return path[len(lib_dir):].split(os.path.sep)[0] - def _filter_blacklisted_agents(self): self.agents = [agent for agent in self.agents if not agent.is_blacklisted] return @@ -323,7 +341,11 @@ class UpdateHandler(object): self._filter_blacklisted_agents() except Exception as e: msg = u"Exception occurred loading available agents: {0}".format(ustr(e)) - add_event(u"WALA", is_success=False, message=msg) + add_event( + AGENT_NAME, + version=CURRENT_VERSION, + is_success=False, + message=msg) return def _purge_agents(self): @@ -335,7 +357,7 @@ class UpdateHandler(object): for agent_path in glob.iglob(path): try: name = fileutil.trim_ext(agent_path, "zip") - m = AGENT_NAME_PATTERN.match(name) + m = AGENT_DIR_PATTERN.match(name) if m is not None and not FlexibleVersion(m.group(1)) in known_versions: if os.path.isfile(agent_path): os.remove(agent_path) @@ -344,7 +366,11 @@ class UpdateHandler(object): except Exception as e: msg = u"Exception purging {0}: {1}".format(agent_path, ustr(e)) logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + add_event( + AGENT_NAME, + version=CURRENT_VERSION, + is_success=False, + message=msg) return def _set_agents(self, agents=[]): @@ -357,7 +383,7 @@ class GuestAgent(object): def __init__(self, path=None, pkg=None): self.pkg = pkg if path is not None: - m = AGENT_NAME_PATTERN.match(path) + m = AGENT_DIR_PATTERN.match(path) if m == None: raise UpdateError(u"Illegal agent directory: {0}".format(path)) version = m.group(1) @@ -408,14 +434,19 @@ class GuestAgent(object): return os.path.isfile(self.get_agent_manifest_path()) def mark_failure(self, is_fatal=False): - if not os.path.isdir(self.get_agent_dir()): - os.makedirs(self.get_agent_dir()) - self.error.mark_failure(is_fatal) - self.error.save() - if is_fatal: - msg = u"Agent {0} is permenantly blacklisted".format(self.name) + try: + if not os.path.isdir(self.get_agent_dir()): + os.makedirs(self.get_agent_dir()) + self.error.mark_failure(is_fatal) + self.error.save() + if is_fatal: + msg = u"Agent {0} is permenantly blacklisted".format(self.name) + logger.warn(msg) + add_event(AGENT_NAME, version=self.version, is_success=False, message=msg) + except Exception as e: + msg = u"Agent {0} failed recording error state: {1}".format(ustr(e)) logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + add_event(AGENT_NAME, version=self.version, is_success=False, message=msg) return def _ensure_downloaded(self): @@ -423,7 +454,7 @@ class GuestAgent(object): if self.is_blacklisted: msg = u"Agent {0} is blacklisted - skipping download".format(self.name) logger.info(msg) - add_event(u"WALA", is_success=True, message=msg) + add_event(AGENT_NAME, version=self.version, is_success=True, message=msg) return if self.is_downloaded: @@ -439,6 +470,15 @@ class GuestAgent(object): self._load_manifest() self._load_error() + msg = u"Agent {0} downloaded successfully".format(self.name) + logger.info(msg) + add_event( + AGENT_NAME, + version=self.version, + op=WALAEventOperation.Install, + is_success=True, + message=msg) + except Exception as e: # Note the failure, blacklist the agent if the package downloaded # - An exception with a downloaded package indicates the package @@ -447,13 +487,18 @@ class GuestAgent(object): msg = u"Agent {0} download failed with exception: {1}".format(self.name, ustr(e)) logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + add_event( + AGENT_NAME, + version=self.version, + op=WALAEventOperation.Install, + is_success=False, + message=msg) return def _download(self): msg = u"Initiating download of Agent {0}".format(self.name) logger.info(msg) - add_event(u"WALA", message=msg) + add_event(AGENT_NAME, version=self.version, message=msg) package = None for uri in self.pkg.uris: @@ -466,7 +511,7 @@ class GuestAgent(object): except restutil.HttpError as e: msg = u"Agent {0} download from {1} failed".format(self.name, uri.uri) logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + add_event(AGENT_NAME, version=self.version, is_success=False, message=msg) if not os.path.isfile(self.get_agent_pkg_path()): msg = u"Unable to download Agent {0} from any URI".format(self.name) @@ -474,9 +519,14 @@ class GuestAgent(object): return def _load_error(self): - if self.error is None: - self.error = GuestAgentError(self.get_agent_error_file()) - self.error.load() + try: + if self.error is None: + self.error = GuestAgentError(self.get_agent_error_file()) + self.error.load() + except Exception as e: + msg = u"Agent {0} failed loading error state: {1}".format(ustr(e)) + logger.warn(msg) + add_event(AGENT_NAME, version=self.version, is_success=False, message=msg) return def _load_manifest(self): @@ -541,7 +591,7 @@ class GuestAgent(object): msg = u"Agent {0} successfully unpacked".format(self.name) logger.info(msg) - add_event(u"WALA", message=msg) + add_event(AGENT_NAME, version=self.version, message=msg) return @@ -580,24 +630,14 @@ class GuestAgentError(object): def load(self): if self.path is not None and os.path.isfile(self.path): - try: - with open(self.path, 'r') as f: - self.from_json(json.load(f)) - except Exception as e: - msg = u"Exception reading error record from {0}: {1}".format(self.path, ustr(e)) - logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + with open(self.path, 'r') as f: + self.from_json(json.load(f)) return def save(self): if os.path.isdir(os.path.dirname(self.path)): - try: - with open(self.path, 'w') as f: - json.dump(self.to_json(), f) - except Exception as e: - msg = u"Exception saving error record to {0}: {1}".format(self.path, ustr(e)) - logger.warn(msg) - add_event(u"WALA", is_success=False, message=msg) + with open(self.path, 'w') as f: + json.dump(self.to_json(), f) return def from_json(self, data): diff --git a/tests/common/test_version.py b/tests/common/test_version.py new file mode 100644 index 0000000..6a4dc38 --- /dev/null +++ b/tests/common/test_version.py @@ -0,0 +1,65 @@ +# Copyright 2014 Microsoft Corporation +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# +# Requires Python 2.4+ and Openssl 1.0+ +# + +from __future__ import print_function + +import copy +import glob +import json +import os +import platform +import random +import subprocess +import sys +import tempfile +import zipfile + +from tests.protocol.mockwiredata import * +from tests.tools import * + +import azurelinuxagent.common.conf as conf +import azurelinuxagent.common.logger as logger +import azurelinuxagent.common.utils.fileutil as fileutil + +from azurelinuxagent.common.utils.flexible_version import FlexibleVersion +from azurelinuxagent.common.version import * + + +class TestCurrentAgentName(AgentTestCase): + def setUp(self): + AgentTestCase.setUp(self) + return + + @patch("os.getcwd", return_value="/default/install/directory") + def test_extract_name_finds_installed(self, mock_cwd): + current_agent, current_version = set_current_agent() + self.assertEqual(AGENT_LONG_VERSION, current_agent) + self.assertEqual(AGENT_VERSION, str(current_version)) + return + + @patch("os.getcwd") + def test_extract_name_finds_latest_agent(self, mock_cwd): + path = os.path.join(conf.get_lib_dir(), "{0}-{1}".format( + AGENT_NAME, + "1.2.3")) + mock_cwd.return_value = path + agent = os.path.basename(path) + version = AGENT_NAME_PATTERN.match(agent).group(1) + current_agent, current_version = set_current_agent() + self.assertEqual(agent, current_agent) + self.assertEqual(version, str(current_version)) + return diff --git a/tests/ga/test_update.py b/tests/ga/test_update.py index 3036784..1a29b3f 100644 --- a/tests/ga/test_update.py +++ b/tests/ga/test_update.py @@ -53,6 +53,20 @@ WITH_ERROR = { "was_fatal" : False } +EMPTY_MANIFEST = { + "name": "WALinuxAgent", + "version": 1.0, + "handlerManifest": { + "installCommand": "", + "uninstallCommand": "", + "updateCommand": "", + "enableCommand": "", + "disableCommand": "", + "rebootAfterInstall": False, + "reportHeartbeat": False + } +} + def get_agent_pkgs(in_dir=os.path.join(data_dir, "ga")): path = os.path.join(in_dir, AGENT_PKG_GLOB) @@ -116,7 +130,7 @@ class UpdateTestCase(AgentTestCase): return get_agent_pkgs(in_dir=self.tmp_dir) def agent_versions(self): - v = [FlexibleVersion(AGENT_NAME_PATTERN.match(a).group(1)) for a in self.agent_dirs()] + v = [FlexibleVersion(AGENT_DIR_PATTERN.match(a).group(1)) for a in self.agent_dirs()] v.sort(reverse=True) return v @@ -638,20 +652,6 @@ class TestUpdate(UpdateTestCase): v = a.version return - @patch("os.getcwd", return_value="/default/install/directory") - def test_extract_name_finds_installed(self, mock_cwd): - self.assertEqual("Installed", self.update_handler._extract_name()) - return - - @patch("os.getcwd") - def test_extract_name_finds_latest_agent(self, mock_cwd): - self.prepare_agents() - mock_cwd.return_value = self.agent_dirs()[0] - self.assertEqual( - os.path.basename(self.agent_dirs()[0]), - self.update_handler._extract_name()) - return - def test_filter_blacklisted_agents(self): self.prepare_agents() @@ -759,13 +759,11 @@ class TestUpdate(UpdateTestCase): def _test_run_latest(self, return_value=0, side_effect=None): mock_child = Mock() mock_child.wait = Mock(return_value=return_value, side_effect=side_effect) - with patch('sys.exit', return_value=0) as mock_exit: - with patch('subprocess.Popen', return_value=mock_child) as mock_popen: - self.update_handler.run_latest() - self.assertEqual(1, len(mock_popen.mock_calls)) - self.assertEqual(1, len(mock_exit.mock_calls)) + with patch('subprocess.Popen', return_value=mock_child) as mock_popen: + self.update_handler.run_latest() + self.assertEqual(1, len(mock_popen.mock_calls)) - return mock_popen.call_args + return mock_popen.call_args def test_run_latest(self): self.prepare_agents()