search

interledger / interledger-rs

An easy-to-use, high-performance Interledger implementation written in Rust
http://interledger.rs
Other
198 stars 70 forks source link

`two_nodes_btp` is unstable #464

Open dora-gt opened 4 years ago

dora-gt commented 4 years ago

It seems that two_nodes_btp test is unstable.

When it failed, I just reran. https://circleci.com/gh/interledger-rs/interledger-rs/2641 Then it succeeded. https://circleci.com/gh/interledger-rs/interledger-rs/2642

It might be worth changing `expect("xxxx")' to investigate a bit more.

dora-gt commented 4 years ago

memo

thread 'tokio-runtime-worker-11' panicked at 'assertion failed: `(left == right)`
  left: `0`,
 right: `2`', crates/ilp-node/tests/three_nodes.rs:221:33
stack backtrace:
emschwartz commented 4 years ago

I'm not sure why the packet said it timed out but STREAM should retry on R00 errors https://github.com/interledger-rs/interledger-rs/issues/467

dora-gt commented 4 years ago

Err: () ... 😭 https://circleci.com/gh/interledger-rs/interledger-rs/2720

---- two_nodes_btp stdout ----
Error executing tests: ()
thread 'two_nodes_btp' panicked at 'called `Result::unwrap()` on an `Err` value: ()', src/libcore/result.rs:1084:5
emschwartz commented 4 years ago

@dora-gt that's that same R00 error:

[DEBUG interledger_stream::client] Prepare 1 with amount 2000 was rejected with code: R00 (2000 left to send)
dora-gt commented 4 years ago

Ahhhh I see but it seems strange enough to take about 30secs to send a payment even if it should retry then. I'm wondering why.

[INFO  warp::filters::log] 127.0.0.1:39062 "POST /accounts/bob_on_b/payments HTTP/1.1" 500 "-" "reqwest/0.9.22" 27.019914015s
emschwartz commented 4 years ago

@dora-gt can this be closed now?

dora-gt commented 4 years ago

Yes, I'm closing.

I'm wondering whether the three_nodes test is failing because of the same reason. Let's see if it is solved as well. I'll open another issue if that still happens.

dora-gt commented 4 years ago

I'm reopening this, I'm not sure what is the cause but it is failing again.

https://circleci.com/gh/interledger-rs/interledger-rs/3562?utm_campaign=vcs-integration-link&utm_medium=referral&utm_source=github-build-link

error detail ``` running 1 test 2019-11-12T03:01:09.827626867+00:00 DEBUG interledger-node: Starting Interledger node with ILP address: local.host 2019-11-12T03:01:09.828718396+00:00 DEBUG node_a: interledger_store_redis::store: Connected subscription client to redis: Client { connection_info: ConnectionInfo { addr: Unix("/tmp/redis-rs-test-8501404627386110010-9821656944019440599.sock"), db: 1, passwd: None } } 2019-11-12T03:01:09.832662304+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: None, other routes: [] 2019-11-12T03:01:09.832766875+00:00 TRACE interledger_store_redis::store: Routing table is: {} 2019-11-12T03:01:09.840367261+00:00 DEBUG interledger-node: Starting Interledger node with ILP address: example.parent 2019-11-12T03:01:09.841094136+00:00 DEBUG node_b: interledger_store_redis::store: Connected subscription client to redis: Client { connection_info: ConnectionInfo { addr: Unix("/tmp/redis-rs-test-8501404627386110010-9821656944019440599.sock"), db: 2, passwd: None } } 2019-11-12T03:01:09.844539444+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: None, other routes: [] 2019-11-12T03:01:09.844633034+00:00 TRACE interledger_store_redis::store: Routing table is: {} 2019-11-12T03:01:09.849764107+00:00 INFO node_a: interledger-node: Interledger.rs node HTTP API listening on: 127.0.0.1:3010 2019-11-12T03:01:09.849940259+00:00 INFO node_a: interledger-node: Settlement API listening on: 127.0.0.1:3011 2019-11-12T03:01:09.850033252+00:00 DEBUG node_a: interledger-node: Not using exchange rate provider. Rates must be set via the HTTP API 2019-11-12T03:01:09.858567941+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:09.858649018+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:09.859620704+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:09.863942357+00:00 INFO node_b: interledger-node: Interledger.rs node HTTP API listening on: 127.0.0.1:3020 2019-11-12T03:01:09.864142743+00:00 INFO node_b: interledger-node: Settlement API listening on: 127.0.0.1:3021 2019-11-12T03:01:09.864260066+00:00 DEBUG node_b: interledger-node: Not using exchange rate provider. Rates must be set via the HTTP API 2019-11-12T03:01:09.867424399+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:09.867500306+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:09.868146714+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:10.058288373+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.058387204+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.058994709+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:10.067862633+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.067959597+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.068541819+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:10.258809084+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.258911618+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.259470236+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:10.267727293+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.267815858+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.268316312+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:10.349524663+00:00 DEBUG interledger_store_redis::store: Generated account id for bob_on_b: d8a75691-1ed1-45e9-b387-4554ac193be5 2019-11-12T03:01:10.351452945+00:00 DEBUG interledger_store_redis::store: Generated account id for a_on_b: d1cb8eca-a743-478d-a5da-9cf7324f8895 2019-11-12T03:01:10.352043813+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: None, other routes: [("example.parent.bob_on_b", AccountId(d8a75691-1ed1-45e9-b387-4554ac193be5))] 2019-11-12T03:01:10.352198691+00:00 TRACE interledger_store_redis::store: Routing table is: {"example.parent.bob_on_b": AccountId(d8a75691-1ed1-45e9-b387-4554ac193be5)} 2019-11-12T03:01:10.352299367+00:00 DEBUG interledger_store_redis::store: Inserted account d8a75691-1ed1-45e9-b387-4554ac193be5 (ILP address: example.parent.bob_on_b) 2019-11-12T03:01:10.353418618+00:00 INFO interledger-api: 127.0.0.1:59832 "POST /accounts HTTP/1.1" 200 "-" "reqwest/0.9.22" 9.576885ms 2019-11-12T03:01:10.353588069+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: None, other routes: [("example.parent.bob_on_b", AccountId(d8a75691-1ed1-45e9-b387-4554ac193be5)), ("example.parent.a_on_b", AccountId(d1cb8eca-a743-478d-a5da-9cf7324f8895))] 2019-11-12T03:01:10.353701964+00:00 TRACE interledger_store_redis::store: Routing table is: {"example.parent.a_on_b": AccountId(d1cb8eca-a743-478d-a5da-9cf7324f8895), "example.parent.bob_on_b": AccountId(d8a75691-1ed1-45e9-b387-4554ac193be5)} 2019-11-12T03:01:10.353785939+00:00 DEBUG interledger_store_redis::store: Inserted account d1cb8eca-a743-478d-a5da-9cf7324f8895 (ILP address: example.parent.a_on_b) 2019-11-12T03:01:10.355157216+00:00 INFO interledger-api: 127.0.0.1:59830 "POST /accounts HTTP/1.1" 200 "-" "reqwest/0.9.22" 11.373496ms 2019-11-12T03:01:10.361072847+00:00 DEBUG interledger_store_redis::store: Generated account id for b_on_a: b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.363407184+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: None, other routes: [("local.host.b_on_a", AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634))] 2019-11-12T03:01:10.363513282+00:00 TRACE interledger_store_redis::store: Routing table is: {"local.host.b_on_a": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)} 2019-11-12T03:01:10.363573579+00:00 DEBUG interledger_store_redis::store: Inserted account b744f931-ef6c-4e5b-81e5-47bd12415634 (ILP address: local.host.b_on_a) 2019-11-12T03:01:10.363653417+00:00 TRACE interledger_api::routes::accounts: Newly inserted account has a BTP URL configured, will try to connect 2019-11-12T03:01:10.363750701+00:00 DEBUG interledger_btp::client: Connecting to ws://localhost:3020/ilp/btp 2019-11-12T03:01:10.364418164+00:00 DEBUG interledger_store_redis::store: Generated account id for alice_on_a: bb783990-a81d-4091-ba57-feba75acf5ac 2019-11-12T03:01:10.365657941+00:00 INFO interledger-api: 127.0.0.1:59840 "GET /ilp/btp HTTP/1.1" 101 "-" "-" 292.594µs 2019-11-12T03:01:10.366018109+00:00 TRACE interledger_btp::client: Connected to account b744f931-ef6c-4e5b-81e5-47bd12415634 (URI: ws://localhost:3020/ilp/btp), sending auth packet 2019-11-12T03:01:10.366291791+00:00 DEBUG interledger_btp::client: Connected to account b744f931-ef6c-4e5b-81e5-47bd12415634's server 2019-11-12T03:01:10.366523189+00:00 DEBUG interledger_api::routes::accounts: Getting ILP address from parent account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:10.367053842+00:00 TRACE node_a:outgoing{request.id=568d12ac-7e7b-4a84-bd35-bf4790a015c0 prepare.destination=peer.config from.id=b744f931-ef6c-4e5b-81e5-47bd12415634 to.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9 to.username=b_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::expiry_shortener_service: Shortening packet expiry duration to 30000ms in the future 2019-11-12T03:01:10.367209752+00:00 TRACE node_a:outgoing{request.id=568d12ac-7e7b-4a84-bd35-bf4790a015c0 prepare.destination=peer.config from.id=b744f931-ef6c-4e5b-81e5-47bd12415634 to.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9 to.username=b_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: No open connection for account: b744f931-ef6c-4e5b-81e5-47bd12415634, forwarding request to the next service 2019-11-12T03:01:10.367284111+00:00 TRACE node_a:outgoing{request.id=568d12ac-7e7b-4a84-bd35-bf4790a015c0 prepare.destination=peer.config from.id=b744f931-ef6c-4e5b-81e5-47bd12415634 to.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9 to.username=b_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 3252660993 to account b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.371145653+00:00 DEBUG interledger_btp::server: Got BTP connection for username: a_on_b 2019-11-12T03:01:10.377753304+00:00 DEBUG interledger_btp::server: Added connection for account a_on_b: (id: d1cb8eca-a743-478d-a5da-9cf7324f8895) 2019-11-12T03:01:10.377941244+00:00 DEBUG interledger_btp::service: Unable to parse ILP packet from BTP packet (if this is the first time this appears, the packet was probably the auth response) 2019-11-12T03:01:10.378400271+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 3252660993 Prepare { destination: Address("peer.config"), amount: 0, expires_at: "2019-11-12T03:01:40.367+00:00", execution_condition: "66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925", data_length: 0 } 2019-11-12T03:01:10.378645255+00:00 TRACE interledger_btp::service: Handling incoming request 3252660993 from account: a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895) 2019-11-12T03:01:10.379060366+00:00 DEBUG node_b:btp:incoming{request.id=c284162a-c934-4a95-b7a7-104f1bf09f89 prepare.destination=peer.config prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}: interledger_ildcp::server: Responding to query for ildcp info by account: Address("example.parent.a_on_b") 2019-11-12T03:01:10.379217502+00:00 INFO node_b:btp:incoming{request.id=c284162a-c934-4a95-b7a7-104f1bf09f89 prepare.destination=peer.config prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.379883030+00:00 TRACE interledger_btp::service: Got fulfill response to request id 3252660993 2019-11-12T03:01:10.380429244+00:00 INFO node_a:outgoing{request.id=568d12ac-7e7b-4a84-bd35-bf4790a015c0 prepare.destination=peer.config from.id=b744f931-ef6c-4e5b-81e5-47bd12415634 to.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9 to.username=b_on_a to.asset_code=XYZ to.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.380906249+00:00 DEBUG interledger_api::routes::accounts: Got ILDCP response from parent: Ok(IldcpResponse { ilp_address: "Address("example.parent.a_on_b")", asset_code: "XYZ", asset_scale: 9 }) 2019-11-12T03:01:10.380977025+00:00 DEBUG interledger_api::routes::accounts: ILP address is now: example.parent.a_on_b 2019-11-12T03:01:10.381151467+00:00 DEBUG interledger_api::routes::accounts: Asking for routes from Account { id: AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), username: Username("b_on_a"), ilp_address: Address("local.host.b_on_a"), asset_code: "XYZ", asset_scale: 9, max_packet_amount: 18446744073709551615, min_balance: None, ilp_over_http_url: None, ilp_over_http_incoming_token: None, ilp_over_http_outgoing_token: None, ilp_over_btp_url: Some("btp+ws://localhost:3020/ilp/btp"), ilp_over_btp_incoming_token: None, ilp_over_btp_outgoing_token: Some(SecretBytes(...)), settle_threshold: None, settle_to: None, routing_relation: Parent, round_trip_time: 500, packets_per_minute_limit: None, amount_per_minute_limit: None, settlement_engine_url: None } 2019-11-12T03:01:10.381309460+00:00 DEBUG interledger_store_redis::store: Setting ILP address to: example.parent.a_on_b 2019-11-12T03:01:10.381614338+00:00 TRACE node_a:outgoing{request.id=bb190df4-3d6e-42e7-a1c1-950b10bae679 prepare.destination=peer.route.control from.id=b744f931-ef6c-4e5b-81e5-47bd12415634 to.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9 to.username=b_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::expiry_shortener_service: Shortening packet expiry duration to 30000ms in the future 2019-11-12T03:01:10.381760143+00:00 TRACE node_a:outgoing{request.id=bb190df4-3d6e-42e7-a1c1-950b10bae679 prepare.destination=peer.route.control from.id=b744f931-ef6c-4e5b-81e5-47bd12415634 to.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9 to.username=b_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: No open connection for account: b744f931-ef6c-4e5b-81e5-47bd12415634, forwarding request to the next service 2019-11-12T03:01:10.381835899+00:00 TRACE node_a:outgoing{request.id=bb190df4-3d6e-42e7-a1c1-950b10bae679 prepare.destination=peer.route.control from.id=b744f931-ef6c-4e5b-81e5-47bd12415634 to.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9 to.username=b_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 99154104 to account b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.382516955+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 99154104 Prepare { destination: Address("peer.route.control"), amount: 0, expires_at: "2019-11-12T03:01:40.381+00:00", execution_condition: "66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925", data_length: 23 } 2019-11-12T03:01:10.382743528+00:00 TRACE interledger_btp::service: Handling incoming request 99154104 from account: a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895) 2019-11-12T03:01:10.383262954+00:00 DEBUG node_b:btp:incoming{request.id=fc332cbe-d9d2-459d-a394-a172b9dbd19a prepare.destination=peer.route.control prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Got route control request from account a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895): RouteControlRequest { mode: Sync, last_known_routing_table_id: "00000000000000000000000000000000", last_known_epoch: 0, features: [] } 2019-11-12T03:01:10.383406088+00:00 TRACE node_b:btp:incoming{request.id=fc332cbe-d9d2-459d-a394-a172b9dbd19a prepare.destination=peer.route.control prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Checking whether account was previously listed as unavailable 2019-11-12T03:01:10.383622646+00:00 DEBUG node_b:btp:incoming{request.id=fc332cbe-d9d2-459d-a394-a172b9dbd19a prepare.destination=peer.route.control prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Sending individual route update to account: d1cb8eca-a743-478d-a5da-9cf7324f8895 for epochs from: 0 to: 0 2019-11-12T03:01:10.383881312+00:00 TRACE node_b:btp:incoming{request.id=fc332cbe-d9d2-459d-a394-a172b9dbd19a prepare.destination=peer.route.control prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:outgoing{request.id=07e407b4-5323-438a-b047-4c20fb57acac prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::expiry_shortener_service: Shortening packet expiry duration to 30000ms in the future 2019-11-12T03:01:10.384101862+00:00 TRACE node_b:btp:incoming{request.id=fc332cbe-d9d2-459d-a394-a172b9dbd19a prepare.destination=peer.route.control prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:outgoing{request.id=07e407b4-5323-438a-b047-4c20fb57acac prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 1962254189 to account d1cb8eca-a743-478d-a5da-9cf7324f8895 2019-11-12T03:01:10.384572299+00:00 INFO node_b:btp:incoming{request.id=fc332cbe-d9d2-459d-a394-a172b9dbd19a prepare.destination=peer.route.control prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.384765452+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 1962254189 Prepare { destination: Address("peer.route.update"), amount: 0, expires_at: "2019-11-12T03:01:40.383+00:00", execution_condition: "66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925", data_length: 102 } 2019-11-12T03:01:10.384948847+00:00 TRACE interledger_btp::service: Handling incoming request 1962254189 from account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:10.385049598+00:00 TRACE interledger_btp::service: Got fulfill response to request id 99154104 2019-11-12T03:01:10.385407665+00:00 INFO node_a:outgoing{request.id=bb190df4-3d6e-42e7-a1c1-950b10bae679 prepare.destination=peer.route.control from.id=b744f931-ef6c-4e5b-81e5-47bd12415634 to.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9 to.username=b_on_a to.asset_code=XYZ to.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.385814694+00:00 DEBUG node_a:btp:incoming{request.id=81fead7e-850c-4e9a-8b32-67730614d796 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Got route update request from account b744f931-ef6c-4e5b-81e5-47bd12415634: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 0, from_epoch_index: 0, to_epoch_index: 0, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [Route { prefix: "example.parent", path: [], auth: "0000000000000000000000000000000000000000000000000000000000000000", props: [] }], withdrawn_routes: [] } 2019-11-12T03:01:10.386001830+00:00 WARN node_a:btp:incoming{request.id=81fead7e-850c-4e9a-8b32-67730614d796 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Got route for a different global prefix: Route { prefix: "example.parent", path: [], auth: "0000000000000000000000000000000000000000000000000000000000000000", props: [] } 2019-11-12T03:01:10.386176497+00:00 TRACE node_a:btp:incoming{request.id=81fead7e-850c-4e9a-8b32-67730614d796 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Got heartbeat route update for table ID: e3a20ce40dae70eb51e6a2959329ce81, epoch: 0 2019-11-12T03:01:10.386294236+00:00 TRACE node_a:btp:incoming{request.id=81fead7e-850c-4e9a-8b32-67730614d796 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Updated routing table e3a20ce40dae70eb51e6a2959329ce81 to epoch: 0 2019-11-12T03:01:10.386394308+00:00 TRACE node_a:btp:incoming{request.id=81fead7e-850c-4e9a-8b32-67730614d796 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Route update request did not contain any prefixes we need to update our routes for 2019-11-12T03:01:10.386564260+00:00 INFO node_a:btp:incoming{request.id=81fead7e-850c-4e9a-8b32-67730614d796 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.387627680+00:00 TRACE interledger_btp::service: Got fulfill response to request id 1962254189 2019-11-12T03:01:10.387950190+00:00 INFO node_b:btp:incoming{request.id=fc332cbe-d9d2-459d-a394-a172b9dbd19a prepare.destination=peer.route.control prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:outgoing{request.id=07e407b4-5323-438a-b047-4c20fb57acac prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.406418919+00:00 DEBUG interledger_store_redis::store: Set default route to account id: b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.407597946+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: Some(AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), other routes: [("local.host.b_on_a", AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), ("local.host.alice_on_a", AccountId(bb783990-a81d-4091-ba57-feba75acf5ac))] 2019-11-12T03:01:10.407721262+00:00 TRACE interledger_store_redis::store: Routing table is: {"": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "local.host.b_on_a": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "local.host.alice_on_a": AccountId(bb783990-a81d-4091-ba57-feba75acf5ac)} 2019-11-12T03:01:10.407807869+00:00 DEBUG interledger_store_redis::store: Inserted account bb783990-a81d-4091-ba57-feba75acf5ac (ILP address: local.host.alice_on_a) 2019-11-12T03:01:10.408585247+00:00 INFO interledger-api: 127.0.0.1:35120 "POST /accounts HTTP/1.1" 200 "-" "reqwest/0.9.22" 49.582372ms 2019-11-12T03:01:10.412161613+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: Some(AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), other routes: [("local.host.b_on_a", AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), ("local.host.alice_on_a", AccountId(bb783990-a81d-4091-ba57-feba75acf5ac))] 2019-11-12T03:01:10.412277910+00:00 TRACE interledger_store_redis::store: Routing table is: {"": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "local.host.b_on_a": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "local.host.alice_on_a": AccountId(bb783990-a81d-4091-ba57-feba75acf5ac)} 2019-11-12T03:01:10.412688804+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: Some(AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), other routes: [("local.host.b_on_a", AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), ("local.host.alice_on_a", AccountId(bb783990-a81d-4091-ba57-feba75acf5ac))] 2019-11-12T03:01:10.412777736+00:00 TRACE interledger_store_redis::store: Routing table is: {"local.host.b_on_a": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "local.host.alice_on_a": AccountId(bb783990-a81d-4091-ba57-feba75acf5ac)} 2019-11-12T03:01:10.413046553+00:00 INFO interledger-api: 127.0.0.1:35122 "POST /accounts HTTP/1.1" 200 "-" "reqwest/0.9.22" 54.007158ms 2019-11-12T03:01:10.463232125+00:00 DEBUG interledger_ccp::server: Setting new route for prefix: example.parent.a_on_b -> Account: a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895) 2019-11-12T03:01:10.463405965+00:00 DEBUG interledger_ccp::server: Setting new route for prefix: example.parent.bob_on_b -> Account: bob_on_b (id: d8a75691-1ed1-45e9-b387-4554ac193be5) 2019-11-12T03:01:10.464240541+00:00 TRACE interledger_store_redis::store: Saved 2 routes to Redis 2019-11-12T03:01:10.464892879+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: None, other routes: [("example.parent.bob_on_b", AccountId(d8a75691-1ed1-45e9-b387-4554ac193be5)), ("example.parent.a_on_b", AccountId(d1cb8eca-a743-478d-a5da-9cf7324f8895))] 2019-11-12T03:01:10.464998097+00:00 TRACE interledger_store_redis::store: Routing table is: {"example.parent.a_on_b": AccountId(d1cb8eca-a743-478d-a5da-9cf7324f8895), "example.parent.bob_on_b": AccountId(d8a75691-1ed1-45e9-b387-4554ac193be5)} 2019-11-12T03:01:10.465086034+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.465131369+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.465495329+00:00 DEBUG interledger_ccp::server: Changing ILP address from local.host to example.parent.a_on_b 2019-11-12T03:01:10.467812852+00:00 TRACE interledger_ccp::server: Sending route update for epochs 0 - 1 to accounts: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 0, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [Route { prefix: "example.parent", path: [], auth: "0000000000000000000000000000000000000000000000000000000000000000", props: [] }], withdrawn_routes: [] } a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895, ilp_address: example.parent.a_on_b) 2019-11-12T03:01:10.468143802+00:00 TRACE node_b:outgoing{request.id=01c6de0c-bc77-43ab-95bb-f9c17ea0ebc5 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::expiry_shortener_service: Shortening packet expiry duration to 30000ms in the future 2019-11-12T03:01:10.468367577+00:00 TRACE node_b:outgoing{request.id=01c6de0c-bc77-43ab-95bb-f9c17ea0ebc5 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 2758960264 to account d1cb8eca-a743-478d-a5da-9cf7324f8895 2019-11-12T03:01:10.469484486+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 2758960264 Prepare { destination: Address("peer.route.update"), amount: 0, expires_at: "2019-11-12T03:01:40.468+00:00", execution_condition: "66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925", data_length: 102 } 2019-11-12T03:01:10.469785430+00:00 TRACE interledger_btp::service: Handling incoming request 2758960264 from account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:10.470191020+00:00 DEBUG node_a:btp:incoming{request.id=bd56c591-3248-458a-b998-0c4a78c9d260 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Got route update request from account b744f931-ef6c-4e5b-81e5-47bd12415634: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 0, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [Route { prefix: "example.parent", path: [], auth: "0000000000000000000000000000000000000000000000000000000000000000", props: [] }], withdrawn_routes: [] } 2019-11-12T03:01:10.470448542+00:00 TRACE node_a:btp:incoming{request.id=bd56c591-3248-458a-b998-0c4a78c9d260 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Updated routing table e3a20ce40dae70eb51e6a2959329ce81 to epoch: 1 2019-11-12T03:01:10.470565279+00:00 DEBUG node_a:btp:incoming{request.id=bd56c591-3248-458a-b998-0c4a78c9d260 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Recalculating best routes for prefixes: example.parent 2019-11-12T03:01:10.470871014+00:00 INFO node_a:btp:incoming{request.id=bd56c591-3248-458a-b998-0c4a78c9d260 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.471494003+00:00 TRACE interledger_btp::service: Got fulfill response to request id 2758960264 2019-11-12T03:01:10.471831014+00:00 INFO node_b:outgoing{request.id=01c6de0c-bc77-43ab-95bb-f9c17ea0ebc5 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.472019039+00:00 TRACE interledger_ccp::server: Updating unavailable accounts 2019-11-12T03:01:10.474323030+00:00 DEBUG interledger_ccp::server: Setting new route for prefix: local.host.b_on_a -> Account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:10.474467703+00:00 DEBUG interledger_ccp::server: Setting new route for prefix: local.host.alice_on_a -> Account: alice_on_a (id: bb783990-a81d-4091-ba57-feba75acf5ac) 2019-11-12T03:01:10.475438136+00:00 TRACE interledger_store_redis::store: Saved 2 routes to Redis 2019-11-12T03:01:10.476204910+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: Some(AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), other routes: [("local.host.alice_on_a", AccountId(bb783990-a81d-4091-ba57-feba75acf5ac)), ("local.host.b_on_a", AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634))] 2019-11-12T03:01:10.476312304+00:00 TRACE interledger_store_redis::store: Routing table is: {"local.host.b_on_a": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "local.host.alice_on_a": AccountId(bb783990-a81d-4091-ba57-feba75acf5ac)} 2019-11-12T03:01:10.476396676+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.476441099+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.477059347+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:10.479414777+00:00 DEBUG interledger_ccp::server: Setting new route for prefix: example.parent -> Account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:10.480315656+00:00 TRACE interledger_store_redis::store: Saved 3 routes to Redis 2019-11-12T03:01:10.481074718+00:00 TRACE interledger_store_redis::store: Loaded routes from redis. Static routes: [], default route: Some(AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), other routes: [("local.host.b_on_a", AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)), ("local.host.alice_on_a", AccountId(bb783990-a81d-4091-ba57-feba75acf5ac)), ("example.parent", AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634))] 2019-11-12T03:01:10.481186346+00:00 TRACE interledger_store_redis::store: Routing table is: {"local.host.b_on_a": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "local.host.alice_on_a": AccountId(bb783990-a81d-4091-ba57-feba75acf5ac), "example.parent": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634), "": AccountId(b744f931-ef6c-4e5b-81e5-47bd12415634)} 2019-11-12T03:01:10.661591783+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.661683095+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.664265706+00:00 TRACE interledger_ccp::server: Sending route update for epochs 1 - 1 to accounts: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 1, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [], withdrawn_routes: [] } a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895, ilp_address: example.parent.a_on_b) 2019-11-12T03:01:10.664539876+00:00 TRACE node_b:outgoing{request.id=e32e2c5c-19e5-479b-81b6-ad8e1754c0fe prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::expiry_shortener_service: Shortening packet expiry duration to 30000ms in the future 2019-11-12T03:01:10.664704408+00:00 TRACE node_b:outgoing{request.id=e32e2c5c-19e5-479b-81b6-ad8e1754c0fe prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 2964785266 to account d1cb8eca-a743-478d-a5da-9cf7324f8895 2019-11-12T03:01:10.665533715+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 2964785266 Prepare { destination: Address("peer.route.update"), amount: 0, expires_at: "2019-11-12T03:01:40.664+00:00", execution_condition: "66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925", data_length: 51 } 2019-11-12T03:01:10.665712361+00:00 TRACE interledger_btp::service: Handling incoming request 2964785266 from account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:10.666055007+00:00 DEBUG node_a:btp:incoming{request.id=26284935-7202-4d98-9867-9f9f91ef0b60 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Got route update request from account b744f931-ef6c-4e5b-81e5-47bd12415634: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 1, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [], withdrawn_routes: [] } 2019-11-12T03:01:10.666181878+00:00 TRACE node_a:btp:incoming{request.id=26284935-7202-4d98-9867-9f9f91ef0b60 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Got heartbeat route update for table ID: e3a20ce40dae70eb51e6a2959329ce81, epoch: 1 2019-11-12T03:01:10.666272652+00:00 TRACE node_a:btp:incoming{request.id=26284935-7202-4d98-9867-9f9f91ef0b60 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Updated routing table e3a20ce40dae70eb51e6a2959329ce81 to epoch: 1 2019-11-12T03:01:10.666340001+00:00 TRACE node_a:btp:incoming{request.id=26284935-7202-4d98-9867-9f9f91ef0b60 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Route update request did not contain any prefixes we need to update our routes for 2019-11-12T03:01:10.666459256+00:00 INFO node_a:btp:incoming{request.id=26284935-7202-4d98-9867-9f9f91ef0b60 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.667019468+00:00 TRACE interledger_btp::service: Got fulfill response to request id 2964785266 2019-11-12T03:01:10.667364929+00:00 INFO node_b:outgoing{request.id=e32e2c5c-19e5-479b-81b6-ad8e1754c0fe prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.667558042+00:00 TRACE interledger_ccp::server: Updating unavailable accounts 2019-11-12T03:01:10.670443430+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.670508887+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.671217491+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:10.860842121+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.860939851+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.863492143+00:00 TRACE interledger_ccp::server: Sending route update for epochs 1 - 1 to accounts: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 1, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [], withdrawn_routes: [] } a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895, ilp_address: example.parent.a_on_b) 2019-11-12T03:01:10.863820443+00:00 TRACE node_b:outgoing{request.id=27097af1-a568-41e0-8c2f-6c6ad7a71573 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::expiry_shortener_service: Shortening packet expiry duration to 30000ms in the future 2019-11-12T03:01:10.863981606+00:00 TRACE node_b:outgoing{request.id=27097af1-a568-41e0-8c2f-6c6ad7a71573 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 2009413858 to account d1cb8eca-a743-478d-a5da-9cf7324f8895 2019-11-12T03:01:10.864616297+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 2009413858 Prepare { destination: Address("peer.route.update"), amount: 0, expires_at: "2019-11-12T03:01:40.863+00:00", execution_condition: "66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925", data_length: 51 } 2019-11-12T03:01:10.864837695+00:00 TRACE interledger_btp::service: Handling incoming request 2009413858 from account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:10.865155447+00:00 DEBUG node_a:btp:incoming{request.id=b5bd071b-e068-4fa1-942f-a9d808067d3c prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Got route update request from account b744f931-ef6c-4e5b-81e5-47bd12415634: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 1, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [], withdrawn_routes: [] } 2019-11-12T03:01:10.865305327+00:00 TRACE node_a:btp:incoming{request.id=b5bd071b-e068-4fa1-942f-a9d808067d3c prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Got heartbeat route update for table ID: e3a20ce40dae70eb51e6a2959329ce81, epoch: 1 2019-11-12T03:01:10.865379474+00:00 TRACE node_a:btp:incoming{request.id=b5bd071b-e068-4fa1-942f-a9d808067d3c prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Updated routing table e3a20ce40dae70eb51e6a2959329ce81 to epoch: 1 2019-11-12T03:01:10.865439711+00:00 TRACE node_a:btp:incoming{request.id=b5bd071b-e068-4fa1-942f-a9d808067d3c prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Route update request did not contain any prefixes we need to update our routes for 2019-11-12T03:01:10.865561427+00:00 INFO node_a:btp:incoming{request.id=b5bd071b-e068-4fa1-942f-a9d808067d3c prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.866073908+00:00 TRACE interledger_btp::service: Got fulfill response to request id 2009413858 2019-11-12T03:01:10.866325092+00:00 INFO node_b:outgoing{request.id=27097af1-a568-41e0-8c2f-6c6ad7a71573 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.866455837+00:00 TRACE interledger_ccp::server: Updating unavailable accounts 2019-11-12T03:01:10.870368542+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:10.870435617+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:10.871065329+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:10.934932157+00:00 TRACE interledger_spsp::client: Converted payment pointer: http://localhost:3020/accounts/bob_on_b/spsp to URL: http://localhost:3020/accounts/bob_on_b/spsp 2019-11-12T03:01:10.935017792+00:00 TRACE interledger_spsp::client: Querying receiver: http://localhost:3020/accounts/bob_on_b/spsp 2019-11-12T03:01:10.946537768+00:00 DEBUG interledger_stream::server: Generated address: example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc 2019-11-12T03:01:10.946626121+00:00 DEBUG interledger_spsp::server: Generated address and secret for: Address("example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc") 2019-11-12T03:01:10.946800461+00:00 INFO interledger-api: 127.0.0.1:59898 "GET /accounts/bob_on_b/spsp HTTP/1.1" 200 "-" "reqwest/0.9.22" 4.478744ms 2019-11-12T03:01:10.948934177+00:00 DEBUG interledger_spsp::client: Sending SPSP payment to address: example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc 2019-11-12T03:01:10.949496463+00:00 DEBUG node_a:api:incoming{request.id=0a69a9c6-47a3-42d9-8762-0218f9fe716d prepare.destination=peer.config prepare.amount=0 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ildcp::server: Responding to query for ildcp info by account: Address("local.host.alice_on_a") 2019-11-12T03:01:10.949633296+00:00 INFO node_a:api:incoming{request.id=0a69a9c6-47a3-42d9-8762-0218f9fe716d prepare.destination=peer.config prepare.amount=0 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:10.949896887+00:00 DEBUG interledger_ildcp::client: Got ILDCP response: IldcpResponse { ilp_address: "Address("local.host.alice_on_a")", asset_code: "XYZ", asset_scale: 9 } 2019-11-12T03:01:10.949967739+00:00 WARN interledger_stream::client: Destination ILP address starts with a different scheme prefix ("example') than ours ("local'), this probably isn't going to work 2019-11-12T03:01:10.950092397+00:00 DEBUG interledger_stream::client: Sending packet 1 with amount: 1000 and encrypted STREAM packet: StreamPacket { sequence: 1, ilp_packet_type: Prepare, prepare_amount: 0, frames: [ StreamMoneyFrame { stream_id: 1, shares: 1 }, ConnectionNewAddressFrame { source_account: local.host.alice_on_a } ] } 2019-11-12T03:01:10.950247809+00:00 DEBUG interledger_stream::congestion: Prepare packet of 1000, amount in flight is now: 1000 2019-11-12T03:01:10.950548646+00:00 TRACE node_a:api:incoming{request.id=c9383554-dd63-47bb-a838-eaa78b677fb0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_router::router: Found matching route for address: "example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc". Prefix: "example.parent", account: b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.955963561+00:00 TRACE node_a:api:incoming{request.id=c9383554-dd63-47bb-a838-eaa78b677fb0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=b744f931-ef6c-4e5b-81e5-47bd12415634 prepare.amount=1000}:{to.username=alice_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::exchange_rates_service: Converted incoming amount of: 1000 XYZ (scale 9) from account bb783990-a81d-4091-ba57-feba75acf5ac to outgoing amount of: 1000 XYZ (scale 9) for account b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.958000815+00:00 TRACE node_a:api:incoming{request.id=c9383554-dd63-47bb-a838-eaa78b677fb0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=b744f931-ef6c-4e5b-81e5-47bd12415634 prepare.amount=1000}:{to.username=alice_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_store_redis::store: Processed prepare with incoming amount: 1000. Account bb783990-a81d-4091-ba57-feba75acf5ac has balance (including prepaid amount): -1000 2019-11-12T03:01:10.958249150+00:00 TRACE node_a:api:incoming{request.id=c9383554-dd63-47bb-a838-eaa78b677fb0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=b744f931-ef6c-4e5b-81e5-47bd12415634 prepare.amount=1000}:{to.username=alice_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: No open connection for account: b744f931-ef6c-4e5b-81e5-47bd12415634, forwarding request to the next service 2019-11-12T03:01:10.958424784+00:00 TRACE node_a:api:incoming{request.id=c9383554-dd63-47bb-a838-eaa78b677fb0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=b744f931-ef6c-4e5b-81e5-47bd12415634 prepare.amount=1000}:{to.username=alice_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 1714927557 to account b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.959546468+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 1714927557 Prepare { destination: Address("example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc"), amount: 1000, expires_at: "2019-11-12T03:01:39.950+00:00", execution_condition: "3df513c41386de80069f6eb95fad70a2928ab379ba25874d944f9a14e98eb9af", data_length: 66 } 2019-11-12T03:01:10.959806674+00:00 TRACE interledger_btp::service: Handling incoming request 1714927557 from account: a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895) 2019-11-12T03:01:10.960168238+00:00 TRACE node_b:btp:incoming{request.id=33bb9807-7dd4-41cf-a233-17c5c65da3f2 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}: interledger_router::router: Found matching route for address: "example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc". Prefix: "example.parent.bob_on_b", account: d8a75691-1ed1-45e9-b387-4554ac193be5 2019-11-12T03:01:10.962900630+00:00 TRACE node_b:btp:incoming{request.id=33bb9807-7dd4-41cf-a233-17c5c65da3f2 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=d8a75691-1ed1-45e9-b387-4554ac193be5 prepare.amount=1000}:{to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::exchange_rates_service: Converted incoming amount of: 1000 XYZ (scale 9) from account d1cb8eca-a743-478d-a5da-9cf7324f8895 to outgoing amount of: 1000 XYZ (scale 9) for account d8a75691-1ed1-45e9-b387-4554ac193be5 2019-11-12T03:01:10.963500791+00:00 TRACE node_b:btp:incoming{request.id=33bb9807-7dd4-41cf-a233-17c5c65da3f2 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=d8a75691-1ed1-45e9-b387-4554ac193be5 prepare.amount=1000}:{to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_store_redis::store: Processed prepare with incoming amount: 1000. Account d1cb8eca-a743-478d-a5da-9cf7324f8895 has balance (including prepaid amount): -1000 2019-11-12T03:01:10.963746074+00:00 DEBUG node_b:btp:incoming{request.id=33bb9807-7dd4-41cf-a233-17c5c65da3f2 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=d8a75691-1ed1-45e9-b387-4554ac193be5 prepare.amount=1000}:{to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_stream::server: Fulfilling prepare for amount 1000 with fulfillment: 52b15c67e799f9adc1c4ab2f46142eb9fcae6298bbd6a7acdca4866581d0e2b7 and encrypted stream packet: StreamPacket { sequence: 1, ilp_packet_type: Fulfill, prepare_amount: 1000, frames: [ StreamMaxMoneyFrame { stream_id: 1, receive_max: 18446744073709551615, total_received: 0 }, ConnectionAssetDetailsFrame { source_asset_code: "XYZ", source_asset_scale: 9 } ] } 2019-11-12T03:01:10.964289623+00:00 INFO node_b:btp:incoming{request.id=33bb9807-7dd4-41cf-a233-17c5c65da3f2 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:{fulfillment=52b15c67e799f9adc1c4ab2f46142eb9fcae6298bbd6a7acdca4866581d0e2b7}: interledger-node: result="fulfill" 2019-11-12T03:01:10.964836137+00:00 DEBUG interledger_store_redis::store: Publishing payment notification {"to_username":"bob_on_b","from_username":"a_on_b","destination":"example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc","amount":1000,"timestamp":"2019-11-12T03:01:10.963864224+00:00"} for account d8a75691-1ed1-45e9-b387-4554ac193be5 2019-11-12T03:01:10.964945794+00:00 TRACE interledger_btp::service: Got fulfill response to request id 1714927557 2019-11-12T03:01:10.965438865+00:00 INFO node_a:api:incoming{request.id=c9383554-dd63-47bb-a838-eaa78b677fb0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=1000 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:{fulfillment=52b15c67e799f9adc1c4ab2f46142eb9fcae6298bbd6a7acdca4866581d0e2b7}: interledger-node: result="fulfill" 2019-11-12T03:01:10.965570448+00:00 DEBUG interledger_stream::congestion: Fulfilled packet of 1000, doubling max in flight to: 2000 time,max_amount_in_flight,amount_fulfilled 1573527670965,2000,1000 2019-11-12T03:01:10.965707018+00:00 DEBUG interledger_stream::client: Prepare 1 with amount 1000 was fulfilled (0 left to send) 2019-11-12T03:01:10.965859121+00:00 DEBUG interledger_stream::client: Closing connection 2019-11-12T03:01:10.965897772+00:00 TRACE interledger_store_redis::store: Processed fulfill for account d8a75691-1ed1-45e9-b387-4554ac193be5 for outgoing amount 1000. Fulfill call result: 1000 0 2019-11-12T03:01:10.965986984+00:00 DEBUG interledger_service_util::balance_service: Account balance after fulfill: 1000. Amount that needs to be settled: 0 2019-11-12T03:01:10.966229203+00:00 TRACE node_a:api:incoming{request.id=495fe198-6c0e-43b7-984d-c2a42edd93b0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=0 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_router::router: Found matching route for address: "example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc". Prefix: "example.parent", account: b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.967006075+00:00 TRACE interledger_store_redis::store: Processed fulfill for account b744f931-ef6c-4e5b-81e5-47bd12415634 for outgoing amount 1000. Fulfill call result: 1000 0 2019-11-12T03:01:10.967094430+00:00 DEBUG interledger_service_util::balance_service: Account balance after fulfill: 1000. Amount that needs to be settled: 0 2019-11-12T03:01:10.972123700+00:00 TRACE interledger_store_redis::store: Subscribed message received for account d8a75691-1ed1-45e9-b387-4554ac193be5: PaymentNotification { to_username: Username("bob_on_b"), from_username: Username("a_on_b"), destination: Address("example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc"), amount: 1000, timestamp: "2019-11-12T03:01:10.963864224+00:00" } 2019-11-12T03:01:10.972220371+00:00 TRACE interledger_store_redis::store: Ignoring message for account d8a75691-1ed1-45e9-b387-4554ac193be5 because there were no open subscriptions 2019-11-12T03:01:10.972316777+00:00 TRACE interledger_store_redis::store: Subscribed message received for account d8a75691-1ed1-45e9-b387-4554ac193be5: PaymentNotification { to_username: Username("bob_on_b"), from_username: Username("a_on_b"), destination: Address("example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc"), amount: 1000, timestamp: "2019-11-12T03:01:10.963864224+00:00" } 2019-11-12T03:01:10.972439214+00:00 TRACE interledger_store_redis::store: Ignoring message for account d8a75691-1ed1-45e9-b387-4554ac193be5 because there were no open subscriptions 2019-11-12T03:01:10.972585224+00:00 TRACE node_a:api:incoming{request.id=495fe198-6c0e-43b7-984d-c2a42edd93b0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=0 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=b744f931-ef6c-4e5b-81e5-47bd12415634 prepare.amount=0}:{to.username=alice_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: No open connection for account: b744f931-ef6c-4e5b-81e5-47bd12415634, forwarding request to the next service 2019-11-12T03:01:10.972773913+00:00 TRACE node_a:api:incoming{request.id=495fe198-6c0e-43b7-984d-c2a42edd93b0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=0 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=b744f931-ef6c-4e5b-81e5-47bd12415634 prepare.amount=0}:{to.username=alice_on_a to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 3915783816 to account b744f931-ef6c-4e5b-81e5-47bd12415634 2019-11-12T03:01:10.973528058+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 3915783816 Prepare { destination: Address("example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc"), amount: 0, expires_at: "2019-11-12T03:01:39.965+00:00", execution_condition: "2e2588046134956d73525d50f165ef4b4430b7a73e8461a1405783914e42bb87", data_length: 40 } 2019-11-12T03:01:10.973735541+00:00 TRACE interledger_btp::service: Handling incoming request 3915783816 from account: a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895) 2019-11-12T03:01:10.974170236+00:00 TRACE node_b:btp:incoming{request.id=2470551a-1ac9-4685-9213-c58d7ee6884b prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}: interledger_router::router: Found matching route for address: "example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc". Prefix: "example.parent.bob_on_b", account: d8a75691-1ed1-45e9-b387-4554ac193be5 2019-11-12T03:01:10.976421501+00:00 DEBUG node_b:btp:incoming{request.id=2470551a-1ac9-4685-9213-c58d7ee6884b prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=d8a75691-1ed1-45e9-b387-4554ac193be5 prepare.amount=0}:{to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_stream::server: Packet is unfulfillable 2019-11-12T03:01:10.976521141+00:00 DEBUG node_b:btp:incoming{request.id=2470551a-1ac9-4685-9213-c58d7ee6884b prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:forwarding{to.id=d8a75691-1ed1-45e9-b387-4554ac193be5 prepare.amount=0}:{to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_stream::server: Rejecting Prepare and including encrypted stream packet StreamPacket { sequence: 2, ilp_packet_type: Reject, prepare_amount: 0, frames: [ ] } 2019-11-12T03:01:10.976826119+00:00 INFO node_b:btp:incoming{request.id=2470551a-1ac9-4685-9213-c58d7ee6884b prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=0 from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9}:{reject.code=F99 reject.message= reject.triggered_by=example.parent.bob_on_b}: interledger-node: result="reject" 2019-11-12T03:01:10.977438347+00:00 TRACE interledger_btp::service: Got reject response to request id 3915783816 2019-11-12T03:01:10.977784991+00:00 INFO node_a:api:incoming{request.id=495fe198-6c0e-43b7-984d-c2a42edd93b0 prepare.destination=example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc prepare.amount=0 from.id=bb783990-a81d-4091-ba57-feba75acf5ac}:{from.username=alice_on_a from.ilp_address=local.host.alice_on_a from.asset_code=XYZ from.asset_scale=9}:{reject.code=F99 reject.message= reject.triggered_by=example.parent.bob_on_b}: interledger-node: result="reject" 2019-11-12T03:01:10.977908178+00:00 DEBUG interledger_stream::client: Prepare 2 with amount 0 was rejected with code: F99 (0 left to send) 2019-11-12T03:01:10.977968013+00:00 DEBUG interledger_stream::client: Send money future finished. Delivered: 1000 (2 packets fulfilled, 1 packets rejected) 2019-11-12T03:01:10.978013962+00:00 DEBUG interledger_spsp::client: Sent SPSP payment. StreamDelivery: StreamDelivery { from: Address("local.host.alice_on_a"), to: Address("example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc"), sent_amount: 1000, sent_asset_scale: 9, sent_asset_code: "XYZ", delivered_amount: 1000, delivered_asset_scale: Some(9), delivered_asset_code: Some("XYZ") } 2019-11-12T03:01:10.978094586+00:00 DEBUG interledger_api::routes::accounts: Sent SPSP payment, receipt: StreamDelivery { from: Address("local.host.alice_on_a"), to: Address("example.parent.bob_on_b.DaGDZnjMah5V_3Kk6r7jEBtc"), sent_amount: 1000, sent_asset_scale: 9, sent_asset_code: "XYZ", delivered_amount: 1000, delivered_asset_scale: Some(9), delivered_asset_code: Some("XYZ") } 2019-11-12T03:01:10.978312579+00:00 INFO interledger-api: 127.0.0.1:35178 "POST /accounts/alice_on_a/payments HTTP/1.1" 200 "-" "reqwest/0.9.22" 48.86042ms 2019-11-12T03:01:11.004348348+00:00 INFO interledger-api: 127.0.0.1:35190 "GET /accounts/alice_on_a/balance HTTP/1.1" 200 "-" "reqwest/0.9.22" 11.250077ms 2019-11-12T03:01:11.009448557+00:00 INFO interledger-api: 127.0.0.1:59908 "GET /accounts/bob_on_b/balance HTTP/1.1" 200 "-" "reqwest/0.9.22" 16.209988ms 2019-11-12T03:01:11.018606658+00:00 TRACE interledger_spsp::client: Converted payment pointer: http://localhost:3010/accounts/alice_on_a/spsp to URL: http://localhost:3010/accounts/alice_on_a/spsp 2019-11-12T03:01:11.018690933+00:00 TRACE interledger_spsp::client: Querying receiver: http://localhost:3010/accounts/alice_on_a/spsp 2019-11-12T03:01:11.029389746+00:00 DEBUG interledger_stream::server: Generated address: local.host.alice_on_a.bI8MsxLoBV7XgPmacP5_OoSx 2019-11-12T03:01:11.029476469+00:00 DEBUG interledger_spsp::server: Generated address and secret for: Address("local.host.alice_on_a.bI8MsxLoBV7XgPmacP5_OoSx") 2019-11-12T03:01:11.029626965+00:00 INFO interledger-api: 127.0.0.1:35198 "GET /accounts/alice_on_a/spsp HTTP/1.1" 200 "-" "reqwest/0.9.22" 3.843161ms 2019-11-12T03:01:11.031157187+00:00 DEBUG interledger_spsp::client: Sending SPSP payment to address: local.host.alice_on_a.bI8MsxLoBV7XgPmacP5_OoSx 2019-11-12T03:01:11.031637290+00:00 DEBUG node_b:api:incoming{request.id=169dc759-aca2-4186-b11d-a3c08ad8ac80 prepare.destination=peer.config prepare.amount=0 from.id=d8a75691-1ed1-45e9-b387-4554ac193be5}:{from.username=bob_on_b from.ilp_address=example.parent.bob_on_b from.asset_code=XYZ from.asset_scale=9}: interledger_ildcp::server: Responding to query for ildcp info by account: Address("example.parent.bob_on_b") 2019-11-12T03:01:11.031769542+00:00 INFO node_b:api:incoming{request.id=169dc759-aca2-4186-b11d-a3c08ad8ac80 prepare.destination=peer.config prepare.amount=0 from.id=d8a75691-1ed1-45e9-b387-4554ac193be5}:{from.username=bob_on_b from.ilp_address=example.parent.bob_on_b from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:11.031916207+00:00 DEBUG interledger_ildcp::client: Got ILDCP response: IldcpResponse { ilp_address: "Address("example.parent.bob_on_b")", asset_code: "XYZ", asset_scale: 9 } 2019-11-12T03:01:11.031981649+00:00 WARN interledger_stream::client: Destination ILP address starts with a different scheme prefix ("local') than ours ("example'), this probably isn't going to work 2019-11-12T03:01:11.032104677+00:00 DEBUG interledger_stream::client: Sending packet 1 with amount: 2000 and encrypted STREAM packet: StreamPacket { sequence: 1, ilp_packet_type: Prepare, prepare_amount: 0, frames: [ StreamMoneyFrame { stream_id: 1, shares: 1 }, ConnectionNewAddressFrame { source_account: example.parent.bob_on_b } ] } 2019-11-12T03:01:11.032256637+00:00 DEBUG interledger_stream::congestion: Prepare packet of 2000, amount in flight is now: 2000 2019-11-12T03:01:11.032531317+00:00 ERROR node_b:api:incoming{request.id=424e8f00-8b8f-4f6a-9444-366d5401b0b9 prepare.destination=local.host.alice_on_a.bI8MsxLoBV7XgPmacP5_OoSx prepare.amount=2000 from.id=d8a75691-1ed1-45e9-b387-4554ac193be5}:{from.username=bob_on_b from.ilp_address=example.parent.bob_on_b from.asset_code=XYZ from.asset_scale=9}: interledger_router::router: No route found for request (warning: address does not start with the right scheme prefix, expected: "example"): IncomingRequest { prepare: Prepare { destination: Address("local.host.alice_on_a.bI8MsxLoBV7XgPmacP5_OoSx"), amount: 2000, expires_at: "2019-11-12T03:01:41.032215878+00:00", execution_condition: "6f4d0bb271ab85a38ec360d021382a0875594e2742dce1945f643d1ff9c82469", data_length: 68 }, from: Account { id: AccountId(d8a75691-1ed1-45e9-b387-4554ac193be5), username: Username("bob_on_b"), ilp_address: Address("example.parent.bob_on_b"), asset_code: "XYZ", asset_scale: 9, max_packet_amount: 18446744073709551615, min_balance: None, ilp_over_http_url: None, ilp_over_http_incoming_token: Some(SecretBytes(...)), ilp_over_http_outgoing_token: None, ilp_over_btp_url: None, ilp_over_btp_incoming_token: None, ilp_over_btp_outgoing_token: None, settle_threshold: None, settle_to: None, routing_relation: NonRoutingAccount, round_trip_time: 500, packets_per_minute_limit: None, amount_per_minute_limit: None, settlement_engine_url: None } } 2019-11-12T03:01:11.032726240+00:00 INFO node_b:api:incoming{request.id=424e8f00-8b8f-4f6a-9444-366d5401b0b9 prepare.destination=local.host.alice_on_a.bI8MsxLoBV7XgPmacP5_OoSx prepare.amount=2000 from.id=d8a75691-1ed1-45e9-b387-4554ac193be5}:{from.username=bob_on_b from.ilp_address=example.parent.bob_on_b from.asset_code=XYZ from.asset_scale=9}:{reject.code=F02 reject.message= reject.triggered_by=example.parent}: interledger-node: result="reject" 2019-11-12T03:01:11.032841241+00:00 DEBUG interledger_stream::client: Prepare 1 with amount 2000 was rejected with code: F02 (2000 left to send) 2019-11-12T03:01:11.032891842+00:00 WARN interledger_stream::client: Unable to parse STREAM packet from reject data for sequence 1 2019-11-12T03:01:11.032946274+00:00 ERROR interledger_stream::client: Send money stopped because of error: SendMoneyError("Packet was rejected with error: F02 ") 2019-11-12T03:01:11.033007323+00:00 ERROR interledger_spsp::client: Error sending payment: SendMoneyError("Packet was rejected with error: F02 ") time,max_amount_in_flight,amount_fulfilled 2019-11-12T03:01:11.033081379+00:00 ERROR interledger_api::routes::accounts: Error sending SPSP payment: SendMoneyError(2000) 2019-11-12T03:01:11.033452451+00:00 INFO interledger-api: 127.0.0.1:59910 "POST /accounts/bob_on_b/payments HTTP/1.1" 500 "-" "reqwest/0.9.22" 20.230974ms Error sending SPSP payment: Error(Status(500), "http://localhost:3020/accounts/bob_on_b/payments") Error sending from node 2 to node 1: () 2019-11-12T03:01:11.062139503+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:11.062234351+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:11.064653484+00:00 TRACE interledger_ccp::server: Sending route update for epochs 1 - 1 to accounts: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 1, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [], withdrawn_routes: [] } a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895, ilp_address: example.parent.a_on_b) 2019-11-12T03:01:11.064918135+00:00 TRACE node_b:outgoing{request.id=f47c43f6-db48-41e0-9bcd-28a985e3c38f prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::expiry_shortener_service: Shortening packet expiry duration to 30000ms in the future 2019-11-12T03:01:11.065094839+00:00 TRACE node_b:outgoing{request.id=f47c43f6-db48-41e0-9bcd-28a985e3c38f prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 1105446403 to account d1cb8eca-a743-478d-a5da-9cf7324f8895 2019-11-12T03:01:11.066004127+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 1105446403 Prepare { destination: Address("peer.route.update"), amount: 0, expires_at: "2019-11-12T03:01:41.064+00:00", execution_condition: "66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925", data_length: 51 } 2019-11-12T03:01:11.066201976+00:00 TRACE interledger_btp::service: Handling incoming request 1105446403 from account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:11.067591019+00:00 DEBUG node_a:btp:incoming{request.id=a9bcb61a-b379-4400-ab38-f4cc40be81f3 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Got route update request from account b744f931-ef6c-4e5b-81e5-47bd12415634: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 1, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [], withdrawn_routes: [] } 2019-11-12T03:01:11.067735499+00:00 TRACE node_a:btp:incoming{request.id=a9bcb61a-b379-4400-ab38-f4cc40be81f3 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Got heartbeat route update for table ID: e3a20ce40dae70eb51e6a2959329ce81, epoch: 1 2019-11-12T03:01:11.067811067+00:00 TRACE node_a:btp:incoming{request.id=a9bcb61a-b379-4400-ab38-f4cc40be81f3 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Updated routing table e3a20ce40dae70eb51e6a2959329ce81 to epoch: 1 2019-11-12T03:01:11.067870746+00:00 TRACE node_a:btp:incoming{request.id=a9bcb61a-b379-4400-ab38-f4cc40be81f3 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Route update request did not contain any prefixes we need to update our routes for 2019-11-12T03:01:11.067998376+00:00 INFO node_a:btp:incoming{request.id=a9bcb61a-b379-4400-ab38-f4cc40be81f3 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:11.068883130+00:00 TRACE interledger_btp::service: Got fulfill response to request id 1105446403 2019-11-12T03:01:11.069175061+00:00 INFO node_b:outgoing{request.id=f47c43f6-db48-41e0-9bcd-28a985e3c38f prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:11.069383118+00:00 TRACE interledger_ccp::server: Updating unavailable accounts 2019-11-12T03:01:11.070243267+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:11.070302474+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:11.070889498+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:11.262184907+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:11.262283277+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:11.265207204+00:00 TRACE interledger_ccp::server: Sending route update for epochs 1 - 1 to accounts: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 1, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [], withdrawn_routes: [] } a_on_b (id: d1cb8eca-a743-478d-a5da-9cf7324f8895, ilp_address: example.parent.a_on_b) 2019-11-12T03:01:11.265497026+00:00 TRACE node_b:outgoing{request.id=65462e6d-1848-46c2-b5d8-66030a5d6098 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_service_util::expiry_shortener_service: Shortening packet expiry duration to 30000ms in the future 2019-11-12T03:01:11.265662833+00:00 TRACE node_b:outgoing{request.id=65462e6d-1848-46c2-b5d8-66030a5d6098 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}: interledger_btp::service: Sending outgoing request 320406108 to account d1cb8eca-a743-478d-a5da-9cf7324f8895 2019-11-12T03:01:11.266502818+00:00 TRACE interledger_btp::service: Got incoming Prepare packet on request ID: 320406108 Prepare { destination: Address("peer.route.update"), amount: 0, expires_at: "2019-11-12T03:01:41.265+00:00", execution_condition: "66687aadf862bd776c8fc18b8e9f8e20089714856ee233b3902a591d0d5f2925", data_length: 51 } 2019-11-12T03:01:11.266715067+00:00 TRACE interledger_btp::service: Handling incoming request 320406108 from account: b_on_a (id: b744f931-ef6c-4e5b-81e5-47bd12415634) 2019-11-12T03:01:11.267112613+00:00 DEBUG node_a:btp:incoming{request.id=02206182-0ada-4267-a4ed-cdbb324e7022 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Got route update request from account b744f931-ef6c-4e5b-81e5-47bd12415634: RouteUpdateRequest { routing_table_id: "e3a20ce40dae70eb51e6a2959329ce81", current_epoch_index: 1, from_epoch_index: 1, to_epoch_index: 1, hold_down_time: 30000, speaker: Address("example.parent"), new_routes: [], withdrawn_routes: [] } 2019-11-12T03:01:11.267244922+00:00 TRACE node_a:btp:incoming{request.id=02206182-0ada-4267-a4ed-cdbb324e7022 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Got heartbeat route update for table ID: e3a20ce40dae70eb51e6a2959329ce81, epoch: 1 2019-11-12T03:01:11.267317385+00:00 TRACE node_a:btp:incoming{request.id=02206182-0ada-4267-a4ed-cdbb324e7022 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::routing_table: Updated routing table e3a20ce40dae70eb51e6a2959329ce81 to epoch: 1 2019-11-12T03:01:11.267377963+00:00 TRACE node_a:btp:incoming{request.id=02206182-0ada-4267-a4ed-cdbb324e7022 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}: interledger_ccp::server: Route update request did not contain any prefixes we need to update our routes for 2019-11-12T03:01:11.267502501+00:00 INFO node_a:btp:incoming{request.id=02206182-0ada-4267-a4ed-cdbb324e7022 prepare.destination=peer.route.update prepare.amount=0 from.id=b744f931-ef6c-4e5b-81e5-47bd12415634}:{from.username=b_on_a from.ilp_address=local.host.b_on_a from.asset_code=XYZ from.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:11.268089713+00:00 TRACE interledger_btp::service: Got fulfill response to request id 320406108 2019-11-12T03:01:11.268353486+00:00 INFO node_b:outgoing{request.id=65462e6d-1848-46c2-b5d8-66030a5d6098 prepare.destination=peer.route.update from.id=d1cb8eca-a743-478d-a5da-9cf7324f8895 to.id=d1cb8eca-a743-478d-a5da-9cf7324f8895}:{from.username=a_on_b from.ilp_address=example.parent.a_on_b from.asset_code=XYZ from.asset_scale=9 to.username=a_on_b to.asset_code=XYZ to.asset_scale=9}:{fulfillment=0000000000000000000000000000000000000000000000000000000000000000}: interledger-node: result="fulfill" 2019-11-12T03:01:11.268493636+00:00 TRACE interledger_ccp::server: Updating unavailable accounts 2019-11-12T03:01:11.269609604+00:00 TRACE interledger_ccp::server: Checking accounts to skip 2019-11-12T03:01:11.269672176+00:00 TRACE interledger_ccp::server: Skipping accounts: [] 2019-11-12T03:01:11.270218081+00:00 TRACE interledger_ccp::server: No accounts to broadcast routes to 2019-11-12T03:01:11.302819949+00:00 WARN interledger_store_redis::store: Could not issue psubscribe to Redis: Could not read enough bytes 2019-11-12T03:01:11.302820038+00:00 WARN interledger_store_redis::store: Could not issue psubscribe to Redis: Could not read enough bytes test two_nodes_btp ... FAILED failures: ---- two_nodes_btp stdout ---- Error executing tests: () thread 'two_nodes_btp' panicked at 'called `Result::unwrap()` on an `Err` value: ()', src/libcore/result.rs:1165:5 stack backtrace: 0: 0x55bce11f3b04 - backtrace::backtrace::libunwind::trace::hda41dbcdfba36aa0 at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/libunwind.rs:88 1: 0x55bce11f3b04 - backtrace::backtrace::trace_unsynchronized::h1a8d6e1f8cb3f5d4 at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.37/src/backtrace/mod.rs:66 2: 0x55bce11f3b04 - std::sys_common::backtrace::_print_fmt::h610c4127487e10da at src/libstd/sys_common/backtrace.rs:76 3: 0x55bce11f3b04 - ::fmt::h0722dc552e01bd1d at src/libstd/sys_common/backtrace.rs:60 4: 0x55bce121b2cc - core::fmt::write::h01edf6dd68a42c9c at src/libcore/fmt/mod.rs:1030 5: 0x55bcdf8ceea5 - std::io::Write::write_fmt::hd48b46e5c13c6612 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/io/mod.rs:1412 6: 0x55bce11ec361 - std::io::impls::>::write_fmt::hc4feb234d1aa0439 at src/libstd/io/impls.rs:141 7: 0x55bce11f6045 - std::sys_common::backtrace::_print::hd8d5d08a1795e743 at src/libstd/sys_common/backtrace.rs:64 8: 0x55bce11f6045 - std::sys_common::backtrace::print::hf89a79e3921a2366 at src/libstd/sys_common/backtrace.rs:49 9: 0x55bce11f6045 - std::panicking::default_hook::{{closure}}::h3a8f42beb3bb8ae3 at src/libstd/panicking.rs:196 10: 0x55bce11f5ccc - std::panicking::default_hook::h8f803b0bc31a5c37 at src/libstd/panicking.rs:207 11: 0x55bce11f6745 - std::panicking::rust_panic_with_hook::h825f041245da8739 at src/libstd/panicking.rs:473 12: 0x55bce11f62e2 - std::panicking::continue_panic_fmt::hbe0378e33481e81b at src/libstd/panicking.rs:380 13: 0x55bce11f61d6 - rust_begin_unwind at src/libstd/panicking.rs:307 14: 0x55bce12177ca - core::panicking::panic_fmt::h527855ce0bc891f6 at src/libcore/panicking.rs:85 15: 0x55bce12178c7 - core::result::unwrap_failed::ha8b77e6004f0ba38 at src/libcore/result.rs:1165 16: 0x55bce0e59322 - core::result::Result::unwrap::h4be7a47527a32392 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libcore/result.rs:933 17: 0x55bcdf8613fb - btp::two_nodes_btp::h5224fb3393e070b7 at crates/ilp-node/tests/btp.rs:112 18: 0x55bcdf8b40fa - btp::two_nodes_btp::{{closure}}::hd0edd9a316d9e544 at crates/ilp-node/tests/btp.rs:15 19: 0x55bcdf8917fe - core::ops::function::FnOnce::call_once::hef9465b86f326af1 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libcore/ops/function.rs:227 20: 0x55bcdf8d8d9f - as core::ops::function::FnOnce>::call_once::h60313ef8cd80fa37 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922 21: 0x55bce11fefba - __rust_maybe_catch_panic at src/libpanic_unwind/lib.rs:80 22: 0x55bcdf8f35ae - std::panicking::try::h218111062acbd8af at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/panicking.rs:271 23: 0x55bcdf8f35ae - std::panic::catch_unwind::hb43bd7e3eefd561b at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/panic.rs:394 24: 0x55bcdf8f35ae - test::run_test::run_test_inner::{{closure}}::h61999fd5b32b527c at src/libtest/lib.rs:1413 25: 0x55bcdf8ce615 - std::sys_common::backtrace::__rust_begin_short_backtrace::h94f0165e3063a572 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/sys_common/backtrace.rs:126 26: 0x55bcdf8d2815 - std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}::ha13ef4f272e8d7f5 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/thread/mod.rs:470 27: 0x55bcdf8d2815 - as core::ops::function::FnOnce<()>>::call_once::h4be9743fa104fe58 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/panic.rs:315 28: 0x55bcdf8d2815 - std::panicking::try::do_call::hc01172ae30fe685a at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/panicking.rs:292 29: 0x55bce11fefba - __rust_maybe_catch_panic at src/libpanic_unwind/lib.rs:80 30: 0x55bcdf8d2d82 - std::panicking::try::h28c280234b112988 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/panicking.rs:271 31: 0x55bcdf8d2d82 - std::panic::catch_unwind::h80abb9ed16b7a343 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/panic.rs:394 32: 0x55bcdf8d2d82 - std::thread::Builder::spawn_unchecked::{{closure}}::h079ad7fe053e2851 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libstd/thread/mod.rs:469 33: 0x55bcdf8d2d82 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h66965f502b707a1a at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/libcore/ops/function.rs:227 34: 0x55bce11e7f1f - as core::ops::function::FnOnce>::call_once::h483711add4ba2330 at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922 35: 0x55bce11fe320 - as core::ops::function::FnOnce>::call_once::h7605b45eb29ed0be at /rustc/4560ea788cb760f0a34127156c78e2552949f734/src/liballoc/boxed.rs:922 36: 0x55bce11fe320 - std::sys_common::thread::start_thread::h557b0c2dc4449562 at src/libstd/sys_common/thread.rs:13 37: 0x55bce11fe320 - std::sys::unix::thread::Thread::new::thread_start::h7c2a7f9b68fe4bba at src/libstd/sys/unix/thread.rs:79 38: 0x7f46c56b1fa3 - start_thread 39: 0x7f46c55c64cf - clone 40: 0x0 - failures: two_nodes_btp test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out ```
dora-gt commented 4 years ago

