From 55fc69cf8d2720b666e9b3b21c8b9eb5965ceadc Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Mon, 28 Dec 2015 06:50:13 +0000
Subject: [PATCH 01/27] Basic logging for Discord account creation and database
 updating.

---
 alliance_auth/settings.py.example    | 32 ++++++++++++++++++++++++
 celerytask/tasks.py                  | 37 ++++++++++++++++++++++++++--
 services/managers/discord_manager.py | 36 +++++++++++++++++++++++++++
 services/views.py                    | 14 +++++++++++
 4 files changed, 117 insertions(+), 2 deletions(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index 67535b05..ef565cff 100755
--- a/alliance_auth/settings.py.example
+++ b/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',
+        }
+    }
+}
diff --git a/celerytask/tasks.py b/celerytask/tasks.py
index 6aad687f..74595cbe 100755
--- a/celerytask/tasks.py
+++ b/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)
 
diff --git a/services/managers/discord_manager.py b/services/managers/discord_manager.py
index 9ab4ff97..cc9370c2 100644
--- a/services/managers/discord_manager.py
+++ b/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
diff --git a/services/views.py b/services/views.py
index dacefebd..6ab727f4 100755
--- a/services/views.py
+++ b/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))

From 235385ce399d9e065ba11ea4e61280207b1ebec9 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Mon, 28 Dec 2015 18:07:14 +0000
Subject: [PATCH 02/27] Added more logging to TS3 manager.

---
 services/managers/teamspeak3_manager.py | 40 ++++++++++++++++++++++---
 1 file changed, 36 insertions(+), 4 deletions(-)

diff --git a/services/managers/teamspeak3_manager.py b/services/managers/teamspeak3_manager.py
index 291b58a1..349e6cfb 100755
--- a/services/managers/teamspeak3_manager.py
+++ b/services/managers/teamspeak3_manager.py
@@ -2,7 +2,9 @@ from django.conf import settings
 
 from services.managers.util.ts3 import TS3Server
 from services.models import TSgroup
+import logging
 
+logger = logging.getLogger(__name__)
 
 class Teamspeak3Manager:
     def __init__(self):
@@ -13,6 +15,7 @@ class Teamspeak3Manager:
         server = TS3Server(settings.TEAMSPEAK3_SERVER_IP, settings.TEAMSPEAK3_SERVER_PORT)
         server.login(settings.TEAMSPEAK3_SERVERQUERY_USER, settings.TEAMSPEAK3_SERVERQUERY_PASSWORD)
         server.use(settings.TEAMSPEAK3_VIRTUAL_SERVER)
+        logger.debug("Got TS3 server instance based on settings.")
         return server
 
     @staticmethod
@@ -31,27 +34,34 @@ class Teamspeak3Manager:
 
     @staticmethod
     def _get_userid(uid):
+        logger.debug("Looking for uid %s on TS3 server." % uid)
         server = Teamspeak3Manager.__get_created_server()
         ret = server.send_command('customsearch', {'ident': 'sso_uid', 'pattern': uid})
         if ret and 'keys' in ret and 'cldbid' in ret['keys']:
+            logger.debug("Got userid %s for uid %s" % (ret['keys']['cldbid'], uid))
             return ret['keys']['cldbid']
 
     @staticmethod
     def _group_id_by_name(groupname):
         server = Teamspeak3Manager.__get_created_server()
+        logger.debug("Looking for group %s on TS3 server." % groupname)
         group_cache = server.send_command('servergrouplist')
-
+        logger.debug("Received group cache from server: %s" % group_cache)
         for group in group_cache:
+            logger.debug("Checking group %s" % group)
             if group['keys']['name'] == groupname:
+                logger.debug("Found group %s, returning id %s" % (groupname, group['keys']['sgid']))
                 return group['keys']['sgid']
-
+        logger.debug("Group %s not found on server." % groupname)
         return None
 
     @staticmethod
     def _create_group(groupname):
+        logger.debug("Creating group %s on TS3 server." % groupname)
         server = Teamspeak3Manager.__get_created_server()
         sgid = Teamspeak3Manager._group_id_by_name(groupname)
         if not sgid:
+            logger.debug("Group does not yet exist. Proceeding with creation.")
             ret = server.send_command('servergroupadd', {'name': groupname})
             Teamspeak3Manager.__group_cache = None
             sgid = ret['keys']['sgid']
@@ -64,72 +74,94 @@ class Teamspeak3Manager:
             server.send_command('servergroupaddperm',
                                 {'sgid': sgid, 'permsid': 'i_group_needed_member_remove_power', 'permvalue': 100,
                                  'permnegated': 0, 'permskip': 0})
+        logger.debug("Returning group id %s" % sqid)
         return sgid
 
     @staticmethod
     def _user_group_list(cldbid):
+        logger.debug("Retrieving group list for user with id %s" % cldbid)
         server = Teamspeak3Manager.__get_created_server()
         groups = server.send_command('servergroupsbyclientid', {'cldbid': cldbid})
+        logger.debug("Retrieved group list: %s" % groups)
         outlist = {}
 
         if type(groups) == list:
+            logger.debug("Recieved multiple groups. Iterating.")
             for group in groups:
+                logger.debug("Assigning name/id dict: %s = %s" % (group['keys']['name'], group['keys']['sgid']))
                 outlist[group['keys']['name']] = group['keys']['sgid']
         elif type(groups) == dict:
+            logger.debug("Recieved single group.")
+            logger.debug("Assigning name/id dict: %s = %s" % (groups['keys']['name'], groups['keys']['sgid']))
             outlist[groups['keys']['name']] = groups['keys']['sgid']
-
+        logger.debug("Returning name/id pairing: %s" % outlist)
         return outlist
 
     @staticmethod
     def _group_list():
+        logger.debug("Retrieving group list on TS3 server.")
         server = Teamspeak3Manager.__get_created_server()
         group_cache = server.send_command('servergrouplist')
+        logger.debug("Received group cache from server: %s" % group_cache)
         outlist = {}
         if group_cache:
             for group in group_cache:
+                logger.debug("Assigning name/id dict: %s = %s" % (group['keys']['name'], group['keys']['sgid']))
                 outlist[group['keys']['name']] = group['keys']['sgid']
         else:
+            logger.debug("Received empty group cache. 1024 error.")
             print '1024 error'
-
+        logger.debug("Returning name/id pairing: %s" % outlist)
         return outlist
 
     @staticmethod
     def _add_user_to_group(uid, groupid):
+        logger.debug("Adding group id %s to TS3 user id %s" % (groupid, uid))
         server = Teamspeak3Manager.__get_created_server()
         server_groups = Teamspeak3Manager._group_list()
         user_groups = Teamspeak3Manager._user_group_list(uid)
         
         if not groupid in user_groups.values():
+            logger.debug("User does not have group already. Issuing command to add.")
             server.send_command('servergroupaddclient',
                                 {'sgid': str(groupid), 'cldbid': uid})
 
     @staticmethod
     def _remove_user_from_group(uid, groupid):
+        logger.debug("Removing group id %s from TS3 user id %s" % (groupid, uid))
         server = Teamspeak3Manager.__get_created_server()
         server_groups = Teamspeak3Manager._group_list()
         user_groups = Teamspeak3Manager._user_group_list(uid)
 
         if str(groupid) in user_groups.values():
+            logger.debug("User is in group. Issuing command to remove.")
             server.send_command('servergroupdelclient',
                                 {'sgid': str(groupid), 'cldbid': uid})
 
     @staticmethod
     def _sync_ts_group_db():
+        logger.debug("_sync_ts_group_db function called.")
         try:
             remote_groups = Teamspeak3Manager._group_list()
             local_groups = TSgroup.objects.all()
+            logger.debug("Comparing remote groups to TSgroup objects: %s" % local_groups)
             for key in remote_groups:
+                logger.debug("Typecasting remote_group value at position %s to int: %s" % (key, remote_groups[key]))
                 remote_groups[key] = int(remote_groups[key])
             
             for group in local_groups:
+                logger.debug("Checking local group %s" % group)
                 if group.ts_group_id not in remote_groups.values():
+                    logger.debug("Local group id %s not found on server. Deleting model %s" % (group.ts_group_id, group))
                     TSgroup.objects.filter(ts_group_id=group.ts_group_id).delete()
             for key in remote_groups:
                 g = TSgroup(ts_group_id=remote_groups[key],ts_group_name=key)
                 q = TSgroup.objects.filter(ts_group_id=g.ts_group_id)
                 if not q:
+                    logger.debug("Local group does not exist for TS group %s. Creating TSgroup model %s" % (remote_groups[key], g))
                     g.save()
         except:
+            logger.debug("An unhandled exception has occured while syncinc TS groups.", exc_info=True)
             pass
 
     @staticmethod

From d44d73d445329a9df16c320f79050812c5281d0f Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Mon, 28 Dec 2015 19:51:09 +0000
Subject: [PATCH 03/27] Corrected logging of services module.

---
 alliance_auth/settings.py.example | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index ef565cff..c360cc48 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -373,7 +373,11 @@ LOGGING = {
             'handlers': ['debug_file'],
             'level': 'DEBUG',
         },
-        'services': {
+        'services.views': {
+            'handlers': ['debug_file'],
+            'level': 'DEBUG',
+        },
+        'services.managers': {
             'handlers': ['debug_file'],
             'level': 'DEBUG',
         }

From 834cd8865e3f19e14cba1d43b2d3b9db540deac0 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Mon, 28 Dec 2015 20:21:17 +0000
Subject: [PATCH 04/27] Added console logging output.

---
 alliance_auth/settings.py.example    | 20 +++++++++++++-------
 services/managers/discord_manager.py |  1 +
 2 files changed, 14 insertions(+), 7 deletions(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index c360cc48..95c1d2e3 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -366,20 +366,26 @@ LOGGING = {
             'class': 'logging.FileHandler',
             'filename': 'debug.log',
             'formatter': 'verbose'
+        },
+        'console': {
+            'level': 'DEBUG',
+            'class': 'logging.StreamHandler',
+            'formatter': 'verbose',
         }
     },
     'loggers': {
         'celerytask': {
-            'handlers': ['debug_file'],
-            'level': 'DEBUG',
-        },
-        'services.views': {
-            'handlers': ['debug_file'],
+            'handlers': ['debug_file', 'console'],
             'level': 'DEBUG',
         },
         'services.managers': {
-            'handlers': ['debug_file'],
+            'handlers': ['debug_file', 'console'],
             'level': 'DEBUG',
-        }
+        },
+        'services.views': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
     }
 }
+
diff --git a/services/managers/discord_manager.py b/services/managers/discord_manager.py
index cc9370c2..1f95ccd6 100644
--- a/services/managers/discord_manager.py
+++ b/services/managers/discord_manager.py
@@ -25,6 +25,7 @@ class DiscordAPIManager:
         self.email = email
         self.password = password
         self.server_id = server_id
+        logger.debug("Initialized DiscordAPIManager with server id %s" % self.server_id)
 
     def __del__(self):
         if hasattr(self, 'token'):

From b43902c178e8d0ad142c912bbaba6c23a637941a Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Mon, 28 Dec 2015 21:13:04 +0000
Subject: [PATCH 05/27] Another tweak to logging settings.

---
 alliance_auth/settings.py.example | 6 +-----
 1 file changed, 1 insertion(+), 5 deletions(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index 95c1d2e3..2de69666 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -378,11 +378,7 @@ LOGGING = {
             'handlers': ['debug_file', 'console'],
             'level': 'DEBUG',
         },
-        'services.managers': {
-            'handlers': ['debug_file', 'console'],
-            'level': 'DEBUG',
-        },
-        'services.views': {
+        'services': {
             'handlers': ['debug_file', 'console'],
             'level': 'DEBUG',
         },

From 604c08b3b78dcb8fac550a40c61a52d643124a47 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 29 Dec 2015 19:36:28 +0000
Subject: [PATCH 06/27] Discord Auth Token caching implemented to work around
 rate limits. Addresses #146

---
 services/managers/discord_manager.py | 47 ++++++++++++++++++++++------
 services/models.py                   |  8 ++++-
 2 files changed, 44 insertions(+), 11 deletions(-)

diff --git a/services/managers/discord_manager.py b/services/managers/discord_manager.py
index 1f95ccd6..d487377f 100644
--- a/services/managers/discord_manager.py
+++ b/services/managers/discord_manager.py
@@ -3,6 +3,7 @@ import json
 from django.conf import settings
 import re
 import os
+from services.models import DiscordAuthToken
 
 import logging
 
@@ -13,15 +14,15 @@ DISCORD_URL = "https://discordapp.com/api"
 class DiscordAPIManager:
 
     def __init__(self, server_id, email, password):
-        data = {
-            "email" : email,
-            "password": password,
-        }
-        custom_headers = {'content-type':'application/json'}
-        path = DISCORD_URL + "/auth/login"
-        r = requests.post(path, headers=custom_headers, data=json.dumps(data))
-        r.raise_for_status()
-        self.token = r.json()['token']
+#        data = {
+#            "email" : email,
+#            "password": password,
+#        }
+#        custom_headers = {'content-type':'application/json'}
+#        path = DISCORD_URL + "/auth/login"
+#        r = requests.post(path, headers=custom_headers, data=json.dumps(data))
+#        r.raise_for_status()
+        self.token = DiscordAPIManager.get_token_by_user(email, password)
         self.email = email
         self.password = password
         self.server_id = server_id
@@ -36,6 +37,18 @@ class DiscordAPIManager:
                 r = requests.post(path, headers=custom_headers, data=json.dumps(data))
                 r.raise_for_status()
 
+    @staticmethod
+    def validate_token(token):
+        custom_headers = {'accept': 'application/json', 'authorization': token}
+        path = DISCORD_URL + "/users/@me"
+        r = requests.get(path, headers=custom_headers)
+        if r.status_code == 200:
+            logger.debug("Token starting with %s still valid." % token[0:5])
+            return True
+        else:
+            logger.debug("Token starting with %s vailed validation with status code %s" % (token[0:5], r.status_code))
+            return False        
+
     @staticmethod
     def get_auth_token():
         data = {
@@ -227,6 +240,16 @@ class DiscordAPIManager:
 
     @staticmethod
     def get_token_by_user(email, password):
+        if DiscordAuthToken.objects.filter(email=email).exists():
+            logger.debug("Discord auth token cached for supplied email starting with %s" % email[0:3])
+            auth = DiscordAuthToken.objects.get(email=email)
+            if DiscordAPIManager.validate_token(auth.token):
+                logger.debug("Token still valid. Returning token starting with %s" % auth.token[0:5])
+                return auth.token
+            else:
+                logger.debug("Token has expired. Deleting.")
+                auth.delete()
+        logger.debug("Generating auth token for email starting with %s and password of length %s" % (email[0:3], len(password)))
         data = {
             "email" : email,
             "password": password,
@@ -236,7 +259,11 @@ class DiscordAPIManager:
         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']
+        token = r.json()['token']
+        auth = DiscordAuthToken(email=email, token=token)
+        auth.save()
+        logger.debug("Created cached token for email starting with %s" % email[0:3])
+        return token
 
     @staticmethod
     def get_user_profile(email, password):
diff --git a/services/models.py b/services/models.py
index 87a5ad57..396036f0 100644
--- a/services/models.py
+++ b/services/models.py
@@ -29,4 +29,10 @@ class UserTSgroup(models.Model):
         verbose_name='User TS Group'
 
     def __str__(self):
-        return self.user.name
\ No newline at end of file
+        return self.user.name
+
+class DiscordAuthToken(models.Model):
+    email = models.CharField(max_length=254, primary_key=True)
+    token = models.CharField(max_length=254)
+    def __str__(self):
+        return self.email

From ab7017094e3812f5bd33cf718ca2c058404e8fab Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 29 Dec 2015 19:48:09 +0000
Subject: [PATCH 07/27] Corrected logger string formatting for update groups.

---
 services/managers/discord_manager.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/services/managers/discord_manager.py b/services/managers/discord_manager.py
index d487377f..85399acf 100644
--- a/services/managers/discord_manager.py
+++ b/services/managers/discord_manager.py
@@ -329,7 +329,7 @@ class DiscordManager:
 
     @staticmethod
     def update_groups(user_id, groups):
-        logger.debug("Updating groups for user_id %s: %s" % 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:

From 087dc24344a7b45bad23bde7b3d9d1703181fd86 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 29 Dec 2015 19:58:16 +0000
Subject: [PATCH 08/27] Another correction to logging for discord manager.

---
 services/managers/discord_manager.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/services/managers/discord_manager.py b/services/managers/discord_manager.py
index 85399acf..1f4d3f29 100644
--- a/services/managers/discord_manager.py
+++ b/services/managers/discord_manager.py
@@ -181,7 +181,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))
+        logger.debug("Received status code %s after setting roles of user %s to %s" % (r.status_code, user_id, role_ids))
         r.raise_for_status()
 
     @staticmethod

From 3f359ecae16be094f57ba542001fc4a43061d351 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 29 Dec 2015 22:43:29 +0000
Subject: [PATCH 09/27] Logging added to all service managers. Unrelated,
 getting ImportError when trying to start shell. I broke something.

---
 services/managers/discord_manager.py    | 25 ++-----
 services/managers/eve_api_manager.py    | 88 ++++++++++++++++++-------
 services/managers/ipboard_manager.py    | 26 ++++++--
 services/managers/mumble_manager.py     | 61 ++++++++++++-----
 services/managers/openfire_manager.py   | 28 +++++++-
 services/managers/phpbb3_manager.py     | 51 +++++++++++---
 services/managers/teamspeak3_manager.py | 27 ++++++--
 7 files changed, 224 insertions(+), 82 deletions(-)

diff --git a/services/managers/discord_manager.py b/services/managers/discord_manager.py
index 1f4d3f29..03509c6c 100644
--- a/services/managers/discord_manager.py
+++ b/services/managers/discord_manager.py
@@ -14,29 +14,12 @@ DISCORD_URL = "https://discordapp.com/api"
 class DiscordAPIManager:
 
     def __init__(self, server_id, email, password):
-#        data = {
-#            "email" : email,
-#            "password": password,
-#        }
-#        custom_headers = {'content-type':'application/json'}
-#        path = DISCORD_URL + "/auth/login"
-#        r = requests.post(path, headers=custom_headers, data=json.dumps(data))
-#        r.raise_for_status()
         self.token = DiscordAPIManager.get_token_by_user(email, password)
         self.email = email
         self.password = password
         self.server_id = server_id
         logger.debug("Initialized DiscordAPIManager with server id %s" % self.server_id)
 
-    def __del__(self):
-        if hasattr(self, 'token'):
-            if self.token and self.token != "":
-                data = {'token': self.token}
-                path = DISCORD_URL + "/auth/logout"
-                custom_headers = {'content-type':'application/json'}
-                r = requests.post(path, headers=custom_headers, data=json.dumps(data))
-                r.raise_for_status()
-
     @staticmethod
     def validate_token(token):
         custom_headers = {'accept': 'application/json', 'authorization': token}
@@ -102,6 +85,7 @@ class DiscordAPIManager:
         custom_headers = {'authorization': self.token}
         path = DISCORD_URL + "/guilds/" + str(self.server_id) + "/bans/" + str(user_id) + "?delete-message-days=" + str(delete_message_age)
         r = requests.put(path, headers=custom_headers)
+        logger.debug("Received status code %s after banning user %s" % (r.status_code, user_id))
         r.raise_for_status()
 
     def unban_user(self, user_id):
@@ -345,7 +329,7 @@ class DiscordManager:
                 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))
+        logger.info("Setting discord groups for user %s to %s" % (user_id, group_ids))
         api.set_roles(user_id, group_ids)
 
     @staticmethod
@@ -356,6 +340,7 @@ class DiscordManager:
         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))
+        logger.info("Created new group on discord server with name %s" % groupname)
         return named_group['id']
 
     @staticmethod
@@ -402,7 +387,7 @@ class DiscordManager:
             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)
+            logger.info("Added user to discord server %s with id %s" % (settings.DISCORD_SERVER_ID, user_id))
             return user_id
         except:
             logger.exception("An unhandled exception has occured.", exc_info=True)
@@ -411,9 +396,11 @@ class DiscordManager:
     @staticmethod
     def delete_user(user_id):
         try:
+            logger.debug("Deleting user with id %s from discord server." % user_id)
             api = DiscordAPIManager(settings.DISCORD_SERVER_ID, settings.DISCORD_USER_EMAIL, settings.DISCORD_USER_PASSWORD)
             DiscordManager.update_groups(user_id, [])
             api.ban_user(user_id)
+            logger.info("Deleted user with id %s from discord server id %s" % (user_id, settings.DISCORD_SERVER_ID))
             return True
         except:
             return False
diff --git a/services/managers/eve_api_manager.py b/services/managers/eve_api_manager.py
index 498feea1..455494fe 100644
--- a/services/managers/eve_api_manager.py
+++ b/services/managers/eve_api_manager.py
@@ -4,6 +4,9 @@ import evelink.eve
 
 from django.conf import settings
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 class EveApiManager():
     def __init__(self):
@@ -12,44 +15,51 @@ class EveApiManager():
     @staticmethod
     def get_characters_from_api(api_id, api_key):
         chars = []
+        logger.debug("Getting characters from api id %s" % api_id)
         try:
             api = evelink.api.API(api_key=(api_id, api_key))
             # Should get characters
             account = evelink.account.Account(api=api)
             chars = account.characters()
         except evelink.api.APIError as error:
-            print error
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
+        logger.info("Retrieved characters %s from api id %s" % (chars, api_id))
         return chars
 
     @staticmethod
     def get_corporation_ticker_from_id(corp_id):
+        logger.debug("Getting ticker for corp id %s" % corp_id)
         ticker = ""
         try:
             api = evelink.api.API()
             corp = evelink.corp.Corp(api)
             response = corp.corporation_sheet(corp_id)
+            logger.debug("Retrieved corp sheet for id %s: %s" % (corp_id, response))
             ticker = response[0]['ticker']
         except evelink.api.APIError as error:
-            print error
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
+        logger.info("Determined corp id %s ticker: %s" % (corp_id, ticker))
         return ticker
 
     @staticmethod
     def get_alliance_information(alliance_id):
         results = {}
+        logger.debug("Getting info for alliance with id %s" % alliance_id)
         try:
             api = evelink.api.API()
             eve = evelink.eve.EVE(api=api)
             alliance = eve.alliances()
             results = alliance[0][int(alliance_id)]
         except evelink.api.APIError as error:
-            print error
-
+            logger.exception("Unhandled APIError occured.", exc_info=True)
+        logger.debug("Got alliance info %s" % results)
         return results
 
     @staticmethod
     def get_corporation_information(corp_id):
+        logger.debug("Getting info for corp with id %s" % corp_id)
         results = {}
         try:
             api = evelink.api.API()
@@ -57,171 +67,205 @@ class EveApiManager():
             corpinfo = corp.corporation_sheet(corp_id=int(corp_id))
             results = corpinfo[0]
         except evelink.api.APIError as error:
-            print error
-
+            logger.exception("Unhandled APIError occured.", exc_info=True)
+        logger.debug("Got corp info %s" % results)
         return results
 
     @staticmethod
     def check_api_is_type_account(api_id, api_key):
+        logger.debug("Checking if api id %s is account." % api_id)
         try:
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
+            logger.debug("API id %s is type %s" % (api_id, info[0]['type']))
             return info[0]['type'] == "account"
 
         except evelink.api.APIError as error:
-            print error
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
         return False
 
 
     @staticmethod
     def check_api_is_full(api_id, api_key):
+        logger.debug("Checking if api id %s meets member requirements." % api_id)
         try:
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
-            return info[0]['access_mask'] & settings.MEMBER_API_MASK == int(settings.MEMBER_API_MASK)
+            logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.MEMBER_API_MASK)
+            return info[0]['access_mask'] & int(settings.MEMBER_API_MASK) == int(settings.MEMBER_API_MASK))
 
         except evelink.api.APIError as error:
-            print error
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
         return False
 
     @staticmethod
     def check_blue_api_is_full(api_id, api_key):
+        logger.debug("Checking if api id %s meets blue requirements." % api_id)
         try:
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
-            return info[0]['access_mask'] & settings.BLUE_API_MASK == int(settings.BLUE_API_MASK)
+            logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.BLUE_API_MASK)
+            return info[0]['access_mask'] & int(settings.BLUE_API_MASK) == int(settings.BLUE_API_MASK)
  
         except evelink.api.APIError as error:
-            print error
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
 
     @staticmethod
     def get_api_info(api_id, api_key):
+        logger.debug("Getting api info for key id %s" % api_id)
         try:
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
+            logger.debug("Got info for api id %s: %s" % (api_id, info))
             return info
 
         except evelink.api.APIError as error:
-            print error
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
         return False
 
     @staticmethod
     def api_key_is_valid(api_id, api_key):
+        logger.debug("Checking if api id %s is valid." % api_id)
         try:
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
+            logger.info("Verified api id %s is still valid." % api_id)
             return True
         except evelink.api.APIError as error:
-            return False
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
+        logger.info("API id %s is invalid." % api_id)
         return False
 
     @staticmethod
     def check_if_api_server_online():
+        logger.debug("Checkin if API server online.")
         try:
             api = evelink.api.API()
             server = evelink.server.Server(api=api)
             info = server.server_status()
+            logger.info("Verified API server is online and reachable.")
             return True
         except evelink.api.APIError as error:
-            return False
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
+        logger.warn("Unable to reach API server.")
         return False
 
     @staticmethod
     def check_if_id_is_corp(corp_id):
+        logger.debug("Checking if id %s is a corp." % corp_id)
         try:
             api = evelink.api.API()
             corp = evelink.corp.Corp(api=api)
             corpinfo = corp.corporation_sheet(corp_id=int(corp_id))
             results = corpinfo[0]
+            logger.info("Confirmed id %s is a corp." % corp_id)
             return True
         except evelink.api.APIError as error:
-            return False
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
+        logger.debug("Unable to verify id %s is corp." % corp_id)
         return False
 
     @staticmethod
     def get_corp_standings():
         if settings.CORP_API_ID != "":
             try:
+                logger.debug("Getting corp standings with api id %s" % settings.CORP_API_ID)
                 api = evelink.api.API(api_key=(settings.CORP_API_ID, settings.CORP_API_VCODE))
                 corp = evelink.corp.Corp(api=api)
                 corpinfo = corp.contacts()
                 results = corpinfo[0]
+                logger.info("Got corp standings from settings: %s" % results)
                 return results
             except evelink.api.APIError as error:
-                pass
-
+                logger.exception("Unhandled APIError occured.", exc_info=True)
+        else:
+            logger.error("No corp API key supplied in settings. Unable to get standings.")
         return {}
 
     @staticmethod
     def check_if_id_is_alliance(alliance_id):
+        logger.debug("Checking if id %s is an alliance." % alliance_id)
         try:
             api = evelink.api.API()
             eve = evelink.eve.EVE(api=api)
             alliance = eve.alliances()
             results = alliance[0][int(alliance_id)]
             if results:
+                logger.info("Confirmed id %s is an alliance." % alliance_id)
                 return True
         except evelink.api.APIError as error:
-            return False
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
+        logger.info("Unable to verify id %s is an alliance." % alliance_id)
         return False
 
     @staticmethod
     def check_if_id_is_character(character_id):
+        logger.debug("Checking if id %s is a character." % character_id)
         try:
             api = evelink.api.API()
             eve = evelink.eve.EVE(api=api)
             results = eve.character_info_from_id(character_id)
             if results:
+                logger.info("Confirmed id %s is a character." % character_id)
                 return True
         except evelink.api.APIError as error:
-            return False
+            logger.exception("Unhandled APIError occured.", exc_info=True)
 
+        logger.info("Unable to verify id %s is a character." % character_id)
         return False
 
     @staticmethod
     def check_if_alliance_exists(alliance_id):
+        logger.debug("Checking if alliance id %s exists." % alliance_id)
         try:
             api = evelink.api.API()
             eve = evelink.eve.EVE(api=api)
             alliances = eve.alliances()
             if int(alliance_id) in alliances[0]:
+                logger.info("Verified alliance id %s exists." % alliance_id)
                 return True
             else:
+                logger.info("Verified alliance id %s does not exist." % alliance_id)
                 return False
         except evelink.api.APIError as error:
-            print error
+            logger.exception("Unhandled APIError occured.", exc_info=True)
             return False
         except ValueError as error:
             #attempts to catch error resulting from checking alliance_of nonetype models
-            print error
+            logger.exception("Unhandled ValueError occured. Possible nonetype alliance model.", exc_info=True)
             return False
+        logger.warn("Exception prevented verification of alliance id %s existance. Assuming false." % alliance_id)
         return False
 
     @staticmethod
     def check_if_corp_exists(corp_id):
+        logger.debug("Checking if corp id %s exists." % corp_id)
         try:
             api = evelink.api.API()
             corp = evelink.corp.Corp(api=api)
             corpinfo = corp.corporation_sheet(corp_id=corp_id)
             if corpinfo[0]['members']['current'] > 0:
+                logger.info("Verified corp id %s exists with member count %s" % (corp_id, corpinfo[0]['members']['current']))
                 return True
             else:
+                logger.info("Verified corp id %s has closed. Member count %s" % (corp_id, corpinfo[0]['members']['current']))
                 return False
         except evelink.api.APIError as error:
             #could be smart and check for error code523 to verify error due to no corp instead of catch-all
-            print error
+            logger.exception("Unhandled APIError occured.", exc_info=True)
             return False
+        logger.warn("Exception prevented verification of corp id %s existance. Assuming false." % corp_id)
         return False
diff --git a/services/managers/ipboard_manager.py b/services/managers/ipboard_manager.py
index a85a146a..0ae66105 100755
--- a/services/managers/ipboard_manager.py
+++ b/services/managers/ipboard_manager.py
@@ -4,6 +4,9 @@ from hashlib import md5
 
 from django.conf import settings
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 class IPBoardManager:
     def __init__(self):
@@ -39,29 +42,35 @@ class IPBoardManager:
     def add_user(username, email):
         """ Add user to service """
         sanatized = str(IPBoardManager.__santatize_username(username))
+        logger.debug("Adding user to IPBoard with username %s" % sanatized)
         plain_password = IPBoardManager.__generate_random_pass()
         password = md5(plain_password).hexdigest()
         ret = IPBoardManager.exec_xmlrpc('createUser', username=sanatized, email=str(email), display_name=sanatized,
                                          md5_passwordHash=password)
+        logger.info("Added IPBoard user with username %s" % sanatized)
         return sanatized, plain_password
 
     @staticmethod
     def delete_user(username):
         """ Delete user """
         ret = IPBoardManager.exec_xmlrpc('deleteUser', username=username)
+        logger.info("Deleted IPBoard user with username %s" % username)
         return username
 
     @staticmethod
     def disable_user(username):
         """ Disable user """
         ret = IPBoardManager.exec_xmlrpc('disableUser', username=username)
