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

̶U̶n̶f̶o̶r̶c̶e̶d̶ ̶e̶x̶i̶t̶ rpc requests causing panic on startup #1492

Closed
0pcom opened this issue Feb 18, 2023 · 0 comments · Fixed by #1671
Closed

̶U̶n̶f̶o̶r̶c̶e̶d̶ ̶e̶x̶i̶t̶ rpc requests causing panic on startup #1492

0pcom opened this issue Feb 18, 2023 · 0 comments · Fixed by #1671
Labels
bug Something isn't working

Comments

@0pcom
Copy link
Collaborator

0pcom commented Feb 18, 2023 •
edited
Loading

̶M̶y̶ ̶g̶u̶e̶s̶s̶ ̶i̶s̶ ̶t̶h̶a̶t̶ ̶t̶h̶e̶ ̶c̶o̶n̶f̶i̶g̶ ̶i̶s̶ ̶l̶e̶f̶t̶ ̶i̶n̶ ̶a̶ ̶m̶o̶d̶i̶f̶i̶e̶d̶ ̶s̶t̶a̶t̶e̶ ̶i̶n̶ ̶c̶e̶r̶t̶a̶i̶n̶ ̶i̶n̶s̶t̶a̶n̶c̶e̶s̶,̶ ̶s̶o̶ ̶t̶h̶a̶t̶ ̶t̶h̶e̶ ̶v̶i̶s̶o̶r̶ ̶c̶a̶n̶'̶t̶ ̶s̶t̶a̶r̶t̶ ̶a̶g̶a̶i̶n̶s̶t̶ ̶i̶t̶.̶
̶R̶e̶g̶e̶n̶e̶r̶a̶t̶i̶n̶g̶ ̶t̶h̶e̶ ̶c̶o̶n̶f̶i̶g̶ ̶s̶e̶e̶m̶s̶ ̶t̶o̶ ̶s̶o̶l̶v̶e̶ ̶t̶h̶e̶ ̶i̶s̶s̶u̶e̶.̶
the panic shown was caused by

watch -n 1 skywire-cli visor tp ls

running in a terminal in the background while attempting to start skywire
...
For reference, the script I was running

#!/usr/bin/bash
set -x
[[ -f visor-tp.txt ]] && rm visor-tp.txt
[[ -f visor-tps.txt ]] && rm visor-tps.txt
[[ -f tptypes.txt ]] && rm tptypes.txt
echo "stcp" | tee -a tptypes.txt ; echo "stcpr" | tee -a tptypes.txt ; echo "sudph" | tee -a tptypes.txt ; echo  "dmsg" | tee -a tptypes.txt
[[ ! -f uptimes.json ]] && curl https://ut.skywire.skycoin.com/uptimes | jq | tee uptimes.json
(($(($(date +%s) - $(date +%s -r "uptimes.json"))) < 3600)) && echo "uptimes.json is recent.. age: $(($(date +%s) - $(date +%s -r "uptimes.json"))) seconds" || curl https://ut.skywire.skycoin.com/uptimes | jq | tee uptimes.json
[[ "$(skywire-cli visor tp ls | tail -n1 | awk '{print $2}')" != "id" ]] && skywire-cli visor tp rm $(skywire-cli visor tp ls | tail -n1 | awk '{print $2}')
#tac oldvisors.txt | while read _i ; do
cat uptimes.json | grep key | cut -d '"' -f 4  | while read _i ; do
#  [[ "$(skywire-cli visor tp ls | tail -n1 | awk '{print $2}')" != "id" ]] && [[ "$(skywire-cli visor tp ls | tail -n1 | awk '{print $2}')" != "" ]] && skywire-cli visor tp rm $(skywire-cli visor tp ls | tail -n1 | awk '{print $2}')
  if [[ "$(curl -L https://ut.skywire.skycoin.com/uptimes?visors=$_i | grep true)" == *"true"* ]] ; then
    echo "skywire-cli visor tp add $_i" | tee visor-tp.txt
    parallel -a tptypes.txt "unbuffer skywire-cli visor tp add -t {} $_i | tee -a visor-tp.txt"
#    skywire-cli visor tp add -t skywire-tcp $_i | tee -a visor-tp.txt
    [[ "$(skywire-cli visor tp ls | grep skywire-tcp | grep $_i | awk '{print $2}')" != "" ]] && skywire-cli visor tp rm $(skywire-cli visor tp ls | grep skywire-tcp | grep $_i | awk '{print $2}')
