Development feat structured logging #881

sameh-farouk · 2023-10-30T03:40:43Z

Description

Note: Require tfchain Runtime to include the update from another PR

The goal of this PR it to instrument the bridge source code for the sake of improving observability and perform tracing on workflows and data.

For full description and event schema see the the included doc here

Related Issues:

Fixes Bridge: Improved observability for our bridges #874

Checklist:

Please delete options that are not relevant.

My commits follow this conventional commits guide.

muhamadazmy

Over time this gonna be hard to maintain

First read the comments
Second i think it's gonna be really hard to maintain context of operation and error like this.
event_action, event_kind, category are not well defined, they don't have known types and rely on whatever the developer type in. which makes it hard to track and prone to typoes

muhamadazmy · 2023-11-13T10:22:28Z

bridge/tfchain_bridge/main.go

-		zerolog.SetGlobalLevel(zerolog.DebugLevel)
-		log.Debug().Msg("debug mode enabled")
-	}
+	logger.Init_logger(debug)


Init_logger should be InitLogger

muhamadazmy · 2023-11-13T10:23:11Z

bridge/tfchain_bridge/main.go

 	}
+	source_log_entry := logger.SourceCommonLogEntry{


Why using snake case naming in go ? go always uses camelCase

muhamadazmy · 2023-11-13T10:26:05Z

bridge/tfchain_bridge/main.go

+			Str("event_action", "bridge_unexpectedly_exited").
+			Str("event_kind", "error").
+			Str("category", "availability").


Shouldn't this be part of the error context somehow? not printed as strings? May be return some sort of a ErrorContext that implements error then once received an ErrorContext can be downcasted, then the data extracted from it and printed.

The values of the category, event-kind, and action can then be pre-defined constants

muhamadazmy · 2023-11-13T10:30:22Z

bridge/tfchain_bridge/pkg/bridge/mint.go

@@ -23,18 +26,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().


I am not sure if we should log before return every error, or just log when we receive an error. If the caller to mint function now decide to log the returned error we will have double logs.

What I do is that I always log an error if i can't bubble it up more, the error then can have all the information we need to build a detailed log

Otherwise we can endup with the same error printed multiple times

muhamadazmy · 2023-11-13T10:34:43Z

bridge/tfchain_bridge/pkg/bridge/mint.go

@@ -46,37 +61,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 = context.WithValue(ctx, "refund_reason", "no memo in transaction")


this is not a nice way to set (and get) context. typoes and naming conflicts are a problem instead it's ususally done like this

type refundReasonKey struct {} func WithRefundReason(ctx, reason string) Context { return context.WithValue(ctx, refundReasonKey{}, reason) } func GetRefundReason(ctx) string { return context.GetValue(ctx, refundReasonKey{}).(string) }

This makes sure

no key conflict because a key is a type, not a value (actually it's the zero value of a type but 2 zero values of 2 different types don't equal each other)

Clear interface to set, get a reason and reason type is clear

no possible typoes or mistakes

sameh-farouk · 2023-11-14T18:32:27Z

event_action, event_kind, category are not well defined, they don't have known types and rely on whatever the developer type in. which makes it hard to track and prone to typoes

@muhamadazmy
In this iteration, the majority of the effort was spent on designing the events schema and documenting it, complete with examples and use cases. So it may not be undefined as you think. While I acknowledge that it is not enforced yet, prone to errors, and needs to be refactored into an interface, I decided to leave this to the next iteration as it already took longer than expected.

renauter

Great job!!
Very complete and very well documented.
I basically read the documentation and made some formatting remarks.
Implementation seems ok, I guess @muhamadazmy is better placed to evaluate the Go code and I see he already made its comments.
I would also add ADR file since it is an important feature from bridge side.

renauter · 2023-11-22T12:44:02Z

bridge/docs/observability.md

+- `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. 


has been proposed

renauter · 2023-11-22T12:45:00Z

bridge/docs/observability.md

+- `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.


a refund request was skipped

renauter · 2023-11-22T12:45:21Z

bridge/docs/observability.md

+- `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.


has been completed

renauter · 2023-11-22T12:46:47Z

bridge/docs/observability.md

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


You ... It ...

renauter · 2023-11-22T12:48:10Z

bridge/docs/observability.md

+
+### Metrics:
+
+This events describes a numeric measurement taken at given point in time.


These events

renauter · 2023-11-22T13:02:03Z

bridge/docs/observability.md

+| 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` |


event, alert, error, metric

renauter · 2023-11-22T13:05:51Z

bridge/docs/observability.md

+- 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.


event: ...

alert: ...

error: ...

metric: ...

renauter · 2023-11-22T13:06:54Z

bridge/docs/observability.md

+- availability
+- persistency
+- stellar_monitor
+- tfchain_monitor
+- transfer
+- mint
+- refund
+- withdraw
+- vault


availability

persistency

stellar_monitor

tfchain_monitor

transfer

mint

refund

withdraw

vault

renauter · 2023-11-22T13:09:47Z

bridge/docs/observability.md

+- 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.


The source field set contains all fields which are included in the source object. It is common across all types of events except for bridge_init_aborted error event.

renauter · 2023-11-22T13:26:29Z

bridge/docs/observability.md

+##### bridge_init_aborted
+
+- kind: error
+
+- category: availability


I would use this formatting for all event sections below to improve md file readability:

bridge_init_aborted event

kind: error

category: availability

…into development-feat-structured-logging

feat: instrumenting bridge for better observibility and log correlation

c9080e7

sameh-farouk force-pushed the development-feat-structured-logging branch from c2a2538 to c9080e7 Compare October 30, 2023 03:47

sameh-farouk added 9 commits October 30, 2023 14:31

fix: fixing override global logger after configuring it

25b2e7e

feat: making log messages more consistent

d709806

feat: making log messages more consistent

80f3f28

feat: making log messages more consistent

13f271a

fix: use provided context insted of new one

c9c9edb

feat: improvme log schema and log messages

37e5d51

doc: add obeservation and log schema documentaion

c175fb3

doc: minor update

b08dcc9

feat: adding metric for wallet balance

dbac152

sameh-farouk marked this pull request as ready for review November 5, 2023 12:22

sameh-farouk requested review from renauter and LeeSmet as code owners November 5, 2023 12:22

sameh-farouk added 7 commits November 5, 2023 15:06

doc: update observibility doc

01020e2

doc: update observability doc

8883739

doc: fix typo

8c94f53

doc: fix typo

5a0bd64

feat: retrive tx hash from mintCompleted event

d7484ac

doc: add usage examples

a8b5957

doc: revise docs

cf55fd8

muhamadazmy requested changes Nov 13, 2023

View reviewed changes

renauter approved these changes Nov 22, 2023

View reviewed changes

renauter mentioned this pull request Nov 27, 2023

move bridge to threefoldfoundation #899

Open

muhamadazmy approved these changes Dec 14, 2023

View reviewed changes

sameh-farouk added 3 commits December 17, 2023 17:25

avoid naming conflicts in context values + change few names

24081a2

Merge branch 'development' of https://github.com/threefoldtech/tfchain …

13d0fbe

…into development-feat-structured-logging

fix go format

ed5a393

sameh-farouk merged commit 42cf314 into development Dec 18, 2023
2 checks passed

sameh-farouk mentioned this pull request Dec 18, 2023

Bridge daemon exited when a withdrawn transaction fails #878

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Development feat structured logging #881

Development feat structured logging #881

sameh-farouk commented Oct 30, 2023 •

edited

Loading

muhamadazmy left a comment

muhamadazmy Nov 13, 2023

muhamadazmy Nov 13, 2023

muhamadazmy Nov 13, 2023

muhamadazmy Nov 13, 2023

muhamadazmy Nov 13, 2023

sameh-farouk commented Nov 14, 2023

renauter left a comment •

edited

Loading

renauter Nov 22, 2023

renauter Nov 22, 2023

renauter Nov 22, 2023

renauter Nov 22, 2023

renauter Nov 22, 2023

renauter Nov 22, 2023

renauter Nov 22, 2023

renauter Nov 22, 2023

renauter Nov 22, 2023

renauter Nov 22, 2023


		### Metrics:

		This events describes a numeric measurement taken at given point in time.

Development feat structured logging #881

Development feat structured logging #881

Conversation

sameh-farouk commented Oct 30, 2023 • edited Loading

Description

Related Issues:

Checklist:

muhamadazmy left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sameh-farouk commented Nov 14, 2023

renauter left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bridge_init_aborted event

sameh-farouk commented Oct 30, 2023 •

edited

Loading

renauter left a comment •

edited

Loading

`bridge_init_aborted` event