Crash in ddoc_cache_lru: no match of right hand value not_found

[bravier]

Hello,

A few days ago, we experienced a CouchDB crash in production and we're having a hard time understanding what went bad and why.

The exact error is ddoc_cache_lru terminated with reason: no match of right hand value not_found at ddoc_cache_lru:remove_key.

Can someone explain what happened? Is it something we should be worried about?
It's the first time we experience this while running CouchDB for multiple years in production.
Resource usage on the machine where normal when it happened.

Thanks!

OS: CentOS 8
CouchDB version: 3.2.1
Erlang version: 24.1.7
Javascript Engine: SpiderMonkey 60

Complete log

janv. 25 13:25:54 john%40doe.com GET /some_db/_design/some_index/_view/by_date?startkey=%5B%22something%EF%BF%BF%22%5D&endkey=%5B%22something%22%5D&limit=1&descending=true 404 ok 3
janv. 25 13:25:54 john%40doe.com GET /some_db/_design/some_index/_view/by_date?startkey=%5B%22something%EF%BF%BF%22%5D&endkey=%5B%22something%22%5D&limit=1&descending=true 404 ok 5
janv. 25 13:25:54 bob PUT /some_db/_design%2Fsome_index 201 ok 43
janv. 25 13:25:54 bob PUT /some_db/_design%2Fsome_index 409 ok 93
janv. 25 13:25:55 -------- gen_server ddoc_cache_lru terminated with reason: no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:308) <= ddoc_cache_lru:handle_info/2(line:219) <= gen_server:try_dispatch/4(line:695) <= gen_server:handle_msg/6(line:771) <= proc_lib:init_p_do_apply/3(line:226)
janv. 25 13:25:55 vps couchdb[2998967]:   last msg: redacted
janv. 25 13:25:55 vps couchdb[2998967]:      state: {st,#Ref<0.2942121600.3594125314.214729>,#Ref<0.2942121600.3594125314.214730>,<0.2096.0>}
janv. 25 13:25:55 vps couchdb[2998967]:     extra: []
janv. 25 13:25:55 -------- gen_server ddoc_cache_lru terminated with reason: no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:308) <= ddoc_cache_lru:handle_info/2(line:219) <= gen_server:try_dispatch/4(line:695) <= gen_server:handle_msg/6(line:771) <= proc_lib:init_p_do_apply/3(line:226)
janv. 25 13:25:55 vps couchdb[2998967]:   last msg: redacted
janv. 25 13:25:55 vps couchdb[2998967]:      state: {st,#Ref<0.2942121600.3594125314.214729>,#Ref<0.2942121600.3594125314.214730>,<0.2096.0>}
janv. 25 13:25:55 vps couchdb[2998967]:     extra: []
janv. 25 13:25:55 9eaaf44c96 could not load validation funs {{{badmatch,not_found},[{ddoc_cache_lru,remove_key,2,[{file,"src/ddoc_cache_lru.erl"},{line,308}]},{ddoc_cache_lru,handle_info,2,[{file,"src/ddoc_cache_lru.erl"},{line,219}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,695}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,771}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]},{gen_server,call,[ddoc_cache_lru,{start,{ddoc_cache_entry_validation_funs,<<"some_db">>},undefined},infinity]}}
janv. 25 13:25:55 7f7d3e8004 req_err(412647710) {{badmatch,not_found},
janv. 25 13:25:55 vps couchdb[2998967]:  [{ddoc_cache_lru,remove_key,2,[{file,"src/ddoc_cache_lru.erl"},{line,308}]},
janv. 25 13:25:55 vps couchdb[2998967]:   {ddoc_cache_lru,handle_info,2,[{file,"src/ddoc_cache_lru.erl"},{line,219}]},
janv. 25 13:25:55 vps couchdb[2998967]:   {gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,695}]},
janv. 25 13:25:55 vps couchdb[2998967]:   {gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,771}]},
janv. 25 13:25:55 vps couchdb[2998967]:   {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]} : {gen_server,call,
janv. 25 13:25:55 vps couchdb[2998967]:     [ddoc_cache_lru,
janv. 25 13:25:55 vps couchdb[2998967]:      {start,
janv. 25 13:25:55 vps couchdb[2998967]:          {ddoc_cache_entry_ddocid,
janv. 25 13:25:55 vps couchdb[2998967]:              {<<"some_db">>,
janv. 25 13:25:55 vps couchdb[2998967]:               <<"_design/some_index">>}},
janv. 25 13:25:55 vps couchdb[2998967]:          undefined},
janv. 25 13:25:55 vps couchdb[2998967]:      infinity]}
janv. 25 13:25:55 vps couchdb[2998967]:     [<<"gen_server:call/3 L247">>,<<"ddoc_cache_lru:lru_start/2 L243">>,<<"chttpd_db:handle_design_req/2 L365">>,<<"chttpd:handle_req_after_auth/2 L327">>,<<"chttpd:process_request/1 L310">>,<<"chttpd:handle_request_int/1 L249">>,<<"mochiweb_http:headers/6 L150">>,<<"proc_lib:init_p_do_apply/3 L226">>]
janv. 25 13:25:55 7f7d3e8004 localhost:5984 127.0.0.1 john%40doe.com GET /some_db/_design/some_index/_view/by_date?startkey=%5B%22something%EF%BF%BF%22%5D&endkey=%5B%22something%22%5D&limit=1&descending=true 500 ok 229
janv. 25 13:25:55 -------- CRASH REPORT Process ddoc_cache_lru (<0.2095.0>) with 15 neighbors crashed with reason: no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:308) <= ddoc_cache_lru:handle_info/2(line:219) <= gen_server:try_dispatch/4(line:695) <= gen_server:handle_msg/6(line:771) <= proc_lib:init_p_do_apply/3(line:226); initial_call: {ddoc_cache_lru,init,['Argument__1']}, ancestors: [ddoc_cache_sup,<0.1915.0>], message_queue_len: 9, links: [<0.11247.854>,<0.23021.1039>,<0.29471.942>,<0.30507.984>,<0.31352.610>,...], dictionary: [], trap_exit: true, status: running, heap_size: 1598, stack_size: 29, reductions: 74308717
janv. 25 13:25:55 -------- Supervisor ddoc_cache_sup had child ddoc_cache_lru started with ddoc_cache_lru:start_link() at <0.2095.0> exit with reason no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:308) <= ddoc_cache_lru:handle_info/2(line:219) <= gen_server:try_dispatch/4(line:695) <= gen_server:handle_msg/6(line:771) <= proc_lib:init_p_do_apply/3(line:226) in context child_terminated

