Fix race condition when inserting into domain_event table #3212

arcusfelis · 2021-08-10T13:33:31Z

This PR addresses MIM-1459 "Inconsistent values in mongoose_domain_core".

Proposed changes include:

Fix for a race condition in PgSQL when allocating IDs.

Example

Node mim:

f().
recon_trace:calls({mongoose_domain_sql, select_updates_from, fun(_) -> return_trace() end}, 5000, [{scope, local}]).
From = 20000.
timer:sleep(6000).
[spawn(fun() -> mongoose_domain_api:insert_domain(<<"test", (integer_to_binary(N))/binary>>, <<"test type">>) end) || N <- lists:seq(From, From + 2000, 2)].

Node mim2:

f().
recon_trace:calls({mongoose_domain_sql, select_updates_from, fun(_) -> return_trace() end}, 5000, [{scope, local}]).
From = 20000.
timer:sleep(4000).
[spawn(fun() -> mongoose_domain_api:insert_domain(<<"test", (integer_to_binary(N))/binary>>, <<"test type">>) end) || N <- lists:seq(From + 1, From + 2001, 2)].

Do the check:

Nodes = [node()|nodes()].
List = [rpc:call(Node, mongoose_domain_api, get_domains_by_host_type, [<<"test type">>]) || Node <- Nodes].
[A,B|_] = List.
rp(lists:sort(A -- B)).
rp(lists:sort(B -- A)).

Not empty lists of difference in domains from two nodes.

Why does it happen?

PG assigns auto increment ids outside of a transaction. So, we could have to wait for records to be committed sometimes (rarely, usually 1 second waiting would be enough, once a missing event is detected).

What is the fix?

We check that ids we get from DB are incrementing without any gaps 1,2,3,4,5...
If a gap is detected (i.e. something like 1,2,4,5), we just wait and retry.

Domain_settings table has the same issue, but it would be triggered only at the load time, which is rare.
But what we can do is to maybe start rolling event updates not from the last event at the moment, but from an event, which is at least 10 (or 30?) seconds old.

Alternative fix

Don't use auto-increments. Always do in a transaction:

SELECT max(id) + 1 FROM domain_events;

to get an ID for a new event. If a transaction fails - just restart it.
This could be a bit slower on insertion, but could be a cleaner solution ;)

The alt fix would not work under intensive domain insertion rate though.

Logging

Will print

when=2021-08-11T15:54:49.286084+00:00 level=warning what=wait_for_gaps pid=<0.3267.0> at=mongoose_domain_gaps:handle_gaps/1:20 gaps=[1981]

codecov · 2021-08-10T13:44:46Z

Codecov Report

Merging #3212 (c68ab32) into master (88c9463) will increase coverage by 0.09%.
The diff coverage is 77.55%.

@@            Coverage Diff             @@
##           master    #3212      +/-   ##
==========================================
+ Coverage   80.23%   80.32%   +0.09%     
==========================================
  Files         397      398       +1     
  Lines       32474    32517      +43     
==========================================
+ Hits        26054    26120      +66     
+ Misses       6420     6397      -23

Impacted Files	Coverage Δ
src/domain/mongoose_domain_loader.erl	`75.47% <53.84%> (-8.98%)`	⬇️
src/domain/mongoose_domain_gaps.erl	`85.29% <85.29%> (ø)`
src/domain/mongoose_domain_sql.erl	`81.90% <100.00%> (ø)`
src/domain/service_domain_db.erl	`78.12% <100.00%> (+0.34%)`	⬆️
src/mod_roster.erl	`79.17% <0.00%> (-0.25%)`	⬇️
src/mod_muc_log.erl	`77.88% <0.00%> (ø)`
src/mod_muc_room.erl	`77.18% <0.00%> (+0.05%)`	⬆️
src/pubsub/mod_pubsub.erl	`73.23% <0.00%> (+0.05%)`	⬆️
src/ejabberd_sm.erl	`84.59% <0.00%> (+0.32%)`	⬆️
... and 8 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 88c9463...c68ab32. Read the comment docs.

