two_nodes_btp

• Very rarely but reproducible.

Suspicious

[2m2019-10-29T09:38:12.895918+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=8c461135-2958-4bcd-883f-7897e121e143 prepare.destination=example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc prepare.amount=2000 from.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m:[1mforwarding[0m[1m{[0mto.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15 prepare.amount=2000[1m}[0m:[1m[0m[1m{[0mto.username=b_on_a to.asset_code=XYZ to.asset_scale=9[1m}[0m: interledger_btp::service: No open connection for account: 21e40d70-895c-44a2-96a7-9d1ad9d86a15, forwarding request to the next service

Success case log https://github.com/dora-gt/interledger-rs-backyard/blob/master/quality-assurance/issue-%23464/two_nodes_btp_logs/9.log

[2m2019-10-29T09:38:11.088658+00:00 [0m[35mTRACE[0m interledger_btp::service: Got incoming Prepare packet on request ID: 1802866474 Prepare { destination: Address("example.parent.a_on_b.alice_on_a.2sHUyzgUZw7BLNHiniKDpQOyT1r0OCwy4L9_gsD4pBg"), amount: 2000, expires_at: "2019-10-29T09:38:40.083+00:00", execution_condition: "e0bad12bb1e0f7e4c9e34a21122579b654fbf4763f4e6bbbbdd64d9ef0446951", data_length: 68 }    
[2m2019-10-29T09:38:11.088903+00:00 [0m[35mTRACE[0m interledger_btp::service: Handling incoming request 1802866474 from account: b_on_a (id: a13227c6-36cf-4b8f-aff9-a7cde3c3e365)    
[2m2019-10-29T09:38:11.089297+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=0d20b5c7-38c5-4017-9d08-8dfba2c3bdc5 prepare.destination=example.parent.a_on_b.alice_on_a.2sHUyzgUZw7BLNHiniKDpQOyT1r0OCwy4L9_gsD4pBg prepare.amount=2000 from.id=a13227c6-36cf-4b8f-aff9-a7cde3c3e365[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m: interledger_router::router: Found matching route for address: "example.parent.a_on_b.alice_on_a.2sHUyzgUZw7BLNHiniKDpQOyT1r0OCwy4L9_gsD4pBg". Prefix: "example.parent.a_on_b.alice_on_a", account: d83e9f90-91e1-4e33-9e6e-15531b5bd1ee    
[2m2019-10-29T09:38:11.091801+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=0d20b5c7-38c5-4017-9d08-8dfba2c3bdc5 prepare.destination=example.parent.a_on_b.alice_on_a.2sHUyzgUZw7BLNHiniKDpQOyT1r0OCwy4L9_gsD4pBg prepare.amount=2000 from.id=a13227c6-36cf-4b8f-aff9-a7cde3c3e365[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m:[1mforwarding[0m[1m{[0mto.id=d83e9f90-91e1-4e33-9e6e-15531b5bd1ee prepare.amount=2000[1m}[0m:[1m[0m[1m{[0mto.username=b_on_a to.asset_code=XYZ to.asset_scale=9[1m}[0m: interledger_service_util::exchange_rates_service: Converted incoming amount of: 2000 XYZ (scale 9) from account a13227c6-36cf-4b8f-aff9-a7cde3c3e365 to outgoing amount of: 2000 XYZ (scale 9) for account d83e9f90-91e1-4e33-9e6e-15531b5bd1ee    
[2m2019-10-29T09:38:11.092532+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=0d20b5c7-38c5-4017-9d08-8dfba2c3bdc5 prepare.destination=example.parent.a_on_b.alice_on_a.2sHUyzgUZw7BLNHiniKDpQOyT1r0OCwy4L9_gsD4pBg prepare.amount=2000 from.id=a13227c6-36cf-4b8f-aff9-a7cde3c3e365[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m:[1mforwarding[0m[1m{[0mto.id=d83e9f90-91e1-4e33-9e6e-15531b5bd1ee prepare.amount=2000[1m}[0m:[1m[0m[1m{[0mto.username=b_on_a to.asset_code=XYZ to.asset_scale=9[1m}[0m: interledger_store_redis::store: Processed prepare with incoming amount: 2000. Account a13227c6-36cf-4b8f-aff9-a7cde3c3e365 has balance (including prepaid amount): -1000     
[2m2019-10-29T09:38:11.092839+00:00 [0m[34mDEBUG[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=0d20b5c7-38c5-4017-9d08-8dfba2c3bdc5 prepare.destination=example.parent.a_on_b.alice_on_a.2sHUyzgUZw7BLNHiniKDpQOyT1r0OCwy4L9_gsD4pBg prepare.amount=2000 from.id=a13227c6-36cf-4b8f-aff9-a7cde3c3e365[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m:[1mforwarding[0m[1m{[0mto.id=d83e9f90-91e1-4e33-9e6e-15531b5bd1ee prepare.amount=2000[1m}[0m:[1m[0m[1m{[0mto.username=b_on_a to.asset_code=XYZ to.asset_scale=9[1m}[0m: interledger_stream::server: Fulfilling prepare for amount 2000 with fulfillment: 55cfdb60ed858f562f3d5e58e4ca4ddc0a9424a2c66765142894143fdc2417b8 and encrypted stream packet: StreamPacket { sequence: 1, ilp_packet_type: Fulfill, prepare_amount: 2000, frames: [ StreamMaxMoneyFrame { stream_id: 1, receive_max: 18446744073709551615, total_received: 0 } ] }

Failure case log https://github.com/dora-gt/interledger-rs-backyard/blob/master/quality-assurance/issue-%23464/two_nodes_btp_logs/10.log

[2m2019-10-29T09:38:12.891695+00:00 [0m[35mTRACE[0m interledger_btp::service: Got incoming Prepare packet on request ID: 2456425636 Prepare { destination: Address("example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc"), amount: 2000, expires_at: "2019-10-29T09:38:41.886+00:00", execution_condition: "5067804647c93916c707d2edec18c3c72d9b4cf6bcae9671500acf13f6da058b", data_length: 68 }    
[2m2019-10-29T09:38:12.891934+00:00 [0m[35mTRACE[0m interledger_btp::service: Handling incoming request 2456425636 from account: b_on_a (id: 21e40d70-895c-44a2-96a7-9d1ad9d86a15)    
[2m2019-10-29T09:38:12.892285+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=8c461135-2958-4bcd-883f-7897e121e143 prepare.destination=example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc prepare.amount=2000 from.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m: interledger_router::router: Found matching route for address: "example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc". Prefix: "example.parent.a_on_b.alice_on_a", account: 21e40d70-895c-44a2-96a7-9d1ad9d86a15    
[2m2019-10-29T09:38:12.894877+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=8c461135-2958-4bcd-883f-7897e121e143 prepare.destination=example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc prepare.amount=2000 from.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m:[1mforwarding[0m[1m{[0mto.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15 prepare.amount=2000[1m}[0m:[1m[0m[1m{[0mto.username=b_on_a to.asset_code=XYZ to.asset_scale=9[1m}[0m: interledger_service_util::exchange_rates_service: Converted incoming amount of: 2000 XYZ (scale 9) from account 21e40d70-895c-44a2-96a7-9d1ad9d86a15 to outgoing amount of: 2000 XYZ (scale 9) for account 21e40d70-895c-44a2-96a7-9d1ad9d86a15    
[2m2019-10-29T09:38:12.895662+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=8c461135-2958-4bcd-883f-7897e121e143 prepare.destination=example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc prepare.amount=2000 from.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m:[1mforwarding[0m[1m{[0mto.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15 prepare.amount=2000[1m}[0m:[1m[0m[1m{[0mto.username=b_on_a to.asset_code=XYZ to.asset_scale=9[1m}[0m: interledger_store_redis::store: Processed prepare with incoming amount: 2000. Account 21e40d70-895c-44a2-96a7-9d1ad9d86a15 has balance (including prepaid amount): -1000     
[2m2019-10-29T09:38:12.895918+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=8c461135-2958-4bcd-883f-7897e121e143 prepare.destination=example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc prepare.amount=2000 from.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m:[1mforwarding[0m[1m{[0mto.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15 prepare.amount=2000[1m}[0m:[1m[0m[1m{[0mto.username=b_on_a to.asset_code=XYZ to.asset_scale=9[1m}[0m: interledger_btp::service: No open connection for account: 21e40d70-895c-44a2-96a7-9d1ad9d86a15, forwarding request to the next service    

It seems that incoming request is being forwrded to the same account...?

[2m2019-10-29T09:38:12.892285+00:00 [0m[35mTRACE[0m [1mnode_a[0m:[1mbtp[0m:[1mincoming[0m[1m{[0mrequest.id=8c461135-2958-4bcd-883f-7897e121e143 prepare.destination=example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc prepare.amount=2000 from.id=21e40d70-895c-44a2-96a7-9d1ad9d86a15[1m}[0m:[1m[0m[1m{[0mfrom.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9[1m}[0m: interledger_router::router: Found matching route for address: "example.parent.a_on_b.alice_on_a.0PaNXH-rmwzw87jpA4wLvtUrVKaFLkivJ0yLWGMJAAc". Prefix: "example.parent.a_on_b.alice_on_a", account: 21e40d70-895c-44a2-96a7-9d1ad9d86a15    

In the faulure case, the account b_on_a is 21e40d70-895c-44a2-96a7-9d1ad9d86a15, and the incoming packet for alice_on_a is routed to account 21e40d70-895c-44a2-96a7-9d1ad9d86a15. This is strange.

• Setting new route for prefix: example.parent.a_on_b.alice_on_a -> Account: b_on_a

[2m2019-10-29T09:38:12.870194+00:00 [0m[34mDEBUG[0m interledger_ccp::server: Setting new route for prefix: example.parent.a_on_b.alice_on_a -> Account: b_on_a (id: 21e40d70-895c-44a2-96a7-9d1ad9d86a15) 

example.parent.a_on_b.alice_on_a is routed to b_on_a?? As the result, the routing table gets broken.

[2m2019-10-29T09:38:12.872139+00:00 [0m[35mTRACE[0m interledger_store_redis::store: Routing table is: {b"example.parent": AccountId(21e40d70-895c-44a2-96a7-9d1ad9d86a15), b"": AccountId(21e40d70-895c-44a2-96a7-9d1ad9d86a15), b"example.parent.a_on_b.alice_on_a": AccountId(21e40d70-895c-44a2-96a7-9d1ad9d86a15), b"local.host.b_on_a": AccountId(21e40d70-895c-44a2-96a7-9d1ad9d86a15), b"local.host.alice_on_a": AccountId(30c2bd51-32d9-45c2-aee5-1fee7744ad18)}

It should be like:

Setting new route for prefix: example.parent.a_on_b.alice_on_a -> Account: alice_on_a (id: d83e9f90-91e1-4e33-9e6e-15531b5bd1ee) 

---

This is strange because at this point, it should know local.host.b_on_a is example.parent.

[2m2019-10-30T05:23:37.423822+00:00 [0m[35mTRACE[0m interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: Some(AccountId(6672869f-0319-44e1-97f3-961f4a1fe6a7)), other routes: [("local.host.b_on_a", AccountId(6672869f-0319-44e1-97f3-961f4a1fe6a7)), ("example.parent.a_on_b.alice_on_a", AccountId(6013ac52-7f19-4c44-af2c-c898b0de625a))]