provisionning: log received provisionning messages and actions (#56907)

This commit is contained in:
Benjamin Dauvergne 2021-09-13 14:30:25 +02:00
parent 96ce1fb02f
commit add04ecadb
5 changed files with 99 additions and 32 deletions

View File

@ -15,6 +15,7 @@
# along with this program. If not, see <http://www.gnu.org/licenses/>.
import json
import logging
import os
import sys
@ -24,6 +25,8 @@ from tenant_schemas.utils import tenant_context
from hobo.multitenant.middleware import TenantMiddleware
from hobo.provisionning.utils import NotificationProcessing, TryAgain
logger = logging.getLogger(__name__)
class Command(BaseCommand, NotificationProcessing):
requires_system_checks = False
@ -60,6 +63,8 @@ class Command(BaseCommand, NotificationProcessing):
if entity_id not in audience:
return
object_type = notification['objects']['@type']
msg = 'received request for %sing %%d %%s objects (Celery)' % action
logger.info(msg, len(notification['objects']['data']), object_type)
for i in range(20):
try:
getattr(cls, 'provision_' + object_type)(

View File

@ -13,9 +13,13 @@ def provision_user_groups(user, uuids):
logger = logging.getLogger(__name__)
existing_pks = user.groups.values_list('pk', flat=True)
not_found = set(uuids)
for role in Role.objects.filter(uuid__in=uuids).exclude(pk__in=existing_pks):
not_found.discard(role.uuid)
if role.pk in existing_pks:
continue
user.groups.through.objects.get_or_create(group=role, user=user)
logger.info(u'adding role %s to %s (%s)', role, user, user.pk)
logger.info('adding role %s to %s (%s)', role, user, user.pk)
qs = user.groups.through.objects.filter(user=user, group__role__isnull=False).exclude(
group__role__uuid__in=uuids
)
@ -26,4 +30,6 @@ def provision_user_groups(user, uuids):
except DatabaseError:
pass
else:
logger.info(u'removed role %s from %s (%s)', rel.group, user, user.pk)
logger.info('removed role %s from %s (%s)', rel.group, user, user.pk)
for uuid in not_found:
logger.warning('role %s of user %s does not exist', uuid, user)

View File

@ -15,6 +15,7 @@
# along with this program. If not, see <http://www.gnu.org/licenses/>.
import json
import logging
import sys
from django.conf import settings
@ -27,6 +28,8 @@ from django.utils.six.moves.urllib.parse import urlparse
from hobo.provisionning.utils import NotificationProcessing
from hobo.rest_authentication import PublikAuthentication, PublikAuthenticationFailed
logger = logging.getLogger(__name__)
class ProvisionningMiddleware(MiddlewareMixin, NotificationProcessing):
def process_request(self, request):
@ -54,6 +57,8 @@ class ProvisionningMiddleware(MiddlewareMixin, NotificationProcessing):
full = notification['full'] if 'full' in notification else False
data = notification['objects']['data']
msg = 'received request for %sing %%d %%s objects (HTTP)' % action
logger.info(msg, len(notification['objects']['data']), object_type)
if 'uwsgi' in sys.modules and 'sync' not in request.GET:
from hobo.provisionning.spooler import provision
@ -75,7 +80,6 @@ class ProvisionningMiddleware(MiddlewareMixin, NotificationProcessing):
)
else:
self.provision(object_type=object_type, issuer=issuer, action=action, data=data, full=full)
return JsonResponse({'err': 0})
def hobo_specific_setup(self):

View File

@ -16,7 +16,6 @@
import hashlib
import logging
import random
from django.contrib.auth.models import Group
from django.db import IntegrityError
@ -26,11 +25,31 @@ from django.db.transaction import atomic
from hobo.agent.common.models import Role
from hobo.multitenant.utils import provision_user_groups
logger = logging.getLogger(__name__)
class TryAgain(Exception):
pass
def user_str(user):
'''Compute a string representation of user'''
s = ''
if user.first_name or user.last_name:
s += '"'
if user.first_name:
s += user.first_name
if user.first_name and user.last_name:
s += ' '
if user.last_name:
s += user.last_name
s += '" '
if user.email:
s += user.email + ' '
s += user.username
return s
class NotificationProcessing:
@classmethod
def check_valid_notification(cls, notification):
@ -72,6 +91,17 @@ class NotificationProcessing:
try:
with atomic():
if action == 'provision':
new = False
updated = set()
attributes = {
'first_name': o['first_name'][:30],
'last_name': o['last_name'][:150],
'email': o['email'][:254],
'username': o['uuid'][:150],
'is_superuser': o['is_superuser'],
'is_staff': o['is_superuser'],
'is_active': o.get('is_active', True),
}
assert cls.check_valid_user(o)
try:
mellon_user = UserSAMLIdentifier.objects.get(
@ -85,20 +115,22 @@ class NotificationProcessing:
)
except User.DoesNotExist:
# temp user object
random_uid = str(random.randint(1, 10000000000000))
user = User.objects.create(username=random_uid)
user = User.objects.create(**attributes)
new = True
saml_issuer, created = Issuer.objects.get_or_create(entity_id=issuer)
mellon_user = UserSAMLIdentifier.objects.create(
user=user, issuer=saml_issuer, name_id=o['uuid']
)
user.first_name = o['first_name'][:30]
user.last_name = o['last_name'][:150]
user.email = o['email'][:254]
user.username = o['uuid'][:150]
user.is_superuser = o['is_superuser']
user.is_staff = o['is_superuser']
user.is_active = o.get('is_active', True)
user.save()
if new:
logger.info('provisionned new user %s', user_str(user))
else:
for key in attributes:
if getattr(user, key) != attributes[key]:
setattr(user, key, attributes[key])
updated.add(key)
if updated:
user.save()
logger.info('updated user %s(%s)', user_str(user), updated)
role_uuids = [role['uuid'] for role in o.get('roles', [])]
provision_user_groups(user, role_uuids)
elif action == 'deprovision':
@ -106,12 +138,16 @@ class NotificationProcessing:
uuids.add(o['uuid'])
except IntegrityError:
raise TryAgain
if full and action == 'provision':
for usi in UserSAMLIdentifier.objects.exclude(name_id__in=uuids):
usi.user.delete()
elif action == 'deprovision':
for user in User.objects.filter(saml_identifiers__name_id__in=uuids):
user.delete()
if (full and action == 'provision') or (action == 'deprovision'):
if action == 'deprovision':
qs = User.objects.filter(saml_identifiers__name_id__in=uuids)
else:
qs = User.objects.exclude(saml_identifiers__name_id__in=uuids)
# retrieve users before deleting them
qs = qs[:]
qs.delete()
for user in qs:
logger.info('deprovisionning user %s', user_str(user))
group_name_max_length = Group._meta.get_field('name').max_length
@ -128,7 +164,6 @@ class NotificationProcessing:
@classmethod
def provision_role(cls, issuer, action, data, full=False):
logger = logging.getLogger(__name__)
uuids = set()
roles_by_uuid = dict()
@ -145,6 +180,8 @@ class NotificationProcessing:
assert 'uuid' in o
uuids.add(o['uuid'])
if action == 'provision':
created = False
save = False
assert cls.check_valid_role(o)
role_name = cls.truncate_role_name(o['name'])
try:
@ -158,17 +195,16 @@ class NotificationProcessing:
defaults={
'uuid': o['uuid'],
'description': o['description'],
'details': o.get('details', u''),
'details': o.get('details', ''),
'emails': o.get('emails', []),
'emails_to_members': o.get('emails_to_members', True),
},
)
except IntegrityError:
# Can happen if uuid and name already exist
logger.error(u'cannot provision role "%s" (%s)', o['name'], o['uuid'])
logger.error('cannot provision role "%s" (%s)', o['name'], o['uuid'])
continue
if not created:
save = False
if role.name != role_name:
role.name = role_name
save = True
@ -178,8 +214,8 @@ class NotificationProcessing:
if role.description != o['description']:
role.description = o['description']
save = True
if role.details != o.get('details', u''):
role.details = o.get('details', u'')
if role.details != o.get('details', ''):
role.details = o.get('details', '')
save = True
if role.emails != o.get('emails', []):
role.emails = o.get('emails', [])
@ -193,12 +229,28 @@ class NotificationProcessing:
role.save()
except IntegrityError:
# Can happen if uuid and name already exist
logger.error(u'cannot provision role "%s" (%s)', o['name'], o['uuid'])
logger.error('cannot provision role "%s" (%s)', o['name'], o['uuid'])
continue
if created:
logger.info('provisionned new role %s (%s)', o['name'], o['uuid'])
if save:
logger.info('updated role %s (%s)', o['name'], o['uuid'])
if full and action == 'provision':
Role.objects.exclude(uuid__in=uuids).delete()
qs = Role.objects.exclude(uuid__in=uuids)
logger.info(
'deprovisionning roles %s',
', '.join('%s (%s)' % (name, uuid) for name, uuid in qs.values_list('name', 'uuid')),
)
qs.delete()
for role in qs:
role.delete()
elif action == 'deprovision':
Role.objects.filter(uuid__in=uuids).delete()
qs = Role.objects.filter(uuid__in=uuids)
logger.info(
'deprovisionning roles %s',
', '.join('%s (%s)' % (name, uuid) for name, uuid in qs.values_list('name', 'uuid')),
)
qs.delete()
@classmethod
def provision(cls, object_type, issuer, action, data, full):

View File

@ -2,9 +2,9 @@
import logging
import pytest
from django.db import connection
from django.test.utils import CaptureQueriesContext
import pytest
pytestmark = pytest.mark.django_db
@ -268,7 +268,7 @@ def test_hobo_notify_roles_db_queries(caplog, tenants):
}
with CaptureQueriesContext(connection) as ctx:
Command.process_notification(tenant, notification)
assert len(ctx.captured_queries) == 33
assert len(ctx.captured_queries) == 39
assert Group.objects.count() == 1
assert Role.objects.count() == 1
@ -338,7 +338,7 @@ def test_hobo_notify_roles_db_queries(caplog, tenants):
}
with CaptureQueriesContext(connection) as ctx:
Command.process_notification(tenant, notification)
assert len(ctx.captured_queries) == 15
assert len(ctx.captured_queries) == 18
assert Group.objects.count() == 0
assert Role.objects.count() == 0