diff --git a/bridge/docs/observability.md b/bridge/docs/observability.md new file mode 100644 index 000000000..59b41eec4 --- /dev/null +++ b/bridge/docs/observability.md @@ -0,0 +1,1422 @@ +# Bridge Observability +The bridge is event-driven distributed system, it can be challenging to understand how requests or transfers move through the system and where bottlenecks may occur. +This is where techniques like distributed tracing, structured logs, and structured events comes in to allows developers and operators to monitor and understand the behavior of complex systems. + +By using these techniques, developers and operators can gain a more complete understanding of how their applications are performing in production and quickly identify issues when they arise. + +## Structured events +This section describes the structure and contents of the bridge logs. +It defines a common set of field names and data types, as well as descriptions and examples of how to use them. + +Bridge logs are structured and represented in JSON format. +It uses a common structure for logs, making it easier to ingest, correlate, search, and aggregate on individual fields within your logs. + +For interfaces designed for humans, they can simply display the "message" key and hide the other metadata, making the log easy to ready without sacrificing the metadata. + +The logs entries serve as events (represents an immutable event that occurred in the past), and adopting past-tense verb naming schema. + +### Events: +#### Operational Events: +These events to audit how the bridge system is operating. + +##### Bridge availability events +- `bridge_init_aborted`: The bridge failed to initiated mostly due to misconfiguration. +- `bridge_started`: The bridge started successfully. +- `bridge_unexpectedly_exited`: The bridge panicked. +- `bridge_stopped`: The bridge stopped normally mostly for maintenance or new version enrollment. + +##### Persistency events +- `stellar_cursor_saved`: The bridge saved the account operation cursor. + +##### Stellar monitor events +- `transactions_fetched`: The bridge fetched transactions data from stellar network. Should be received periodically and can be used as a mark message to detect availability issues. Also include stellar cursor position. +- `fetch_transactions_failed`: The bridge failed to fetch transactions data from stellar network. + +##### TFChain monitor events +- `block_events_fetched`: The bridge fetched transactions data from TFChain network for a block. Should be received every block and can be used as a mark message to detect availability issues. Also include the TFChain height. +- `fetch_finalized_Heads_failed`: The bridge failed to fetch transactions data from TFChain network. + +#### Business Events: +These events are for business intelligence and always tied to a user transfer, and include a `trace_id` field. + +you can use `trace_id` to correlate multiple log entries and track an transfer from one chain to the other. it is simply a stellar tx ID or TFChain burn ID depend on the side the transfer initiated from. + +For example, if a customer is complaining that their deposit never bridged, you could filter logs using `trace_id` field with the id of the customer deposit to get overview of all events related to this deposit id and see what went wrong. + +##### Cross-chain transfer events +- `transfer_initiated`: The bridge initiated a cross chain transfer (after receiving a deposit from stellar side or burn event from TFChain side). +- `transfer_completed`: The bridge has completed a cross chain transfer (either by bridging tokens to the other chain or issuing a refund if something went wrong). +- `transfer_failed`: a withdraw can not be completed and refund is not possible as well. + +##### Cross-chain transfer phases +##### Mint related +- `mint_skipped`: a mint request skipped by the bridge instance as it has already been minted. +- `mint_proposed`: a mint has proposed or voted by the bridge instance. +- `mint_completed`: a mint has completed and received on the target TFChain account. + +##### Refund related +- `event_refund_tx_ready_received`: The bridge instance has received TFChain `RefundTransactionReady` event which means all bridge validators signed a refund transaction. +- `event_refund_tx_expired_received`: The bridge instance has received TFChain `RefundTransactionExpired` event. +- `refund_skipped`: a refund request skipped by the bridge instance as it has already been refunded. +- `refund_proposed`: a refund has proposed or signed by the bridge instance. +- `refund_completed`: a refund has completed and received on the target stellar account. + +##### Withdraw related +- `event_burn_tx_created_received`: The bridge instance has received TFChain `BurnTransactionCreated` event. +- `event_burn_tx_ready_received`: The bridge instance has received TFChain `BurnTransactionReady` event which means all bridge validators signed a withdraw transaction. +- `event_burn_tx_expired_received`: The bridge instance has received TFChain `BurnTransactionExpired` event. +- `withdraw_skipped`: a refund request skipped by the bridge instance as it has already been refunded. +- `withdraw_proposed`: a withdraw has proposed or signed by the bridge instance. +- `withdraw_completed`: a withdraw has completed and received on the target stellar account. + +##### Bridge vault account related +- `payment_received` : This event represents successful payment to the bridge account (a deposit). +- `stellar_transaction_submitted` : This event represents successful transaction from the bridge account (a refund or a withdraw). + +### Metrics: + +This events describes a numeric measurement taken at given point in time. +Metric events are often collected on a predictable frequency. + +#### Bridge vault account related +- `wallet_balance`: This event describes a tft balance locked on the bridge and collected once a minute. + +### Log schema: + +#### Base fields +The base field set contains all fields which are at the root of the events. These fields are common across all types of events. + +| Field | Type | Description | Required | +| --- | --- | --- | --- | +| level | string | yes | The level or severity of the log event | +| version | number | yes |Log schema version | +| source | object | yes | Information about the bridge instance | +| event_action | string | yes | The action captured by the event | +| event_kind | string | yes | Can gives high-level information about what type of information the event contains, without being specific to the contents of the event. One of `Event`, `Alert`, `Error`, `metric` | +| metadata | object | no | Only present for logs that contain meta data about the event | +| message | string | yes | The log message | +| time | time | yes | The timestamp of the log event | +| error | string | no | Only present for logs that contain an exception or error. The message of the exception or error | +| category | string | no | One of `availability`, `persistency`, `stellar_monitor`, `tfchain_monitor`, `transfer`, `mint`, `refund`, `withdraw`, `vault` | +| trace_id | string | no | Only present on business events. a unique identifier that is assigned to a trace, which represents a complete cross-chain transfer flow. | + +#### Categorization Fields +##### event_kind field +The value of this field can be used to inform how these kinds of events should be handled. + +- alert: This value indicates an event such as an alert or notable event. + +- event: This value is the most general and most common value for this field. It is used to represent events that indicate that something happened. + +- error: This value indicates that an error occurred during the operation of the bridge. + +- metric: This events describes a numeric measurement taken at given point in time. + +##### category field +The value of this represents the "big buckets" of event categories + +- availability +- persistency +- stellar_monitor +- tfchain_monitor +- transfer +- mint +- refund +- withdraw +- vault + +#### source object +the source field set contains all fields which are included in the source object, it is common across all types of events except of `bridge_init_aborted` error event. + +| Field | Type | Required | Description | +| --- | --- | --- | --- | +| Instance_public_key | string | yes | Instance public key which you can use to filter logs by instance | +| Bridge_wallet_address | string | yes | The bridge account address which you can use to filter logs by bridge | +| Stellar_network | string | yes | Stellar network name which you can use to filter logs by environment | +| Tfchain_url | string | yes | The url of the substrate rpc node which you can use to filter logs by environment | + +#### Event-specific fields: + +##### bridge_init_aborted + +- kind: error + +- category: availability + + + + + + + + + + + + + + + + +
bridge_init_aborted Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### bridge_started + +- kind: event + +- category: availability + + + + + + + + + + + + + + + + + + + + + + + + + +
bridge_started Event Properties
PropertyTypeRequiredDescription
rescan_flagboolyesThe value of the bridge configuration flag which used to instruct the bridge to scan the vault account from the earliest known operation.
deposit_feenumberyesThe bridge fees to charge per deposit which fetched from TFChain.
+ +##### bridge_unexpectedly_exited + +- kind: error + +- category: availability + + + + + + + + + + + + + + + + +
bridge_unexpectedly_exited Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### bridge_stopped + +- kind: event + +- category: availability + + + + + + + + + + + + + + + + +
bridge_stopped Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### stellar_cursor_saved + +- kind: event + +- category: persistency + + + + + + + + + + + + + + + + + + + +
stellar_cursor_saved Event Properties
PropertyTypeRequiredDescription
cursornumberyesthe Cursor is an integer that points to a specific location in a collection of horizon responses.
+ +##### transactions_fetched + +- kind: event + +- category: stellar_monitor + + + + + + + + + + + + + + + + + + + + + + + + + +
transactions_fetched Event Properties
PropertyTypeRequiredDescription
cursornumberyesthe Cursor is an integer that points to a specific location in a collection of horizon responses.
countnumberyesThe count of the fetched transactions from horizon.
+ +##### fetch_transactions_failed + +- kind: alert + +- category: stellar_monitor + + + + + + + + + + + + + + + + + + + +
fetch_transactions_failed Event Properties
PropertyTypeRequiredDescription
cursornumberyesthe Cursor is an integer that points to a specific location in a collection of horizon responses.
+ +##### block_events_fetched + +- kind: event + +- category: tfchain_monitor + + + + + + + + + + + + + + + + + + + +
block_events_fetched Event Properties
PropertyTypeRequiredDescription
heightnumberyesThe block height of a TFChain
+ +##### fetch_finalized_Heads_failed + +- kind: alert + +- category: tfchain_monitor + + + + + + + + + + + + + + + + +
fetch_finalized_Heads_failed Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### transfer_initiated + +- kind: event + +- category: transfer + + + + + + + + + + + + + + + + + + + +
transfer_initiated Event Properties
PropertyTypeRequiredDescription
typestringyesThe type of this transfer. One of `burn` (from tfchain side) or `deposit` (from stellar side).
+ +##### transfer_completed + +- kind: event + +- category: transfer + + + + + + + + + + + + + + + + + + + +
transfer_completed Event Properties
PropertyTypeRequiredDescription
outcomestringyesOne of `refunded` or `bridged`.
+ +##### transfer_failed + +- kind: alert + +- category: transfer + + + + + + + + + + + + + + + + + + + + + + + + + +
transfer_failed Event Properties
PropertyTypeRequiredDescription
reasonstringyesThe reason behind the failure of this transfer.
typestringyesThe type of this transfer. One of `burn` (from tfchain side) or `deposit` (from stellar side).
+ +##### mint_skipped + +- kind: event + +- category: mint + + + + + + + + + + + + + + + + +
mint_skipped Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### mint_proposed + +- kind: event + +- category: mint + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + +
mint_proposed Event Properties
PropertyTypeRequiredDescription
amountnumberyesdeposited amount to be minted on tfchain.
tx_idnumberyesThe stellar deposit tx ID.
tostringyesThe tfchain target account address.
+ +##### mint_completed + +- kind: event + +- category: mint + + + + + + + + + + + + + + + + +
mint_completed Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### event_refund_tx_ready_received + +- kind: event + +- category: refund + + + + + + + + + + + + + + + + +
event_refund_tx_ready_received Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### event_refund_tx_expired_received + +- kind: alert + +- category: refund + + + + + + + + + + + + + + + + +
event_refund_tx_expired_received Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### refund_skipped + +- kind: event + +- category: refund + + + + + + + + + + + + + + + + +
refund_skipped Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### refund_proposed + +- kind: event + +- category: refund + + + + + + + + + + + + + + + + + + + +
refund_proposed Event Properties
PropertyTypeRequiredDescription
reasonstringyesThe reason for refunding this transaction.
+ +##### refund_completed + +- kind: event + +- category: refund + + + + + + + + + + + + + + + + +
refund_completed Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### event_burn_tx_created_received + +- kind: event + +- category: withdraw + + + + + + + + + + + + + + + + +
event_burn_tx_created_received Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### event_burn_tx_ready_received + +- kind: event + +- category: withdraw + + + + + + + + + + + + + + + + +
event_burn_tx_ready_received Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### event_burn_tx_expired_received + +- kind: alert + +- category: withdraw + + + + + + + + + + + + + + + + +
event_burn_tx_expired_received Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### withdraw_skipped + +- kind: event + +- category: withdraw + + + + + + + + + + + + + + + + +
withdraw_skipped Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### withdraw_proposed + +- kind: event + +- category: withdraw + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + +
withdraw_proposed Event Properties
PropertyTypeRequiredDescription
amountnumberyesBurned amount.
tx_idnumberyesThe burn ID.
tostringyesThe stellar target account address.
+ +##### withdraw_completed + +- kind: event + +- category: withdraw + + + + + + + + + + + + + + + + +
withdraw_completed Event Properties
PropertyTypeRequiredDescription
No metadata
+ +##### payment_received + +- kind: event + +- category: vault + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + +
payment_received Event Properties
PropertyTypeRequiredDescription
fromstringyesThe stellar source account address
amountdecimalyesDeposit amount
tx_hashstringyestransaction hash
ledger_close_timetimeyestransaction time
+ +##### stellar_transaction_submitted + +- kind: event + +- category: vault + + + + + + + + + + + + + + + + + + + +
stellar_transaction_submitted Event Properties
PropertyTypeRequiredDescription
result_tx_idstringyesThe stellar id of the bridge executed transaction.
+ +##### wallet_balance + +- kind: metric + +- category: vault + + + + + + + + + + + + + + + + + + + +
wallet_balance Event Properties
PropertyTypeRequiredDescription
tftnumberyesThe tft amount locked in the bridge vault account. collected once a minute
+ +## Usage examples: + +### Example 1 + +One example, if a customer is complaining that their deposit never bridged, you could filter logs using `trace_id` field with the id of the customer deposit to get overview of all events related to this deposit id and see what went wrong. + + - trace_id = `16d8b06b59aaa5514c645260263e5477bb8aad211502c56cb8849ed5b423d354` + +The result would be an array of well defined events, and for a well behave cross-transfer from stellar network to tfchain network it should include these events in the same order: + +*payment_received* --> *transfer_initiated* --> *mint_proposed* --> *mint_completed* --> *transfer_completed* + +the filtered result would be similar to the one below: + +``` +[ + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "16d8b06b59aaa5514c645260263e5477bb8aad211502c56cb8849ed5b423d354", + "event_action": "payment_received", + "event_kind": "event", + "category": "vault", + "metadata": { + "from": "GD4MUF7FTWOGNREGKMQWC3NOJGBNASEFNEOUJTLNW4FDONV5CEUTGKS4", + "amount": "5.0000000" + }, + "tx_hash": "16d8b06b59aaa5514c645260263e5477bb8aad211502c56cb8849ed5b423d354", + "ledger_close_time": "2023-11-05 17:08:28 +0000 UTC", + "time": "2023-11-05T19:08:32+02:00", + "message": "a payment has 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" + }, + "trace_id": "16d8b06b59aaa5514c645260263e5477bb8aad211502c56cb8849ed5b423d354", + "event_action": "transfer_initiated", + "event_kind": "event", + "category": "transfer", + "metadata": { + "type": "deposit" + }, + "time": "2023-11-05T19:08:33+02:00", + "message": "a transfer has initiated" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "16d8b06b59aaa5514c645260263e5477bb8aad211502c56cb8849ed5b423d354", + "event_action": "mint_proposed", + "event_kind": "event", + "category": "mint", + "metadata": { + "amount": 50000000, + "tx_id": "16d8b06b59aaa5514c645260263e5477bb8aad211502c56cb8849ed5b423d354", + "to": "5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY" + }, + "time": "2023-11-05T19:08:36+02:00", + "message": "a mint has proposed with the target substrate address of 5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "16d8b06b59aaa5514c645260263e5477bb8aad211502c56cb8849ed5b423d354", + "event_action": "mint_completed", + "event_kind": "event", + "category": "mint", + "time": "2023-11-05T19:08:49+02:00", + "message": "found MintCompleted event" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "16d8b06b59aaa5514c645260263e5477bb8aad211502c56cb8849ed5b423d354", + "event_action": "transfer_completed", + "event_kind": "event", + "category": "transfer", + "metadata": { + "outcome": "bridged" + }, + "time": "2023-11-05T19:08:49+02:00", + "message": "transfer has completed" + } +] +``` + +The `transfer_completed` event’s `outcome` field value of `bridged` indicates that the TFT was successfully transferred. + +### Example 2 + +For a cross-chain transfer from TFChain to Stellar, the trace_id will be an integer. + + - trace_id = `10` + +Let’s examine the event actions for this transfer: + +*event_burn_tx_created_received* --> *transfer_initiated* --> *mint_proposed* --> *mint_completed* --> *transfer_completed* + +This time, the transfer was not completed on the other network and was instead refunded. However, using the `trace_id`, you can still trace the transfer from start to end. The filtered result would be similar to the one below: + + +``` +[ + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "10", + "event_action": "event_burn_tx_created_received", + "event_kind": "event", + "category": "withdraw", + "time": "2023-11-05T20:16:31+02:00", + "message": "found BurnTransactionCreated event" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "10", + "event_action": "transfer_initiated", + "event_kind": "event", + "category": "transfer", + "metadata": { + "type": "burn" + }, + "time": "2023-11-05T20:16:31+02:00", + "message": "a transfer has initiated" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "10", + "event_action": "mint_proposed", + "event_kind": "event", + "category": "mint", + "metadata": { + "amount": 40000000, + "tx_id": "10", + "to": "0xd43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d" + }, + "time": "2023-11-05T20:16:36+02:00", + "message": "a mint has proposed with the target substrate address of 0xd43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "10", + "event_action": "mint_completed", + "event_kind": "event", + "category": "mint", + "time": "2023-11-05T20:16:50+02:00", + "message": "found MintCompleted event" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "10", + "event_action": "transfer_completed", + "event_kind": "event", + "category": "transfer", + "metadata": { + "outcome": "refunded" + }, + "time": "2023-11-05T20:16:50+02:00", + "message": "transfer has completed" + } +] +``` + +Notably, the `transfer_completed` event’s `outcome` field value of refunded indicates that the TFT was refunded to the source account. + +### Example 3 + +Here is another example of a cross-chain transfer from TFChain to Stellar, where the events show that the transfer was successful. + + - trace_id = `13` + +*event_burn_tx_created_received* --> *transfer_initiated* --> *withdraw_proposed* --> *event_burn_tx_ready_received* --> *stellar_transaction_submitted* --> *withdraw_completed* --> *transfer_completed* + +For a more simplified view, you can filter events by the transfer category to display only the start and end events of the transfer in question. + +``` +[ + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "13", + "event_action": "event_burn_tx_created_received", + "event_kind": "event", + "category": "withdraw", + "time": "2023-11-05T20:57:08+02:00", + "message": "found BurnTransactionCreated event" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "13", + "event_action": "transfer_initiated", + "event_kind": "event", + "category": "transfer", + "metadata": { + "type": "burn" + }, + "time": "2023-11-05T20:57:08+02:00", + "message": "a transfer has initiated" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "13", + "event_action": "withdraw_proposed", + "event_kind": "event", + "category": "withdraw", + "metadata": { + "amount": 40000000, + "tx_id": "13", + "to": "GBK4SQ5HUMWKMSYVEAFPPO4W27YRPGHE4CGQOKEFQ3WGPTSNURZPISO3" + }, + "time": "2023-11-05T20:57:12+02:00", + "message": "a withdraw has proposed with the target stellar address of GBK4SQ5HUMWKMSYVEAFPPO4W27YRPGHE4CGQOKEFQ3WGPTSNURZPISO3" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "13", + "event_action": "event_burn_tx_ready_received", + "event_kind": "event", + "category": "withdraw", + "time": "2023-11-05T20:57:25+02:00", + "message": "found BurnTransactionReady event" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "13", + "event_action": "stellar_transaction_submitted", + "event_kind": "event", + "category": "vault", + "metadata": { + "result_tx_id": "777f561a4b91928f4679ad182be2178a29d5f0a3ee28a0461708d183d0a00a7d" + }, + "time": "2023-11-05T20:57:32+02:00", + "message": "the transaction submitted to the Stellar network, and its unique identifier is 777f561a4b91928f4679ad182be2178a29d5f0a3ee28a0461708d183d0a00a7d" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "13", + "event_action": "withdraw_completed", + "event_kind": "event", + "category": "withdraw", + "time": "2023-11-05T20:57:32+02:00", + "message": "the withdraw has proceed" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "13", + "event_action": "transfer_completed", + "event_kind": "event", + "category": "transfer", + "metadata": { + "outcome": "bridged" + }, + "time": "2023-11-05T20:57:32+02:00", + "message": "the transfer has completed" + } +] +``` + +### Example 4 + +The final example illustrates the expected events when a transfer from Stellar to TFChin fails. We will filter the events using the `trace_id`, which is the deposit transaction ID. + + - trace_id = `7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f` + +The `transfer_completed` event contains the `outcome` of the transfer, which is refunded. + +Also Upon reviewing the `refund_proposed` event, we found that the `reason` field indicates that the memo was not properly formatted. + +``` +[ + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f", + "event_action": "payment_received", + "event_kind": "event", + "category": "vault", + "metadata": { + "from": "GD4MUF7FTWOGNREGKMQWC3NOJGBNASEFNEOUJTLNW4FDONV5CEUTGKS4", + "amount": "5.0000000" + }, + "tx_hash": "7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f", + "ledger_close_time": "2023-11-05 19:05:48 +0000 UTC", + "time": "2023-11-05T21:05:57+02:00", + "message": "a payment has 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" + }, + "trace_id": "7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f", + "event_action": "transfer_initiated", + "event_kind": "event", + "category": "transfer", + "metadata": { + "type": "deposit" + }, + "time": "2023-11-05T21:05:57+02:00", + "message": "a transfer has initiated" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f", + "event_action": "refund_proposed", + "event_kind": "event", + "category": "refund", + "metadata": { + "reason": "memo is not properly formatted" + }, + "time": "2023-11-05T21:06:00+02:00", + "message": "a refund has proposed due to memo is not properly formatted" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f", + "event_action": "event_refund_tx_ready_received", + "event_kind": "event", + "category": "refund", + "time": "2023-11-05T21:06:12+02:00", + "message": "found RefundTransactionReady event" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f", + "event_action": "stellar_transaction_submitted", + "event_kind": "event", + "category": "vault", + "metadata": { + "result_tx_id": "161c06d9ebd518beee0147c5e9e8b67c851f1c443b30444aff415668e76b09de" + }, + "time": "2023-11-05T21:06:16+02:00", + "message": "the transaction submitted to the Stellar network, and its unique identifier is 161c06d9ebd518beee0147c5e9e8b67c851f1c443b30444aff415668e76b09de" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f", + "event_action": "refund_completed", + "event_kind": "event", + "category": "refund", + "time": "2023-11-05T21:06:18+02:00", + "message": "the transaction has refunded" + }, + { + "level": "info", + "version": 1, + "source": { + "Instance_public_key": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Bridge_wallet_address": "GBD3PXJEQOCQ5VR2JSMFNXYBBQF5RDEZP5GMTXDYZWMNZQJHR6HFX3AJ", + "Stellar_network": "testnet", + "Tfchain_url": "ws://localhost:9944" + }, + "trace_id": "7f0406ad7b8d4f0de6dade19eb3979ef93857a56c6daa4bf9f2b0bb22a21d84f", + "event_action": "transfer_completed", + "event_kind": "event", + "category": "transfer", + "metadata": { + "outcome": "refunded" + }, + "time": "2023-11-05T21:06:18+02:00", + "message": "the transfer has completed" + } +] +``` diff --git a/bridge/docs/readme.md b/bridge/docs/readme.md index 65eb72780..66e030883 100644 --- a/bridge/docs/readme.md +++ b/bridge/docs/readme.md @@ -37,4 +37,8 @@ Refer to [production](./production.md) for more information on how to setup a pr When you have setup the bridge in either development or production mode you can start bridging. -See [bridging](./bridging.md) for more information on how to bridge. \ No newline at end of file +See [bridging](./bridging.md) for more information on how to bridge. + +## Log schema +Bridge validators use simple event log for the sake of improving observability and perform tracing on workflows and data. +you can find more about the log schema and how it can improve the observability of the system in [the bride observability document](./observability.md). diff --git a/bridge/tfchain_bridge/main.go b/bridge/tfchain_bridge/main.go index 43fba8724..c6d2a630b 100644 --- a/bridge/tfchain_bridge/main.go +++ b/bridge/tfchain_bridge/main.go @@ -7,11 +7,11 @@ import ( "syscall" "time" - "github.com/rs/zerolog" "github.com/rs/zerolog/log" flag "github.com/spf13/pflag" "github.com/threefoldtech/tfchain_bridge/pkg" "github.com/threefoldtech/tfchain_bridge/pkg/bridge" + "github.com/threefoldtech/tfchain_bridge/pkg/logger" ) func main() { @@ -30,12 +30,7 @@ func main() { flag.Parse() - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stdout}) - zerolog.SetGlobalLevel(zerolog.InfoLevel) - if debug { - zerolog.SetGlobalLevel(zerolog.DebugLevel) - log.Debug().Msg("debug mode enabled") - } + logger.InitLogger(debug) ctx, cancel := context.WithCancel(context.Background()) defer cancel() @@ -43,23 +38,46 @@ func main() { timeout, timeoutCancel := context.WithTimeout(ctx, time.Second*15) defer timeoutCancel() - br, err := bridge.NewBridge(timeout, bridgeCfg) + br, address, err := bridge.NewBridge(timeout, bridgeCfg) if err != nil { - panic(err) + log.Fatal(). + Err(err). + Str("event_action", "bridge_init_aborted"). + Str("event_kind", "error"). + Str("category", "availability"). + Msg("the bridge instance cannot be started") + } + sourceLogEntry := logger.SourceCommonLogEntry{ + Instance_public_key: address, + Bridge_wallet_address: bridgeCfg.StellarBridgeAccount, + Stellar_network: bridgeCfg.StellarNetwork, + Tfchain_url: bridgeCfg.TfchainURL, } + log.Logger = log.Logger.With().Interface("source", sourceLogEntry).Logger() + sigs := make(chan os.Signal, 1) signal.Notify(sigs, syscall.SIGINT, syscall.SIGTERM) go func() { - log.Info().Msg("awaiting signal") + log.Debug().Msg("awaiting signal") <-sigs - log.Info().Msg("shutting now") + log.Debug().Msg("shutting now") cancel() }() if err = br.Start(ctx); err != nil && err != context.Canceled { - log.Fatal().Err(err).Msg("exited unexpectedly") + log.Fatal(). + Err(err). + Str("event_action", "bridge_unexpectedly_exited"). + Str("event_kind", "error"). + Str("category", "availability"). + Msg("the bridge instance has exited unexpectedly") } + log.Info(). + Str("event_action", "bridge_stopped"). + Str("event_kind", "event"). + Str("category", "availability"). + Msg("the bridge instance has stopped") } diff --git a/bridge/tfchain_bridge/pkg/bridge/bridge.go b/bridge/tfchain_bridge/pkg/bridge/bridge.go index 6dc7c69cb..85c233b6c 100644 --- a/bridge/tfchain_bridge/pkg/bridge/bridge.go +++ b/bridge/tfchain_bridge/pkg/bridge/bridge.go @@ -2,8 +2,10 @@ package bridge import ( "context" + "time" "github.com/pkg/errors" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" "github.com/threefoldtech/tfchain_bridge/pkg" "github.com/threefoldtech/tfchain_bridge/pkg/stellar" @@ -24,20 +26,20 @@ type Bridge struct { depositFee int64 } -func NewBridge(ctx context.Context, cfg pkg.BridgeConfig) (*Bridge, error) { +func NewBridge(ctx context.Context, cfg pkg.BridgeConfig) (*Bridge, string, error) { subClient, err := subpkg.NewSubstrateClient(cfg.TfchainURL, cfg.TfchainSeed) if err != nil { - return nil, err + return nil, "", err } blockPersistency, err := pkg.InitPersist(cfg.PersistencyFile) if err != nil { - return nil, err + return nil, "", err } wallet, err := stellar.NewStellarWallet(ctx, &cfg.StellarConfig) if err != nil { - return nil, err + return nil, "", err } if cfg.RescanBridgeAccount { @@ -46,18 +48,18 @@ func NewBridge(ctx context.Context, cfg pkg.BridgeConfig) (*Bridge, error) { // and mint accordingly err = blockPersistency.SaveStellarCursor("0") if err != nil { - return nil, err + return nil, "", err } err = blockPersistency.SaveHeight(0) if err != nil { - return nil, err + return nil, "", err } } // fetch the configured depositfee depositFee, err := subClient.GetDepositFee() if err != nil { - return nil, err + return nil, "", err } bridge := &Bridge{ @@ -67,39 +69,60 @@ func NewBridge(ctx context.Context, cfg pkg.BridgeConfig) (*Bridge, error) { config: &cfg, depositFee: depositFee, } - - return bridge, nil + // stat deposit fee? + return bridge, wallet.GetKeypair().Address(), nil } func (bridge *Bridge) Start(ctx context.Context) error { + log.Info(). + Str("event_action", "bridge_started"). + Str("event_kind", "event"). + Str("category", "availability"). + Dict("metadata", zerolog.Dict(). + Bool("rescan_flag", bridge.config.RescanBridgeAccount). + Int64("deposit_fee", bridge.depositFee)). + Msg("the bridge instance has started") height, err := bridge.blockPersistency.GetHeight() if err != nil { - return errors.Wrap(err, "failed to get block height from persistency") + return errors.Wrap(err, "an error occurred while reading block height from persistency") } - log.Info().Msg("starting stellar subscription...") + log.Debug(). + Msg("The Stellar subscription is starting") stellarSub := make(chan stellar.MintEventSubscription) go func() { defer close(stellarSub) if err = bridge.wallet.StreamBridgeStellarTransactions(ctx, stellarSub, height.StellarCursor); err != nil { - log.Fatal().Msgf("failed to monitor bridge account %s", err.Error()) + log.Fatal(). + Err(err). + Str("event_action", "bridge_unexpectedly_exited"). + Str("event_kind", "error"). + Str("category", "availability"). + Msg("the bridge instance has exited unexpectedly") } }() - log.Info().Msg("starting tfchain subscription...") + log.Debug(). + Msg("The TFChain subscription is starting") tfchainSub := make(chan subpkg.EventSubscription) go func() { defer close(tfchainSub) if err := bridge.subClient.SubscribeTfchainBridgeEvents(ctx, tfchainSub); err != nil { - log.Fatal().Msgf("failed to subscribe to tfchain %s", err.Error()) + log.Fatal(). + Err(err). + Str("event_action", "bridge_unexpectedly_exited"). + Str("event_kind", "error"). + Str("category", "availability"). + Msg("the bridge instance has exited unexpectedly") } }() + afterMinute := time.After(60 * time.Second) for { select { case data := <-tfchainSub: if data.Err != nil { - return errors.Wrap(err, "failed to process events") + return errors.Wrap(err, "failed to get tfchain events") } for _, withdrawCreatedEvent := range data.Events.WithdrawCreatedEvents { err := bridge.handleWithdrawCreated(ctx, withdrawCreatedEvent) @@ -108,13 +131,13 @@ func (bridge *Bridge) Start(ctx context.Context) error { if errors.Is(err, pkg.ErrTransactionAlreadyBurned) || errors.Is(err, pkg.ErrTransactionAlreadyMinted) { continue } - return errors.Wrap(err, "failed to handle withdraw created") + return errors.Wrap(err, "an error occurred while handling WithdrawCreatedEvents") } } for _, withdrawExpiredEvent := range data.Events.WithdrawExpiredEvents { err := bridge.handleWithdrawExpired(ctx, withdrawExpiredEvent) if err != nil { - return errors.Wrap(err, "failed to handle withdraw expired") + return errors.Wrap(err, "an error occurred while handling WithdrawExpiredEvents") } } for _, withdawReadyEvent := range data.Events.WithdrawReadyEvents { @@ -123,14 +146,13 @@ func (bridge *Bridge) Start(ctx context.Context) error { if errors.Is(err, pkg.ErrTransactionAlreadyBurned) { continue } - return errors.Wrap(err, "failed to handle withdraw ready") + return errors.Wrap(err, "an error occurred while handling WithdrawReadyEvents") } - log.Info().Uint64("ID", withdawReadyEvent.ID).Msg("withdraw processed") } for _, refundExpiredEvent := range data.Events.RefundExpiredEvents { err := bridge.handleRefundExpired(ctx, refundExpiredEvent) if err != nil { - return errors.Wrap(err, "failed to handle refund expired") + return errors.Wrap(err, "an error occurred while handling RefundExpiredEvents") } } for _, refundReadyEvent := range data.Events.RefundReadyEvents { @@ -139,13 +161,12 @@ func (bridge *Bridge) Start(ctx context.Context) error { if errors.Is(err, pkg.ErrTransactionAlreadyRefunded) { continue } - return errors.Wrap(err, "failed to handle refund ready") + return errors.Wrap(err, "an error occurred while handling RefundReadyEvents") } - log.Info().Str("hash", refundReadyEvent.Hash).Msg("refund processed") } case data := <-stellarSub: if data.Err != nil { - return errors.Wrap(err, "failed to get mint events") + return errors.Wrap(err, "failed to get stellar payments") } for _, mEvent := range data.Events { @@ -154,12 +175,26 @@ func (bridge *Bridge) Start(ctx context.Context) error { if errors.Is(err, pkg.ErrTransactionAlreadyMinted) { continue } - return errors.Wrap(err, "failed to handle mint") + return errors.Wrap(err, "an error occurred while processing the payment received") // mint could be initiated already but there is a problem saving the cursor } - log.Info().Str("hash", mEvent.Tx.Hash).Msg("mint processed") } + time.Sleep(0) + case <-afterMinute: + balance, err := bridge.wallet.StatBridgeAccount() + if err != nil { + log.Logger.Warn().Err(err).Msgf("Can't retrieve the wallet balance at the moment") + } + log.Logger.Info(). + Str("event_action", "wallet_balance"). + Str("event_kind", "metric"). + Str("category", "vault"). + Dict("metadata", zerolog.Dict(). + Str("tft", balance)). + Msgf("TFT Balance is %s", balance) + afterMinute = time.After(60 * time.Second) case <-ctx.Done(): return ctx.Err() } + time.Sleep(1 * time.Second) } } diff --git a/bridge/tfchain_bridge/pkg/bridge/mint.go b/bridge/tfchain_bridge/pkg/bridge/mint.go index 38479d470..9228f547f 100644 --- a/bridge/tfchain_bridge/pkg/bridge/mint.go +++ b/bridge/tfchain_bridge/pkg/bridge/mint.go @@ -7,14 +7,18 @@ import ( "strings" "github.com/pkg/errors" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" hProtocol "github.com/stellar/go/protocols/horizon" substrate "github.com/threefoldtech/tfchain/clients/tfchain-client-go" "github.com/threefoldtech/tfchain_bridge/pkg" + _logger "github.com/threefoldtech/tfchain_bridge/pkg/logger" ) // mint handler for stellar func (bridge *Bridge) mint(ctx context.Context, senders map[string]*big.Int, tx hProtocol.Transaction) error { + logger := log.Logger.With().Str("trace_id", tx.ID).Logger() + minted, err := bridge.subClient.IsMintedAlready(tx.Hash) if err != nil { if !errors.Is(err, substrate.ErrMintTransactionNotFound) { @@ -23,18 +27,30 @@ func (bridge *Bridge) mint(ctx context.Context, senders map[string]*big.Int, tx } if minted { - log.Info().Str("tx_id", tx.Hash).Msg("transaction is already minted") + logger.Info(). + Str("event_action", "mint_skipped"). + Str("event_kind", "event"). + Str("category", "mint"). + Msg("the transaction has already been minted") return pkg.ErrTransactionAlreadyMinted } if len(senders) == 0 { return nil } - + logger.Info(). + Str("event_action", "transfer_initiated"). + Str("event_kind", "event"). + Str("category", "transfer"). + Dict("metadata", zerolog.Dict(). + Str("type", "deposit")). + Msg("a transfer has initiated") + + // only one payment in transaction is allowed if len(senders) > 1 { - log.Info().Msgf("cannot process mint transaction, multiple senders found, refunding now") + ctx = _logger.WithRefundReason(ctx, "multiple senders found") for sender, depositAmount := range senders { - return bridge.refund(context.Background(), sender, depositAmount.Int64(), tx) + return bridge.refund(ctx, sender, depositAmount.Int64(), tx) // so how this should refund the multiple senders ? } } @@ -46,37 +62,35 @@ func (bridge *Bridge) mint(ctx context.Context, senders map[string]*big.Int, tx } if tx.Memo == "" { - log.Info().Str("tx_id", tx.Hash).Msg("transaction has empty memo, refunding now") - return bridge.refund(context.Background(), receiver, depositedAmount.Int64(), tx) + ctx = _logger.WithRefundReason(ctx, "no memo in transaction") + return bridge.refund(ctx, receiver, depositedAmount.Int64(), tx) } if tx.MemoType == "return" { - log.Debug().Str("tx_id", tx.Hash).Msg("transaction has a return memo hash, skipping this transaction") + logger.Debug().Str("tx_id", tx.Hash).Msg("the transaction is being skipped because it contains a return memo") // save cursor cursor := tx.PagingToken() err := bridge.blockPersistency.SaveStellarCursor(cursor) if err != nil { - log.Err(err).Msg("error while saving cursor") - return err + return errors.Wrap(err, "an error occurred while saving stellar cursor") } - log.Info().Msg("stellar cursor saved") return nil } - // if the deposited amount is lower than the depositfee, trigger a refund + // if the deposited amount is lower than the deposit fee, trigger a refund if depositedAmount.Cmp(big.NewInt(bridge.depositFee)) <= 0 { - return bridge.refund(context.Background(), receiver, depositedAmount.Int64(), tx) + ctx = _logger.WithRefundReason(ctx, "insufficient deposit amount to cover fee") + return bridge.refund(ctx, receiver, depositedAmount.Int64(), tx) } destinationSubstrateAddress, err := bridge.getSubstrateAddressFromMemo(tx.Memo) if err != nil { - log.Info().Msgf("error while decoding tx memo: %s", err.Error()) + logger.Debug().Err(err).Msg("there was an issue decoding the memo for the transaction") // memo is not formatted correctly, issue a refund - return bridge.refund(context.Background(), receiver, depositedAmount.Int64(), tx) + ctx = _logger.WithRefundReason(ctx, "memo is not properly formatted") + return bridge.refund(ctx, receiver, depositedAmount.Int64(), tx) } - log.Info().Int64("amount", depositedAmount.Int64()).Str("tx_id", tx.Hash).Msgf("target substrate address to mint on: %s", destinationSubstrateAddress) - accountID, err := substrate.FromAddress(destinationSubstrateAddress) if err != nil { return err @@ -87,11 +101,20 @@ func (bridge *Bridge) mint(ctx context.Context, senders map[string]*big.Int, tx return err } + logger.Info(). + Str("event_action", "mint_proposed"). + Str("event_kind", "event"). + Str("category", "mint"). + Dict("metadata", zerolog.Dict(). + Int64("amount", depositedAmount.Int64()). + Str("tx_id", tx.Hash). + Str("to", destinationSubstrateAddress)). + Msgf("a mint has proposed with the target substrate address of %s", destinationSubstrateAddress) + // save cursor cursor := tx.PagingToken() if err = bridge.blockPersistency.SaveStellarCursor(cursor); err != nil { - log.Err(err).Msgf("error while saving cursor") - return err + return errors.Wrap(err, "an error occurred while saving stellar cursor") } return nil diff --git a/bridge/tfchain_bridge/pkg/bridge/refund.go b/bridge/tfchain_bridge/pkg/bridge/refund.go index ffa2e055a..7efbcfb2b 100644 --- a/bridge/tfchain_bridge/pkg/bridge/refund.go +++ b/bridge/tfchain_bridge/pkg/bridge/refund.go @@ -2,10 +2,14 @@ package bridge import ( "context" + "fmt" + "github.com/pkg/errors" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" hProtocol "github.com/stellar/go/protocols/horizon" "github.com/threefoldtech/tfchain_bridge/pkg" + _logger "github.com/threefoldtech/tfchain_bridge/pkg/logger" subpkg "github.com/threefoldtech/tfchain_bridge/pkg/substrate" ) @@ -22,22 +26,25 @@ func (bridge *Bridge) refund(ctx context.Context, destination string, amount int // save cursor cursor := tx.PagingToken() - log.Info().Msgf("saving cursor now %s", cursor) - if err = bridge.blockPersistency.SaveStellarCursor(cursor); err != nil { - log.Error().Msgf("error while saving cursor: %s", err.Error()) - return err - } - return nil + err = bridge.blockPersistency.SaveStellarCursor(cursor) + // no need to check for err, if err is nil, Wrap returns nil. + return errors.Wrap(err, "an error occurred while saving stellar cursor") } func (bridge *Bridge) handleRefundExpired(ctx context.Context, refundExpiredEvent subpkg.RefundTransactionExpiredEvent) error { + logger := log.Logger.With().Str("trace_id", refundExpiredEvent.Hash).Logger() + refunded, err := bridge.subClient.IsRefundedAlready(refundExpiredEvent.Hash) if err != nil { return err } if refunded { - log.Info().Str("tx_id", refundExpiredEvent.Hash).Msg("tx is refunded already, skipping...") + logger.Info(). + Str("event_action", "refund_skipped"). + Str("event_kind", "event"). + Str("category", "refund"). + Msg("the transaction has already been refunded") return nil } @@ -46,17 +53,35 @@ func (bridge *Bridge) handleRefundExpired(ctx context.Context, refundExpiredEven return err } - return bridge.subClient.RetryCreateRefundTransactionOrAddSig(ctx, refundExpiredEvent.Hash, refundExpiredEvent.Target, int64(refundExpiredEvent.Amount), signature, bridge.wallet.GetKeypair().Address(), sequenceNumber) + err = bridge.subClient.RetryCreateRefundTransactionOrAddSig(ctx, refundExpiredEvent.Hash, refundExpiredEvent.Target, int64(refundExpiredEvent.Amount), signature, bridge.wallet.GetKeypair().Address(), sequenceNumber) + if err != nil { + return err + } + + reason := fmt.Sprint(_logger.GetRefundReason(ctx)) + logger.Info(). + Str("event_action", "refund_proposed"). + Str("event_kind", "event"). + Str("category", "refund"). + Dict("metadata", zerolog.Dict(). + Str("reason", reason)). + Msgf("a refund has proposed due to %s", reason) + return nil } func (bridge *Bridge) handleRefundReady(ctx context.Context, refundReadyEvent subpkg.RefundTransactionReadyEvent) error { + logger := log.Logger.With().Str("trace_id", refundReadyEvent.Hash).Logger() refunded, err := bridge.subClient.IsRefundedAlready(refundReadyEvent.Hash) if err != nil { return err } if refunded { - log.Info().Str("tx_id", refundReadyEvent.Hash).Msg("tx is refunded already, skipping...") + logger.Info(). + Str("event_action", "refund_skipped"). + Str("event_kind", "event"). + Str("category", "refund"). + Msg("the transaction has already been refunded") return pkg.ErrTransactionAlreadyRefunded } @@ -70,5 +95,22 @@ func (bridge *Bridge) handleRefundReady(ctx context.Context, refundReadyEvent su return err } - return bridge.subClient.RetrySetRefundTransactionExecutedTx(ctx, refund.TxHash) + err = bridge.subClient.RetrySetRefundTransactionExecutedTx(ctx, refund.TxHash) + if err != nil { + return err + } + logger.Info(). + Str("event_action", "refund_completed"). + Str("event_kind", "event"). + Str("category", "refund"). + Msg("the transaction has refunded") + logger.Info(). + Str("event_action", "transfer_completed"). + Str("event_kind", "event"). + Str("category", "transfer"). + Dict("metadata", zerolog.Dict(). + Str("outcome", "refunded")). + Msg("the transfer has completed") + + return nil } diff --git a/bridge/tfchain_bridge/pkg/bridge/withdraw.go b/bridge/tfchain_bridge/pkg/bridge/withdraw.go index 0dc82961b..177faeacb 100644 --- a/bridge/tfchain_bridge/pkg/bridge/withdraw.go +++ b/bridge/tfchain_bridge/pkg/bridge/withdraw.go @@ -7,6 +7,7 @@ import ( "math/big" "github.com/centrifuge/go-substrate-rpc-client/v4/types" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" substrate "github.com/threefoldtech/tfchain/clients/tfchain-client-go" "github.com/threefoldtech/tfchain_bridge/pkg" @@ -14,16 +15,31 @@ import ( ) func (bridge *Bridge) handleWithdrawCreated(ctx context.Context, withdraw subpkg.WithdrawCreatedEvent) error { + logger := log.Logger.With().Str("trace_id", fmt.Sprint(withdraw.ID)).Logger() + burned, err := bridge.subClient.IsBurnedAlready(types.U64(withdraw.ID)) if err != nil { return err } if burned { - log.Info().Uint64("ID", uint64(withdraw.ID)).Msgf("tx is burned already, skipping...") + logger.Info(). + Str("event_action", "withdraw_skipped"). + Str("event_kind", "event"). + Str("category", "withdraw"). + Msg("the withdraw transaction has already been processed") return pkg.ErrTransactionAlreadyBurned } + logger.Info(). + Str("event_action", "transfer_initiated"). + Str("event_kind", "event"). + Str("category", "transfer"). + Dict("metadata", zerolog.Dict(). + Str("type", "burn")). + Msg("a transfer has initiated") + + // check if it can hold tft : TODO check trust line TFT limit if it can receive the amount if err := bridge.wallet.CheckAccount(withdraw.Target); err != nil { return bridge.handleBadWithdraw(ctx, withdraw) } @@ -34,17 +50,35 @@ func (bridge *Bridge) handleWithdrawCreated(ctx context.Context, withdraw subpkg } log.Debug().Msgf("stellar account sequence number: %d", sequenceNumber) - return bridge.subClient.RetryProposeWithdrawOrAddSig(ctx, withdraw.ID, withdraw.Target, big.NewInt(int64(withdraw.Amount)), signature, bridge.wallet.GetKeypair().Address(), sequenceNumber) + err = bridge.subClient.RetryProposeWithdrawOrAddSig(ctx, withdraw.ID, withdraw.Target, big.NewInt(int64(withdraw.Amount)), signature, bridge.wallet.GetKeypair().Address(), sequenceNumber) + if err != nil { + return nil + } + + logger.Info(). + Str("event_action", "withdraw_proposed"). + Str("event_kind", "event"). + Str("category", "withdraw"). + Dict("metadata", zerolog.Dict(). + Uint64("amount", withdraw.Amount). + Str("tx_id", fmt.Sprint(withdraw.ID)). + Str("to", withdraw.Target)). + Msgf("a withdraw has proposed with the target stellar address of %s", withdraw.Target) + return nil } func (bridge *Bridge) handleWithdrawExpired(ctx context.Context, withdrawExpired subpkg.WithdrawExpiredEvent) error { + logger := log.Logger.With().Str("trace_id", fmt.Sprint(withdrawExpired.ID)).Logger() + ok, source := withdrawExpired.Source.Unwrap() if !ok { - // log and skip + // log and skip ? FATAL ? + logger.Error().Msg("this should never be triggered unless this bridge release was deployed before the runtime 147 upgrade!") return nil } + // refundable path (starting from tfchain runtime 147) return bridge.handleWithdrawCreated(ctx, subpkg.WithdrawCreatedEvent{ ID: withdrawExpired.ID, Source: source, @@ -54,13 +88,19 @@ func (bridge *Bridge) handleWithdrawExpired(ctx context.Context, withdrawExpired } func (bridge *Bridge) handleWithdrawReady(ctx context.Context, withdrawReady subpkg.WithdrawReadyEvent) error { + logger := log.Logger.With().Str("trace_id", fmt.Sprint(withdrawReady.ID)).Logger() + // ctx_with_trace_id := context.WithValue(ctx, "trace_id", fmt.Sprint(withdrawReady.ID)) burned, err := bridge.subClient.IsBurnedAlready(types.U64(withdrawReady.ID)) if err != nil { return err } if burned { - log.Info().Uint64("ID", uint64(withdrawReady.ID)).Msg("tx is burned already, skipping...") + logger.Info(). + Str("event_action", "withdraw_skipped"). + Str("event_kind", "event"). + Str("category", "withdraw"). + Msg("the withdraw transaction has already been processed") return pkg.ErrTransactionAlreadyBurned } @@ -70,21 +110,32 @@ func (bridge *Bridge) handleWithdrawReady(ctx context.Context, withdrawReady sub } if len(burnTx.Signatures) == 0 { - log.Info().Msg("found 0 signatures, aborting") return pkg.ErrNoSignatures } // todo add memo hash - err = bridge.wallet.CreatePaymentWithSignaturesAndSubmit(ctx, burnTx.Target, uint64(burnTx.Amount), "", burnTx.Signatures, int64(burnTx.SequenceNumber)) + err = bridge.wallet.CreatePaymentWithSignaturesAndSubmit(ctx, burnTx.Target, uint64(burnTx.Amount), fmt.Sprint(withdrawReady.ID), burnTx.Signatures, int64(burnTx.SequenceNumber)) if err != nil { return err } + logger.Info(). + Str("event_action", "withdraw_completed"). + Str("event_kind", "event"). + Str("category", "withdraw"). + Msg("the withdraw has proceed") + logger.Info(). + Str("event_action", "transfer_completed"). + Str("event_kind", "event"). + Str("category", "transfer"). + Dict("metadata", zerolog.Dict(). + Str("outcome", "bridged")). + Msg("the transfer has completed") return bridge.subClient.RetrySetWithdrawExecuted(ctx, withdrawReady.ID) } func (bridge *Bridge) handleBadWithdraw(ctx context.Context, withdraw subpkg.WithdrawCreatedEvent) error { - log.Info().Uint64("ID", uint64(withdraw.ID)).Msg("tx is an invalid burn transaction, minting on chain again...") + logger := log.Logger.With().Str("trace_id", fmt.Sprint(withdraw.ID)).Logger() mintID := fmt.Sprintf("refund-%d", withdraw.ID) minted, err := bridge.subClient.IsMintedAlready(mintID) @@ -95,16 +146,27 @@ func (bridge *Bridge) handleBadWithdraw(ctx context.Context, withdraw subpkg.Wit } if minted { - log.Debug().Str("txHash", mintID).Msg("transaction is already minted") + logger.Info(). + Str("event_action", "mint_skipped"). + Str("event_kind", "event"). + Str("category", "mint"). + Msg("the transaction has already been minted") return pkg.ErrTransactionAlreadyMinted } - log.Info().Str("mintID", mintID).Msg("going to propose mint transaction") err = bridge.subClient.RetryProposeMintOrVote(ctx, mintID, substrate.AccountID(withdraw.Source), big.NewInt(int64(withdraw.Amount))) if err != nil { return err } - log.Info().Uint64("ID", uint64(withdraw.ID)).Msg("setting invalid burn transaction as executed") + logger.Info(). + Str("event_action", "mint_proposed"). + Str("event_kind", "event"). + Str("category", "mint"). + Dict("metadata", zerolog.Dict(). + Int64("amount", int64(withdraw.Amount)). + Str("tx_id", fmt.Sprint(withdraw.ID)). + Str("to", withdraw.Source.ToHexString())). + Msgf("a mint has proposed with the target substrate address of %s", withdraw.Source.ToHexString()) return bridge.subClient.RetrySetWithdrawExecuted(ctx, withdraw.ID) } diff --git a/bridge/tfchain_bridge/pkg/logger/logger.go b/bridge/tfchain_bridge/pkg/logger/logger.go new file mode 100644 index 000000000..43e3201c9 --- /dev/null +++ b/bridge/tfchain_bridge/pkg/logger/logger.go @@ -0,0 +1,41 @@ +package logger + +import ( + "context" + "os" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +const VERSION = 1 + +func InitLogger(isDebug bool) { + log.Logger = zerolog.New(os.Stdout).With().Timestamp().Uint("version", VERSION).Logger() + logLevel := zerolog.InfoLevel + if isDebug { + logLevel = zerolog.DebugLevel + log.Logger = log.Logger.With().Caller().Logger() + } + + zerolog.SetGlobalLevel(logLevel) +} + +type SourceCommonLogEntry struct { + Instance_public_key string + Bridge_wallet_address string + Stellar_network string + Tfchain_url string +} + +type refundReasonKey struct{} + +func WithRefundReason(ctx context.Context, reason string) context.Context { + return context.WithValue(ctx, refundReasonKey{}, reason) +} + +func GetRefundReason(ctx context.Context) string { + return ctx.Value(refundReasonKey{}).(string) +} + +// TODO: event log interfaces diff --git a/bridge/tfchain_bridge/pkg/persistency.go b/bridge/tfchain_bridge/pkg/persistency.go index da5c8d0a0..8d68beee6 100644 --- a/bridge/tfchain_bridge/pkg/persistency.go +++ b/bridge/tfchain_bridge/pkg/persistency.go @@ -3,6 +3,9 @@ package pkg import ( "encoding/json" "os" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" ) type Blockheight struct { @@ -37,7 +40,18 @@ func (b *ChainPersistency) SaveStellarCursor(cursor string) error { } blockheight.StellarCursor = cursor - return b.Save(blockheight) + err = b.Save(blockheight) + if err != nil { + return err + } + log.Debug(). + Str("event_action", "stellar_cursor_saved"). + Str("event_kind", "event"). + Str("category", "persistency"). + Dict("metadata", zerolog.Dict(). + Str("cursor", cursor)). + Msg("the Stellar cursor has been saved") + return nil } func (b *ChainPersistency) GetHeight() (*Blockheight, error) { diff --git a/bridge/tfchain_bridge/pkg/stellar/stellar.go b/bridge/tfchain_bridge/pkg/stellar/stellar.go index 71380146c..6acb1e02d 100644 --- a/bridge/tfchain_bridge/pkg/stellar/stellar.go +++ b/bridge/tfchain_bridge/pkg/stellar/stellar.go @@ -11,6 +11,7 @@ import ( "time" "github.com/pkg/errors" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" "github.com/stellar/go/amount" "github.com/stellar/go/clients/horizonclient" @@ -92,6 +93,8 @@ func (w *StellarWallet) CreatePaymentAndReturnSignature(ctx context.Context, tar } func (w *StellarWallet) CreatePaymentWithSignaturesAndSubmit(ctx context.Context, target string, amount uint64, txHash string, signatures []substrate.StellarSignature, sequenceNumber int64) error { + ctx_with_trace_id := context.WithValue(ctx, "trace_id", txHash) + txnBuild, err := w.generatePaymentOperation(amount, target, sequenceNumber) if err != nil { return err @@ -115,10 +118,11 @@ func (w *StellarWallet) CreatePaymentWithSignaturesAndSubmit(ctx context.Context } } - return w.submitTransaction(ctx, txn) + return w.submitTransaction(ctx_with_trace_id, txn) } func (w *StellarWallet) CreateRefundPaymentWithSignaturesAndSubmit(ctx context.Context, target string, amount uint64, txHash string, signatures []substrate.StellarSignature, sequenceNumber int64) error { + ctx_with_trace_id := context.WithValue(ctx, "trace_id", txHash) txnBuild, err := w.generatePaymentOperation(amount, target, sequenceNumber) if err != nil { return err @@ -152,7 +156,7 @@ func (w *StellarWallet) CreateRefundPaymentWithSignaturesAndSubmit(ctx context.C } } - return w.submitTransaction(ctx, txn) + return w.submitTransaction(ctx_with_trace_id, txn) } func (w *StellarWallet) CreateRefundAndReturnSignature(ctx context.Context, target string, amount uint64, message string) (string, uint64, error) { @@ -215,7 +219,7 @@ func (w *StellarWallet) generatePaymentOperation(amount uint64, destination stri sourceAccount, err := w.getAccountDetails(w.config.StellarBridgeAccount) if err != nil { - return txnbuild.TransactionParams{}, errors.Wrap(err, "failed to get source account") + return txnbuild.TransactionParams{}, errors.Wrap(err, "an error occurred while getting source account details") } asset := w.getAssetCodeAndIssuer() @@ -252,7 +256,7 @@ func (w *StellarWallet) generatePaymentOperation(amount uint64, destination stri func (w *StellarWallet) createTransaction(ctx context.Context, txn txnbuild.TransactionParams, sign bool) (*txnbuild.Transaction, error) { tx, err := txnbuild.NewTransaction(txn) if err != nil { - return nil, errors.Wrap(err, "failed to build transaction") + return nil, errors.Wrap(err, "an error occurred while building the transaction") } if sign { @@ -261,7 +265,7 @@ func (w *StellarWallet) createTransaction(ctx context.Context, txn txnbuild.Tran if hError, ok := err.(*horizonclient.Error); ok { log.Error().Msgf("Error submitting tx %+v", hError.Problem.Extras) } - return nil, errors.Wrap(err, "failed to sign transaction with keypair") + return nil, errors.Wrap(err, "an error occurred while signing the transaction with keypair") } } @@ -271,7 +275,7 @@ func (w *StellarWallet) createTransaction(ctx context.Context, txn txnbuild.Tran func (w *StellarWallet) submitTransaction(ctx context.Context, txn *txnbuild.Transaction) error { client, err := w.getHorizonClient() if err != nil { - return errors.Wrap(err, "failed to get horizon client") + return errors.Wrap(err, "an error occurred while getting horizon client") } // Submit the transaction @@ -287,9 +291,16 @@ func (w *StellarWallet) submitTransaction(ctx context.Context, txn *txnbuild.Tra if errSequence != nil { return errSequence } - return errors.Wrap(err, "error submitting transaction") - } - log.Info().Str("hash", txResult.Hash).Msg("transaction submitted to the stellar network") + return errors.Wrap(err, "an error occurred while submitting the transaction") + } + log.Info(). + Str("trace_id", fmt.Sprint(ctx.Value("trace_id"))). + Str("event_action", "stellar_transaction_submitted"). + Str("event_kind", "event"). + Str("category", "vault"). + Dict("metadata", zerolog.Dict(). + Str("result_tx_id", txResult.ID)). + Msgf("the transaction submitted to the Stellar network, and its unique identifier is %s", txResult.ID) return nil } @@ -353,10 +364,16 @@ func (w *StellarWallet) StreamBridgeStellarTransactions(ctx context.Context, min case <-ctx.Done(): return ctx.Err() default: - log.Info().Str("account", opRequest.ForAccount).Str("horizon", client.HorizonURL).Str("cursor", opRequest.Cursor).Msgf("fetching stellar transactions") response, err := client.Transactions(opRequest) if err != nil { - log.Err(err).Msg("Error getting transactions for stellar account") + log.Logger.Warn(). + Err(err). + Str("event_action", "fetch_transactions_failed"). + Str("event_kind", "alert"). + Str("category", "stellar_monitor"). + Dict("metadata", zerolog.Dict(). + Str("cursor", opRequest.Cursor)). + Msg("encountered an error while retrieving transactions for bridge Stellar account, retrying in 5 sec") select { case <-ctx.Done(): return ctx.Err() @@ -365,6 +382,15 @@ func (w *StellarWallet) StreamBridgeStellarTransactions(ctx context.Context, min } } + log.Logger.Info(). + Str("event_action", "transactions_fetched"). + Str("event_kind", "event"). + Str("category", "stellar_monitor"). + Dict("metadata", zerolog.Dict(). + Str("cursor", opRequest.Cursor). + Int("count", len(response.Embedded.Records))). + Msg("stellar transactions fetched") + for _, tx := range response.Embedded.Records { mintEvents, err := w.processTransaction(tx) if err != nil { @@ -388,15 +414,15 @@ func (w *StellarWallet) StreamBridgeStellarTransactions(ctx context.Context, min } func (w *StellarWallet) processTransaction(tx hProtocol.Transaction) ([]MintEvent, error) { + logger := log.Logger.With().Str("trace_id", tx.ID).Logger() + if !tx.Successful { return nil, nil } - log.Info().Str("hash", tx.Hash).Msg("received transaction on bridge stellar account") effects, err := w.getTransactionEffects(tx.Hash) if err != nil { - log.Error().Str("error while fetching transaction effects:", err.Error()) - return nil, err + return nil, errors.Wrapf(err, "failed to fetch transaction effects for transaction with id is %s", tx.ID) } asset := w.getAssetCodeAndIssuer() @@ -427,23 +453,33 @@ func (w *StellarWallet) processTransaction(tx hProtocol.Transaction) ([]MintEven return nil, nil } - paymentOpation := op.(operations.Payment) - if paymentOpation.To != w.config.StellarBridgeAccount { + PaymentOperation := op.(operations.Payment) + if PaymentOperation.To != w.config.StellarBridgeAccount { continue } - parsedAmount, err := amount.ParseInt64(paymentOpation.Amount) + parsedAmount, err := amount.ParseInt64(PaymentOperation.Amount) if err != nil { continue } depositedAmount := big.NewInt(int64(parsedAmount)) - if _, ok := senders[paymentOpation.From]; !ok { - senders[paymentOpation.From] = depositedAmount + logger.Info(). + Str("event_action", "payment_received"). + Str("event_kind", "event"). + Str("category", "vault"). + Dict("metadata", zerolog.Dict(). + Str("from", PaymentOperation.From). + Str("amount", PaymentOperation.Amount)). + Str("tx_hash", PaymentOperation.TransactionHash). + Str("ledger_close_time", PaymentOperation.LedgerCloseTime.String()). + Msg("a payment has received on bridge Stellar account") + if _, ok := senders[PaymentOperation.From]; !ok { + senders[PaymentOperation.From] = depositedAmount } else { - senderAmount := senders[paymentOpation.From] + senderAmount := senders[PaymentOperation.From] senderAmount = senderAmount.Add(senderAmount, depositedAmount) - senders[paymentOpation.From] = senderAmount + senders[PaymentOperation.From] = senderAmount } } @@ -529,3 +565,19 @@ func (w *StellarWallet) getAssetCodeAndIssuer() []string { return strings.Split(TFTTest, ":") } } + +func (w *StellarWallet) StatBridgeAccount() (string, error) { + acc, err := w.getAccountDetails(w.config.StellarBridgeAccount) + if err != nil { + return "", err + } + + asset := w.getAssetCodeAndIssuer() + + for _, balance := range acc.Balances { + if balance.Code == asset[0] || balance.Issuer == asset[1] { + return balance.Balance, nil + } + } + return "", nil +} diff --git a/bridge/tfchain_bridge/pkg/substrate/events.go b/bridge/tfchain_bridge/pkg/substrate/events.go index 44be57afd..466ac8655 100644 --- a/bridge/tfchain_bridge/pkg/substrate/events.go +++ b/bridge/tfchain_bridge/pkg/substrate/events.go @@ -2,11 +2,15 @@ package substrate import ( "context" + "fmt" + "strings" "time" "github.com/cenkalti/backoff/v4" "github.com/centrifuge/go-substrate-rpc-client/v4/types" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" + "github.com/stellar/go/support/errors" substrate "github.com/threefoldtech/tfchain/clients/tfchain-client-go" ) @@ -60,14 +64,15 @@ type RefundTransactionExpiredEvent struct { } func (client *SubstrateClient) SubscribeTfchainBridgeEvents(ctx context.Context, eventChannel chan<- EventSubscription) error { + cl, _, err := client.GetClient() if err != nil { - log.Fatal().Msg("failed to get client") + return errors.Wrap(err, "an error occurred while getting substrate client") } chainHeadsSub, err := cl.RPC.Chain.SubscribeFinalizedHeads() if err != nil { - log.Fatal().Msg("failed to subscribe to finalized heads") + return errors.Wrap(err, "an error occurred while subscribing to finalized heads") } for { @@ -80,7 +85,6 @@ func (client *SubstrateClient) SubscribeTfchainBridgeEvents(ctx context.Context, } eventChannel <- data case err := <-chainHeadsSub.Err(): - log.Err(err).Msg("error with subscription") bo := backoff.NewExponentialBackOff() bo.MaxElapsedTime = time.Duration(time.Minute * 10) // 10 minutes @@ -88,7 +92,12 @@ func (client *SubstrateClient) SubscribeTfchainBridgeEvents(ctx context.Context, chainHeadsSub, err = cl.RPC.Chain.SubscribeFinalizedHeads() return err }, bo, func(err error, d time.Duration) { - log.Warn().Err(err).Msgf("connection to chain lost, reopening connection in %s", d.String()) + log.Warn(). + Err(err). + Str("event_action", "fetch_finalized_Heads_failed"). + Str("event_kind", "alert"). + Str("category", "tfchain_monitor"). + Msgf("connection to chain lost, reopening connection in %s", d.String()) }) case <-ctx.Done(): @@ -99,16 +108,23 @@ func (client *SubstrateClient) SubscribeTfchainBridgeEvents(ctx context.Context, } func (client *SubstrateClient) processEventsForHeight(height uint32) (Events, error) { - log.Info().Uint32("ID", height).Msg("fetching events for blockheight") + if height == 0 { return Events{}, nil } records, err := client.GetEventsForBlock(height) if err != nil { - log.Err(err).Uint32("ID", height).Msg("failed to decode block for height") - return Events{}, err + return Events{}, errors.Wrapf(err, "an error occurred while decoding events for height %d", height) + } + log.Info(). + Str("event_action", "block_events_fetched"). + Str("event_kind", "event"). + Str("category", "tfchain_monitor"). + Dict("metadata", zerolog.Dict(). + Uint32("height", height)). + Msg("tfchain events fetched") return client.processEventRecords(records), nil } @@ -121,14 +137,24 @@ func (client *SubstrateClient) processEventRecords(events *substrate.EventRecord var withdrawExpiredEvents []WithdrawExpiredEvent for _, e := range events.TFTBridgeModule_RefundTransactionReady { - log.Info().Str("hash", string(e.RefundTransactionHash)).Msg("found refund transaction ready event") + log.Info(). + Str("trace_id", string(e.RefundTransactionHash)). + Str("event_action", "event_refund_tx_ready_received"). + Str("event_kind", "event"). + Str("category", "refund"). + Msg("found RefundTransactionReady event") refundTransactionReadyEvents = append(refundTransactionReadyEvents, RefundTransactionReadyEvent{ Hash: string(e.RefundTransactionHash), }) } for _, e := range events.TFTBridgeModule_RefundTransactionExpired { - log.Info().Str("hash", string(e.RefundTransactionHash)).Msgf("found expired refund transaction") + log.Info(). + Str("trace_id", string(e.RefundTransactionHash)). + Str("event_action", "event_refund_tx_expired_received"). + Str("event_kind", "alert"). + Str("category", "refund"). + Msgf("found RefundTransactionExpired event") refundTransactionExpiredEvents = append(refundTransactionExpiredEvents, RefundTransactionExpiredEvent{ Hash: string(e.RefundTransactionHash), Target: string(e.Target), @@ -137,7 +163,12 @@ func (client *SubstrateClient) processEventRecords(events *substrate.EventRecord } for _, e := range events.TFTBridgeModule_BurnTransactionCreated { - log.Info().Uint64("ID", uint64(e.BurnTransactionID)).Msg("found burn transaction created event") + log.Info(). + Str("trace_id", fmt.Sprint(e.BurnTransactionID)). + Str("event_action", "event_burn_tx_created_received"). + Str("event_kind", "event"). + Str("category", "withdraw"). + Msg("found BurnTransactionCreated event") withdrawCreatedEvents = append(withdrawCreatedEvents, WithdrawCreatedEvent{ ID: uint64(e.BurnTransactionID), Source: e.Source, @@ -147,14 +178,24 @@ func (client *SubstrateClient) processEventRecords(events *substrate.EventRecord } for _, e := range events.TFTBridgeModule_BurnTransactionReady { - log.Info().Uint64("ID", uint64(e.BurnTransactionID)).Msg("found burn transaction ready event") + log.Info(). + Str("trace_id", fmt.Sprint(e.BurnTransactionID)). + Str("event_action", "event_burn_tx_ready_received"). + Str("event_kind", "event"). + Str("category", "withdraw"). + Msg("found BurnTransactionReady event") withdrawReadyEvents = append(withdrawReadyEvents, WithdrawReadyEvent{ ID: uint64(e.BurnTransactionID), }) } for _, e := range events.TFTBridgeModule_BurnTransactionExpired { - log.Info().Uint64("ID", uint64(e.BurnTransactionID)).Msg("found burn transaction expired event") + log.Info(). + Str("trace_id", fmt.Sprint(e.BurnTransactionID)). + Str("event_action", "event_burn_tx_expired_received"). + Str("event_kind", "alert"). + Str("category", "withdraw"). + Msg("found BurnTransactionExpired event") withdrawExpiredEvents = append(withdrawExpiredEvents, WithdrawExpiredEvent{ ID: uint64(e.BurnTransactionID), Source: e.Source, @@ -163,6 +204,31 @@ func (client *SubstrateClient) processEventRecords(events *substrate.EventRecord }) } + for _, e := range events.TFTBridgeModule_MintCompleted { + trace_id := e.TxHash + logger := log.Logger.With().Str("trace_id", strings.TrimLeft(trace_id, "refund-")).Logger() + outcome := "" + if strings.HasPrefix(trace_id, "refund") { + outcome = "refunded" + } else { + outcome = "bridged" + } + + logger.Info(). + Str("event_action", "mint_completed"). + Str("event_kind", "event"). + Str("category", "mint"). + Msg("found MintCompleted event") + + logger.Info(). + Str("event_action", "transfer_completed"). + Str("event_kind", "event"). + Str("category", "transfer"). + Dict("metadata", zerolog.Dict(). + Str("outcome", outcome)). + Msg("transfer has completed") + } + return Events{ WithdrawCreatedEvents: withdrawCreatedEvents, WithdrawReadyEvents: withdrawReadyEvents,