diff --git a/hub/kojihub.py b/hub/kojihub.py index ecb3e159..ea0924fc 100644 --- a/hub/kojihub.py +++ b/hub/kojihub.py @@ -31,12 +31,10 @@ import koji.policy import datetime import errno import logging -import logging.handlers import fcntl import fnmatch from koji.util import md5_constructor import os -import pgdb import random import re import rpm @@ -49,12 +47,15 @@ import types import xmlrpclib from koji.context import context + +logger = logging.getLogger('koji.hub') + def log_error(msg): if hasattr(context,'req'): context.req.log_error(msg) else: sys.stderr.write(msg + "\n") - logging.getLogger('koji.hub').error(msg) + logger.error(msg) class Task(object): diff --git a/hub/kojixmlrpc.py b/hub/kojixmlrpc.py index 47e80382..87b05549 100644 --- a/hub/kojixmlrpc.py +++ b/hub/kojixmlrpc.py @@ -21,6 +21,7 @@ # Mike McLean from ConfigParser import ConfigParser +import logging import sys import time import traceback @@ -234,11 +235,9 @@ class ModXMLRPCRequestHandler(object): sys.stderr.flush() response = dumps(Fault(faultCode, faultString)) - if _opt_bool(context.opts, 'KojiDebug'): - sys.stderr.write("Returning %d bytes after %f seconds\n" % - (len(response),time.time() - start)) - sys.stderr.flush() - + logger.debug("Returning %d bytes after %f seconds\n", len(response), + time.time() - start) + return response def _dispatch(self,method,params): @@ -262,21 +261,20 @@ class ModXMLRPCRequestHandler(object): params,opts = koji.decode_args(*params) if _opt_bool(context.opts, 'KojiDebug'): - sys.stderr.write("Handling method %s for session %s (#%s)\n" \ - % (method, context.session.id, context.session.callnum)) + logger.debug("Handling method %s for session %s (#%s)", + method, context.session.id, context.session.callnum) if method != 'uploadFile': - sys.stderr.write("Params: %s\n" % pprint.pformat(params)) - sys.stderr.write("Opts: %s\n" % pprint.pformat(opts)) + logger.debug("Params: %s\n", pprint.pformat(params)) + logger.debug("Opts: %s\n", pprint.pformat(opts)) start = time.time() - + ret = func(*params,**opts) if _opt_bool(context.opts, 'KojiDebug'): - sys.stderr.write("Completed method %s for session %s (#%s): %f seconds\n" - % (method, context.session.id, context.session.callnum, - time.time()-start)) - sys.stderr.flush() - + logger.debug("Completed method %s for session %s (#%s): %f seconds", + method, context.session.id, context.session.callnum, + time.time()-start) + return ret def multiCall(self, calls): @@ -439,15 +437,14 @@ def load_plugins(opts): return tracker = koji.plugin.PluginTracker(path=opts['PluginPath'].split(':')) for name in opts['Plugins'].split(): - sys.stderr.write('Loading plugin: %s\n' % name) + logger.info('Loading plugin: %s\n', name) try: tracker.load(name) except Exception: - sys.stderr.write(''.join(traceback.format_exception(*sys.exc_info()))) + logger.error(''.join(traceback.format_exception(*sys.exc_info()))) #make this non-fatal, but set ServerOffline opts['ServerOffline'] = True opts['OfflineMessage'] = 'configuration error' - sys.stderr.flush() return tracker _default_policies = { @@ -493,6 +490,40 @@ def get_policy(opts, plugins): return policy +class HubFormatter(logging.Formatter): + """Support some koji specific fields in the format string""" + + def format(self, record): + record.method = getattr(context, 'method', None) + if hasattr(context, 'session'): + record.user_id = context.session.user_id + record.session_id = context.session.id + record.callnum = context.session.callnum + record.user_name = context.session.user_data.get('name') + else: + record.user_id = None + record.session_id = None + record.callnum = None + record.user_name = None + return logging.Formatter.format(self, record) + + +def setup_logging(opts): + #TODO - more robust config + global logger + logger = logging.getLogger("koji") + if opts.get('KojiDebug'): + logger.setLevel(logging.DEBUG) + else: + logger.setLevel(logging.INFO) + #for now, just stderr logging (stderr goes to httpd logs) + #koji.add_stderr_logger("koji") + handler = logging.StreamHandler() + handler.setFormatter(HubFormatter('%(asctime)s [%(levelname)s] (%(method)s, %(user_name)s) %(name)s: %(message)s')) + handler.setLevel(logging.DEBUG) + logger.addHandler(handler) + + # # mod_python handler # @@ -506,6 +537,7 @@ def handler(req, profiling=False): if firstcall: firstcall = False opts = load_config(req) + setup_logging(opts) plugins = load_plugins(opts) registry = get_registry(opts, plugins) policy = get_policy(opts, plugins) @@ -543,7 +575,7 @@ def handler(req, profiling=False): password = opts.get("DBPass",None), host = opts.get("DBHost", None)) try: - context.cnx = koji.db.connect(_opt_bool(opts, 'KojiDebug')) + context.cnx = koji.db.connect() except Exception: offline_reply(req, msg="database outage") return apache.OK diff --git a/koji/auth.py b/koji/auth.py index 06b5fbe0..ace1af7c 100644 --- a/koji/auth.py +++ b/koji/auth.py @@ -44,6 +44,8 @@ class Session(object): self.master = None self.key = None self.user_id = None + self.hostip = None + self.user_data = {} self.message = '' self.exclusive = False self.lockerror = None diff --git a/koji/db.py b/koji/db.py index 18a68691..ca91ab4d 100644 --- a/koji/db.py +++ b/koji/db.py @@ -21,6 +21,7 @@ # Mike McLean +import logging import sys import pgdb import time @@ -41,9 +42,8 @@ _DBopts = None _DBconn = context.ThreadLocal() class DBWrapper: - def __init__(self, cnx, debug=False): + def __init__(self, cnx): self.cnx = cnx - self.debug = debug def __getattr__(self, key): if not self.cnx: @@ -53,7 +53,7 @@ class DBWrapper: def cursor(self, *args, **kw): if not self.cnx: raise StandardError, 'connection is closed' - return CursorWrapper(self.cnx.cursor(*args, **kw),self.debug) + return CursorWrapper(self.cnx.cursor(*args, **kw)) def close(self): # Rollback any uncommitted changes and clear the connection so @@ -67,21 +67,17 @@ class DBWrapper: class CursorWrapper: - def __init__(self, cursor, debug=False): + def __init__(self, cursor): self.cursor = cursor - self.debug = debug + self.logger = logging.getLogger('koji.db') def __getattr__(self, key): return getattr(self.cursor, key) def _timed_call(self, method, args, kwargs): - if self.debug: - start = time.time() + start = time.time() ret = getattr(self.cursor,method)(*args,**kwargs) - if self.debug: - sys.stderr.write("%s operation completed in %.4f seconds\n" % - (method, time.time() - start)) - sys.stderr.flush() + self.logger.debug("%s operation completed in %.4f seconds", method, time.time() - start) return ret def fetchone(self,*args,**kwargs): @@ -91,16 +87,13 @@ class CursorWrapper: return self._timed_call('fetchall',args,kwargs) def execute(self, operation, parameters=()): - if self.debug: - sys.stderr.write(_quoteparams(operation,parameters)) - sys.stderr.write("\n") - sys.stderr.flush() + debug = self.logger.isEnabledFor(logging.DEBUG) + if debug: + self.logger.debug(_quoteparams(operation,parameters)) start = time.time() ret = self.cursor.execute(operation, parameters) - if self.debug: - sys.stderr.write("Execute operation completed in %.4f seconds\n" % - (time.time() - start)) - sys.stderr.flush() + if debug: + self.logger.debug("Execute operation completed in %.4f seconds\n", time.time() - start) return ret @@ -117,7 +110,7 @@ def setDBopts(**opts): def getDBopts(): return _DBopts -def connect(debug=False): +def connect(): global _DBconn if hasattr(_DBconn, 'conn'): # Make sure the previous transaction has been @@ -132,7 +125,7 @@ def connect(debug=False): # BEGIN will be a harmless no-op, though there may be a warning. conn.cursor().execute('BEGIN') conn.rollback() - return DBWrapper(conn, debug) + return DBWrapper(conn) except pgdb.Error: del _DBconn.conn #create a fresh connection @@ -144,7 +137,7 @@ def connect(debug=False): # return conn _DBconn.conn = conn - return DBWrapper(conn, debug) + return DBWrapper(conn) if __name__ == "__main__": setDBopts( database = "test", user = "test")