Skip to content
This repository has been archived by the owner on Sep 10, 2020. It is now read-only.

Investigate nectar closing connection with cnd #106

Open
da-kami opened this issue Aug 12, 2020 · 1 comment
Open

Investigate nectar closing connection with cnd #106

da-kami opened this issue Aug 12, 2020 · 1 comment
Labels
bug Something isn't working

Comments

@da-kami
Copy link
Contributor

da-kami commented Aug 12, 2020 •
edited
Loading

Setup

System: MacOS Catalina 10.15.5

  1. start cnd
  2. start nectar
  3. Dial from cnd to nectar (using nectar's port and localhost IP-adr)

Nectar's rate update (and hence order publication) set to 10 minutes.

on nectar branch https://github.com/coblox/nectar/tree/new-orderbook

Behaviour

The connection between Nectar and cnd is just closed after 10 minutes.

Note that this always happens at the moment, not matter if during, after swap execution, or just order fetching.
Note that Nectar was set to publish orders only every 10 minutes (fetch rate after 10 minutes and place new order based on it). This might be related, but not necessarily.

Example logs where cnd dials nectar and then just runs fetching orders until connection is closed is below.

cnd:

Aug 12 15:14:44.617  INFO http: - "POST /dial HTTP/1.1" 200 "-" "PostmanRuntime/7.26.2" 1.74729ms    
Aug 12 15:14:44.652 DEBUG comit::network::orderbook::order_source: connected to 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J, attempting to get orders
Aug 12 15:14:44.675 DEBUG comit::network::orderbook::order_source: fetched 2 orders from 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J

...

12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 15:20:32.278 DEBUG comit::network::orderbook::order_source: fetched 2 orders from 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 15:20:38.275 DEBUG comit::network::orderbook::order_source: fetched 2 orders from 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 15:20:43.277 DEBUG comit::network::orderbook::order_source: fetched 2 orders from 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 15:20:48.278 DEBUG comit::network::orderbook::order_source: fetched 2 orders from 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 15:20:53.831  INFO comit::network::orderbook::order_source: removing 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J as a potential order source because we failed to establish a connection to them: ConnectionClosed

nectar:

/Users/dakami/.cargo/bin/cargo run --color=always --package nectar --bin nectar -- --config /Users/dakami/CoBloX/repos/nectar/demo/example-config.toml trade
    Finished dev [unoptimized + debuginfo] target(s) in 1.18s
     Running `target/debug/nectar --config /Users/dakami/CoBloX/repos/nectar/demo/example-config.toml trade`
Using config file /Users/dakami/CoBloX/repos/nectar/demo/example-config.toml
Aug 12 15:10:47.531  INFO nectar::trace: Initialized tracing with level: TRACE
Aug 12 15:10:47.536  INFO nectar::config::seed: Read in seed from file: /Users/dakami/Library/Application Support/nectar/seed.pem
Aug 12 15:10:48.248  INFO nectar::network: Started with peer-id: 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 15:10:48.249  INFO nectar::network: Started with peer-id: 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 15:10:48.249  INFO libp2p_gossipsub::behaviour: Subscribed to topic: /comit/makers    
Aug 12 15:10:48.250  INFO nectar::network: Publishing new order: Sell, 0.09990725 BTC, 1166.76881727 DAI
Aug 12 15:10:48.251  INFO comit::network::orderbook::orders: created new order with id d44812da-e862-407d-9a6d-79b01f883d75
Aug 12 15:10:48.251  INFO nectar::network: Publishing new order: Buy, 0.0009464 BTC, 10 DAI
Aug 12 15:10:48.251  INFO comit::network::orderbook::orders: created new order with id 86340909-087f-4014-847f-d9c0cb68dd7a
Aug 12 15:10:48.252  INFO nectar::command::trade: NewListenAddr("/ip4/127.0.0.1/tcp/9940")
Aug 12 15:10:48.252  INFO nectar::command::trade: NewListenAddr("/ip6/::1/tcp/9940")
Aug 12 15:10:48.252  INFO nectar::command::trade: NewListenAddr("/ip4/10.1.20.38/tcp/9940")
Aug 12 15:14:44.618  INFO nectar::command::trade: IncomingConnection { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/53972" }
Aug 12 15:14:44.638 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:14:44.642 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:14:44.642  INFO libp2p_gossipsub::behaviour: New peer connected: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR")    
Aug 12 15:14:44.642 DEBUG comit::network::orderbook::order_source: connected to 12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR, attempting to get orders
Aug 12 15:14:44.642  INFO nectar::command::trade: ConnectionEstablished { peer_id: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR"), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/53972" }, num_established: 1 }
Aug 12 15:14:44.655 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:14:44.655 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:14:44.657 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:14:44.658 DEBUG comit::network::orderbook::order_source: fetched 0 orders from 12D3KooWJd

...

Aug 12 15:20:43.275 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:20:48.272 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:20:48.274 DEBUG comit::network::orderbook::order_source: fetched 0 orders from 12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR
Aug 12 15:20:48.275 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:20:48.758  INFO nectar::network: Publishing new order: Sell, 0.09990725 BTC, 1167.32480111625 DAI
Aug 12 15:20:48.758  INFO comit::network::orderbook::orders: created new order with id 04596aef-3389-490f-94de-3df43f3ffe96
Aug 12 15:20:48.758  INFO nectar::network: Publishing new order: Buy, 0.00094595 BTC, 10 DAI
Aug 12 15:20:48.758  INFO comit::network::orderbook::orders: created new order with id 84d70acd-8abe-4044-b20e-9b08bc4bf33a
Aug 12 15:20:53.829 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:20:53.832  INFO nectar::command::trade: ConnectionClosed { peer_id: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR"), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/53972" }, num_established: 0, cause: IO(Custom { kind: Other, error: "yamux error: connection is closed" }) }
Aug 12 15:20:53.833  INFO comit::network::orderbook::order_source: removing 12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR as a potential order source because we failed to establish a connection to them: ConnectionClosed
Aug 12 15:30:50.646  INFO nectar::network: Publishing new order: Sell, 0.09990725 BTC, 1162.5517322475 DAI
Aug 12 15:30:50.646  INFO comit::network::orderbook::orders: created new order with id f2306d19-3253-4539-8427-3272017e034a
Aug 12 15:30:50.646  INFO nectar::network: Publishing new order: Buy, 0.00094983 BTC, 10 DAI
Aug 12 15:30:50.647  INFO comit::network::orderbook::orders: created new order with id 0454ac4f-32f8-45e3-838c-4b744fc9e86a

