Netbox API: request failed with code 500 - Cannot assing <SimpleLazyObject: <django.contrib.auth.models.AnonymousUser>>

[alinmear]

NetBox version

2.11.6

Python version

3.7

Steps to Reproduce

We have multiple Scripts that are running against our Netbox Instance. Some of them are utilizing read only tokens and others read_write tokens. From time to time the following exception occurs:

The request failed with code 500 Internal Server Error {'error': 'Cannot assign <SimpleLazyObject: <django.contrib.auth.models.AnonymousUser object at 0x7fe517e70780>>": "ObjectChange.user'" must be a "User" instance.', 'exception': 'ValueError', 'netbox_version': '2.11.6', 'python_version': '3.7.8'}

After that we have Changes on Objects with the change_user of the read_only token. Maybe there is any kind of race condition or something like that. Does anybody has an idea, how to further investigate this problem?

Expected Behavior

There is no exception and change user are not mixed with read_only user.

Observed Behavior

Exception occurs and change_user is read_only user

[jeremystretch]

This keeps coming up, and unfortunately has proven quite difficult to squash. How are you running NetBox? With gunicorn or uWSGI? Can you share your WSGI configuration?

The current understanding (I think) is that this bug can be side-stepped by limiting each worker to a single thread. @tyler-8 please correct me if that's wrong.

[robertpenz]

We are running on gunicorn with apache as reverse proxy for terminating TLS

gunicorn is running with the following:
workers = 9
threads = 9

Should we switch to wsgi?

[jeremystretch]

Try setting threads = 1

[tyler-8]

This keeps coming up, and unfortunately has proven quite difficult to squash. How are you running NetBox? With gunicorn or uWSGI? Can you share your WSGI configuration?

The current understanding (I think) is that this bug can be side-stepped by limiting each worker to a single thread. @tyler-8 please correct me if that's wrong.

Correct - one thread per worker-process on the NetBox server seems to resolve the issue for multi-threaded clients.

My hunch is that there's something that isn't thread-safe in the handling of either user API tokens for creating objects, or the object changelog process that's initiated from doing a write operation. At one point I was trying to test with uwsgi vs gunicorn on this issue to see if it made any difference but haven't had a chance to pick up that thread (lol) again.

[robertpenz]

Thx we will try that. We're quite able to reproduce that error with a stress test. We've one script that loops over all devices/vms and put them into a queue. This queue is worked on by 5-10 threads which first checks if the devices should be monitored and if yes loops over all interfaces of that switch/router and imports that to the monitoring system. (It does a little bit more, but that sums it up nicely). That script on its own works without a problem, but when another script is changing something at the same time we run into the problem. The easiest way to trigger the problem was to run a script with one thread which just changes the dnsname or description of all IP Addresses.

When you do that, you get 2 possible outcomes.

1. The change of the IP objects is sometimes attributed to the user of the script that does only read. At least in the webhook logs.
2. One of both scripts get an 500.

[tyler-8]

@alinmear @robertpenz would you both try this branch and see if you can still re-create the issue?

https://github.com/tyler-8/netbox/tree/objectchange_threadsafe

[Edit] Doesn't look like it's working as consistently as I initially thought.

[tyler-8]

I think the only way forward to fixing this for real is to use threading.local() similar to https://github.com/jazzband/django-auditlog or https://github.com/ninemoreminutes/django-crum/ (or just use django-crum itself depending on if @jeremystretch wants to take on a dependency).

Related reading I went through while digging in to this:

• https://stackoverflow.com/questions/6214509/is-django-middleware-thread-safe
• https://stackoverflow.com/questions/26240832/django-and-middleware-which-uses-request-user-is-always-anonymous/
• https://blog.roseman.org.uk/2010/02/01/middleware-post-processing-django-gotcha/
• https://stackoverflow.com/questions/20907631/are-django-signals-thread-safe

[tyler-8]

Okay - try the branch again with the current commit https://github.com/tyler-8/netbox/tree/objectchange_threadsafe . I've implemented a thread-lock for the change_logging context manager. Signal connections themselves aren't thread-safe, at least not in the way they're being used for the object change log.

[DanSheps]

@tyler-8 What affect might this have on NetBox overall (performance, etc)?

[tyler-8]

Threading in general should improve performance for most users by allowing gunicorn/NetBox to serve more users at a time more efficiently - especially on the HTTP GET side of things. This change would only impact write-operations (POST/PATCH/PUT), GETs are unaffected. Right now, anyone running gunicorn with threads = 1 would see zero difference, no matter the number of workers.

For users running threads > 1 they shouldn't see the error noted in OP (and other GitHub issues like #7696 ) but like all Python threading, there's likely a thread-count/per-worker of diminishing returns or where performance would suffer (though this is no different than before my change really). 2-4 threads per-worker seems like a good number since generally NetBox isn't very CPU intensive (at least on the gunicorn side).

My rough understanding is that signals and middleware have quirks when using a WSGI server with threaded workers. This change adds a lock around the change_logging context manager's tasks to make sure one request doesn't stomp on another somehow (which seems to be what was happening before). When there are concurrent write-operations happening, a lock introduces a slowdown, by design, to keep data accurate. Whether or not that difference is noticeable depends on the number of concurrent client connections doing write operations.

In the other two similar plugins I linked earlier, both rely on threading.Local() to ensure each thread has its own local storage for request data, which may also work, and require more complexity than I've gone with here. More testing is needed for sure though.

[jeremystretch]

I apologize for not keeping up this as well as I should have. (I've been focused on v3.1 feature work lately.) Allow me to summarize the conversation so far.

1. Is the current change logging middleware implementation thread-safe?

The working assumption is that no, it is not, hence the error reported above. @tyler-8's work appears to confirm this.

2. Can the current implementation be made thread-safe?

Per @tyler-8's proposed modification, probably.

3. Would this change have a significant negative performance impact?

My understanding is that wrapping the request processing inside threading.Lock() essentially effects single-threaded operation, but I may be mistaken. I need to do some reading on this topic. (Thanks for the links above, Tyler!)

4. Would an alternative solution using thread-local storage (TLS) be preferable?

IIRC we originally used TLS for the change logging middleware but moved away from it to resolve a similar bug. However, a lot has changed since then, and it may have been an error in the implementation. It's certainly worth taking another look at. I'm happy to draw inspiration from django-crum as a proven solution, though I'm not sure it makes sense to take on as a dependency, primarily because we also need to store the webhook queue and likely similar per-request data in the future.

(Please correct me if any of the above is wrong.)

[tyler-8]

1. I think it may be two truly separate issues related to threading; this one (and the previous ones like it "SimpleLazyObject") , and NetBox mixes authors of modifications in the changelog when there are a lot of concurrent modifications #7696 - which might be made thread-safe by simply using unique dispatch_uid's like `post_save.connect(handle_changed_object, dispatch_uid=f'handle_changed_object_{request.id}') - I just started testing with that.

It's possible that the threading.Lock() helped the mismatched author problem by ensuring only one series of signals were used at a time using the handle_changed_object name. If the UID is made truly unique, that issue looks like it may go away even with threads enabled and no Lock.

2. I certainly think so, just need to find the right combination. One solution isn't going to fix both problems I suspect.

3. The lock is a bottleneck, but wrapped around a potentially non-thread-safe operation, so the goal is to keep the amount of 'locked' work minimal. In this case it's only write operations that invoke the object change workflow. Even then - it's only for that one worker process, threads in other work processes don't share with threads in the "current" process. And as noted above, potentially solved another way for at least one of the two issues.

4. For the "SimpleLazyObject" issue, TLS may be required still. I need to do more test runs with the lock in place. "We" know how to re-create it (perform lots of concurrent write-operations with server threading enabled) but it doesn't happen 100% of the time - just due to the way the requests are being "load balanced" across the workers and threads.