Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Behavior on connection loss #1789

Open
0pcom opened this issue Mar 23, 2024 · 1 comment
Open

Behavior on connection loss #1789

0pcom opened this issue Mar 23, 2024 · 1 comment

Comments

@0pcom
Copy link
Collaborator

0pcom commented Mar 23, 2024 •
edited
Loading

Something we rarely look at is what happens on internet connection loss.

A visor with a running proxy server and the following transports was used

$ skywire-cli visor tp ls
type      id                                       remote_pk                                                              mode        label
sudph     247984d4-4a1a-0eda-a67c-9e69bf0fb169     0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac     regular     automatic
dmsg      c6e0e33b-3ffb-0de4-ae5e-27e85caaace1     03d0c4a4df6fd1db6f9329a8bbfeb6879a171d554afe9bfbdcac5cb9c34f62a2d6     regular     automatic

The network was disconnected temporarily via NetworkManager Applet on linux in order to observe the visor debug logging, and then the network was reconnected

The following visor debug logging was produced:

[2024-03-23T17:03:59.012351811-05:00] DEBUG (STDOUT) [proc:skysocks-client:f40bbfff4dd9439b8cc9381ae716296b]: Opened session skysocks client
[2024-03-23T17:10:18.806815158-05:00] DEBUG [tp:038240]: Stopped log loop
[2024-03-23T17:10:18.806867398-05:00] DEBUG [tp:038240]: Stopped serving. remaining_tps=1 remote_pk=0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac tp_id=247984d4-4a1a-0eda-a67c-9e69bf0fb169 tp_index=2
[2024-03-23T17:10:19.085090879-05:00] DEBUG [transport_manager]: Deleted 1 unused transport entries
[2024-03-23T17:10:27.751535905-05:00] ERROR httpClient.BindSUDPR [address_resolver]: Failed to send UDP heartbeat packet to address-resolver error="write udp [::]:53156->192.53.117.238:30178: sendto: network is unreachable"
2024/03/23 17:10:28 [ERR] yamux: keepalive failed: i/o deadline reached
[2024-03-23T17:10:28.196594258-05:00] WARN [dmsgC]: Stopped accepting streams. error="keepalive timeout" session=02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd
[2024-03-23T17:10:28.196617623-05:00] DEBUG readPacket [tp:03d0c4]: Failed to read packet header. error="EOF"
[2024-03-23T17:10:28.196809194-05:00] WARN [tp:03d0c4]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2024-03-23T17:10:28.196765753-05:00] DEBUG [dmsgC]: Session stopped. error="failed to serve dialed session to 02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd: keepalive timeout"
[2024-03-23T17:10:28.196971636-05:00] DEBUG [tp:03d0c4]: Stopped log loop
[2024-03-23T17:10:28.197075207-05:00] DEBUG [tp:03d0c4]: Stopped serving. remaining_tps=0 remote_pk=03d0c4a4df6fd1db6f9329a8bbfeb6879a171d554afe9bfbdcac5cb9c34f62a2d6 tp_id=c6e0e33b-3ffb-0de4-ae5e-27e85caaace1 tp_index=1
[2024-03-23T17:10:28.201686944-05:00] DEBUG [tp:03d0c4]: Error deleting transport error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" tp-id=c6e0e33b-3ffb-0de4-ae5e-27e85caaace1
[2024-03-23T17:10:28.201801303-05:00] WARN [tp:03d0c4]: Failed to update transport status. error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" timeout=true
[2024-03-23T17:10:28.202213712-05:00] ERROR [dmsgC:disc]: Failed to perform request. endpoint="http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/" error="Post "http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/": dial tcp: lookup dmsgd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:28.202280611-05:00] WARN EntityCommon.delSession [dmsgC]: Callback returned non-nil error. error="Post "http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/": dial tcp: lookup dmsgd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:28.202413423-05:00] DEBUG [dmsgC]: Dialing session... remote_pk=0326978f5a53aff537dbb47fed58b1f123af3b00132d365f1309a14db4168dcff7
[2024-03-23T17:10:28.20252456-05:00] WARN [dmsgC]: Failed to establish session. current_backoff="5s" error="dial tcp 70.121.23.42:9083: connect: network is unreachable" remote_pk=0326978f5a53aff537dbb47fed58b1f123af3b00132d365f1309a14db4168dcff7
[2024-03-23T17:10:29.085197274-05:00] DEBUG [transport_manager]: Deleted 1 unused transport entries
[2024-03-23T17:10:29.19707424-05:00] WARN retrier [tp:03d0c4]: Retrying... current_backoff=2s error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:29.200221251-05:00] DEBUG [tp:03d0c4]: Error deleting transport error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" tp-id=c6e0e33b-3ffb-0de4-ae5e-27e85caaace1
[2024-03-23T17:10:29.200304576-05:00] WARN [tp:03d0c4]: Failed to update transport status. error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" timeout=true
[2024-03-23T17:10:31.198037222-05:00] WARN retrier [tp:03d0c4]: Retrying... current_backoff=4s error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:31.201130619-05:00] DEBUG [tp:03d0c4]: Error deleting transport error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" tp-id=c6e0e33b-3ffb-0de4-ae5e-27e85caaace1
[2024-03-23T17:10:31.201209375-05:00] WARN [tp:03d0c4]: Failed to update transport status. error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" timeout=true
[2024-03-23T17:10:35.198216235-05:00] WARN retrier [tp:03d0c4]: Retrying... current_backoff=8s error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:35.201381347-05:00] DEBUG [tp:03d0c4]: Error deleting transport error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" tp-id=c6e0e33b-3ffb-0de4-ae5e-27e85caaace1
[2024-03-23T17:10:35.201462321-05:00] WARN [tp:03d0c4]: Failed to update transport status. error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" timeout=true
[2024-03-23T17:10:38.813609815-05:00] ERROR (STDERR) [proc:skysocks-client:f40bbfff4dd9439b8cc9381ae716296b]: Copy error: writeto tcp 127.0.0.1:1080->127.0.0.1:48784: connection write timeout
2024/03/23 17:10:42 [ERR] yamux: keepalive failed: i/o deadline reached
[2024-03-23T17:10:42.713906376-05:00] WARN [dmsgC]: Stopped accepting streams. error="keepalive timeout" session=03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5
[2024-03-23T17:10:42.714126216-05:00] DEBUG [dmsgC]: Session stopped. error="failed to serve dialed session to 03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5: keepalive timeout"
[2024-03-23T17:10:42.717575587-05:00] ERROR [dmsgC:disc]: Failed to perform request. endpoint="http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/" error="Post "http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/": dial tcp: lookup dmsgd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:42.717643255-05:00] WARN EntityCommon.delSession [dmsgC]: Callback returned non-nil error. error="Post "http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/": dial tcp: lookup dmsgd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:42.71778831-05:00] DEBUG [dmsgC]: Dialing session... remote_pk=0228af3fd99c8d86a882495c8e0202bdd4da78c69e013065d8634286dd4a0ac098
[2024-03-23T17:10:42.717916084-05:00] WARN [dmsgC]: Failed to establish session. current_backoff="6.5s" error="dial tcp 170.187.225.246:30084: connect: network is unreachable" remote_pk=0228af3fd99c8d86a882495c8e0202bdd4da78c69e013065d8634286dd4a0ac098
[2024-03-23T17:10:43.198870431-05:00] WARN retrier [tp:03d0c4]: Retrying... current_backoff=16s error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:43.201943766-05:00] DEBUG [tp:03d0c4]: Error deleting transport error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" tp-id=c6e0e33b-3ffb-0de4-ae5e-27e85caaace1
[2024-03-23T17:10:43.202019531-05:00] WARN [tp:03d0c4]: Failed to update transport status. error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution" timeout=true
2024/03/23 17:10:44 [ERR] yamux: keepalive failed: i/o deadline reached
[2024-03-23T17:10:44.131607638-05:00] WARN [dmsgC]: Stopped accepting streams. error="keepalive timeout" session=0281a102c82820e811368c8d028cf11b1a985043b726b1bcdb8fce89b27384b2cb
[2024-03-23T17:10:44.135148566-05:00] ERROR [dmsgC:disc]: Failed to perform request. endpoint="http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/" error="Post "http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/": dial tcp: lookup dmsgd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:44.135232155-05:00] WARN EntityCommon.delSession [dmsgC]: Callback returned non-nil error. error="Post "http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/": dial tcp: lookup dmsgd.skywire.skycoin.com: Temporary failure in name resolution"
2024/03/23 17:10:44 [ERR] yamux: keepalive failed: i/o deadline reached
[2024-03-23T17:10:44.99379251-05:00] WARN [dmsgC]: Stopped accepting streams. error="keepalive timeout" session=03717576ada5b1744e395c66c2bb11cea73b0e23d0dcd54422139b1a7f12e962c4
[2024-03-23T17:10:44.99732101-05:00] ERROR [dmsgC:disc]: Failed to perform request. endpoint="http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/" error="Post "http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/": dial tcp: lookup dmsgd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:44.997356797-05:00] WARN EntityCommon.delSession [dmsgC]: Callback returned non-nil error. error="Post "http:https://dmsgd.skywire.skycoin.com/dmsg-discovery/entry/": dial tcp: lookup dmsgd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:49.218887913-05:00] DEBUG [dmsgC]: Dialing session... remote_pk=0371ab4bcff7b121f4b91f6856d6740c6f9dc1fe716977850aeb5d84378b300a13
[2024-03-23T17:10:49.219019091-05:00] WARN [dmsgC]: Failed to establish session. current_backoff="8.45s" error="dial tcp 139.162.160.227:30087: connect: network is unreachable" remote_pk=0371ab4bcff7b121f4b91f6856d6740c6f9dc1fe716977850aeb5d84378b300a13
[2024-03-23T17:10:50.084868121-05:00] DEBUG router.rulesGC [router]: Removed rules. rules_count=2
[2024-03-23T17:10:50.084970818-05:00] DEBUG router.removeRouteGroupOfRule [router]: Closing noise route group associated with rule... rt_desc="rAddr:0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c:49224, lAddr:0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac:3" rule_keyRtID=4 rule_type="Consume"
[2024-03-23T17:10:57.669443393-05:00] DEBUG [dmsgC]: Dialing session... remote_pk=03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5
[2024-03-23T17:10:57.972312842-05:00] DEBUG (STDOUT) [proc:skysocks-client:f40bbfff4dd9439b8cc9381ae716296b]: Accepted skysocks client
[2024-03-23T17:10:58.631636663-05:00] DEBUG [dmsgC]: Updating entry. entry=	version: 0.0.1
	sequence: 3
	registered at: 1711200092767593505
	static public key: 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c
	signature: d60028dc0dfc751423340459347522fc776bdfb3f968da183cc13dcfe37c795d3c2055eba0157d4c4af186165878e62aca94c24a9445dae52606c4ee6399600a01
	entry is registered as client. Related info: 
		delegated servers: 
			03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5