The Cause

The reason was that RedisStore::insert_account was not fully atomic. The code to reproduce the bug is here: https://github.com/interledger-rs/interledger-rs/commit/a3917726b12a31648c192d28c703ab5c1dce4d58

If the accounts of alice_on_a and b_on_a are being added at the same time and unfortunately, b_on_a is added when alice_on_a is being added, alice_on_a is added with a wrong ILP address.

Imagine that, this line is executed: https://github.com/interledger-rs/interledger-rs/blob/two_nodes_btp-reproduce/crates/interledger-store-redis/src/store.rs#L979

and then, b_on_a is added at the same time, which means the procedure of b_on_a updates the ILP address of the node. After that, the procedure of alice_on_a executes this line: https://github.com/interledger-rs/interledger-rs/blob/two_nodes_btp-reproduce/crates/interledger-store-redis/src/store.rs#L994

Then the ILP address of alice_on_a becomes local.host.alice_on_a, which should be example.parent.a_on_b.alice_on_a, and the payments from Node B to Node A fail.

Success case redis data ``` redis /tmp/redis-rs-test-4322682017757775539-16574310618772940287.sock[1]> hgetall accounts:a8815a3a-03d5-499f-ab18-b96cb34174f1 1) "id" 2) "a8815a3a-03d5-499f-ab18-b96cb34174f1" 3) "username" 4) "alice_on_a" 5) "ilp_address" 6) "example.parent.a_on_b.alice_on_a" 7) "asset_code" 8) "XYZ" 9) "asset_scale" 10) "9" 11) "max_packet_amount" 12) "18446744073709551615" 13) "routing_relation" 14) "NonRoutingAccount" 15) "round_trip_time" 16) "500" 17) "ilp_over_http_incoming_token" 18) "q\xa0\x91\x7f\xca\xfeg\xc1\xb3\xc2QC3\xcf\x14\x1aO\xa2\xf3\x91\xe39f\xa8\x80\xc7|Q\xce|\x8f{\x0f'3P\x13\xfc/\xb5\x9f[y\x80\x90\xdd\x82\xbfL\xed" 19) "balance" 20) "1000" 21) "prepaid_amount" 22) "0" ```
Failure case redis data ``` hgetall accounts:6486e42b-23a2-4d7b-9d4c-efea74a7d0bd 1) "id" 2) "6486e42b-23a2-4d7b-9d4c-efea74a7d0bd" 3) "username" 4) "alice_on_a" 5) "ilp_address" 6) "local.host.alice_on_a" 7) "asset_code" 8) "XYZ" 9) "asset_scale" 10) "9" 11) "max_packet_amount" 12) "18446744073709551615" 13) "routing_relation" 14) "NonRoutingAccount" 15) "round_trip_time" 16) "500" 17) "ilp_over_http_incoming_token" 18) "\xe7&Fc\x19n-\x80o7\x9b\x91N\x1eu4y\xace\xc9nD\x04EsC\x04\x0e\x18\x85\x9bR\b\x0e)\xeb\xba\xa2\xc2z\xeb\x9d\x91\xca!3\xb3\xe8\xc8\xea" 19) "balance" 20) "-1000" 21) "prepaid_amount" 22) "0" ```

