finish adding updates

Merged:
adobe-apiplatform#615
adobe-apiplatform#619
https://github.com/adobe-apiplatform/user-sync.py/pull/621/files

user_sync/app.py

@@ -54,16 +54,23 @@
 LOG_STRING_FORMAT = '%(asctime)s %(process)d %(levelname)s %(name)s - %(message)s'
 LOG_DATE_FORMAT = '%Y-%m-%d %H:%M:%S'
 
+# Trace logger for debugging
+logging.TRACE_NUM = 5
+logging.addLevelName(logging.TRACE_NUM, "TRACE")
+def trace(self, message, *args, **kws):
+    if self.isEnabledFor(logging.TRACE_NUM):
+        self._log(logging.TRACE_NUM, message, args, **kws)
+logging.Logger.trace = trace
+
 # file logger, defined early so later functions can refer to it.
 logger = logging.getLogger('main')
 
-
 def init_console_log():
     handler = logging.StreamHandler(sys.stdout)
     handler.setFormatter(logging.Formatter(LOG_STRING_FORMAT, LOG_DATE_FORMAT))
     root_logger = logging.getLogger()
     root_logger.addHandler(handler)
-    root_logger.setLevel(logging.DEBUG)
+    root_logger.setLevel(logging.TRACE_NUM)
     return handler
 
 
@@ -317,6 +324,7 @@ def init_log(logging_config):
     options = builder.get_options()
 
     level_lookup = {
+        'trace': logging.TRACE_NUM,
         'debug': logging.DEBUG,
         'info': logging.INFO,
         'warning': logging.WARNING,
@@ -348,7 +356,6 @@ def init_log(logging_config):
         if unknown_file_log_level:
             logger.log(logging.WARNING, 'Unknown file log level: %s setting to info' % options['file_log_level'])
 
-
 def log_parameters(argv, config_loader):
     """
     Log the invocation parameters to make it easier to diagnose problem with customers

user_sync/post_sync/connectors/sign_sync/__init__.py

@@ -9,6 +9,7 @@
 from .client import SignClient
 
 
+# noinspection PyUnresolvedReferences
 class SignConnector(PostSyncConnector):
     name = 'sign_sync'
 
@@ -55,18 +56,21 @@ def run(self, post_sync_data):
             if umapi_users is None:
                 raise AssertionException("Error getting umapi users from post_sync_data")
             self.update_sign_users(umapi_users, sign_client, org_name)
+            self.logger.debug("---------------------------------")
 
     def update_sign_users(self, umapi_users, sign_client, org_name):
         sign_users = sign_client.get_users()
-        self.logger.debug('s-users:')
-        for s in sign_users:
-            self.logger.debug(str(s))
-        self.logger.info("Total sign users: " + str(len(sign_users)))
-        self.logger.info("Total umapi users: " + str(len(umapi_users)))
+        self.logger.debug("---------------------------------")
+        self.logger.debug("Total sign users: " + str(len(sign_users)))
+        self.logger.debug("Total umapi users: " + str(len(umapi_users)))
+
+
+
         for _, umapi_user in umapi_users.items():
+            self.logger.trace("---------------------------------")
             sign_user = sign_users.get(umapi_user['email'].lower())
             if not self.should_sync(umapi_user, sign_user, org_name):
-                self.logger.debug("skipped\n")
+                self.logger.trace("Skipping user due to should_sync == False: " + umapi_user['email'])
                 continue
 
             assignment_group = None
@@ -79,8 +83,6 @@ def update_sign_users(self, umapi_users, sign_client, org_name):
             if assignment_group is None:
                 assignment_group = sign_client.DEFAULT_GROUP_NAME
 
-            self.logger.debug("assigned: " + str(assignment_group))
-            self.logger.debug("")
             group_id = sign_client.groups.get(assignment_group)
             admin_roles = self.admin_roles.get(org_name, {})
             user_roles = self.resolve_new_roles(umapi_user, admin_roles)
@@ -91,6 +93,10 @@ def update_sign_users(self, umapi_users, sign_client, org_name):
                 "lastName": sign_user['lastName'],
                 "roles": user_roles,
             }
+
+            self.logger.trace("Matched group '{0}' and roles {1} to {2}"
+                              .format(assignment_group, user_roles, umapi_user['email']))
+
             if sign_user['group'].lower() == assignment_group and self.roles_match(user_roles, sign_user['roles']):
                 self.logger.debug("skipping Sign update for '{}' -- no updates needed".format(umapi_user['email']))
                 continue
@@ -101,6 +107,7 @@ def update_sign_users(self, umapi_users, sign_client, org_name):
             except AssertionError as e:
                 self.logger.error("Error updating user {}".format(e))
 
+
     @staticmethod
     def roles_match(resolved_roles, sign_roles):
         if isinstance(sign_roles, str):
@@ -130,15 +137,22 @@ def should_sync(self, umapi_user, sign_user, org_name):
         """
         # UMAPI will often return a product profile with extra characters appended. This re.sub will remove that.
         # eg. 'Example Product Profile' will come through as 'Example Product Profile_EC79122-provisioning'
-        umapi_group = []
+        umapi_groups = []
         for group in umapi_user['groups']:
-            group_fixed = re.sub("_[A-Za-z0-9]+(?i)-provisioning$", '', group)
-            if group_fixed != group:
-                self.logger.debug("Likely provisioning group mismatch - overriding group name: {0} -> {1}"
-                                  .format(group, group_fixed))
-            umapi_group.append(group_fixed)
-        return sign_user is not None and set(umapi_group) & set(self.entitlement_groups[org_name]) and \
-               umapi_user['type'] in self.identity_types
+            fixed_group = re.sub("_[A-Za-z0-9]+(?i)-provisioning$", '', group)
+            umapi_groups.append(fixed_group)
+        intersecting_groups = set(umapi_groups) & set(self.entitlement_groups[org_name])
+
+        info = {
+            'User is not none': sign_user is not None,
+            'Umapi groups': umapi_user['groups'],
+            'Entitlement groups': self.entitlement_groups[org_name],
+            'Umapi + Entitlement intersect': intersecting_groups
+        }
+
+        self.logger.trace("Trace info for {0} {1}: {2}".format(umapi_user['type'], umapi_user['email'], info))
+
+        return sign_user is not None and intersecting_groups and umapi_user['type'] in self.identity_types
 
     @staticmethod
     def _groupify(groups):

user_sync/post_sync/connectors/sign_sync/client.py

@@ -111,6 +111,7 @@ def get_users(self):
             user['roles'] = self.user_roles(user)
             users[user['email']] = user
             self.logger.debug('retrieved user details for Sign user {}'.format(user['email']))
+            self.logger.trace(str(user))
 
         return users