Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

handling of auctions ending in the future is broken #7775

Closed
turadg opened this issue May 17, 2023 · 0 comments · Fixed by #7778
Closed

handling of auctions ending in the future is broken #7775

turadg opened this issue May 17, 2023 · 0 comments · Fixed by #7778
Assignees
Labels
bug Something isn't working vaults_triage DO NOT USE

Comments

@turadg
Copy link
Member

turadg commented May 17, 2023

Describe the bug

Case 2 of the auction timing recovery fails.

To Reproduce

Use branch #7773

TARGET=agoric-upgrade-10 make build_test run

Wait for block 880.

2023-05-17T19:10:04.953Z block-manager: block 880 begin
2023-05-17T19:10:05.184Z SwingSet: vat: v39: ----- SCHED.8  2 startSchedulingFromScratch
2023-05-17T19:10:05.185Z SwingSet: vat: v39: ----- SCHED.8  3 nextRound { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_684_350_000n }
2023-05-17T19:10:05.186Z SwingSet: vat: v39: ----- SCHED.8  4 priceLock { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_684_348_202n }
2023-05-17T19:10:05.189Z SwingSet: vat: v39: ----- SCHED.8  5 received param update
2023-05-17T19:10:05.273Z SwingSet: vat: v39: ----- SCHED.8  6 received param update
2023-05-17T19:10:05.278Z SwingSet: vat: v39: ----- SCHED.8  7 START  { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_684_350_002n }
2023-05-17T19:10:05.279Z SwingSet: vat: v39: ----- SCHED.8  8 queueLiveSchedule repeating { absValue: 1_684_350_000n, timerBrand: Object [Alleged: timerBrand] {} } { timerBrand: Object [Alleged: timerBrand] {}, relValue: 2n } { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_684_350_002n }
2023-05-17T19:10:05.279Z SwingSet: vat: v39: ----- SCHED.8  9 nextRound { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_684_351_800n }
2023-05-17T19:10:05.280Z SwingSet: vat: v39: ----- SMath.7  2 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_684_350_002n } { absValue: 1_684_350_000n, timerBrand: Object [Alleged: timerBrand] {} }
2023-05-17T19:10:05.281Z SwingSet: vat: v39: ----- SCHED.8  10 priceLock { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_684_351_502n }
2023-05-17T19:10:05.288Z SwingSet: vat: v39: ----- SCHED.8  11 wake step { absValue: 1_684_350_002n, timerBrand: Object [Alleged: timerBrand] {} }
2023-05-17T19:10:05.288Z SwingSet: vat: v39: ----- SCHED.8  12 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_684_350_002n } { absValue: 1_684_350_002n, timerBrand: Object [Alleged: timerBrand] {} }
2023-05-17T19:10:05.289Z SwingSet: vat: v39: ----- Auction.9  2 startRound
2023-05-17T19:10:05.292Z SwingSet: vat: v39: (Error#1)
2023-05-17T19:10:05.292Z SwingSet: vat: v39: Error#1: Unable to start auction cleanly. skipping this auction round.
2023-05-17T19:10:05.292Z SwingSet: vat: v39: Error: Unable to start auction cleanly. skipping this auction round.
 at construct ()
 at Error (/bundled-source/.../node_modules/ses/src/error/tame-error-constructor.js:56)
 at makeError (/bundled-source/.../node_modules/ses/src/error/assert.js:243)
 at advanceRound (.../inter-protocol/src/auction/scheduler.js:184)
 at clockTick (.../inter-protocol/src/auction/scheduler.js:199)
 at clockTick (.../inter-protocol/src/auction/scheduler.js:138)
 at wake (.../inter-protocol/src/auction/scheduler.js:240)
 at apply ()
 at apply ()
 at dispatchToHandler (/bundled-source/.../node_modules/@endo/eventual-send/src/handled-promise.js:163)
 at win (/bundled-source/.../node_modules/@endo/eventual-send/src/handled-promise.js:511)
 at ()

2023-05-17T19:10:05.292Z SwingSet: vat: v39: ----- Auction.9  3 finalize
2023-05-17T19:10:05.312Z SwingSet: vat: v39: ----- AucBook.6  2 BOOK notifier 12010000/1000000
2023-05-17T19:10:05.341Z SwingSet: vat: v42: ----- LIQ.5  8 SCHEDULE { clockStep: { relValue: 20n, timerBrand: Object [Alleged: timerBrand] {} }, endRate: 6_500n, endTime: { absValue: 1_684_350_762n, timerBrand: Object [Alleged: timerBrand] {} }, lockTime: { absValue: 1_684_350_302n, timerBrand: Object [Alleged: timerBrand] {} }, startDelay: { relValue: 2n, timerBrand: Object [Alleged: timerBrand] {} }, startTime: { absValue: 1_684_350_602n, timerBrand: Object [Alleged: timerBrand] {} }, steps: 8n }
2023-05-17T19:10:05.342Z SwingSet: vat: v42: ----- LIQ.5  9 CASE 2: endTime is in the future or now so reschedule waking
2023-05-17T19:10:05.396Z SwingSet: vat: v42: ----- LIQ.5  10 SCHEDULE { clockStep: { relValue: 20n, timerBrand: Object [Alleged: timerBrand] {} }, endRate: 6_500n, endTime: { absValue: 1_684_350_762n, timerBrand: Object [Alleged: timerBrand] {} }, lockTime: { absValue: 1_684_350_302n, timerBrand: Object [Alleged: timerBrand] {} }, startDelay: { relValue: 2n, timerBrand: Object [Alleged: timerBrand] {} }, startTime: { absValue: 1_684_350_602n, timerBrand: Object [Alleged: timerBrand] {} }, steps: 8n }
2023-05-17T19:10:05.397Z SwingSet: vat: v42: ----- LIQ.5  11 CASE 2: endTime is in the future or now so reschedule waking
2023-05-17T19:10:05.439Z SwingSet: vat: v42: ----- LIQ.5  12 SCHEDULE { clockStep: { relValue: 20n, timerBrand: Object [Alleged: timerBrand] {} }, endRate: 6_500n, endTime: { absValue: 1_684_350_762n, timerBrand: Object [Alleged: timerBrand] {} }, lockTime: { absValue: 1_684_350_302n, timerBrand: Object [Alleged: timerBrand] {} }, startDelay: { relValue: 2n, timerBrand: Object [Alleged: timerBrand] {} }, startTime: { absValue: 1_684_350_602n, timerBrand: Object [Alleged: timerBrand] {} }, steps: 8n }
2023-05-17T19:10:05.439Z SwingSet: vat: v42: ----- LIQ.5  13 CASE 2: endTime is in the future or now so reschedule waking
2023-05-17T19:10:06.019Z SwingSet: vat: v42: ----- LIQ.5  14 SCHEDULE { clockStep: { relValue: 20n, timerBrand: Object [Alleged: timerBrand] {} }, endRate: 6_500n, endTime: { absValue: 1_684_350_762n, timerBrand: Object [Alleged: timerBrand] {} }, lockTime: { absValue: 1_684_350_302n, timerBrand: Object [Alleged: timerBrand] {} }, startDelay: { relValue: 2n, timerBrand: Object [Alleged: timerBrand] {} }, startTime: { absValue: 1_684_350_602n, timerBrand: Object [Alleged: timerBrand] {} }, steps: 8n }
2023-05-17T19:10:06.020Z SwingSet: vat: v42: ----- LIQ.5  15 CASE 2: endTime is in the future or now so reschedule waking
2023-05-17T19:10:06.058Z SwingSet: vat: v42: ----- LIQ.5  16 SCHEDULE { clockStep: { relValue: 20n, timerBrand: Object [Alleged: timerBrand] {} }, endRate: 6_500n, endTime: { absValue: 1_684_350_762n, timerBrand: Object [Alleged: timerBrand] {} }, lockTime: { absValue: 1_684_350_302n, timerBrand: Object [Alleged: timerBrand] {} }, startDelay: { relValue: 2n, timerBrand: Object [Alleged: timerBrand] {} }, startTime: { absValue: 1_684_350_602n, timerBrand: Object [Alleged: timerBrand] {} }, steps: 8n }
2023-05-17T19:10:06.058Z SwingSet: vat: v42: ----- LIQ.5  17 CASE 2: endTime is in the future or now so reschedule waking
2023-05-17T19:10:06.097Z SwingSet: vat: v42: ----- LIQ.5  18 SCHEDULE { clockStep: { relValue: 20n, timerBrand: Object [Alleged: timerBrand] {} }, endRate: 6_500n, endTime: { absValue: 1_684_350_762n, timerBrand: Object [Alleged: timerBrand] {} }, lockTime: { absValue: 1_684_350_302n, timerBrand: Object [Alleged: timerBrand] {} }, startDelay: { relValue: 2n, timerBrand: Object [Alleged: timerBrand] {} }, startTime: { absValue: 1_684_350_602n, timerBrand: Object [Alleged: timerBrand] {} }, steps: 8n }

…ad infinitum.

Expected behavior

Case 2 recovers without looping so rapidly.

Fix should have a test that covers case 2.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working vaults_triage DO NOT USE
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants