Netbox Consuming 100% of CPU over time with LDAP authentication enabled

[nniehoff]

Environment

• Python version: 3.7.6
• NetBox version: 2.9.4

Steps to Reproduce

1. Configure LDAP authentication, following the documentation here using a Microsoft Active Directory server as the LDAP server. Some key configurations to note:
   1a. Our AUTH_LDAP_SERVER_URI is an ldaps endpoint.
   1b. AUTH_LDAP_GROUP_TYPE is set to NestedActiveDirectoryGroupType()
2. Log on/Log off several times over a several hour period

Expected Behavior

Netbox should run with no noticeable increase in CPU usage over time.

Observed Behavior

Over the course of several (appx 8 in our case) hours the CPU usage of uwsgi serving netbox increases gradually over time until it is using 100% of the CPU.

[jeremystretch]

1. This appears to be a duplicate of Excessive response times for LDAP user accounts #5192.
2. If it's not, you'll need to provide far more detail than "Configure LDAP authentication." Sharing your complete configuration and noting what you're using for LDAP authentication would be a good start.

[nniehoff]

To be more explicit about our LDAP configuration the entire contents are here with some redactions:

import os
import logging

from django_auth_ldap.config import LDAPGroupQuery, LDAPSearch, NestedActiveDirectoryGroupType
import ldap

# Instantiate logger
my_logger = logging.getLogger('django_auth_ldap')


# Server URI
# AUTH_LDAP_SERVER_URI = "ldaps://ad1-ldaps.example.com"
AUTH_LDAP_SERVER_URI = "ldaps://10.10.10.10"

# The following may be needed if you are binding to Active Directory.
AUTH_LDAP_CONNECTION_OPTIONS = {ldap.OPT_REFERRALS: 0}

# Set the DN and password for the NetBox service account.
AUTH_LDAP_BIND_DN = f"{os.environ.get('LDAP_USERNAME', '')}@example.com"
AUTH_LDAP_BIND_PASSWORD = os.environ.get("LDAP_PASSWORD", "")

# Include this setting if you want to ignore certificate errors. This might be needed to accept a self-signed cert.
# Note that this is a NetBox-specific setting which sets:
#     ldap.set_option(ldap.OPT_X_TLS_REQUIRE_CERT, ldap.OPT_X_TLS_NEVER)
LDAP_IGNORE_CERT_ERRORS = True

# This search matches users with the sAMAccountName equal to the provided username. This is required if the user's
# username is not in their DN (Active Directory).
AUTH_LDAP_USER_SEARCH = LDAPSearch(
    "dc=example,dc=com", ldap.SCOPE_SUBTREE, "(&(objectClass=user)(sAMAccountName=%(user)s))"
)

# If a user's DN is producible from their username, we don't need to search.
# AUTH_LDAP_USER_DN_TEMPLATE = "sAMAccountName=%(user)s,dc=example,dc=com"

# You can map user attributes to Django attributes as so.
AUTH_LDAP_USER_ATTR_MAP = {
    "first_name": "givenName",
    "last_name": "sn",
    "email": "mail",
}

# This search ought to return all groups to which the user belongs. django_auth_ldap uses this to determine group
# hierarchy.
AUTH_LDAP_GROUP_SEARCH = LDAPSearch(
    "dc=example,dc=com", ldap.SCOPE_SUBTREE, "(objectClass=group)"
)
AUTH_LDAP_GROUP_TYPE = NestedActiveDirectoryGroupType()

# Define a group required to login.
# AUTH_LDAP_REQUIRE_GROUP = "CN=Netbox-ReadOnly,OU=Resource_Groups,OU=Support - Netbox,OU=Infrastructure"

# Mirror LDAP group assignments.
AUTH_LDAP_MIRROR_GROUPS = True

