Missing object change webhooks and change logs when running Netbox in multi-threading mode

[haminhcong]

NetBox version

v3.2.3

Python version

3.8

Steps to Reproduce

1. Create a VM with Ubuntu 20.04 Server Image and IP, example 192.168.122.126, install python3.8-venv, python3-dev and gcc packages.
2. Install nginx: sudo apt install nginx
3. Disable ufw: sudo ufw disable
4. Create a working directory, example /home/testuser01
5. Clone netbox repo and checkout version v3.2.3

git clone https://github.com/netbox-community/netbox.git
git checkout v3.2.3
cd  netbox

6. Create virtual environment and install dependencies & uwsgi (or gunicorn if you test with gunicorn)

cd /home/testuser01/netbox
python3.8 -m venv venv
source venv/bin/activate
pip install -r requirements.txt
pip install uwsgi==2.0.20

7. Create redis and postgres database in VM with port 6379 and 5432
8. Create netbox/netbox/configuration.py file

#########################
#                       #
#   Required settings   #
#                       #
#########################

# This is a list of valid fully-qualified domain names (FQDNs) for the NetBox server. NetBox will not permit write
# access to the server via any other hostnames. The first FQDN in the list will be treated as the preferred name.
#
# Example: ALLOWED_HOSTS = ['netbox.example.com', 'netbox.internal.local']
ALLOWED_HOSTS = ['*']

# PostgreSQL database configuration. See the Django documentation for a complete list of available parameters:
#   https://docs.djangoproject.com/en/stable/ref/settings/#databases
DATABASE = {
    'NAME': 'netbox',         # Database name
    'USER': 'netbox',               # PostgreSQL username
    'PASSWORD': 'J5brHrAXFLQSif0K',           # PostgreSQL password
    'HOST': 'localhost',      # Database server
    'PORT': '5432',               # Database port (leave blank for default)
    'CONN_MAX_AGE': 300,      # Max database connection age
}

# Redis database settings. Redis is used for caching and for queuing background tasks such as webhook events. A separate
# configuration exists for each. Full connection details are required in both sections, and it is strongly recommended
# to use two separate database IDs.
REDIS = {
    'tasks': {
        'HOST': 'localhost',
        'PORT': 6379,
        # Comment out `HOST` and `PORT` lines and uncomment the following if using Redis Sentinel
        # 'SENTINELS': [('mysentinel.redis.example.com', 6379)],
        # 'SENTINEL_SERVICE': 'netbox',
        'PASSWORD': 'H733Kdjndks81',
        'DATABASE': 0,
        'SSL': False,
        # Set this to True to skip TLS certificate verification
        # This can expose the connection to attacks, be careful
        # 'INSECURE_SKIP_TLS_VERIFY': False,
    },
    'caching': {
        'HOST': 'localhost',
        'PORT': 6379,
        # Comment out `HOST` and `PORT` lines and uncomment the following if using Redis Sentinel
        # 'SENTINELS': [('mysentinel.redis.example.com', 6379)],
        # 'SENTINEL_SERVICE': 'netbox',
        'PASSWORD': 'H733Kdjndks81',
        'DATABASE': 1,
        'SSL': False,
        # Set this to True to skip TLS certificate verification
        # This can expose the connection to attacks, be careful
        # 'INSECURE_SKIP_TLS_VERIFY': False,
    }
}

# This key is used for secure generation of random numbers and strings. It must never be exposed outside of this file.
# For optimal security, SECRET_KEY should be at least 50 characters in length and contain a mix of letters, numbers, and
# symbols. NetBox will not run without this defined. For more information, see
# https://docs.djangoproject.com/en/stable/ref/settings/#std:setting-SECRET_KEY
SECRET_KEY = 'r8OwDznj!!dci#P9ghmRfdu1Ysxm0AiPeDCQhKE+N_rClfWNj'


#########################
#                       #
#   Optional settings   #
#                       #
#########################

# Specify one or more name and email address tuples representing NetBox administrators. These people will be notified of
# application errors (assuming correct email settings are provided).
ADMINS = [
    # ('John Doe', '[email protected]'),
]

# Enable any desired validators for local account passwords below. For a list of included validators, please see the
# Django documentation at https://docs.djangoproject.com/en/stable/topics/auth/passwords/#password-validation.
AUTH_PASSWORD_VALIDATORS = [
    # {
    #     'NAME': 'django.contrib.auth.password_validation.MinimumLengthValidator',
    #     'OPTIONS': {
    #         'min_length': 10,
    #     }
    # },
]

# Base URL path if accessing NetBox within a directory. For example, if installed at https://example.com/netbox/, set:
# BASE_PATH = 'netbox/'
BASE_PATH = ''

# API Cross-Origin Resource Sharing (CORS) settings. If CORS_ORIGIN_ALLOW_ALL is set to True, all origins will be
# allowed. Otherwise, define a list of allowed origins using either CORS_ORIGIN_WHITELIST or
# CORS_ORIGIN_REGEX_WHITELIST. For more information, see https://github.com/ottoyiu/django-cors-headers
CORS_ORIGIN_ALLOW_ALL = False
CORS_ORIGIN_WHITELIST = [
    # 'https://hostname.example.com',
]
CORS_ORIGIN_REGEX_WHITELIST = [
    # r'^(https?://)?(\w+\.)?example\.com$',
]

# Set to True to enable server debugging. WARNING: Debugging introduces a substantial performance penalty and may reveal
# sensitive information about your installation. Only enable debugging while performing testing. Never enable debugging
# on a production system.
DEBUG = False

# Email settings
EMAIL = {
    'SERVER': 'localhost',
    'PORT': 25,
    'USERNAME': '',
    'PASSWORD': '',
    'USE_SSL': False,
    'USE_TLS': False,
    'TIMEOUT': 10,  # seconds
    'FROM_EMAIL': '',
}

# Exempt certain models from the enforcement of view permissions. Models listed here will be viewable by all users and
# by anonymous users. List models in the form `<app>.<model>`. Add '*' to this list to exempt all models.
EXEMPT_VIEW_PERMISSIONS = [
    # 'dcim.site',
    # 'dcim.region',
    # 'ipam.prefix',
]

# HTTP proxies NetBox should use when sending outbound HTTP requests (e.g. for webhooks).
# HTTP_PROXIES = {
#     'http': 'http://10.10.1.10:3128',
#     'https': 'http://10.10.1.10:1080',
# }

# IP addresses recognized as internal to the system. The debugging toolbar will be available only to clients accessing
# NetBox from an internal IP.
INTERNAL_IPS = ('127.0.0.1', '::1')

# Enable custom logging. Please see the Django documentation for detailed guidance on configuring custom logs:
#   https://docs.djangoproject.com/en/stable/topics/logging/
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False, 
    'formatters': {
        'standard': {
            'format': '{levelname} {name} {message}',
            'style': '{',
        },
    },
}

LOGGING['handlers'] = {
    'console': {
        'level': 'DEBUG',
        'class': 'logging.StreamHandler',
        'formatter': 'standard'
    }
}
LOGGING['loggers'] = {
    '': {
        'handlers': ['console'],
        'level': 'INFO',
        'propagate': True,
    },
    'django': {
        'handlers': ['console'],
        'level': 'INFO',
        'propagate': True,
    },
    'django.request': {
        'handlers': ['console'],
        'level': 'INFO',
        'propagate': True
    },
    'django.server': {
        'handlers': ['console'],
        'level': 'INFO',
        'propagate': True
    },
    'gunicorn.access': {
        'level': 'INFO',
        'handlers': ['console'],
        'propagate': False
    },
    "gunicorn.error": {
        'level': 'INFO',
        'handlers': ['console'],
        'propagate': False
    }
}


# Automatically reset the lifetime of a valid session upon each authenticated request. Enables users to remain
# authenticated to NetBox indefinitely.
LOGIN_PERSISTENCE = False

# Setting this to True will permit only authenticated users to access any part of NetBox. By default, anonymous users
# are permitted to access most data in NetBox but not make any changes.
LOGIN_REQUIRED = False

