Echo log to /dev/console during provisioning

azurelinuxagent/agent.py

@@ -37,10 +37,13 @@
 from azurelinuxagent.common.logcollector import LogCollector, OUTPUT_RESULTS_FILE_PATH
 from azurelinuxagent.common.osutil import get_osutil
 from azurelinuxagent.common.utils import fileutil
-from azurelinuxagent.common.version import AGENT_NAME, AGENT_LONG_VERSION, \
+from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
+from azurelinuxagent.common.version import AGENT_NAME, AGENT_LONG_VERSION, AGENT_VERSION, \
     DISTRO_NAME, DISTRO_VERSION, \
     PY_VERSION_MAJOR, PY_VERSION_MINOR, \
-    PY_VERSION_MICRO, GOAL_STATE_AGENT_VERSION
+    PY_VERSION_MICRO, GOAL_STATE_AGENT_VERSION, \
+    get_daemon_version, set_daemon_version
+from azurelinuxagent.pa.provision.default import ProvisionHandler
 
 
 class Agent(object):
@@ -64,8 +67,11 @@ def __init__(self, verbose, conf_file_path=None):
         # Init log
         verbose = verbose or conf.get_logs_verbose()
         level = logger.LogLevel.VERBOSE if verbose else logger.LogLevel.INFO
