AMBARI-8923. Improve debug logging for tasks. (aonishuk)

ambari-agent/src/test/python/resource_management/TestPackageResource.py

@@ -36,11 +36,11 @@ class TestPackageResource(TestCase):
       Package("some_package",
       )
     call_mock.assert_has_calls([call("dpkg --get-selections | grep -v deinstall | awk '{print $1}' | grep ^some-package$"),
-                                call(['/usr/bin/apt-get', '-q', '-o', 'Dpkg::Options::=--force-confdef', '--allow-unauthenticated', '--assume-yes', 'install', 'some-package'], sudo=True, env={'DEBIAN_FRONTEND': 'noninteractive'}),
-                                call(['/usr/bin/apt-get', 'update', '-qq'], sudo=True)])
+                                call(['/usr/bin/apt-get', '-q', '-o', 'Dpkg::Options::=--force-confdef', '--allow-unauthenticated', '--assume-yes', 'install', 'some-package'], logoutput=False, sudo=True, env={'DEBIAN_FRONTEND': 'noninteractive'}),
+                                call(['/usr/bin/apt-get', 'update', '-qq'], logoutput=False, sudo=True)])
     
     shell_mock.assert_has_calls([call(['/usr/bin/apt-get', '-q', '-o', 'Dpkg::Options::=--force-confdef', 
-                                       '--allow-unauthenticated', '--assume-yes', 'install', 'some-package'], sudo=True)])
+                                       '--allow-unauthenticated', '--assume-yes', 'install', 'some-package'], logoutput=False, sudo=True)])
   
   @patch.object(shell, "call")
   @patch.object(shell, "checked_call")
@@ -51,7 +51,7 @@ class TestPackageResource(TestCase):
       Package("some_package",
       )
     call_mock.assert_has_calls([call("dpkg --get-selections | grep -v deinstall | awk '{print $1}' | grep ^some-package$"),
-                                call(['/usr/bin/apt-get', '-q', '-o', 'Dpkg::Options::=--force-confdef', '--allow-unauthenticated', '--assume-yes', 'install', 'some-package'], sudo=True, env={'DEBIAN_FRONTEND': 'noninteractive'})])
+                                call(['/usr/bin/apt-get', '-q', '-o', 'Dpkg::Options::=--force-confdef', '--allow-unauthenticated', '--assume-yes', 'install', 'some-package'], logoutput=False, sudo=True, env={'DEBIAN_FRONTEND': 'noninteractive'})])
     
     self.assertEqual(shell_mock.call_count, 0, "shell.checked_call shouldn't be called")
 
@@ -66,7 +66,7 @@ class TestPackageResource(TestCase):
       Package("some_package",
       )
     call_mock.assert_called_with('installed_pkgs=`rpm -qa some_package` ; [ ! -z "$installed_pkgs" ]')