# The length of time (in seconds) for which a user will remain logged into the web UI before being prompted to
# re-authenticate. (Default: 1209600 [14 days])
LOGIN_TIMEOUT = None

# The file path where uploaded media such as image attachments are stored. A trailing slash is not needed. Note that
# the default value of this setting is derived from the installed location.
# MEDIA_ROOT = '/opt/netbox/netbox/media'

# By default uploaded media is stored on the local filesystem. Using Django-storages is also supported. Provide the
# class path of the storage driver in STORAGE_BACKEND and any configuration options in STORAGE_CONFIG. For example:
# STORAGE_BACKEND = 'storages.backends.s3boto3.S3Boto3Storage'
# STORAGE_CONFIG = {
#     'AWS_ACCESS_KEY_ID': 'Key ID',
#     'AWS_SECRET_ACCESS_KEY': 'Secret',
#     'AWS_STORAGE_BUCKET_NAME': 'netbox',
#     'AWS_S3_REGION_NAME': 'eu-west-1',
# }

# Expose Prometheus monitoring metrics at the HTTP endpoint '/metrics'
METRICS_ENABLED = False

# Enable installed plugins. Add the name of each plugin to the list.
PLUGINS = []

# Plugins configuration settings. These settings are used by various plugins that the user may have installed.
# Each key in the dictionary is the name of an installed plugin and its value is a dictionary of settings.
# PLUGINS_CONFIG = {
#     'my_plugin': {
#         'foo': 'bar',
#         'buzz': 'bazz'
#     }
# }

# Remote authentication support
REMOTE_AUTH_ENABLED = False
REMOTE_AUTH_BACKEND = 'netbox.authentication.RemoteUserBackend'
REMOTE_AUTH_HEADER = 'HTTP_REMOTE_USER'
REMOTE_AUTH_AUTO_CREATE_USER = True
REMOTE_AUTH_DEFAULT_GROUPS = []
REMOTE_AUTH_DEFAULT_PERMISSIONS = {}

# This repository is used to check whether there is a new release of NetBox available. Set to None to disable the
# version check or use the URL below to check for release in the official NetBox repository.
RELEASE_CHECK_URL = None
# RELEASE_CHECK_URL = 'https://api.github.com/repos/netbox-community/netbox/releases'

# The file path where custom reports will be stored. A trailing slash is not needed. Note that the default value of
# this setting is derived from the installed location.
# REPORTS_ROOT = '/opt/netbox/netbox/reports'

# Maximum execution time for background tasks, in seconds.
RQ_DEFAULT_TIMEOUT = 300

# The file path where custom scripts will be stored. A trailing slash is not needed. Note that the default value of
# this setting is derived from the installed location.
# SCRIPTS_ROOT = '/opt/netbox/netbox/scripts'

# The name to use for the session cookie.
SESSION_COOKIE_NAME = 'sessionid'

# By default, NetBox will store session data in the database. Alternatively, a file path can be specified here to use
# local file storage instead. (This can be useful for enabling authentication on a standby instance with read-only
# database access.) Note that the user as which NetBox runs must have read and write permissions to this path.
SESSION_FILE_PATH = None

# Time zone (default: UTC)
TIME_ZONE = 'UTC'

# Date/time formatting. See the following link for supported formats:
# https://docs.djangoproject.com/en/stable/ref/templates/builtins/#date
DATE_FORMAT = 'N j, Y'
SHORT_DATE_FORMAT = 'Y-m-d'
TIME_FORMAT = 'g:i a'
SHORT_TIME_FORMAT = 'H:i:s'
DATETIME_FORMAT = 'N j, Y g:i a'
SHORT_DATETIME_FORMAT = 'Y-m-d H:i'

9. Add log to Netbox handle_changed_object function in file netbox/extras/signals.py to check process result is correct or not

def handle_changed_object(sender, instance, **kwargs):
    """
    Fires when an object is created or updated.
    """
    if not hasattr(instance, 'to_objectchange'):
        return
    logger = logging.getLogger('object_change_handler')
    logger.info(f'Handle event object class {ContentType.objects.get_for_model(instance)} '
                f'with Object ID {instance.pk} changed!')

