This is an automated email from the git hooks/post-receive script.
teigland pushed a change to branch testing2 in repository sanlock.
at f30507b sanlock: improve paxos logging for debugging
This branch includes the following new commits:
new 4523a63 sanlock: fix detection of shared lease new 11aa9d7 sanlock: fix release interference with paxos new 516e5ea sanlock: use careful release on error paths new f30507b sanlock: improve paxos logging for debugging
The 4 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.
This is an automated email from the git hooks/post-receive script.
teigland pushed a commit to branch testing2 in repository sanlock.
commit 4523a63bb21983d64d4f526955850b40d4ec131b Author: David Teigland teigland@redhat.com Date: Tue Nov 21 11:02:17 2017 -0600
sanlock: fix detection of shared lease
When a host is acquiring a lease and detects that another host holds it shared, it will check if the host with the shared lease is dead. Before the dead-host check, the shared lease holder may have released its shared lease by clearing its mode_block. The host checking the shared lease needs to check if the shared lease has been released. --- src/resource.c | 53 ++++++++++++++++++++++++++++++++++++++--------------- 1 file changed, 38 insertions(+), 15 deletions(-)
diff --git a/src/resource.c b/src/resource.c index 317fcb7..6309b9c 100644 --- a/src/resource.c +++ b/src/resource.c @@ -291,8 +291,9 @@ void check_mode_block(struct token *token, uint64_t next_lver, int q, char *dblo if (mb.flags & MBLOCK_SHARED) { set_id_bit(q + 1, token->shared_bitmap, NULL); token->shared_count++; - log_token(token, "ballot %llu mode[%d] shared %d", - (unsigned long long)next_lver, q, token->shared_count); + log_token(token, "ballot %llu mode[%d] shared %d gen %llu", + (unsigned long long)next_lver, q, token->shared_count, + (unsigned long long)mb.generation); } }
@@ -370,14 +371,13 @@ static int write_host_block(struct task *task, struct token *token, }
static int read_mode_block(struct task *task, struct token *token, - uint64_t host_id, uint64_t *max_gen) + uint64_t host_id, struct mode_block *mb_out) { struct sync_disk *disk; struct mode_block *mb_end; struct mode_block mb; char *iobuf, **p_iobuf; uint64_t offset; - uint64_t max = 0; int num_disks = token->r.num_disks; int iobuf_len, rv, d;
@@ -406,24 +406,23 @@ static int read_mode_block(struct task *task, struct token *token,
mode_block_in(mb_end, &mb);
- if (!(mb.flags & MBLOCK_SHARED)) - continue; + memcpy(mb_out, &mb, sizeof(struct mode_block));
- if (!max || mb.generation > max) - max = mb.generation; + /* FIXME: combine results for multi-disk case */ + break; }
if (rv != SANLK_AIO_TIMEOUT) free(iobuf);
- *max_gen = max; return rv; }
static int clear_dead_shared(struct task *task, struct token *token, int num_hosts, int *live_count) { - uint64_t host_id, max_gen = 0; + struct mode_block mb; + uint64_t host_id; int i, rv = 0, live = 0;
for (i = 0; i < num_hosts; i++) { @@ -435,16 +434,36 @@ static int clear_dead_shared(struct task *task, struct token *token, if (!test_id_bit(host_id, token->shared_bitmap)) continue;
- rv = read_mode_block(task, token, host_id, &max_gen); + memset(&mb, 0, sizeof(mb)); + + rv = read_mode_block(task, token, host_id, &mb); if (rv < 0) { log_errot(token, "clear_dead_shared read_mode_block %llu %d", (unsigned long long)host_id, rv); return rv; }
- if (host_live(token->r.lockspace_name, host_id, max_gen)) { + log_token(token, "clear_dead_shared host_id %llu mode_block: flags %x gen %llu", + (unsigned long long)host_id, mb.flags, (unsigned long long)mb.generation); + + /* + * We get to this function because we saw the shared flag during + * paxos, but the holder of the shared lease may have dropped their + * shared lease and cleared the mode_block since then. + */ + if (!(mb.flags & MBLOCK_SHARED)) + continue; + + if (!mb.generation) { + /* shouldn't happen; if the shared flag is set, the generation should also be set. */ + log_errot(token, "clear_dead_shared host_id %llu mode_block: flags %x gen %llu", + (unsigned long long)host_id, mb.flags, (unsigned long long)mb.generation); + continue; + } + + if (host_live(token->r.lockspace_name, host_id, mb.generation)) { log_token(token, "clear_dead_shared host_id %llu gen %llu alive", - (unsigned long long)host_id, (unsigned long long)max_gen); + (unsigned long long)host_id, (unsigned long long)mb.generation); live++; continue; } @@ -456,8 +475,12 @@ static int clear_dead_shared(struct task *task, struct token *token, return rv; }
- log_token(token, "clear_dead_shared host_id %llu gen %llu dead and cleared", - (unsigned long long)host_id, (unsigned long long)max_gen); + /* + * not an error, just useful to have a record of when we clear a shared + * lock that was left by a failed host. + */ + log_errot(token, "cleared shared lease for dead host_id %llu gen %llu", + (unsigned long long)host_id, (unsigned long long)mb.generation); }
*live_count = live;
This is an automated email from the git hooks/post-receive script.
teigland pushed a commit to branch testing2 in repository sanlock.
commit 11aa9d757e8f290e67033ca51b64bf0312618874 Author: David Teigland teigland@redhat.com Date: Wed Nov 22 16:04:36 2017 -0600
sanlock: fix release interference with paxos
The process of releasing a lease on disk involved first zeroing our own dblock values prior to zeroing the leader record. Clearing dblock values can interfere with an in-progress paxos ballot, and can result in a second host owning the same lease version that we released.
The incorrect zeroing of dblocks was added in commit d6bef45b9716c581d99466280a52a01c9ebe3bf7
The reason for zeroing was to fix an issue with shared leases here: e40e1f6e22f9b10f08d53fc7da94f5158d9e4ae8 That issue is now resolved by setting a new flag in the dblock to indicate we are releasing the lease. The new flag is set, along with the unchanged dblock values, before clearing the leader block. --- src/leader.h | 2 +- src/ondisk.c | 2 ++ src/paxos_dblock.h | 8 +++++ src/paxos_lease.c | 86 ++++++++++++++++++++++++++++++++++++++++++++------ src/resource.c | 64 +++++++++++++++++++++++++++++++------ src/sanlock_internal.h | 1 + 6 files changed, 143 insertions(+), 20 deletions(-)
diff --git a/src/leader.h b/src/leader.h index b95866a..d67c243 100644 --- a/src/leader.h +++ b/src/leader.h @@ -18,7 +18,7 @@ #define PAXOS_DISK_MAGIC 0x06152010 #define PAXOS_DISK_CLEAR 0x11282016 #define PAXOS_DISK_VERSION_MAJOR 0x00060000 -#define PAXOS_DISK_VERSION_MINOR 0x00000002 +#define PAXOS_DISK_VERSION_MINOR 0x00000003
#define DELTA_DISK_MAGIC 0x12212010 #define DELTA_DISK_VERSION_MAJOR 0x00030000 diff --git a/src/ondisk.c b/src/ondisk.c index 83b6832..21f9b64 100644 --- a/src/ondisk.c +++ b/src/ondisk.c @@ -92,6 +92,7 @@ void paxos_dblock_in(struct paxos_dblock *end, struct paxos_dblock *pd) pd->inp3 = le64_to_cpu(end->inp3); pd->lver = le64_to_cpu(end->lver); pd->checksum = le32_to_cpu(end->checksum); + pd->flags = le32_to_cpu(end->flags); }
void paxos_dblock_out(struct paxos_dblock *pd, struct paxos_dblock *end) @@ -104,6 +105,7 @@ void paxos_dblock_out(struct paxos_dblock *pd, struct paxos_dblock *end) end->lver = cpu_to_le64(pd->lver); /* N.B. the checksum must be computed after the byte swapping */ /* paxos_dblock_out(pd, end); checksum = compute(end), end->checksum = cpu_to_le32(checksum); */ + end->flags = cpu_to_le32(pd->flags); }
void mode_block_in(struct mode_block *end, struct mode_block *mb) diff --git a/src/paxos_dblock.h b/src/paxos_dblock.h index a07abc4..7d08c95 100644 --- a/src/paxos_dblock.h +++ b/src/paxos_dblock.h @@ -12,6 +12,8 @@
#define DBLOCK_CHECKSUM_LEN 48 /* ends before checksum field */
+#define DBLOCK_FL_RELEASED 0x00000001 + struct paxos_dblock { uint64_t mbal; uint64_t bal; @@ -20,6 +22,12 @@ struct paxos_dblock { uint64_t inp3; /* host_id's timestamp */ uint64_t lver; uint32_t checksum; + uint32_t flags; /* DBLOCK_FL_ */ };
+/* + * This struct cannot grow any larger than MBLOCK_OFFSET (128) + * because the mode_block starts at that offset in the same sector. + */ + #endif diff --git a/src/paxos_lease.c b/src/paxos_lease.c index 726056f..c13c5a2 100644 --- a/src/paxos_lease.c +++ b/src/paxos_lease.c @@ -1627,9 +1627,9 @@ int paxos_lease_acquire(struct task *task, if (cur_leader.write_id != cur_leader.owner_id) { rv = read_dblock(task, token, &token->disks[0], cur_leader.owner_id, &owner_dblock); - if (!rv && !owner_dblock.lver) { + 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 free", + log_errot(token, "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, @@ -1956,28 +1956,68 @@ int paxos_lease_release(struct task *task, last = leader_last;
if (leader.lver != last->lver) { - log_errot(token, "paxos_release %llu other lver %llu", + log_errot(token, "paxos_release other lver " + "last lver %llu owner %llu %llu %llu writer %llu %llu %llu " + "disk lver %llu owner %llu %llu %llu writer %llu %llu %llu", (unsigned long long)last->lver, - (unsigned long long)leader.lver); + (unsigned long long)last->owner_id, + (unsigned long long)last->owner_generation, + (unsigned long long)last->timestamp, + (unsigned long long)last->write_id, + (unsigned long long)last->write_generation, + (unsigned long long)last->write_timestamp, + (unsigned long long)leader.lver, + (unsigned long long)leader.owner_id, + (unsigned long long)leader.owner_generation, + (unsigned long long)leader.timestamp, + (unsigned long long)leader.write_id, + (unsigned long long)leader.write_generation, + (unsigned long long)leader.write_timestamp); return SANLK_RELEASE_LVER; }
if (leader.timestamp == LEASE_FREE) { - log_errot(token, "paxos_release %llu already free %llu %llu %llu", + log_errot(token, "paxos_release already free " + "last lver %llu owner %llu %llu %llu writer %llu %llu %llu " + "disk lver %llu owner %llu %llu %llu writer %llu %llu %llu", (unsigned long long)last->lver, + (unsigned long long)last->owner_id, + (unsigned long long)last->owner_generation, + (unsigned long long)last->timestamp, + (unsigned long long)last->write_id, + (unsigned long long)last->write_generation, + (unsigned long long)last->write_timestamp, + (unsigned long long)leader.lver, (unsigned long long)leader.owner_id, (unsigned long long)leader.owner_generation, - (unsigned long long)leader.timestamp); + (unsigned long long)leader.timestamp, + (unsigned long long)leader.write_id, + (unsigned long long)leader.write_generation, + (unsigned long long)leader.write_timestamp); + return SANLK_RELEASE_OWNER; }
if (leader.owner_id != token->host_id || leader.owner_generation != token->host_generation) { - log_errot(token, "paxos_release %llu other owner %llu %llu %llu", + log_errot(token, "paxos_release other owner " + "last lver %llu owner %llu %llu %llu writer %llu %llu %llu " + "disk lver %llu owner %llu %llu %llu writer %llu %llu %llu", (unsigned long long)last->lver, + (unsigned long long)last->owner_id, + (unsigned long long)last->owner_generation, + (unsigned long long)last->timestamp, + (unsigned long long)last->write_id, + (unsigned long long)last->write_generation, + (unsigned long long)last->write_timestamp, + (unsigned long long)leader.lver, (unsigned long long)leader.owner_id, (unsigned long long)leader.owner_generation, - (unsigned long long)leader.timestamp); + (unsigned long long)leader.timestamp, + (unsigned long long)leader.write_id, + (unsigned long long)leader.write_generation, + (unsigned long long)leader.write_timestamp); + return SANLK_RELEASE_OWNER; }
@@ -1993,19 +2033,45 @@ int paxos_lease_release(struct task *task, * perfectly fine (use log_error since it's interesting * to see when this happens.) */ - log_errot(token, "paxos_release %llu leader different " - "write %llu %llu %llu vs %llu %llu %llu", + log_errot(token, "paxos_release different vals " + "last lver %llu owner %llu %llu %llu writer %llu %llu %llu " + "disk lver %llu owner %llu %llu %llu writer %llu %llu %llu", (unsigned long long)last->lver, + (unsigned long long)last->owner_id, + (unsigned long long)last->owner_generation, + (unsigned long long)last->timestamp, (unsigned long long)last->write_id, (unsigned long long)last->write_generation, (unsigned long long)last->write_timestamp, + (unsigned long long)leader.lver, + (unsigned long long)leader.owner_id, + (unsigned long long)leader.owner_generation, + (unsigned long long)leader.timestamp, (unsigned long long)leader.write_id, (unsigned long long)leader.write_generation, (unsigned long long)leader.write_timestamp); + /* log_leader_error(0, token, &token->disks[0], last, "paxos_release"); log_leader_error(0, token, &token->disks[0], &leader, "paxos_release"); */ + + /* + * If another host was the writer and committed us as the + * owner, then we don't zero the leader record when we release, + * we just release our dblock (by setting the release flag, + * already done prior to calling paxos_lease_release). This is + * because other hosts will ignore our leader record if we were + * not the writer once we release our dblock. Those other + * hosts will then run a ballot and commit/write a new leader. + * If we are also zeroing the leader, that can race with + * another host writing a new leader, and we could clobber the + * new leader. + */ + if (leader.write_id != token->host_id) { + log_token(token, "paxos_release %llu skip leader write", (unsigned long long)last->lver); + return 0; + } }
if (resrename) diff --git a/src/resource.c b/src/resource.c index 6309b9c..3339422 100644 --- a/src/resource.c +++ b/src/resource.c @@ -361,8 +361,21 @@ static int write_host_block(struct task *task, struct token *token, log_errot(token, "write_host_block host_id %llu flags %x gen %llu rv %d", (unsigned long long)host_id, mb_flags, (unsigned long long)mb_gen, rv); } else { - log_token(token, "write_host_block host_id %llu flags %x gen %llu", - (unsigned long long)host_id, mb_flags, (unsigned long long)mb_gen); + if (pd) + log_token(token, "write_host_block host_id %llu flags %x gen %llu dblock %llu:%llu:%llu:%llu:%llu:%llu%s", + (unsigned long long)host_id, + mb_flags, + (unsigned long long)mb_gen, + (unsigned long long)pd->mbal, + (unsigned long long)pd->bal, + (unsigned long long)pd->inp, + (unsigned long long)pd->inp2, + (unsigned long long)pd->inp3, + (unsigned long long)pd->lver, + (pd->flags & DBLOCK_FL_RELEASED) ? ":RELEASED." : "."); + else + log_token(token, "write_host_block host_id %llu flags %x gen %llu dblock 0", + (unsigned long long)host_id, mb_flags, (unsigned long long)mb_gen); }
if (rv != SANLK_AIO_TIMEOUT) @@ -370,6 +383,29 @@ static int write_host_block(struct task *task, struct token *token, return rv; }
+static int write_host_block_zero_dblock_release(struct task *task, struct token *token) +{ + struct paxos_dblock dblock; + + memcpy(&dblock, &token->resource->acquire_dblock, sizeof(dblock)); + + dblock.flags = DBLOCK_FL_RELEASED; + + return write_host_block(task, token, token->host_id, 0, 0, &dblock); +} + +static int write_host_block_shared_dblock_release(struct task *task, struct token *token) +{ + struct paxos_dblock dblock; + + memcpy(&dblock, &token->resource->acquire_dblock, sizeof(dblock)); + + dblock.flags = DBLOCK_FL_RELEASED; + + return write_host_block(task, token, token->host_id, token->host_generation, + MBLOCK_SHARED, &dblock); +} + static int read_mode_block(struct task *task, struct token *token, uint64_t host_id, struct mode_block *mb_out) { @@ -838,6 +874,8 @@ static int _release_token(struct task *task, struct token *token, */
if (r_flags & R_ERASE_ALL) { + /* FIXME: figure out what to clear to avoid disrupting ongoing paxos */ + rv = write_host_block(task, token, token->host_id, 0, 0, NULL); if (rv < 0) { log_errot(token, "release_token erase all write_host_block %d", rv); @@ -868,6 +906,8 @@ static int _release_token(struct task *task, struct token *token, (unsigned long long)lver, rv);
} else if (r_flags & R_UNDO_SHARED) { + /* FIXME: figure out what to clear to avoid disrupting ongoing paxos */ + rv = write_host_block(task, token, token->host_id, 0, 0, NULL); if (rv < 0) { log_errot(token, "release_token undo shared write_host_block %d", rv); @@ -889,7 +929,7 @@ static int _release_token(struct task *task, struct token *token, } else if (r_flags & R_SHARED) { /* normal release of sh lease */
- rv = write_host_block(task, token, token->host_id, 0, 0, NULL); + rv = write_host_block_zero_dblock_release(task, token); if (rv < 0) { log_errot(token, "release_token shared write_host_block %d", rv); ret = rv; @@ -919,7 +959,7 @@ static int _release_token(struct task *task, struct token *token, }
/* Failure here is not a big deal and can be ignored. */ - rv = write_host_block(task, token, token->host_id, 0, 0, NULL); + rv = write_host_block_zero_dblock_release(task, token); if (rv < 0) log_errot(token, "release_token write_host_block %d", rv);
@@ -1300,8 +1340,7 @@ static int convert_ex2sh_token(struct task *task, struct resource *r, struct tok if (r->flags & R_LVB_WRITE_RELEASE) write_lvb_block(task, r, token);
- /* FIXME: preserve dblock */ - rv = write_host_block(task, token, token->host_id, token->host_generation, MBLOCK_SHARED, NULL); + rv = write_host_block_shared_dblock_release(task, token); if (rv < 0) { log_errot(token, "convert_ex2sh write_host_block error %d", rv); return rv; @@ -1668,13 +1707,15 @@ int acquire_token(struct task *task, struct token *token, uint32_t cmd_flags, if (!(token->acquire_flags & SANLK_RES_SHARED)) token->r.lver = leader.lver;
+ memcpy(&token->resource->acquire_dblock, &dblock, sizeof(dblock)); + /* * acquiring shared lease, so we set SHARED in our mode_block * and release the leader owner. */
if (token->acquire_flags & SANLK_RES_SHARED) { - rv = write_host_block(task, token, token->host_id, token->host_generation, MBLOCK_SHARED, &dblock); + rv = write_host_block_shared_dblock_release(task, token); if (rv < 0) { log_errot(token, "acquire_token sh write_host_block error %d", rv); r->flags &= ~R_SHARED; @@ -2033,6 +2074,8 @@ static void resource_thread_release(struct task *task, struct resource *r, struc log_token(token, "release async r_flags %x", r_flags);
if (r_flags & R_ERASE_ALL) { + /* FIXME: figure out what to clear to avoid disrupting ongoing paxos */ + rv = write_host_block(task, token, token->host_id, 0, 0, NULL); if (rv < 0) log_errot(token, "release async erase all write_host_block %d", rv); @@ -2058,6 +2101,8 @@ static void resource_thread_release(struct task *task, struct resource *r, struc (unsigned long long)r->leader.lver, rv);
} else if (r_flags & R_UNDO_SHARED) { + /* FIXME: figure out what to clear to avoid disrupting ongoing paxos */ + rv = write_host_block(task, token, token->host_id, 0, 0, NULL); if (rv < 0) log_errot(token, "release async undo shared write_host_block %d", rv); @@ -2075,7 +2120,7 @@ static void resource_thread_release(struct task *task, struct resource *r, struc } else if (r_flags & R_SHARED) { /* normal release of sh lease */
- rv = write_host_block(task, token, token->host_id, 0, 0, NULL); + rv = write_host_block_zero_dblock_release(task, token); if (rv < 0) log_errot(token, "release async shared write_host_block %d", rv);
@@ -2094,7 +2139,7 @@ static void resource_thread_release(struct task *task, struct resource *r, struc }
/* Failure here is not a big deal and can be ignored. */ - rv = write_host_block(task, token, token->host_id, 0, 0, NULL); + rv = write_host_block_zero_dblock_release(task, token); if (rv < 0) log_errot(token, "release async write_host_block %d", rv);
@@ -2256,6 +2301,7 @@ static void *resource_thread(void *arg GNUC_UNUSED) tt->host_generation = r->host_generation; tt->token_id = r->release_token_id; tt->io_timeout = r->io_timeout; + tt->resource = r;
/* * Set the time after which we should try to release this diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h index 472380f..279b56d 100644 --- a/src/sanlock_internal.h +++ b/src/sanlock_internal.h @@ -130,6 +130,7 @@ struct resource { char killpath[SANLK_HELPER_PATH_LEN]; /* copied from client */ char killargs[SANLK_HELPER_ARGS_LEN]; /* copied from client */ struct leader_record leader; /* copy of last leader_record we wrote */ + struct paxos_dblock acquire_dblock; /* dblock we wrote in acquire */ struct sanlk_resource r; };
This is an automated email from the git hooks/post-receive script.
teigland pushed a commit to branch testing2 in repository sanlock.
commit 516e5ea54a385dfac4b673c238fc4a02d37a1fc4 Author: David Teigland teigland@redhat.com Date: Mon Nov 27 15:13:01 2017 -0600
sanlock: use careful release on error paths
Extend the previous commit to instances of release called on error paths. --- src/resource.c | 45 +++++++++++++++++++++------------------------ src/sanlock_internal.h | 2 +- 2 files changed, 22 insertions(+), 25 deletions(-)
diff --git a/src/resource.c b/src/resource.c index 3339422..81b6d99 100644 --- a/src/resource.c +++ b/src/resource.c @@ -383,22 +383,22 @@ static int write_host_block(struct task *task, struct token *token, return rv; }
-static int write_host_block_zero_dblock_release(struct task *task, struct token *token) +static int write_mblock_zero_dblock_release(struct task *task, struct token *token) { struct paxos_dblock dblock;
- memcpy(&dblock, &token->resource->acquire_dblock, sizeof(dblock)); + memcpy(&dblock, &token->resource->dblock, sizeof(dblock));
dblock.flags = DBLOCK_FL_RELEASED;
return write_host_block(task, token, token->host_id, 0, 0, &dblock); }
-static int write_host_block_shared_dblock_release(struct task *task, struct token *token) +static int write_mblock_shared_dblock_release(struct task *task, struct token *token) { struct paxos_dblock dblock;
- memcpy(&dblock, &token->resource->acquire_dblock, sizeof(dblock)); + memcpy(&dblock, &token->resource->dblock, sizeof(dblock));
dblock.flags = DBLOCK_FL_RELEASED;
@@ -773,6 +773,11 @@ static int release_disk(struct task *task, struct token *token, * leader says we own the lease, but our dblock is cleared, then our * leader write in release was clobbered, and other hosts will run a * ballot to set a new owner. + * UPDATE to above: we no longer clear our dblock values because that + * can interfere with other hosts running a paxos ballot at the same time, + * instead we now set the DBLOCK_FL_RELEASED flag in our dblock, leaving our + * other dblock values intact, and other hosts look for this flag to indicate + * that we have released. * * [**] For ERASE_ALL we don't want another host running the ballot to select * our dblock values and commit them, making us the owner after we've aborted @@ -874,9 +879,7 @@ static int _release_token(struct task *task, struct token *token, */
if (r_flags & R_ERASE_ALL) { - /* FIXME: figure out what to clear to avoid disrupting ongoing paxos */ - - rv = write_host_block(task, token, token->host_id, 0, 0, NULL); + rv = write_mblock_zero_dblock_release(task, token); if (rv < 0) { log_errot(token, "release_token erase all write_host_block %d", rv); ret = rv; @@ -906,9 +909,7 @@ static int _release_token(struct task *task, struct token *token, (unsigned long long)lver, rv);
} else if (r_flags & R_UNDO_SHARED) { - /* FIXME: figure out what to clear to avoid disrupting ongoing paxos */ - - rv = write_host_block(task, token, token->host_id, 0, 0, NULL); + rv = write_mblock_zero_dblock_release(task, token); if (rv < 0) { log_errot(token, "release_token undo shared write_host_block %d", rv); ret = rv; @@ -929,7 +930,7 @@ static int _release_token(struct task *task, struct token *token, } else if (r_flags & R_SHARED) { /* normal release of sh lease */
- rv = write_host_block_zero_dblock_release(task, token); + rv = write_mblock_zero_dblock_release(task, token); if (rv < 0) { log_errot(token, "release_token shared write_host_block %d", rv); ret = rv; @@ -959,7 +960,7 @@ static int _release_token(struct task *task, struct token *token, }
/* Failure here is not a big deal and can be ignored. */ - rv = write_host_block_zero_dblock_release(task, token); + rv = write_mblock_zero_dblock_release(task, token); if (rv < 0) log_errot(token, "release_token write_host_block %d", rv);
@@ -1219,6 +1220,7 @@ static int convert_sh2ex_token(struct task *task, struct resource *r, struct tok }
memcpy(&r->leader, &leader, sizeof(struct leader_record)); + memcpy(&r->dblock, &dblock, sizeof(dblock)); token->r.lver = leader.lver;
/* paxos_lease_acquire set token->shared_count to the number of @@ -1340,7 +1342,7 @@ static int convert_ex2sh_token(struct task *task, struct resource *r, struct tok if (r->flags & R_LVB_WRITE_RELEASE) write_lvb_block(task, r, token);
- rv = write_host_block_shared_dblock_release(task, token); + rv = write_mblock_shared_dblock_release(task, token); if (rv < 0) { log_errot(token, "convert_ex2sh write_host_block error %d", rv); return rv; @@ -1702,20 +1704,19 @@ int acquire_token(struct task *task, struct token *token, uint32_t cmd_flags, }
memcpy(&r->leader, &leader, sizeof(struct leader_record)); + memcpy(&r->dblock, &dblock, sizeof(dblock));
/* copy lver into token because inquire looks there for it */ if (!(token->acquire_flags & SANLK_RES_SHARED)) token->r.lver = leader.lver;
- memcpy(&token->resource->acquire_dblock, &dblock, sizeof(dblock)); - /* * acquiring shared lease, so we set SHARED in our mode_block * and release the leader owner. */
if (token->acquire_flags & SANLK_RES_SHARED) { - rv = write_host_block_shared_dblock_release(task, token); + rv = write_mblock_shared_dblock_release(task, token); if (rv < 0) { log_errot(token, "acquire_token sh write_host_block error %d", rv); r->flags &= ~R_SHARED; @@ -2074,9 +2075,7 @@ static void resource_thread_release(struct task *task, struct resource *r, struc log_token(token, "release async r_flags %x", r_flags);
if (r_flags & R_ERASE_ALL) { - /* FIXME: figure out what to clear to avoid disrupting ongoing paxos */ - - rv = write_host_block(task, token, token->host_id, 0, 0, NULL); + rv = write_mblock_zero_dblock_release(task, token); if (rv < 0) log_errot(token, "release async erase all write_host_block %d", rv);
@@ -2101,9 +2100,7 @@ static void resource_thread_release(struct task *task, struct resource *r, struc (unsigned long long)r->leader.lver, rv);
} else if (r_flags & R_UNDO_SHARED) { - /* FIXME: figure out what to clear to avoid disrupting ongoing paxos */ - - rv = write_host_block(task, token, token->host_id, 0, 0, NULL); + rv = write_mblock_zero_dblock_release(task, token); if (rv < 0) log_errot(token, "release async undo shared write_host_block %d", rv);
@@ -2120,7 +2117,7 @@ static void resource_thread_release(struct task *task, struct resource *r, struc } else if (r_flags & R_SHARED) { /* normal release of sh lease */
- rv = write_host_block_zero_dblock_release(task, token); + rv = write_mblock_zero_dblock_release(task, token); if (rv < 0) log_errot(token, "release async shared write_host_block %d", rv);
@@ -2139,7 +2136,7 @@ static void resource_thread_release(struct task *task, struct resource *r, struc }
/* Failure here is not a big deal and can be ignored. */ - rv = write_host_block_zero_dblock_release(task, token); + rv = write_mblock_zero_dblock_release(task, token); if (rv < 0) log_errot(token, "release async write_host_block %d", rv);
diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h index 279b56d..5d799b9 100644 --- a/src/sanlock_internal.h +++ b/src/sanlock_internal.h @@ -130,7 +130,7 @@ struct resource { char killpath[SANLK_HELPER_PATH_LEN]; /* copied from client */ char killargs[SANLK_HELPER_ARGS_LEN]; /* copied from client */ struct leader_record leader; /* copy of last leader_record we wrote */ - struct paxos_dblock acquire_dblock; /* dblock we wrote in acquire */ + struct paxos_dblock dblock; /* copy of last paxos_dblock we wrote */ struct sanlk_resource r; };
This is an automated email from the git hooks/post-receive script.
teigland pushed a commit to branch testing2 in repository sanlock.
commit f30507b9e800a9d8f8a00cbc7e609528a9bc14e7 Author: David Teigland teigland@redhat.com Date: Mon Nov 20 15:00:54 2017 -0600
sanlock: improve paxos logging for debugging
log interesting paxos events to sanlock.log, not /var/log/messages
log more dblock info in abort messages
ballot abort for larger lver does happen, so treat it just like larger mbal and retry
in release, check for different write_id first, rather than checking for different lver or owner first, because the different lver or owner is possible with a different write_id. This avoids logging misleading message and avoids an error from release. --- src/paxos_lease.c | 337 ++++++++++++++++++++++++++++++++++++++++-------------- 1 file changed, 248 insertions(+), 89 deletions(-)
diff --git a/src/paxos_lease.c b/src/paxos_lease.c index c13c5a2..dc2df4f 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 6 +#define BK_STR_SIZE 64 + static uint32_t roundup_power_of_two(uint32_t val) { val--; @@ -431,6 +447,9 @@ static int run_ballot(struct task *task, struct token *token, 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,21 @@ 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 && (bk_debug_count < BK_DEBUG_COUNT)) { + 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 +577,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 +604,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 +647,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 +688,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 +707,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 +718,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 +732,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 +744,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 +760,21 @@ 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 && (bk_debug_count < BK_DEBUG_COUNT)) { + 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 +791,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 +818,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); @@ -1120,8 +1236,12 @@ static int _lease_read_one(struct task *task, 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 +1282,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 +1292,21 @@ static int _lease_read_one(struct task *task,
paxos_dblock_in(bk_end, &bk);
+ if (log_bk_vals && bk.mbal && (bk_debug_count < BK_DEBUG_COUNT)) { + 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 +1319,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); @@ -1227,7 +1373,7 @@ static int _lease_read_num(struct task *task,
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); + &dblock_one, &mbal_one, &q_one, caller, 0); if (rv < 0) continue;
@@ -1297,7 +1443,7 @@ static int _lease_read_num(struct task *task,
static int paxos_lease_read(struct task *task, struct token *token, 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; @@ -1307,7 +1453,7 @@ static int paxos_lease_read(struct task *task, struct token *token, 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); + 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 " @@ -1427,7 +1573,8 @@ int paxos_lease_acquire(struct task *task,
restart:
- error = paxos_lease_read(task, token, &cur_leader, &max_mbal, "paxos_acquire"); + /* acquire io: read 1 */ + error = paxos_lease_read(task, token, &cur_leader, &max_mbal, "paxos_acquire", 1); if (error < 0) goto out;
@@ -1596,21 +1743,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 +1766,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, @@ -1730,6 +1868,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 +1882,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 +1896,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, @@ -1796,13 +1937,12 @@ int paxos_lease_acquire(struct task *task, error = run_ballot(task, token, cur_leader.num_hosts, next_lver, our_mbal, &dblock);
- if (error == SANLK_DBLOCK_MBAL) { + 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 +1998,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, @@ -1955,6 +2096,58 @@ int paxos_lease_release(struct task *task, else last = leader_last;
+ /* + * This will happen when two hosts finish the same ballot + * successfully, the second commiting the same inp values + * that the first did, as it should. But the second will + * write it's own write_id/gen/timestap, which will differ + * from what the first host wrote. So when the first host + * rereads here in the release, it will find different + * write_id/gen/timestamp from what it wrote. This is + * perfectly fine (use log warn since it's interesting + * to see when this happens.) + * + * If another host was the writer and committed us as the + * owner, then we don't zero the leader record when we release, + * we just release our dblock (by setting the release flag, + * already done prior to calling paxos_lease_release). This is + * because other hosts will ignore our leader record if we were + * not the writer once we release our dblock. Those other + * hosts will then run a ballot and commit/write a new leader. + * If we are also zeroing the leader, that can race with + * another host writing a new leader, and we could clobber the + * new leader. + */ + if (leader.write_id != token->host_id) { + log_level(0, token->token_id, NULL, LOG_WARNING, + "paxos_release skip write " + "last lver %llu owner %llu %llu %llu writer %llu %llu %llu " + "disk lver %llu owner %llu %llu %llu writer %llu %llu %llu", + (unsigned long long)last->lver, + (unsigned long long)last->owner_id, + (unsigned long long)last->owner_generation, + (unsigned long long)last->timestamp, + (unsigned long long)last->write_id, + (unsigned long long)last->write_generation, + (unsigned long long)last->write_timestamp, + (unsigned long long)leader.lver, + (unsigned long long)leader.owner_id, + (unsigned long long)leader.owner_generation, + (unsigned long long)leader.timestamp, + (unsigned long long)leader.write_id, + (unsigned long long)leader.write_generation, + (unsigned long long)leader.write_timestamp); + 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 " @@ -1994,7 +2187,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; }
@@ -2017,22 +2209,10 @@ 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; }
if (memcmp(&leader, last, sizeof(struct leader_record))) { - /* - * This will happen when two hosts finish the same ballot - * successfully, the second commiting the same inp values - * that the first did, as it should. But the second will - * write it's own write_id/gen/timestap, which will differ - * from what the first host wrote. So when the first host - * rereads here in the release, it will find different - * write_id/gen/timestamp from what it wrote. This is - * perfectly fine (use log_error since it's interesting - * to see when this happens.) - */ log_errot(token, "paxos_release different vals " "last lver %llu owner %llu %llu %llu writer %llu %llu %llu " "disk lver %llu owner %llu %llu %llu writer %llu %llu %llu", @@ -2050,28 +2230,7 @@ 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); - - /* - log_leader_error(0, token, &token->disks[0], last, "paxos_release"); - log_leader_error(0, token, &token->disks[0], &leader, "paxos_release"); - */ - - /* - * If another host was the writer and committed us as the - * owner, then we don't zero the leader record when we release, - * we just release our dblock (by setting the release flag, - * already done prior to calling paxos_lease_release). This is - * because other hosts will ignore our leader record if we were - * not the writer once we release our dblock. Those other - * hosts will then run a ballot and commit/write a new leader. - * If we are also zeroing the leader, that can race with - * another host writing a new leader, and we could clobber the - * new leader. - */ - if (leader.write_id != token->host_id) { - log_token(token, "paxos_release %llu skip leader write", (unsigned long long)last->lver); - return 0; - } + return SANLK_RELEASE_OWNER; }
if (resrename)
sanlock-devel@lists.fedorahosted.org