Supervisor problem in dev mode?

[Troy Farrell]

Hi Sandstormers,

I would like someone to confirm that I'm not losing my mind.  I'm trying to port a new application and not getting any response from the grain.  Running vagrant-spk dev gives me the normal message:

App is now available from Sandstorm server at:

    http://local.sandstorm.io:6090

Ctrl+C to disconnect.

The new grain never responds.  Instead, I see this in the grain console:

...** SANDSTORM SUPERVISOR: Starting up grain. Sandbox type: userns

and this in my process tree ($ ps ef):

 1188 pts/0    Ss+    0:00 spk dev --pkg-def=/opt/app/.sandstorm/sandstorm-pkgdef.capnp:pkgdef SSH_CONNECTION=10.0.2.2 53990 10.0.2.15 22 LANG=en_US.UTF-8 XDG
 1202 pts/0    Z+     0:00  \_ [sandstorm] <defunct>

I'm not doing anything different from the many other apps that I've ported.  The launcher.sh script results in a working app when I run it from vagrant-spk vm ssh.  Any ideas?

Thanks!

Troy

[Ian Denhardt]

Anything interesting in sandstorm.log?

Quoting Troy Farrell (2022-01-24 07:49:00)

> --
> You received this message because you are subscribed to the Google
> Groups "Sandstorm Development" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to [1]sandstorm-de...@googlegroups.com.
> To view this discussion on the web visit
> [2]https://groups.google.com/d/msgid/sandstorm-dev/9562f402-b2b8-4083-9
> 7d1-01cc207f651an%40googlegroups.com.
>
> Verweise
>
> 1. mailto:sandstorm-de...@googlegroups.com
> 2. https://groups.google.com/d/msgid/sandstorm-dev/9562f402-b2b8-4083-97d1-01cc207f651an%40googlegroups.com?utm_medium=email&utm_source=footer

[Troy Farrell]

Great question!  I forgot to check the log.  When I run vagrant-spk dev, I see these entries added to sandstorm.log:

** Accepted new dev session connection...
Unhandled exception in Promise:  [Error: remote exception: grain is not running] {
  cppFile: '(remote)',
  line: 0,
  kjType: 'disconnected'
}
Unhandled exception in Promise:  [Error: remote exception: grain is not running] {
  cppFile: '(remote)',
  line: 0,
  kjType: 'disconnected'
}
Unhandled exception in Promise:  [Error: remote exception: grain is not running] {
  cppFile: '(remote)',
  line: 0,
  kjType: 'disconnected'
}

When I press CTRL + C to stop the dev session, I see these entries added to sandstorm.log:

Unhandled exception in Promise:  [Error: remote exception: grain is not running] {
  cppFile: '(remote)',
  line: 0,
  kjType: 'disconnected'
}
Unhandled exception in Promise:  [Error: remote exception: grain is not running] {
  cppFile: '(remote)',
  line: 0,
  kjType: 'disconnected'
}
Unhandled exception in Promise:  [Error: remote exception: grain is not running] {
  cppFile: '(remote)',
  line: 0,
  kjType: 'disconnected'
}

I don't see any clues as to which promises have unhandled exceptions.

[Ian Denhardt]

Quoting Troy Farrell (2022-01-24 20:06:51)

> I don't see any clues as to which promises have unhandled exceptions.

I assume these are just the exceptions that are thrown by outstanding
capnp rpc calls into the grain when it shuts down.

Bizzare. Is the code for this somewhere for me to try to reproduce?

[Troy Farrell]

On Monday, January 24, 2022 at 7:14:26 PM UTC-6 Ian wrote:

Quoting Troy Farrell (2022-01-24 20:06:51)

> I don't see any clues as to which promises have unhandled exceptions.

I assume these are just the exceptions that are thrown by outstanding
capnp rpc calls into the grain when it shuts down.

Based upon my observations of the log when I reproduce it, I think that you're right.

Bizzare. Is the code for this somewhere for me to try to reproduce?

I see the same problem when I use any of my projects with vagrant-spk.  To be clear, I'm seeing it with a Node.js + sandstorm-http-bridge project, a Python + sandstorm-http-bridge project and a Rust + Cap'n Proto API project.  I just duplicated the problem with this repository: https://github.com/troyjfarrell/sandstorm-rawapi-example-rust

Steps to reproduce:

0. % uname -a
   Darwin Troys-MacBook-Pro.local 20.6.0 Darwin Kernel Version 20.6.0: Wed Nov 10 22:23:07 PST 2021; root:xnu-7195.141.14~1/RELEASE_X86_64 x86_64
   % python -V
   3.10.0
   % git -C ~/Projects/sandstorm-io/vagrant-spk log --format=oneline -n 1
   f9d0fddca04c63c3cb1fb64a555decc5ab42821f (HEAD -> master) Merge pull request #322 from sandstorm-io/update-mysql-key
   % vagrant --version
   Vagrant 2.2.19
   % VirtualBox --help
   Oracle VM VirtualBox VM Selector v6.1.32
   …