+        logger.info("Disabled IPBoard user with username %s" % username)
         return username
 
     @staticmethod
     def update_user(username, email, password):
         """ Add user to service """
         password = md5(password).hexdigest()
+        logger.debug("Updating IPBoard username %s with email %s and password hash starting with %s" % (username, email, password[0:5]))
         ret = IPBoardManager.exec_xmlrpc('updateUser', username=username, email=email, md5_passwordHash=password)
+        logger.info("Updated IPBoard user with username %s" % username)
         return username
 
     @staticmethod
@@ -70,6 +79,7 @@ class IPBoardManager:
         ret = IPBoardManager.exec_xmlrpc('getAllGroups')
         for group in ret:
             groups.append(group["g_title"])
+        logger.info("Retrieved group list from IPBoard: %s" % groups)
         return groups
 
     @staticmethod
@@ -79,21 +89,25 @@ class IPBoardManager:
         if type(ret) is list:
             for group in ret:
                 groups.append(group["g_title"])
+        logger.info("Got user %s IPBoard groups %s" % username, groups)
         return groups
 
     @staticmethod
     def add_group(group):
         ret = IPBoardManager.exec_xmlrpc('addGroup', group=group)
+        logger.info("Added IPBoard group %s, response %s" % (group, ret))
         return ret
 
     @staticmethod
     def add_user_to_group(username, group):
         ret = IPBoardManager.exec_xmlrpc('addUserToGroup', username=username, group=group)
+        logger.info("Added IPBoard user %s to group %s, response %s" % (username, group, ret))
         return ret
 
     @staticmethod
     def remove_user_from_group(username, group):
         ret = IPBoardManager.exec_xmlrpc('removeUserFromGroup', username=username, group=group)
+        logger.info("Removed IPBoard user %s from group %s, reponse %s" % (username, group, ret))
         return ret
 
     @staticmethod
@@ -104,27 +118,27 @@ class IPBoardManager:
 
     @staticmethod
     def update_groups(username, groups):
-
+        logger.debug("Updating IPBoard user %s with groups %s" % (username, groups))
         forum_groups = IPBoardManager.get_all_groups()
         user_groups = set(IPBoardManager.get_user_groups(username))
         act_groups = set([g.replace(' ', '-') for g in groups])
         addgroups = act_groups - user_groups
         remgroups = user_groups - act_groups
 
-        print addgroups
-        print remgroups
+        logger.info("Updating IPBoard groups for user %s - adding %s, removing %s" % (username, addgroups, remgroups))
         for g in addgroups:
             if not g in forum_groups:
                 IPBoardManager.add_group(g)
-            print username
-            print g
+            logger.debug("Adding user %s to IPBoard group %s" % (username, g))
             IPBoardManager.add_user_to_group(username, g)
 
         for g in remgroups:
+            logger.debug("Removing user %s from IPBoard group %s" % (username, g))
             IPBoardManager.remove_user_from_group(username, g)
 
     @staticmethod
     def update_user_password(username, email):
+        logger.debug("Settings new IPBoard password for user %s" % username))
         plain_password = IPBoardManager.__generate_random_pass()
         IPBoardManager.update_user(username, email, plain_password)
-        return plain_password
\ No newline at end of file
+        return plain_password
diff --git a/services/managers/mumble_manager.py b/services/managers/mumble_manager.py
index 5ad28163..d40ac249 100755
--- a/services/managers/mumble_manager.py
+++ b/services/managers/mumble_manager.py
@@ -6,6 +6,9 @@ import django
 from django.db import connections
 from django.conf import settings
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 class MumbleManager:
     SQL_SELECT_USER_MAX_ID = r"SELECT max(user_id)+1 as next_id from murmur_users"
@@ -76,30 +79,38 @@ class MumbleManager:
         for row in rows:
             out[row[1]] = row[0]
 
+        logger.debug("Got mumble groups %s" % out)
         return out
 
     @staticmethod
     def _get_group(name):
+        logger.debug("Looking for group name %s in mumble." % name)
         dbcursor = connections['mumble'].cursor()
         dbcursor.execute(MumbleManager.SQL_GET_GROUP_FROM_NAME, [settings.MUMBLE_SERVER_ID, name])
         row = dbcursor.fetchone()
         if row:
+            logger.debug("Found group %s in mumble - %s" % (name, row[0]))
             return row[0]
 
     @staticmethod
     def _get_user_groups(name):
+        logger.debug("Getting mumble groups for username %s" % name)
         dbcursor = connections['mumble'].cursor()
         user_id = MumbleManager.get_user_id_by_name(name)
         dbcursor.execute(MumbleManager.SQL_GET_USER_GROUPS, [user_id])
-        return [row[0] for row in dbcursor.fetchall()]
+        out = [row[0] for row in dbcursor.fetchall()]
+        logger.debug("Got user %s mumble groups %s" % (name, out))
+        return out
 
     @staticmethod
     def _add_group(name):
+        logger.debug("Adding group %s to mumble server." % name)
         dbcursor = connections['mumble'].cursor()
         dbcursor.execute(MumbleManager.SQL_SELECT_GROUP_MAX_ID)
         row = dbcursor.fetchone()
         groupid = row[0]
         dbcursor.execute(MumbleManager.SQL_ADD_GROUP, [groupid, settings.MUMBLE_SERVER_ID, name])
+        logger.info("Created group %s on mumble server with id %s" % (name, groupid)
         return groupid
 
     @staticmethod
@@ -107,124 +118,142 @@ class MumbleManager:
         if userid != None:
             dbcursor = connections['mumble'].cursor()
             dbcursor.execute(MumbleManager.SQL_ADD_USER_TO_GROUP, [groupid, settings.MUMBLE_SERVER_ID, userid])
+            logger.info("Added user id %s to mumble group id %s" % (userid, groupid))
 
     @staticmethod
     def _del_user_from_group(userid, groupid):
         dbcursor = connections['mumble'].cursor()
         dbcursor.execute(MumbleManager.SQL_DELETE_USER_FROM_GROUP, [groupid, settings.MUMBLE_SERVER_ID, userid])
+        logger.info("Removed user id %s from mumble group id %s" % (userid, groupid))
 
     @staticmethod
     def get_user_id_by_name(name):
+        logger.debug("Getting mumble user id for user with name %s" % name)
         dbcursor = connections['mumble'].cursor()
         dbcursor.execute(MumbleManager.SQL_SELECT_GET_USER_ID_BY_NAME, [name, settings.MUMBLE_SERVER_ID])
         row = dbcursor.fetchone()
         if row:
+            logger.debug("Got mumble user id %s for name %s" % (row[0], name))
             return row[0]
 
     @staticmethod
     def create_user(corp_ticker, username):
+        logger.debug("Creating mumble user with username %s and ticker %s" % (username, corp_ticker))
         dbcursor = connections['mumble'].cursor()
         username_clean = MumbleManager.__santatize_username(MumbleManager.__generate_username(username, corp_ticker))
         password = MumbleManager.__generate_random_pass()
         pwhash = MumbleManager._gen_pwhash(password)
-
+        logger.debug("Proceeding with mumble user creation: clean username %s, pwhash starts with %s" % (username_clean, pwhash[0:5]))
         try:
             dbcursor.execute(MumbleManager.SQL_SELECT_USER_MAX_ID)
             user_id = dbcursor.fetchone()[0]
 
             dbcursor.execute(MumbleManager.SQL_CREATE_USER,
                              [settings.MUMBLE_SERVER_ID, user_id, username_clean, pwhash])
-
+            logger.info("Added user to mumble with username %s" % username_clean)
             return username_clean, password
         except django.db.utils.IntegrityError as error:
-            print error
+            logger.exception("IntegrityError during mumble create_user occured.", exc_info=True)
         except:
-            print "Unexpected error:", sys.exc_info()[0]
-
+            logger.exception("Unhandled exception occured.", exc_info=True)
+        logger.error("Exception prevented creation of mumble user. Returning blank for username, password.")
         return "", ""
 
     @staticmethod
     def create_blue_user(corp_ticker, username):
+        logger.debug("Creating mumble blue user with username %s and ticker %s" % (username, corp_ticker))
         dbcursor = connections['mumble'].cursor()
         username_clean = MumbleManager.__santatize_username(MumbleManager.__generate_username_blue(username,
                                                                 corp_ticker))
         password = MumbleManager.__generate_random_pass()
         pwhash = MumbleManager._gen_pwhash(password)
-
+        logger.debug("Proceeding with mumble user creation: clean username %s, pwhash starts with %s" % (username_clean, pwhash[0:5]))
         try:
             dbcursor.execute(MumbleManager.SQL_SELECT_USER_MAX_ID)
             user_id = dbcursor.fetchone()[0]
 
             dbcursor.execute(MumbleManager.SQL_CREATE_USER,
                              [settings.MUMBLE_SERVER_ID, user_id, username_clean, pwhash])
-
+            logger.info("Added blue user to mumble with username %s" % username_clean)
             return username_clean, password
         except:
-            print "Unexpected error:", sys.exc_info()[0]
-
+            logger.exception("Unhandled exception occured.", exc_info=True)
+        logger.error("Exception prevented creation of mumble blue user. Returning blank for username, password.")
         return "", ""
 
     @staticmethod
     def check_user_exist(username):
+        logger.debug("Checking if username %s exists on mumble." % username)
         dbcursor = connections['mumble'].cursor()
         dbcursor.execute(MumbleManager.SQL_CHECK_USER_EXIST,
                          [username, settings.MUMBLE_SERVER_ID])
 
         row = dbcursor.fetchone()
         if row and row[0].lower() == username.lower():
+            logger.debug("Found username %s on mumble." % username)
             return True
+        logger.debug("Unable to find username %s on mumble." % username)
         return False
 
     @staticmethod
     def delete_user(username):
+        logger.debug("Deleting user %s from mumble." % username)
         dbcursor = connections['mumble'].cursor()
         if MumbleManager.check_user_exist(username):
             try:
 
                 dbcursor.execute(MumbleManager.SQL_DELETE_USER,
                                  [username, settings.MUMBLE_SERVER_ID])
+                logger.info("Deleted user %s from mumble." % username)
                 return True
             except:
+                logger.exception("Exception prevented deletion of user %s from mumble." % username, exc_info=True)
                 return False
-
+        logger.error("User %s not found on mumble. Unable to delete." % username)
         return False
 
     @staticmethod
     def update_user_password(username):
+        logger.debug("Updating mumble user %s password." % username)
         dbcursor = connections['mumble'].cursor()
         password = MumbleManager.__generate_random_pass()
         pwhash = MumbleManager._gen_pwhash(password)
-
+        logger.debug("Proceeding with mumble user %s password update - pwhash starts with %s" % (username, pwhash[0:5]))
         if MumbleManager.check_user_exist(username):
             try:
 
                 dbcursor.execute(MumbleManager.SQL_UPDATE_USER_PASSWORD,
                                  [pwhash, username, settings.MUMBLE_SERVER_ID])
+                logger.info("Updated mumble user %s password." % username)
                 return password
             except:
+                logger.exception("Exception prevented updating of mumble user %s password." % username, exc_info=True)
                 return ""
-
+        logger.error("User %s not found on mumble. Unable to update password." % username)
         return ""
 
     @staticmethod
     def update_groups(username, groups):
+        logger.debug("Updating mumble user %s groups %s" % (username, groups))
         userid = MumbleManager.get_user_id_by_name(username)
         mumble_groups = MumbleManager._get_groups()
         user_groups = set(MumbleManager._get_user_groups(username))
         act_groups = set([g.replace(' ', '-') for g in groups])
         addgroups = act_groups - user_groups
         remgroups = user_groups - act_groups
-
+        logger.info("Updating mumble user %s groups - adding %s, removing %s" % (username, addgroups, remgroups))
         for g in addgroups:
             if not g in mumble_groups:
                 mumble_groups[g] = MumbleManager._add_group(g)
             try:
+                logger.debug("Adding mumble user %s to group %s" % (userid, mumble_groups[g]))
                 MumbleManager._add_user_to_group(userid, mumble_groups[g])
             except:
-                print "Error occurred while adding a mumble to a group"
+                logger.exception("Exception occured while adding mumble user %s with id %s to group %s with id %s" % (username, userid, g, mumble_groups[g]), exc_info=True)
 
         for g in remgroups:
             try:
+                logger.debug("Deleting mumble user %s from group %s" % (userid, mumble_groups[g]))
                 MumbleManager._del_user_from_group(userid, mumble_groups[g])
             except:
-                print "Error occurred while removing a mumble user from group"
+                logger.exception("Exception occured whule removing mumble user %s with id %s from group %s with id %s" % (username, userid, g, mumble_groups[g]), exc_info=True))
diff --git a/services/managers/openfire_manager.py b/services/managers/openfire_manager.py
index aea8bdf2..73022d52 100755
--- a/services/managers/openfire_manager.py
+++ b/services/managers/openfire_manager.py
@@ -9,6 +9,9 @@ import threading
 from ofrestapi.users import Users as ofUsers
 from ofrestapi import exception
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 class OpenfireManager:
     def __init__(self):
@@ -16,6 +19,7 @@ class OpenfireManager:
 
     @staticmethod
     def send_broadcast_threaded(group_name, broadcast_message):
+        logger.info("Starting broadcast to %s with message %s" % (group_name, broadcast_message))
         broadcast_thread = XmppThread(1, "XMPP Broadcast Thread", 1, group_name, broadcast_message)
         broadcast_thread.start()
 
@@ -37,55 +41,68 @@ class OpenfireManager:
 
     @staticmethod
     def add_user(username):
-
+        logger.debug("Adding username %s to openfire." % username)
         try:
             sanatized_username = OpenfireManager.__santatize_username(username)
             password = OpenfireManager.__generate_random_pass()
             api = ofUsers(settings.OPENFIRE_ADDRESS, settings.OPENFIRE_SECRET_KEY)
             api.add_user(sanatized_username, password)
-
+            logger.info("Added openfire user %s" % username)
         except exception.UserAlreadyExistsException:
             # User exist
+            logger.warn("Attempting to add a user %s to openfire which already exists on server." % username)
             return "", ""
 
         return sanatized_username, password
 
     @staticmethod
     def delete_user(username):
+        logger.debug("Deleting user %s from openfire." % username)
         try:
             api = ofUsers(settings.OPENFIRE_ADDRESS, settings.OPENFIRE_SECRET_KEY)
             api.delete_user(username)
+            logger.info("Deleted user %s from openfire." % username)
             return True
         except exception.UserNotFoundException:
+            logger.warn("Attempting to delete a user %s from openfire which was not found on server." % username)
             return False
 
     @staticmethod
     def lock_user(username):
+        logger.debug("Locking openfire user %s" % username)
         api = ofUsers(settings.OPENFIRE_ADDRESS, settings.OPENFIRE_SECRET_KEY)
         api.lock_user(username)
+        logger.info("Locked openfire user %s" % username)
 
     @staticmethod
     def unlock_user(username):
+        logger.debug("Unlocking openfire user %s" % username)
         api = ofUsers(settings.OPENFIRE_ADDRESS, settings.OPENFIRE_SECRET_KEY)
         api.unlock_user(username)
+        logger.info("Unlocked openfire user %s" % username)
 
     @staticmethod
     def update_user_pass(username):
+        logger.debug("Updating openfire user %s password." % username)
         try:
             password = OpenfireManager.__generate_random_pass()
             api = ofUsers(settings.OPENFIRE_ADDRESS, settings.OPENFIRE_SECRET_KEY)
             api.update_user(username, password=password)
+            logger.info("Updated openfire user %s password." % username)
             return password
         except exception.UserNotFoundException:
+            logger.error("Unable to update openfire user %s password - user not found on server." % username)
             return ""
 
     @staticmethod
     def update_user_groups(username, password, groups):
+        logger.debug("Updating openfire user %s groups %s" % (username, groups))
         api = ofUsers(settings.OPENFIRE_ADDRESS, settings.OPENFIRE_SECRET_KEY)
         response = api.get_user_groups(username)
         remote_groups = []
         if response:
             remote_groups = response['groupname']
+        logger.debug("Openfire user %s has groups %s" % (username, remote_groups))
         add_groups = []
         del_groups = []
         for g in groups:
@@ -94,6 +111,7 @@ class OpenfireManager:
         for g in remote_groups:
             if not g in groups:
                 del_groups.append(g)
+        logger.info("Updating openfire groups for user %s - adding %s, removing %s" % (username, add_groups, del_groups))
         if add_groups:
             api.add_user_groups(username, add_groups)
         if del_groups:
@@ -101,24 +119,28 @@ class OpenfireManager:
         
     @staticmethod
     def delete_user_groups(username, groups):
-
+        logger.debug("Deleting openfire groups %s from user %s" % (groups, username))
         api = ofUsers(settings.OPENFIRE_ADDRESS, settings.OPENFIRE_SECRET_KEY)
         api.delete_user_groups(username, groups)
+        logger.info("Deleted groups %s from openfire user %s" % (groups, username))
 
     @staticmethod
     def send_broadcast_message(group_name, broadcast_message):
+        logger.debug("Sending jabber ping to group %s with message %s" % (group_name, broadcast_message))
         # create to address
         client = xmpp.Client(settings.JABBER_URL)
         client.connect(server=(settings.JABBER_SERVER, settings.JABBER_PORT))
         client.auth(settings.BROADCAST_USER, settings.BROADCAST_USER_PASSWORD, 'broadcast')
 
         to_address = group_name + '@' + settings.BROADCAST_SERVICE_NAME + '.' + settings.JABBER_URL
+        logger.debug("Determined ping to address: %s" % to_address)
         message = xmpp.Message(to_address, broadcast_message)
         message.setAttr('type', 'chat')
         client.send(message)
         client.Process(1)
 
         client.disconnect()
+        logger.info("Sent jabber ping to group %s" % group_name)
 
 class XmppThread (threading.Thread):
     def __init__(self, threadID, name, counter, group, message,):
diff --git a/services/managers/phpbb3_manager.py b/services/managers/phpbb3_manager.py
index 26ffea4d..1ee0a1cb 100755
--- a/services/managers/phpbb3_manager.py
+++ b/services/managers/phpbb3_manager.py
@@ -5,6 +5,9 @@ from datetime import datetime
 from passlib.apps import phpbb3_context
 from django.db import connections
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 class Phpbb3Manager:
     SQL_ADD_USER = r"INSERT INTO phpbb_users (username, username_clean, " \
@@ -39,6 +42,7 @@ class Phpbb3Manager:
 
     @staticmethod
     def __add_avatar(username, characterid):
+        logger.debug("Adding EVE character id %s portrait as phpbb avater for user %s" % (characterid, username))
         avatar_url = "http://image.eveonline.com/Character/" + characterid + "_64.jpg"
         cursor = connections['phpbb3'].cursor()
         userid = Phpbb3Manager.__get_user_id(username)
@@ -63,7 +67,7 @@ class Phpbb3Manager:
         cursor = connections['phpbb3'].cursor()
         cursor.execute(Phpbb3Manager.SQL_GET_GROUP_ID, [groupname])
         row = cursor.fetchone()
-
+        logger.debug("Got phpbb group id %s for groupname %s" % (row[0], groupname))
         return row[0]
 
     @staticmethod
@@ -72,8 +76,10 @@ class Phpbb3Manager:
         cursor.execute(Phpbb3Manager.SQL_USER_ID_FROM_USERNAME, [username])
         row = cursor.fetchone()
         if row is not None:
+            logger.debug("Got phpbb user id %s for username %s" % (row[0], username))
             return row[0]
         else:
+            logger.warn("Username %s not found on phpbb." % username)
             return None
 
     @staticmethod
@@ -84,14 +90,16 @@ class Phpbb3Manager:
         out = {}
         for row in rows:
             out[row[1]] = row[0]
-
+        logger.debug("Got phpbb groups %s" % out)
         return out
 
     @staticmethod
     def __get_user_groups(userid):
         cursor = connections['phpbb3'].cursor()
         cursor.execute(Phpbb3Manager.SQL_GET_USER_GROUPS, [userid])
-        return [row[0] for row in cursor.fetchall()]
+        out = [row[0] for row in cursor.fetchall()]
+        logger.debug("Got user %s phpbb groups %s" % (userid, out))
+        return out
 
     @staticmethod
     def __get_current_utc_date():
@@ -103,6 +111,7 @@ class Phpbb3Manager:
     def __create_group(groupname):
         cursor = connections['phpbb3'].cursor()
         cursor.execute(Phpbb3Manager.SQL_ADD_GROUP, [groupname, groupname])
+        logger.info("Created phpbb group %s" % groupname)
         return Phpbb3Manager.__get_group_id(groupname)
 
     @staticmethod
@@ -110,7 +119,9 @@ class Phpbb3Manager:
         try:
             cursor = connections['phpbb3'].cursor()
             cursor.execute(Phpbb3Manager.SQL_ADD_USER_GROUP, [groupid, userid, 0])
+            logger.info("Added phpbb user id to group id %s" % (userid, groupid))
         except:
+            logger.exception("Unable to add phpbb user id %s to group id %s" % (userid, groupid), exc_info=True)
             pass
 
     @staticmethod
@@ -118,19 +129,23 @@ class Phpbb3Manager:
         cursor = connections['phpbb3'].cursor()
         try:
             cursor.execute(Phpbb3Manager.SQL_REMOVE_USER_GROUP, [userid, groupid])
+            logger.info("Removed phpbb user id %s from group id %s" % (userid, groupid))
         except:
+            logger.exception("Unable to remove phpbb user id %s from group id %s" % (userid, groupid), exc_info=True)
             pass
 
     @staticmethod
     def add_user(username, email, groups, characterid):
+        logger.debug("Adding phpbb user with username %s, email %s, groups %s, characterid %s" % (username, email, groups, characterid))
         cursor = connections['phpbb3'].cursor()
 
         username_clean = Phpbb3Manager.__santatize_username(username)
         password = Phpbb3Manager.__generate_random_pass()
         pwhash = Phpbb3Manager.__gen_hash(password)
-
+        logger.debug("Proceeding to add phpbb user %s and pwhash starting with %s" % (username_clean, pwhash[0:5]))
         # check if the username was simply revoked
         if Phpbb3Manager.check_user(username_clean):
+            logger.warn("Unable to add phpbb user with username %s - already exists. Updating user instead." % username)
             Phpbb3Manager.__update_user_info(username_clean, email, pwhash)
         else:
             try:
@@ -140,13 +155,16 @@ class Phpbb3Manager:
                                                             "", ""])
                 Phpbb3Manager.update_groups(username_clean, groups)
                 Phpbb3Manager.__add_avatar(username_clean, characterid)
+                logger.info("Added phpbb user %s" % username)
             except:
+                logger.exception("Unable to add phpbb user %s" % username, exc_info=True)
                 pass
 
         return username_clean, password
 
     @staticmethod
     def disable_user(username):
+        logger.debug("Disabling phpbb user %s" % username)
         cursor = connections['phpbb3'].cursor()
 
         password = Phpbb3Manager.__gen_hash(Phpbb3Manager.__generate_random_pass())
@@ -154,32 +172,35 @@ class Phpbb3Manager:
         try:
             pwhash = Phpbb3Manager.__gen_hash(password)
             cursor.execute(Phpbb3Manager.SQL_DIS_USER, [revoke_email, pwhash, username])
+            logger.info("Disabled phpbb user %s" % username)
             return True
         except TypeError as e:
-            print e
+            logger.exception("TypeError occured while disabling user %s - failed to disable." % username, exc_info=True)
             return False
 
     @staticmethod
     def delete_user(username):
+        logger.debug("Deleting phpbb user %s" % username)
         cursor = connections['phpbb3'].cursor()
 
         if Phpbb3Manager.check_user(username):
             cursor.execute(Phpbb3Manager.SQL_DEL_USER, [username])
+            logger.info("Deleted phpbb user %s" % username)
             return True
+        logger.warn("Unable to delete phpbb user %s - user not found on phpbb." % username)
         return False
 
     @staticmethod
     def update_groups(username, groups):
         userid = Phpbb3Manager.__get_user_id(username)
+        logger.debug("Updating phpbb user %s with id %s groups %s" % (username, userid, groups))
         if userid is not None:
             forum_groups = Phpbb3Manager.__get_all_groups()
             user_groups = set(Phpbb3Manager.__get_user_groups(userid))
             act_groups = set([g.replace(' ', '-') for g in groups])
             addgroups = act_groups - user_groups
             remgroups = user_groups - act_groups
-            print username
-            print addgroups
-            print remgroups
+            logger.info("Updating phpbb user %s groups - adding %s, removing %s" % (username, addgroups, remgroups))
             for g in addgroups:
                 if not g in forum_groups:
                     forum_groups[g] = Phpbb3Manager.__create_group(g)
@@ -190,6 +211,7 @@ class Phpbb3Manager:
 
     @staticmethod
     def remove_group(username, group):
+        logger.debug("Removing phpbb user %s from group %s" % (username, group))
         cursor = connections['phpbb3'].cursor()
         userid = Phpbb3Manager.__get_user_id(username)
         if userid is not None:
@@ -199,35 +221,46 @@ class Phpbb3Manager:
                 if groupid:
                     try:
                         cursor.execute(Phpbb3Manager.SQL_REMOVE_USER_GROUP, [userid, groupid])
+                        logger.info("Removed phpbb user %s from group %s" % (username, group))
                     except:
+                        logger.exception("Exception prevented removal of phpbb user %s with id %s from group %s with id %s" % (username, userid, group, groupid), exc_info=True)
                         pass
 
     @staticmethod
     def check_user(username):
+        logger.debug("Checking phpbb username %s" % username)
         cursor = connections['phpbb3'].cursor()
         """ Check if the username exists """
         cursor.execute(Phpbb3Manager.SQL_USER_ID_FROM_USERNAME, [Phpbb3Manager.__santatize_username(username)])
         row = cursor.fetchone()
         if row:
+            logger.debug("Found user %s on phpbb" % username)
             return True
+        logger.debug("User %s not found on phpbb" % username)
         return False
 
     @staticmethod
     def update_user_password(username, characterid):
+        logger.debug("Updating phpbb user %s password" % username)
         cursor = connections['phpbb3'].cursor()
         password = Phpbb3Manager.__generate_random_pass()
         if Phpbb3Manager.check_user(username):
             pwhash = Phpbb3Manager.__gen_hash(password)
+            logger.debug("Proceeding to update phpbb user %s password with pwhash starting with %s" % (username, pwhash[0:5]))
             cursor.execute(Phpbb3Manager.SQL_UPDATE_USER_PASSWORD, [pwhash, username])
             Phpbb3Manager.__add_avatar(username, characterid)
+            logger.info("Updated phpbb user %s password." % username)
             return password
-
+        logger.error("Unable to update phpbb user %s password - user not found on phpbb." % username)
         return ""
 
     @staticmethod
     def __update_user_info(username, email, password):
+        logger.debug("Updating phpbb user %s info: username %s password of length %s" % (username, email, len(password)))
         cursor = connections['phpbb3'].cursor()
         try:
             cursor.execute(Phpbb3Manager.SQL_DIS_USER, [email, password, username])
+            logger.info("Updated phpbb user %s info" % username)
         except:
+            logger.exception("Unable to update phpbb user %s info." % username, exc_info=True
             pass
diff --git a/services/managers/teamspeak3_manager.py b/services/managers/teamspeak3_manager.py
index 349e6cfb..700bef61 100755
--- a/services/managers/teamspeak3_manager.py
+++ b/services/managers/teamspeak3_manager.py
@@ -74,7 +74,7 @@ class Teamspeak3Manager:
             server.send_command('servergroupaddperm',
                                 {'sgid': sgid, 'permsid': 'i_group_needed_member_remove_power', 'permvalue': 100,
                                  'permnegated': 0, 'permskip': 0})
-        logger.debug("Returning group id %s" % sqid)
+        logger.info("Created group on TS3 server with name %s and id %s" % (groupname, sqid))
         return sgid
 
     @staticmethod
@@ -109,7 +109,7 @@ class Teamspeak3Manager:
                 logger.debug("Assigning name/id dict: %s = %s" % (group['keys']['name'], group['keys']['sgid']))
                 outlist[group['keys']['name']] = group['keys']['sgid']
         else:
-            logger.debug("Received empty group cache. 1024 error.")
+            logger.error("Received empty group cache while retrieving group cache from TS3 server. 1024 error.", exc_info=True)
             print '1024 error'
         logger.debug("Returning name/id pairing: %s" % outlist)
         return outlist
@@ -125,6 +125,7 @@ class Teamspeak3Manager:
             logger.debug("User does not have group already. Issuing command to add.")
             server.send_command('servergroupaddclient',
                                 {'sgid': str(groupid), 'cldbid': uid})
+            logger.info("Added user id %s to group id %s on TS3 server." % (uid, groupid))
 
     @staticmethod
     def _remove_user_from_group(uid, groupid):
@@ -137,6 +138,7 @@ class Teamspeak3Manager:
             logger.debug("User is in group. Issuing command to remove.")
             server.send_command('servergroupdelclient',
                                 {'sgid': str(groupid), 'cldbid': uid})
+            logger.info("Removed user id %s from group id %s on TS3 server." % (uid, groupid))
 
     @staticmethod
     def _sync_ts_group_db():
@@ -170,7 +172,7 @@ class Teamspeak3Manager:
                                                                corp_ticker))
         server = Teamspeak3Manager.__get_created_server()
         token = ""
-
+        logger.debug("Adding user to TS3 server with cleaned username %s" % username_clean)
         server_groups = Teamspeak3Manager._group_list()
 
         if not settings.DEFAULT_AUTH_GROUP in server_groups:
@@ -188,6 +190,7 @@ class Teamspeak3Manager:
                     token = ret['keys']['token']
         except:
             pass
+        logger.info("Created user %s on TS3 server, got token %s" % (username_clean, token))
 
         return username_clean, token
 
@@ -197,7 +200,7 @@ class Teamspeak3Manager:
                                                                     corp_ticker))
         server = Teamspeak3Manager.__get_created_server()
         token = ""
-
+        logger.debug("Adding user to TS3 server with cleaned username %s" % username_clean)
         server_groups = Teamspeak3Manager._group_list()
         if not settings.DEFAULT_BLUE_GROUP in server_groups:
             Teamspeak3Manager._create_group(settings.DEFAULT_BLUE_GROUP)
@@ -215,6 +218,7 @@ class Teamspeak3Manager:
 
         except:
             pass
+        logger.info("Created blue user %s on TS3 server, got token %s" % (username_clean, token))
 
         return username_clean, token
 
@@ -222,16 +226,20 @@ class Teamspeak3Manager:
     def delete_user(uid):
         server = Teamspeak3Manager.__get_created_server()
         user = Teamspeak3Manager._get_userid(uid)