[2024-03-23T17:10:59.151656288-05:00] DEBUG [dmsgC]: Dialing session... remote_pk=02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd
[2024-03-23T17:10:59.151755815-05:00] DEBUG [dmsgC]: Serving session. remote_pk=03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5
[2024-03-23T17:10:59.199756532-05:00] WARN retrier [tp:03d0c4]: Retrying... current_backoff=16s error="Delete "http:https://tpd.skywire.skycoin.com/transports/id:c6e0e33b-3ffb-0de4-ae5e-27e85caaace1": dial tcp: lookup tpd.skywire.skycoin.com: Temporary failure in name resolution"
[2024-03-23T17:10:59.901389015-05:00] DEBUG [dmsgC]: Updating entry. entry=	version: 0.0.1
	sequence: 4
	registered at: 1711231858631784481
	static public key: 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c
	signature: 3d7a74d1535e58a6f729fa285f4354205f8091f33183d0f3c5a41bcbfda45a5533f8faded96251d5ed41c77997e0ecca6d74eae1163d9ebf936eb822c4ec6f4500
	entry is registered as client. Related info: 
		delegated servers: 
			02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd
			03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5


[2024-03-23T17:11:00.402315733-05:00] DEBUG [dmsgC]: Session stopped. error="failed to serve dialed session to 0281a102c82820e811368c8d028cf11b1a985043b726b1bcdb8fce89b27384b2cb: keepalive timeout"
[2024-03-23T17:11:00.402396552-05:00] DEBUG [dmsgC]: Dialing session... remote_pk=02a49bc0aa1b5b78f638e9189be4ed095bac5d6839c828465a8350f80ac07629c0
[2024-03-23T17:11:00.40239992-05:00] DEBUG [dmsgC]: Serving session. remote_pk=02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd
[2024-03-23T17:11:01.158049817-05:00] DEBUG [dmsgC]: Updating entry. entry=	version: 0.0.1
	sequence: 5
	registered at: 1711231859901513714
	static public key: 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c
	signature: 7e26cd9b9cff472c72691dbfe248a1102cfb84e6e24f94da33afdf445cf7fe4a1bf90cc9dbec4a36bf9a3102ce2d5438ae42b30aa9089a828ebf70736fb4695301
	entry is registered as client. Related info: 
		delegated servers: 
			03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5
			02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd
			02a49bc0aa1b5b78f638e9189be4ed095bac5d6839c828465a8350f80ac07629c0


