From 800d4a1e9b1897d8572c178769c87c8f4b0e1599 Mon Sep 17 00:00:00 2001 From: Troy Kessler <43882936+troykessler@users.noreply.github.com> Date: Fri, 29 Dec 2023 17:09:19 +0100 Subject: [PATCH] fix: archive debug bundle on invalid vote and added unit tests (#112) --- .../src/methods/helpers/archiveDebugBundle.ts | 13 ++- .../validate/validateBundleProposal.ts | 87 ++++++++++++++----- common/protocol/test/vote_abstain.test.ts | 67 ++++++++------ common/protocol/test/vote_invalid.test.ts | 67 ++++++++------ common/protocol/test/vote_valid.test.ts | 37 +++++--- 5 files changed, 181 insertions(+), 90 deletions(-) diff --git a/common/protocol/src/methods/helpers/archiveDebugBundle.ts b/common/protocol/src/methods/helpers/archiveDebugBundle.ts index 3acc39ba..26fd771d 100644 --- a/common/protocol/src/methods/helpers/archiveDebugBundle.ts +++ b/common/protocol/src/methods/helpers/archiveDebugBundle.ts @@ -25,6 +25,8 @@ export function archiveDebugBundle( metadata: object ): void { try { + this.logger.info("Archiving debug bundle"); + // if "debug" folder under target path does not exist create it if (!existsSync(path.join(this.home, `debug`))) { mkdirSync(path.join(this.home, `debug`), { recursive: true }); @@ -89,10 +91,9 @@ export function archiveDebugBundle( const zipPath = path.join( this.home, `debug`, - `${voteType}_${Math.floor(Date.now() / 1000)}_${storageId.slice( - 0, - 6 - )}.zip` + `${voteType}_${this.pool.id}_${Math.floor( + Date.now() / 1000 + )}_${storageId.slice(0, 6)}.zip` ); // save zip file @@ -101,6 +102,10 @@ export function archiveDebugBundle( .pipe(createWriteStream(zipPath)) .on("finish", () => { this.logger.info("Successfully saved debug information"); + }) + .on("error", (err) => { + this.logger.error("Failed to save debug information"); + this.logger.error(standardizeError(err)); }); } catch (err) { this.logger.error("Failed to save debug information"); diff --git a/common/protocol/src/methods/validate/validateBundleProposal.ts b/common/protocol/src/methods/validate/validateBundleProposal.ts index ec100f0e..09495d7c 100644 --- a/common/protocol/src/methods/validate/validateBundleProposal.ts +++ b/common/protocol/src/methods/validate/validateBundleProposal.ts @@ -237,14 +237,50 @@ export async function validateBundleProposal( this.logger.debug( `this.runtime.validateDataItem($THIS, $PROPOSED_DATA_ITEM, $VALIDATION_DATA_ITEM)` ); - const vote = await this.runtime.validateDataItem( - this, - proposedBundle[i], - validationBundle[i] - ); + const vote = await this.runtime + .validateDataItem(this, proposedBundle[i], validationBundle[i]) + .catch((err) => { + this.logger.error( + `Unexpected error validating data item with runtime. Voting abstain ...` + ); + this.logger.error(standardizeError(err)); + + this.archiveDebugBundle( + VoteType.VOTE_TYPE_ABSTAIN, + proposedBundle, + validationBundle, + { + reason: "unexpected error validating data item with runtime", + err: err, + proposed: proposedBundle[i], + validation: validationBundle[i], + } + ); + + return null; + }); + + // vote abstain if vote is null + if (vote === null) { + const success = await this.voteBundleProposal( + this.pool.bundle_proposal!.storage_id, + VoteType.VOTE_TYPE_ABSTAIN + ); + return success; + } // vote abstain if data item validation returned abstain if (vote === VoteType.VOTE_TYPE_ABSTAIN) { + // archive local abstain bundle for debug purposes + this.archiveDebugBundle( + VoteType.VOTE_TYPE_ABSTAIN, + proposedBundle, + validationBundle, + { + reason: "custom runtime validation returned abstain", + } + ); + const success = await this.voteBundleProposal( this.pool.bundle_proposal!.storage_id, VoteType.VOTE_TYPE_ABSTAIN @@ -275,13 +311,15 @@ export async function validateBundleProposal( `Finished validating bundle by custom runtime validation. Result = ${valid}` ); + let bundleSummary; + // only continue with bundle summary validation if proposed bundle is valid if (valid) { // vote invalid if bundle summary does not match with proposed summary this.logger.debug(`Validating bundle proposal by bundle summary`); this.logger.debug(`this.runtime.summarizeDataBundle($PROPOSED_BUNDLE)`); - const bundleSummary = await this.runtime + bundleSummary = await this.runtime .summarizeDataBundle(this, proposedBundle) .catch((err) => { this.logger.error( @@ -289,6 +327,16 @@ export async function validateBundleProposal( ); this.logger.error(standardizeError(err)); + this.archiveDebugBundle( + VoteType.VOTE_TYPE_ABSTAIN, + proposedBundle, + validationBundle, + { + reason: "unexpected error summarizing bundle with runtime", + err: err, + } + ); + return null; }); @@ -312,21 +360,20 @@ export async function validateBundleProposal( this.logger.debug( `Finished validating bundle by bundle summary. Result = ${valid}` ); + } - if (!valid) { - // archive local invalid bundle for debug purposes - this.archiveDebugBundle( - VoteType.VOTE_TYPE_INVALID, - proposedBundle, - validationBundle, - { - reason: - "custom data item validation failed or bundle summary mismatches", - proposed: this.pool.bundle_proposal!.bundle_summary, - validation: bundleSummary, - } - ); - } + if (!valid) { + // archive local invalid bundle for debug purposes + this.archiveDebugBundle( + VoteType.VOTE_TYPE_INVALID, + proposedBundle, + validationBundle, + { + reason: "custom runtime validation returned invalid", + proposed: this.pool.bundle_proposal!.bundle_summary, + validation: bundleSummary, + } + ); } // vote with either valid or invalid diff --git a/common/protocol/test/vote_abstain.test.ts b/common/protocol/test/vote_abstain.test.ts index 896e752e..53fd8ba8 100644 --- a/common/protocol/test/vote_abstain.test.ts +++ b/common/protocol/test/vote_abstain.test.ts @@ -106,6 +106,8 @@ describe("vote abstain tests", () => { v["waitForNextBundleProposal"] = jest.fn(); + v["archiveDebugBundle"] = jest.fn(); + v["continueRound"] = jest .fn() .mockReturnValueOnce(true) @@ -277,10 +279,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote abstain because local bundle could only be loaded partially", async () => { @@ -447,10 +450,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote abstain because local bundle could only be loaded partially multiple times", async () => { @@ -618,10 +622,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote abstain because bundle from storage provider could not be loaded", async () => { @@ -794,10 +799,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote abstain because bundle from storage provider could not be loaded multiple times", async () => { @@ -977,10 +983,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote abstain because local and storage provider bundle could not be loaded", async () => { @@ -1155,10 +1162,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote abstain after validator has already voted abstain", async () => { @@ -1307,10 +1315,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote abstain after validator has already voted valid", async () => { @@ -1433,10 +1442,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote abstain after validator has already voted invalid", async () => { @@ -1560,10 +1570,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote abstain where voteBundleProposal fails", async () => { @@ -1734,10 +1745,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to validate bundle but summarizeDataBundle fails", async () => { @@ -1889,10 +1901,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to validate bundle but validateDataItem fails", async () => { @@ -2032,10 +2045,11 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote abstain because decompression fails", async () => { @@ -2170,9 +2184,10 @@ describe("vote abstain tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); }); diff --git a/common/protocol/test/vote_invalid.test.ts b/common/protocol/test/vote_invalid.test.ts index a130b86c..134230e2 100644 --- a/common/protocol/test/vote_invalid.test.ts +++ b/common/protocol/test/vote_invalid.test.ts @@ -101,6 +101,8 @@ describe("invalid votes tests", () => { v["waitForNextBundleProposal"] = jest.fn(); + v["archiveDebugBundle"] = jest.fn(); + v["continueRound"] = jest .fn() .mockReturnValueOnce(true) @@ -255,10 +257,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote invalid because proposed data_size does not match", async () => { @@ -389,10 +392,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote invalid because proposed from_key does not match", async () => { @@ -525,10 +529,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote invalid because proposed to_key does not match", async () => { @@ -661,10 +666,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote invalid because proposed bundle_summary does not match", async () => { @@ -814,10 +820,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote abstain because proposed data_hash does not match", async () => { @@ -948,10 +955,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote invalid after validator has voted abstain bebore", async () => { @@ -1097,10 +1105,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote invalid after validator has voted invalid before", async () => { @@ -1229,10 +1238,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote invalid after validator has voted valid before", async () => { @@ -1359,10 +1369,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote invalid but local bundle could not be loaded in the first try", async () => { @@ -1520,10 +1531,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote invalid but bundle from storage provider could not be loaded in the first try", async () => { @@ -1693,10 +1705,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote invalid where voteBundleProposal fails", async () => { @@ -1898,10 +1911,11 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(2); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote invalid because bundle is empty", async () => { @@ -2023,9 +2037,10 @@ describe("invalid votes tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(1); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); }); diff --git a/common/protocol/test/vote_valid.test.ts b/common/protocol/test/vote_valid.test.ts index f3391911..0915cb0d 100644 --- a/common/protocol/test/vote_valid.test.ts +++ b/common/protocol/test/vote_valid.test.ts @@ -92,6 +92,8 @@ describe("vote valid tests", () => { v["waitForNextBundleProposal"] = jest.fn(); + v["archiveDebugBundle"] = jest.fn(); + v["continueRound"] = jest .fn() .mockReturnValueOnce(true) @@ -248,10 +250,11 @@ describe("vote valid tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote valid but local bundle could not be loaded in the first try", async () => { @@ -412,10 +415,11 @@ describe("vote valid tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("vote valid but bundle from storage provider could not be loaded in the first try", async () => { @@ -588,10 +592,11 @@ describe("vote valid tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote valid after validator has voted abstain bebore", async () => { @@ -738,10 +743,11 @@ describe("vote valid tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote valid after validator has voted invalid before", async () => { @@ -863,10 +869,11 @@ describe("vote valid tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote valid after validator has voted valid before", async () => { @@ -986,10 +993,11 @@ describe("vote valid tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); test("try to vote valid where voteBundleProposal fails", async () => { @@ -1193,9 +1201,10 @@ describe("vote valid tests", () => { // ASSERT NODEJS INTERFACES // ======================== + // assert that debug bundle was saved + expect(v["archiveDebugBundle"]).toHaveBeenCalledTimes(0); + // assert that only one round ran expect(v["waitForNextBundleProposal"]).toHaveBeenCalledTimes(1); - - // TODO: assert timeouts }); });