10. Collect statics: python netbox/manage.py collectstatic
11. Create uwsgi.ini config file for uwsgi in directory /home/testuser01/netbox

[uwsgi]
http-socket = :8001
protocol = http
module = netbox.wsgi
chdir=/home/testuser01/netbox/netbox
#mark the initial process as a master
master = true

# maximum number of worker processes
processes = 2
threads = 16
harakiri = 120
max-worker-lifetime = 3600           ; Restart workers after this many seconds
max-worker-lifetime-delta = 110
reload-on-rss = 320                 ; Restart workers after this much resident memory
evil-reload-on-rss = 352                 ; Restart workers after this much resident memory
worker-reload-mercy = 60             ; How long to wait before forcefully killing workers

listen = 1000 # set max connections to 1000 in uWSGI

die-on-term = true
lazy-apps = true ; safely init worker processes
vacuum = true   ; clear environment on exit

disable-logging = true
log-4xx = true
log-5xx = true

strict = false              ; Need to disable strict mode when using max-worker-lifetime-delta option

12. Run uwsgi process uwsgi --ini uwsgi.ini
13. Create new terminal, sudo to root user on VM, create nginx config file /etc/nginx/nginx.conf

worker_processes 1;

events {
    worker_connections 1024;
}

http {
    include              /etc/nginx/mime.types;
    default_type         application/octet-stream;
    sendfile             on;
    tcp_nopush           on;
    keepalive_timeout    65;
    gzip                 on;
    server_tokens        off;
    client_max_body_size 20M;


    server {
        listen      8080;

        location /static/ {
            alias /home/testuser01/netbox/netbox/static/;
        }

        location / {
            proxy_read_timeout 180;
            proxy_pass http://127.0.0.1:8001;
            proxy_set_header X-Forwarded-Host $http_host;
            proxy_set_header X-Real-IP $remote_addr;
            proxy_set_header X-Forwarded-Proto $scheme;
            add_header P3P 'CP="ALL DSP COR PSAa PSDa OUR NOR ONL UNI COM NAV"';
        }

        location /nginx_status {
            stub_status;
            allow 127.0.0.1;
        }
    }
}

14. Restart nginx service systemctl restart nginx
15. Access netbox from PC, example http://192.168.122.126:8080/
16. Login to netbox, create default device_type, device_role, site, rack. Create API Token
17. Add multiple devices (199 devices) concurrently by run multi-threaded python client

import concurrent.futures
import time

from netbox_api.api import netbox_app_api


def create_device(device_name):
    print(f'Creating Device {device_name}')
    created_device = netbox_app_api.netbox_devices_create(
        {
            'device_type': 1,
            'device_role': 1,
            'face': 'front',
            'site': 1,
            'rack': 1,
            'name': device_name
        }
    )

    return created_device


with concurrent.futures.ThreadPoolExecutor(
        max_workers=200
) as executor:
    # Start the load operations and mark each future with its URL
    result_sv_mapping = {
        executor.submit(create_device,
                        f'Device Index 1 {device_index}'): device_index  # noqa: E501
        for device_index in range(1, 200)
    }
    for result_t in concurrent.futures.as_completed(result_sv_mapping):  # noqa: E501
        netbox_device = result_sv_mapping[result_t]

1. Count total change log in uwsgi stdout, or count total change log created in Netbox after process done

Expected Behavior

• Have total 199 Device Created change logs on Netbox Change log
• Have total 199 Handle event object class prefix logs on Netbox uwsgi Stdout

Observed Behavior

• Less than 199 Device Created change logs on Netbox Change log
  
• Less than 199 Device Created change logs on Netbox uwsgi stdout log. For instance in one of my test, only 167 change events processed as following log recored (plese count number lines contains Handle event object class dcim): vm-scenario-log-missing-webhook.txt

[haminhcong]

Reason

After some experiments, I disabled disconnect method on change_logging context manager function

https://github.com/netbox-community/netbox/blob/v3.2.3/netbox/extras/context_managers.py#L12