Another example log where it happens after (successful) swap execution:

cnd:

Aug 12 14:49:59.766  INFO cnd::herc20: yielded event Redeemed
Aug 12 14:49:59.766  INFO cnd::herc20: swap finished
Aug 12 14:50:00.693  INFO http: - "GET /swaps/88fa1e28-c944-439d-9da5-9ce1d6ec9ee2 HTTP/1.1" 200 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.130 Electron/7.2.4 Safari/537.36" 2.486211ms    
Aug 12 14:50:01.497  INFO comit::network::orderbook::order_source: removing 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J as a potential order source because we failed to establish a connection to them: ConnectionClosed
Aug 12 14:50:01.728  INFO http: - "GET /swaps/88fa1e28-c944-439d-9da5-9ce1d6ec9ee2 HTTP/1.1" 200 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.130 Electron/7.2.4 Safari/537.36" 1.567835ms

nectar:

Aug 12 14:49:59.222 TRACE watch_redeem: comit::btsieve::ethereum::web3_connector: Fetched receipt from web3: 0x2132227e48884273290987a980053d2130a0354809e470589d7f46f8c3f559b1
Aug 12 14:49:59.222  INFO watch_redeem: comit::btsieve::ethereum: transaction matched
Aug 12 14:49:59.583  INFO nectar::network: Publishing new order: Buy, 0.00094626 BTC, 10 DAI
Aug 12 14:49:59.583  INFO comit::network::orderbook::orders: created new order with id 4cc393f5-0a55-40b9-a468-2642fd2f73ce
Aug 12 14:49:59.648  INFO nectar::network: Publishing new order: Sell, 0.09990725 BTC, 1166.941906580625 DAI
Aug 12 14:49:59.648  INFO comit::network::orderbook::orders: created new order with id 7bc8021f-6836-4b20-be38-18f678b853f5
Aug 12 14:50:01.494 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 14:50:01.497  INFO nectar::command::trade: ConnectionClosed { peer_id: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR"), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/61576" }, num_established: 0, cause: IO(Custom { kind: Other, error: "yamux error: decode error: i/o error: I/O error: Connection reset by peer (os error 54)" }) }
Aug 12 14:59:00.061  INFO nectar::network: Publishing new order: Sell, 0.09990725 BTC, 1167.76539208875 DAI
Aug 12 14:59:00.061  INFO comit::network::orderbook::orders: created new order with id 6c4e697d-3c90-4ec3-ae6d-aa33b4727d8a
Aug 12 14:59:00.061  INFO nectar::network: Publishing new order: Buy, 0.00094559 BTC, 10 DAI
Aug 12 14:59:00.062  INFO comit::network::orderbook::orders: created new order with id 134c308c-827e-4c81-9656-3d77a6a14015
Aug 12 15:01:01.795  INFO nectar::command::trade: IncomingConnection { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/49171" }
Aug 12 15:01:01.807 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:01.808 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:01.808  INFO libp2p_gossipsub::behaviour: New peer connected: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR")    
Aug 12 15:01:01.809 DEBUG comit::network::orderbook::order_source: connected to 12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR, attempting to get orders
Aug 12 15:01:01.809  INFO nectar::command::trade: ConnectionEstablished { peer_id: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR"), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/49171" }, num_established: 1 }
Aug 12 15:01:01.818 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:01.818 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:01.820 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:01.822 DEBUG comit::network::orderbook::order_source: fetched 0 orders from 12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR
Aug 12 15:01:01.825 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:01.835  INFO nectar::command::trade: ConnectionClosed { peer_id: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR"), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/49171" }, num_established: 0, cause: IO(Custom { kind: Other, error: "yamux error: connection is closed" }) }
Aug 12 15:01:23.049  INFO nectar::command::trade: IncomingConnection { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/49301" }
Aug 12 15:01:23.066 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:23.085 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:23.086  INFO libp2p_gossipsub::behaviour: New peer connected: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR")    
Aug 12 15:01:23.086 DEBUG comit::network::orderbook::order_source: connected to 12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR, attempting to get orders
Aug 12 15:01:23.086  INFO nectar::command::trade: ConnectionEstablished { peer_id: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR"), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/49301" }, num_established: 1 }
Aug 12 15:01:23.116 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:23.119 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:23.121 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:23.122 DEBUG comit::network::orderbook::order_source: fetched 0 orders from 12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR
Aug 12 15:01:23.123 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 15:01:23.173  INFO nectar::command::trade: ConnectionClosed { peer_id: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR"), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/49301" }, num_established: 0, cause: IO(Custom { kind: Other, error: "yamux error: connection is closed" }) }

