diff --git a/mellon/adapters.py b/mellon/adapters.py index 7989f07..6ec5f80 100644 --- a/mellon/adapters.py +++ b/mellon/adapters.py @@ -83,13 +83,13 @@ class DefaultAdapter(object): def load_metadata_path(self, idp, i): path = idp['METADATA_PATH'] if not os.path.exists(path): - logger.warning('metadata path %s does not exist', path) + logger.warning('mellon: metadata path %s does not exist', path) return last_update = idp.get('METADATA_PATH_LAST_UPDATE', 0) try: mtime = os.stat(path).st_mtime except OSError as e: - logger.warning('metadata path %s : stat() call failed, %s', path, e) + logger.warning('mellon: metadata path %s : stat() call failed, %s', path, e) return if last_update == 0 or mtime >= last_update: idp['METADATA_PATH_LAST_UPDATE'] = time.time() @@ -97,15 +97,15 @@ class DefaultAdapter(object): with open(path) as fd: metadata = fd.read() except OSError as e: - logger.warning('metadata path %s : open()/read() call failed, %s', path, e) + logger.warning('mellon: metadata path %s : open()/read() call failed, %s', path, e) return entity_id = self.load_entity_id(metadata, i) if not entity_id: - logger.error('invalid metadata file retrieved from %s', path) + logger.error('mellon: invalid metadata file retrieved from %s', path) return if 'ENTITY_ID' in idp and idp['ENTITY_ID'] != entity_id: logger.error( - 'metadata path %s : entityID changed %r != %r', path, entity_id, idp['ENTITY_ID'] + 'mellon: metadata path %s : entityID changed %r != %r', path, entity_id, idp['ENTITY_ID'] ) del idp['ENTITY_ID'] idp['METADATA'] = metadata @@ -178,7 +178,7 @@ class DefaultAdapter(object): if 'ENTITY_ID' in idp and idp['ENTITY_ID'] != entity_id: # entityID change is always en error logger.error( - 'metadata url %s : entityID changed %r != %r', url, entity_id, idp['ENTITY_ID'] + 'mellon: metadata url %s, entityID changed %r != %r', url, entity_id, idp['ENTITY_ID'] ) del idp['ENTITY_ID'] @@ -190,12 +190,15 @@ class DefaultAdapter(object): fd.write(response.text.encode('utf-8')) except OSError as e: logger.error( - 'metadata url %s : could not write file cache %s, %s', url, file_cache_path, e + 'mellon: metadata url %s : could not write file cache %s, %s', + url, + file_cache_path, + e, ) idp['METADATA_PATH'] = file_cache_path # prevent reloading of the file cache immediately idp['METADATA_PATH_LAST_UPDATE'] = time.time() + 1 - logger.debug('metadata url %s : update throught HTTP', url) + logger.info('mellon: metadata url %s updated', url) finally: # release thread object idp.pop('METADATA_URL_UPDATE_THREAD', None) @@ -204,7 +207,9 @@ class DefaultAdapter(object): stale_timeout = 24 * metadata_cache_time if last_update and (now - idp['METADATA_URL_LAST_UPDATE']) > stale_timeout: logger.error( - 'metadata url %s: not updated since %.1f hours', url, stale_timeout / 3600.0 + 'mellon: metadata url %s: not updated since %.1f hours', + url, + stale_timeout / 3600.0, ) # we have cache, update in background @@ -244,14 +249,14 @@ class DefaultAdapter(object): try: doc = ET.fromstring(metadata) except (TypeError, ET.ParseError): - logger.error('METADATA of %d-th idp is invalid', i) + logger.error('mellon: METADATA of %d-th idp is invalid', i) return None if doc.tag != '{%s}EntityDescriptor' % lasso.SAML2_METADATA_HREF: - logger.error('METADATA of %d-th idp has no EntityDescriptor root tag', i) + logger.error('mellon: METADATA of %d-th idp has no EntityDescriptor root tag', i) return None if 'entityID' not in doc.attrib: - logger.error('METADATA of %d-th idp has no entityID attribute on its root tag', i) + logger.error('mellon: METADATA of %d-th idp has no entityID attribute on its root tag', i) return None return doc.attrib['entityID'] @@ -277,11 +282,11 @@ class DefaultAdapter(object): :30 ] except ValueError: - logger.error('invalid username template %r', username_template) + logger.error('mellon: invalid username template %r', username_template) except (AttributeError, KeyError, IndexError) as e: - logger.error('invalid reference in username template %r: %s', username_template, e) + logger.error('mellon: invalid reference in username template %r: %s', username_template, e) except Exception: - logger.exception('unknown error when formatting username') + logger.exception('mellon: unknown error when formatting username') else: return username @@ -291,7 +296,6 @@ class DefaultAdapter(object): def finish_create_user(self, idp, saml_attributes, user): username = self.format_username(idp, saml_attributes) if not username: - logger.warning('could not build a username, login refused') raise UserCreationError user.username = username user.save() @@ -306,7 +310,7 @@ class DefaultAdapter(object): name_id = name_id[0] else: logger.warning( - 'more than one value for attribute %r, cannot federate', + 'mellon: more than one value for attribute %r, cannot federate', transient_federation_attribute, ) return None @@ -316,7 +320,9 @@ class DefaultAdapter(object): self.request, _('A transient NameID was received but TRANSIENT_FEDERATION_ATTRIBUTE is not set.'), ) - logger.warning('transient NameID was received but TRANSIENT_FEDERATION_ATTRIBUTE is not set') + logger.warning( + 'mellon: transient NameID was received but TRANSIENT_FEDERATION_ATTRIBUTE is not set' + ) return None else: name_id = saml_attributes['name_id_content'] @@ -327,7 +333,7 @@ class DefaultAdapter(object): ) user = saml_identifier.user user.saml_identifier = saml_identifier - logger.info('looked up user %s with name_id %s from issuer %s', user, name_id, issuer) + logger.info('mellon: looked up user %s with name_id %s from issuer %s', user, name_id, issuer) return user except models.UserSAMLIdentifier.DoesNotExist: pass @@ -337,14 +343,16 @@ class DefaultAdapter(object): created = False if not user: if not utils.get_setting(idp, 'PROVISION'): - logger.debug('provisionning disabled, login refused') + logger.warning('mellon: login refused for %s, PROVISION is disabled', saml_attributes) return None created = True user = self.create_user(User) nameid_user = self._link_user(idp, saml_attributes, issuer, name_id, user) if user != nameid_user: - logger.info('looked up user %s with name_id %s from issuer %s', nameid_user, name_id, issuer) + logger.info( + 'mellon: looked up user %s with name_id %s from issuer %s', nameid_user, name_id, issuer + ) if created: user.delete() return nameid_user @@ -355,7 +363,9 @@ class DefaultAdapter(object): except UserCreationError: user.delete() return None - logger.info('created new user %s with name_id %s from issuer %s', nameid_user, name_id, issuer) + logger.info( + 'mellon: created new user %s with name_id %s from issuer %s', nameid_user, name_id, issuer + ) return nameid_user def lookup_by_attributes(self, idp, saml_attributes): @@ -367,7 +377,8 @@ class DefaultAdapter(object): def _lookup_by_attributes(self, idp, saml_attributes, lookup_by_attributes): if not isinstance(lookup_by_attributes, list): logger.error( - 'invalid LOOKUP_BY_ATTRIBUTES configuration %r: it must be a list', lookup_by_attributes + 'mellon: invalid LOOKUP_BY_ATTRIBUTES configuration %r: it must be a list', + lookup_by_attributes, ) return None @@ -375,30 +386,34 @@ class DefaultAdapter(object): for line in lookup_by_attributes: if not isinstance(line, dict): logger.error( - 'invalid LOOKUP_BY_ATTRIBUTES configuration %r: it must be a list of dicts', line + 'mellon: invalid LOOKUP_BY_ATTRIBUTES configuration %r: it must be a list of dicts', line ) continue user_field = line.get('user_field') if not hasattr(user_field, 'isalpha'): - logger.error('invalid LOOKUP_BY_ATTRIBUTES configuration %r: user_field is missing', line) + logger.error( + 'mellon: invalid LOOKUP_BY_ATTRIBUTES configuration %r: user_field is missing', line + ) continue try: User._meta.get_field(user_field) except FieldDoesNotExist: logger.error( - 'invalid LOOKUP_BY_ATTRIBUTES configuration %r, user field %s does not exist', + 'mellon: invalid LOOKUP_BY_ATTRIBUTES configuration %r, user field %s does not exist', line, user_field, ) continue saml_attribute = line.get('saml_attribute') if not hasattr(saml_attribute, 'isalpha'): - logger.error('invalid LOOKUP_BY_ATTRIBUTES configuration %r: saml_attribute is missing', line) + logger.error( + 'mellon: invalid LOOKUP_BY_ATTRIBUTES configuration %r: saml_attribute is missing', line + ) continue values = saml_attributes.get(saml_attribute) if not values: logger.warning( - 'looking for user by saml attribute %r and user field %r, skipping because empty', + 'mellon: looking for user by saml attribute %r and user field %r, skipping because empty', saml_attribute, user_field, ) @@ -412,15 +427,15 @@ class DefaultAdapter(object): saml_identifiers__isnull=True, **{key: value} ) if not users_found: - logger.debug( - 'looking for users by attribute %r and user field %r with value %r: not found', + logger.warning( + 'mellon: looking for users by attribute %r and user field %r with value %r: not found', saml_attribute, user_field, value, ) continue logger.info( - 'looking for user by attribute %r and user field %r with value %r: found %s', + 'mellon: looking for user by attribute %r and user field %r with value %r: found %s', saml_attribute, user_field, value, @@ -429,11 +444,13 @@ class DefaultAdapter(object): users.update(users_found) if len(users) == 1: user = list(users)[0] - logger.info('looking for user by attributes %r: found user %s', lookup_by_attributes, user) + logger.info( + 'mellon: looking for user by attributes %r: found user %s', lookup_by_attributes, user + ) return user elif len(users) > 1: logger.warning( - 'looking for user by attributes %r: too many users found(%d), failing', + 'mellon: looking for user by attributes %r: too many users found(%d), failing', lookup_by_attributes, len(users), ) @@ -463,9 +480,9 @@ class DefaultAdapter(object): try: value = force_text(tpl).format(realm=realm, attributes=saml_attributes, idp=idp) except ValueError: - logger.warning('invalid attribute mapping template %r', tpl) + logger.warning('mellon: invalid attribute mapping template %r', tpl) except (AttributeError, KeyError, IndexError, ValueError) as e: - logger.warning('invalid reference in attribute mapping template %r: %s', tpl, e) + logger.warning('mellon: invalid reference in attribute mapping template %r: %s', tpl, e) else: model_field = user._meta.get_field(field) if hasattr(model_field, 'max_length'): @@ -475,7 +492,11 @@ class DefaultAdapter(object): setattr(user, field, value) attribute_set = True logger.info( - 'set field %s of user %s to value %r (old value %r)', field, user, value, old_value + 'mellon: set field %s of user %s to value %r (old value %r)', + field, + user, + value, + old_value, ) if attribute_set: user.save() @@ -499,13 +520,13 @@ class DefaultAdapter(object): user.is_staff = True user.is_superuser = True attribute_set = True - logger.info('flag is_staff and is_superuser added to user %s', user) + logger.info('mellon: flag is_staff and is_superuser added to user %s', user) break else: if user.is_superuser or user.is_staff: user.is_staff = False user.is_superuser = False - logger.info('flag is_staff and is_superuser removed from user %s', user) + logger.info('mellon: flag is_staff and is_superuser removed from user %s', user) attribute_set = True if attribute_set: user.save() @@ -528,11 +549,15 @@ class DefaultAdapter(object): continue groups.append(group) for group in Group.objects.filter(pk__in=[g.pk for g in groups]).exclude(user=user): - logger.info('adding group %s (%s) to user %s (%s)', group, group.pk, user, user.pk) + logger.info('mellon: adding group %s (%s) to user %s (%s)', group, group.pk, user, user.pk) User.groups.through.objects.get_or_create(group=group, user=user) qs = User.groups.through.objects.exclude(group__pk__in=[g.pk for g in groups]).filter(user=user) for rel in qs: logger.info( - 'removing group %s (%s) from user %s (%s)', rel.group, rel.group.pk, rel.user, rel.user.pk + 'mellon: removing group %s (%s) from user %s (%s)', + rel.group, + rel.group.pk, + rel.user, + rel.user.pk, ) qs.delete() diff --git a/tests/test_default_adapter.py b/tests/test_default_adapter.py index 0c434cd..a8e3b4d 100644 --- a/tests/test_default_adapter.py +++ b/tests/test_default_adapter.py @@ -252,7 +252,7 @@ def test_lookup_user_by_attributes_bad_setting1(settings, idp, saml_attributes, adapter = DefaultAdapter() settings.MELLON_LOOKUP_BY_ATTRIBUTES = 'coin' assert adapter.lookup_user(idp, saml_attributes) is None - assert caplog.records[-1].message.endswith('it must be a list') + assert 'it must be a list' in caplog.text def test_lookup_user_by_attributes_bad_setting2(settings, idp, saml_attributes, caplog): @@ -261,7 +261,7 @@ def test_lookup_user_by_attributes_bad_setting2(settings, idp, saml_attributes, adapter = DefaultAdapter() settings.MELLON_LOOKUP_BY_ATTRIBUTES = ['coin'] assert adapter.lookup_user(idp, saml_attributes) is None - assert caplog.records[-1].message.endswith('it must be a list of dicts') + assert 'it must be a list of dicts' in caplog.text def test_lookup_user_by_attributes_bad_setting3(settings, idp, saml_attributes, caplog): @@ -270,7 +270,7 @@ def test_lookup_user_by_attributes_bad_setting3(settings, idp, saml_attributes, adapter = DefaultAdapter() settings.MELLON_LOOKUP_BY_ATTRIBUTES = [{}] assert adapter.lookup_user(idp, saml_attributes) is None - assert caplog.records[-1].message.endswith('user_field is missing') + assert 'user_field is missing' in caplog.text def test_lookup_user_by_attributes_bad_setting4(settings, idp, saml_attributes, caplog): @@ -279,7 +279,7 @@ def test_lookup_user_by_attributes_bad_setting4(settings, idp, saml_attributes, adapter = DefaultAdapter() settings.MELLON_LOOKUP_BY_ATTRIBUTES = [{'user_field': 'username'}] assert adapter.lookup_user(idp, saml_attributes) is None - assert caplog.records[-1].message.endswith('saml_attribute is missing') + assert 'saml_attribute is missing' in caplog.text def test_lookup_user_by_attributes_not_found(settings, idp, saml_attributes, caplog): @@ -290,7 +290,7 @@ def test_lookup_user_by_attributes_not_found(settings, idp, saml_attributes, cap settings.MELLON_LOOKUP_BY_ATTRIBUTES = [{'user_field': 'username', 'saml_attribute': 'saml_at1'}] saml_attributes['saml_at1'] = ['john.doe'] assert adapter.lookup_user(idp, saml_attributes) is None - assert caplog.records[-2].message.endswith(': not found') + assert ': not found' in caplog.text def test_lookup_user_by_attributes_too_many1(settings, idp, saml_attributes, john, jane, caplog): @@ -300,7 +300,7 @@ def test_lookup_user_by_attributes_too_many1(settings, idp, saml_attributes, joh settings.MELLON_LOOKUP_BY_ATTRIBUTES = [{'user_field': 'email', 'saml_attribute': 'saml_at1'}] saml_attributes['saml_at1'] = ['john.doe@example.com'] assert adapter.lookup_user(idp, saml_attributes) is None - assert 'too many users found(2)' in caplog.records[-1].message + assert 'too many users found(2)' in caplog.text def test_lookup_user_by_attributes_too_manyi2(settings, idp, saml_attributes, john, jane, caplog): @@ -315,7 +315,7 @@ def test_lookup_user_by_attributes_too_manyi2(settings, idp, saml_attributes, jo {'user_field': 'username', 'saml_attribute': 'saml_at2'}, ] assert adapter.lookup_user(idp, saml_attributes) is None - assert 'too many users found(2)' in caplog.records[-1].message + assert 'too many users found(2)' in caplog.text def test_lookup_user_by_attributes_found(settings, idp, saml_attributes, john, jane, caplog): @@ -397,8 +397,9 @@ def test_load_metadata_url(settings, adapter, metadata, httpserver, freezer, cap new_meta = adapter.load_metadata(idp, 0) assert new_meta != metadata assert new_meta == metadata.replace('idp5', 'idp6') - assert 'entityID changed' in caplog.records[-1].message - assert caplog.records[-1].levelname == 'ERROR' + assert any( + 'entityID changed' in record.message and record.levelname == 'ERROR' for record in caplog.records + ) # test load from file cache del idp['METADATA'] del idp['METADATA_PATH']