search

vegaprotocol / vega

A Go implementation of the Vega Protocol, a protocol for creating and trading derivatives on a fully decentralised network.
https://vega.xyz
GNU Affero General Public License v3.0
37 stars 19 forks source link

[Bug]: Market proposal "Enacted" event is arguably late being emitted #8479

Closed jgsbennett closed 11 months ago

jgsbennett commented 1 year ago

Problem encountered

I see the "Enacted" event for a market emitted two blocks later than the "Continuous Trading" market updated event, which feels a bit weird. Nothing breaking, but weird. See logs below.

Observed behaviour

"Enacted" event for market proposal is sent out multiple blocks after the "Continuous trading" event that signals that a market is now enacted/trading

Expected behaviour

Both events are ideally sent out in the block that it happens...

Steps to reproduce

1. Run any test where a market is created, and then inspect the PROPOSAL and MARKET_UPDATED event files.
2. i.e: `pytest tests/matching_engine -k test_FilledIOCMarketOrder`

Software version

d95ce8e2707c6aa6ee4b103c30c8aff66bd6820d

Failing test

No response

Jenkins run

No response

Configuration used

No response

Relevant log output

{"id":"4030-26","block":"C82CDB5F4AF82099346C9141B1BB737BA28C34F24521A0BECBE54526A749649A","type":"BUS_EVENT_TYPE_MARKET_UPDATED","marketUpdated":{"id":"10ad95a37cf69182897df52036274f68766f4b69f0a7e2e0a61ad4a1a35e87bd","tradableInstrument":{"instrument":{"code":"CRYPTO:VEGA CORE SYS TEST","name":"Futures System-Tests Market","metadata":{"tags":["asset_class:fx/crypto","product:futures"]},"future":{"settlementAsset":"2804e0898abb47f10600ffcf336a7e79874b077a8aa9d434b4ad923cd68432de","quoteName":"USD","dataSourceSpecForSettlementData":{"id":"60803fd455705e83f24521cc2bd3f129593a602bae663655695f32ab650914a2","data":{"external":{"oracle":{"signers":[{"pubKey":{"key":"587ca1cc934963e467680bbe020ac3ae7ce39e29497aa164ccded315f0f4804b"}}],"filters":[{"key":{"name":"oracle.test.settlementE7EB3","type":"TYPE_INTEGER","numberDecimalPlaces":"5"},"conditions":[{"operator":"OPERATOR_GREATER_THAN_OR_EQUAL","value":"0"}]}]}}}},"dataSourceSpecForTradingTermination":{"id":"95e5e48a2ffdccc048c37ece648dce84f6717ca79505810f0541b271b6ee0313","data":{"external":{"oracle":{"signers":[{"pubKey":{"key":"587ca1cc934963e467680bbe020ac3ae7ce39e29497aa164ccded315f0f4804b"}}],"filters":[{"key":{"name":"oracle.test.terminationF079A","type":"TYPE_BOOLEAN"},"conditions":[{"operator":"OPERATOR_EQUALS","value":"True"}]}]}}}},"dataSourceSpecBinding":{"settlementDataProperty":"oracle.test.settlementE7EB3","tradingTerminationProperty":"oracle.test.terminationF079A"}}},"marginCalculator":{"scalingFactors":{"searchLevel":1.1,"initialMargin":1.2,"collateralRelease":1.4}},"logNormalRiskModel":{"riskAversionParameter":0.001,"tau":0.00011407711613050422,"params":{"r":0.016,"sigma":1.5}}},"decimalPlaces":"5","fees":{"factors":{"makerFee":"0.004","infrastructureFee":"0.001","liquidityFee":"0.3"}},"openingAuction":{"duration":"35"},"priceMonitoringSettings":{"parameters":{}},"liquidityMonitoringParameters":{"targetStakeParameters":{"timeWindow":"10","scalingFactor":5},"triggeringRatio":"0","auctionExtension":"1"},"tradingMode":"TRADING_MODE_CONTINUOUS","state":"STATE_ACTIVE","marketTimestamps":{"proposed":"1686320568802388038","pending":"1686320578000000000","open":"1686320613176835286"},"positionDecimalPlaces":"5","lpPriceRange":"1","linearSlippageFactor":"0.01","quadraticSlippageFactor":"0"},"version":1,"chainId":"testnet-001","txHash":"C82CDB5F4AF82099346C9141B1BB737BA28C34F24521A0BECBE54526A749649A"}
Block 4030 it announces it is in continuous trading...
{"id":"4032-19","block":"B784C03155DDC185583DBC9773833D9669EA6FA6BED44178E2547C812B63F272","type":"BUS_EVENT_TYPE_PROPOSAL","proposal":{"id":"10ad95a37cf69182897df52036274f68766f4b69f0a7e2e0a61ad4a1a35e87bd","reference":"C83D48106B","partyId":"587ca1cc934963e467680bbe020ac3ae7ce39e29497aa164ccded315f0f4804b","state":"STATE_ENACTED","timestamp":"1686320568802388038","terms":{"closingTimestamp":"1686320578","enactmentTimestamp":"1686320613","newMarket":{"changes":{"instrument":{"name":"Futures System-Tests Market","code":"CRYPTO:VEGA CORE SYS TEST","future":{"settlementAsset":"2804e0898abb47f10600ffcf336a7e79874b077a8aa9d434b4ad923cd68432de","quoteName":"USD","dataSourceSpecForSettlementData":{"external":{"oracle":{"signers":[{"pubKey":{"key":"587ca1cc934963e467680bbe020ac3ae7ce39e29497aa164ccded315f0f4804b"}}],"filters":[{"key":{"name":"oracle.test.settlementE7EB3","type":"TYPE_INTEGER","numberDecimalPlaces":"5"},"conditions":[{"operator":"OPERATOR_GREATER_THAN_OR_EQUAL","value":"0"}]}]}}},"dataSourceSpecForTradingTermination":{"external":{"oracle":{"signers":[{"pubKey":{"key":"587ca1cc934963e467680bbe020ac3ae7ce39e29497aa164ccded315f0f4804b"}}],"filters":[{"key":{"name":"oracle.test.terminationF079A","type":"TYPE_BOOLEAN"},"conditions":[{"operator":"OPERATOR_EQUALS","value":"True"}]}]}}},"dataSourceSpecBinding":{"settlementDataProperty":"oracle.test.settlementE7EB3","tradingTerminationProperty":"oracle.test.terminationF079A"}}},"decimalPlaces":"5","metadata":["asset_class:fx/crypto","product:futures"],"priceMonitoringParameters":{},"liquidityMonitoringParameters":{"targetStakeParameters":{"timeWindow":"10","scalingFactor":5},"triggeringRatio":"0","auctionExtension":"1"},"logNormal":{"riskAversionParameter":0.001,"tau":0.00011407711613050422,"params":{"r":0.016,"sigma":1.5}},"positionDecimalPlaces":"5","lpPriceRange":"1","linearSlippageFactor":"0.01","quadraticSlippageFactor":"0"}}},"rationale":{"description":"Proposal submitted to enact a new Market","title":"Market Proposal"},"requiredParticipation":"0.00000015","requiredMajority":"0.66"},"version":1,"chainId":"testnet-001","txHash":"B784C03155DDC185583DBC9773833D9669EA6FA6BED44178E2547C812B63F272"}
But it is only two blocks later (4032) that it announces it is enacted.
gordsport commented 1 year ago

