Reel::StateError: already processing a request

[tmornini]

Hey there!

I just did my first testing with HTTP/1.1 Connection: Keep-Alive using siege 3.0.5 (which, incidentally, feels like a beast from an ancient era) like this:

siege -c 8 -b -t 1S "http://0.0.0.0:3000/v3/orgs POST < payload.json"

Siege reports 100% successful requests, but when it completes, the server crashes as below.

Transactions:            220 hits
Availability:         100.00 %
Elapsed time:           0.99 secs
Data transferred:         0.05 MB
Response time:            0.04 secs
Transaction rate:       222.22 trans/sec
Throughput:           0.06 MB/sec
Concurrency:            7.79
Successful transactions:         220
Failed transactions:             0
Longest transaction:          0.06
Shortest transaction:         0.01

This could easily be something in my code, but from the backtrace it doesn't look like it. :-)

My Reel::Server::HTTP is here: https://gist.github.com/tmornini/9946289

v3 $ ./api.rb
starting Subledger API...
E, [2014-04-02T17:37:02.015086 #8339] ERROR -- : Subledger::Server::Reel crashed!
Reel::StateError: already processing a request
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/bundler/gems/reel-dba5c521b8f4/lib/reel/connection.rb:55:in `request'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/bundler/gems/reel-dba5c521b8f4/lib/reel/connection.rb:72:in `each_request'
  /Users/tmornini/subledger/v3/lib/subledger/server/reel.rb:21:in `on_connection'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/bundler/gems/reel-dba5c521b8f4/lib/reel/server.rb:56:in `call'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/bundler/gems/reel-dba5c521b8f4/lib/reel/server.rb:56:in `handle_connection'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:122:in `dispatch'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `block in handle_message'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'
W, [2014-04-02T17:37:02.015520 #8339]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
W, [2014-04-02T17:37:02.015599 #8339]  WARN -- : Terminating task: type=:call, meta={:method_name=>:handle_connection}, status=:callwait
E, [2014-04-02T17:37:02.016259 #8339] ERROR -- : Subledger::Server::Reel: CLEANUP CRASHED!
Reel::StateError: already processing a request
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/bundler/gems/reel-dba5c521b8f4/lib/reel/connection.rb:55:in `request'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/bundler/gems/reel-dba5c521b8f4/lib/reel/connection.rb:72:in `each_request'
  /Users/tmornini/subledger/v3/lib/subledger/server/reel.rb:21:in `on_connection'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/bundler/gems/reel-dba5c521b8f4/lib/reel/server.rb:56:in `call'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/bundler/gems/reel-dba5c521b8f4/lib/reel/server.rb:56:in `handle_connection'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:122:in `dispatch'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `block in handle_message'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
  /Users/tmornini/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'
D, [2014-04-02T17:37:02.016588 #8339] DEBUG -- : Terminating 37 actors...

[tarcieri]

I can't see anything wrong just looking at your code. This error indicates you're trying to read a request header+body at the same time you're already reading one, i.e. perhaps there's a case where you haven't fully consumed the request body before attempting to read another request.

Reel is a fully pipelined HTTP server which means its semantics are a bit more complicated than most. I'm not sure we have all the sharp edges in the API ironed out yet.

[tmornini]

Oh, I think I know what the issue might be.

I currently read the request body post-authorization. I'll try reading it early and see if that makes the difference.

It seems weird however that the system runs perfectly until the test completes successfully. My guts tell me it's triggered when client closes a previously Kept-Alive connection.

I'll continue to investigate and update when I have new details.

[tmornini]

I just tortured it a bit and cannot reproduce this, whereas it was 100% reproducible when I reported this. I'm putting it down to a days work refactoring toward simplicity. :-)