Visor hangs on shutdown with ctrl+C

[0pcom]

ctrl+z is not the right way to shut it down as it leaves the process running in the background and only recovers the terminal.

tested with develop branch on linux

[0pcom]

I've just reproduced this while using a local deployment

[2023-06-12T10:35:50.679143765-05:00] DEBUG httpClient.BindSUDPR [address_resolver]: SUDPH Local port: 51397
[2023-06-12T10:35:50.846783574-05:00] DEBUG dtm.establishTracker [dmsg_tracker_manager]: Dmsgtracker client Established. client_pk=02cf226af53dc6e507dc12a7a444b76d9aa7bfbd48b5f83a8124af76e14f78e39a
[2023-06-12T10:36:00.868716273-05:00] ERROR [sudph]: Failed to listen on port: handshake failed: timeout

[2023-06-12T10:36:06.430628405-05:00] DEBUG [visor]: Saving transport to 027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed via dmsg
[2023-06-12T10:36:06.430705887-05:00] DEBUG [transport_manager]: Initializing TP with ID 23757e5e-7767-035a-819d-5c523c7cbedf
[2023-06-12T10:36:06.430854497-05:00] DEBUG [transport_manager]: Dialing transport to 027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed via dmsg
[2023-06-12T10:36:06.714541548-05:00] DEBUG [tp:027087]: Sent signal to 'mt.transportCh'.
[2023-06-12T10:36:06.714624859-05:00] DEBUG [transport_manager]: saved transport: remote(027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed) type(dmsg) tpID(23757e5e-7767-035a-819d-5c523c7cbedf)
[2023-06-12T10:36:06.714742849-05:00] DEBUG [visor]: Saved transport to 027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed via dmsg, label user
[2023-06-12T10:36:06.714758793-05:00] DEBUG [tp:027087]: Serving. remote_pk=027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed tp_id=23757e5e-7767-035a-819d-5c523c7cbedf tp_index=1
[2023-06-12T10:36:16.636218072-05:00] DEBUG [visor]: Saving transport to 027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed via sudph
[2023-06-12T10:36:16.636345363-05:00] DEBUG [transport_manager]: Initializing TP with ID 4a65da91-8c87-070d-bc3f-99a0444b7a20
[2023-06-12T10:36:16.636536375-05:00] DEBUG [transport_manager]: Dialing transport to 027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed via sudph
[2023-06-12T10:36:16.927248714-05:00] DEBUG [transport_manager]: Error dialing transport to 027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed via sudph: mt.client.Dial: resolve PK: no entry for this PK
[2023-06-12T10:36:17.609262384-05:00] DEBUG [tp:027087]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=4a65da91-8c87-070d-bc3f-99a0444b7a20
[2023-06-12T10:36:40.288442875-05:00] DEBUG [dmsgC]: Discovering dmsg servers...
^C[2023-06-12T10:52:46.452827432-05:00] INFO []: Closing with received signal. signal=interrupt
[2023-06-12T10:52:46.452998335-05:00] DEBUG [transport_setup]: Dmsg client stopped serving. error="dmsg error 200 - local entity closed"
[2023-06-12T10:52:46.453021952-05:00] INFO [visor:shutdown]: Begin shutdown.
[2023-06-12T10:52:46.453163896-05:00] DEBUG [17/17] [visor:shutdown:hypervisor]: Shutting down module...
[2023-06-12T10:52:46.453329925-05:00] DEBUG [17/17] [visor:shutdown:hypervisor]: Module stopped cleanly. elapsed=172.515µs
[2023-06-12T10:52:46.453387976-05:00] DEBUG [16/17] [visor:shutdown:skywire_ping]: Shutting down module...
[2023-06-12T10:52:46.453444211-05:00] DEBUG [16/17] [visor:shutdown:skywire_ping]: Module stopped cleanly. elapsed=61.104µs
[2023-06-12T10:52:46.453487989-05:00] DEBUG [15/17] [visor:shutdown:sky_forwarding]: Shutting down module...
[2023-06-12T10:52:46.453536423-05:00] DEBUG [15/17] [visor:shutdown:sky_forwarding]: Module stopped cleanly. elapsed=53.967µs
[2023-06-12T10:52:46.453573947-05:00] DEBUG [14/17] [visor:shutdown:dmsgctrl]: Shutting down module...
[2023-06-12T10:52:46.4536166-05:00] DEBUG [14/17] [visor:shutdown:dmsgctrl]: Module stopped cleanly. elapsed=47.877µs
[2023-06-12T10:52:46.453648052-05:00] DEBUG [13/17] [visor:shutdown:uptime_tracker]: Shutting down module...
[2023-06-12T10:52:46.453687482-05:00] DEBUG [13/17] [visor:shutdown:uptime_tracker]: Module stopped cleanly. elapsed=44.344µs
[2023-06-12T10:52:46.453732627-05:00] DEBUG [12/17] [visor:shutdown:launcher.proc_manager]: Shutting down module...
[2023-06-12T10:52:46.453336828-05:00] DEBUG (STDOUT) [proc:skysocks:db650f3771534df89ce585a7e3cef188]: Failed to accept skysocks connection, but server is closed: listening on closed connection
[2023-06-12T10:52:46.45344863-05:00] INFO [proc:skysocks:db650f3771534df89ce585a7e3cef188]: App skysocks is Stopped
[2023-06-12T10:52:46.660319046-05:00] DEBUG [app_discovery]: Entry deleted successfully appName="skysocks" entry={"address":"02cf226af53dc6e507dc12a7a444b76d9aa7bfbd48b5f83a8124af76e14f78e39a:3","geo":{"country":"US","lat":33.14,"lon":-96.75,"region":"TX"},"type":"skysocks","version":"v1.3.10-9-g9ec059dc"}
[2023-06-12T10:52:46.6605305-05:00] DEBUG [proc_manager]: App stopped successfully. app_name="skysocks"
[2023-06-12T10:52:46.660652216-05:00] DEBUG [12/17] [visor:shutdown:launcher.proc_manager]: Module stopped cleanly. elapsed=206.914298ms
[2023-06-12T10:52:46.660744181-05:00] DEBUG [11/17] [visor:shutdown:dmsghttp.logserver]: Shutting down module...
[2023-06-12T10:52:46.66087716-05:00] DEBUG [11/17] [visor:shutdown:dmsghttp.logserver]: Module stopped cleanly. elapsed=144.713µs
[2023-06-12T10:52:46.660932255-05:00] DEBUG [10/17] [visor:shutdown:router.serve]: Shutting down module...
[2023-06-12T10:52:46.661037035-05:00] DEBUG [router]: Closing all App connections and RouteGroups
[2023-06-12T10:52:46.66117221-05:00] DEBUG serveRouteGroup [launcher]: Stopped accepting routes. _=skynet error="accept skynet: use of closed network connection"
[2023-06-12T10:52:46.6611791-05:00] DEBUG [router]: Setup client stopped serving. error="dmsg error 200 - local entity closed"
[2023-06-12T10:52:46.661194325-05:00] DEBUG [10/17] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=262.55µs
[2023-06-12T10:52:46.661464022-05:00] DEBUG [9/17] [visor:shutdown:transport_setup.rpc]: Shutting down module...
[2023-06-12T10:52:46.661605283-05:00] DEBUG [9/17] [visor:shutdown:transport_setup.rpc]: Module stopped cleanly. elapsed=151.889µs
[2023-06-12T10:52:46.661658536-05:00] DEBUG [8/17] [visor:shutdown:transport.manager]: Shutting down module...
[2023-06-12T10:52:46.661831278-05:00] DEBUG [tp:027087]: Stopped log loop
[2023-06-12T10:52:46.661891479-05:00] DEBUG [tp:027087]: Stopped serving. remaining_tps=0 remote_pk=027087fe40d97f7f0be4a0dc768462ddbb371d4b9e7679d4f11f117d757b9856ed tp_id=23757e5e-7767-035a-819d-5c523c7cbedf tp_index=1
[2023-06-12T10:52:46.661957662-05:00] DEBUG readPacket [tp:027087]: Failed to read packet header. error="EOF"
[2023-06-12T10:52:46.66203597-05:00] WARN [tp:027087]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2023-06-12T10:52:46.829949696-05:00] DEBUG [tp:027087]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=23757e5e-7767-035a-819d-5c523c7cbedf
[2023-06-12T10:52:46.830099208-05:00] DEBUG [stcp]: Cleanly stopped serving.

But in fact shutdown is never reached and the process won't exit with ctrl+C

the operative error / cause seems to be:

[2023-06-12T10:36:00.868716273-05:00] ERROR [sudph]: Failed to listen on port: handshake failed: timeout

This seems to be a deployment-related issue for my deployment, so it won't necessarily affect the skywire production deployment but it could