Erroneous invocations of Event Rules/Webhooks with M2M relationships #15194

peteeckel · 2024-02-20T10:45:28Z

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.

The text was updated successfully, but these errors were encountered:

peteeckel · 2024-02-21T14:52:11Z

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 · 2024-02-21T17:52:52Z

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
------------

…eued webhooks

jeffgdotorg · 2024-02-29T16:29:59Z

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

…eued webhooks

peteeckel · 2024-03-01T18:07:58Z

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.

…eued webhooks

peteeckel added the type: bug A confirmed report of unexpected behavior in the application label Feb 20, 2024

peteeckel added a commit to peteeckel/netbox that referenced this issue Feb 21, 2024

Fixes: netbox-community#15194 - Check the whole queue for matching qu…

b2cc35b

…eued webhooks

peteeckel added a commit to peteeckel/netbox that referenced this issue Feb 21, 2024

Fixes: netbox-community#15194 - Check the whole queue for matching qu…

ed2a387

…eued webhooks

peteeckel added a commit to peteeckel/netbox that referenced this issue Feb 22, 2024

Fixes: netbox-community#15194 - Check the whole queue for matching qu…

5134034

…eued webhooks

jeffgdotorg added the status: accepted This issue has been accepted for implementation label Feb 29, 2024

jeffgdotorg assigned peteeckel Feb 29, 2024

peteeckel added a commit to peteeckel/netbox that referenced this issue Feb 29, 2024

Fixes: netbox-community#15194 - Check the whole queue for matching qu…

a2e6304

…eued webhooks

peteeckel linked a pull request Feb 29, 2024 that will close this issue

Fixes: #15194 - Check the whole queue for matching queued webhooks #15318

Open

peteeckel added a commit to peteeckel/netbox that referenced this issue Mar 1, 2024

Fixes: netbox-community#15194 - Check the whole queue for matching qu…

1728997

…eued webhooks

peteeckel mentioned this issue Mar 28, 2024

Unable to import plugin netbox_access_lists: Module not found. netbox-community/netbox-plugin-tutorial#33

Open

jeremystretch added the severity: medium Results in substantial degraded or broken functionality for specfic workflows label May 13, 2024

peteeckel added a commit to peteeckel/netbox that referenced this issue May 28, 2024

Fixes: netbox-community#15194 - Check the whole queue for matching qu…

e535c14

…eued webhooks

peteeckel mentioned this issue May 29, 2024

DNS Record Webhook Returns Empty Tags peteeckel/netbox-plugin-dns#277

Closed

peteeckel added a commit to peteeckel/netbox that referenced this issue May 30, 2024

Fixes: netbox-community#15194 - Check the whole queue for matching qu…

b5cb67b

…eued webhooks

jeremystretch added a commit that referenced this issue May 31, 2024

Fixes #15194: Prevent enqueuing duplicate events for an object

e53c212

jeremystretch linked a pull request May 31, 2024 that will close this issue

Fixes #15194: Prevent enqueuing duplicate events for an object #16366

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Erroneous invocations of Event Rules/Webhooks with M2M relationships #15194

Erroneous invocations of Event Rules/Webhooks with M2M relationships #15194

peteeckel commented Feb 20, 2024 •

edited

peteeckel commented Feb 21, 2024 •

edited

peteeckel commented Feb 21, 2024 •

edited

jeffgdotorg commented Feb 29, 2024

peteeckel commented Mar 1, 2024

Erroneous invocations of Event Rules/Webhooks with M2M relationships #15194

Erroneous invocations of Event Rules/Webhooks with M2M relationships #15194

Comments

peteeckel commented Feb 20, 2024 • edited

Deployment Type

Software Versions

Description

Steps to reproduce

Analysis

peteeckel commented Feb 21, 2024 • edited

peteeckel commented Feb 21, 2024 • edited

jeffgdotorg commented Feb 29, 2024

peteeckel commented Mar 1, 2024

peteeckel commented Feb 20, 2024 •

edited

peteeckel commented Feb 21, 2024 •

edited

peteeckel commented Feb 21, 2024 •

edited