View results return deleted documents in `main`

[nickva]

Deleted documents end up returning view results. If include_docs=true is used the emitted documents is returned as null. This may be related to #3381

View results return:

{"id":"doc660","key":9,"value":[9,"649-1393896c61576b7b80d086f4f3858e78",2935760,122458],"doc":null}

and yet:

curl 'foo:bar@localhost:15984/db1/doc660'
{"error":"not_found","reason":"deleted"}

Reproducer script (thanks to @rnewson)

#!/usr/bin/env python
​
import random
import requests
import threading
​
url='http://127.0.0.1:15984/db1/'
​
def thread_fun():
    s = requests.Session()
    s.auth = ('foo', 'bar')
    while True:
        doc_id = random.randrange(1, 100)
        doc =  {"foo": random.randrange(1,1000000)}
        r = s.get('{}/doc{}'.format(url, doc_id))
        if r.status_code == 200:
            doc['_rev'] = r.json()['_rev']
            if random.random() > 0.5:
                doc['_deleted'] = True
        s.put('{}/doc{}'.format(url, doc_id), json = doc)
​
​
if __name__ == "__main__":
    s = requests.Session()
    s.auth = ('foo', 'bar')
    s.delete(url)
    s.put(url)
    s.put('{}/_design/foo'.format(url), data = '{"views":{"bar":{"map":"function (doc) { emit(doc.foo, doc.foo); }"}}}')
​
    for x in range(10):
        t = threading.Thread(target=thread_fun)
        t.start()

[android-programmer]

what is the environment ?

[nickva]

@android-programmer The environment is a recent version of the main branch (running on FDB).

[nickva]

Debugging this a bit more:

I initially suspected it maybe related to the 27e8e33 commit to minimize conflicts and use snapshot reads for db seq. So I reverted that commit but was still able to reproduce the issue. I had to modify the script slightly to not delete and re-create the view as the commit fixed the view indexer constantly conflicting and never finishing.

Then I noticed that curl -s $DB/db1/_design/foo/_info returns the latest db sequence so the view is considered "updated" to the latest db_seq, which rules out the view somehow not processes all of the changes feed and stopping early.

% curl $DB/db1/_design/foo/_view/bar'?include_docs=true&limit=10'
{"total_rows":98,"offset":null,"rows":[
...
{"id":"doc66","key":46591,"value":"1-90516cb1e0f4bc21e154f63be6fddb2a","doc":null},
...
]}

% curl -s $DB/db1/_design/foo/_info| jq '.view_index.update_seq'
"000000069d8cf42c00000000"

% curl -s $DB/db1 | jq .update_seq
"000000069d8cf42c00000000"

% curl -s  $DB/db1/_changes | grep doc66
{"seq":"000000069d7fe8be00000000","id":"doc66","changes":[{"rev":"16-1c15c73b3bbea9c5427cb8497e8c18b9"}],"deleted":true},

[nickva]

A trick that might help debug the issue is to use the local_seq view option then emit update_sequence for each doc in the view.

#!/usr/bin/env python

import json
import random
import requests
import threading

URL = 'http://127.0.0.1:15984/db1'
USER = 'adm'
PASS = 'pass'
#doc.foo
VIEW = {
    "views" : {
        "bar":{
            "map":"function (doc) {emit(doc._id, [doc._rev, doc._local_seq]); }"
        }
    },
    "options": {"local_seq": True}
}
def thread_fun():
    s = requests.Session()
    s.auth = (USER, PASS)
    while True:
        doc_id = random.randrange(1, 10)
        doc = {}
        r = s.get('{}/doc{}'.format(URL, doc_id))
        if r.status_code == 200:
            doc['_rev'] = r.json()['_rev']
            if random.random() > 0.5:
                doc['_deleted'] = True
        s.put('{}/doc{}'.format(URL, doc_id), json = doc)


if __name__ == "__main__":
    s = requests.Session()
    s.auth = (USER, PASS)
    s.delete(URL)
    s.put(URL)
    s.put('{}/_design/foo'.format(URL), data = json.dumps(VIEW))
    random.seed(42)
    for x in range(1):
        t = threading.Thread(target=thread_fun)
        t.start()

