From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Return-Path: Date: Wed, 29 Aug 2018 18:21:15 +0300 From: Sergei Kalashnikov Subject: Re: [tarantool-patches] [PATCH v2] xlog: add request details to panic message for broken LSN Message-ID: <20180829152113.GA3636@localhost.localdomain> References: <1535368944-23713-1-git-send-email-ztarvos@gmail.com> <20180827170407.2igpxsf4zprp7vdu@esperanza> <20180828162740.GA11135@localhost.localdomain> <20180829095247.xbrk7euqwnssvl5q@esperanza> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20180829095247.xbrk7euqwnssvl5q@esperanza> To: Vladimir Davydov Cc: tarantool-patches List-ID: On Wed, Aug 29, 2018 at 12:52:47PM +0300, Vladimir Davydov wrote: > On Tue, Aug 28, 2018 at 07:27:41PM +0300, Sergei Kalashnikov wrote: > > diff --git a/src/box/relay.cc b/src/box/relay.cc > > index 138e66d..9f07655 100644 > > --- a/src/box/relay.cc > > +++ b/src/box/relay.cc > > @@ -676,6 +676,12 @@ relay_send_row(struct xstream *stream, struct xrow_header *packet) > > if (packet->replica_id != relay->replica->id || > > packet->lsn <= vclock_get(&relay->local_vclock_at_subscribe, > > packet->replica_id)) { > > + struct errinj *inj = errinj(ERRINJ_RELAY_BREAK_LSN, > > + ERRINJ_INT); > > + if (inj != NULL && packet->lsn == inj->iparam) { > > + packet->lsn = inj->iparam - 1; > > + say_warn("injected broken lsn: %lld", packet->lsn); > > Nit: int64_t isn't guaranteed to be equivalent to long long. Please > converse packet->lsn to long long explicitly. > OK, fixed. > > + } > > relay_send(relay, packet); > > } > > } > > diff --git a/src/box/wal.c b/src/box/wal.c > > index cd068a4..ade2c71 100644 > > --- a/src/box/wal.c > > +++ b/src/box/wal.c > > @@ -186,6 +186,11 @@ xlog_write_entry(struct xlog *l, struct journal_entry *entry) > > struct xrow_header **row = entry->rows; > > for (; row < entry->rows + entry->n_rows; row++) { > > (*row)->tm = ev_now(loop()); > > + struct errinj *inj = errinj(ERRINJ_XLOG_BREAK_LSN, ERRINJ_INT); > > + if (inj != NULL && inj->iparam == (*row)->lsn) { > > + (*row)->lsn = inj->iparam - 1; > > + say_warn("injected broken lsn: %lld", (*row)->lsn); > > Ditto. > Fixed. > > + } > > if (xlog_write_row(l, *row) < 0) { > > /* > > * Rollback all un-written rows > > diff --git a/src/errinj.h b/src/errinj.h > > index 64d13b0..c658cd7 100644 > > --- a/src/errinj.h > > +++ b/src/errinj.h > > @@ -118,6 +118,8 @@ struct errinj { > > _(ERRINJ_VY_LOG_FILE_RENAME, ERRINJ_BOOL, {.bparam = false}) \ > > _(ERRINJ_VY_RUN_FILE_RENAME, ERRINJ_BOOL, {.bparam = false}) \ > > _(ERRINJ_VY_INDEX_FILE_RENAME, ERRINJ_BOOL, {.bparam = false}) \ > > + _(ERRINJ_RELAY_BREAK_LSN, ERRINJ_INT, {.iparam = -1}) \ > > + _(ERRINJ_XLOG_BREAK_LSN, ERRINJ_INT, {.iparam = -1}) \ > > Nit: please rename ERRINJ_XLOG_BREAK_LSN to ERRINJ_WAL_BREAK_LSN - > it's used by the WAL thread, after all. > Done. > > diff --git a/test/xlog/panic_on_broken_lsn.test.lua b/test/xlog/panic_on_broken_lsn.test.lua > > new file mode 100644 > > index 0000000..d4abf6f > > --- /dev/null > > +++ b/test/xlog/panic_on_broken_lsn.test.lua > > @@ -0,0 +1,72 @@ > > +-- Issue 3105: Test logging of request with broken lsn before panicking > > +-- Two cases are covered: Recovery and Joining a new replica > > +env = require('test_run') > > +test_run = env.new() > > +test_run:cmd('restart server default with cleanup=True') > > We strive to make our tests run as fast as possible, that's why we don't > restart the default instance before/after each test. Instead we clean up > only what we have to. In your case, it means revoking privileges you > granted, dropping spaces you created, and disabling error injections you > enabled. > > Since in your test you assume that a new replica is assigned id 2, you > should call test_run:cleanup_cluster() in the beginning of this test. > This is much cheaper than restarting the default instance. > > If you don't restart the default instance, LSNs and space ids might be > different from run to run. That's OK, you can filter them out in the > test output, e.g. see > > https://github.com/tarantool/tarantool/blob/ac17838c9634ba7ebe329290ebd3314e37ec2255/test/replication/status.test.lua#L117 > I changed the test accordingly. Thanks for valuable info. > > + > > +fio = require('fio') > > +test_run:cmd("setopt delimiter ';'") > > +function grep_file_tail(filepath, bytes, pattern) > > + local fh = fio.open(filepath, {'O_RDONLY'}) > > + local size = fh:seek(0, 'SEEK_END') > > + if size < bytes then > > + bytes = size > > + end > > + fh:seek(-bytes, 'SEEK_END') > > + local line = fh:read(bytes) > > + fh:close() > > + return string.match(line, pattern) > > +end; > > +test_run:cmd("setopt delimiter ''"); > > + > > +-- Testing case of panic on recovery > > +test_run:cmd('create server panic with script="xlog/panic.lua"') > > +test_run:cmd('start server panic') > > +test_run:switch('panic') > > + > > +box.space._schema:replace{"t0", "v0"} > > +lsn = box.info.vclock[1] > > +box.error.injection.set("ERRINJ_XLOG_BREAK_LSN", lsn + 1) > > +box.space._schema:replace{"t0", "v1"} > > +box.error.injection.set("ERRINJ_XLOG_BREAK_LSN", -1) > > + > > +test_run:switch('default') > > +test_run:cmd('stop server panic') > > + > > +dirname = fio.pathjoin(fio.cwd(), "panic") > > +xlogs = fio.glob(dirname .. "/*.xlog") > > +fio.unlink(xlogs[#xlogs]) > > I don't understand why you need to delete the last xlog here. > This last xlog is always empty, so recovery_scan() skips the vclock_follow() call and it doesn't panic unless I delete the file. I'm not sure why it gets created since I didn't create checkpoints in the test explicitly. Later on, the actual row recovery happens, but recover_xlog() silently skips unordered lsn. > > + > > +test_run:cmd('start server panic with crash_expected=True') > > + > > +logpath = fio.pathjoin(fio.cwd(), 'panic.log') > > + > > +-- Check that log contains the mention of broken LSN and the request printout > > +grep_file_tail(logpath, 256, "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1, req: {.*}") > > + > > +test_run:cmd('cleanup server panic') > > +test_run:cmd('delete server panic') > > + > > +-- Testing case of panic on joining a new replica > > +box.schema.user.grant('guest', 'super') > > Please instead use > > box.schema.user.grant('guest', 'replication') > Done. > > +_ = box.schema.space.create('test') > > +_ = box.space.test:create_index('pk') > > +box.space.test:auto_increment{'v0'} > > +lsn = box.info.vclock[1] > > +box.error.injection.set("ERRINJ_RELAY_BREAK_LSN", lsn + 1) > > +box.space.test:auto_increment{'v1'} > > + > > +test_run:cmd('create server replica with rpl_master=default, script="xlog/replica.lua"') > > +test_run:cmd('start server replica with crash_expected=True') > > +fiber = require('fiber') > > +while box.info.replication == nil do fiber.sleep(0.001) end > > +while box.info.replication[2].downstream.status ~= "stopped" do fiber.sleep(0.001) end > > + > > +test_run:switch('default') > > Pointless 'switch' - the test is already running on behalf of the > default instance here. > Fixed. > > +logpath = fio.pathjoin(fio.cwd(), 'replica.log') > > +-- Check that log contains the mention of broken LSN and the request printout > > +grep_file_tail(logpath, 256, "LSN for 1 is used twice or COMMIT order is broken: confirmed: 5, new: 5, req: {.*}") > > + > > +test_run:cmd('cleanup server replica') > > +test_run:cmd('delete server replica') > > +test_run:cmd('restart server default with cleanup=True') Please find below the fixed patch. =================================== >From 2199d4e7e44fc8f6d93aca2774890b2dfd71f716 Mon Sep 17 00:00:00 2001 From: Sergei Kalashnikov Date: Wed, 29 Aug 2018 17:35:42 +0300 Subject: [PATCH v2] xlog: add request details to panic message for broken LSN Aid the debugging of replication issues related to out-of-order requests. Adds the details of request/tuple to the diagnostic message whenever possible. Closes #3105 --- https://github.com/tarantool/tarantool/issues/3105 https://github.com/tarantool/tarantool/commits/ztarvos/gh-3105-log-request-broken-lsn Changes in v2: - Removed vclock_follow_unsafe() - Renamed the new function vclock_follow_xrow(), removed extra params and moved it to the header. - Added error injections and simplified the test. - Added test for replica join case. - Removed trailing spaces. src/box/applier.cc | 6 +- src/box/recovery.cc | 4 +- src/box/relay.cc | 7 ++ src/box/vclock.c | 8 +- src/box/vclock.h | 8 ++ src/box/wal.c | 14 ++- src/box/xrow.h | 31 ++++++ src/errinj.h | 2 + test/box/errinj.result | 4 + test/xlog/panic_on_broken_lsn.result | 187 +++++++++++++++++++++++++++++++++ test/xlog/panic_on_broken_lsn.test.lua | 77 ++++++++++++++ test/xlog/suite.ini | 2 +- 12 files changed, 331 insertions(+), 19 deletions(-) create mode 100644 test/xlog/panic_on_broken_lsn.result create mode 100644 test/xlog/panic_on_broken_lsn.test.lua diff --git a/src/box/applier.cc b/src/box/applier.cc index dbb4d05..5d87867 100644 --- a/src/box/applier.cc +++ b/src/box/applier.cc @@ -336,8 +336,7 @@ applier_join(struct applier *applier) coio_read_xrow(coio, ibuf, &row); applier->last_row_time = ev_monotonic_now(loop()); if (iproto_type_is_dml(row.type)) { - vclock_follow(&replicaset.vclock, row.replica_id, - row.lsn); + vclock_follow_xrow(&replicaset.vclock, &row); xstream_write_xc(applier->subscribe_stream, &row); } else if (row.type == IPROTO_OK) { /* @@ -503,8 +502,7 @@ applier_subscribe(struct applier *applier) * the row is skipped when the replication * is resumed. */ - vclock_follow(&replicaset.vclock, row.replica_id, - row.lsn); + vclock_follow_xrow(&replicaset.vclock, &row); struct replica *replica = replica_by_id(row.replica_id); struct latch *latch = (replica ? &replica->order_latch : &replicaset.applier.order_latch); diff --git a/src/box/recovery.cc b/src/box/recovery.cc index fe14def..77357f0 100644 --- a/src/box/recovery.cc +++ b/src/box/recovery.cc @@ -135,7 +135,7 @@ recovery_scan(struct recovery *r, struct vclock *end_vclock) return; struct xrow_header row; while (xlog_cursor_next(&cursor, &row, true) == 0) - vclock_follow(end_vclock, row.replica_id, row.lsn); + vclock_follow_xrow(end_vclock, &row); xlog_cursor_close(&cursor, false); } @@ -266,7 +266,7 @@ recover_xlog(struct recovery *r, struct xstream *stream, * in case of forced recovery, when we skip the * failed row anyway. */ - vclock_follow(&r->vclock, row.replica_id, row.lsn); + vclock_follow_xrow(&r->vclock, &row); if (xstream_write(stream, &row) == 0) { ++row_count; if (row_count % 100000 == 0) diff --git a/src/box/relay.cc b/src/box/relay.cc index 138e66d..b0bc03e 100644 --- a/src/box/relay.cc +++ b/src/box/relay.cc @@ -676,6 +676,13 @@ relay_send_row(struct xstream *stream, struct xrow_header *packet) if (packet->replica_id != relay->replica->id || packet->lsn <= vclock_get(&relay->local_vclock_at_subscribe, packet->replica_id)) { + struct errinj *inj = errinj(ERRINJ_RELAY_BREAK_LSN, + ERRINJ_INT); + if (inj != NULL && packet->lsn == inj->iparam) { + packet->lsn = inj->iparam - 1; + say_warn("injected broken lsn: %lld", + (long long) packet->lsn); + } relay_send(relay, packet); } } diff --git a/src/box/vclock.c b/src/box/vclock.c index 2189ea8..b5eb280 100644 --- a/src/box/vclock.c +++ b/src/box/vclock.c @@ -42,13 +42,7 @@ vclock_follow(struct vclock *vclock, uint32_t replica_id, int64_t lsn) assert(lsn >= 0); assert(replica_id < VCLOCK_MAX); int64_t prev_lsn = vclock->lsn[replica_id]; - if (lsn <= prev_lsn) { - /* Never confirm LSN out of order. */ - panic("LSN for %u is used twice or COMMIT order is broken: " - "confirmed: %lld, new: %lld", - (unsigned) replica_id, - (long long) prev_lsn, (long long) lsn); - } + assert(lsn > prev_lsn); /* Easier add each time than check. */ vclock->map |= 1 << replica_id; vclock->lsn[replica_id] = lsn; diff --git a/src/box/vclock.h b/src/box/vclock.h index 928717c..111e291 100644 --- a/src/box/vclock.h +++ b/src/box/vclock.h @@ -199,6 +199,14 @@ vclock_sum(const struct vclock *vclock) return vclock->signature; } +/** + * Update vclock with the next LSN value for given replica id. + * + * @param vclock Vector clock. + * @param replica_id Replica identifier. + * @param lsn Next lsn. + * @return previous lsn value. + */ int64_t vclock_follow(struct vclock *vclock, uint32_t replica_id, int64_t lsn); diff --git a/src/box/wal.c b/src/box/wal.c index cd068a4..a11e0ad 100644 --- a/src/box/wal.c +++ b/src/box/wal.c @@ -186,6 +186,12 @@ xlog_write_entry(struct xlog *l, struct journal_entry *entry) struct xrow_header **row = entry->rows; for (; row < entry->rows + entry->n_rows; row++) { (*row)->tm = ev_now(loop()); + struct errinj *inj = errinj(ERRINJ_WAL_BREAK_LSN, ERRINJ_INT); + if (inj != NULL && inj->iparam == (*row)->lsn) { + (*row)->lsn = inj->iparam - 1; + say_warn("injected broken lsn: %lld", + (long long) (*row)->lsn); + } if (xlog_write_row(l, *row) < 0) { /* * Rollback all un-written rows @@ -652,8 +658,7 @@ wal_assign_lsn(struct wal_writer *writer, struct xrow_header **row, (*row)->lsn = vclock_inc(&writer->vclock, instance_id); (*row)->replica_id = instance_id; } else { - vclock_follow(&writer->vclock, (*row)->replica_id, - (*row)->lsn); + vclock_follow_xrow(&writer->vclock, *row); } } } @@ -878,9 +883,8 @@ wal_write(struct journal *journal, struct journal_entry *entry) */ if (vclock_get(&replicaset.vclock, instance_id) < (*last)->lsn) { - vclock_follow(&replicaset.vclock, - instance_id, - (*last)->lsn); + vclock_follow_xrow(&replicaset.vclock, + *last); } break; } diff --git a/src/box/xrow.h b/src/box/xrow.h index 4721670..3fc007a 100644 --- a/src/box/xrow.h +++ b/src/box/xrow.h @@ -522,6 +522,37 @@ xrow_to_iovec(const struct xrow_header *row, struct iovec *out); void xrow_decode_error(struct xrow_header *row); +/** + * Update vclock with the next LSN value for given replica id. + * The function will cause panic if the next LSN happens to be + * out of order. The details of provided row are included into + * diagnostic message. + * + * @param vclock Vector clock. + * @param row Data row. + * @return Previous LSN value. + */ +static inline int64_t +vclock_follow_xrow(struct vclock* vclock, const struct xrow_header *row) +{ + assert(row); + assert(row->replica_id < VCLOCK_MAX); + if (row->lsn <= vclock->lsn[row->replica_id]) { + struct request req; + const char *req_str = "n/a"; + if (xrow_decode_dml((struct xrow_header *)row, &req, 0) == 0) + req_str = request_str(&req); + /* Never confirm LSN out of order. */ + panic("LSN for %u is used twice or COMMIT order is broken: " + "confirmed: %lld, new: %lld, req: %s", + (unsigned) row->replica_id, + (long long) vclock->lsn[row->replica_id], + (long long) row->lsn, + req_str); + } + return vclock_follow(vclock, row->replica_id, row->lsn); +} + #if defined(__cplusplus) } /* extern "C" */ diff --git a/src/errinj.h b/src/errinj.h index 64d13b0..b6d4a4c 100644 --- a/src/errinj.h +++ b/src/errinj.h @@ -118,6 +118,8 @@ struct errinj { _(ERRINJ_VY_LOG_FILE_RENAME, ERRINJ_BOOL, {.bparam = false}) \ _(ERRINJ_VY_RUN_FILE_RENAME, ERRINJ_BOOL, {.bparam = false}) \ _(ERRINJ_VY_INDEX_FILE_RENAME, ERRINJ_BOOL, {.bparam = false}) \ + _(ERRINJ_RELAY_BREAK_LSN, ERRINJ_INT, {.iparam = -1}) \ + _(ERRINJ_WAL_BREAK_LSN, ERRINJ_INT, {.iparam = -1}) \ ENUM0(errinj_id, ERRINJ_LIST); extern struct errinj errinjs[]; diff --git a/test/box/errinj.result b/test/box/errinj.result index c7e4ce2..8dae761 100644 --- a/test/box/errinj.result +++ b/test/box/errinj.result @@ -58,8 +58,12 @@ errinj.info() state: 0 ERRINJ_XLOG_META: state: false + ERRINJ_WAL_BREAK_LSN: + state: -1 ERRINJ_WAL_WRITE_DISK: state: false + ERRINJ_RELAY_BREAK_LSN: + state: -1 ERRINJ_VY_LOG_FILE_RENAME: state: false ERRINJ_VY_RUN_WRITE: diff --git a/test/xlog/panic_on_broken_lsn.result b/test/xlog/panic_on_broken_lsn.result new file mode 100644 index 0000000..ad10217 --- /dev/null +++ b/test/xlog/panic_on_broken_lsn.result @@ -0,0 +1,187 @@ +-- Issue 3105: Test logging of request with broken lsn before panicking +-- Two cases are covered: Recovery and Joining a new replica +env = require('test_run') +--- +... +test_run = env.new() +--- +... +test_run:cleanup_cluster() +--- +... +fio = require('fio') +--- +... +test_run:cmd("setopt delimiter ';'") +--- +- true +... +function grep_file_tail(filepath, bytes, pattern) + local fh = fio.open(filepath, {'O_RDONLY'}) + local size = fh:seek(0, 'SEEK_END') + if size < bytes then + bytes = size + end + fh:seek(-bytes, 'SEEK_END') + local line = fh:read(bytes) + fh:close() + return string.match(line, pattern) +end; +--- +... +test_run:cmd("setopt delimiter ''"); +--- +- true +... +-- Testing case of panic on recovery +test_run:cmd('create server panic with script="xlog/panic.lua"') +--- +- true +... +test_run:cmd('start server panic') +--- +- true +... +test_run:switch('panic') +--- +- true +... +box.space._schema:replace{"t0", "v0"} +--- +- ['t0', 'v0'] +... +lsn = box.info.vclock[1] +--- +... +box.error.injection.set("ERRINJ_WAL_BREAK_LSN", lsn + 1) +--- +- ok +... +box.space._schema:replace{"t0", "v1"} +--- +- ['t0', 'v1'] +... +box.error.injection.set("ERRINJ_WAL_BREAK_LSN", -1) +--- +- ok +... +test_run:switch('default') +--- +- true +... +test_run:cmd('stop server panic') +--- +- true +... +dirname = fio.pathjoin(fio.cwd(), "panic") +--- +... +xlogs = fio.glob(dirname .. "/*.xlog") +--- +... +fio.unlink(xlogs[#xlogs]) +--- +- true +... +test_run:cmd('start server panic with crash_expected=True') +--- +- false +... +logpath = fio.pathjoin(fio.cwd(), 'panic.log') +--- +... +-- Check that log contains the mention of broken LSN and the request printout +grep_file_tail(logpath, 256, "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1, req: {.*}") +--- +- 'LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1, req: {type: + ''REPLACE'', lsn: 1, space_id: 272, index_id: 0, tuple: ["t0", "v1"]}' +... +test_run:cmd('cleanup server panic') +--- +- true +... +test_run:cmd('delete server panic') +--- +- true +... +-- Testing case of panic on joining a new replica +box.schema.user.grant('guest', 'replication') +--- +... +_ = box.schema.space.create('test') +--- +... +_ = box.space.test:create_index('pk') +--- +... +box.space.test:auto_increment{'v0'} +--- +- [1, 'v0'] +... +lsn = box.info.vclock[1] +--- +... +box.error.injection.set("ERRINJ_RELAY_BREAK_LSN", lsn + 1) +--- +- ok +... +box.space.test:auto_increment{'v1'} +--- +- [2, 'v1'] +... +test_run:cmd('create server replica with rpl_master=default, script="xlog/replica.lua"') +--- +- true +... +test_run:cmd('start server replica with crash_expected=True') +--- +- false +... +fiber = require('fiber') +--- +... +while box.info.replication == nil do fiber.sleep(0.001) end +--- +... +while box.info.replication[2].downstream.status ~= "stopped" do fiber.sleep(0.001) end +--- +... +box.error.injection.set("ERRINJ_RELAY_BREAK_LSN", -1) +--- +- ok +... +logpath = fio.pathjoin(fio.cwd(), 'replica.log') +--- +... +-- Check that log contains the mention of broken LSN and the request printout +test_run:cmd("push filter 'lsn: "..lsn..", space_id: [0-9]+' to 'lsn: , space_id: '") +--- +- true +... +test_run:cmd("push filter 'confirmed: "..lsn..", new: "..lsn.."' to ''") +--- +- true +... +grep_file_tail(logpath, 256, "(LSN for 1 is used twice or COMMIT order is broken: confirmed: "..lsn..", new: "..lsn.."), req: ({.*})") +--- +- 'LSN for 1 is used twice or COMMIT order is broken: ' +- '{type: ''INSERT'', lsn: , space_id: , index_id: 0, tuple: [2, "v1"]}' +... +test_run:cmd("clear filter") +--- +- true +... +test_run:cmd('cleanup server replica') +--- +- true +... +test_run:cmd('delete server replica') +--- +- true +... +box.space.test:drop() +--- +... +box.schema.user.revoke('guest', 'replication') +--- +... diff --git a/test/xlog/panic_on_broken_lsn.test.lua b/test/xlog/panic_on_broken_lsn.test.lua new file mode 100644 index 0000000..dd450d1 --- /dev/null +++ b/test/xlog/panic_on_broken_lsn.test.lua @@ -0,0 +1,77 @@ +-- Issue 3105: Test logging of request with broken lsn before panicking +-- Two cases are covered: Recovery and Joining a new replica +env = require('test_run') +test_run = env.new() +test_run:cleanup_cluster() + +fio = require('fio') +test_run:cmd("setopt delimiter ';'") +function grep_file_tail(filepath, bytes, pattern) + local fh = fio.open(filepath, {'O_RDONLY'}) + local size = fh:seek(0, 'SEEK_END') + if size < bytes then + bytes = size + end + fh:seek(-bytes, 'SEEK_END') + local line = fh:read(bytes) + fh:close() + return string.match(line, pattern) +end; +test_run:cmd("setopt delimiter ''"); + +-- Testing case of panic on recovery +test_run:cmd('create server panic with script="xlog/panic.lua"') +test_run:cmd('start server panic') +test_run:switch('panic') + +box.space._schema:replace{"t0", "v0"} +lsn = box.info.vclock[1] +box.error.injection.set("ERRINJ_WAL_BREAK_LSN", lsn + 1) +box.space._schema:replace{"t0", "v1"} +box.error.injection.set("ERRINJ_WAL_BREAK_LSN", -1) + +test_run:switch('default') +test_run:cmd('stop server panic') + +dirname = fio.pathjoin(fio.cwd(), "panic") +xlogs = fio.glob(dirname .. "/*.xlog") +fio.unlink(xlogs[#xlogs]) + +test_run:cmd('start server panic with crash_expected=True') + +logpath = fio.pathjoin(fio.cwd(), 'panic.log') + +-- Check that log contains the mention of broken LSN and the request printout +grep_file_tail(logpath, 256, "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1, req: {.*}") + +test_run:cmd('cleanup server panic') +test_run:cmd('delete server panic') + +-- Testing case of panic on joining a new replica +box.schema.user.grant('guest', 'replication') +_ = box.schema.space.create('test') +_ = box.space.test:create_index('pk') +box.space.test:auto_increment{'v0'} +lsn = box.info.vclock[1] +box.error.injection.set("ERRINJ_RELAY_BREAK_LSN", lsn + 1) +box.space.test:auto_increment{'v1'} + +test_run:cmd('create server replica with rpl_master=default, script="xlog/replica.lua"') +test_run:cmd('start server replica with crash_expected=True') +fiber = require('fiber') +while box.info.replication == nil do fiber.sleep(0.001) end +while box.info.replication[2].downstream.status ~= "stopped" do fiber.sleep(0.001) end +box.error.injection.set("ERRINJ_RELAY_BREAK_LSN", -1) + +logpath = fio.pathjoin(fio.cwd(), 'replica.log') +-- Check that log contains the mention of broken LSN and the request printout +test_run:cmd("push filter 'lsn: "..lsn..", space_id: [0-9]+' to 'lsn: , space_id: '") +test_run:cmd("push filter 'confirmed: "..lsn..", new: "..lsn.."' to ''") +grep_file_tail(logpath, 256, "(LSN for 1 is used twice or COMMIT order is broken: confirmed: "..lsn..", new: "..lsn.."), req: ({.*})") +test_run:cmd("clear filter") + +test_run:cmd('cleanup server replica') +test_run:cmd('delete server replica') + +box.space.test:drop() +box.schema.user.revoke('guest', 'replication') diff --git a/test/xlog/suite.ini b/test/xlog/suite.ini index 8ee9720..ffc812e 100644 --- a/test/xlog/suite.ini +++ b/test/xlog/suite.ini @@ -4,7 +4,7 @@ description = tarantool write ahead log tests script = xlog.lua disabled = snap_io_rate.test.lua valgrind_disabled = -release_disabled = errinj.test.lua panic_on_lsn_gap.test.lua +release_disabled = errinj.test.lua panic_on_lsn_gap.test.lua panic_on_broken_lsn.test.lua config = suite.cfg use_unix_sockets = True long_run = snap_io_rate.test.lua -- 1.8.3.1