[jaydoane]

Interestingly enough, I recently created a patch for this very issue but didn't merged it because we're not sure how it might have gotten into that state, and are worried that the patch would just cover over a deeper problem.

Cloudant does see these occasionally in our logs, and it doesn't seem to cause any serious problems, but I think it would be nice to figure it out, since the crashes themselves seem kind of scary.

[bravier]

Thanks for the details @jaydoane!

but I think it would be nice to figure it out

I agree. It would be interesting to know more about this issue.
Don't hesitate to ask for more info if it can help here.

[nickva]

@bravier would you be able to share a bit more about the type of the cluster or the type of design documents to help narrow down the cause?

Is the cluster fairly "busy" or this happens even when there is little traffic? Any other errors in the log, like exceptions, stack traces, or timeouts?

Are there are lot of design documents, and to they change often? Using any validate_doc_update functions in the design doc or just plain map reduce views.

Ideally it would perfect to have a small reproducer script but that may be hard to create sometimes if the failure is a race condition or is intermittent.

[guanfeix]

OS: Oracle CentOS 7
CouchDB version: 3.2.1
Erlang version: R16B REALEASE 03.18
it's a single node,a little traffic,maybe about sixty dbs,each with around ten view_functions average

[bravier]

@nickva sorry for the long response delay.

the type of the cluster or the type of design documents

We're using a 3 nodes cluster and the crash happened in a map function.

Is the cluster fairly "busy" or this happens even when there is little traffic?

Considering the date and time the error happened, I would say that the cluster was indeed busy. It's hard to know what you consider "busy" but it was definitely not little traffic.

Any other errors in the log, like exceptions, stack traces, or timeouts?

I've copy/pasted all the logs I was able to gather in my first message. I have nothing more.

Are there are lot of design documents, and to they change often? Using any validate_doc_update functions in the design doc or just plain map reduce views.

We have thousands of databases and each database can have at most 2 design documents.
One of these design document is using validate_doc_update but the one impacted by the crash is just using plain map function.
They both doesn't change.

Hope this can help!
I see you might have found something to explain the error. Great news!

[nickva]

@bravier and @guanfeix thank you both for the extra debugging info, it's much appreciated

[jaydoane]

A fix for this issue has been merged and should be available in the next release: #3890