added logging messages to django_authopenid library for debugging, \

also fixed up format of logging output and added HOW_TO_DEBUG file

7 files changed, 208 insertions, 60 deletions

diff --git a/HOW_TO_DEBUG b/HOW_TO_DEBUG
new file mode 100644
index 00000000..ba36198a
--- /dev/null
+++ b/HOW_TO_DEBUG
@@ -0,0 +1,39 @@
+1) LOGGING
+Please remember that log files may contain plaintext passwords, etc.
+
+Please do not add print statements - at least do not commit them to git
+because in some environments printing to stdout causes errors
+
+Instead use python logging this way:
+--------------------------------
+#somewere on top of file
+import logging
+
+#anywhere below
+logging.debug('this maybe works')
+logging.error('have big error!')
+#or even
+logging.debug('') #this will add time, line number, function and file record 
+#sometimes useful record for call tracing on its own
+#etc - take a look at http://docs.python.org/library/logging.html
+-------------------------------
+
+in OSQA logging is currently set up in settings_local.py.dist
+please update it if you need - in older revs logging strings have less info
+
+messages of interest can be grepped out of the log file by module/file/function name
+e.g. to take out all django_authopenid logs run: 
+>grep 'osqa\/django_authopenid' log/django.osqa.log | sed 's/^.*MSG: //'
+in the example above 'sed' call truncates out a long prefix
+and makes output look more meaningful
+
+2) DJANGO DEBUG TOOLBAR
+osqa works with django debug toolbar
+if debugging under apache server, check 
+that debug toolbar media is loaded correctly
+if toolbar is enabled but you do not see it, possibly some Alias statement
+in apache config is wrong in your VirtualHost or elsewhere
+
+3) If you discover new debugging techniques, please add here.
+Possible areas to improve - at this point there is no SQL query logging,
+as well as request data and http header.
diff --git a/django_authopenid/forms.py b/django_authopenid/forms.py
index 2fe6db74..5ec21c1c 100644
--- a/django_authopenid/forms.py
+++ b/django_authopenid/forms.py
@@ -94,7 +94,6 @@ class ClassicLoginForm(forms.Form):
         self.cleaned_data[field] = value
         return value 
 
-
     def clean_username(self):
         return self._clean_nonempty_field('username')
 
@@ -103,7 +102,7 @@ class ClassicLoginForm(forms.Form):
 
     def clean(self):
         """ 
-        this clean function actuall cleans username and password
+        this clean function actually cleans username and password
 
         test if password is valid for this username 
         this is really the "authenticate" function
@@ -118,7 +117,6 @@ class ClassicLoginForm(forms.Form):
 
         self.user_cache = None
         if username and password: 
-
             if settings.USE_EXTERNAL_LEGACY_LOGIN == True:
                 pw_ok = False
                 try:
diff --git a/django_authopenid/middleware.py b/django_authopenid/middleware.py
index 2900d54c..2be8da90 100644
--- a/django_authopenid/middleware.py
+++ b/django_authopenid/middleware.py
@@ -2,6 +2,8 @@
 from django_authopenid import mimeparse
 from django.http import HttpResponseRedirect
 from django.core.urlresolvers import reverse
+from django.conf import settings
+import logging
 
 __all__ = ["OpenIDMiddleware"]
 
@@ -12,6 +14,7 @@ class OpenIDMiddleware(object):
     """
     def process_request(self, request):
         request.openid = request.session.get('openid', None)
+        logging.debug('openid in session is: %s' % str(request.openid))
     
     def process_response(self, request, response):
         if response.status_code != 200 or len(response.content) < 200:
@@ -20,5 +23,6 @@ class OpenIDMiddleware(object):
         if path == "/" and request.META.has_key('HTTP_ACCEPT') and \
                 mimeparse.best_match(['text/html', 'application/xrds+xml'], 
                     request.META['HTTP_ACCEPT']) == 'application/xrds+xml':
+            logging.debug('redirecting to yadis_xrdf:%s' % reverse('yadis_xrdf'))
             return HttpResponseRedirect(reverse('yadis_xrdf'))
         return response
diff --git a/django_authopenid/models.py b/django_authopenid/models.py
index 7b2e1c02..a12c2fec 100644
--- a/django_authopenid/models.py
+++ b/django_authopenid/models.py
@@ -71,6 +71,10 @@ class UserPasswordQueue(models.Model):
         return self.user.username
 
 class ExternalLoginData(models.Model):
+    """this class was added by Evgeny to associate
+    external authentication user with django user
+    probably it just does not belong here... (EF)
+    """
     external_username = models.CharField(max_length=40, unique=True, null=False)
     external_session_data = models.TextField()
     user = models.ForeignKey(User, null=True)
diff --git a/django_authopenid/util.py b/django_authopenid/util.py
index 165756e0..969af0b9 100644
--- a/django_authopenid/util.py
+++ b/django_authopenid/util.py
@@ -14,7 +14,7 @@ try:
 except:
     from yadis import xri
 
-import time, base64, hashlib, operator
+import time, base64, hashlib, operator, logging
 from utils.forms import clean_next, get_next_url
 
 from models import Association, Nonce
@@ -23,6 +23,7 @@ __all__ = ['OpenID', 'DjangoOpenIDStore', 'from_openid_response', 'clean_next']
 
 class OpenID:
     def __init__(self, openid_, issued, attrs=None, sreg_=None):
+        logging.debug('init janrain openid object')
         self.openid = openid_
         self.issued = issued
         self.attrs = attrs or {}
diff --git a/django_authopenid/views.py b/django_authopenid/views.py
index b09dea7c..16a78864 100755
--- a/django_authopenid/views.py
+++ b/django_authopenid/views.py
@@ -60,7 +60,6 @@ except ImportError:
 import re
 import urllib
 
-
 from forum.forms import SimpleEmailSubscribeForm 
 from django_authopenid.util import OpenID, DjangoOpenIDStore, from_openid_response
 from django_authopenid.models import UserAssociation, UserPasswordQueue, ExternalLoginData
@@ -84,6 +83,7 @@ def login(request,user):
     #2) login and get new session key
     _login(request,user)
     #3) send signal with old session key as argument
+    logging.debug('logged in user %s with session key %s' % (user.username, session_key))
     user_logged_in.send(user=user,session_key=session_key,sender=None)
 
 def logout(request):
@@ -116,17 +116,22 @@ def ask_openid(request, openid_url, redirect_to, on_failure=None,
             settings, 'OPENID_DISALLOW_INAMES', False
     ):
         msg = _("i-names are not supported")
+        logging.debug('openid failed becaise i-names are not supported')
         return on_failure(request, msg)
     consumer = Consumer(request.session, DjangoOpenIDStore())
     try:
         auth_request = consumer.begin(openid_url)
     except DiscoveryFailure:
         msg = _(u"OpenID %(openid_url)s is invalid" % {'openid_url':openid_url})
+        logging.debug(msg)
         return on_failure(request, msg)
 
+    logging.debug('openid seemed to work')
     if sreg_request:
+        logging.debug('adding sreg_request - wtf it is?')
         auth_request.addExtension(sreg_request)
     redirect_url = auth_request.redirectURL(trust_root, redirect_to)
+    logging.debug('redirecting to %s' % redirect_url)
     return HttpResponseRedirect(redirect_url)
 
 def complete(request, on_success=None, on_failure=None, return_to=None):
@@ -134,30 +139,40 @@ def complete(request, on_success=None, on_failure=None, return_to=None):
     on_success = on_success or default_on_success
     on_failure = on_failure or default_on_failure
     
+    logging.debug('in django_authopenid.complete')
+    
     consumer = Consumer(request.session, DjangoOpenIDStore())
     # make sure params are encoded in utf8
     params = dict((k,smart_unicode(v)) for k, v in request.GET.items())
     openid_response = consumer.complete(params, return_to)
     
     if openid_response.status == SUCCESS:
+        logging.debug('SUCCESS')
         return on_success(request, openid_response.identity_url,
                 openid_response)
     elif openid_response.status == CANCEL:
+        logging.debug('CANCEL')
         return on_failure(request, 'The request was canceled')
     elif openid_response.status == FAILURE:
+        logging.debug('FAILURE')
         return on_failure(request, openid_response.message)
     elif openid_response.status == SETUP_NEEDED:
+        logging.debug('SETUP NEEDED')
         return on_failure(request, 'Setup needed')
     else:
+        logging.debug('BAD OPENID STATUS')
         assert False, "Bad openid status: %s" % openid_response.status
 
 def default_on_success(request, identity_url, openid_response):
     """ default action on openid signin success """
+    logging.debug('')
     request.session['openid'] = from_openid_response(openid_response)
+    logging.debug('performing default action on openid success %s' % get_next_url(request))
     return HttpResponseRedirect(get_next_url(request))
 
 def default_on_failure(request, message):
     """ default failure action on signin """
+    logging.debug('default openid failure action')
     return render_to_response('openid_failure.html', {
         'message': message
     })
@@ -177,11 +192,12 @@ def signin(request,newquestion=False,newanswer=False):
     """
     signin page. It manages the legacy authentification (user/password) 
     and openid authentification
-
+    
     url: /signin/
     
     template : authopenid/signin.htm
     """
+    logging.debug('in signin view')
     request.encoding = 'UTF-8'
     on_failure = signin_failure
     email_feeds_form = SimpleEmailSubscribeForm()
@@ -189,9 +205,10 @@ def signin(request,newquestion=False,newanswer=False):
     form_signin = OpenidSigninForm(initial={'next':next})
     form_auth = ClassicLoginForm(initial={'next':next})
     
-    if request.POST:   
+    if request.method == 'POST':
         #'blogin' - password login
         if 'blogin' in request.POST.keys():
+            logging.debug('processing classic login form submission')
             form_auth = ClassicLoginForm(request.POST)
             if form_auth.is_valid():
                 #have login and password and need to login through external website
@@ -201,19 +218,19 @@ def signin(request,newquestion=False,newanswer=False):
                     next = form_auth.cleaned_data['next']
                     if form_auth.get_user() == None:
                         #need to create internal user
-
+                        
                         #1) save login and password temporarily in session
                         request.session['external_username'] = username
                         request.session['external_password'] = password
-
+                        
                         #2) try to extract user email and nickname from external service
                         email = EXTERNAL_LOGIN_APP.api.get_email(username,password)
                         screen_name = EXTERNAL_LOGIN_APP.api.get_screen_name(username,password)
-
+                        
                         #3) see if username clashes with some existing user
                         #if so, we have to prompt the user to pick a different name
                         username_taken = User.is_username_taken(screen_name)
-
+                        
                         email_feeds_form = SimpleEmailSubscribeForm()
                         form_data = {'username':screen_name,'email':email,'next':next}
                         form = OpenidRegisterForm(initial=form_data)
@@ -237,8 +254,9 @@ def signin(request,newquestion=False,newanswer=False):
                     user = form_auth.get_user()
                     login(request, user)
                     return HttpResponseRedirect(get_next_url(request))
-
+        
         elif 'bnewaccount' in request.POST.keys():
+            logging.debug('processing classic (login/password) create account form submission')
             #register externally logged in password user with a new local account
             if settings.USE_EXTERNAL_LEGACY_LOGIN == True:
                 form = OpenidRegisterForm(request.POST) 
@@ -283,10 +301,12 @@ def signin(request,newquestion=False,newanswer=False):
                             context_instance=RequestContext(request))
             else:
                 raise Http404
-
+        
         elif 'bsignin' in request.POST.keys() or 'openid_username' in request.POST.keys():
+            logging.debug('processing signin with openid submission')
             form_signin = OpenidSigninForm(request.POST)
             if form_signin.is_valid():