Possible Countermeasure

I think we have to make RedisStore::insert_account fully atomic. For example, lock the ILP address first, and execute redis_insert_account, and after that, unlock the ILP address.

Actually I tried some approaches but it was really difficult because RwLock cannot be used in multi-thread executor like tokio (am I right?), and also futures 0.1.29 doesn't provide nice locking library.

Does anyone come up with a nice way to solve this?

@interledger-rs/contributors

dora-gt commented 4 years ago

Also I think it would be nice to investigate other functions around redis about whether it is fully atomic or not, being careful about deadlocks.

dora-gt commented 4 years ago

Ref:

bstrie commented 4 years ago

I have no trouble believing there are race conditions in this code (I had previously noted having seen some in https://github.com/interledger-rs/interledger-rs/issues/196#issuecomment-523664862 , and I think I may have left some comments in the redis store remarking at plausible race conditions). At the ones I was looking at it seemed like the difficulty was that we may have needed to move things into Lua scripts in order to achieve atomicity, which is kind of a pain. Going forward my work on the SQLite store will allow us to have a backend with proper transactions.

dora-gt commented 4 years ago

Thanks Ben, yes, I agree that one of possible countermeasures is moving the variable into stores that could ensure the atomicity.

I think this problem is very profound. I mean, I think we should not update the ILP address of the node during any payment processes. For example, what happens if the ILP address is updated when some Stream payments are being processed? Maybe this is not tested and might cause some undesired behavior. We should start locking the ILP address when we get Prepares till we send Fulfills at least the read level... though that might be a very rare case.

dora-gt commented 4 years ago

After exploring some functions on futures (tokio::sync::lock, futures_locks), experimenting those and looking into the implementation, I finally became to think about:

  1. We should get rid of RwLock or Mutex because it is not safe in the Async context (mentioned here).
  2. We should get rid of the ilp_address variable in RedisStore and lock the ILP address on any Stores including Redis, SQL because we have to make it scalable and then locking the ILP address on a single node doesn't make sense.
    • We could utilize SELECT xx FROM xx LOCK IN SHARE MODE or something like it.
    • I'm not sure we have something similar in Redis though... maybe not because Redis is a single thread model, we have to figure out how to realize. Maybe the optimistic lock pattern could be used.

So I think I should revisit this problem later after SQL store is implemented by @bstrie . I'll fix just not to let tests fail though it is not an essential solution.

JFYI: What is interesting regarding futures_locks is that they provide async RwLock. tokio::sync::lock doesn't provide RwLock though there are more useful libraries in the current async environment.

emschwartz commented 4 years ago

Can this be closed now?

dora-gt commented 4 years ago

I think we have to essentially fix this problem, later after SQL is integrated. So this should not be closed IMO.