# HG changeset patch # User durandn # Date 1457961449 -3600 # Node ID eb9e83610c99670f6db40d4447edf6199f000d46 # Parent 360b1bcb252e55eeb454f49d5cb22b5ad9e36722 added logging and logs config diff -r 360b1bcb252e -r eb9e83610c99 oauth/client.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"]) diff -r 360b1bcb252e -r eb9e83610c99 server/src/metaeducation/auth.py --- 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) diff -r 360b1bcb252e -r eb9e83610c99 server/src/metaeducation/middleware.py --- 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 diff -r 360b1bcb252e -r eb9e83610c99 server/src/metaeducation/mtdc_oauth_provider/views.py --- 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) diff -r 360b1bcb252e -r eb9e83610c99 server/src/metaeducation/settings/dev.py.tmpl --- 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/ diff -r 360b1bcb252e -r eb9e83610c99 server/src/metaeducation/signals.py --- 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: