search

threefoldtech / tfchain

Threefold Chain.
Apache License 2.0
15 stars 11 forks source link

Bridge: Improved observability for our bridges #874

Closed sameh-farouk closed 8 months ago

sameh-farouk commented 11 months ago
sameh-farouk commented 10 months ago

Update: I have explored the code base of the bridge and the tft-bridge pallet to understand the implementation details of the cross-chain transfer flow. I have also compiled what I learned so far into new bridge documentation and opened a PR.

The bridge outputs human-readable logs and tracks only a few events that happen and acts upon them.

My current focus is to come up with an efficient schema for the logs and categorize them as well. I also want to make the bridge more aware of the transaction phases by possibly scanning other transfer-related events, so that tools parsing the logs can have a full image of the transfers.

sameh-farouk commented 10 months ago

Update: We’re almost there! A draft pull request has been opened and should be ready for review soon after some polishing and cleaning. also log schema need to be documented.

Please note that the merge will be blocked due to a small change required in Tfchain minting events. An issue will be opened for it.

The logs below is Outdated: Here’s a preview of the audit logs (subject to changes as PR progressed) associated with a deposit that had an invalid memo before and after I’ve instrumented the app with structured logs.

before:

6:27PM INF received transaction on bridge stellar account hash=078fa58d2b585aa40b92dae1c77fde1a2fa2fe28f61c0670beb1c4d6dfc8959c
6:27PM INF fetching stellar transactions account=GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ cursor=9195456261275648 horizon=https://horizon-testnet.stellar.org/
6:27PM INF error while decoding tx memo: twin not found: object not found
6:27PM INF saving cursor now 9195456261275648
6:27PM INF mint processed hash=078fa58d2b585aa40b92dae1c77fde1a2fa2fe28f61c0670beb1c4d6dfc8959c
6:27PM INF fetching events for blockheight ID=2039
6:28PM INF fetching stellar transactions account=GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ cursor=9195456261275648 horizon=https://horizon-testnet.stellar.org/
6:28PM INF fetching events for blockheight ID=2040
6:28PM INF fetching events for blockheight ID=2041
6:28PM INF found refund transaction ready event hash=078fa58d2b585aa40b92dae1c77fde1a2fa2fe28f61c0670beb1c4d6dfc8959c
6:28PM INF transaction submitted to the stellar network hash=c8860fc13d395437c5b98c3c7c45f2645fc2ccd1c4da486bfe2a905b6cf45fe1
6:28PM INF fetching stellar transactions account=GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ cursor=9195456261275648 horizon=https://horizon-testnet.stellar.org/
6:28PM INF received transaction on bridge stellar account hash=c8860fc13d395437c5b98c3c7c45f2645fc2ccd1c4da486bfe2a905b6cf45fe1
6:28PM INF refund processed hash=078fa58d2b585aa40b92dae1c77fde1a2fa2fe28f61c0670beb1c4d6dfc8959c

after:

[
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event": {
      "bridge_account": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "horizon_url": "https://horizon-testnet.stellar.org/",
      "cursor": "9742459001114624"
    },
    "event_type": "transactions_fetched",
    "count": 1,
    "time": "2023-10-30T11:37:12+02:00",
    "message": "stellar transactions fetched"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "span_id": "3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9",
    "event_type": "payment_received",
    "event": {
      "_links": {
        "self": {
          "href": "https://horizon-testnet.stellar.org/operations/9742940037459969"
        },
        "transaction": {
          "href": "https://horizon-testnet.stellar.org/transactions/3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9"
        },
        "effects": {
          "href": "https://horizon-testnet.stellar.org/operations/9742940037459969/effects"
        },
        "succeeds": {
          "href": "https://horizon-testnet.stellar.org/effects?order=desc&cursor=9742940037459969"
        },
        "precedes": {
          "href": "https://horizon-testnet.stellar.org/effects?order=asc&cursor=9742940037459969"
        }
      },
      "id": "9742940037459969",
      "paging_token": "9742940037459969",
      "transaction_successful": true,
      "source_account": "GD4MUF7FTWOGNREGKMQWC3NOJGBNASEFNEOUJTLNW4FDONV5CEUTGKS4",
      "type": "payment",
      "type_i": 1,
      "created_at": "2023-10-30T09:37:05Z",
      "transaction_hash": "3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9",
      "asset_type": "credit_alphanum4",
      "asset_code": "TFT",
      "asset_issuer": "GA47YZA3PKFUZMPLQ3B5F2E3CJIB57TGGU7SPCQT2WAEYKN766PWIMB3",
      "from": "GD4MUF7FTWOGNREGKMQWC3NOJGBNASEFNEOUJTLNW4FDONV5CEUTGKS4",
      "to": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "amount": "50.0000000"
    },
    "time": "2023-10-30T11:37:12+02:00",
    "message": "a payment received on bridge stellar account"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "span_id": "3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9",
    "event_type": "transfer_initiated",
    "event": {
      "type": "deposit"
    },
    "time": "2023-10-30T11:37:12+02:00",
    "message": "transfer with id 3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9 initiated"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event": {
      "bridge_account": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "horizon_url": "https://horizon-testnet.stellar.org/",
      "cursor": "9742940037459968"
    },
    "event_type": "transactions_fetched",
    "count": 0,
    "time": "2023-10-30T11:37:12+02:00",
    "message": "stellar transactions fetched"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event_type": "block_events_fetched",
    "event": {
      "height": 17637
    },
    "time": "2023-10-30T11:37:13+02:00",
    "message": "tfchain events fetched"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "span_id": "3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9",
    "event_type": "refund_proposed",
    "event": {
      "reason": "memo is not formatted correctly"
    },
    "time": "2023-10-30T11:37:18+02:00",
    "message": "refund initiated due to memo is not formatted correctly"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event_type": "block_events_fetched",
    "event": {
      "height": 17638
    },
    "time": "2023-10-30T11:37:19+02:00",
    "message": "tfchain events fetched"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event": {
      "bridge_account": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "horizon_url": "https://horizon-testnet.stellar.org/",
      "cursor": "9742940037459968"
    },
    "event_type": "transactions_fetched",
    "count": 0,
    "time": "2023-10-30T11:37:22+02:00",
    "message": "stellar transactions fetched"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event_type": "block_events_fetched",
    "event": {
      "height": 17639
    },
    "time": "2023-10-30T11:37:26+02:00",
    "message": "tfchain events fetched"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event_type": "block_events_fetched",
    "event": {
      "height": 17640
    },
    "time": "2023-10-30T11:37:32+02:00",
    "message": "tfchain events fetched"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event_type": "event_refund_tx_ready_received",
    "span_id": "3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9",
    "time": "2023-10-30T11:37:32+02:00",
    "message": "found refund transaction ready event"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "event": {
      "bridge_account": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "horizon_url": "https://horizon-testnet.stellar.org/",
      "cursor": "9742940037459968"
    },
    "event_type": "transactions_fetched",
    "count": 0,
    "time": "2023-10-30T11:37:33+02:00",
    "message": "stellar transactions fetched"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "span_id": "3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9",
    "event_type": "refund_completed",
    "time": "2023-10-30T11:37:36+02:00",
    "message": "refund processed"
  },
  {
    "level": "info",
    "version": 1,
    "source": {
      "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ",
      "Stellar_network": "testnet",
      "Tfchain_url": "ws://localhost:9944"
    },
    "span_id": "3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9",
    "event_type": "transfer_completed",
    "event": {
      "outcome": "refunded"
    },
    "time": "2023-10-30T11:37:36+02:00",
    "message": "transfer with id 3c88c4ca5144cee37a1d2a6a4f2bf5c874adb74f1f85bee1b84d3dbd86e81fd9 completed"
  }
]
sameh-farouk commented 10 months ago

Update: I spent a considerable amount of time grappling with the concept of Observability and the bridge design on the tfchain runtime. I wrote a detailed documentation about the bridging implementation while reading the source code and got it merged.

With the aim of improving observability and the ability to perform tracing on cross-chain transfers, I designed an event schema for the bridge and included its documentation here: https://github.com/threefoldtech/tfchain/blob/development-feat-structured-logging/bridge/docs/observability.md

I also finished instrumenting the bridge source code and the PR is ready for review but is currently blocked on https://github.com/threefoldtech/tfchain/issues/882.