Rethink log levels

[dora-gt]

It seems that some Error level logs are output consistently in tests. I'm not sure it deserves to be called Errors because we are just ignoring the outputs. Error generally means we have to do something immediately to fix it IMO. It might be annoying if we are operating interledger-rs on the production environment because it would be alerted consistently.

So I think we have to rethink and possibly to fix some of log outputs or its logic.

[dora-gt]

Also we definitely need #317.

[emschwartz]

Could you give examples of log lines that you think shouldn't be printed?

[dora-gt]

Here are some examples:

• ERROR interledger_api::routes::accounts: Error creating account. Settlement engine responded with HTTP code: 404 Not Found
• ERROR node_b:api:incoming{request.id=13c9f60e-8c0d-47df-92a2-838d6f35b8a5 prepare.destination=example.parent.a_on_b.alice_on_a.s_Zdm9jyi9L0WWki79YhatPx prepare.amount=2000 from.id=aa510f4d-4543-430e-ba7c-ccc6f6beb6ee}:{from.username=bob_on_b from.ilp_address=example.parent.bob_on_b from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=3118db21-092e-46db-bbed-0f053b7a297c prepare.amount=2000}:{to.username=bob_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_stream::crypto: Error decrypting Unspecified
• [WARN interledger_store::redis] Error handling prepare from account: 20789690-68e9-4e4f-929d-88ff10ea6780: An error was signalled by the server: Error running script (call to f_b1d4df274d7d4b31063b798b9c8f6fcfde1cab01): @user_script:12: user_script:12: Incoming prepare of 10000 would bring account 20789690-68e9-4e4f-929d-88ff10ea6780 under its minimum balance. Current balance: 0, min balance: -1000
  • This might be just a CI setup problem.

[emschwartz]

ERROR interledger_api::routes::accounts: Error creating account. Settlement engine responded with HTTP code: 404 Not Found

That does sound like a problem so it seems like it should either be a warning or error. If that's the expected behavior, is there a way to differentiate between the case where we expect that result and responses like that (that maybe happen later) that would be unexpected and problematic?

interledger_stream::crypto: Error decrypting Unspecified

Can you look into what's causing that? That's a very unhelpful error, but there should be an error logged if there is actually something going wrong.

Error handling prepare from account: 20789690-68e9-4e4f-929d-88ff10ea6780: An error was signalled by the server: Error running script (call to f_b1d4df274d7d4b31063b798b9c8f6fcfde1cab01): @user_script:12: user_script:12: Incoming prepare of 10000 would bring account 20789690-68e9-4e4f-929d-88ff10ea6780 under its minimum balance. Current balance: 0, min balance: -1000

There should be a warning logged when a packet is rejected because it would go below the minimum balance but that message could be a lot shorter and clearer. We should get rid of the part mentioning the redis script and the redundant mention of the account ID.

[georgeroman]

@dora-gt Can you remember why the Error decrypting Unspecified error was triggered? I'm running into the same issue (followed by interledger_stream::server: Unable to parse data, rejecting Prepare packet) and some help debugging it would be helpful.

[dora-gt]

@georgeroman Sorry I don't remember. I wish I had time to dig into but recently I'm very hectic to dedicate to my current project. I'm sorry. If I'm free this weekend, I might be able to.

[georgeroman]

No worries, I’ll look into it by myself and let you know if I manage to address it.

…

On Mon, 20 Jul 2020 at 07:00, Taiga Nakayama ***@***.***> wrote: @georgeroman <https://github.com/georgeroman> Sorry I don't remember. I wish I had time to dig into but recently I'm very hectic to dedicate to my current project. I'm sorry. If I'm free this weekend, I might be able to. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#522 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AHKY5T5AJBBB4JXUKJGIXDTR4O6PPANCNFSM4JP4L5IA> .

[georgeroman]

@dora-gt I just managed to fix the issue. I was issuing a payment involving three ILP nodes (as in the eth-xrp-three-nodes example) but I was only setting the exchange rates for the intermediate connector. Providing exchange rates to all three connectors fixed the issue for me.

[koivunej]

interledger_stream::crypto: Error decrypting Unspecified

Can you look into what's causing that? That's a very unhelpful error, but there should be an error logged if there is actually something going wrong.

Fixed this in #703. It took a few attempts, but eventually I saw that it was just being used to convert into F06 reject which would be handled by the caller by forwarding the request on to the next handler. This got me to notice that all invalid stream packets, even the ones which decrypt successfully, are handled by forwarding them on to next layer. Created #704 for this.

No need to close this issue however as the logging output of interledger-rs would still need some good ideas. At the moment, there are just lot of logs being produced while nodes in multinode tests cannot be identified.