@jgsbennett

When triaging this its been deemed that this should not be possible and MUST be fixed before any deployment if it is indeed an issue.

Do you have a test that shows this failing?

jgsbennett commented 1 year ago

Well here's another example from last night's run that actually caused a test failure because the test was trying to check the two events happen within a second of each other... (I didn't realise this test existed, since usually we must be getting > 2 blocks per second and so the test doesn't fail, even though I would personally have expected this to be the same block) https://jenkins.ops.vega.xyz/job/common/job/system-tests-wrapper/78692/testReport/junit/tests.matching_engine/auction_trading_test/test_opening_auction_opens_after_enactment/ https://jenkins.ops.vega.xyz/job/common/job/system-tests-wrapper/78692/artifact/test_logs/tests.matching_engine.auction_trading_test/test_opening_auction_opens_after_enactment/BUS_EVENT_TYPE_MARKET_UPDATED.txt https://jenkins.ops.vega.xyz/job/common/job/system-tests-wrapper/78692/artifact/test_logs/tests.matching_engine.auction_trading_test/test_opening_auction_opens_after_enactment/BUS_EVENT_TYPE_PROPOSAL.txt

{"id":"7057-132","block":"2548885C603A9681AA05BE6450334A7FB21C503337CFD37C12DC6C3CAC0E4574","type":"BUS_EVENT_TYPE_MARKET_UPDATED","marketUpdated":{"id":"1952f7476f059c7b24f65cf0d89ebf139a0f88d80a95a53d11f71147ed7bc81c","tradableInstrument":{"instrument":{"code":"CRYPTO:VEGA CORE SYS TEST","name":"Futures System-Tests Market","metadata":{"tags":["asset_class:fx/crypto","product:futures"]},"future":{"settlementAsset":"10d6782a1e81fb0851fb97ace6ed21bc34f14fec1c5da6b1783a8a6c0dd266ce","quoteName":"USD","dataSourceSpecForSettlementData":{"id":"c56640ed7e3b24d8f1db58c3a6fd0db8ea6c1cfe553c8db56e227a3a7d6d84a8","data":{"external":{"oracle":{"signers":[{"pubKey":{"key":"7228c4a22dc4afe6b1f36cf1ac13b63b85cee33038c851947c7a49c9241611c5"}}],"filters":[{"key":{"name":"oracle.test.settlementC059C","type":"TYPE_INTEGER","numberDecimalPlaces":"5"},"conditions":[{"operator":"OPERATOR_GREATER_THAN_OR_EQUAL","value":"0"}]}]}}}},"dataSourceSpecForTradingTermination":{"id":"ae662990a17a7671fec9cc0c688389ebc332b1056b26e6e25aa58baccfe6280a","data":{"external":{"oracle":{"signers":[{"pubKey":{"key":"7228c4a22dc4afe6b1f36cf1ac13b63b85cee33038c851947c7a49c9241611c5"}}],"filters":[{"key":{"name":"oracle.test.terminationD2281","type":"TYPE_BOOLEAN"},"conditions":[{"operator":"OPERATOR_EQUALS","value":"True"}]}]}}}},"dataSourceSpecBinding":{"settlementDataProperty":"oracle.test.settlementC059C","tradingTerminationProperty":"oracle.test.terminationD2281"}}},"marginCalculator":{"scalingFactors":{"searchLevel":1.1,"initialMargin":1.2,"collateralRelease":1.4}},"logNormalRiskModel":{"riskAversionParameter":0.001,"tau":0.00011407711613050422,"params":{"r":0.016,"sigma":1.5}}},"decimalPlaces":"5","fees":{"factors":{"makerFee":"0.004","infrastructureFee":"0.001","liquidityFee":"0.3"}},"openingAuction":{"duration":"41"},"priceMonitoringSettings":{"parameters":{}},"liquidityMonitoringParameters":{"targetStakeParameters":{"timeWindow":"10","scalingFactor":5},"triggeringRatio":"0","auctionExtension":"1"},"tradingMode":"TRADING_MODE_CONTINUOUS","state":"STATE_ACTIVE","marketTimestamps":{"proposed":"1687918743837268019","pending":"1687918747000000000","open":"1687918788060815293"},"positionDecimalPlaces":"5","lpPriceRange":"1","linearSlippageFactor":"0.01","quadraticSlippageFactor":"0"},"version":1,"chainId":"testnet-001","txHash":"2548885C603A9681AA05BE6450334A7FB21C503337CFD37C12DC6C3CAC0E4574"}
{"id":"7059-171","block":"0BB8DBCB1470798B5670F10DFC8C7F64106525D8C2961A5F554CBEC00754EE3A","type":"BUS_EVENT_TYPE_PROPOSAL","proposal":{"id":"1952f7476f059c7b24f65cf0d89ebf139a0f88d80a95a53d11f71147ed7bc81c","reference":"D7F7CF3E17","partyId":"7228c4a22dc4afe6b1f36cf1ac13b63b85cee33038c851947c7a49c9241611c5","state":"STATE_ENACTED","timestamp":"1687918743837268019","terms":{"closingTimestamp":"1687918747","enactmentTimestamp":"1687918788","newMarket":{"changes":{"instrument":{"name":"Futures System-Tests Market","code":"CRYPTO:VEGA CORE SYS TEST","future":{"settlementAsset":"10d6782a1e81fb0851fb97ace6ed21bc34f14fec1c5da6b1783a8a6c0dd266ce","quoteName":"USD","dataSourceSpecForSettlementData":{"external":{"oracle":{"signers":[{"pubKey":{"key":"7228c4a22dc4afe6b1f36cf1ac13b63b85cee33038c851947c7a49c9241611c5"}}],"filters":[{"key":{"name":"oracle.test.settlementC059C","type":"TYPE_INTEGER","numberDecimalPlaces":"5"},"conditions":[{"operator":"OPERATOR_GREATER_THAN_OR_EQUAL","value":"0"}]}]}}},"dataSourceSpecForTradingTermination":{"external":{"oracle":{"signers":[{"pubKey":{"key":"7228c4a22dc4afe6b1f36cf1ac13b63b85cee33038c851947c7a49c9241611c5"}}],"filters":[{"key":{"name":"oracle.test.terminationD2281","type":"TYPE_BOOLEAN"},"conditions":[{"operator":"OPERATOR_EQUALS","value":"True"}]}]}}},"dataSourceSpecBinding":{"settlementDataProperty":"oracle.test.settlementC059C","tradingTerminationProperty":"oracle.test.terminationD2281"}}},"decimalPlaces":"5","metadata":["asset_class:fx/crypto","product:futures"],"priceMonitoringParameters":{},"liquidityMonitoringParameters":{"targetStakeParameters":{"timeWindow":"10","scalingFactor":5},"triggeringRatio":"0","auctionExtension":"1"},"logNormal":{"riskAversionParameter":0.001,"tau":0.00011407711613050422,"params":{"r":0.016,"sigma":1.5}},"positionDecimalPlaces":"5","lpPriceRange":"1","linearSlippageFactor":"0.01","quadraticSlippageFactor":"0"}}},"rationale":{"description":"Proposal submitted to enact a new Market","title":"Market Proposal"},"requiredParticipation":"0.00000015","requiredMajority":"0.66"},"version":1,"chainId":"testnet-001","txHash":"0BB8DBCB1470798B5670F10DFC8C7F64106525D8C2961A5F554CBEC00754EE3A"}

