search

get10101 / itchysats

CFDs on Bitcoin.
https://itchysats.network
MIT License
61 stars 17 forks source link

Flaky liquidation actor test #2606

Closed da-kami closed 2 years ago

da-kami commented 2 years ago

See test run: https://github.com/itchysats/itchysats/runs/7611016167?check_suite_focus=true First seen on PR: https://github.com/itchysats/itchysats/pull/2599

Copied logs:

 running 1 test
2022-08-01T12:33:26.229461Z DEBUG given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate:start_both:Start maker: maker::actor_system: Maker actor system ready
2022-08-01T12:33:26.233879Z  INFO maker::connection: Listening on 127.0.0.1:41673
2022-08-01T12:33:26.245047Z  INFO Handle NewListenAddress: xtra_libp2p::endpoint: Listen address added address=/ip4/127.0.0.1/tcp/35813
2022-08-01T12:33:26.718108Z  INFO given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate:start_both:Start taker: daemon_tests: Connecting to maker /ip4/127.0.0.1/tcp/35813/p2p/12D3KooWRyHFsHo72WWsFqBkeN1m1R9CvWPApu9dEwmMqVdXEyk1
2022-08-01T12:33:26.719799Z DEBUG given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate:start_both:Start taker:Create TakerActorSystem{n_payouts=200 connect_timeout_secs=10 environment=Test}: daemon: Taker actor system ready
2022-08-01T12:33:26.723040Z DEBUG online_status::Actor started: daemon::online_status: Online status watch actor started. Monitoring for peer id changes: PeerId("12D3KooWRyHFsHo72WWsFqBkeN1m1R9CvWPApu9dEwmMqVdXEyk1")
2022-08-01T12:33:26.723743Z DEBUG Start dialer actor: xtra_libp2p::dialer: Starting dialer actor
2022-08-01T12:33:26.725844Z DEBUG connect: daemon::connection: No connection to the maker
2022-08-01T12:33:26.727049Z DEBUG connect:Handle Connect: daemon::connection: Connecting to maker address=127.0.0.1:41673
2022-08-01T12:33:26.748658Z DEBUG maker::connection: Upgrade new connection taker_address=127.0.0.1:45102
2022-08-01T12:33:26.762425Z DEBUG responder_handshake: daemon::noise: Noise protocol responder handshake is complete
2022-08-01T12:33:26.767026Z DEBUG connect:Handle Connect:initiator_handshake: daemon::noise: Noise protocol initiator handshake is complete
2022-08-01T12:33:26.781836Z  INFO Handle ConnectionReady: maker::connection: Connection is ready taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 taker_address=127.0.0.1:45102 wire_version=2.1.0 daemon_version=0.1.0 environment=Test peer_id=Some(12D3KooWE2ond2RuV7xb16E7NwmABUx6McmuvSXWVZefWveZpC5P)
2022-08-01T12:33:26.784219Z TRACE Handle SendHeartbeat: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:33:26.784954Z TRACE Handle TakerConnected:Handle TakerMessage: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::CurrentOffers"
2022-08-01T12:33:26.790300Z  INFO connect:Handle Connect: daemon::connection: Received Hello message from maker maker_identity=11ad505a586a5f4d64ed3164589e3adc206f5dd4434cab7f8a668ef2ac481221 actual_version=2.1.0
2022-08-01T12:33:26.790451Z  INFO connect:Handle Connect: daemon::connection: Established connection to maker address=127.0.0.1:41673
2022-08-01T12:33:26.796300Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:33:26.796710Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::CurrentOffers"
2022-08-01T12:33:26.799617Z  INFO Handle NewConnection: xtra_libp2p::endpoint: Connection established peer=12D3KooWE2ond2RuV7xb16E7NwmABUx6McmuvSXWVZefWveZpC5P
2022-08-01T12:33:26.804075Z  INFO Start dialer actor:Handle Dial:dial:connect:Handle Connect:Dial new connection:Handle NewConnection: xtra_libp2p::endpoint: Connection established peer=12D3KooWRyHFsHo72WWsFqBkeN1m1R9CvWPApu9dEwmMqVdXEyk1
2022-08-01T12:33:26.807373Z DEBUG Start dialer actor:Handle Dial:dial:connect:Handle Connect:Dial new connection:Handle NewConnection:Handle endpoint :: ConnectionEstablished: daemon::online_status: Adding newly established connection to online_status: PeerId("12D3KooWRyHFsHo72WWsFqBkeN1m1R9CvWPApu9dEwmMqVdXEyk1")
2022-08-01T12:33:26.859714Z  INFO Handle IdentifyMsgReceived: daemon::identify::dialer: New identify message received peer_id=12D3KooWE2ond2RuV7xb16E7NwmABUx6McmuvSXWVZefWveZpC5P daemon_version=0.1.0 environment=Test wire_version=0.3.0
2022-08-01T12:33:26.905144Z  INFO Handle IdentifyMsgReceived: daemon::identify::dialer: New identify message received peer_id=12D3KooWRyHFsHo72WWsFqBkeN1m1R9CvWPApu9dEwmMqVdXEyk1 daemon_version=0.1.0 environment=Unknown wire_version=0.3.0
2022-08-01T12:33:26.907114Z TRACE given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate:Handle OfferParams:Handle BroadcastOffers:Broadcast offers to taker: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::CurrentOffers"
2022-08-01T12:33:26.911344Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::CurrentOffers"
2022-08-01T12:33:26.951925Z  INFO daemon::order::taker: Placing order order=PlaceOrder { id: OrderId(0695310d-3c2e-4ef6-a7ab-048812029579), offer: Offer { id: OrderId(0a91af5e-cb56-496d-ab93-2cb228b3be88), trading_pair: BtcUsd, position_maker: Short, price: Price(394096), min_quantity: Usd(100), max_quantity: Usd(1000), leverage_taker: Leverage(2), leverage_choices: [Leverage(2)], creation_timestamp_maker: Timestamp(1659357206), settlement_interval: Duration { seconds: 86400, nanoseconds: 0 }, origin: Theirs, oracle_event_id: BitMexPriceEventId { timestamp: OffsetDateTime { utc_datetime: PrimitiveDateTime { date: Date { year: 2022, ordinal: 214 }, time: Time { hour: 13, minute: 0, second: 0, nanosecond: 0 } }, offset: UtcOffset { hours: 0, minutes: 0, seconds: 0 } }, digits: 20 }, tx_fee_rate: TxFeeRate(1), funding_rate: FundingRate(0.00024), opening_fee: OpeningFee { fee: Amount(0.00000002 BTC) } }, quantity: Usd(100), leverage: Leverage(2), maker_peer_id: PeerId("12D3KooWRyHFsHo72WWsFqBkeN1m1R9CvWPApu9dEwmMqVdXEyk1"), maker_identity: Identity(PublicKey(MontgomeryPoint([17, 173, 80, 90, 88, 106, 95, 77, 100, 237, 49, 100, 88, 158, 58, 220, 32, 111, 93, 212, 67, 76, 171, 127, 138, 102, 142, 242, 172, 72, 18, 33]))) }
2022-08-01T12:33:26.985964Z  INFO Register new inbound substream{substream=NewInboundSubstream { peer: PeerId("12D3KooWE2ond2RuV7xb16E7NwmABUx6McmuvSXWVZefWveZpC5P"), stream: Substream { inner: Negotiated { state: Completed { io: Stream { id: 3, connection: b168fa15 } } } } }}:Handle NewInboundSubstream: daemon::order::maker: Taker wants to place an order taker=12D3KooWE2ond2RuV7xb16E7NwmABUx6McmuvSXWVZefWveZpC5P quantity=100 order_id=0695310d-3c2e-4ef6-a7ab-048812029579
2022-08-01T12:33:27.014527Z DEBUG given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate:Handle AcceptOrder:Handle Decision: daemon::order::maker: Instructed to Accept order 0695310d-3c2e-4ef6-a7ab-048812029579
2022-08-01T12:33:27.014782Z  INFO daemon::order::maker: Order accepted taker=12D3KooWE2ond2RuV7xb16E7NwmABUx6McmuvSXWVZefWveZpC5P quantity=100 order_id=0695310d-3c2e-4ef6-a7ab-048812029579
2022-08-01T12:33:27.016040Z  INFO daemon::order::taker: Order accepted order_id=0695310d-3c2e-4ef6-a7ab-048812029579 maker_peer_id=12D3KooWRyHFsHo72WWsFqBkeN1m1R9CvWPApu9dEwmMqVdXEyk1
2022-08-01T12:33:27.049775Z DEBUG Setup contract: daemon::setup_contract: setup_params=SetupParams { margin: Amount(0.00025375 BTC), counterparty_margin: Amount(0.00012687 BTC), counterparty_identity: Identity(PublicKey(MontgomeryPoint([104, 101, 108, 108, 111, 32, 119, 111, 114, 108, 100, 44, 32, 111, 104, 32, 119, 104, 97, 116, 32, 97, 32, 98, 101, 97, 117, 116, 105, 102, 117, 108]))), price: Price(394096), quantity: Usd(100), long_leverage: Leverage(2), short_leverage: Leverage(1), refund_timelock: 216, tx_fee_rate: TxFeeRate(1), fee_account: FeeAccount { balance: SignedAmount(-0.00000009 BTC), position: Short, role: Maker } } role=Maker position=Short n_payouts=200
2022-08-01T12:33:27.131288Z DEBUG Setup contract: daemon::setup_contract: setup_params=SetupParams { margin: Amount(0.00012687 BTC), counterparty_margin: Amount(0.00025375 BTC), counterparty_identity: Identity(PublicKey(MontgomeryPoint([17, 173, 80, 90, 88, 106, 95, 77, 100, 237, 49, 100, 88, 158, 58, 220, 32, 111, 93, 212, 67, 76, 171, 127, 138, 102, 142, 242, 172, 72, 18, 33]))), price: Price(394096), quantity: Usd(100), long_leverage: Leverage(2), short_leverage: Leverage(1), refund_timelock: 216, tx_fee_rate: TxFeeRate(1), fee_account: FeeAccount { balance: SignedAmount(0.00000009 BTC), position: Long, role: Taker } } role=Taker position=Long n_payouts=200
2022-08-01T12:33:27.207427Z  INFO Setup contract: daemon::setup_contract: Exchanged setup parameters
2022-08-01T12:33:27.277790Z  INFO Setup contract: daemon::setup_contract: Exchanged setup parameters
2022-08-01T12:33:31.788961Z TRACE Handle SendHeartbeat: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:33:31.791090Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:33:36.791383Z TRACE Handle SendHeartbeat: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:33:36.793192Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:33:36.894416Z  INFO Setup contract: daemon::setup_contract: Created CFD transactions
2022-08-01T12:33:37.346299Z  INFO Setup contract: daemon::setup_contract: Created CFD transactions
2022-08-01T12:33:51.670651Z  INFO Setup contract: daemon::setup_contract: Exchanged CFD transactions
2022-08-01T12:34:10.451381Z  INFO Setup contract: daemon::setup_contract: Exchanged CFD transactions
2022-08-01T12:34:10.470615Z TRACE Handle SendHeartbeat: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:10.473807Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:15.473556Z TRACE Handle SendHeartbeat: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:15.475264Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:20.476044Z TRACE Handle SendHeartbeat: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:20.477294Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:25.478042Z TRACE Handle SendHeartbeat: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:25.479503Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::Heartbeat"
test given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate has been running for over 60 seconds
2022-08-01T12:34:26.181055Z  INFO Setup contract: daemon::setup_contract: Verified all signatures
2022-08-01T12:34:26.321390Z  INFO Setup contract: daemon::setup_contract: Verified all signatures
2022-08-01T12:34:26.324338Z  INFO Setup contract: daemon::setup_contract: Exchanged signed lock transaction
2022-08-01T12:34:26.379857Z  INFO Setup contract: daemon::setup_contract: Exchanged signed lock transaction
2022-08-01T12:34:28.635311Z  INFO model::cfd: Contract setup was completed order_id=0695310d-3c2e-4ef6-a7ab-048812029579
2022-08-01T12:34:29.027184Z  INFO model::cfd: Contract setup was completed order_id=0695310d-3c2e-4ef6-a7ab-048812029579
2022-08-01T12:34:30.545696Z TRACE Handle SendHeartbeat: wire: Sending taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14 msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:30.549829Z TRACE Forward MakerStreamMessage:Handle MakerStreamMessage: wire: Received msg_name="MakerToTaker::Heartbeat"
2022-08-01T12:34:31.001906Z DEBUG maker::connection: Connection got dropped taker_id=98bfe1af2c3dae9187c47f7ded06428c334924a61518bf78a17cf6077224ba14
test given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate ... FAILED