[2024-03-23T17:11:01.659359984-05:00] DEBUG [dmsgC]: Session stopped. error="failed to serve dialed session to 03717576ada5b1744e395c66c2bb11cea73b0e23d0dcd54422139b1a7f12e962c4: keepalive timeout"
[2024-03-23T17:11:01.659435209-05:00] DEBUG [dmsgC]: Discovering dmsg servers...
[2024-03-23T17:11:01.659446881-05:00] DEBUG [dmsgC]: Serving session. remote_pk=02a49bc0aa1b5b78f638e9189be4ed095bac5d6839c828465a8350f80ac07629c0
[2024-03-23T17:11:07.972988976-05:00] DEBUG (STDOUT) [proc:skysocks-client:f40bbfff4dd9439b8cc9381ae716296b]: Closing proxy client
[2024-03-23T17:11:07.973113443-05:00] ERROR (STDERR) [proc:skysocks-client:f40bbfff4dd9439b8cc9381ae716296b]: Session failed, closing skysocks clientError serving proxy client: error opening yamux stream: connection write timeout
[2024-03-23T17:11:07.973196034-05:00] INFO [proc:skysocks-client:f40bbfff4dd9439b8cc9381ae716296b]: App skysocks-client is Stopped
[2024-03-23T17:11:07.978744661-05:00] INFO [proc:skysocks-client:f40bbfff4dd9439b8cc9381ae716296b]: App skysocks-client is Stopped
[2024-03-23T17:12:12.973587973-05:00] ERROR (STDERR) [proc:skysocks-client:f40bbfff4dd9439b8cc9381ae716296b]: 2024/03/23 17:12:12 [ERR] yamux: aborted stream open (destination=0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac:3): i/o deadline reached

