Use python logging in install / log cherrypy at right severity

This replaces the print statements in the installer code with
a python logger so we can log all output to the installer log
and a subset of it to stdout in one step without duplication.

The cherrypy.log.error() logs to the "error" log at a severity
of logging.INFO by default. Set an appropriate log level for
these as well.

https://fedorahosted.org/ipsilon/ticket/35

Signed-off-by: Rob Crittenden <rcritten@redhat.com>
Reviewed-by: Simo Sorce <simo@redhat.com>

15 files changed, 84 insertions, 59 deletions

diff --git a/ipsilon/admin/common.py b/ipsilon/admin/common.py
index a85a15d..87bfcd5 100644
--- a/ipsilon/admin/common.py
+++ b/ipsilon/admin/common.py
@@ -16,6 +16,7 @@
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
 import cherrypy
+import logging
 from ipsilon.util.page import Page
 from ipsilon.util.page import admin_protect
 from ipsilon.util.endpoint import allow_iframe
@@ -113,7 +114,8 @@ class AdminPluginConfig(AdminPage):
 
             if value != option.get_value():
                 cherrypy.log.error("Storing [%s]: %s = %s" %
-                                   (self._po.name, name, value))
+                                   (self._po.name, name, value),
+                                   severity=logging.DEBUG)
             option.set_value(value)
             new_db_values[name] = option.export_value()
 
@@ -222,7 +224,8 @@ class AdminPlugins(AdminPage):
             return
 
         for plugin in self._site[facility].available:
-            cherrypy.log.error('Admin info plugin: %s' % plugin)
+            cherrypy.log.error('Admin info plugin: %s' % plugin,
+                               severity=logging.DEBUG)
             obj = self._site[facility].available[plugin]
             page = AdminPluginConfig(obj, self._site, self)
             if hasattr(obj, 'admin'):
diff --git a/ipsilon/helpers/ipa.py b/ipsilon/helpers/ipa.py
index 5c01faa..e6f87e8 100644
--- a/ipsilon/helpers/ipa.py
+++ b/ipsilon/helpers/ipa.py
@@ -20,7 +20,6 @@ import pwd
 import os
 import socket
 import subprocess
-import sys
 
 from ipsilon.helpers.common import EnvHelpersInstaller
 
@@ -95,21 +94,19 @@ class Installer(EnvHelpersInstaller):
         # Check if we already have a keytab for HTTP
         if 'gssapi_httpd_keytab' in opts:
             msg = "Searching for keytab in: %s" % opts['gssapi_httpd_keytab']
-            print >> sys.stdout, msg,
             if os.path.exists(opts['gssapi_httpd_keytab']):
-                print >> sys.stdout, "... Found!"
+                logger.info(msg + "... Found!")
                 return
             else:
-                print >> sys.stdout, "... Not found!"
+                logger.info(msg + "... Not found!")
 
         msg = "Searching for keytab in: %s" % HTTPD_IPA_KEYTAB
-        print >> sys.stdout, msg,
         if os.path.exists(HTTPD_IPA_KEYTAB):
             opts['gssapi_httpd_keytab'] = HTTPD_IPA_KEYTAB
-            print >> sys.stdout, "... Found!"
+            logger.info(msg + "... Found!")
             return
         else:
-            print >> sys.stdout, "... Not found!"
+            logger.info(msg + "... Not found!")
 
         us = socket.gethostname()
         princ = 'HTTP/%s@%s' % (us, self.realm)
@@ -125,15 +122,13 @@ class Installer(EnvHelpersInstaller):
             api.Backend.rpcclient.connect()
             logger.debug('Try RPC connection')
             api.Backend.rpcclient.forward('ping')
-            print >> sys.stdout, "... Succeeded!"
+            logger.debug("... Succeeded!")
         except ipaerrors.KerberosError as e:
-            print >> sys.stderr, NO_CREDS_FOR_KEYTAB
             logger.error('Invalid credentials: [%s]', repr(e))
             if api.Backend.rpcclient.isconnected():
                 api.Backend.rpcclient.disconnect()
             raise Exception('Invalid credentials: [%s]' % e)
         except ipaerrors.PublicError as e:
-            print >> sys.stderr, "Can't connect to any IPA server"
             logger.error(
                 'Cannot connect to the server due to generic error: %s', e)
             if api.Backend.rpcclient.isconnected():
@@ -153,12 +148,11 @@ class Installer(EnvHelpersInstaller):
         except ipaerrors.DuplicateEntry:
             logger.debug('Principal %s already exists', princ)
         except ipaerrors.NotFound as e:
-            print >> sys.stderr, "%s" % e
             logger.error('%s', e)
             raise Exception('%s' % e)
         except ipaerrors.ACIError as e:
-            print >> sys.stderr, NO_CREDS_FOR_KEYTAB
-            logger.error('Invalid credentials: [%s]', repr(e))
+            logger.error(NO_CREDS_FOR_KEYTAB)
+            logger.debug('Invalid credentials: [%s]', repr(e))
             raise Exception('Invalid credentials: [%s]' % e)
         finally:
             server = api.Backend.rpcclient.api.env.server
@@ -168,14 +162,14 @@ class Installer(EnvHelpersInstaller):
         try:
             msg = "Trying to fetch keytab[%s] for %s" % (
                   opts['gssapi_httpd_keytab'], princ)
-            print >> sys.stdout, msg,
+            logger.info(msg)
             subprocess.check_output([IPA_GETKEYTAB,
                                      '-s', server, '-p', princ,
                                      '-k', opts['gssapi_httpd_keytab']],
                                     stderr=subprocess.STDOUT)
         except subprocess.CalledProcessError, e:
             # unfortunately this one is fatal
-            print >> sys.stderr, FAILED_TO_GET_KEYTAB
+            logger.error(FAILED_TO_GET_KEYTAB)
             logger.info('Error trying to get HTTP keytab:')
             logger.info('Cmd> %s\n%s', e.cmd, e.output)
             raise Exception('Missing keytab: [%s]' % e)
diff --git a/ipsilon/info/infosssd.py b/ipsilon/info/infosssd.py
index 559469a..69d68c0 100644
--- a/ipsilon/info/infosssd.py
+++ b/ipsilon/info/infosssd.py
@@ -15,6 +15,7 @@ import cherrypy
 import time
 import subprocess
 import SSSDConfig
+import logging
 
 SSSD_CONF = '/etc/sssd/sssd.conf'
 
@@ -151,7 +152,7 @@ class Installer(InfoProviderInstaller):
         except Exception as e:  # pylint: disable=broad-except
             # Unable to read existing SSSD config so it is probably not
             # configured.
-            print 'Loading SSSD config failed: %s' % e
+            logging.info('Loading SSSD config failed: %s', e)
             return False
 
         if not opts['info_sssd_domain']:
@@ -163,7 +164,7 @@ class Installer(InfoProviderInstaller):
             try:
                 sssd_domain = sssdconfig.get_domain(domain)
             except SSSDConfig.NoDomainError:
-                print 'No SSSD domain %s' % domain
+                logging.info('No SSSD domain %s', domain)
                 continue
             else:
                 sssd_domain.set_option(
@@ -171,10 +172,10 @@ class Installer(InfoProviderInstaller):
                 )
                 sssdconfig.save_domain(sssd_domain)
                 configured += 1
-                print "Configured SSSD domain %s" % domain
+                logging.info("Configured SSSD domain %s", domain)
 
         if configured == 0:
-            print 'No SSSD domains configured'
+            logging.info('No SSSD domains configured')
             return False
 
         try:
diff --git a/ipsilon/install/ipsilon-client-install b/ipsilon/install/ipsilon-client-install
index 89e6c6c..a136576 100755
--- a/ipsilon/install/ipsilon-client-install
+++ b/ipsilon/install/ipsilon-client-install
@@ -421,14 +421,14 @@ if __name__ == '__main__':
     except Exception, e:  # pylint: disable=broad-except
         log_exception(e)
         if 'uninstall' in args and args['uninstall'] is True:
-            print 'Uninstallation aborted.'
+            logging.info('Uninstallation aborted.')
         else:
-            print 'Installation aborted.'
+            logging.info('Installation aborted.')
         out = 1
     finally:
         if out == 0:
             if 'uninstall' in args and args['uninstall'] is True:
-                print 'Uninstallation complete.'
+                logging.info('Uninstallation complete.')
             else:
-                print 'Installation complete.'
+                logging.info('Installation complete.')
     sys.exit(out)
diff --git a/ipsilon/install/ipsilon-server-install b/ipsilon/install/ipsilon-server-install
index 5f95d7e..eeb87dd 100755
--- a/ipsilon/install/ipsilon-server-install
+++ b/ipsilon/install/ipsilon-server-install
@@ -79,7 +79,15 @@ def openlogs():
         lh = logging.StreamHandler(sys.stderr)
     formatter = logging.Formatter('[%(asctime)s] %(message)s')
     lh.setFormatter(formatter)
+    lh.setLevel(logging.DEBUG)
     logger.addHandler(lh)
+    logger.propagate = False
+    ch = logging.StreamHandler(sys.stdout)
+    formatter = logging.Formatter('%(message)s')
+    ch.setFormatter(formatter)
+    ch.setLevel(logging.INFO)
+    logger.addHandler(ch)
+    cherrypy.log.error_log.setLevel(logging.DEBUG)
 
 
 def install(plugins, args):
@@ -178,7 +186,7 @@ def install(plugins, args):
     for plugin_name in plugins['Environment Helpers']:
         plugin = plugins['Environment Helpers'][plugin_name]
         if plugin.configure_server(args) == False:
-            print 'Configuration of environment helper %s failed' % plugin_name
+            logger.info('Configuration of environment helper %s failed' % plugin_name)
 
     logger.info('Configuring login managers')
     for plugin_name in args['lm_order']:
@@ -187,19 +195,19 @@ def install(plugins, args):
         except KeyError:
             sys.exit('Login provider %s not installed' % plugin_name)
         if plugin.configure(args) == False:
-            print 'Configuration of login manager %s failed' % plugin_name
+            logger.info('Configuration of login manager %s failed' % plugin_name)
 
     logger.info('Configuring Info provider')
     for plugin_name in plugins['Info Provider']:
         plugin = plugins['Info Provider'][plugin_name]
         if plugin.configure(args) == False:
-            print 'Configuration of info provider %s failed' % plugin_name
+            logger.info('Configuration of info provider %s failed' % plugin_name)
 
     logger.info('Configuring Authentication Providers')
     for plugin_name in plugins['Auth Providers']:
         plugin = plugins['Auth Providers'][plugin_name]
         if plugin.configure(args) == False:
-            print 'Configuration of auth provider %s failed' % plugin_name
+            logger.info('Configuration of auth provider %s failed' % plugin_name)
 
     # Fixup permissions so only the ipsilon user can read these files
     files.fix_user_dirs(instance_conf, opts['system_user'])
@@ -235,25 +243,25 @@ def uninstall(plugins, args):
     for plugin_name in plugins['Environment Helpers']:
         plugin = plugins['Environment Helpers'][plugin_name]
         if plugin.unconfigure(args) == False:
-            print 'Removal of environment helper %s failed' % plugin_name
+            logger.info('Removal of environment helper %s failed' % plugin_name)
 
     logger.info('Removing login managers')
     for plugin_name in plugins['Login Managers']:
         plugin = plugins['Login Managers'][plugin_name]
         if plugin.unconfigure(args) == False:
-            print 'Removal of login manager %s failed' % plugin_name
+            logger.info('Removal of login manager %s failed' % plugin_name)
 
     logger.info('Removing Info providers')
     for plugin_name in plugins['Info Provider']:
         plugin = plugins['Info Provider'][plugin_name]
         if plugin.unconfigure(args) == False:
-            print 'Removal of info provider %s failed' % plugin_name
+            logger.info('Removal of info provider %s failed' % plugin_name)
 
     logger.info('Removing Authentication Providers')
     for plugin_name in plugins['Auth Providers']:
         plugin = plugins['Auth Providers'][plugin_name]
         if plugin.unconfigure(args) == False:
-            print 'Removal of auth provider %s failed' % plugin_name
+            logger.info('Removal of auth provider %s failed' % plugin_name)
 
     logger.info('Removing httpd configuration')
     os.remove(httpd_conf)
