Truffleruby: Not running Sinatra apps

[ashishbista]

I was super excited when RVM added support for TruffleRuby. I know it doesn't support Rails yet. So, I created a 'Hello World' Sinatra app. But, TruffleRuby seems not to be able to run it.

I just have the following two files in the app:

# app.rb

require 'sinatra'

get '/' do
  'Hello world!'
end

# config.ru

require './app'
run Sinatra::Application

I installed puma and sinatra in TruffleRuby.

$ rvm use truffleruby
Using /Users/ashish/.rvm/gems/truffleruby-1.0.0-rc2
$ gem install puma --no-document
Fetching: puma-3.11.4.gem (100%)
Building native extensions.  This could take a while...
Successfully installed puma-3.11.4
1 gem installed

$ gem install puma --no-document
Fetching: puma-3.11.4.gem (100%)
Building native extensions.  This could take a while...
Successfully installed puma-3.11.4
1 gem installed

Then, I tried to run the app using rackup command:

$ rackup
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
Puma starting in single mode...
* Version 3.11.4 (truffleruby 1.0.0-rc2 - ruby 2.4.4), codename: Love Song
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://localhost:9292
Use Ctrl-C to stop

The app seems to be running. But, it has not exposed port 9292.

 ps aux | grep puma
ashish            3373   0.0  3.4  5028996 568188 s004  S+    9:26PM   0:10.17 puma 3.11.4 (tcp://localhost:9292) [bench]

Connections to port 9292 are getting refused.

$ nc -zv localhost 9292
nc: connectx to localhost port 9292 (tcp) failed: Connection refused
nc: connectx to localhost port 9292 (tcp) failed: Connection refused

I even tried to run app.rb directly. But, it didn't boot puma and exited giving the following message.

$ ruby app.rb
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
$ 

Same app works in MRI 2.5.1.

$ rackup
Puma starting in single mode...
* Version 3.11.4 (ruby 2.5.1-p57), codename: Love Song
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://localhost:9292
Use Ctrl-C to stop
::1 - - [18/Jun/2018:20:14:59 -0400] "GET / HTTP/1.1" 200 12 0.0143

$ nc -zv localhost 9292
found 0 associations
found 1 connections:
     1:    flags=82<CONNECTED,PREFERRED>
    outif lo0
    src ::1 port 58345
    dst ::1 port 9292
    rank info not available
    TCP aux info available

[eregon]

Thank you for the great report!

Running with WEBrick (rackup -s webrick) seems to work fine for me, but indeed it doesn't seem to work with Puma with rackup or rackup -s puma.

On the other hand launching with puma directly works for me:

$ puma config.ru

The block supersedes default value argument warnings look like a bug but they are printed in all configurations, even with WEBrick.

I am not sure what doesn't work with rackup -s puma. We'll need to investigate more.
As you noticed the output looks fine but the port is not opened (I checked with lsof).

[eregon]

One extra problem you mentioned is ruby app.rb doesn't launch the server.
That needs more investigation as well.

[ashishbista]

puma config.ru and rackup -s webrick did open the port. I was able to access it through the browser. But, when I hit the page 4-5 times, the app exits automatically.

➜  bench puma config.ru
Puma starting in single mode...
* Version 3.11.4 (truffleruby 1.0.0-rc2 - ruby 2.4.4), codename: Love Song
* Min threads: 0, max threads: 16
* Environment: development
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
* Listening on tcp://0.0.0.0:9292
Use Ctrl-C to stop
127.0.0.1 - - [19/Jun/2018:18:14:24 -0400] "GET / HTTP/1.1" 200 12 0.0380
127.0.0.1 - - [19/Jun/2018:18:14:24 -0400] "GET /favicon.ico HTTP/1.1" 404 469 0.0240
127.0.0.1 - - [19/Jun/2018:18:14:25 -0400] "GET / HTTP/1.1" 200 12 0.0110
127.0.0.1 - - [19/Jun/2018:18:14:25 -0400] "GET / HTTP/1.1" 200 12 0.1610
127.0.0.1 - - [19/Jun/2018:18:14:25 -0400] "GET / HTTP/1.1" 200 12 0.0070
127.0.0.1 - - [19/Jun/2018:18:14:25 -0400] "GET / HTTP/1.1" 200 12 0.0060
➜  bench

[eregon]

That's odd, I cannot reproduce.
I can hit it 100s of times and it works fine for me.

Could you try puma --debug config.ru?
And when it exits, could you show the exit status with echo $??

[ashishbista]

Exit status is 141:

➜  bench puma --debug config.ru
Puma starting in single mode...
* Version 3.11.4 (truffleruby 1.0.0-rc2 - ruby 2.4.4), codename: Love Song
* Min threads: 0, max threads: 16
* Environment: development
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
block supersedes default value argument
* Listening on tcp://0.0.0.0:9292
Use Ctrl-C to stop
127.0.0.1 - - [20/Jun/2018:14:40:59 -0400] "GET / HTTP/1.1" 200 12 0.0450
127.0.0.1 - - [20/Jun/2018:14:41:00 -0400] "GET /favicon.ico HTTP/1.1" 404 469 0.0280
127.0.0.1 - - [20/Jun/2018:14:41:02 -0400] "GET / HTTP/1.1" 200 12 0.0120
127.0.0.1 - - [20/Jun/2018:14:41:03 -0400] "GET / HTTP/1.1" 200 12 0.0070
127.0.0.1 - - [20/Jun/2018:14:41:03 -0400] "GET / HTTP/1.1" 200 12 0.0080
➜  bench echo $?
141
➜  bench

[eregon]

Thanks, exit status 141 is SIGPIPE, which means a write to a pipe or socket was attempted, but the reader closed it.

Normally, when such a thing happens, Ruby raises Errno::EPIPE:

$ chruby 2.4.4
$ ruby -ve 'r,w=IO.pipe; w.write "a"; puts "Wrote a"; r.close; w.write "b"'
ruby 2.4.4p296 (2018-03-28 revision 63013) [x86_64-linux]
Wrote a
-e:1:in `write': Broken pipe (Errno::EPIPE)
    from -e:1:in `<main>'
zsh: exit 1

and this works with TruffleRuby on JVM, but not on SubstrateVM:

$ chruby graalvm-ce-1.0.0-rc2

$ ruby --jvm -ve 'r,w=IO.pipe; w.write "a"; puts "Wrote a"; r.close; w.write "b"'
truffleruby 1.0.0-rc2, like ruby 2.4.4, GraalVM CE [x86_64-linux]
Wrote a
-e:1:in `errno_error': Broken pipe (Errno::EPIPE)
    from -e:1:in `new'
    from -e:1:in `handle'
    from -e:1:in `write_string'
    from -e:1:in `write'
    from -e:1:in `<main>'
zsh: exit 1

$ ruby --native -ve 'r,w=IO.pipe; w.write "a"; puts "Wrote a"; r.close; w.write "b"'
truffleruby 1.0.0-rc2, like ruby 2.4.4, GraalVM CE Native [x86_64-linux]
Wrote a
zsh: broken pipe

BTW, zsh has a nice PRINT_EXIT_VALUE option to print non-zero exit statuses (shown above), which is very useful to debug unexpected stopping processes.
I'm not sure Bash has such functionality but it seems possible with a bit of googling.

So, we need to handle SIGPIPE on SVM.

[ashishbista]

Thanks for the zsh tip. Let me know if you need anything else from my side.

[eregon]

I fixed the SIGPIPE issue with a2db8a337268b03679d6781a083ed499adfa805d and test in 09bb8a3f8bbdc198fc235595163876fa5d690c86.
This will be in the next release, 1.0.0-rc3.

[eregon]

The issue of the server process dying unexpectedly was fixed in TruffleRuby 1.0.0-rc3.
So running with webrick (rackup -s webrick) or directly with Puma (puma config.ru) should work now.
Please try it.

I am not sure why we don't open the port with Puma when using rackup -s puma though.
The other problem that ruby app.rb doesn't launch the server needs more investigation as well.

[ashishbista]

Yes, rackup -s webrick and puma config.ru are working now. The other issues are still there.

[eregon]

The reason ruby app.rb doesn't work is Sinatra has a list of Regexps to filter files to ignore and one of our standard library path is not correctly filtered.
The at_exit hook Sinatra installs runs the application if the first file of the filtered caller is the same as $0 (the main script).
We need to find a way to fit in this ignore list, or hide the problematic path from caller.

[eregon]

https://github.com/oracle/truffleruby/commit/d6c8ce215f5ab24aa67dbd1d54904aae87704fe0 fixes starting a Sinatra app with ruby app.rb, so that works now.

The last remaining problem is rackup -s puma doesn't seem to open the port.
And well, the warnings should be fixed too.

[eregon]

The warnings come from https://github.com/sinatra/mustermann/blob/v1.0.2/mustermann/lib/mustermann/pattern.rb#L59, and this seems a bug of mustermann when ObjectSpace::WeakMap is not defined, which is the case on TruffleRuby.

mustermann passes both a default value and a block to Hash#fetch, which triggers rightfully the warning:

@map.fetch(string, options) { super(string, options) { options } }

I'll report a bug to mustermann.

[eregon]

The final issue, rackup -s puma is because TruffleRuby's Socket.getifaddrs() has a bug and doesn't return any address (just an empty Array instead).

Puma uses Socket.ip_address_list which uses Socket.getifaddrs when the host is "localhost".
Therefore one workaround which already works is rackup -s puma --host 127.0.0.1.
I'll fix Socket.getifaddrs().

[ashishbista]

Nice work 👍

[eregon]

Socket.getifaddrs() is now fixed with 0e2e01f88c21d945b4161527a68557928506bed2 and so rackup -s puma or just rackup when Puma is installed works.
This will be in the next release (around end of the month).

I'll close this issue as I believe I addressed everything. I'll comment once the next release is available.

[eregon]

@ashishbista Thank you again for the bug report, 4 problems found in one issue and a super-simple app that's efficient reporting!

[ashishbista]

I'm happy that this helped. I'll test it again when we get next release. And, I will see if I can find more issues.

[eregon]

TruffleRuby 1.0.0-rc5 was released, with all fixes for this bug report.
@ashishbista Could you verify it works as expected now?

[ashishbista]

@eregon Thanks for informing me about the release and fixing the issues reporting in this report.

I tested all the issues mentioned above. All the issues are fixed now. But, the warning message that mustermann gives is still there:

truffleruby-1.0.0-rc5/gems/mustermann-1.0.2/lib/mustermann/pattern.rb:59: warning: block supersedes default value argument

I went little ahead and tried to benchmark the performance ofapp.rb in both MRI and TruffleRuby. It turns out that the application is slower in TruffleRuby than AMI.

# MRI 2.5.1
$ puma -t 16:16

# In another terminal

ab -n 5000 -c 10 http://127.0.0.1:9292/
...
Benchmarking 127.0.0.1 (be patient)
Completed 500 requests
Completed 1000 requests
Completed 1500 requests
Completed 2000 requests
Completed 2500 requests
Completed 3000 requests
Completed 3500 requests
Completed 4000 requests
Completed 4500 requests
Completed 5000 requests
Finished 5000 requests


Server Software:
Server Hostname:        127.0.0.1
Server Port:            9292

Document Path:          /
Document Length:        12 bytes

Concurrency Level:      10
Time taken for tests:   5.234 seconds
Complete requests:      5000
Failed requests:        0
Total transferred:      925000 bytes
HTML transferred:       60000 bytes
Requests per second:    955.24 [#/sec] (mean)
Time per request:       10.469 [ms] (mean)
Time per request:       1.047 [ms] (mean, across all concurrent requests)
Transfer rate:          172.58 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:     0   10  10.9      5      53
Waiting:        0    4   2.0      4      19
Total:          1   10  10.9      6      53

Percentage of the requests served within a certain time (ms)
  50%      6
  66%      7
  75%      9
  80%     12
  90%     33
  95%     35
  98%     37
  99%     40
 100%     53 (longest request)

So, It's taking 5.234 seconds in MRI.

I ran the same command (puma -t 16:16) to run the application in TruffleRuby 1.0.0-rc5 and used the same AapacheBench setup (ab -n 5000 -c 10 http://127.0.0.1:9292/).

It was initially taking as much as 40.869 seconds in TruffleRuby. But, after running the benchmark command 5-6 times, the test time went down to 9.154 seconds, which is still slower than MRI.

 ab -n 5000 -c 10 http://127.0.0.1:9292/
...
Benchmarking 127.0.0.1 (be patient)
Completed 500 requests
Completed 1000 requests
Completed 1500 requests
Completed 2000 requests
Completed 2500 requests
Completed 3000 requests
Completed 3500 requests
Completed 4000 requests
Completed 4500 requests
Completed 5000 requests
Finished 5000 requests


Server Software:
Server Hostname:        127.0.0.1
Server Port:            9292

Document Path:          /
Document Length:        12 bytes

Concurrency Level:      10
Time taken for tests:   9.154 seconds
Complete requests:      5000
Failed requests:        0
Total transferred:      925000 bytes
HTML transferred:       60000 bytes
Requests per second:    546.19 [#/sec] (mean)
Time per request:       18.309 [ms] (mean)
Time per request:       1.831 [ms] (mean, across all concurrent requests)
Transfer rate:          98.68 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.2      0       3
Processing:     2   18  54.7      7    1058
Waiting:        1   11  52.6      5    1058
Total:          2   18  54.8      7    1060

Percentage of the requests served within a certain time (ms)
  50%      7
  66%     10
  75%     14
  80%     21
  90%     37
  95%     42
  98%    119
  99%    215
 100%   1060 (longest request)

[eregon]

@ashishbista Thank you for confirming!
Yes, the warning is still there until either mustermann fixes https://github.com/sinatra/mustermann/issues/89 or we implement ObjectSpace::WeakMap https://github.com/oracle/truffleruby/issues/1385.

Could you report the performance as a separate issue? (copy/pasting most of the message is fine)
This will make it easier to track.

[eregon]

I submitted a PR to Mustermann to fix the warning and it was merged: https://github.com/sinatra/mustermann/pull/90
However, we'll still need to wait for a release of Mustermann to stop the warning from appearing (or TruffleRuby implements ObjectSpace::WeakMap #1385).

[eregon]

With the release of mustermann v1.0.3, I can confirm there are no warnings anymore with:

$ chruby truffleruby-1.0.0-rc5
$ gem install sinatra
$ ruby app.rb
[2018-08-16 20:44:12] INFO  WEBrick 1.3.1
[2018-08-16 20:44:12] INFO  ruby 2.4.4 (2018-07-25) [x86_64-linux]
== Sinatra (v2.0.3) has taken the stage on 4567 for development with backup from WEBrick
[2018-08-16 20:44:13] INFO  WEBrick::HTTPServer#start: pid=21815 port=4567
::1 - - [16/Aug/2018:20:44:14 +0200] "GET / HTTP/1.1" 200 40 0.0250
::1 - - [16/Aug/2018:20:44:13 CEST] "GET / HTTP/1.1" 200 40
- -> /