Setup log levels at environment #32

mojoX911 · 2021-08-01T11:19:47Z

Fixes #30 .

This should fix the logging issues.

codecov-commenter · 2021-08-01T11:27:04Z

Codecov Report

Merging #32 (10ee94d) into master (171a386) will decrease coverage by 2.49%.
The diff coverage is 77.03%.

@@            Coverage Diff             @@
##           master      #32      +/-   ##
==========================================
- Coverage   78.71%   76.21%   -2.50%     
==========================================
  Files           8        8              
  Lines        2720     2800      +80     
==========================================
- Hits         2141     2134       -7     
- Misses        579      666      +87

Impacted Files	Coverage Δ
src/maker_protocol.rs	`77.34% <60.27%> (-1.70%)`	⬇️
src/main.rs	`44.17% <88.88%> (+0.81%)`	⬆️
src/taker_protocol.rs	`92.50% <98.11%> (-2.43%)`	⬇️
src/messages.rs	`47.61% <0.00%> (-39.29%)`	⬇️
src/contracts.rs	`83.67% <0.00%> (-2.60%)`	⬇️
src/wallet_sync.rs	`74.06% <0.00%> (-0.62%)`	⬇️
src/offerbook_sync.rs	`82.60% <0.00%> (-0.49%)`	⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 171a386...10ee94d. Read the comment docs.

src/main.rs

GeneFerneau · 2021-08-05T19:00:24Z

Concept + code review ACK 2ba210d

GeneFerneau · 2021-08-13T01:51:50Z

reACK a1c0a5f

chris-belcher · 2021-08-19T14:44:12Z

Please explain why the Once::call_once part is needed? main() and test_standard_coin_swap() will each only get invoked once I think?

Looks good to me though, please squish the commits.

mojoX911 · 2021-08-21T05:36:41Z

Please explain why the Once::call_once part is needed? main() and test_standard_coin_swap() will each only get invoked once I think?

main() will get evoked every time we say teleport do-something. So if we don't have the Once constrain, every time we run the binary the logging setup will try to initialise. This will cause error (in 2nd and subsequent calls of teleport) saying "init() should not be called after initialization". To mitigate that, this is the way to ensure we call init() only once, even though we run the binary multiple times.

mojoX911 · 2021-08-21T05:39:50Z

Rebased and squashed.

chris-belcher · 2021-08-25T17:39:51Z

I did a coinswap on this branch but the makers only printed out a little bit of information, here is an example:

[2021-08-25T16:52:17Z TRACE teleport::maker_protocol] adding incoming_swapcoin contract_tx = Transaction { version: 2, lock_time: 0, input: [TxIn { previous_output: OutPoint { txid: 643f48b0b2ac7183280fda90a2a97af8ba0531f26a73de0623d3c538b6afcb02, vout: 1 }, script_sig: Script(), sequence: 0, witness: [] }], output: [TxOut { value: 132327, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 49570a8bebf763a8593949f2a845665420e8c6ea9a7831ee8af27c8f7a6eccc4) }] } fo = TxOut { value: 133327, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 89949a8f291fd43680e5aecc9417175d88ba2f6bcd2ecf6db593b8fd6f7190b4) }
[2021-08-25T16:52:18Z TRACE teleport::maker_protocol] adding incoming_swapcoin contract_tx = Transaction { version: 2, lock_time: 0, input: [TxIn { previous_output: OutPoint { txid: 60d8cdfd01303110521d13faaaea00b972727cb35adccc1eae9c6acb0e5b2583, vout: 0 }, script_sig: Script(), sequence: 0, witness: [] }], output: [TxOut { value: 206816, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 76b7afe94c2ca7d8a1bba61460a9defef072c84e66d85373b0fba54b1aaf8b79) }] } fo = TxOut { value: 207816, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 8d5d7759bdb6e22e3935089bf3a0812c6dd9f984570f16bf794f5687697160da) }
[2021-08-25T16:52:19Z TRACE teleport::maker_protocol] adding incoming_swapcoin contract_tx = Transaction { version: 2, lock_time: 0, input: [TxIn { previous_output: OutPoint { txid: 0233015f708f581ae2522d5f4ff3237d8ae732cddb8b338312a51ae38e9e509d, vout: 1 }, script_sig: Script(), sequence: 0, witness: [] }], output: [TxOut { value: 157857, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 2ab928fe99745a986a8b3502b4c5402a4ec810f13aa298dfe1aa6f308dd3e20e) }] } fo = TxOut { value: 158857, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 6ee2843734d806afcf9845b4c462b3dc95ca331ac37828246cc5c90a77c2f770) }
[2021-08-25T16:53:17Z TRACE teleport::maker_protocol] timeout branch, accepting clients=true