# Define special user types using groups. Exercise great caution when assigning superuser status.
AUTH_LDAP_USER_FLAGS_BY_GROUP = {
    "is_active": (
        LDAPGroupQuery("CN=Netbox-ReadOnly,OU=Resource_Groups,OU=Support - Netbox,OU=Infrastructure Services,DC=example,DC=com") |
        LDAPGroupQuery("CN=Netbox-StandardAccess,OU=Resource_Groups,OU=Support - Netbox,OU=Infrastructure Services,DC=example,DC=com") |
        LDAPGroupQuery("CN=Netbox-Admins,OU=Resource_Groups,OU=Support - Netbox,OU=Infrastructure Services,DC=example,DC=com")
    ),
    "is_staff": "CN=Netbox-Admins,OU=Resource_Groups,OU=Support - Netbox,OU=Infrastructure Services,DC=example,DC=com",
    "is_superuser": "CN=DNetbox-Admins,OU=Resource_Groups,OU=Support - Netbox,OU=Infrastructure Services,DC=example,DC=com",
}

# For more granular permissions, we can map LDAP groups to Django groups.
AUTH_LDAP_FIND_GROUP_PERMS = True

# Cache groups for one hour to reduce LDAP traffic
AUTH_LDAP_CACHE_TIMEOUT = 3600

[nniehoff]

I created several flamegraphs to watch instrument the uwsgi processes which were running during the high CPU usage. I found a lot of time was being spent in authentication.py:177. I'm not sure why logging handlers are being created and added to the logger with every new instance of this class, it seems like the LOGGING configuration should be handled by the LOGGING configuration parameter in configuration.py. I did find removing the additional logging configuration in my environment has drastically helped my issue. I'm still monitoring for more data.

[nniehoff]

1. This appears to be a duplicate of Excessive response times for LDAP user accounts #5192.

I'm not sure this is a duplicate. I don't see any occurrence of "Initiating TLS" in my logs as is mentioned in the other issue. I've enabled debug logging in my environment with my changes from my PR. I'll continue to monitor and note any TLS related log entries.

2. If it's not, you'll need to provide far more detail than "Configure LDAP authentication." Sharing your complete configuration and noting what you're using for LDAP authentication would be a good start.

I hope the above provides enough detail about the configuration.

[jeremystretch]

I'm not sure why logging handlers are being created and added to the logger with every new instance of this class, it seems like the LOGGING configuration should be handled by the LOGGING configuration parameter in configuration.py.

I seem to recall some discussion way back when LDAP support was first added, where it was decided to intentionally force LDAP logging on the console because so many people experience problems with it, though I can't say for certain. (Note that the current LDAPBackend class was a complete copy & paste from the prior implementation within settings.py, so the logging code was simply copied over.)

I'm okay with removing the logging code if we clearly communicate the change to users, so that they are aware LDAP logging will need to be manually configured moving forward. However, I'd also like to be more certain that this is the underlying cause of the reported bug before doing so. If the logging code is the culprit, it seems unlikely that this bug would manifest in some LDAP-enabled instance but not others.

[nniehoff]

That's interesting about the logging from settings.py. I have another environment (my production environment) that is currently running 2.8.8. In that environment, I don't see the CPU usage but I do see some high memory usage occasionally which I'm still troubleshooting, I might have to look into this as well. I'll attach a flamegraph that is a good example of CPU time being spent at authentication.py:177. From the flamegraph you can see 87.8% of the time was spent here. This is what lead me down this path. I'm thinking the change in 2.9 we are now creating more instances of the LDAPBackend class which in turn is calling new more frequently than in 2.8. The flamegraph was captured using 50 samples/sec for 60 seconds.
flamegraph.zip

[nniehoff]

We have not seen any re-occurrence of high CPU usage in 48 hours after removing the logging configuration from authentication.py. I have DEBUG logging enabled for LDAP and I also see no occurrences of "initiating TLS" in the logs, I suspect this is due to LDAP_IGNORE_CERT_ERRORS = True in this environment. I'm thinking this is not a duplicate of #5192

[DanSheps]

I am going to mark this as a duplicate of #5199 then @nniehoff

[DanSheps]

Duplicate of #5199