Basic logging for Discord account creation and database updating.

alliance_auth/settings.py.example

@@ -347,3 +347,35 @@ TEAMSPEAK3_PUBLIC_URL = os.environ.get('AA_TEAMSPEAK3_PUBLIC_URL', 'yourdomain.c
 DISCORD_SERVER_ID = os.environ.get('AA_DISCORD_SERVER_ID', '')
 DISCORD_USER_EMAIL = os.environ.get('AA_DISCORD_USER_EMAIL', '')
 DISCORD_USER_PASSWORD = os.environ.get('AA_DISCORD_USER_PASSWORD', '')
+
+LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'formatters': {
+        'verbose': {
+            'format' : "[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s",
+            'datefmt' : "%d/%b/%Y %H:%M:%S"
+        },
+        'simple': {
+            'format': '%(levelname)s %(message)s'
+        },
+    },
+    'handlers': {
+        'debug_file': {
+            'level': 'DEBUG',
+            'class': 'logging.FileHandler',
+            'filename': 'debug.log',
+            'formatter': 'verbose'
+        }
+    },
+    'loggers': {
+        'celerytask': {
+            'handlers': ['debug_file'],
+            'level': 'DEBUG',
+        },
+        'services': {
+            'handlers': ['debug_file'],
+            'level': 'DEBUG',
+        }
+    }
+}

celerytask/tasks.py

@@ -26,6 +26,10 @@ from eveonline.models import EveCharacter
 from eveonline.models import EveCorporationInfo
 from authentication.managers import AuthServicesInfoManager
 
+import logging
+
+logger = logging.getLogger(__name__)
+
 def disable_alliance_member(user, char_id):
     remove_member_permission(user, 'member')
     remove_user_from_group(user, settings.DEFAULT_AUTH_GROUP)
@@ -113,13 +117,16 @@ def update_teamspeak3_groups(user):
     Teamspeak3Manager.update_groups(authserviceinfo.teamspeak3_uid, groups)
 
 def update_discord_groups(user):
+    logger.debug("Updating discord groups for user %s" % user)
     syncgroups = SyncGroupCache.objects.filter(user=user)
     authserviceinfo = AuthServicesInfo.objects.get(user=user)
     groups = []
     for syncgroup in syncgroups:
         groups.append(str(syncgroup.groupname))
 
+    logger.debug("Found %s syncgroups." % len(groups))
     if len(groups) == 0:
+        logger.debug("No syncgroups found for user. Adding empty group.")
         groups.append('empty')
 
     DiscordManager.update_groups(authserviceinfo.discord_uid, groups)
@@ -140,80 +147,106 @@ def remove_all_syncgroups_for_service(user, servicename):
 
 
 def add_to_databases(user, groups, syncgroups):
+    logger.debug("add_to_database for user %s called. groups %s - syncgroups %s" % (user, groups, syncgroups))
     authserviceinfo = None
     try:
         authserviceinfo = AuthServicesInfo.objects.get(user=user)
+        logger.debug("Got authservicesinfo object %s" % authserviceinfo)
     except:
+        logger.debug("No authservicesinfo object found for user %s" % user)
         pass
 
     if authserviceinfo:
         authserviceinfo = AuthServicesInfo.objects.get(user=user)
 		
 	if authserviceinfo.teamspeak3_uid and authserviceinfo.teamspeak3_uid != "":
-                update_teamspeak3_groups(user)
+            logger.debug("Updating user TS groups.")
+            update_teamspeak3_groups(user)
 				
         for group in groups:
             if authserviceinfo.jabber_username and authserviceinfo.jabber_username != "":
                 if syncgroups.filter(groupname=group.name).filter(servicename="openfire").exists() is not True:
+                    logger.debug("User %s has jabber username %s - missing group %s." % (user, authserviceinfo.jabber_username, group.name))
                     create_syncgroup_for_user(user, group.name, "openfire")
                     update_jabber_groups(user)
             if authserviceinfo.mumble_username and authserviceinfo.mumble_username != "":
                 if syncgroups.filter(groupname=group.name).filter(servicename="mumble").exists() is not True:
+                    logger.debug("User %s has mumble username %s - missing group %s." % (user, authserviceinfo.mumble_username, group.name))
                     create_syncgroup_for_user(user, group.name, "mumble")
                     update_mumble_groups(user)
             if authserviceinfo.forum_username and authserviceinfo.forum_username != "":
                 if syncgroups.filter(groupname=group.name).filter(servicename="phpbb3").exists() is not True:
+                    logger.debug("User %s has phpbb username %s - missing group %s." % (user, authserviceinfo.forum_username, group.name))
                     create_syncgroup_for_user(user, group.name, "phpbb3")
                     update_forum_groups(user)
             if authserviceinfo.ipboard_username and authserviceinfo.ipboard_username != "":
                 if syncgroups.filter(groupname=group.name).filter(servicename="ipboard").exists() is not True:
+                    logger.debug("User %s has ipboard username %s - missing group %s." % (user, authserviceinfo.ipboard_username, group.name))
                     create_syncgroup_for_user(user, group.name, "ipboard")
                     update_ipboard_groups(user)
             if authserviceinfo.discord_uid and authserviceinfo.discord_uid != "":
                 if syncgroups.filter(groupname=group.name).filter(servicename="discord").exists() is not True:
+                    logger.debug("User %s has discord uid %s - missing group %s." % (user, authserviceinfo.discord_uid, group.name))
                     create_syncgroup_for_user(user, group.name, "discord")
                     update_discord_groups(user)
 
 
 def remove_from_databases(user, groups, syncgroups):
+    logger.debug("remove_from_database for user %s called. groups %s - syncgroups %s" % (user, groups, syncgroups))
     authserviceinfo = None
     try:
         authserviceinfo = AuthServicesInfo.objects.get(user=user)
+        logger.debug("Got authservicesinfo object %s" % authserviceinfo)
     except:
+        logger.debug("No authservicesinfo object found for user %s" % user)
         pass
 
     if authserviceinfo:
         update = False
         for syncgroup in syncgroups:
             group = groups.filter(name=syncgroup.groupname)
-
+            logger.debug("Got group %s for syncgroup %s" % (group, syncgroup))
             if not group:
+                logger.debug("Deleting syncgroup %s" % syncgroup)
                 syncgroup.delete()
                 update = True
 
         if update:
+            logger.debug("Syncgroups updated. Propogating to services for user %s" % user)
             if authserviceinfo.jabber_username and authserviceinfo.jabber_username != "":
+                logger.debug("User %s has jabber username %s - updating groups." % (user, authserviceinfo.jabber_username))
                 update_jabber_groups(user)
             if authserviceinfo.mumble_username and authserviceinfo.mumble_username != "":
+                logger.debug("User %s has mumble username %s - updating groups." % (user, authserviceinfo.mumble_username))
                 update_mumble_groups(user)
             if authserviceinfo.forum_username and authserviceinfo.forum_username != "":
+                logger.debug("User %s has forum username %s - updating groups." % (user, authserviceinfo.forum_username))
                 update_forum_groups(user)
             if authserviceinfo.ipboard_username and authserviceinfo.ipboard_username != "":
+                logger.debug("User %s has ipboard username %s - updating groups." % (user, authserviceinfo.ipboard_username))
                 update_ipboard_groups(user)
             if authserviceinfo.teamspeak3_uid and authserviceinfo.teamspeak3_uid != "":
+                logger.debug("User %s has ts3 uid %s - updating groups." % (user, authserviceinfo.teamspeak3_uid))
                 update_teamspeak3_groups(user)
             if authserviceinfo.discord_uid and authserviceinfo.discord_uid != "":
+                logger.debug("User %s has discord uid %s - updating groups." % (user, authserviceinfo.discord_uid))
                 update_discord_groups(user)
 
 
 # Run every minute
 @periodic_task(run_every=crontab(minute="*/1"))
 def run_databaseUpdate():
+    logger.debug("Starting database update.")
     users = User.objects.all()
+    logger.debug("Syncing TS groups.")
     Teamspeak3Manager._sync_ts_group_db()
+    logger.debug("Finished syncing TS groups.")
     for user in users:
+        logger.debug("Initiating database update for user %s" % user)
         groups = user.groups.all()
+        logger.debug("User has groups %s" % groups)
         syncgroups = SyncGroupCache.objects.filter(user=user)
+        logger.debug("User has syncgroups %s" % syncgroups)
         add_to_databases(user, groups, syncgroups)
         remove_from_databases(user, groups, syncgroups)
 

services/managers/discord_manager.py

@@ -4,6 +4,10 @@ from django.conf import settings
 import re
 import os
 
+import logging
+
+logger = logging.getLogger(__name__)
+
 DISCORD_URL = "https://discordapp.com/api"
 
 class DiscordAPIManager:
@@ -40,6 +44,7 @@ class DiscordAPIManager:
         custom_headers = {'content-type':'application/json'}
         path = DISCORD_URL + "/auth/login"
         r = requests.post(path, headers=custom_headers, data=json.dumps(data))
+        logger.debug("Received status code %s during token generation for settings discord user." % r.status_code)
         r.raise_for_status()
         return r.json()['token']
 
@@ -89,12 +94,14 @@ class DiscordAPIManager:
         custom_headers = {'authorization': self.token}
         path = DISCORD_URL + "/guilds/" + str(self.server_id) + "/bans/" + str(user_id)
         r = requests.delete(path, headers=custom_headers)
+        logger.debug("Received status code %s after deleting ban for user %s" % (r.status_code, user_id))
         r.raise_for_status()
 
     def generate_role(self):
         custom_headers = {'accept':'application/json', 'authorization': self.token}
         path = DISCORD_URL + "/guilds/" + str(self.server_id) + "/roles"
         r = requests.post(path, headers=custom_headers)
+        logger.debug("Received status code %s after generating new role." % r.status_code)
         r.raise_for_status()
         return r.json()
 
@@ -108,6 +115,7 @@ class DiscordAPIManager:
         }
         path = DISCORD_URL + "/guilds/" + str(self.server_id) + "/roles/" + str(role_id)
         r = requests.patch(path, headers=custom_headers, data=json.dumps(data))
+        logger.debug("Received status code %s after editing role id %s" % (r.status_code, role_id))
         r.raise_for_status()
         return r.json()
 
@@ -130,6 +138,7 @@ class DiscordAPIManager:
         custom_headers = {'accept': 'application/json', 'authorization': token}
         path = DISCORD_URL + "/invite/" + str(invite_id)
         r = requests.post(path, headers=custom_headers)
+        logger.debug("Received status code %s after accepting invite." % r.status_code)
         r.raise_for_status()
         return r.json()
 
@@ -143,6 +152,7 @@ class DiscordAPIManager:
             'xkcdpass': xkcdpass,
         }
         r = requests.post(path, headers=custom_headers, data=json.dumps(data))
+        logger.debug("Received status code %s after creating invite." % r.status_code)
         r.raise_for_status()
         return r.json()
 
@@ -157,6 +167,7 @@ class DiscordAPIManager:
         path = DISCORD_URL + "/guilds/" + str(self.server_id) + "/members/" + str(user_id)
         data = { 'roles': role_ids }
         r = requests.patch(path, headers=custom_headers, data=json.dumps(data))
+        logger.debug("Received status code %s after setting roles of user %s to %s" % (user_id, role_ids))
         r.raise_for_status()
 
     @staticmethod
@@ -197,14 +208,20 @@ class DiscordAPIManager:
         custom_headers = {'authorization': self.token, 'accept':'application/json'}
         path = DISCORD_URL + "/guilds/" + str(self.server_id) + "/roles"
         r = requests.get(path, headers=custom_headers)
+        logger.debug("Received status code %s after retrieving role list from server." % r.status_code)
         r.raise_for_status()
         return r.json()
 
     def get_group_id(self, group_name):
+        logger.debug("Determining role id for group name %s" % group_name)
         all_roles = self.get_roles()
+        logger.debug("Retrieved role list for server: %s" % all_roles)
         for role in all_roles:
+            logger.debug("Checking role %s" % role)
             if role['name'] == group_name:
+                logger.debug("Found role matching name: %s" % role['id'])
                 return role['id']
+        logger.debug("Role not found on server. Raising KeyError")
         raise KeyError('Group not found on server: ' + group_name)
 
     @staticmethod
@@ -216,6 +233,7 @@ class DiscordAPIManager:
         custom_headers = {'content-type':'application/json'}
         path = DISCORD_URL + "/auth/login"
         r = requests.post(path, headers=custom_headers, data=json.dumps(data))
+        logger.debug("Received status code %s after generating auth token for custom user." % r.status_code)
         r.raise_for_status()
         return r.json()['token']
 
@@ -225,6 +243,7 @@ class DiscordAPIManager:
         custom_headers = {'accept': 'application/json', 'authorization': token}
         path = DISCORD_URL + "/users/@me"
         r = requests.get(path, headers=custom_headers)
+        logger.debug("Received status code %s after retrieving user profile with email %s" % (r.status_code, email[0:3]))
         r.raise_for_status()
         return r.json()
 
@@ -282,24 +301,33 @@ class DiscordManager:
 
     @staticmethod
     def update_groups(user_id, groups):
