changeset 3481:9a3deab96cb7

improve auth/session logging, add auth/session debug logging config
author Thomas Waldmann <tw AT waldmann-edv DOT de>
date Sat, 05 Apr 2008 22:20:38 +0200
parents b318efb0136b
children b0a794176dc4
files MoinMoin/auth/__init__.py MoinMoin/auth/interwiki.py MoinMoin/auth/mysql_group.py MoinMoin/session.py wiki/config/logging/logfile_debug_auth
diffstat 5 files changed, 89 insertions(+), 28 deletions(-) [+]
line wrap: on
line diff
--- a/MoinMoin/auth/__init__.py	Sat Apr 05 19:20:19 2008 +0200
+++ b/MoinMoin/auth/__init__.py	Sat Apr 05 22:20:38 2008 +0200
@@ -201,6 +201,7 @@
         return user_obj, True
     def logout(self, request, user_obj, **kw):
         if self.name and user_obj and user_obj.auth_method == self.name:
+            logging.debug("%s: logout - invalidating user %r" % (self.name, user_obj.name))
             user_obj.valid = False
         return user_obj, True
     def login_hint(self, request):
@@ -208,9 +209,8 @@
 
 class MoinLogin(BaseAuth):
     """ handle login from moin login form """
-    def __init__(self, verbose=False):
+    def __init__(self):
         BaseAuth.__init__(self)
-        self.verbose = verbose
 
     login_inputs = ['username', 'password']
     name = 'moin_login'
@@ -229,19 +229,17 @@
 
         _ = request.getText
 
-        verbose = self.verbose
-
-        if verbose: logging.info("performing login action")
+        logging.debug("%s: performing login action" % self.name)
 
         if username and not password:
             return ContinueLogin(user_obj, _('Missing password. Please enter user name and password.'))
 
         u = user.User(request, name=username, password=password, auth_method=self.name)
         if u.valid:
-            if verbose: logging.info("got valid user %r" % u.name)
+            logging.debug("%s: successfully authenticated user %r (valid)" % (self.name, u.name))
             return ContinueLogin(u)
         else:
-            if verbose: logging.info("login not valid, previous valid=%d." % user_obj.valid)
+            logging.debug("%s: could not authenticate user %r (not valid)" % (self.name, username))
             return ContinueLogin(user_obj, _("Invalid username or password."))
 
     def login_hint(self, request):
--- a/MoinMoin/auth/interwiki.py	Sat Apr 05 19:20:19 2008 +0200
+++ b/MoinMoin/auth/interwiki.py	Sat Apr 05 22:20:38 2008 +0200
@@ -7,8 +7,6 @@
     @license: GNU GPL, see COPYING for details.
 """
 
-verbose = False
-
 import xmlrpclib
 
 from MoinMoin import log
@@ -33,21 +31,21 @@
         if not username or not password:
             return ContinueLogin(user_obj)
 
-        if verbose: logging.info("trying to auth %r" % username)
+        logging.debug("trying to authenticate %r" % username)
         wikiname, username = username.split(' ', 1) # XXX Hack because ':' is not allowed in name field
         wikitag, wikiurl, name, err = wikiutil.resolve_interwiki(request, wikiname, username)
 
-        if verbose: logging.info("resolve wiki returned: %r %r %r %r" % (wikitag, wikiurl, name, err))
+        logging.debug("resolve wiki returned: %r %r %r %r" % (wikitag, wikiurl, name, err))
         if err or wikitag not in self.trusted_wikis:
             return ContinueLogin(user_obj)
 
         homewiki = xmlrpclib.ServerProxy(wikiurl + "?action=xmlrpc2")
         auth_token = homewiki.getAuthToken(name, password)
         if not auth_token:
-            if verbose: logging.info("%r wiki did not return an auth token." % wikitag)
+            logging.debug("%r wiki did not return an auth token." % wikitag)
             return ContinueLogin(user_obj)
 
-        if verbose: logging.info("successfully got an auth token for %r. trying to get user profile data..." % name)
+        logging.debug("successfully got an auth token for %r. trying to get user profile data..." % name)
 
         mc = xmlrpclib.MultiCall(homewiki)
         mc.applyAuthToken(auth_token)
@@ -55,14 +53,14 @@
         result, account_data = mc()
 
         if result != "SUCCESS":
-            if verbose: logging.info("%r wiki did not accept auth token." % wikitag)
+            logging.debug("%r wiki did not accept auth token." % wikitag)
             return ContinueLogin(None)
 
         if not account_data:
-            if verbose: logging.info("%r wiki did not return a user profile." % wikitag)
+            logging.debug("%r wiki did not return a user profile." % wikitag)
             return ContinueLogin(None)
 
-        if verbose: logging.info("%r wiki returned a user profile." % wikitag)
+        logging.debug("%r wiki returned a user profile." % wikitag)
 
         # TODO: check remote auth_attribs
         u = user.User(request, name=name, auth_method=self.name, auth_attribs=('name', 'aliasname', 'password', 'email', ))
@@ -71,6 +69,6 @@
                 setattr(u, key, value)
         u.valid = True
         u.create_or_update(True)
-        if verbose: logging.info("successful interwiki auth for %r" % name)
+        logging.debug("successful interwiki auth for %r" % name)
         return ContinueLogin(u)
 
--- a/MoinMoin/auth/mysql_group.py	Sat Apr 05 19:20:19 2008 +0200
+++ b/MoinMoin/auth/mysql_group.py	Sat Apr 05 22:20:38 2008 +0200
@@ -21,30 +21,27 @@
     We require an already-authenticated user_obj and
     check that the user is part of an authorized group.
     """
