auctioneer doesn't recover when collateral is added without a price #8296

otoole-brendan · 2023-09-01T03:22:47Z

Describe the bug

While testing changing oracle prices for ATOM and stATOM with Simply Staking on Devnet in order to test liquidation - I noticed that when checking inter auction status that the auction hadn't ran since 8/23:

% inter auction status --book 2
{
  "schedule": {
    "activeStartTime": "2023-08-23T17:00:02.000Z",
    "nextStartTime": "2023-08-23T18:00:02.000Z",
    "nextDescendingStepTime": "2023-08-23T17:12:02.000Z"
  },
  "book2": {
    "startCollateral": "0 stATOM",
    "collateralAvailable": "0 stATOM"
  },
  "params": {
    "DiscountStep": "5.00%",
    "ClockStep": "00:00:30",
    "LowestRate": "65.00%"

red herring from ollinet logs

Per Dan:
logs show

2023-09-01T03:10:06.502Z SwingSet: vat: v42: ----- SCHED.8  14414 nextRound { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_693_538_400n }

which translates to...

new Date(1000*1_693_538_400)
Thu Aug 31 2023 22:20:00 GMT-0500 (Central Daylight Time)

so it could be that under the covers, all is well, but vstorage isn't getting updated somehow.

To Reproduce

Steps to reproduce the behavior:

Go CLI, point to devnet
Check auction inter status
Also - check Vaults UI on Devnet - notice no next liquidation price (Based on auction)

Expected behavior

Auction should continue to run

The text was updated successfully, but these errors were encountered:

dckc · 2023-09-01T16:02:37Z

oops... the log excerpt above was from ollinet

dckc · 2023-09-01T16:02:59Z

Diagnosis: auction schedule endTime is past

This seems somewhat by-design, as a result of #7775:

2023-08-23T18:24:19.227Z SwingSet: vat: v47: ----- LIQ.5  4970 CASE 3: endTime is past; wait for repair
2023-08-23T18:24:19.228Z SwingSet: vat: v47: 🛠️ No wake for reschedule. Repair by resetting auction params.

ps shows v47:zcf-b1-6c08a-vaultFactory

Impact: auctions for all collaterals affected by a problem with 1

context: devnet proposal 2

{"level":"info","module":"x/gov","proposal":2,"result":"passed","title":"Enable stATOM Vault","time":"2023-08-23T17:11:59Z","message":"proposal tallied"}

...

2023-08-23T17:13:24.028Z SwingSet: vat: v1: instance stATOM-USD price feed settled; remaining: []
2023-08-23T17:13:24.319Z SwingSet: vat: v17: charter: adding instance stATOM-USD price feed
2023-08-23T17:13:25.001Z SwingSet: vat: v61: ----- FlxAgg.7  2 makeOracleInvitation agoric1ldmtatp24qlllgxmrsjzcpe20fvlkp448zcuce
2023-08-23T17:13:25.025Z SwingSet: vat: v61: ----- FlxAgg.7  3 makeOracleInvitation agoric140dmkrz2e42ergjj7gyvejhzmjzurvqeq82ang
2023-08-23T17:13:25.054Z SwingSet: vat: v61: ----- FlxAgg.7  4 makeOracleInvitation agoric1w8wktaur4zf8qmmtn3n7x3r0jhsjkjntcm3u6h

...

2023-08-23T18:00:15.136Z SwingSet: vat: v44: ----- AucBook.6  34667 capturing oracle price  { denominator: { brand: Object [Alleged: ATOM brand] {}, value: 1_000_000n }, numerator: { brand: Object [Alleged: IST brand] {}, value: 9_445_342n } }
2023-08-23T18:00:15.148Z SwingSet: vat: v44: ----- AucBook.6  34668 capturing oracle price  { denominator: { brand: Object [Alleged: stATOM brand] {}, value: 1n }, numerator: { brand: Object [Alleged: IST brand] {}, value: 0n } }
2023-08-23T18:00:15.169Z SwingSet: ls: v44: Logging sent error stack (Error#2)
2023-08-23T18:00:15.169Z SwingSet: ls: v44: Error#2: can't start an auction round while one is active
2023-08-23T18:00:15.170Z SwingSet: ls: v44: Error: can't start an auction round while one is active
 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 fail (/bundled-source/.../node_modules/ses/src/error/assert.js:357)
 at startAuction (.../inter-protocol/src/auction/scheduler.js:265)
 at startAuction (.../inter-protocol/src/auction/scheduler.js:264)

dckc · 2023-09-01T16:03:46Z

treatment: update auction params (not yet effective)

It had the desired effect to some extent:

2023-09-01T16:02:26.930Z SwingSet: vat: v44: ----- SCHED.8  34732 received param update { current: { AuctionStartDelay: { type: 'relativeTime', value: { relValue: 3n, timerBrand: Object [Alleged: timerBrand] {} } }, ClockStep: { type: 'relativeTime', value: { relValue: 30n, timerBrand: Object [Alleged: timerBrand] {} } }, DiscountStep: { type: 'nat', value: 500n }, Electorate: { type: 'invitation', value: { brand: Object [Alleged: Zoe Invitation brand] {}, value: [ [Object] ] } }, LowestRate: { type: 'nat', value: 6_500n }, PriceLockPeriod: { type: 'relativeTime', value: { relValue: 300n, timerBrand: Object [Alleged: timerBrand] {} } }, StartFrequency: { type: 'relativeTime', value: { relValue: 600n, timerBrand: Object [Alleged: timerBrand] {} } }, StartingRate: { type: 'nat', value: 10_500n } } }

2023-09-01T16:02:27.990Z SwingSet: vat: v47: ----- LIQ.5  4973 setWakeupsForNextAuction at 1_693_584_141n with { clockStep: { relValue: 180n, timerBrand: Object [Alleged: timerBrand] {} }, endRate: 6_500n, endTime: { absValue: 1_692_815_042n, timerBrand: Object [Alleged: timerBrand] {} }, lockTime: { absValue: 1_692_811_802n, timerBrand: Object [Alleged: timerBrand] {} }, startDelay: { relValue: 2n, timerBrand: Object [Alleged: timerBrand] {} }, startTime: { absValue: 1_692_813_602n, timerBrand: Object [Alleged: timerBrand] {} }, steps: 8n }

but then immediately:

2023-09-01T16:02:27.993Z SwingSet: vat: v47: ----- LIQ.5  4974 CASE 3: endTime is past; wait for repair
2023-09-01T16:02:27.994Z SwingSet: vat: v47: 🛠️ No wake for reschedule. Repair by resetting auction params.

vat id info from ps:

v44:zcf-b1-a5683-auctioneer
v47:zcf-b1-6c08a-vaultFactory

Chris-Hibbert · 2023-09-01T21:58:19Z

Here's the log transcript of the auctioneer on the last auction round:

2023-08-23T15:24:11.684Z SwingSet: vat: v44: ----- Auction.9  15025 finalize
2023-08-23T15:24:11.688Z SwingSet: vat: v44: ----- AucBook.6  34634 endAuction
2023-08-23T16:00:10.415Z SwingSet: vat: v44: ----- AucBook.6  34635 capturing oracle price  { denominator: { brand: Object [Alleged: ATOM brand] {}, value: 1_000_000n }, numerator: { brand: Object [Alleged: IST brand] {}, value: 9_445_342n } }
2023-08-23T16:00:10.427Z SwingSet: vat: v44: Auction started late by {"timerBrand":"[Alleged: timerBrand]","relValue":"[4n]"}. Starting {"absValue":"[1692806404n]","timerBrand":"[Alleged: timerBrand]"}
2023-08-23T16:00:10.428Z SwingSet: vat: v44: ----- SCHED.8  34697 START  { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n }
2023-08-23T16:00:10.430Z SwingSet: vat: v44: ----- SCHED.8  34698 scheduleDescendingSteps repeating { absValue: 1_692_806_404n, timerBrand: Object [Alleged: timerBrand] {} } { timerBrand: Object [Alleged: timerBrand] {}, relValue: 0n } { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n }
2023-08-23T16:00:10.436Z SwingSet: vat: v44: ----- SCHED.8  34699 nextRound { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_000n }
2023-08-23T16:00:10.437Z SwingSet: vat: v44: ----- SMath.7  14870 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_404n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:00:10.873Z SwingSet: vat: v44: ----- SCHED.8  34700 wake step { absValue: 1_692_806_404n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:00:10.874Z SwingSet: vat: v44: ----- SCHED.8  34701 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_404n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:00:10.875Z SwingSet: vat: v44: ----- Auction.9  15026 startRound
2023-08-23T16:00:10.880Z SwingSet: vat: v44: ----- AucBook.6  34636 set startPrice { denominator: { brand: Object [Alleged: ATOM brand] {}, value: 1_000_000n }, numerator: { brand: Object [Alleged: IST brand] {}, value: 9_445_342n } } null
2023-08-23T16:00:10.886Z SwingSet: vat: v44: ----- AucBook.6  34637 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 10_500n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T16:00:10.892Z SwingSet: vat: v44: ----- AucBook.6  34638 settling 0 0
2023-08-23T16:00:10.900Z SwingSet: vat: v44: ----- SMath.7  14871 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_404n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:03:14.835Z SwingSet: vat: v44: ----- SCHED.8  34702 wake step { absValue: 1_692_806_588n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:03:14.843Z SwingSet: vat: v44: ----- SCHED.8  34703 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_588n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:03:14.844Z SwingSet: vat: v44: ----- Auction.9  15027 reducePriceAndTrade
2023-08-23T16:03:14.850Z SwingSet: vat: v44: ----- AucBook.6  34639 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 10_000n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T16:03:14.857Z SwingSet: vat: v44: ----- AucBook.6  34640 settling 0 0
2023-08-23T16:03:14.867Z SwingSet: vat: v44: ----- SMath.7  14872 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_588n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:06:18.233Z SwingSet: vat: v44: ----- SCHED.8  34704 wake step { absValue: 1_692_806_772n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:06:18.234Z SwingSet: vat: v44: ----- SCHED.8  34705 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_772n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:06:18.235Z SwingSet: vat: v44: ----- Auction.9  15028 reducePriceAndTrade
2023-08-23T16:06:18.242Z SwingSet: vat: v44: ----- AucBook.6  34641 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 9_500n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T16:06:18.250Z SwingSet: vat: v44: ----- AucBook.6  34642 settling 0 0
2023-08-23T16:06:18.259Z SwingSet: vat: v44: ----- SMath.7  14873 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_772n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:09:11.405Z SwingSet: vat: v44: ----- SCHED.8  34706 wake step { absValue: 1_692_806_945n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:09:11.407Z SwingSet: vat: v44: ----- SCHED.8  34707 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_945n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:09:11.408Z SwingSet: vat: v44: ----- Auction.9  15029 reducePriceAndTrade
2023-08-23T16:09:11.415Z SwingSet: vat: v44: ----- AucBook.6  34643 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 9_000n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T16:09:11.438Z SwingSet: vat: v44: ----- AucBook.6  34644 settling 0 0
2023-08-23T16:09:11.450Z SwingSet: vat: v44: ----- SMath.7  14874 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_806_945n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:12:15.403Z SwingSet: vat: v44: ----- SCHED.8  34708 wake step { absValue: 1_692_807_129n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:12:15.405Z SwingSet: vat: v44: ----- SCHED.8  34709 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_129n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:12:15.406Z SwingSet: vat: v44: ----- Auction.9  15030 reducePriceAndTrade
2023-08-23T16:12:15.412Z SwingSet: vat: v44: ----- AucBook.6  34645 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 8_500n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T16:12:15.418Z SwingSet: vat: v44: ----- AucBook.6  34646 settling 0 0
2023-08-23T16:12:15.428Z SwingSet: vat: v44: ----- SMath.7  14875 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_129n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:15:13.644Z SwingSet: vat: v44: ----- SCHED.8  34710 wake step { absValue: 1_692_807_307n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:15:13.646Z SwingSet: vat: v44: ----- SCHED.8  34711 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_307n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:15:13.647Z SwingSet: vat: v44: ----- Auction.9  15031 reducePriceAndTrade
2023-08-23T16:15:13.654Z SwingSet: vat: v44: ----- AucBook.6  34647 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 8_000n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T16:15:13.661Z SwingSet: vat: v44: ----- AucBook.6  34648 settling 0 0
2023-08-23T16:15:13.674Z SwingSet: vat: v44: ----- SMath.7  14876 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_307n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:18:12.129Z SwingSet: vat: v44: ----- SCHED.8  34712 wake step { absValue: 1_692_807_486n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:18:12.131Z SwingSet: vat: v44: ----- SCHED.8  34713 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_486n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:18:12.132Z SwingSet: vat: v44: ----- Auction.9  15032 reducePriceAndTrade
2023-08-23T16:18:12.137Z SwingSet: vat: v44: ----- AucBook.6  34649 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 7_500n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T16:18:12.144Z SwingSet: vat: v44: ----- AucBook.6  34650 settling 0 0
2023-08-23T16:18:12.152Z SwingSet: vat: v44: ----- SMath.7  14877 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_486n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:21:16.108Z SwingSet: vat: v44: ----- SCHED.8  34714 wake step { absValue: 1_692_807_664n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:21:16.109Z SwingSet: vat: v44: ----- SCHED.8  34715 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_664n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:21:16.110Z SwingSet: vat: v44: ----- Auction.9  15033 reducePriceAndTrade
2023-08-23T16:21:16.114Z SwingSet: vat: v44: ----- AucBook.6  34651 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 7_000n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T16:21:16.124Z SwingSet: vat: v44: ----- AucBook.6  34652 settling 2 0
2023-08-23T16:21:16.179Z SwingSet: vat: v44: ----- SMath.7  14878 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_664n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:24:13.626Z SwingSet: vat: v44: ----- SCHED.8  34716 wake step { absValue: 1_692_807_847n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:24:13.628Z SwingSet: vat: v44: ----- SCHED.8  34717 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_806_402n } { absValue: 1_692_807_847n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T16:24:13.629Z SwingSet: vat: v44: ----- Auction.9  15034 finalize
2023-08-23T16:24:13.632Z SwingSet: vat: v44: ----- AucBook.6  34653 endAuction
2023-08-23T17:00:06.530Z SwingSet: vat: v44: ----- AucBook.6  34654 capturing oracle price  { denominator: { brand: Object [Alleged: ATOM brand] {}, value: 1_000_000n }, numerator: { brand: Object [Alleged: IST brand] {}, value: 9_445_342n } }
2023-08-23T17:00:06.538Z SwingSet: vat: v44: ----- SCHED.8  34718 START  { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n }
2023-08-23T17:00:06.540Z SwingSet: vat: v44: ----- SCHED.8  34719 scheduleDescendingSteps repeating { absValue: 1_692_810_000n, timerBrand: Object [Alleged: timerBrand] {} } { timerBrand: Object [Alleged: timerBrand] {}, relValue: 2n } { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n }
2023-08-23T17:00:06.550Z SwingSet: vat: v44: ----- SCHED.8  34720 nextRound { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_813_600n }
2023-08-23T17:00:06.552Z SwingSet: vat: v44: ----- SMath.7  14879 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_000n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:00:12.162Z SwingSet: vat: v44: ----- SCHED.8  34721 wake step { absValue: 1_692_810_006n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:00:12.167Z SwingSet: vat: v44: ----- SCHED.8  34722 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_006n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:00:12.169Z SwingSet: vat: v44: ----- Auction.9  15035 startRound
2023-08-23T17:00:12.174Z SwingSet: vat: v44: ----- AucBook.6  34655 set startPrice { denominator: { brand: Object [Alleged: ATOM brand] {}, value: 1_000_000n }, numerator: { brand: Object [Alleged: IST brand] {}, value: 9_445_342n } } null
2023-08-23T17:00:12.180Z SwingSet: vat: v44: ----- AucBook.6  34656 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 10_500n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T17:00:12.186Z SwingSet: vat: v44: ----- AucBook.6  34657 settling 0 0
2023-08-23T17:00:12.193Z SwingSet: vat: v44: ----- SMath.7  14880 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_006n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:03:10.557Z SwingSet: vat: v44: ----- SCHED.8  34723 wake step { absValue: 1_692_810_184n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:03:10.558Z SwingSet: vat: v44: ----- SCHED.8  34724 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_184n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:03:10.560Z SwingSet: vat: v44: ----- Auction.9  15036 reducePriceAndTrade 
2023-08-23T17:03:10.564Z SwingSet: vat: v44: ----- AucBook.6  34658 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 10_000n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T17:03:10.571Z SwingSet: vat: v44: ----- AucBook.6  34659 settling 0 0
2023-08-23T17:03:10.580Z SwingSet: vat: v44: ----- SMath.7  14881 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_184n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:06:15.047Z SwingSet: vat: v44: ----- SCHED.8  34725 wake step { absValue: 1_692_810_369n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:06:15.051Z SwingSet: vat: v44: ----- SCHED.8  34726 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_369n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:06:15.052Z SwingSet: vat: v44: ----- Auction.9  15037 reducePriceAndTrade
2023-08-23T17:06:15.057Z SwingSet: vat: v44: ----- AucBook.6  34660 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 9_500n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T17:06:15.064Z SwingSet: vat: v44: ----- AucBook.6  34661 settling 0 0
2023-08-23T17:06:15.072Z SwingSet: vat: v44: ----- SMath.7  14882 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_369n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:09:10.353Z SwingSet: vat: v44: ----- SCHED.8  34727 wake step { absValue: 1_692_810_544n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:09:10.355Z SwingSet: vat: v44: ----- SCHED.8  34728 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_544n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:09:10.356Z SwingSet: vat: v44: ----- Auction.9  15038 reducePriceAndTrade
2023-08-23T17:09:10.363Z SwingSet: vat: v44: ----- AucBook.6  34662 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 9_000n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T17:09:10.376Z SwingSet: vat: v44: ----- AucBook.6  34663 settling 0 0
2023-08-23T17:09:10.389Z SwingSet: vat: v44: ----- SMath.7  14883 calc { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_544n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:14:22.958Z SwingSet: vat: v44: ----- SCHED.8  34729 wake step { absValue: 1_692_810_732n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:14:22.959Z SwingSet: vat: v44: ----- SCHED.8  34730 clockTick { timerBrand: Object [Alleged: timerBrand] {}, absValue: 1_692_810_002n } { absValue: 1_692_810_732n, timerBrand: Object [Alleged: timerBrand] {} }
2023-08-23T17:14:22.961Z SwingSet: vat: v44: ----- Auction.9  15039 reducePriceAndTrade
2023-08-23T17:14:22.968Z SwingSet: vat: v44: ----- AucBook.6  34664 Object [Alleged: ATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 8_500n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T17:14:22.976Z SwingSet: vat: v44: ----- AucBook.6  34665 settling 0 0
2023-08-23T17:14:23.004Z SwingSet: vat: v44: ----- AucBook.6  34666 Object [Alleged: stATOM brand] {} settleAtNewRate { numerator: { brand: Object [Alleged: IST brand] {}, value: 8_500n }, denominator: { brand: Object [Alleged: IST brand] {}, value: 10_000n } }
2023-08-23T17:14:23.037Z SwingSet: ls: v44: Logging sent error stack (Error#1)
2023-08-23T17:14:23.038Z SwingSet: ls: v44: Error#1: price must be captured before auction starts
2023-08-23T17:14:23.039Z SwingSet: ls: v44: Error: price must be captured before auction starts
2023-08-23T17:14:23.039Z SwingSet: ls: v44: Error#1 ERROR_NOTE: Sent as error:liveSlots:v44#70001
2023-08-23T18:00:15.136Z SwingSet: vat: v44: ----- AucBook.6  34667 capturing oracle price  { denominator: { brand: Object [Alleged: ATOM brand] {}, value: 1_000_000n }, numerator: { brand: Object [Alleged: IST brand] {}, value: 9_445_342n } }
2023-08-23T18:00:15.148Z SwingSet: vat: v44: ----- AucBook.6  34668 capturing oracle price  { denominator: { brand: Object [Alleged: stATOM brand] {}, value: 1n }, numerator: { brand: Object [Alleged: IST brand] {}, value: 0n } }
2023-08-23T18:00:15.169Z SwingSet: ls: v44: Logging sent error stack (Error#2)
2023-08-23T18:00:15.169Z SwingSet: ls: v44: Error#2: can't start an auction round while one is active
2023-08-23T18:00:15.170Z SwingSet: ls: v44: Error: can't start an auction round while one is active
2023-08-23T18:00:15.171Z SwingSet: ls: v44: Error#2 ERROR_NOTE: Sent as error:liveSlots:v44#70002
2023-08-23T19:00:05.266Z SwingSet: vat: v44: ----- AucBook.6  34669 BOOK notifier 8820000/1000000
2023-08-25T16:35:13.142Z SwingSet: vat: v44: ----- AucBook.6  34670 BOOK notifier 8820000/1000000
2023-08-25T16:35:24.549Z SwingSet: vat: v44: ----- AucBook.6  34671 BOOK notifier 10405000/1000000
2023-08-25T16:36:07.908Z SwingSet: vat: v44: ----- AucBook.6  34672 BOOK notifier 11990000/1000000
2023-08-25T21:02:20.587Z SwingSet: vat: v44: ----- AucBook.6  34673 BOOK notifier 9187745/1000000

from 16:00:10 to 16:24:13, we see the previous complete round of the auction. There are 8 steps (startRound and 7 reducePriceAndTrade). The interrupted round only. had 4 reducePriceAndTrade steps before it stopped.

That round was the first time the stATOM book appeared, and it immediately complained that it didn't have a price. 43 minutes later, the auctioneer gets a price update for stATOM, but by then it's too late.

I think what happened is that the auctionBook threw an exception while performing a task for clockTick(), and the scheduler therefore descheduled that waker. That impies that most code that is started by a waker should return quickly, but not throw. I think auctionBook.settleAtNewRate() should return rather than throwing when there's no price, so other collaterals can continue their work, and the schedule will continue and be refreshed after the end of the auction.

Separately, the current code has no way to recover if nextSchedule exists and has a startTime in the past. All the wakeups have already fired, and the only interrupt comes from setting new parameters, but if nextSchedule is already set, it does nothing, with the expectation that a wakeup will eventually fire and at that point the new parameters will be made use of.

dckc · 2023-09-07T16:57:21Z

@otoole-brendan you don't need auctions running on devnet any time soon, right? I think the next steps to that are tracked elsewhere:

otoole-brendan added the bug Something isn't working label Sep 1, 2023

otoole-brendan changed the title ~~Auctions scheduler stopped on 8/23 on Devnet~~ No sign of auction status since 8/23 on Devnet Sep 1, 2023

dckc added the auction label Sep 1, 2023

dckc self-assigned this Sep 1, 2023

dckc assigned Chris-Hibbert and unassigned dckc Sep 1, 2023

dckc mentioned this issue Sep 4, 2023

fix: Make the auction schedule robust when adding collateral types #8301

Merged

Chris-Hibbert mentioned this issue Sep 5, 2023

All Auction timer repeated actions should catch exceptions or have a way to recover #8307

Closed

mergify bot closed this as completed in #8301 Sep 7, 2023

dckc changed the title ~~No sign of auction status since 8/23 on Devnet~~ auctioneer doesn't recover when collateral is added without a price Sep 7, 2023

dckc mentioned this issue Sep 12, 2023

test stATOM proposal in CI using an upgrade test #8177

Closed

Chris-Hibbert mentioned this issue Sep 27, 2023

refactor: delay addition of issuer to auctioneer until a good time #8398

Merged

aj-agoric mentioned this issue Oct 2, 2023

timing work-around for stATOM proposal #8347

Closed

Chris-Hibbert mentioned this issue Oct 5, 2023

feat: catch all exceptions in auction wakers #8438

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

auctioneer doesn't recover when collateral is added without a price #8296

auctioneer doesn't recover when collateral is added without a price #8296

otoole-brendan commented Sep 1, 2023 •

edited by dckc

Loading

dckc commented Sep 1, 2023

dckc commented Sep 1, 2023 •

edited

Loading

dckc commented Sep 1, 2023 •

edited

Loading

Chris-Hibbert commented Sep 1, 2023

dckc commented Sep 7, 2023

auctioneer doesn't recover when collateral is added without a price #8296

auctioneer doesn't recover when collateral is added without a price #8296

Comments

otoole-brendan commented Sep 1, 2023 • edited by dckc Loading

Describe the bug

To Reproduce

Expected behavior

dckc commented Sep 1, 2023

dckc commented Sep 1, 2023 • edited Loading

Diagnosis: auction schedule endTime is past

Impact: auctions for all collaterals affected by a problem with 1

context: devnet proposal 2

dckc commented Sep 1, 2023 • edited Loading

treatment: update auction params (not yet effective)

Chris-Hibbert commented Sep 1, 2023

dckc commented Sep 7, 2023

otoole-brendan commented Sep 1, 2023 •

edited by dckc

Loading

dckc commented Sep 1, 2023 •

edited

Loading

dckc commented Sep 1, 2023 •

edited

Loading