netbox
netbox copied to clipboard
Missing object change webhooks and change logs when running Netbox in multi-threading mode
NetBox version
v3.2.3
Python version
3.8
Steps to Reproduce
- Create a VM with Ubuntu 20.04 Server Image and IP, example
192.168.122.126
, installpython3.8-venv
,python3-dev
andgcc
packages. - Install nginx:
sudo apt install nginx
- Disable ufw:
sudo ufw disable
- Create a working directory, example
/home/testuser01
- 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
- 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
- Create redis and postgres database in VM with port
6379
and5432
- 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'
- Add log to Netbox
handle_changed_object
function in filenetbox/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!')
- Collect statics:
python netbox/manage.py collectstatic
- 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
- Run uwsgi process
uwsgi --ini uwsgi.ini
- 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;
}
}
}
- Restart nginx service
systemctl restart nginx
- Access netbox from PC, example
http://192.168.122.126:8080/
- Login to netbox, create default device_type, device_role, site, rack. Create API Token
- 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]
- 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 containsHandle event object class dcim
): vm-scenario-log-missing-webhook.txt
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
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
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()
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.
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.
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.
Hi, I think I'm experiencing the same issue on our NetBox instance running on AWS.
Steps to reproduce the issue for me:
- Perform a bulk update via the API on a small number of records
- At the same time open a few pages from the GUI (can be any page: interface, device, log entry, ....)
- The number of log entries for record changed is less than the number of records in the bulk update
- 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!
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:
https://github.com/netbox-community/netbox/blob/a397ce234aa0edf9d93b158d7f37fdbb548d6cf8/netbox/extras/context_managers.py#L30-L31
Until then I would advise you to set threads to 1 and scale workers up instead.
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.
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.
@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.
Excellent, thank you for taking the time to test @haminhcong!