(0.1ms) DROP TABLE IF EXISTS "canvas_sync_job_logs"  (0.1ms) SELECT sqlite_version(*)  (1.7ms) CREATE TABLE "canvas_sync_job_logs" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "started_at" datetime, "completed_at" datetime, "exception" varchar, "backtrace" text, "job_class" varchar, "status" varchar, "metadata" text, "job_arguments" text, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL)  (0.1ms) DROP TABLE IF EXISTS "courses"  (1.1ms) CREATE TABLE "courses" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "canvas_course_id" bigint NOT NULL, "sis_id" varchar, "short_name" varchar, "long_name" varchar, "status" varchar, "canvas_account_id" integer, "canvas_term_id" integer, "term_sis_id" integer, "start_date" datetime, "end_date" datetime, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL)  (0.9ms) CREATE UNIQUE INDEX "index_courses_on_canvas_course_id" ON "courses" ("canvas_course_id")  (0.1ms) DROP TABLE IF EXISTS "enrollments"  (1.0ms) CREATE TABLE "enrollments" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "canvas_enrollment_id" bigint NOT NULL, "canvas_course_id" bigint, "course_sis_id" varchar, "canvas_user_id" bigint, "user_sis_id" varchar, "role" varchar, "role_id" integer, "canvas_section_id" bigint, "section_sis_id" varchar, "status" varchar, "base_role_type" varchar, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL)  (1.0ms) CREATE INDEX "index_enrollments_on_canvas_course_id" ON "enrollments" ("canvas_course_id")  (0.1ms)  SELECT sql FROM sqlite_master WHERE name='index_enrollments_on_canvas_course_id' AND type='index' UNION ALL SELECT sql FROM sqlite_temp_master WHERE name='index_enrollments_on_canvas_course_id' AND type='index'   (1.0ms) CREATE UNIQUE INDEX "index_enrollments_on_canvas_enrollment_id" ON "enrollments" ("canvas_enrollment_id")  (0.2ms)  SELECT sql FROM sqlite_master WHERE name='index_enrollments_on_canvas_enrollment_id' AND type='index' UNION ALL SELECT sql FROM sqlite_temp_master WHERE name='index_enrollments_on_canvas_enrollment_id' AND type='index'   (0.1ms)  SELECT sql FROM sqlite_master WHERE name='index_enrollments_on_canvas_course_id' AND type='index' UNION ALL SELECT sql FROM sqlite_temp_master WHERE name='index_enrollments_on_canvas_course_id' AND type='index'   (1.0ms) CREATE INDEX "index_enrollments_on_canvas_user_id" ON "enrollments" ("canvas_user_id")  (0.1ms) DROP TABLE IF EXISTS "sections"  (1.0ms) CREATE TABLE "sections" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "canvas_section_id" bigint NOT NULL, "sis_id" varchar, "canvas_course_id" bigint, "name" varchar, "status" varchar, "start_date" datetime, "end_date" datetime, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL)  (0.9ms) CREATE INDEX "index_sections_on_canvas_course_id" ON "sections" ("canvas_course_id")  (0.1ms)  SELECT sql FROM sqlite_master WHERE name='index_sections_on_canvas_course_id' AND type='index' UNION ALL SELECT sql FROM sqlite_temp_master WHERE name='index_sections_on_canvas_course_id' AND type='index'   (0.9ms) CREATE UNIQUE INDEX "index_sections_on_canvas_section_id" ON "sections" ("canvas_section_id")  (0.1ms) DROP TABLE IF EXISTS "terms"  (0.9ms) CREATE TABLE "terms" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "canvas_term_id" integer NOT NULL, "name" varchar, "start_at" datetime, "end_at" datetime, "workflow_state" varchar, "grading_period_group_id" integer, "sis_id" varchar, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL)  (0.9ms) CREATE UNIQUE INDEX "index_terms_on_canvas_term_id" ON "terms" ("canvas_term_id")  (0.1ms) DROP TABLE IF EXISTS "users"  (1.2ms) CREATE TABLE "users" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "canvas_user_id" bigint NOT NULL, "sis_id" varchar, "email" varchar, "first_name" varchar, "last_name" varchar, "status" varchar, "login_id" varchar, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL)  (1.1ms) CREATE UNIQUE INDEX "index_users_on_canvas_user_id" ON "users" ("canvas_user_id")  (1.1ms) CREATE TABLE "schema_migrations" ("version" varchar NOT NULL PRIMARY KEY)  (0.1ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC  (0.9ms) INSERT INTO "schema_migrations" (version) VALUES (20170918221413)  (1.2ms) INSERT INTO "schema_migrations" (version) VALUES (20170905192509), (20170906193506), (20170906203438), (20170914181345), (20170915210836);   (1.5ms) CREATE TABLE "ar_internal_metadata" ("key" varchar NOT NULL PRIMARY KEY, "value" varchar, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL) ActiveRecord::InternalMetadata Load (0.1ms) SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? LIMIT ? [["key", "environment"], ["LIMIT", 1]]  (0.0ms) begin transaction SQL (0.3ms) INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES (?, ?, ?, ?) [["key", "environment"], ["value", "test"], ["created_at", "2017-11-02 21:24:41.277398"], ["updated_at", "2017-11-02 21:24:41.277398"]]  (1.1ms) commit transaction ActiveRecord::InternalMetadata Load (0.1ms) SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? LIMIT ? [["key", "environment"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.0ms) commit transaction  (0.1ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC  (0.1ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SELECT COUNT(*) FROM "canvas_sync_job_logs" [ActiveJob] [GoodJob] [87676425-eadf-401a-8529-32bcb8bfb822] Performing GoodJob (Job ID: 87676425-eadf-401a-8529-32bcb8bfb822) from Async(default) with arguments: "argument" [ActiveJob] [GoodJob] [87676425-eadf-401a-8529-32bcb8bfb822]  (0.2ms) SAVEPOINT active_record_1 [ActiveJob] [GoodJob] [87676425-eadf-401a-8529-32bcb8bfb822] SQL (0.6ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.579194"], ["job_class", "GoodJob"], ["job_arguments", "---\n- argument\n"], ["created_at", "2017-11-02 21:24:41.588937"], ["updated_at", "2017-11-02 21:24:41.588937"]] [ActiveJob] [GoodJob] [87676425-eadf-401a-8529-32bcb8bfb822]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [GoodJob] [87676425-eadf-401a-8529-32bcb8bfb822]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [GoodJob] [87676425-eadf-401a-8529-32bcb8bfb822] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.592547"], ["updated_at", "2017-11-02 21:24:41.592826"], ["id", 1]] [ActiveJob] [GoodJob] [87676425-eadf-401a-8529-32bcb8bfb822]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [GoodJob] [87676425-eadf-401a-8529-32bcb8bfb822] Performed GoodJob (Job ID: 87676425-eadf-401a-8529-32bcb8bfb822) from Async(default) in 14.89ms  (0.1ms) SELECT COUNT(*) FROM "canvas_sync_job_logs" CanvasSync::JobLog Load (0.1ms) SELECT "canvas_sync_job_logs".* FROM "canvas_sync_job_logs" ORDER BY "canvas_sync_job_logs"."id" DESC LIMIT ? [["LIMIT", 1]]  (0.5ms) rollback transaction  (0.0ms) begin transaction [ActiveJob] [BadJob] [98ce3654-261b-4efd-b9e2-107449c652c5] Performing BadJob (Job ID: 98ce3654-261b-4efd-b9e2-107449c652c5) from Async(default) with arguments: "argument" [ActiveJob] [BadJob] [98ce3654-261b-4efd-b9e2-107449c652c5]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [BadJob] [98ce3654-261b-4efd-b9e2-107449c652c5] SQL (0.3ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.598843"], ["job_class", "BadJob"], ["job_arguments", "---\n- argument\n"], ["created_at", "2017-11-02 21:24:41.599381"], ["updated_at", "2017-11-02 21:24:41.599381"]] [ActiveJob] [BadJob] [98ce3654-261b-4efd-b9e2-107449c652c5]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [BadJob] [98ce3654-261b-4efd-b9e2-107449c652c5]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [BadJob] [98ce3654-261b-4efd-b9e2-107449c652c5] SQL (0.2ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "exception" = ?, "backtrace" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.601037"], ["exception", "EvilError: EvilError"], ["backtrace", "[\"/Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/job_spec.rb:12:in `perform'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:37:in `block in perform_now'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:108:in `block in run_callbacks'\", \"/Users/ncollings/workspace/canvas_sync/lib/canvas_sync/job.rb:14:in `block in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/i18n-0.8.6/lib/i18n.rb:257:in `with_locale'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/translation.rb:7:in `block (2 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:24:in `block (4 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `block in instrument'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications/instrumenter.rb:21:in `instrument'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `instrument'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:23:in `block (3 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:44:in `block in tag_logger'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69:in `block in tagged'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:26:in `tagged'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69:in `tagged'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:44:in `tag_logger'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:20:in `block (2 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:135:in `run_callbacks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:33:in `perform_now'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:16:in `perform_now'\", \"/Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/job_spec.rb:32:in `block (4 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/matchers/built_in/raise_error.rb:52:in `matches?'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:27:in `with_matcher'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:48:in `handle_matcher'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/expectation_target.rb:65:in `to'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/expectation_target.rb:101:in `to'\", \"/Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/job_spec.rb:31:in `block (3 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:254:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:254:in `block in run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:500:in `block in with_around_and_singleton_context_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:457:in `block in with_around_example_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:464:in `block in run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:604:in `block in run_around_example_hooks_for'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:342:in `call'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-rails-3.6.1/lib/rspec/rails/adapters.rb:127:in `block (2 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:447:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:447:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:375:in `execute_with'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:606:in `block (2 levels) in run_around_example_hooks_for'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:342:in `call'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:607:in `run_around_example_hooks_for'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:464:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:457:in `with_around_example_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:500:in `with_around_and_singleton_context_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:251:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:627:in `block in run_examples'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:623:in `map'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:623:in `run_examples'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:589:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `block in run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `map'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `block (3 levels) in run_specs'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `map'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `block (2 levels) in run_specs'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/configuration.rb:1894:in `with_suite_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:113:in `block in run_specs'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/reporter.rb:79:in `report'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:112:in `run_specs'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:87:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:71:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:45:in `invoke'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/exe/rspec:4:in `'\", \"/Users/ncollings/.rbenv/versions/2.4.1/bin/rspec:23:in `load'\", \"/Users/ncollings/.rbenv/versions/2.4.1/bin/rspec:23:in `'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:in `load'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:in `kernel_load'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:27:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:362:in `exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:22:in `dispatch'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:13:in `start'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/exe/bundle:30:in `block in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/friendly_errors.rb:121:in `with_friendly_errors'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/exe/bundle:22:in `'\", \"/Users/ncollings/.rbenv/versions/2.4.1/bin/bundle:22:in `load'\", \"/Users/ncollings/.rbenv/versions/2.4.1/bin/bundle:22:in `
'\"]"], ["updated_at", "2017-11-02 21:24:41.601269"], ["id", 1]] [ActiveJob] [BadJob] [98ce3654-261b-4efd-b9e2-107449c652c5]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [BadJob] [98ce3654-261b-4efd-b9e2-107449c652c5] Error performing BadJob (Job ID: 98ce3654-261b-4efd-b9e2-107449c652c5) from Async(default) in 4.1ms: EvilError (EvilError): /Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/job_spec.rb:12:in `perform' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:37:in `block in perform_now' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:108:in `block in run_callbacks' /Users/ncollings/workspace/canvas_sync/lib/canvas_sync/job.rb:14:in `block in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/i18n-0.8.6/lib/i18n.rb:257:in `with_locale' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/translation.rb:7:in `block (2 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:24:in `block (4 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `block in instrument' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications/instrumenter.rb:21:in `instrument' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `instrument' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:23:in `block (3 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:44:in `block in tag_logger' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69:in `block in tagged' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:26:in `tagged' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69:in `tagged' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:44:in `tag_logger' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:20:in `block (2 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:135:in `run_callbacks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:33:in `perform_now' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:16:in `perform_now' /Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/job_spec.rb:32:in `block (4 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/matchers/built_in/raise_error.rb:52:in `matches?' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:27:in `with_matcher' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:48:in `handle_matcher' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/expectation_target.rb:65:in `to' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/expectation_target.rb:101:in `to' /Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/job_spec.rb:31:in `block (3 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:254:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:254:in `block in run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:500:in `block in with_around_and_singleton_context_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:457:in `block in with_around_example_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:464:in `block in run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:604:in `block in run_around_example_hooks_for' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:342:in `call' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-rails-3.6.1/lib/rspec/rails/adapters.rb:127:in `block (2 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:447:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:447:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:375:in `execute_with' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:606:in `block (2 levels) in run_around_example_hooks_for' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:342:in `call' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:607:in `run_around_example_hooks_for' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:464:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:457:in `with_around_example_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:500:in `with_around_and_singleton_context_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:251:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:627:in `block in run_examples' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:623:in `map' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:623:in `run_examples' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:589:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `block in run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `map' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `block (3 levels) in run_specs' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `map' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `block (2 levels) in run_specs' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/configuration.rb:1894:in `with_suite_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:113:in `block in run_specs' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/reporter.rb:79:in `report' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:112:in `run_specs' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:87:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:71:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:45:in `invoke' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/exe/rspec:4:in `' /Users/ncollings/.rbenv/versions/2.4.1/bin/rspec:23:in `load' /Users/ncollings/.rbenv/versions/2.4.1/bin/rspec:23:in `' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:in `load' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:in `kernel_load' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:27:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:362:in `exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:22:in `dispatch' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:13:in `start' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/exe/bundle:30:in `block in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/friendly_errors.rb:121:in `with_friendly_errors' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/exe/bundle:22:in `' /Users/ncollings/.rbenv/versions/2.4.1/bin/bundle:22:in `load' /Users/ncollings/.rbenv/versions/2.4.1/bin/bundle:22:in `
' CanvasSync::JobLog Load (0.1ms) SELECT "canvas_sync_job_logs".* FROM "canvas_sync_job_logs" ORDER BY "canvas_sync_job_logs"."id" DESC LIMIT ? [["LIMIT", 1]]  (0.4ms) rollback transaction  (0.0ms) begin transaction [ActiveJob] [CanvasSync::Jobs::ReportChecker] [09b86f5d-cfd9-4795-b22e-976fc9465fcf] Performing CanvasSync::Jobs::ReportChecker (Job ID: 09b86f5d-cfd9-4795-b22e-976fc9465fcf) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, "provisioning_csv", 1, "FakeProcessor", {} [ActiveJob] [CanvasSync::Jobs::ReportChecker] [09b86f5d-cfd9-4795-b22e-976fc9465fcf]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [09b86f5d-cfd9-4795-b22e-976fc9465fcf] SQL (0.3ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.605928"], ["job_class", "CanvasSync::Jobs::ReportChecker"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- provisioning_csv\n- 1\n- FakeProcessor\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n"], ["created_at", "2017-11-02 21:24:41.606279"], ["updated_at", "2017-11-02 21:24:41.606279"]] [ActiveJob] [CanvasSync::Jobs::ReportChecker] [09b86f5d-cfd9-4795-b22e-976fc9465fcf]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [09b86f5d-cfd9-4795-b22e-976fc9465fcf]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [09b86f5d-cfd9-4795-b22e-976fc9465fcf] SQL (0.3ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.633229"], ["updated_at", "2017-11-02 21:24:41.634097"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::ReportChecker] [09b86f5d-cfd9-4795-b22e-976fc9465fcf]  (0.2ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [09b86f5d-cfd9-4795-b22e-976fc9465fcf] Performed CanvasSync::Jobs::ReportChecker (Job ID: 09b86f5d-cfd9-4795-b22e-976fc9465fcf) from Async(default) in 31.44ms  (0.6ms) rollback transaction  (0.1ms) begin transaction [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c] Performing CanvasSync::Jobs::ReportChecker (Job ID: 1ace51a3-c5ed-4b71-89a9-68882f7c999c) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, "provisioning_csv", 1, "FakeProcessor", {} [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c] SQL (0.4ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.640543"], ["job_class", "CanvasSync::Jobs::ReportChecker"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- provisioning_csv\n- 1\n- FakeProcessor\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n"], ["created_at", "2017-11-02 21:24:41.641132"], ["updated_at", "2017-11-02 21:24:41.641132"]] [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c] Enqueued CanvasSync::Jobs::ReportChecker (Job ID: 4735b472-f322-455b-a3e6-fb1461cc1139) to Async(default) at 2017-11-02 21:25:11 UTC with arguments: {:jobs=>[], :global_options=>{}}, "provisioning_csv", 1, "FakeProcessor", {} [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.650029"], ["updated_at", "2017-11-02 21:24:41.650501"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [1ace51a3-c5ed-4b71-89a9-68882f7c999c] Performed CanvasSync::Jobs::ReportChecker (Job ID: 1ace51a3-c5ed-4b71-89a9-68882f7c999c) from Async(default) in 11.75ms  (1.3ms) rollback transaction  (0.1ms) begin transaction [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0] Performing CanvasSync::Jobs::ReportChecker (Job ID: 94a8981f-0a7b-44ea-8ab4-5af64543f6e0) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, "provisioning_csv", 1, "FakeProcessor", {} [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0] SQL (0.3ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.655818"], ["job_class", "CanvasSync::Jobs::ReportChecker"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- provisioning_csv\n- 1\n- FakeProcessor\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n"], ["created_at", "2017-11-02 21:24:41.656212"], ["updated_at", "2017-11-02 21:24:41.656212"]] [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0] Report failed to process; status was {"status"=>"error"} for report_name: provisioning_csv, report_id: 1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "exception" = ?, "backtrace" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.670678"], ["exception", "RuntimeError: Report failed to process; status was {\"status\"=>\"error\"} for report_name: provisioning_csv, report_id: 1"], ["backtrace", "[\"/Users/ncollings/workspace/canvas_sync/lib/canvas_sync/jobs/report_checker.rb:28:in `perform'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:37:in `block in perform_now'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:108:in `block in run_callbacks'\", \"/Users/ncollings/workspace/canvas_sync/lib/canvas_sync/job.rb:14:in `block in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/i18n-0.8.6/lib/i18n.rb:257:in `with_locale'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/translation.rb:7:in `block (2 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:24:in `block (4 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `block in instrument'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications/instrumenter.rb:21:in `instrument'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `instrument'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:23:in `block (3 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:44:in `block in tag_logger'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69:in `block in tagged'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:26:in `tagged'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69:in `tagged'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:44:in `tag_logger'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:20:in `block (2 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:135:in `run_callbacks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:33:in `perform_now'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:16:in `perform_now'\", \"/Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/report_checker_spec.rb:12:in `start_job'\", \"/Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/report_checker_spec.rb:55:in `block (5 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/matchers/built_in/raise_error.rb:52:in `matches?'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:27:in `with_matcher'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:48:in `handle_matcher'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/expectation_target.rb:65:in `to'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/expectation_target.rb:101:in `to'\", \"/Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/report_checker_spec.rb:55:in `block (4 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:254:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:254:in `block in run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:500:in `block in with_around_and_singleton_context_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:457:in `block in with_around_example_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:464:in `block in run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:604:in `block in run_around_example_hooks_for'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:342:in `call'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-rails-3.6.1/lib/rspec/rails/adapters.rb:127:in `block (2 levels) in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:447:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:447:in `instance_exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:375:in `execute_with'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:606:in `block (2 levels) in run_around_example_hooks_for'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:342:in `call'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:607:in `run_around_example_hooks_for'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:464:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:457:in `with_around_example_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:500:in `with_around_and_singleton_context_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:251:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:627:in `block in run_examples'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:623:in `map'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:623:in `run_examples'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:589:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `block in run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `map'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `block in run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `map'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `block (3 levels) in run_specs'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `map'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `block (2 levels) in run_specs'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/configuration.rb:1894:in `with_suite_hooks'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:113:in `block in run_specs'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/reporter.rb:79:in `report'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:112:in `run_specs'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:87:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:71:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:45:in `invoke'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/exe/rspec:4:in `'\", \"/Users/ncollings/.rbenv/versions/2.4.1/bin/rspec:23:in `load'\", \"/Users/ncollings/.rbenv/versions/2.4.1/bin/rspec:23:in `'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:in `load'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:in `kernel_load'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:27:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:362:in `exec'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:22:in `dispatch'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:13:in `start'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/exe/bundle:30:in `block in '\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/friendly_errors.rb:121:in `with_friendly_errors'\", \"/Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/exe/bundle:22:in `'\", \"/Users/ncollings/.rbenv/versions/2.4.1/bin/bundle:22:in `load'\", \"/Users/ncollings/.rbenv/versions/2.4.1/bin/bundle:22:in `
'\"]"], ["updated_at", "2017-11-02 21:24:41.670913"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportChecker] [94a8981f-0a7b-44ea-8ab4-5af64543f6e0] Error performing CanvasSync::Jobs::ReportChecker (Job ID: 94a8981f-0a7b-44ea-8ab4-5af64543f6e0) from Async(default) in 16.62ms: RuntimeError (Report failed to process; status was {"status"=>"error"} for report_name: provisioning_csv, report_id: 1): /Users/ncollings/workspace/canvas_sync/lib/canvas_sync/jobs/report_checker.rb:28:in `perform' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:37:in `block in perform_now' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:108:in `block in run_callbacks' /Users/ncollings/workspace/canvas_sync/lib/canvas_sync/job.rb:14:in `block in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/i18n-0.8.6/lib/i18n.rb:257:in `with_locale' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/translation.rb:7:in `block (2 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:24:in `block (4 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `block in instrument' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications/instrumenter.rb:21:in `instrument' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166:in `instrument' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:23:in `block (3 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:44:in `block in tag_logger' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69:in `block in tagged' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:26:in `tagged' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69:in `tagged' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:44:in `tag_logger' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/logging.rb:20:in `block (2 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:135:in `run_callbacks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:33:in `perform_now' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activejob-5.1.3/lib/active_job/execution.rb:16:in `perform_now' /Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/report_checker_spec.rb:12:in `start_job' /Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/report_checker_spec.rb:55:in `block (5 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/matchers/built_in/raise_error.rb:52:in `matches?' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:27:in `with_matcher' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/handler.rb:48:in `handle_matcher' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/expectation_target.rb:65:in `to' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-expectations-3.6.0/lib/rspec/expectations/expectation_target.rb:101:in `to' /Users/ncollings/workspace/canvas_sync/spec/canvas_sync/jobs/report_checker_spec.rb:55:in `block (4 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:254:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:254:in `block in run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:500:in `block in with_around_and_singleton_context_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:457:in `block in with_around_example_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:464:in `block in run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:604:in `block in run_around_example_hooks_for' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:342:in `call' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-rails-3.6.1/lib/rspec/rails/adapters.rb:127:in `block (2 levels) in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:447:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:447:in `instance_exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:375:in `execute_with' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:606:in `block (2 levels) in run_around_example_hooks_for' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:342:in `call' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:607:in `run_around_example_hooks_for' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/hooks.rb:464:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:457:in `with_around_example_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:500:in `with_around_and_singleton_context_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example.rb:251:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:627:in `block in run_examples' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:623:in `map' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:623:in `run_examples' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:589:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `block in run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `map' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `block in run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `map' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/example_group.rb:590:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `block (3 levels) in run_specs' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `map' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:118:in `block (2 levels) in run_specs' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/configuration.rb:1894:in `with_suite_hooks' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:113:in `block in run_specs' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/reporter.rb:79:in `report' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:112:in `run_specs' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:87:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:71:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/lib/rspec/core/runner.rb:45:in `invoke' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rspec-core-3.6.0/exe/rspec:4:in `' /Users/ncollings/.rbenv/versions/2.4.1/bin/rspec:23:in `load' /Users/ncollings/.rbenv/versions/2.4.1/bin/rspec:23:in `' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:in `load' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:in `kernel_load' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:27:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:362:in `exec' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:22:in `dispatch' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/cli.rb:13:in `start' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/exe/bundle:30:in `block in ' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/lib/bundler/friendly_errors.rb:121:in `with_friendly_errors' /Users/ncollings/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.4/exe/bundle:22:in `' /Users/ncollings/.rbenv/versions/2.4.1/bin/bundle:22:in `load' /Users/ncollings/.rbenv/versions/2.4.1/bin/bundle:22:in `
'  (1.1ms) rollback transaction  (0.0ms) begin transaction [ActiveJob] [CanvasSync::Jobs::ReportProcessorJob] [bac85159-596d-498c-a42a-af23f31e7052] Performing CanvasSync::Jobs::ReportProcessorJob (Job ID: bac85159-596d-498c-a42a-af23f31e7052) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, "provisioning_csv", "https://test.instructure.com/sample_report_download", "FakeProcessor", {} [ActiveJob] [CanvasSync::Jobs::ReportProcessorJob] [bac85159-596d-498c-a42a-af23f31e7052]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportProcessorJob] [bac85159-596d-498c-a42a-af23f31e7052] SQL (0.3ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.675414"], ["job_class", "CanvasSync::Jobs::ReportProcessorJob"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- provisioning_csv\n- https://test.instructure.com/sample_report_download\n- FakeProcessor\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n"], ["created_at", "2017-11-02 21:24:41.675754"], ["updated_at", "2017-11-02 21:24:41.675754"]] [ActiveJob] [CanvasSync::Jobs::ReportProcessorJob] [bac85159-596d-498c-a42a-af23f31e7052]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportProcessorJob] [bac85159-596d-498c-a42a-af23f31e7052]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportProcessorJob] [bac85159-596d-498c-a42a-af23f31e7052] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.714323"], ["updated_at", "2017-11-02 21:24:41.714773"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::ReportProcessorJob] [bac85159-596d-498c-a42a-af23f31e7052]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportProcessorJob] [bac85159-596d-498c-a42a-af23f31e7052] Performed CanvasSync::Jobs::ReportProcessorJob (Job ID: bac85159-596d-498c-a42a-af23f31e7052) from Async(default) in 40.68ms  (1.0ms) rollback transaction  (0.0ms) begin transaction [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba] Performing CanvasSync::Jobs::ReportStarter (Job ID: 6173075d-e6af-419d-b534-2a0605ecf9ba) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, "provisioning_csv", {"parameters[users]"=>true}, "CoolProcessor", {:models=>["users"]} [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba] SQL (0.4ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.718739"], ["job_class", "CanvasSync::Jobs::ReportStarter"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- provisioning_csv\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n parameters[users]: true\n- CoolProcessor\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n models:\n - users\n"], ["created_at", "2017-11-02 21:24:41.726125"], ["updated_at", "2017-11-02 21:24:41.726125"]] [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba] Enqueued CanvasSync::Jobs::ReportChecker (Job ID: 53eb5e68-c4f3-44d6-b630-36b472e54db4) to Async(default) at 2017-11-02 21:25:11 UTC with arguments: {:jobs=>[], :global_options=>{}}, "provisioning_csv", 1, "CoolProcessor", {:models=>["users"]} [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.729882"], ["updated_at", "2017-11-02 21:24:41.730220"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::ReportStarter] [6173075d-e6af-419d-b534-2a0605ecf9ba] Performed CanvasSync::Jobs::ReportStarter (Job ID: 6173075d-e6af-419d-b534-2a0605ecf9ba) from Async(default) in 12.93ms  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Term Exists (0.2ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 3977706], ["LIMIT", 1]] SQL (0.5ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 3977706], ["name", "Cool Term"], ["start_at", "2017-10-30 21:24:38.724817"], ["end_at", "2017-11-05 21:24:38.726016"], ["workflow_state", "active"], ["sis_id", "c8a7ff18e305eb00819b03f6c8181863"], ["created_at", "2017-11-02 21:24:41.747514"], ["updated_at", "2017-11-02 21:24:41.747514"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 Term Exists (0.2ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 28010032], ["LIMIT", 1]] SQL (0.2ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 28010032], ["name", "Cool Term"], ["start_at", "2017-10-30 21:24:38.724817"], ["end_at", "2017-11-05 21:24:38.726016"], ["workflow_state", "active"], ["sis_id", "836c8edeed556adeaf0b7afe503ac374"], ["created_at", "2017-11-02 21:24:41.750943"], ["updated_at", "2017-11-02 21:24:41.750943"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SAVEPOINT active_record_1 Term Exists (0.2ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 61451015], ["LIMIT", 1]] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 61451015], ["name", "Cool Term"], ["start_at", "2017-10-30 21:24:38.724817"], ["end_at", "2017-11-05 21:24:38.726016"], ["workflow_state", "inactive"], ["sis_id", "a2928c62e3e95522d5409716403faf2e"], ["created_at", "2017-11-02 21:24:41.754841"], ["updated_at", "2017-11-02 21:24:41.754841"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702] Performing CanvasSync::Jobs::SyncProvisioningReportJob (Job ID: dfa314b0-c7f1-441f-afa4-2af94cec1702) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, {:models=>["users", "courses"], :term_scope=>"active"} [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702] SQL (0.1ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.756665"], ["job_class", "CanvasSync::Jobs::SyncProvisioningReportJob"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n models:\n - users\n - courses\n term_scope: active\n"], ["created_at", "2017-11-02 21:24:41.757091"], ["updated_at", "2017-11-02 21:24:41.757091"]] [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702] Term Load (0.1ms) SELECT "terms".* FROM "terms" WHERE "terms"."workflow_state" = ? AND (start_at <= '2017-11-17 21:24:41.759302' OR start_at IS NULL) AND (end_at >= '2017-10-18 21:24:41.759571' OR end_at IS NULL) ORDER BY "terms"."id" ASC LIMIT ? [["workflow_state", "active"], ["LIMIT", 1000]] [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.760639"], ["updated_at", "2017-11-02 21:24:41.760907"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [dfa314b0-c7f1-441f-afa4-2af94cec1702] Performed CanvasSync::Jobs::SyncProvisioningReportJob (Job ID: dfa314b0-c7f1-441f-afa4-2af94cec1702) from Async(default) in 5.61ms  (0.7ms) rollback transaction  (0.0ms) begin transaction [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb] Performing CanvasSync::Jobs::SyncProvisioningReportJob (Job ID: e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, {:models=>["users", "courses"]} [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb] SQL (0.4ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.764655"], ["job_class", "CanvasSync::Jobs::SyncProvisioningReportJob"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n models:\n - users\n - courses\n"], ["created_at", "2017-11-02 21:24:41.765076"], ["updated_at", "2017-11-02 21:24:41.765076"]] [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.767394"], ["updated_at", "2017-11-02 21:24:41.767639"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncProvisioningReportJob] [e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb] Performed CanvasSync::Jobs::SyncProvisioningReportJob (Job ID: e0b3c7e7-ab3a-41ba-b5e8-44cf718548eb) from Async(default) in 4.08ms  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SELECT COUNT(*) FROM "terms" [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Performing CanvasSync::Jobs::SyncTermsJob (Job ID: cc1db221-d50b-48ca-98cb-4a3f90e0a2fe) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, {} [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] SQL (0.2ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.771614"], ["job_class", "CanvasSync::Jobs::SyncTermsJob"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n"], ["created_at", "2017-11-02 21:24:41.771913"], ["updated_at", "2017-11-02 21:24:41.771913"]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Load (0.1ms) SELECT "terms".* FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 1], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 1], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "workflow_state", "grading_period_group_id", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 1], ["name", "Default Term"], ["workflow_state", "active"], ["grading_period_group_id", 1], ["sis_id", "Test"], ["created_at", "2017-11-02 21:24:41.777741"], ["updated_at", "2017-11-02 21:24:41.777741"]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Load (0.1ms) SELECT "terms".* FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 6], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 6], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "workflow_state", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_term_id", 6], ["name", "Average Term 1"], ["workflow_state", "active"], ["created_at", "2017-11-02 21:24:41.786956"], ["updated_at", "2017-11-02 21:24:41.786956"]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Load (0.0ms) SELECT "terms".* FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 7], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 7], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "workflow_state", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_term_id", 7], ["name", "Average Term 2"], ["workflow_state", "active"], ["created_at", "2017-11-02 21:24:41.788631"], ["updated_at", "2017-11-02 21:24:41.788631"]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Load (0.0ms) SELECT "terms".* FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 5], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 5], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 5], ["name", "Syllabus Term"], ["start_at", "2017-08-14 06:00:00"], ["end_at", "2017-08-31 06:00:00"], ["workflow_state", "active"], ["sis_id", "SYTERM"], ["created_at", "2017-11-02 21:24:41.792549"], ["updated_at", "2017-11-02 21:24:41.792549"]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Load (0.0ms) SELECT "terms".* FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 4], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 4], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "grading_period_group_id", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 4], ["name", "Ellucian Term"], ["start_at", "2017-08-01 06:00:00"], ["end_at", "2017-10-31 06:00:00"], ["workflow_state", "active"], ["grading_period_group_id", 1], ["sis_id", "SH"], ["created_at", "2017-11-02 21:24:41.794502"], ["updated_at", "2017-11-02 21:24:41.794502"]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Load (0.1ms) SELECT "terms".* FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 3], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 3], ["LIMIT", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 3], ["name", "Current Term"], ["start_at", "2017-03-19 06:00:00"], ["end_at", "2017-08-01 06:00:00"], ["workflow_state", "active"], ["created_at", "2017-11-02 21:24:41.796626"], ["updated_at", "2017-11-02 21:24:41.796626"]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.0ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.797631"], ["updated_at", "2017-11-02 21:24:41.797981"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncTermsJob] [cc1db221-d50b-48ca-98cb-4a3f90e0a2fe] Performed CanvasSync::Jobs::SyncTermsJob (Job ID: cc1db221-d50b-48ca-98cb-4a3f90e0a2fe) from Async(default) in 28.2ms  (0.1ms) SELECT COUNT(*) FROM "terms"  (0.7ms) rollback transaction  (0.1ms) begin transaction [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0] Performing CanvasSync::Jobs::SyncUsersJob (Job ID: 350e6964-e9e5-4d2a-96cd-b900ffde23f0) from Async(default) with arguments: {:jobs=>[], :global_options=>{}}, {} [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0] SQL (0.5ms) INSERT INTO "canvas_sync_job_logs" ("started_at", "job_class", "job_arguments", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["started_at", "2017-11-02 21:24:41.803762"], ["job_class", "CanvasSync::Jobs::SyncUsersJob"], ["job_arguments", "---\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess\n jobs: []\n global_options: !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n- !ruby/hash:ActiveSupport::HashWithIndifferentAccess {}\n"], ["created_at", "2017-11-02 21:24:41.804369"], ["updated_at", "2017-11-02 21:24:41.804369"]] [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0] Enqueued CanvasSync::Jobs::ReportChecker (Job ID: 8ba5113c-389c-423e-989e-927db2ad3876) to Async(default) at 2017-11-02 21:25:11 UTC with arguments: {:jobs=>[], :global_options=>{}}, "proservices_provisioning_csv", 1, "CanvasSync::Processors::ProvisioningReportProcessor", {:models=>["users"]} [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0]  (0.1ms) SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0] SQL (0.1ms) UPDATE "canvas_sync_job_logs" SET "completed_at" = ?, "updated_at" = ? WHERE "canvas_sync_job_logs"."id" = ? [["completed_at", "2017-11-02 21:24:41.807980"], ["updated_at", "2017-11-02 21:24:41.808353"], ["id", 1]] [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0]  (0.1ms) RELEASE SAVEPOINT active_record_1 [ActiveJob] [CanvasSync::Jobs::SyncUsersJob] [350e6964-e9e5-4d2a-96cd-b900ffde23f0] Performed CanvasSync::Jobs::SyncUsersJob (Job ID: 350e6964-e9e5-4d2a-96cd-b900ffde23f0) from Async(default) in 6.6ms  (1.0ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Course Exists (0.1ms) SELECT 1 AS one FROM "courses" WHERE "courses"."canvas_course_id" = ? LIMIT ? [["canvas_course_id", 64443679], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "courses" ("canvas_course_id", "sis_id", "short_name", "long_name", "start_date", "end_date", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_course_id", 64443679], ["sis_id", "6c977802e78b5f2dbb14351cfdbd7c58"], ["short_name", "Cool Course"], ["long_name", "Really Really Cool Course"], ["start_date", "2017-10-30 21:24:41.825693"], ["end_date", "2017-11-23 21:24:41.825812"], ["created_at", "2017-11-02 21:24:41.827295"], ["updated_at", "2017-11-02 21:24:41.827295"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Course Exists (0.1ms) SELECT 1 AS one FROM "courses" WHERE "courses"."canvas_course_id" IS NULL AND ("courses"."id" != ?) LIMIT ? [["id", 1], ["LIMIT", 1]]  (0.5ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Course Exists (0.1ms) SELECT 1 AS one FROM "courses" WHERE "courses"."canvas_course_id" = ? LIMIT ? [["canvas_course_id", 22569266], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "courses" ("canvas_course_id", "sis_id", "short_name", "long_name", "start_date", "end_date", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_course_id", 22569266], ["sis_id", "e9c22740932a31a35c7eaec089b8b54b"], ["short_name", "Cool Course"], ["long_name", "Really Really Cool Course"], ["start_date", "2017-10-30 21:24:41.852901"], ["end_date", "2017-11-23 21:24:41.853020"], ["created_at", "2017-11-02 21:24:41.854059"], ["updated_at", "2017-11-02 21:24:41.854059"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Course Load (0.1ms) SELECT "courses".* FROM "courses" ORDER BY "courses"."id" ASC LIMIT ? [["LIMIT", 1]] Course Exists (0.1ms) SELECT 1 AS one FROM "courses" WHERE "courses"."canvas_course_id" = ? LIMIT ? [["canvas_course_id", 22569266], ["LIMIT", 1]]  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Course Exists (0.1ms) SELECT 1 AS one FROM "courses" WHERE "courses"."canvas_course_id" = ? LIMIT ? [["canvas_course_id", 46894132], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "courses" ("canvas_course_id", "sis_id", "short_name", "long_name", "start_date", "end_date", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_course_id", 46894132], ["sis_id", "182683b1bb1e16cfeef7e933c5a1564f"], ["short_name", "Cool Course"], ["long_name", "Really Really Cool Course"], ["start_date", "2017-10-30 21:24:41.859566"], ["end_date", "2017-11-23 21:24:41.859667"], ["created_at", "2017-11-02 21:24:41.860608"], ["updated_at", "2017-11-02 21:24:41.860608"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.4ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Course Exists (0.2ms) SELECT 1 AS one FROM "courses" WHERE "courses"."canvas_course_id" = ? LIMIT ? [["canvas_course_id", 98532154], ["LIMIT", 1]] SQL (0.5ms) INSERT INTO "courses" ("canvas_course_id", "sis_id", "short_name", "long_name", "start_date", "end_date", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_course_id", 98532154], ["sis_id", "981553970015857e54f773e67b38b97d"], ["short_name", "Cool Course"], ["long_name", "Really Really Cool Course"], ["start_date", "2017-10-30 21:24:41.864853"], ["end_date", "2017-11-23 21:24:41.865077"], ["created_at", "2017-11-02 21:24:41.866654"], ["updated_at", "2017-11-02 21:24:41.866654"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.8ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Course Exists (0.2ms) SELECT 1 AS one FROM "courses" WHERE "courses"."canvas_course_id" = ? LIMIT ? [["canvas_course_id", 66121916], ["LIMIT", 1]] SQL (0.9ms) INSERT INTO "courses" ("canvas_course_id", "sis_id", "short_name", "long_name", "start_date", "end_date", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_course_id", 66121916], ["sis_id", "0ea7151b89a546b99ebe492156d56ce5"], ["short_name", "Cool Course"], ["long_name", "Really Really Cool Course"], ["start_date", "2017-10-30 21:24:41.872002"], ["end_date", "2017-11-23 21:24:41.872222"], ["created_at", "2017-11-02 21:24:41.873640"], ["updated_at", "2017-11-02 21:24:41.873640"]]  (0.2ms) RELEASE SAVEPOINT active_record_1  (0.8ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Enrollment Exists (0.1ms) SELECT 1 AS one FROM "enrollments" WHERE "enrollments"."canvas_enrollment_id" = ? LIMIT ? [["canvas_enrollment_id", 85348988], ["LIMIT", 1]] SQL (0.4ms) INSERT INTO "enrollments" ("canvas_enrollment_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_enrollment_id", 85348988], ["created_at", "2017-11-02 21:24:41.896064"], ["updated_at", "2017-11-02 21:24:41.896064"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Enrollment Exists (0.1ms) SELECT 1 AS one FROM "enrollments" WHERE "enrollments"."canvas_enrollment_id" IS NULL AND ("enrollments"."id" != ?) LIMIT ? [["id", 1], ["LIMIT", 1]]  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.2ms) SAVEPOINT active_record_1 Enrollment Exists (0.2ms) SELECT 1 AS one FROM "enrollments" WHERE "enrollments"."canvas_enrollment_id" = ? LIMIT ? [["canvas_enrollment_id", 76889930], ["LIMIT", 1]] SQL (0.4ms) INSERT INTO "enrollments" ("canvas_enrollment_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_enrollment_id", 76889930], ["created_at", "2017-11-02 21:24:41.909041"], ["updated_at", "2017-11-02 21:24:41.909041"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Enrollment Load (0.1ms) SELECT "enrollments".* FROM "enrollments" ORDER BY "enrollments"."id" ASC LIMIT ? [["LIMIT", 1]] Enrollment Exists (0.1ms) SELECT 1 AS one FROM "enrollments" WHERE "enrollments"."canvas_enrollment_id" = ? LIMIT ? [["canvas_enrollment_id", 76889930], ["LIMIT", 1]]  (0.7ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Enrollment Exists (0.2ms) SELECT 1 AS one FROM "enrollments" WHERE "enrollments"."canvas_enrollment_id" = ? LIMIT ? [["canvas_enrollment_id", 23772210], ["LIMIT", 1]] SQL (0.4ms) INSERT INTO "enrollments" ("canvas_enrollment_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_enrollment_id", 23772210], ["created_at", "2017-11-02 21:24:41.917006"], ["updated_at", "2017-11-02 21:24:41.917006"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.4ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Enrollment Exists (0.1ms) SELECT 1 AS one FROM "enrollments" WHERE "enrollments"."canvas_enrollment_id" = ? LIMIT ? [["canvas_enrollment_id", 66034611], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "enrollments" ("canvas_enrollment_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_enrollment_id", 66034611], ["created_at", "2017-11-02 21:24:41.921960"], ["updated_at", "2017-11-02 21:24:41.921960"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.8ms) rollback transaction  (0.2ms) begin transaction  (0.2ms) SAVEPOINT active_record_1 Enrollment Exists (0.3ms) SELECT 1 AS one FROM "enrollments" WHERE "enrollments"."canvas_enrollment_id" = ? LIMIT ? [["canvas_enrollment_id", 48342766], ["LIMIT", 1]] SQL (0.5ms) INSERT INTO "enrollments" ("canvas_enrollment_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_enrollment_id", 48342766], ["created_at", "2017-11-02 21:24:41.928915"], ["updated_at", "2017-11-02 21:24:41.928915"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.6ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Section Exists (0.1ms) SELECT 1 AS one FROM "sections" WHERE "sections"."canvas_section_id" = ? LIMIT ? [["canvas_section_id", 49752496], ["LIMIT", 1]] SQL (0.4ms) INSERT INTO "sections" ("canvas_section_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_section_id", 49752496], ["created_at", "2017-11-02 21:24:41.944768"], ["updated_at", "2017-11-02 21:24:41.944768"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Section Exists (0.1ms) SELECT 1 AS one FROM "sections" WHERE "sections"."canvas_section_id" IS NULL AND ("sections"."id" != ?) LIMIT ? [["id", 1], ["LIMIT", 1]]  (0.9ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Section Exists (0.3ms) SELECT 1 AS one FROM "sections" WHERE "sections"."canvas_section_id" = ? LIMIT ? [["canvas_section_id", 10919952], ["LIMIT", 1]] SQL (0.4ms) INSERT INTO "sections" ("canvas_section_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_section_id", 10919952], ["created_at", "2017-11-02 21:24:41.958480"], ["updated_at", "2017-11-02 21:24:41.958480"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Section Load (0.1ms) SELECT "sections".* FROM "sections" ORDER BY "sections"."id" ASC LIMIT ? [["LIMIT", 1]] Section Exists (0.1ms) SELECT 1 AS one FROM "sections" WHERE "sections"."canvas_section_id" = ? LIMIT ? [["canvas_section_id", 10919952], ["LIMIT", 1]]  (0.7ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Section Exists (0.3ms) SELECT 1 AS one FROM "sections" WHERE "sections"."canvas_section_id" = ? LIMIT ? [["canvas_section_id", 23865100], ["LIMIT", 1]] SQL (0.4ms) INSERT INTO "sections" ("canvas_section_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_section_id", 23865100], ["created_at", "2017-11-02 21:24:41.967548"], ["updated_at", "2017-11-02 21:24:41.967548"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.5ms) rollback transaction  (0.1ms) begin transaction  (0.2ms) SAVEPOINT active_record_1 Section Exists (0.4ms) SELECT 1 AS one FROM "sections" WHERE "sections"."canvas_section_id" = ? LIMIT ? [["canvas_section_id", 56305225], ["LIMIT", 1]] SQL (0.4ms) INSERT INTO "sections" ("canvas_section_id", "created_at", "updated_at") VALUES (?, ?, ?) [["canvas_section_id", 56305225], ["created_at", "2017-11-02 21:24:41.974949"], ["updated_at", "2017-11-02 21:24:41.974949"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.6ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Term Exists (0.2ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 61974683], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 61974683], ["name", "Cool Term"], ["start_at", "2017-10-30 21:24:38.724817"], ["end_at", "2017-11-05 21:24:38.726016"], ["workflow_state", "active"], ["sis_id", "2fcf487ea761d2c1a04a3fccf1d4c7cb"], ["created_at", "2017-11-02 21:24:41.987286"], ["updated_at", "2017-11-02 21:24:41.987286"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" IS NULL AND ("terms"."id" != ?) LIMIT ? [["id", 1], ["LIMIT", 1]]  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 48671642], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 48671642], ["name", "Cool Term"], ["start_at", "2017-10-30 21:24:38.724817"], ["end_at", "2017-11-05 21:24:38.726016"], ["workflow_state", "active"], ["sis_id", "3c41e9b83b55f70bb82525c2b49bcbde"], ["created_at", "2017-11-02 21:24:41.993528"], ["updated_at", "2017-11-02 21:24:41.993528"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Term Load (0.1ms) SELECT "terms".* FROM "terms" ORDER BY "terms"."id" ASC LIMIT ? [["LIMIT", 1]] Term Exists (0.2ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 48671642], ["LIMIT", 1]]  (0.6ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Term Exists (0.3ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 59712727], ["LIMIT", 1]] SQL (0.6ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 59712727], ["name", "Cool Term"], ["start_at", "2017-10-30 21:24:38.724817"], ["end_at", "2017-11-05 21:24:38.726016"], ["workflow_state", "active"], ["sis_id", "5ca46c2b9ed3f490c1bf0ae0b55744e6"], ["created_at", "2017-11-02 21:24:42.013093"], ["updated_at", "2017-11-02 21:24:42.013093"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.7ms) rollback transaction  (0.2ms) begin transaction  (0.2ms) SAVEPOINT active_record_1 Term Exists (0.4ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 77452985], ["LIMIT", 1]] SQL (0.5ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 77452985], ["name", "Cool Term"], ["start_at", "2017-10-31 21:24:42.019320"], ["end_at", "2017-11-05 21:24:42.019507"], ["workflow_state", "active"], ["sis_id", "4475bc274cc7530ead7768bda9e7ebdd"], ["created_at", "2017-11-02 21:24:42.022697"], ["updated_at", "2017-11-02 21:24:42.022697"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 26957397], ["LIMIT", 1]] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 26957397], ["name", "Cool Term"], ["start_at", "2017-10-30 21:24:38.724817"], ["end_at", "2017-11-05 21:24:38.726016"], ["workflow_state", "inactive"], ["sis_id", "0ce2e51d505e457c968988c7cb958723"], ["created_at", "2017-11-02 21:24:42.025721"], ["updated_at", "2017-11-02 21:24:42.025721"]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 49767174], ["LIMIT", 1]] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 49767174], ["name", "Cool Term"], ["start_at", "2017-09-02 21:24:42.026782"], ["end_at", "2017-10-02 21:24:42.026880"], ["workflow_state", "active"], ["sis_id", "bab8b4f016e0a9a5fb1d2890fc72903f"], ["created_at", "2017-11-02 21:24:42.027958"], ["updated_at", "2017-11-02 21:24:42.027958"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 84281144], ["LIMIT", 1]] SQL (0.1ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 84281144], ["name", "Cool Term"], ["start_at", "2018-05-02 21:24:42.028923"], ["end_at", "2018-11-02 21:24:42.028978"], ["workflow_state", "active"], ["sis_id", "0e072a744b1bbc8bf579eef980451706"], ["created_at", "2017-11-02 21:24:42.030025"], ["updated_at", "2017-11-02 21:24:42.030025"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Term Load (0.1ms) SELECT "terms".* FROM "terms" WHERE "terms"."workflow_state" = ? AND (start_at <= '2017-11-17 21:24:42.031063' OR start_at IS NULL) AND (end_at >= '2017-10-18 21:24:42.031309' OR end_at IS NULL) [["workflow_state", "active"]]  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SELECT COUNT(*) FROM "terms" Term Load (0.1ms) SELECT "terms".* FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 1], ["LIMIT", 1]]  (0.1ms) SAVEPOINT active_record_1 Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 1], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "terms" ("canvas_term_id", "name", "workflow_state", "grading_period_group_id", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 1], ["name", "Default Term"], ["workflow_state", "active"], ["grading_period_group_id", 1], ["sis_id", "Test"], ["created_at", "2017-11-02 21:24:42.036746"], ["updated_at", "2017-11-02 21:24:42.036746"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SELECT COUNT(*) FROM "terms" Term Load (0.1ms) SELECT "terms".* FROM "terms" ORDER BY "terms"."id" DESC LIMIT ? [["LIMIT", 1]]  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 1], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "terms" ("canvas_term_id", "name", "start_at", "end_at", "workflow_state", "sis_id", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["canvas_term_id", 1], ["name", "Cool Term"], ["start_at", "2017-10-30 21:24:38.724817"], ["end_at", "2017-11-05 21:24:38.726016"], ["workflow_state", "active"], ["sis_id", "9ab3781b29b796bd828d2657c58a3146"], ["created_at", "2017-11-02 21:24:42.041514"], ["updated_at", "2017-11-02 21:24:42.041514"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SELECT COUNT(*) FROM "terms" Term Load (0.1ms) SELECT "terms".* FROM "terms" WHERE "terms"."canvas_term_id" = ? LIMIT ? [["canvas_term_id", 1], ["LIMIT", 1]]  (0.0ms) SAVEPOINT active_record_1 Term Exists (0.1ms) SELECT 1 AS one FROM "terms" WHERE "terms"."canvas_term_id" = ? AND ("terms"."id" != ?) LIMIT ? [["canvas_term_id", 1], ["id", 1], ["LIMIT", 1]] SQL (0.2ms) UPDATE "terms" SET "name" = ?, "start_at" = ?, "end_at" = ?, "grading_period_group_id" = ?, "sis_id" = ?, "updated_at" = ? WHERE "terms"."id" = ? [["name", "Default Term"], ["start_at", nil], ["end_at", nil], ["grading_period_group_id", 1], ["sis_id", "Test"], ["updated_at", "2017-11-02 21:24:42.044679"], ["id", 1]]  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SELECT COUNT(*) FROM "terms" Term Load (0.1ms) SELECT "terms".* FROM "terms" WHERE "terms"."id" = ? LIMIT ? [["id", 1], ["LIMIT", 1]]  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 User Exists (0.3ms) SELECT 1 AS one FROM "users" WHERE "users"."canvas_user_id" = ? LIMIT ? [["canvas_user_id", 44879384], ["LIMIT", 1]] SQL (0.7ms) INSERT INTO "users" ("canvas_user_id", "sis_id", "email", "first_name", "last_name", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?) [["canvas_user_id", 44879384], ["sis_id", "fecdc7645acaebffb722573e2443d2ce"], ["email", "cooldude@coolsite.com"], ["first_name", "Cool"], ["last_name", "Dude"], ["created_at", "2017-11-02 21:24:42.069090"], ["updated_at", "2017-11-02 21:24:42.069090"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 User Exists (0.1ms) SELECT 1 AS one FROM "users" WHERE "users"."canvas_user_id" IS NULL AND ("users"."id" != ?) LIMIT ? [["id", 1], ["LIMIT", 1]]  (0.7ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 User Exists (0.1ms) SELECT 1 AS one FROM "users" WHERE "users"."canvas_user_id" = ? LIMIT ? [["canvas_user_id", 18355299], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "users" ("canvas_user_id", "sis_id", "email", "first_name", "last_name", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?) [["canvas_user_id", 18355299], ["sis_id", "81b24552754ecb69e90c70e8f8fc5591"], ["email", "cooldude@coolsite.com"], ["first_name", "Cool"], ["last_name", "Dude"], ["created_at", "2017-11-02 21:24:42.077336"], ["updated_at", "2017-11-02 21:24:42.077336"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 User Load (0.1ms) SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT ? [["LIMIT", 1]] User Exists (0.1ms) SELECT 1 AS one FROM "users" WHERE "users"."canvas_user_id" = ? LIMIT ? [["canvas_user_id", 18355299], ["LIMIT", 1]]  (0.6ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 User Exists (0.1ms) SELECT 1 AS one FROM "users" WHERE "users"."canvas_user_id" = ? LIMIT ? [["canvas_user_id", 49125775], ["LIMIT", 1]] SQL (0.3ms) INSERT INTO "users" ("canvas_user_id", "sis_id", "email", "first_name", "last_name", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?) [["canvas_user_id", 49125775], ["sis_id", "db62bb371d0225f61c71bcea2da404d7"], ["email", "cooldude@coolsite.com"], ["first_name", "Cool"], ["last_name", "Dude"], ["created_at", "2017-11-02 21:24:42.084484"], ["updated_at", "2017-11-02 21:24:42.084484"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SELECT COUNT(*) FROM "users"  (0.1ms) SELECT sqlite_version(*) Ignoring on_duplicate_key_update because it is not supported by the database.  (0.1ms) SAVEPOINT active_record_1 User Create Many Without Validations Or Callbacks (0.3ms) INSERT INTO "users" ("canvas_user_id","sis_id","email","first_name","last_name","status","login_id","created_at","updated_at") VALUES (1,'sis_id_1','poorbastard@yharnam.com','Patches','the Spider','active','spiderdude1337','2017-11-02 21:24:42.089489','2017-11-02 21:24:42.089489'),(2,'sis_id_2','dreamer@yharnam.com','Hunter','Djura','active','retireddude109','2017-11-02 21:24:42.089489','2017-11-02 21:24:42.089489')  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SELECT COUNT(*) FROM "users"  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SELECT COUNT(*) FROM "courses" Ignoring on_duplicate_key_update because it is not supported by the database.  (0.1ms) SAVEPOINT active_record_1 Course Create Many Without Validations Or Callbacks (0.4ms) INSERT INTO "courses" ("canvas_course_id","sis_id","short_name","long_name","canvas_account_id","canvas_term_id","term_sis_id","start_date","end_date","status","created_at","updated_at") VALUES (1,'course_sis_id_1','C1','Course #1',1,1,0,'2017-03-27T15:53:18-06:00','2017-04-27T06:21:18-06:00','active','2017-11-02 21:24:42.093797','2017-11-02 21:24:42.093797'),(2,'course_sis_id_2','C2','Course #2',1,1,0,'2017-03-27T15:53:18-06:00','2017-04-27T06:21:18-06:00','unpublished','2017-11-02 21:24:42.093797','2017-11-02 21:24:42.093797')  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SELECT COUNT(*) FROM "courses"  (0.5ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SELECT COUNT(*) FROM "enrollments" Ignoring on_duplicate_key_update because it is not supported by the database.  (0.1ms) SAVEPOINT active_record_1 Enrollment Create Many Without Validations Or Callbacks (0.3ms) INSERT INTO "enrollments" ("canvas_enrollment_id","canvas_course_id","course_sis_id","canvas_user_id","user_sis_id","role","role_id","canvas_section_id","section_sis_id","status","base_role_type","created_at","updated_at") VALUES (1,1,'sis_MUSC_2520_834',2,'sis_dalvarez_247','teacher',4,1,'sis_section_MUSC_2520_752','active','TeacherEnrollment','2017-11-02 21:24:42.106360','2017-11-02 21:24:42.106360'),(2,1,'sis_MUSC_2520_834',3,'sis_jweaver_720','student',4,1,'sis_section_MUSC_2520_752','active','StudentEnrollment','2017-11-02 21:24:42.106360','2017-11-02 21:24:42.106360')  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SELECT COUNT(*) FROM "enrollments"  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SELECT COUNT(*) FROM "sections" Ignoring on_duplicate_key_update because it is not supported by the database.  (0.1ms) SAVEPOINT active_record_1 Section Create Many Without Validations Or Callbacks (0.3ms) INSERT INTO "sections" ("canvas_section_id","sis_id","canvas_course_id","name","status","start_date","end_date","created_at","updated_at") VALUES (1,'sis_section_1',1,'Cool Section','active','2017-03-27T15:53:18-06:00','2017-03-27T15:53:18-06:00','2017-11-02 21:24:42.111091','2017-11-02 21:24:42.111091'),(2,'sis_section_2',2,'Lame Section','active','2017-03-27T15:53:18-06:00','2017-03-27T15:53:18-06:00','2017-11-02 21:24:42.111091','2017-11-02 21:24:42.111091')  (0.1ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SELECT COUNT(*) FROM "sections"  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SELECT COUNT(*) FROM "users"  (0.1ms) SELECT COUNT(*) FROM "courses" Ignoring on_duplicate_key_update because it is not supported by the database.  (0.1ms) SAVEPOINT active_record_1 Course Create Many Without Validations Or Callbacks (0.4ms) INSERT INTO "courses" ("canvas_course_id","sis_id","short_name","long_name","canvas_account_id","canvas_term_id","term_sis_id","start_date","end_date","status","created_at","updated_at") VALUES (1,'course_sis_id_1','C1','Course #1',1,1,0,'2017-03-27T15:53:18-06:00','2017-04-27T06:21:18-06:00','active','2017-11-02 21:24:42.120698','2017-11-02 21:24:42.120698'),(2,'course_sis_id_2','C2','Course #2',1,1,0,'2017-03-27T15:53:18-06:00','2017-04-27T06:21:18-06:00','unpublished','2017-11-02 21:24:42.120698','2017-11-02 21:24:42.120698')  (0.1ms) RELEASE SAVEPOINT active_record_1 Ignoring on_duplicate_key_update because it is not supported by the database.  (0.1ms) SAVEPOINT active_record_1 User Create Many Without Validations Or Callbacks (0.2ms) INSERT INTO "users" ("canvas_user_id","sis_id","email","first_name","last_name","status","login_id","created_at","updated_at") VALUES (1,'sis_id_1','poorbastard@yharnam.com','Patches','the Spider','active','spiderdude1337','2017-11-02 21:24:42.123146','2017-11-02 21:24:42.123146'),(2,'sis_id_2','dreamer@yharnam.com','Hunter','Djura','active','retireddude109','2017-11-02 21:24:42.123146','2017-11-02 21:24:42.123146')  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.1ms) SELECT COUNT(*) FROM "users"  (0.2ms) SELECT COUNT(*) FROM "courses"  (0.7ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) rollback transaction