Logging added to all service managers.

Unrelated, getting ImportError when trying to start shell. I broke something.

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

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

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
+        logger.info("Updating IPBoard groups for user %s - adding %s, removing %s" % (username, addgroups, remgroups))
-        print remgroups
         for g in addgroups:
             if not g in forum_groups:
                 IPBoardManager.add_group(g)
-            print username
+            logger.debug("Adding user %s to IPBoard group %s" % (username, g))
-            print 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

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))

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,):

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
+            logger.info("Updating phpbb user %s groups - adding %s, removing %s" % (username, addgroups, remgroups))
-            print addgroups
-            print 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

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
+            logger.info("Finished checking user id %s groups. Adding %s, removing %s." % (uid, addgroups, remgroups))
-            print addgroups
-            print 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)