Better logging for AdminTool and ipa-ldap-updater

- Automatically add a "Logging and output options" group with the --quiet,
    --verbose, --log-file options.
- Set up logging based on these options; details are in the setup_logging
    docstring and in the design document.
- Don't bind log methods as individual methods of the class. This means one
    less linter exception.
- Make the help for command line options consistent with optparse's --help and
    --version options.

Design document: http://freeipa.org/page/V3/Logging_and_output

freeipa.spec.in

@@ -438,7 +438,7 @@ fi
 %posttrans server
 # This must be run in posttrans so that updates from previous
 # execution that may no longer be shipped are not applied.
-/usr/sbin/ipa-ldap-updater --upgrade >/dev/null || :
+/usr/sbin/ipa-ldap-updater --upgrade --quiet || :
 
 %preun server
 if [ $1 = 0 ]; then
@@ -769,6 +769,9 @@ fi
 %ghost %attr(0644,root,apache) %config(noreplace) %{_sysconfdir}/ipa/ca.crt
 
 %changelog
+* Tue Jan 29 2013 Petr Viktorin <pviktori@redhat.com> - 3.0.99-14
+- Use ipa-ldap-updater --quiet instead of redirecting to /dev/null
+
 * Tue Jan 29 2013 Rob Crittenden <rcritten@redhat.com> - 3.0.99-13
 - Set certmonger minimum version to 0.65 for NSS locking during
   renewal

ipapython/admintool.py

@@ -76,14 +76,15 @@ class AdminTool(object):
     Class attributes to define in subclasses:
     command_name - shown in logs
     log_file_name - if None, logging is to stderr only
-    needs_root - if true, non-root users can't run the tool
     usage - text shown in help
+
+    See the setup_logging method for more info on logging.
     """
     command_name = None
     log_file_name = None
-    needs_root = False
     usage = None
 
+    log = None
     _option_parsers = dict()
 
     @classmethod
@@ -95,10 +96,23 @@ class AdminTool(object):
         cls.add_options(parser)
 
     @classmethod
-    def add_options(cls, parser):
+    def add_options(cls, parser, debug_option=False):
-        """Add command-specific options to the option parser"""
+        """Add command-specific options to the option parser
-        parser.add_option("-d", "--debug", dest="debug", default=False,
+
+        :param parser: The parser to add options to
+        :param debug_option: Add a --debug option as an alias to --verbose
+        """
+        group = OptionGroup(parser, "Logging and output options")
+        group.add_option("-v", "--verbose", dest="verbose", default=False,
             action="store_true", help="print debugging information")
+        if debug_option:
+            group.add_option("-d", "--debug", dest="verbose", default=False,
+                action="store_true", help="alias for --verbose (deprecated)")
+        group.add_option("-q", "--quiet", dest="quiet", default=False,
+            action="store_true", help="output only errors")
+        group.add_option("--log-file", dest="log_file", default=None,
+            metavar="FILE", help="log to the given file")
+        parser.add_option_group(group)
 
     @classmethod
     def run_cli(cls):
@@ -145,6 +159,8 @@ class AdminTool(object):
         This includes validating options, setting up logging, doing the
         actual work, and handling the result.
         """
+        self._setup_logging(no_file=True)
+        return_value = 1
         try:
             self.validate_options()
             self.ask_for_options()
@@ -160,14 +176,17 @@ class AdminTool(object):
         self.log_success()
         return return_value
 
-    def validate_options(self):
+    def validate_options(self, needs_root=False):
         """Validate self.options
 
         It's also possible to compute and store information that will be
         useful later, but no changes to the system should be made here.
         """
-        if self.needs_root and os.getegid() != 0:
+        if needs_root and os.getegid() != 0:
             raise ScriptError('Must be root to run %s' % self.command_name, 1)
+        if self.options.verbose and self.options.quiet:
+            raise ScriptError(
+                'The --quiet and --verbose options are mutually exclusive')
 
     def ask_for_options(self):
         """Ask for missing options interactively
@@ -175,14 +194,67 @@ class AdminTool(object):
         Similar to validate_options. This is separate method because we want
         any validation errors to abort the script before bothering the user
         with prompts.
+
+        Any options that might be asked for should also be validated here.
         """
         pass
 
-    def setup_logging(self):
+    def setup_logging(self, log_file_mode='w'):
-        """Set up logging"""
+        """Set up logging
+
+        :param _to_file: Setting this to false will disable logging to file.
+            For internal use.
+
+        If the --log-file option was given or if a filename is in
+        self.log_file_name, the tool will log to that file. In this case,
+        all messages are logged.
+
+        What is logged to the console depends on command-line options:
+        the default is INFO; --quiet sets ERROR; --verbose sets DEBUG.
+
+        Rules of thumb for logging levels:
+        - CRITICAL for fatal errors
+        - ERROR for critical things that the admin must see, even with --quiet
+        - WARNING for things that need to stand out in the log
+        - INFO to display normal messages
+        - DEBUG to spam about everything the program does
+        - a plain print for things that should not be log (for example,
+            interactive prompting)
+
+        To log, use `self.log.info()`, `self.log.warning()`, etc.
+
+        Logging to file is only set up after option validation and prompting;
+        before that, all output will go to the console only.
+        """
+        self._setup_logging(log_file_mode=log_file_mode)
+
+    def _setup_logging(self, log_file_mode='w', no_file=False):
+        if no_file:
+            log_file_name = None
+        elif self.options.log_file:
+            log_file_name = self.options.log_file
+        else:
+            log_file_name = self.log_file_name
+        if self.options.verbose:
+            console_format = '%(name)s: %(levelname)s: %(message)s'
+            verbose = True
+            debug = True
+        else:
+            console_format = '%(message)s'
+            debug = False
+            if self.options.quiet:
+                verbose = False
+            else:
+                verbose = True
         ipa_log_manager.standard_logging_setup(
-            self.log_file_name, debug=self.options.debug)
+            log_file_name, console_format=console_format,
-        ipa_log_manager.log_mgr.get_logger(self, True)
+            filemode=log_file_mode, debug=debug, verbose=verbose)
+        self.log = ipa_log_manager.log_mgr.get_logger(self)
+        if log_file_name:
+            self.log.debug('Logging to %s' % log_file_name)
+        elif not no_file:
+            self.log.debug('Not logging to a file')
+
 
     def handle_error(self, exception):
         """Given an exception, return a message (or None) and process exit code
@@ -206,27 +278,15 @@ class AdminTool(object):
         assumed to have run successfully, and the return value is used as the
         SystemExit code.
         """