It's a bit strange to me since I can see in the maker_protocol.rs file the function handle_message has a log::trace! statement, so it should be printing out way more debug information.

mojoX911 · 2021-08-27T06:35:28Z

Huh, that's weird.. Let me get into my debugger, and get back to this.

mojoX911 · 2021-09-03T17:49:26Z

Fixed the bug. Updated logging initialization.

Default logging is info.

Can be changed to other levels by changing this value

teleport-transactions/src/main.rs

Line 357 in 330d56c

.default_filter_or("teleport=info")

to filter specific object in debug log use teleport=debug/<object-name>.

Beyond that I have been playing around with log messages and it seems the info level messages can be refactored to show more readable protocol communication by default. This can be helpful for new devs trying to understand the communication flow.

Updated the info loggings to better reflect communications as they happen. While debug logs include all the object displays in pretty format.

This gives us log displays like below in info mode

[2021-09-03T17:29:27Z INFO  teleport::taker_protocol] ===> [Maker-0:6102] | Sending TakerHello
[2021-09-03T17:29:27Z INFO  teleport::taker_protocol] <=== [Internal:6102] | Received MakerHello
[2021-09-03T17:29:27Z INFO  teleport::taker_protocol] ===> [Maker-0:6102] | Sending Proof of Funding
[2021-09-03T17:29:31Z INFO  teleport::taker_protocol] <=== [Internal] | Recieved SignSendersAndReceiversContractTxes
[2021-09-03T17:29:31Z INFO  teleport::taker_protocol] [Maker-0:Self] | Taker is previous peer. Signing Receivers Contract Txs
[2021-09-03T17:29:31Z INFO  teleport::taker_protocol] ===> [0:16102] Maker-1 is next peer. Requesting to sign Sender's Contract Txs

The Taker logs are structured like [<context>:<peer_port>] | <description>.

Maker Log:

[2021-09-03T17:29:54Z INFO  teleport::maker_protocol] <=== [34058] | Accepted Connection From
[2021-09-03T17:29:54Z INFO  teleport::maker_protocol] ===> [34058] | Sending Maker Hello
[2021-09-03T17:29:54Z INFO  teleport::maker_protocol] <=== [34058] | Recieved TakerHello
[2021-09-03T17:29:54Z INFO  teleport::maker_protocol] <===[34058] | Recieved SignReceiversContractTx
[2021-09-03T17:29:54Z INFO  teleport::maker_protocol] ===> [34058] | Sending ReceiversContractSig
[2021-09-03T17:29:54Z INFO  teleport::maker_protocol] Reached EOF

Maker logs are simple [peer_port] | <description>.

I tried to cover all the message comms, so the flow can be seen.

This unfortunately makes this PR little large. Happy to take it into a new PR if needed.

@chris-belcher @GeneFerneau let me know what you think.

This adds an env_logger and sets it up in main. Its run within a std::sync::Once to ensure its only setup once even though main executes multiple times. Logger will throw error otherwise. Adds logging in the test.

- Logging framework is refactored to categorize loggings into `info`, `debug`, `warn` and `error`. - Default logging level is `info` - Generic Logging format: "===> [Peer Port] | <Description>" - Object details are hidden in `debug` level Objective of more extensive logging is to observe protocol communications in more readable mode. Can be helpful for new devs.

mojoX911 · 2021-09-10T18:23:09Z

Updated with more clean logging.. That context thing for takers wasn't really helpful..

Now the logs are more concise:

