mozreview: log user events; r=smacleod draft
authorGregory Szorc <gps@mozilla.com>
Thu, 07 Jan 2016 16:59:32 -0800
changeset 6707 6c164172d1ecdf2c8b0acc20eda349716f78be5e
parent 6706 941aecdaad4b8e570f03c896bd45a61f524c6e68
child 6708 bac671496fbf8a1857b6b2a3ad28a5a6d89bc9a3
push id513
push usergszorc@mozilla.com
push dateWed, 13 Jan 2016 02:13:15 +0000
reviewerssmacleod
mozreview: log user events; r=smacleod As part of developing an upcoming feature, I ran into bugs related to user state. To help me debug the issue, I added logging of key user events. This log should also be useful for forensics and is generally good to have.
pylib/mozreview/mozreview/bugzilla/models.py
pylib/rbbz/rbbz/auth.py
--- a/pylib/mozreview/mozreview/bugzilla/models.py
+++ b/pylib/mozreview/mozreview/bugzilla/models.py
@@ -1,21 +1,24 @@
 # This Source Code Form is subject to the terms of the Mozilla Public
 # License, v. 2.0. If a copy of the MPL was not distributed with this
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 import datetime
+import logging
 import re
 
 from django.contrib.auth.models import User
 from django.db import models, transaction
 from reviewboard.accounts.models import Profile
 from reviewboard.reviews.models import ReviewRequest
 
 
+logger = logging.getLogger(__name__)
+
 # Note that Review Board only allows a subset of legal IRC-nick characters.
 # Specifically, Review Board does not allow [ \ ] ^ ` { | }
 # Anyone with those in their :ircnicks will have them truncated at the last
 # legal character.  Not great, but we can later implement a UI for letting
 # people change their usernames in Review Board.
 BZ_IRCNICK_RE = re.compile(':([A-Za-z0-9_\-\.]+)')
 
 
@@ -88,47 +91,70 @@ def get_or_create_bugzilla_users(user_da
             bugzilla_user_map = BugzillaUserMap(user=user,
                                                 bugzilla_user_id=bz_user_id)
             bugzilla_user_map.save()
 
             profile = Profile.objects.get_or_create(user=user)[0]
             if not profile.is_private:
                 profile.is_private = True
                 profile.save()
+
+            logger.info('created user %s:%s from bugzilla user %s/%s/%s' % (
+                user.id, user.username,
+                bz_user_id, email, real_name
+            ))
         else:
             modified = False
             user = bugzilla_user_map.user
+            old_username = user.username
 
             if user.username != username:
+                logger.info('updating username of %s from %s to %s' % (
+                    user.id, user.username, username
+                ))
                 user.username = username
                 modified = True
 
             if user.email != email:
+                logger.info('updating email of %s:%s from %s to %s' % (
+                    user.id, user.username, user.email, email
+                ))
                 user.email = email
                 modified = True
 
             if user.first_name != real_name:
+                logger.info('updating first name of %s:%s from %s to %s' % (
+                    user.id, user.username, user.first_name, real_name
+                ))
                 user.first_name = real_name
                 modified = True
 
             # Note that users *must* be disabled in Bugzilla and *cannot*
             # be disabled in Review Board, since, if user.is_active is False,
             # we can't tell if this was a result of can_login going False
             # at some previous time or the action of a Review Board admin.
             if user.is_active != can_login:
+                logger.info('updating active of %s:%s to %s' % (
+                    user.id, user.username, can_login
+                ))
                 user.is_active = can_login
                 modified = True
 
             if modified:
                 try:
                     user.save()
                 except:
                     # Blanket exceptions are terrible, but there appears to
                     # be no way to catch a generic IntegrityError.
-                    user.username = placeholder_username(email, bz_user_id)
+                    new_username = placeholder_username(email, bz_user_id)
+                    logger.info('could not set preferred username %s; '
+                                'updating username of %s from %s to %s' % (
+                        username, user.id, old_username, new_username
+                    ))
+                    user.username = new_username
                     user.save()
 
         users.append(user)
     return users
 
 
 def get_bugzilla_api_key(user):
     if not user or not user.is_authenticated():
@@ -143,16 +169,19 @@ def get_bugzilla_api_key(user):
 def set_bugzilla_api_key(user, api_key):
     """Assigns a Bugzilla API key to a user.
 
     The user must exist before this function is called.
     """
     bugzilla_user_map = BugzillaUserMap.objects.get(user=user)
     if bugzilla_user_map.api_key != api_key:
         bugzilla_user_map.api_key = api_key
+        logger.info('updating bugzilla api key for %s:%s' % (
+            user.id, user.username
+        ))
         bugzilla_user_map.save()
 
 
 def prune_inactive_users(commit=False, verbose=False):
     """Delete inactive users.
 
     We will delete users which have not done any of the following:
     - created a review request
--- a/pylib/rbbz/rbbz/auth.py
+++ b/pylib/rbbz/rbbz/auth.py
@@ -22,16 +22,19 @@ from mozreview.bugzilla.models import (
 )
 from mozreview.errors import (
     BugzillaAPIKeyNeededError,
     WebLoginNeededError,
 )
 from rbbz.forms import BugzillaAuthSettingsForm
 
 
+logger = logging.getLogger(__name__)
+
+
 class BugzillaBackend(AuthBackend):
     """
     Authenticate a user via Bugzilla XMLRPC.
     """
 
     backend_id = _('bugzilla')
     name = _('Bugzilla')
     login_instructions = _('using your Bugzilla credentials.')
@@ -232,16 +235,19 @@ class BugzillaBackend(AuthBackend):
                 # attached to this.
                 if u['real_name'] == query:
                     return True
 
                 return False
 
             users = bugzilla.query_users(query)
             users['users'] = [u for u in users['users'] if user_relevant(u)]
+            logger.info('importing Bugzilla users from query "%s": %s' % (
+                        query,
+                        ' ,'.join(sorted(u['email'] for u in users['users']))))
             get_or_create_bugzilla_users(users)
         except BugzillaError as e:
             raise UserQueryError('Bugzilla error: %s' % e.msg)
 
     def search_users(self, query, request):
         """Search anywhere in name to support BMO :irc_nick convention."""
         q = Q(username__icontains=query)
         q = q | Q(email__icontains=query)