-        self.debug('%s was invoked with arguments %s and options: %s',
+        self.log.debug('%s was invoked with arguments %s and options: %s',
                 self.command_name, self.args, self.safe_options)
 
     def log_failure(self, error_message, return_value, exception, backtrace):
-        try:
+        self.log.debug(''.join(traceback.format_tb(backtrace)))
-            self.log
+        self.log.debug('The %s command failed, exception: %s: %s',
-        except AttributeError:
+            self.command_name, type(exception).__name__, exception)
-            # Logging was not set up yet
+        if error_message:
-            if error_message:
+            self.log.error(error_message)
-                print >> sys.stderr, '\n', error_message
-        else:
-            self.info(''.join(traceback.format_tb(backtrace)))
-            self.info('The %s command failed, exception: %s: %s',
-                self.command_name, type(exception).__name__, exception)
-            if error_message:
-                self.error(error_message)
 
     def log_success(self):
-        try:
+        self.log.info('The %s command was successful', self.command_name)
-            self.log
-        except AttributeError:
-            pass
-        else:
-            self.info('The %s command was successful', self.command_name)

ipaserver/install/ipa_ldap_updater.py

@@ -34,7 +34,6 @@ from ipapython import ipautil, admintool
 from ipaserver.install import installutils
 from ipaserver.install.ldapupdate import LDAPUpdate, UPDATES_DIR
 from ipaserver.install.upgradeinstance import IPAUpgrade
-from ipapython import ipa_log_manager
 
 
 class LDAPUpdater(admintool.AdminTool):
@@ -45,26 +44,26 @@ class LDAPUpdater(admintool.AdminTool):
 
     @classmethod
     def add_options(cls, parser):
-        super(LDAPUpdater, cls).add_options(parser)
+        super(LDAPUpdater, cls).add_options(parser, debug_option=True)
 
         parser.add_option("-t", "--test", action="store_true", dest="test",
             default=False,
-            help="Run through the update without changing anything")
+            help="run through the update without changing anything")
         parser.add_option("-y", dest="password",
-            help="File containing the Directory Manager password")
+            help="file containing the Directory Manager password")
         parser.add_option("-l", '--ldapi', action="store_true", dest="ldapi",
             default=False,
-            help="Connect to the LDAP server using the ldapi socket")
+            help="connect to the LDAP server using the ldapi socket")
         parser.add_option("-u", '--upgrade', action="store_true",
             dest="upgrade", default=False,
-            help="Upgrade an installed server in offline mode")
+            help="upgrade an installed server in offline mode")
         parser.add_option("-p", '--plugins', action="store_true",
             dest="plugins", default=False,
-            help="Execute update plugins. " +
+            help="execute update plugins " +
-                "Always true when applying all update files.")
+                "(implied when no input files are given)")
         parser.add_option("-W", '--password', action="store_true",
             dest="ask_password",
-            help="Prompt for the Directory Manager password")
+            help="prompt for the Directory Manager password")
 
     @classmethod
     def get_command_class(cls, options, args):
@@ -73,9 +72,9 @@ class LDAPUpdater(admintool.AdminTool):
         else:
             return LDAPUpdater_NonUpgrade
 
-    def validate_options(self):
+    def validate_options(self, **kwargs):
         options = self.options
-        super(LDAPUpdater, self).validate_options()
+        super(LDAPUpdater, self).validate_options(**kwargs)
 
         self.files = self.args
 
@@ -100,19 +99,12 @@ class LDAPUpdater(admintool.AdminTool):
             self.dirman_password = None
 
     def setup_logging(self):
-        ipa_log_manager.standard_logging_setup(self.log_file_name,
+        super(LDAPUpdater, self).setup_logging(log_file_mode='a')
-            console_format='%(levelname)s: %(message)s',
-            debug=self.options.debug, filemode='a')
-        ipa_log_manager.log_mgr.get_logger(self, True)
 
     def run(self):
         super(LDAPUpdater, self).run()
 
-        api.bootstrap(
+        api.bootstrap(in_server=True, context='updates')
-                in_server=True,
-                context='updates',
-                debug=self.options.debug,
-            )
         api.finalize()
 
     def handle_error(self, exception):
@@ -120,14 +112,13 @@ class LDAPUpdater(admintool.AdminTool):
 
 
 class LDAPUpdater_Upgrade(LDAPUpdater):
-    needs_root = True
     log_file_name = '/var/log/ipaupgrade.log'
 
     def validate_options(self):
         if os.getegid() != 0:
             raise admintool.ScriptError('Must be root to do an upgrade.', 1)
 
-        super(LDAPUpdater_Upgrade, self).validate_options()
+        super(LDAPUpdater_Upgrade, self).validate_options(needs_root=True)
 
     def run(self):
         super(LDAPUpdater_Upgrade, self).run()
@@ -145,7 +136,7 @@ class LDAPUpdater_Upgrade(LDAPUpdater):
         elif upgrade.upgradefailed:
             raise admintool.ScriptError('IPA upgrade failed.', 1)
         elif upgrade.modified and options.test:
-            self.info('Update complete, changes to be made, test mode')
+            self.log.info('Update complete, changes to be made, test mode')
             return 2
 
 
@@ -160,8 +151,13 @@ class LDAPUpdater_NonUpgrade(LDAPUpdater):
         self.run_plugins = not self.files or options.plugins
 
         # Need root for running plugins
-        if self.run_plugins and os.getegid() != 0:
+        if os.getegid() != 0:
-            raise admintool.ScriptError('Plugins can only be run as root.', 1)
+            if self.run_plugins:
+                raise admintool.ScriptError(
+                    'Plugins can only be run as root.', 1)
+            else:
+                # Can't log to the default file as non-root
+                self.log_file_name = None
 
     def ask_for_options(self):
         super(LDAPUpdater_NonUpgrade, self).ask_for_options()
@@ -192,5 +188,5 @@ class LDAPUpdater_NonUpgrade(LDAPUpdater):
         modified = ld.update(self.files)
 
         if modified and options.test:
-            self.info('Update complete, changes to be made, test mode')
+            self.log.info('Update complete, changes to be made, test mode')
             return 2

make-lint

@@ -59,7 +59,6 @@ class IPATypeChecker(TypeChecker):
         'urlparse.ParseResult': ['params'],
 
         # IPA classes
-        'ipapython.admintool.AdminTool': LOGGING_ATTRS,
         'ipalib.base.NameSpace': ['add', 'mod', 'del', 'show', 'find'],
         'ipalib.cli.Collector': ['__options'],
         'ipalib.config.Env': ['*'],