#    skywire-cli visor tp add -t stcpr $_i | tee -a visor-tp.txt
    [[ "$(skywire-cli visor tp ls | grep stcpr | grep $_i | awk '{print $2}')" != "" ]] && skywire-cli visor tp rm $(skywire-cli visor tp ls | grep stcpr | grep $_i | awk '{print $2}')
#    skywire-cli visor tp add -t sudph $_i | tee -a visor-tp.txt
    [[ "$(skywire-cli visor tp ls | grep sudph | grep $_i | awk '{print $2}')" != "" ]] && skywire-cli visor tp rm $(skywire-cli visor tp ls | grep sudph | grep $_i | awk '{print $2}')
#    skywire-cli visor tp add -t dmsg $_i | tee -a visor-tp.txt
    [[ "$(skywire-cli visor tp ls | grep dmsg | grep $_i | awk '{print $2}')" != "" ]] && skywire-cli visor tp rm $(skywire-cli visor tp ls | grep dmsg | grep $_i | awk '{print $2}')
    cat visor-tp.txt | grep -v remote_pk | grep -v '^"$' | grep -v '00000000-0000-0000-0000-000000000000' | grep 'FATAL' | while read _j ; do
      echo "$_i $_j" | tee -a visor-tps.txt
    done
    cat visor-tp.txt | grep -v remote_pk | grep -v '^"$' | grep -v '00000000-0000-0000-0000-000000000000' | grep -v 'FATAL' | tee -a visor-tps.txt
  fi
done

I exited the script. I exited the visor. I restarted the visor, redirecting the output to a file, which in itself should not have caused an issue