mongoose-im · 2021-08-10T13:44:54Z

small_tests_24 / small_tests / 9bbd884
Reports root / small

internal_mnesia_24 / internal_mnesia / 9bbd884
Reports root/ big
OK: 1588 / Failed: 0 / User-skipped: 287 / Auto-skipped: 0

dynamic_domains_24 / pgsql_mnesia / 9bbd884
Reports root/ big
OK: 1644 / Failed: 0 / User-skipped: 111 / Auto-skipped: 0

small_tests_22 / small_tests / 9bbd884
Reports root / small

dynamic_domains_23 / pgsql_mnesia / 9bbd884
Reports root/ big
OK: 1644 / Failed: 0 / User-skipped: 111 / Auto-skipped: 0

small_tests_23 / small_tests / 9bbd884
Reports root / small

ldap_mnesia_24 / ldap_mnesia / 9bbd884
Reports root/ big
OK: 1515 / Failed: 0 / User-skipped: 360 / Auto-skipped: 0

ldap_mnesia_23 / ldap_mnesia / 9bbd884
Reports root/ big
OK: 1515 / Failed: 0 / User-skipped: 360 / Auto-skipped: 0

ldap_mnesia_22 / ldap_mnesia / 9bbd884
Reports root/ big
OK: 1515 / Failed: 0 / User-skipped: 360 / Auto-skipped: 0

pgsql_mnesia_24 / pgsql_mnesia / 9bbd884
Reports root/ big
OK: 3086 / Failed: 0 / User-skipped: 184 / Auto-skipped: 0

pgsql_mnesia_22 / pgsql_mnesia / 9bbd884
Reports root/ big
OK: 3086 / Failed: 0 / User-skipped: 184 / Auto-skipped: 0

mysql_redis_24 / mysql_redis / 9bbd884
Reports root/ big
OK: 3087 / Failed: 3 / User-skipped: 201 / Auto-skipped: 0

mam_SUITE:rdbms_prefs_cases:prefs_set_cdata_request

{error,{test_case_failed,"ASSERT EQUAL\n\tExpected {prefs_result_iq,<<\"roster\">>,\n                  [<<\"[email protected]\">>,\n                   <<\"[email protected]\">>],\n                  []}\n\tValue {prefs_result_iq,<<\"always\">>,\n                 [<<\"[email protected]\">>,\n                <<\"[email protected]\">>],\n                 []}\n"}}

Fix race condition when inserting into domain_event table #3212

Fix race condition when inserting into domain_event table #3212

Conversation

arcusfelis commented Aug 10, 2021 • edited Loading

Example

Why does it happen?

What is the fix?

Alternative fix

Logging

codecov bot commented Aug 10, 2021 • edited Loading

Codecov Report

mongoose-im commented Aug 10, 2021 • edited Loading

mongoose-im commented Aug 11, 2021 • edited Loading

mongoose-im commented Aug 11, 2021 • edited Loading

chrzaszcz left a comment • edited Loading

Choose a reason for hiding this comment

mongoose-im commented Aug 12, 2021 • edited Loading

mongoose-im commented Aug 12, 2021 • edited Loading

chrzaszcz left a comment

Choose a reason for hiding this comment

arcusfelis commented Aug 10, 2021 •

edited

Loading

codecov bot commented Aug 10, 2021 •

edited

Loading

mongoose-im commented Aug 10, 2021 •

edited

Loading

mongoose-im commented Aug 11, 2021 •

edited

Loading

mongoose-im commented Aug 11, 2021 •

edited

Loading

chrzaszcz left a comment •

edited

Loading

mongoose-im commented Aug 12, 2021 •

edited

Loading

mongoose-im commented Aug 12, 2021 •

edited

Loading