+        logger.debug("Deleting user %s with id %s from TS3 server." % (user, uid))
         if user:
             for client in server.send_command('clientlist'):
                 if client['keys']['client_database_id'] == user:
+                    logger.debug("Found user %s on TS3 server - issuing deletion command." % user)
                     server.send_command('clientkick', {'clid': client['keys']['clid'], 'reasonid': 5,
                                                        'reasonmsg': 'Auth service deleted'})
 
             ret = server.send_command('clientdbdelete', {'cldbid': user})
             if ret == '0':
+                logger.info("Deleted user with id %s from TS3 server." % uid)
                 return True
         else:
+            logger.warn("User with id %s not found on TS3 server. Assuming succesful deletion." % uid)
             return True
 
     @staticmethod
@@ -243,37 +251,42 @@ class Teamspeak3Manager:
 
     @staticmethod
     def generate_new_permissionkey(uid, username, corpticker):
+        logger.debug("Re-issuing permission key for user id %s." % uid)
         Teamspeak3Manager.delete_user(uid)
         return Teamspeak3Manager.add_user(username, corpticker)
 
     @staticmethod
     def generate_new_blue_permissionkey(uid, username, corpticker):
+        logger.debug("Re-issuing blue permission key for user id %s" % uid)
         Teamspeak3Manager.delete_user(uid)
         return Teamspeak3Manager.add_blue_user(username, corpticker)
 
     @staticmethod
     def update_groups(uid, ts_groups):
+        logger.debug("Updating uid %s groups %s" % (uid, ts_groups))
         userid = Teamspeak3Manager._get_userid(uid)
         addgroups = []
         remgroups = []
         if userid is not None:
             user_ts_groups = Teamspeak3Manager._user_group_list(userid)
+            logger.debug("User has groups on TS3 server: %s" % user_ts_groups)
             for key in user_ts_groups:
                 user_ts_groups[key] = int(user_ts_groups[key])
             for ts_group_key in ts_groups:
+                logger.debug("Checking if user has group %s on TS3 server." % ts_group_key)
                 if ts_groups[ts_group_key] not in user_ts_groups.values():
                     addgroups.append(ts_groups[ts_group_key])
             for user_ts_group_key in user_ts_groups:
                 if user_ts_groups[user_ts_group_key] not in ts_groups.values():
                     remgroups.append(user_ts_groups[user_ts_group_key])
 
-            print userid
-            print addgroups
-            print remgroups
+            logger.info("Finished checking user id %s groups. Adding %s, removing %s." % (uid, addgroups, remgroups))
 
             for g in addgroups:
+                logger.debug("Issuing add command for group %s" % g)
                 Teamspeak3Manager._add_user_to_group(userid, g)
 
             for g in remgroups:
+                logger.debug("Issuing remove command for group %s" % g)
                 Teamspeak3Manager._remove_user_from_group(userid, g)
 

From 8b2b253c586480ba9ebad166298f92d45e9059b5 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 29 Dec 2015 23:00:06 +0000
Subject: [PATCH 10/27] Adding missing brackets.

---
 services/managers/eve_api_manager.py | 6 +++---
 services/managers/ipboard_manager.py | 2 +-
 2 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/services/managers/eve_api_manager.py b/services/managers/eve_api_manager.py
index 455494fe..d1621fa2 100644
--- a/services/managers/eve_api_manager.py
+++ b/services/managers/eve_api_manager.py
@@ -94,7 +94,7 @@ class EveApiManager():
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
-            logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.MEMBER_API_MASK)
+            logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.MEMBER_API_MASK))
             return info[0]['access_mask'] & int(settings.MEMBER_API_MASK) == int(settings.MEMBER_API_MASK))
 
         except evelink.api.APIError as error:
@@ -109,7 +109,7 @@ class EveApiManager():
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
-            logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.BLUE_API_MASK)
+            logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.BLUE_API_MASK))
             return info[0]['access_mask'] & int(settings.BLUE_API_MASK) == int(settings.BLUE_API_MASK)
  
         except evelink.api.APIError as error:
@@ -148,7 +148,7 @@ class EveApiManager():
 
     @staticmethod
     def check_if_api_server_online():
-        logger.debug("Checkin if API server online.")
+        logger.debug("Checking if API server online.")
         try:
             api = evelink.api.API()
             server = evelink.server.Server(api=api)
diff --git a/services/managers/ipboard_manager.py b/services/managers/ipboard_manager.py
index 0ae66105..3313215f 100755
--- a/services/managers/ipboard_manager.py
+++ b/services/managers/ipboard_manager.py
@@ -89,7 +89,7 @@ class IPBoardManager:
         if type(ret) is list:
             for group in ret:
                 groups.append(group["g_title"])
-        logger.info("Got user %s IPBoard groups %s" % username, groups)
+        logger.info("Got user %s IPBoard groups %s" % (username, groups))
         return groups
 
     @staticmethod

From cd44f00881b0fff5716993a78f758fe44340ffec Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Wed, 30 Dec 2015 11:22:40 +0000
Subject: [PATCH 11/27] Finished auditing service manager logging.

---
 services/managers/phpbb3_manager.py     | 6 +++---
 services/managers/teamspeak3_manager.py | 3 +--
 2 files changed, 4 insertions(+), 5 deletions(-)

diff --git a/services/managers/phpbb3_manager.py b/services/managers/phpbb3_manager.py
index 1ee0a1cb..89d36fb4 100755
--- a/services/managers/phpbb3_manager.py
+++ b/services/managers/phpbb3_manager.py
@@ -79,7 +79,7 @@ class Phpbb3Manager:
             logger.debug("Got phpbb user id %s for username %s" % (row[0], username))
             return row[0]
         else:
-            logger.warn("Username %s not found on phpbb." % username)
+            logger.warn("Username %s not found on phpbb. Unable to determine user id." % username)
             return None
 
     @staticmethod
@@ -119,7 +119,7 @@ class Phpbb3Manager:
         try:
             cursor = connections['phpbb3'].cursor()
             cursor.execute(Phpbb3Manager.SQL_ADD_USER_GROUP, [groupid, userid, 0])
-            logger.info("Added phpbb user id to group id %s" % (userid, groupid))
+            logger.info("Added phpbb user id %s to group id %s" % (userid, groupid))
         except:
             logger.exception("Unable to add phpbb user id %s to group id %s" % (userid, groupid), exc_info=True)
             pass
@@ -262,5 +262,5 @@ class Phpbb3Manager:
             cursor.execute(Phpbb3Manager.SQL_DIS_USER, [email, password, username])
             logger.info("Updated phpbb user %s info" % username)
         except:
-            logger.exception("Unable to update phpbb user %s info." % username, exc_info=True
+            logger.exception("Unable to update phpbb user %s info." % username, exc_info=True)
             pass
diff --git a/services/managers/teamspeak3_manager.py b/services/managers/teamspeak3_manager.py
index 700bef61..c1818cee 100755
--- a/services/managers/teamspeak3_manager.py
+++ b/services/managers/teamspeak3_manager.py
@@ -110,7 +110,6 @@ class Teamspeak3Manager:
                 outlist[group['keys']['name']] = group['keys']['sgid']
         else:
             logger.error("Received empty group cache while retrieving group cache from TS3 server. 1024 error.", exc_info=True)
-            print '1024 error'
         logger.debug("Returning name/id pairing: %s" % outlist)
         return outlist
 
@@ -280,7 +279,7 @@ class Teamspeak3Manager:
                 if user_ts_groups[user_ts_group_key] not in ts_groups.values():
                     remgroups.append(user_ts_groups[user_ts_group_key])
 
-            logger.info("Finished checking user id %s groups. Adding %s, removing %s." % (uid, addgroups, remgroups))
+            logger.info("Finished checking user id %s groups. Adding %s, removing %s." % (userid, addgroups, remgroups))
 
             for g in addgroups:
                 logger.debug("Issuing add command for group %s" % g)

From b9125c3d5ca628ddb96029997cbf22b9a2537912 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Wed, 30 Dec 2015 15:29:27 +0000
Subject: [PATCH 12/27] Finished adding logging to service views and managers.

---
 services/managers/eve_api_manager.py |  2 +-
 services/managers/ipboard_manager.py |  2 +-
 services/managers/mumble_manager.py  |  4 +-
 services/views.py                    | 89 ++++++++++++++++++++++++++--
 4 files changed, 87 insertions(+), 10 deletions(-)

diff --git a/services/managers/eve_api_manager.py b/services/managers/eve_api_manager.py
index d1621fa2..b2891401 100644
--- a/services/managers/eve_api_manager.py
+++ b/services/managers/eve_api_manager.py
@@ -95,7 +95,7 @@ class EveApiManager():
             account = evelink.account.Account(api=api)
             info = account.key_info()
             logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.MEMBER_API_MASK))
-            return info[0]['access_mask'] & int(settings.MEMBER_API_MASK) == int(settings.MEMBER_API_MASK))
+            return info[0]['access_mask'] & int(settings.MEMBER_API_MASK) == int(settings.MEMBER_API_MASK)
 
         except evelink.api.APIError as error:
             logger.exception("Unhandled APIError occured.", exc_info=True)
diff --git a/services/managers/ipboard_manager.py b/services/managers/ipboard_manager.py
index 3313215f..496818de 100755
--- a/services/managers/ipboard_manager.py
+++ b/services/managers/ipboard_manager.py
@@ -138,7 +138,7 @@ class IPBoardManager:
 
     @staticmethod
     def update_user_password(username, email):
-        logger.debug("Settings new IPBoard password for user %s" % username))
+        logger.debug("Settings new IPBoard password for user %s" % username)
         plain_password = IPBoardManager.__generate_random_pass()
         IPBoardManager.update_user(username, email, plain_password)
         return plain_password
diff --git a/services/managers/mumble_manager.py b/services/managers/mumble_manager.py
index d40ac249..4306249a 100755
--- a/services/managers/mumble_manager.py
+++ b/services/managers/mumble_manager.py
@@ -110,7 +110,7 @@ class MumbleManager:
         row = dbcursor.fetchone()
         groupid = row[0]
         dbcursor.execute(MumbleManager.SQL_ADD_GROUP, [groupid, settings.MUMBLE_SERVER_ID, name])
-        logger.info("Created group %s on mumble server with id %s" % (name, groupid)
+        logger.info("Created group %s on mumble server with id %s" % (name, groupid))
         return groupid
 
     @staticmethod
@@ -256,4 +256,4 @@ class MumbleManager:
                 logger.debug("Deleting mumble user %s from group %s" % (userid, mumble_groups[g]))
                 MumbleManager._del_user_from_group(userid, mumble_groups[g])
             except:
-                logger.exception("Exception occured whule removing mumble user %s with id %s from group %s with id %s" % (username, userid, g, mumble_groups[g]), exc_info=True))
+                logger.exception("Exception occured while removing mumble user %s with id %s from group %s with id %s" % (username, userid, g, mumble_groups[g]), exc_info=True)
diff --git a/services/views.py b/services/views.py
index 6ab727f4..595e76e0 100755
--- a/services/views.py
+++ b/services/views.py
@@ -36,8 +36,10 @@ logger = logging.getLogger(__name__)
 
 @login_required
 def fleet_formatter_view(request):
+    logger.debug("fleet_formatter_view called by user %s" % request.user)
     if request.method == 'POST':
         form = FleetFormatterForm(request.POST)
+        logger.debug("Received POST request containing form, valid: %s" % form.is_valid())
         if form.is_valid():
             generated = "Fleet Name: " + form.cleaned_data['fleet_name'] + "\n"
             generated = generated + "FC: " + form.cleaned_data['fleet_commander'] + "\n"
@@ -51,9 +53,11 @@ def fleet_formatter_view(request):
             generated = generated + "Important: " + form.cleaned_data['important'] + "\n"
             if form.cleaned_data['comments'] != "":
                 generated = generated + "Why: " + form.cleaned_data['comments'] + "\n"
+            logger.info("Formatted fleet broadcast for user %s" % request.user)
     else:
         form = FleetFormatterForm()
         generated = ""
+        logger.debug("Returning empty form to user %s" % request.user)
 
     context = {'form': form, 'generated': generated}
 
@@ -62,12 +66,15 @@ def fleet_formatter_view(request):
 @login_required
 @permission_required('auth.jabber_broadcast')
 def jabber_broadcast_view(request):
+    logger.debug("jabber_broadcast_view called by user %s" % request.user)
     success = False
     if request.method == 'POST':
         form = JabberBroadcastForm(request.POST)
+        logger.debug("Received POST request containing form, valid: %s" % form.is_valid())
         if form.is_valid():
             user_info = AuthServicesInfo.objects.get(user=request.user)
             main_char = EveCharacter.objects.get(character_id=user_info.main_char_id)
+            logger.debug("Processing jabber broadcast for user %s with main character %s" % (user_info, main_char))
             if user_info.main_char_id != "":
                 message_to_send = form.cleaned_data['message'] + "\n##### SENT BY: " + "[" + main_char.corporation_ticker + "]" + main_char.character_name + " TO: " + form.cleaned_data['group'] + " WHEN: " + datetime.datetime.utcnow().strftime("%Y-%m-%d %H:%M:%S") + " #####\n##### Replies are NOT monitored #####\n"
                 group_to_send = form.cleaned_data['group']
@@ -81,8 +88,10 @@ def jabber_broadcast_view(request):
                 OpenfireManager.send_broadcast_threaded(group_to_send, message_to_send,)
 
             success = True
+            logger.info("Sent jabber broadcast on behalf of user %s" % request.user)
     else:
         form = JabberBroadcastForm()
+        logger.debug("Returning blank form to user %s" % request.user)
 
     context = {'form': form, 'success': success}
     return render_to_response('registered/jabberbroadcast.html', context, context_instance=RequestContext(request))
@@ -90,6 +99,7 @@ def jabber_broadcast_view(request):
 
 @login_required
 def services_view(request):
