You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@couchdb.apache.org by GitBox <gi...@apache.org> on 2022/03/29 04:54:14 UTC
[GitHub] [couchdb] jaydoane edited a comment on pull request #3890: Handle `not_found` lookups removing ddoc cache key
jaydoane edited a comment on pull request #3890:
URL: https://github.com/apache/couchdb/pull/3890#issuecomment-1081381897
I added logging to `ddoc_cache_entry:terminate/1` as well:
```
[info] 2022-03-29T02:54:26.712593Z node1@127.0.0.1 <0.4621.0> -------- ddoc_cache_lru:start Key={ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}} Pid=<0.25927.8>, Pids=#Ref<0.4244486069.2869821445.124970> Dbs=#Ref<0.4244486069.2869821445.124971>
[info] 2022-03-29T02:54:26.713215Z node1@127.0.0.1 <0.25927.8> -------- ddoc_cache_entry:terminate St={st,{ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}},{open_ok,{not_found,missing}},undefined,undefined,undefined,1}
[info] 2022-03-29T02:54:27.148635Z node1@127.0.0.1 <0.4621.0> -------- ddoc_cache_lru:start Key={ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}} Pid=<0.25936.8>, Pids=#Ref<0.4244486069.2869821445.124970> Dbs=#Ref<0.4244486069.2869821445.124971>
[info] 2022-03-29T02:54:27.149547Z node1@127.0.0.1 <0.25936.8> -------- ddoc_cache_entry:terminate St={st,{ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}},{open_ok,{not_found,missing}},undefined,undefined,undefined,1}
[info] 2022-03-29T02:54:27.712771Z node1@127.0.0.1 <0.4621.0> -------- ddoc_cache_lru:start Key={ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}} Pid=<0.26015.8>, Pids=#Ref<0.4244486069.2869821445.124970> Dbs=#Ref<0.4244486069.2869821445.124971>
[info] 2022-03-29T02:54:27.713406Z node1@127.0.0.1 <0.26015.8> -------- ddoc_cache_entry:terminate St={st,{ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}},{open_ok,{not_found,missing}},undefined,undefined,undefined,1}
```
and noticed that there's typically ~1ms between spawn and termination of a ddoc_cache_entry.
If I artificially widen that gap by adding a delay in terminate like so:
```diff
--- a/src/ddoc_cache/src/ddoc_cache_entry.erl
+++ b/src/ddoc_cache/src/ddoc_cache_entry.erl
@@ -145,6 +145,8 @@ init({Key, Wrapped}) ->
gen_server:enter_loop(?MODULE, [], St, hibernate).
terminate(_Reason, St) ->
+ timer:sleep(1),
+ couch_log:info("~p:terminate St=~p", [?MODULE, St]),
#st{
key = Key,
opener = Pid,
```
I can reproduce this every time using this in a remsh:
```
(node1@127.0.0.1)8> ddoc_cache:open(<<"users">>, <<"_design/feature_flags">>), ddoc_cache:open(<<"users">>, <<"_design/feature_flags">>).
{not_found,missing}
```
which does this in the logs:
```
[info] 2022-03-29T04:06:01.698265Z node1@127.0.0.1 <0.14792.12> -------- ddoc_cache_lru:start Key={ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}} Pid=<0.18310.12>, Pids=#Ref<0.4244486069.2877947905.247295> Dbs=#Ref<0.4244486069.2877947905.247296>
[info] 2022-03-29T04:06:01.700248Z node1@127.0.0.1 <0.14792.12> -------- ddoc_cache_lru:start Key={ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}} Pid=<0.18373.12>, Pids=#Ref<0.4244486069.2877947905.247295> Dbs=#Ref<0.4244486069.2877947905.247296>
[info] 2022-03-29T04:06:01.701389Z node1@127.0.0.1 <0.18310.12> -------- ddoc_cache_entry:terminate St={st,{ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}},{open_ok,{not_found,missing}},undefined,undefined,undefined,1}
[info] 2022-03-29T04:06:01.702401Z node1@127.0.0.1 <0.18373.12> -------- ddoc_cache_entry:terminate St={st,{ddoc_cache_entry_ddocid,{<<"users">>,<<"_design/feature_flags">>}},{open_ok,{not_found,missing}},undefined,undefined,undefined,1}
[error] 2022-03-29T04:06:01.702893Z node1@127.0.0.1 <0.14792.12> -------- gen_server ddoc_cache_lru terminated with reason: no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:301) <= 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)
last msg: redacted
state: {st,#Ref<0.4244486069.2877947905.247295>,#Ref<0.4244486069.2877947905.247296>,<0.14791.12>}
extra: []
[error] 2022-03-29T04:06:01.703080Z node1@127.0.0.1 <0.14792.12> -------- gen_server ddoc_cache_lru terminated with reason: no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:301) <= 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)
last msg: redacted
state: {st,#Ref<0.4244486069.2877947905.247295>,#Ref<0.4244486069.2877947905.247296>,<0.14791.12>}
extra: []
[error] 2022-03-29T04:06:01.703257Z node1@127.0.0.1 <0.14792.12> -------- CRASH REPORT Process ddoc_cache_lru (<0.14792.12>) with 0 neighbors crashed with reason: no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:301) <= 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.4616.0>], message_queue_len: 0, links: [<0.14791.12>,<0.4620.0>], dictionary: [], trap_exit: true, status: running, heap_size: 1598, stack_size: 29, reductions: 4403
[error] 2022-03-29T04:06:01.703434Z node1@127.0.0.1 <0.14792.12> -------- CRASH REPORT Process ddoc_cache_lru (<0.14792.12>) with 0 neighbors crashed with reason: no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:301) <= 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.4616.0>], message_queue_len: 0, links: [<0.14791.12>,<0.4620.0>], dictionary: [], trap_exit: true, status: running, heap_size: 1598, stack_size: 29, reductions: 4403
[error] 2022-03-29T04:06:01.703588Z node1@127.0.0.1 <0.4620.0> -------- Supervisor ddoc_cache_sup had child ddoc_cache_lru started with ddoc_cache_lru:start_link() at <0.14792.12> exit with reason no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:301) <= 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
[error] 2022-03-29T04:06:01.703695Z node1@127.0.0.1 <0.4620.0> -------- Supervisor ddoc_cache_sup had child ddoc_cache_lru started with ddoc_cache_lru:start_link() at <0.14792.12> exit with reason no match of right hand value not_found at ddoc_cache_lru:remove_key/2(line:301) <= 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
```
In short, any two `ddoc_cache:open` calls to the same non-existent ddoc that occur close enough in time can cause that error.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@couchdb.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org