Proxy deadlock results in CI failing

[geigerzaehler]

Since the radicle-link upgrade (#2028) our CI has started failing, both on Github and Buildkite.

It seems that this is caused by radicle-proxy going not binding to the local API anymore. This causes the tests to error with “Failed to fetch”. This error always occurs after the proxy is reset and a new keystore is created. The last log lines from the proxy are

2021-07-13T11:18:53.074 WARN  api::http::control::handler                 > reload requested
2021-07-13T11:18:53.074 INFO  proxy::http                                 > "GET /v1/control/reset HTTP/1.1" 200 585.566µs
2021-07-13T11:18:53.078 INFO  api::process                                > starting API
2021-07-13T11:18:53.083 INFO  proxy::http                                 > "OPTIONS /v1/keystore HTTP/1.1" 200 82.036µs
2021-07-13T11:18:53.098 INFO  proxy::http                                 > "POST /v1/keystore HTTP/1.1" 204 9.948806ms

After this all subsequent tests fail with “Failed to fetch”.

[geigerzaehler]

After some more investigation it looks like the proxy is deadlocking. This only seems to happen if the proxy is reloaded multiple times. Reloading the proxy means that the radicle_daemon peer is torn down and reinitialized. The deadlock may be caused by the peer not being torn down properly and not all tasks being aborted.

[rudolfs]

This seems to happen also when running Upstream in dev mode via yarn start. It takes about 30min for the hang to occour. Here's what I see in the logs when it hangs:

...
 2021-07-20T14:50:58.533 DEBUG librad::net::peer::storage                  > ask; want=Payload { urn: Urn { id: Oid(6473a027a10e24148872cda22d67bf831ed32adf), path: Some(RefLike("rad/id")) }, rev: Some(Git(e0ad2de9be92f2f5ea12c71c465307d6f5bed906)), origin: None }
 2021-07-20T14:50:58.533 DEBUG librad::net::protocol::tick                 > tock; tock=SendConnected { to: hynkyndc6w3p8urucakobzna7sxwgcqny7xxtw88dtx3pkf7m3nrzc, message: Gossip(Want { origin: GenericPeerInfo { peer_id: hyy4ebh8amk3ypyawgpjnfpbgkxqwdo5n1iif5s17yghwmewrf4d8a, advertised_info: PeerAdvertisement { listen_addrs: Within { inner: [95.111.216.99:12345], min: 0, max: 16 }, capabilities: {} }, seen_addrs: Within { inner: [], min: 0, max: 16 } }, val: Payload { urn: Urn { id: Oid(6473a027a10e24148872cda22d67bf831ed32adf), path: Some(RefLike("rad/id")) }, rev: Some(Git(e0ad2de9be92f2f5ea12c71c465307d6f5bed906)), origin: None } }) }
 2021-07-20T14:50:58.533 INFO  librad::net::protocol::io::send::rpc        > send_rpc; remote_id=hynkyndc6w3p8urucakobzna7sxwgcqny7xxtw88dtx3pkf7m3nrzc remote_addr=34.141.175.140:12345
 2021-07-20T14:50:58.534 DEBUG librad::net::protocol::tick                 > tock
 2021-07-20T14:50:58.576 INFO  librad::net::protocol::io::streams          > new ingress stream
 2021-07-20T14:50:58.577 INFO  librad::net::protocol::broadcast            > apply; remote_id=hybz9gfgtd9d4pd14a6r66j5hz6f77fed4jdu7pana4fxaxbt369kg message=Want { origin: GenericPeerInfo { peer_id: hyy4ebh8amk3ypyawgpjnfpbgkxqwdo5n1iif5s17yghwmewrf4d8a, advertised_info: PeerAdvertisement { listen_addrs: Within { inner: [95.111.216.99:12345], min: 0, max: 16 }, capabilities: {} }, seen_addrs: Within { inner: [], min: 0, max: 16 } }, val: Payload { urn: Urn { id: Oid(6473a027a10e24148872cda22d67bf831ed32adf), path: Some(RefLike("rad/id")) }, rev: Some(Git(e0ad2de9be92f2f5ea12c71c465307d6f5bed906)), origin: None } }
 2021-07-20T14:50:58.577 DEBUG librad::net::peer::storage                  > ask; want=Payload { urn: Urn { id: Oid(6473a027a10e24148872cda22d67bf831ed32adf), path: Some(RefLike("rad/id")) }, rev: Some(Git(e0ad2de9be92f2f5ea12c71c465307d6f5bed906)), origin: None }
 2021-07-20T14:50:58.577 DEBUG librad::net::protocol::tick                 > tock; tock=SendConnected { to: hynkyndc6w3p8urucakobzna7sxwgcqny7xxtw88dtx3pkf7m3nrzc, message: Gossip(Want { origin: GenericPeerInfo { peer_id: hyy4ebh8amk3ypyawgpjnfpbgkxqwdo5n1iif5s17yghwmewrf4d8a, advertised_info: PeerAdvertisement { listen_addrs: Within { inner: [95.111.216.99:12345], min: 0, max: 16 }, capabilities: {} }, seen_addrs: Within { inner: [], min: 0, max: 16 } }, val: Payload { urn: Urn { id: Oid(6473a027a10e24148872cda22d67bf831ed32adf), path: Some(RefLike("rad/id")) }, rev: Some(Git(e0ad2de9be92f2f5ea12c71c465307d6f5bed906)), origin: None } }) }
 2021-07-20T14:50:58.577 INFO  librad::net::protocol::io::send::rpc        > send_rpc; remote_id=hynkyndc6w3p8urucakobzna7sxwgcqny7xxtw88dtx3pkf7m3nrzc remote_addr=34.141.175.140:12345
 2021-07-20T14:50:58.578 DEBUG librad::net::protocol::tick                 > tock
 2021-07-20T14:51:57.099 DEBUG librad::net::quic::connection::tracking     > GC conn=140594076971024 prev_epoch=0 curr_epoch=1 tracked_epoch=1
 2021-07-20T14:51:57.099 DEBUG librad::net::quic::connection::tracking     > GC conn=140594154417168 prev_epoch=0 curr_epoch=1 tracked_epoch=1
 2021-07-20T14:53:02.106 DEBUG librad::net::quic::connection::tracking     > GC conn=140594076971024 prev_epoch=1 curr_epoch=2 tracked_epoch=1
 2021-07-20T14:53:02.106 DEBUG librad::net::quic::connection::tracking     > GC conn=140594154417168 prev_epoch=1 curr_epoch=2 tracked_epoch=1
 2021-07-20T14:53:02.106 INFO  librad::net::quic::stream                   > on_stream_error; dir="recv" remote_id=hynkyndc6w3p8urucakobzna7sxwgcqny7xxtw88dtx3pkf7m3nrzc remote_addr=34.141.175.140:12345
 2021-07-20T14:53:02.107 WARN  librad::net::quic::connection               > stream error err=Custom { kind: NotConnected, error: ConnectionClosed(LocallyClosed) }