curl $DB/db1/_design/foo/_view/bar'?include_docs=true&limit=10'
{"total_rows":9,"offset":null,"rows":[
{"id":"doc1","key":"doc1","value":["239-a68671522c8878b3e142c2e0c4e0c088","00000007c21912e900000000"],"doc":{"_id":"doc1","_rev":"252-6d90b849a9794f0c10c118255992ea91"}},
{"id":"doc2","key":"doc2","value":["260-59a6c60bddf9044d90c571569cb2c5af","00000007c222b81800000000"],"doc":null},
{"id":"doc3","key":"doc3","value":["259-bee2fc5c0c38d01495d883c25b20fffb","00000007c20d6a3b00000000"],"doc":null},
{"id":"doc4","key":"doc4","value":["267-da90f2173898fb5a5482a9a1dc36e56e","00000007c21e82cf00000000"],"doc":{"_id":"doc4","_rev":"280-c55640f682430b2b497a91499bcfd675"}},
{"id":"doc5","key":"doc5","value":["243-69229d2e0837f8ecf47595ce8b9efddb","00000007c227d2aa00000000"],"doc":null},
{"id":"doc6","key":"doc6","value":["249-a35e458fe1eacba23641d6213230576c","00000007c2041e7700000000"],"doc":null},
{"id":"doc7","key":"doc7","value":["268-bbc6d12f87a0031f8d2de6edcd4fb3d7","00000007c22354ca00000000"],"doc":{"_id":"doc7","_rev":"275-506c6db6153a407c4eefe34fa03f69dc"}},
{"id":"doc8","key":"doc8","value":["281-70a9df96a142c04ea0e45fc3ceea93a6","00000007c225fcb600000000"],"doc":{"_id":"doc8","_rev":"290-89c40a21527dc196d31118dfbce63dbe"}},
{"id":"doc9","key":"doc9","value":["281-54c6e5c3e806d21fcb39f3787440e845","00000007c266503b00000000"],"doc":{"_id":"doc9","_rev":"281-54c6e5c3e806d21fcb39f3787440e845"}}

[nickva]

Something maybe odd with IDTree or ViewMap BTree updates. This a log of all the write_docs docs, then the IDMap and ViewMap items:

[error] 2021-02-25T23:32:24.797212Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => false,id => <<"doc5">>,sequence => <<"00000008684c7fbb00000000">>}
[error] 2021-02-25T23:32:24.797263Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => true,id => <<"doc8">>,sequence => <<"00000008684d588a00000000">>}
[error] 2021-02-25T23:32:24.797296Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => false,id => <<"doc7">>,sequence => <<"00000008684e915100000000">>}
[error] 2021-02-25T23:32:24.797343Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => true,id => <<"doc2">>,sequence => <<"000000086850064b00000000">>}
[error] 2021-02-25T23:32:24.797375Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => false,id => <<"doc9">>,sequence => <<"00000008685131a900000000">>}
[error] 2021-02-25T23:32:24.797403Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => true,id => <<"doc6">>,sequence => <<"000000086851c7b200000000">>}
[error] 2021-02-25T23:32:24.797433Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => false,id => <<"doc3">>,sequence => <<"0000000868525b8b00000000">>}
[error] 2021-02-25T23:32:24.797463Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => true,id => <<"doc1">>,sequence => <<"000000086854237300000000">>}
[error] 2021-02-25T23:32:24.797494Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => false,id => <<"doc4">>,sequence => <<"000000086855493400000000">>}
[error] 2021-02-25T23:32:24.798140Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc1">>,#Ref<0.2949210352.4145020935.107350>}
[error] 2021-02-25T23:32:24.798187Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc2">>,#Ref<0.2949210352.4145020935.107350>}
[error] 2021-02-25T23:32:24.798214Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc3">>,[{0,[<<"doc3">>]}]}
[error] 2021-02-25T23:32:24.798250Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc4">>,[{0,[<<"doc4">>]}]}
[error] 2021-02-25T23:32:24.798274Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc5">>,[{0,[<<"doc5">>]}]}
[error] 2021-02-25T23:32:24.798297Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc6">>,#Ref<0.2949210352.4145020935.107350>}
[error] 2021-02-25T23:32:24.798322Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc7">>,[{0,[<<"doc7">>]}]}
[error] 2021-02-25T23:32:24.798352Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc8">>,#Ref<0.2949210352.4145020935.107350>}
[error] 2021-02-25T23:32:24.798382Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@202 IDTree {<<"doc9">>,[{0,[<<"doc9">>]}]}
[error] 2021-02-25T23:32:24.798924Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@213 ViewMap {{<<"doc3">>,<<"doc3">>},[<<"22-097e4e5fed3b10b9e00cc0ee2c35dd43">>,<<"0000000868525b8b00000000">>]}
[error] 2021-02-25T23:32:24.798963Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@213 ViewMap {{<<"doc4">>,<<"doc4">>},[<<"24-56e5817ad4df6a2391016f3f8fa51079">>,<<"000000086855493400000000">>]}
[error] 2021-02-25T23:32:24.799005Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@213 ViewMap {{<<"doc5">>,<<"doc5">>},[<<"19-a2949bfc9889ebd35035a56e6ffc4ad1">>,<<"00000008684c7fbb00000000">>]}
[error] 2021-02-25T23:32:24.799037Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@213 ViewMap {{<<"doc7">>,<<"doc7">>},[<<"20-2b4f169ba4d20df8bb1563819b8e6b2d">>,<<"00000008684e915100000000">>]}
[error] 2021-02-25T23:32:24.799073Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_trees:update_views@213 ViewMap {{<<"doc9">>,<<"doc9">>},[<<"30-63abba104dee58f12376d0ffd340b8ec">>,<<"00000008685131a900000000">>]}
[error] 2021-02-25T23:32:24.799385Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:is_update_finished@273 is_update finished true AtDbSeq:true LastSeq:<<"000000086855493400000000">> DbSeq:<<"000000086855493400000000">> AtViewVs:false ViewVs:not_found

We notice that doc6 should be deleted and is updated with a deletedRef in couch_views_tree:update_views/3, however it still shows up in the view results:

% curl $DB/db1/_design/foo/_view/bar'?include_docs=true&limit=10'
{"total_rows":6,"offset":null,"rows":[
{"id":"doc3","key":"doc3","value":["22-097e4e5fed3b10b9e00cc0ee2c35dd43","0000000868525b8b00000000"],"doc":{"_id":"doc3","_rev":"22-097e4e5fed3b10b9e00cc0ee2c35dd43"}},
{"id":"doc4","key":"doc4","value":["24-56e5817ad4df6a2391016f3f8fa51079","000000086855493400000000"],"doc":{"_id":"doc4","_rev":"24-56e5817ad4df6a2391016f3f8fa51079"}},
{"id":"doc5","key":"doc5","value":["19-a2949bfc9889ebd35035a56e6ffc4ad1","00000008684c7fbb00000000"],"doc":{"_id":"doc5","_rev":"19-a2949bfc9889ebd35035a56e6ffc4ad1"}},
{"id":"doc6","key":"doc6","value":["11-bb8b0b3302cad9e88443e0f6a66b8834","000000086809697700000000"],"doc":null},
{"id":"doc7","key":"doc7","value":["20-2b4f169ba4d20df8bb1563819b8e6b2d","00000008684e915100000000"],"doc":{"_id":"doc7","_rev":"20-2b4f169ba4d20df8bb1563819b8e6b2d"}},
{"id":"doc9","key":"doc9","value":["30-63abba104dee58f12376d0ffd340b8ec","00000008685131a900000000"],"doc":{"_id":"doc9","_rev":"30-63abba104dee58f12376d0ffd340b8ec"}}
]}

And the view sequence is stale in the view result:

[error] 2021-02-25T23:32:24.797403Z node1@127.0.0.1 <0.513.0> --------  +++++++ couch_views_indexer:write_docs@442 writting doc:#{deleted => true,id => <<"doc6">>,sequence => <<"000000086851c7b200000000">>}

vs

{"id":"doc6","key":"doc6","value":["11-bb8b0b3302cad9e88443e0f6a66b8834","000000086809697700000000"],"doc":null},

[kocolosk]

This workload seems to cause quite a large number of commit conflicts for the indexer. Should the indexer be executing snapshot reads for the document data so that concurrent modifications of documents don't cause the commit in the view index to abort? More a performance issue than a correctness one, but it seems to me that a fast client updating a single document in a loop, combined with a suitably complex piece of JS code in a map function, could cause the indexer to get into an endless loop. I don't think that's what we want.

I wasn't able to track it down completely but I also wonder if the bug is somewhere in those restarts. I did notice situations where e.g. the indexer would be indexing a batch of 5 documents, 1 of those documents would get updated concurrently, the indexer would restart and only index the other 4 documents, and the 5th one would be the one that was messed up in the view.

[kocolosk]

(previous comment deleted because inaccurate -- just forgot to hit save on the updated view definition and it was throwing a JS error on the indexing :))

[davisp]

This should be fixed by #3385.

[kocolosk]

Not entirely. There's still an issue that the document is loaded in a separate transaction. If the doc is deleted between the completion of the view indexing and the request to attach the doc we will still hit this issue.

[nickva]

@kocolosk there is a separate issue that focuses mainly on that aspect #3381

After @davisp's fix I can't reproduce this issue if the view is allowed to "settle" and process all the changes up to database's last update_seq.

[kocolosk]

Agreed, if this issue is scoped to permanent inconsistencies then we are all set here.