+        logger.debug("Updating groups for user_id %s: %s" % user_id, groups)
         group_ids = []
         api = DiscordAPIManager(settings.DISCORD_SERVER_ID, settings.DISCORD_USER_EMAIL, settings.DISCORD_USER_PASSWORD)
         if len(groups) == 0:
+            logger.debug("No groups provided - generating empty array of group ids.")
             group_ids = []
         else:
             for g in groups:
                 try:
+                    logger.debug("Retrieving group id for group %s" % g)
                     group_id = api.get_group_id(g)
                     group_ids.append(group_id)
+                    logger.debug("Got id %s" % group_id)
                 except:
+                    logger.debug("Group id retrieval generated exception - generating new group on discord server.", exc_info=True)
                     group_ids.append(DiscordManager.create_group(g))
+        logger.debug("Setting groups for user %s to %s" % (user_id, group_ids))
         api.set_roles(user_id, group_ids)
 
     @staticmethod
     def create_group(groupname):
+        logger.debug("Creating new group %s" % groupname)
         api = DiscordAPIManager(settings.DISCORD_SERVER_ID, settings.DISCORD_USER_EMAIL, settings.DISCORD_USER_PASSWORD)
         new_group = api.generate_role()
+        logger.debug("Created new role on server with id %s: %s" % (new_group['id'], new_group))
         named_group = api.edit_role(new_group['id'], groupname)
+        logger.debug("Renamed group id %s to %s" % (new_group['id'], groupname))
         return named_group['id']
 
     @staticmethod
@@ -332,16 +360,24 @@ class DiscordManager:
     @staticmethod
     def add_user(email, password):
         try:
+            logger.debug("Adding new user to discord with email %s and password of length %s" % (email[0:3], len(password)))
             api = DiscordAPIManager(settings.DISCORD_SERVER_ID, settings.DISCORD_USER_EMAIL, settings.DISCORD_USER_PASSWORD)
             profile = DiscordAPIManager.get_user_profile(email, password)
+            logger.debug("Got profile for user: %s" % profile)
             user_id = profile['id']
+            logger.debug("Determined user id: %s" % user_id)
             if api.check_if_user_banned(user_id):
+                logger.debug("User is currently banned. Unbanning %s" % user_id)
                 api.unban_user(user_id)
             invite_code = api.create_invite()['code']
+            logger.debug("Generated invite code beginning with %s" % invite_code[0:5])
             token = DiscordAPIManager.get_token_by_user(email, password)
+            logger.debug("Got auth token for supplied credentials beginning with %s" % token[0:5])
             DiscordAPIManager.accept_invite(invite_code, token)
+            logger.debug("Added user to server with id %s" % user_id)
             return user_id
         except:
+            logger.exception("An unhandled exception has occured.", exc_info=True)
             return ""
 
     @staticmethod

services/views.py

@@ -30,6 +30,9 @@ from util import check_if_user_has_permission
 import threading
 import datetime 
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 @login_required
 def fleet_formatter_view(request):
@@ -345,23 +348,34 @@ def reset_discord(request):
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def activate_discord(request):
+    logger.debug("activate_discord called.")
     success = False
     if request.method == 'POST':
+        logger.debug("Received POST request with form.")
         form = DiscordForm(request.POST)
+        logger.debug("Form is valid: %s" % form.is_valid())
         if form.is_valid():
             email = form.cleaned_data['email']
+            logger.debug("Form contains email address beginning with %s" % email[0:3])
             password = form.cleaned_data['password']
+            logger.debug("Form contains password of length %s" % len(password))
             try:
                 user_id = DiscordManager.add_user(email, password)
+                logger.debug("Received user_id %s" % user_id)
                 if user_id != "":
                     AuthServicesInfoManager.update_user_discord_info(user_id, request.user)
+                    logger.debug("Updated discord id %s for user %s" % (user_id, request.user))
                     update_discord_groups(request.user)
+                    logger.debug("Updated discord groups for user %s. Succesful activation." % request.user)
                     success = True
                     return HttpResponseRedirect("/services/")
             except:
+                logger.exception("An unhandled exception has occured.", exc_info=True)
                 pass
     else:
+        logger.debug("Request is not type POST - providing empty form.")
         form = DiscordForm()
 
+    logger.debug("Rendering form for user with success %s" % success)
     context = {'form': form, 'success': success}
     return render_to_response('registered/discord.html', context, context_instance=RequestContext(request))