{"action":"created","issue":{"url":"https://api.github.com/repos/basho/riak_kv/issues/1563","repository_url":"https://api.github.com/repos/basho/riak_kv","labels_url":"https://api.github.com/repos/basho/riak_kv/issues/1563/labels{/name}","comments_url":"https://api.github.com/repos/basho/riak_kv/issues/1563/comments","events_url":"https://api.github.com/repos/basho/riak_kv/issues/1563/events","html_url":"https://github.com/basho/riak_kv/pull/1563","id":193948070,"number":1563,"title":"catch sudden qbuf gen_server EXITs in riak kv_qry_worker","user":{"login":"hmmr","id":1107079,"avatar_url":"https://avatars.githubusercontent.com/u/1107079?v=3","gravatar_id":"","url":"https://api.github.com/users/hmmr","html_url":"https://github.com/hmmr","followers_url":"https://api.github.com/users/hmmr/followers","following_url":"https://api.github.com/users/hmmr/following{/other_user}","gists_url":"https://api.github.com/users/hmmr/gists{/gist_id}","starred_url":"https://api.github.com/users/hmmr/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/hmmr/subscriptions","organizations_url":"https://api.github.com/users/hmmr/orgs","repos_url":"https://api.github.com/users/hmmr/repos","events_url":"https://api.github.com/users/hmmr/events{/privacy}","received_events_url":"https://api.github.com/users/hmmr/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":8,"created_at":"2016-12-07T03:20:11Z","updated_at":"2016-12-07T17:43:17Z","closed_at":"2016-12-07T17:43:16Z","pull_request":{"url":"https://api.github.com/repos/basho/riak_kv/pulls/1563","html_url":"https://github.com/basho/riak_kv/pull/1563","diff_url":"https://github.com/basho/riak_kv/pull/1563.diff","patch_url":"https://github.com/basho/riak_kv/pull/1563.patch"},"body":"This is an attempt to address a crash such as observed in `riak_kv_qry_N` gen_server with these symptoms:\r\n\r\n```\r\n2016-12-06 17:08:58.573 [info] <0.450.0>@riak_kv_qry_worker:estimate_query_size:284 Cancelling LIMIT 99999 query because projected result size exceeds limit (26999730 > 100, subqueries 2 of 50 done, query {riak_select_v3,{riak_sel_clause_v1,rows,[],[varchar,varchar,timestamp,varchar,sint64],[<<\"a\">>,<<\"b\">>,<<\"c\">>,<<\"d\">>,<<\"e\">>],[#Fun<riak_kv_qry_compiler.5.29991689>],[#Fun<riak_kv_qry_compiler.8.29991689>]},<<\"t1\">>,[{startkey,[{<<\"a\">>,varchar,<<\"A00001\">>},{<<\"b\">>,varchar,<<\"B\">>},{<<\"c\">>,timestamp,5000000}]},{endkey,[{<<\"a\">>,varchar,<<\"A00001\">>},{<<\"b\">>,varchar,<<\"B\">>},{<<\"c\">>,timestamp,5010000}]},{filter,[]}],[{<<\"d\">>,asc,nulls_last}],[99999],riak_ql_table_t1_320523031941664944417524937300681317050,{key_v1,[{param_v2,[<<\"a\">>],undefined},{param_v2,[<<\"b\">>],undefined},{hash_fn_v1,riak_ql_quanta,quantum,[{param_v2,[<<\"c\">>],undefined},10,s],timestamp}]},true,timeseries,undefined,{key_v1,[{param_v2,[<<\"a\">>],undefined},{param_v2,[<<\"b\">>],undefined},{param_v2,[<<\"c\">>],undefined}]},[],[],undefined})\r\n2016-12-06 17:08:58.619 [warning] <0.446.0>@riak_kv_qry_buffers_ldb:new_table:60 qbuf eleveldb:open(./data/query_buffers/t1_a+b+c+d+e_d.al__00000441380000618066) failed: {db_open,\"IO error: ./data/query_buffers/t1_a+b+c+d+e_d.al__00000441380000618066/LOCK: Not a directory\"}\r\n2016-12-06 17:08:58.619 [warning] <0.2354.0>@riak_kv_qry:maybe_create_query_buffer:300 Failed to set up query buffer for {riak_select_v3,{riak_sel_clause_v1,rows,[],[],[],[{identifier,[<<\"*\">>]}],[]},<<\"t1\">>,[{and_,{'<=',<<\"c\">>,{integer,5510000}},{and_,{'>=',<<\"c\">>,{integer,5000000}},{and_,{'=',<<\"a\">>,{binary,<<\"A00001\">>}},{'=',<<\"b\">>,{binary,<<\"B\">>}}}}}],[{<<\"d\">>,asc,nulls_last}],[],riak_ql_table_t1_320523031941664944417524937300681317050,none,false,sql,undefined,undefined,[],[],undefined}: db_open\r\n2016-12-06 17:09:08.097 [info] <0.446.0>@riak_kv_qry_buffers:do_reap_expired_qbufs:576 Reaped incompletely filled qbuf <<\"t1_a+b+c+d+e_d.al__00000441380000420040\">>\r\n2016-12-06 17:09:08.104 [info] <0.446.0>@riak_kv_qry_buffers:do_reap_expired_qbufs:576 Reaped incompletely filled qbuf <<\"t1_a+b+c+d+e_d.al__00000441380000512049\">>\r\n2016-12-06 17:09:14.794 [warning] <0.6.0> lager_error_logger_h dropped 16 messages in the last second that exceeded the limit of 100 messages/sec\r\n2016-12-06 17:09:14.794 [error] <0.450.0> gen_server riak_kv_qry_2 terminated with reason: {timeout,{gen_server,call,[riak_kv_qry_buffers,{batch_put,<<131,114,0,3,100,0,14,100,101,118,49,64,49,50,55,46,48,46,48,46,49,1,0,0,78,13,0,0,0,0,0,0,0,0>>,[[<<\"A00001\">>,<<\"B\">>,5370000,<<\"k00031\">>,369],[<<\"A00001\">>,<<\"B\">>,5372000,<<\"k00-31\">>,371],[<<\"A00001\">>,<<\"B\">>,5374000,<<\"k00-81\">>,373],[<<\"A00001\">>,<<\"B\">>,5376000,<<\"k0-100\">>,[]],[<<\"A00001\">>,<<\"B\">>,5378000,<<\"k00-81\">>,377]]}]}}\r\n2016-12-06 17:09:14.794 [error] <0.450.0> CRASH REPORT Process riak_kv_qry_2 with 0 neighbours exited with reason: {timeout,{gen_server,call,[riak_kv_qry_buffers,{batch_put,<<131,114,0,3,100,0,14,100,101,118,49,64,49,50,55,46,48,46,48,46,49,1,0,0,78,13,0,0,0,0,0,0,0,0>>,[[<<\"A00001\">>,<<\"B\">>,5370000,<<\"k00031\">>,369],[<<\"A00001\">>,<<\"B\">>,5372000,<<\"k00-31\">>,371],[<<\"A00001\">>,<<\"B\">>,5374000,<<\"k00-81\">>,373],[<<\"A00001\">>,<<\"B\">>,5376000,<<\"k0-100\">>,[]],[<<\"A00001\">>,<<\"B\">>,5378000,<<\"k00-81\">>,377]]}]}} in gen_server:terminate/6 line 744\r\n2016-12-06 17:09:14.795 [error] <0.444.0> Supervisor riak_kv_qry_sup had child riak_kv_qry_2 started with riak_kv_qry_worker:start_link(riak_kv_qry_2) at <0.450.0> exit with reason {timeout,{gen_server,call,[riak_kv_qry_buffers,{batch_put,<<131,114,0,3,100,0,14,100,101,118,49,64,49,50,55,46,48,46,48,46,49,1,0,0,78,13,0,0,0,0,0,0,0,0>>,[[<<\"A00001\">>,<<\"B\">>,5370000,<<\"k00031\">>,369],[<<\"A00001\">>,<<\"B\">>,5372000,<<\"k00-31\">>,371],[<<\"A00001\">>,<<\"B\">>,5374000,<<\"k00-81\">>,373],[<<\"A00001\">>,<<\"B\">>,5376000,<<\"k0-100\">>,[]],[<<\"A00001\">>,<<\"B\">>,5378000,<<\"k00-81\">>,377]]}]}} in context child_terminated\r\n```\r\n\r\nIn a session of speculative debugging (apparently this requires superfast or superslow machines as it could not be reproduced locally) of a failing run of `ts_simple_query_buffers`), I see the situation leading up to the crash unfolding as follows:\r\n\r\n* In test case `query_orderby_max_data_size_error`, a query with a lot of subqueries (the one with `LIMIT 99999`) spawns 20 query workers (the current value of `riak_kv.timeseries_query_max_running_fsms`;\r\n* On arrival of the first two, `riak_kv_qry_worker:estimate_query_size` figures the total expected size of the query will be too large, and invokes `cancel_error_query`, with the remaining 18 still spinning;\r\n* Over at `ts_simple_query_buffers`, CT machinery receives and acks the error, and proceed to run the next test case, `query_orderby_ldb_io_error`;\r\n* That test case does evil to the query_buffer directory, effectively causing all calls involving the underlying leveldb instance to fail with `db_open` -- again, this is the expected outcome in this test case, and it is duly acked;\r\n* Those late query workers start sending chunks of data, eventually calling `riak_kv_qry_buffers:put_data`, which for reasons unclear to me, times out. Exactly why it times out -- and why that should throw an exception -- is unclear.\r\n* The exception propagates and brings down the `riak_kv_qry_N` worker.\r\n\r\nAgain, I did not see the exception itself, but there's an advice I figured I should follow: http://erlang.org/pipermail/erlang-questions/2013-June/074131.html. That is, protect calls of `riak_kv_qry_buffer` functions with a catch."},"comment":{"url":"https://api.github.com/repos/basho/riak_kv/issues/comments/265517422","html_url":"https://github.com/basho/riak_kv/pull/1563#issuecomment-265517422","issue_url":"https://api.github.com/repos/basho/riak_kv/issues/1563","id":265517422,"user":{"login":"thumbot","id":20921557,"avatar_url":"https://avatars.githubusercontent.com/u/20921557?v=3","gravatar_id":"","url":"https://api.github.com/users/thumbot","html_url":"https://github.com/thumbot","followers_url":"https://api.github.com/users/thumbot/followers","following_url":"https://api.github.com/users/thumbot/following{/other_user}","gists_url":"https://api.github.com/users/thumbot/gists{/gist_id}","starred_url":"https://api.github.com/users/thumbot/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/thumbot/subscriptions","organizations_url":"https://api.github.com/users/thumbot/orgs","repos_url":"https://api.github.com/users/thumbot/repos","events_url":"https://api.github.com/users/thumbot/events{/privacy}","received_events_url":"https://api.github.com/users/thumbot/received_events","type":"User","site_admin":false},"created_at":"2016-12-07T17:43:17Z","updated_at":"2016-12-07T17:43:17Z","body":"Successfully merged *basho/riak_kv/pulls/1563* (*90691590aff2aeb33a32625574d9c0ccb9b6d2ee* on to *riak_ts-develop*)\n\n ```yaml    \n---\n:sha: 459ec6865d40976f23bd865f32fb9c73751c9cbe\n:merged: true\n:message: Pull Request successfully merged\n\n ``` \n"}}
{"actor":{"display_login":"thumbot"}}