Erroneous invocations of Event Rules/Webhooks with M2M relationships

[peteeckel]

Deployment Type

Self-hosted

Software Versions

• NetBox >= 3.5, including the 4.0 track in the feature branch

Description

This is probably the most obscure issue I've filed for a long time, so I apologise up front for the difficulties in reproducing it. I did my best to minimise it, but "minimise" in that case means "bring it down to a really involved scenario with non-obvious circumstances". Nevertheless, it's a real issue and it finds one consequence in this issue for the NetBox DNS plugin.

In fact, after some analysis I could trace it down to a very specific situation: There is a problem with incorrectly created Webhooks when an M2M field is updated and the save() function of one of the models involved in the M2M relation causes other save() operations to occur after super().save(). This results in multiple invocations of a Webhook (or, in NetBox >= 4.0, an Event Rule) defined for that model, where the first invocation has wrong data.

Steps to reproduce

(this is where trouble starts)

To make reprocuing the issue easier, I created a test plugin that is a very stripped down version of the NetBox DNS plugin. The code can be found on GitHub.

• Start with a working NetBox instance, preferably from the current feature track
• Clone the test plugin from GitHub into a separate directory:

cd /<install dir>/
git clone https://github.com/peteeckel/netbox-test-plugin

• Install the test plugin in the NetBox instance, using an editable pip3 install:

/opt/netbox/venv/bin/python3 -m pip install -e /<install dir>/netbox-test-plugin/
Obtaining file:///<install dir>/netbox-test-plugin
  Installing build dependencies ... done
  Checking if build backend supports build_editable ... done
  Getting requirements to build editable ... done
  Preparing editable metadata (pyproject.toml) ... done
Building wheels for collected packages: netbox-test
  Building editable for netbox-test (pyproject.toml) ... done
  Created wheel for netbox-test: filename=netbox_test-0.0.1-py3-none-any.whl size=1225 sha256=9e63f8bcac499827ef8e8318b66d29ae0821211832dc09faa563b977d8cd4f23
  Stored in directory: /tmp/pip-ephem-wheel-cache-_bg6_cmf/wheels/c5/e0/a6/8fef4a82d11a698c7cf40511af87f78c6b4fc47d7fb2a25b65
Successfully built netbox-test
Installing collected packages: netbox-test
Successfully installed netbox-test-0.0.1

• Configure NetBox to use the test plugin by editing /<netbox install path>/netbox/netbox/configuration.py, run the migration and restart:

...
PLUGINS = [
    'netbox_test',
]
...

/opt/netbox/netbox/manage.py migrate
Operations to perform:
  Apply all migrations: account, auth, circuits, contenttypes, core, dcim, django_rq, extras, ipam, netbox_dns, netbox_test, sessions, social_django, taggit, tenancy, users, virtualization, vpn, wireless
Running migrations:
  Applying netbox_test.0001_initial... OK
systemctl restart netbox netbox-rq

• Verify that the plugin's navigation items are dislpayed under 'Plugins'. There should be entries for 'Test Nameservers' and 'Test Zones':

• Create some test data to work with. This is done most easily from nbshell:

/opt/netbox/netbox/manage.py nbshell
>>> from netbox_test.models import TestNameServer, TestZone
>>> TestNameServer.objects.create(name='ns1.example.com')
>>> TestNameServer.objects.create(name='ns2.example.com')
>>> TestZone.objects.create(name='zone1.example.com')

• Create a webhook definition for the Django test listener:

• Create an event rule for update events for the netbox_test.TestZone object type triggering the Webhook:

• Start the Django test listener:

/opt/netbox/netbox/manage.py webhook_receiver
Listening on port http://localhost:9000. Stop with CONTROL-C.

• Now edit the test zone zone1.example.com by adding one or two of the defined test name servers in the GUI and watch the test listener. It's crucial that this is done in the GUI! The result should be similar to this:

[1] Tue, 20 Feb 2024 10:02:49 GMT 127.0.0.1 "POST / HTTP/1.1" 200 -
Host: localhost:9000
Accept-Encoding: identity
User-Agent: python-urllib3/2.1.0
Content-Type: application/json
Content-Length: 893

{
    "event": "updated",
    "timestamp": "2024-02-20T10:02:49.828871+00:00",
    "model": "testzone",
    "username": "admin",
    "request_id": "26970ed9-74ab-4aa0-a971-4be8d2a74f18",
    "data": {
        "id": 1,
        "name": "zone1.example.com",
        "nameservers": [
            {
                "id": 1,
                "name": "ns1.example.com",
                "url": "/api/plugins/netbox_test/test-name-servers/1/",
                "display": "ns1.example.com"
            },
            {
                "id": 2,
                "name": "ns2.example.com",
                "url": "/api/plugins/netbox_test/test-name-servers/2/",
                "display": "ns2.example.com"
            }
        ],
        "url": "/api/plugins/netbox_test/test-zones/1/",
        "display": "zone1.example.com"
    },
    "snapshots": {
        "prechange": {
            "created": "2024-02-20T09:52:48.981Z",
            "name": "zone1.example.com",
            "nameservers": [],
            "custom_fields": {},
            "tags": []
        },
        "postchange": {
            "created": "2024-02-20T09:52:48.981Z",
            "last_updated": "2024-02-20T10:02:49.787Z",
            "name": "zone1.example.com",
            "nameservers": [
                1,
                2
            ],
            "custom_fields": {},
            "tags": []
        }
    }
}
Completed request #1
------------

• This is the correct behaviour, no problems yet.
• Edit /<install dir>/netbox-plugin-test/netbox_test/models.py, adding the following code to the TestZone model class:

def save(self, *args, **kwargs):
    super().save(*args, **kwargs)
    
    TestNameServer.objects.first().save()

• Restart NetBox
• Again, make any change to the list of name servers for the zone in the GUI, e.g. remove or add one name server. In the following example, I removed name server ns2.example.com. The resulting output of the test listener is now this:

[2] Tue, 20 Feb 2024 10:09:20 GMT 127.0.0.1 "POST / HTTP/1.1" 200 -
Host: localhost:9000
Accept-Encoding: identity
User-Agent: python-urllib3/2.1.0
Content-Type: application/json
Content-Length: 897

{
    "event": "updated",
    "timestamp": "2024-02-20T10:09:20.072952+00:00",
    "model": "testzone",
    "username": "admin",
    "request_id": "03714c43-832c-462e-b462-85973b545b8e",
    "data": {
        "id": 1,
        "name": "zone1.example.com",
        "nameservers": [
            {
                "id": 1,
                "name": "ns1.example.com",
                "url": "/api/plugins/netbox_test/test-name-servers/1/",
                "display": "ns1.example.com"
            },
            {
                "id": 2,
                "name": "ns2.example.com",
                "url": "/api/plugins/netbox_test/test-name-servers/2/",
                "display": "ns2.example.com"
            }
        ],
        "url": "/api/plugins/netbox_test/test-zones/1/",
        "display": "zone1.example.com"
    },
    "snapshots": {
        "prechange": {
            "created": "2024-02-20T09:52:48.981Z",
            "name": "zone1.example.com",
            "nameservers": [
                1,
                2
            ],
            "custom_fields": {},
            "tags": []
        },
        "postchange": {
            "created": "2024-02-20T09:52:48.981Z",
            "last_updated": "2024-02-20T10:09:20.017Z",
            "name": "zone1.example.com",
            "nameservers": [
                1,
                2
            ],
            "custom_fields": {},
            "tags": []
        }
    }
}
Completed request #2
------------
[3] Tue, 20 Feb 2024 10:09:20 GMT 127.0.0.1 "POST / HTTP/1.1" 200 -
Host: localhost:9000
Accept-Encoding: identity
User-Agent: python-urllib3/2.1.0
Content-Type: application/json
Content-Length: 770