1. % git clone https://github.com/troyjfarrell/sandstorm-rawapi-example-rust
2. % cd sandstorm-rawapi-example-rust
   % python ~/Projects/sandstorm-io/vagrant-spk/vagrant-spk vm up
   …lots of downloading and compiling…
   ==> default: Your virtual server is running at http://local.sandstorm.io:6090.
3. % python ~/Projects/sandstorm-io/vagrant-spk/vagrant-spk dev
   …lots of downloading and compiling…
      Compiling sandstorm-raw-api-example v0.0.1 (/opt/app)
       Finished release [optimized] target(s) in 2m 19s

   App is now available from Sandstorm server at:

       http://local.sandstorm.io:6090

   Ctrl+C to disconnect.

4. (New shell, same directory)
   % python ~/Projects/sandstorm-io/vagrant-spk/vagrant-spk vm ssh
   Calling 'vagrant' 'ssh' in /Users/user/sandstorm-rawapi-example-rust/.sandstorm
   Linux localhost 4.9.0-12-amd64 #1 SMP Debian 4.9.210-1 (2020-01-20) x86_64

   The programs included with the Debian GNU/Linux system are free software;
   the exact distribution terms for each program are described in the
   individual files in /usr/share/doc/*/copyright.

   Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent
   permitted by applicable law.
   You have mail.
   Last login: Tue Jan 25 11:45:52 2022 from 10.0.2.2
   vagrant@localhost:~$ ps ef
     PID TTY      STAT   TIME COMMAND
   31652 pts/1    Ss     0:00 -bash LANG=en_US.UTF-8 USER=vagrant LOGNAME=vagrant HOME=/home/vagrant PATH=/usr/local/bin:/usr/bin:/bin:/usr/games MAIL=/var/mail
   31662 pts/1    R+     0:00  \_ ps ef LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=
   30524 pts/0    Ss+    0:00 spk dev --pkg-def=/opt/app/.sandstorm/sandstorm-pkgdef.capnp:pkgdef SSH_CONNECTION=10.0.2.2 50960 10.0.2.15 22 LANG=en_US.UTF-8 XD
   31610 pts/0    Z+     0:00  \_ [sandstorm] <defunct>
   vagrant@localhost:~$ tail -n5 -f /opt/sandstorm/var/log/sandstorm.log
   Applying migration 41
   Applied migration 41
   Running new server startup function 1
   Running new server startup function 1

   ** Accepted new dev session connection...

   I opened a new grain in the browser and the grain stayed at 6.14kB in size and never responded.  The grain console only showed this:

   ...** SANDSTORM SUPERVISOR: Starting up grain. Sandbox type: userns

   When I closed the grain, this was added to sandstorm.log:

   Unhandled exception in Promise:  [Error: remote exception: grain is not running] {
     cppFile: '(remote)',
     line: 0,
     kjType: 'disconnected'
   }

I suspect that if you can duplicate this, then you'll be well on your way to figuring out the problem.  It seems to me that Sandstorm is failing to start the grain, but I haven't figured out why.  I've tried putting "touch /var/hello" in launcher.sh, but that doesn't work.  I just don't see any indication that the grain is actually being executed.

Thanks for taking a look!

Troy

[Troy Farrell]

If any of you dives into this, I would love to know how you do it.  I have built and installed sandstorm from source in the Debian Buster VM.  I'm trying to run this command from GDB:

vagrant@localhost:~$ /opt/sandstorm/sandstorm spk dev --pkg-def:/opt/app/.sandstorm/sandstorm-pkgdef.capnp:pkgdef

I want to take a look at the doDev function:
https://github.com/sandstorm-io/sandstorm/blob/4849adc0396d5be6edfa4e1262be693c11c503a5/src/sandstorm/spk.c%2B%2B#L1949

Because I'm a rookie with GDB, my session looks like this:

(gdb) break /ekam-provider/canonical/sandstorm/spk.c++:1949
Note: breakpoint 1 also set at pc 0x6c5a5c.
BFD: reopening /opt/sandstorm/sandstorm-custom.2022-01-27_14-49-17/sandstorm: No such file or directory

Breakpoint 2 at 0x6c5a5c: file /ekam-provider/canonical/sandstorm/spk.c++, line 1950.
(gdb) run
BFD: reopening /opt/sandstorm/sandstorm-custom.2022-01-27_14-49-17/sandstorm: No such file or directory

BFD: reopening /opt/sandstorm/sandstorm-custom.2022-01-27_14-49-17/sandstorm: No such file or directory

`/opt/sandstorm/sandstorm-custom.2022-01-27_14-49-17/sandstorm' has disappeared; keeping its symbols.
`/opt/sandstorm/sandstorm-custom.2022-01-27_14-49-17/sandstorm' has disappeared; keeping its symbols.
Starting program: /opt/sandstorm/sandstorm spk dev --pkg-def=/opt/app/.sandstorm/sandstorm-pkgdef.capnp:pkgdef
BFD: reopening /opt/sandstorm/sandstorm-custom.2022-01-27_14-49-17/sandstorm: No such file or directory

BFD: reopening /opt/sandstorm/sandstorm-custom.2022-01-27_14-49-17/sandstorm: No such file or directory

warning: Corrupted shared library list: 0x0 != 0x6c656d61632d6469
warning: Corrupted shared library list: 0x0 != 0x706172772d3239
[Detaching after fork from child process 22027]
sandstorm/config.c++:276: warning: The option ALLOW_LEGACY_RELAXED_CSP will be removed soon. Apps that rely on loading third party resources should be modified to embed those resources in the app package instead.

App is now available from Sandstorm server at:

    http://local.sandstorm.io:6090

Ctrl+C to disconnect.

^CRequesting shutdown due to signal: Interrupt
Unmounted cleanly.
Updating file list.
[Inferior 1 (process 22026) exited normally]
(gdb)

I think that I managed to set the breakpoint that I want, but the break does not happen for some reason.  I'll keep pounding on this whether I get help or not, since it's blocking my progress, but any pointers would be appreciated, as I'm in way over my head at this point.

Thanks,

Troy

[Ian Denhardt]

Quoting Troy Farrell (2022-01-25 12:05:58)

> I just duplicated the problem with this repository:
> https://github.com/troyjfarrell/sandstorm-rawapi-example-rust

I tried and was unable to; the grain's UI shows up just fine for me :(

Is there anything in the grain log if you go fish it out of
/opt/sandstorm/var/sanstorm/grains/<grain-id>/log, instead of looking at
it in the UI? Sometimes it's hard to catch the messages in the UI if the
grain shuts down quickly.

Also, does anything show up in dmesg when you try to start the grain?

-Ian

[Ian Denhardt]

Quoting Ian Denhardt (2022-01-27 14:42:35)

> Quoting Troy Farrell (2022-01-25 12:05:58)

> [...]

Another thing to check: do other (non-dev mode) grains start up as
expected? i.e. if you install something in the app market, does it
run?

[Troy Farrell]

This is one of the strangest bugs I've looked at in recent days.  The behavior is the same on release 293 and on HEAD built from source.  The behavior is the same on Debian 9 or 10 in the VM.  The behavior is the same whether I use Firefox or Safari.  The behavior is the same whether I am developing the app or using an app from the app store.  Logically, I and my MacBook Pro are the only common elements in all of my tests.

The grain logs are the same as I've posted above:

** SANDSTORM SUPERVISOR: Starting up grain. Sandbox type: userns

** SANDSTORM SUPERVISOR: Grain still in use; staying up for now.
** SANDSTORM SUPERVISOR: Grain no longer in use; shutting down.

The only relevant line in any of the system logs is the FUSE line:

Jan 27 23:13:13 buster kernel: [ 2500.903368] fuse init (API version 7.27)

Thanks for your thoughts!

[Troy Farrell]

Problem solved.  My laptop's DNS was not resolving local.sandstorm.io or *.local.sandstorm.io.  I didn't see it at local.sandstorm.io because I have an entry for local.sandstorm.io in /etc/hosts.  Here's what I discovered:

$ dig ui-70958c7f73f2fe717f402d62242af193.local.sandstorm.io

; <<>> DiG 9.10.6 <<>> ui-70958c7f73f2fe717f402d62242af193.local.sandstorm.io
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 54402
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;ui-70958c7f73f2fe717f402d62242af193.local.sandstorm.io.        IN A

;; ANSWER SECTION:
ui-70958c7f73f2fe717f402d62242af193.local.sandstorm.io.        1 IN HINFO "This query has been locally blocked" "by dnscrypt-proxy"

;; Query time: 28 msec
;; SERVER: 172.24.117.23#53(172.24.117.23)
;; WHEN: Fri Jan 28 00:15:18 CST 2022
;; MSG SIZE  rcvd: 192

This DNS server (172.24.117.23) is provided by an Algo VPN.  The ad blocking part of the VPN configuration blocks the resolution of 127.*:

https://github.com/trailofbits/algo/blob/4b1081b7b80522cfeecda186c972c3f81503636d/roles/dns/templates/ip-blacklist.txt.j2#L3

I turned off the VPN and all of the grains work.  I turned it back on and none of the grains will load.

Ian, thanks for taking the time to look into this with me.

Troy

[Ian Denhardt]

Quoting Troy Farrell (2022-01-28 01:29:32)
> Problem solved.

Hooray!

> Ian, thanks for taking the time to look into this with me.

Absolutely. Glad you figured it out.

-Ian