Netbox Consuming 100% of CPU with LDAP authentication enabled

[nniehoff]

Environment

• Python version: 3.7.9
• NetBox version: 2.9.7

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()
   1c. LDAP_IGNORE_CERT_ERRORS = True
2. Start NetBox using uwsgi
3. Wait for a while and the CPU Usage will hit near 100%.

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

I believe the issue is from these lines as I have investigated several flame graphs (see #5194) and have seen the issue specifically line 177 using nearly all of the CPU time. Moving the logging configuration for authentication.py to the LOGGING parameter in configuration.py seems to address this issue in my environment.

Expected Behavior

NetBox should idle with very little CPU usage

Observed Behavior

NetBox idles with near 100% CPU usage

[DanSheps]

Moving the logging configuration for authentication.py to the LOGGING parameter in configuration.py seems to address this issue in my environment.

Could you explain this more?

[nniehoff]

In my environment I removed these lines, I then added the following to my configuration.py:

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "handlers": {
        'netbox_auth_log': {
            'level': 'DEBUG' if DEBUG else 'INFO',
            'class': 'logging.handlers.TimedRotatingFileHandler',
            'filename': '/var/log/netbox_auth.log',
            'when': 'midnight',
            'utc': True,
            'interval': 1,
            'backupCount': 5,
        },
    },
    'loggers': {
        'django_auth_ldap': {
            'handlers': ['netbox_auth_log'],
            'level': 'DEBUG' if DEBUG else 'INFO',
            'propagate': False,
        },
    },
}

I don't see any logging from django_auth_ldap in the log however, I only see logs from netbox.auth.* which I also have configured to use the same handler.

[jeremystretch]

I don't really have my head around this at the moment, but is the proposal to simply remove the hard-coded logging (lines 176-178) from LDAPBackend? That seems reasonable, provided users are still able to capture log messages originating from django_auth_ldap by modifying their LOGGING configuration locally.

[nniehoff]

I don't really have my head around this at the moment, but is the proposal to simply remove the hard-coded logging (lines 176-178) from LDAPBackend? That seems reasonable, provided users are still able to capture log messages originating from django_auth_ldap by modifying their LOGGING configuration locally.

Right, until today I thought my LOGGING configuration was working I'm still digging why I'm not seeing the django logs now.

[lampwins]

I have never understood why we have these manual logging lines in there, to begin with, but I have not spent any time digging into it.

[nniehoff]

Ok, this morning I was able to get ldap logs through to the logging handler as I described above. I am going to do a clean build just to make sure but I believe removing the 3 lines discussed and updating the docs should cover the change. I'm happy to do the work if you would like.