gunicorn spends 80% of each request in get_object_permissions()

[heroin-moose]

NetBox version

v3.0.3

Python version

3.9

Steps to Reproduce

1. Configure Netbox with AD authentication (a few thousands users + heavy nesting)
2. Create a bunch of devices (~500 servers in my case, ~500 cables, ~50 VLANs, ~500 IP addresses, ~40 prefixes, ~40 racks in 3 sites)
3. Try to access https://netbox.example.com/dcim/devices/1234
4. See that gunicorn process is suddenly eats 100% CPU and the request takes more than a second

Expected Behavior

The request should be completed way faster.

Observed Behavior

For me the situtation looks like this: the HTTP request takes ~1.6s to complete and ~1.3s of that request was spent in authentication.py:get_object_permissions(). I am terrible with Python, but I came up with a patch:

@@ -11,6 +11,9 @@ from django.db.models import Q
 from users.models import ObjectPermission
 from utilities.permissions import permission_is_exempt, resolve_permission, resolve_permission_ct

+import time
+import syslog
+
 UserModel = get_user_model()


@@ -38,11 +42,18 @@ class ObjectPermissionMixin():

         # Create a dictionary mapping permissions to their constraints
         perms = defaultdict(list)
+        i = 0
+        start = time.time()
         for obj_perm in object_permissions:
             for object_type in obj_perm.object_types.all():
                 for action in obj_perm.actions:
                     perm_name = f"{object_type.app_label}.{action}_{object_type.model}"
                     perms[perm_name].extend(obj_perm.list_constraints())
+                    syslog.syslog(perm_name)
+                    i += 1
+        end = time.time()
+        t = end - start
+        syslog.syslog("took " + str(t) + " seconds with " + str(i) + " iterations")

         return perms

The output:

Sep 29 22:55:18 netbox.example.com gunicorn[78629]: took 1.325146198272705 seconds with 10397 iterations

Wow. That's a lot. Okay, more dirty patching:

@@ -24,7 +27,7 @@ class ObjectPermissionMixin():
         return user_obj._object_perm_cache

     def get_permission_filter(self, user_obj):
-        return Q(users=user_obj) | Q(groups__user=user_obj)
+        return Q(users=user_obj)

     def get_object_permissions(self, user_obj):
         """

And now I have this:

Sep 29 22:57:51 netbox.example.com gunicorn[78889]: took 0.17675495147705078 seconds with 1126 iterations

Still a lot (the request itself took ~400ms), but a lot better.

I'm not familiar with Netbox internals at all, so I'm not sure where to start digging.

[jeremystretch]

Nice sleuthing! This looks related to (if not the same root issue as) #6926. Do you agree?

Also, can you confirm whether this is reproducible using local authentication, or only as an LDAP user?

[heroin-moose]

Nice sleuthing! This looks related to (if not the same root issue as) #6926. Do you agree?

I'm not sure, but looks related. AUTH_LDAP_FIND_GROUP_PERMS does not help me either.

Also, can you confirm whether this is reproducible using local authentication, or only as an LDAP user?

Can I enable both AD and local?

[jeremystretch]

Sure. I mean, does it happen if you log in as a user with a local NetBox account? (One defined under admin > users.)

[heroin-moose]

Trying to remember the password for netbox user...

[heroin-moose]

No, it does not happen, NetBox is much more responsive and this function is not called at all.

[heroin-moose]

Any other info you need?

[kkthxbye-code]

To add to this, we experienced probably the same problem. I didn't have time to debug the issue, but for us it was caused by the way our permissions were structured.

We had a netbox-user and a netbox-admin group mapped by LDAP. Each group had an individual object permission for view, change, delete:

• delete_rack
• view_rack
• change_rack
• view_device
• change_device
  etc.

These were assigned to the groups (all of the for the admin group and all except adminish tasks for the other group). These permissions were created by netbox at one point (or netbox_docker?) at around v2.7, but netbox does not seem to seed the permissions anymore on fresh installs. I solved the issue on our end by just creating two larger permissions, one called all_permissions and one all_permissions_except_admin, then response time was fast for both local and ldap users.

In summation, the issue with our deployment was pre-seeded individual object permissions assigned to the mapped ldap group (around 300 permissions I think).

[heroin-moose]

If I do understand correctly the root issue is not the fact that get_object_permissions() loops 10k times. The problem is that it does so on every request (i.e. it's not cached). Am I right, @jeremystretch?

[heroin-moose]

So, anything else I can do to help you fix this?

[jeremystretch]

@heroin-moose you're certainly welcome to volunteer a fix, if you can identify one that doesn't break the behavior of permissions.

[heroin-moose]

Can you describe the intended algorithm behind this function? Is my assumption that it shall not called on each request, but cached instead, correct?

[jeremystretch]

I'm sorry, I don't have any time to budget on this particular problem right now. Maybe you can track down the person who wrote it.