Race condition with DELETE on plural endpoint

[gabisurita]

gsurita-30820:~ gsurita$ http delete https://kinto.dev.mozaws.net/v1/buckets -a a:a
HTTP/1.1 500 Internal Server Error
Access-Control-Expose-Headers: Retry-After, Content-Length, Alert, Backoff
Connection: keep-alive
Content-Length: 183
Content-Type: application/json
Date: Fri, 24 Feb 2017 22:07:35 GMT
Server: nginx
X-Content-Type-Options: nosniff

{
    "code": 500,
    "errno": 999,
    "error": "Internal Server Error",
    "info": "https://github.com/Kinto/kinto/issues/",
    "message": "A programmatic error occured, developers have been informed."
}

[glasserc]

Very strange! I logged into the server and didn't see anything in the logs. You said you couldn't reproduce this locally, right?

[gabisurita]

Yeah. I've tested the deployed version (5.3.2) and it looks fine. I think this might be a broken plugin that's making the whole server fail.

[Natim]

Ok I am going to upgrade to kinto 6 and see if we fixed the issue.

[Natim]

Can you try again with that version?

[Natim]

I could reproduce:

  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/kinto/core/events.py", line 149, in notify_resource_event
    impacted.append({'new': new, 'old': old[i]})
IndexError: list index out of range

[gabisurita]

I can't reproduce it anymore.

@Natim how did you do it?

[Natim]

$ http delete https://kinto.dev.mozaws.net/v1/buckets -a test:test
HTTP/1.1 500 Internal Server Error
Access-Control-Expose-Headers: Retry-After, Alert, Backoff, Content-Length
Connection: keep-alive
Content-Length: 177
Content-Type: application/json
Date: Tue, 07 Mar 2017 07:17:28 GMT
Server: nginx
X-Content-Type-Options: nosniff

{
    "code": 500, 
    "errno": 999, 
    "error": "Internal Server Error", 
    "info": "https://github.com/Kinto/kinto/issues/", 
    "message": "A programmatic error occured, developers have been informed."
}

I still can

[leplatrem]

http put https://kinto.dev.mozaws.net/v1/buckets/a -a a:a

HTTP/1.1 201 Created
Access-Control-Expose-Headers: Content-Length, Retry-After, Backoff, Alert
Connection: keep-alive
Content-Length: 152
Content-Type: application/json
Date: Tue, 07 Mar 2017 12:58:50 GMT
ETag: "1488891530236"
Last-Modified: Tue, 07 Mar 2017 12:58:50 GMT
Server: nginx
X-Content-Type-Options: nosniff

{
    "data": {
        "id": "a", 
        "last_modified": 1488891530236
    }, 
    "permissions": {
        "write": [
            "basicauth:cec4ef00dfaac462ae18c78f53798e1ee0bb25b583a6f9056e8d001d58e0f56d"
        ]
    }
}

➜  ~ http delete https://kinto.dev.mozaws.net/v1/buckets -a a:a

HTTP/1.1 200 OK
Access-Control-Expose-Headers: Content-Length, Retry-After, Backoff, Alert
Connection: keep-alive
Content-Length: 66
Content-Type: application/json
Date: Tue, 07 Mar 2017 12:58:52 GMT
ETag: "1488891532818"
Last-Modified: Tue, 07 Mar 2017 12:58:52 GMT
Server: nginx
Total-Records: 1
X-Content-Type-Options: nosniff

{
    "data": [
        {
            "deleted": true, 
            "id": "a", 
            "last_modified": 1488891532818
        }
    ]
}

Shall we close?

[gabisurita]

I can reproduce with @Natim token. WTF?!

[Natim]

  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/tweens.py", line 22, in excview_tween
    response = handler(request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid_tm/__init__.py", line 119, in tm_tween
    reraise(*exc_info)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid_tm/compat.py", line 15, in reraise
    raise value
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid_tm/__init__.py", line 98, in tm_tween
    response = handler(request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/router.py", line 155, in handle_request
    view_name
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/view.py", line 612, in _call_view
    response = view_callable(context, request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/config/views.py", line 181, in __call__
    return view(context, request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/viewderivers.py", line 389, in attr_view
    return view(context, request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/viewderivers.py", line 367, in predicate_wrapper
    return view(context, request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/viewderivers.py", line 300, in secured_view
    return view(context, request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/viewderivers.py", line 438, in rendered_view
    result = view(context, request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/pyramid/viewderivers.py", line 147, in _requestonly_view
    response = view(request)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/cornice/service.py", line 491, in wrapper
    response = view_()
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/kinto/core/resource/__init__.py", line 393, in collection_delete
    return self.postprocess(deleted, action=action, old=records)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/kinto/core/resource/__init__.py", line 1196, in postprocess
    data = super().postprocess(result, action, old)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/kinto/core/resource/__init__.py", line 710, in postprocess
    old=old)
  File "/home/ubuntu/venvs/kinto35/lib/python3.5/site-packages/kinto/core/events.py", line 149, in notify_resource_event
    impacted.append({'new': new, 'old': old[i]})
IndexError: list index out of range lang=None uid=842ba3f6b700d048458dcdb203805df2df12877819389513352cad3afb92bf0c

[Natim]

To be honest I don't know how this can happen...

    if action == ACTIONS.DELETE:
        if not isinstance(data, list):
            impacted = [{'new': data, 'old': old}]
        else:
            impacted = []
            for i, new in enumerate(data):
                impacted.append({'new': new, 'old': old[i]})

[leplatrem]

When the provided old does not have the same length as the new. So in the resource view collection_delete(), when the delete_records() does not return the same length as get_all() ?

[Natim]

This might be related to a fix that we did here: https://github.com/Kinto/kinto/pull/1249

[Natim]

I couldn't reproduce anymore with the fix. Feel free to reopen if you see the bug again.

[leplatrem]

In the resource code, in collection_delete() we do:

1. records = get_all()
2. deleted = delete_all()
3. notify(deleted, action=action, old=records)

There can be a race condition between 1. and 2.

With #1386 we could have only one call to delete_all()

/cc @glasserc

https://github.com/Kinto/kinto/blob/5426bbde435970bf9c1bd70b48b84f4d6e3e2ebb/kinto/core/resource/__init__.py#L372-L379