netbox-community / pynetbox

Python API client library for Netbox.
Apache License 2.0
571 stars 170 forks source link

ContentError when prefixes.available_ips prefix is full #338

Closed anttof closed 3 years ago

anttof commented 3 years ago

Hi,

We are using: Netbox Version: 2.10.4 Pynetbox Version: 5.3.1

We seem to be getting pynetbox.ContentError when using prefixes.available-ips and the prefix itself is full and I can't seem to figure out why.

Request that caused Issue:

2021-03-15 20:32:05,998 urllib3.connectionpool DEBUG https://netbox-stage.test.net:443 "POST /api/ipam/prefixes/1572/available-ips/ HTTP/1.1" 200 None

Output from print(reqdict) after modifying: https://github.com/digitalocean/pynetbox/blob/master/pynetbox/core/query.py#L276 which seems to be causing the issue when calling " return req.json()"

{'_content': b'{"detail":"An insufficient number of IP addresses are available within the prefix 10.30.0.46/31 (1 requested, 0 available)"}HTTP/1.1 201 CreatedServer: gunicorn/20.0.4\r\nDate: Mon, 15 Mar 2021 19:32:04 GMT\r\nConnection: keep-alive\r\nContent-Type: application/json\r\nVary: Accept, Cookie, Origin\r\nAllow: GET, POST, HEAD, OPTIONS\r\nAPI-Version: 2.10\r\nX-Content-Type-Options: nosniff\r\nReferrer-Policy: same-origin\r\nX-Frame-Options: SAMEORIGIN\r\nContent-Length: 635\r\n\r\n{"id":14935,"url":"https://netbox-stage.test.net/api/ipam/ip-addresses/14935/","family":{"value":4,"label":"IPv4"},"address":"10.30.0.49/31","vrf":{"id":303,"url":"https://netbox-stage.test.net/api/ipam/vrfs/303/","name":"b2-net-mgmt","rd":"8473:1000","display_name":"b2-net-mgmt (8473:1000)"},"tenant":null,"status":{"value":"active","label":"Active"},"role":null,"assigned_object_type":null,"assigned_object_id":null,"assigned_object":null,"nat_inside":null,"nat_outside":null,"dns_name":"","description":"","tags":[],"custom_fields":{"service_id":null},"created":"2021-03-15","last_updated":"2021-03-15T20:32:04.279486+01:00"}', '_content_consumed': True, '_next': None, 'status_code': 200, 'headers': {'Date': 'Mon, 15 Mar 2021 19:32:04 GMT', 'Server': 'Apache/2.4.18 (Ubuntu)', 'Keep-Alive': 'timeout=5, max=61', 'Connection': 'Keep-Alive', 'Transfer-Encoding': 'chunked'}, 'raw': <urllib3.response.HTTPResponse object at 0x7f4a4bf80b50>, 'url': 'https://netbox-stage.test.net/api/ipam/prefixes/1572/available-ips/', 'encoding': None, 'history': [], 'reason': 'OK', 'cookies': <RequestsCookieJar[]>, 'elapsed': datetime.timedelta(microseconds=44528), 'request': <PreparedRequest [POST]>, 'connection': <requests.adapters.HTTPAdapter object at 0x7f4a4bf69190>}

Traceback:

Traceback (most recent call last):
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/query.py", line 277, in _make_call
    return req.json()
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/requests/models.py", line 891, in json
    return complexjson.loads(
  File "/usr/lib/python3.8/json/__init__.py", line 357, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.8/json/decoder.py", line 340, in decode
    raise JSONDecodeError("Extra data", s, end)
json.decoder.JSONDecodeError: Extra data: line 1 column 125 (char 124)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "./app/ipam/services.py", line 418, in get_prefixes
    nb_prefixes = self.nb.ipam.prefixes.filter( **nb_filter )
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/endpoint.py", line 230, in filter
    return response_loader(req.get(), self.return_obj, self)
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/query.py", line 357, in get
    return req_all_threaded(add_params)
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/query.py", line 337, in req_all_threaded
    req = self._make_call(add_params=add_params)
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/query.py", line 279, in _make_call
    raise ContentError(req)
pynetbox.core.query.ContentError: The server returned invalid (non-json) data. Maybe not a NetBox server?
raddessi commented 3 years ago

Just to confirm, are either of the ip addresses 10.30.0.46 or 10.30.0.47 present in netbox when you get this error?

anttof commented 3 years ago

Yes, they are both present in netbox.

I think I have managed to narrow down the problem a bit. Here is essentially what I'm doing:

I have a list of Netbox prefix objects that I'm looping through (trying to allocate an IP) - If AllocationError occurs, I move on to the next prefix object and do the same. This works OK but whatever action I do next related to Prefixes, i am met with ContentError related to the previous Prefix that I tried to allocate an IP from. I have managed to replicate it with a smaller piece of code which hopefully explains it a bit better.

nb = pynetbox.api(
    NETBOX_URL,
    token=NETBOX_API_KEY,
    threading=False # Threading doesn't seem to have impact on the outcome
)

nb_filter = {'family': 4, 'status': 'active', 'cf_service_id': 1234569, 'role': 'net-mgmt-cpe'}

print("Fetching prefixes...")
nb_prefixes = nb.ipam.prefixes.filter( **nb_filter )
print(f"Prefixes Found: {nb_prefixes}")

for p in nb_prefixes:
    try:
        allocated_ip = p.available_ips.create()

    except pynetbox.AllocationError as e:
        print(f"Prefix is full, this is fine: {p.prefix}")
        continue 

#time.sleep(5) # This seems to fix the issue. 
print("Fetching prefixes...")
nb_prefixes = nb.ipam.prefixes.filter( **nb_filter )
# Error occurs here when trying to fetch prefixes again. 

Running above code results in the following:

Fetching prefixes...
{'_content': b'{"count":1,"next":null,"previous":null,"results":[{"id":1555,"url":"https://netbox-stage.test.net/api/ipam/prefixes/1555/","family":{"value":4,"label":"IPv4"},"prefix":"10.30.0.6/31","site":null,"vrf":{"id":303,"url":"https://netbox-stage.test.net/api/ipam/vrfs/303/","name":"b2-net-mgmt","rd":"8473:1000","display_name":"b2-net-mgmt (8473:1000)"},"tenant":{"id":1334,"url":"https://netbox-stage.test.net/api/tenancy/tenants/1334/","name":"B123458","slug":"b123458"},"vlan":null,"status":{"value":"active","label":"Active"},"role":{"id":28,"url":"https://netbox-stage.test.net/api/ipam/roles/28/","name":"net-mgmt-cpe","slug":"net-mgmt-cpe"},"is_pool":false,"description":"GATEWAY","tags":[],"custom_fields":{"auto_managed":false,"service_id":"1234569","site_id":null},"created":"2021-03-10","last_updated":"2021-03-10T09:36:08.436766+01:00"}]}', '_content_consumed': True, '_next': None, 'status_code': 200, 'headers': {'Date': 'Wed, 17 Mar 2021 10:35:04 GMT', 'Server': 'gunicorn/20.0.4', 'Content-Type': 'application/json', 'Vary': 'Accept,Cookie,Origin', 'Allow': 'GET, POST, PUT, PATCH, DELETE, HEAD, OPTIONS', 'API-Version': '2.10', 'X-Content-Type-Options': 'nosniff', 'Referrer-Policy': 'same-origin', 'X-Frame-Options': 'SAMEORIGIN', 'Content-Length': '856', 'Keep-Alive': 'timeout=5, max=100', 'Connection': 'Keep-Alive'}, 'raw': <urllib3.response.HTTPResponse object at 0x7fb5cf268a60>, 'url': 'https://netbox-stage.test.net/api/ipam/prefixes/?family=4&status=active&cf_service_id=1234569&role=net-mgmt-cpe', 'encoding': 'utf-8', 'history': [], 'reason': 'OK', 'cookies': <RequestsCookieJar[]>, 'elapsed': datetime.timedelta(microseconds=93017), 'request': <PreparedRequest [GET]>, 'connection': <requests.adapters.HTTPAdapter object at 0x7fb5cf25b4f0>}
Prefixes Found: [10.30.0.6/31]
Prefix is full, this is fine: 10.30.0.6/31
Fetching prefixes...
{'_content': b'{"detail":"An insufficient number of IP addresses are available within the prefix 10.30.0.6/31 (1 requested, 0 available)"}HTTP/1.1 200 OKServer: gunicorn/20.0.4\r\nDate: Wed, 17 Mar 2021 10:35:04 GMT\r\nConnection: keep-alive\r\nContent-Type: application/json\r\nVary: Accept, Cookie, Origin\r\nAllow: GET, POST, PUT, PATCH, DELETE, HEAD, OPTIONS\r\nAPI-Version: 2.10\r\nX-Content-Type-Options: nosniff\r\nReferrer-Policy: same-origin\r\nX-Frame-Options: SAMEORIGIN\r\nContent-Length: 856\r\n\r\n{"count":1,"next":null,"previous":null,"results":[{"id":1555,"url":"https://netbox-stage.test.net/api/ipam/prefixes/1555/","family":{"value":4,"label":"IPv4"},"prefix":"10.30.0.6/31","site":null,"vrf":{"id":303,"url":"https://netbox-stage.test.net/api/ipam/vrfs/303/","name":"b2-net-mgmt","rd":"8473:1000","display_name":"b2-net-mgmt (8473:1000)"},"tenant":{"id":1334,"url":"https://netbox-stage.test.net/api/tenancy/tenants/1334/","name":"B123458","slug":"b123458"},"vlan":null,"status":{"value":"active","label":"Active"},"role":{"id":28,"url":"https://netbox-stage.test.net/api/ipam/roles/28/","name":"net-mgmt-cpe","slug":"net-mgmt-cpe"},"is_pool":false,"description":"GATEWAY","tags":[],"custom_fields":{"auto_managed":false,"service_id":"1234569","site_id":null},"created":"2021-03-10","last_updated":"2021-03-10T09:36:08.436766+01:00"}]}', '_content_consumed': True, '_next': None, 'status_code': 200, 'headers': {'Date': 'Wed, 17 Mar 2021 10:35:04 GMT', 'Server': 'Apache/2.4.18 (Ubuntu)', 'Keep-Alive': 'timeout=5, max=98', 'Connection': 'Keep-Alive', 'Transfer-Encoding': 'chunked'}, 'raw': <urllib3.response.HTTPResponse object at 0x7fb5cf268c40>, 'url': 'https://netbox-stage.test.net/api/ipam/prefixes/?family=4&status=active&cf_service_id=1234569&role=net-mgmt-cpe', 'encoding': None, 'history': [], 'reason': 'OK', 'cookies': <RequestsCookieJar[]>, 'elapsed': datetime.timedelta(microseconds=61523), 'request': <PreparedRequest [GET]>, 'connection': <requests.adapters.HTTPAdapter object at 0x7fb5cf25b4f0>}
Traceback (most recent call last):
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/query.py", line 277, in _make_call
    return req.json()
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/requests/models.py", line 891, in json
    return complexjson.loads(
  File "/usr/lib/python3.8/json/__init__.py", line 357, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.8/json/decoder.py", line 340, in decode
    raise JSONDecodeError("Extra data", s, end)
json.decoder.JSONDecodeError: Extra data: line 1 column 124 (char 123)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "ipam_content_error.py", line 29, in <module>
    nb_prefixes = nb.ipam.prefixes.filter( **nb_filter )
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/endpoint.py", line 230, in filter
    return response_loader(req.get(), self.return_obj, self)
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/query.py", line 359, in get
    return req_all()
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/query.py", line 310, in req_all
    req = self._make_call(add_params=add_params)
  File "/home/anto/nrm/venv/lib/python3.8/site-packages/pynetbox/core/query.py", line 279, in _make_call
    raise ContentError(req)
pynetbox.core.query.ContentError: The server returned invalid (non-json) data. Maybe not a NetBox server?

However, I also just now tried implementing exact same scenario using the rest API and I get the same results... So I guess the problem might be with netbox itself? The problem seems to resolve when specifying a sleep timer of a couple of seconds but I feel like this shouldn't be necessary.

API_HEADERS = {
        'Authorization': f'Token {NETBOX_API_KEY}',
        'Accept': 'application/json',
        'Content-Type': 'application/json'}

nb_filter = "family=4&status=active&cf_service_id=1234569&role=net-mgmt-cpe"

print("Fetching prefixes...")
nb_prefixes = requests.get(f"{NETBOX_URL}/api/ipam/prefixes?{nb_filter}", headers=API_HEADERS).json()
print(f"Prefixes Found: {nb_prefixes}")

for p in nb_prefixes["results"]:
    try:
        url = f"{p['url']}available-ips/"
        allocated_ip = requests.post(url, headers=API_HEADERS).json()
    except:
        continue

#time.sleep(5) # This seems to fix the issue. 
print("Fetching prefixes...")
nb_prefixes = requests.get(f"{NETBOX_URL}/api/ipam/prefixes?{nb_filter}", headers=API_HEADERS).json()
# Error occurs here when trying to fetch prefixes again. 
anttof commented 3 years ago

I think this is related to the following regarding available-ips endpoints:

"A convenience method for returning available IP addresses within a prefix. By default, the number of IPs returned will be equivalent to PAGINATE_COUNT. An arbitrary limit (up to MAX_PAGE_SIZE, if set) may be passed, however results will not be paginated.

The advisory lock decorator uses a PostgreSQL advisory lock to prevent this API from being invoked in parallel, which results in a race condition where multiple insertions can occur."

It seems like using this API endpoint results in locking the database for all other endpoints if I'm understanding it correctly. Replacing the second fetching of prefixes with the following: (devices with of course is another table in the database) also results in the same issue.

devices = requests.get(f"{NETBOX_URL}/api/dcim/devices", headers=API_HEADERS).json()

I am not sure if this type of issue should be handled by:

Please let me know and I can open up the issue on the Netbox repository instead (if this is even considered an issue or if it is up to me to implement some form of sleep timer)

raddessi commented 3 years ago

I think the @zachmoody needs to comment on this but from what you found it seems to me like this is likely an issue in netbox itself like you suggested. I would have to read more in to the code around the available-ips endpoint however.

zachmoody commented 3 years ago

Odd, honestly wouldn't be surprised if it turned out to be a caching problem either. But yeah, if you're reproducing with just requests I don't think it'd be a pynetbox issue. Might be worth a shot over on the NetBox issue tracker after ruling out caching.