added logging and logs config
authordurandn
Mon, 14 Mar 2016 14:17:29 +0100
changeset 32 eb9e83610c99
parent 31 360b1bcb252e
child 33 c648c98bcee7
added logging and logs config
oauth/client.py
server/src/metaeducation/auth.py
server/src/metaeducation/middleware.py
server/src/metaeducation/mtdc_oauth_provider/views.py
server/src/metaeducation/settings/dev.py.tmpl
server/src/metaeducation/signals.py
--- a/oauth/client.py	Fri Mar 11 16:32:30 2016 +0100
+++ b/oauth/client.py	Mon Mar 14 14:17:29 2016 +0100
@@ -51,7 +51,7 @@
         session['remote_oauth_clientcredentials'] = (json.loads(resp.text)['access_token'], '')
         resp = remote.get('user/InfoComplete')
         print("clientcredentials resp data: "+str(resp.data))
-        server = resp.data.get("username", "")
+        server = resp.data.get("displayName", "")
         session["server"] = server
     return render_template('client/index.html', current_user_id=session["me_id"], current_username=session["me"], oauth_username=session["server"])
 
--- a/server/src/metaeducation/auth.py	Fri Mar 11 16:32:30 2016 +0100
+++ b/server/src/metaeducation/auth.py	Mon Mar 14 14:17:29 2016 +0100
@@ -1,34 +1,42 @@
-from rest_framework.authentication import BaseAuthentication
+from urllib import parse
+
+import requests, re, json, logging
+
+from django.conf import settings
 from django.contrib.auth import get_user_model, login
 from django.contrib.auth.models import Permission
-from django.conf import settings
-from urllib import parse
-import requests
-import re
-import json
+from rest_framework.authentication import BaseAuthentication
+
+
+logger = logging.getLogger(__name__)
 
 class MtdcOAuth2ClientCredentialsAuthentication(BaseAuthentication):
     
     def authenticate(self, request):
         # get token, get username
         if ("act_as" not in request.GET) and ('HTTP_RENKAN_ACT_AS' not in request.META):
+            logger.debug("CLIENT CREDENTIAL AUTH: no act_as, not client credentials")
             return
         else:
             external_id = request.GET.get('act_as', request.META.get("HTTP_RENKAN_ACT_AS", ""))
         try: 
             user = get_user_model().objects.get(external_id=external_id)
         except get_user_model().DoesNotExist:
+            logger.debug("CLIENT CREDENTIAL AUTH: User does not exist, abort")
             return
         if 'HTTP_AUTHORIZATION' not in request.META:
+            logger.debug("CLIENT CREDENTIAL AUTH: no token, abort")
             return
         else:
             token = re.search("(?<=\s).*", request.META["HTTP_AUTHORIZATION"]).group(0)
-        print(token)
+            logger.debug("CLIENT CREDENTIAL AUTH: token is "+token)
         # send token to Oauth server
         token_validate_response = requests.get(
             settings.MTDC_VALIDATE_TOKEN_BASE_URL+token+"?redirect_uri="+parse.quote_plus(settings.MTDC_GED_BASE_URL)
         )
         if token_validate_response.status_code != 200:
+            logger.debug("CLIENT CREDENTIAL AUTH: token validate failed, abort")
             return
+        logger.debug("CLIENT CREDENTIAL AUTH: user "+external_id+" is authenticated by token "+token+", auth success")
         return (user, None)
     
--- a/server/src/metaeducation/middleware.py	Fri Mar 11 16:32:30 2016 +0100
+++ b/server/src/metaeducation/middleware.py	Mon Mar 14 14:17:29 2016 +0100
@@ -1,7 +1,11 @@
-from django.shortcuts import redirect
+import logging
+from re import compile
+from urllib.parse import urlencode
+
 from django.conf import settings
-from urllib.parse import urlencode
-from re import compile
+from django.shortcuts import redirect
+
+logger = logging.getLogger(__name__)
 
 EXEMPT_URLS = [compile(settings.LOGIN_URL.lstrip('/'))]
 if hasattr(settings, 'OAUTH_EXEMPT_URLS'):
@@ -15,9 +19,11 @@
         if not request.user.is_authenticated():
             path = request.path_info.lstrip('/')
             if not any(m.match(path) for m in EXEMPT_URLS):
+                logger.debug("LOGIN_REQUIRED: User is not logged and this request triggered Oauth redirects")
                 if request.GET.get("context", ""):
                     context = request.GET["context"]
                     response = redirect(settings.LOGIN_URL)