-    shell_mock.assert_called_with(['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'install', 'some_package'], sudo=True)
+    shell_mock.assert_called_with(['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'install', 'some_package'], logoutput=False, sudo=True)
 
   @patch.object(shell, "call")
   @patch.object(shell, "checked_call")
@@ -77,7 +77,7 @@ class TestPackageResource(TestCase):
       Package("some_package",
       )
     call_mock.assert_called_with('installed_pkgs=`rpm -qa some_package` ; [ ! -z "$installed_pkgs" ]')
-    shell_mock.assert_called_with(['/usr/bin/zypper', '--quiet', 'install', '--auto-agree-with-licenses', '--no-confirm', 'some_package'], sudo=True)
+    shell_mock.assert_called_with(['/usr/bin/zypper', '--quiet', 'install', '--auto-agree-with-licenses', '--no-confirm', 'some_package'], logoutput=False, sudo=True)
 
   @patch.object(shell, "call", new = MagicMock(return_value=(0, None)))
   @patch.object(shell, "checked_call")
@@ -117,7 +117,7 @@ class TestPackageResource(TestCase):
       Package("some_package",
               action = "remove"
       )
-    shell_mock.assert_called_with(['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'erase', 'some_package'], sudo=True)
+    shell_mock.assert_called_with(['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'erase', 'some_package'], logoutput=False, sudo=True)
 
   @patch.object(shell, "call", new = MagicMock(return_value=(0, None)))
   @patch.object(shell, "checked_call")
@@ -127,7 +127,7 @@ class TestPackageResource(TestCase):
       Package("some_package",
               action = "remove"
       )
-    shell_mock.assert_called_with(['/usr/bin/zypper', '--quiet', 'remove', '--no-confirm', 'some_package'], sudo=True)
+    shell_mock.assert_called_with(['/usr/bin/zypper', '--quiet', 'remove', '--no-confirm', 'some_package'], logoutput=False, sudo=True)
 
   @patch.object(shell, "call", new = MagicMock(return_value=(1, None)))
   @patch.object(shell, "checked_call")
@@ -137,7 +137,7 @@ class TestPackageResource(TestCase):
       Package("some_package",
               version = "3.5.0"
       )
-    shell_mock.assert_called_with(['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'install', 'some_package-3.5.0'], sudo=True)
+    shell_mock.assert_called_with(['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'install', 'some_package-3.5.0'], logoutput=False, sudo=True)
 
   @replace_underscores
   def func_to_test(self, name):

ambari-common/src/main/python/resource_management/core/environment.py

@@ -23,6 +23,7 @@ Ambari Agent
 __all__ = ["Environment"]
 
 import os
+import logging
 import shutil
 import time
 from datetime import datetime
@@ -38,13 +39,16 @@ from resource_management.core.logger import Logger
 class Environment(object):
   _instances = []
 
-  def __init__(self, basedir=None, test_mode=False):
+  def __init__(self, basedir=None, test_mode=False, logging_level=logging.INFO):
     """
     @param basedir: basedir/files, basedir/templates are the places where templates / static files
     are looked up
     @param test_mode: if this is enabled, resources won't be executed until manualy running env.run().
     """
     self.reset(basedir, test_mode)
+    
+    if not Logger.logger:
+      Logger.initialize_logger(logging_level)
 
   def reset(self, basedir, test_mode):
     self.system = System.get_instance()
@@ -103,8 +107,6 @@ class Environment(object):
         self.config.params[variable] = value
         
   def run_action(self, resource, action):
-    Logger.debug("Performing action %s on %s" % (action, resource))
-
     provider_class = find_provider(self, resource.__class__.__name__,
                                    resource.provider)
     provider = provider_class(resource)

ambari-common/src/main/python/resource_management/core/logger.py

@@ -21,16 +21,36 @@ Ambari Agent
 """
 
 __all__ = ["Logger"]
+import sys
 import logging
 from resource_management.libraries.script.config_dictionary import UnknownConfiguration
 
 MESSAGE_MAX_LEN = 256
+DICTIONARY_MAX_LEN = 5
 
 class Logger:
-  logger = logging.getLogger("resource_management")
-
+  logger = None
   # unprotected_strings : protected_strings map
   sensitive_strings = {}
+  
+  @staticmethod
+  def initialize_logger(logging_level=logging.INFO, name='resource_management', format='%(asctime)s - %(message)s'):
+    # set up logging (two separate loggers for stderr and stdout with different loglevels)
+    logger = logging.getLogger(name)
+    logger.setLevel(logging_level)
+    formatter = logging.Formatter(format)
+    chout = logging.StreamHandler(sys.stdout)
+    chout.setLevel(logging_level)
+    chout.setFormatter(formatter)
+    cherr = logging.StreamHandler(sys.stderr)
+    cherr.setLevel(logging.ERROR)
+    cherr.setFormatter(formatter)
+    logger.addHandler(cherr)
+    logger.addHandler(chout)
+    
+    Logger.logger = logger
+    
+    return logger, chout, cherr
 
   @staticmethod
   def error(text):
@@ -78,13 +98,17 @@ class Logger:
       text = text.replace(placeholder, '')
 
     return text
-
+  
   @staticmethod
   def _get_resource_repr(resource):
+    return Logger.get_function_repr(repr(resource), resource.arguments)
+
+  @staticmethod
+  def get_function_repr(name, arguments):
     logger_level = logging._levelNames[Logger.logger.level]
 
     arguments_str = ""
-    for x,y in resource.arguments.iteritems():
+    for x,y in arguments.iteritems():
 
       # strip unicode 'u' sign
       if isinstance(y, unicode):
@@ -94,7 +118,7 @@ class Logger:
         val = repr(y).lstrip('u')
       # don't show dicts of configurations
       # usually too long
-      elif logger_level != 'DEBUG' and isinstance(y, dict):
+      elif isinstance(y, dict) and len(y) > DICTIONARY_MAX_LEN:
         val = "..."
       # for configs which didn't come
       elif isinstance(y, UnknownConfiguration):
@@ -118,4 +142,4 @@ class Logger:
     if arguments_str:
       arguments_str = arguments_str[:-2]
 
-    return unicode("{0} {{{1}}}").format(resource, arguments_str)
+    return unicode("{0} {{{1}}}").format(name, arguments_str)

ambari-common/src/main/python/resource_management/core/providers/package/__init__.py

@@ -20,8 +20,11 @@ Ambari Agent
 
 """
 
+import logging
+
 from resource_management.core.base import Fail
 from resource_management.core.providers import Provider
+from resource_management.core.logger import Logger
 
 
 class PackageProvider(Provider):
@@ -53,3 +56,7 @@ class PackageProvider(Provider):
     else:
       return self.resource.package_name
     
+  def get_logoutput(self):
+    return self.resource.logoutput==True and Logger.logger.isEnabledFor(logging.INFO) or self.resource.logoutput==None and Logger.logger.isEnabledFor(logging.DEBUG)
+    
+    

ambari-common/src/main/python/resource_management/core/providers/package/apt.py

@@ -25,9 +25,16 @@ from resource_management.core.shell import string_cmd_from_args_list
 from resource_management.core.logger import Logger
 
 INSTALL_CMD_ENV = {'DEBIAN_FRONTEND':'noninteractive'}
-INSTALL_CMD = ['/usr/bin/apt-get', '-q', '-o', "Dpkg::Options::=--force-confdef", '--allow-unauthenticated', '--assume-yes', 'install']
+INSTALL_CMD = {
+  True: ['/usr/bin/apt-get', '-o', "Dpkg::Options::=--force-confdef", '--allow-unauthenticated', '--assume-yes', 'install'],
+  False: ['/usr/bin/apt-get', '-q', '-o', "Dpkg::Options::=--force-confdef", '--allow-unauthenticated', '--assume-yes', 'install'],
+}
+REMOVE_CMD = {
+  True: ['/usr/bin/apt-get', '-y', 'remove'],
+  False: ['/usr/bin/apt-get', '-y', '-q', 'remove'],
+}
 REPO_UPDATE_CMD = ['/usr/bin/apt-get', 'update','-qq']
-REMOVE_CMD = ['/usr/bin/apt-get', '-y', '-q', 'remove']
+
 CHECK_CMD = "dpkg --get-selections | grep -v deinstall | awk '{print $1}' | grep ^%s$"
 
 def replace_underscores(function_to_decorate):
@@ -42,21 +49,21 @@ class AptProvider(PackageProvider):
   @replace_underscores
   def install_package(self, name, use_repos=[]):
     if not self._check_existence(name):
-      cmd = INSTALL_CMD + [name]
+      cmd = INSTALL_CMD[self.get_logoutput()]  + [name]
       Logger.info("Installing package %s ('%s')" % (name, string_cmd_from_args_list(cmd)))
-      code, out = shell.call(cmd, sudo=True, env=INSTALL_CMD_ENV)
+      code, out = shell.call(cmd, sudo=True, env=INSTALL_CMD_ENV, logoutput=self.get_logoutput())
       
       # apt-get update wasn't done too long
       if code:
         Logger.info("Execution of '%s' returned %d. %s" % (cmd, code, out))
         Logger.info("Failed to install package %s. Executing `%s`" % (name, string_cmd_from_args_list(REPO_UPDATE_CMD)))
-        code, out = shell.call(REPO_UPDATE_CMD, sudo=True)
+        code, out = shell.call(REPO_UPDATE_CMD, sudo=True, logoutput=self.get_logoutput())
         
         if code:
           Logger.info("Execution of '%s' returned %d. %s" % (REPO_UPDATE_CMD, code, out))
           
         Logger.info("Retrying to install package %s" % (name))
-        shell.checked_call(cmd, sudo=True)
+        shell.checked_call(cmd, sudo=True, logoutput=self.get_logoutput())
     else:
       Logger.info("Skipping installing existent package %s" % (name))
 
@@ -67,9 +74,9 @@ class AptProvider(PackageProvider):
   @replace_underscores
   def remove_package(self, name):
     if self._check_existence(name):
-      cmd = REMOVE_CMD + [name]
+      cmd = REMOVE_CMD[self.get_logoutput()] + [name]
       Logger.info("Removing package %s ('%s')" % (name, string_cmd_from_args_list(cmd)))
-      shell.checked_call(cmd, sudo=True)
+      shell.checked_call(cmd, sudo=True, logoutput=self.get_logoutput())
     else:
       Logger.info("Skipping removing non-existent package %s" % (name))
 

ambari-common/src/main/python/resource_management/core/providers/package/yumrpm.py

@@ -25,20 +25,28 @@ from resource_management.core import shell
 from resource_management.core.shell import string_cmd_from_args_list
 from resource_management.core.logger import Logger
 
-INSTALL_CMD = ['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'install']
-REMOVE_CMD = ['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'erase']
+INSTALL_CMD = {
+  True: ['/usr/bin/yum', '-y', 'install'],
+  False: ['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'install'],
+}
+
+REMOVE_CMD = {
+  True: ['/usr/bin/yum', '-y', 'erase'],
+  False: ['/usr/bin/yum', '-d', '0', '-e', '0', '-y', 'erase'],
+}
+
 CHECK_CMD = "installed_pkgs=`rpm -qa %s` ; [ ! -z \"$installed_pkgs\" ]"
 
 class YumProvider(PackageProvider):
   def install_package(self, name, use_repos=[]):
     if not self._check_existence(name) or use_repos:
-      cmd = INSTALL_CMD
+      cmd = INSTALL_CMD[self.get_logoutput()]
       if use_repos:
         enable_repo_option = '--enablerepo=' + ",".join(use_repos)
         cmd = cmd + ['--disablerepo=*', enable_repo_option]
       cmd = cmd + [name]
       Logger.info("Installing package %s ('%s')" % (name, string_cmd_from_args_list(cmd)))
-      shell.checked_call(cmd, sudo=True)
+      shell.checked_call(cmd, sudo=True, logoutput=self.get_logoutput())
     else:
       Logger.info("Skipping installing existent package %s" % (name))
 
@@ -47,9 +55,9 @@ class YumProvider(PackageProvider):
 
   def remove_package(self, name):
     if self._check_existence(name):
-      cmd = REMOVE_CMD + [name]
+      cmd = REMOVE_CMD[self.get_logoutput()] + [name]
       Logger.info("Removing package %s ('%s')" % (name, string_cmd_from_args_list(cmd)))
-      shell.checked_call(cmd, sudo=True)
+      shell.checked_call(cmd, sudo=True, logoutput=self.get_logoutput())
     else:
       Logger.info("Skipping removing non-existent package %s" % (name))
 

ambari-common/src/main/python/resource_management/core/providers/package/zypper.py

@@ -25,16 +25,22 @@ from resource_management.core import shell
 from resource_management.core.shell import string_cmd_from_args_list
 from resource_management.core.logger import Logger
 
-INSTALL_CMD = ['/usr/bin/zypper', '--quiet', 'install', '--auto-agree-with-licenses', '--no-confirm']
-REMOVE_CMD = ['/usr/bin/zypper', '--quiet', 'remove', '--no-confirm']
+INSTALL_CMD = {
+  True: ['/usr/bin/zypper', 'install', '--auto-agree-with-licenses', '--no-confirm'],
+  False: ['/usr/bin/zypper', '--quiet', 'install', '--auto-agree-with-licenses', '--no-confirm'],
+}
+REMOVE_CMD = {
+  True: ['/usr/bin/zypper', 'remove', '--no-confirm'],
+  False: ['/usr/bin/zypper', '--quiet', 'remove', '--no-confirm'],
+}
 CHECK_CMD = "installed_pkgs=`rpm -qa %s` ; [ ! -z \"$installed_pkgs\" ]"
 
 class ZypperProvider(PackageProvider):
   def install_package(self, name, use_repos=[]):
     if not self._check_existence(name):
-      cmd = INSTALL_CMD + [name]
+      cmd = INSTALL_CMD[self.get_logoutput()] + [name]
       Logger.info("Installing package %s ('%s')" % (name, string_cmd_from_args_list(cmd)))
-      shell.checked_call(cmd, sudo=True)
+      shell.checked_call(cmd, sudo=True, logoutput=self.get_logoutput())
     else:
       Logger.info("Skipping installing existent package %s" % (name))
 
@@ -43,9 +49,9 @@ class ZypperProvider(PackageProvider):
   
   def remove_package(self, name):
     if self._check_existence(name):
-      cmd = REMOVE_CMD + [name]
+      cmd = REMOVE_CMD[self.get_logoutput()] + [name]
       Logger.info("Removing package %s ('%s')" % (name, string_cmd_from_args_list(cmd)))
-      shell.checked_call(cmd, sudo=True)
+      shell.checked_call(cmd, sudo=True, logoutput=self.get_logoutput())
     else:
       Logger.info("Skipping removing non-existent package %s" % (name))
 

ambari-common/src/main/python/resource_management/core/providers/system.py

@@ -245,9 +245,7 @@ class ExecuteProvider(Provider):
     if self.resource.creates:
       if os.path.exists(self.resource.creates):
         return
-
-    Logger.debug("Executing %s" % self.resource)
-
+      
     env = self.resource.environment
           
     for i in range (0, self.resource.tries):

ambari-common/src/main/python/resource_management/core/resources/packaging.py

@@ -32,6 +32,12 @@ class Package(Resource):
 
   # Allow using only specific list of repositories when performing action
   use_repos = ResourceArgument(default=[])
+  """
+  True           -  log it in INFO mode
+  False          -  never log it
+  None (default) -  log it in DEBUG mode
+  """
+  logoutput = ResourceArgument(default=None)
 
   version = ResourceArgument()
   actions = ["install", "upgrade", "remove"]

ambari-common/src/main/python/resource_management/core/shell.py

@@ -26,6 +26,7 @@ __all__ = ["non_blocking_call", "checked_call", "call", "quote_bash_args", "as_u
 import sys
 import logging
 import string
+import inspect
 import subprocess
 import threading
 import traceback
@@ -34,6 +35,8 @@ from exceptions import Fail
 from exceptions import ExecuteTimeoutException
 from resource_management.core.logger import Logger
 
+# use quiet=True calls from this folder (logs get too messy duplicating the resources with its commands)
+RMF_FOLDER = 'resource_management/'
 EXPORT_PLACEHOLDER = "[RMF_EXPORT_PLACEHOLDER]"
 ENV_PLACEHOLDER = "[RMF_ENV_PLACEHOLDER]"
 
@@ -42,24 +45,51 @@ PLACEHOLDERS_TO_STR = {
   ENV_PLACEHOLDER: "{env_str}"
 }
 
-def checked_call(command, verbose=False, logoutput=False,
+def log_function_call(function):
+  def inner(command, **kwargs):
+    caller_filename = inspect.getouterframes(inspect.currentframe())[1][1]
+    # quiet = can be False/True or None -- which means undefined yet
+    quiet = kwargs['quiet'] if 'quiet' in kwargs else None
+    is_internal_call = RMF_FOLDER in caller_filename
+    
+    if quiet == False or (quiet == None and not is_internal_call):
+      command_alias = string_cmd_from_args_list(command) if isinstance(command, (list, tuple)) else command
+      log_msg = Logger.get_function_repr("{0}['{1}']".format(function.__name__, command_alias), kwargs)
+      Logger.info(log_msg)
+      
+    # logoutput=False - never log
+    # logoutput=True - log in INFO level
+    # logouput=None - log in DEBUG level
+    # logouput=not-specified - log in DEBUG level, not counting internal calls
+    kwargs['logoutput'] = ('logoutput' in kwargs and kwargs['logoutput'] and Logger.logger.isEnabledFor(logging.INFO)) or \
+      ('logoutput' in kwargs and kwargs['logoutput']==None and Logger.logger.isEnabledFor(logging.DEBUG)) or \
+      (not 'logoutput' in kwargs and not is_internal_call and Logger.logger.isEnabledFor(logging.DEBUG))
+       
+    return function(command, **kwargs)
+    
+  return inner
+
+@log_function_call
+def checked_call(command, quiet=False, logoutput=None,
          cwd=None, env=None, preexec_fn=None, user=None, wait_for_finish=True, timeout=None, path=None, sudo=False, on_new_line=None):
   """
   Execute the shell command and throw an exception on failure.
   @throws Fail
   @return: return_code, output
   """
-  return _call(command, verbose, logoutput, True, cwd, env, preexec_fn, user, wait_for_finish, timeout, path, sudo, on_new_line)
+  return _call(command, logoutput, True, cwd, env, preexec_fn, user, wait_for_finish, timeout, path, sudo, on_new_line)
 
-def call(command, verbose=False, logoutput=False,
+@log_function_call
+def call(command, quiet=False, logoutput=None,
          cwd=None, env=None, preexec_fn=None, user=None, wait_for_finish=True, timeout=None, path=None, sudo=False, on_new_line=None):
   """
   Execute the shell command despite failures.
   @return: return_code, output
   """
-  return _call(command, verbose, logoutput, False, cwd, env, preexec_fn, user, wait_for_finish, timeout, path, sudo, on_new_line)
+  return _call(command, logoutput, False, cwd, env, preexec_fn, user, wait_for_finish, timeout, path, sudo, on_new_line)
 
-def non_blocking_call(command, verbose=False,
+@log_function_call
+def non_blocking_call(command, quiet=False,
          cwd=None, env=None, preexec_fn=None, user=None, timeout=None, path=None, sudo=False):
   """
   Execute the shell command and don't wait until it's completion
@@ -68,9 +98,9 @@ def non_blocking_call(command, verbose=False,
   (use proc.stdout.readline to read output in cycle, don't foget to proc.stdout.close(),
   to get return code use proc.wait() and after that proc.returncode)
   """
-  return _call(command, verbose, False, True, cwd, env, preexec_fn, user, False, timeout, path, sudo, None)
+  return _call(command, False, True, cwd, env, preexec_fn, user, False, timeout, path, sudo, None)
 
-def _call(command, verbose=False, logoutput=False, throw_on_failure=True,
+def _call(command, logoutput=None, throw_on_failure=True,
          cwd=None, env=None, preexec_fn=None, user=None, wait_for_finish=True, timeout=None, path=None, sudo=False, on_new_line=None):
   """
   Execute shell command
@@ -104,9 +134,6 @@ def _call(command, verbose=False, logoutput=False, throw_on_failure=True,
   env_str = _get_environment_str(env)
   for placeholder, replacement in PLACEHOLDERS_TO_STR.iteritems():
     command = command.replace(placeholder, replacement.format(env_str=env_str))
-  
-  if verbose:
-    Logger.info("Running: " + command)
 
   # --noprofile is used to preserve PATH set for ambari-agent
   subprocess_command = ["/bin/bash","--login","--noprofile","-c", command]

ambari-common/src/main/python/resource_management/libraries/functions/default.py

@@ -33,8 +33,6 @@ def default(name, default_value):
     if x in curr_dict:
       curr_dict = curr_dict[x]
     else:
-      if not isinstance(default_value, UnknownConfiguration):
-        Logger.debug("Cannot find configuration: '%s'. Using '%s' value as default" % (name, default_value))
       return default_value
 
   return curr_dict

ambari-common/src/main/python/resource_management/libraries/script/script.py

@@ -32,6 +32,7 @@ from resource_management.libraries.resources import PropertiesFile
 from resource_management.core.resources import File, Directory
 from resource_management.core.source import InlineTemplate
 from resource_management.core.environment import Environment
+from resource_management.core.logger import Logger
 from resource_management.core.exceptions import Fail, ClientComponentHasNoStatus, ComponentIsNotRunning
 from resource_management.core.resources.packaging import Package
 from resource_management.libraries.script.config_dictionary import ConfigDictionary, UnknownConfiguration
@@ -48,7 +49,7 @@ USAGE = """Usage: {0} <COMMAND> <JSON_CONFIG> <BASEDIR> <STROUTPUT> <LOGGING_LEV
 
 <COMMAND> command type (INSTALL/CONFIGURE/START/STOP/SERVICE_CHECK...)
 <JSON_CONFIG> path to command json file. Ex: /var/lib/ambari-agent/data/command-2.json
-<BASEDIR> path to service metadata dir. Ex: /var/lib/ambari-agent/cache/stacks/HDP/2.0.6/services/HDFS
+<BASEDIR> path to service metadata dir. Ex: /var/lib/ambari-agent/cache/common-services/HDFS/2.1.0.2.0/package
 <STROUTPUT> path to file with structured command output (file will be created). Ex:/tmp/my.txt
 <LOGGING_LEVEL> log level for stdout. Ex:DEBUG,INFO
 <TMP_DIR> temporary directory for executable scripts. Ex: /var/lib/ambari-agent/data/tmp
@@ -96,19 +97,8 @@ class Script(object):
     Sets up logging;
     Parses command parameters and executes method relevant to command type
     """
-    # set up logging (two separate loggers for stderr and stdout with different loglevels)
-    logger = logging.getLogger('resource_management')
-    logger.setLevel(logging.DEBUG)
-    formatter = logging.Formatter('%(asctime)s - %(message)s')
-    chout = logging.StreamHandler(sys.stdout)
-    chout.setLevel(logging.INFO)
-    chout.setFormatter(formatter)
-    cherr = logging.StreamHandler(sys.stderr)
-    cherr.setLevel(logging.ERROR)
-    cherr.setFormatter(formatter)
-    logger.addHandler(cherr)
-    logger.addHandler(chout)
-
+    logger, chout, cherr = Logger.initialize_logger()
+    
     # parse arguments
     if len(sys.argv) < 7:
      logger.error("Script expects at least 6 arguments")

ambari-server/src/main/resources/common-services/HDFS/2.1.0.2.0/package/scripts/utils.py

@@ -58,7 +58,7 @@ def failover_namenode():
   """
   import params
   check_service_cmd = format("hdfs haadmin -getServiceState {namenode_id}")
-  code, out = call(check_service_cmd, verbose=True, logoutput=True, user=params.hdfs_user)
+  code, out = call(check_service_cmd, logoutput=True, user=params.hdfs_user)
 
   state = "unknown"
   if code == 0 and out:
@@ -94,7 +94,7 @@ def kill_zkfc(zkfc_user):
     zkfc_pid_file = get_service_pid_file("zkfc", zkfc_user)
     if zkfc_pid_file:
       check_process = format("ls {zkfc_pid_file} > /dev/null 2>&1 && ps -p `cat {zkfc_pid_file}` > /dev/null 2>&1")
-      code, out = call(check_process, verbose=True)
+      code, out = call(check_process)
       if code == 0:
         Logger.debug("ZKFC is running and will be killed to initiate namenode failover.")
         kill_command = format("{check_process} && kill -9 `cat {zkfc_pid_file}` > /dev/null 2>&1")

ambari-server/src/main/resources/common-services/HIVE/0.12.0.2.0/package/scripts/mysql_users.py

@@ -40,8 +40,7 @@ def mysql_adduser():
   Execute(cmd,
           tries=3,
           try_sleep=5,
-          path='/usr/sbin:/sbin:/usr/local/bin:/bin:/usr/bin',
-          logoutput=True,
+          path='/usr/sbin:/sbin:/usr/local/bin:/bin:/usr/bin'
   )
 
 # Removes hive access from components
@@ -66,6 +65,5 @@ def mysql_deluser():
           tries=3,
           try_sleep=5,
           path='/usr/sbin:/sbin:/usr/local/bin:/bin:/usr/bin',
-          logoutput=True,
   )
 

ambari-server/src/main/resources/common-services/KAFKA/0.8.1.2.2/package/scripts/service_check.py

@@ -25,24 +25,17 @@ class ServiceCheck(Script):
       env.set_params(params)
       
       kafka_config = self.read_kafka_config()
-      environment = self.get_env()
       
       create_topic_cmd_created_output = "Created topic \"ambari_kafka_service_check\"."
       create_topic_cmd_exists_output = "Topic \"ambari_kafka_service_check\" already exists."
       
-      print "Running kafka create topic command"
-      create_topic_cmd = (params.kafka_home+'/bin/kafka-topics.sh', '--zookeeper '+kafka_config['zookeeper.connect'],
-                          '--create --topic ambari_kafka_service_check', '--partitions 1 --replication-factor 1')
+      source_cmd = format("source {conf_dir}/kafka-env.sh")
+      create_topic_cmd = format("{kafka_home}/bin/kafka-topics.sh --zookeeper {kafka_config[zookeeper.connect]} --create --topic ambari_kafka_service_check --partitions 1 --replication-factor 1")
       
-      code, out = shell.checked_call(create_topic_cmd, 
-                                     verbose=True, env=environment)
-
-      if out.find(create_topic_cmd_created_output) != -1:
-          print out
-      elif out.find(create_topic_cmd_exists_output) != -1:
-          print "Topic ambari_kafka_service_check exists"
-      else:
-          raise Fail(out)
+      print "Running kafka create topic command"
+      Execute(format("{source_cmd} ; {create_topic_cmd} | grep '{create_topic_cmd_created_output}\|{create_topic_cmd_exists_output}'"),
+              logoutput=True,
+      )
 
   def read_kafka_config(self):
     import params
@@ -55,16 +48,5 @@ class ServiceCheck(Script):
     
     return kafka_config
 
-  def get_env(self):
-    import params
-    code, out = shell.checked_call(format('source {conf_dir}/kafka-env.sh && env'))
-    
-    environment = {}
-    for line in out.split("\n"):
-      (key, _, value) = line.partition("=")
-      environment[key] = value.replace("\n","")
-      
-    return environment
-
 if __name__ == "__main__":
     ServiceCheck().execute()

ambari-server/src/main/resources/common-services/ZOOKEEPER/3.4.5.2.0/package/scripts/zookeeper_server.py

@@ -41,7 +41,7 @@ def call_and_match_output(command, regex_expression, err_message):
   """
   # TODO Rolling Upgrade, does this work in Ubuntu? If it doesn't see dynamic_variable_interpretation.py to see how stdout was redirected
   # to a temporary file, which was then read.
-  code, out = call(command, verbose=True)
+  code, out = call(command)
   if not (out and re.search(regex_expression, out, re.IGNORECASE)):
     raise Fail(err_message)
 
@@ -84,7 +84,7 @@ class ZookeeperServer(Script):
     quorum_err_message = "Failed to establish zookeeper quorum"
     call_and_match_output(create_command, 'Created', quorum_err_message)
     call_and_match_output(list_command, r"\[.*?" + unique + ".*?\]", quorum_err_message)
-    call(delete_command, verbose=True)
+    call(delete_command)
 
   def stop(self, env, rolling_restart=False):
     import params

ambari-server/src/main/resources/custom_actions/scripts/ru_execute_tasks.py

@@ -99,20 +99,20 @@ class ExecuteUpgradeTasks(Script):
           unless = replace_variables(unless, host_name, version)
 
           if first:
-            code, out = call(first, verbose=True)
+            code, out = call(first)
             Logger.info("Pre-condition command. Code: %s, Out: %s" % (str(code), str(out)))
             if code != 0:
               break
 
           if unless:
-            code, out = call(unless, verbose=True)
+            code, out = call(unless)
             Logger.info("Unless command. Code: %s, Out: %s" % (str(code), str(out)))
             if code == 0:
               break
 
           for i in range(1, effective_times+1):
             # TODO, Execute already has a tries and try_sleep, see hdfs_namenode.py for an example
-            code, out = call(command, verbose=True)
+            code, out = call(command)
             Logger.info("Command. Code: %s, Out: %s" % (str(code), str(out)))
 
             if code == 0 or code in ignore_return_codes:
@@ -123,7 +123,7 @@ class ExecuteUpgradeTasks(Script):
               try:
                 if on_failure:
                   on_failure = replace_variables(on_failure, host_name, version)
-                  code_failure_handler, out_failure_handler = call(on_failure, verbose=True)
+                  code_failure_handler, out_failure_handler = call(on_failure)
                   Logger.error("Failure Handler. Code: %s, Out: %s" % (str(code_failure_handler), str(out_failure_handler)))
               except:
                 pass

ambari-server/src/main/resources/stacks/HDP/1.3.2/hooks/before-ANY/files/changeToSecureUid.sh

@@ -49,5 +49,5 @@ old_uid=$(id -u $username)
 sudo_prefix="sudo -H -E"
 echo "Changing uid of $username from $old_uid to $newUid"
 echo "Changing directory permisions for ${dir_array[@]}"
-$sudo_prefix usermod -u $newUid $username && for dir in ${dir_array[@]} ; do ls $dir && echo "Changing permission for $dir" && $sudo_prefix chown -Rh $newUid $dir ; done
+$sudo_prefix usermod -u $newUid $username && for dir in ${dir_array[@]} ; do ls $dir 2> /dev/null && echo "Changing permission for $dir" && $sudo_prefix chown -Rh $newUid $dir ; done
 exit 0

ambari-server/src/main/resources/stacks/HDP/2.0.6/hooks/before-ANY/files/changeToSecureUid.sh

@@ -49,5 +49,5 @@ old_uid=$(id -u $username)
 sudo_prefix="sudo -H -E"
 echo "Changing uid of $username from $old_uid to $newUid"
 echo "Changing directory permisions for ${dir_array[@]}"
-$sudo_prefix usermod -u $newUid $username && for dir in ${dir_array[@]} ; do ls $dir && echo "Changing permission for $dir" && $sudo_prefix chown -Rh $newUid $dir ; done
+$sudo_prefix usermod -u $newUid $username && for dir in ${dir_array[@]} ; do ls $dir 2> /dev/null && echo "Changing permission for $dir" && $sudo_prefix chown -Rh $newUid $dir ; done
 exit 0

ambari-server/src/test/python/stacks/2.0.6/HIVE/test_mysql_server.py

@@ -146,8 +146,7 @@ class TestMySqlServer(RMFTestCase):
     self.assertResourceCalled('Execute', 'bash -x /tmp/addMysqlUser.sh mysql hive \'!`"\'"\'"\' 1\' c6402.ambari.apache.org',
       path = ['/usr/sbin:/sbin:/usr/local/bin:/bin:/usr/bin'],
       tries = 3,
-      try_sleep = 5,
-      logoutput = True,
+      try_sleep = 5
     )
     
   def assert_configure_secured(self):
@@ -164,8 +163,7 @@ class TestMySqlServer(RMFTestCase):
     self.assertResourceCalled('Execute', 'bash -x /tmp/addMysqlUser.sh mysql hive \'!`"\'"\'"\' 1\' c6402.ambari.apache.org',
       path = ['/usr/sbin:/sbin:/usr/local/bin:/bin:/usr/bin'],
       tries = 3,
-      try_sleep = 5,
-      logoutput = True,
+      try_sleep = 5
     )
 
   def assert_clean_default(self):
@@ -176,8 +174,7 @@ class TestMySqlServer(RMFTestCase):
     self.assertResourceCalled('Execute', 'bash -x /tmp/removeMysqlUser.sh mysql hive c6402.ambari.apache.org',
                               path = ['/usr/sbin:/sbin:/usr/local/bin:/bin:/usr/bin'],
                               tries = 3,
-                              try_sleep = 5,
-                              logoutput = True,
+                              try_sleep = 5
                               )
 
   def assert_clean_secured(self):
@@ -188,6 +185,5 @@ class TestMySqlServer(RMFTestCase):
     self.assertResourceCalled('Execute', 'bash -x /tmp/removeMysqlUser.sh mysql hive c6402.ambari.apache.org',
                               path = ['/usr/sbin:/sbin:/usr/local/bin:/bin:/usr/bin'],
                               tries = 3,
-                              try_sleep = 5,
-                              logoutput = True,
+                              try_sleep = 5
                               )