Setup log levels at environment

[mojoX911]

Fixes #30 .

This should fix the logging issues.

[codecov-commenter]

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%)	:arrow_down:
src/main.rs	44.17% <88.88%> (+0.81%)	:arrow_up:
src/taker_protocol.rs	92.50% <98.11%> (-2.43%)	:arrow_down:
src/messages.rs	47.61% <0.00%> (-39.29%)	:arrow_down:
src/contracts.rs	83.67% <0.00%> (-2.60%)	:arrow_down:
src/wallet_sync.rs	74.06% <0.00%> (-0.62%)	:arrow_down:
src/offerbook_sync.rs	82.60% <0.00%> (-0.49%)	:arrow_down:

---

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.

[GeneFerneau]

Concept + code review ACK 2ba210d

[GeneFerneau]

reACK a1c0a5f

[chris-belcher]

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]

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]

Rebased and squashed.

[chris-belcher]

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]

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

[mojoX911]

Fixed the bug. Updated logging initialization.

Default logging is info.

Can be changed to other levels by changing this value https://github.com/bitcoin-teleport/teleport-transactions/blob/330d56c63d790b9c2d1ea16085c8998857c66ed2/src/main.rs#L357

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.

[mojoX911]

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]

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