Request sporadically fails in Puma with "interpreter fell through to end unexpectedly (RuntimeError)"

[dgolombek]

Environment Information

Provide at least:

• JRuby version (jruby -v) and command line (flags, JRUBY_OPTS, etc)
  9.2.11.0
  JVM_MEM_OPTS="-Xmx1G
  -Xms1G
  -XX:+UseG1GC
  -XX:MaxGCPauseMillis=200
  -XX:+UseStringDeduplication
  -XX:+HeapDumpOnOutOfMemoryError"
  JVM_JRUBY_OPTS="-Djruby.native.enabled=true
  -Djruby.native.verbose=true
  -Djruby.thread.pool.enabled=true
  -Djruby.compile.invokedynamic=false"
  OpenJDK 1.8.0_252

Running in a Jar built with Warbler, served via Puma 2.9.2 (yes, we need to update that really badly).

start-stop-daemon --start -u service \ -c service:service --exec /usr/bin/java \ --name ${SVC} -- -server \ -Dname=${SVC} \ ${JVM_MEM_OPTS} \ ${JVM_JRUBY_OPTS} \ -Djsse.enableSNIExtension=false \ -Djava.net.preferIPv4Stack=true \ -Dhttps.protocols=TLSv1.2 \ -Djava.security.egd=file:/dev/./urandom \ -Dorg.slf4j.simpleLogger.defaultLogLevel=WARN \ -jar ${JAR} server:${SVC}:run >> ${LOG_FILE} 2>&1

• Operating system and platform (e.g. uname -a)
  Ubuntu Xenial 16.04
  4.4.0-1107-aws Bump compilation heap size for jruby-1_6 #118-Ubuntu SMP ... x86_64 x86_64 x86_64 GNU/Linux

Rack 1.6.11
JrubyRack 1.1.17
Sinatra 1.4.8

Expected Behavior

Puma serves request consistently

Actual Behavior

About 20% of the time (still collecting frequency data), Puma returns a 500 response with the message:

Puma caught this error: BUG: interpreter fell through to end unexpectedly (RuntimeError) 10:02:57 uri:classloader:/code/lib/rack/km/decoder.class:113:in 'response' 10:02:57 uri:classloader:/code/lib/rack/km/decoder.class:39:in 'call' 10:02:57 uri:classloader:/gems/puma-2.9.2-java/lib/puma/rack_patch.rb:13:incall'
10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:219:in call' 10:02:57 uri:classloader:/gems/puma-2.9.2-java/lib/puma/rack_patch.rb:13:in call'
10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:219:in call' 10:02:57 uri:classloader:/gems/rack-1.6.11/lib/rack/logger.rb:15:in call'
10:02:57 uri:classloader:/gems/puma-2.9.2-java/lib/puma/rack_patch.rb:13:in call' 10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:219:in call'
10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:212:in call' 10:02:57 uri:classloader:/gems/rack-1.6.11/lib/rack/head.rb:13:in call'
10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:182:in call' 10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:2013:in call'
10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in block in call' 10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:1787:in synchronize'
10:02:57 uri:classloader:/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in call' 10:02:57 uri:classloader:/gems/puma-2.9.2-java/lib/puma/server.rb:490:in handle_request'
10:02:57 uri:classloader:/gems/puma-2.9.2-java/lib/puma/server.rb:361:in process_client' 10:02:57 uri:classloader:/gems/puma-2.9.2-java/lib/puma/server.rb:254:in block in run'
10:02:57 uri:classloader:/gems/puma-2.9.2-java/lib/puma/thread_pool.rb:92:in block in spawn_thread''

The method causing the problem:

  # Helper method for responding
  #
  # @param env [Rack::Env] the rack environment
  # @param code [Fixnum] the HTTP status code
  # @param body [String] optional body
  # @param headers [Hash] optional headers
  #
  # @return [Array] the response from rack
  def response(env, code, body={}, headers={})
    @logger.info("some useful info")

    if public_api?(env)
      [code, headers, [""]]
    else
      body = {:error => body} if code > 399
      [code, headers, [body.to_json]]
    end
  end

  def public_api?(env)
    env['PATH_INFO'].start_with?("/api/public/")
  end

Line 113 is the "if public_api?(env)" call.

This method is being called with return response(env, 401, e.inspect) where e is a subclass of StandardError.

We can't reproduce this in unit tests or in staging environments, so it may be tied to load (not much, ~3 requests/second). I'm going to add explicit return statements to response() to see if that makes the problem go away, and will try to reproduce in staging so that we can investigate this without impacting production.

[dgolombek]

Adding explicit return statements to this method fixed the problem. I haven't been able to reproduce in staging yet but will keep trying.