After saving a thread: Completed 500 Internal Server Error #179

numeroteca · 2013-09-07T21:24:37Z

I am getting this error "We're sorry, but something went wrong" after coding and saving a thread, or after editing a thread (see log bellow). It has happened before several times, but I haven't been able to reproduce it always in the same conditions.

I have seen this bug with the thread http://pageonex.com/numeroteca/corrupcion-espana-septiembre-2013/, and I've also seen the same behaviour at http://pageonex.com/albocoven/apagon/ (a one day thread).

Sometimes, after a while, it gets fixed and things work again.

This is the log:

Started GET "/numeroteca/corrupcion-espana-septiembre-2013/" for 95.16.125.184 at 2013-09-07 21:14:14 +0000
Processing by CodingController#display as HTML
  Parameters: {"username"=>"numeroteca", "thread_name"=>"corrupcion-espana-septiembre-2013"}
  Rendered coding/display.html.erb within layouts/application (3.9ms)
Completed 500 Internal Server Error in 21ms

ActionView::Template::Error (undefined method `[]' for nil:NilClass):
    108: <div class="row">
    109:    <div class="span2">
    110:        <ul class='thread-coposite-labels'>
    111:            <% @img_map_info['row_info'].each do |media_id,info| %>
    112:                <li style="height:<%=info['height']%>px"><%=info['name']%></li>
    113:            <% end %>
    114:        </ul>
  app/views/coding/display.html.erb:111:in `_app_views_coding_display_html_erb__4444082875986360646_23128300'

Sometimes I just get 500 Internal Server Error. Is this a question of lack of RAM?

numeroteca · 2013-09-12T21:16:20Z

The thread http://pageonex.com/numeroteca/corrupcion-espana-septiembre-2013/ worked again after editing it an adding two more days.

rahulbot · 2013-09-13T19:00:13Z

That suggest that @img_map_info is nil, which can happen when it dies in the middle of generating composite images (cause it never gets to creating the image map, which happens after creating the actual images). I'll try to put in some protection to handle that case better.

…ddle (#179)

rahulbot · 2013-09-20T20:10:26Z

@numeroteca are you still seeing this after my last commit, or is it behaving better now?

numeroteca · 2013-09-21T10:02:15Z

The error message provided at c34ce04 makes the fail better when the composite image can not be generated However, waiting or reloading usually does not help.

Everyday I add one day to the thread http://pageonex.com/numeroteca/corrupcion-espana-septiembre-2013/ and it always returns a "500 Internal Server Error", but it is not a @img_map_info problem. The server stops and returns no error.
The log before crashing:

Started GET "/numeroteca/corrupcion-espana-septiembre-2013/" for 188.78.132.93 at 2013-09-22 08:27:33 +0000
Processing by CodingController#display as HTML
  Parameters: {"username"=>"numeroteca", "thread_name"=>"corrupcion-espana-septiembre-2013"}
Creating composites for 'corrupcion-espana-septiembre-2013' (199) at app/assets/images/threads/2/199/970px
  determining row heights
  creating background image grid

After refreshing the page it woks again. Wondering if there a way to avoid this?

numeroteca · 2013-10-04T21:25:51Z

Now I am seeing the same behavior with a new thread (8 newspaper, 3 days, 4 topics) http://pageonex.com/numeroteca/corrupcion-espana-octubre-2013/. It fails when creating the overlays iamges for the topics, this is the log

  Parameters: {"username"=>"numeroteca", "thread_name"=>"corrupcion-espana-octubre-2013"}
Creating composites for 'corrupcion-espana-octubre-2013' (246) at app/assets/images/threads/2/246/970px
  determining row heights
  creating background image grid
  creating overlays for topics

Sometimes it failed after one more step: ruby combining into composites

I erased 2 of the topics, and left the thread whit 2 topics, and it worked again.
No image had been coded yet.

I tested again an added more topics (up to 6) and it crashed again when creating overlays for topics.

Could it be something related to lack of memory? When I entered the server I saw the swap usage at 99%. Now is at 80%.

numeroteca · 2013-10-04T22:11:05Z

I made a few more tests extending the days of the thread (days > 3 or 4), and it worked well. So I guess it might be related to handling too big images when threads are to short (days < 3). @rahulbot , @elplatt do you think it could be related to that?

If that is the case, it might be that something with "adds max thumbnail width to composite" bd73c8c might be not working.

To have a a better display view I am thinking we should also limit the height of the rows so we never have huge images in the display view. To make that we would need to modify the bar chart, as the images will no longer occupy the entire width, but only the left part.

numeroteca · 2013-10-14T23:55:59Z

Since the previous mentioned thread is working again, I have replicated this issue in the development server http://dev.pageonex.com/numeroteca/test-few-papers/

numeroteca · 2013-12-10T22:37:26Z

Reproducing step by step the problems of a short thread (one or two days), @elplatt.
Made with Firefox on Ubuntu 12.04.

Create thread (8 newspapers 1 day 1 topic) http://pageonex.com/numeroteca/test-thread-for-crashes/ Save. It works ok.
Edit thread: adds another day (2 days thread) and updates
Returns: "500 Internal Server Error"
According to the logs there is a Mysql2::Error :

 determining row heights
  creating background image grid
Started GET "/numeroteca/corrupcion-spain-enero-2013/coding/?i=99347" for 180.76.5.144 at 2013-12-10 22:18:59 +0000
Processing by CodingController#process_images as */*
  Parameters: {"i"=>"99347", "username"=>"numeroteca", "thread_name"=>"corrupcion-spain-enero-2013"}
  Rendered coding/_coding_footer.html.erb (0.2ms)
  Rendered coding/process_images.html.erb within layouts/application (4234.0ms)
Completed 200 OK in 4243ms (Views: 3899.6ms | ActiveRecord: 339.7ms)
  creating overlays for topics
Started GET "/numeroteca/corrupcion-spain-enero-2013/coding/?i=99347" for 180.76.5.95 at 2013-12-10 22:19:07 +0000

Mysql2::Error (Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)):
  vendor/bundle/ruby/1.9.1/gems/mysql2-0.3.11/lib/mysql2/client.rb:44:in `connect'
  vendor/bundle/ruby/1.9.1/gems/mysql2-0.3.11/lib/mysql2/client.rb:44:in `initialize'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/mysql2_adapter.rb:16:in `new'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/mysql2_adapter.rb:16:in `mysql2_connection'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:315:in `new_connection'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:325:in `checkout_new_connection'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:247:in `block (2 levels) in checkout'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:242:in `loop'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:242:in `block in checkout'
  /usr/lib/ruby/1.9.1/monitor.rb:211:in `mon_synchronize'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:239:in `checkout'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:102:in `block in connection'
  /usr/lib/ruby/1.9.1/monitor.rb:211:in `mon_synchronize'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:101:in `connection'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:410:in `retrieve_connection'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_specification.rb:171:in `retrieve_connection'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_specification.rb:145:in `connection'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/query_cache.rb:67:in `rescue in call'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/query_cache.rb:61:in `call'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:479:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/callbacks.rb:405:in `_run__356723871747437564__call__4044405225065308654__callbacks'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/callbacks.rb:405:in `__run_callback'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/callbacks.rb:81:in `run_callbacks'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/rack/logger.rb:32:in `call_app'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/rack/logger.rb:16:in `block in call'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/tagged_logging.rb:22:in `tagged'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/rack/logger.rb:16:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_dispatch/middleware/request_id.rb:22:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/methodoverride.rb:21:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/runtime.rb:17:in `call'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/lock.rb:15:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
  vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:245:in `fetch'
  vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:185:in `lookup'
  vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:66:in `call!'
  vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/engine.rb:479:in `call'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/application.rb:223:in `call'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/railtie/configurable.rb:30:in `method_missing'
  passenger (3.0.19) lib/phusion_passenger/rack/request_handler.rb:96:in `process_request'
  passenger (3.0.19) lib/phusion_passenger/abstract_request_handler.rb:516:in `accept_and_process_next_request'
  passenger (3.0.19) lib/phusion_passenger/abstract_request_handler.rb:274:in `main_loop'
  passenger (3.0.19) lib/phusion_passenger/rack/application_spawner.rb:206:in `start_request_handler'
  passenger (3.0.19) lib/phusion_passenger/rack/application_spawner.rb:171:in `block in handle_spawn_application'
  passenger (3.0.19) lib/phusion_passenger/utils.rb:470:in `safe_fork'
  passenger (3.0.19) lib/phusion_passenger/rack/application_spawner.rb:166:in `handle_spawn_application'
  passenger (3.0.19) lib/phusion_passenger/abstract_server.rb:357:in `server_main_loop'
  passenger (3.0.19) lib/phusion_passenger/abstract_server.rb:206:in `start_synchronously'
  passenger (3.0.19) lib/phusion_passenger/abstract_server.rb:180:in `start'
  passenger (3.0.19) lib/phusion_passenger/rack/application_spawner.rb:129:in `start'
  passenger (3.0.19) lib/phusion_passenger/spawn_manager.rb:253:in `block (2 levels) in spawn_rack_application'
  passenger (3.0.19) lib/phusion_passenger/abstract_server_collection.rb:132:in `lookup_or_add'
  passenger (3.0.19) lib/phusion_passenger/spawn_manager.rb:246:in `block in spawn_rack_application'
  passenger (3.0.19) lib/phusion_passenger/abstract_server_collection.rb:82:in `block in synchronize'
  <internal:prelude>:10:in `synchronize'
  passenger (3.0.19) lib/phusion_passenger/abstract_server_collection.rb:79:in `synchronize'
  passenger (3.0.19) lib/phusion_passenger/spawn_manager.rb:244:in `spawn_rack_application'
  passenger (3.0.19) lib/phusion_passenger/spawn_manager.rb:137:in `spawn_application'
  passenger (3.0.19) lib/phusion_passenger/spawn_manager.rb:275:in `handle_spawn_application'
  passenger (3.0.19) lib/phusion_passenger/abstract_server.rb:357:in `server_main_loop'
  passenger (3.0.19) lib/phusion_passenger/abstract_server.rb:206:in `start_synchronously'
  passenger (3.0.19) helper-scripts/passenger-spawn-server:99:in `<main>'

I reload: image grid is not there.
I go to the "coding" view and add one area to one image:

logs: 
  determining row heights
  creating background image grid
  creating overlays for topics
  combining into composites

It returns 500 Internal Server Error after combining into composites.

I reload: the bar chart works, the image still missing.
I go to edit the thread, without changing anything click "update". And now everything works fine: both bar chart and image work in the display view.
I go to edit and select 2 other days (the first day becomes the last one): It returns 500 Internal Server Error after "creating overlays for topics".
After reloading the chart works but the image is missing.
After updating and reloading once, the chart works but the image is missing.

numeroteca · 2014-01-23T19:16:38Z

I made a video showing how it goes to "500 internal server error" when editing a thread and adding one extra day, including logs and top:
http://www.youtube.com/watch?v=wuBMPu7Hty0

numeroteca · 2014-03-25T13:55:01Z

After adding more RAM to the server "500 internal server error" has not been seen again.

rahulbot added a commit that referenced this issue Sep 13, 2013

fail more gracefully if the composite image generation died in the mi…

c34ce04

…ddle (#179)

ghost assigned numeroteca Sep 20, 2013

numeroteca mentioned this issue Nov 5, 2013

Error while exporting to JPEG #175

Closed

numeroteca closed this as completed Mar 25, 2014

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

After saving a thread: Completed 500 Internal Server Error #179

After saving a thread: Completed 500 Internal Server Error #179

numeroteca commented Sep 7, 2013

numeroteca commented Sep 12, 2013

rahulbot commented Sep 13, 2013

rahulbot commented Sep 20, 2013

numeroteca commented Sep 21, 2013

numeroteca commented Oct 4, 2013

numeroteca commented Oct 4, 2013

numeroteca commented Oct 14, 2013

numeroteca commented Dec 10, 2013

numeroteca commented Jan 23, 2014

numeroteca commented Mar 25, 2014

After saving a thread: Completed 500 Internal Server Error #179

After saving a thread: Completed 500 Internal Server Error #179

Comments

numeroteca commented Sep 7, 2013

numeroteca commented Sep 12, 2013

rahulbot commented Sep 13, 2013

rahulbot commented Sep 20, 2013

numeroteca commented Sep 21, 2013

numeroteca commented Oct 4, 2013

numeroteca commented Oct 4, 2013

numeroteca commented Oct 14, 2013

numeroteca commented Dec 10, 2013

numeroteca commented Jan 23, 2014

numeroteca commented Mar 25, 2014