=> Booting Thin => Rails 4.0.13 application starting in development on http://0.0.0.0:3000 => Run `rails server -h` for more startup options => Ctrl-C to shutdown server D, [2017-03-17T20:27:52.446325 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:27:52.462912 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.480707 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:27:52.481115 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.492020 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:27:52.492312 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.503940 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:27:52.504238 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.515974 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:27:52.516273 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.574080 #20652] DEBUG -- : 705 rows, 43.5 KB D, [2017-03-17T20:27:52.574478 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.606400 #20652] DEBUG -- : 1 row, 11 Bytes D, [2017-03-17T20:27:52.606677 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.687098 #20652] DEBUG -- : 12 rows, 419 Bytes D, [2017-03-17T20:27:52.687550 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.715648 #20652] DEBUG -- : 1 row, 1 Byte D, [2017-03-17T20:27:52.716012 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.731067 #20652] DEBUG -- : 1 row, 2 Bytes D, [2017-03-17T20:27:52.731367 #20652] DEBUG -- : app/models/crontab.rb:5:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.733225 #20652] DEBUG -- :  (0.8ms) BEGIN D, [2017-03-17T20:27:52.782435 #20652] DEBUG -- : Delayed::Backend::ActiveRecord::Job Load (6.9ms) SELECT "delayed_jobs".* FROM "delayed_jobs" WHERE "delayed_jobs"."queue" = 'crontab' D, [2017-03-17T20:27:52.790227 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:27:52.790496 #20652] DEBUG -- : app/models/crontab.rb:11:in `block in run' app/models/crontab.rb:10:in `run' config/initializers/crontab.rb:1:in `' config/environment.rb:7:in `' config.ru:2:in `block in
' config.ru:in `new' config.ru:in `
' D, [2017-03-17T20:27:52.792086 #20652] DEBUG -- :  (0.8ms) COMMIT Thin web server (v1.6.2 codename Doc Brown) Maximum connections set to 1024 Listening on 0.0.0.0:3000, CTRL+C to stop D, [2017-03-17T20:28:08.631966 #20652] DEBUG -- : D, [2017-03-17T20:28:08.633085 #20652] DEBUG -- : D, [2017-03-17T20:28:08.633626 #20652] DEBUG -- : D, [2017-03-17T20:28:08.634218 #20652] DEBUG -- : I, [2017-03-17T20:28:08.636615 #20652] INFO -- : Started GET "/" for 127.0.0.1 at 2017-03-17 20:28:08 +0000 I, [2017-03-17T20:28:08.636923 #20652] INFO -- : Started GET "/" for 127.0.0.1 at 2017-03-17 20:28:08 +0000 D, [2017-03-17T20:28:08.948895 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.949375 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.949675 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.949959 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.961082 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.961341 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.961564 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.961701 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.970616 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.970929 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.971109 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.971245 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.979449 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.979706 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.979873 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.980001 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.989556 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.989810 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:08.989975 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:08.990105 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:09.038673 #20652] DEBUG -- : 705 rows, 43.5 KB D, [2017-03-17T20:28:09.039089 #20652] DEBUG -- : 705 rows, 43.5 KB D, [2017-03-17T20:28:09.039443 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:09.039898 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:09.077226 #20652] DEBUG -- : 1 row, 11 Bytes D, [2017-03-17T20:28:09.077583 #20652] DEBUG -- : 1 row, 11 Bytes D, [2017-03-17T20:28:09.077829 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:09.078034 #20652] DEBUG -- : config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:10.287090 #20652] INFO -- : Processing by BountySourceController#home as I, [2017-03-17T20:28:10.287440 #20652] INFO -- : Processing by BountySourceController#home as D, [2017-03-17T20:28:11.073733 #20652] DEBUG -- : 1 row, 1 Byte D, [2017-03-17T20:28:11.073999 #20652] DEBUG -- : 1 row, 1 Byte D, [2017-03-17T20:28:11.074165 #20652] DEBUG -- : app/models/person.rb:138:in `' app/models/person.rb:39:in `' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.074346 #20652] DEBUG -- : app/models/person.rb:138:in `' app/models/person.rb:39:in `' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.103474 #20652] DEBUG -- : 27 rows, 1.01 KB D, [2017-03-17T20:28:11.103863 #20652] DEBUG -- : 27 rows, 1.01 KB D, [2017-03-17T20:28:11.104035 #20652] DEBUG -- : app/models/person.rb:138:in `' app/models/person.rb:39:in `' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.104198 #20652] DEBUG -- : app/models/person.rb:138:in `' app/models/person.rb:39:in `' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.124170 #20652] DEBUG -- : 1 row, 2 Bytes D, [2017-03-17T20:28:11.124424 #20652] DEBUG -- : 1 row, 2 Bytes D, [2017-03-17T20:28:11.124644 #20652] DEBUG -- : app/models/person.rb:138:in `' app/models/person.rb:39:in `' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.124783 #20652] DEBUG -- : app/models/person.rb:138:in `' app/models/person.rb:39:in `' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.287280 #20652] DEBUG -- : 1 row, 1 Byte D, [2017-03-17T20:28:11.287554 #20652] DEBUG -- : 1 row, 1 Byte D, [2017-03-17T20:28:11.287723 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.287859 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.301714 #20652] DEBUG -- : 1 row, 2 Bytes D, [2017-03-17T20:28:11.302078 #20652] DEBUG -- : 1 row, 2 Bytes D, [2017-03-17T20:28:11.302406 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.302709 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.313950 #20652] DEBUG -- : AccessToken Load (3.7ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.314214 #20652] DEBUG -- : AccessToken Load (3.7ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.327944 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:11.328200 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:11.328365 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.328505 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:11.331152 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.331408 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.334837 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.335330 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.338024 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.338375 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.340645 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:11.340895 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 I, [2017-03-17T20:28:11.735087 #20652] INFO -- : Rendered layouts/_env.html.erb (30.5ms) I, [2017-03-17T20:28:11.735483 #20652] INFO -- : Rendered layouts/_env.html.erb (30.5ms) I, [2017-03-17T20:28:14.700003 #20652] INFO -- : Rendered layouts/bounty_source.html.erb within layouts/bounty_source (3288.2ms) I, [2017-03-17T20:28:14.700373 #20652] INFO -- : Rendered layouts/bounty_source.html.erb within layouts/bounty_source (3288.2ms) I, [2017-03-17T20:28:14.712079 #20652] INFO -- : Rendered layouts/_env.html.erb (1.4ms) I, [2017-03-17T20:28:14.712357 #20652] INFO -- : Rendered layouts/_env.html.erb (1.4ms) D, [2017-03-17T20:28:14.740564 #20652] DEBUG -- : SQL Logging: 13 statements executed, returning 44.5 KB D, [2017-03-17T20:28:14.740820 #20652] DEBUG -- : SQL Logging: 13 statements executed, returning 44.5 KB D, [2017-03-17T20:28:14.741008 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:14.741153 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:14.744083 #20652] DEBUG -- : Executed 7 times in 28.8ms (1.1/4.1/20.8ms min/median/max), returning 706 rows (43.5 KB): SCHEMA First exec was: SET client_min_messages TO 'warning' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:14.744337 #20652] DEBUG -- : Executed 7 times in 28.8ms (1.1/4.1/20.8ms min/median/max), returning 706 rows (43.5 KB): SCHEMA First exec was: SET client_min_messages TO 'warning' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:14.747041 #20652] DEBUG -- : Executed 3 times in 22.5ms (4.0/7.5/11.7ms min/median/max), returning 29 rows (1.01 KB): SCHEMA First exec was: SELECT COUNT(*) FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE c.relkind in ('v','r') AND c.relname = 'people' AND n.nspname = ANY (current_schemas(false)) app/models/person.rb:138:in `' app/models/person.rb:39:in `' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:14.747289 #20652] DEBUG -- : Executed 3 times in 22.5ms (4.0/7.5/11.7ms min/median/max), returning 29 rows (1.01 KB): SCHEMA First exec was: SELECT COUNT(*) FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE c.relkind in ('v','r') AND c.relname = 'people' AND n.nspname = ANY (current_schemas(false)) app/models/person.rb:138:in `' app/models/person.rb:39:in `' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:14.748916 #20652] DEBUG -- : Executed 2 times in 5.7ms (2.8/2.9/2.9ms min/median/max), returning 2 rows (3 Bytes): SCHEMA First exec was: SELECT COUNT(*) FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE c.relkind in ('v','r') AND c.relname = 'access_tokens' AND n.nspname = ANY (current_schemas(false)) app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:14.749200 #20652] DEBUG -- : Executed 2 times in 5.7ms (2.8/2.9/2.9ms min/median/max), returning 2 rows (3 Bytes): SCHEMA First exec was: SELECT COUNT(*) FROM pg_class c LEFT JOIN pg_namespace n ON n.oid = c.relnamespace WHERE c.relkind in ('v','r') AND c.relname = 'access_tokens' AND n.nspname = ANY (current_schemas(false)) app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:14.751285 #20652] DEBUG -- : Executed 1 time in 4.6ms (4.6/4.6/4.6ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:14.751659 #20652] DEBUG -- : Executed 1 time in 4.6ms (4.6/4.6/4.6ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:14.752733 #20652] INFO -- : Completed 200 OK in 4450ms (Views: 3395.2ms | ActiveRecord: 30.9ms) I, [2017-03-17T20:28:14.753080 #20652] INFO -- : Completed 200 OK in 4450ms (Views: 3395.2ms | ActiveRecord: 30.9ms) W, [2017-03-17T20:28:14.753773 #20652] WARN -- : 127.0.0.1 GET / 200 OK BountySourceController#home HTML 4465.0 (DB 30.9, View 3395.2) {} {} W, [2017-03-17T20:28:14.754042 #20652] WARN -- : 127.0.0.1 GET / 200 OK BountySourceController#home HTML 4465.0 (DB 30.9, View 3395.2) {} {} D, [2017-03-17T20:28:14.931320 #20652] DEBUG -- : D, [2017-03-17T20:28:14.931583 #20652] DEBUG -- : D, [2017-03-17T20:28:14.931739 #20652] DEBUG -- : D, [2017-03-17T20:28:14.931872 #20652] DEBUG -- : I, [2017-03-17T20:28:14.932334 #20652] INFO -- : Started GET "/assets/bountysource.css" for 127.0.0.1 at 2017-03-17 20:28:14 +0000 I, [2017-03-17T20:28:14.932627 #20652] INFO -- : Started GET "/assets/bountysource.css" for 127.0.0.1 at 2017-03-17 20:28:14 +0000 D, [2017-03-17T20:28:15.222440 #20652] DEBUG -- : D, [2017-03-17T20:28:15.222700 #20652] DEBUG -- : D, [2017-03-17T20:28:15.222854 #20652] DEBUG -- : D, [2017-03-17T20:28:15.222986 #20652] DEBUG -- : I, [2017-03-17T20:28:15.223409 #20652] INFO -- : Started GET "/assets/app.js" for 127.0.0.1 at 2017-03-17 20:28:15 +0000 I, [2017-03-17T20:28:15.223798 #20652] INFO -- : Started GET "/assets/app.js" for 127.0.0.1 at 2017-03-17 20:28:15 +0000 D, [2017-03-17T20:28:18.164481 #20652] DEBUG -- : D, [2017-03-17T20:28:18.164885 #20652] DEBUG -- : D, [2017-03-17T20:28:18.165209 #20652] DEBUG -- : D, [2017-03-17T20:28:18.165639 #20652] DEBUG -- : I, [2017-03-17T20:28:18.167672 #20652] INFO -- : Started GET "/track/?data=eyJldmVudCI6ICJtcF9wYWdlX3ZpZXciLCJwcm9wZXJ0aWVzIjogeyIkb3MiOiAiTGludXgiLCIkYnJvd3NlciI6ICJGaXJlZm94IiwiJGN1cnJlbnRfdXJsIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwiJGJyb3dzZXJfdmVyc2lvbiI6IDUyLCIkc2NyZWVuX2hlaWdodCI6IDYwMCwiJHNjcmVlbl93aWR0aCI6IDEwMjQsIm1wX2xpYiI6ICJ3ZWIiLCIkbGliX3ZlcnNpb24iOiAiMi4xMS4wIiwiZGlzdGluY3RfaWQiOiAiMTVhZGRiMGY3MWUxOC0wZjA0YjMxZWI5MDMzYjgtMzg2OTQ2NDYtOTYwMDAtMTVhZGRiMGY3MjE0MyIsIiRpbml0aWFsX3JlZmVycmVyIjogIiRkaXJlY3QiLCIkaW5pdGlhbF9yZWZlcnJpbmdfZG9tYWluIjogIiRkaXJlY3QiLCJtcF9wYWdlIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwibXBfYnJvd3NlciI6ICJGaXJlZm94IiwibXBfcGxhdGZvcm0iOiAiTGludXgiLCJ0b2tlbiI6ICJkZXYifX0%3D&ip=1&_=1489782498154" for 127.0.0.1 at 2017-03-17 20:28:18 +0000 I, [2017-03-17T20:28:18.167984 #20652] INFO -- : Started GET "/track/?data=eyJldmVudCI6ICJtcF9wYWdlX3ZpZXciLCJwcm9wZXJ0aWVzIjogeyIkb3MiOiAiTGludXgiLCIkYnJvd3NlciI6ICJGaXJlZm94IiwiJGN1cnJlbnRfdXJsIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwiJGJyb3dzZXJfdmVyc2lvbiI6IDUyLCIkc2NyZWVuX2hlaWdodCI6IDYwMCwiJHNjcmVlbl93aWR0aCI6IDEwMjQsIm1wX2xpYiI6ICJ3ZWIiLCIkbGliX3ZlcnNpb24iOiAiMi4xMS4wIiwiZGlzdGluY3RfaWQiOiAiMTVhZGRiMGY3MWUxOC0wZjA0YjMxZWI5MDMzYjgtMzg2OTQ2NDYtOTYwMDAtMTVhZGRiMGY3MjE0MyIsIiRpbml0aWFsX3JlZmVycmVyIjogIiRkaXJlY3QiLCIkaW5pdGlhbF9yZWZlcnJpbmdfZG9tYWluIjogIiRkaXJlY3QiLCJtcF9wYWdlIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwibXBfYnJvd3NlciI6ICJGaXJlZm94IiwibXBfcGxhdGZvcm0iOiAiTGludXgiLCJ0b2tlbiI6ICJkZXYifX0%3D&ip=1&_=1489782498154" for 127.0.0.1 at 2017-03-17 20:28:18 +0000 I, [2017-03-17T20:28:18.312955 #20652] INFO -- : Processing by BountySourceController#home as I, [2017-03-17T20:28:18.313217 #20652] INFO -- : Processing by BountySourceController#home as I, [2017-03-17T20:28:18.313581 #20652] INFO -- : Parameters: {"data"=>"eyJldmVudCI6ICJtcF9wYWdlX3ZpZXciLCJwcm9wZXJ0aWVzIjogeyIkb3MiOiAiTGludXgiLCIkYnJvd3NlciI6ICJGaXJlZm94IiwiJGN1cnJlbnRfdXJsIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwiJGJyb3dzZXJfdmVyc2lvbiI6IDUyLCIkc2NyZWVuX2hlaWdodCI6IDYwMCwiJHNjcmVlbl93aWR0aCI6IDEwMjQsIm1wX2xpYiI6ICJ3ZWIiLCIkbGliX3ZlcnNpb24iOiAiMi4xMS4wIiwiZGlzdGluY3RfaWQiOiAiMTVhZGRiMGY3MWUxOC0wZjA0YjMxZWI5MDMzYjgtMzg2OTQ2NDYtOTYwMDAtMTVhZGRiMGY3MjE0MyIsIiRpbml0aWFsX3JlZmVycmVyIjogIiRkaXJlY3QiLCIkaW5pdGlhbF9yZWZlcnJpbmdfZG9tYWluIjogIiRkaXJlY3QiLCJtcF9wYWdlIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwibXBfYnJvd3NlciI6ICJGaXJlZm94IiwibXBfcGxhdGZvcm0iOiAiTGludXgiLCJ0b2tlbiI6ICJkZXYifX0=", "ip"=>"1", "_"=>"1489782498154", "path"=>"track"} I, [2017-03-17T20:28:18.313883 #20652] INFO -- : Parameters: {"data"=>"eyJldmVudCI6ICJtcF9wYWdlX3ZpZXciLCJwcm9wZXJ0aWVzIjogeyIkb3MiOiAiTGludXgiLCIkYnJvd3NlciI6ICJGaXJlZm94IiwiJGN1cnJlbnRfdXJsIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwiJGJyb3dzZXJfdmVyc2lvbiI6IDUyLCIkc2NyZWVuX2hlaWdodCI6IDYwMCwiJHNjcmVlbl93aWR0aCI6IDEwMjQsIm1wX2xpYiI6ICJ3ZWIiLCIkbGliX3ZlcnNpb24iOiAiMi4xMS4wIiwiZGlzdGluY3RfaWQiOiAiMTVhZGRiMGY3MWUxOC0wZjA0YjMxZWI5MDMzYjgtMzg2OTQ2NDYtOTYwMDAtMTVhZGRiMGY3MjE0MyIsIiRpbml0aWFsX3JlZmVycmVyIjogIiRkaXJlY3QiLCIkaW5pdGlhbF9yZWZlcnJpbmdfZG9tYWluIjogIiRkaXJlY3QiLCJtcF9wYWdlIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwibXBfYnJvd3NlciI6ICJGaXJlZm94IiwibXBfcGxhdGZvcm0iOiAiTGludXgiLCJ0b2tlbiI6ICJkZXYifX0=", "ip"=>"1", "_"=>"1489782498154", "path"=>"track"} D, [2017-03-17T20:28:18.318992 #20652] DEBUG -- : AccessToken Load (1.7ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.319476 #20652] DEBUG -- : AccessToken Load (1.7ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.332391 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:18.332645 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:18.332813 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:18.332951 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:18.335366 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.335619 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.338933 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.339291 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.342440 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.342718 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.345173 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:18.345431 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 I, [2017-03-17T20:28:18.412105 #20652] INFO -- : Rendered layouts/_env.html.erb (9.5ms) I, [2017-03-17T20:28:18.412527 #20652] INFO -- : Rendered layouts/_env.html.erb (9.5ms) I, [2017-03-17T20:28:18.449330 #20652] INFO -- : Rendered layouts/bounty_source.html.erb within layouts/bounty_source (76.2ms) I, [2017-03-17T20:28:18.449707 #20652] INFO -- : Rendered layouts/bounty_source.html.erb within layouts/bounty_source (76.2ms) I, [2017-03-17T20:28:18.471984 #20652] INFO -- : Rendered layouts/_env.html.erb (2.4ms) I, [2017-03-17T20:28:18.472345 #20652] INFO -- : Rendered layouts/_env.html.erb (2.4ms) D, [2017-03-17T20:28:18.501440 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:18.501827 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:18.513736 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:18.514101 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:18.516784 #20652] DEBUG -- : Executed 1 time in 3.3ms (3.3/3.3/3.3ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:18.517116 #20652] DEBUG -- : Executed 1 time in 3.3ms (3.3/3.3/3.3ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:18.517534 #20652] INFO -- : Completed 200 OK in 186ms (Views: 152.4ms | ActiveRecord: 2.3ms) I, [2017-03-17T20:28:18.517736 #20652] INFO -- : Completed 200 OK in 186ms (Views: 152.4ms | ActiveRecord: 2.3ms) W, [2017-03-17T20:28:18.518637 #20652] WARN -- : 127.0.0.1 GET /track?data=eyJldmVudCI6ICJtcF9wYWdlX3ZpZXciLCJwcm9wZXJ0aWVzIjogeyIkb3MiOiAiTGludXgiLCIkYnJvd3NlciI6ICJGaXJlZm94IiwiJGN1cnJlbnRfdXJsIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwiJGJyb3dzZXJfdmVyc2lvbiI6IDUyLCIkc2NyZWVuX2hlaWdodCI6IDYwMCwiJHNjcmVlbl93aWR0aCI6IDEwMjQsIm1wX2xpYiI6ICJ3ZWIiLCIkbGliX3ZlcnNpb24iOiAiMi4xMS4wIiwiZGlzdGluY3RfaWQiOiAiMTVhZGRiMGY3MWUxOC0wZjA0YjMxZWI5MDMzYjgtMzg2OTQ2NDYtOTYwMDAtMTVhZGRiMGY3MjE0MyIsIiRpbml0aWFsX3JlZmVycmVyIjogIiRkaXJlY3QiLCIkaW5pdGlhbF9yZWZlcnJpbmdfZG9tYWluIjogIiRkaXJlY3QiLCJtcF9wYWdlIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwibXBfYnJvd3NlciI6ICJGaXJlZm94IiwibXBfcGxhdGZvcm0iOiAiTGludXgiLCJ0b2tlbiI6ICJkZXYifX0%3D&ip=1&_=1489782498154 200 OK BountySourceController#home 203.7 (DB 2.3, View 152.4) {"data"=>"eyJldmVudCI6ICJtcF9wYWdlX3ZpZXciLCJwcm9wZXJ0aWVzIjogeyIkb3MiOiAiTGludXgiLCIkYnJvd3NlciI6ICJGaXJlZm94IiwiJGN1cnJlbnRfdXJsIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwiJGJyb3dzZXJfdmVyc2lvbiI6IDUyLCIkc2NyZWVuX2hlaWdodCI6IDYwMCwiJHNjcmVlbl93aWR0aCI6IDEwMjQsIm1wX2xpYiI6ICJ3ZWIiLCIkbGliX3ZlcnNpb24iOiAiMi4xMS4wIiwiZGlzdGluY3RfaWQiOiAiMTVhZGRiMGY3MWUxOC0wZjA0YjMxZWI5MDMzYjgtMzg2OTQ2NDYtOTYwMDAtMTVhZGRiMGY3MjE0MyIsIiRpbml0aWFsX3JlZmVycmVyIjogIiRkaXJlY3QiLCIkaW5pdGlhbF9yZWZlcnJpbmdfZG9tYWluIjogIiRkaXJlY3QiLCJtcF9wYWdlIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwibXBfYnJvd3NlciI6ICJGaXJlZm94IiwibXBfcGxhdGZvcm0iOiAiTGludXgiLCJ0b2tlbiI6ICJkZXYifX0=", "ip"=>"1", "_"=>"1489782498154", "path"=>"track"} {} W, [2017-03-17T20:28:18.518940 #20652] WARN -- : 127.0.0.1 GET /track?data=eyJldmVudCI6ICJtcF9wYWdlX3ZpZXciLCJwcm9wZXJ0aWVzIjogeyIkb3MiOiAiTGludXgiLCIkYnJvd3NlciI6ICJGaXJlZm94IiwiJGN1cnJlbnRfdXJsIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwiJGJyb3dzZXJfdmVyc2lvbiI6IDUyLCIkc2NyZWVuX2hlaWdodCI6IDYwMCwiJHNjcmVlbl93aWR0aCI6IDEwMjQsIm1wX2xpYiI6ICJ3ZWIiLCIkbGliX3ZlcnNpb24iOiAiMi4xMS4wIiwiZGlzdGluY3RfaWQiOiAiMTVhZGRiMGY3MWUxOC0wZjA0YjMxZWI5MDMzYjgtMzg2OTQ2NDYtOTYwMDAtMTVhZGRiMGY3MjE0MyIsIiRpbml0aWFsX3JlZmVycmVyIjogIiRkaXJlY3QiLCIkaW5pdGlhbF9yZWZlcnJpbmdfZG9tYWluIjogIiRkaXJlY3QiLCJtcF9wYWdlIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwibXBfYnJvd3NlciI6ICJGaXJlZm94IiwibXBfcGxhdGZvcm0iOiAiTGludXgiLCJ0b2tlbiI6ICJkZXYifX0%3D&ip=1&_=1489782498154 200 OK BountySourceController#home 203.7 (DB 2.3, View 152.4) {"data"=>"eyJldmVudCI6ICJtcF9wYWdlX3ZpZXciLCJwcm9wZXJ0aWVzIjogeyIkb3MiOiAiTGludXgiLCIkYnJvd3NlciI6ICJGaXJlZm94IiwiJGN1cnJlbnRfdXJsIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwiJGJyb3dzZXJfdmVyc2lvbiI6IDUyLCIkc2NyZWVuX2hlaWdodCI6IDYwMCwiJHNjcmVlbl93aWR0aCI6IDEwMjQsIm1wX2xpYiI6ICJ3ZWIiLCIkbGliX3ZlcnNpb24iOiAiMi4xMS4wIiwiZGlzdGluY3RfaWQiOiAiMTVhZGRiMGY3MWUxOC0wZjA0YjMxZWI5MDMzYjgtMzg2OTQ2NDYtOTYwMDAtMTVhZGRiMGY3MjE0MyIsIiRpbml0aWFsX3JlZmVycmVyIjogIiRkaXJlY3QiLCIkaW5pdGlhbF9yZWZlcnJpbmdfZG9tYWluIjogIiRkaXJlY3QiLCJtcF9wYWdlIjogImh0dHA6Ly8wLjAuMC4wOjMwMDAvIiwibXBfYnJvd3NlciI6ICJGaXJlZm94IiwibXBfcGxhdGZvcm0iOiAiTGludXgiLCJ0b2tlbiI6ICJkZXYifX0=", "ip"=>"1", "_"=>"1489782498154", "path"=>"track"} {} D, [2017-03-17T20:28:19.145634 #20652] DEBUG -- : D, [2017-03-17T20:28:19.145975 #20652] DEBUG -- : D, [2017-03-17T20:28:19.146168 #20652] DEBUG -- : D, [2017-03-17T20:28:19.146302 #20652] DEBUG -- : I, [2017-03-17T20:28:19.147026 #20652] INFO -- : Started GET "/assets/app.js" for 127.0.0.1 at 2017-03-17 20:28:19 +0000 I, [2017-03-17T20:28:19.147226 #20652] INFO -- : Started GET "/assets/app.js" for 127.0.0.1 at 2017-03-17 20:28:19 +0000 D, [2017-03-17T20:28:20.451757 #20652] DEBUG -- : D, [2017-03-17T20:28:20.454224 #20652] DEBUG -- : D, [2017-03-17T20:28:20.456895 #20652] DEBUG -- : D, [2017-03-17T20:28:20.457162 #20652] DEBUG -- : I, [2017-03-17T20:28:20.459558 #20652] INFO -- : Started GET "/user?access_token=[FILTERED]&callback=CORS&mixpanel_id=15addb0f71e18-0f04b31eb9033b8-38694646-96000-15addb0f72143&page=1&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:20 +0000 I, [2017-03-17T20:28:20.459923 #20652] INFO -- : Started GET "/user?access_token=[FILTERED]&callback=CORS&mixpanel_id=15addb0f71e18-0f04b31eb9033b8-38694646-96000-15addb0f72143&page=1&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:20 +0000 I, [2017-03-17T20:28:20.566548 #20652] INFO -- : Processing by BountySourceController#home as I, [2017-03-17T20:28:20.566930 #20652] INFO -- : Processing by BountySourceController#home as I, [2017-03-17T20:28:20.567422 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "mixpanel_id"=>"15addb0f71e18-0f04b31eb9033b8-38694646-96000-15addb0f72143", "page"=>"1", "per_page"=>"250", "path"=>"user"} I, [2017-03-17T20:28:20.567845 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "mixpanel_id"=>"15addb0f71e18-0f04b31eb9033b8-38694646-96000-15addb0f72143", "page"=>"1", "per_page"=>"250", "path"=>"user"} D, [2017-03-17T20:28:20.601382 #20652] DEBUG -- : 7 rows, 278 Bytes D, [2017-03-17T20:28:20.601718 #20652] DEBUG -- : 7 rows, 278 Bytes D, [2017-03-17T20:28:20.602008 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:20.602247 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:20.609752 #20652] DEBUG -- : AccessToken Load (4.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:20.610140 #20652] DEBUG -- : AccessToken Load (4.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:20.630001 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:20.631117 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:20.634371 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:20.634810 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:20.771194 #20652] DEBUG -- :  (3.5ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:20.772220 #20652] DEBUG -- :  (3.5ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:20.991135 #20652] DEBUG -- : Person Load (5.9ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:20.991519 #20652] DEBUG -- : Person Load (5.9ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:21.009380 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:21.009758 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:21.010213 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.010559 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.228810 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:21.229544 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:21.239027 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:21.239409 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:21.249820 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:21.250200 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:28:21.287753 #20652] INFO -- : Rendered layouts/_env.html.erb (7.6ms) I, [2017-03-17T20:28:21.288136 #20652] INFO -- : Rendered layouts/_env.html.erb (7.6ms) I, [2017-03-17T20:28:21.327503 #20652] INFO -- : Rendered layouts/bounty_source.html.erb within layouts/bounty_source (62.3ms) I, [2017-03-17T20:28:21.328202 #20652] INFO -- : Rendered layouts/bounty_source.html.erb within layouts/bounty_source (62.3ms) I, [2017-03-17T20:28:21.340048 #20652] INFO -- : Rendered layouts/_env.html.erb (2.5ms) I, [2017-03-17T20:28:21.340985 #20652] INFO -- : Rendered layouts/_env.html.erb (2.5ms) D, [2017-03-17T20:28:21.540900 #20652] DEBUG -- : Person Exists (2.7ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:21.541271 #20652] DEBUG -- : Person Exists (2.7ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:21.565084 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:21.565430 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:21.565742 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.566041 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.585106 #20652] DEBUG -- : SQL Logging: 4 statements executed, returning 659 Bytes D, [2017-03-17T20:28:21.585463 #20652] DEBUG -- : SQL Logging: 4 statements executed, returning 659 Bytes D, [2017-03-17T20:28:21.585826 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:21.586135 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:21.589774 #20652] DEBUG -- : Executed 1 time in 7.4ms (7.4/7.4/7.4ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.590142 #20652] DEBUG -- : Executed 1 time in 7.4ms (7.4/7.4/7.4ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.592422 #20652] DEBUG -- : Executed 1 time in 5.5ms (5.5/5.5/5.5ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.592809 #20652] DEBUG -- : Executed 1 time in 5.5ms (5.5/5.5/5.5ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.595599 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 7 rows (278 Bytes): SCHEMA First exec was: SELECT a.attname, format_type(a.atttypid, a.atttypmod), pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod FROM pg_attribute a LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum WHERE a.attrelid = '"access_tokens"'::regclass AND a.attnum > 0 AND NOT a.attisdropped ORDER BY a.attnum app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.595990 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 7 rows (278 Bytes): SCHEMA First exec was: SELECT a.attname, format_type(a.atttypid, a.atttypmod), pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod FROM pg_attribute a LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum WHERE a.attrelid = '"access_tokens"'::regclass AND a.attnum > 0 AND NOT a.attisdropped ORDER BY a.attnum app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.598608 #20652] DEBUG -- : Executed 1 time in 4.1ms (4.1/4.1/4.1ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:21.599044 #20652] DEBUG -- : Executed 1 time in 4.1ms (4.1/4.1/4.1ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:21.599660 #20652] INFO -- : Completed 200 OK in 1015ms (Views: 122.8ms | ActiveRecord: 21.2ms) I, [2017-03-17T20:28:21.600004 #20652] INFO -- : Completed 200 OK in 1015ms (Views: 122.8ms | ActiveRecord: 21.2ms) W, [2017-03-17T20:28:21.600786 #20652] WARN -- : 127.0.0.1 GET /user?access_token=1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f&callback=CORS&mixpanel_id=15addb0f71e18-0f04b31eb9033b8-38694646-96000-15addb0f72143&page=1&per_page=250 200 OK BountySourceController#home JSON 1031.9 (DB 21.2, View 122.8) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "mixpanel_id"=>"15addb0f71e18-0f04b31eb9033b8-38694646-96000-15addb0f72143", "page"=>"1", "per_page"=>"250", "path"=>"user"} {} W, [2017-03-17T20:28:21.601141 #20652] WARN -- : 127.0.0.1 GET /user?access_token=1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f&callback=CORS&mixpanel_id=15addb0f71e18-0f04b31eb9033b8-38694646-96000-15addb0f72143&page=1&per_page=250 200 OK BountySourceController#home JSON 1031.9 (DB 21.2, View 122.8) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "mixpanel_id"=>"15addb0f71e18-0f04b31eb9033b8-38694646-96000-15addb0f72143", "page"=>"1", "per_page"=>"250", "path"=>"user"} {} D, [2017-03-17T20:28:21.865091 #20652] DEBUG -- : D, [2017-03-17T20:28:21.865457 #20652] DEBUG -- : D, [2017-03-17T20:28:21.865777 #20652] DEBUG -- : D, [2017-03-17T20:28:21.866045 #20652] DEBUG -- : I, [2017-03-17T20:28:21.866802 #20652] INFO -- : Started GET "/assets/Bountysource-green.png" for 127.0.0.1 at 2017-03-17 20:28:21 +0000 I, [2017-03-17T20:28:21.867079 #20652] INFO -- : Started GET "/assets/Bountysource-green.png" for 127.0.0.1 at 2017-03-17 20:28:21 +0000 D, [2017-03-17T20:28:22.410477 #20652] DEBUG -- : D, [2017-03-17T20:28:22.410859 #20652] DEBUG -- : D, [2017-03-17T20:28:22.411165 #20652] DEBUG -- : D, [2017-03-17T20:28:22.411446 #20652] DEBUG -- : I, [2017-03-17T20:28:22.413219 #20652] INFO -- : Started GET "/people/count?access_token=[FILTERED]&callback=CORS&page=1&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:22 +0000 I, [2017-03-17T20:28:22.413655 #20652] INFO -- : Started GET "/people/count?access_token=[FILTERED]&callback=CORS&page=1&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:22 +0000 I, [2017-03-17T20:28:22.535431 #20652] INFO -- : Processing by BountySourceController#home as I, [2017-03-17T20:28:22.535764 #20652] INFO -- : Processing by BountySourceController#home as I, [2017-03-17T20:28:22.536042 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"250", "path"=>"people/count"} I, [2017-03-17T20:28:22.536208 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"250", "path"=>"people/count"} D, [2017-03-17T20:28:22.543480 #20652] DEBUG -- : AccessToken Load (2.6ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:22.543937 #20652] DEBUG -- : AccessToken Load (2.6ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:22.558544 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:22.558917 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:22.559275 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.559751 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.569388 #20652] DEBUG -- :  (2.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:22.569696 #20652] DEBUG -- :  (2.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:22.578461 #20652] DEBUG -- : Person Load (2.7ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:22.578932 #20652] DEBUG -- : Person Load (2.7ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:22.597478 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:22.597882 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:22.598199 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.598486 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.609189 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:22.609585 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:22.617461 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:22.617763 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:22.622795 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:22.623170 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:28:22.645794 #20652] INFO -- : Rendered layouts/_env.html.erb (1.8ms) I, [2017-03-17T20:28:22.646095 #20652] INFO -- : Rendered layouts/_env.html.erb (1.8ms) I, [2017-03-17T20:28:22.683878 #20652] INFO -- : Rendered layouts/bounty_source.html.erb within layouts/bounty_source (47.5ms) I, [2017-03-17T20:28:22.684244 #20652] INFO -- : Rendered layouts/bounty_source.html.erb within layouts/bounty_source (47.5ms) I, [2017-03-17T20:28:22.696211 #20652] INFO -- : Rendered layouts/_env.html.erb (3.7ms) I, [2017-03-17T20:28:22.696661 #20652] INFO -- : Rendered layouts/_env.html.erb (3.7ms) D, [2017-03-17T20:28:22.740771 #20652] DEBUG -- : Person Exists (2.2ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:22.741069 #20652] DEBUG -- : Person Exists (2.2ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:22.759885 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:22.760253 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:22.760574 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.760890 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.775420 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:28:22.775813 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:28:22.776195 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:22.776505 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:22.778901 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.779361 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.781616 #20652] DEBUG -- : Executed 1 time in 4.1ms (4.1/4.1/4.1ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.781985 #20652] DEBUG -- : Executed 1 time in 4.1ms (4.1/4.1/4.1ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.784594 #20652] DEBUG -- : Executed 1 time in 3.3ms (3.3/3.3/3.3ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:22.785018 #20652] DEBUG -- : Executed 1 time in 3.3ms (3.3/3.3/3.3ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:22.785624 #20652] INFO -- : Completed 200 OK in 236ms (Views: 103.1ms | ActiveRecord: 10.4ms) I, [2017-03-17T20:28:22.785914 #20652] INFO -- : Completed 200 OK in 236ms (Views: 103.1ms | ActiveRecord: 10.4ms) W, [2017-03-17T20:28:22.786456 #20652] WARN -- : 127.0.0.1 GET /people/count?access_token=1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f&callback=CORS&page=1&per_page=250 200 OK BountySourceController#home JSON 249.6 (DB 10.4, View 103.1) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"250", "path"=>"people/count"} {} W, [2017-03-17T20:28:22.786758 #20652] WARN -- : 127.0.0.1 GET /people/count?access_token=1.1489778189.166e2f95903c1332c10b91c7c464bacdf42ac26f&callback=CORS&page=1&per_page=250 200 OK BountySourceController#home JSON 249.6 (DB 10.4, View 103.1) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"250", "path"=>"people/count"} {} D, [2017-03-17T20:28:25.628099 #20652] DEBUG -- : D, [2017-03-17T20:28:25.628941 #20652] DEBUG -- : D, [2017-03-17T20:28:25.641200 #20652] DEBUG -- : D, [2017-03-17T20:28:25.641565 #20652] DEBUG -- : I, [2017-03-17T20:28:25.642368 #20652] INFO -- : Started GET "/admin" for 127.0.0.1 at 2017-03-17 20:28:25 +0000 I, [2017-03-17T20:28:25.642675 #20652] INFO -- : Started GET "/admin" for 127.0.0.1 at 2017-03-17 20:28:25 +0000 I, [2017-03-17T20:28:25.805560 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:25.805927 #20652] INFO -- : Processing by AdminController#home as D, [2017-03-17T20:28:25.818262 #20652] DEBUG -- : AccessToken Load (3.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.818604 #20652] DEBUG -- : AccessToken Load (3.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.835075 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:25.835418 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:25.835729 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:25.835987 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:25.839670 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.840071 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.843925 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.844245 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.846934 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.847271 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.851489 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:25.851744 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 I, [2017-03-17T20:28:26.046590 #20652] INFO -- : Rendered layouts/_env.html.erb (2.2ms) I, [2017-03-17T20:28:26.046984 #20652] INFO -- : Rendered layouts/_env.html.erb (2.2ms) I, [2017-03-17T20:28:27.418234 #20652] INFO -- : Rendered layouts/admin.html.erb (1544.6ms) I, [2017-03-17T20:28:27.418561 #20652] INFO -- : Rendered layouts/admin.html.erb (1544.6ms) D, [2017-03-17T20:28:27.420307 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:27.420556 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:27.420731 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:27.420867 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:27.422322 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:27.422566 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:27.422873 #20652] INFO -- : Completed 200 OK in 1613ms (Views: 1565.7ms | ActiveRecord: 3.7ms) I, [2017-03-17T20:28:27.423040 #20652] INFO -- : Completed 200 OK in 1613ms (Views: 1565.7ms | ActiveRecord: 3.7ms) W, [2017-03-17T20:28:27.423355 #20652] WARN -- : 127.0.0.1 GET /admin 200 OK AdminController#home HTML 1616.7 (DB 3.7, View 1565.7) {} {} W, [2017-03-17T20:28:27.423628 #20652] WARN -- : 127.0.0.1 GET /admin 200 OK AdminController#home HTML 1616.7 (DB 3.7, View 1565.7) {} {} D, [2017-03-17T20:28:29.135812 #20652] DEBUG -- : D, [2017-03-17T20:28:29.136218 #20652] DEBUG -- : D, [2017-03-17T20:28:29.136610 #20652] DEBUG -- : D, [2017-03-17T20:28:29.136939 #20652] DEBUG -- : I, [2017-03-17T20:28:29.138621 #20652] INFO -- : Started GET "/admin/delayed_jobs/info?callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:29 +0000 I, [2017-03-17T20:28:29.138937 #20652] INFO -- : Started GET "/admin/delayed_jobs/info?callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:29 +0000 I, [2017-03-17T20:28:29.258716 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:29.259082 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:29.259481 #20652] INFO -- : Parameters: {"callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs/info"} I, [2017-03-17T20:28:29.259810 #20652] INFO -- : Parameters: {"callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs/info"} D, [2017-03-17T20:28:29.267500 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.267887 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.285223 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:29.285592 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:29.286064 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:29.286404 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:29.290512 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.290888 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.295105 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.295496 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.299840 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.300234 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.304472 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:29.304858 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 I, [2017-03-17T20:28:29.326887 #20652] INFO -- : Rendered layouts/_env.html.erb (2.1ms) I, [2017-03-17T20:28:29.327216 #20652] INFO -- : Rendered layouts/_env.html.erb (2.1ms) I, [2017-03-17T20:28:29.346663 #20652] INFO -- : Rendered layouts/admin.html.erb (33.4ms) I, [2017-03-17T20:28:29.346996 #20652] INFO -- : Rendered layouts/admin.html.erb (33.4ms) D, [2017-03-17T20:28:29.358996 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:29.359337 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:29.359609 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:29.359890 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:29.362166 #20652] DEBUG -- : Executed 1 time in 4.1ms (4.1/4.1/4.1ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:29.362508 #20652] DEBUG -- : Executed 1 time in 4.1ms (4.1/4.1/4.1ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:29.363161 #20652] INFO -- : Completed 200 OK in 97ms (Views: 41.0ms | ActiveRecord: 3.4ms) I, [2017-03-17T20:28:29.363575 #20652] INFO -- : Completed 200 OK in 97ms (Views: 41.0ms | ActiveRecord: 3.4ms) W, [2017-03-17T20:28:29.364221 #20652] WARN -- : 127.0.0.1 GET /admin/delayed_jobs/info?callback=CORS&per_page=250 200 OK AdminController#home JSON 103.6 (DB 3.4, View 41.0) {"callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs/info"} {} W, [2017-03-17T20:28:29.364654 #20652] WARN -- : 127.0.0.1 GET /admin/delayed_jobs/info?callback=CORS&per_page=250 200 OK AdminController#home JSON 103.6 (DB 3.4, View 41.0) {"callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs/info"} {} D, [2017-03-17T20:28:30.050433 #20652] DEBUG -- : D, [2017-03-17T20:28:30.050813 #20652] DEBUG -- : D, [2017-03-17T20:28:30.051130 #20652] DEBUG -- : D, [2017-03-17T20:28:30.051407 #20652] DEBUG -- : I, [2017-03-17T20:28:30.053137 #20652] INFO -- : Started GET "/admin/stats?callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:30 +0000 I, [2017-03-17T20:28:30.053565 #20652] INFO -- : Started GET "/admin/stats?callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:30 +0000 I, [2017-03-17T20:28:30.169687 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:30.170078 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:30.170514 #20652] INFO -- : Parameters: {"callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} I, [2017-03-17T20:28:30.170830 #20652] INFO -- : Parameters: {"callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} D, [2017-03-17T20:28:30.177678 #20652] DEBUG -- : AccessToken Load (2.3ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.178026 #20652] DEBUG -- : AccessToken Load (2.3ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.195240 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:30.195608 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:30.196004 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:30.196713 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:30.201319 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.201669 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.205813 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.206191 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.210168 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.210573 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.215378 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.215734 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 I, [2017-03-17T20:28:30.235590 #20652] INFO -- : Rendered layouts/_env.html.erb (3.9ms) I, [2017-03-17T20:28:30.235980 #20652] INFO -- : Rendered layouts/_env.html.erb (3.9ms) I, [2017-03-17T20:28:30.255819 #20652] INFO -- : Rendered layouts/admin.html.erb (32.7ms) I, [2017-03-17T20:28:30.256160 #20652] INFO -- : Rendered layouts/admin.html.erb (32.7ms) D, [2017-03-17T20:28:30.273389 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:30.273889 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:30.274269 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:30.274580 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:30.277338 #20652] DEBUG -- : Executed 1 time in 3.6ms (3.6/3.6/3.6ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:30.277717 #20652] DEBUG -- : Executed 1 time in 3.6ms (3.6/3.6/3.6ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:30.278331 #20652] INFO -- : Completed 200 OK in 96ms (Views: 39.4ms | ActiveRecord: 3.1ms) I, [2017-03-17T20:28:30.278665 #20652] INFO -- : Completed 200 OK in 96ms (Views: 39.4ms | ActiveRecord: 3.1ms) W, [2017-03-17T20:28:30.279391 #20652] WARN -- : 127.0.0.1 GET /admin/stats?callback=CORS&per_page=250 200 OK AdminController#home JSON 107.6 (DB 3.1, View 39.4) {"callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} W, [2017-03-17T20:28:30.279748 #20652] WARN -- : 127.0.0.1 GET /admin/stats?callback=CORS&per_page=250 200 OK AdminController#home JSON 107.6 (DB 3.1, View 39.4) {"callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} D, [2017-03-17T20:28:30.291020 #20652] DEBUG -- : D, [2017-03-17T20:28:30.291379 #20652] DEBUG -- : D, [2017-03-17T20:28:30.291694 #20652] DEBUG -- : D, [2017-03-17T20:28:30.292008 #20652] DEBUG -- : I, [2017-03-17T20:28:30.293385 #20652] INFO -- : Started GET "/admin/stats?callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:30 +0000 I, [2017-03-17T20:28:30.295605 #20652] INFO -- : Started GET "/admin/stats?callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:30 +0000 I, [2017-03-17T20:28:30.412123 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:30.412519 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:30.413013 #20652] INFO -- : Parameters: {"callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} I, [2017-03-17T20:28:30.413374 #20652] INFO -- : Parameters: {"callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} D, [2017-03-17T20:28:30.424595 #20652] DEBUG -- : AccessToken Load (6.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.424981 #20652] DEBUG -- : AccessToken Load (6.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.448359 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:30.448725 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:30.449059 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:30.449419 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:30.453283 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.453747 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.459180 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.459615 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.463414 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.463994 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.468215 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:30.468594 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 I, [2017-03-17T20:28:30.484980 #20652] INFO -- : Rendered layouts/_env.html.erb (2.4ms) I, [2017-03-17T20:28:30.485395 #20652] INFO -- : Rendered layouts/_env.html.erb (2.4ms) I, [2017-03-17T20:28:30.504726 #20652] INFO -- : Rendered layouts/admin.html.erb (29.3ms) I, [2017-03-17T20:28:30.505058 #20652] INFO -- : Rendered layouts/admin.html.erb (29.3ms) D, [2017-03-17T20:28:30.516514 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:30.516899 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:28:30.517263 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:30.517558 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:30.520094 #20652] DEBUG -- : Executed 1 time in 8.0ms (8.0/8.0/8.0ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:30.520515 #20652] DEBUG -- : Executed 1 time in 8.0ms (8.0/8.0/8.0ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:30.521065 #20652] INFO -- : Completed 200 OK in 101ms (Views: 35.4ms | ActiveRecord: 7.3ms) I, [2017-03-17T20:28:30.521402 #20652] INFO -- : Completed 200 OK in 101ms (Views: 35.4ms | ActiveRecord: 7.3ms) W, [2017-03-17T20:28:30.522056 #20652] WARN -- : 127.0.0.1 GET /admin/stats?callback=CORS&per_page=250 200 OK AdminController#home JSON 107.6 (DB 7.3, View 35.4) {"callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} W, [2017-03-17T20:28:30.522436 #20652] WARN -- : 127.0.0.1 GET /admin/stats?callback=CORS&per_page=250 200 OK AdminController#home JSON 107.6 (DB 7.3, View 35.4) {"callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} D, [2017-03-17T20:28:42.560526 #20652] DEBUG -- : D, [2017-03-17T20:28:42.561029 #20652] DEBUG -- : D, [2017-03-17T20:28:42.561476 #20652] DEBUG -- : D, [2017-03-17T20:28:42.561880 #20652] DEBUG -- : I, [2017-03-17T20:28:42.562836 #20652] INFO -- : Started POST "/admin/login" for 127.0.0.1 at 2017-03-17 20:28:42 +0000 I, [2017-03-17T20:28:42.563339 #20652] INFO -- : Started POST "/admin/login" for 127.0.0.1 at 2017-03-17 20:28:42 +0000 I, [2017-03-17T20:28:42.891562 #20652] INFO -- : Processing by Api::V0::HomeController#login as I, [2017-03-17T20:28:42.891831 #20652] INFO -- : Processing by Api::V0::HomeController#login as I, [2017-03-17T20:28:42.892154 #20652] INFO -- : Parameters: {"email"=>"test@test.com", "password"=>"[FILTERED]", "admin_secret"=>"[FILTERED]", "per_page"=>250, "callback"=>"CORS", "vendor_string"=>"bountysource", "home"=>{"email"=>"test@test.com", "password"=>"[FILTERED]", "admin_secret"=>"[FILTERED]", "per_page"=>250, "callback"=>"CORS"}} I, [2017-03-17T20:28:42.892317 #20652] INFO -- : Parameters: {"email"=>"test@test.com", "password"=>"[FILTERED]", "admin_secret"=>"[FILTERED]", "per_page"=>250, "callback"=>"CORS", "vendor_string"=>"bountysource", "home"=>{"email"=>"test@test.com", "password"=>"[FILTERED]", "admin_secret"=>"[FILTERED]", "per_page"=>250, "callback"=>"CORS"}} D, [2017-03-17T20:28:42.899740 #20652] DEBUG -- : AccessToken Load (1.7ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.899998 #20652] DEBUG -- : AccessToken Load (1.7ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.910532 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:42.910805 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:42.911009 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:42.911165 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:42.913853 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.914139 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.916631 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.916880 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.919420 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.919710 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.922234 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.922507 #20652] DEBUG -- : CACHE (0.1ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:42.931284 #20652] DEBUG -- : Person Load (2.1ms) SELECT "people".* FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."email" = 'test@test.com' LIMIT 1 D, [2017-03-17T20:28:42.931546 #20652] DEBUG -- : Person Load (2.1ms) SELECT "people".* FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."email" = 'test@test.com' LIMIT 1 D, [2017-03-17T20:28:42.942451 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:42.942719 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:42.942887 #20652] DEBUG -- : app/models/person.rb:245:in `authenticate' app/controllers/application_controller.rb:161:in `find_person' app/controllers/application_controller.rb:174:in `info_for_paper_trail' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:42.943034 #20652] DEBUG -- : app/models/person.rb:245:in `authenticate' app/controllers/application_controller.rb:161:in `find_person' app/controllers/application_controller.rb:174:in `info_for_paper_trail' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.154138 #20652] DEBUG -- : CACHE (0.1ms) SELECT "people".* FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."email" = 'test@test.com' LIMIT 1 D, [2017-03-17T20:28:43.154406 #20652] DEBUG -- : CACHE (0.1ms) SELECT "people".* FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."email" = 'test@test.com' LIMIT 1 D, [2017-03-17T20:28:43.370477 #20652] DEBUG -- :  (0.9ms) BEGIN D, [2017-03-17T20:28:43.370750 #20652] DEBUG -- :  (0.9ms) BEGIN D, [2017-03-17T20:28:43.503141 #20652] DEBUG -- : Person Load (1.9ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:43.503614 #20652] DEBUG -- : Person Load (1.9ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:43.524543 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:43.524798 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:43.525217 #20652] DEBUG -- : app/models/access_token.rb:45:in `generate_token' app/models/access_token.rb:28:in `token' app/models/person.rb:287:in `create_access_token' app/controllers/api/v0/home_controller.rb:10:in `login' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.525363 #20652] DEBUG -- : app/models/access_token.rb:45:in `generate_token' app/models/access_token.rb:28:in `token' app/models/person.rb:287:in `create_access_token' app/controllers/api/v0/home_controller.rb:10:in `login' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.572417 #20652] DEBUG -- : SQL (41.4ms) INSERT INTO "access_tokens" ("created_at", "person_id", "remote_ip", "token", "updated_at", "user_agent") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" [["created_at", Fri, 17 Mar 2017 20:28:43 UTC +00:00], ["person_id", 1], ["remote_ip", "127.0.0.1"], ["token", "1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38"], ["updated_at", Fri, 17 Mar 2017 20:28:43 UTC +00:00], ["user_agent", "Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0"]] D, [2017-03-17T20:28:43.572722 #20652] DEBUG -- : SQL (41.4ms) INSERT INTO "access_tokens" ("created_at", "person_id", "remote_ip", "token", "updated_at", "user_agent") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" [["created_at", Fri, 17 Mar 2017 20:28:43 UTC +00:00], ["person_id", 1], ["remote_ip", "127.0.0.1"], ["token", "1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38"], ["updated_at", Fri, 17 Mar 2017 20:28:43 UTC +00:00], ["user_agent", "Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0"]] D, [2017-03-17T20:28:43.603037 #20652] DEBUG -- : 1 row, 1 Byte D, [2017-03-17T20:28:43.603618 #20652] DEBUG -- : 1 row, 1 Byte D, [2017-03-17T20:28:43.604128 #20652] DEBUG -- : app/models/person.rb:287:in `create_access_token' app/controllers/api/v0/home_controller.rb:10:in `login' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.604525 #20652] DEBUG -- : app/models/person.rb:287:in `create_access_token' app/controllers/api/v0/home_controller.rb:10:in `login' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.631137 #20652] DEBUG -- :  (22.0ms) COMMIT D, [2017-03-17T20:28:43.631513 #20652] DEBUG -- :  (22.0ms) COMMIT D, [2017-03-17T20:28:43.644681 #20652] DEBUG -- : SQL Logging: 4 statements executed, returning 395 Bytes D, [2017-03-17T20:28:43.645033 #20652] DEBUG -- : SQL Logging: 4 statements executed, returning 395 Bytes D, [2017-03-17T20:28:43.645298 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:43.645507 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:43.647455 #20652] DEBUG -- : Executed 1 time in 42.8ms (42.8/42.8/42.8ms min/median/max), returning 1 row (1 Byte): SQL First exec was: INSERT INTO "access_tokens" ("created_at", "person_id", "remote_ip", "token", "updated_at", "user_agent") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" app/models/person.rb:287:in `create_access_token' app/controllers/api/v0/home_controller.rb:10:in `login' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.647850 #20652] DEBUG -- : Executed 1 time in 42.8ms (42.8/42.8/42.8ms min/median/max), returning 1 row (1 Byte): SQL First exec was: INSERT INTO "access_tokens" ("created_at", "person_id", "remote_ip", "token", "updated_at", "user_agent") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" app/models/person.rb:287:in `create_access_token' app/controllers/api/v0/home_controller.rb:10:in `login' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.649773 #20652] DEBUG -- : Executed 1 time in 3.5ms (3.5/3.5/3.5ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/access_token.rb:45:in `generate_token' app/models/access_token.rb:28:in `token' app/models/person.rb:287:in `create_access_token' app/controllers/api/v0/home_controller.rb:10:in `login' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.650109 #20652] DEBUG -- : Executed 1 time in 3.5ms (3.5/3.5/3.5ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/access_token.rb:45:in `generate_token' app/models/access_token.rb:28:in `token' app/models/person.rb:287:in `create_access_token' app/controllers/api/v0/home_controller.rb:10:in `login' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.651957 #20652] DEBUG -- : Executed 1 time in 3.0ms (3.0/3.0/3.0ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."email" = 'test@test.com' LIMIT 1 app/models/person.rb:245:in `authenticate' app/controllers/application_controller.rb:161:in `find_person' app/controllers/application_controller.rb:174:in `info_for_paper_trail' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.652288 #20652] DEBUG -- : Executed 1 time in 3.0ms (3.0/3.0/3.0ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."email" = 'test@test.com' LIMIT 1 app/models/person.rb:245:in `authenticate' app/controllers/application_controller.rb:161:in `find_person' app/controllers/application_controller.rb:174:in `info_for_paper_trail' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.654883 #20652] DEBUG -- : Executed 1 time in 2.7ms (2.7/2.7/2.7ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:43.655303 #20652] DEBUG -- : Executed 1 time in 2.7ms (2.7/2.7/2.7ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:43.655778 #20652] INFO -- : Completed 200 OK in 750ms (Views: 1.3ms | ActiveRecord: 70.6ms) I, [2017-03-17T20:28:43.656021 #20652] INFO -- : Completed 200 OK in 750ms (Views: 1.3ms | ActiveRecord: 70.6ms) W, [2017-03-17T20:28:43.656698 #20652] WARN -- : 127.0.0.1 POST /admin/login 200 OK Api::V0::HomeController#login JSON 763.6 (DB 70.6, View 1.3) {"email"=>"test@test.com", "password"=>"[FILTERED]", "admin_secret"=>"[FILTERED]", "per_page"=>250, "callback"=>"CORS", "vendor_string"=>"bountysource", "home"=>{"email"=>"test@test.com", "password"=>"[FILTERED]", "admin_secret"=>"[FILTERED]", "per_page"=>250, "callback"=>"CORS"}} {} W, [2017-03-17T20:28:43.656951 #20652] WARN -- : 127.0.0.1 POST /admin/login 200 OK Api::V0::HomeController#login JSON 763.6 (DB 70.6, View 1.3) {"email"=>"test@test.com", "password"=>"[FILTERED]", "admin_secret"=>"[FILTERED]", "per_page"=>250, "callback"=>"CORS", "vendor_string"=>"bountysource", "home"=>{"email"=>"test@test.com", "password"=>"[FILTERED]", "admin_secret"=>"[FILTERED]", "per_page"=>250, "callback"=>"CORS"}} {} D, [2017-03-17T20:28:44.277408 #20652] DEBUG -- : D, [2017-03-17T20:28:44.277790 #20652] DEBUG -- : D, [2017-03-17T20:28:44.278108 #20652] DEBUG -- : D, [2017-03-17T20:28:44.278408 #20652] DEBUG -- : I, [2017-03-17T20:28:44.280484 #20652] INFO -- : Started GET "/admin/stats?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:44 +0000 I, [2017-03-17T20:28:44.280804 #20652] INFO -- : Started GET "/admin/stats?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:44 +0000 I, [2017-03-17T20:28:44.397624 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:44.397980 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:44.398513 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} I, [2017-03-17T20:28:44.398860 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} D, [2017-03-17T20:28:44.409411 #20652] DEBUG -- : AccessToken Load (4.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:44.409809 #20652] DEBUG -- : AccessToken Load (4.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:44.429972 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:44.430396 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:44.430761 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.431064 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.446349 #20652] DEBUG -- :  (2.5ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:44.446736 #20652] DEBUG -- :  (2.5ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:44.459811 #20652] DEBUG -- : Person Load (2.6ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:44.460405 #20652] DEBUG -- : Person Load (2.6ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:44.483939 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:44.484418 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:44.484784 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.485104 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.501020 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:44.501415 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:44.513163 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:44.514001 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:44.521327 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:44.521742 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:28:44.540693 #20652] INFO -- : Rendered layouts/_env.html.erb (2.4ms) I, [2017-03-17T20:28:44.541079 #20652] INFO -- : Rendered layouts/_env.html.erb (2.4ms) I, [2017-03-17T20:28:44.559674 #20652] INFO -- : Rendered layouts/admin.html.erb (29.4ms) I, [2017-03-17T20:28:44.560057 #20652] INFO -- : Rendered layouts/admin.html.erb (29.4ms) D, [2017-03-17T20:28:44.575060 #20652] DEBUG -- : Person Exists (2.5ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:44.575440 #20652] DEBUG -- : Person Exists (2.5ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:44.602055 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:44.602421 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:44.602777 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.603099 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.618440 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:28:44.618794 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:28:44.619134 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:44.619433 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:44.621853 #20652] DEBUG -- : Executed 1 time in 5.7ms (5.7/5.7/5.7ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.622213 #20652] DEBUG -- : Executed 1 time in 5.7ms (5.7/5.7/5.7ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.624311 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.624681 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.630155 #20652] DEBUG -- : Executed 1 time in 4.3ms (4.3/4.3/4.3ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.631244 #20652] DEBUG -- : Executed 1 time in 4.3ms (4.3/4.3/4.3ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:44.632425 #20652] INFO -- : Completed 200 OK in 216ms (Views: 36.2ms | ActiveRecord: 12.5ms) I, [2017-03-17T20:28:44.633064 #20652] INFO -- : Completed 200 OK in 216ms (Views: 36.2ms | ActiveRecord: 12.5ms) W, [2017-03-17T20:28:44.633887 #20652] WARN -- : 127.0.0.1 GET /admin/stats?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 233.3 (DB 12.5, View 36.2) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} W, [2017-03-17T20:28:44.634463 #20652] WARN -- : 127.0.0.1 GET /admin/stats?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 233.3 (DB 12.5, View 36.2) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} D, [2017-03-17T20:28:44.648034 #20652] DEBUG -- : D, [2017-03-17T20:28:44.648400 #20652] DEBUG -- : D, [2017-03-17T20:28:44.653818 #20652] DEBUG -- : D, [2017-03-17T20:28:44.654151 #20652] DEBUG -- : I, [2017-03-17T20:28:44.655950 #20652] INFO -- : Started GET "/admin/stats?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:44 +0000 I, [2017-03-17T20:28:44.656319 #20652] INFO -- : Started GET "/admin/stats?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:44 +0000 I, [2017-03-17T20:28:44.760925 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:44.761302 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:44.761763 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} I, [2017-03-17T20:28:44.762101 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} D, [2017-03-17T20:28:44.770913 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:44.771295 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:44.789098 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:44.789468 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:44.789812 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.790112 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.801698 #20652] DEBUG -- :  (3.1ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:44.802072 #20652] DEBUG -- :  (3.1ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:44.811358 #20652] DEBUG -- : Person Load (2.6ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:44.811720 #20652] DEBUG -- : Person Load (2.6ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:44.831198 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:44.831551 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:44.831902 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.832227 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.846419 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:44.846813 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:44.856646 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:44.857021 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:44.862982 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:44.863338 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:28:44.882056 #20652] INFO -- : Rendered layouts/_env.html.erb (2.4ms) I, [2017-03-17T20:28:44.882691 #20652] INFO -- : Rendered layouts/_env.html.erb (2.4ms) I, [2017-03-17T20:28:44.902109 #20652] INFO -- : Rendered layouts/admin.html.erb (29.7ms) I, [2017-03-17T20:28:44.902465 #20652] INFO -- : Rendered layouts/admin.html.erb (29.7ms) D, [2017-03-17T20:28:44.916226 #20652] DEBUG -- : Person Exists (2.5ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:44.916693 #20652] DEBUG -- : Person Exists (2.5ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:44.935244 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:44.935625 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:44.935989 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.936309 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.951702 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:28:44.952092 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:28:44.952480 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:44.952788 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:44.955668 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.956115 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.958566 #20652] DEBUG -- : Executed 1 time in 4.0ms (4.0/4.0/4.0ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.958933 #20652] DEBUG -- : Executed 1 time in 4.0ms (4.0/4.0/4.0ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.961452 #20652] DEBUG -- : Executed 1 time in 4.0ms (4.0/4.0/4.0ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:44.961828 #20652] DEBUG -- : Executed 1 time in 4.0ms (4.0/4.0/4.0ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:44.962418 #20652] INFO -- : Completed 200 OK in 187ms (Views: 37.2ms | ActiveRecord: 11.4ms) I, [2017-03-17T20:28:44.962754 #20652] INFO -- : Completed 200 OK in 187ms (Views: 37.2ms | ActiveRecord: 11.4ms) W, [2017-03-17T20:28:44.963446 #20652] WARN -- : 127.0.0.1 GET /admin/stats?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 200.4 (DB 11.4, View 37.2) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} W, [2017-03-17T20:28:44.963936 #20652] WARN -- : 127.0.0.1 GET /admin/stats?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 200.4 (DB 11.4, View 37.2) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} D, [2017-03-17T20:28:49.371406 #20652] DEBUG -- : D, [2017-03-17T20:28:49.371806 #20652] DEBUG -- : D, [2017-03-17T20:28:49.372256 #20652] DEBUG -- : D, [2017-03-17T20:28:49.372569 #20652] DEBUG -- : I, [2017-03-17T20:28:49.374364 #20652] INFO -- : Started GET "/admin/stats?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:49 +0000 I, [2017-03-17T20:28:49.374691 #20652] INFO -- : Started GET "/admin/stats?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:28:49 +0000 I, [2017-03-17T20:28:49.481523 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:49.481921 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:28:49.482374 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} I, [2017-03-17T20:28:49.482704 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} D, [2017-03-17T20:28:49.491079 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:49.491462 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:49.508638 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:49.508994 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:28:49.509343 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.509664 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.533954 #20652] DEBUG -- :  (11.3ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:49.534322 #20652] DEBUG -- :  (11.3ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:49.544072 #20652] DEBUG -- : Person Load (2.9ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:49.544414 #20652] DEBUG -- : Person Load (2.9ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:49.566518 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:49.566943 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:28:49.567319 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.567641 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.579079 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:49.579446 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:28:49.589108 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:49.590144 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:28:49.596740 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:28:49.597126 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:28:49.629342 #20652] INFO -- : Rendered layouts/_env.html.erb (7.7ms) I, [2017-03-17T20:28:49.629678 #20652] INFO -- : Rendered layouts/_env.html.erb (7.7ms) I, [2017-03-17T20:28:49.647194 #20652] INFO -- : Rendered layouts/admin.html.erb (33.0ms) I, [2017-03-17T20:28:49.647530 #20652] INFO -- : Rendered layouts/admin.html.erb (33.0ms) D, [2017-03-17T20:28:49.660445 #20652] DEBUG -- : Person Exists (3.2ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:49.660790 #20652] DEBUG -- : Person Exists (3.2ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:28:49.697374 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:49.697737 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:28:49.698034 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.698327 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.714192 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:28:49.714617 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:28:49.714996 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:49.715304 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:28:49.717639 #20652] DEBUG -- : Executed 1 time in 4.5ms (4.5/4.5/4.5ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.718009 #20652] DEBUG -- : Executed 1 time in 4.5ms (4.5/4.5/4.5ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.720518 #20652] DEBUG -- : Executed 1 time in 4.5ms (4.5/4.5/4.5ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.720888 #20652] DEBUG -- : Executed 1 time in 4.5ms (4.5/4.5/4.5ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.723123 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:28:49.723630 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:28:49.724209 #20652] INFO -- : Completed 200 OK in 227ms (Views: 48.1ms | ActiveRecord: 20.5ms) I, [2017-03-17T20:28:49.724519 #20652] INFO -- : Completed 200 OK in 227ms (Views: 48.1ms | ActiveRecord: 20.5ms) W, [2017-03-17T20:28:49.725202 #20652] WARN -- : 127.0.0.1 GET /admin/stats?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 241.6 (DB 20.5, View 48.1) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} W, [2017-03-17T20:28:49.725531 #20652] WARN -- : 127.0.0.1 GET /admin/stats?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 241.6 (DB 20.5, View 48.1) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"stats"} {} D, [2017-03-17T20:29:04.468924 #20652] DEBUG -- : D, [2017-03-17T20:29:04.469198 #20652] DEBUG -- : D, [2017-03-17T20:29:04.469358 #20652] DEBUG -- : D, [2017-03-17T20:29:04.469488 #20652] DEBUG -- : I, [2017-03-17T20:29:04.470688 #20652] INFO -- : Started GET "/admin/delayed_jobs/info?access_token=[FILTERED]&callback=CORS&group_stats=true&per_page=250" for 127.0.0.1 at 2017-03-17 20:29:04 +0000 I, [2017-03-17T20:29:04.470882 #20652] INFO -- : Started GET "/admin/delayed_jobs/info?access_token=[FILTERED]&callback=CORS&group_stats=true&per_page=250" for 127.0.0.1 at 2017-03-17 20:29:04 +0000 I, [2017-03-17T20:29:04.590447 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:29:04.590811 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:29:04.591275 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "group_stats"=>"true", "per_page"=>"250", "path"=>"delayed_jobs/info"} I, [2017-03-17T20:29:04.591891 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "group_stats"=>"true", "per_page"=>"250", "path"=>"delayed_jobs/info"} D, [2017-03-17T20:29:04.602361 #20652] DEBUG -- : AccessToken Load (3.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:04.602724 #20652] DEBUG -- : AccessToken Load (3.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:04.620844 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:29:04.621274 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:29:04.621638 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.622056 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.632471 #20652] DEBUG -- :  (2.7ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:04.632848 #20652] DEBUG -- :  (2.7ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:04.641802 #20652] DEBUG -- : Person Load (2.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:04.642189 #20652] DEBUG -- : Person Load (2.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:04.661887 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:29:04.662272 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:29:04.662631 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.662951 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.675145 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:04.675542 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:04.684349 #20652] DEBUG -- : CACHE (0.4ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:04.684805 #20652] DEBUG -- : CACHE (0.4ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:04.691858 #20652] DEBUG -- : CACHE (0.4ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:04.692239 #20652] DEBUG -- : CACHE (0.4ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:29:04.710716 #20652] INFO -- : Rendered layouts/_env.html.erb (2.7ms) I, [2017-03-17T20:29:04.711090 #20652] INFO -- : Rendered layouts/_env.html.erb (2.7ms) I, [2017-03-17T20:29:04.730535 #20652] INFO -- : Rendered layouts/admin.html.erb (30.0ms) I, [2017-03-17T20:29:04.731011 #20652] INFO -- : Rendered layouts/admin.html.erb (30.0ms) D, [2017-03-17T20:29:04.744377 #20652] DEBUG -- : Person Exists (2.7ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:29:04.744759 #20652] DEBUG -- : Person Exists (2.7ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:29:04.764812 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:29:04.765180 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:29:04.765504 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.765771 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.780799 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:29:04.781186 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:29:04.781604 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:29:04.781916 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:29:04.784292 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.784697 #20652] DEBUG -- : Executed 1 time in 4.4ms (4.4/4.4/4.4ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.787306 #20652] DEBUG -- : Executed 1 time in 4.1ms (4.1/4.1/4.1ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.787721 #20652] DEBUG -- : Executed 1 time in 4.1ms (4.1/4.1/4.1ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.789908 #20652] DEBUG -- : Executed 1 time in 3.8ms (3.8/3.8/3.8ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.790273 #20652] DEBUG -- : Executed 1 time in 3.8ms (3.8/3.8/3.8ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:29:04.790870 #20652] INFO -- : Completed 200 OK in 186ms (Views: 36.6ms | ActiveRecord: 11.6ms) I, [2017-03-17T20:29:04.791217 #20652] INFO -- : Completed 200 OK in 186ms (Views: 36.6ms | ActiveRecord: 11.6ms) W, [2017-03-17T20:29:04.791954 #20652] WARN -- : 127.0.0.1 GET /admin/delayed_jobs/info?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&group_stats=true&per_page=250 200 OK AdminController#home JSON 199.0 (DB 11.6, View 36.6) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "group_stats"=>"true", "per_page"=>"250", "path"=>"delayed_jobs/info"} {} W, [2017-03-17T20:29:04.792332 #20652] WARN -- : 127.0.0.1 GET /admin/delayed_jobs/info?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&group_stats=true&per_page=250 200 OK AdminController#home JSON 199.0 (DB 11.6, View 36.6) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "group_stats"=>"true", "per_page"=>"250", "path"=>"delayed_jobs/info"} {} D, [2017-03-17T20:29:04.801256 #20652] DEBUG -- : D, [2017-03-17T20:29:04.801651 #20652] DEBUG -- : D, [2017-03-17T20:29:04.801981 #20652] DEBUG -- : D, [2017-03-17T20:29:04.802678 #20652] DEBUG -- : I, [2017-03-17T20:29:04.812025 #20652] INFO -- : Started GET "/admin/delayed_jobs?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:29:04 +0000 I, [2017-03-17T20:29:04.812384 #20652] INFO -- : Started GET "/admin/delayed_jobs?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:29:04 +0000 I, [2017-03-17T20:29:04.908552 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:29:04.908898 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:29:04.909361 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs"} I, [2017-03-17T20:29:04.909708 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs"} D, [2017-03-17T20:29:04.918013 #20652] DEBUG -- : AccessToken Load (2.3ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:04.918419 #20652] DEBUG -- : AccessToken Load (2.3ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:04.936096 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:29:04.936480 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:29:04.936831 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.937160 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.946802 #20652] DEBUG -- :  (2.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:04.947144 #20652] DEBUG -- :  (2.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:04.955712 #20652] DEBUG -- : Person Load (2.1ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:04.956089 #20652] DEBUG -- : Person Load (2.1ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:04.972995 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:29:04.973351 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:29:04.973923 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.974263 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:04.988534 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:04.988926 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:04.997287 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:04.997669 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:05.004427 #20652] DEBUG -- : CACHE (0.5ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:05.004788 #20652] DEBUG -- : CACHE (0.5ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:29:05.023205 #20652] INFO -- : Rendered layouts/_env.html.erb (2.7ms) I, [2017-03-17T20:29:05.023659 #20652] INFO -- : Rendered layouts/_env.html.erb (2.7ms) I, [2017-03-17T20:29:05.043915 #20652] INFO -- : Rendered layouts/admin.html.erb (30.8ms) I, [2017-03-17T20:29:05.044300 #20652] INFO -- : Rendered layouts/admin.html.erb (30.8ms) D, [2017-03-17T20:29:05.057386 #20652] DEBUG -- : Person Exists (2.0ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:29:05.057725 #20652] DEBUG -- : Person Exists (2.0ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:29:05.077843 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:29:05.078168 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:29:05.078422 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:05.078704 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:05.096765 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:29:05.097150 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:29:05.097527 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:29:05.097828 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:29:05.100098 #20652] DEBUG -- : Executed 1 time in 3.8ms (3.8/3.8/3.8ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:05.100506 #20652] DEBUG -- : Executed 1 time in 3.8ms (3.8/3.8/3.8ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:05.102959 #20652] DEBUG -- : Executed 1 time in 3.8ms (3.8/3.8/3.8ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:05.103347 #20652] DEBUG -- : Executed 1 time in 3.8ms (3.8/3.8/3.8ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:05.106077 #20652] DEBUG -- : Executed 1 time in 3.3ms (3.3/3.3/3.3ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:05.106452 #20652] DEBUG -- : Executed 1 time in 3.3ms (3.3/3.3/3.3ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:29:05.107091 #20652] INFO -- : Completed 200 OK in 184ms (Views: 37.7ms | ActiveRecord: 9.5ms) I, [2017-03-17T20:29:05.107437 #20652] INFO -- : Completed 200 OK in 184ms (Views: 37.7ms | ActiveRecord: 9.5ms) W, [2017-03-17T20:29:05.109047 #20652] WARN -- : 127.0.0.1 GET /admin/delayed_jobs?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 197.2 (DB 9.5, View 37.7) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs"} {} W, [2017-03-17T20:29:05.109399 #20652] WARN -- : 127.0.0.1 GET /admin/delayed_jobs?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 197.2 (DB 9.5, View 37.7) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs"} {} D, [2017-03-17T20:29:23.607802 #20652] DEBUG -- : D, [2017-03-17T20:29:23.608169 #20652] DEBUG -- : D, [2017-03-17T20:29:23.608462 #20652] DEBUG -- : D, [2017-03-17T20:29:23.608742 #20652] DEBUG -- : I, [2017-03-17T20:29:23.610608 #20652] INFO -- : Started GET "/admin/people?access_token=[FILTERED]&callback=CORS&page=1&per_page=50" for 127.0.0.1 at 2017-03-17 20:29:23 +0000 I, [2017-03-17T20:29:23.610906 #20652] INFO -- : Started GET "/admin/people?access_token=[FILTERED]&callback=CORS&page=1&per_page=50" for 127.0.0.1 at 2017-03-17 20:29:23 +0000 I, [2017-03-17T20:29:23.728091 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:29:23.728417 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:29:23.728774 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"50", "path"=>"people"} I, [2017-03-17T20:29:23.729094 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"50", "path"=>"people"} D, [2017-03-17T20:29:23.736038 #20652] DEBUG -- : AccessToken Load (2.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:23.736413 #20652] DEBUG -- : AccessToken Load (2.0ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:23.753412 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:29:23.753909 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:29:23.754225 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.754487 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.771098 #20652] DEBUG -- :  (8.9ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:23.771568 #20652] DEBUG -- :  (8.9ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:23.779574 #20652] DEBUG -- : Person Load (1.9ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:23.779924 #20652] DEBUG -- : Person Load (1.9ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:23.798425 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:29:23.798797 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:29:23.799154 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.799492 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.811648 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:23.812053 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:29:23.822868 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:23.823253 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:29:23.829918 #20652] DEBUG -- : CACHE (0.3ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:29:23.830389 #20652] DEBUG -- : CACHE (0.3ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:29:23.852711 #20652] INFO -- : Rendered layouts/_env.html.erb (5.5ms) I, [2017-03-17T20:29:23.853149 #20652] INFO -- : Rendered layouts/_env.html.erb (5.5ms) I, [2017-03-17T20:29:23.872720 #20652] INFO -- : Rendered layouts/admin.html.erb (33.3ms) I, [2017-03-17T20:29:23.873112 #20652] INFO -- : Rendered layouts/admin.html.erb (33.3ms) D, [2017-03-17T20:29:23.886700 #20652] DEBUG -- : Person Exists (2.1ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:29:23.887100 #20652] DEBUG -- : Person Exists (2.1ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:29:23.906281 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:29:23.906647 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:29:23.906965 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.907398 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.928061 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:29:23.928421 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:29:23.928772 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:29:23.929046 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:29:23.931812 #20652] DEBUG -- : Executed 1 time in 3.6ms (3.6/3.6/3.6ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.932200 #20652] DEBUG -- : Executed 1 time in 3.6ms (3.6/3.6/3.6ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.934390 #20652] DEBUG -- : Executed 1 time in 3.5ms (3.5/3.5/3.5ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.934751 #20652] DEBUG -- : Executed 1 time in 3.5ms (3.5/3.5/3.5ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.936821 #20652] DEBUG -- : Executed 1 time in 3.4ms (3.4/3.4/3.4ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:29:23.937198 #20652] DEBUG -- : Executed 1 time in 3.4ms (3.4/3.4/3.4ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:29:23.937771 #20652] INFO -- : Completed 200 OK in 190ms (Views: 40.9ms | ActiveRecord: 15.5ms) I, [2017-03-17T20:29:23.938109 #20652] INFO -- : Completed 200 OK in 190ms (Views: 40.9ms | ActiveRecord: 15.5ms) W, [2017-03-17T20:29:23.938911 #20652] WARN -- : 127.0.0.1 GET /admin/people?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&page=1&per_page=50 200 OK AdminController#home JSON 209.0 (DB 15.5, View 40.9) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"50", "path"=>"people"} {} W, [2017-03-17T20:29:23.939272 #20652] WARN -- : 127.0.0.1 GET /admin/people?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&page=1&per_page=50 200 OK AdminController#home JSON 209.0 (DB 15.5, View 40.9) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"50", "path"=>"people"} {} D, [2017-03-17T20:30:03.309285 #20652] DEBUG -- : D, [2017-03-17T20:30:03.309682 #20652] DEBUG -- : D, [2017-03-17T20:30:03.310013 #20652] DEBUG -- : D, [2017-03-17T20:30:03.310316 #20652] DEBUG -- : I, [2017-03-17T20:30:03.311169 #20652] INFO -- : Started GET "/admin/people" for 127.0.0.1 at 2017-03-17 20:30:03 +0000 I, [2017-03-17T20:30:03.311453 #20652] INFO -- : Started GET "/admin/people" for 127.0.0.1 at 2017-03-17 20:30:03 +0000 I, [2017-03-17T20:30:03.412122 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:30:03.412542 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:30:03.412871 #20652] INFO -- : Parameters: {"path"=>"people"} I, [2017-03-17T20:30:03.413166 #20652] INFO -- : Parameters: {"path"=>"people"} D, [2017-03-17T20:30:03.420896 #20652] DEBUG -- : AccessToken Load (2.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.421341 #20652] DEBUG -- : AccessToken Load (2.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.439035 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:30:03.439358 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:30:03.439664 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:03.440014 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:03.444152 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.444508 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.448583 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.449074 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.453246 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.453832 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.457592 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:03.457937 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 I, [2017-03-17T20:30:03.473331 #20652] INFO -- : Rendered layouts/_env.html.erb (2.5ms) I, [2017-03-17T20:30:03.473915 #20652] INFO -- : Rendered layouts/_env.html.erb (2.5ms) I, [2017-03-17T20:30:03.492284 #20652] INFO -- : Rendered layouts/admin.html.erb (27.4ms) I, [2017-03-17T20:30:03.492659 #20652] INFO -- : Rendered layouts/admin.html.erb (27.4ms) D, [2017-03-17T20:30:03.495169 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:30:03.495562 #20652] DEBUG -- : SQL Logging: 1 statement executed, returning 0 Bytes D, [2017-03-17T20:30:03.496069 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:30:03.496383 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:30:03.499097 #20652] DEBUG -- : Executed 1 time in 3.8ms (3.8/3.8/3.8ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:03.499477 #20652] DEBUG -- : Executed 1 time in 3.8ms (3.8/3.8/3.8ms min/median/max), returning 0 rows (0 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" IS NULL ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:30:03.500070 #20652] INFO -- : Completed 200 OK in 80ms (Views: 33.6ms | ActiveRecord: 3.1ms) I, [2017-03-17T20:30:03.500398 #20652] INFO -- : Completed 200 OK in 80ms (Views: 33.6ms | ActiveRecord: 3.1ms) W, [2017-03-17T20:30:03.501025 #20652] WARN -- : 127.0.0.1 GET /admin/people 200 OK AdminController#home HTML 86.8 (DB 3.1, View 33.6) {"path"=>"people"} {} W, [2017-03-17T20:30:03.501363 #20652] WARN -- : 127.0.0.1 GET /admin/people 200 OK AdminController#home HTML 86.8 (DB 3.1, View 33.6) {"path"=>"people"} {} D, [2017-03-17T20:30:04.002022 #20652] DEBUG -- : D, [2017-03-17T20:30:04.002410 #20652] DEBUG -- : D, [2017-03-17T20:30:04.002723 #20652] DEBUG -- : D, [2017-03-17T20:30:04.002969 #20652] DEBUG -- : I, [2017-03-17T20:30:04.003750 #20652] INFO -- : Started GET "/assets/admin.css" for 127.0.0.1 at 2017-03-17 20:30:04 +0000 I, [2017-03-17T20:30:04.004054 #20652] INFO -- : Started GET "/assets/admin.css" for 127.0.0.1 at 2017-03-17 20:30:04 +0000 D, [2017-03-17T20:30:04.114569 #20652] DEBUG -- : D, [2017-03-17T20:30:04.114957 #20652] DEBUG -- : D, [2017-03-17T20:30:04.115264 #20652] DEBUG -- : D, [2017-03-17T20:30:04.115557 #20652] DEBUG -- : I, [2017-03-17T20:30:04.116212 #20652] INFO -- : Started GET "/assets/admin.js" for 127.0.0.1 at 2017-03-17 20:30:04 +0000 I, [2017-03-17T20:30:04.116511 #20652] INFO -- : Started GET "/assets/admin.js" for 127.0.0.1 at 2017-03-17 20:30:04 +0000 D, [2017-03-17T20:30:07.487767 #20652] DEBUG -- : D, [2017-03-17T20:30:07.488149 #20652] DEBUG -- : D, [2017-03-17T20:30:07.488529 #20652] DEBUG -- : D, [2017-03-17T20:30:07.488852 #20652] DEBUG -- : I, [2017-03-17T20:30:07.489604 #20652] INFO -- : Started GET "/assets/Bountysource-green.png" for 127.0.0.1 at 2017-03-17 20:30:07 +0000 I, [2017-03-17T20:30:07.489984 #20652] INFO -- : Started GET "/assets/Bountysource-green.png" for 127.0.0.1 at 2017-03-17 20:30:07 +0000 D, [2017-03-17T20:30:07.772936 #20652] DEBUG -- : D, [2017-03-17T20:30:07.773339 #20652] DEBUG -- : D, [2017-03-17T20:30:07.773791 #20652] DEBUG -- : D, [2017-03-17T20:30:07.774120 #20652] DEBUG -- : I, [2017-03-17T20:30:07.775915 #20652] INFO -- : Started GET "/admin/delayed_jobs/info?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:30:07 +0000 I, [2017-03-17T20:30:07.776253 #20652] INFO -- : Started GET "/admin/delayed_jobs/info?access_token=[FILTERED]&callback=CORS&per_page=250" for 127.0.0.1 at 2017-03-17 20:30:07 +0000 I, [2017-03-17T20:30:07.879004 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:30:07.879384 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:30:07.879817 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs/info"} I, [2017-03-17T20:30:07.880247 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs/info"} D, [2017-03-17T20:30:07.887330 #20652] DEBUG -- : AccessToken Load (2.4ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:07.887702 #20652] DEBUG -- : AccessToken Load (2.4ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:07.903924 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:30:07.904285 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:30:07.904599 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:07.904889 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:07.916157 #20652] DEBUG -- :  (2.8ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:30:07.916545 #20652] DEBUG -- :  (2.8ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:30:07.925232 #20652] DEBUG -- : Person Load (2.1ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:30:07.925594 #20652] DEBUG -- : Person Load (2.1ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:30:07.943958 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:30:07.944283 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:30:07.944557 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:07.944836 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:07.958024 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:07.958421 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:07.965688 #20652] DEBUG -- : CACHE (0.1ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:30:07.965958 #20652] DEBUG -- : CACHE (0.1ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:30:07.972035 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:30:07.972309 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:30:07.990758 #20652] INFO -- : Rendered layouts/_env.html.erb (2.3ms) I, [2017-03-17T20:30:07.991139 #20652] INFO -- : Rendered layouts/_env.html.erb (2.3ms) I, [2017-03-17T20:30:08.011240 #20652] INFO -- : Rendered layouts/admin.html.erb (30.2ms) I, [2017-03-17T20:30:08.011754 #20652] INFO -- : Rendered layouts/admin.html.erb (30.2ms) D, [2017-03-17T20:30:08.026212 #20652] DEBUG -- : Person Exists (2.5ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:30:08.026586 #20652] DEBUG -- : Person Exists (2.5ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:30:08.045467 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:30:08.045817 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:30:08.046081 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:08.046308 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:08.060103 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:30:08.060484 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:30:08.060857 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:30:08.061220 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:30:08.064152 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:08.064533 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:08.067135 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:08.067498 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:08.069626 #20652] DEBUG -- : Executed 1 time in 3.7ms (3.7/3.7/3.7ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:08.069988 #20652] DEBUG -- : Executed 1 time in 3.7ms (3.7/3.7/3.7ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:30:08.070540 #20652] INFO -- : Completed 200 OK in 177ms (Views: 38.1ms | ActiveRecord: 10.5ms) I, [2017-03-17T20:30:08.070858 #20652] INFO -- : Completed 200 OK in 177ms (Views: 38.1ms | ActiveRecord: 10.5ms) W, [2017-03-17T20:30:08.071533 #20652] WARN -- : 127.0.0.1 GET /admin/delayed_jobs/info?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 190.3 (DB 10.5, View 38.1) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs/info"} {} W, [2017-03-17T20:30:08.071915 #20652] WARN -- : 127.0.0.1 GET /admin/delayed_jobs/info?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&per_page=250 200 OK AdminController#home JSON 190.3 (DB 10.5, View 38.1) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "per_page"=>"250", "path"=>"delayed_jobs/info"} {} D, [2017-03-17T20:30:08.888655 #20652] DEBUG -- : D, [2017-03-17T20:30:08.889813 #20652] DEBUG -- : D, [2017-03-17T20:30:08.891200 #20652] DEBUG -- : D, [2017-03-17T20:30:08.891550 #20652] DEBUG -- : I, [2017-03-17T20:30:08.894187 #20652] INFO -- : Started GET "/admin/people?access_token=[FILTERED]&callback=CORS&page=1&per_page=50" for 127.0.0.1 at 2017-03-17 20:30:08 +0000 I, [2017-03-17T20:30:08.894537 #20652] INFO -- : Started GET "/admin/people?access_token=[FILTERED]&callback=CORS&page=1&per_page=50" for 127.0.0.1 at 2017-03-17 20:30:08 +0000 I, [2017-03-17T20:30:08.999482 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:30:08.999844 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:30:09.000258 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"50", "path"=>"people"} I, [2017-03-17T20:30:09.000550 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"50", "path"=>"people"} D, [2017-03-17T20:30:09.009299 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:09.009647 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:09.026437 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:30:09.026831 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:30:09.027180 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.027452 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.038825 #20652] DEBUG -- :  (2.3ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:30:09.039122 #20652] DEBUG -- :  (2.3ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:30:09.047535 #20652] DEBUG -- : Person Load (2.1ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:30:09.047888 #20652] DEBUG -- : Person Load (2.1ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:30:09.070206 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:30:09.070621 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:30:09.070998 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.071350 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.085163 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:09.085536 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:30:09.096191 #20652] DEBUG -- : CACHE (0.3ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:30:09.096586 #20652] DEBUG -- : CACHE (0.3ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:30:09.103022 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:30:09.103409 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:30:09.126223 #20652] INFO -- : Rendered layouts/_env.html.erb (2.2ms) I, [2017-03-17T20:30:09.126593 #20652] INFO -- : Rendered layouts/_env.html.erb (2.2ms) I, [2017-03-17T20:30:09.149941 #20652] INFO -- : Rendered layouts/admin.html.erb (37.8ms) I, [2017-03-17T20:30:09.150346 #20652] INFO -- : Rendered layouts/admin.html.erb (37.8ms) D, [2017-03-17T20:30:09.166370 #20652] DEBUG -- : Person Exists (4.6ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:30:09.166828 #20652] DEBUG -- : Person Exists (4.6ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:30:09.191277 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:30:09.191646 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:30:09.191976 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.192259 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.207568 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:30:09.207982 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:30:09.208397 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:30:09.208709 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:30:09.211258 #20652] DEBUG -- : Executed 1 time in 6.1ms (6.1/6.1/6.1ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.211683 #20652] DEBUG -- : Executed 1 time in 6.1ms (6.1/6.1/6.1ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.215498 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.215866 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.217903 #20652] DEBUG -- : Executed 1 time in 3.7ms (3.7/3.7/3.7ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:30:09.218303 #20652] DEBUG -- : Executed 1 time in 3.7ms (3.7/3.7/3.7ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:30:09.218884 #20652] INFO -- : Completed 200 OK in 204ms (Views: 44.6ms | ActiveRecord: 12.2ms) I, [2017-03-17T20:30:09.219219 #20652] INFO -- : Completed 200 OK in 204ms (Views: 44.6ms | ActiveRecord: 12.2ms) W, [2017-03-17T20:30:09.219885 #20652] WARN -- : 127.0.0.1 GET /admin/people?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&page=1&per_page=50 200 OK AdminController#home JSON 218.3 (DB 12.2, View 44.6) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"50", "path"=>"people"} {} W, [2017-03-17T20:30:09.220256 #20652] WARN -- : 127.0.0.1 GET /admin/people?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&page=1&per_page=50 200 OK AdminController#home JSON 218.3 (DB 12.2, View 44.6) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "page"=>"1", "per_page"=>"50", "path"=>"people"} {} D, [2017-03-17T20:33:14.742032 #20652] DEBUG -- : D, [2017-03-17T20:33:14.742440 #20652] DEBUG -- : D, [2017-03-17T20:33:14.742854 #20652] DEBUG -- : D, [2017-03-17T20:33:14.743135 #20652] DEBUG -- : I, [2017-03-17T20:33:14.746991 #20652] INFO -- : Started GET "/admin/cash_outs?access_token=[FILTERED]&callback=CORS&include_address=true&include_mailing_address=true&include_person=true&order=-created&per_page=250&sent=false" for 127.0.0.1 at 2017-03-17 20:33:14 +0000 I, [2017-03-17T20:33:14.747398 #20652] INFO -- : Started GET "/admin/cash_outs?access_token=[FILTERED]&callback=CORS&include_address=true&include_mailing_address=true&include_person=true&order=-created&per_page=250&sent=false" for 127.0.0.1 at 2017-03-17 20:33:14 +0000 I, [2017-03-17T20:33:14.895002 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:33:14.895272 #20652] INFO -- : Processing by AdminController#home as I, [2017-03-17T20:33:14.895542 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "include_address"=>"true", "include_mailing_address"=>"true", "include_person"=>"true", "order"=>"-created", "per_page"=>"250", "sent"=>"false", "path"=>"cash_outs"} I, [2017-03-17T20:33:14.895807 #20652] INFO -- : Parameters: {"access_token"=>"[FILTERED]", "callback"=>"CORS", "include_address"=>"true", "include_mailing_address"=>"true", "include_person"=>"true", "order"=>"-created", "per_page"=>"250", "sent"=>"false", "path"=>"cash_outs"} D, [2017-03-17T20:33:14.902171 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:33:14.902472 #20652] DEBUG -- : AccessToken Load (2.5ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:33:14.920527 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:33:14.920894 #20652] DEBUG -- : 1 row, 184 Bytes D, [2017-03-17T20:33:14.921268 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:14.921598 #20652] DEBUG -- : app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:14.934090 #20652] DEBUG -- :  (2.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:33:14.934475 #20652] DEBUG -- :  (2.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:33:14.944236 #20652] DEBUG -- : Person Load (2.3ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:33:14.944607 #20652] DEBUG -- : Person Load (2.3ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:33:14.963239 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:33:14.963680 #20652] DEBUG -- : 1 row, 197 Bytes D, [2017-03-17T20:33:14.964058 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:14.964393 #20652] DEBUG -- : app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:14.977103 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:33:14.977479 #20652] DEBUG -- : CACHE (0.2ms) SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 D, [2017-03-17T20:33:14.986092 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:33:14.986496 #20652] DEBUG -- : CACHE (0.2ms) SELECT COUNT(*) FROM "people" WHERE ("people"."deleted" != 't') AND "people"."suspended_at" IS NULL AND "people"."id" = 1 D, [2017-03-17T20:33:14.994196 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] D, [2017-03-17T20:33:14.994581 #20652] DEBUG -- : CACHE (0.2ms) SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 [["id", 1]] I, [2017-03-17T20:33:15.013333 #20652] INFO -- : Rendered layouts/_env.html.erb (2.5ms) I, [2017-03-17T20:33:15.013827 #20652] INFO -- : Rendered layouts/_env.html.erb (2.5ms) I, [2017-03-17T20:33:15.035161 #20652] INFO -- : Rendered layouts/admin.html.erb (32.3ms) I, [2017-03-17T20:33:15.035542 #20652] INFO -- : Rendered layouts/admin.html.erb (32.3ms) D, [2017-03-17T20:33:15.050473 #20652] DEBUG -- : Person Exists (2.7ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:33:15.050922 #20652] DEBUG -- : Person Exists (2.7ms) SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 D, [2017-03-17T20:33:15.074955 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:33:15.075339 #20652] DEBUG -- : 0 rows, 0 Bytes D, [2017-03-17T20:33:15.075691 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:15.076064 #20652] DEBUG -- : app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:15.100198 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:33:15.100772 #20652] DEBUG -- : SQL Logging: 3 statements executed, returning 381 Bytes D, [2017-03-17T20:33:15.101150 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:33:15.101481 #20652] DEBUG -- : Top 10 SQL executions: D, [2017-03-17T20:33:15.103371 #20652] DEBUG -- : Executed 1 time in 4.3ms (4.3/4.3/4.3ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:15.104212 #20652] DEBUG -- : Executed 1 time in 4.3ms (4.3/4.3/4.3ms min/median/max), returning 0 rows (0 Bytes): Person Exists First exec was: SELECT 1 AS one FROM "people" WHERE ("people"."email" = 'test@test.com' AND "people"."id" != 1) LIMIT 1 app/models/person.rb:371:in `was_seen!' app/controllers/application_controller.rb:166:in `update_person_last_seen_at' app/controllers/application_controller.rb:102:in `response_to_jsonp' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:15.106318 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:15.106705 #20652] DEBUG -- : Executed 1 time in 3.9ms (3.9/3.9/3.9ms min/median/max), returning 1 row (197 Bytes): Person Load First exec was: SELECT "people".* FROM "people" WHERE "people"."id" = $1 LIMIT 1 app/models/person.rb:298:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:15.109266 #20652] DEBUG -- : Executed 1 time in 3.4ms (3.4/3.4/3.4ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' D, [2017-03-17T20:33:15.109650 #20652] DEBUG -- : Executed 1 time in 3.4ms (3.4/3.4/3.4ms min/median/max), returning 1 row (184 Bytes): AccessToken Load First exec was: SELECT "access_tokens".* FROM "access_tokens" WHERE "access_tokens"."token" = '1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38' ORDER BY "access_tokens"."id" ASC LIMIT 1 app/models/person.rb:296:in `find_by_access_token' app/controllers/application_controller.rb:66:in `current_user' app/controllers/concerns/request_tracking.rb:12:in `add_tracking' config/initializers/log_level.rb:30:in `block (2 levels) in ' config/initializers/log_level.rb:29:in `block in ' lib/middleware/force_accept_header.rb:11:in `call' config/initializers/get_method_override.rb:21:in `call' I, [2017-03-17T20:33:15.110380 #20652] INFO -- : Completed 200 OK in 201ms (Views: 39.1ms | ActiveRecord: 10.3ms) I, [2017-03-17T20:33:15.110708 #20652] INFO -- : Completed 200 OK in 201ms (Views: 39.1ms | ActiveRecord: 10.3ms) W, [2017-03-17T20:33:15.111709 #20652] WARN -- : 127.0.0.1 GET /admin/cash_outs?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&include_address=true&include_mailing_address=true&include_person=true&order=-created&per_page=250&sent=false 200 OK AdminController#home JSON 214.7 (DB 10.3, View 39.1) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "include_address"=>"true", "include_mailing_address"=>"true", "include_person"=>"true", "order"=>"-created", "per_page"=>"250", "sent"=>"false", "path"=>"cash_outs"} {} W, [2017-03-17T20:33:15.112062 #20652] WARN -- : 127.0.0.1 GET /admin/cash_outs?access_token=1.1489782523.fc53ab7ace0bc3c0cbea88a8e7fbad98cf079e38.dev&callback=CORS&include_address=true&include_mailing_address=true&include_person=true&order=-created&per_page=250&sent=false 200 OK AdminController#home JSON 214.7 (DB 10.3, View 39.1) {"access_token"=>"[FILTERED]", "callback"=>"CORS", "include_address"=>"true", "include_mailing_address"=>"true", "include_person"=>"true", "order"=>"-created", "per_page"=>"250", "sent"=>"false", "path"=>"cash_outs"} {} Stopping ... Exiting