image

image

Observations

  • The transport being used was immediately deleted, before anything else happened.
    All transports were removed from the visor immediately on disconnect. (Is this desired behavior?)
  • The visor attempted to delete the transport from TPD but it was not able to because the internet was not connected.
  • on re-connection, the transport was not apparently deleted from TPD (see last line)
[user@linux skywire]$ skywire-cli rtree
Tree        *Online        *Offline        *Not in UT                            TPID                                 Type
└─┬0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c
  ├──03d0c4a4df6fd1db6f9329a8bbfeb6879a171d554afe9bfbdcac5cb9c34f62a2d6          c6e0e33b-3ffb-0de4-ae5e-27e85caaace1 dmsg
  ├──0202037ce4ca982cb8d4b2c1b41df1ccc64ffcf58dfbb38ed0c3c7e41465668545          7b4eda5b-327b-092a-adee-a066430f68ad sudph
  ├──0203522e92b0ee7ea4c860bff55d353025b79fa2d34b198c26699458a5f29118fb          faa48469-5c74-0372-9087-1ccc45a0807f sudph
  ├─┬0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac          247984d4-4a1a-0eda-a67c-9e69bf0fb169 sudph
  • The visor attempts to stay in constant connection to TPD, at least in the case that it has transports
  • The visor attempts to stay in constant connection to dmsg
  • The connection to dmsg was re-established