-    def __init__(self, host, user, passwd, dbname, query, verbose=False):
+    def __init__(self, host, user, passwd, dbname, query):
         BaseAuth.__init__(self)
         self.mysql_group_query = query
         self.host = host
         self.user = user
         self.passwd = passwd
         self.dbname = dbname
-        self.verbose = verbose
 
     def login(self, request, user_obj, **kw):
         _ = request.getText
 
-        verbose = self.verbose
-
-        if verbose: logging.info("got: user_obj=%r" % user_obj)
+        logging.debug("got: user_obj=%r" % user_obj)
 
         if not (user_obj and user_obj.valid):
             # No other method succeeded, so we cannot authorize
             # but maybe some following auth methods can still "fix" that.
-            if verbose: logging.info("did not get valid user from previous auth method")
+            logging.debug("did not get valid user from previous auth method")
             return ContinueLogin(user_obj)
 
         # Got a valid user object - we can do stuff!
-        if verbose: logging.info("got valid user (name=%s) from previous auth method" % user_obj.auth_username)
+        logging.debug("got valid user (name=%r) from previous auth method" % user_obj.auth_username)
 
         # XXX Check auth_username for dodgy chars (should be none as it is authenticated, but...)
         # shouldn't really be necessary since execute() quotes them all...
@@ -54,7 +51,7 @@
             m = MySQLdb.connect(host=self.host, user=self.user,
                                 passwd=self.passwd, db=self.dbname)
         except:
-            logging.exception("authorization failed due to exception connecting to DB, traceback follows...")
+            logging.exception("authorization failed due to exception when connecting to DB, traceback follows...")
             return CancelLogin(_('Failed to connect to database.'))
 
         c = m.cursor()
@@ -62,10 +59,10 @@
         results = c.fetchall()
         if results:
             # Checked out OK
-            if verbose: logging.info("got %d results -- authorized!" % len(results))
+            logging.debug("got %d results -- authorized!" % len(results))
             return ContinueLogin(user_obj)
         else:
-            if verbose: logging.info("did not get match from DB -- not authorized")
+            logging.debug("did not get match from DB -- not authorized")
             return CancelLogin(_("Invalid username or password."))
 
     # XXX do we really want this? could it be enough to check when they log in?
--- a/MoinMoin/session.py	Sat Apr 05 19:20:19 2008 +0200
+++ b/MoinMoin/session.py	Sat Apr 05 22:20:38 2008 +0200
@@ -5,12 +5,17 @@
     with help from a SessionHandler instance (see below.)
 
 
-    @copyright: 2007      MoinMoin:JohannesBerg
+    @copyright: 2007 MoinMoin:JohannesBerg,
+                2008 MoinMoin:ThomasWaldmann
 
     @license: GNU GPL, see COPYING for details.
 """
 
 import Cookie
+
+from MoinMoin import log
+logging = log.getLogger(__name__)
+
 from MoinMoin import caching
 from MoinMoin.user import User
 from MoinMoin.util import random_string
@@ -101,7 +106,9 @@
                                       use_pickle=True)
         try:
             self._data = self._ce.content()
+            logging.debug("loaded session data from cache entry: %r" % self._data)
             if self['expires'] <= time.time():
+                logging.debug("session expired, removing session cache entry")
                 self._ce.remove()
                 self._data = {'expires': 0}
         except caching.CacheError:
@@ -110,6 +117,7 @@
     def __setitem__(self, name, value):
         self._data[name] = value
         if len(self._data) > 1 and self['expires'] > time.time():
+            logging.debug("storing %r:%r item into session cache entry" % (name, value))
             self._ce.update(self._data)
 
     def __getitem__(self, name):
@@ -119,10 +127,12 @@
         return name in self._data
 
     def __delitem__(self, name):
+        old_value = self._data[name]
         del self._data[name]
         if len(self._data) <= 1:
             self._ce.remove()
         elif self['expires'] > time.time():
+            logging.debug("removing %r:%r item from session cache entry" % (name, old_value))
             self._ce.update(self._data)
 
     def get(self, name, default=None):
@@ -146,6 +156,7 @@
     def cleanup(cls, request):
         cachelist = caching.get_cache_list(request, 'session', 'farm')
         tnow = time.time()
+        removed_count = 0
         for name in cachelist:
             entry = caching.CacheEntry(request, 'session', name, 'farm',
                                        use_pickle=True)
@@ -153,8 +164,10 @@
                 data = entry.content()
                 if 'expires' in data and data['expires'] < tnow:
                     entry.remove()
+                    removed_count += 1
             except caching.CacheError:
                 pass
+        logging.debug("removed %d expired sessions while performing session cache cleanup" % removed_count)
     cleanup = classmethod(cleanup)
 
 
@@ -320,6 +333,7 @@
     def set(self, request, session_name, expires):
         """ Set moin_session cookie """
         self._set_cookie(request, session_name, expires)
+        logging.debug("setting cookie with session_name %r, expiry %r" % (session_name, expires))
 
     def get(self, request):
         session_name = None
@@ -328,6 +342,7 @@
             session_name = ''.join([c for c in session_name
                                     if c in self._SESSION_NAME_CHARS])
             session_name = session_name[:self._SESSION_NAME_LEN]
+            logging.debug("got cookie with session_name %r" % session_name)
         return session_name
 
 
@@ -371,6 +386,7 @@
         user_obj = None
         session_name = session_id_handler.get(request)
         if session_name:
+            logging.debug("starting session (reusing session_name %r)" % session_name)
             sessiondata = self.dataclass(request, session_name)
             sessiondata.is_new = False
             sessiondata.is_stored = True
@@ -395,11 +411,13 @@
                 sessiondata.is_stored = store
         else:
             session_name = session_id_handler.generate_new_id(request)
+            logging.debug("starting session (new session_name %r)" % session_name)
             store = hasattr(request.cfg, 'anonymous_session_lifetime')
             sessiondata = self.dataclass(request, session_name)
             sessiondata.is_new = True
             sessiondata.is_stored = store
             request.session = sessiondata
+        logging.debug("session started for user %r" % user_obj)
         return user_obj
 
     def after_auth(self, request, session_id_handler, user_obj):
@@ -412,6 +430,7 @@
             expires = time.time() + lifetime
             session_id_handler.set(request, session.name, expires)
             request.session.set_expiry(expires)
+            logging.debug("after auth: storing valid user into session: %r" % user_obj.name)
         else:
             if 'user.id' in session:
                 session.delete()
@@ -420,8 +439,10 @@
                 expires = time.time() + lifetime
                 session_id_handler.set(request, session.name, expires)
                 request.session.set_expiry(expires)
+                logging.debug("after auth: no valid user, anon session: %r" % session.name)
             else:
                 session.delete()
+                logging.debug("after auth: no valid user, no anon session")
 
     def finish(self, request, session_id_handler, user_obj):
         # every once a while, clean up deleted sessions:
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/wiki/config/logging/logfile_debug_auth	Sat Apr 05 22:20:38 2008 +0200
@@ -0,0 +1,47 @@
+# This is a sample auth/session debug logging configuration.
+# If one encounters problem, one usually want to have lots of information -
+# but only from SOME parts of moin not from every part.
+# Thus we configure the root logger to use INFO loglevel and
+# some specific loggers to use DEBUG logging.
+
+[DEFAULT]
+# Logfile to create.
+# Make sure the running moin process has create/write rights there.
+logfile=/tmp/moin.log
+
+[loggers]
+keys=root,moin_auth,moin_session
+
+[handlers]
+keys=logfile
+
+[formatters]
+keys=logfile
+
+[logger_root]
+level=INFO
+handlers=logfile
+
+[logger_moin_auth]
+level=DEBUG
+handlers=logfile
+propagate=0
+qualname=MoinMoin.auth
+
+[logger_moin_session]
+level=DEBUG
+handlers=logfile
+propagate=0
+qualname=MoinMoin.session
+
+[handler_logfile]
+class=FileHandler
+formatter=logfile
+level=DEBUG
+args=('%(logfile)s', 'at')
+
+[formatter_logfile]
+format=%(asctime)s %(name)s %(levelname)s %(message)s
+datefmt=
+class=logging.Formatter
+