@@ -395,13 +403,13 @@ if __name__ == '__main__':
 
         logger.setLevel(logging.DEBUG)
 
-        logger.info('Intallation arguments:')
+        logger.debug('Installation arguments:')
         for k in sorted(opts.iterkeys()):
-            logger.info('%s: %s', k, opts[k])
+            logger.debug('%s: %s', k, opts[k])
 
         if 'uninstall' in opts and opts['uninstall'] is True:
             if not os.path.exists(os.path.join(CONFDIR, opts['instance'])):
-                print 'Instance %s could not be found' % opts['instance']
+                logger.info('Instance %s could not be found' % opts['instance'])
                 sys.exit(0)
             uninstall(fplugins, opts)
         else:
@@ -409,10 +417,10 @@ if __name__ == '__main__':
     except Exception, e:  # pylint: disable=broad-except
         logger.exception(e)
         if 'uninstall' in opts and opts['uninstall'] is True:
-            print 'Uninstallation aborted.'
+            logger.info('Uninstallation aborted.')
         else:
-            print 'Installation aborted.'
-        print 'See log file %s for details' % LOGFILE
+            logger.info('Installation aborted.')
+        logger.info('See log file %s for details' % LOGFILE)
         out = 1
     except SystemExit:
         out = 1
@@ -420,8 +428,8 @@ if __name__ == '__main__':
     finally:
         if out == 0:
             if 'uninstall' in opts and opts['uninstall'] is True:
-                print 'Uninstallation complete.'
+                logger.info('Uninstallation complete.')
             else:
-                print 'Installation complete.'
-                print 'Please restart HTTPD to enable the IdP instance.'
+                logger.info('Installation complete.')
+                logger.info('Please restart HTTPD to enable the IdP instance.')
     sys.exit(out)
diff --git a/ipsilon/login/authfas.py b/ipsilon/login/authfas.py
index 4ae0dc4..1489f73 100644
--- a/ipsilon/login/authfas.py
+++ b/ipsilon/login/authfas.py
@@ -7,6 +7,7 @@ from ipsilon.util.plugin import PluginObject
 from ipsilon.util.policy import Policy
 from ipsilon.util import config as pconfig
 import cherrypy
+import logging
 
 from fedora.client.fasproxy import FasProxyClient
 from fedora.client import AuthError
@@ -54,9 +55,12 @@ class FAS(LoginFormBase):
             try:
                 _, data = self.lm.fpc.login(username, password)
             except AuthError, e:
-                cherrypy.log.error("Authentication error [%s]" % str(e))
+                cherrypy.log.error("Authentication error [%s]" % str(e),
+                                   severity=logging.ERROR)
             except Exception, e:  # pylint: disable=broad-except
-                cherrypy.log.error("Unknown Error [%s]" % str(e))
+                cherrypy.log.error("Unknown Error [%s]" % str(e),
+                                   severity=logging.ERROR)
+
             if data and data.user:
                 userdata = self.make_userdata(data.user)
                 return self.lm.auth_successful(self.trans,
@@ -64,10 +68,10 @@ class FAS(LoginFormBase):
                                                userdata=userdata)
             else:
                 error = "Authentication failed"
-                cherrypy.log.error(error)
+                cherrypy.log.error(error, severity=logging.ERROR)
         else:
             error = "Username or password is missing"