$ skywire dmsg curl dmsg:https://$(skywire cli visor pk):80/health
{"build_info":{"version":"v1.3.20-rc2","commit":"8e782b1305d75f7052215ad7591726fbd970eaa8","date":"2024-03-21T16:17:12Z"},"started_at":"2024-03-21T11:18:15.084136303-05:00"}

Further Examination

Attempt to re-establish the same transport type to the same visor succeeded

$ skywire-cli visor tp add -t sudph 0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac
[2024-03-23T17:45:56.912743601-05:00] INFO [skywire-cli]: Established sudph transport to 0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac
type      id                                       remote_pk                                                              mode        label
sudph     247984d4-4a1a-0eda-a67c-9e69bf0fb169     0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac     regular     user

Deleting the transport also worked

[DMSGHTTP] 2024/03/23 - 17:27:59 | 200 |      151.18µs |                 | 034f4f56b75877bec27c3fd1bafe3a73d80cd9346f75105d5e59e5170606acf5a1:49153 | GET      /health
[2024-03-23T17:45:55.343786776-05:00] DEBUG [visor]: Saving transport to 0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac via sudph
[2024-03-23T17:45:55.343838087-05:00] DEBUG [transport_manager]: Initializing TP with ID 247984d4-4a1a-0eda-a67c-9e69bf0fb169
[2024-03-23T17:45:55.343927113-05:00] DEBUG [transport_manager]: Dialing transport to 0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac via sudph
[2024-03-23T17:45:55.852389636-05:00] DEBUG [sudph]: Resolved PK 0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac to visor data {104.62.49.99:51817 false {51817 [127.0.0.1 192.168.0.8 ::1]}}
[2024-03-23T17:45:55.852465754-05:00] DEBUG [sudph]: Dialing 104.62.49.99:51817
[2024-03-23T17:45:55.85260025-05:00] DEBUG [sudph]: Dialed 104.62.49.99:51817
[2024-03-23T17:45:55.852639705-05:00] DEBUG [sudph]: Performing handshake with 104.62.49.99:51817
[2024-03-23T17:45:55.95590329-05:00] DEBUG [sudph]: Sent handshake to 104.62.49.99:51817, local addr 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c:49158, remote addr 0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac:45
[2024-03-23T17:45:56.911974834-05:00] DEBUG [tp:038240]: Sent signal to 'mt.transportCh'.
[2024-03-23T17:45:56.912064985-05:00] DEBUG [transport_manager]: saved transport: remote(0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac) type(sudph) tpID(247984d4-4a1a-0eda-a67c-9e69bf0fb169)
[2024-03-23T17:45:56.912111222-05:00] DEBUG [visor]: Saved transport to 0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac via sudph, label user
[2024-03-23T17:45:56.912264423-05:00] DEBUG [tp:038240]: Serving. remote_pk=0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac tp_id=247984d4-4a1a-0eda-a67c-9e69bf0fb169 tp_index=1
[2024-03-23T17:47:43.054053654-05:00] DEBUG [tp:038240]: Stopped log loop
[2024-03-23T17:47:43.054098998-05:00] DEBUG [tp:038240]: Stopped serving. remaining_tps=0 remote_pk=0382406ebecec832a1c27dece7cf58425a1c98753c7b3be8428d4414eada0986ac tp_id=247984d4-4a1a-0eda-a67c-9e69bf0fb169 tp_index=1
[2024-03-23T17:47:43.054072049-05:00] DEBUG readPacket [tp:038240]: Failed to read packet header. error="io: read/write on closed pipe"
[2024-03-23T17:47:43.054155162-05:00] WARN [tp:038240]: Failed to read packet, closing transport error="io: read/write on closed pipe" src="read_loop"
[2024-03-23T17:47:43.532505515-05:00] DEBUG [tp:038240]: Error deleting transport error=<nil> tp-id=247984d4-4a1a-0eda-a67c-9e69bf0fb169

