From aa5dc3b417db962a075a092d0d3528010c1059f7 Mon Sep 17 00:00:00 2001 From: Rob Crittenden Date: Tue, 21 Apr 2015 18:19:17 -0400 Subject: [PATCH] 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 Reviewed-by: Simo Sorce --- ipsilon/admin/common.py | 7 +++-- ipsilon/helpers/ipa.py | 24 ++++++--------- ipsilon/info/infosssd.py | 9 +++--- ipsilon/install/ipsilon-client-install | 8 ++--- ipsilon/install/ipsilon-server-install | 42 +++++++++++++++----------- ipsilon/login/authfas.py | 12 +++++--- ipsilon/login/authform.py | 3 +- ipsilon/login/authgssapi.py | 4 ++- ipsilon/login/authtest.py | 5 +-- ipsilon/providers/saml2/admin.py | 3 +- ipsilon/rest/common.py | 4 ++- ipsilon/util/data.py | 3 +- ipsilon/util/log.py | 3 +- ipsilon/util/plugin.py | 12 +++++--- ipsilon/util/user.py | 4 ++- 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 . 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 -- 2.20.1