-            cherrypy.log.error("Error: " + error)
+            cherrypy.log.error("Error: " + error, severity=logging.ERROR)
 
         context = self.create_tmpl_context(
             username=username,
diff --git a/ipsilon/login/authform.py b/ipsilon/login/authform.py
index 808c32c..ecce919 100644
--- a/ipsilon/login/authform.py
+++ b/ipsilon/login/authform.py
@@ -23,6 +23,7 @@ from ipsilon.util import config as pconfig
 from string import Template
 import cherrypy
 import subprocess
+import logging
 
 
 class Form(LoginFormBase):
@@ -38,7 +39,7 @@ class Form(LoginFormBase):
                 error = cherrypy.request.headers['EXTERNAL_AUTH_ERROR']
             except KeyError:
                 error = "Unknown error using external authentication"
-                cherrypy.log.error("Error: %s" % error)
+                cherrypy.log.error("Error: %s" % error, logging.ERROR)
             return self.lm.auth_failed(self.trans)
 
 
diff --git a/ipsilon/login/authgssapi.py b/ipsilon/login/authgssapi.py
index 97c3834..3ef7616 100644
--- a/ipsilon/login/authgssapi.py
+++ b/ipsilon/login/authgssapi.py
@@ -22,6 +22,7 @@ from ipsilon.util.user import UserSession
 from string import Template
 import cherrypy
 import os
+import logging
 
 
 class GSSAPI(LoginPageBase):
@@ -56,7 +57,8 @@ class GSSAPIAuth(LoginPageBase):
 class GSSAPIError(LoginPageBase):
 
     def root(self, *args, **kwargs):
-        cherrypy.log.error('REQUEST: %s' % cherrypy.request.headers)
+        cherrypy.log.error('REQUEST: %s' % cherrypy.request.headers,
+                           severity=logging.DEBUG)
         # If we have no negotiate header return whatever mod_auth_gssapi
         # generated and wait for the next request
 
diff --git a/ipsilon/login/authtest.py b/ipsilon/login/authtest.py
index 5f0ff6e..7769650 100644
--- a/ipsilon/login/authtest.py
+++ b/ipsilon/login/authtest.py
@@ -20,6 +20,7 @@ from ipsilon.login.common import LoginFormBase, LoginManagerBase, \
 from ipsilon.util.plugin import PluginObject
 from ipsilon.util import config as pconfig
 import cherrypy
+import logging
 
 
 class TestAuth(LoginFormBase):
@@ -46,7 +47,7 @@ class TestAuth(LoginFormBase):
                 error = "Authentication failed"
         else:
             error = "Username or password is missing"
-            cherrypy.log.error("Error: " + error)
+            cherrypy.log.error("Error: " + error, severity=logging.ERROR)
 
         context = self.create_tmpl_context(
             username=username,
@@ -120,7 +121,7 @@ class Installer(LoginManagerInstaller):
         if opts['testauth'] != 'yes':
             return
 
-        print self.pargs
+        logging.debug(self.pargs)
         # Add configuration data to database
         po = PluginObject(*self.pargs)
         po.name = 'testauth'
diff --git a/ipsilon/providers/saml2/admin.py b/ipsilon/providers/saml2/admin.py
index 931d096..158e590 100644
--- a/ipsilon/providers/saml2/admin.py
+++ b/ipsilon/providers/saml2/admin.py
@@ -28,6 +28,7 @@ from ipsilon.providers.saml2.provider import ServiceProviderCreator
 from ipsilon.providers.saml2.provider import InvalidProviderId
 from copy import deepcopy
 import requests
+import logging
 
 
 class NewSPAdminPage(AdminPage):
@@ -195,7 +196,7 @@ class SPAdminPage(AdminPage):
                         set(value) == set(option.get_value())):
                     continue
                 cherrypy.log.error("Storing %s = %s" %
-                                   (name, value))
+                                   (name, value), severity=logging.DEBUG)
                 new_db_values[name] = value
 
         if len(new_db_values) != 0:
diff --git a/ipsilon/rest/common.py b/ipsilon/rest/common.py
index 7baea94..904545c 100644
--- a/ipsilon/rest/common.py
+++ b/ipsilon/rest/common.py
@@ -2,6 +2,7 @@
 
 import cherrypy
 import json
+import logging
 from functools import wraps
 from ipsilon.util.endpoint import Endpoint
 
@@ -54,7 +55,8 @@ class RestPlugins(RestPage):
         for plugin in self._site[facility].available:
             obj = self._site[facility].available[plugin]
             if hasattr(obj, 'rest'):
-                cherrypy.log.error('Rest plugin: %s' % plugin)
+                cherrypy.log.error('Rest plugin: %s' % plugin,
+                                   severity=logging.DEBUG)
                 obj.rest.mount(self)
 
     def root_with_msg(self, message=None, message_type=None, changed=None):