Deleting transports that TPD says this visor has but which this visor does not have does not work

Further observation of the behavior of remote visors when transports fail is needed
@0pcom
Copy link
Collaborator Author

0pcom commented Mar 24, 2024

a transport from machine 1 was established to machine 2

$ skywire-cli visor tp ls
type      id                                       remote_pk                                                              mode        label
sudph     eada53a2-6afb-05c7-aeea-6b804e798401     03c758a0daabab4b4bbd524cf46306212818b051b9d92949bd8acdf6226aad32e6     regular     user

The machine 1 was left alone, and machine 2 was shut down, gracefully.

Upon returning to machine 1, the transport which had been established still existed (see above)

However, the entry for that transport did not exist in TPD and had been removed, apparently at the time the other machine was shut down.

No indication of any error or change in the visor debug logging for machine 1 was observed

[2024-03-23T19:26:08.412471062-05:00] DEBUG [visor]: Saving transport to 03c758a0daabab4b4bbd524cf46306212818b051b9d92949bd8acdf6226aad32e6 via sudph
[2024-03-23T19:26:08.41251521-05:00] DEBUG [transport_manager]: Initializing TP with ID eada53a2-6afb-05c7-aeea-6b804e798401
[2024-03-23T19:26:08.412626422-05:00] DEBUG [transport_manager]: Dialing transport to 03c758a0daabab4b4bbd524cf46306212818b051b9d92949bd8acdf6226aad32e6 via sudph
[2024-03-23T19:26:08.932671941-05:00] DEBUG [sudph]: Resolved PK 03c758a0daabab4b4bbd524cf46306212818b051b9d92949bd8acdf6226aad32e6 to visor data {70.121.23.42:60843 false {60843 [127.0.0.1 192.168.2.130 ::1]}}
[2024-03-23T19:26:08.932749682-05:00] DEBUG [sudph]: Dialing 70.121.23.42:60843
[2024-03-23T19:26:08.932903284-05:00] DEBUG [sudph]: Dialed 70.121.23.42:60843
[2024-03-23T19:26:08.932946149-05:00] DEBUG [sudph]: Performing handshake with 70.121.23.42:60843
[2024-03-23T19:26:08.941792824-05:00] DEBUG [sudph]: Sent handshake to 70.121.23.42:60843, local addr 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c:49159, remote addr 03c758a0daabab4b4bbd524cf46306212818b051b9d92949bd8acdf6226aad32e6:45
[2024-03-23T19:26:09.532743874-05:00] DEBUG [tp:03c758]: Sent signal to 'mt.transportCh'.
[2024-03-23T19:26:09.532832613-05:00] DEBUG [transport_manager]: saved transport: remote(03c758a0daabab4b4bbd524cf46306212818b051b9d92949bd8acdf6226aad32e6) type(sudph) tpID(eada53a2-6afb-05c7-aeea-6b804e798401)
[2024-03-23T19:26:09.532866677-05:00] DEBUG [visor]: Saved transport to 03c758a0daabab4b4bbd524cf46306212818b051b9d92949bd8acdf6226aad32e6 via sudph, label user
[2024-03-23T19:26:09.532933277-05:00] DEBUG [tp:03c758]: Serving. remote_pk=03c758a0daabab4b4bbd524cf46306212818b051b9d92949bd8acdf6226aad32e6 tp_id=eada53a2-6afb-05c7-aeea-6b804e798401 tp_index=1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@0pcom