-        logger.add_logger_appender(logger.AppenderType.FILE, level,
-                                   path=conf.get_agent_log_file())
+        logger.add_logger_appender(logger.AppenderType.FILE, level, path=conf.get_agent_log_file())
+
+        # echo the log to /dev/console if the machine will be provisioned
+        if conf.get_logs_console() and not ProvisionHandler.is_provisioned():
+            self.__add_console_appender(level)
 
         if event.send_logs_to_telemetry():
             logger.add_logger_appender(logger.AppenderType.TELEMETRY,
@@ -94,10 +100,14 @@ def __init__(self, verbose, conf_file_path=None):
         event.init_event_logger(event_dir)
         event.enable_unhandled_err_dump("WALA")
 
+    def __add_console_appender(self, level):
+        logger.add_logger_appender(logger.AppenderType.CONSOLE, level, path="/dev/console")
+
     def daemon(self):
         """
         Run agent daemon
         """
+        set_daemon_version(AGENT_VERSION)
         logger.set_prefix("Daemon")
         threading.current_thread().setName("Daemon")
         child_args = None \
@@ -140,6 +150,21 @@ def run_exthandlers(self, debug=False):
         """
         logger.set_prefix("ExtHandler")
         threading.current_thread().setName("ExtHandler")
+
+        #
+        # Agents < 2.2.53 used to echo the log to the console. Since the extension handler could have been started by
+        # one of those daemons, output a message indicating that output to the console will stop, otherwise users
+        # may think that the agent died if they noticed that output to the console stops abruptly.
+        #
+        # Feel free to remove this code if telemetry shows there are no more agents <= 2.2.53 in the field.
+        #
+        if conf.get_logs_console() and get_daemon_version() < FlexibleVersion("2.2.53"):
+            self.__add_console_appender(logger.LogLevel.INFO)
+            try:
+                logger.info(u"The agent will now check for updates and then will process extensions. Output to /dev/console will be suspended during those operations.")
+            finally:
+                logger.disable_console_output()
+
         from azurelinuxagent.ga.update import get_update_handler
         update_handler = get_update_handler()
         update_handler.run(debug)

azurelinuxagent/common/logger.py

@@ -165,6 +165,18 @@ def add_appender(self, appender_type, level, path):
         appender = _create_logger_appender(appender_type, level, path)
         self.appenders.append(appender)
 
+    def console_output_enabled(self):
+        """
+        Returns True if the current list of appenders includes at least one ConsoleAppender
+        """
+        return any(isinstance(appender, ConsoleAppender) for appender in self.appenders)
+
+    def disable_console_output(self):
+        """
+        Removes all ConsoleAppenders from the current list of appenders
+        """
+        self.appenders = [appender for appender in self.appenders if not isinstance(appender, ConsoleAppender)]
+
 
 class Appender(object): # pylint: disable=R0903
     def __init__(self, level):
@@ -256,6 +268,14 @@ def add_logger_appender(appender_type, level=LogLevel.INFO, path=None):
     DEFAULT_LOGGER.add_appender(appender_type, level, path)
 
 
+def console_output_enabled():
+    return DEFAULT_LOGGER.console_output_enabled()
+
+
+def disable_console_output():
+    DEFAULT_LOGGER.disable_console_output()
+
+
 def reset_periodic():
     DEFAULT_LOGGER.reset_periodic()
 

azurelinuxagent/common/version.py

@@ -25,6 +25,32 @@
 from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
 from azurelinuxagent.common.future import ustr, get_linux_distribution
 
+__DAEMON_VERSION_ENV_VARIABLE = '_AZURE_GUEST_AGENT_DAEMON_VERSION_'
+"""
+    The daemon process sets this variable's value to the daemon's version number.
+    The variable is set only on versions >= 2.2.53
+"""
+
+
+def set_daemon_version(flexible_version):
+    """
+    Sets the value of the _AZURE_GUEST_AGENT_DAEMON_VERSION_ environment variable.
+    """
+    os.environ[__DAEMON_VERSION_ENV_VARIABLE] = ustr(flexible_version)
+
+
+def get_daemon_version():
+    """
+    Retrieves the value of the _AZURE_GUEST_AGENT_DAEMON_VERSION_ environment variable.
+    The value indicates the version of the daemon that started the current agent process or, if the current
+    process is the daemon, the version of the current process.
+    If the variable is not set (because the agent is < 2.2.53, or the process was not started by the daemon and
+    the process is not the daemon itself) the function returns "0.0.0.0"
+    """
+    if __DAEMON_VERSION_ENV_VARIABLE in os.environ:
+        return FlexibleVersion(os.environ[__DAEMON_VERSION_ENV_VARIABLE])
+    return FlexibleVersion("0.0.0.0")
+
 
 def get_f5_platform():
     """

azurelinuxagent/daemon/main.py

@@ -173,5 +173,10 @@ def daemon(self, child_args=None):
 
         self.sleep_if_disabled()
 
+        # Disable output to /dev/console once provisioning has completed
+        if logger.console_output_enabled():
+            logger.info("End of log to /dev/console. The agent will now check for updates and then will process extensions.")
+            logger.disable_console_output()
+
         while self.running:
             self.update_handler.run_latest(child_args=child_args)

azurelinuxagent/pa/provision/cloudinit.py

@@ -43,7 +43,7 @@ def __init__(self): # pylint: disable=W0235
 
     def run(self):
         try:
-            if super(CloudInitProvisionHandler, self).is_provisioned():
+            if super(CloudInitProvisionHandler, self).check_provisioned_file():
                 logger.info("Provisioning already completed, skipping.")
                 return
 

azurelinuxagent/pa/provision/default.py

@@ -64,7 +64,7 @@ def run(self):
             utc_start = datetime.utcnow()
             thumbprint = None # pylint: disable=W0612
 
-            if self.is_provisioned():
+            if self.check_provisioned_file():
                 logger.info("Provisioning already completed, skipping.")
                 return
 
@@ -165,26 +165,34 @@ def get_ssh_host_key_thumbprint(self, chk_err=True):
             raise ProvisionError(("Failed to generate ssh host key: "
                                   "ret={0}, out= {1}").format(ret[0], ret[1]))
 
-    def provisioned_file_path(self):
+    @staticmethod
+    def provisioned_file_path():
         return os.path.join(conf.get_lib_dir(), PROVISIONED_FILE)
 
-    def is_provisioned(self):
-        '''
-        A VM is considered provisionend *anytime* the provisioning
+    @staticmethod
+    def is_provisioned():
+        """
+        A VM is considered provisioned *anytime* the provisioning
         sentinel file exists and not provisioned *anytime* the file
         is absent.
+        """
+        return os.path.isfile(ProvisionHandler.provisioned_file_path())
 
+    def check_provisioned_file(self):
+        """
         If the VM was provisioned using an agent that did not record
         the VM unique identifier, the provisioning file will be re-written
         to include the identifier.
 
         A warning is logged *if* the VM unique identifier has changed
         since VM was provisioned.
-        '''
-        if not os.path.isfile(self.provisioned_file_path()):
+
+        Returns False if the VM has not been provisioned.
+        """
+        if not ProvisionHandler.is_provisioned():
             return False
 
-        s = fileutil.read_file(self.provisioned_file_path()).strip() # pylint: disable=C0103
+        s = fileutil.read_file(ProvisionHandler.provisioned_file_path()).strip() # pylint: disable=C0103
         if not self.osutil.is_current_instance_id(s):
             if len(s) > 0: # pylint: disable=len-as-condition
                 logger.warn("VM is provisioned, "
@@ -202,7 +210,7 @@ def is_provisioned(self):
 
     def write_provisioned(self):
         fileutil.write_file(
-            self.provisioned_file_path(),
+            ProvisionHandler.provisioned_file_path(),
             get_osutil().get_instance_id())
 
     @staticmethod

tests/common/test_logger.py

@@ -20,10 +20,7 @@
 import tempfile
 from datetime import datetime, timedelta
 
-# pylint: disable=unused-import
-from azurelinuxagent.common.event import __event_logger__, add_log_event, MAX_NUMBER_OF_EVENTS, TELEMETRY_LOG_EVENT_ID,\
-    TELEMETRY_LOG_PROVIDER_ID, EVENTS_DIRECTORY 
-# pylint: enable=unused-import
+from azurelinuxagent.common.event import __event_logger__, add_log_event, MAX_NUMBER_OF_EVENTS, EVENTS_DIRECTORY
 
 import azurelinuxagent.common.logger as logger
 from azurelinuxagent.common.utils import fileutil
@@ -565,3 +562,32 @@ def test_stdout_appender(self, mock_sys_stdout):
 
         # Validating only test-error gets logged and not others.
         self.assertEqual(1, mock_sys_stdout.call_count)
+
+    def test_console_output_enabled_should_return_true_when_there_are_no_console_appenders(self):
+        my_logger = logger.Logger()
+        my_logger.add_appender(logger.AppenderType.STDOUT, logger.LogLevel.INFO, None)
+        my_logger.add_appender(logger.AppenderType.CONSOLE, logger.LogLevel.INFO, None)
+
+        self.assertTrue(my_logger.console_output_enabled(), "Console output should be enabled, appenders = {0}".format(my_logger.appenders))
+
+    def test_console_output_enabled_should_return_false_when_there_are_no_console_appenders(self):
+        my_logger = logger.Logger()
+        my_logger.add_appender(logger.AppenderType.STDOUT, logger.LogLevel.INFO, None)
+
+        self.assertFalse(my_logger.console_output_enabled(), "Console output should not be enabled, appenders = {0}".format(my_logger.appenders))
+
+    def test_disable_console_output_should_remove_all_console_appenders(self):
+        my_logger = logger.Logger()
+        my_logger.add_appender(logger.AppenderType.STDOUT, logger.LogLevel.INFO, None)
+        my_logger.add_appender(logger.AppenderType.CONSOLE, logger.LogLevel.INFO, None)
+        my_logger.add_appender(logger.AppenderType.STDOUT, logger.LogLevel.INFO, None)
+        my_logger.add_appender(logger.AppenderType.CONSOLE, logger.LogLevel.INFO, None)
+
+        my_logger.disable_console_output()
+
+        self.assertTrue(
+            len(my_logger.appenders) == 2 and all(isinstance(a, logger.StdoutAppender) for a in my_logger.appenders),
+            "The console appender was not removed: {0}".format(my_logger.appenders))
+
+
+

tests/common/test_version.py

@@ -27,7 +27,8 @@
 from azurelinuxagent.common.version import set_current_agent, \
     AGENT_LONG_VERSION, AGENT_VERSION, AGENT_NAME, AGENT_NAME_PATTERN, \
     get_f5_platform, get_distro, get_lis_version, PY_VERSION_MAJOR, \
-    PY_VERSION_MINOR
+    PY_VERSION_MINOR, get_daemon_version, set_daemon_version, __DAEMON_VERSION_ENV_VARIABLE as DAEMON_VERSION_ENV_VARIABLE
+from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
 from tests.tools import AgentTestCase, open_patch, patch
 
 
@@ -123,6 +124,23 @@ def test_get_lis_version_should_return_a_string(self):
         lis_version = get_lis_version()
         self.assertIsInstance(lis_version, str)
 
+    def test_get_daemon_version_should_return_the_version_that_was_previously_set(self):
+        set_daemon_version("1.2.3.4")
+
+        try:
+            self.assertEqual(
+                FlexibleVersion("1.2.3.4"), get_daemon_version(),
+                "The daemon version should be 1.2.3.4. Environment={0}".format(os.environ)
+            )
+        finally:
+            os.environ.pop(DAEMON_VERSION_ENV_VARIABLE)
+
+    def test_get_daemon_version_should_return_zero_when_the_version_has_not_been_set(self):
+        self.assertEqual(
+            FlexibleVersion("0.0.0.0"), get_daemon_version(),
+            "The daemon version should not be defined. Environment={0}".format(os.environ)
+        )
+
 
 class TestCurrentAgentName(AgentTestCase):
     def setUp(self):

tests/pa/test_provision.py

@@ -66,26 +66,26 @@ def test_provisioning_is_skipped_when_not_enabled(self, mock_conf): # pylint: di
         ph.osutil.get_instance_id = Mock(
                         return_value='B9F3C233-9913-9F42-8EB3-BA656DF32502')
 
-        ph.is_provisioned = Mock()
+        ph.check_provisioned_file = Mock()
         ph.report_ready = Mock()
         ph.write_provisioned = Mock()
 
         ph.run()
 
-        self.assertEqual(0, ph.is_provisioned.call_count)
+        self.assertEqual(0, ph.check_provisioned_file.call_count)
         self.assertEqual(1, ph.report_ready.call_count)
         self.assertEqual(1, ph.write_provisioned.call_count)
 
     @patch('os.path.isfile', return_value=False)
-    def test_is_provisioned_not_provisioned(self, mock_isfile): # pylint: disable=unused-argument
+    def test_check_provisioned_file_not_provisioned(self, mock_isfile): # pylint: disable=unused-argument
         ph = ProvisionHandler() # pylint: disable=invalid-name
-        self.assertFalse(ph.is_provisioned())
+        self.assertFalse(ph.check_provisioned_file())
 
     @patch('os.path.isfile', return_value=True)
     @patch('azurelinuxagent.common.utils.fileutil.read_file',
             return_value="B9F3C233-9913-9F42-8EB3-BA656DF32502")
     @patch('azurelinuxagent.pa.deprovision.get_deprovision_handler')
-    def test_is_provisioned_is_provisioned(self,
+    def test_check_provisioned_file_is_provisioned(self,
             mock_deprovision, mock_read, mock_isfile): # pylint: disable=unused-argument
 
         ph = ProvisionHandler() # pylint: disable=invalid-name
@@ -96,15 +96,15 @@ def test_is_provisioned_is_provisioned(self,
         deprovision_handler = Mock()
         mock_deprovision.return_value = deprovision_handler
 
-        self.assertTrue(ph.is_provisioned())
+        self.assertTrue(ph.check_provisioned_file())
         self.assertEqual(1, ph.osutil.is_current_instance_id.call_count)
         self.assertEqual(0, deprovision_handler.run_changed_unique_id.call_count)
 
     @patch('os.path.isfile', return_value=True)
     @patch('azurelinuxagent.common.utils.fileutil.read_file',
             return_value="B9F3C233-9913-9F42-8EB3-BA656DF32502")
     @patch('azurelinuxagent.pa.deprovision.get_deprovision_handler')
-    def test_is_provisioned_not_deprovisioned(self,
+    def test_check_provisioned_file_not_deprovisioned(self,
             mock_deprovision, mock_read, mock_isfile): # pylint: disable=unused-argument
 
         ph = ProvisionHandler() # pylint: disable=invalid-name
@@ -116,7 +116,7 @@ def test_is_provisioned_not_deprovisioned(self,
         deprovision_handler = Mock()
         mock_deprovision.return_value = deprovision_handler
 
-        self.assertTrue(ph.is_provisioned())
+        self.assertTrue(ph.check_provisioned_file())
         self.assertEqual(1, ph.osutil.is_current_instance_id.call_count)
         self.assertEqual(1, deprovision_handler.run_changed_unique_id.call_count)