[2023-02-18T10:47:23-06:00] DEBUG [tp:0203a1]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=9c4bc3ca-a29e-0489-9f3c-8665d42c93df
^C[2023-02-18T10:47:24-06:00] INFO []: Closing with received signal. signal=interrupt
[2023-02-18T10:47:24-06:00] INFO [proc:vpn-server:fb67be679a8c4be29a90436f5264373c]: App vpn-server is Stopped
[2023-02-18T10:47:24-06:00] DEBUG serveRouteGroup [launcher]: Stopped accepting routes. _=skynet error="context canceled"
[2023-02-18T10:47:24-06:00] INFO [proc:skychat:98f9edaff5eb4beaa5c6c9a20b2efcf7]: App skychat is Stopped
[2023-02-18T10:47:24-06:00] INFO [visor:shutdown]: Begin shutdown.
[2023-02-18T10:47:24-06:00] DEBUG [transport_setup]: Dmsg client stopped serving. error="dmsg error 200 - local entity closed"
[2023-02-18T10:47:24-06:00] DEBUG [transport_manager]: Error dialing transport to 02dafe8a05e335a91f23fe55f0e5da66be47fcffe7c4448fb888962c93f10b3d15 via stcpr: mt.client.Dial: dial tcp 45.63.99.70:39896: operation was canceled
[2023-02-18T10:47:24-06:00] DEBUG (STDOUT) [proc:skysocks:5207fd978d3d457ca1a923b31323b5cb]: Failed to accept skysocks connection, but server is closed: listening on closed connection
[2023-02-18T10:47:24-06:00] DEBUG (STDOUT) [proc:vpn-server:fb67be679a8c4be29a90436f5264373c]: Set IPv4 forwarding = 1
[2023-02-18T10:47:24-06:00] INFO [proc:skysocks:5207fd978d3d457ca1a923b31323b5cb]: App skysocks is Stopped
[2023-02-18T10:47:24-06:00] ERROR [launcher]: serveRouteGroup stopped unexpectedly. _=skynet error="context canceled"
[2023-02-18T10:47:24-06:00] DEBUG [18/18] [visor:shutdown:hypervisor]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG (STDOUT) [proc:vpn-server:fb67be679a8c4be29a90436f5264373c]: Set IPv6 forwarding = 1
[2023-02-18T10:47:24-06:00] DEBUG [18/18] [visor:shutdown:hypervisor]: Module stopped cleanly. elapsed=13.638124ms
[2023-02-18T10:47:24-06:00] DEBUG (STDOUT) [proc:vpn-server:fb67be679a8c4be29a90436f5264373c]: Disabled IP masquerading for eno1
[2023-02-18T10:47:24-06:00] DEBUG [17/18] [visor:shutdown:skywire_ping]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [17/18] [visor:shutdown:skywire_ping]: Module stopped cleanly. elapsed=3.368227ms
[2023-02-18T10:47:24-06:00] DEBUG [16/18] [visor:shutdown:sky_forwarding]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [16/18] [visor:shutdown:sky_forwarding]: Module stopped cleanly. elapsed=3.139032ms
[2023-02-18T10:47:24-06:00] DEBUG [15/18] [visor:shutdown:dmsgctrl]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG (STDOUT) [proc:vpn-server:fb67be679a8c4be29a90436f5264373c]: Restored iptables forward policy to ACCEPT
[2023-02-18T10:47:24-06:00] DEBUG [15/18] [visor:shutdown:dmsgctrl]: Module stopped cleanly. elapsed=2.909554ms
[2023-02-18T10:47:24-06:00] DEBUG [14/18] [visor:shutdown:uptime_tracker]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [14/18] [visor:shutdown:uptime_tracker]: Module stopped cleanly. elapsed=2.724567ms
[2023-02-18T10:47:24-06:00] DEBUG [13/18] [visor:shutdown:launcher.proc_manager]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [proc_manager]: App stopped successfully. app_name="skysocks"
[2023-02-18T10:47:24-06:00] DEBUG [proc_manager]: App stopped successfully. app_name="vpn-server"
[2023-02-18T10:47:24-06:00] DEBUG [13/18] [visor:shutdown:launcher.proc_manager]: Module stopped cleanly. elapsed=9.088136ms
[2023-02-18T10:47:24-06:00] DEBUG [12/18] [visor:shutdown:transport_setup.rpc]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [12/18] [visor:shutdown:transport_setup.rpc]: Module stopped cleanly. elapsed=2.979278ms
[2023-02-18T10:47:24-06:00] DEBUG [11/18] [visor:shutdown:router.serve]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [router]: Closing all App connections and RouteGroups
[2023-02-18T10:47:24-06:00] DEBUG [11/18] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=5.981177ms
[2023-02-18T10:47:24-06:00] DEBUG [router]: Setup client stopped serving. error="dmsg error 200 - local entity closed"
[2023-02-18T10:47:24-06:00] DEBUG [10/18] [visor:shutdown:dmsghttp.logserver]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [10/18] [visor:shutdown:dmsghttp.logserver]: Module stopped cleanly. elapsed=3.707246ms
[2023-02-18T10:47:24-06:00] DEBUG [9/18] [visor:shutdown:public_autoconnect]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [9/18] [visor:shutdown:public_autoconnect]: Module stopped cleanly. elapsed=3.154841ms
[2023-02-18T10:47:24-06:00] DEBUG [8/18] [visor:shutdown:transport.manager]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [sudph]: Cleanly stopped serving.
[2023-02-18T10:47:24-06:00] DEBUG [stcp]: Cleanly stopped serving.
[2023-02-18T10:47:24-06:00] DEBUG httpClient.delBindSUDPH [address_resolver]: Deleted bind pk: 024b774d2115af59051cde18ed2ef9206fbb9cee572c3660e4445e21f4cf6cf906 from Address resolver successfully
[2023-02-18T10:47:24-06:00] DEBUG [address_resolver]: SUDPH conn closed on shutdown message: use of closed network connection
[2023-02-18T10:47:24-06:00] DEBUG [router]: Stopped reading packets error="transport is no longer being served"
[2023-02-18T10:47:24-06:00] DEBUG [8/18] [visor:shutdown:transport.manager]: Module stopped cleanly. elapsed=9.421752ms
[2023-02-18T10:47:24-06:00] DEBUG [7/18] [visor:shutdown:router.serve]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [dmsg_pty:cli-server]: Cleanly stopped serving.
[2023-02-18T10:47:24-06:00] DEBUG [7/18] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=6.028216ms
[2023-02-18T10:47:24-06:00] DEBUG [6/18] [visor:shutdown:router.serve]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [dmsg_pty]: Serve() ended. error=<nil>
[2023-02-18T10:47:24-06:00] DEBUG [dmsg_pty]: Cleanly stopped serving. error="dmsg error 200 - local entity closed"
[2023-02-18T10:47:24-06:00] DEBUG [6/18] [visor:shutdown:router.serve]: Module stopped cleanly. elapsed=7.426043ms
[2023-02-18T10:47:24-06:00] DEBUG [5/18] [visor:shutdown:dmsg_tracker_manager]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [5/18] [visor:shutdown:dmsg_tracker_manager]: Module stopped cleanly. elapsed=3.107402ms
[2023-02-18T10:47:24-06:00] DEBUG [4/18] [visor:shutdown:cli.listener]: Shutting down module...
2023/02/18 10:47:24 rpc.Serve: accept:accept tcp 127.0.0.1:3435: use of closed network connection
[2023-02-18T10:47:24-06:00] DEBUG [4/18] [visor:shutdown:cli.listener]: Module stopped cleanly. elapsed=3.167963ms
[2023-02-18T10:47:24-06:00] DEBUG [3/18] [visor:shutdown:dmsg]: Shutting down module...
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Stopped serving client!
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Stopped accepting streams. error="session shutdown" session=03717576ada5b1744e395c66c2bb11cea73b0e23d0dcd54422139b1a7f12e962c4
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Session closed. error=<nil>
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Session closed. error=<nil>
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Stopped accepting streams. error="session shutdown" session=03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Stopped accepting streams. error="session shutdown" session=0281a102c82820e811368c8d028cf11b1a985043b726b1bcdb8fce89b27384b2cb
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Session closed. error=<nil>
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Stopped accepting streams. error="session shutdown" session=02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Session closed. error=<nil>
[2023-02-18T10:47:24-06:00] DEBUG ClientSession.DialStream [dmsgC]: Stream closed on failure. close_error=<nil> dst_addr=0203a15284a9bec61e9804b69f9ed16c545324c996f59c39b9bb434236768041cd:45 error="EOF" session=02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Stopped accepting streams. error="session shutdown" session=02a49bc0aa1b5b78f638e9189be4ed095bac5d6839c828465a8350f80ac07629c0
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Session closed. error=<nil>
[2023-02-18T10:47:24-06:00] DEBUG [transport_manager]: Error dialing transport to 0203a15284a9bec61e9804b69f9ed16c545324c996f59c39b9bb434236768041cd via dmsg: mt.client.Dial: EOF
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Session closed. error=<nil>
[2023-02-18T10:47:24-06:00] DEBUG [dmsgC]: Stopped accepting streams. error="session shutdown" session=0371ab4bcff7b121f4b91f6856d6740c6f9dc1fe716977850aeb5d84378b300a13
[2023-02-18T10:47:25-06:00] DEBUG [dmsgC]: All sessions closed.
[2023-02-18T10:47:25-06:00] DEBUG [transport_manager]: Dmsg client stopped serving. error="dmsg error 200 - local entity closed"
[2023-02-18T10:47:25-06:00] DEBUG [visor]: Dmsg client stopped serving. error="dmsg error 200 - local entity closed"
[2023-02-18T10:47:25-06:00] DEBUG [tp:02dafe]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=7843c709-f17c-0da9-9f55-b28f06953bbe
[2023-02-18T10:47:25-06:00] WARN [public_autoconnect]: Failed to add transport to public visor error="save transport: mt.client.Dial: dial tcp 45.63.99.70:39896: operation was canceled" pk=02dafe8a05e335a91f23fe55f0e5da66be47fcffe7c4448fb888962c93f10b3d15 type="stcpr"
[2023-02-18T10:47:25-06:00] DEBUG [public_autoconnect]: Trying to add transport to public visor attempt=0 pk=02116cf99f36260bbb1fbf39c321f29127547422ae0c0ded5ec398d6c0b9e2b641
[2023-02-18T10:47:25-06:00] INFO [public_autoconnect]: Fetching public visors
[2023-02-18T10:47:25-06:00] ERROR [public_autoconnect]: Cannot fetch public services: context canceled
[2023-02-18T10:47:25-06:00] DEBUG [app_discovery]: Entry deleted successfully appName="skysocks" entry={"address":"024b774d2115af59051cde18ed2ef9206fbb9cee572c3660e4445e21f4cf6cf906:3","geo":{"country":"US","lat":33.14,"lon":-96.75,"region":"TX"},"type":"skysocks","version":"unknown"}
[2023-02-18T10:47:25-06:00] DEBUG [dmsgC]: Deleting entry. entry=	version: 0.0.1
	sequence: 5
	registered at: 1676738661631699736
	static public key: 024b774d2115af59051cde18ed2ef9206fbb9cee572c3660e4445e21f4cf6cf906
	signature: 32543858eeae792f65256130ee91731f0e9fcbae1dc415d9c0d9a7ab7994db08346ef7784f1ccbffd28d3d33d85590fffb51109ba8286e8ea5f8ea0b688cf55300
	entry is registered as client. Related info: 
		delegated servers: 
			03717576ada5b1744e395c66c2bb11cea73b0e23d0dcd54422139b1a7f12e962c4
			03d5b55d1133b26485c664cf8b95cff6746d1e321c34e48c9fed293eff0d6d49e5
			0281a102c82820e811368c8d028cf11b1a985043b726b1bcdb8fce89b27384b2cb
			02a2d4c346dabd165fd555dfdba4a7f4d18786fe7e055e562397cd5102bdd7f8dd
			02a49bc0aa1b5b78f638e9189be4ed095bac5d6839c828465a8350f80ac07629c0
			0371ab4bcff7b121f4b91f6856d6740c6f9dc1fe716977850aeb5d84378b300a13


