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

7 files changed, 24 insertions, 16 deletions

diff --git a/ipalib/backend.py b/ipalib/backend.py
index ad45238d8..2262e9227 100644
--- a/ipalib/backend.py
+++ b/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)
diff --git a/ipalib/frontend.py b/ipalib/frontend.py
index b9b75372c..45f5b74c6 100644
--- a/ipalib/frontend.py
+++ b/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:
diff --git a/ipalib/plugable.py b/ipalib/plugable.py
index a7e61ddbd..723414ced 100644
--- a/ipalib/plugable.py
+++ b/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:
diff --git a/ipalib/plugins/user.py b/ipalib/plugins/user.py
index 12e17131f..2b0e88487 100644
--- a/ipalib/plugins/user.py
+++ b/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)
diff --git a/ipalib/plugins/virtual.py b/ipalib/plugins/virtual.py
index 1d70793f1..c827d3d9d 100644
--- a/ipalib/plugins/virtual.py
+++ b/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)
 
diff --git a/ipapython/ipautil.py b/ipapython/ipautil.py
index 7a91dcba0..85db920e0 100644
--- a/ipapython/ipautil.py
+++ b/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)
diff --git a/ipaserver/rpcserver.py b/ipaserver/rpcserver.py
index ff2b04b5b..701ebb651 100644
--- a/ipaserver/rpcserver.py
+++ b/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)