diff --git a/ipsilon/util/data.py b/ipsilon/util/data.py
index a365e33..0d1c2df 100644
--- a/ipsilon/util/data.py
+++ b/ipsilon/util/data.py
@@ -24,6 +24,7 @@ from sqlalchemy.sql import select
 import ConfigParser
 import os
 import uuid
+import logging
 
 
 OPTIONS_COLUMNS = ['name', 'option', 'value']
@@ -36,7 +37,7 @@ class SqlStore(Log):
     @classmethod
     def get_connection(cls, name):
         if name not in cls.__instances.keys():
-            print 'SqlStore new: %s' % name
+            logging.debug('SqlStore new: %s', name)
             cls.__instances[name] = SqlStore(name)
         return cls.__instances[name]
 
diff --git a/ipsilon/util/log.py b/ipsilon/util/log.py
index 6ccfc42..ae851af 100644
--- a/ipsilon/util/log.py
+++ b/ipsilon/util/log.py
@@ -7,6 +7,7 @@ import cStringIO
 import inspect
 import os
 import traceback
+import logging
 
 
 def log_request_response():
@@ -327,6 +328,6 @@ class Log(object):
         cherrypy.log(fact)
 
     def error(self, fact):
-        cherrypy.log.error('ERROR: %s' % fact)
+        cherrypy.log.error('ERROR: %s' % fact, severity=logging.ERROR)
         if cherrypy.config.get('stacktrace_on_error', False):
             cherrypy.log.error(Log.stacktrace())
diff --git a/ipsilon/util/plugin.py b/ipsilon/util/plugin.py
index be6dd2f..2f9c003 100644
--- a/ipsilon/util/plugin.py
+++ b/ipsilon/util/plugin.py
@@ -19,6 +19,7 @@ import os
 import imp
 import cherrypy
 import inspect
+import logging
 from ipsilon.util.data import AdminStore
 from ipsilon.util.log import Log
 
@@ -30,7 +31,7 @@ class Plugins(object):
 
     def _load_class(self, tree, class_type, file_name, *pargs):
         cherrypy.log.error('Check module %s for class %s' % (file_name,
-                                                             class_type))
+                           class_type), severity=logging.DEBUG)
         name, ext = os.path.splitext(os.path.split(file_name)[-1])
         try:
             if ext.lower() == '.py':
@@ -40,21 +41,24 @@ class Plugins(object):
             else:
                 return
         except Exception, e:  # pylint: disable=broad-except
-            cherrypy.log.error('Failed to load "%s" module: [%s]' % (name, e))
+            cherrypy.log.error('Failed to load "%s" module: [%s]' % (name, e),
+                               severity=logging.ERROR)
             return
 
         if hasattr(mod, class_type):
             instance = getattr(mod, class_type)(*pargs)
             public_name = getattr(instance, 'name', name)
             tree[public_name] = instance
-            cherrypy.log.error('Added module %s as %s' % (name, public_name))
+            cherrypy.log.error('Added module %s as %s' % (name, public_name),
+                               severity=logging.DEBUG)
 
     def _load_classes(self, tree, path, class_type, *pargs):
         files = None
         try:
             files = os.listdir(path)
         except Exception, e:  # pylint: disable=broad-except
-            cherrypy.log.error('No modules in %s: [%s]' % (path, e))
+            cherrypy.log.error('No modules in %s: [%s]' % (path, e),
+                               severity=logging.ERROR)
             return
 
         for name in files:
diff --git a/ipsilon/util/user.py b/ipsilon/util/user.py
index aaab947..38449cc 100644
--- a/ipsilon/util/user.py
+++ b/ipsilon/util/user.py
@@ -18,6 +18,7 @@
 from ipsilon.util.data import UserStore
 from ipsilon.util.log import Log
 import cherrypy
+import logging
 
 
 class Site(object):
@@ -142,7 +143,8 @@ class UserSession(Log):
             if not type(user) is User:
                 raise TypeError
             # Completely reset user data
-            cherrypy.log.error('%s %s' % (user.name, user.fullname))
+            cherrypy.log.error('%s %s' % (user.name, user.fullname),
+                               severity=logging.INFO)
             user.reset()
 
         # Destroy current session in all cases