{
    "event": "updated",
    "timestamp": "2024-02-20T10:09:20.080091+00:00",
    "model": "testzone",
    "username": "admin",
    "request_id": "03714c43-832c-462e-b462-85973b545b8e",
    "data": {
        "id": 1,
        "name": "zone1.example.com",
        "nameservers": [
            {
                "id": 1,
                "name": "ns1.example.com",
                "url": "/api/plugins/netbox_test/test-name-servers/1/",
                "display": "ns1.example.com"
            }
        ],
        "url": "/api/plugins/netbox_test/test-zones/1/",
        "display": "zone1.example.com"
    },
    "snapshots": {
        "prechange": {
            "created": "2024-02-20T09:52:48.981Z",
            "name": "zone1.example.com",
            "nameservers": [
                1,
                2
            ],
            "custom_fields": {},
            "tags": []
        },
        "postchange": {
            "created": "2024-02-20T09:52:48.981Z",
            "last_updated": "2024-02-20T10:09:20.017Z",
            "name": "zone1.example.com",
            "nameservers": [
                1
            ],
            "custom_fields": {},
            "tags": []
        }
    }
}
Completed request #3
------------

And that is the problem. Two invocations of the Webhook occur, of which the first one has the wrong data (still both TestNameServer entries are listed), the second one is correct.

For this to occur it's not important that the object saved in the customised save() operation is a TestNameServer, any NetBox object class will do. The only thing that is relevant to the issue is that any save() operation for a different object type occurs within the save() method after super().save() was invoked.

Analysis

I tracked down the cause of this issue to the NetBox code in netbox/extras/signals.py:

    # If this is an M2M change, update the previously queued webhook (from post_save)
    queue = events_queue.get()
    if m2m_changed and queue and is_same_object(instance, queue[-1], request.id):
        instance.refresh_from_db()  # Ensure that we're working with fresh M2M assignments
        queue[-1]['data'] = serialize_for_event(instance)
        queue[-1]['snapshots']['postchange'] = get_snapshots(instance, action)['postchange']
    else:
        enqueue_object(queue, instance, request.user, request.id, action)
    events_queue.set(queue)

This code handles the queue of changes made to an object and correlates the change in the M2M relation to the change to the object itself. Unfortunately, it does that by looking at queue[-1], which would actually contain the change to the object if there hadn't been a save() operation in between caused by our custom save() method above.

As it is, the M2M change is not correlated to the object change, and so the Webhook is triggered twice, once (incorrectly) without and once with the changed M2M data in its payload.

[peteeckel]

Update: I created a rather simple fix for this, so if this bug gets accepted I can provide a PR.

develop...peteeckel:netbox:15194-fix-duplicate-webhook-invocations

[peteeckel]

With the patch in place, the webhook is triggered only once and correctly (same operation as above):

[1] Wed, 21 Feb 2024 17:51:32 GMT 127.0.0.1 "POST / HTTP/1.1" 200 -
Host: localhost:9000
Accept-Encoding: identity
User-Agent: python-urllib3/2.1.0
Content-Type: application/json
Content-Length: 770

{
    "event": "updated",
    "timestamp": "2024-02-21T17:51:32.797105+00:00",
    "model": "testzone",
    "username": "admin",
    "request_id": "df1ea10d-a772-481c-ba6e-054f612c6ec8",
    "data": {
        "id": 1,
        "name": "zone1.example.com",
        "nameservers": [
            {
                "id": 1,
                "name": "ns1.example.com",
                "url": "/api/plugins/netbox_test/test-name-servers/1/",
                "display": "ns1.example.com"
            }
        ],
        "url": "/api/plugins/netbox_test/test-zones/1/",
        "display": "zone1.example.com"
    },
    "snapshots": {
        "prechange": {
            "created": "2024-02-20T09:52:48.981Z",
            "name": "zone1.example.com",
            "nameservers": [
                2,
                1
            ],
            "custom_fields": {},
            "tags": []
        },
        "postchange": {
            "created": "2024-02-20T09:52:48.981Z",
            "last_updated": "2024-02-21T17:51:32.736Z",
            "name": "zone1.example.com",
            "nameservers": [
                1
            ],
            "custom_fields": {},
            "tags": []
        }
    }
}
Completed request #1
------------

[jeffgdotorg]

@peteeckel please go ahead and create a PR. Apologies for the delay.

[peteeckel]

During testing I found that this is unfortunately not limited to M2M changes. Repeated save() operations for the same object within the same request will also cause multiple webhook invocations, all but the last of which have incorrect data.