Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closes #2057 by adding extra zrpcunsafe logging #2058

Merged
merged 4 commits into from Feb 2, 2017

Conversation

Projects
None yet
7 participants
@bitcartel
Copy link
Contributor

commented Feb 1, 2017

No description provided.

@bitcartel bitcartel added this to the 1.0.6 milestone Feb 1, 2017

@bitcartel bitcartel requested review from ebfull and nathan-at-least Feb 1, 2017

@bitcartel

This comment has been minimized.

Copy link
Contributor Author

commented Feb 1, 2017

Enable with debug=zrpcunsafe in zcash.conf, or -debug=zrpcunsafe when launching zcashd.
Full opid is now logged, instead of sometimes using a fragment of the opid.
Log messages start with opid, so previous log message async rpc finished (..) now reads opid: finished (..)
Here's what a z_sendmany looks like with zrpcunsafe logging:

2017-02-01 05:58:46 opid-e0184640-3ce0-437d-933a-be05965339dc: starting ({"fromaddress":"ztr4Ef2m7CFTtTvs4UpDz8zJY4Swukr3NRKThfLE12sNdGdav7Yf55G9HMAzGM3baR1FD43u9jb5JsAN67BBvz1UsVdLxoi","amounts":[{"address":"ztZdxLCX7XB6Q7AvYyFgDsqDHkJdcYKjiiwZozEQoiNC5Y1RZNXs341NctNCPkkMb8o3sh9UGzu4BHYMrhUc8RDHpp67zUA","amount":0.00030000}],"minconf":1,"fee":0.00001000})
2017-02-01 05:58:46 opid-e0184640-3ce0-437d-933a-be05965339dc: found unspent note (txid=d3f87622ca, vjoinsplit=0, ciphertext=0, amount=9.82859423, memo=f600000000)
2017-02-01 05:58:46 opid-e0184640-3ce0-437d-933a-be05965339dc: spending 0.00031 to send 0.0003 with fee 0.00001
2017-02-01 05:58:46  -  transparent input: 0.00 (to choose from)
2017-02-01 05:58:46  -      private input: 9.82859423 (to choose from)
2017-02-01 05:58:46  - transparent output: 0.00
2017-02-01 05:58:46  -     private output: 0.0003
2017-02-01 05:58:46  -                fee: 0.00001
2017-02-01 05:58:46 opid-e0184640-3ce0-437d-933a-be05965339dc: spending note (txid=d3f87622ca, vjoinsplit=0, ciphertext=0, amount=9.82859423, height=148, confirmations=1)
2017-02-01 05:58:46 opid-e0184640-3ce0-437d-933a-be05965339dc: generating note for change (amount=9.82828423)
2017-02-01 05:58:46 opid-e0184640-3ce0-437d-933a-be05965339dc: creating joinsplit at index 0 (vpub_old=0.00, vpub_new=0.00001, in[0]=9.82859423, in[1]=0.00, out[0]=0.0003, out[1]=9.82828423)
2017-02-01 05:58:56 Adding fixed seed nodes as DNS doesn't seem to be available.
2017-02-01 05:59:25 AddToWallet f96313af97ba3ca0df1577fb32b36f1815f4e4d0cd0e48e01a4a9eba4b1dca8e  new
2017-02-01 05:59:25 opid-e0184640-3ce0-437d-933a-be05965339dc: finished (status=success, tx=CTransaction(hash=f96313af97, ver=2, vin.size=0, vout.size=0, nLockTime=0)
)
@tromer

This comment has been minimized.

Copy link
Contributor

commented Feb 1, 2017

Let's add the method name z_sendmany to the debug output, to distinguish it from other future async operations (as in #1960, #2024).

Also, seems best for the finished message to include the full hash, not just its prefix. (For example, the explorer.zcha.in can only look up transactions by their full hash.)

@nathan-at-least

This comment has been minimized.

Copy link
Contributor

commented Feb 1, 2017

Concept ACK. I agree w/ both of @tromer's requests. Starting review now.

@nathan-at-least
Copy link
Contributor

left a comment

Two simple requests for change: adding the z_sendmany method name and the full txid to log outputs.

