From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 063D32925E for ; Mon, 27 Aug 2018 07:23:31 -0400 (EDT) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing.freelists.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 8hGGvPdSGAIJ for ; Mon, 27 Aug 2018 07:23:30 -0400 (EDT) Received: from mail-lj1-f196.google.com (mail-lj1-f196.google.com [209.85.208.196]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTPS id 8345A2922B for ; Mon, 27 Aug 2018 07:23:30 -0400 (EDT) Received: by mail-lj1-f196.google.com with SMTP id q127-v6so12011372ljq.11 for ; Mon, 27 Aug 2018 04:23:30 -0700 (PDT) From: Sergei Kalashnikov Subject: [tarantool-patches] [PATCH v2] xlog: add request details to panic message for broken LSN Date: Mon, 27 Aug 2018 14:22:24 +0300 Message-Id: <1535368944-23713-1-git-send-email-ztarvos@gmail.com> Sender: tarantool-patches-bounce@freelists.org Errors-to: tarantool-patches-bounce@freelists.org Reply-To: tarantool-patches@freelists.org List-help: List-unsubscribe: List-software: Ecartis version 1.0.0 List-Id: tarantool-patches List-subscribe: List-owner: List-post: List-archive: To: tarantool-patches@freelists.org Cc: Sergei Kalashnikov 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 src/box/applier.cc | 6 +- src/box/recovery.cc | 4 +- src/box/relay.cc | 8 + src/box/vclock.c | 8 +- src/box/vclock.h | 8 + src/box/wal.c | 8 +- src/box/xlog.c | 8 + src/box/xrow.h | 29 ++++ src/errinj.h | 2 + test/box/errinj.result | 4 + test/xlog/log_request_broken_lsn_panic.result | 187 ++++++++++++++++++++++++ test/xlog/log_request_broken_lsn_panic.test.lua | 78 ++++++++++ test/xlog/panic_replica.lua | 9 ++ test/xlog/suite.ini | 2 +- 14 files changed, 342 insertions(+), 19 deletions(-) create mode 100644 test/xlog/log_request_broken_lsn_panic.result create mode 100644 test/xlog/log_request_broken_lsn_panic.test.lua create mode 100644 test/xlog/panic_replica.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..2d0b651 100644 --- a/src/box/relay.cc +++ b/src/box/relay.cc @@ -678,4 +678,12 @@ relay_send_row(struct xstream *stream, struct xrow_header *packet) packet->replica_id)) { relay_send(relay, packet); } +#ifndef NDEBUG + struct errinj *inj = errinj(ERRINJ_RELAY_BREAK_LSN, ERRINJ_INT); + if (inj != NULL && packet->lsn == inj->iparam) { + relay_send(relay, packet); + diag_set(ClientError, ER_INJECTION, + "relay broken lsn injection lsn"); + } +#endif } 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..9cc1901 100644 --- a/src/box/wal.c +++ b/src/box/wal.c @@ -652,8 +652,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 +877,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/xlog.c b/src/box/xlog.c index d399a72..46cf7ed 100644 --- a/src/box/xlog.c +++ b/src/box/xlog.c @@ -1246,6 +1246,14 @@ xlog_write_row(struct xlog *log, const struct xrow_header *packet) size_t page_offset = obuf_size(&log->obuf); /** encode row into iovec */ struct iovec iov[XROW_IOVMAX]; +#ifndef NDEBUG + struct errinj *inj = errinj(ERRINJ_XLOG_BREAK_LSN, ERRINJ_INT); + if (inj != NULL && inj->iparam == packet->lsn) { + ((struct xrow_header *)packet)->lsn = inj->iparam - 1; + diag_set(ClientError, ER_INJECTION, + "xlog broken lsn injection lsn"); + } +#endif /** don't write sync to the disk */ int iovcnt = xrow_header_encode(packet, 0, iov, 0); if (iovcnt < 0) { diff --git a/src/box/xrow.h b/src/box/xrow.h index 4721670..f7eda91 100644 --- a/src/box/xrow.h +++ b/src/box/xrow.h @@ -522,6 +522,35 @@ 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; + xrow_decode_dml((struct xrow_header *)row, &req, 0); + /* 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, + request_str(&req)); + } + 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..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}) \ ENUM0(errinj_id, ERRINJ_LIST); extern struct errinj errinjs[]; diff --git a/test/box/errinj.result b/test/box/errinj.result index c7e4ce2..dca2c2d 100644 --- a/test/box/errinj.result +++ b/test/box/errinj.result @@ -16,6 +16,8 @@ errinj.info() state: 0 ERRINJ_WAL_WRITE: state: false + ERRINJ_XLOG_BREAK_LSN: + state: -1 ERRINJ_HTTPC_EXECUTE: state: false ERRINJ_VYRUN_DATA_READ: @@ -60,6 +62,8 @@ errinj.info() state: false 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/log_request_broken_lsn_panic.result b/test/xlog/log_request_broken_lsn_panic.result new file mode 100644 index 0000000..2fd29c1 --- /dev/null +++ b/test/xlog/log_request_broken_lsn_panic.result @@ -0,0 +1,187 @@ +-- Issue 3105: Test logging of request with broken lsn before panicking +-- Two cases are covered: Recovery and Initial Join +env = require('test_run') +--- +... +test_run = env.new() +--- +... +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 replica with script="xlog/panic_replica.lua"') +--- +- true +... +test_run:cmd('start server replica') +--- +- true +... +test_run:switch('replica') +--- +- true +... +box.space._schema:replace{"t0", "v0"} +--- +- ['t0', 'v0'] +... +lsn = box.info.vclock[1] +--- +... +box.error.injection.set("ERRINJ_XLOG_BREAK_LSN", lsn + 1) +--- +- ok +... +box.space._schema:replace{"t0", "v1"} +--- +- ['t0', 'v1'] +... +box.error.injection.set("ERRINJ_XLOG_BREAK_LSN", -1) +--- +- ok +... +test_run:switch('default') +--- +- true +... +test_run:cmd('stop server replica') +--- +- true +... +dirname = fio.pathjoin(fio.cwd(), "panic_replica") +--- +... +xlogs = fio.glob(dirname .. "/*.xlog") +--- +... +fio.unlink(xlogs[#xlogs]) +--- +- true +... +test_run:cmd('start server replica with crash_expected=True') +--- +- false +... +logpath = fio.pathjoin(fio.cwd(), 'panic_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: 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 replica') +--- +- true +... +test_run:cmd('delete server replica') +--- +- true +... +-- Testing case of panic on initial join +test_run:cmd('create server leader with script="xlog/replica.lua"') +--- +- true +... +test_run:cmd("start server leader") +--- +- true +... +test_run:switch('leader') +--- +- true +... +box.schema.user.grant('guest', 'super') +--- +... +_ = 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=leader, script="xlog/panic_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 +--- +... +test_run:switch('default') +--- +- true +... +-- 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: 6, new: 6, req: {.*}") +--- +- 'LSN for 1 is used twice or COMMIT order is broken: confirmed: 6, new: 6, req: {type: + ''INSERT'', lsn: 6, space_id: 512, index_id: 0, tuple: [2, "v1"]}' +... +test_run:cmd('stop server leader') +--- +- true +... +test_run:cmd('cleanup server leader') +--- +- true +... +test_run:cmd('delete server leader') +--- +- true +... +test_run:cmd('cleanup server replica') +--- +- true +... +test_run:cmd('delete server replica') +--- +- true +... diff --git a/test/xlog/log_request_broken_lsn_panic.test.lua b/test/xlog/log_request_broken_lsn_panic.test.lua new file mode 100644 index 0000000..e0b3295 --- /dev/null +++ b/test/xlog/log_request_broken_lsn_panic.test.lua @@ -0,0 +1,78 @@ +-- Issue 3105: Test logging of request with broken lsn before panicking +-- Two cases are covered: Recovery and Initial Join +env = require('test_run') +test_run = env.new() + +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 replica with script="xlog/panic_replica.lua"') +test_run:cmd('start server replica') +test_run:switch('replica') + +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 replica') + +dirname = fio.pathjoin(fio.cwd(), "panic_replica") +xlogs = fio.glob(dirname .. "/*.xlog") +fio.unlink(xlogs[#xlogs]) + +test_run:cmd('start server replica with crash_expected=True') + +logpath = fio.pathjoin(fio.cwd(), 'panic_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: 1, new: 1, req: {.*}") + +test_run:cmd('cleanup server replica') +test_run:cmd('delete server replica') + +-- Testing case of panic on initial join +test_run:cmd('create server leader with script="xlog/replica.lua"') +test_run:cmd("start server leader") +test_run:switch('leader') + +box.schema.user.grant('guest', 'super') +_ = 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=leader, script="xlog/panic_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') +-- 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: 6, new: 6, req: {.*}") + +test_run:cmd('stop server leader') +test_run:cmd('cleanup server leader') +test_run:cmd('delete server leader') + +test_run:cmd('cleanup server replica') +test_run:cmd('delete server replica') diff --git a/test/xlog/panic_replica.lua b/test/xlog/panic_replica.lua new file mode 100644 index 0000000..ed0ba38 --- /dev/null +++ b/test/xlog/panic_replica.lua @@ -0,0 +1,9 @@ +#!/usr/bin/env tarantool + +box.cfg({ + listen = os.getenv("LISTEN"), + replication = os.getenv("MASTER"), + memtx_memory = 107374182, +}) + +require('console').listen(os.getenv('ADMIN')) diff --git a/test/xlog/suite.ini b/test/xlog/suite.ini index 8ee9720..f27b0f9 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 log_request_broken_lsn_panic.test.lua config = suite.cfg use_unix_sockets = True long_run = snap_io_rate.test.lua -- 1.8.3.1