+                logging.debug('OpenidSigninForm is valid')
                 next = form_signin.cleaned_data['next']
                 sreg_req = sreg.SRegRequest(optional=['nickname', 'email'])
                 redirect_to = "%s%s?%s" % (
@@ -299,13 +319,17 @@ def signin(request,newquestion=False,newanswer=False):
                         redirect_to, 
                         on_failure=signin_failure, 
                         sreg_request=sreg_req)
-
-
+            else:
+                logging.debug('OpenidSigninForm is NOT valid! -> redisplay login view')
+    
     #if request is GET
+    if request.method == 'GET':
+        logging.debug('request method was GET')
     question = None
     if newquestion == True:
         from forum.models import AnonymousQuestion as AQ
         session_key = request.session.session_key
+        logging.debug('retrieving anonymously posted question associated with session %s' % session_key)
         qlist = AQ.objects.filter(session_key=session_key).order_by('-added_at')
         if len(qlist) > 0:
             question = qlist[0]
@@ -313,10 +337,12 @@ def signin(request,newquestion=False,newanswer=False):
     if newanswer == True:
         from forum.models import AnonymousAnswer as AA
         session_key = request.session.session_key
+        logging.debug('retrieving posted answer associated with session %s' % session_key)
         alist = AA.objects.filter(session_key=session_key).order_by('-added_at')
         if len(alist) > 0:
             answer = alist[0]
