adapters: improve log messages (#55544)
- add mellon: prefix to all messages - log all failures at the warning or error level instead of debug
This commit is contained in:
parent
abe0328a22
commit
472ce61844
|
|
@ -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()
|
||||
|
|
|
|||
|
|
@ -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']
|
||||
|
|
|
|||
Loading…
Reference in New Issue