+    logger.debug("services_view called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
 
     return render_to_response('registered/services.html', {'authinfo': authinfo},
@@ -103,184 +113,236 @@ def service_blue_alliance_test(user):
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def activate_forum(request):
+    logger.debug("activate_forum called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     # Valid now we get the main characters
     character = EveManager.get_character_by_id(authinfo.main_char_id)
+    logger.debug("Adding phpbb user for user %s with main character %s" % (request.user, character))
     result = Phpbb3Manager.add_user(character.character_name, request.user.email, ['REGISTERED'], authinfo.main_char_id)
     # if empty we failed
     if result[0] != "":
         AuthServicesInfoManager.update_user_forum_info(result[0], result[1], request.user)
+        logger.debug("Updated authserviceinfo for user %s with forum credentials. Updating groups." % request.user)
         update_forum_groups(request.user)
+        logger.info("Succesfully activated forum for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccesful attempt to activate forum for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def deactivate_forum(request):
+    logger.debug("deactivate_forum called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = Phpbb3Manager.disable_user(authinfo.forum_username)
     remove_all_syncgroups_for_service(request.user, "phpbb")
     # false we failed
     if result:
         AuthServicesInfoManager.update_user_forum_info("", "", request.user)
+        logger.info("Succesfully deactivated forum for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccesful attempt to activate forum for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def reset_forum_password(request):
+    logger.debug("reset_forum_password called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = Phpbb3Manager.update_user_password(authinfo.forum_username, authinfo.main_char_id)
     # false we failed
     if result != "":
         AuthServicesInfoManager.update_user_forum_info(authinfo.forum_username, result, request.user)
+        logger.info("Succesfully reset forum password for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccessful attempt to reset forum password for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def activate_ipboard_forum(request):
+    logger.debug("activate_ipboard_forum called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     # Valid now we get the main characters
     character = EveManager.get_character_by_id(authinfo.main_char_id)
+    logger.debug("Adding ipboard user for user %s with main character %s" % (request.user, character))
     result = IPBoardManager.add_user(character.character_name, request.user.email)
     if result[0] != "":
         AuthServicesInfoManager.update_user_ipboard_info(result[0], result[1], request.user)
+        logger.debug("Updated authserviceinfo for user %s with ipboard credentials. Updating groups." % request.user)
         update_ipboard_groups(request.user)
+        logger.info("Succesfully activated ipboard for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccesful attempt to activate ipboard for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def deactivate_ipboard_forum(request):
+    logger.debug("deactivate_ipboard_forum called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = IPBoardManager.disable_user(authinfo.ipboard_username)
     remove_all_syncgroups_for_service(request.user, "ipboard")
     # false we failed
     if result:
         AuthServicesInfoManager.update_user_ipboard_info("", "", request.user)
+        logger.info("Succesfully deactivated ipboard for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccessful attempt to deactviate ipboard for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def reset_ipboard_password(request):
+    logger.debug("reset_ipboard_password called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = IPBoardManager.update_user_password(authinfo.ipboard_username, request.user.email)
     if result != "":
         AuthServicesInfoManager.update_user_ipboard_info(authinfo.ipboard_username, result, request.user)
+        logger.info("Succesfully reset ipboard password for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccesful attempt to reset ipboard password for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def activate_jabber(request):
+    logger.debug("activate_jabber called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     character = EveManager.get_character_by_id(authinfo.main_char_id)
+    logger.debug("Adding jabber user for user %s with main character %s" % (request.user, character))
     info = OpenfireManager.add_user(character.character_name)
     # If our username is blank means we already had a user
     if info[0] is not "":
         AuthServicesInfoManager.update_user_jabber_info(info[0], info[1], request.user)
+        logger.debug("Updated authserviceinfo for user %s with jabber credentials. Updating groups." % request.user)
         update_jabber_groups(request.user)
+        logger.info("Succesfully activated jabber for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccesful attempt to activate jabber for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def deactivate_jabber(request):
+    logger.debug("deactivate_jabber called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = OpenfireManager.delete_user(authinfo.jabber_username)
     remove_all_syncgroups_for_service(request.user, "openfire")
     # If our username is blank means we failed
     if result:
         AuthServicesInfoManager.update_user_jabber_info("", "", request.user)
+        logger.info("Succesfully deactivated jabber for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccesful attempt to deactivate jabber for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def reset_jabber_password(request):
+    logger.debug("reset_jabber_password called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = OpenfireManager.update_user_pass(authinfo.jabber_username)
     # If our username is blank means we failed
     if result != "":
         AuthServicesInfoManager.update_user_jabber_info(authinfo.jabber_username, result, request.user)
+        logger.info("Succesfully reset jabber password for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccessful attempt to reset jabber for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def activate_mumble(request):
+    logger.debug("activate_mumble called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     character = EveManager.get_character_by_id(authinfo.main_char_id)
     if check_if_user_has_permission(request.user, "blue_member"):
+        logger.debug("Adding mumble user for blue user %s with main character %s" % (request.user, character))
         result = MumbleManager.create_blue_user(character.corporation_ticker, character.character_name)
     else:
+        logger.debug("Adding mumble user for user %s with main character %s" % (request.user, character))
         result = MumbleManager.create_user(character.corporation_ticker, character.character_name)
     # if its empty we failed
     if result[0] is not "":
         AuthServicesInfoManager.update_user_mumble_info(result[0], result[1], request.user)
+        logger.debug("Updated authserviceinfo for user %s with mumble credentials. Updating groups." % request.user)
         update_mumble_groups(request.user)
+        logger.info("Succesfully activated mumble for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccessful attempt to activate mumble for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def deactivate_mumble(request):
+    logger.debug("deactivate_mumble called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = MumbleManager.delete_user(authinfo.mumble_username)
     remove_all_syncgroups_for_service(request.user, "mumble")
     # if false we failed
     if result:
         AuthServicesInfoManager.update_user_mumble_info("", "", request.user)
+        logger.info("Succesfully deactivated mumble for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccessful attempt to deactivate mumble for user %s" % request.user)
     return HttpResponseRedirect("/")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def reset_mumble_password(request):
+    logger.debug("reset_mumble_password called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = MumbleManager.update_user_password(authinfo.mumble_username)
 
     # if blank we failed
     if result != "":
         AuthServicesInfoManager.update_user_mumble_info(authinfo.mumble_username, result, request.user)
+        logger.info("Succesfully reset mumble password for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccesful attempt to reset mumble password for user %s" % request.user)
     return HttpResponseRedirect("/")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def activate_teamspeak3(request):
+    logger.debug("activate_teamspeak3 called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     character = EveManager.get_character_by_id(authinfo.main_char_id)
     if check_if_user_has_permission(request.user, "blue_member"):
+        logger.debug("Adding TS3 user for blue user %s with main character %s" % (request.user, character))
         result = Teamspeak3Manager.add_blue_user(character.character_name, character.corporation_ticker)
     else:
+        logger.debug("Adding TS3 user for user %s with main character %s" % (request.user, character))
         result = Teamspeak3Manager.add_user(character.character_name, character.corporation_ticker)
 
     # if its empty we failed
     if result[0] is not "":
         AuthServicesInfoManager.update_user_teamspeak3_info(result[0], result[1], request.user)
+        logger.debug("Updated authserviceinfo for user %s with TS3 credentials. Updating groups." % request.user)
         update_teamspeak3_groups(request.user)
+        logger.info("Succesfully activated TS3 for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccessful attempt to activate TS3 for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def deactivate_teamspeak3(request):
+    logger.debug("deactivate_teamspeak3 called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = Teamspeak3Manager.delete_user(authinfo.teamspeak3_uid)
 
@@ -289,37 +351,45 @@ def deactivate_teamspeak3(request):
     # if false we failed
     if result:
         AuthServicesInfoManager.update_user_teamspeak3_info("", "", request.user)
-
+        logger.info("Succesfully deactivated TS3 for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccessful attempt to deactivate TS3 for user %s" % request.user)
     return HttpResponseRedirect("/")
 
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def reset_teamspeak3_perm(request):
+    logger.debug("reset_teamspeak3_perm called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     character = EveManager.get_character_by_id(authinfo.main_char_id)
-
+    logger.debug("Deleting TS3 user for user %s" % request.user)
     Teamspeak3Manager.delete_user(authinfo.teamspeak3_uid)
 
     remove_all_syncgroups_for_service(request.user, "teamspeak3")
 
     if check_if_user_has_permission(request.user, "blue_member"):
+        logger.debug("Generating new permission key for blue user %s with main character %s" % (request.user, character))
         result = Teamspeak3Manager.generate_new_blue_permissionkey(authinfo.teamspeak3_uid, character.character_name,
                                                                    character.corporation_ticker)
     else:
+        logger.debug("Generating new permission key for user %s with main character %s" % (request.user, character))
         result = Teamspeak3Manager.generate_new_permissionkey(authinfo.teamspeak3_uid, character.character_name,
                                                               character.corporation_ticker)
 
     # if blank we failed
     if result != "":
         AuthServicesInfoManager.update_user_teamspeak3_info(result[0], result[1], request.user)
+        logger.debug("Updated authserviceinfo for user %s with TS3 credentials. Updating groups." % request.user)
         update_teamspeak3_groups(request.user)
+        logger.info("Successfully reset TS3 permission key for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccessful attempt to reset TS3 permission key for user %s" % request.user)
     return HttpResponseRedirect("/")
 
 @login_required
 def fleet_fits(request):
+    logger.debug("fleet_fits called by user %s" % request.user)
     context = {}
     return render_to_response('registered/fleetfits.html', context,
 context_instance=RequestContext(request))
@@ -327,28 +397,34 @@ context_instance=RequestContext(request))
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def deactivate_discord(request):
+    logger.debug("deactivate_discord called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = DiscordManager.delete_user(authinfo.discord_uid)
     if result:
         remove_all_syncgroups_for_service(request.user, "discord")
         AuthServicesInfoManager.update_user_discord_info("", request.user)
+        logger.info("Succesfully deactivated discord for user %s" % request.user)
         return HttpResponseRedirect("/services/")
+    logger.error("Unsuccesful attempt to deactivate discord for user %s" % request.user)
     return HttpResponseRedirect("/dashboard")
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def reset_discord(request):
+    logger.debug("reset_discord called by user %s" % request.user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     result = DiscordManager.delete_user(authinfo.discord_uid)
     if result:
         AuthServicesInfoManager.update_user_discord_info("",request.user)
+        logger.info("Succesfully deleted discord user for user %s - forwarding to discord activation." % request.user)
         return HttpResponseRedirect("/activate_discord/")
+    logger.error("Unsuccessful attempt to reset discord for user %s" % request.user)
     return HttpResponseRedirect("/services/")
 
 @login_required
 @user_passes_test(service_blue_alliance_test)
 def activate_discord(request):
-    logger.debug("activate_discord called.")
+    logger.debug("activate_discord called by user %s" % request.user)
     success = False
     if request.method == 'POST':
         logger.debug("Received POST request with form.")
@@ -361,13 +437,14 @@ def activate_discord(request):
             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)
+                logger.debug("Received discord uid %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)
+                    logger.debug("Updated discord groups for user %s." % request.user)
                     success = True
+                    logger.info("Succesfully activated discord for user %s" % request.user)
                     return HttpResponseRedirect("/services/")
             except:
                 logger.exception("An unhandled exception has occured.", exc_info=True)
@@ -376,6 +453,6 @@ def activate_discord(request):
         logger.debug("Request is not type POST - providing empty form.")
         form = DiscordForm()
 
-    logger.debug("Rendering form for user with success %s" % success)
+    logger.debug("Rendering form for user %s with success %s" % (request.user, success))
     context = {'form': form, 'success': success}
     return render_to_response('registered/discord.html', context, context_instance=RequestContext(request))

From a789edb3d8a8f127931958e6f34fa015369553d9 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sat, 2 Jan 2016 21:24:40 +0000
Subject: [PATCH 13/27] Logging everywhere. Corrected corp model updating logic
 to handle owning corp. Corrected typecasting during api access mask
 comparison. Removed error protection during user TS3 group updating to
 propogate errors.

Relevent issues:
Sorry for the spam.
---
 alliance_auth/settings.py.example |  38 ++++++-
 authentication/managers.py        |  36 ++++++-
 authentication/views.py           |  17 ++-
 celerytask/tasks.py               | 169 ++++++++++++++++++++++++------
 eveonline/forms.py                |   8 ++
 eveonline/managers.py             |  51 ++++++++-
 eveonline/views.py                |  39 ++++++-
 groupmanagement/views.py          |  22 ++++
 hrapplications/views.py           |  48 ++++++++-
 portal/views.py                   |   6 ++
 registration/forms.py             |   8 ++
 registration/views.py             |  13 ++-
 srp/views.py                      |  58 ++++++++--
 timerboard/views.py               |  19 +++-
 util/__init__.py                  |  10 ++
 util/common_task.py               |  20 ++++
 16 files changed, 505 insertions(+), 57 deletions(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index 2de69666..e5235035 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -362,7 +362,7 @@ LOGGING = {
     },
     'handlers': {
         'debug_file': {
-            'level': 'DEBUG',
+            'level': 'INFO',
             'class': 'logging.FileHandler',
             'filename': 'debug.log',
             'formatter': 'verbose'
@@ -374,14 +374,50 @@ LOGGING = {
         }
     },
     'loggers': {
+        'authentication': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
         'celerytask': {
             'handlers': ['debug_file', 'console'],
             'level': 'DEBUG',
         },
+        'eveonline': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
+        'groupmanagement': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
+        'hrapplications': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
+        'portal': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
+        'registration': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
         'services': {
             'handlers': ['debug_file', 'console'],
             'level': 'DEBUG',
         },
+        'srp': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
+        'timerboard': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
+        'util': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'DEBUG',
+        },
     }
 }
 
diff --git a/authentication/managers.py b/authentication/managers.py
index 0cea7a07..dbccc4e4 100755
--- a/authentication/managers.py
+++ b/authentication/managers.py
@@ -2,6 +2,9 @@ from django.contrib.auth.models import User
 
 from models import AuthServicesInfo
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 class AuthServicesInfoManager:
     def __init__(self):
@@ -10,10 +13,11 @@ class AuthServicesInfoManager:
     @staticmethod
     def __get_or_create(user):
         if AuthServicesInfo.objects.filter(user=user).exists():
+            logger.debug("Returning existing authservicesinfo model for user %s" % user)
             return AuthServicesInfo.objects.get(user=user)
         else:
             # We have to create
-            print 'here'
+            logger.info("Creating new authservicesinfo model for user %s" % user)
             authserviceinfo = AuthServicesInfo()
             authserviceinfo.user = user
             authserviceinfo.save()
@@ -23,66 +27,96 @@ class AuthServicesInfoManager:
     def get_auth_service_info(user):
         if User.objects.filter(username=user.username).exists():
             return AuthServicesInfoManager.__get_or_create(user)
+        logger.error("Failed to get authservicesinfo object for user %s: user does not exist." % user)
         return None
 
     @staticmethod
     def update_main_char_Id(char_id, user):
         if User.objects.filter(username=user.username).exists():
+            logger.debug("Updating user %s main character to id %s" % (user, char_id))
             authserviceinfo = AuthServicesInfoManager.__get_or_create(user)
             authserviceinfo.main_char_id = char_id
             authserviceinfo.save(update_fields=['main_char_id'])
+            logger.info("Updated user %s main character to id %s" % (user, char_id))
+        logger.error("Failed to update user %s main character id to %s: user does not exist." % (user, char_id))
 
     @staticmethod
     def update_user_forum_info(username, password, user):
         if User.objects.filter(username=user.username).exists():
+            logger.debug("Updating user %s forum info: username %s" % (user, username))
             authserviceinfo = AuthServicesInfoManager.__get_or_create(user)
             authserviceinfo.forum_username = username
             authserviceinfo.forum_password = password
             authserviceinfo.save(update_fields=['forum_username', 'forum_password'])
+            logger.info("Updated user %s forum info in authservicesinfo model." % user)
+        else:
+            logger.error("Failed to update user %s forum info: user does not exist." % user)
 
     @staticmethod
     def update_user_jabber_info(username, password, user):
         if User.objects.filter(username=user.username).exists():
+            logger.debug("Updating user %s jabber info: username %s" % (user, username))
             authserviceinfo = AuthServicesInfoManager.__get_or_create(user)
             authserviceinfo.jabber_username = username
             authserviceinfo.jabber_password = password
             authserviceinfo.save(update_fields=['jabber_username', 'jabber_password'])
+            logger.info("Updated user %s jabber info in authservicesinfo model." % user)
+        else:
+            logger.error("Failed to update user %s jabber info: user does not exist." % user)
 
 
     @staticmethod
     def update_user_mumble_info(username, password, user):
         if User.objects.filter(username=user.username).exists():
+            logger.debug("Updating user %s mumble info: username %s" % (user, username))
             authserviceinfo = AuthServicesInfoManager.__get_or_create(user)
             authserviceinfo.mumble_username = username
             authserviceinfo.mumble_password = password
             authserviceinfo.save(update_fields=['mumble_username', 'mumble_password'])
+            logger.info("Updated user %s mumble info in authservicesinfo model." % user)
+        else:
+            logger.error("Failed to update user %s mumble info: user does not exist." % user)
 
     @staticmethod
     def update_user_ipboard_info(username, password, user):
         if User.objects.filter(username=user.username).exists():
+            logger.debug("Updating user %s ipboard info: uername %s" % (user, username))
             authserviceinfo = AuthServicesInfoManager.__get_or_create(user)
             authserviceinfo.ipboard_username = username
             authserviceinfo.ipboard_password = password
             authserviceinfo.save(update_fields=['ipboard_username', 'ipboard_password'])
+            logger.info("Updated user %s ipboard info in authservicesinfo model." % user)
+        else:
+            logger.error("Failed to update user %s ipboard info: user does not exist." % user)
 
     @staticmethod
     def update_user_teamspeak3_info(uid, perm_key, user):
         if User.objects.filter(username=user.username).exists():
+            logger.debug("Updating user %s teamspeak3 info: uid %s" % (user, uid))
             authserviceinfo = AuthServicesInfoManager.__get_or_create(user)
             authserviceinfo.teamspeak3_uid = uid
             authserviceinfo.teamspeak3_perm_key = perm_key
             authserviceinfo.save(update_fields=['teamspeak3_uid', 'teamspeak3_perm_key'])
+            logger.info("Updated user %s teamspeak3 info in authservicesinfo model." % user)
+        else:
+            logger.error("Failed to update user %s teamspeak3 info: user does not exist." % user)
 
     @staticmethod
     def update_is_blue(is_blue, user):
         if User.objects.filter(username=user.username).exists():
+            logger.debug("Updating user %s blue status: %s" % (user, is_blue))
             authserviceinfo = AuthServicesInfoManager.__get_or_create(user)
             authserviceinfo.is_blue = is_blue
             authserviceinfo.save(update_fields=['is_blue'])
+            logger.info("Updated user %s blue status to %s in authservicesinfo model." % (user, is_blue))
 
     @staticmethod
     def update_user_discord_info(user_id, user):
         if User.objects.filter(username=user.username).exists():
+            logger.debug("Updating user %s discord info: user_id %s" % (user, user_id))
             authserviceinfo = AuthServicesInfoManager.__get_or_create(user)
             authserviceinfo.discord_uid = user_id
             authserviceinfo.save(update_fields=['discord_uid'])
+            logger.info("Updated user %s discord info in authservicesinfo model." % user)
+        else:
+            logger.error("Failed to update user %s discord info: user does not exist." % user)
diff --git a/authentication/views.py b/authentication/views.py
index aba82e89..5dc123ac 100644
--- a/authentication/views.py
+++ b/authentication/views.py
@@ -7,26 +7,39 @@ from django.template import RequestContext
 
 from forms import LoginForm
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 def login_user(request):
+    logger.debug("login_user called by user %s" % request.user)
     if request.method == 'POST':
         form = LoginForm(request.POST)
-
+        logger.debug("Request of type POST, received form, valid: %s" % form.is_valid())
         if form.is_valid():
             user = authenticate(username=form.cleaned_data['username'], password=form.cleaned_data['password'])
+            logger.debug("Authentication attempt with supplied credentials. Received user %s" % user)
             if user is not None:
                 if user.is_active:
+                    logger.info("Successful login attempt from user %s" % user)
                     login(request, user)
                     return HttpResponseRedirect("/dashboard")
+                else:
+                    logger.info("Login attempt failed for user %s: user marked inactive." % user)
+            else:
+                logger.info("Failed login attempt: provided username %s" % form.cleaned_data['username'])
 
             return render_to_response('public/login.html', {'form': form, 'error': True},
                                       context_instance=RequestContext(request))
     else:
+        logger.debug("Providing new login form.")
         form = LoginForm()
 
     return render_to_response('public/login.html', {'form': form}, context_instance=RequestContext(request))
 
 
 def logout_user(request):
+    logger.debug("logout_user called by user %s" % request.user)
     logout(request)
-    return HttpResponseRedirect("/")
\ No newline at end of file
+    logger.info("Successful logout for user %s" % request.user)
+    return HttpResponseRedirect("/")
diff --git a/celerytask/tasks.py b/celerytask/tasks.py
index 2986efbc..762aac53 100755
--- a/celerytask/tasks.py
+++ b/celerytask/tasks.py
@@ -31,82 +31,98 @@ import logging
 logger = logging.getLogger(__name__)
 
 def disable_alliance_member(user, char_id):
+    logger.debug("Disabling alliance member %s" % user)
     remove_member_permission(user, 'member')
     remove_user_from_group(user, settings.DEFAULT_AUTH_GROUP)
     remove_user_from_group(user,
                            generate_corp_group_name(
                                EveManager.get_character_by_id(char_id).corporation_name))
     deactivate_services(user)
+    logger.info("Disabled alliance member %s" % user)
 
 def disable_expired_member(user):
+    logger.debug("Disabling expired member %s" % user)
     deactivate_services(user)
     user.user_permissions.clear()
     user.groups.clear()
     user.save()
+    logger.info("Disabled expired member %s" % user)
 
 def disable_blue_member(user):
+    logger.debug("Disabling blue member %s" % user)
     remove_member_permission(user, 'blue_member')
     remove_user_from_group(user, settings.DEFAULT_BLUE_GROUP)
     deactivate_services(user)
     AuthServicesInfoManager.update_is_blue(False, user)
+    logger.info("Disabled blue member %s" % user)
 
 def is_teamspeak3_active():
     return settings.ENABLE_AUTH_TEAMSPEAK3 or settings.ENABLE_BLUE_TEAMSPEAK3
 
 def update_jabber_groups(user):
+    logger.debug("Updating jabber groups for user %s" % user)
     syncgroups = SyncGroupCache.objects.filter(user=user)
     authserviceinfo = AuthServicesInfo.objects.get(user=user)
     groups = []
-
+    logger.debug("User %s has %s syncgroups." % (user, len(syncgroups)))
     for syncgroup in syncgroups:
         groups.append(str(syncgroup.groupname))
 
     if len(groups) == 0:
         groups.append('empty')
+    logger.debug("Updating user %s jabber groups to %s" % (user, groups))
 
     OpenfireManager.update_user_groups(authserviceinfo.jabber_username, authserviceinfo.jabber_password, groups)
+    logger.info("Updated user %s jabber groups." % user)
 
 
 def update_mumble_groups(user):
+    logger.debug("Updating mumble groups for user %s" % user)
     syncgroups = SyncGroupCache.objects.filter(user=user)
     authserviceinfo = AuthServicesInfo.objects.get(user=user)
     groups = []
+    logger.debug("User %s has %s syncgroups." % (user, len(syncgroups)))
     for syncgroup in syncgroups:
         groups.append(str(syncgroup.groupname))
 
     if len(groups) == 0:
         groups.append('empty')
-
+    logger.debug("Updating user %s mumble groups to %s" % (user, groups))
     MumbleManager.update_groups(authserviceinfo.mumble_username, groups)
-
+    logger.info("Updated user %s mumble groups." % user)
 
 def update_forum_groups(user):
+    logger.debug("Updating forum groups for user %s" % user)
     syncgroups = SyncGroupCache.objects.filter(user=user)
     authserviceinfo = AuthServicesInfo.objects.get(user=user)
     groups = []
+    logger.debug("User %s has %s syncgroups." % (user, len(syncgroups)))
     for syncgroup in syncgroups:
         groups.append(str(syncgroup.groupname))
 
     if len(groups) == 0:
         groups.append('empty')
-
+    logger.debug("Updating user %s forum groups to %s" % (user, groups))
     Phpbb3Manager.update_groups(authserviceinfo.forum_username, groups)
-
+    logger.info("Updated user %s forum groups." % user)
 
 def update_ipboard_groups(user):
+    logger.debug("Updating user %s ipboard groups." % user)
     syncgroups = SyncGroupCache.objects.filter(user=user)
     authserviceinfo = AuthServicesInfo.objects.get(user=user)
     groups = []
+    logger.debug("User %s has %s syncgroups." % (user, len(syncgroups)))
     for syncgroup in syncgroups:
         groups.append(str(syncgroup.groupname))
 
     if len(groups) == 0:
         groups.append('empty')
-
+    logger.debug("Updating user %s ipboard groups to %s" % (user, groups))
     IPBoardManager.update_groups(authserviceinfo.ipboard_username, groups)
-
+    logger.info("Updated user %s ipboard groups." % user)
 
 def update_teamspeak3_groups(user):
+    logger.debug("Updating user %s teamspeak3 groups" % user)
     usergroups = user.groups.all()
     authserviceinfo = AuthServicesInfo.objects.get(user=user)
     groups = {}
@@ -116,8 +132,9 @@ def update_teamspeak3_groups(user):
             for filtered_group in filtered_groups:
                 for ts_group in filtered_group.ts_group.all():
                     groups[ts_group.ts_group_name] = ts_group.ts_group_id
-    if (is_teamspeak3_active()):
-        Teamspeak3Manager.update_groups(authserviceinfo.teamspeak3_uid, groups)
+    logger.debug("Updating user %s teamspeak3 groups to %s" % (user, groups))
+    Teamspeak3Manager.update_groups(authserviceinfo.teamspeak3_uid, groups)
+    logger.info("Updated user %s teamspeak3 groups." % user)
 
 def update_discord_groups(user):
     logger.debug("Updating discord groups for user %s" % user)
@@ -127,26 +144,33 @@ def update_discord_groups(user):
     for syncgroup in syncgroups:
         groups.append(str(syncgroup.groupname))
 
-    logger.debug("Found %s syncgroups." % len(groups))
+    logger.debug("User %s has %s syncgroups." % (user, len(syncgroups)))
     if len(groups) == 0:
         logger.debug("No syncgroups found for user. Adding empty group.")
         groups.append('empty')
-
+    logger.debug("Updating user %s discord groups to %s" % (user, groups))
     DiscordManager.update_groups(authserviceinfo.discord_uid, groups)
+    logger.info("Updated user %s discord groups." % user)
 
 def create_syncgroup_for_user(user, groupname, servicename):
+    logger.debug("Creating syncgroupcache for user %s group %s in service %s" % (user, groupname, servicename))
     synccache = SyncGroupCache()
     synccache.groupname = groupname
     synccache.user = user
     synccache.servicename = servicename
     synccache.save()
+    logger.info("Created syncgroup for user %s group %s in service %s" % (user, groupname, servicename))
 
 
 def remove_all_syncgroups_for_service(user, servicename):
+    logger.debug("Removing all syncgroups for user %s service %s" % (user, servicename))
     syncgroups = SyncGroupCache.objects.filter(user=user)
+    logger.debug("User %s has %s syncgroups." % (user, len(syncgroups)))
     for syncgroup in syncgroups:
         if syncgroup.servicename == servicename:
+            logger.debug("Deleting syncgroups %s" % syncgroup)
             syncgroup.delete()
+    logger.info("Removed all syncgroups for user %s service %s" % (user, servicename))
 
 
 def add_to_databases(user, groups, syncgroups):
@@ -258,43 +282,53 @@ def run_databaseUpdate():
 @periodic_task(run_every=crontab(minute=0, hour="*/3"))
 def run_api_refresh():
     users = User.objects.all()
-
+    logger.debug("Running api refresh on %s users." % len(users))
     for user in users:
         # Check if the api server is online
+        logger.debug("Running api refresh for user %s" % user)
         if EveApiManager.check_if_api_server_online():
             api_key_pairs = EveManager.get_api_key_pairs(user.id)
+            logger.debug("User %s has api key pairs %s" % (user, api_key_pairs))
             if api_key_pairs:
                 valid_key = False
                 authserviceinfo = AuthServicesInfo.objects.get(user=user)
 
-                print 'Running update on user: ' + user.username
+                logger.debug("User %s has api keys. Proceeding to refresh." % user)
                 if authserviceinfo.main_char_id:
                     if authserviceinfo.main_char_id != "":
                         #preserve old corp ID for corp change test on members
                         oldcorp_id = 0
                         if EveManager.get_character_by_id(authserviceinfo.main_char_id):
                             oldcorp_id = EveCharacter.objects.get(character_id=authserviceinfo.main_char_id).corporation_id
+                            logger.debug("Determined user %s current main corp id %s" % (user, oldcorp_id))
                         for api_key_pair in api_key_pairs:
-                            print 'Running on ' + api_key_pair.api_id + ':' + api_key_pair.api_key
+                            logger.debug("Running update on api key %s" % api_key_pair.api_id)
                             if EveApiManager.api_key_is_valid(api_key_pair.api_id, api_key_pair.api_key):
                                 #check to ensure API key meets min spec
+                                logger.info("Determined api key %s is still active." % api_key_pair.api_id)
                                 still_valid = True
                                 if authserviceinfo.is_blue:
                                     if settings.BLUE_API_ACCOUNT:
                                         if not EveApiManager.check_api_is_type_account(api_key_pair.api_id, api_key_pair.api_key):
+                                            logger.info("Determined api key %s for blue user %s is no longer type account as requred." % (api_key_pair.api_id, user))
                                             still_valid = False
                                     if not EveApiManager.check_blue_api_is_full(api_key_pair.api_id, api_key_pair.api_key):
+                                            logger.info("Determined api key %s for blue user %s no longer meets minimum access mask as required." % (api_key_pair.api_id, user))
                                             still_valid = False
                                 else:
                                     if settings.MEMBER_API_ACCOUNT:
                                         if not EveApiManager.check_api_is_type_account(api_key_pair.api_id, api_key_pair.api_key):
+                                            logger.info("Determined api key %s for user %s is no longer type account as required." % (api_key_pair.api_id, user))
                                             still_valid = False
                                     if not EveApiManager.check_api_is_full(api_key_pair.api_id, api_key_pair.api_key):
+                                            logger.info("Determined api key %s for user %s no longer meets minimum access mask as required." % (api_key_pair.api_id, user))
                                             still_valid = False
                                 if still_valid is not True:
+                                    logger.debug("API key %s has failed validation; it and its characters will be deleted." % api_key_pair.api_id)
                                     EveManager.delete_characters_by_api_id(api_key_pair.api_id, user.id)
                                     EveManager.delete_api_key_pair(api_key_pair.api_id, user.id)
-                                else:                                    
+                                else:
+                                    logger.info("Determined api key %s still meets requirements." % api_key_pair.api_id)
                                     # Update characters
                                     characters = EveApiManager.get_characters_from_api(api_key_pair.api_id,
                                                                                        api_key_pair.api_key)
@@ -304,25 +338,32 @@ def run_api_refresh():
                                         # Ensure we have a model for all characters on key
                                         if not EveManager.check_if_character_exist(characters.result[char]['name']):
                                             new_character = True
+                                            logger.debug("API key %s has a new character on the account: %s" % (api_key_pair.api_id, characters.result[char]['name']))
                                     if new_character:
+                                        logger.debug("Creating new character %s from api key %s" % (characters.result[char]['name'], api_key_pair.api_id))
                                         EveManager.create_characters_from_list(characters, user, api_key_pair.api_key)
                                     valid_key = True
                             else:
+                                logger.debug("API key %s is no longer active; it and its characters will be deleted." % api_key_pair.api_id)
                                 EveManager.delete_characters_by_api_id(api_key_pair.api_id, user.id)
                                 EveManager.delete_api_key_pair(api_key_pair.api_id, user.id)
 
                         if valid_key:
                             # Check our main character
                             character = EveManager.get_character_by_id(authserviceinfo.main_char_id)
+                            logger.debug("User %s has valid api key, checking main character %s" % (user, character))
                             if character is not None and EveManager.check_if_corporation_exists_by_id(character.corporation_id):
                                 corp = EveManager.get_corporation_info_by_id(character.corporation_id)
                                 main_corp_id = EveManager.get_charater_corporation_id_by_id(authserviceinfo.main_char_id)
                                 main_alliance_id = EveManager.get_charater_alliance_id_by_id(authserviceinfo.main_char_id)
+                                logger.debug("User %s main character %s has corp %s with alliance id %s" % (user, character, corp, main_alliance_id))
                                 if (settings.IS_CORP and main_corp_id == settings.CORP_ID) or (not settings.IS_CORP and main_alliance_id == settings.ALLIANCE_ID):
+                                    logger.debug("User %s corp or alliance meets membership requirements. Ensuring has required permissions and groups." % user)
                                     if not check_if_user_has_permission(user, "member"):
                                         #transition from none or blue to member
                                         if check_if_user_has_permission(user, "blue_member"):
                                             #strip blue status
+                                            logger.debug("Removing user %s blue permission and group to prepare for member transition." % user)
                                             remove_member_permission(user, "blue_member")
                                             remove_user_from_group(user, settings.DEFAULT_BLUE_GROUP)
                                             AuthServicesInfoManager.update_is_blue(False, user)
@@ -331,51 +372,65 @@ def run_api_refresh():
                                         add_user_to_group(user, settings.DEFAULT_AUTH_GROUP)
                                         #add to required corp group
                                         add_user_to_group(user, generate_corp_group_name(character.corporation_name))
+                                        logger.info("User %s transitioned to full member during api refresh." % user)
                                     elif corp.corporation_id != oldcorp_id:
                                         #changed corps, both corps auth'd, need to change group assignment
+                                        logger.debug("User %s main character changed corp from id %s to %s, both meet membership requirements. Updating corp group." % (user, oldcorp_id, corp.corporation_id))
                                         oldcorp = EveCorporationInfo.objects.get(corporation_id=oldcorp_id)
                                         remove_user_from_group(user, generate_corp_group_name(oldcorp.corporation_name))
                                         add_user_to_group(user, generate_corp_group_name(character.corporation_name))
                                         #reset services to force new mumble names and group assignments
                                         deactivate_services(user)
+                                        logger.info("User %s transferred corps from member to member. Reassigned groups." % user)
                                 elif corp is not None:
+                                    logger.debug("User %s main corp %s does not meet membership requirements." % (user, corp))
                                     if corp.is_blue is not True:
                                         if check_if_user_has_permission(user, "member"):
                                             #transition from member to nobody
                                             disable_alliance_member(user, authserviceinfo.main_char_id)
+                                            logger.info("User %s no longer member: main has left member corp/alliance." % user)
                                         elif check_if_user_has_permission(user, "blue_member"):
                                             #transition from blue to nobody
                                             disable_blue_member(user)
+                                            logger.info("User %s no longer blue: main has left blue entities." % user)
                                         else:
                                             #stay nobody, make sure no services
                                             deactivate_services(user)
+                                            logger.debug("Ensured non-member %s has no services." % user)
                                     else:
                                         if check_if_user_has_permission(user, "member"):
                                             #remove auth member to prepare for member to blue transition
                                             disable_alliance_member(user, authserviceinfo.main_char_id)
+                                            logger.debug("Removed user %s member group/permissions to transition to blue." % user)
                                         if not check_if_user_has_permission(user, "blue_member"):
                                             #perform nobody to blue transition
                                             add_member_permission(user, "blue_member")
                                             add_user_to_group(user, settings.DEFAULT_BLUE_GROUP)
                                             AuthServicesInfoManager.update_is_blue(True, user)
+                                            logger.info("User %s transitioned to blue member during api refresh." % user)
 
                                 else:
                                     # disable accounts with missing corp model (not blue or member)
                                     if check_if_user_has_permission(user, "member"):
                                         disable_alliance_member(user, authserviceinfo.main_char_id)
+                                        logger.info("User %s disabled (previously member) as unable to check missing corp model." % user)
                                     elif check_if_user_has_permission(user, "blue_member"):
                                         disable_blue_member(user)
+                                        logger.info("User %s disabled (previously blue) as unable to check missing corp model." % user)
                                     else:
                                         deactivate_services(user)
+                                        logger.debug("Ensured non-member %s has no services." % user)
                             else:
                                 # nuke it, the hard way
                                 disable_expired_member(user)                                
+                                logger.info("User %s disabled due to missing main character or corp model." % user)
                         else:
                             # disable accounts with invalid keys
                             disable_expired_member(user)
+                            logger.info("User %s has no valid api keys and has been disabled." % user)
 
                 else:
-                    print 'No main_char_id set'
+                    logger.warn("User %s has no main character id, unable to validate membership.")
 
 
 # Run Every 2 hours
@@ -383,36 +438,48 @@ def run_api_refresh():
 def run_corp_update():
     # I am not proud of this block of code
     if EveApiManager.check_if_api_server_online():
-
+        logger.debug("API server online and reachable. Proceeding with corp update.")
         if settings.IS_CORP:
             # Create the corp
+            logger.debug("Ensuring corp model exists for owning corp id %s due to settings.IS_CORP %s" % (settings.CORP_ID, settings.IS_CORP))
             ownercorpinfo = EveApiManager.get_corporation_information(settings.CORP_ID)
+            logger.debug("Determined ownercorp info: %s" % ownercorpinfo)
             if not EveManager.check_if_corporation_exists_by_id(ownercorpinfo['id']):
+                logger.debug("Owning corp id %s does not have a model. Creating." % ownercorpinfo['id'])
                 if ownercorpinfo['alliance']['id'] is None:
+                    logger.debug("Owning corp does not have an alliance. Creating model with alliance=None")
                     EveManager.create_corporation_info(ownercorpinfo['id'], ownercorpinfo['name'], ownercorpinfo['ticker'],
                                                        ownercorpinfo['members']['current'], False, None)
                 else:
                     alliance_info = EveApiManager.get_alliance_information(ownercorpinfo['alliance']['id'])
-                    if not EveManager.check_if_alliance_exists_by_id(settings.ALLIANCE_ID):
-                        EveManager.create_alliance_info(settings.ALLIANCE_ID, alliance_info['name'], alliance_info['ticker'],
+                    logger.debug("Owning corp has an alliance, got info: %s" % alliance_info)
+                    if not EveManager.check_if_alliance_exists_by_id(ownercorpinfo['alliance']['id']):
+                        logger.debug("Owning corp missing alliance model. Creating for id %s" % ownercorpinfo['alliance']['id'])
+                        EveManager.create_alliance_info(ownercorpinfo['alliance']['id'], alliance_info['name'], alliance_info['ticker'],
                                                         alliance_info['executor_id'], alliance_info['member_count'], False)
                     alliance = EveManager.get_alliance_info_by_id(ownercorpinfo['alliance']['id'])
+                    logger.debug("Got alliance model %s for owning corp. Creating corp model." % alliance)
                     EveManager.create_corporation_info(ownercorpinfo['id'], ownercorpinfo['name'], ownercorpinfo['ticker'],
                                                        ownercorpinfo['members']['current'], False, alliance)
 
         else:
             # Updated alliance info
+            logger.debug("Getting info for owning alliance %s" % settings.ALLIANCE_ID)
             alliance_info = EveApiManager.get_alliance_information(settings.ALLIANCE_ID)
- 
+            logger.debug("Owning alliance info: %s" % alliance_info)
              # Populate alliance info
             if not EveManager.check_if_alliance_exists_by_id(settings.ALLIANCE_ID):
+                logger.debug("Missing alliance model for owning alliance. Creating with id %s" % settings.ALLIANCE_ID)
                 EveManager.create_alliance_info(settings.ALLIANCE_ID, alliance_info['name'], alliance_info['ticker'],
                                              alliance_info['executor_id'], alliance_info['member_count'], False)
             alliance = EveManager.get_alliance_info_by_id(settings.ALLIANCE_ID)
+            logger.debug("Got owning alliance model %s" % alliance)
             # Create the corps in the alliance
             for alliance_corp in alliance_info['member_corps']:
                 corpinfo = EveApiManager.get_corporation_information(alliance_corp)
+                logger.debug("Got corpinfo for alliance member corp: %s" % corpinfo)
                 if not EveManager.check_if_corporation_exists_by_id(corpinfo['id']):
+                    logger.debug("Alliance member corp id %s missing model - creating." % corpinfo['id'])
                     EveManager.create_corporation_info(corpinfo['id'], corpinfo['name'], corpinfo['ticker'],
                                                     corpinfo['members']['current'], False, alliance)
 
@@ -420,129 +487,167 @@ def run_corp_update():
         #refer to https://github.com/eve-val/evelink/blob/master/evelink/parsing/contact_list.py#L43
         standing_level = 'alliance'
         if settings.IS_CORP:
+            logger.debug("Switching statings check to corp level.")
             standing_level = 'corp'
 
         # Create the corps in the standings
         corp_standings = EveApiManager.get_corp_standings()
+        logger.debug("Got %s corp standings." % len(corp_standings))
         if corp_standings:
             for standing_id in EveApiManager.get_corp_standings()[standing_level]:
+                logger.debug("Processing standing id %s" % standing_id)
                 if int(corp_standings[standing_level][standing_id]['standing']) >= settings.BLUE_STANDING:
+                    logger.debug("Standing %s meets or exceeds blue threshold." % standing_id)
                     if EveApiManager.check_if_id_is_character(standing_id):
+                        logger.debug("Standing id %s is a character. Not creating model.")
                         pass
                     elif EveApiManager.check_if_id_is_corp(standing_id):
                         corpinfo = EveApiManager.get_corporation_information(standing_id)
+                        logger.debug("Standing id %s is a corp. Got corpinfo: %s" % (standing_id, corpinfo))
                         if not EveManager.check_if_corporation_exists_by_id(standing_id):
+                            logger.debug("Corp model for standing id %s does not exist. Creating" % standing_id)
                             EveManager.create_corporation_info(corpinfo['id'], corpinfo['name'], corpinfo['ticker'],
                                                                corpinfo['members']['current'], True, None)
                     else:
                         # Alliance id create corps
                         blue_alliance_info = EveApiManager.get_alliance_information(standing_id)
-
+                        logger.debug("Standing id %s is alliance. Got alliance info: %s" % (standing_id, blue_alliance_info))
                         if not EveManager.check_if_alliance_exists_by_id(standing_id):
+                            logger.debug("Alliance model for standing id %s does not exist. Creating" % standing_id)
                             EveManager.create_alliance_info(standing_id, blue_alliance_info['name'],
                                                             blue_alliance_info['ticker'],
                                                             blue_alliance_info['executor_id'],
                                                             blue_alliance_info['member_count'], True)
 
                         blue_alliance = EveManager.get_alliance_info_by_id(standing_id)
-
+                        logger.debug("Got alliance model %s for standing id %s" % (blue_alliance, standing_id))
                         for blue_alliance_corp in blue_alliance_info['member_corps']:
                             blue_info = EveApiManager.get_corporation_information(blue_alliance_corp)
+                            logger.debug("Got corpinfo for member corp id %s of blue alliance %s: %s" % (blue_info['id'], blue_alliance, blue_info))
                             if not EveManager.check_if_corporation_exists_by_id(blue_info['id']):
+                                logger.debug("Blue alliance %s member corp id %s missing model. Creating." % (blue_alliance, blue_info['id']))
                                 EveManager.create_corporation_info(blue_info['id'], blue_info['name'],
                                                                    blue_info['ticker'],
                                                                    blue_info['members']['current'], True, blue_alliance)
 
             # Update all allinace info's
             for all_alliance_info in EveManager.get_all_alliance_info():
+                logger.debug("Validating alliance model %s" % all_alliance_info)
                 if EveApiManager.check_if_alliance_exists(all_alliance_info.alliance_id):
                     all_alliance_api_info = EveApiManager.get_alliance_information(all_alliance_info.alliance_id)
+                    logger.debug("Got alliance %s alliance info: %s" % (all_alliance_info, all_alliance_api_info))
                     if (not settings.IS_CORP and all_alliance_info.alliance_id == settings.ALLIANCE_ID):
+                        logger.debug("Alliance %s is owning alliance. Updating info." % all_alliance_info)
                         EveManager.update_alliance_info(all_alliance_api_info['id'], all_alliance_api_info['executor_id'],
                                                         all_alliance_api_info['member_count'], False)
                     elif standing_level in corp_standings:
                         if int(all_alliance_info.alliance_id) in corp_standings[standing_level]:
                             if int(corp_standings[standing_level][int(all_alliance_info.alliance_id)][
                                 'standing']) >= settings.BLUE_STANDING:
+                                logger.debug("Alliance %s is blue. Updating." % all_alliance_info)
                                 EveManager.update_alliance_info(all_alliance_api_info['id'],
                                                                 all_alliance_api_info['executor_id'],
                                                                 all_alliance_api_info['member_count'], True)
                             else:
+                                logger.debug("Alliance %s does not meet blue standing threshold. Updating as non-blue." % all_alliance_info)
                                 EveManager.update_alliance_info(all_alliance_api_info['id'],
                                                                 all_alliance_api_info['executor_id'],
                                                                 all_alliance_api_info['member_count'], False)
                         else:
+                            logger.debug("Alliance %s not in standings. Updating as non-blue." % all_alliance_info)
                             EveManager.update_alliance_info(all_alliance_api_info['id'],
                                                             all_alliance_api_info['executor_id'],
                                                             all_alliance_api_info['member_count'], False)
                     else:
+                        logger.debug("No standings found. Updating alliance %s as non-blue." % all_alliance_info)
                         EveManager.update_alliance_info(all_alliance_api_info['id'],
                                                         all_alliance_api_info['executor_id'],
                                                         all_alliance_api_info['member_count'], False)
                 else:
+                    logger.info("Alliance %s has closed. Deleting model." % all_alliance_info)
                     #alliance no longer exists
                     all_alliance_info.delete()
 
             # Update corp infos
             for all_corp_info in EveManager.get_all_corporation_info():
+                logger.debug("Validating corp model %s" % all_corp_info)
                 if EveApiManager.check_if_corp_exists(all_corp_info.corporation_id):
                     alliance = None
                     corpinfo = EveApiManager.get_corporation_information(all_corp_info.corporation_id)
                     if corpinfo['alliance']['id'] is not None:
                         alliance = EveManager.get_alliance_info_by_id(corpinfo['alliance']['id'])
+                    logger.debug("Got corpinfo %s and allianceinfo %s" % (corpinfo, alliance))
 
-                    if alliance is not None and all_corp_info.alliance is not None:
-
+                    if (settings.IS_CORP and all_corp_info.corporation_id == settings.CORP_ID):
+                        logger.debug("Corp %s is owning corp. Updating." % all_corp_info)
+                        EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], None, False)
+                    elif int(all_corp_info.corporation_id) in corp_standings[standing_level]:
+                        if int(corp_standings[standing_level][int(all_corp_info.corporation_id)][
+                            'standing']) >= settings.BLUE_STANDING:
+                            logger.debug("Corp %s is blue. Updating." % all_corp_info)
+                            EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], None, True)
+                        else:
+                            logger.debug("Corp %s does not meet blue standing threshold. Updating as non-blue." % all_corp_info)
+                            EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], None, False)
+                    elif alliance is not None and all_corp_info.alliance is not None:
+                        logger.debug("Corp %s not in standings - checking alliance with model %s" % (all_corp_info, alliance))
                         if (not settings.IS_CORP) and (all_corp_info.alliance.alliance_id == settings.ALLIANCE_ID):
+                            logger.debug("Corp %s is member of owning alliance. Updating." % all_corp_info)
                             EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], alliance, False)
                         elif int(alliance.alliance_id) in corp_standings[standing_level]:
                             if int(corp_standings[standing_level][int(alliance.alliance_id)][
                                 'standing']) >= settings.BLUE_STANDING:
+                                logger.debug("Corp %s alliance %s is blue. Updating." % (all_corp_info, alliance))
                                 EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], alliance,
                                                                    True)
                             else:
+                                logger.debug("Corp %s alliance %s does not meet blue standing threshold. Updating as non-blue." % (all_corp_info, alliance))
                                 EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], alliance,
                                                                    False)
                         else:
+                            logger.debug("Corp %s alliance %s not found in standings. Updating as non-blue." % (all_corp_info, alliance))
                             EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], alliance,
                                                                False)
                     else:
-                        if int(all_corp_info.corporation_id) in corp_standings[standing_level]:
-                            if int(corp_standings[standing_level][int(all_corp_info.corporation_id)][
-                                'standing']) >= settings.BLUE_STANDING:
-                                EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], None, True)
-                            else:
-                                EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], None, False)
-                        else:
-                            EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], None, False)
+                        logger.info("Corp model %s is not owning, member of owning alliance, or in standings. Updating as non-blue." % all_corp_info)
+                        EveManager.update_corporation_info(corpinfo['id'], corpinfo['members']['current'], None, False)
                 else:
                     #corp has closed
+                    logger.info("Corp %s has closed. Deleting model." % all_corp_info)
                     all_corp_info.delete()
 
         # Remove irrelevent corp and alliance models
         # Check the corps
         for all_corp_info in EveManager.get_all_corporation_info():
+            logger.debug("Checking to delete corp model %s" % all_corp_info)
             if settings.IS_CORP:
                 if all_corp_info.corporation_id != settings.CORP_ID:
                     if not all_corp_info.is_blue:
+                        logger.info("Corp model %s is not owning corp nor blue. Deleting." % all_corp_info)
                         all_corp_info.delete()
             else:
                 if all_corp_info.alliance is not None:
                     if all_corp_info.alliance.alliance_id != settings.ALLIANCE_ID:
                         if not all_corp_info.is_blue:
+                            logger.info("Corp model %s not in owning alliance nor blue. Deleting." % all_corp_info)
                             all_corp_info.delete()
                 elif not all_corp_info.is_blue:
+                    logger.info("Corp model %s has no alliance and is not blue. Deleting." % all_corp_info)
                     all_corp_info.delete()
 
         # Check the alliances
         for all_alliance_info in EveManager.get_all_alliance_info():
+            logger.debug("Checking to delete alliance model %s" % all_alliance_info)
             if settings.IS_CORP:
                 if all_alliance_info.is_blue is not True:
                     if ownercorpinfo['alliance']['id'] is not None:
                         if int(all_alliance_info.alliance_id) != ownercorpinfo['alliance']['id']:
+                            logger.info("Alliance model %s not owning corp alliance nor blue. Deleting." % all_alliance_info)
                             all_alliance_info.delete()
                     else:
+                        logger.info("Alliance model %s not blue to alliance-less owning corp. Deleting." % all_alliance_info)
                         all_alliance_info.delete()
             elif all_alliance_info.alliance_id != settings.ALLIANCE_ID:
                 if all_alliance_info.is_blue is not True:
+                    logger.info("Alliance model %s not owning alliance nor blue. Deleting." % all_alliance_info)
                     all_alliance_info.delete()
diff --git a/eveonline/forms.py b/eveonline/forms.py
index 547862b9..5eddf39f 100644
--- a/eveonline/forms.py
+++ b/eveonline/forms.py
@@ -4,6 +4,9 @@ from django.conf import settings
 from services.managers.eve_api_manager import EveApiManager
 from eveonline.managers import EveManager
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 class UpdateKeyForm(forms.Form):
     api_id = forms.CharField(max_length=254, required=True, label="Key ID")
@@ -12,6 +15,7 @@ class UpdateKeyForm(forms.Form):
 
     def clean(self):
         if EveManager.check_if_api_key_pair_exist(self.cleaned_data['api_id']):
+            logger.debug("UpdateKeyForm failed cleaning as API id %s already exists." % self.cleaned_data['api_id'])
             raise forms.ValidationError(u'API key already exist')
 
         check_blue = False
@@ -24,20 +28,24 @@ class UpdateKeyForm(forms.Form):
             if settings.BLUE_API_ACCOUNT:
                 if not EveApiManager.check_api_is_type_account(self.cleaned_data['api_id'],
                                                                self.cleaned_data['api_key']):
+                    logger.debug("UpdateKeyForm failed cleaning as API id %s does not meet blue api key account requirement." % self.cleaned_data['api_id'])
                     raise forms.ValidationError(u'API not of type account')
 
             if not EveApiManager.check_blue_api_is_full(self.cleaned_data['api_id'],
                                                    self.cleaned_data['api_key']):
+                logger.debug("UpdateKeyForm failed cleaning as API id %s does not meet minimum blue api access mask requirement." % self.cleaned_data['api_id'])
                 raise forms.ValidationError(u'API supplied is too restricted. Minimum access mask is ' + str(settings.BLUE_API_MASK))
 
         else:
             if settings.MEMBER_API_ACCOUNT:
                 if not EveApiManager.check_api_is_type_account(self.cleaned_data['api_id'],
                                                            self.cleaned_data['api_key']):
+                    logger.debug("UpdateKeyForm failed cleaning as API id %s does not meet member api key account requirement." % self.cleaned_data['api_id'])
                     raise forms.ValidationError(u'API not of type account')
 
             if not EveApiManager.check_api_is_full(self.cleaned_data['api_id'],
                                                    self.cleaned_data['api_key']):
+                logger.debug("UpdateKeyForm failed cleaning as API id %s does not meet minimum member api access mask requirement." % self.cleaned_data['api_id'])
                 raise forms.ValidationError(u'API supplied is too restricted. Minimum access mask is ' + str(settings.MEMBER_API_MASK))
 
         return self.cleaned_data
diff --git a/eveonline/managers.py b/eveonline/managers.py
index b604b1c5..9b972c99 100644
--- a/eveonline/managers.py
+++ b/eveonline/managers.py
@@ -4,7 +4,9 @@ from models import EveAllianceInfo
 from models import EveCorporationInfo
 
 from services.managers.eve_api_manager import EveApiManager
+import logging
 
+logger = logging.getLogger(__name__)
 
 class EveManager:
     def __init__(self):
@@ -14,7 +16,7 @@ class EveManager:
     def create_character(character_id, character_name, corporation_id,
                          corporation_name, corporation_ticker, alliance_id,
                          alliance_name, user, api_id):
-
+        logger.debug("Creating model for character %s id %s" % (character_name, character_id))
         if not EveCharacter.objects.filter(character_id=character_id).exists():
             eve_char = EveCharacter()
             eve_char.character_id = character_id
@@ -27,10 +29,13 @@ class EveManager:
             eve_char.user = user
             eve_char.api_id = api_id
             eve_char.save()
+            logger.info("Created new character model %s for user" % (eve_char, user))
+        else:
+            logger.warn("Attempting to create existing character model with id %s" % character_id)
 
     @staticmethod
     def create_characters_from_list(chars, user, api_id):
-
+        logger.debug("Creating characters from batch: %s" % chars)
         for char in chars.result:
             if not EveManager.check_if_character_exist(chars.result[char]['name']):
                 EveManager.create_character(chars.result[char]['id'],
@@ -45,9 +50,11 @@ class EveManager:
 
     @staticmethod
     def update_characters_from_list(chars):
+        logger.debug("Updating characters from list: %s" % chars.result)
         for char in chars.result:
             if EveManager.check_if_character_exist(chars.result[char]['name']):
                 eve_char = EveManager.get_character_by_character_name(chars.result[char]['name'])
+                logger.debug("Got existing character model %s" % eve_char)
                 eve_char.corporation_id = chars.result[char]['corp']['id']
                 eve_char.corporation_name = chars.result[char]['corp']['name']
                 eve_char.corporation_ticker = EveApiManager.get_corporation_ticker_from_id(
@@ -55,20 +62,28 @@ class EveManager:
                 eve_char.alliance_id = chars.result[char]['alliance']['id']
                 eve_char.alliance_name = chars.result[char]['alliance']['name']
                 eve_char.save()
+                logger.info("Updated character model %s" % eve_char)
+            else:
+                logger.warn("Attempting to update non-existing character model with name %s" % char['name'])
 
 
     @staticmethod
     def create_api_keypair(api_id, api_key, user_id):
+        logger.debug("Creating api keypair id %s for user_id %s" % (api_id, user_id))
         if not EveApiKeyPair.objects.filter(api_id=api_id).exists():
             api_pair = EveApiKeyPair()
             api_pair.api_id = api_id
             api_pair.api_key = api_key
             api_pair.user = user_id
             api_pair.save()
+            logger.info("Created api keypair id %s for user %s" % (api_id, user_id))
+        else:
+            logger.warn("Attempting to create existing api keypair with id %s" % api_id)
 
     @staticmethod
     def create_alliance_info(alliance_id, alliance_name, alliance_ticker, alliance_executor_corp_id,
                              alliance_member_count, is_blue):
+        logger.debug("Creating alliance info for alliance %s id %s" % (alliance_name, alliance_id))
         if not EveManager.check_if_alliance_exists_by_id(alliance_id):
             alliance_info = EveAllianceInfo()
             alliance_info.alliance_id = alliance_id
@@ -78,18 +93,26 @@ class EveManager:
             alliance_info.member_count = alliance_member_count
             alliance_info.is_blue = is_blue
             alliance_info.save()
+            logger.info("Created alliance model for %s" % alliance_info)
+        else:
+            logger.warn("Attempting to create existing alliance model with id %s" % alliance_id)
 
     @staticmethod
     def update_alliance_info(alliance_id, alliance_executor_corp_id, alliance_member_count, is_blue):
+        logger.debug("Updating alliance model with id %s" % alliance_id)
         if EveManager.check_if_alliance_exists_by_id(alliance_id):
             alliance_info = EveAllianceInfo.objects.get(alliance_id=alliance_id)
             alliance_info.executor_corp_id = alliance_executor_corp_id
             alliance_info.member_count = alliance_member_count
             alliance_info.is_blue = is_blue
             alliance_info.save()
+            logger.info("Updated alliance model %s" % alliance_info)
+        else:
+            logger.warn("Attempting to update non-existing alliance model with id %s" % alliance_id)
 
     @staticmethod
     def create_corporation_info(corp_id, corp_name, corp_ticker, corp_member_count, is_blue, alliance):
+        logger.debug("Creating corp info for corp %s id %s" % (corp_name, corp_id))
         if not EveManager.check_if_corporation_exists_by_id(corp_id):
             corp_info = EveCorporationInfo()
             corp_info.corporation_id = corp_id
@@ -100,45 +123,67 @@ class EveManager:
             if alliance:
                 corp_info.alliance = alliance
             corp_info.save()
+            logger.info("Created corp model for %s" % corp)
+        else:
+            logger.warn("Attempting to create existing corp model with id %s" % corp_id)
 
     @staticmethod
     def update_corporation_info(corp_id, corp_member_count, alliance, is_blue):
+        logger.debug("Updating corp model with id %s" % corp_id)
         if EveManager.check_if_corporation_exists_by_id(corp_id):
             corp_info = EveCorporationInfo.objects.get(corporation_id=corp_id)
             corp_info.member_count = corp_member_count
             corp_info.alliance = alliance
             corp_info.is_blue = is_blue
             corp_info.save()
+            logger.info("Updated corp model %s" % corp_info)
+        else:
+            logger.warn("Attempting to update non-existant corp model with id %s" % corp_id)
 
     @staticmethod
     def get_api_key_pairs(user):
         if EveApiKeyPair.objects.filter(user=user).exists():
+            logger.debug("Returning api keypairs for user %s" % user)
             return EveApiKeyPair.objects.filter(user=user)
+        else:
+            logger.debug("No api keypairs found for user %s" % user)
 
     @staticmethod
     def check_if_api_key_pair_exist(api_id):
         if EveApiKeyPair.objects.filter(api_id=api_id).exists():
+            logger.debug("Determined api id %s exists." % api_id)
             return True
         else:
+            logger.debug("Determined api id %s does not exist." % api_id)
             return False
 
     @staticmethod
     def delete_api_key_pair(api_id, user_id):
+        logger.debug("Deleting api id %s" % api_id)
         if EveApiKeyPair.objects.filter(api_id=api_id).exists():
             # Check that its owned by our user_id
             apikeypair = EveApiKeyPair.objects.get(api_id=api_id)
             if apikeypair.user.id == user_id:
+                logger.info("Deleted user %s api key id %s" % (user_id, api_id))
                 apikeypair.delete()
+            else:
+                logger.error("Unable to delete api: user mismatch: key id %s not owned by %s" % (api_id, user_id))
+        else:
+            logger.warn("Unable to locate api id %s - cannot delete." % api_id)
 
     @staticmethod
     def delete_characters_by_api_id(api_id, user_id):
+        logger.debug("Deleting all characters associated with api id %s" % api_id)
         if EveCharacter.objects.filter(api_id=api_id).exists():
             # Check that its owned by our user_id
             characters = EveCharacter.objects.filter(api_id=api_id)
-
+            logger.debug("Got user %s characters %s from api %s" % (user_id, characters, api_id))
             for char in characters:
                 if char.user.id == user_id:
+                    logger.info("Deleting user %s character %s from api %s" % (user_id, char, api_id))
                     char.delete()
+                else:
+                    logger.error("Unable to delete character %s by api %s: user mismatch: character not owned by %s" % (char, api_id, user_id))
 
     @staticmethod
     def check_if_character_exist(char_name):
diff --git a/eveonline/views.py b/eveonline/views.py
index e6da28a0..725b2bc7 100755
--- a/eveonline/views.py
+++ b/eveonline/views.py
@@ -21,27 +21,34 @@ from eveonline.models import EveCharacter
 from eveonline.models import EveApiKeyPair
 from authentication.models import AuthServicesInfo
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 def disable_member(user, char_id):
+    logger.debug("Disabling user %s with character id %s" % (user, char_id))
     remove_member_permission(user, 'member')
     remove_user_from_group(user, settings.DEFAULT_AUTH_GROUP)
     remove_user_from_group(user,
                            generate_corp_group_name(
                                EveManager.get_character_by_id(char_id).corporation_name))
     deactivate_services(user)
+    logger.info("Disabled member %s" % user)
 
 
 def disable_blue_member(user):
+    logger.debug("Disabling blue user %s" % user)
     remove_member_permission(user, 'blue_member')
     remove_user_from_group(user, settings.DEFAULT_BLUE_GROUP)
     deactivate_services(user)
-
+    logger.info("Disabled blue user %s" % user)
 
 @login_required
 def add_api_key(request):
+    logger.debug("add_api_key called by user %s" % request.user)
     if request.method == 'POST':
         form = UpdateKeyForm(request.POST)
-
+        logger.debug("Request type POST with form valid: %s" % form.is_valid())
         if form.is_valid():
             EveManager.create_api_keypair(form.cleaned_data['api_id'],
                                           form.cleaned_data['api_key'],
@@ -51,8 +58,12 @@ def add_api_key(request):
             characters = EveApiManager.get_characters_from_api(form.cleaned_data['api_id'],
                                                                form.cleaned_data['api_key'])
             EveManager.create_characters_from_list(characters, request.user, form.cleaned_data['api_id'])
+            logger.info("Successfully processed api add form for user %s" % request.user)
             return HttpResponseRedirect("/api_key_management/")
+        else:
+            logger.debug("Form invalid: returning to form.")
     else:
+        logger.debug("Providing empty update key form for user %s" % request.user)
         form = UpdateKeyForm()
     context = {'form': form, 'apikeypairs': EveManager.get_api_key_pairs(request.user.id)}
     return render_to_response('registered/addapikey.html', context,
@@ -61,6 +72,7 @@ def add_api_key(request):
 
 @login_required
 def api_key_management_view(request):
+    logger.debug("api_key_management_view called by user %s" % request.user)
     context = {'apikeypairs': EveManager.get_api_key_pairs(request.user.id)}
 
     return render_to_response('registered/apikeymanagment.html', context,
@@ -69,6 +81,7 @@ def api_key_management_view(request):
 
 @login_required
 def api_key_removal(request, api_id):
+    logger.debug("api_key_removal called by user %s for api id %s" % (request.user, api_id))
     authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
     # Check if our users main id is in the to be deleted characters
     characters = EveManager.get_characters_by_owner_id(request.user.id)
@@ -76,20 +89,23 @@ def api_key_removal(request, api_id):
         for character in characters:
             if character.character_id == authinfo.main_char_id:
                 if character.api_id == api_id:
-                    # TODO: Remove servies also
+                    # TODO: Remove services also
                     if authinfo.is_blue:
+                        logger.debug("Blue user %s deleting api for main character. Disabling." % request.user)
                         disable_blue_member(request.user)
                     else:
+                        logger.debug("User %s deleting api for main character. Disabling." % request.user)
                         disable_member(request.user, authinfo.main_char_id)
 
     EveManager.delete_api_key_pair(api_id, request.user.id)
     EveManager.delete_characters_by_api_id(api_id, request.user.id)
-
+    logger.info("Succesfully processed api delete request by user %s for api %s" % (request.user, api_id))
     return HttpResponseRedirect("/api_key_management/")
 
 
 @login_required
 def characters_view(request):
+    logger.debug("characters_view called by user %s" % request.user)
     render_items = {'characters': EveManager.get_characters_by_owner_id(request.user.id),
                     'authinfo': AuthServicesInfoManager.get_auth_service_info(request.user)}
     return render_to_response('registered/characters.html', render_items, context_instance=RequestContext(request))
@@ -97,30 +113,34 @@ def characters_view(request):
 
 @login_required
 def main_character_change(request, char_id):
+    logger.debug("main_character_change called by user %s for character id %s" % (request.user, char_id))
     if EveManager.check_if_character_owned_by_user(char_id, request.user):
         previousmainid = AuthServicesInfoManager.get_auth_service_info(request.user).main_char_id
         AuthServicesInfoManager.update_main_char_Id(char_id, request.user)
         # Check if character is in the alliance
         character_info = EveManager.get_character_by_id(char_id)
         corporation_info = EveManager.get_corporation_info_by_id(character_info.corporation_id)
-
+        logger.debug("User %s changing main character to %s in corp %s" % (request.user, character_info, corporation_info))
         if (settings.IS_CORP and EveManager.get_charater_corporation_id_by_id(char_id) == settings.CORP_ID) or (not settings.IS_CORP and EveManager.get_charater_alliance_id_by_id(char_id) == settings.ALLIANCE_ID):
             add_member_permission(request.user, 'member')
             add_user_to_group(request.user, settings.DEFAULT_AUTH_GROUP)
             add_user_to_group(request.user,
                               generate_corp_group_name(EveManager.get_character_by_id(char_id).corporation_name))
+            logger.info("User %s transitioned to full member by chaning main character to %s" % (request.user, character_info))
 
         elif corporation_info != None:
             if corporation_info.is_blue:
                 add_member_permission(request.user, 'blue_member')
                 add_user_to_group(request.user, settings.DEFAULT_BLUE_GROUP)
                 AuthServicesInfoManager.update_is_blue(True, request.user)
+                logger.info("User %s transitioned to blue by changing main character to %s" % (request.user, character_info))
             else:
                 if check_if_user_has_permission(request.user, 'member'):
                     disable_member(request.user, previousmainid)
 
                 if check_if_user_has_permission(request.user, 'blue_member'):
                     disable_blue_member(request.user)
+                logger.info("User %s disabled as new main character %s not member nor blue." % (request.user, character_info))
         else:
             # TODO: disable serivces
             if check_if_user_has_permission(request.user, 'member'):
@@ -128,6 +148,7 @@ def main_character_change(request, char_id):
 
             if check_if_user_has_permission(request.user, 'blue_member'):
                 disable_blue_member(request.user)
+            logger.info("User %s disabled as new main character %s does not have corp model to check." % (request.user, character_indo))
 
         return HttpResponseRedirect("/characters")
     return HttpResponseRedirect("/characters")
@@ -136,14 +157,18 @@ def main_character_change(request, char_id):
 @login_required
 @permission_required('auth.corp_stats')
 def corp_stats_view(request):
+    logger.debug("corp_stats_view called by user %s" % request.user)
     # Get the corp the member is in
     auth_info = AuthServicesInfo.objects.get(user=request.user)
+    logger.debug("Got user %s authservicesinfo model %s" % (request.user, auth_info))
     if EveCharacter.objects.filter(character_id=auth_info.main_char_id).exists():
         main_char = EveCharacter.objects.get(character_id=auth_info.main_char_id)
+        logger.debug("Got user %s main character model %s" % (request.user, main_char))
         if EveCorporationInfo.objects.filter(corporation_id=main_char.corporation_id).exists():
             current_count = 0
             allcharacters = {}
             corp = EveCorporationInfo.objects.get(corporation_id=main_char.corporation_id)
+            logger.debug("Got user %s main character's corp model %s" % (request.user, corp))
             all_characters = EveCharacter.objects.all()
             for char in all_characters:
                 if char:
@@ -157,4 +182,8 @@ def corp_stats_view(request):
                        "currentCount": current_count,
                        "characters": allcharacters}
             return render_to_response('registered/corpstats.html', context, context_instance=RequestContext(request))
+        else:
+            logger.error("Unable to locate user %s main character's corp model with id %s. Cannot provide corp stats." % (request.user, main_char.corporation_id))
+    else:
+        logger.error("Unable to locate user %s main character model with id %s. Cannot provide corp stats." % (request.user, auth_info.main_char_id))
     return render_to_response('registered/corpstats.html', None, context_instance=RequestContext(request))
diff --git a/groupmanagement/views.py b/groupmanagement/views.py
index 44042e5f..f5a6d4ad 100755
--- a/groupmanagement/views.py
+++ b/groupmanagement/views.py
@@ -12,10 +12,14 @@ from models import HiddenGroup
 from authentication.managers import AuthServicesInfoManager
 from eveonline.managers import EveManager
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 @login_required
 @permission_required('auth.group_management')
 def group_management(request):
+    logger.debug("group_management called by user %s" % request.user)
     acceptrequests = []
     leaverequests = []
 
@@ -24,6 +28,7 @@ def group_management(request):
             leaverequests.append(grouprequest)
         else:
             acceptrequests.append(grouprequest)
+    logger.debug("Providing user %s with %s acceptrequests and %s leaverequests." % (request.user, len(acceptrequests), len(leaverequests)))
 
     render_items = {'acceptrequests': acceptrequests, 'leaverequests': leaverequests}
 
@@ -34,13 +39,16 @@ def group_management(request):
 @login_required
 @permission_required('auth.group_management')
 def group_accept_request(request, group_request_id):
+    logger.debug("group_accept_request called by user %s for grouprequest id %s" % (request.user, group_request_id))
     try:
         group_request = GroupRequest.objects.get(id=group_request_id)
         group, created = Group.objects.get_or_create(name=group_request.group.name)
         group_request.user.groups.add(group)
         group_request.user.save()
         group_request.delete()
+        logger.info("User %s accepted group request from user %s to group %s" % (request.user, group_request.user, group_request.group.name))
     except:
+        logger.exception("Unhandled exception occured while user %s attempting to accept grouprequest id %s." % (request.user, group_request_id), exc_info=True)
         pass
 
     return HttpResponseRedirect("/group/management/")
@@ -49,12 +57,15 @@ def group_accept_request(request, group_request_id):
 @login_required
 @permission_required('auth.group_management')
 def group_reject_request(request, group_request_id):
+    logger.debug("group_reject_request called by user %s for group request id %s" % (request.user, group_request_id))
     try:
         group_request = GroupRequest.objects.get(id=group_request_id)
 
         if group_request:
+            logger.info("User %s rejected group request from user %s for %s" % (request.user, group_request.user, group_request.group.name))
             group_request.delete()
     except:
+        logger.exception("Unhandled exception occured while user %s attempting to reject group request id %s." % (request.user, group_request_id), exc_info=True)
         pass
 
     return HttpResponseRedirect("/group/management/")
@@ -63,13 +74,16 @@ def group_reject_request(request, group_request_id):
 @login_required
 @permission_required('auth.group_management')
 def group_leave_accept_request(request, group_request_id):
+    logger.debug("group_leave_accept_request called by user %s for group request id %s" % (request.user, group_request_id))
     try:
         group_request = GroupRequest.objects.get(id=group_request_id)
         group, created = Group.objects.get_or_create(name=group_request.group.name)
         group_request.user.groups.remove(group)
         group_request.user.save()
         group_request.delete()
+        logger.info("User %s accepted group leave request from user %s to group %s" % (request.user, group_request.user, group_request.group.name))
     except:
+        logger.exception("Unhandled exception occured while user %s attempting to accept group leave request id %s." % (request.user, group_request_id), exc_info=True)
         pass
 
     return HttpResponseRedirect("/group/management/")
@@ -78,12 +92,15 @@ def group_leave_accept_request(request, group_request_id):
 @login_required
 @permission_required('auth.group_management')
 def group_leave_reject_request(request, group_request_id):
+    logger.debug("group_leave_reject_request called by user %s for group request id %s" % (request.user, group_request_id))
     try:
         group_request = GroupRequest.objects.get(id=group_request_id)
 
         if group_request:
             group_request.delete()
+            logger.info("User %s rejected group leave request from user %s for %s" % (request.user, group_request.user, group_request.group.name))
     except:
+        logger.exception("Unhandled exception occured while user %s attempting to reject group leave request id %s." % (request.user, group_request_id), exc_info=True)
         pass
 
     return HttpResponseRedirect("/group/management/")
@@ -91,6 +108,7 @@ def group_leave_reject_request(request, group_request_id):
 
 @login_required
 def groups_view(request):
+    logger.debug("groups_view called by user %s" % request.user)
     paired_list = []
 
     for group in Group.objects.all():
@@ -126,6 +144,7 @@ def groups_view(request):
 
 @login_required
 def group_request_add(request, group_id):
+    logger.debug("group_request_add called by user %s for group_id" % (request.user, group_id))
     auth_info = AuthServicesInfoManager.get_auth_service_info(request.user)
     grouprequest = GroupRequest()
     grouprequest.status = 'pending'
@@ -134,12 +153,14 @@ def group_request_add(request, group_id):
     grouprequest.main_char = EveManager.get_character_by_id(auth_info.main_char_id)
     grouprequest.leave_request = False
     grouprequest.save()
+    logger.info("Created group request for user %s to group %s" % (request.user, Group.objects.get(id=group_id)))
 
     return HttpResponseRedirect("/groups")
 
 
 @login_required
 def group_request_leave(request, group_id):
+    logger.debug("group_request_leave called by user %s for group id %s" % (request.user, group_id))
     auth_info = AuthServicesInfoManager.get_auth_service_info(request.user)
     grouprequest = GroupRequest()
     grouprequest.status = 'pending'
@@ -148,5 +169,6 @@ def group_request_leave(request, group_id):
     grouprequest.main_char = EveManager.get_character_by_id(auth_info.main_char_id)
     grouprequest.leave_request = True
     grouprequest.save()
+    logger.info("Created group leave request for user %s to group %s" % (request.user, Group.objects.get(id=group_id)))
 
     return HttpResponseRedirect("/groups")
diff --git a/hrapplications/views.py b/hrapplications/views.py
index 7345e7f9..3c559d72 100755
--- a/hrapplications/views.py
+++ b/hrapplications/views.py
@@ -16,13 +16,18 @@ from authentication.models import AuthServicesInfo
 from django.conf import settings
 from eveonline.managers import EveManager
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 @login_required
 def hr_application_management_view(request):
+	logger.debug("hr_application_management_view called by user %s" % request.user)
 	personal_app = None
 	corp_applications = None
 
 	if request.user.is_superuser:
+		logger.debug("User %s is superuser: returning all applications." % request.user)
 		corp_applications = HRApplication.objects.all()
 	else:
 		# Get the corp the member is in
@@ -41,6 +46,7 @@ def hr_application_management_view(request):
 				else:
 					corp_applications = None
 			except:
+				logger.error("Unable to determine user %s main character id %s corp. Returning no corp hrapplications." % (request.user, auth_info.main_char_id))
 				corp_applications = None
 	context = {'personal_apps': HRApplication.objects.all().filter(user=request.user),
 			   'applications': corp_applications,
@@ -52,10 +58,12 @@ def hr_application_management_view(request):
 
 @login_required
 def hr_application_create_view(request):
+	logger.debug("hr_application_create_view called by user %s" % request.user)
 	success = False
 
 	if request.method == 'POST':
 		form = HRApplicationForm(request.POST)
+		logger.debug("Request type POST with form valid: %s" % form.is_valid())
 		if form.is_valid():
 			application = HRApplication()
 			application.user = request.user
@@ -68,7 +76,9 @@ def hr_application_create_view(request):
 			application.extra = form.cleaned_data['extra']
 			application.save()
 			success = True
+			logger.info("Created HRApplication for user %s to corp %s" % (request.user, application.corp))
 	else:
+		logger.debug("Providing empty form.")
 		form = HRApplicationForm()
 
 	context = {'form': form, 'success': success}
@@ -78,11 +88,15 @@ def hr_application_create_view(request):
 
 @login_required
 def hr_application_personal_view(request, app_id):
+	logger.debug("hr_application_personal_view called by user %s for app id %s" % (request.user, app_id))
 	if HRApplication.objects.filter(id=app_id).exists():
 		application = HRApplication.objects.get(id=app_id)
+		logger.debug("Got application id %s: %s" % (app_id, application))
 		if application.user != request.user:
+			logger.warn("HRApplication id %s user %s does not match request user %s - returning blank application." % (app_id, application.user, request.user))
 			application = HRApplication()
 	else:
+		logger.warn("Unable to locate HRApplication matching id %s - returning blank application to user %s" % (app_id, request.user))
 		application = HRApplication()
 	context = {'application': application}
 
@@ -92,19 +106,24 @@ def hr_application_personal_view(request, app_id):
 
 @login_required
 def hr_application_personal_removal(request, app_id):
+	logger.debug("hr_application_personal_removal called by user %s for app id %s" % (request.user, app_id))
 	if HRApplication.objects.filter(id=app_id).exists():
 		application = HRApplication.objects.get(id=app_id)
 		if application.user == request.user:
 			application.delete()
-
+			logger.info("Deleted HRApplication with id %s for user %s to corp %s" % (app_id, request.user, application.corp))
+		else:
+			logger.warn("HRapplication id %s user %s does not match request user %s - refusing to delete." % (app_id, application.user, request.user))
 	return HttpResponseRedirect("/hr_application_management/")
 
 
 @login_required
 @permission_required('auth.human_resources')
 def hr_application_view(request, app_id):
+	logger.debug("hr_application_view called by user %s for app id %s" % (request.user, app_id))
 	if request.method == 'POST':
 		form = HRApplicationCommentForm(request.POST)
+		logger.debug("Request type POST contains form valid: %s" % form.is_valid())
 		if form.is_valid():
 			auth_info = AuthServicesInfo.objects.get(user=request.user)
 
@@ -114,16 +133,20 @@ def hr_application_view(request, app_id):
 			comment.commenter_character = EveCharacter.objects.get(character_id=auth_info.main_char_id)
 			comment.comment = form.cleaned_data['comment']
 			comment.save()
+			logger.info("Saved comment by user %s to hrapplication %s" % (request.user, comment.hrapplication))
 
 	else:
+		logger.debug("Returning blank HRApplication comment form.")
 		form = HRApplicationCommentForm()
 
 	if HRApplication.objects.filter(id=app_id).exists():
 		application = HRApplication.objects.get(id=app_id)
 		comments = HRApplicationComment.objects.all().filter(application=application)
+		logger.debug("Retrieved hrpplication id %s for user %s with comments %s" % (app_id, request.user, commends))
 	else:
 		application = HRApplication()
 		comments = []
+		logger.error("HRAppllication with id %s not found - returning blank applicatin to user %s" % request.user)
 
 	context = {'application': application, 'comments': comments, 'comment_form': form}
 
@@ -134,10 +157,16 @@ def hr_application_view(request, app_id):
 @login_required
 @permission_required('auth.human_resources')
 def hr_application_remove(request, app_id):
+	logger.debug("hr_application_remove called by user %s for app id %s" % (request.user, app_id))
 	if HRApplication.objects.filter(id=app_id).exists():
 		application = HRApplication.objects.get(id=app_id)
 		if application:
+			logger.info("Deleted HRApplication id %s on behalf of user %s" % (app_id, request.user))
 			application.delete()
+		else:
+                    logger.error("Unable to delete HRApplication with id %s for user %s: application is NoneType" % (app_id, request.user))
+	else:
+		logger.error("Unable to delete HRApplication with id %s for user %s: application not found." % (app_id, request.user))
 
 	return HttpResponseRedirect("/hr_application_management/")
 
@@ -145,6 +174,7 @@ def hr_application_remove(request, app_id):
 @login_required
 @permission_required('auth.human_resources')
 def hr_application_approve(request, app_id):
+	logger.debug("hr_application_approve called by user %s for app id %s" % (request.user, app_id))
 	if HRApplication.objects.filter(id=app_id).exists():
 		auth_info = AuthServicesInfo.objects.get(user=request.user)
 		application = HRApplication.objects.get(id=app_id)
@@ -152,6 +182,9 @@ def hr_application_approve(request, app_id):
 		application.reviewer_user = request.user
 		application.reviewer_character = EveCharacter.objects.get(character_id=auth_info.main_char_id)
 		application.save()
+		logger.info("HRApplication for user %s to corp %s approved by %s" % (application.user, application.corp, request.user))
+	else:
+		logger.error("User %s unable to approve HRApplication id %s - hrapplication with that id not found." % (request.user, app_id))
 
 	return HttpResponseRedirect("/hr_application_management/")
 
@@ -159,6 +192,7 @@ def hr_application_approve(request, app_id):
 @login_required
 @permission_required('auth.human_resources')
 def hr_application_reject(request, app_id):
+	logger.debug("hr_application_reject called by user %s for app id %s" % (request.user, app_id))
 	if HRApplication.objects.filter(id=app_id).exists():
 		auth_info = AuthServicesInfo.objects.get(user=request.user)
 		application = HRApplication.objects.get(id=app_id)
@@ -166,6 +200,9 @@ def hr_application_reject(request, app_id):
 		application.reviewer_user = request.user
 		application.reviewer_character = EveCharacter.objects.get(character_id=auth_info.main_char_id)
 		application.save()
+		logger.info("HRApplication for user %s to corp %s rejected by %s" % (application.user, application.corp, request.user))
+	else:
+		logger.error("User %s unable to reject HRApplication id %s - hrapplication with that id not found." % (request.user, app_id))
 
 	return HttpResponseRedirect("/hr_application_management/")
 
@@ -173,33 +210,42 @@ def hr_application_reject(request, app_id):
 @login_required
 @permission_required('auth.human_resources')
 def hr_application_search(request):
+	logger.debug("hr_application_search called by user %s" % request.user)
 	if request.method == 'POST':
 		form = HRApplicationSearchForm(request.POST)
+		logger.debug("Request type POST contains form valid: %s" % form.is_valid())
 		if form.is_valid():
 			# Really dumb search and only checks character name
 			# This can be improved but it does the job for now
 			searchstring = form.cleaned_data['search_string']
 			applications = []
+			logger.debug("Searching for application with character name %s for user %s" % (searchstring, request.user))
 
 			for application in HRApplication.objects.all():
 				if searchstring in application.character_name:
 					applications.append(application)
+			logger.info("Found %s HRApplications for user %s matching search string %s" % (len(applications), request.user, searchstring))
 
 			context = {'applications': applications, 'search_form': HRApplicationSearchForm()}
 
 			return render_to_response('registered/hrapplicationsearchview.html',
 									  context, context_instance=RequestContext(request))
 	else:
+		logger.debug("Returning empty search form for user %s" % request.user)
 		return HttpResponseRedirect("/hr_application_management/")
 
 
 @login_required
 @permission_required('auth.human_resources')
 def hr_application_mark_in_progress(request, app_id):
+	logger.debug("hr_application_mark_in_progress called by user %s for app id %s" % (request.user, app_id))
 	if HRApplication.objects.filter(id=app_id).exists():
 		auth_info = AuthServicesInfo.objects.get(user=request.user)
 		application = HRApplication.objects.get(id=app_id)
 		application.reviewer_inprogress_character = EveCharacter.objects.get(character_id=auth_info.main_char_id)
 		application.save()
+		logger.info("Marked HRApplication for user %s to corp %s in progress by user %s" % (application.user, application.corp, request.user))
+	else:
+		logger.error("Unable to mark HRApplication id %s in progress by user %s - hrapplication matching id not found." % (app_id, request.user))
 
 	return HttpResponseRedirect("/hr_application_view/" + str(app_id))
diff --git a/portal/views.py b/portal/views.py
index 7ee8e625..32ec7309 100755
--- a/portal/views.py
+++ b/portal/views.py
@@ -5,15 +5,20 @@ from django.contrib.auth.decorators import login_required
 from eveonline.managers import EveManager
 from authentication.managers import AuthServicesInfoManager
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 
 # Create your views here.
 def index_view(request):
+    logger.debug("index_view called by user %s" % request.user)
     return render_to_response('public/index.html', None, context_instance=RequestContext(request))
 
 
 @login_required
 def dashboard_view(request):
+    logger.debug("dashboard_view called by user %s" % request.user)
     render_items = {'characters': EveManager.get_characters_by_owner_id(request.user.id),
                     'authinfo': AuthServicesInfoManager.get_auth_service_info(request.user)}
     return render_to_response('registered/dashboard.html', render_items, context_instance=RequestContext(request))
@@ -21,4 +26,5 @@ def dashboard_view(request):
 
 @login_required
 def help_view(request):
+    logger.debug("help_view called by user %s" % request.user)
     return render_to_response('registered/help.html', None, context_instance=RequestContext(request))
diff --git a/registration/forms.py b/registration/forms.py
index da570c7c..34533811 100644
--- a/registration/forms.py
+++ b/registration/forms.py
@@ -2,6 +2,9 @@ from django import forms
 from django.contrib.auth.models import User
 import re
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 class RegistrationForm(forms.Form):
     username = forms.CharField(max_length=30, required=True)
@@ -12,24 +15,29 @@ class RegistrationForm(forms.Form):
 
     def clean(self):
         if ' ' in self.cleaned_data['username']:
+            logger.error("RegistrationForm username contains spaces. Raising ValidationError. Username: %s" % self.cleaned_data['username'])
             raise forms.ValidationError(u'Username cannot contain a space')
 
         # We attempt to get the user object if we succeed we know email as been used
         try:
             User.objects.get(email=self.cleaned_data['email'])
+            logger.error("RegistrationForm email already registered. Raising ValidationError")
             raise forms.ValidationError(u'Email as already been used')
         except:
             pass
 
         if not re.match("^\w+$", self.cleaned_data['username']):
+            logger.error("RegistrationForm username contains non-alphanumeric characters. Raising ValueError. Username: %s" % self.cleaned_data['username'])
             raise forms.ValidationError(u'Username contains illegal characters')
 
         if 'password' in self.cleaned_data and 'password_again' in self.cleaned_data:
             if self.cleaned_data['password'] != self.cleaned_data['password_again']:
+                logger.error("RegistrationForm password mismatch. Raising ValueError")
                 raise forms.ValidationError(u'Passwords do not match')
 
         if 'email' in self.cleaned_data and 'email_again' in self.cleaned_data:
             if self.cleaned_data['email'] != self.cleaned_data['email_again']:
+                logger.error("RegistrationForm email mismatch. Raising ValidationError")
                 raise forms.ValidationError(u'Emails do not match')
 
         return self.cleaned_data
diff --git a/registration/views.py b/registration/views.py
index 5ed7b0fb..929b988f 100644
--- a/registration/views.py
+++ b/registration/views.py
@@ -5,11 +5,15 @@ from django.template import RequestContext
 
 from forms import RegistrationForm
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 def register_user_view(request):
+    logger.debug("register_user_view called by user %s" % request.user)
     if request.method == 'POST':
         form = RegistrationForm(request.POST)
-
+        logger.debug("Request type POST contains form valid: %s" % form.is_valid())
         if form.is_valid():
 
             if not User.objects.filter(username=form.cleaned_data['username']).exists():
@@ -17,14 +21,19 @@ def register_user_view(request):
                                                 form.cleaned_data['email'], form.cleaned_data['password'])
 
                 user.save()
+                logger.info("Created new user %s" % user)
 
                 return HttpResponseRedirect("/dashboard")
 
             else:
+                logger.error("Unable to register new user: username %s already exists." % form.cleaned_data['username'])
                 return render_to_response('public/register.html', {'form': form, 'error': True}
                                           , context_instance=RequestContext(request))
+        else:
+            logger.debug("Registration form invalid. Returning for user %s to make corrections." % request.user)
 
     else:
+        logger.debug("Returning blank registration form.")
         form = RegistrationForm()
 
-    return render_to_response('public/register.html', {'form': form}, context_instance=RequestContext(request))
\ No newline at end of file
+    return render_to_response('public/register.html', {'form': form}, context_instance=RequestContext(request))
diff --git a/srp/views.py b/srp/views.py
index 2ae7061e..930820f0 100755
--- a/srp/views.py
+++ b/srp/views.py
@@ -16,6 +16,9 @@ from form import SrpFleetUserRequestForm
 from form import SrpFleetUpdateCostForm
 from form import SrpFleetMainUpdateForm
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 def srp_util_test(user):
     return check_if_user_has_permission(user, 'member') or check_if_user_has_permission(user, 'blue_member')
@@ -24,6 +27,7 @@ def srp_util_test(user):
 @login_required
 @user_passes_test(srp_util_test)
 def srp_management(request):
+    logger.debug("srp_management called by user %s" % request.user)
     totalcost = 0
     runningcost = 0
     price_pair = {}
@@ -32,7 +36,9 @@ def srp_management(request):
             totalcost = totalcost + fleet_data.srp_total_amount
             runningcost = runningcost + fleet_data.srp_total_amount
         price_pair[fleet_main.id] = runningcost
+        logger.debug("Determined SRP fleet %s costs %s" % (fleet_main.id, runningcost))
         runningcost = 0
+    logger.debug("Determined total outstanding SRP cost %s" % totalcost)
 
     context = {"srpfleets": SrpFleetMain.objects.filter(fleet_srp_status=""), "totalcost": totalcost,
                "price_pair": price_pair}
@@ -42,6 +48,7 @@ def srp_management(request):
 @login_required
 @user_passes_test(srp_util_test)
 def srp_management_all(request):
+    logger.debug("srp_management_all called by user %s" % request.user)
     totalcost = 0
     runningcost = 0
     price_pair = {}
@@ -50,7 +57,9 @@ def srp_management_all(request):
             totalcost = totalcost + fleet_data.srp_total_amount
             runningcost = runningcost + fleet_data.srp_total_amount
         price_pair[fleet_main.id] = runningcost
+        logger.debug("Determined SRP fleet %s costs %s" % (fleet_main.id, runningcost))
         runningcost = 0
+    logger.debug("Determined all-time total SRP cost %s" % totalcost)
 
     context = {"srpfleets": SrpFleetMain.objects.all(), "totalcost": totalcost, "price_pair": price_pair}
     return render_to_response('registered/srpmanagement.html', context, context_instance=RequestContext(request))
@@ -59,11 +68,13 @@ def srp_management_all(request):
 @login_required
 @user_passes_test(srp_util_test)
 def srp_fleet_view(request, fleet_id):
+    logger.debug("srp_fleet_view called by user %s for fleet id %s" % (request.user, fleet_id))
     if SrpFleetMain.objects.filter(id=fleet_id).exists():
         fleet_main = SrpFleetMain.objects.get(id=fleet_id)
         totalcost = 0
         for fleet_data in SrpUserRequest.objects.filter(srp_fleet_main=fleet_main):
             totalcost = totalcost + fleet_data.srp_total_amount
+        logger.debug("Determiend fleet id %s total cost %s" % (fleet_id, totalcost))
 
         context = {"fleet_id": fleet_id, "fleet_status": fleet_main.fleet_srp_status,
                    "srpfleetrequests": SrpUserRequest.objects.filter(srp_fleet_main=fleet_main),
@@ -72,18 +83,20 @@ def srp_fleet_view(request, fleet_id):
         return render_to_response('registered/srpfleetdata.html', context, context_instance=RequestContext(request))
 
     else:
+        logger.error("Unable to view SRP fleet id %s for user %s - fleet matching id not found." % (fleet_id, request.user))
         return HttpResponseRedirect("/srp")
 
 
 @login_required
 @permission_required('auth.srp_management')
 def srp_fleet_add_view(request):
+    logger.debug("srp_fleet_add_view called by user %s" % request.user)
     completed = False
     completed_srp_code = ""
 
     if request.method == 'POST':
         form = SrpFleetMainForm(request.POST)
-
+        logger.debug("Request type POST contains form valid: %s" % form.is_valid())
         if form.is_valid():
             authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
             character = EveManager.get_character_by_id(authinfo.main_char_id)
@@ -99,8 +112,10 @@ def srp_fleet_add_view(request):
 
             completed = True
             completed_srp_code = srp_fleet_main.fleet_srp_code
+            logger.info("Created SRP Fleet %s by user %s" % (srp_fleet_main.fleet_name, request.user))
 
     else:
+        logger.debug("Returning blank SrpFleetMainForm")
         form = SrpFleetMainForm()
 
     render_items = {'form': form, "completed": completed, "completed_srp_code": completed_srp_code}
@@ -111,47 +126,59 @@ def srp_fleet_add_view(request):
 @login_required
 @permission_required('auth.srp_management')
 def srp_fleet_remove(request, fleet_id):
+    logger.debug("srp_fleet_remove called by user %s for fleet id %s" % (request.user, fleet_id))
     if SrpFleetMain.objects.filter(id=fleet_id).exists():
         srpfleetmain = SrpFleetMain.objects.get(id=fleet_id)
         srpfleetmain.delete()
-
+        logger.info("SRP Fleet %s deleted by user %s" % (srpfleetmain.fleet_name, request.user))
+    else:
+        logger.error("Unable to delete SRP fleet id %s for user %s - fleet matching id not found." % (fleet_id, request.user))
     return HttpResponseRedirect("/srp")
 
 
 @login_required
 @permission_required('auth.srp_management')
 def srp_fleet_mark_completed(request, fleet_id):
+    logger.debug("srp_fleet_mark_completed called by user %s for fleet id %s" % (request.user, fleet_id))
     if SrpFleetMain.objects.filter(id=fleet_id).exists():
         srpfleetmain = SrpFleetMain.objects.get(id=fleet_id)
         srpfleetmain.fleet_srp_status = "Completed"
         srpfleetmain.save()
-
+        logger.info("Marked SRP Fleet %s as completed by user %s" % (srpfleetmain.fleet_name, request.user))
+    else:
+        logger.error("Unable to mark SRP fleet with id %s as completed for user %s - fleet matching id not found." % (fleet_id, request.user))
     return HttpResponseRedirect("/srp_fleet_view/" + str(fleet_id))
 
 
 @login_required
 @permission_required('auth.srp_management')
 def srp_fleet_mark_uncompleted(request, fleet_id):
+    logger.debug("srp_fleet_mark_uncompleted called by user %s for fleet id %s" % (request.user, fleet_id))
     if SrpFleetMain.objects.filter(id=fleet_id).exists():
         srpfleetmain = SrpFleetMain.objects.get(id=fleet_id)
         srpfleetmain.fleet_srp_status = ""
         srpfleetmain.save()
-
+        logger.info("Marked SRP Fleet %s as incomplete for user %s" % (fleet_id, request.user))
+    else:
+        logger.error("Unable to mark SRP Fleet id %s as incomplete for user %s - fleet matching id not found." % (fleet_id, request.user))
     return HttpResponseRedirect("/srp_fleet_view/" + str(fleet_id))
 
 
 @login_required
 @user_passes_test(srp_util_test)
 def srp_request_view(request, fleet_srp):
+    logger.debug("srp_request_view called by user %s for fleet srp code %s" % (request.user, fleet_srp))
     completed = False
     no_srp_code = False
     srp_code = ""
 
     if SrpFleetMain.objects.filter(fleet_srp_code=fleet_srp).exists() is False:
         no_srp_code = True
+        logger.error("Unable to locate SRP Fleet using code %s for user %s" % (fleet_srp, request.user))
 
     if request.method == 'POST':
         form = SrpFleetUserRequestForm(request.POST)
+        logger.debug("Request type POST contains form valid: %s" % form.is_valid())
 
         if form.is_valid():
             authinfo = AuthServicesInfoManager.get_auth_service_info(request.user)
@@ -166,8 +193,10 @@ def srp_request_view(request, fleet_srp):
             srp_request.save()
 
             completed = True
+            logger.info("Created SRP Request on behalf of user %s for fleet name %s" % (request.user, srp_fleet_main.fleet_name))
 
     else:
+        logger.debug("Returning blank SrpFleetUserRequestForm")
         form = SrpFleetUserRequestForm()
 
     render_items = {'form': form, "completed": completed, "no_srp_code": no_srp_code}
@@ -178,14 +207,17 @@ def srp_request_view(request, fleet_srp):
 @login_required
 @permission_required('auth.srp_management')
 def srp_request_remove(request, srp_request_id):
+    logger.debug("srp_request_remove called by user %s for srp request id %s" % (request.user, srp_request_id))
     stored_fleet_view = None
 
     if SrpUserRequest.objects.filter(id=srp_request_id).exists():
         srpuserrequest = SrpUserRequest.objects.get(id=srp_request_id)
         stored_fleet_view = srpuserrequest.srp_fleet_main.id
         srpuserrequest.delete()
+        logger.info("Deleted SRP request id %s for user %s" % (srp_request_id, request.user))
 
     if stored_fleet_view is None:
+        logger.error("Unable to delete srp request id %s for user %s - request matching id not found." % (srp_request_id, request.user))
         return HttpResponseRedirect("/srp")
     else:
         return HttpResponseRedirect("/srp_fleet_view/" + str(stored_fleet_view))
@@ -194,6 +226,7 @@ def srp_request_remove(request, srp_request_id):
 @login_required
 @permission_required('auth.srp_management')
 def srp_request_approve(request, srp_request_id):
+    logger.debug("srp_request_approve called by user %s for srp request id %s" % (request.user, srp_request_id))
     stored_fleet_view = None
 
     if SrpUserRequest.objects.filter(id=srp_request_id).exists():
@@ -201,8 +234,9 @@ def srp_request_approve(request, srp_request_id):
         stored_fleet_view = srpuserrequest.srp_fleet_main.id
         srpuserrequest.srp_status = "Approved"
         srpuserrequest.save()
-
+        logger.info("Approved SRP request id %s for character %s by user %s" % (srp_request_id, srpuserrequest.character, request.user))
     if stored_fleet_view is None:
+        logger.error("Unable to approve srp request id %s on behalf of user %s - request matching id not found." % (srp_request_id, request.user))
         return HttpResponseRedirect("/srp")
     else:
         return HttpResponseRedirect("/srp_fleet_view/" + str(stored_fleet_view))
@@ -211,6 +245,7 @@ def srp_request_approve(request, srp_request_id):
 @login_required
 @permission_required('auth.srp_management')
 def srp_request_reject(request, srp_request_id):
+    logger.debug("srp_request_reject called by user %s for srp request id %s" % (request.user, srp_request_id))
     stored_fleet_view = None
 
     if SrpUserRequest.objects.filter(id=srp_request_id).exists():
@@ -218,8 +253,10 @@ def srp_request_reject(request, srp_request_id):
         stored_fleet_view = srpuserrequest.srp_fleet_main.id
         srpuserrequest.srp_status = "Rejected"
         srpuserrequest.save()
+        logger.info("SRP request id %s for character %s rejected by %s" % (srp_request_id, srpuserrequest.character, request.user))
 
     if stored_fleet_view is None:
+        logger.error("Unable to reject SRP request id %s on behalf of user %s - request matching id not found." % (srp_request_id, request.user))
         return HttpResponseRedirect("/srp")
     else:
         return HttpResponseRedirect("/srp_fleet_view/" + str(stored_fleet_view))
@@ -228,22 +265,26 @@ def srp_request_reject(request, srp_request_id):
 @login_required
 @permission_required('auth.srp_management')
 def srp_request_update_amount_view(request, fleet_srp_request_id):
+    logger.debug("srp_request_update_amount_view called by user %s for fleet srp request id %s" % (request.user, fleet_srp_request_id))
     no_srp_code = False
     srp_code = ""
 
     if SrpUserRequest.objects.filter(id=fleet_srp_request_id).exists() is False:
+        logger.error("Unable to locate SRP request id %s for user %s" % (fleet_srp_request_id, request.user))
         no_srp_code = True
 
     if request.method == 'POST':
         form = SrpFleetUpdateCostForm(request.POST)
-
+        logger.debug("Request type POST contains form valid: %s" % form.is_valid())
         if form.is_valid():
             srp_request = SrpUserRequest.objects.get(id=fleet_srp_request_id)
             srp_request.srp_total_amount = form.cleaned_data['srp_total_amount']
             srp_request.save()
+            logger.info("Updated srp request id %s total to %s by user %s" % (fleet_srp_request_id, form.cleaned_data['srp_total_amount'], request.user))
 
             return HttpResponseRedirect("/srp_fleet_view/" + str(srp_request.srp_fleet_main.id))
     else:
+        logger.debug("Returning blank SrpFleetUpdateCostForm")
         form = SrpFleetUpdateCostForm()
 
     render_items = {'form': form, "no_srp_code": no_srp_code}
@@ -255,19 +296,24 @@ def srp_request_update_amount_view(request, fleet_srp_request_id):
 @login_required
 @permission_required('auth.srp_management')
 def srp_fleet_edit_view(request, fleet_id):
+    logger.debug("srp_fleet_edit_view called by user %s for fleet id %s" % (request.user, fleet_id))
     no_fleet_id = False
     form = None
     if SrpFleetMain.objects.filter(id=fleet_id).exists():
         if request.method == 'POST':
             form = SrpFleetMainUpdateForm(request.POST)
+            logger.debug("Request type POST contains form valid: %s" % form.is_valid())
             if form.is_valid():
                 srpfleetmain = SrpFleetMain.objects.get(id=fleet_id)
                 srpfleetmain.fleet_srp_aar_link = form.cleaned_data['fleet_aar_link']
                 srpfleetmain.save()
+                logger.info("User %s edited SRP Fleet %s" % (request.user, srpfleetmain.fleet_name))
                 return HttpResponseRedirect("/srp")
         else:
+            logger.debug("Returning blank SrpFleetMainUpdateForm")
             form = SrpFleetMainUpdateForm()
     else:
+        logger.error("Unable to edit srp fleet id %s for user %s - fleet matching id not found." % (fleet_id, request.user))
         no_fleet_id = True
 
     render_items = {'form': form, "no_fleet_id": no_fleet_id}
diff --git a/timerboard/views.py b/timerboard/views.py
index 51296cf4..1d9f0fbb 100755
--- a/timerboard/views.py
+++ b/timerboard/views.py
@@ -13,6 +13,9 @@ from eveonline.managers import EveManager
 from form import TimerForm
 from models import Timer
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 def timer_util_test(user):
     return check_if_user_has_permission(user, 'member') or check_if_user_has_permission(user, 'blue_member')
@@ -22,13 +25,14 @@ def timer_util_test(user):
 @user_passes_test(timer_util_test)
 @permission_required('auth.timer_view')
 def timer_view(request):
+    logger.debug("timer_view called by user %s" % request.user)
     timer_list = Timer.objects.all()
     closest_timer = None
     if timer_list:
         closest_timer = \
         sorted(list(Timer.objects.all()), key=lambda d: abs(datetime.datetime.now() - d.eve_time.replace(tzinfo=None)))[
             0]
-
+    logger.debug("Determined closest timer is %s" % closest_timer)
     render_items = {'timers': Timer.objects.all(),
                     'closest_timer': closest_timer}
 
@@ -38,20 +42,21 @@ def timer_view(request):
 @login_required
 @permission_required('auth.timer_management')
 def add_timer_view(request):
+    logger.debug("add_timer_view called by user %s" % request.user)
     if request.method == 'POST':
         form = TimerForm(request.POST)
-
+        logger.debug("Request type POST contains form valid: %s" % form.is_valid())
         if form.is_valid():
             # Get character
             auth_info = AuthServicesInfoManager.get_auth_service_info(request.user)
             character = EveManager.get_character_by_id(auth_info.main_char_id)
             corporation = EveManager.get_corporation_info_by_id(character.corporation_id)
-
+            logger.debug("Determined timer add request on behalf of character %s corporation %s" % (character, corporation))
             # calculate future time
             future_time = datetime.timedelta(days=form.cleaned_data['days_left'], hours=form.cleaned_data['hours_left'], minutes=form.cleaned_data['minutes_left'])
             current_time = datetime.datetime.utcnow()
             eve_time = current_time + future_time
-
+            logger.debug("Determined timer eve time is %s - current time %s, adding %s" % (eve_time, current_time, future_time))
             # handle valid form
             timer = Timer()
             timer.details = form.cleaned_data['details']
@@ -65,8 +70,10 @@ def add_timer_view(request):
             timer.eve_corp = corporation
             timer.user = request.user
             timer.save()
+            logger.info("Created new timer in %s at %s by user %s" % (timer.system, timer.eve_time, request.user))
             return HttpResponseRedirect("/timers/")
     else:
+        logger.debug("Returning new TimerForm")
         form = TimerForm()
 
     render_items = {'form': form}
@@ -77,7 +84,11 @@ def add_timer_view(request):
 @login_required
 @permission_required('auth.timer_management')
 def remove_timer(request, timer_id):
+    logger.debug("remove_timer called by user %s for timer id %s" % (request.user, timer_id))
     if Timer.objects.filter(id=timer_id).exists():
         timer = Timer.objects.get(id=timer_id)
         timer.delete()
+        logger.debug("Deleting timer id %s by user %s" % (timer_id, request.user))
+    else:
+        logger.error("Unable to delete timer id %s for user %s - timer matching id not found." % (timer_id, request.user))
     return HttpResponseRedirect("/timers/")
diff --git a/util/__init__.py b/util/__init__.py
index c3821670..f9205361 100755
--- a/util/__init__.py
+++ b/util/__init__.py
@@ -6,6 +6,9 @@ from django.contrib.auth.models import Group
 from django.contrib.auth.models import Permission
 from django.conf import settings
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 def bootstrap_permissions():
     ct = ContentType.objects.get_for_model(User)
@@ -20,18 +23,22 @@ def bootstrap_permissions():
     Permission.objects.get_or_create(codename="srp_management", content_type=ct, name="srp_management")
     Group.objects.get_or_create(name=settings.DEFAULT_AUTH_GROUP)
     Group.objects.get_or_create(name=settings.DEFAULT_BLUE_GROUP)
+    logger.info("Bootstrapped permissions for auth and created default groups.")
 
 
 def add_member_permission(user, permission):
+    logger.debug("Adding permission %s to member %s" % (permission, user))
     ct = ContentType.objects.get_for_model(User)
     stored_permission, created = Permission.objects.get_or_create(codename=permission,
                                                                   content_type=ct, name=permission)
     user = User.objects.get(username=user.username)
     user.user_permissions.add(stored_permission)
+    logger.info("Added permission %s to user %s" % (permission, user))
     user.save()
 
 
 def remove_member_permission(user, permission):
+    logger.debug("Removing permission %s from member %s" % (permission, user))
     ct = ContentType.objects.get_for_model(User)
     stored_permission, created = Permission.objects.get_or_create(codename=permission,
                                                                   content_type=ct, name=permission)
@@ -41,6 +48,9 @@ def remove_member_permission(user, permission):
     if user.has_perm('auth.' + permission):
         user.user_permissions.remove(stored_permission)
         user.save()
+        logger.info("Removed permission %s from member %s" % (permission, user))
+    else:
+        logger.warn("Attempting to remove permission user %s does not have: %s" % (user, permission))
 
 
 def check_if_user_has_permission(user, permission):
diff --git a/util/common_task.py b/util/common_task.py
index fe312f95..41002f08 100755
--- a/util/common_task.py
+++ b/util/common_task.py
@@ -9,40 +9,60 @@ from services.managers.ipboard_manager import IPBoardManager
 from services.managers.teamspeak3_manager import Teamspeak3Manager
 from services.managers.discord_manager import DiscordManager
 
+import logging
+
+logger = logging.getLogger(__name__)
 
 def add_user_to_group(user, groupname):
+    logger.debug("Addung user %s to group %s" % (user, groupname))
     user = User.objects.get(username=user.username)
     group, created = Group.objects.get_or_create(name=groupname)
+    if created:
+        logger.info("Created new group %s" % groupname)
     user.groups.add(group)
     user.save()
+    logger.info("Added user %s to group %s" % (user, group))
 
 
 def remove_user_from_group(user, groupname):
+    logger.debug("Removing user %s from group %s" % (user, groupname))
     user = User.objects.get(username=user.username)
     group, created = Group.objects.get_or_create(name=groupname)
+    if created:
+        logger.warn("Created new group %s during attempt to remove user %s from it. This shouldn't have happened." % (group, user))
     if user.groups.filter(name=groupname):
         user.groups.remove(group)
         user.save()
+        logger.info("Removed user %s from group %s" % (user, group))
+    else:
+        logger.warn("Unable to remove user %s from groyp %s - user not in group." % (user, group))
 
 
 def deactivate_services(user):
+    logger.debug("Deactivating services for user %s" % user)
     authinfo = AuthServicesInfoManager.get_auth_service_info(user)
     if authinfo.mumble_username and authinfo.mumble_username != "":
+        logger.debug("User %s has mumble account %s. Deleting." % (user, authinfo.mumble_username))
         MumbleManager.delete_user(authinfo.mumble_username)
         AuthServicesInfoManager.update_user_mumble_info("", "", user)
     if authinfo.jabber_username and authinfo.jabber_username != "":
+        logger.debug("User %s has jabber account %s. Deleting." % (user, authinfo.jabber_username))
         OpenfireManager.delete_user(authinfo.jabber_username)
         AuthServicesInfoManager.update_user_jabber_info("", "", user)
     if authinfo.forum_username and authinfo.forum_username != "":
+        logger.debug("User %s has forum account %s. Deleting." % (user, authinfo.forum_username))
         Phpbb3Manager.disable_user(authinfo.forum_username)
         AuthServicesInfoManager.update_user_forum_info("", "", user)
     if authinfo.ipboard_username and authinfo.ipboard_username != "":
+        logger.debug("User %s has ipboard account %s. Deleting." % (user, authinfo.ipboard_username))
         IPBoardManager.disable_user(authinfo.ipboard_username)
         AuthServicesInfoManager.update_user_forum_info("", "", user)
     if authinfo.teamspeak3_uid and authinfo.teamspeak3_uid != "":
+        logger.debug("User %s has mumble account %s. Deleting." % (user, authinfo.teamspeak3_uid))
         Teamspeak3Manager.delete_user(authinfo.teamspeak3_uid)
         AuthServicesInfoManager.update_user_teamspeak3_info("", "", user)
     if authinfo.discord_uid and authinfo.discord_uid != "":
+        logger.debug("User %s has discord account %s. Deleting." % (user, authinfo.discord_uid))
         DiscordManager.delete_user(authinfo.discord_uid)
         AuthServicesInfoManager.update_user_discord_info("", user)
 

From 017b6bc7ce6d908806ca82063bce7c83ac88ec99 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sat, 2 Jan 2016 21:43:51 +0000
Subject: [PATCH 14/27] Lowered log level of api results to declutter logs.

---
 services/managers/eve_api_manager.py | 24 ++++++++++++------------
 1 file changed, 12 insertions(+), 12 deletions(-)

diff --git a/services/managers/eve_api_manager.py b/services/managers/eve_api_manager.py
index b2891401..20bbd1b3 100644
--- a/services/managers/eve_api_manager.py
+++ b/services/managers/eve_api_manager.py
@@ -24,7 +24,7 @@ class EveApiManager():
         except evelink.api.APIError as error:
             logger.exception("Unhandled APIError occured.", exc_info=True)
 
-        logger.info("Retrieved characters %s from api id %s" % (chars, api_id))
+        logger.debug("Retrieved characters %s from api id %s" % (chars, api_id))
         return chars
 
     @staticmethod
@@ -40,7 +40,7 @@ class EveApiManager():
         except evelink.api.APIError as error:
             logger.exception("Unhandled APIError occured.", exc_info=True)
 
-        logger.info("Determined corp id %s ticker: %s" % (corp_id, ticker))
+        logger.debug("Determined corp id %s ticker: %s" % (corp_id, ticker))
         return ticker
 
     @staticmethod
@@ -169,7 +169,7 @@ class EveApiManager():
             corp = evelink.corp.Corp(api=api)
             corpinfo = corp.corporation_sheet(corp_id=int(corp_id))
             results = corpinfo[0]
-            logger.info("Confirmed id %s is a corp." % corp_id)
+            logger.debug("Confirmed id %s is a corp." % corp_id)
             return True
         except evelink.api.APIError as error:
             logger.exception("Unhandled APIError occured.", exc_info=True)
@@ -186,7 +186,7 @@ class EveApiManager():
                 corp = evelink.corp.Corp(api=api)
                 corpinfo = corp.contacts()
                 results = corpinfo[0]
-                logger.info("Got corp standings from settings: %s" % results)
+                logger.debug("Got corp standings from settings: %s" % results)
                 return results
             except evelink.api.APIError as error:
                 logger.exception("Unhandled APIError occured.", exc_info=True)
@@ -203,12 +203,12 @@ class EveApiManager():
             alliance = eve.alliances()
             results = alliance[0][int(alliance_id)]
             if results:
-                logger.info("Confirmed id %s is an alliance." % alliance_id)
+                logger.debug("Confirmed id %s is an alliance." % alliance_id)
                 return True
         except evelink.api.APIError as error:
             logger.exception("Unhandled APIError occured.", exc_info=True)
 
-        logger.info("Unable to verify id %s is an alliance." % alliance_id)
+        logger.debug("Unable to verify id %s is an alliance." % alliance_id)
         return False
 
     @staticmethod
@@ -219,12 +219,12 @@ class EveApiManager():
             eve = evelink.eve.EVE(api=api)
             results = eve.character_info_from_id(character_id)
             if results:
-                logger.info("Confirmed id %s is a character." % character_id)
+                logger.debug("Confirmed id %s is a character." % character_id)
                 return True
         except evelink.api.APIError as error:
             logger.exception("Unhandled APIError occured.", exc_info=True)
 
-        logger.info("Unable to verify id %s is a character." % character_id)
+        logger.debug("Unable to verify id %s is a character." % character_id)
         return False
 
     @staticmethod
@@ -235,10 +235,10 @@ class EveApiManager():
             eve = evelink.eve.EVE(api=api)
             alliances = eve.alliances()
             if int(alliance_id) in alliances[0]:
-                logger.info("Verified alliance id %s exists." % alliance_id)
+                logger.debug("Verified alliance id %s exists." % alliance_id)
                 return True
             else:
-                logger.info("Verified alliance id %s does not exist." % alliance_id)
+                logger.debug("Verified alliance id %s does not exist." % alliance_id)
                 return False
         except evelink.api.APIError as error:
             logger.exception("Unhandled APIError occured.", exc_info=True)
@@ -258,10 +258,10 @@ class EveApiManager():
             corp = evelink.corp.Corp(api=api)
             corpinfo = corp.corporation_sheet(corp_id=corp_id)
             if corpinfo[0]['members']['current'] > 0:
-                logger.info("Verified corp id %s exists with member count %s" % (corp_id, corpinfo[0]['members']['current']))
+                logger.debug("Verified corp id %s exists with member count %s" % (corp_id, corpinfo[0]['members']['current']))
                 return True
             else:
-                logger.info("Verified corp id %s has closed. Member count %s" % (corp_id, corpinfo[0]['members']['current']))
+                logger.debug("Verified corp id %s has closed. Member count %s" % (corp_id, corpinfo[0]['members']['current']))
                 return False
         except evelink.api.APIError as error:
             #could be smart and check for error code523 to verify error due to no corp instead of catch-all

From c0666298643389600c6b8669abc3c075cf2f6d78 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sat, 2 Jan 2016 22:15:38 +0000
Subject: [PATCH 15/27] Corrected logging errors.

---
 eveonline/managers.py    | 6 +++---
 eveonline/views.py       | 2 +-
 groupmanagement/views.py | 2 +-
 hrapplications/views.py  | 5 +++++
 services/views.py        | 2 +-
 5 files changed, 11 insertions(+), 6 deletions(-)

diff --git a/eveonline/managers.py b/eveonline/managers.py
index 9b972c99..2d873d93 100644
--- a/eveonline/managers.py
+++ b/eveonline/managers.py
@@ -29,13 +29,13 @@ class EveManager:
             eve_char.user = user
             eve_char.api_id = api_id
             eve_char.save()
-            logger.info("Created new character model %s for user" % (eve_char, user))
+            logger.info("Created new character model %s for user %s" % (eve_char, user))
         else:
             logger.warn("Attempting to create existing character model with id %s" % character_id)
 
     @staticmethod
     def create_characters_from_list(chars, user, api_id):
-        logger.debug("Creating characters from batch: %s" % chars)
+        logger.debug("Creating characters from batch: %s" % chars.result)
         for char in chars.result:
             if not EveManager.check_if_character_exist(chars.result[char]['name']):
                 EveManager.create_character(chars.result[char]['id'],
@@ -123,7 +123,7 @@ class EveManager:
             if alliance:
                 corp_info.alliance = alliance
             corp_info.save()
-            logger.info("Created corp model for %s" % corp)
+            logger.info("Created corp model for %s" % corp_info)
         else:
             logger.warn("Attempting to create existing corp model with id %s" % corp_id)
 
diff --git a/eveonline/views.py b/eveonline/views.py
index 725b2bc7..fc9ed613 100755
--- a/eveonline/views.py
+++ b/eveonline/views.py
@@ -148,7 +148,7 @@ def main_character_change(request, char_id):
 
             if check_if_user_has_permission(request.user, 'blue_member'):
                 disable_blue_member(request.user)
-            logger.info("User %s disabled as new main character %s does not have corp model to check." % (request.user, character_indo))
+            logger.info("User %s disabled as new main character %s does not have corp model to check." % (request.user, character_info))
 
         return HttpResponseRedirect("/characters")
     return HttpResponseRedirect("/characters")
diff --git a/groupmanagement/views.py b/groupmanagement/views.py
index f5a6d4ad..b466692d 100755
--- a/groupmanagement/views.py
+++ b/groupmanagement/views.py
@@ -144,7 +144,7 @@ def groups_view(request):
 
 @login_required
 def group_request_add(request, group_id):
-    logger.debug("group_request_add called by user %s for group_id" % (request.user, group_id))
+    logger.debug("group_request_add called by user %s for group id %s" % (request.user, group_id))
     auth_info = AuthServicesInfoManager.get_auth_service_info(request.user)
     grouprequest = GroupRequest()
     grouprequest.status = 'pending'
diff --git a/hrapplications/views.py b/hrapplications/views.py
index 3c559d72..de7e9c7c 100755
--- a/hrapplications/views.py
+++ b/hrapplications/views.py
@@ -230,6 +230,11 @@ def hr_application_search(request):
 
 			return render_to_response('registered/hrapplicationsearchview.html',
 									  context, context_instance=RequestContext(request))
+		else:
+			context = {'applications': None, 'search_form': form}
+			return render_to_response('registered/hrapplicationsearchview.html',
+                                                                          context, context_instance=RequestContext(request))
+	
 	else:
 		logger.debug("Returning empty search form for user %s" % request.user)
 		return HttpResponseRedirect("/hr_application_management/")
diff --git a/services/views.py b/services/views.py
index 595e76e0..c5d502e1 100755
--- a/services/views.py
+++ b/services/views.py
@@ -37,6 +37,7 @@ logger = logging.getLogger(__name__)
 @login_required
 def fleet_formatter_view(request):
     logger.debug("fleet_formatter_view called by user %s" % request.user)
+    generated = ""
     if request.method == 'POST':
         form = FleetFormatterForm(request.POST)
         logger.debug("Received POST request containing form, valid: %s" % form.is_valid())
@@ -56,7 +57,6 @@ def fleet_formatter_view(request):
             logger.info("Formatted fleet broadcast for user %s" % request.user)
     else:
         form = FleetFormatterForm()
-        generated = ""
         logger.debug("Returning empty form to user %s" % request.user)
 
     context = {'form': form, 'generated': generated}

From 5f70e68cc2d1eafe0c81e839a31b554030513da6 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sat, 2 Jan 2016 22:19:41 +0000
Subject: [PATCH 16/27] Typo.

---
 celerytask/tasks.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/celerytask/tasks.py b/celerytask/tasks.py
index 762aac53..271ecc9d 100755
--- a/celerytask/tasks.py
+++ b/celerytask/tasks.py
@@ -487,7 +487,7 @@ def run_corp_update():
         #refer to https://github.com/eve-val/evelink/blob/master/evelink/parsing/contact_list.py#L43
         standing_level = 'alliance'
         if settings.IS_CORP:
-            logger.debug("Switching statings check to corp level.")
+            logger.debug("Switching standings check to corp level.")
             standing_level = 'corp'
 
         # Create the corps in the standings

From 583be5a72e017e48db292c1543e945a722598e64 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sat, 2 Jan 2016 22:34:44 +0000
Subject: [PATCH 17/27] Changed to rotating log file handler. Added logging
 description in settings.py Updated .gitignore to ignore rotated log files.

Logging adapted from http://stackoverflow.com/questions/14354066/django-log-rotating-and-log-file-ownership
---
 .gitignore                        |  2 +-
 alliance_auth/settings.py.example | 49 ++++++++++++++++++++-----------
 2 files changed, 33 insertions(+), 18 deletions(-)

diff --git a/.gitignore b/.gitignore
index 111ee21b..9f48ec85 100644
--- a/.gitignore
+++ b/.gitignore
@@ -45,7 +45,7 @@ coverage.xml
 *.pot
 
 # Django stuff:
-*.log
+*.log*
 
 # Sphinx documentation
 docs/_build/
diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index e5235035..6e90eeb8 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -348,6 +348,19 @@ 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 Configuration
+#####################################
+# Set log_file and console level to desired state:
+# DEBUG - basically stack trace, explains every step
+# INFO - model creation, deletion, updates, etc
+# WARN - unexpected function outcomes that do not impact user
+# ERROR - unexcpeted function outcomes which prevent user from achieving desired outcome
+# EXCEPTION - something critical went wrong, unhandled
+#####################################
+# Recommended level for log_file is INFO, console is DEBUG
+# Change log level of individual apps below to narrow your debugging
+#####################################
 LOGGING = {
     'version': 1,
     'disable_existing_loggers': False,
@@ -361,61 +374,63 @@ LOGGING = {
         },
     },
     'handlers': {
-        'debug_file': {
-            'level': 'INFO',
-            'class': 'logging.FileHandler',
-            'filename': 'debug.log',
-            'formatter': 'verbose'
+        'log_file': {
+            'level': 'INFO',         # edit this line to change logging level to file
+            'class': 'logging.handlers.RotatingFileHandler',
+            'filename': os.path.join(BASE_DIR,'allianceauth.log'),
+            'formatter': 'verbose',
+            'maxBytes': 1024*1024*5, # edit this line to change max log file size
+            'backupCount': 5,        # edit this line to change number of log backups
         },
         'console': {
-            'level': 'DEBUG',
+            'level': 'DEBUG',        # edit this line to change logging level to console
             'class': 'logging.StreamHandler',
             'formatter': 'verbose',
         }
     },
     'loggers': {
         'authentication': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'celerytask': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'eveonline': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'groupmanagement': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'hrapplications': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'portal': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'registration': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'services': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'srp': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'timerboard': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
         'util': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
     }

From 6c3085f78c2eb2bb3891d070f33da816c01d677f Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sun, 3 Jan 2016 08:57:52 +0000
Subject: [PATCH 18/27] Added django core logging with default loglevel ERROR
 Corrected logic for logging message in authentication/managers.py

---
 alliance_auth/settings.py.example | 4 ++++
 authentication/managers.py        | 3 ++-
 2 files changed, 6 insertions(+), 1 deletion(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index 6e90eeb8..92f56728 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -433,6 +433,10 @@ LOGGING = {
             'handlers': ['log_file', 'console'],
             'level': 'DEBUG',
         },
+        'django': {
+            'handlers': ['debug_file', 'console'],
+            'level': 'ERROR',
+        },
     }
 }
 
diff --git a/authentication/managers.py b/authentication/managers.py
index dbccc4e4..c79a36cd 100755
--- a/authentication/managers.py
+++ b/authentication/managers.py
@@ -38,7 +38,8 @@ class AuthServicesInfoManager:
             authserviceinfo.main_char_id = char_id
             authserviceinfo.save(update_fields=['main_char_id'])
             logger.info("Updated user %s main character to id %s" % (user, char_id))
-        logger.error("Failed to update user %s main character id to %s: user does not exist." % (user, char_id))
+        else:
+            logger.error("Failed to update user %s main character id to %s: user does not exist." % (user, char_id))
 
     @staticmethod
     def update_user_forum_info(username, password, user):

From 08cd2c1f1ade6845f5710329b0beab47ab7df6aa Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sun, 3 Jan 2016 20:08:44 +0000
Subject: [PATCH 19/27] Corrections for typos in logging. Rephrased EveManager
 exceptions to reflect determination id is not of type rather than failure of
 function.

---
 eveonline/managers.py                   |  4 ++--
 groupmanagement/views.py                | 10 +++++-----
 hrapplications/views.py                 | 11 ++++++-----
 services/managers/discord_manager.py    |  5 +++--
 services/managers/eve_api_manager.py    | 18 +++++++++---------
 services/managers/ipboard_manager.py    | 10 +++++-----
 services/managers/openfire_manager.py   |  6 +++---
 services/managers/phpbb3_manager.py     | 20 ++++++++++++++------
 services/managers/teamspeak3_manager.py | 16 ++++++++--------
 util/common_task.py                     |  2 +-
 10 files changed, 56 insertions(+), 46 deletions(-)

diff --git a/eveonline/managers.py b/eveonline/managers.py
index 2d873d93..a471aa4d 100644
--- a/eveonline/managers.py
+++ b/eveonline/managers.py
@@ -167,7 +167,7 @@ class EveManager:
                 logger.info("Deleted user %s api key id %s" % (user_id, api_id))
                 apikeypair.delete()
             else:
-                logger.error("Unable to delete api: user mismatch: key id %s not owned by %s" % (api_id, user_id))
+                logger.error("Unable to delete api: user mismatch: key id %s owned by user id %s, not deleting user id %s" % (api_id, apikeypair.user.id, user_id))
         else:
             logger.warn("Unable to locate api id %s - cannot delete." % api_id)
 
@@ -183,7 +183,7 @@ class EveManager:
                     logger.info("Deleting user %s character %s from api %s" % (user_id, char, api_id))
                     char.delete()
                 else:
-                    logger.error("Unable to delete character %s by api %s: user mismatch: character not owned by %s" % (char, api_id, user_id))
+                    logger.error("Unable to delete character %s by api %s: user mismatch: character owned by user id%s, not deleting user id %s" % (char, api_id, char.user.id, user_id))
 
     @staticmethod
     def check_if_character_exist(char_name):
diff --git a/groupmanagement/views.py b/groupmanagement/views.py
index b466692d..c916a935 100755
--- a/groupmanagement/views.py
+++ b/groupmanagement/views.py
@@ -62,10 +62,10 @@ def group_reject_request(request, group_request_id):
         group_request = GroupRequest.objects.get(id=group_request_id)
 
         if group_request:
-            logger.info("User %s rejected group request from user %s for %s" % (request.user, group_request.user, group_request.group.name))
+            logger.info("User %s rejected group request from user %s to group %s" % (request.user, group_request.user, group_request.group.name))
             group_request.delete()
     except:
-        logger.exception("Unhandled exception occured while user %s attempting to reject group request id %s." % (request.user, group_request_id), exc_info=True)
+        logger.exception("Unhandled exception occured while user %s attempting to reject group request id %s" % (request.user, group_request_id), exc_info=True)
         pass
 
     return HttpResponseRedirect("/group/management/")
@@ -83,7 +83,7 @@ def group_leave_accept_request(request, group_request_id):
         group_request.delete()
         logger.info("User %s accepted group leave request from user %s to group %s" % (request.user, group_request.user, group_request.group.name))
     except:
-        logger.exception("Unhandled exception occured while user %s attempting to accept group leave request id %s." % (request.user, group_request_id), exc_info=True)
+        logger.exception("Unhandled exception occured while user %s attempting to accept group leave request id %s" % (request.user, group_request_id), exc_info=True)
         pass
 
     return HttpResponseRedirect("/group/management/")
@@ -98,9 +98,9 @@ def group_leave_reject_request(request, group_request_id):
 
         if group_request:
             group_request.delete()
-            logger.info("User %s rejected group leave request from user %s for %s" % (request.user, group_request.user, group_request.group.name))
+            logger.info("User %s rejected group leave request from user %s for group %s" % (request.user, group_request.user, group_request.group.name))
     except:
-        logger.exception("Unhandled exception occured while user %s attempting to reject group leave request id %s." % (request.user, group_request_id), exc_info=True)
+        logger.exception("Unhandled exception occured while user %s attempting to reject group leave request id %s" % (request.user, group_request_id), exc_info=True)
         pass
 
     return HttpResponseRedirect("/group/management/")
diff --git a/hrapplications/views.py b/hrapplications/views.py
index de7e9c7c..3948d0d0 100755
--- a/hrapplications/views.py
+++ b/hrapplications/views.py
@@ -96,7 +96,7 @@ def hr_application_personal_view(request, app_id):
 			logger.warn("HRApplication id %s user %s does not match request user %s - returning blank application." % (app_id, application.user, request.user))
 			application = HRApplication()
 	else:
-		logger.warn("Unable to locate HRApplication matching id %s - returning blank application to user %s" % (app_id, request.user))
+		logger.error("Unable to locate HRApplication matching id %s - returning blank application to user %s" % (app_id, request.user))
 		application = HRApplication()
 	context = {'application': application}
 
@@ -113,7 +113,7 @@ def hr_application_personal_removal(request, app_id):
 			application.delete()
 			logger.info("Deleted HRApplication with id %s for user %s to corp %s" % (app_id, request.user, application.corp))
 		else:
-			logger.warn("HRapplication id %s user %s does not match request user %s - refusing to delete." % (app_id, application.user, request.user))
+			logger.error("HRapplication id %s user %s does not match request user %s - refusing to delete." % (app_id, application.user, request.user))
 	return HttpResponseRedirect("/hr_application_management/")
 
 
@@ -142,7 +142,7 @@ def hr_application_view(request, app_id):
 	if HRApplication.objects.filter(id=app_id).exists():
 		application = HRApplication.objects.get(id=app_id)
 		comments = HRApplicationComment.objects.all().filter(application=application)
-		logger.debug("Retrieved hrpplication id %s for user %s with comments %s" % (app_id, request.user, commends))
+		logger.debug("Retrieved hrpplication id %s on behalf of user %s with comments %s" % (app_id, request.user, commends))
 	else:
 		application = HRApplication()
 		comments = []
@@ -164,9 +164,9 @@ def hr_application_remove(request, app_id):
 			logger.info("Deleted HRApplication id %s on behalf of user %s" % (app_id, request.user))
 			application.delete()
 		else:
-                    logger.error("Unable to delete HRApplication with id %s for user %s: application is NoneType" % (app_id, request.user))
+                    logger.error("Unable to delete HRApplication with id %s on behalf of user %s: application is NoneType" % (app_id, request.user))
 	else:
-		logger.error("Unable to delete HRApplication with id %s for user %s: application not found." % (app_id, request.user))
+		logger.error("Unable to delete HRApplication with id %s on behalf of user %s: application not found." % (app_id, request.user))
 
 	return HttpResponseRedirect("/hr_application_management/")
 
@@ -231,6 +231,7 @@ def hr_application_search(request):
 			return render_to_response('registered/hrapplicationsearchview.html',
 									  context, context_instance=RequestContext(request))
 		else:
+			logger.debug("Form invalid - returning for user %s to retry." % request.user)
 			context = {'applications': None, 'search_form': form}
 			return render_to_response('registered/hrapplicationsearchview.html',
                                                                           context, context_instance=RequestContext(request))
diff --git a/services/managers/discord_manager.py b/services/managers/discord_manager.py
index 03509c6c..64ceab86 100644
--- a/services/managers/discord_manager.py
+++ b/services/managers/discord_manager.py
@@ -26,10 +26,10 @@ class DiscordAPIManager:
         path = DISCORD_URL + "/users/@me"
         r = requests.get(path, headers=custom_headers)
         if r.status_code == 200:
-            logger.debug("Token starting with %s still valid." % token[0:5])
+            logger.debug("Token starting with %s passed validation." % token[0:5])
             return True
         else:
-            logger.debug("Token starting with %s vailed validation with status code %s" % (token[0:5], r.status_code))
+            logger.debug("Token starting with %s failed validation with status code %s" % (token[0:5], r.status_code))
             return False        
 
     @staticmethod
@@ -403,4 +403,5 @@ class DiscordManager:
             logger.info("Deleted user with id %s from discord server id %s" % (user_id, settings.DISCORD_SERVER_ID))
             return True
         except:
+            logger.exception("An unhandled exception has occured.", exc_info=True)
             return False
diff --git a/services/managers/eve_api_manager.py b/services/managers/eve_api_manager.py
index 20bbd1b3..8df6f6f7 100644
--- a/services/managers/eve_api_manager.py
+++ b/services/managers/eve_api_manager.py
@@ -94,7 +94,7 @@ class EveApiManager():
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
-            logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.MEMBER_API_MASK))
+            logger.debug("API has mask %s, required is %s" % (info[0]['access_mask'], settings.MEMBER_API_MASK))
             return info[0]['access_mask'] & int(settings.MEMBER_API_MASK) == int(settings.MEMBER_API_MASK)
 
         except evelink.api.APIError as error:
@@ -109,7 +109,7 @@ class EveApiManager():
             api = evelink.api.API(api_key=(api_id, api_key))
             account = evelink.account.Account(api=api)
             info = account.key_info()
-            logger.debug("API has mask %s, required is %s." % (info[0]['access_mask'], settings.BLUE_API_MASK))
+            logger.debug("API has mask %s, required is %s" % (info[0]['access_mask'], settings.BLUE_API_MASK))
             return info[0]['access_mask'] & int(settings.BLUE_API_MASK) == int(settings.BLUE_API_MASK)
  
         except evelink.api.APIError as error:
@@ -141,7 +141,7 @@ class EveApiManager():
             logger.info("Verified api id %s is still valid." % api_id)
             return True
         except evelink.api.APIError as error:
-            logger.exception("Unhandled APIError occured.", exc_info=True)
+            logger.exception("APIError occured while validating api id %s" % api_id, exc_info=True)
 
         logger.info("API id %s is invalid." % api_id)
         return False
@@ -156,7 +156,7 @@ class EveApiManager():
             logger.info("Verified API server is online and reachable.")
             return True
         except evelink.api.APIError as error:
-            logger.exception("Unhandled APIError occured.", exc_info=True)
+            logger.exception("APIError occured while trying to query api server. Possibly offline?", exc_info=True)
 
         logger.warn("Unable to reach API server.")
         return False
@@ -172,14 +172,14 @@ class EveApiManager():
             logger.debug("Confirmed id %s is a corp." % corp_id)
             return True
         except evelink.api.APIError as error:
-            logger.exception("Unhandled APIError occured.", exc_info=True)
+            logger.exception("APIError occured while checking if id %s is corp. Possibly not corp?" % corp_id, exc_info=True)
 
         logger.debug("Unable to verify id %s is corp." % corp_id)
         return False
 
     @staticmethod
     def get_corp_standings():
-        if settings.CORP_API_ID != "":
+        if settings.CORP_API_ID and settings.CORP_API_VCODE:
             try:
                 logger.debug("Getting corp standings with api id %s" % settings.CORP_API_ID)
                 api = evelink.api.API(api_key=(settings.CORP_API_ID, settings.CORP_API_VCODE))
@@ -206,9 +206,9 @@ class EveApiManager():
                 logger.debug("Confirmed id %s is an alliance." % alliance_id)
                 return True
         except evelink.api.APIError as error:
-            logger.exception("Unhandled APIError occured.", exc_info=True)
+            logger.exception("APIError occured while checking if id %s is an alliance. Possibly not alliance?" % alliance_id, exc_info=True)
 
-        logger.debug("Unable to verify id %s is an alliance." % alliance_id)
+        logger.debug("Unable to verify id %s is an an alliance." % alliance_id)
         return False
 
     @staticmethod
@@ -222,7 +222,7 @@ class EveApiManager():
                 logger.debug("Confirmed id %s is a character." % character_id)
                 return True
         except evelink.api.APIError as error:
-            logger.exception("Unhandled APIError occured.", exc_info=True)
+            logger.exception("APIError occured while checking if id %s is a character. Possibly not character?" % character_id, exc_info=True)
 
         logger.debug("Unable to verify id %s is a character." % character_id)
         return False
diff --git a/services/managers/ipboard_manager.py b/services/managers/ipboard_manager.py
index 496818de..16ea220a 100755
--- a/services/managers/ipboard_manager.py
+++ b/services/managers/ipboard_manager.py
@@ -79,7 +79,7 @@ class IPBoardManager:
         ret = IPBoardManager.exec_xmlrpc('getAllGroups')
         for group in ret:
             groups.append(group["g_title"])
-        logger.info("Retrieved group list from IPBoard: %s" % groups)
+        logger.debug("Retrieved group list from IPBoard: %s" % groups)
         return groups
 
     @staticmethod
@@ -89,25 +89,25 @@ class IPBoardManager:
         if type(ret) is list:
             for group in ret:
                 groups.append(group["g_title"])
-        logger.info("Got user %s IPBoard groups %s" % (username, groups))
+        logger.debug("Got user %s IPBoard groups %s" % (username, groups))
         return groups
 
     @staticmethod
     def add_group(group):
         ret = IPBoardManager.exec_xmlrpc('addGroup', group=group)
-        logger.info("Added IPBoard group %s, response %s" % (group, ret))
+        logger.info("Added IPBoard group %s" % group)
         return ret
 
     @staticmethod
     def add_user_to_group(username, group):
         ret = IPBoardManager.exec_xmlrpc('addUserToGroup', username=username, group=group)
-        logger.info("Added IPBoard user %s to group %s, response %s" % (username, group, ret))
+        logger.info("Added IPBoard user %s to group %s" % (username, group))
         return ret
 
     @staticmethod
     def remove_user_from_group(username, group):
         ret = IPBoardManager.exec_xmlrpc('removeUserFromGroup', username=username, group=group)
-        logger.info("Removed IPBoard user %s from group %s, reponse %s" % (username, group, ret))
+        logger.info("Removed IPBoard user %s from group %s" % (username, group))
         return ret
 
     @staticmethod
diff --git a/services/managers/openfire_manager.py b/services/managers/openfire_manager.py
index 73022d52..0e4fdd85 100755
--- a/services/managers/openfire_manager.py
+++ b/services/managers/openfire_manager.py
@@ -19,7 +19,7 @@ class OpenfireManager:
 
     @staticmethod
     def send_broadcast_threaded(group_name, broadcast_message):
-        logger.info("Starting broadcast to %s with message %s" % (group_name, broadcast_message))
+        logger.debug("Starting broadcast to %s with message %s" % (group_name, broadcast_message))
         broadcast_thread = XmppThread(1, "XMPP Broadcast Thread", 1, group_name, broadcast_message)
         broadcast_thread.start()
 
@@ -50,7 +50,7 @@ class OpenfireManager:
             logger.info("Added openfire user %s" % username)
         except exception.UserAlreadyExistsException:
             # User exist
-            logger.warn("Attempting to add a user %s to openfire which already exists on server." % username)
+            logger.error("Attempting to add a user %s to openfire which already exists on server." % username)
             return "", ""
 
         return sanatized_username, password
@@ -64,7 +64,7 @@ class OpenfireManager:
             logger.info("Deleted user %s from openfire." % username)
             return True
         except exception.UserNotFoundException:
-            logger.warn("Attempting to delete a user %s from openfire which was not found on server." % username)
+            logger.error("Attempting to delete a user %s from openfire which was not found on server." % username)
             return False
 
     @staticmethod
diff --git a/services/managers/phpbb3_manager.py b/services/managers/phpbb3_manager.py
index 89d36fb4..98939e6a 100755
--- a/services/managers/phpbb3_manager.py
+++ b/services/managers/phpbb3_manager.py
@@ -7,6 +7,8 @@ from django.db import connections
 
 import logging
 
+from django.conf import settings
+
 logger = logging.getLogger(__name__)
 
 class Phpbb3Manager:
@@ -64,6 +66,7 @@ class Phpbb3Manager:
 
     @staticmethod
     def __get_group_id(groupname):
+        logger.debug("Getting phpbb3 group id for groupname %s" % groupname)
         cursor = connections['phpbb3'].cursor()
         cursor.execute(Phpbb3Manager.SQL_GET_GROUP_ID, [groupname])
         row = cursor.fetchone()
@@ -72,6 +75,7 @@ class Phpbb3Manager:
 
     @staticmethod
     def __get_user_id(username):
+        logger.debug("Getting phpbb3 user id for username %s" % username)
         cursor = connections['phpbb3'].cursor()
         cursor.execute(Phpbb3Manager.SQL_USER_ID_FROM_USERNAME, [username])
         row = cursor.fetchone()
@@ -79,11 +83,12 @@ class Phpbb3Manager:
             logger.debug("Got phpbb user id %s for username %s" % (row[0], username))
             return row[0]
         else:
-            logger.warn("Username %s not found on phpbb. Unable to determine user id." % username)
+            logger.error("Username %s not found on phpbb. Unable to determine user id." % username)
             return None
 
     @staticmethod
     def __get_all_groups():
+        logger.debug("Getting all phpbb3 groups.")
         cursor = connections['phpbb3'].cursor()
         cursor.execute(Phpbb3Manager.SQL_GET_ALL_GROUPS)
         rows = cursor.fetchall()
@@ -95,6 +100,7 @@ class Phpbb3Manager:
 
     @staticmethod
     def __get_user_groups(userid):
+        logger.debug("Getting phpbb3 user id %s groups" % userid)
         cursor = connections['phpbb3'].cursor()
         cursor.execute(Phpbb3Manager.SQL_GET_USER_GROUPS, [userid])
         out = [row[0] for row in cursor.fetchall()]
@@ -109,6 +115,7 @@ class Phpbb3Manager:
 
     @staticmethod
     def __create_group(groupname):
+        logger.debug("Creating phpbb3 group %s" % groupname)
         cursor = connections['phpbb3'].cursor()
         cursor.execute(Phpbb3Manager.SQL_ADD_GROUP, [groupname, groupname])
         logger.info("Created phpbb group %s" % groupname)
@@ -116,6 +123,7 @@ class Phpbb3Manager:
 
     @staticmethod
     def __add_user_to_group(userid, groupid):
+        logger.debug("Adding phpbb3 user id %s to group id %s" % (userid, groupid))
         try:
             cursor = connections['phpbb3'].cursor()
             cursor.execute(Phpbb3Manager.SQL_ADD_USER_GROUP, [groupid, userid, 0])
@@ -126,6 +134,7 @@ class Phpbb3Manager:
 
     @staticmethod
     def __remove_user_from_group(userid, groupid):
+        logger.debug("Removing phpbb3 user id %s from group id %s" % (userid, groupid))
         cursor = connections['phpbb3'].cursor()
         try:
             cursor.execute(Phpbb3Manager.SQL_REMOVE_USER_GROUP, [userid, groupid])
@@ -155,9 +164,9 @@ class Phpbb3Manager:
                                                             "", ""])
                 Phpbb3Manager.update_groups(username_clean, groups)
                 Phpbb3Manager.__add_avatar(username_clean, characterid)
-                logger.info("Added phpbb user %s" % username)
+                logger.info("Added phpbb user %s" % username_clean)
             except:
-                logger.exception("Unable to add phpbb user %s" % username, exc_info=True)
+                logger.exception("Unable to add phpbb user %s" % username_clean, exc_info=True)
                 pass
 
         return username_clean, password
@@ -168,7 +177,7 @@ class Phpbb3Manager:
         cursor = connections['phpbb3'].cursor()
 
         password = Phpbb3Manager.__gen_hash(Phpbb3Manager.__generate_random_pass())
-        revoke_email = "revoked@the99eve.com"
+        revoke_email = "revoked@" + settings.DOMAIN
         try:
             pwhash = Phpbb3Manager.__gen_hash(password)
             cursor.execute(Phpbb3Manager.SQL_DIS_USER, [revoke_email, pwhash, username])
@@ -187,7 +196,7 @@ class Phpbb3Manager:
             cursor.execute(Phpbb3Manager.SQL_DEL_USER, [username])
             logger.info("Deleted phpbb user %s" % username)
             return True
-        logger.warn("Unable to delete phpbb user %s - user not found on phpbb." % username)
+        logger.error("Unable to delete phpbb user %s - user not found on phpbb." % username)
         return False
 
     @staticmethod
@@ -230,7 +239,6 @@ class Phpbb3Manager:
     def check_user(username):
         logger.debug("Checking phpbb username %s" % username)
         cursor = connections['phpbb3'].cursor()
-        """ Check if the username exists """
         cursor.execute(Phpbb3Manager.SQL_USER_ID_FROM_USERNAME, [Phpbb3Manager.__santatize_username(username)])
         row = cursor.fetchone()
         if row:
diff --git a/services/managers/teamspeak3_manager.py b/services/managers/teamspeak3_manager.py
index c1818cee..76532fba 100755
--- a/services/managers/teamspeak3_manager.py
+++ b/services/managers/teamspeak3_manager.py
@@ -74,7 +74,7 @@ class Teamspeak3Manager:
             server.send_command('servergroupaddperm',
                                 {'sgid': sgid, 'permsid': 'i_group_needed_member_remove_power', 'permvalue': 100,
                                  'permnegated': 0, 'permskip': 0})
-        logger.info("Created group on TS3 server with name %s and id %s" % (groupname, sqid))
+        logger.info("Created group on TS3 server with name %s and id %s" % (groupname, sgid))
         return sgid
 
     @staticmethod
@@ -109,7 +109,7 @@ class Teamspeak3Manager:
                 logger.debug("Assigning name/id dict: %s = %s" % (group['keys']['name'], group['keys']['sgid']))
                 outlist[group['keys']['name']] = group['keys']['sgid']
         else:
-            logger.error("Received empty group cache while retrieving group cache from TS3 server. 1024 error.", exc_info=True)
+            logger.error("Received empty group cache while retrieving group cache from TS3 server. 1024 error.")
         logger.debug("Returning name/id pairing: %s" % outlist)
         return outlist
 
@@ -162,7 +162,7 @@ class Teamspeak3Manager:
                     logger.debug("Local group does not exist for TS group %s. Creating TSgroup model %s" % (remote_groups[key], g))
                     g.save()
         except:
-            logger.debug("An unhandled exception has occured while syncinc TS groups.", exc_info=True)
+            logger.exception("An unhandled exception has occured while syncing TS groups.", exc_info=True)
             pass
 
     @staticmethod
@@ -189,7 +189,7 @@ class Teamspeak3Manager:
                     token = ret['keys']['token']
         except:
             pass
-        logger.info("Created user %s on TS3 server, got token %s" % (username_clean, token))
+        logger.info("Created permission token for user %s on TS3 server" % username_clean)
 
         return username_clean, token
 
@@ -217,7 +217,7 @@ class Teamspeak3Manager:
 
         except:
             pass
-        logger.info("Created blue user %s on TS3 server, got token %s" % (username_clean, token))
+        logger.info("Created permission token for blue user %s on TS3 server" % username_clean)
 
         return username_clean, token
 
@@ -250,7 +250,7 @@ class Teamspeak3Manager:
 
     @staticmethod
     def generate_new_permissionkey(uid, username, corpticker):
-        logger.debug("Re-issuing permission key for user id %s." % uid)
+        logger.debug("Re-issuing permission key for user id %s" % uid)
         Teamspeak3Manager.delete_user(uid)
         return Teamspeak3Manager.add_user(username, corpticker)
 
@@ -262,7 +262,7 @@ class Teamspeak3Manager:
 
     @staticmethod
     def update_groups(uid, ts_groups):
-        logger.debug("Updating uid %s groups %s" % (uid, ts_groups))
+        logger.debug("Updating uid %s TS3 groups %s" % (uid, ts_groups))
         userid = Teamspeak3Manager._get_userid(uid)
         addgroups = []
         remgroups = []
@@ -279,7 +279,7 @@ class Teamspeak3Manager:
                 if user_ts_groups[user_ts_group_key] not in ts_groups.values():
                     remgroups.append(user_ts_groups[user_ts_group_key])
 
-            logger.info("Finished checking user id %s groups. Adding %s, removing %s." % (userid, addgroups, remgroups))
+            logger.info("Finished checking user id %s TS3 groups - adding %s, removing %s." % (userid, addgroups, remgroups))
 
             for g in addgroups:
                 logger.debug("Issuing add command for group %s" % g)
diff --git a/util/common_task.py b/util/common_task.py
index 41002f08..c29f5aee 100755
--- a/util/common_task.py
+++ b/util/common_task.py
@@ -35,7 +35,7 @@ def remove_user_from_group(user, groupname):
         user.save()
         logger.info("Removed user %s from group %s" % (user, group))
     else:
-        logger.warn("Unable to remove user %s from groyp %s - user not in group." % (user, group))
+        logger.warn("Unable to remove user %s from group %s - user not in group." % (user, group))
 
 
 def deactivate_services(user):

From 019cf891b089ac78383184d270e0b6894cb7df43 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sun, 3 Jan 2016 21:19:43 +0000
Subject: [PATCH 20/27] corrected django logging handler to reference log_file

---
 alliance_auth/settings.py.example | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index 92f56728..3d77e872 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -434,7 +434,7 @@ LOGGING = {
             'level': 'DEBUG',
         },
         'django': {
-            'handlers': ['debug_file', 'console'],
+            'handlers': ['log_file', 'console'],
             'level': 'ERROR',
         },
     }

From b5b13e828a327f94966e27f7529c9b53916ca5aa Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Sun, 3 Jan 2016 21:41:25 +0000
Subject: [PATCH 21/27] Registered DiscordAuthToken to admin site.

---
 services/admin.py | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/services/admin.py b/services/admin.py
index 2026832a..ed775610 100644
--- a/services/admin.py
+++ b/services/admin.py
@@ -2,6 +2,7 @@ from django.contrib import admin
 from .models import AuthTS
 from .models import TSgroup
 from .models import UserTSgroup
+from .models import DiscordAuthToken
 
 class AuthTSgroupAdmin(admin.ModelAdmin):
 	fields = ['auth_group','ts_group']
@@ -15,4 +16,6 @@ class UserTSgroupAdmin(admin.ModelAdmin):
 	filter_horizontal = ('ts_group',)
 
 admin.site.register(AuthTS, AuthTSgroupAdmin)
-admin.site.register(TSgroup, TSgroupAdmin)
\ No newline at end of file
+admin.site.register(TSgroup, TSgroupAdmin)
+
+admin.site.register(DiscordAuthToken)

From 2c6ca5f273791e292ddf36a298745b84845b7020 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 5 Jan 2016 22:53:52 +0000
Subject: [PATCH 22/27] Assign user to discordauthtoken for security  -
 prevents exploit of another user entering incorrect password for email yet
 passing validation using existing token mentioned in #146  - does not protect
 against same user entering wrong password (I can live with this.) Periodic
 task to remove invalid token every 2 hours

---
 celerytask/tasks.py                  | 14 ++++++++-
 services/managers/discord_manager.py | 47 +++++++++++++++++-----------
 services/models.py                   |  8 +++--
 services/views.py                    |  2 +-
 4 files changed, 47 insertions(+), 24 deletions(-)

diff --git a/celerytask/tasks.py b/celerytask/tasks.py
index 271ecc9d..f1c26465 100755
--- a/celerytask/tasks.py
+++ b/celerytask/tasks.py
@@ -9,7 +9,7 @@ from services.managers.mumble_manager import MumbleManager
 from services.managers.phpbb3_manager import Phpbb3Manager
 from services.managers.ipboard_manager import IPBoardManager
 from services.managers.teamspeak3_manager import Teamspeak3Manager
-from services.managers.discord_manager import DiscordManager
+from services.managers.discord_manager import DiscordManager, DiscordAPIManager
 from services.models import AuthTS
 from services.models import TSgroup
 from authentication.models import AuthServicesInfo
@@ -25,6 +25,7 @@ from util.common_task import generate_corp_group_name
 from eveonline.models import EveCharacter
 from eveonline.models import EveCorporationInfo
 from authentication.managers import AuthServicesInfoManager
+from services.models import DiscordAuthToken
 
 import logging
 
@@ -277,6 +278,17 @@ def run_databaseUpdate():
         add_to_databases(user, groups, syncgroups)
         remove_from_databases(user, groups, syncgroups)
 
+# Run every 2 hours
+@periodic_task(run_every=crontab(minute="0", hour="*/2"))
+def run_discord_token_cleanup():
+    logger.debug("Running validation of all DiscordAuthTokens")
+    for auth in DiscordAuthToken.objects.all():
+        logger.debug("Testing DiscordAuthToken %s" % auth)
+        if DiscordAPIManager.validate_token(auth.token):
+            logger.debug("Token passes validation. Retaining %s" % auth)
+        else:
+            logger.debug("DiscordAuthToken failed validation. Deleting %s" % auth)
+            auth.delete()
 
 # Run every 3 hours
 @periodic_task(run_every=crontab(minute=0, hour="*/3"))
diff --git a/services/managers/discord_manager.py b/services/managers/discord_manager.py
index 64ceab86..f1310b64 100644
--- a/services/managers/discord_manager.py
+++ b/services/managers/discord_manager.py
@@ -13,8 +13,8 @@ DISCORD_URL = "https://discordapp.com/api"
 
 class DiscordAPIManager:
 
-    def __init__(self, server_id, email, password):
-        self.token = DiscordAPIManager.get_token_by_user(email, password)
+    def __init__(self, server_id, email, password, user=None):
+        self.token = DiscordAPIManager.get_token_by_user(email, password, user)
         self.email = email
         self.password = password
         self.server_id = server_id
@@ -131,9 +131,8 @@ class DiscordAPIManager:
         r.raise_for_status()
         return r.json()
 
-    @staticmethod
-    def accept_invite(invite_id, token):
-        custom_headers = {'accept': 'application/json', 'authorization': token}
+    def accept_invite(self, invite_id):
+        custom_headers = {'accept': 'application/json', 'authorization': self.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)
@@ -223,17 +222,20 @@ class DiscordAPIManager:
         raise KeyError('Group not found on server: ' + group_name)
 
     @staticmethod
-    def get_token_by_user(email, password):
+    def get_token_by_user(email, password, user):
         if DiscordAuthToken.objects.filter(email=email).exists():
-            logger.debug("Discord auth token cached for supplied email starting with %s" % email[0:3])
             auth = DiscordAuthToken.objects.get(email=email)
+            if not auth.user == user:
+                raise ValueError("User mismatch while validating DiscordAuthToken for email %s - user %s, requesting user %s" % (email, auth.user, user))                
+            logger.debug("Discord auth token cached for supplied email starting with %s" % email[0:3])
+            auth = DiscordAuthToken.objects.get(email=email, user=user)
             if DiscordAPIManager.validate_token(auth.token):
                 logger.debug("Token still valid. Returning token starting with %s" % auth.token[0:5])
                 return auth.token
             else:
                 logger.debug("Token has expired. Deleting.")
                 auth.delete()
-        logger.debug("Generating auth token for email starting with %s and password of length %s" % (email[0:3], len(password)))
+        logger.debug("Generating auth token for email starting with %s user %s and password of length %s" % (email[0:3], user, len(password)))
         data = {
             "email" : email,
             "password": password,
@@ -244,11 +246,19 @@ class DiscordAPIManager:
         logger.debug("Received status code %s after generating auth token for custom user." % r.status_code)
         r.raise_for_status()
         token = r.json()['token']
-        auth = DiscordAuthToken(email=email, token=token)
+        auth = DiscordAuthToken(email=email, token=token, user=user)
         auth.save()
         logger.debug("Created cached token for email starting with %s" % email[0:3])
         return token
 
+    def get_profile(self):
+        custom_headers = {'accept': 'application/json', 'authorization': self.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, self.email[0:3]))
+        r.raise_for_status()
+        return r.json()
+
     @staticmethod
     def get_user_profile(email, password):
         token = DiscordAPIManager.get_token_by_user(email, password)
@@ -371,22 +381,21 @@ class DiscordManager:
             return current_password
 
     @staticmethod
-    def add_user(email, password):
+    def add_user(email, password, user):
         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("Adding new user %s to discord with email %s and password of length %s" % (user, email[0:3], len(password)))
+            server_api = DiscordAPIManager(settings.DISCORD_SERVER_ID, settings.DISCORD_USER_EMAIL, settings.DISCORD_USER_PASSWORD)
+            user_api = DiscordAPIManager(settings.DISCORD_SERVER_ID, email, password, user=user)
+            profile = user_api.get_profile()
             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):
+            if server_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']
+                server_api.unban_user(user_id)
+            invite_code = server_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)
+            user_api.accept_invite(invite_code)
             logger.info("Added user to discord server %s with id %s" % (settings.DISCORD_SERVER_ID, user_id))
             return user_id
         except:
diff --git a/services/models.py b/services/models.py
index 396036f0..2cc7f017 100644
--- a/services/models.py
+++ b/services/models.py
@@ -1,5 +1,5 @@
 from django.db import models
-from django.contrib.auth.models import Group
+from django.contrib.auth.models import Group, User
 
 class TSgroup(models.Model):
     ts_group_id = models.IntegerField(primary_key=True)
@@ -32,7 +32,9 @@ class UserTSgroup(models.Model):
         return self.user.name
 
 class DiscordAuthToken(models.Model):
-    email = models.CharField(max_length=254, primary_key=True)
+    email = models.CharField(max_length=254, unique=True)
     token = models.CharField(max_length=254)
+    user = models.ForeignKey(User, on_delete=models.CASCADE, null=True)
     def __str__(self):
-        return self.email
+        output = "Discord Token for email %s user %s" % (self.email, self.user)
+        return output.encode('utf-8')
diff --git a/services/views.py b/services/views.py
index c5d502e1..1c0e4b06 100755
--- a/services/views.py
+++ b/services/views.py
@@ -436,7 +436,7 @@ def activate_discord(request):
             password = form.cleaned_data['password']
             logger.debug("Form contains password of length %s" % len(password))
             try:
-                user_id = DiscordManager.add_user(email, password)
+                user_id = DiscordManager.add_user(email, password, request.user)
                 logger.debug("Received discord uid %s" % user_id)
                 if user_id != "":
                     AuthServicesInfoManager.update_user_discord_info(user_id, request.user)

From b31dcb7ac0c78b143a8245b4fee2793e0e9b37c8 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 5 Jan 2016 23:36:17 +0000
Subject: [PATCH 23/27] Permission 'jabber_broadcast_all' to restrict groups  -
 without, can only broadcast to own groups  - with, can broadcast to all and
 every group Updated form to check request user for permission and groups when
 generating form For #159

---
 services/forms.py | 17 ++++++++++++-----
 services/views.py |  5 +++--
 util/__init__.py  |  1 +
 3 files changed, 16 insertions(+), 7 deletions(-)

diff --git a/services/forms.py b/services/forms.py
index 0696c939..65277517 100644
--- a/services/forms.py
+++ b/services/forms.py
@@ -1,13 +1,20 @@
 from django import forms
 from django.contrib.auth.models import Group
+from util import check_if_user_has_permission
 
 
 class JabberBroadcastForm(forms.Form):
-    allchoices = []
-    allchoices.append(('all', 'all'))
-    for group in Group.objects.all():
-        allchoices.append((str(group.name), str(group.name)))
-    group = forms.ChoiceField(choices=allchoices, widget=forms.Select)
+    def __init__(self, user, *args, **kwargs):
+        super(JabberBroadcastForm, self).__init__(*args, **kwargs)
+        allchoices = []
+        if check_if_user_has_permission(user, 'jabber_broadcast_all'):
+            allchoices.append(('all', 'all'))
+            for g in Group.objects.all():
+                allchoices.append((str(g.name), str(g.name)))
+        else:
+            for g in user.groups.all():
+                allchoices.append((str(g.name), str(g.name)))
+        self.fields['group'] = forms.ChoiceField(choices=allchoices, widget=forms.Select)
     message = forms.CharField(widget=forms.Textarea)
 
 
diff --git a/services/views.py b/services/views.py
index 1c0e4b06..6cac1456 100755
--- a/services/views.py
+++ b/services/views.py
@@ -4,6 +4,7 @@ from django.shortcuts import render_to_response
 from django.contrib.auth.decorators import login_required
 from django.contrib.auth.decorators import permission_required
 from django.contrib.auth.decorators import user_passes_test
+from django.contrib.auth.models import Group
 
 from eveonline.models import EveCharacter
 from authentication.models import AuthServicesInfo
@@ -90,8 +91,8 @@ def jabber_broadcast_view(request):
             success = True
             logger.info("Sent jabber broadcast on behalf of user %s" % request.user)
     else:
-        form = JabberBroadcastForm()
-        logger.debug("Returning blank form to user %s" % request.user)
+        form = JabberBroadcastForm(request.user)
+        logger.debug("Generated broadcast form for user %s containing %s groups" % (request.user, len(form.fields['group'].choices)))
 
     context = {'form': form, 'success': success}
     return render_to_response('registered/jabberbroadcast.html', context, context_instance=RequestContext(request))
diff --git a/util/__init__.py b/util/__init__.py
index f9205361..1d4a35e1 100755
--- a/util/__init__.py
+++ b/util/__init__.py
@@ -15,6 +15,7 @@ def bootstrap_permissions():
     Permission.objects.get_or_create(codename="member", content_type=ct, name="member")
     Permission.objects.get_or_create(codename="group_management", content_type=ct, name="group_management")
     Permission.objects.get_or_create(codename="jabber_broadcast", content_type=ct, name="jabber_broadcast")
+    Permission.objects.get_or_create(codename="jabber_broadcast_all", content_type=ct, name="jabber_broadcast_all")
     Permission.objects.get_or_create(codename="human_resources", content_type=ct, name="human_resources")
     Permission.objects.get_or_create(codename="blue_member", content_type=ct, name="blue_member")
     Permission.objects.get_or_create(codename="corp_stats", content_type=ct, name="corp_stats")

From 87393b85299efeb2f08c0b07600fcbfe24639f5f Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 5 Jan 2016 23:56:27 +0000
Subject: [PATCH 24/27] Variable forum/killboard/media urls on index #140  -
 only rendered if set, otherwise link removed

---
 alliance_auth/settings.py.example |  9 +++++++++
 stock/templates/public/index.html | 33 ++++++++++++++++++++-----------
 util/context_processors.py        |  2 ++
 3 files changed, 32 insertions(+), 12 deletions(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index 3d77e872..7d402b56 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -188,6 +188,15 @@ EMAIL_HOST_USER = os.environ.get('AA_EMAIL_HOST_USER', '')
 EMAIL_HOST_PASSWORD = os.environ.get('AA_EMAIL_HOST_PASSWORD', '')
 EMAIL_USE_TLS = 'True' == os.environ.get('AA_EMAIL_USE_TLS', 'True')
 
+####################
+# Front Page Links
+####################
+# KILLBOARD_URL - URL for your killboard. Blank to hide link
+# MEDIA_URL - URL for your media page (youtube etc). Blank to hide link
+####################
+KILLBOARD_URL = os.environ.get('AA_KILLBOARD_URL', DOMAIN + '/killboard')
+MEDIA_URL = os.environ.get('AA_MEDIA_URL', '')
+
 #########################
 # Default Group Settings
 #########################
diff --git a/stock/templates/public/index.html b/stock/templates/public/index.html
index 76821d67..039b7523 100644
--- a/stock/templates/public/index.html
+++ b/stock/templates/public/index.html
@@ -52,18 +52,27 @@
             <img src="{% static 'img/index_images/auth.png' %}" border="0">
         </a>
     </p>
-
-    <p style="text-align:center">
-        <a href="/forums/">
-            <img src="{% static 'img/index_images/forums.png' %}" border="0">
-        </a>
-    </p>
-
-    <p style="text-align:center">
-        <a href="/killboard/">
-            <img src="{% static 'img/index_images/killboard.png' %}" border="0">
-        </a>
-    </p>
+    {% if FORUM_URL %}
+        <p style="text-align:center">
+            <a href="{{FORUM_URL}}">
+                <img src="{% static 'img/index_images/forums.png' %}" border="0">
+            </a>
+        </p>
+    {% endif %}
+    {% if KILLBOARD_URL %}
+        <p style="text-align:center">
+            <a href="{{KILLBOARD_URL}}">
+                <img src="{% static 'img/index_images/killboard.png' %}" border="0">
+            </a>
+        </p>
+    {% endif %}
+    {% if MEDIA_URL %}
+        <p style="text-align:center">
+            <a href="{{MEDIA_URL}}">
+                <img src="{% static 'img/index_images/media.png' %}" border="0">
+            </a>
+        </p>
+    {% endif %}
 </div>
 </body>
 </html>
diff --git a/util/context_processors.py b/util/context_processors.py
index 3ddbbe92..2d8444a3 100755
--- a/util/context_processors.py
+++ b/util/context_processors.py
@@ -44,4 +44,6 @@ def domain_url(request):
             'TEAMSPEAK3_PUBLIC_URL': settings.TEAMSPEAK3_PUBLIC_URL,
             'JACK_KNIFE_URL': settings.JACK_KNIFE_URL,
             'DISCORD_SERVER_ID': settings.DISCORD_SERVER_ID,
+            'KILLBOARD_URL': settings.KILLBOARD_URL,
+            'MEDIA_URL': settings.MEDIA_URL,
             'CURRENT_UTC_TIME': timezone.now()}

From 50ea33a2475b54e8de5abd901d1f7e5db0c3672f Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Tue, 5 Jan 2016 23:59:50 +0000
Subject: [PATCH 25/27] Relocate FORUM_URL to Front Page Links

---
 alliance_auth/settings.py.example | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index 7d402b56..b830b0a0 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -193,9 +193,11 @@ EMAIL_USE_TLS = 'True' == os.environ.get('AA_EMAIL_USE_TLS', 'True')
 ####################
 # KILLBOARD_URL - URL for your killboard. Blank to hide link
 # MEDIA_URL - URL for your media page (youtube etc). Blank to hide link
+# FORUM_URL - URL for your forums. Blank to hide link
 ####################
 KILLBOARD_URL = os.environ.get('AA_KILLBOARD_URL', DOMAIN + '/killboard')
 MEDIA_URL = os.environ.get('AA_MEDIA_URL', '')
+FORUM_URL = os.environ.get('AA_FORUM_URL', '')
 
 #########################
 # Default Group Settings
@@ -288,12 +290,10 @@ JACK_KNIFE_URL = os.environ.get('AA_JACK_KNIFE_URL', 'http://ridetheclown.com/ev
 #####################
 # Forum Configuration
 #####################
-# FORUM_URL - Forum url location
 # IPBOARD_ENDPOINT - Api endpoint if using ipboard
 # IPBOARD_APIKEY - Api key to interact with ipboard
 # IPBOARD_APIMODULE - Module for alliance auth *leave alone*
 #####################
-FORUM_URL = os.environ.get('AA_FORUM_URL', "http://yourdomain.com")
 IPBOARD_ENDPOINT = os.environ.get('AA_IPBOARD_ENDPOINT', 'yourdomain.com/interface/board/index.php')
 IPBOARD_APIKEY = os.environ.get('AA_IPBOARD_APIKEY', 'somekeyhere')
 IPBOARD_APIMODULE = 'aa'

From 31ec79290aca63f1bef6c6b11a572b616436c8d0 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Wed, 6 Jan 2016 00:32:13 +0000
Subject: [PATCH 26/27] Updated password reset email to determin domain #160

---
 stock/templates/registration/password_reset_email.html | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/stock/templates/registration/password_reset_email.html b/stock/templates/registration/password_reset_email.html
index 63d42122..1b3d2c05 100644
--- a/stock/templates/registration/password_reset_email.html
+++ b/stock/templates/registration/password_reset_email.html
@@ -4,12 +4,12 @@
 
     {% trans "Please go to the following page and choose a new password:" %}
     {% block reset_link %}
-        https://someurl.com{% url 'password_reset_confirm' uidb64=uid token=token %}
+        {{domain}}{% url 'password_reset_confirm' uidb64=uid token=token %}
     {% endblock %}
     {% trans "Your username, in case you've forgotten:" %} {{ user.get_username }}
 
     {% trans "Thanks for using our site!" %}
 
-    {% blocktrans %}Your Corporation{% endblocktrans %}
+    {% blocktrans %}Your IT Team{% endblocktrans %}
 
 {% endautoescape %}

From b7a15dff73f85dcf7a6b16b34f7bee99237cf909 Mon Sep 17 00:00:00 2001
From: Adarnof <adarnof@gmail.com>
Date: Wed, 6 Jan 2016 05:21:36 +0000
Subject: [PATCH 27/27] Changed default killboard url to blank.

---
 alliance_auth/settings.py.example | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/alliance_auth/settings.py.example b/alliance_auth/settings.py.example
index b830b0a0..dde3385c 100755
--- a/alliance_auth/settings.py.example
+++ b/alliance_auth/settings.py.example
@@ -195,7 +195,7 @@ EMAIL_USE_TLS = 'True' == os.environ.get('AA_EMAIL_USE_TLS', 'True')
 # MEDIA_URL - URL for your media page (youtube etc). Blank to hide link
 # FORUM_URL - URL for your forums. Blank to hide link
 ####################
-KILLBOARD_URL = os.environ.get('AA_KILLBOARD_URL', DOMAIN + '/killboard')
+KILLBOARD_URL = os.environ.get('AA_KILLBOARD_URL', '')
 MEDIA_URL = os.environ.get('AA_MEDIA_URL', '')
 FORUM_URL = os.environ.get('AA_FORUM_URL', '')