-
+    
+    logging.debug('showing signin view')
     return render_to_response('authopenid/signin.html', {
         'question':question,
         'answer':answer,
@@ -329,32 +355,41 @@ def signin(request,newquestion=False,newanswer=False):
 
 def complete_signin(request):
     """ in case of complete signin with openid """
+    logging.debug('')#blank log just for the trace
     return complete(request, signin_success, signin_failure,
             get_url_host(request) + reverse('user_complete_signin'))
 
 def signin_success(request, identity_url, openid_response):
     """
     openid signin success.
-
+    
     If the openid is already registered, the user is redirected to 
     url set par next or in settings with OPENID_REDIRECT_NEXT variable.
     If none of these urls are set user is redirectd to /.
-
+    
     if openid isn't registered user is redirected to register page.
     """
 
+    logging.debug('')
     openid_ = from_openid_response(openid_response) #create janrain OpenID object
     request.session['openid'] = openid_
     try:
+        logging.debug('trying to get user associated with this openid...')
         rel = UserAssociation.objects.get(openid_url__exact = str(openid_))
+        logging.debug('success')
     except:
+        logging.debug('failed --> try to register brand new user')
         # try to register this new user
         return register(request)
     user_ = rel.user
     if user_.is_active:
         user_.backend = "django.contrib.auth.backends.ModelBackend"
+        logging.debug('user is active --> attached django auth ModelBackend --> calling login')
         login(request, user_)
-        
+        logging.debug('success')
+    else:
+        logging.debug('user is inactive, do not log them in')
+    logging.debug('redirecting to %s' % get_next_url(request))
     return HttpResponseRedirect(get_next_url(request))
 
 def is_association_exist(openid_url):
@@ -364,29 +399,32 @@ def is_association_exist(openid_url):
         uassoc = UserAssociation.objects.get(openid_url__exact = openid_url)
     except:
         is_exist = False
+    logging.debug(str(is_exist))
     return is_exist
 
 @not_authenticated
 def register(request):
     """
     register an openid.
-
+    
     If user is already a member he can associate its openid with 
     its account.
-
+    
     A new account could also be created and automaticaly associated
     to the openid.
-
+    
     url : /complete/
-
+    
     template : authopenid/complete.html
     """
-
+    
+    logging.debug('')
     openid_ = request.session.get('openid', None)
     next = get_next_url(request)
     if not openid_:
+        logging.debug('oops, no openid in session --> go back to signin')
         return HttpResponseRedirect(reverse('user_signin') + '?next=%s' % next)
-
+    
     nickname = openid_.sreg.get('nickname', '')
     email = openid_.sreg.get('email', '')
     form1 = OpenidRegisterForm(initial={
@@ -399,55 +437,73 @@ def register(request):
         'username': nickname,
     })
     email_feeds_form = SimpleEmailSubscribeForm()
-
+    
     user_ = None
     is_redirect = False
-    if request.POST:
+    logging.debug('request method is %s' % request.method)
+    if request.method == 'POST':
         if 'bnewaccount' in request.POST.keys():
+            logging.debug('trying to create new account associated with openid')
             form1 = OpenidRegisterForm(request.POST)
             email_feeds_form = SimpleEmailSubscribeForm(request.POST)
-            if form1.is_valid() and email_feeds_form.is_valid():
+            if not form1.is_valid():
+                logging.debug('OpenidRegisterForm is INVALID')
+            elif not email_feeds_form.is_valid():
+                logging.debug('SimpleEmailSubscribeForm is INVALID')
+            else:
+                logging.debug('OpenidRegisterForm and SimpleEmailSubscribeForm are valid')
                 next = form1.cleaned_data['next']
                 is_redirect = True
+                logging.debug('creatng new django user %s ...' % form1.cleaned_data['username'])
                 tmp_pwd = User.objects.make_random_password()
                 user_ = User.objects.create_user(form1.cleaned_data['username'],
                          form1.cleaned_data['email'], tmp_pwd)
-
+                
                 user_.set_unusable_password()
                 # make association with openid
-                uassoc = UserAssociation(openid_url=str(openid_),
-                        user_id=user_.id)
+                logging.debug('creating new openid user association %s <--> %s' \
+                            % (user_.username, str(openid_)))
+                uassoc = UserAssociation(openid_url=str(openid_), user_id=user_.id)
                 uassoc.save()
-                    
+                
                 # login 
                 user_.backend = "django.contrib.auth.backends.ModelBackend"
+                logging.debug('logging the user in')
                 login(request, user_)
+                logging.debug('saving email feed settings')
                 email_feeds_form.save(user_)
         elif 'bverify' in request.POST.keys():
+            logging.debug('processing OpenidVerify form')
             form2 = OpenidVerifyForm(request.POST)
             if form2.is_valid():
+                logging.debug('form is valid')
                 is_redirect = True
                 next = form2.cleaned_data['next']
                 user_ = form2.get_user()
-
+                logging.debug('creating new openid user association %s <--> %s' \
+                            % (user_.username, str(openid_)))
                 uassoc = UserAssociation(openid_url=str(openid_),
                         user_id=user_.id)
                 uassoc.save()
+                logging.debug('logging the user in')
                 login(request, user_)
-
+        
         #check if we need to post a question that was added anonymously
         #this needs to be a function call becase this is also done
         #if user just logged in and did not need to create the new account
         
         if user_ != None:
             if settings.EMAIL_VALIDATION == 'on':
+                logging.debug('sending email validation')
                 send_new_email_key(user_,nomessage=True)
                 output = validation_email_sent(request)
                 set_email_validation_message(user_) #message set after generating view
                 return output
             if user_.is_authenticated():
+                logging.debug('success, send user to main page')
                 return HttpResponseRedirect(reverse('index'))
             else:
+                logging.debug('have really strange error')
                 raise Exception('openid login failed')#should not ever get here
     
     openid_str = str(openid_)
@@ -455,7 +511,7 @@ def register(request):
     base_url = bits[2] #assume this is base url
     url_bits = base_url.split('.')
     provider_name = url_bits[-2].lower()
-
+    
     providers = {'yahoo':'<font color="purple">Yahoo!</font>',
                 'flickr':'<font color="#0063dc">flick</font><font color="#ff0084">r</font>&trade;',
                 'google':'Google&trade;',
@@ -464,9 +520,11 @@ def register(request):
                 }
     if provider_name not in providers:
         provider_logo = provider_name
+        logging.error('openid provider named "%s" has no pretty customized logo' % provider_name)
     else:
         provider_logo = providers[provider_name]
-
+    
+    logging.debug('printing authopenid/complete.html output')
     return render_to_response('authopenid/complete.html', {
         'form1': form1,
         'form2': form2,
@@ -484,10 +542,11 @@ def signin_failure(request, message):
 
     template : "authopenid/signin.html"
     """
+    logging.debug('')
     next = get_next_url(request)
     form_signin = OpenidSigninForm(initial={'next': next})
     form_auth = ClassicLoginForm(initial={'next': next})
-
+    
     return render_to_response('authopenid/signin.html', {
         'msg': message,
         'form1': form_auth,
@@ -498,18 +557,21 @@ def signin_failure(request, message):
 def signup(request):
     """
     signup page. Create a legacy account
-
+    
     url : /signup/"
-
+    
     templates: authopenid/signup.html, authopenid/confirm_email.txt
     """
+    logging.debug('')
     if settings.USE_EXTERNAL_LEGACY_LOGIN == True:
+        logging.debug('handling external legacy login registration')
         return HttpResponseRedirect(reverse('user_external_legacy_login_signup'))
     next = get_next_url(request)
-    if request.POST:
+    logging.debug('request method was %s' % request.method)
+    if request.method == 'POST':
         form = ClassicRegisterForm(request.POST)
         email_feeds_form = SimpleEmailSubscribeForm(request.POST)
-
+        
         #validation outside if to remember form values
         form1_is_valid = form.is_valid()
         form2_is_valid = email_feeds_form.is_valid()
@@ -518,11 +580,11 @@ def signup(request):
             username = form.cleaned_data['username']
             password = form.cleaned_data['password1']
             email = form.cleaned_data['email']
-
+            
             user_ = User.objects.create_user( username,email,password )
             if settings.USE_EXTERNAL_LEGACY_LOGIN == True:
                 EXTERNAL_LOGIN_APP.api.create_user(username,email,password)
-           
+            
             user_.backend = "django.contrib.auth.backends.ModelBackend"
             login(request, user_)
             email_feeds_form.save(user_)
@@ -540,10 +602,14 @@ def signup(request):
             message = message_template.render(message_context)
             send_mail(subject, message, settings.DEFAULT_FROM_EMAIL, 
                     [user_.email])
+            logging.debug('new user with login and password created!')
             return HttpResponseRedirect(next)
+        else:
+            logging.debug('create classic account forms were invalid')
     else:
         form = ClassicRegisterForm(initial={'next':next})
         email_feeds_form = SimpleEmailSubscribeForm()
+    logging.debug('printing legacy signup form')
     return render_to_response('authopenid/signup.html', {
         'form': form, 
         'email_feeds_form': email_feeds_form 
@@ -557,15 +623,20 @@ def signout(request):
 
     url : /signout/"
     """
+    logging.debug('')
     try:
+        logging.debug('deleting openid session var')
         del request.session['openid']
     except KeyError:
+        logging.debug('failed')
         pass
     logout(request)
+    logging.debug('user logged out')
     return HttpResponseRedirect(get_next_url(request))
     
 def xrdf(request):
     url_host = get_url_host(request)
+    logging.debug('what does this do??')
     return_to = [
         "%s%s" % (url_host, reverse('user_complete_signin'))
     ]
@@ -586,6 +657,7 @@ def account_settings(request):
 
     template : authopenid/settings.html
     """
+    logging.debug('')
     msg = request.GET.get('msg', '')
     is_openid = True
 
@@ -610,6 +682,7 @@ def changepw(request):
     url : /changepw/
     template: authopenid/changepw.html
     """
+    logging.debug('')
     user_ = request.user
 
     if user_.has_usable_password():
@@ -710,6 +783,7 @@ def send_email_key(request):
 
 #internal server view used as return value by other views
 def validation_email_sent(request):
+    logging.debug('')
     return render_to_response('authopenid/changeemail.html',
                     { 'email': request.user.email, 
                     'change_email_url': reverse('user_changeemail'),
@@ -721,6 +795,7 @@ def verifyemail(request,id=None,key=None):
     view that is shown when user clicks email validation link
     url = /email/verify/{{user.id}}/{{user.email_key}}/
     """
+    logging.debug('')
     if settings.EMAIL_VALIDATION != 'off':
         user = User.objects.get(id=id)
         if user:
@@ -731,6 +806,8 @@ def verifyemail(request,id=None,key=None):
                 return render_to_response('authopenid/changeemail.html', {
                     'action_type': 'validation_complete',
                     }, context_instance=RequestContext(request))
+            else:
+                logging.error('hmm, no user found for email validation message - foul play?')
     raise Http404
 
 @login_required
@@ -742,6 +819,7 @@ def changeemail(request, action='change'):
 
     template : authopenid/changeemail.html
     """
+    logging.debug('')
     msg = request.GET.get('msg', None)
     extension_args = {}
     user_ = request.user
@@ -786,6 +864,7 @@ def changeemail(request, action='change'):
     return output
 
 def emailopenid_success(request, identity_url, openid_response):
+    logging.debug('')
     openid_ = from_openid_response(openid_response)
 
     user_ = request.user
@@ -815,6 +894,7 @@ def emailopenid_success(request, identity_url, openid_response):
     
 
 def emailopenid_failure(request, message):
+    logging.debug('')
     redirect_to = "%s?msg=%s" % (
             reverse('user_changeemail'), urlquote_plus(message))
     return HttpResponseRedirect(redirect_to)
@@ -829,6 +909,7 @@ def changeopenid(request):
 
     template: authopenid/changeopenid.html
     """
+    logging.error('change openid view - never tested it yet!!!')
 
     extension_args = {}
     openid_url = ''
@@ -862,6 +943,7 @@ def changeopenid(request):
         }, context_instance=RequestContext(request))
 
 def changeopenid_success(request, identity_url, openid_response):
+    logging.error('never tested this worflow')
     openid_ = from_openid_response(openid_response)
     is_exist = True
     try:
@@ -895,6 +977,7 @@ def changeopenid_success(request, identity_url, openid_response):
     
 
 def changeopenid_failure(request, message):
+    logging.error('never tested this workflow')
     redirect_to = "%s?msg=%s" % (
             reverse('user_changeopenid'), 
             urlquote_plus(message))
@@ -905,16 +988,17 @@ def delete(request):
     """
     delete view. Allow user to delete its account. Password/openid are required to 
     confirm it. He should also check the confirm checkbox.
-
+    
     url : /delete
-
+    
     template : authopenid/delete.html
     """
-
+    logging.error('deleting account - never tested this')
+    
     extension_args = {}
     
     user_ = request.user
-
+    
     redirect_to = get_url_host(request) + reverse('user_delete') 
     if request.POST:
         form = DeleteForm(request.POST, user=user_)
@@ -930,7 +1014,7 @@ def delete(request):
                 redirect_to) 
     
     form = DeleteForm(user=user_)
-
+    
     msg = request.GET.get('msg','')
     return render_to_response('authopenid/delete.html', {
         'form': form, 
@@ -938,6 +1022,7 @@ def delete(request):
         }, context_instance=RequestContext(request))
 
 def deleteopenid_success(request, identity_url, openid_response):
+    logging.error('never tested this')
     openid_ = from_openid_response(openid_response)
 
     user_ = request.user
@@ -963,10 +1048,12 @@ def deleteopenid_success(request, identity_url, openid_response):
     
 
 def deleteopenid_failure(request, message):
+    logging.error('never tested this')
     redirect_to = "%s?msg=%s" % (reverse('user_delete'), urlquote_plus(message))
     return HttpResponseRedirect(redirect_to)
 
 def external_legacy_login_info(request):
+    logging.debug('maybe this view does not belong in this library')
     feedback_url = reverse('feedback')
     return render_to_response('authopenid/external_legacy_login_info.html', 
                     {'feedback_url':feedback_url}, 
@@ -977,18 +1064,22 @@ def sendpw(request):
     send a new password to the user. It return a mail with 
     a new pasword and a confirm link in. To activate the 
     new password, the user should click on confirm link.
-
+    
     url : /sendpw/
-
+    
     templates :  authopenid/sendpw_email.txt, authopenid/sendpw.html
     """
+    logging.debug('')
     if settings.USE_EXTERNAL_LEGACY_LOGIN == True:
+        logging.debug('delegating to view dealing with external password recovery')
         return HttpResponseRedirect(reverse('user_external_legacy_login_issues'))
-
+    
     msg = request.GET.get('msg','')
-    if request.POST:
+    logging.debug('request method is %s' % request.method)
+    if request.method == 'POST':
         form = EmailPasswordForm(request.POST)
         if form.is_valid():
+            logging.debug('EmailPasswordForm is valid')
             new_pw = User.objects.make_random_password()
             confirm_key = UserPasswordQueue.objects.get_new_confirm_key()
             try:
@@ -1007,6 +1098,7 @@ def sendpw(request):
             message_template = loader.get_template(
                     'authopenid/sendpw_email.txt')
             key_link = settings.APP_URL + reverse('user_confirmchangepw') + '?key=' + confirm_key
+            logging.debug('emailing new password for %s' % form.user_cache.username)
             message_context = Context({ 
                 'site_url': settings.APP_URL + reverse('index'),
                 'key_link': key_link,
@@ -1019,13 +1111,13 @@ def sendpw(request):
             msg = _("A new password and the activation link were sent to your email address.")
     else:
         form = EmailPasswordForm()
-        
+    
+    logging.debug('showing reset password form')
     return render_to_response('authopenid/sendpw.html', {
         'form': form,
         'msg': msg 
         }, context_instance=RequestContext(request))
 
-
 def confirmchangepw(request):
     """
     view to set new password when the user click on confirm link
@@ -1033,14 +1125,16 @@ def confirmchangepw(request):
     replace old password with new password and remove confirm
     ley from the queue. Then it redirect the user to signin
     page.
-
+    
     url : /sendpw/confirm/?key
-
+    
     """
+    logging.debug('')
     confirm_key = request.GET.get('key', '')
     if not confirm_key:
+        logging.error('someone called confirm password without a key!')
         return HttpResponseRedirect(reverse('index'))
-
+    
     try:
         uqueue = UserPasswordQueue.objects.get(
                 confirm_key__exact=confirm_key
@@ -1048,25 +1142,28 @@ def confirmchangepw(request):
     except:
         msg = _("Could not change password. Confirmation key '%s'\
                 is not registered." % confirm_key) 
+        logging.error(msg)
         redirect = "%s?msg=%s" % (
                 reverse('user_sendpw'), urlquote_plus(msg))
         return HttpResponseRedirect(redirect)
-
+    
     try:
         user_ = User.objects.get(id=uqueue.user.id)
     except:
         msg = _("Can not change password. User don't exist anymore \
                 in our database.") 
+        logging.error(msg)
         redirect = "%s?msg=%s" % (reverse('user_sendpw'), 
                 urlquote_plus(msg))
         return HttpResponseRedirect(redirect)
-
+    
     user_.set_password(uqueue.new_password)
     user_.save()
     uqueue.delete()
     msg = _("Password changed for %s. You may now sign in." % 
             user_.username) 
+    logging.debug(msg)
     redirect = "%s?msg=%s" % (reverse('user_signin'), 
                                         urlquote_plus(msg))
-
+    
     return HttpResponseRedirect(redirect)
diff --git a/settings_local.py.dist b/settings_local.py.dist
index 7fbc0729..0ef11eca 100755
--- a/settings_local.py.dist
+++ b/settings_local.py.dist
@@ -15,6 +15,11 @@ LOG_FILENAME = 'django.osqa.log'
 #for logging
 import logging
 logging.basicConfig(filename=os.path.join(SITE_SRC_ROOT, 'log', LOG_FILENAME), level=logging.DEBUG,)
+logging.basicConfig(
+    filename=os.path.join(SITE_SRC_ROOT, 'log', LOG_FILENAME),
+    level=logging.DEBUG,
+    format='%(pathname)s TIME: %(asctime)s MSG: %(filename)s:%(funcName)s:%(lineno)d %(message)s',
+)
 
 #ADMINS and MANAGERS
 ADMINS = (('Forum Admin', 'forum@example.com'),)