search

publiclab / mapknitter

Upload your own aerial images, position (rubbersheet) them in a web interface over existing map data, and share via web or composite and export for print.
http://mapknitter.org
GNU General Public License v3.0
267 stars 207 forks source link

Papertrail issue (unknown cause) is causing 500 errors #982

Closed icarito closed 5 years ago

icarito commented 5 years ago

Although load doesn't seem high. I think I've isolated this case (sorry about the whitespace): imagen

The result is some heavy delay in rendering MapController: fractal-pasted-image

This seems to have started about a month ago and got bad enough to cause downtime just now (having checked Skylight).

Actually the report says it got worse the week of 19th to 25th of August. imagen

grvsachdeva commented 5 years ago

I tried loading the maps#show. But, didn't observed anything suspicious. For me, these were the logs:

Started GET "/maps/test-map" for 127.0.0.1 at 2019-09-02 11:16:48 +0530
Processing by MapsController#show as HTML
  Parameters: {"id"=>"test-map"}
  Map Load (0.4ms)  SELECT  `maps`.* FROM `maps` WHERE `maps`.`slug` = 'test-map' LIMIT 1
  ↳ app/controllers/maps_controller.rb:198
  Warpable Exists (0.3ms)  SELECT  1 AS one FROM `warpables` WHERE `warpables`.`map_id` = 1 LIMIT 1
  ↳ app/models/map.rb:187
  Warpable Load (0.4ms)  SELECT `warpables`.* FROM `warpables` WHERE `warpables`.`map_id` = 1 AND (width > 0 AND nodes <> "")
  ↳ app/models/map.rb:191
  Rendering layouts/knitter2.html.erb
  Rendering maps/show.html.erb within layouts/knitter2
  User Load (0.3ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 0 LIMIT 1
  ↳ app/views/maps/show.html.erb:6
  Rendered maps/_share.html.erb (0.3ms)
  Rendered maps/_geocoder.js.erb (0.3ms)
  Rendered maps/_edit.html.erb (137.1ms)
  Tag Load (0.5ms)  SELECT `tags`.* FROM `tags` WHERE `tags`.`map_id` = 1
  ↳ app/views/tags/_index.html.erb:4
  Rendered tags/_index.html.erb (8.1ms)
  Comment Load (0.3ms)  SELECT `comments`.* FROM `comments` WHERE `comments`.`map_id` = 1
  ↳ app/views/comments/_index.html.erb:1
  Rendered comments/_index.html.erb (1.4ms)
  Rendered comments/_new.html.erb (0.4ms)
  CACHE Warpable Exists (0.0ms)  SELECT  1 AS one FROM `warpables` WHERE `warpables`.`map_id` = 1 LIMIT 1
  ↳ app/views/images/_index.html.erb:21
  Warpable Load (0.4ms)  SELECT `warpables`.* FROM `warpables` WHERE `warpables`.`map_id` = 1
  ↳ app/views/images/_index.html.erb:40
  Node Load (0.5ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
  CACHE Node Load (0.0ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
  CACHE Node Load (0.0ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
  CACHE Node Load (0.0ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
  PaperTrail::Version Load (2.1ms)  SELECT `versions`.* FROM `versions` WHERE `versions`.`item_id` = 3 AND `versions`.`item_type` = 'Warpable' ORDER BY `versions`.`created_at` ASC, `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:120
  PaperTrail::Version Load (0.5ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 3 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  User Load (0.2ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1
  ↳ app/views/images/_index.html.erb:125
  CACHE PaperTrail::Version Load (0.0ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 3 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  CACHE User Load (0.0ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1  [["id", 1], ["LIMIT", 1]]
  ↳ app/views/images/_index.html.erb:125
  CACHE PaperTrail::Version Load (0.0ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 3 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  PaperTrail::Version Load (0.5ms)  SELECT `versions`.* FROM `versions` WHERE `versions`.`item_id` = 2 AND `versions`.`item_type` = 'Warpable' ORDER BY `versions`.`created_at` ASC, `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:120
  PaperTrail::Version Load (0.9ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 2 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  PaperTrail::Version Load (0.4ms)  SELECT `versions`.* FROM `versions` WHERE `versions`.`item_id` = 1 AND `versions`.`item_type` = 'Warpable' ORDER BY `versions`.`created_at` ASC, `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:120
  PaperTrail::Version Load (0.3ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 1 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  Rendered images/_index.html.erb (110.3ms)
  Rendered maps/show.html.erb within layouts/knitter2 (269.7ms)
  Rendered layouts/_login_form.html.erb (0.8ms)
  Rendered layouts/_login_modal.html.erb (2.4ms)
  Rendered layouts/_login.html.erb (4.3ms)
  Rendered layouts/_header.html.erb (6.0ms)
  Export Load (0.4ms)  SELECT `exports`.* FROM `exports` WHERE `exports`.`map_id` = 1
  ↳ app/views/maps/_exports.html.erb:1
  Rendered maps/_exports.html.erb (7.7ms)
  Rendered maps/_share.html.erb (0.3ms)
  Rendered maps/_geocoder.js.erb (0.0ms)
  Rendered maps/_edit.html.erb (3.0ms)
  Rendered tags/_index.html.erb (0.5ms)
  Rendered comments/_index.html.erb (0.1ms)
  Rendered comments/_new.html.erb (0.0ms)
  Rendered maps/_sidebar_annotations.html.erb (0.3ms)
  Rendered maps/_sidebar_exports.html.erb (1.3ms)
  Rendered images/_new.html.erb (1.1ms)
  Rendered layouts/knitter2.html.erb (377.6ms)
Completed 200 OK in 387ms (Views: 324.1ms | ActiveRecord: 57.4ms)

Started GET "/cable" for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Started GET "/cable/" [WebSocket] for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: upgrade, HTTP_UPGRADE: websocket)
An unauthorized connection attempt was rejected
Failed to upgrade to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: upgrade, HTTP_UPGRADE: websocket)
Finished "/cable/" [WebSocket] for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Finished "/cable/" [WebSocket] for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Started GET "/maps/test-map/warpables.json" for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Processing by MapsController#images as JSON
  Parameters: {"id"=>"test-map"}
  Map Load (0.6ms)  SELECT  `maps`.* FROM `maps` WHERE `maps`.`slug` = 'test-map' LIMIT 1
  ↳ app/controllers/maps_controller.rb:198
  Warpable Load (22.6ms)  SELECT `warpables`.* FROM `warpables` WHERE `warpables`.`map_id` = 1
  ↳ app/controllers/maps_controller.rb:115
  Node Load (0.6ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
Completed 200 OK in 39ms (Views: 12.8ms | ActiveRecord: 23.8ms)
grvsachdeva commented 5 years ago

@icarito @jywarren can you paste log for this maps#show request/response so that we can see which query is taking time?

Thanks!

alaxalves commented 5 years ago

I tried loading the maps#show. But, didn't observed anything suspicious. For me, these were the logs:

Started GET "/maps/test-map" for 127.0.0.1 at 2019-09-02 11:16:48 +0530
Processing by MapsController#show as HTML
  Parameters: {"id"=>"test-map"}
  Map Load (0.4ms)  SELECT  `maps`.* FROM `maps` WHERE `maps`.`slug` = 'test-map' LIMIT 1
  ↳ app/controllers/maps_controller.rb:198
  Warpable Exists (0.3ms)  SELECT  1 AS one FROM `warpables` WHERE `warpables`.`map_id` = 1 LIMIT 1
  ↳ app/models/map.rb:187
  Warpable Load (0.4ms)  SELECT `warpables`.* FROM `warpables` WHERE `warpables`.`map_id` = 1 AND (width > 0 AND nodes <> "")
  ↳ app/models/map.rb:191
  Rendering layouts/knitter2.html.erb
  Rendering maps/show.html.erb within layouts/knitter2
  User Load (0.3ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 0 LIMIT 1
  ↳ app/views/maps/show.html.erb:6
  Rendered maps/_share.html.erb (0.3ms)
  Rendered maps/_geocoder.js.erb (0.3ms)
  Rendered maps/_edit.html.erb (137.1ms)
  Tag Load (0.5ms)  SELECT `tags`.* FROM `tags` WHERE `tags`.`map_id` = 1
  ↳ app/views/tags/_index.html.erb:4
  Rendered tags/_index.html.erb (8.1ms)
  Comment Load (0.3ms)  SELECT `comments`.* FROM `comments` WHERE `comments`.`map_id` = 1
  ↳ app/views/comments/_index.html.erb:1
  Rendered comments/_index.html.erb (1.4ms)
  Rendered comments/_new.html.erb (0.4ms)
  CACHE Warpable Exists (0.0ms)  SELECT  1 AS one FROM `warpables` WHERE `warpables`.`map_id` = 1 LIMIT 1
  ↳ app/views/images/_index.html.erb:21
  Warpable Load (0.4ms)  SELECT `warpables`.* FROM `warpables` WHERE `warpables`.`map_id` = 1
  ↳ app/views/images/_index.html.erb:40
  Node Load (0.5ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
  CACHE Node Load (0.0ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
  CACHE Node Load (0.0ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
  CACHE Node Load (0.0ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
  PaperTrail::Version Load (2.1ms)  SELECT `versions`.* FROM `versions` WHERE `versions`.`item_id` = 3 AND `versions`.`item_type` = 'Warpable' ORDER BY `versions`.`created_at` ASC, `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:120
  PaperTrail::Version Load (0.5ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 3 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  User Load (0.2ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1
  ↳ app/views/images/_index.html.erb:125
  CACHE PaperTrail::Version Load (0.0ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 3 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  CACHE User Load (0.0ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1  [["id", 1], ["LIMIT", 1]]
  ↳ app/views/images/_index.html.erb:125
  CACHE PaperTrail::Version Load (0.0ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 3 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  PaperTrail::Version Load (0.5ms)  SELECT `versions`.* FROM `versions` WHERE `versions`.`item_id` = 2 AND `versions`.`item_type` = 'Warpable' ORDER BY `versions`.`created_at` ASC, `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:120
  PaperTrail::Version Load (0.9ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 2 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  PaperTrail::Version Load (0.4ms)  SELECT `versions`.* FROM `versions` WHERE `versions`.`item_id` = 1 AND `versions`.`item_type` = 'Warpable' ORDER BY `versions`.`created_at` ASC, `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:120
  PaperTrail::Version Load (0.3ms)  SELECT `versions`.`id` FROM `versions` WHERE `versions`.`item_type` = 'Warpable' AND `versions`.`item_id` = 1 ORDER BY `versions`.`id` ASC
  ↳ app/views/images/_index.html.erb:123
  Rendered images/_index.html.erb (110.3ms)
  Rendered maps/show.html.erb within layouts/knitter2 (269.7ms)
  Rendered layouts/_login_form.html.erb (0.8ms)
  Rendered layouts/_login_modal.html.erb (2.4ms)
  Rendered layouts/_login.html.erb (4.3ms)
  Rendered layouts/_header.html.erb (6.0ms)
  Export Load (0.4ms)  SELECT `exports`.* FROM `exports` WHERE `exports`.`map_id` = 1
  ↳ app/views/maps/_exports.html.erb:1
  Rendered maps/_exports.html.erb (7.7ms)
  Rendered maps/_share.html.erb (0.3ms)
  Rendered maps/_geocoder.js.erb (0.0ms)
  Rendered maps/_edit.html.erb (3.0ms)
  Rendered tags/_index.html.erb (0.5ms)
  Rendered comments/_index.html.erb (0.1ms)
  Rendered comments/_new.html.erb (0.0ms)
  Rendered maps/_sidebar_annotations.html.erb (0.3ms)
  Rendered maps/_sidebar_exports.html.erb (1.3ms)
  Rendered images/_new.html.erb (1.1ms)
  Rendered layouts/knitter2.html.erb (377.6ms)
Completed 200 OK in 387ms (Views: 324.1ms | ActiveRecord: 57.4ms)

Started GET "/cable" for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Started GET "/cable/" [WebSocket] for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: upgrade, HTTP_UPGRADE: websocket)
An unauthorized connection attempt was rejected
Failed to upgrade to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: upgrade, HTTP_UPGRADE: websocket)
Finished "/cable/" [WebSocket] for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Finished "/cable/" [WebSocket] for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Started GET "/maps/test-map/warpables.json" for 127.0.0.1 at 2019-09-02 11:16:49 +0530
Processing by MapsController#images as JSON
  Parameters: {"id"=>"test-map"}
  Map Load (0.6ms)  SELECT  `maps`.* FROM `maps` WHERE `maps`.`slug` = 'test-map' LIMIT 1
  ↳ app/controllers/maps_controller.rb:198
  Warpable Load (22.6ms)  SELECT `warpables`.* FROM `warpables` WHERE `warpables`.`map_id` = 1
  ↳ app/controllers/maps_controller.rb:115
  Node Load (0.6ms)  SELECT `nodes`.* FROM `nodes` WHERE `nodes`.`id` IN (5, 6, 7, 8)
  ↳ app/models/warpable.rb:135
Completed 200 OK in 39ms (Views: 12.8ms | ActiveRecord: 23.8ms)

@gauravano Have you lifted MK on production mode?

grvsachdeva commented 5 years ago

No, development mode.

alaxalves commented 5 years ago

No, development mode.

I think this might be a production issue.

grvsachdeva commented 5 years ago

Yes, possible. We can only be certain after seeing logs of the req/res

icarito commented 5 years ago

Really I'm not sure if these are the problematic requests in question, but I've made a gist with some particularly slow requests here: https://gist.github.com/icarito/685b4aaf8c9b71b089b29c8705039424 Thanks for looking into it!