@contextmanager
def change_logging(request):
    """
    Enable change logging by connecting the appropriate signals to their receivers before code is run, and
    disconnecting them afterward.

    :param request: WSGIRequest object with a unique `id` set
    """
    set_request(request)
    thread_locals.webhook_queue = []

    # Connect our receivers to the post_save and post_delete signals.
    post_save.connect(handle_changed_object, dispatch_uid='handle_changed_object')
    m2m_changed.connect(handle_changed_object, dispatch_uid='handle_changed_object')
    pre_delete.connect(handle_deleted_object, dispatch_uid='handle_deleted_object')
    clear_webhooks.connect(clear_webhook_queue, dispatch_uid='clear_webhook_queue')

    yield

    # Disconnect change logging signals. This is necessary to avoid recording any errant
    # changes during test cleanup.
    # post_save.disconnect(handle_changed_object, dispatch_uid='handle_changed_object')
    # m2m_changed.disconnect(handle_changed_object, dispatch_uid='handle_changed_object')
    # pre_delete.disconnect(handle_deleted_object, dispatch_uid='handle_deleted_object')
    # clear_webhooks.disconnect(clear_webhook_queue, dispatch_uid='clear_webhook_queue')

    # Flush queued webhooks to RQ
    flush_webhooks(thread_locals.webhook_queue)
    del thread_locals.webhook_queue

    # Clear the request from thread-local storage
    set_request(None)

then rebuild container and re-run concurrent test and recored result. And this time I recorded total 199 Object Change created in netbox container log and netbox Change Log

log-has-enough-webhook.txt

I think that the reason for this problem is when re-entrant, post_save.disconnect, m2m_changed.disconnect is not thread-safe and changing global state, so other thread in same process with post_save.disconnect, m2m_changed.disconnect caller is losing connecting with handle_changed_object function (because post_save.disconnect deleted this connection), then the result is we losing some object changes when run netbox v3.2.3 in multi-threaded wsgi server.

Referrence: https://stackoverflow.com/a/69401372

[haminhcong]

More information:

The post_save, m2m_changed, pre_delete are global variables objects in Django, it means that these variables is shared between threads. Because of that, if you change this variable in one theard, this will be also affect to other threads in same process.

https://github.com/django/django/blob/4.0.4/django/db/models/signals.py#L42

pre_init = ModelSignal(use_caching=True)
post_init = ModelSignal(use_caching=True)

pre_save = ModelSignal(use_caching=True)
post_save = ModelSignal(use_caching=True)

pre_delete = ModelSignal(use_caching=True)
post_delete = ModelSignal(use_caching=True)

m2m_changed = ModelSignal(use_caching=True)

pre_migrate = Signal()
post_migrate = Signal()

[jeremystretch]

Build Netbox Container Image with multi-threaded supported wsgi (gunicorn or uwsgi)

This repo accepts issues for the core NetBox project only. If you are using the Docker image, please file any issues under that repo. If you are able to replicate the problem using NetBox core only, please rewrite your issue above to provide the steps to do so.

[haminhcong]

Build Netbox Container Image with multi-threaded supported wsgi (gunicorn or uwsgi)

This repo accepts issues for the core NetBox project only. If you are using the Docker image, please file any issues under that repo. If you are able to replicate the problem using NetBox core only, please rewrite your issue above to provide the steps to do so.

Hi Jeremy @jeremystretch, I tested with uwsgi multi-thread with Netbox Core on a VM environment and see the same result I reported earlier (Object Change count less than 199). You can install uwsgi on a VM, run uwsgi --ini uwsgi.ini then run my test script to check result. Or if you test with gunicorn you will also get the same result. Docker Container Image isn't problem in this issue.

I rewrited issue content to provide the steps to test my scenario with Netbox Core on Ubuntu 20.04 environment.

[github-actions]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. NetBox is governed by a small group of core maintainers which means not all opened issues may receive direct feedback. Do not attempt to circumvent this process by "bumping" the issue; doing so will result in its immediate closure and you may be barred from participating in any future discussions. Please see our contributing guide.

[srfwx]

Hi,
I think I'm experiencing the same issue on our NetBox instance running on AWS.

Steps to reproduce the issue for me:

1. Perform a bulk update via the API on a small number of records
2. At the same time open a few pages from the GUI (can be any page: interface, device, log entry, ....)
3. The number of log entries for record changed is less than the number of records in the bulk update
4. All records have however correctly been updated (can be seen from the last_updated field)

Here's the script I use to reproduce the issue:

#!/usr/bin/env bash

force_update () {
  RECORDS=$(curl -ks -X PATCH ${NETBOX_URL}api/dcim/interfaces/ \
       -H "Authorization: Token $NETBOX_TOKEN" \
       -H 'Content-Type: application/json' \
       -H 'Accept: application/json' \
       -d '[{"id": 530438}, {"id": 530484}, {"id": 529117}, {"id": 529149}]') 
  RECORDS_NBR=$(echo $RECORDS | jq -r '. | length')
}

count_updates() {
  RECORDS=$(curl -ks \
      -H "Authorization: Token $NETBOX_TOKEN" \
      -H 'Accept: application/json' \
      "${NETBOX_URL}api/extras/object-changes/?changed_object_type=dcim.Interface&action=update&time_after=$1")
  CHANGES_COUNT=$(echo $RECORDS | jq -r '.count')
}

while true
do
    TIMESTAMP=$(date -u +"%Y-%m-%dT%H:%M:%SZ")
    echo Starting at $TIMESTAMP
    force_update
    count_updates "$TIMESTAMP"
    echo $RECORDS_NBR records updated, $CHANGES_COUNT log entries found
    if [[ "$RECORDS_NBR" != "$CHANGES_COUNT" ]]
    then
	echo ERROR FOUND
	exit 1
    fi
    sleep 1
done

In the example above I update 4 interfaces, but it can be other objects, you must change the ids to match proper records in your database though.
When started, the script will happily loop for a while. Then I am able to trigger the exit statement by going to NetBox GUI, and doing a bunch of "CTRL-CLICK" in a row (to any single URL usually).

Here's my current gunicorn config:

bind = '127.0.0.1:8001'
workers = 3
threads = 8
timeout = 600
max_requests = 300
max_requests_jitter = 50

I confirm that the proposed changes to def change_logging seem to work for me too. I am then not able to trigger the issue anymore. I am however not sure if it is safe to leave it running like this?

Thanks @haminhcong for your findings, and as this is my first contribution I want to express my appreciation for @jeremystretch amazing work on this project!

[kkthxbye-code]

I am however not sure if it is safe to leave it running like this?

Removing the disconnect from the context manager means that the already connected receivers are connected again on each request. I guess it would also mean that the receivers are always connected instead of being connected on each request (and report/script execution).

I'm sure it works, but it's not the correct solution.

@jeremystretch will have to chime in regarding the intention of the context manager, I'm not sure what the history is behind this comment:

netbox/netbox/extras/context_managers.py

Lines 30 to 31 in a397ce2

	# Disconnect change logging signals. This is necessary to avoid recording any errant
	# changes during test cleanup.

Until then I would advise you to set threads to 1 and scale workers up instead.

[github-actions]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. NetBox is governed by a small group of core maintainers which means not all opened issues may receive direct feedback. Do not attempt to circumvent this process by "bumping" the issue; doing so will result in its immediate closure and you may be barred from participating in any future discussions. Please see our contributing guide.

[jeremystretch]

I just pushed branch 9439-multi-threading, which replaces thread-local storage with context vars within the context manager. @haminhcong @srfwx are either of you available to help test? So far I've not been able to reproduce the problem locally.

[haminhcong]

@jeremystretch Hi Jeremy, I think your solution in 9439-multi-threading is good. I tested with branch 9439-multi-threading and branch develop and here is the result

Branch develop

• Run netbox with uwsgi multi threading (2 workers, 16 threads per worker)
• Create 200 Devices concurrently
• Only 180 change logs were recorded

Branch 9439-multi-threading

• Run netbox with uwsgi multi threading (2 workers, 16 threads per worker)
• Create 200 Devices concurrently
• All 200 change logs were recorded

@srfwx can you test Jeremy solution with your tests to confirm that the problem is resolved? Thank you.

[jeremystretch]

Excellent, thank you for taking the time to test @haminhcong!