investigation of unauthorized (public) queries (get_objects_for_user)

added to epic &10

Okay first, establish a baseline. I'm doing this on the production box because there's lots of exposed objects. Let's look at the following scenario: the AnonymousUser and a normie LVK user (I can't use my own account since is_superuser bypasses much of django's permission structures). I'm going to volunteer @patrick.godwin's account as a guinea pig. I'm also going to restrict my permissions changes to MDC superevents so i don't interfere with any production data.

As such, I'm going to filter the log objects (and by proxy, files, comments, etc) for MS230519q and and time for AnonymousUser and patrick:

In [1]: from aws_xray_sdk.core import xray_recorder
   ...: xray_recorder.begin_segment("Migration Segment")
Out[1]: <aws_xray_sdk.core.models.segment.Segment at 0x7fd0648075f8>

In [2]: from superevents.models import Superevent, Log

In [3]: from django.contrib.auth.models import User, Group, Permission

In [4]:  an = User.objects.get(username='AnonymousUser')

In [5]: pg = User.objects.get(username='patrick.godwin@ligo.org')

In [6]: from guardian.shortcuts import get_objects_for_user

In [7]: ms = Superevent.get_by_date_id('MS230519q')

In [8]: ms.log_set.count()
Out[8]: 183

So that superevent has 183 log objects. Let's confirm that patrick can see all of them, and how long it takes. Note that viewing a log carries with it the superevents.view_log permission:

In [11]: %time get_objects_for_user(pg, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 3.11 ms, sys: 4 µs, total: 3.11 ms
Wall time: 8.71 ms
Out[11]: 183

In [12]: %time get_objects_for_user(pg, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 2.9 ms, sys: 49 µs, total: 2.94 ms
Wall time: 9.15 ms
Out[12]: 183

In [13]: %time get_objects_for_user(pg, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 2.13 ms, sys: 841 µs, total: 2.97 ms
Wall time: 6.66 ms
Out[13]: 183

So we're confirming that it takes patrick around 6-9ms to view all 183 logs. Now let's try for the AnonymousUser. First, how many objects have the "public tag? Because the public_users view permission gets added when tag is added:

In [14]: ms.log_set.filter(tags__name='public').count()
Out[14]: 27

Let's confirm that the anonymous user can fetch 27 objects, and how long it takes:

In [15]: %time get_objects_for_user(an, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 9.44 ms, sys: 1.01 ms, total: 10.5 ms
Wall time: 881 ms
Out[15]: 27

In [16]: %time get_objects_for_user(an, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 5.3 ms, sys: 1.06 ms, total: 6.36 ms
Wall time: 550 ms
Out[16]: 27

In [17]: %time get_objects_for_user(an, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 6.54 ms, sys: 160 µs, total: 6.7 ms
Wall time: 705 ms
Out[17]: 27

There. Using this function gets the same number of objects, but it's 100x slower...

digging in more.

so lvk users should be part of the internal_users group, and anonymoususer should be part of the public_users group. Let's confirm, then look at their permissions:

In [18]: an.groups.all()
Out[18]: <QuerySet [<Group: public_users>]>

In [19]: pg.groups.all()
Out[19]: <QuerySet [<Group: internal_users>]>

In [20]: pu=an.groups.first()

In [22]: iu=pg.groups.first()

In [23]: iu.permissions.all()
Out[23]: <QuerySet [<Permission: superevents | labelling | Can add labelling>, <Permission: superevents | labelling | Can delete labelling>, <Permission: superevents | log | Add tag to log>, <Permission: superevents | log | Remove tag from log>, <Permission: superevents | log | Can view log>, <Permission: superevents | signoff | Can view signoff>, <Permission: superevents | superevent | Can add test superevent>, <Permission: superevents | superevent | Can add log messages and EM observation data to uperevent>, <Permission: superevents | superevent | Can change test superevent>, <Permission: superevents | superevent | Can confirm test superevent as GW>, <Permission: superevents | superevent | Can view superevent>, <Permission: superevents | superevent group object permission | Can view superevent groupobjectpermission>, <Permission: superevents | vo event | Can add vo event>]>

In [24]: pu.permissions.all()
Out[24]: <QuerySet []>

huh, so the public_users group doesn't have any permissions associated with it. let's take that as granted to see what difference it makes. What about the groupobjectpermissions for a private vs an exposed log message?

In [27]: private_log = ms.log_set.last()

In [28]: private_log.comment
Out[28]: 'Superevent created with t_start=1368550707.765985, t_0=1368550708.765985, t_end=1368550709.765985, preferred_event=M407459'

In [29]: private_log.tags.all()
Out[29]: <QuerySet []>

In [30]: private_log.loggroupobjectpermission_set.all()
Out[30]: <QuerySet []>

In [31]: public_log = ms.log_set.filter(tags__name='public').last()

In [32]: public_log.comment
Out[32]: 'Source classification copied from M407459'

In [33]: public_log.tags.all()
Out[33]: <QuerySet [<Tag: LV-EM>, <Tag: Public>, <Tag: p_astro>]>

In [34]: public_log.loggroupobjectpermission_set.all()
Out[34]: <QuerySet [<LogGroupObjectPermission: Log object (6269523) | public_users | view_log>, <LogGroupObjectPermission: Log object (6269523) | lvem_observers | view_log>]>

okay, so the public-facing log DOES have the permission required for the public (and lvem, but that's redundant) to view it. And note that the GroupObjectPermission is (obviously) tied to the public_users group.

I think for some reason, instead of filtering for the small set of logs that have the permission, get_objects_for_user might be getting the list of ALL log objects that have the permission, and then filtering from there? that seems backward. But also explain analyze (#249 (comment 689232)) was filtering O(100,000) rows, so i'm not sure.

continuing step 1: mitigation. What happens if i remove the public permissions from old log messages? so basically hiding old (older than one month?) annotations.

if I have to recreate these permissions by hand, I did the following on dev1 as an experiment. First i retrieved a public log:

In [29]: public_log.loggroupobjectpermission_set.all()
Out[29]: <QuerySet [<LogGroupObjectPermission: Log object (4400264) | public_users | view_log>, <LogGroupObjectPermission: Log object (4400264) | lvem_observers | view_log>]>

and then examined the three necessary components of the LogGroupObjectPermission for the log with id = 4400264:

In [32]: LogGroupObjectPermission.objects.filter(content_object_id=4400264)
Out[32]: <QuerySet [<LogGroupObjectPermission: Log object (4400264) | public_users | view_log>, <LogGroupObjectPermission: Log object (4400264) | lvem_observers | view_log>]>

In [33]: for i in LogGroupObjectPermission.objects.filter(content_object_id=4400264):
    ...:     print(i.permission)
    ...:
superevents | log | Can view log
superevents | log | Can view log

In [34]: p = LogGroupObjectPermission.objects.filter(content_object_id=4400264).first().permission

In [35]: p
Out[35]: <Permission: superevents | log | Can view log>

In [36]: p.__dict__
Out[36]:
{'_state': <django.db.models.base.ModelState at 0x7f3c622b6780>,
 'id': 129,
 'name': 'Can view log',
 'content_type_id': 35,
 'codename': 'view_log'}

That way, if you have the log id, then you recreate it if you have the id, the group, and the permission (superevent.view_log). Example:

In [38]: gop =  LogGroupObjectPermission.objects.filter(content_object_id=4400264).first()

In [39]: gop
Out[39]: <LogGroupObjectPermission: Log object (4400264) | public_users | view_log>

In [40]: gop.delete()
Out[40]: (1, {'superevents.LogGroupObjectPermission': 1})

In [41]: LogGroupObjectPermission.objects.filter(content_object_id=4400264)
Out[41]: <QuerySet [<LogGroupObjectPermission: Log object (4400264) | lvem_observers | view_log>]>

In [43]: new_gop = LogGroupObjectPermission.objects.create(content_object_id=4400264, group=Group.objects.get(name='public_users'), permission=p)

In [44]: LogGroupObjectPermission.objects.filter(content_object_id=4400264)
Out[44]: <QuerySet [<LogGroupObjectPermission: Log object (4400264) | lvem_observers | view_log>, <LogGroupObjectPermission: Log object (4400264) | public_users | view_log>]>

So what i'll do is i'll back up the log id, then delete the permissions.

So let's see how many mdc superevent, public-facing logs we have:

In [51]: from datetime import timedelta
    ...:
    ...: from django.utils.timezone import now
    ...:

In [52]: t_now = now()

In [53]: date_cutoff = t_now - timedelta(days=31)

In [54]: Log.objects.filter(superevent__category='M', tags__name='lvem', created__lt=date_cutoff)
Out[54]: <QuerySet [<Log: Log object (6111536)>, <Log: Log object (6111507)>, <Log: Log object (6111497)>, <Log: Log object (6111487)>, <Log: Log object (6111486)>, <Log: Log object (6111480)>, <Log: Log object (6111476)>, <Log: Log object (6111465)>, <Log: Log object (6111463)>, <Log: Log object (6111459)>, <Log: Log object (6111453)>, <Log: Log object (6111451)>, <Log: Log object (6111444)>, <Log: Log object (6111419)>, <Log: Log object (6111393)>, <Log: Log object (6111371)>, <Log: Log object (6111370)>, <Log: Log object (6111362)>, <Log: Log object (6111354)>, <Log: Log object (6111341)>, '...(remaining elements truncated)...']>

In [55]: Log.objects.filter(superevent__category='M', tags__name='lvem', created__lt=date_cutoff).count()
Out[55]: 639892

yeesh, okay. so i'm going to loop through and remove the permissions from all of those objects. might take a while so i'm running in a screen. hold on....

It could a couple hours to clear out the permissions, but it looks like it was worth it:

In [31]: %time get_objects_for_user(an, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 11.8 ms, sys: 1.08 ms, total: 12.9 ms
Wall time: 47.8 ms
Out[31]: 27

In [32]: %time get_objects_for_user(an, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 6.64 ms, sys: 0 ns, total: 6.64 ms
Wall time: 35 ms
Out[32]: 27

In [33]: %time get_objects_for_user(an, 'superevents.view_log', klass=ms.log_set.all()).count()
CPU times: user 7.87 ms, sys: 638 µs, total: 8.51 ms
Wall time: 68.4 ms
Out[33]: 27

10-20x faster, I'll take it as a bandaid. There has to be something else going on but this should help in the meantime.

Also here's a chart of database load over the past 24 hours, showing where i removed the view permission for the old log messages:

Getting ambitious over here, I did the same for superevent visibility:

In [20]: msevent_list = Superevent.objects.filter(created__lt=date_cutoff, category='M')

In [21]: msevent_list.count()
Out[21]: 35786

In [22]: for ms in msevent_list:
    ...:     print(ms.superevent_id)
    ...:     ms.supereventgroupobjectpermission_set.all().delete()

I'll monitor queries over the weekend, and will add this to the management tool.

mentioned in issue #301

mentioned in commit 38fb7162

mentioned in merge request !186 (merged)

mentioned in commit a01cfc54

mentioned in commit 57654c4f

mentioned in commit 0a86cf68

mentioned in merge request !209

mentioned in commit f1183539

mentioned in issue #346 (closed)

closed with merge request !186 (merged)

mentioned in issue #66

investigation of unauthorized (public) queries (get_objects_for_user)

Child items ...

Activity