One general testing request: There are no tests for these log outputs. If it's at all feasible to test them, let's do that (even if it's messy). Can you spend a 1 hour timebox seeing if an RPC test could locate the debug log and grep it? If it doesn't seem obviously feasible in one hour, comment on that here, and I consider that good enough effort.

Eventually it would be nice want to be able to make test assertions about log outputs in order to e.g. prevent breaking 'log format contracts' with parsers or to e.g. check for privacy leaks in specific debug modes. That sounds like a somewhat involved test harness task that deserves its own ticket. (So this is not a request for this PR.)


// Log the context info i.e. the call parameters to z_sendmany
if (LogAcceptCategory("zrpcunsafe")) {
LogPrint("zrpcunsafe", "%s: starting (%s)\n", getId(), json_spirit::write_string( contextInfo, false));

This comment has been minimized.

Copy link
@nathan-at-least

nathan-at-least Feb 1, 2017

Contributor

Request for change: Here's where it would be good to add the method name z_sendmany. In the future when we have other long operations, log parsers can distinguish between them.

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

LogPrint("zrpcunsafe", "%s: starting z_sendmany(%s)\n"...

This comment has been minimized.

Copy link
@bitcartel

bitcartel Feb 1, 2017

Author Contributor

Done, but now labelled as 'initialized' since the z_sendmany op is queued and might not start processing for a while.

@@ -134,7 +139,7 @@ void AsyncRPCOperation_sendmany::main() {
set_state(OperationStatus::FAILED);
}

std::string s = strprintf("async rpc %s finished (status=%s", getId(), getStateAsString());
std::string s = strprintf("%s: finished (status=%s", getId(), getStateAsString());
if (success) {
s += strprintf(", tx=%s)\n", tx_.ToString());

This comment has been minimized.

Copy link
@nathan-at-least

nathan-at-least Feb 1, 2017

Contributor

Request for Change: Here's where we want to ensure the full txid is logged. We could either do it here or have a 'verbose mode' of ToString or an alternate method that includes the full txid.

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

Or we just output the txid instead, since that should be sufficient to find the transaction in the local wallet.

This comment has been minimized.

Copy link
@bitcartel

bitcartel Feb 1, 2017

Author Contributor

Done

@str4d
Copy link
Contributor

left a comment

General ACK, but same requests as @nathan-at-least.


// Log the context info i.e. the call parameters to z_sendmany
if (LogAcceptCategory("zrpcunsafe")) {
LogPrint("zrpcunsafe", "%s: starting (%s)\n", getId(), json_spirit::write_string( contextInfo, false));

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

LogPrint("zrpcunsafe", "%s: starting z_sendmany(%s)\n"...

@@ -134,7 +139,7 @@ void AsyncRPCOperation_sendmany::main() {
set_state(OperationStatus::FAILED);
}

std::string s = strprintf("async rpc %s finished (status=%s", getId(), getStateAsString());
std::string s = strprintf("%s: finished (status=%s", getId(), getStateAsString());
if (success) {
s += strprintf(", tx=%s)\n", tx_.ToString());

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

Or we just output the txid instead, since that should be sufficient to find the transaction in the local wallet.

@@ -270,7 +275,7 @@ bool AsyncRPCOperation_sendmany::main_impl() {
}

LogPrint("zrpc", "%s: spending %s to send %s with fee %s\n",
getId().substr(0,10), FormatMoney(targetAmount, false), FormatMoney(sendAmount, false), FormatMoney(minersFee, false));
getId(), FormatMoney(targetAmount, false), FormatMoney(sendAmount, false), FormatMoney(minersFee, false));
LogPrint("zrpc", " - transparent input: %s (to choose from)\n", FormatMoney(t_inputs_total, false));
LogPrint("zrpc", " - private input: %s (to choose from)\n", FormatMoney(z_inputs_total, false));
LogPrint("zrpc", " - transparent output: %s\n", FormatMoney(t_outputs_total, false));

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

Here's an example of info that should probably be in "zrpcunsafe", but that's outside the scope of this PR.

This comment has been minimized.

Copy link
@bitcartel

bitcartel Feb 1, 2017

Author Contributor

Yes we can discuss in another PR with @daira. IIRC from earlier discussions, the zrpc debugging revealed information useful for the sender to debug the transaction that gets built, but it did not link sender and receiver.

@bitcartel

This comment has been minimized.

Copy link
Contributor Author

commented Feb 1, 2017

@ebfull @str4d @nathan-at-least Updated to address review comments. Added debug.log test to existing z_sendmany qa rpc test.

2017-02-01 17:19:15 opid-ae0bb613-7b8c-45aa-81fd-ad7b9decb676: z_sendmany initialized (params={"fromaddress":"ztr4Ef2m7CFTtTvs4UpDz8zJY4Swukr3NRKThfLE12sNdGdav7Yf55G9HMAzGM3baR1FD43u9jb5JsAN67BBvz1UsVdLxoi","amounts":[{"address":"ztZdxLCX7XB6Q7AvYyFgDsqDHkJdcYKjiiwZozEQoiNC5Y1RZNXs341NctNCPkkMb8o3sh9UGzu4BHYMrhUc8RDHpp67zUA","amount":0.00030000}],"minconf":1,"fee":0.00001000}
...
2017-02-01 17:19:58 opid-ae0bb613-7b8c-45aa-81fd-ad7b9decb676: z_sendmany finished (status=success, txid=4565e1f1065c7b6d94801a11d6b52348e09d7e1a2d406b78f01e4b72d5c38deb)

@bitcartel bitcartel requested a review from ebfull Feb 1, 2017

@ebfull

This comment has been minimized.

Copy link
Contributor

commented Feb 1, 2017

Looks good to me!

@ebfull

ebfull approved these changes Feb 1, 2017

@str4d
Copy link
Contributor

left a comment

One requested change, and some log level questions I'd like input from other engineers on.

logcounter = logcounter + 1
if myopid + ": z_sendmany finished" in logline and mytxid in logline:
logcounter = logcounter + 1
assert_equal(logcounter, 2)

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

This test doesn't check that the lines occur in the correct order. I think something like this would work:

initcounter = 0
fincounter = 0
for logline in logdata:
    if myopid + ": z_sendmany initialized" in logline and mytaddr in logline and myzaddr in logline:
        initcounter = initcounter + 1
    if myopid + ": z_sendmany finished" in logline and mytxid in logline:
        assert_equal(initcounter, 1)
        fincounter = fincounter + 1
assert_equal(initcounter, 1)
assert_equal(fincounter, 1)

This comment has been minimized.

Copy link
@bitcartel

bitcartel Feb 1, 2017

Author Contributor

Done.

LogPrint("zrpc", " - fee: %s\n", FormatMoney(minersFee, false));
getId(), FormatMoney(targetAmount, false), FormatMoney(sendAmount, false), FormatMoney(minersFee, false));
LogPrint("zrpc", "%s: - transparent input: %s (to choose from)\n", getId(), FormatMoney(t_inputs_total, false));
LogPrint("zrpc", "%s: - private input: %s (to choose from)\n", getId(), FormatMoney(z_inputs_total, false));

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

Non-blocking: I think this should be zrpcunsafe.

LogPrint("zrpc", "%s: - transparent input: %s (to choose from)\n", getId(), FormatMoney(t_inputs_total, false));
LogPrint("zrpc", "%s: - private input: %s (to choose from)\n", getId(), FormatMoney(z_inputs_total, false));
LogPrint("zrpc", "%s: - transparent output: %s\n", getId(), FormatMoney(t_outputs_total, false));
LogPrint("zrpc", "%s: - private output: %s\n", getId(), FormatMoney(z_outputs_total, false));

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

Non-blocking: I think this should be zrpcunsafe.

@@ -270,12 +277,12 @@ bool AsyncRPCOperation_sendmany::main_impl() {
}

LogPrint("zrpc", "%s: spending %s to send %s with fee %s\n",

This comment has been minimized.

Copy link
@str4d

str4d Feb 1, 2017

Contributor

Non-blocking: I think this might need to be zrpcunsafe, depending on the source/destination (based on my understanding that zrpcunsafe is for anything that logs data which would otherwise be encrypted on the block chain).

This comment has been minimized.

Copy link
@bitcartel

bitcartel Feb 1, 2017

Author Contributor

Filed a PR where we can discuss and modify for 1.0.6 release: #2060

@bitcartel

This comment has been minimized.

Copy link
Contributor Author

commented Feb 1, 2017

@str4d Log order check added.

@str4d

str4d approved these changes Feb 1, 2017

Copy link
Contributor

left a comment

utACK

@nathan-at-least
Copy link
Contributor

left a comment

Source Review Accepted: These changes implement all three of my requests from last review. I haven't done local unit testing, but I'd be satisfied with CI greenlight.

@bitcartel

This comment has been minimized.

Copy link
Contributor Author

commented Feb 2, 2017

@zkbot r+

@zkbot

This comment has been minimized.

Copy link
Collaborator

commented Feb 2, 2017

📌 Commit a45d2ec has been approved by bitcartel

@zkbot

This comment has been minimized.

Copy link
Collaborator

commented Feb 2, 2017

⌛️ Testing commit a45d2ec with merge 59a0b7c...

zkbot added a commit that referenced this pull request Feb 2, 2017

@daira

daira approved these changes Feb 2, 2017

Copy link
Contributor

left a comment

ut(ACK+cov)

@zkbot

This comment has been minimized.

Copy link
Collaborator

commented Feb 2, 2017

☀️ Test successful - zcash

@zkbot zkbot merged commit a45d2ec into zcash:master Feb 2, 2017

1 check passed

homu Test successful
Details
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.