-                    print(path)
+                    logger.debug("LOGIN_REQUIRED: will redirect to "+settings.LOGIN_URL)
+                    logger.debug("LOGIN_REQUIRED: query args will be "+str({"context": context, "next": settings.BASE_URL+path}))
                     response["LOCATION"] += "?"+urlencode({"context": context, "next": settings.BASE_URL+path})
                     return response
--- a/server/src/metaeducation/mtdc_oauth_provider/views.py	Fri Mar 11 16:32:30 2016 +0100
+++ b/server/src/metaeducation/mtdc_oauth_provider/views.py	Mon Mar 14 14:17:29 2016 +0100
@@ -1,4 +1,4 @@
-import requests
+import requests, logging
 
 from datetime import timedelta
 
@@ -28,6 +28,8 @@
 
 from .provider import MtdcProvider
 
+logger = logging.getLogger(__name__)
+
 class MtdcOAuth2Adapter(OAuth2Adapter, DefaultSocialAccountAdapter):
     provider_id = MtdcProvider.id
     supports_state = False
@@ -39,37 +41,46 @@
     
     def __init__(self, request=None):
         if request:
+            logger.debug("AUTHORIZATION CODE AUTH: init adapter")
             if request.session.get("OAUTH_CONTEXT_BASE_URL", None) is None:
+                logger.debug("AUTHORIZATION CODE AUTH: no context in session, storing context")
                 request.session["OAUTH_CONTEXT_BASE_URL"] = request.GET.get("context", None)
+                logger.debug("AUTHORIZATION CODE AUTH: context queryarg is "+request.GET.get("context", None))
             self.oauth_base_url = request.session.get("OAUTH_CONTEXT_BASE_URL", None)
+            logger.debug("AUTHORIZATION CODE AUTH: context is "+self.oauth_base_url)
             self.access_token_url = self.oauth_base_url + settings.MTDC_ACCESS_TOKEN_URL
             self.authorize_url = self.oauth_base_url + settings.MTDC_AUTHORIZE_URL
             self.profile_url = self.oauth_base_url + settings.MTDC_PROFILE_URL
     
     def pre_social_login(self, request, sociallogin):
-        socialuser = sociallogin.user   
         try:
-            user = get_user_model().objects.get(username=socialuser.username)  # if user exists, connect the account to the existing account and login
-            sociallogin.state['process'] = 'connect'                
+            logger.debug("AUTHORIZATION CODE AUTH: login almost complete, checking if user exists")
+            user = get_user_model().objects.get(external_id=sociallogin.account.extra_data.get('external_id', ''))  # if user exists, connect the account to the existing account and login
+            logger.debug("AUTHORIZATION CODE AUTH: user exists, connecting to existing account")
+            sociallogin.state['process'] = 'connect'             
             perform_login(request, user, 'none')
         except get_user_model().DoesNotExist:
-            pass
+            logger.debug("AUTHORIZATION CODE AUTH: user does not exist")
     
     def get_login_redirect_url(self, request):
         return super(MtdcOAuth2Adapter, self).get_login_redirect_url(self, request)
     
     def new_user(self, request, sociallogin):
         if 'username' in sociallogin.account.extra_data:
+            logger.debug("AUTHORIZATION CODE AUTH: checking if user exists to populate sociallogin")
             user_queryset = get_user_model().objects.filter(external_id=sociallogin.account.extra_data['external_id'], username=sociallogin.account.extra_data['username'])
             if user_queryset.exists():
+                logger.debug("AUTHORIZATION CODE AUTH: user exists")
                 user = user_queryset.first()
             else:
+                logger.debug("AUTHORIZATION CODE AUTH: user does not exist, creating new user and populating")
                 user = get_user_model()()
                 user.username = sociallogin.account.extra_data.get('username', '')
                 user.external_id = sociallogin.account.extra_data.get('external_id', '')
                 user.uai = sociallogin.account.extra_data.get('uai', '')
             return user
         else:
+            logger.debug("AUTHORIZATION CODE AUTH: no username in extra data")
             return get_user_model()()
         
     def populate_user(self,
@@ -85,9 +96,12 @@
         return user
     
     def complete_login(self, request, app, token, **kwargs):
+        logger.debug("AUTHORIZATION CODE AUTH: complete_login: getting profile info")
         resp = requests.get(self.profile_url,
                             params={'access_token': token.token})
         extra_data = resp.json()
+        
+        logger.debug("AUTHORIZATION CODE AUTH: response extra_data: "+str(extra_data))
         if request.session.get("OAUTH_CONTEXT_BASE_URL", None) is not None:
             del request.session["OAUTH_CONTEXT_BASE_URL"]
         return self.get_provider().sociallogin_from_response(request,
@@ -105,10 +119,12 @@
 
 class MtdcOAuth2LoginView(MtdcOAuth2View, OAuth2LoginView):
     def dispatch(self, request):
+        logger.debug("AUTHORIZATION CODE AUTH: dispatching LoginView")
         return super(MtdcOAuth2LoginView, self).dispatch(request)
 
 class MtdcOAuth2CallbackView(MtdcOAuth2View, OAuth2CallbackView):
     def dispatch(self, request):
+        logger.debug("AUTHORIZATION CODE AUTH: dispatching CallbackView")
         return super(MtdcOAuth2CallbackView, self).dispatch(request)
 
 
--- a/server/src/metaeducation/settings/dev.py.tmpl	Fri Mar 11 16:32:30 2016 +0100
+++ b/server/src/metaeducation/settings/dev.py.tmpl	Mon Mar 14 14:17:29 2016 +0100
@@ -44,6 +44,61 @@
 
 STATIC_URL = '/static/'
 
+LOG_FILE = os.path.abspath(os.path.join(BASE_DIR,"../run/log/metaeducation_log.txt"))
+LOG_LEVEL = logging.DEBUG
+LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': True,
+    'filters': {
+        'require_debug_false': {
+            '()': 'django.utils.log.RequireDebugFalse'
+        }
+    },
+    'formatters' : {
+        'simple' : {
+            'format': "%(asctime)s - %(levelname)s : %(message)s",
+        },
+        'semi-verbose': {
+            'format': '%(levelname)s %(asctime)s %(module)s %(message)s'
+        },
+    },
+    'handlers': {
+        'mail_admins': {
+            'level': 'ERROR',
+            'filters': ['require_debug_false'],
+            'class': 'django.utils.log.AdminEmailHandler'
+        },
+        'stream_to_console': {
+            'level': LOG_LEVEL,
+            'class': 'logging.StreamHandler'
+        },
+        'file': {
+            'level': LOG_LEVEL,
+            'class': 'logging.FileHandler',
+            'filename': LOG_FILE,
+            'formatter': 'semi-verbose',
+        },
+    },
+    'loggers': {
+        'django.request': {
+            'handlers': ['file'],
+            'level': LOG_LEVEL,
+            'propagate': True,
+        },
+        'metaeducation': {
+            'handlers': ['file'],
+            'level': LOG_LEVEL,
+            'propagate': True,
+        },
+        'renkanmanager': {
+            'handlers': ['file'],
+            'level': LOG_LEVEL,
+            'propagate': True,
+        },
+    }
+}
+
+
 # Internationalization
 # https://docs.djangoproject.com/en/1.9/topics/i18n/
 
--- a/server/src/metaeducation/signals.py	Fri Mar 11 16:32:30 2016 +0100
+++ b/server/src/metaeducation/signals.py	Mon Mar 14 14:17:29 2016 +0100
@@ -3,7 +3,10 @@
 from django.contrib.auth import get_user_model
 from django.conf import settings
 from django.core.urlresolvers import reverse
-import requests, json, sys
+import requests, json, sys, logging
+
+logger = logging.getLogger(__name__)
+
 
 def reference_created_renkan(sender, instance, created, **kwargs):
     from renkanmanager.models import Renkan
@@ -16,6 +19,7 @@
             }          
         )
         if token_response.status_code == 200:
+            logger.debug("REFERENCING RENKAN: token response is 200")
             token = json.loads(token_response.text)['access_token']
             post_data = json.dumps({
                 "id": str(instance.renkan_guid),
@@ -27,7 +31,8 @@
                 "title": instance.title
             })
             resource_ws_url = settings.MTDC_REFERENCE_RESOURCE_BASE_URL# + str(instance.renkan_guid)
-            
+            logger.debug("REFERENCING RENKAN: sending reference request to: "+resource_ws_url)
+            logger.debug("REFERENCING RENKAN: post_data: "+str(post_data))
             reference_response = requests.post(
                 resource_ws_url,
                 data = post_data,
@@ -36,6 +41,7 @@
                     "content-type": "application/json"
                 }                             
             )
+            logger.debug("REFERENCING RENKAN: response is "+str(reference_response.status_code))
             
 
 if not 'test' in sys.argv: