mardi 5 mai 2015

Attempting to run background task in Rails and use AJAX to update progress works in development, not in production

I have a long simulation which takes a while to complete, anywhere from a few seconds to several minutes depending on how many trials my user chooses to run. I'm using the gem 'spawnling' to run the simulation in the background, and using AJAX to every second query for the current progress to inform the user. I have a form which I submit remotely, which then creates a model which is used to store the progress and the data. After submitting the form remotely, I use the gem 'gon' to periodically check on the progress. When it reaches 100%, it stops watching and makes an AJAX call to return a HighChart showing the results of the simulation and inserts it into the page.

In development, it works exactly as I want. If I look at the log, upon submission of the form, the simulation starts, I get redirected, it returns, and I begin watching the progress.

Started PATCH "/sim_results/276" for 127.0.0.1 at 2015-05-05 16:03:47 -0400
Processing by SimResultsController#update as JS
  Parameters: {"utf8"=>"✓", "round"=>"1", "daily_doubles_remaining"=>"1", "trials"=>"100000", "scores"=>["0", "0", "0"], "buzzer_ratings"=>["1.0", "1.0", "1.0"], "confidence_ratings"=>["0.0", "0.0", "0.0"], "buzz_in_knowledge_ratings"=>["0.0", "0.0", "0.0"], "dd_fj_knowledge_ratings"=>["0.0", "0.0", "0.0"], "clues"=>["0", "1", "2", "3", "4", "5", "6", "7", "8", "9", "10", "11", "12", "13", "14", "15", "16", "17", "18", "19", "20", "21", "22", "23", "24", "25", "26", "27", "28", "29"], "daily_double"=>"", "previous_daily_double"=>"", "sim_result_id"=>"", "commit"=>"Simulate", "id"=>"276"}
Simulation starting.
Redirected to http://localhost:3000/sim_results/276
Simulation trial starting: 0.
Completed 302 Found in 27ms (ActiveRecord: 0.8ms)
Started GET "/sim_results/276" for 127.0.0.1 at 2015-05-05 16:03:47 -0400
Processing by SimResultsController#show as JS
  Parameters: {"id"=>"276"}
  Rendered sim_results/_loading.html.erb (0.4ms)
Completed 200 OK in 13ms (Views: 6.9ms | ActiveRecord: 0.4ms)
Simulation trial starting: 10.
Simulation trial starting: 20.
Simulation trial starting: 30.
Started GET "/sim_results/276?_method=get&gon_return_variable=true&gon_watched_variable=progress" for 127.0.0.1 at 2015-05-05 16:03:48 -0400
Processing by SimResultsController#show as */*
  Parameters: {"gon_return_variable"=>"true", "gon_watched_variable"=>"progress", "id"=>"276"}
Completed 200 OK in 11ms (Views: 0.2ms | ActiveRecord: 8.5ms)
Simulation trial starting: 40.
Simulation trial starting: 50.
Simulation trial starting: 60.
Started GET "/sim_results/276?_method=get&gon_return_variable=true&gon_watched_variable=progress" for 127.0.0.1 at 2015-05-05 16:03:49 -0400
Processing by SimResultsController#show as */*
  Parameters: {"gon_return_variable"=>"true", "gon_watched_variable"=>"progress", "id"=>"276"}
Completed 200 OK in 3ms (Views: 0.1ms | ActiveRecord: 0.2ms)
Simulation trial starting: 70.
Simulation trial starting: 80.
Simulation trial starting: 90.
Started GET "/sim_results/276?_method=get&gon_return_variable=true&gon_watched_variable=progress" for 127.0.0.1 at 2015-05-05 16:03:50 -0400
Processing by SimResultsController#show as */*
  Parameters: {"gon_return_variable"=>"true", "gon_watched_variable"=>"progress", "id"=>"276"}
Completed 200 OK in 6ms (Views: 0.1ms | ActiveRecord: 0.2ms)
Started GET "/sim_results/276" for 127.0.0.1 at 2015-05-05 16:03:50 -0400
Processing by SimResultsController#show as */*
  Parameters: {"id"=>"276"}
  Rendered sim_results/_results.html.erb (5.4ms)
Completed 200 OK in 21ms (Views: 15.7ms | ActiveRecord: 0.2ms)

However, in production, it's another story.

I, [2015-05-05T19:51:45.457240 #25489]  INFO -- : Started PATCH "/sim_results/23" for 24.93.22.1 at 2015-05-05 19:51:45 +0000
I, [2015-05-05T19:51:45.459666 #25489]  INFO -- : Processing by SimResultsController#update as JS
I, [2015-05-05T19:51:45.459783 #25489]  INFO -- :   Parameters: {"utf8"=>"✓", "round"=>"1", "daily_doubles_remaining"=>"1", "trials"=>"100000", "scores"=>["0", "0", "0"], "buzzer_ratings"=>["1.0", "1.0", "1.0"], "confidence_ratings"=>["0.0", "0.0", "0.0"], "buzz_in_knowledge_ratings"=>["0.0", "0.0", "0.0"], "dd_fj_knowledge_ratings"=>["0.0", "0.0", "0.0"], "clues"=>["0", "1", "2", "3", "4", "5", "6", "7", "8", "9", "10", "11", "12", "13", "14", "15", "16", "17", "18", "19", "20", "21", "22", "23", "24", "25", "26", "27", "28", "29"], "daily_double"=>"", "previous_daily_double"=>"", "sim_result_id"=>"", "commit"=>"Simulate", "id"=>"23"}
I, [2015-05-05T19:51:45.465148 #25489]  INFO -- : Simulation starting.
I, [2015-05-05T19:51:45.468300 #25489]  INFO -- : Redirected to http://ift.tt/1dM5nOA
I, [2015-05-05T19:51:45.468559 #25489]  INFO -- : Completed 302 Found in 9ms (ActiveRecord: 3.3ms)
I, [2015-05-05T19:51:45.490673 #25512]  INFO -- : Simulation trial starting: 0.
I, [2015-05-05T19:51:45.938886 #25512]  INFO -- : Simulation trial starting: 10.
I, [2015-05-05T19:51:46.367241 #25512]  INFO -- : Simulation trial starting: 20.
I, [2015-05-05T19:51:46.767434 #25512]  INFO -- : Simulation trial starting: 30.
I, [2015-05-05T19:51:47.215977 #25512]  INFO -- : Simulation trial starting: 40.
I, [2015-05-05T19:51:47.748930 #25512]  INFO -- : Simulation trial starting: 50.
I, [2015-05-05T19:51:48.218826 #25512]  INFO -- : Simulation trial starting: 60.
I, [2015-05-05T19:51:48.640786 #25512]  INFO -- : Simulation trial starting: 70.
I, [2015-05-05T19:51:49.267435 #25512]  INFO -- : Simulation trial starting: 80.
I, [2015-05-05T19:51:49.774944 #25512]  INFO -- : Simulation trial starting: 90.
I, [2015-05-05T19:51:50.310229 #25489]  INFO -- : Started GET "/sim_results/23" for 24.93.22.1 at 2015-05-05 19:51:50 +0000
I, [2015-05-05T19:51:50.312388 #25489]  INFO -- : Processing by SimResultsController#show as JS
I, [2015-05-05T19:51:50.312446 #25489]  INFO -- :   Parameters: {"id"=>"23"}
I, [2015-05-05T19:51:50.319312 #25489]  INFO -- :   Rendered sim_results/_results.html.erb (1.4ms)
I, [2015-05-05T19:51:50.319558 #25489]  INFO -- : Completed 200 OK in 7ms (Views: 3.7ms | ActiveRecord: 1.2ms)
I, [2015-05-05T19:51:51.495898 #25489]  INFO -- : Started GET "/sim_results/23?_method=get&gon_return_variable=true&gon_watched_variable=progress" for 24.93.22.1 at 2015-05-05 19:51:51 +0000
I, [2015-05-05T19:51:51.498151 #25489]  INFO -- : Processing by SimResultsController#show as */*
I, [2015-05-05T19:51:51.498205 #25489]  INFO -- :   Parameters: {"gon_return_variable"=>"true", "gon_watched_variable"=>"progress", "id"=>"23"}
I, [2015-05-05T19:51:51.501890 #25489]  INFO -- : Completed 200 OK in 4ms (Views: 0.1ms | ActiveRecord: 1.3ms)
I, [2015-05-05T19:51:51.573814 #25489]  INFO -- : Started GET "/sim_results/23" for 24.93.22.1 at 2015-05-05 19:51:51 +0000
I, [2015-05-05T19:51:51.575459 #25489]  INFO -- : Processing by SimResultsController#show as */*
I, [2015-05-05T19:51:51.575501 #25489]  INFO -- :   Parameters: {"id"=>"23"}
I, [2015-05-05T19:51:51.580973 #25489]  INFO -- :   Rendered sim_results/_results.html.erb (1.1ms)
I, [2015-05-05T19:51:51.581126 #25489]  INFO -- : Completed 200 OK in 6ms (Views: 2.9ms | ActiveRecord: 1.2ms)

It might be a little hard to follow, but basically, look at how in my development log, the 302 redirect status is immediately followed by GET "/sim_results/#id", and then Completed 200 OK. In development, the 302 redirect happens, but then only after the simulation finishes does the GET "sim_results/#id" start, which then finishes the remote form submit, which then triggers my JavaScript callback function to check for progress. This obviously defeats the whole purpose of checking for progress in the first place since the first time it checks, the progress is at 100%.

In development, this works both using the default WEBrick server and when I switched over to using puma, both running OSX. In production, I'm using AWS Elastic Beanstalk with Amazon Linux 1.1 and Puma. Any thoughts why my redirect is waiting for the background task to complete?

Edit: I probably should have added my redirect code, it's pretty simple but it looks like this:

def update
  result = sim_result
  result.data = {progress: 0}.to_yaml
  result.save

  Spawnling.new do 
    simulate_games()
  end

  redirect_to action: "show", id: params[:id] 
end

In my show method, if the simulation isn't finished it outputs the current progress, and if it is finished, it outputs the results.

Edit again:

I had the thought to see if the redirect was the problem or not, and replace it with a render call, essentially duplicating my show method:

def update
  result = sim_result
  result.data = {progress: 0}.to_yaml
  result.save

  Spawnling.new do 
    simulate_games()
  end
  @progress = "0"
  render partial: "sim_results/loading"
  #redirect_to action: "show", id: params[:id] 
end

Same thing, the ajax:success method doesn't fire until after the simulation finishes.

I, [2015-05-06T00:01:54.729274 #27944]  INFO -- :   Rendered sim_results/_loading.html.erb (0.7ms)
I, [2015-05-06T00:01:54.729634 #27944]  INFO -- : Completed 200 OK in 12ms (Views: 4.7ms | ActiveRecord: 3.5ms)
I, [2015-05-06T00:01:55.180999 #27989]  INFO -- : Simulation 10% done.
I, [2015-05-06T00:01:55.622344 #27989]  INFO -- : Simulation 20% done.
I, [2015-05-06T00:01:56.061575 #27989]  INFO -- : Simulation 30% done.
I, [2015-05-06T00:01:56.501373 #27989]  INFO -- : Simulation 40% done.
I, [2015-05-06T00:01:56.969043 #27989]  INFO -- : Simulation 50% done.
I, [2015-05-06T00:01:57.416849 #27989]  INFO -- : Simulation 60% done.
I, [2015-05-06T00:01:57.869045 #27989]  INFO -- : Simulation 70% done.
I, [2015-05-06T00:01:58.324920 #27989]  INFO -- : Simulation 80% done.
I, [2015-05-06T00:01:58.985362 #27989]  INFO -- : Simulation 90% done.
I, [2015-05-06T00:01:59.425573 #27989]  INFO -- : Simulation 100% done.
I, [2015-05-06T00:02:00.562305 #27944]  INFO -- : Started GET "/sim_results/29?_method=get&gon_return_variable=true&gon_watched_variable=progress" for 24.93.22.1 at 2015-05-06 00:02:00 +0000

So, it's not the redirect which is causing the problem.

Aucun commentaire:

Enregistrer un commentaire