$ ../target/debug/teleport --wallet-file-name=taker-wallet coinswap-send
[2021-09-10T18:17:56Z INFO  teleport::taker_protocol] <=== Got Offers
[2021-09-10T18:18:01Z INFO  teleport::taker_protocol] ===> [16102] | Sending SignSendersContractTx
[2021-09-10T18:18:01Z INFO  teleport::taker_protocol] <=== [16102] | Received SendersContractSig
[2021-09-10T18:18:01Z INFO  teleport::taker_protocol] Broadcasting My Funding Tx: 31b76f7f1a32277784b4e3d9b5bc4ded59f29825c26e36d901c2c07178e0e202
[2021-09-10T18:18:01Z INFO  teleport::taker_protocol] Broadcasting My Funding Tx: 504601b7ec5c2062c6cb66d88d8ea2b963abd49d93778d1c8714d8376c1936fe
[2021-09-10T18:18:01Z INFO  teleport::taker_protocol] Broadcasting My Funding Tx: 456bc03dfe355ebdc46129f0fee4d7c52901696cb5b2ede84507cab7f8a78b8b
[2021-09-10T18:18:01Z INFO  teleport::taker_protocol] Waiting for funding Tx to confirm
[2021-09-10T18:18:28Z INFO  teleport::taker_protocol] Funding Transaction confirmed
[2021-09-10T18:18:28Z INFO  teleport::taker_protocol] ===> [16102] | Sending ProofOfFunding
[2021-09-10T18:18:33Z INFO  teleport::taker_protocol] <=== [16102] | Recieved SignSendersAndReceiversContractTxes
[2021-09-10T18:18:33Z INFO  teleport::taker_protocol] Taker is previous peer. Signing Receivers Contract Txs
[2021-09-10T18:18:33Z INFO  teleport::taker_protocol] ===> [6102] | 6102 is next peer. Sending SignSendersContractTx

chris-belcher · 2021-10-06T17:48:18Z

I finally got round to trying this out. Thanks for the PR.

mojoX911 marked this pull request as draft August 1, 2021 11:19

mojoX911 force-pushed the logging-2 branch from 70061fc to 2ba210d Compare August 1, 2021 12:39

mojoX911 marked this pull request as ready for review August 1, 2021 12:39

GeneFerneau reviewed Aug 5, 2021

View reviewed changes

src/main.rs Outdated Show resolved Hide resolved

mojoX911 force-pushed the logging-2 branch from 2ba210d to a1c0a5f Compare August 6, 2021 05:29

mojoX911 force-pushed the logging-2 branch from a1c0a5f to 3ac462d Compare August 21, 2021 05:39

mojoX911 force-pushed the logging-2 branch 2 times, most recently from 2c1b09d to 44a2f21 Compare September 3, 2021 17:56

mojoX911 added 3 commits September 10, 2021 19:57

Adds env_logger

d1ffc26

This adds an env_logger and sets it up in main. Its run within a std::sync::Once to ensure its only setup once even though main executes multiple times. Logger will throw error otherwise. Adds logging in the test.

Fixed Logging initialisation

7920f1f

mojoX911 force-pushed the logging-2 branch from 44a2f21 to 10ee94d Compare September 10, 2021 18:21

chris-belcher merged commit 5f6283e into bitcoin-teleport:master Oct 6, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Setup log levels at environment #32

Setup log levels at environment #32

mojoX911 commented Aug 1, 2021 •

edited

codecov-commenter commented Aug 1, 2021 •

edited

GeneFerneau commented Aug 5, 2021

GeneFerneau commented Aug 13, 2021

chris-belcher commented Aug 19, 2021 •

edited

mojoX911 commented Aug 21, 2021 •

edited

mojoX911 commented Aug 21, 2021

chris-belcher commented Aug 25, 2021

mojoX911 commented Aug 27, 2021

mojoX911 commented Sep 3, 2021

mojoX911 commented Sep 10, 2021

chris-belcher commented Oct 6, 2021

Setup log levels at environment #32

Setup log levels at environment #32

Conversation

mojoX911 commented Aug 1, 2021 • edited

codecov-commenter commented Aug 1, 2021 • edited

Codecov Report

GeneFerneau commented Aug 5, 2021

GeneFerneau commented Aug 13, 2021

chris-belcher commented Aug 19, 2021 • edited

mojoX911 commented Aug 21, 2021 • edited

mojoX911 commented Aug 21, 2021

chris-belcher commented Aug 25, 2021

mojoX911 commented Aug 27, 2021

mojoX911 commented Sep 3, 2021

mojoX911 commented Sep 10, 2021

chris-belcher commented Oct 6, 2021

mojoX911 commented Aug 1, 2021 •

edited

codecov-commenter commented Aug 1, 2021 •

edited

chris-belcher commented Aug 19, 2021 •

edited

mojoX911 commented Aug 21, 2021 •

edited