Add default success/failure output logging.

Request logging on the server only happened if you added verbose=True
or debug=True to the IPA config file. We should log the basics at
least: who, what, result.

Move a lot of entries from info to debug logging as well.

Related to ticket 873

ipalib/backend.py

@@ -62,7 +62,7 @@ class Connectible(Backend):
         conn = self.create_connection(*args, **kw)
         setattr(context, self.id, Connection(conn, self.disconnect))
         assert self.conn is conn
-        self.info('Created connection context.%s' % self.id)
+        self.debug('Created connection context.%s' % self.id)
 
     def create_connection(self, *args, **kw):
         raise NotImplementedError('%s.create_connection()' % self.id)
@@ -76,7 +76,7 @@ class Connectible(Backend):
             )
         self.destroy_connection()
         delattr(context, self.id)
-        self.info('Destroyed connection context.%s' % self.id)
+        self.debug('Destroyed connection context.%s' % self.id)
 
     def destroy_connection(self):
         raise NotImplementedError('%s.destroy_connection()' % self.id)

ipalib/frontend.py

@@ -412,7 +412,7 @@ class Command(HasParam):
         params.update(self.get_default(**params))
         params = self.normalize(**params)
         params = self.convert(**params)
-        self.info(
+        self.debug(
             '%s(%s)', self.name, ', '.join(self._repr_iter(**params))
         )
         if not self.api.env.in_server and 'version' not in params:

ipalib/plugable.py

@@ -409,10 +409,14 @@ class API(DictProxy):
         stderr = logging.StreamHandler()
         if self.env.debug:
             stderr.setLevel(logging.DEBUG)
-        elif self.env.verbose > 0:
-            stderr.setLevel(logging.INFO)
         else:
-            stderr.setLevel(logging.WARNING)
+            if self.env.context == 'cli':
+                if self.env.verbose > 0:
+                    stderr.setLevel(logging.INFO)
+                else:
+                    stderr.setLevel(logging.WARNING)
+            else:
+                stderr.setLevel(logging.INFO)
         stderr.setFormatter(util.LogFormatter(FORMAT_STDERR))
         log.addHandler(stderr)
 
@@ -549,7 +553,7 @@ class API(DictProxy):
             try:
                 __import__(fullname)
             except errors.SkipPluginModule, e:
-                self.log.info(
+                self.log.debug(
                     'skipping plugin module %s: %s', fullname, e.reason
                 )
             except StandardError, e:

ipalib/plugins/user.py

@@ -296,7 +296,6 @@ class user_del(LDAPDelete):
     msg_summary = _('Deleted user "%(value)s"')
 
     def post_callback(self, ldap, dn, *keys, **options):
-        self.log.info('IPA: %s "%s"' % (self.name, keys[-1]))
         return True
 
 api.register(user_del)

ipalib/plugins/virtual.py

@@ -53,7 +53,7 @@ class VirtualCommand(Command):
             operation = self.operation
 
         ldap = self.api.Backend.ldap2
-        self.log.info("IPA: virtual verify %s" % operation)
+        self.log.debug("IPA: virtual verify %s" % operation)
 
         operationdn = "cn=%s,%s,%s" % (operation, self.api.env.container_virtual, self.api.env.basedn)
 

ipapython/ipautil.py

@@ -145,10 +145,10 @@ def run(args, stdin=None, raiseonerr=True,
         args = args.replace(quoted, 'XXXXXXXX')
         stdout = stdout.replace(quoted, 'XXXXXXXX')
         stderr = stderr.replace(quoted, 'XXXXXXXX')
-    logging.info('args=%s' % args)
+    logging.debug('args=%s' % args)
     if capture_output:
-        logging.info('stdout=%s' % stdout)
-        logging.info('stderr=%s' % stderr)
+        logging.debug('stdout=%s' % stdout)
+        logging.debug('stderr=%s' % stderr)
 
     if p.returncode != 0 and raiseonerr:
         raise CalledProcessError(p.returncode, args)

ipaserver/rpcserver.py

@@ -166,7 +166,7 @@ class session(Executioner):
             raise StandardError('%s.mount(): cannot replace %r with %r at %r' % (
                 self.name, self.__apps[key], app, key)
             )
-        self.info('Mounting %r at %r', app, key)
+        self.debug('Mounting %r at %r', app, key)
         self.__apps[key] = app
 
 
@@ -218,6 +218,11 @@ class WSGIExecutioner(Executioner):
             error = InternalError()
         finally:
             os.environ['LANG']=lang
+        params = self.Command[name].args_options_2_params(*args, **options)
+        if error:
+            self.info('%s: %s(%s): %s', context.principal, name, ', '.join(self.Command[name]._repr_iter(**params)), e.__class__.__name__)
+        else:
+            self.info('%s: %s(%s): SUCCESS', context.principal, name, ', '.join(self.Command[name]._repr_iter(**params)))
         return self.marshal(result, error, _id)
 
     def simple_unmarshal(self, environ):
@@ -288,7 +293,7 @@ class xmlserver(WSGIExecutioner):
                 (args, options) = params_2_args_options(params)
                 response = (self.execute(name, *args, **options),)
         except PublicError, e:
-            self.info('response: %s: %s', e.__class__.__name__, str(e))
+            self.debug('response: %s: %s', e.__class__.__name__, str(e))
             response = Fault(e.errno, e.strerror)
         return xml_dumps(response, methodresponse=True)
 
@@ -299,11 +304,11 @@ class xmlserver(WSGIExecutioner):
 
     def marshal(self, result, error, _id=None):
         if error:
-            self.info('response: %s: %s', error.__class__.__name__, str(error))
+            self.debug('response: %s: %s', error.__class__.__name__, str(error))
             response = Fault(error.errno, error.strerror)
         else:
             if isinstance(result, dict):
-                self.info('response: entries returned %d', result.get('count', 1))
+                self.debug('response: entries returned %d', result.get('count', 1))
             response = (result,)
         return xml_dumps(response, methodresponse=True)