[2023-02-18T10:47:25-06:00] DEBUG [tp:0203a1]: Error deleting transport error="404 Not Found: {"error":"transport not found"}" tp-id=94bfee51-f038-0c3e-b712-26faf865ae20
[2023-02-18T10:47:25-06:00] DEBUG [app_discovery]: Entry deleted successfully appName="vpn-server" entry={"address":"024b774d2115af59051cde18ed2ef9206fbb9cee572c3660e4445e21f4cf6cf906:44","geo":{"country":"US","lat":33.14,"lon":-96.75,"region":"TX"},"type":"vpn","version":"unknown"}
[2023-02-18T10:47:25-06:00] DEBUG [dmsgC]: Entry Deleted successfully.
[2023-02-18T10:47:26-06:00] DEBUG [3/18] [visor:shutdown:dmsg]: Module stopped cleanly. elapsed=1.030570992s
[2023-02-18T10:47:26-06:00] DEBUG [2/18] [visor:shutdown:address_resolver]: Shutting down module...
[2023-02-18T10:47:26-06:00] DEBUG [2/18] [visor:shutdown:address_resolver]: Module stopped cleanly. elapsed=3.226594ms
[2023-02-18T10:47:26-06:00] DEBUG [1/18] [visor:shutdown:event_broadcaster]: Shutting down module...
[2023-02-18T10:47:26-06:00] DEBUG [1/18] [visor:shutdown:event_broadcaster]: Module stopped cleanly. elapsed=3.11591ms
[2023-02-18T10:47:26-06:00] INFO [visor:shutdown]: Shutdown complete. Goodbye!
[user@linux ~]$ sudo unbuffer skywire -p --loglvl debug | tee skywire.out
[sudo] password for user: 
[2023-02-18T10:47:45-06:00] INFO [visor:config]: filepath="/opt/skywire/skywire.json"
[2023-02-18T10:47:45-06:00] INFO []: setting log level to: debug
[2023-02-18T10:47:45-06:00] INFO [visor:startup]: Begin startup. public_key=024b774d2115af59051cde18ed2ef9206fbb9cee572c3660e4445e21f4cf6cf906
[2023-02-18T10:47:45-06:00] INFO [visor:startup]: main module set to hypervisor
[2023-02-18T10:47:45-06:00] DEBUG [hypervisor]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [visor]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [transports]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [address_resolver]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [launcher]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [dmsg_http]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [dmsg_http]: Initialized.
[2023-02-18T10:47:45-06:00] DEBUG [discovery]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [uptime_tracker]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [address_resolver]: Remote UDP server: "ar.skywire.skycoin.com:30178"
[2023-02-18T10:47:45-06:00] DEBUG [dmsg_ctrl]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [system_survey]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [transport]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [dmsghttp_logserver]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [address_resolver]: Initialized.
[2023-02-18T10:47:45-06:00] DEBUG [dmsg_trackers]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [event_broadcaster]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [dmsg]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [discovery]: Initialized.
[2023-02-18T10:47:45-06:00] DEBUG [hypervisors]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [dmsg_pty]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [stun_client]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [stcp]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [stcpr]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [router]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [ping]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [public_autoconnect]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [cli]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [event_broadcaster]: Initialized.
[2023-02-18T10:47:45-06:00] DEBUG [sky_forward_conn]: Starting
[2023-02-18T10:47:45-06:00] DEBUG disc.NewHTTP [dmsgC:disc]: Created HTTP client. addr="http://dmsgd.skywire.skycoin.com"
[2023-02-18T10:47:45-06:00] DEBUG [public_visor]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [transport_setup]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [sudph]: Starting
[2023-02-18T10:47:45-06:00] DEBUG [dmsg]: Initialized.
[2023-02-18T10:47:45-06:00] DEBUG [dmsgC]: Discovering dmsg servers...
[2023-02-18T10:47:45-06:00] DEBUG [hypervisors]: Initialized.
[2023-02-18T10:47:45-06:00] DEBUG [dmsg_pty]: Initialized.
[2023-02-18T10:47:45-06:00] DEBUG [dmsg_trackers]: Initialized.
[2023-02-18T10:47:45-06:00] DEBUG [cli]: Initialized.
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x48 pc=0x9c7aad]

goroutine 179 [running]:
github.com/skycoin/skywire/pkg/transport.(*Manager).WalkTransports(0x0, 0xc0000cb670)
	github.com/skycoin/skywire/pkg/transport/manager.go:509 +0x2d
github.com/skycoin/skywire/pkg/visor.(*Visor).Transports(0x12e1290?, {0x0?, 0xd80f45?, 0xa?}, {0x0?, 0xc00012a200?, 0x0?}, 0x0?)
	github.com/skycoin/skywire/pkg/visor/api.go:961 +0xf6
github.com/skycoin/skywire/pkg/visor.(*RPC).Transports(0xc00028a3c0, 0xc00012a200, 0xc00011a420)
	github.com/skycoin/skywire/pkg/visor/rpc.go:449 +0x150
reflect.Value.call({0xc000116840?, 0xc00011e0b8?, 0x0?}, {0xd79a01, 0x4}, {0xc000321ef8, 0x3, 0x0?})
	reflect/value.go:584 +0x8c5
reflect.Value.Call({0xc000116840?, 0xc00011e0b8?, 0x203000?}, {0xc000321ef8?, 0xd3d020?, 0x12d7d30?})
	reflect/value.go:368 +0xbc
net/rpc.(*service).call(0xc0002ca0c0, 0xc0002f3000?, 0x12d11e0?, 0xc000282280, 0xc000160400, 0xc000321fd0?, {0xc39a60?, 0xc00012a200?, 0x7f911eab9a98?}, {0xc31b20, ...}, ...)
	net/rpc/server.go:382 +0x226
created by net/rpc.(*Server).ServeCodec
	net/rpc/server.go:479 +0x3fe
[user@linux ~]$ sudo unbuffer skywire -p --loglvl debug | tee skywire.out
[2023-02-18T10:47:52-06:00] INFO [visor:config]: filepath="/opt/skywire/skywire.json"
[2023-02-18T10:47:52-06:00] INFO []: setting log level to: debug
[2023-02-18T10:47:52-06:00] INFO [visor:startup]: Begin startup. public_key=024b774d2115af59051cde18ed2ef9206fbb9cee572c3660e4445e21f4cf6cf906
[2023-02-18T10:47:52-06:00] INFO [visor:startup]: main module set to hypervisor
[2023-02-18T10:47:52-06:00] DEBUG [hypervisor]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [visor]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [transports]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [launcher]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [event_broadcaster]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [discovery]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [dmsghttp_logserver]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [public_visor]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [stun_client]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [cli]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [transport_setup]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [hypervisors]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [dmsg_http]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [stcp]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [dmsg_http]: Initialized.
[2023-02-18T10:47:52-06:00] DEBUG [sky_forward_conn]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [transport]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [discovery]: Initialized.
[2023-02-18T10:47:52-06:00] DEBUG [sudph]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [dmsg]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [stcpr]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [ping]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [dmsg_ctrl]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [dmsg_trackers]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [system_survey]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [dmsg_pty]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [router]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [uptime_tracker]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [event_broadcaster]: Initialized.
[2023-02-18T10:47:52-06:00] DEBUG [address_resolver]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [address_resolver]: Remote UDP server: "ar.skywire.skycoin.com:30178"
[2023-02-18T10:47:52-06:00] DEBUG [address_resolver]: Initialized.
[2023-02-18T10:47:52-06:00] DEBUG disc.NewHTTP [dmsgC:disc]: Created HTTP client. addr="http://dmsgd.skywire.skycoin.com"
[2023-02-18T10:47:52-06:00] DEBUG [public_autoconnect]: Starting
[2023-02-18T10:47:52-06:00] DEBUG [dmsg]: Initialized.
[2023-02-18T10:47:52-06:00] DEBUG [dmsgC]: Discovering dmsg servers...
[2023-02-18T10:47:52-06:00] DEBUG [dmsg_trackers]: Initialized.
[2023-02-18T10:47:52-06:00] DEBUG [hypervisors]: Initialized.
[2023-02-18T10:47:52-06:00] DEBUG [dmsg_pty]: Initialized.
[2023-02-18T10:47:52-06:00] DEBUG [cli]: Initialized.
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x48 pc=0x9c7aad]

goroutine 166 [running]:
github.com/skycoin/skywire/pkg/transport.(*Manager).WalkTransports(0x0, 0xc0003d5670)
	github.com/skycoin/skywire/pkg/transport/manager.go:509 +0x2d
github.com/skycoin/skywire/pkg/visor.(*Visor).Transports(0x12e1290?, {0x0?, 0xd80f45?, 0xa?}, {0x0?, 0xc0000363c0?, 0x0?}, 0x0?)
	github.com/skycoin/skywire/pkg/visor/api.go:961 +0xf6
github.com/skycoin/skywire/pkg/visor.(*RPC).Transports(0xc00035ab60, 0xc0000363c0, 0xc000012258)
	github.com/skycoin/skywire/pkg/visor/rpc.go:449 +0x150
reflect.Value.call({0xc00012b560?, 0xc000128918?, 0x13?}, {0xd79a01, 0x4}, {0xc000409ef8, 0x3, 0x3?})
	reflect/value.go:584 +0x8c5
reflect.Value.Call({0xc00012b560?, 0xc000128918?, 0x203000?}, {0xc00052fef8?, 0xd3d020?, 0x12d7d30?})
	reflect/value.go:368 +0xbc
net/rpc.(*service).call(0xc0002bdd00, 0xc0001ed000?, 0x12d11e0?, 0xc0003b80b0, 0xc000197000, 0xc00052ffd0?, {0xc39a60?, 0xc0000363c0?, 0x7fd9ccab8628?}, {0xc31b20, ...}, ...)
	net/rpc/server.go:382 +0x226
created by net/rpc.(*Server).ServeCodec
	net/rpc/server.go:479 +0x3fe
[user@linux ~]$ sudo skywire-autoconfig
 -> Configuring skywire
 --> Generating skywire config with command:
skywire-cli config gen -bepr -x -i  --servevpn     
 --> Skywire configuration updated
config path: /opt/skywire/skywire.json
 -> Start the skywire service with:
	systemctl start skywire

I never approved the idea of the visor writing to its own config, and worked to minimize this as much as possible.

This is only the immediately visible portion of a much larger issue.
Any changes made in the hypervisor UI for such things as app autostart or persistent transports are not currently persisted across update cycles or even running default config gen, or the scripted generation of that command used by skywire-autoconfig.

Efforts were made to set some things separately in an env file, however, this may require a different implementation

the reward setting uses its own file and is persisted.
@0pcom 0pcom added the bug Something isn't working label Feb 18, 2023
@0pcom 0pcom changed the title Unforced exit causing panic on startup ̶U̶n̶f̶o̶r̶c̶e̶d̶ ̶e̶x̶i̶t̶ rpc requests causing panic on startup Feb 18, 2023
@0pcom 0pcom mentioned this issue Jun 6, 2023
Closed
@mrpalide mrpalide mentioned this issue Nov 2, 2023
Merged
@mrpalide mrpalide linked a pull request Nov 2, 2023 that will close this issue
Fix two panic issues on skywire-cli commands #1671
Merged
@jdknives jdknives closed this as completed Nov 2, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix two panic issues on skywire-cli commands mrpalide/skywire
2 participants
@jdknives @0pcom