But if my previous analysis is correct, you can inspect the events for any market in any test and you'll see the same/similar things.

jgsbennett commented 1 year ago

Please remove this workaround when fixed: https://github.com/vegaprotocol/system-tests/pull/2242 Had to add because this issue (I think) is causing various other tests to fail because the enactment event is delayed, which sometimes causes tests to trip if it coincides with some slower-than-expected blocks (another issue).

EVODelavega commented 11 months ago

I just noticed what might be the source of confusion here: the MarketUpdated event contains the market definition, the trading mode is the default trading mode for that market (there were/are plans to support markets that don't do continuous trading, but rather trade in batches (FBA). The event which shows the current trading mode is the market data event.

I understand that this can be rather confusing. The market updated event, though, contains the full market as defined through governance so datanode can accurately serve up the market as defined and currently operating, and is primarily aimed to communicate changes to the market definition that come from governance (market update proposals getting enacted)

TL;DR I don't think this is a bug

jgsbennett commented 11 months ago

I don't see why one market event should be able to respond to to the state change multiple blocks before the other one.

EVODelavega commented 11 months ago

The state change here that is causing the event to be sent is the call to StartOpeningAuction, the data contained in the event is the market definition. As per the proposal, the market is defined to have the default trading mode: TRADING_MODE_CONTINUOUS, this doesn't mean that this is the current trading mode. The events that contain the current trading mode (eg opening auction, monitoring auction, etc...) is the market data event, not the market update events. The market update events signal either the creation of, or updates to the market configuration. As this market previously was in a proposed state, and is now enacted, this is emitting the market update event, containing the market config as it is at the moment where the proposal was enacted (some parameters may have been updated since the proposal was submitted due to network parameters changing for example). The trading mode shown in this event is not the current trading mode, you have to look at the market data events to get that information.