failures:

failures:
    given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 1 filtered out; finished in 65.26s

--- TRY 3 STDERR:                         daemon-tests::liquidation given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate ---
thread 'given_rollover_when_oracle_attests_long_liquidation_price_can_liquidate' panicked at 'called `Option::unwrap()` on a `None` value', daemon-tests/tests/liquidation.rs:92:10
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
da-kami commented 2 years ago

I am a bit confused by 

panicked at 'called `Option::unwrap()` on a `None` value'

because I don't think that there is any panic in the test. We might have just run into a timeout? Maybe you can have a look @luckysori

Restioson commented 2 years ago

The unwrap is 

    let attestation = oracle_data_rollover
        .attestation_for_event(first_liquidation_event)
        .unwrap();

So I guess there's no attestation at that point ?

da-kami commented 2 years ago

Yeah, that is where it panics and you are right that this must be the problem! I thought we would also see the panic in the test logs but since it panics in the test code this is expected behavior.

It appears that there is no attestation for the given first event. This is odd because the event is fixed, I would not know how this can fail. I think the problem might be that we are not awaiting the DLC to actually change, so the latest_dlc might still be the previous one.

klochowicz commented 2 years ago

Happens to me sometimes locally too :/

protip: cargo nextest run --retries=1 typically solves the problem on local machine, it will re-run flaky tests once.