Expected Behaviour

A stable connection over long period of time between Nectar and cnd.
Nectar should only close the connection if there is a problem.
@da-kami da-kami added the bug Something isn't working label Aug 12, 2020
@da-kami
Copy link
Contributor Author

da-kami commented Aug 12, 2020

It seems this issue is actually not time related, but it happens when we publish a new order. Might be related to an error happening on publication of the order or when cnd fetches the new orders from nectar.

I just had a transaction drop that happened after a successful swap, after about 2 minutes after a swap execution, that lead to a balance change that lead to new orders being published.

nectar:

Using config file /Users/dakami/CoBloX/repos/nectar/demo/example-config.toml
Aug 12 17:17:45.698  INFO nectar::trace: Initialized tracing with level: TRACE
Aug 12 17:17:45.702  INFO nectar::config::seed: Read in seed from file: /Users/dakami/Library/Application Support/nectar/seed.pem
Aug 12 17:17:46.457  INFO nectar::network: Started with peer-id: 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 17:17:46.457  INFO nectar::network: Started with peer-id: 12D3KooWH5U7zEknZCU5rDgz5zLPxRFzKrpe8fWvBVNUAbDRuf5J
Aug 12 17:17:46.458  INFO libp2p_gossipsub::behaviour: Subscribed to topic: /comit/makers    
Aug 12 17:17:46.459  INFO nectar::network: Publishing new order: Sell, 0.09990725 BTC, 1169.879179730625 DAI
Aug 12 17:17:46.459  INFO comit::network::orderbook::orders: created new order with id ff843004-fede-4904-9cd5-6608230e3934
Aug 12 17:17:46.459  INFO nectar::network: Publishing new order: Buy, 0.00094389 BTC, 10 DAI
Aug 12 17:17:46.459  INFO comit::network::orderbook::orders: created new order with id 3185d1c1-d6a0-47e1-a74b-43e3ec4ee777
Aug 12 17:17:46.463  INFO nectar::command::trade: NewListenAddr("/ip4/127.0.0.1/tcp/9940")
Aug 12 17:17:46.464  INFO nectar::command::trade: NewListenAddr("/ip6/::1/tcp/9940")
Aug 12 17:17:46.464  INFO nectar::command::trade: NewListenAddr("/ip4/10.1.20.38/tcp/9940")
Aug 12 17:18:03.039  INFO nectar::command::trade: IncomingConnection { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/50064" }
Aug 12 17:18:03.114 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 17:18:03.116 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 17:18:03.117  INFO libp2p_gossipsub::behaviour: New peer connected: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR")  

...

Aug 12 17:18:31.529  INFO nectar::network: Publishing new order: Buy, 0.00094389 BTC, 10 DAI
Aug 12 17:18:31.529  INFO comit::network::orderbook::orders: created new order with id b460ef4c-b811-425d-988f-e81f03f0d958
Aug 12 17:18:31.555  INFO nectar::network: Publishing new order: Sell, 0.09990725 BTC, 1169.879179730625 DAI
Aug 12 17:18:31.555  INFO comit::network::orderbook::orders: created new order with id 9dc9f9c5-cc9f-47cd-921c-2e276dd35c2b
Aug 12 17:18:33.469 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 17:18:33.471 DEBUG comit::network::orderbook::order_source: fetched 0 orders from 12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR
Aug 12 17:18:33.472 DEBUG libp2p_core::upgrade::apply: Successfully applied negotiated protocol    
Aug 12 17:18:33.474  INFO nectar::command::trade: ConnectionClosed { peer_id: PeerId("12D3KooWJdBwGAohCJbaZDFurkFkVkLuXCQmSa7wJ7cVMgujLJRR"), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/9940", send_back_addr: "/ip4/127.0.0.1/tcp/50064" }, num_established: 0, cause: IO(Custom { kind: Other, error: "yamux error: connection is closed" }) }

@da-kami da-kami changed the title Investigate nectar closing connection with cnd after 10 minutes Investigate nectar closing connection with cnd Aug 16, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@da-kami