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.

Sign up for GitHub

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

Jump to bottom

Bridge: Improved observability for our bridges #874

Closed
sameh-farouk opened this issue Oct 12, 2023 · 3 comments · Fixed by #881
Closed

Bridge: Improved observability for our bridges #874

sameh-farouk opened this issue Oct 12, 2023 · 3 comments · Fixed by #881
Assignees
@sameh-farouk
Labels
type_feature New feature or request
Milestone
2.7.0

Comments

@sameh-farouk
Copy link
Member

sameh-farouk commented Oct 12, 2023 •
edited
Loading

@sameh-farouk sameh-farouk changed the title Health Endpoint Bridge: Health Endpoint Oct 12, 2023
@sameh-farouk sameh-farouk added the type_feature New feature or request label Oct 12, 2023
@xmonader xmonader added this to the 2.6.0 milestone Oct 15, 2023
@sameh-farouk sameh-farouk mentioned this issue Oct 15, 2023
Closed
1 task
@sameh-farouk sameh-farouk changed the title Bridge: Health Endpoint Bridge: Improved observability for our bridges Oct 15, 2023
@sameh-farouk sameh-farouk moved this to In Progress in 3.13.x Oct 25, 2023
@sameh-farouk
Copy link
Member Author

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 sameh-farouk mentioned this issue Oct 30, 2023
Merged
1 task
@sameh-farouk
Copy link
Member Author

sameh-farouk commented Oct 30, 2023 •
edited
Loading

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 sameh-farouk mentioned this issue Oct 30, 2023
Closed
@sameh-farouk
Copy link
Member Author

sameh-farouk commented Nov 3, 2023 •
edited
Loading

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 #882.

@sameh-farouk sameh-farouk moved this from In Progress to Blocked in 3.13.x Nov 3, 2023
@sameh-farouk sameh-farouk added type_feature New feature or request and removed type_feature New feature or request labels Nov 6, 2023
@sameh-farouk sameh-farouk modified the milestones: 2.6.0, 2.7.0 Nov 6, 2023
@sameh-farouk sameh-farouk moved this from Blocked to Pending review in 3.13.x Nov 7, 2023
@sameh-farouk sameh-farouk moved this from Pending review to Pending Deployment in 3.13.x Nov 14, 2023
@sameh-farouk sameh-farouk moved this from Pending Deployment to Pending review in 3.13.x Nov 14, 2023
@github-project-automation github-project-automation bot moved this from Pending review to Done in 3.13.x Dec 18, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sameh-farouk sameh-farouk

Labels
type_feature New feature or request
Projects
No open projects
3.13.x
Status: Done
Milestone
2.7.0
Development

Successfully merging a pull request may close this issue.

Development feat structured logging threefoldtech/tfchain
2 participants
@xmonader @sameh-farouk