The visor will now attempt to create a dmsg transport to itself 1 minute after the visor has started, and this check will be repeated every 5 minutes, immediately removing it if it can be created.
On a failed attempt, the next checks will be performed in 1 minute intervals, resetting to 5 minutes on a successful transport creation attempt.
On 3 failed attempts to establish this transport, the visor will be shut down.
This assumes the visor will be restarted by the init daemon / external process control.
The systemd service in the packages will unconditionally restart the visor if the process exits.
$ skywire visor -p --loglvl debug
...
[2024-04-13T05:58:31.795761057-05:00] DEBUG [stun_client]: Initialized.
[2024-04-13T05:58:31.795881416-05:00] DEBUG [transport_manager]: Serving sudph network
[2024-04-13T05:58:31.795930249-05:00] DEBUG [transport_manager]: listening on network: sudph
[2024-04-13T05:58:31.795986618-05:00] DEBUG [sudph]: Initialized.
[2024-04-13T05:58:31.796022836-05:00] DEBUG [transports]: Initialized.
[2024-04-13T05:58:31.796152477-05:00] DEBUG [transportable]: Initialized.
[2024-04-13T05:58:31.796209011-05:00] DEBUG [sudph]: Binding
[2024-04-13T05:58:31.797505684-05:00] DEBUG [ping]: Initialized.
[2024-04-13T05:58:31.797657107-05:00] DEBUG [ping]: Accepting sky ping conn...
[2024-04-13T05:58:31.797708858-05:00] DEBUG [visor]: Initialized.
[2024-04-13T05:58:31.797768265-05:00] INFO [visor:startup]: Startup complete.
[2024-04-13T05:58:31.824368558-05:00] DEBUG httpClient.BindSUDPR [address_resolver]: SUDPH Local port: 34771
[2024-04-13T05:58:32.30899368-05:00] DEBUG [sudph]: Successfully bound sudph to port 34771
[2024-04-13T05:58:32.309099527-05:00] DEBUG [sudph]: listening on addr: [::]:34771
[2024-04-13T06:03:31.796441369-05:00] DEBUG [visor]: Saving transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:03:31.79656667-05:00] DEBUG [transport_manager]: Initializing TP with ID 5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:03:31.796828252-05:00] DEBUG [transport_manager]: Dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:03:32.480425547-05:00] DEBUG [transport_manager]: recv transport request: type(dmsg) remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c)
[2024-04-13T06:03:32.48052235-05:00] DEBUG [transport_manager]: No TP found, creating new one
[2024-04-13T06:03:32.480702813-05:00] DEBUG [tp:032327]: Performing settlement handshake...
[2024-04-13T06:03:32.480782479-05:00] DEBUG [tp:032327]: Serving. remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=1
[2024-04-13T06:03:33.235615294-05:00] DEBUG [tp:032327]: Setting underlying transport...
[2024-04-13T06:03:33.235681611-05:00] DEBUG [tp:032327]: Sent signal to 'mt.transportCh'.
[2024-04-13T06:03:33.235739803-05:00] DEBUG [transport_manager]: accepted tp: type(dmsg) remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c) tpID(5bacb16f-79c4-0d39-aaff-9a82ced5192a) new(true)
[2024-04-13T06:03:33.368828537-05:00] DEBUG [tp:032327]: Sent signal to 'mt.transportCh'.
[2024-04-13T06:03:33.368941516-05:00] DEBUG [transport_manager]: saved transport: remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c) type(dmsg) tpID(5bacb16f-79c4-0d39-aaff-9a82ced5192a)
[2024-04-13T06:03:33.368990283-05:00] DEBUG [visor]: Saved transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg, label user
[2024-04-13T06:03:33.369129882-05:00] DEBUG [tp:032327]: Serving. remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=2
[2024-04-13T06:03:33.369263937-05:00] DEBUG [tp:032327]: Stopped log loop
[2024-04-13T06:03:33.369324872-05:00] DEBUG [tp:032327]: Stopped serving. remaining_tps=1 remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=2
[2024-04-13T06:03:33.369373775-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="transport is no longer being served" src="read_loop"
[2024-04-13T06:03:33.499176898-05:00] DEBUG readPacket [tp:032327]: Failed to read packet header. error="EOF"
[2024-04-13T06:03:33.499269225-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2024-04-13T06:03:33.499377003-05:00] DEBUG [tp:032327]: Stopped log loop
[2024-04-13T06:03:33.499448858-05:00] DEBUG [tp:032327]: Stopped serving. remaining_tps=0 remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=1
[2024-04-13T06:03:33.860455045-05:00] DEBUG [tp:032327]: Error deleting transport error=<nil> tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:03:34.347566839-05:00] DEBUG [tp:032327]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:08:31.796600403-05:00] DEBUG [visor]: Saving transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:08:31.796752186-05:00] DEBUG [transport_manager]: Initializing TP with ID 5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:08:31.796971979-05:00] DEBUG [transport_manager]: Dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:08:32.759436562-05:00] DEBUG [transport_manager]: recv transport request: type(dmsg) remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c)
[2024-04-13T06:08:32.75950108-05:00] DEBUG [transport_manager]: No TP found, creating new one
[2024-04-13T06:08:32.759614001-05:00] DEBUG [tp:032327]: Performing settlement handshake...
[2024-04-13T06:08:32.759668514-05:00] DEBUG [tp:032327]: Serving. remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=1
[2024-04-13T06:08:33.55400538-05:00] DEBUG [tp:032327]: Setting underlying transport...
[2024-04-13T06:08:33.554098575-05:00] DEBUG [tp:032327]: Sent signal to 'mt.transportCh'.
[2024-04-13T06:08:33.554168706-05:00] DEBUG [transport_manager]: accepted tp: type(dmsg) remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c) tpID(5bacb16f-79c4-0d39-aaff-9a82ced5192a) new(true)
[2024-04-13T06:08:33.690531095-05:00] DEBUG [tp:032327]: Sent signal to 'mt.transportCh'.
[2024-04-13T06:08:33.690754058-05:00] DEBUG [transport_manager]: saved transport: remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c) type(dmsg) tpID(5bacb16f-79c4-0d39-aaff-9a82ced5192a)
[2024-04-13T06:08:33.690860496-05:00] DEBUG [visor]: Saved transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg, label user
[2024-04-13T06:08:33.690859155-05:00] DEBUG [tp:032327]: Serving. remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=2
[2024-04-13T06:08:33.691142078-05:00] DEBUG [tp:032327]: Stopped log loop
[2024-04-13T06:08:33.691190696-05:00] DEBUG [tp:032327]: Stopped serving. remaining_tps=1 remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=2
[2024-04-13T06:08:33.691269268-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="transport is no longer being served" src="read_loop"
[2024-04-13T06:08:33.826224693-05:00] DEBUG readPacket [tp:032327]: Failed to read packet header. error="EOF"
[2024-04-13T06:08:33.82637314-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2024-04-13T06:08:33.826530208-05:00] DEBUG [tp:032327]: Stopped log loop
[2024-04-13T06:08:33.826608783-05:00] DEBUG [tp:032327]: Stopped serving. remaining_tps=0 remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=1
[2024-04-13T06:08:34.165086186-05:00] DEBUG [tp:032327]: Error deleting transport error=<nil> tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:08:34.6819493-05:00] DEBUG [tp:032327]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
The self transports are demonstrated here to occur every 5 minutes
The simple test of manually establishing and removing a self-transport in a scripted loop was performed in order to test / verify the exit behavior. The visor does exit successfully in this instance, however an unexpected error was generated during this test
[2024-04-13T06:23:33.362030735-05:00] ERROR [tp:032327]: Failed to register transport. error="500 Internal Server Error: {"error":"ERROR: duplicate key value violates unique constraint \"transports_transport_id_key\" (SQLSTATE 23505)"}"
visor debug logging showing the process exit when the visor is not transportable
[2024-04-13T06:23:30.795420446-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2024-04-13T06:23:30.925461442-05:00] DEBUG readPacket [tp:032327]: Failed to read packet header. error="EOF"
[2024-04-13T06:23:30.925539685-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2024-04-13T06:23:30.925627328-05:00] DEBUG [tp:032327]: Stopped log loop
[2024-04-13T06:23:30.925681957-05:00] DEBUG [tp:032327]: Stopped serving. remaining_tps=0 remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=1
[2024-04-13T06:23:31.295102277-05:00] DEBUG [tp:032327]: Error deleting transport error=<nil> tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:23:31.462833279-05:00] DEBUG [visor]: Saving transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:23:31.462881442-05:00] DEBUG [transport_manager]: Initializing TP with ID 5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:23:31.462971758-05:00] DEBUG [transport_manager]: Dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:23:31.783145118-05:00] DEBUG [tp:032327]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:23:31.796287103-05:00] DEBUG [visor]: Saving transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:23:31.796422414-05:00] DEBUG [transport_manager]: Initializing TP with ID 5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:23:31.79665763-05:00] DEBUG [transport_manager]: Dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:23:32.098864316-05:00] DEBUG [transport_manager]: recv transport request: type(dmsg) remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c)
[2024-04-13T06:23:32.098927015-05:00] DEBUG [transport_manager]: No TP found, creating new one
[2024-04-13T06:23:32.099086053-05:00] DEBUG [tp:032327]: Performing settlement handshake...
[2024-04-13T06:23:32.099153091-05:00] DEBUG [tp:032327]: Serving. remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=1
[2024-04-13T06:23:32.867606929-05:00] DEBUG [tp:032327]: Setting underlying transport...
[2024-04-13T06:23:32.867673971-05:00] DEBUG [tp:032327]: Sent signal to 'mt.transportCh'.
[2024-04-13T06:23:32.867727302-05:00] DEBUG [transport_manager]: accepted tp: type(dmsg) remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c) tpID(5bacb16f-79c4-0d39-aaff-9a82ced5192a) new(true)
[2024-04-13T06:23:32.867778957-05:00] DEBUG [transport_manager]: recv transport request: type(dmsg) remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c)
[2024-04-13T06:23:32.867833226-05:00] DEBUG [transport_manager]: TP found, accepting...
[2024-04-13T06:23:32.867879966-05:00] DEBUG [tp:032327]: Performing settlement handshake...
[2024-04-13T06:23:33.009967695-05:00] DEBUG [tp:032327]: Sent signal to 'mt.transportCh'.
[2024-04-13T06:23:33.010088145-05:00] DEBUG [tp:032327]: Serving. remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=2
[2024-04-13T06:23:33.362030735-05:00] ERROR [tp:032327]: Failed to register transport. error="500 Internal Server Error: {"error":"ERROR: duplicate key value violates unique constraint \"transports_transport_id_key\" (SQLSTATE 23505)"}"
[2024-04-13T06:23:33.362208494-05:00] DEBUG [tp:032327]: Setting underlying transport...
[2024-04-13T06:23:33.362254902-05:00] DEBUG [tp:032327]: Underlying transport already exists, closing new transport.
[2024-04-13T06:23:33.362343934-05:00] WARN [transport_manager]: Failed to accept transport error="underlying transport already exists"
[2024-04-13T06:23:33.362410625-05:00] DEBUG [transport_manager]: saved transport: remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c) type(dmsg) tpID(5bacb16f-79c4-0d39-aaff-9a82ced5192a)
[2024-04-13T06:23:33.362461593-05:00] DEBUG [visor]: Saved transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg, label user
[2024-04-13T06:23:33.493315376-05:00] DEBUG [tp:032327]: Sent signal to 'mt.transportCh'.
[2024-04-13T06:23:33.493373561-05:00] DEBUG [transport_manager]: saved transport: remote(0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c) type(dmsg) tpID(5bacb16f-79c4-0d39-aaff-9a82ced5192a)
[2024-04-13T06:23:33.493414409-05:00] DEBUG [visor]: Saved transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg, label user
[2024-04-13T06:23:33.493422702-05:00] DEBUG [tp:032327]: Serving. remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=3
[2024-04-13T06:23:33.493494935-05:00] DEBUG [tp:032327]: Stopped log loop
[2024-04-13T06:23:33.493512975-05:00] DEBUG [tp:032327]: Stopped serving. remaining_tps=2 remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=3
[2024-04-13T06:23:33.493550029-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="transport is no longer being served" src="read_loop"
[2024-04-13T06:23:33.981744656-05:00] DEBUG [tp:032327]: Error deleting transport error=<nil> tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:23:34.147786997-05:00] DEBUG [visor]: Saving transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:23:34.147823582-05:00] DEBUG [transport_manager]: Initializing TP with ID 5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:23:34.147899012-05:00] DEBUG [transport_manager]: Dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:23:54.916452686-05:00] DEBUG [transport_manager]: Error dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg: settlement handshake failed: context deadline exceeded
[2024-04-13T06:23:55.398538895-05:00] DEBUG [tp:032327]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:28:31.796417795-05:00] DEBUG [visor]: Saving transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:28:31.796543861-05:00] DEBUG [transport_manager]: Initializing TP with ID 5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:28:31.796748076-05:00] DEBUG [transport_manager]: Dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:28:52.605441871-05:00] DEBUG [transport_manager]: Error dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg: settlement handshake failed: context deadline exceeded
[2024-04-13T06:28:53.099059225-05:00] DEBUG [tp:032327]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:28:53.099164574-05:00] WARN [transportable]: Visor is not transportable! Attempt of 3 error="save transport: settlement handshake failed: context deadline exceeded"
[2024-04-13T06:33:31.796580111-05:00] DEBUG [visor]: Saving transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:33:31.796734148-05:00] DEBUG [transport_manager]: Initializing TP with ID 5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:33:31.796972442-05:00] DEBUG [transport_manager]: Dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:33:52.595406325-05:00] DEBUG [transport_manager]: Error dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg: settlement handshake failed: context deadline exceeded
[2024-04-13T06:33:53.099501554-05:00] DEBUG [tp:032327]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:33:53.099631343-05:00] WARN [transportable]: Visor is not transportable! Attempt of 3 error="save transport: settlement handshake failed: context deadline exceeded"
[2024-04-13T06:38:31.796438682-05:00] DEBUG [visor]: Saving transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:38:31.796567973-05:00] DEBUG [transport_manager]: Initializing TP with ID 5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:38:31.796731941-05:00] DEBUG [transport_manager]: Dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg
[2024-04-13T06:38:52.579873685-05:00] DEBUG [transport_manager]: Error dialing transport to 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c via dmsg: settlement handshake failed: context deadline exceeded
[2024-04-13T06:38:53.082181355-05:00] DEBUG [tp:032327]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:38:53.082280698-05:00] WARN [transportable]: Visor is not transportable! Attempt of 3 error="save transport: settlement handshake failed: context deadline exceeded"
[2024-04-13T06:38:53.082318336-05:00] ERROR [transportable]: Visor is not transportable! 3 failed attempts ; exiting now error="save transport: settlement handshake failed: context deadline exceeded"
[2024-04-13T06:38:53.08236433-05:00] INFO [visor:shutdown]: Begin shutdown.
[2024-04-13T06:38:53.082400289-05:00] DEBUG [17/17] [visor:shutdown:skywire_ping]: Shutting down module...
[2024-04-13T06:38:53.082463204-05:00] DEBUG [17/17] [visor:shutdown:skywire_ping]: Module stopped cleanly. elapsed=68.014µs
[2024-04-13T06:38:53.082507457-05:00] DEBUG [16/17] [visor:shutdown:transportable]: Shutting down module...
[2024-04-13T06:38:53.082542351-05:00] DEBUG [16/17] [visor:shutdown:transportable]: Module stopped cleanly. elapsed=40.191µs
[2024-04-13T06:38:53.082578565-05:00] DEBUG [15/17] [visor:shutdown:sky_forwarding]: Shutting down module...
[2024-04-13T06:38:53.082613337-05:00] DEBUG [15/17] [visor:shutdown:sky_forwarding]: Module stopped cleanly. elapsed=37.929µs
[2024-04-13T06:38:53.08264691-05:00] DEBUG [14/17] [visor:shutdown:dmsgctrl]: Shutting down module...
[2024-04-13T06:38:53.082682669-05:00] DEBUG [14/17] [visor:shutdown:dmsgctrl]: Module stopped cleanly. elapsed=38.701µs
[2024-04-13T06:38:53.082717403-05:00] DEBUG [13/17] [visor:shutdown:launcher.proc_manager]: Shutting down module...
[2024-04-13T06:38:53.083196535-05:00] INFO [proc:skychat:73e59f87b24b4d01966b204f44c5215e]: App skychat is Stopped
[2024-04-13T06:38:53.094124797-05:00] DEBUG [proc_manager]: App stopped successfully. app_name="skychat"
[2024-04-13T06:38:53.094953305-05:00] DEBUG (STDOUT) [proc:skysocks:056f3e6859eb4777922f2a030779eb5b]: Failed to accept skysocks connection, but server is closed: listening on closed connection
[2024-04-13T06:38:53.095008429-05:00] INFO [proc:skysocks:056f3e6859eb4777922f2a030779eb5b]: App skysocks is Stopped
[2024-04-13T06:38:53.588465224-05:00] DEBUG [app_discovery]: Entry deleted successfully appName="skysocks" entry={"address":"0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c:3","geo":{"country":"US","lat":33.14,"lon":-96.75,"region":"TX"},"type":"skysocks","version":"v1.3.20-rc2-8-g722cdcd60"}
[2024-04-13T06:38:53.588667196-05:00] DEBUG [proc_manager]: App stopped successfully. app_name="skysocks"
[2024-04-13T06:38:53.588764106-05:00] DEBUG [13/17] [visor:shutdown:launcher.proc_manager]: Module stopped cleanly. elapsed=506.048616ms
[2024-04-13T06:38:53.588823839-05:00] DEBUG [12/17] [visor:shutdown:router.serve]: Shutting down module...
[2024-04-13T06:38:53.588891377-05:00] DEBUG [router]: Closing all App connections and RouteGroups
[2024-04-13T06:38:53.589003927-05:00] DEBUG [12/17] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=191.456µs
[2024-04-13T06:38:53.589014421-05:00] DEBUG serveRouteGroup [launcher]: Stopped accepting routes. _=skynet error="accept skynet: use of closed network connection"
[2024-04-13T06:38:53.589069936-05:00] DEBUG [11/17] [visor:shutdown:dmsghttp.logserver]: Shutting down module...
[2024-04-13T06:38:53.589048245-05:00] DEBUG [router]: Setup client stopped serving. error="dmsg error 200 - local entity closed"
[2024-04-13T06:38:53.589239543-05:00] ERROR [dmsghttp_logserver]: Logserver exited with error. error="http: Server closed"
[2024-04-13T06:38:53.589395604-05:00] DEBUG [11/17] [visor:shutdown:dmsghttp.logserver]: Module stopped cleanly. elapsed=330.84µs
[2024-04-13T06:38:53.589449266-05:00] DEBUG [10/17] [visor:shutdown:transport_setup.rpc]: Shutting down module...
[2024-04-13T06:38:53.589499946-05:00] DEBUG [10/17] [visor:shutdown:transport_setup.rpc]: Module stopped cleanly. elapsed=56.256µs
[2024-04-13T06:38:53.589544517-05:00] DEBUG [9/17] [visor:shutdown:transport.manager]: Shutting down module...
[2024-04-13T06:38:53.589514796-05:00] DEBUG [transport_setup]: Dmsg client stopped serving. error="dmsg error 200 - local entity closed"
[2024-04-13T06:38:53.589647099-05:00] DEBUG [stcp]: Cleanly stopped serving.
[2024-04-13T06:38:53.589738092-05:00] DEBUG httpClient.delBindSUDPH [address_resolver]: Deleted bind pk: 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c from Address resolver successfully
[2024-04-13T06:38:53.589746652-05:00] DEBUG [sudph]: Cleanly stopped serving.
[2024-04-13T06:38:53.58994776-05:00] DEBUG [address_resolver]: SUDPH conn closed on shutdown message: use of closed network connection
[2024-04-13T06:38:53.59009559-05:00] DEBUG [9/17] [visor:shutdown:transport.manager]: Module stopped cleanly. elapsed=553.669µs
[2024-04-13T06:38:53.590154463-05:00] DEBUG [8/17] [visor:shutdown:uptime_tracker]: Shutting down module...
[2024-04-13T06:38:53.590116129-05:00] DEBUG [router]: Stopped reading packets error="transport is no longer being served"
[2024-04-13T06:38:53.590192331-05:00] DEBUG [8/17] [visor:shutdown:uptime_tracker]: Module stopped cleanly. elapsed=44.112µs
[2024-04-13T06:38:53.59032969-05:00] DEBUG [7/17] [visor:shutdown:router.serve]: Shutting down module...
[2024-04-13T06:38:53.59044441-05:00] DEBUG [dmsg_pty:cli-server]: Cleanly stopped serving.
[2024-04-13T06:38:53.590525469-05:00] DEBUG [7/17] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=199.8µs
[2024-04-13T06:38:53.590585064-05:00] DEBUG [6/17] [visor:shutdown:router.serve]: Shutting down module...
[2024-04-13T06:38:53.59064298-05:00] DEBUG [dmsg_pty]: Serve() ended. error=<nil>
[2024-04-13T06:38:53.590757922-05:00] DEBUG [dmsg_pty]: Cleanly stopped serving. error="dmsg error 200 - local entity closed"
[2024-04-13T06:38:53.590846052-05:00] DEBUG [6/17] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=266.7µs
[2024-04-13T06:38:53.590903518-05:00] DEBUG [5/17] [visor:shutdown:dmsg_tracker_manager]: Shutting down module...
[2024-04-13T06:38:53.59099071-05:00] DEBUG [5/17] [visor:shutdown:dmsg_tracker_manager]: Module stopped cleanly. elapsed=93.863µs
[2024-04-13T06:38:53.59104812-05:00] DEBUG [4/17] [visor:shutdown:dmsg]: Shutting down module...
[2024-04-13T06:38:53.591109517-05:00] DEBUG [dmsgC]: Stopped serving client!
[2024-04-13T06:38:53.59113749-05:00] DEBUG [dmsgC]: Stopped accepting streams. error="session shutdown" session=02a49bc0aa1b5b78f638e9189be4ed095bac5d6839c828465a8350f80ac07629c0
[2024-04-13T06:38:53.591218612-05:00] DEBUG readPacket [tp:032327]: Failed to read packet header. error="EOF"
[2024-04-13T06:38:53.59127773-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2024-04-13T06:38:53.591254423-05:00] DEBUG readPacket [tp:032327]: Failed to read packet header. error="EOF"
[2024-04-13T06:38:53.591411874-05:00] WARN [tp:032327]: Failed to read packet, closing transport error="EOF" src="read_loop"
[2024-04-13T06:38:53.591194702-05:00] DEBUG [dmsgC]: Session closed. error=<nil>
[2024-04-13T06:38:53.591413132-05:00] DEBUG [tp:032327]: Stopped log loop
[2024-04-13T06:38:53.591623321-05:00] DEBUG [tp:032327]: Stopped serving. remaining_tps=1 remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=2
[2024-04-13T06:38:53.591590448-05:00] DEBUG [dmsgC]: Stopped accepting streams. error="session shutdown" session=03717576ada5b1744e395c66c2bb11cea73b0e23d0dcd54422139b1a7f12e962c4
[2024-04-13T06:38:53.591505602-05:00] DEBUG [tp:032327]: Stopped log loop
[2024-04-13T06:38:53.591809775-05:00] DEBUG [tp:032327]: Stopped serving. remaining_tps=0 remote_pk=0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c tp_id=5bacb16f-79c4-0d39-aaff-9a82ced5192a tp_index=1
[2024-04-13T06:38:53.591642199-05:00] DEBUG [dmsgC]: Session closed. error=<nil>
[2024-04-13T06:38:53.591911887-05:00] DEBUG [dmsgC]: All sessions closed.
[2024-04-13T06:38:54.062314817-05:00] DEBUG [dmsgC]: Deleting entry. entry= version: 0.0.1
sequence: 1
registered at: 1713005904076565161
static public key: 0323272a60895f56aad82cb767fb5c413807adcf7c9fb0578b1b1c5807c7f29d4c
signature: a1079dd9dc9a4573d510f37471ad91247f962adf5e55771b63bb889a78ce41913dbb372a8d8e601294cefda2a493382ed3d27d892971bdeeac4c772ab4d270e600
entry is registered as client. Related info:
delegated servers:
02a49bc0aa1b5b78f638e9189be4ed095bac5d6839c828465a8350f80ac07629c0
03717576ada5b1744e395c66c2bb11cea73b0e23d0dcd54422139b1a7f12e962c4
[2024-04-13T06:38:54.079104158-05:00] DEBUG [tp:032327]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=5bacb16f-79c4-0d39-aaff-9a82ced5192a
[2024-04-13T06:38:54.541904428-05:00] DEBUG [dmsgC]: Entry Deleted successfully.
[2024-04-13T06:38:54.541998643-05:00] DEBUG [4/17] [visor:shutdown:dmsg]: Module stopped cleanly. elapsed=950.954166ms
[2024-04-13T06:38:54.542064728-05:00] DEBUG [3/17] [visor:shutdown:cli.listener]: Shutting down module...
2024/04/13 06:38:54 rpc.Serve: accept:accept tcp 127.0.0.1:3435: use of closed network connection
[2024-04-13T06:38:54.542194111-05:00] DEBUG [3/17] [visor:shutdown:cli.listener]: Module stopped cleanly. elapsed=142.252µs
[2024-04-13T06:38:54.542243684-05:00] DEBUG [2/17] [visor:shutdown:address_resolver]: Shutting down module...
[2024-04-13T06:38:54.542287603-05:00] DEBUG [2/17] [visor:shutdown:address_resolver]: Module stopped cleanly. elapsed=51.346µs
[2024-04-13T06:38:54.542329981-05:00] DEBUG [1/17] [visor:shutdown:event_broadcaster]: Shutting down module...
[2024-04-13T06:38:54.542375747-05:00] DEBUG [1/17] [visor:shutdown:event_broadcaster]: Module stopped cleanly. elapsed=49.204µs
[2024-04-13T06:38:54.542410662-05:00] INFO [visor:shutdown]: Shutdown complete. Goodbye!
The visor will now attempt to create a dmsg transport to itself 1 minute after the visor has started, and this check will be repeated every 5 minutes, immediately removing it if it can be created.
On a failed attempt, the next checks will be performed in 1 minute intervals, resetting to 5 minutes on a successful transport creation attempt.
On 3 failed attempts to establish this transport, the visor will be shut down.
This assumes the visor will be restarted by the init daemon / external process control. The systemd service in the packages will unconditionally restart the visor if the process exits.
Temporary fix for https://github.com/skycoin/skywire/issues/1803
The self transports are demonstrated here to occur every 5 minutes
The simple test of manually establishing and removing a self-transport in a scripted loop was performed in order to test / verify the exit behavior. The visor does exit successfully in this instance, however an unexpected error was generated during this test
visor debug logging showing the process exit when the visor is not transportable