This is an automated email from the git hooks/post-receive script.
teigland pushed a change to branch master in repository sanlock.
from b90eaeb sanlock: expand access error message adds 6501351 sanlock: preserve dblock values when setting shared flag adds f16530a sanlock: fix detection of shared lease adds 933a474 sanlock: fix release interference with paxos adds 735781d sanlock: fix incorrect error from release adds c1d65fd sanlock: retry ballot when new lver is seen new ab58c89 sanlock: improve log messages in paxos code new c695e1b sanlock: add a NOWAIT flag for convert new 672dbb1 release 3.6.0
The 3 revisions listed above as "new" are entirely new to this repository and will be described in separate emails. The revisions listed as "adds" were already present in the repository and have only been added to this reference.
Summary of changes: VERSION | 2 +- src/client.c | 4 +- src/cmd.c | 2 +- src/direct.c | 3 +- src/leader.h | 2 +- src/main.c | 5 + src/ondisk.c | 2 + src/paxos_dblock.h | 8 + src/paxos_lease.c | 462 +++++++++++++++++++++++++++++++++++++++---------- src/paxos_lease.h | 4 + src/resource.c | 179 ++++++++++++++----- src/resource.h | 2 +- src/sanlock.conf | 3 + src/sanlock_internal.h | 2 + src/sanlock_resource.h | 9 + 15 files changed, 550 insertions(+), 139 deletions(-)
This is an automated email from the git hooks/post-receive script.
teigland pushed a commit to branch master in repository sanlock.
commit ab58c897e547c77721a52c1833cc3865ecaad3b3 Author: David Teigland teigland@redhat.com Date: Mon Nov 20 15:00:54 2017 -0600
sanlock: improve log messages in paxos code
A lot of messages related to "interesting" conditions (which may want later inspection) were being written to /var/log/messages. Change these to be written only to sanlock.log or the memory debug buffer.
Log more paxos details so that the behavior of the algorithm can be more fully reconstructed. --- src/client.c | 4 +- src/main.c | 5 + src/paxos_lease.c | 333 +++++++++++++++++++++++++++++++++++++++---------- src/paxos_lease.h | 1 + src/resource.c | 3 + src/sanlock.conf | 3 + src/sanlock_internal.h | 1 + 7 files changed, 280 insertions(+), 70 deletions(-)
diff --git a/src/client.c b/src/client.c index 45aa06a..ad78c21 100644 --- a/src/client.c +++ b/src/client.c @@ -2014,6 +2014,8 @@ const char *sanlock_strerror(int rv) return "Lease write error in dblock"; case SANLK_DBLOCK_MBAL: return "Lease was acquired by another host in current ballot"; + case SANLK_DBLOCK_LVER: + return "Lease was acquired by another host in new ballot"; case SANLK_DBLOCK_CHECKSUM: return "Lease checksum error in dblock"; case SANLK_LEADER_READ: @@ -2036,8 +2038,6 @@ const char *sanlock_strerror(int rv) return "Lease num_hosts is incorrect"; case SANLK_LEADER_CHECKSUM: return "Lease checksum error in leader"; - case SANLK_ACQUIRE_LVER: - return "Lease leader version is unmatching"; case SANLK_ACQUIRE_LOCKSPACE: return "Lease lockspace is not found"; case SANLK_ACQUIRE_IDDISK: diff --git a/src/main.c b/src/main.c index 13fec0d..0117183 100644 --- a/src/main.c +++ b/src/main.c @@ -2351,6 +2351,10 @@ static void read_config_file(void) } else if (!strcmp(str, "renewal_history_size")) { get_val_int(line, &val); com.renewal_history_size = val; + + } else if (!strcmp(str, "paxos_debug_all")) { + get_val_int(line, &val); + com.paxos_debug_all = val; } }
@@ -3215,6 +3219,7 @@ int main(int argc, char *argv[]) com.renewal_read_extend_sec_set = 0; com.renewal_read_extend_sec = 0; com.renewal_history_size = DEFAULT_RENEWAL_HISTORY_SIZE; + com.paxos_debug_all = 0;
if (getgrnam("sanlock") && getpwnam("sanlock")) { com.uname = (char *)"sanlock"; diff --git a/src/paxos_lease.c b/src/paxos_lease.c index 210543f..a1f43e3 100644 --- a/src/paxos_lease.c +++ b/src/paxos_lease.c @@ -35,6 +35,22 @@ uint32_t crc32c(uint32_t crc, uint8_t *data, size_t length); int get_rand(int a, int b);
+/* + * BK_DEBUG_SIZE: size of buffer to hold ballot debug info, + * this can't be larger than LOG_STR_LEN 512 + * BK_STR_SIZE: the max length of a dblock string for one host + * BK_DEBUG_COUNT: the max number of hosts for which we'll copy + * dblock info + * + * BK_DEBUG_COUNT * BK_STR_SIZE + extra debug text that comes before + * the dblock info needs to be less than BK_DEBUG_SIZE. + * Be very careful about increasing BK_DEBUG_COUNT because the use + * of strncat depends on it. + */ +#define BK_DEBUG_SIZE 512 +#define BK_DEBUG_COUNT 4 +#define BK_STR_SIZE 80 + static uint32_t roundup_power_of_two(uint32_t val) { val--; @@ -427,10 +443,13 @@ static int verify_dblock(struct token *token, struct paxos_dblock *pd, uint32_t * host1 fail */
-static int run_ballot(struct task *task, struct token *token, int num_hosts, - uint64_t next_lver, uint64_t our_mbal, +static int run_ballot(struct task *task, struct token *token, uint32_t flags, + int num_hosts, uint64_t next_lver, uint64_t our_mbal, struct paxos_dblock *dblock_out) { + char bk_debug[BK_DEBUG_SIZE]; + char bk_str[BK_STR_SIZE]; + int bk_debug_count; struct paxos_dblock dblock; struct paxos_dblock bk_in; struct paxos_dblock bk_max; @@ -477,7 +496,7 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, * component is greater than dblock[p].mbal." */
- log_token(token, "ballot %llu phase1 mbal %llu", + log_token(token, "ballot %llu phase1 write mbal %llu", (unsigned long long)next_lver, (unsigned long long)our_mbal);
@@ -491,6 +510,7 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, num_writes = 0;
for (d = 0; d < num_disks; d++) { + /* acquire io: write 1 */ rv = write_dblock(task, token, &token->disks[d], token->host_id, &dblock); if (rv < 0) continue; @@ -504,6 +524,9 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, goto out; }
+ memset(bk_debug, 0, sizeof(bk_debug)); + bk_debug_count = 0; + num_reads = 0;
for (d = 0; d < num_disks; d++) { @@ -513,6 +536,7 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, continue; memset(iobuf[d], 0, iobuf_len);
+ /* acquire io: read 2 */ rv = read_iobuf(disk->fd, disk->offset, iobuf[d], iobuf_len, task, token->io_timeout, NULL); if (rv == SANLK_AIO_TIMEOUT) iobuf[d] = NULL; @@ -528,6 +552,28 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, paxos_dblock_in(bk_end, &bk_in); bk = &bk_in;
+ if (bk_in.mbal && ((flags & PAXOS_ACQUIRE_DEBUG_ALL) || (bk_in.lver >= dblock.lver))) { + if (bk_debug_count >= BK_DEBUG_COUNT) { + log_token(token, "ballot %llu phase1 read %s", + (unsigned long long)next_lver, bk_debug); + memset(bk_debug, 0, sizeof(bk_debug)); + bk_debug_count = 0; + } + + memset(bk_str, 0, sizeof(bk_str)); + snprintf(bk_str, BK_STR_SIZE, "%d:%llu:%llu:%llu:%llu:%llu:%llu:%x,", q, + (unsigned long long)bk_in.mbal, + (unsigned long long)bk_in.bal, + (unsigned long long)bk_in.inp, + (unsigned long long)bk_in.inp2, + (unsigned long long)bk_in.inp3, + (unsigned long long)bk_in.lver, + bk_in.flags); + bk_str[BK_STR_SIZE-1] = '\0'; + strncat(bk_debug, bk_str, BK_STR_SIZE-1); + bk_debug_count++; + } + rv = verify_dblock(token, bk, checksum); if (rv < 0) continue; @@ -538,10 +584,26 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, continue;
if (bk->lver > dblock.lver) { - /* I don't think this should happen */ - log_errot(token, "ballot %llu larger1 lver[%d] %llu", + log_level(0, token->token_id, NULL, LOG_WARNING, + "ballot %llu abort1 larger lver in bk[%d] %llu:%llu:%llu:%llu:%llu:%llu " + "our dblock %llu:%llu:%llu:%llu:%llu:%llu", (unsigned long long)next_lver, q, - (unsigned long long)bk->lver); + (unsigned long long)bk->mbal, + (unsigned long long)bk->bal, + (unsigned long long)bk->inp, + (unsigned long long)bk->inp2, + (unsigned long long)bk->inp3, + (unsigned long long)bk->lver, + (unsigned long long)dblock.mbal, + (unsigned long long)dblock.bal, + (unsigned long long)dblock.inp, + (unsigned long long)dblock.inp2, + (unsigned long long)dblock.inp3, + (unsigned long long)dblock.lver); + + log_token(token, "ballot %llu phase1 read %s", + (unsigned long long)next_lver, bk_debug); + error = SANLK_DBLOCK_LVER; goto out; } @@ -549,10 +611,26 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, /* see "It aborts the ballot" in comment above */
if (bk->mbal > dblock.mbal) { - log_errot(token, "ballot %llu abort1 mbal %llu mbal[%d] %llu", - (unsigned long long)next_lver, - (unsigned long long)our_mbal, q, - (unsigned long long)bk->mbal); + log_level(0, token->token_id, NULL, LOG_WARNING, + "ballot %llu abort1 larger mbal in bk[%d] %llu:%llu:%llu:%llu:%llu:%llu " + "our dblock %llu:%llu:%llu:%llu:%llu:%llu", + (unsigned long long)next_lver, q, + (unsigned long long)bk->mbal, + (unsigned long long)bk->bal, + (unsigned long long)bk->inp, + (unsigned long long)bk->inp2, + (unsigned long long)bk->inp3, + (unsigned long long)bk->lver, + (unsigned long long)dblock.mbal, + (unsigned long long)dblock.bal, + (unsigned long long)dblock.inp, + (unsigned long long)dblock.inp2, + (unsigned long long)dblock.inp3, + (unsigned long long)dblock.lver); + + log_token(token, "ballot %llu phase1 read %s", + (unsigned long long)next_lver, bk_debug); + error = SANLK_DBLOCK_MBAL; goto out; } @@ -576,6 +654,9 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, } }
+ log_token(token, "ballot %llu phase1 read %s", + (unsigned long long)next_lver, bk_debug); + if (!majority_disks(num_disks, num_reads)) { log_errot(token, "ballot %llu dblock read error %d", (unsigned long long)next_lver, rv); @@ -614,8 +695,7 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, dblock.checksum = 0; /* set after paxos_dblock_out */
if (bk_max.inp) { - /* not a problem, but interesting to see, so use log_error */ - log_errot(token, "ballot %llu choose bk_max[%d] lver %llu mbal %llu bal %llu inp %llu %llu %llu", + log_token(token, "ballot %llu choose bk_max[%d] lver %llu mbal %llu bal %llu inp %llu %llu %llu", (unsigned long long)next_lver, q_max, (unsigned long long)bk_max.lver, (unsigned long long)bk_max.mbal, @@ -634,7 +714,7 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts,
phase2 = 1;
- log_token(token, "ballot %llu phase2 bal %llu inp %llu %llu %llu q_max %d", + log_token(token, "ballot %llu phase2 write bal %llu inp %llu %llu %llu q_max %d", (unsigned long long)dblock.lver, (unsigned long long)dblock.bal, (unsigned long long)dblock.inp, @@ -645,6 +725,7 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, num_writes = 0;
for (d = 0; d < num_disks; d++) { + /* acquire io: write 2 */ rv = write_dblock(task, token, &token->disks[d], token->host_id, &dblock); if (rv < 0) continue; @@ -658,6 +739,9 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, goto out; }
+ memset(bk_debug, 0, sizeof(bk_debug)); + bk_debug_count = 0; + num_reads = 0;
for (d = 0; d < num_disks; d++) { @@ -667,6 +751,7 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, continue; memset(iobuf[d], 0, iobuf_len);
+ /* acquire io: read 3 */ rv = read_iobuf(disk->fd, disk->offset, iobuf[d], iobuf_len, task, token->io_timeout, NULL); if (rv == SANLK_AIO_TIMEOUT) iobuf[d] = NULL; @@ -682,6 +767,28 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, paxos_dblock_in(bk_end, &bk_in); bk = &bk_in;
+ if (bk->mbal && ((flags & PAXOS_ACQUIRE_DEBUG_ALL) || (bk->lver >= dblock.lver))) { + if (bk_debug_count >= BK_DEBUG_COUNT) { + log_token(token, "ballot %llu phase2 read %s", + (unsigned long long)next_lver, bk_debug); + memset(bk_debug, 0, sizeof(bk_debug)); + bk_debug_count = 0; + } + + memset(bk_str, 0, sizeof(bk_str)); + snprintf(bk_str, BK_STR_SIZE, "%d:%llu:%llu:%llu:%llu:%llu:%llu:%x,", q, + (unsigned long long)bk->mbal, + (unsigned long long)bk->bal, + (unsigned long long)bk->inp, + (unsigned long long)bk->inp2, + (unsigned long long)bk->inp3, + (unsigned long long)bk->lver, + bk->flags); + bk_str[BK_STR_SIZE-1] = '\0'; + strncat(bk_debug, bk_str, BK_STR_SIZE-1); + bk_debug_count++; + } + rv = verify_dblock(token, bk, checksum); if (rv < 0) continue; @@ -698,22 +805,26 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, * also be caught the the bk->mbal > dblock.mbal condition * below. */ - log_errot(token, "ballot %llu larger2 lver[%d] %llu dblock %llu", - (unsigned long long)next_lver, q, - (unsigned long long)bk->lver, - (unsigned long long)dblock.lver); - log_errot(token, "ballot %llu larger2 mbal[%d] %llu dblock %llu", + log_level(0, token->token_id, NULL, LOG_WARNING, + "ballot %llu abort2 larger lver in bk[%d] %llu:%llu:%llu:%llu:%llu:%llu " + "our dblock %llu:%llu:%llu:%llu:%llu:%llu", (unsigned long long)next_lver, q, (unsigned long long)bk->mbal, - (unsigned long long)dblock.mbal); - log_errot(token, "ballot %llu larger2 inp[%d] %llu %llu %llu dblock %llu %llu %llu", - (unsigned long long)next_lver, q, + (unsigned long long)bk->bal, (unsigned long long)bk->inp, (unsigned long long)bk->inp2, (unsigned long long)bk->inp3, + (unsigned long long)bk->lver, + (unsigned long long)dblock.mbal, + (unsigned long long)dblock.bal, (unsigned long long)dblock.inp, (unsigned long long)dblock.inp2, - (unsigned long long)dblock.inp3); + (unsigned long long)dblock.inp3, + (unsigned long long)dblock.lver); + + log_token(token, "ballot %llu phase2 read %s", + (unsigned long long)next_lver, bk_debug); + error = SANLK_DBLOCK_LVER; goto out; } @@ -721,16 +832,35 @@ static int run_ballot(struct task *task, struct token *token, int num_hosts, /* see "It aborts the ballot" in comment above */
if (bk->mbal > dblock.mbal) { - log_errot(token, "ballot %llu abort2 mbal %llu mbal[%d] %llu", - (unsigned long long)next_lver, - (unsigned long long)our_mbal, q, - (unsigned long long)bk->mbal); + log_level(0, token->token_id, NULL, LOG_WARNING, + "ballot %llu abort2 larger mbal in bk[%d] %llu:%llu:%llu:%llu:%llu:%llu " + "our dblock %llu:%llu:%llu:%llu:%llu:%llu", + (unsigned long long)next_lver, q, + (unsigned long long)bk->mbal, + (unsigned long long)bk->bal, + (unsigned long long)bk->inp, + (unsigned long long)bk->inp2, + (unsigned long long)bk->inp3, + (unsigned long long)bk->lver, + (unsigned long long)dblock.mbal, + (unsigned long long)dblock.bal, + (unsigned long long)dblock.inp, + (unsigned long long)dblock.inp2, + (unsigned long long)dblock.inp3, + (unsigned long long)dblock.lver); + + log_token(token, "ballot %llu phase2 read %s", + (unsigned long long)next_lver, bk_debug); + error = SANLK_DBLOCK_MBAL; goto out; } } }
+ log_token(token, "ballot %llu phase2 read %s", + (unsigned long long)next_lver, bk_debug); + if (!majority_disks(num_disks, num_reads)) { log_errot(token, "ballot %llu dblock read2 error %d", (unsigned long long)next_lver, rv); @@ -1115,13 +1245,18 @@ int paxos_lease_leader_read(struct task *task,
static int _lease_read_one(struct task *task, struct token *token, + uint32_t flags, struct sync_disk *disk, struct leader_record *leader_ret, struct paxos_dblock *our_dblock, uint64_t *max_mbal, int *max_q, - const char *caller) + const char *caller, + int log_bk_vals) { + char bk_debug[BK_DEBUG_SIZE]; + char bk_str[BK_STR_SIZE]; + int bk_debug_count; struct leader_record leader_end; struct paxos_dblock our_dblock_end; struct paxos_dblock bk; @@ -1162,6 +1297,9 @@ static int _lease_read_one(struct task *task, if (rv < 0) goto out;
+ memset(bk_debug, 0, sizeof(bk_debug)); + bk_debug_count = 0; + for (q = 0; q < leader_ret->num_hosts; q++) { bk_end = (struct paxos_dblock *)(iobuf + ((2 + q) * sector_size));
@@ -1169,6 +1307,29 @@ static int _lease_read_one(struct task *task,
paxos_dblock_in(bk_end, &bk);
+ if (log_bk_vals && bk.mbal && + ((flags & PAXOS_ACQUIRE_DEBUG_ALL) || (bk.lver >= leader_ret->lver))) { + if (bk_debug_count >= BK_DEBUG_COUNT) { + log_token(token, "leader %llu dblocks %s", + (unsigned long long)leader_ret->lver, bk_debug); + memset(bk_debug, 0, sizeof(bk_debug)); + bk_debug_count = 0; + } + + memset(bk_str, 0, sizeof(bk_str)); + snprintf(bk_str, BK_STR_SIZE, "%d:%llu:%llu:%llu:%llu:%llu:%llu:%x,", q, + (unsigned long long)bk.mbal, + (unsigned long long)bk.bal, + (unsigned long long)bk.inp, + (unsigned long long)bk.inp2, + (unsigned long long)bk.inp3, + (unsigned long long)bk.lver, + bk.flags); + bk_str[BK_STR_SIZE-1] = '\0'; + strncat(bk_debug, bk_str, BK_STR_SIZE-1); + bk_debug_count++; + } + rv = verify_dblock(token, &bk, checksum); if (rv < 0) goto out; @@ -1181,6 +1342,14 @@ static int _lease_read_one(struct task *task, *max_mbal = tmp_mbal; *max_q = tmp_q;
+ if (log_bk_vals) + log_token(token, "leader %llu owner %llu %llu %llu dblocks %s", + (unsigned long long)leader_ret->lver, + (unsigned long long)leader_ret->owner_id, + (unsigned long long)leader_ret->owner_generation, + (unsigned long long)leader_ret->timestamp, + bk_debug); + out: if (rv != SANLK_AIO_TIMEOUT) free(iobuf); @@ -1191,6 +1360,7 @@ static int _lease_read_one(struct task *task,
static int _lease_read_num(struct task *task, struct token *token, + uint32_t flags, struct leader_record *leader_ret, struct paxos_dblock *our_dblock, uint64_t *max_mbal, @@ -1226,8 +1396,8 @@ static int _lease_read_num(struct task *task, num_reads = 0;
for (d = 0; d < num_disks; d++) { - rv = _lease_read_one(task, token, &token->disks[d], &leader_one, - &dblock_one, &mbal_one, &q_one, caller); + rv = _lease_read_one(task, token, flags, &token->disks[d], &leader_one, + &dblock_one, &mbal_one, &q_one, caller, 0); if (rv < 0) continue;
@@ -1295,19 +1465,19 @@ static int _lease_read_num(struct task *task, * values from it. */
-static int paxos_lease_read(struct task *task, struct token *token, +static int paxos_lease_read(struct task *task, struct token *token, uint32_t flags, struct leader_record *leader_ret, - uint64_t *max_mbal, const char *caller) + uint64_t *max_mbal, const char *caller, int log_bk_vals) { struct paxos_dblock our_dblock; int rv, q = -1;
if (token->r.num_disks > 1) - rv = _lease_read_num(task, token, + rv = _lease_read_num(task, token, flags, leader_ret, &our_dblock, max_mbal, &q, caller); else - rv = _lease_read_one(task, token, &token->disks[0], - leader_ret, &our_dblock, max_mbal, &q, caller); + rv = _lease_read_one(task, token, flags, &token->disks[0], + leader_ret, &our_dblock, max_mbal, &q, caller, log_bk_vals);
if (rv == SANLK_OK) log_token(token, "%s leader %llu owner %llu %llu %llu max mbal[%d] %llu " @@ -1415,7 +1585,7 @@ int paxos_lease_acquire(struct task *task, uint64_t max_mbal; uint64_t num_mbal; uint64_t our_mbal; - int copy_cur_leader = 0; + int copy_cur_leader; int disk_open = 0; int error, rv, us; int other_io_timeout, other_host_dead_seconds; @@ -1426,8 +1596,11 @@ int paxos_lease_acquire(struct task *task, flags, (unsigned long long)acquire_lver, new_num_hosts);
restart: + memset(&tmp_leader, 0, sizeof(tmp_leader)); + copy_cur_leader = 0;
- error = paxos_lease_read(task, token, &cur_leader, &max_mbal, "paxos_acquire"); + /* acquire io: read 1 */ + error = paxos_lease_read(task, token, flags, &cur_leader, &max_mbal, "paxos_acquire", 1); if (error < 0) goto out;
@@ -1596,21 +1769,11 @@ int paxos_lease_acquire(struct task *task,
if ((host_id_leader.timestamp != last_timestamp) || (hs.last_live && (hs.last_check == hs.last_live))) { - if (flags & PAXOS_ACQUIRE_QUIET_FAIL) { - log_token(token, "paxos_acquire owner %llu " - "delta %llu %llu %llu alive", - (unsigned long long)cur_leader.owner_id, - (unsigned long long)host_id_leader.owner_id, - (unsigned long long)host_id_leader.owner_generation, - (unsigned long long)host_id_leader.timestamp); - } else { - log_errot(token, "paxos_acquire owner %llu " - "delta %llu %llu %llu alive", - (unsigned long long)cur_leader.owner_id, - (unsigned long long)host_id_leader.owner_id, - (unsigned long long)host_id_leader.owner_generation, - (unsigned long long)host_id_leader.timestamp); - } + log_token(token, "paxos_acquire owner %llu delta %llu %llu %llu alive", + (unsigned long long)cur_leader.owner_id, + (unsigned long long)host_id_leader.owner_id, + (unsigned long long)host_id_leader.owner_generation, + (unsigned long long)host_id_leader.timestamp); memcpy(leader_ret, &cur_leader, sizeof(struct leader_record));
/* It's possible that the live owner has released the @@ -1629,7 +1792,8 @@ int paxos_lease_acquire(struct task *task, cur_leader.owner_id, &owner_dblock); if (!rv && (owner_dblock.flags & DBLOCK_FL_RELEASED)) { /* not an error, but interesting to see */ - log_errot(token, "paxos_acquire owner %llu %llu %llu writer %llu owner dblock released", + log_level(0, token->token_id, NULL, LOG_WARNING, + "paxos_acquire owner %llu %llu %llu writer %llu owner dblock released", (unsigned long long)cur_leader.owner_id, (unsigned long long)cur_leader.owner_generation, (unsigned long long)cur_leader.timestamp, @@ -1684,12 +1848,26 @@ int paxos_lease_acquire(struct task *task, goto out; }
+ /* + * In this while loop we are waiting for an indication that the + * current owner is alive or dead, but if we see the leader + * owner change in the meantime, we'll restart the entire + * process. + */ + error = paxos_lease_leader_read(task, token, &tmp_leader, "paxos_acquire"); if (error < 0) goto out;
if (memcmp(&cur_leader, &tmp_leader, sizeof(struct leader_record))) { - log_token(token, "paxos_acquire restart leader changed"); + log_token(token, "paxos_acquire restart leader changed1 from " + "%llu %llu %llu to %llu %llu %llu", + (unsigned long long)cur_leader.owner_id, + (unsigned long long)cur_leader.owner_generation, + (unsigned long long)cur_leader.timestamp, + (unsigned long long)tmp_leader.owner_id, + (unsigned long long)tmp_leader.owner_generation, + (unsigned long long)tmp_leader.timestamp); goto restart; } } @@ -1730,6 +1908,7 @@ int paxos_lease_acquire(struct task *task, copy_cur_leader = 0; memcpy(&tmp_leader, &cur_leader, sizeof(struct leader_record)); } else { + /* acquire io: read 1 (for retry) */ error = paxos_lease_leader_read(task, token, &tmp_leader, "paxos_acquire"); if (error < 0) goto out; @@ -1743,9 +1922,10 @@ int paxos_lease_acquire(struct task *task,
if (tmp_leader.owner_id == token->host_id && tmp_leader.owner_generation == token->host_generation) { - /* not a problem, but interesting to see, so use log_error */ + /* not a problem, but interesting to see */
- log_errot(token, "paxos_acquire %llu owner is our inp " + log_level(0, token->token_id, NULL, LOG_WARNING, + "paxos_acquire %llu owner is our inp " "%llu %llu %llu commited by %llu", (unsigned long long)next_lver, (unsigned long long)tmp_leader.owner_id, @@ -1756,9 +1936,10 @@ int paxos_lease_acquire(struct task *task, memcpy(leader_ret, &tmp_leader, sizeof(struct leader_record)); error = SANLK_OK; } else { - /* not a problem, but interesting to see, so use log_error */ + /* not a problem, but interesting to see */
- log_errot(token, "paxos_acquire %llu owner is %llu %llu %llu", + log_level(0, token->token_id, NULL, LOG_WARNING, + "paxos_acquire %llu owner is %llu %llu %llu", (unsigned long long)next_lver, (unsigned long long)tmp_leader.owner_id, (unsigned long long)tmp_leader.owner_generation, @@ -1778,9 +1959,13 @@ int paxos_lease_acquire(struct task *task, * next_lver is 65, but the current lver on disk is 66, causing us to * we fail in the larger1 check.) */ - log_token(token, "paxos_acquire stale next_lver %llu now %llu owner %llu %llu %llu", + log_token(token, "paxos_acquire %llu restart new lver %llu from " + "%llu %llu %llu to %llu %llu %llu", (unsigned long long)next_lver, (unsigned long long)tmp_leader.lver, + (unsigned long long)cur_leader.owner_id, + (unsigned long long)cur_leader.owner_generation, + (unsigned long long)cur_leader.timestamp, (unsigned long long)tmp_leader.owner_id, (unsigned long long)tmp_leader.owner_generation, (unsigned long long)tmp_leader.timestamp); @@ -1788,21 +1973,26 @@ int paxos_lease_acquire(struct task *task, }
if (memcmp(&cur_leader, &tmp_leader, sizeof(struct leader_record))) { - /* I don't think this should ever happen. */ - log_errot(token, "paxos_acquire restart leader changed2"); + log_token(token, "paxos_acquire %llu restart leader changed2 from " + "%llu %llu %llu to %llu %llu %llu", + (unsigned long long)next_lver, + (unsigned long long)cur_leader.owner_id, + (unsigned long long)cur_leader.owner_generation, + (unsigned long long)cur_leader.timestamp, + (unsigned long long)tmp_leader.owner_id, + (unsigned long long)tmp_leader.owner_generation, + (unsigned long long)tmp_leader.timestamp); goto restart; }
- error = run_ballot(task, token, cur_leader.num_hosts, next_lver, our_mbal, - &dblock); + error = run_ballot(task, token, flags, cur_leader.num_hosts, next_lver, our_mbal, &dblock);
if ((error == SANLK_DBLOCK_MBAL) || (error == SANLK_DBLOCK_LVER)) { us = get_rand(0, 1000000); if (us < 0) us = token->host_id * 100;
- /* not a problem, but interesting to see, so use log_error */ - log_errot(token, "paxos_acquire %llu retry delay %d us", + log_token(token, "paxos_acquire %llu retry delay %d us", (unsigned long long)next_lver, us);
usleep(us); @@ -1858,14 +2048,15 @@ int paxos_lease_acquire(struct task *task, }
if (new_leader.owner_id != token->host_id) { - /* not a problem, but interesting to see, so use log_error */ + /* not a problem, but interesting to see */
/* It's possible that we commit an outdated owner id/gen here. If we go back to the top and retry, we may find that the owner host_id is alive but with a newer generation, and we'd be able to get the lease by running the ballot again. */
- log_errot(token, "ballot %llu commit other owner %llu %llu %llu", + log_level(0, token->token_id, NULL, LOG_WARNING, + "ballot %llu commit other owner %llu %llu %llu", (unsigned long long)new_leader.lver, (unsigned long long)new_leader.owner_id, (unsigned long long)new_leader.owner_generation, @@ -1999,6 +2190,14 @@ int paxos_lease_release(struct task *task, return 0; }
+ /* + * When we were the writer of our own leader record, then + * releasing the lease includes both setting the REALEASED flag + * in our dblock and clearing out timestamp in the leader. + * When we reread the leader here in release, we should find + * it the same as we last saw in acquire. + */ + if (leader.lver != last->lver) { log_errot(token, "paxos_release other lver " "last lver %llu owner %llu %llu %llu writer %llu %llu %llu " @@ -2038,7 +2237,6 @@ int paxos_lease_release(struct task *task, (unsigned long long)leader.write_id, (unsigned long long)leader.write_generation, (unsigned long long)leader.write_timestamp); - return SANLK_RELEASE_OWNER; }
@@ -2061,7 +2259,6 @@ int paxos_lease_release(struct task *task, (unsigned long long)leader.write_id, (unsigned long long)leader.write_generation, (unsigned long long)leader.write_timestamp); - return SANLK_RELEASE_OWNER; }
diff --git a/src/paxos_lease.h b/src/paxos_lease.h index cce85ed..e2c2484 100644 --- a/src/paxos_lease.h +++ b/src/paxos_lease.h @@ -13,6 +13,7 @@ #define PAXOS_ACQUIRE_QUIET_FAIL 0x00000002 #define PAXOS_ACQUIRE_SHARED 0x00000004 #define PAXOS_ACQUIRE_OWNER_NOWAIT 0x00000008 +#define PAXOS_ACQUIRE_DEBUG_ALL 0x00000010
uint32_t leader_checksum(struct leader_record *lr);
diff --git a/src/resource.c b/src/resource.c index 81b6d99..af8f91c 100644 --- a/src/resource.c +++ b/src/resource.c @@ -654,6 +654,9 @@ static int acquire_disk(struct task *task, struct token *token, if (com.quiet_fail) flags |= PAXOS_ACQUIRE_QUIET_FAIL;
+ if (com.paxos_debug_all) + flags |= PAXOS_ACQUIRE_DEBUG_ALL; + if (token->acquire_flags & SANLK_RES_SHARED) flags |= PAXOS_ACQUIRE_SHARED;
diff --git a/src/sanlock.conf b/src/sanlock.conf index af753d1..4debc6b 100644 --- a/src/sanlock.conf +++ b/src/sanlock.conf @@ -43,4 +43,7 @@ # # renewal_read_extend_sec = <seconds> # command line: n/a +# +# paxos_debug_all = 0 +# command line: n/a
diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h index 5d799b9..4cee6c1 100644 --- a/src/sanlock_internal.h +++ b/src/sanlock_internal.h @@ -304,6 +304,7 @@ struct command_line { int debug; int debug_renew; int quiet_fail; + int paxos_debug_all; int wait; int use_watchdog; int high_priority; /* -h */
This is an automated email from the git hooks/post-receive script.
teigland pushed a commit to branch master in repository sanlock.
commit c695e1b2fa09274b10678031dfecbf34f3fa209d Author: David Teigland teigland@redhat.com Date: Wed Nov 29 14:38:54 2017 -0600
sanlock: add a NOWAIT flag for convert
Converting sh to ex acquires the paxos lease, like a standard acquire. The caller may want the paxos acquire to avoid blocking for convert like acquire.
Don't log an error message for a lock conflict in conversion. --- src/cmd.c | 2 +- src/resource.c | 22 ++++++++++++++++------ src/resource.h | 2 +- src/sanlock_resource.h | 9 +++++++++ 4 files changed, 27 insertions(+), 8 deletions(-)
diff --git a/src/cmd.c b/src/cmd.c index 453a1b6..c090819 100644 --- a/src/cmd.c +++ b/src/cmd.c @@ -922,7 +922,7 @@ static void cmd_convert(struct task *task, struct cmd_args *ca) goto cmd_done; }
- rv = convert_token(task, &res, token); + rv = convert_token(task, &res, token, ca->header.cmd_flags); if (rv < 0) result = rv;
diff --git a/src/resource.c b/src/resource.c index af8f91c..05bcc61 100644 --- a/src/resource.c +++ b/src/resource.c @@ -1175,10 +1175,12 @@ static struct resource *new_resource(struct token *token) return r; }
-static int convert_sh2ex_token(struct task *task, struct resource *r, struct token *token) +static int convert_sh2ex_token(struct task *task, struct resource *r, struct token *token, + uint32_t cmd_flags) { struct leader_record leader; struct paxos_dblock dblock; + uint32_t flags = 0; int live_count = 0; int retries; int error; @@ -1186,6 +1188,13 @@ static int convert_sh2ex_token(struct task *task, struct resource *r, struct tok
memset(&leader, 0, sizeof(leader));
+ if (cmd_flags & SANLK_CONVERT_OWNER_NOWAIT) + flags |= PAXOS_ACQUIRE_OWNER_NOWAIT; + if (com.quiet_fail) + flags |= PAXOS_ACQUIRE_QUIET_FAIL; + if (com.paxos_debug_all) + flags |= PAXOS_ACQUIRE_DEBUG_ALL; + /* paxos_lease_acquire modifies these token values, and we check them after */ token->shared_count = 0; memset(token->shared_bitmap, 0, HOSTID_BITMAP_SIZE); @@ -1199,12 +1208,12 @@ static int convert_sh2ex_token(struct task *task, struct resource *r, struct tok
token->flags |= T_WRITE_DBLOCK_MBLOCK_SH;
- rv = paxos_lease_acquire(task, token, 0, &leader, &dblock, 0, 0); + rv = paxos_lease_acquire(task, token, flags, &leader, &dblock, 0, 0);
token->flags &= ~T_WRITE_DBLOCK_MBLOCK_SH;
if (rv < 0) { - log_errot(token, "convert_sh2ex acquire error %d t_flags %x", rv, token->flags); + log_token(token, "convert_sh2ex acquire error %d t_flags %x", rv, token->flags);
/* If the acquire failed before anything important was written, then this RETRACT flag will not be set, and there is nothing @@ -1381,7 +1390,8 @@ static int convert_ex2sh_token(struct task *task, struct resource *r, struct tok return SANLK_OK; }
-int convert_token(struct task *task, struct sanlk_resource *res, struct token *cl_token) +int convert_token(struct task *task, struct sanlk_resource *res, struct token *cl_token, + uint32_t cmd_flags) { struct resource *r; struct token *tk; @@ -1451,7 +1461,7 @@ int convert_token(struct task *task, struct sanlk_resource *res, struct token *c }
if (!(res->flags & SANLK_RES_SHARED)) { - rv = convert_sh2ex_token(task, r, token); + rv = convert_sh2ex_token(task, r, token, cmd_flags); } else if (res->flags & SANLK_RES_SHARED) { rv = convert_ex2sh_token(task, r, token); } else { @@ -1686,7 +1696,7 @@ int acquire_token(struct task *task, struct token *token, uint32_t cmd_flags, }
if (rv < 0 && !(token->flags & T_RETRACT_PAXOS)) { - log_errot(token, "acquire_token disk error %d", rv); + log_token(token, "acquire_token disk error %d", rv); r->flags &= ~R_SHARED; /* zero r->leader means not owned and release will just close */ release_token_opened(task, token); diff --git a/src/resource.h b/src/resource.h index 9821cfc..70cfd04 100644 --- a/src/resource.h +++ b/src/resource.h @@ -27,7 +27,7 @@ int resource_orphan_count(char *space_name); void check_mode_block(struct token *token, uint64_t next_lver, int q, char *dblock);
/* locks resource_mutex */ -int convert_token(struct task *task, struct sanlk_resource *res, struct token *cl_token); +int convert_token(struct task *task, struct sanlk_resource *res, struct token *cl_token, uint32_t cmd_flags);
/* locks resource_mutex */ int acquire_token(struct task *task, struct token *token, uint32_t cmd_flags, diff --git a/src/sanlock_resource.h b/src/sanlock_resource.h index d412482..80178d1 100644 --- a/src/sanlock_resource.h +++ b/src/sanlock_resource.h @@ -86,6 +86,15 @@ #define SANLK_REL_ORPHAN 0x00000004
/* + * convert flags + * + * SANLK_CONVERT_OWNER_NOWAIT + * Same as SANLK_ACQUIRE_OWNER_NOWAIT. + */ + +#define SANLK_CONVERT_OWNER_NOWAIT 0x00000008 /* NB: value must match SANLK_ACQUIRE_OWNER_NOWAIT */ + +/* * request flags * * SANLK_REQUEST_NEXT_LVER
This is an automated email from the git hooks/post-receive script.
teigland pushed a commit to branch master in repository sanlock.
commit 672dbb1791f82d1d6ee14827839ea7468ac118dc Author: David Teigland teigland@redhat.com Date: Tue Dec 5 11:17:01 2017 -0600
release 3.6.0 --- VERSION | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/VERSION b/VERSION index 1545d96..40c341b 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -3.5.0 +3.6.0
sanlock-devel@lists.fedorahosted.org