From 55fc69cf8d2720b666e9b3b21c8b9eb5965ceadc Mon Sep 17 00:00:00 2001 From: Adarnof Date: Mon, 28 Dec 2015 06:50:13 +0000 Subject: [PATCH] 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))