Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 19ms (Views: 19.2ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.0ms) Completed 200 OK in 0ms (Views: 0.3ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 3ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) 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 Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287406", "oauth_nonce"=>"erTwBoft7gy2wNGFavT2xpjUCTAjQl91AEu4SvUQ", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"ZywdUy5kAtMr6yBvUtzwPO/FfnU="} Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287406", "oauth_nonce"=>"de4xtIrf62R5UTswIZCopVkSgnajcTXCZ0dsw8lywIc", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"hSY7ReZuQieCX5Wig/60HDw2N/E="} Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287406", "oauth_nonce"=>"t85jkY4B81B8ebs46ec0EqW7RwG5UAochFjtnSbFA", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"KKe/iGQzRCUrZaRk8duH05r5hZw="} Completed 500 Internal Server Error in 1ms (ActiveRecord: 0.1ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287406", "oauth_nonce"=>"BMdhn43LX6SzRSqy3sOWxZ9SjWKFclB4aIm05PZO2A", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"Lo1mJllJJkiSQQhOkdwT3ybAjPg="} Completed 500 Internal Server Error in 1ms (ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 2ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 9ms (Views: 9.2ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.0ms) Completed 200 OK in 0ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287574", "oauth_nonce"=>"7PITv82y5FbbRvxggW3TC8GYlCCVtvNeBthlKIQRBk", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"kqvSbSj7V+FeYYRqCWsCRD5ZuOU="} Completed 500 Internal Server Error in 2ms (ActiveRecord: 1.2ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287574", "oauth_nonce"=>"wKSAWyHC9NTfINRd8DUqjXBEJhjpp4C3RCEEYN6diU", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"gayPi5x6Hs/EBhrF0bgfbXHvLFY="} Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287574", "oauth_nonce"=>"2hjvSsyvq0hOypUWYkCXQYx1WkhL9BaRtnjY0i7k", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"wUq+txzdzyexaC8/VImO3VEvUE8="} Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287574", "oauth_nonce"=>"Nn99JWdHpduQ8jIgJwFcnGiSR3Mn8hLjwSttFB0Ws", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"byaXWdtLl5ShUjdGVtY28y9uAKk="} Completed 500 Internal Server Error in 1ms (ActiveRecord: 0.1ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) 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.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) 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.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287628", "oauth_nonce"=>"X8mmps5dGSgCQSyPQb05NB873SUltrqjFLNcQKuw04", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"Tl+iGzLfy91vSY8XTTjf0g9xzQA="} Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.1ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287628", "oauth_nonce"=>"jFSkNO0SxfE7oqAaSdV3ReMUFoL6y2iIgcA5Gj170c", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"z+hrS73PVqxr9uS2KK65/eHZnRI="} Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287628", "oauth_nonce"=>"y0sPBTTaY4pkjnko0CkN49leqTgZ7WQ1LBe38NzIgPA", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"os/oKb/kHJbikPRhZNgGfS0su40="} Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287628", "oauth_nonce"=>"9M9OIGrZmhnmJJKoUmq827AhROKWrustGbth369HU", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"TquRBPGid/mgwZEMKkeZ9mW9IhQ="} Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 14ms (Views: 13.7ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.0ms) Completed 200 OK in 0ms (Views: 0.3ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 4ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (1.5ms) CREATE TABLE "schema_migrations" ("version" varchar NOT NULL)   (0.0ms) select sqlite_version(*)  (0.7ms) CREATE UNIQUE INDEX "unique_schema_migrations" ON "schema_migrations" ("version") ActiveRecord::SchemaMigration Load (0.0ms) SELECT "schema_migrations".* FROM "schema_migrations" Migrating to CreateLtiProviderLaunches (20130319050003)  (0.0ms) begin transaction  (0.2ms) CREATE TABLE "lti_provider_launches" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "canvas_url" varchar, "nonce" varchar, "provider_params" text, "created_at" datetime, "updated_at" datetime) SQL (0.1ms) INSERT INTO "schema_migrations" ("version") VALUES (?) [["version", "20130319050003"]]  (0.7ms) commit transaction ActiveRecord::SchemaMigration Load (0.0ms) SELECT "schema_migrations".* FROM "schema_migrations" Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 2ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:01:52.808682"], ["updated_at", "2016-08-15 19:01:52.808682"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = ? [["created_at", "2016-08-15 18:51:52.812197"], ["updated_at", "2016-08-15 19:01:52.812561"], ["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 18:56:52.820813') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]] Rendered text template (0.0ms) Completed 200 OK in 9ms (Views: 6.7ms | ActiveRecord: 0.1ms)  (0.7ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:01:52.833906"], ["updated_at", "2016-08-15 19:01:52.833906"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"invalid"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 18:56:52.837223') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "invalid"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms)  (0.6ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:01:52.841606"], ["updated_at", "2016-08-15 19:01:52.841606"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 18:56:52.843984') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 5ms (ActiveRecord: 0.3ms)  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches"  (1.2ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:01:52.854926"], ["updated_at", "2016-08-15 19:01:52.854926"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 18:56:52.857186') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 1ms (ActiveRecord: 0.3ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 4ms (Views: 4.3ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.0ms) Completed 200 OK in 0ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287712", "oauth_nonce"=>"2Jxyk4Qvg1fFuDdHuMIpd5e5UugV3xIdKkSXPJHb0Rs", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"58744D/Fn6sWc5M74hKXTCEfRp8="} Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.4ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287712", "oauth_nonce"=>"XhlZXUlvus57P53TsbDXYmhxTMJxbm2fJ8MpGASdRc", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"RRAnvFyaL7BOvrZacf8ma8K2mKY="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: XhlZXUlvus57P53TsbDXYmhxTMJxbm2fJ8MpGASdRc\noauth_signature: RRAnvFyaL7BOvrZacf8ma8K2mKY=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471287712'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "XhlZXUlvus57P53TsbDXYmhxTMJxbm2fJ8MpGASdRc"], ["created_at", "2016-08-15 19:01:52.898988"], ["updated_at", "2016-08-15 19:01:52.898988"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=XhlZXUlvus57P53TsbDXYmhxTMJxbm2fJ8MpGASdRc Completed 302 Found in 6ms (ActiveRecord: 0.3ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287712", "oauth_nonce"=>"tfK1H7sRqJmSGig9PDVGGM8pBINetDNd6NY4GtGK8E", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"VMux0jce/Nns+9u3X/Mfoiu4Qrg="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: tfK1H7sRqJmSGig9PDVGGM8pBINetDNd6NY4GtGK8E\noauth_signature: VMux0jce/Nns+9u3X/Mfoiu4Qrg=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471287712'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "tfK1H7sRqJmSGig9PDVGGM8pBINetDNd6NY4GtGK8E"], ["created_at", "2016-08-15 19:01:52.912262"], ["updated_at", "2016-08-15 19:01:52.912262"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=tfK1H7sRqJmSGig9PDVGGM8pBINetDNd6NY4GtGK8E Completed 302 Found in 5ms (ActiveRecord: 0.3ms) LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471287712", "oauth_nonce"=>"7LhvQcTU0GF0yAab0Uo3cCFOrQJSaNPmQXB8rqzZUk", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"/BUDtbXT4/5c74Ax78TtJvDSC1g="} Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) 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.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 3ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.4ms) Completed 200 OK in 15ms (Views: 14.4ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.0ms) Completed 200 OK in 0ms (Views: 0.3ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 SQL (0.8ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:07:23.053322"], ["updated_at", "2016-08-15 19:07:23.053322"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = ? [["created_at", "2016-08-15 18:57:23.057605"], ["updated_at", "2016-08-15 19:07:23.057967"], ["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:02:23.065485') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]] Rendered text template (0.0ms) Completed 200 OK in 4ms (Views: 1.3ms | ActiveRecord: 0.1ms)  (0.6ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:07:23.073106"], ["updated_at", "2016-08-15 19:07:23.073106"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.2ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:02:23.076691') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.1ms) SAVEPOINT active_record_1 SQL (0.3ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 6ms (ActiveRecord: 0.6ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:07:23.084808"], ["updated_at", "2016-08-15 19:07:23.084808"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:02:23.086784') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 1ms (ActiveRecord: 0.3ms)  (0.0ms) SELECT COUNT(*) FROM "lti_provider_launches"  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:07:23.090298"], ["updated_at", "2016-08-15 19:07:23.090298"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"invalid"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:02:23.092477') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "invalid"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms)  (0.3ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288043", "oauth_nonce"=>"dTWHjPklKoluppFcPdUmhHcxtNbqAjmSguHNuwqo", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"b95dkDZl+3uC31Q87OWQO+pu7NE="} Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288043", "oauth_nonce"=>"z610gHHNbiiUYg4uMWCkBKpZOw7oF46hHA1xLBI2M", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"kyQOUFYPHawFKVzfojDrYLiawek="} Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288043", "oauth_nonce"=>"N29aj2E8j2g68B71jsYcmHDXSa0CLz7OiLPFCBcxs", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"smI1fuUGLoHq2t+1A1x2X6z4i3k="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: N29aj2E8j2g68B71jsYcmHDXSa0CLz7OiLPFCBcxs\noauth_signature: smI1fuUGLoHq2t+1A1x2X6z4i3k=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288043'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "N29aj2E8j2g68B71jsYcmHDXSa0CLz7OiLPFCBcxs"], ["created_at", "2016-08-15 19:07:23.116117"], ["updated_at", "2016-08-15 19:07:23.116117"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=N29aj2E8j2g68B71jsYcmHDXSa0CLz7OiLPFCBcxs Completed 302 Found in 5ms (ActiveRecord: 0.3ms) LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288043", "oauth_nonce"=>"3L3ISbKiL3lytqi8bprRtDIsLVnHlDEuCcfiEkczeNk", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"3aOcQJ5fnQwlgjW/3ePtoroQQx8="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: 3L3ISbKiL3lytqi8bprRtDIsLVnHlDEuCcfiEkczeNk\noauth_signature: 3aOcQJ5fnQwlgjW/3ePtoroQQx8=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288043'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "3L3ISbKiL3lytqi8bprRtDIsLVnHlDEuCcfiEkczeNk"], ["created_at", "2016-08-15 19:07:23.126639"], ["updated_at", "2016-08-15 19:07:23.126639"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=3L3ISbKiL3lytqi8bprRtDIsLVnHlDEuCcfiEkczeNk Completed 302 Found in 6ms (ActiveRecord: 0.2ms)  (0.3ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) 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.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288088", "oauth_nonce"=>"EZvBNM2EGwdAXwXe2O4KrzwV3eALbMia9xDNC9hPVs", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"4OdGhocgI4A3+uUbD227EWY/eDg="} Rendered text template (0.0ms) Completed 200 OK in 10ms (Views: 8.0ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288088", "oauth_nonce"=>"YULKbRP9307QiZecwzqD96SDNjGXcRkUMiSthxte1vc", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"+pQBx/JgmqxNT88dtmFxzPGowzo="} Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288088", "oauth_nonce"=>"UvgmejFHo1oLuhxnDAPkLjI5d2u1rJ9W5VksGcY09Eo", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"UfE1Ok1sKV3BLKLhf713OAu/pas="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: UvgmejFHo1oLuhxnDAPkLjI5d2u1rJ9W5VksGcY09Eo\noauth_signature: UfE1Ok1sKV3BLKLhf713OAu/pas=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288088'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "UvgmejFHo1oLuhxnDAPkLjI5d2u1rJ9W5VksGcY09Eo"], ["created_at", "2016-08-15 19:08:08.868145"], ["updated_at", "2016-08-15 19:08:08.868145"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=UvgmejFHo1oLuhxnDAPkLjI5d2u1rJ9W5VksGcY09Eo Completed 302 Found in 11ms (ActiveRecord: 0.4ms) LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1  (0.8ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288088", "oauth_nonce"=>"2FAFBJFm0PRO7zzA6wFTCdorSFp3tUW2f2QVkVxVPc", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"PnGP+SI5fc9z57xihXE/5D1mz80="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: 2FAFBJFm0PRO7zzA6wFTCdorSFp3tUW2f2QVkVxVPc\noauth_signature: PnGP+SI5fc9z57xihXE/5D1mz80=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288088'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "2FAFBJFm0PRO7zzA6wFTCdorSFp3tUW2f2QVkVxVPc"], ["created_at", "2016-08-15 19:08:08.888949"], ["updated_at", "2016-08-15 19:08:08.888949"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=2FAFBJFm0PRO7zzA6wFTCdorSFp3tUW2f2QVkVxVPc Completed 302 Found in 6ms (ActiveRecord: 0.3ms)  (0.3ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:08:08.897702"], ["updated_at", "2016-08-15 19:08:08.897702"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = ? [["created_at", "2016-08-15 18:58:08.899068"], ["updated_at", "2016-08-15 19:08:08.899440"], ["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:03:08.905006') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.2ms | ActiveRecord: 0.1ms)  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:08:08.908996"], ["updated_at", "2016-08-15 19:08:08.908996"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.2ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:03:08.912245') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.1ms) SAVEPOINT active_record_1 SQL (0.4ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 5ms (ActiveRecord: 0.8ms)  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches"  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:08:08.920189"], ["updated_at", "2016-08-15 19:08:08.920189"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:03:08.922752') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 1ms (ActiveRecord: 0.3ms)  (1.2ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:08:08.930585"], ["updated_at", "2016-08-15 19:08:08.930585"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"invalid"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:03:08.932880') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "invalid"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms)  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 4ms (Views: 4.3ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.0ms) Completed 200 OK in 0ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 2ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288138", "oauth_nonce"=>"weN0nMblqluUlpdQeOf4pUHyNCp7RStwcpbolE2m3Os", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"7h8XOMDEU1oYaOjGKY5TUQXDnaQ="} Rendered text template (0.0ms) Completed 200 OK in 21ms (Views: 13.4ms | ActiveRecord: 1.2ms)  (0.1ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288138", "oauth_nonce"=>"6NFsvUfKIEta5EJgYKQUCmbLlODmXx5lRuewQ7Hh8", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"GlS6GZryJsqcZAPq+NHrBjerXZ4="} Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288138", "oauth_nonce"=>"b9GlhL7lPB3hLsvHg40cg4NcYh7hl9A5DC0Bs6Ym8", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"OeRQpSZQmDHP4e9vOKJCctCqlB4="}  (0.1ms) SAVEPOINT active_record_1 SQL (1.1ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: b9GlhL7lPB3hLsvHg40cg4NcYh7hl9A5DC0Bs6Ym8\noauth_signature: OeRQpSZQmDHP4e9vOKJCctCqlB4=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288138'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "b9GlhL7lPB3hLsvHg40cg4NcYh7hl9A5DC0Bs6Ym8"], ["created_at", "2016-08-15 19:08:58.044221"], ["updated_at", "2016-08-15 19:08:58.044221"]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=b9GlhL7lPB3hLsvHg40cg4NcYh7hl9A5DC0Bs6Ym8 Completed 302 Found in 17ms (ActiveRecord: 1.3ms) LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1  (0.8ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288138", "oauth_nonce"=>"OTG7WxNr67l2AZq5mkHWKJPPv0QddLQcyqTQoxN9zEc", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"IOE/+AC9jGW2+jTYM3SVi1YUKpo="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: OTG7WxNr67l2AZq5mkHWKJPPv0QddLQcyqTQoxN9zEc\noauth_signature: IOE/+AC9jGW2+jTYM3SVi1YUKpo=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288138'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "OTG7WxNr67l2AZq5mkHWKJPPv0QddLQcyqTQoxN9zEc"], ["created_at", "2016-08-15 19:08:58.075999"], ["updated_at", "2016-08-15 19:08:58.075999"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=OTG7WxNr67l2AZq5mkHWKJPPv0QddLQcyqTQoxN9zEc Completed 302 Found in 5ms (ActiveRecord: 0.3ms)  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 2ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (1.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:08:58.088911"], ["updated_at", "2016-08-15 19:08:58.088911"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = ? [["created_at", "2016-08-15 18:58:58.091457"], ["updated_at", "2016-08-15 19:08:58.091802"], ["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:03:58.097099') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.1ms)  (1.0ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:08:58.102971"], ["updated_at", "2016-08-15 19:08:58.102971"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:03:58.105974') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 8ms (ActiveRecord: 0.4ms)  (0.5ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:08:58.115738"], ["updated_at", "2016-08-15 19:08:58.115738"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:03:58.118070') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 1ms (ActiveRecord: 0.4ms)  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches"  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:08:58.121856"], ["updated_at", "2016-08-15 19:08:58.121856"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"invalid"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:03:58.123946') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "invalid"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms)  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 5ms (Views: 4.4ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.0ms) Completed 200 OK in 0ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (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.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) 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.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) 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.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.4ms) rollback transaction  (0.2ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:09:10.220618"], ["updated_at", "2016-08-15 19:09:10.220618"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"invalid"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:04:10.226730') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "invalid"]] Rendered text template (0.0ms) Completed 200 OK in 13ms (Views: 7.6ms | ActiveRecord: 0.1ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:09:10.242087"], ["updated_at", "2016-08-15 19:09:10.242087"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = ? [["created_at", "2016-08-15 18:59:10.243405"], ["updated_at", "2016-08-15 19:09:10.243733"], ["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:04:10.245969') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:09:10.248525"], ["updated_at", "2016-08-15 19:09:10.248525"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (1.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:04:10.251286') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.1ms) SAVEPOINT active_record_1 SQL (0.3ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 13ms (ActiveRecord: 1.5ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:09:10.266589"], ["updated_at", "2016-08-15 19:09:10.266589"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:04:10.268826') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 1ms (ActiveRecord: 0.4ms)  (0.0ms) SELECT COUNT(*) FROM "lti_provider_launches"  (0.4ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 5ms (Views: 4.1ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.1ms) Completed 200 OK in 0ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 2ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288150", "oauth_nonce"=>"MsKFDZTvONRUvzHqynUG45A098oFJyTaPmFIuAfWJw", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"qw397WapGMt+liWLl9Phowv6Qgw="} Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.5ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288150", "oauth_nonce"=>"DBQRS7OYx9eP68jgecrdkQpLbe6ayqclgh4hf8N1UM", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"AJs2lfQ+GkID5/pV79Sel8cawyk="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: DBQRS7OYx9eP68jgecrdkQpLbe6ayqclgh4hf8N1UM\noauth_signature: AJs2lfQ+GkID5/pV79Sel8cawyk=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288150'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "DBQRS7OYx9eP68jgecrdkQpLbe6ayqclgh4hf8N1UM"], ["created_at", "2016-08-15 19:09:10.308606"], ["updated_at", "2016-08-15 19:09:10.308606"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=DBQRS7OYx9eP68jgecrdkQpLbe6ayqclgh4hf8N1UM Completed 302 Found in 6ms (ActiveRecord: 0.3ms) LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288150", "oauth_nonce"=>"zQXR55fILMNMXYSi9QJhbnAoobOYbEtS8oWE3kNSuE", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"vb7ZSOQYTzaFHEt5M56fodBmLNQ="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: zQXR55fILMNMXYSi9QJhbnAoobOYbEtS8oWE3kNSuE\noauth_signature: vb7ZSOQYTzaFHEt5M56fodBmLNQ=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288150'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "zQXR55fILMNMXYSi9QJhbnAoobOYbEtS8oWE3kNSuE"], ["created_at", "2016-08-15 19:09:10.320326"], ["updated_at", "2016-08-15 19:09:10.320326"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=zQXR55fILMNMXYSi9QJhbnAoobOYbEtS8oWE3kNSuE Completed 302 Found in 7ms (ActiveRecord: 0.3ms)  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288150", "oauth_nonce"=>"eVTLTM4SHCRIVjzO6A3MEWGC5KES6efv2ry29W8kM1w", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"LxPZXkTYLXzw3s2tgoiG396M1ns="} Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.2ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 9ms (Views: 9.3ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.0ms) Completed 200 OK in 0ms (Views: 0.3ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 SQL (1.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:10:33.385709"], ["updated_at", "2016-08-15 19:10:33.385709"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 SQL (0.4ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = ? [["created_at", "2016-08-15 19:00:33.391293"], ["updated_at", "2016-08-15 19:10:33.391681"], ["id", 1]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:05:33.398983') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]] Rendered text template (0.0ms) Completed 200 OK in 5ms (Views: 2.4ms | ActiveRecord: 0.1ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:10:33.406602"], ["updated_at", "2016-08-15 19:10:33.406602"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:05:33.408622') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.1ms) SAVEPOINT active_record_1 SQL (0.4ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 6ms (ActiveRecord: 0.6ms)  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches"  (0.5ms) rollback transaction  (0.2ms) begin transaction  (0.1ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:10:33.419129"], ["updated_at", "2016-08-15 19:10:33.419129"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:05:33.421907') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 1ms (ActiveRecord: 0.3ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:10:33.425153"], ["updated_at", "2016-08-15 19:10:33.425153"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"invalid"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:05:33.427156') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "invalid"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms)  (0.2ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288233", "oauth_nonce"=>"AS2TohHP3sJvsKnhGJgkxcIawvYAmxNq4f9bAfKow0", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"MZkQnLzohDmoEfHftS2M0rYOJcQ="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: AS2TohHP3sJvsKnhGJgkxcIawvYAmxNq4f9bAfKow0\noauth_signature: MZkQnLzohDmoEfHftS2M0rYOJcQ=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288233'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "AS2TohHP3sJvsKnhGJgkxcIawvYAmxNq4f9bAfKow0"], ["created_at", "2016-08-15 19:10:33.435836"], ["updated_at", "2016-08-15 19:10:33.435836"]]  (0.3ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=AS2TohHP3sJvsKnhGJgkxcIawvYAmxNq4f9bAfKow0 Completed 302 Found in 11ms (ActiveRecord: 0.6ms) LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288233", "oauth_nonce"=>"1VgytcvPLxDbZ1oVTmo81Y8dDBaHLXArO8Wl9XaRZE", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"EaWfdTx3cnvldcoXO8UD1uL1O+o="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: 1VgytcvPLxDbZ1oVTmo81Y8dDBaHLXArO8Wl9XaRZE\noauth_signature: EaWfdTx3cnvldcoXO8UD1uL1O+o=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471288233'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "1VgytcvPLxDbZ1oVTmo81Y8dDBaHLXArO8Wl9XaRZE"], ["created_at", "2016-08-15 19:10:33.452021"], ["updated_at", "2016-08-15 19:10:33.452021"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=1VgytcvPLxDbZ1oVTmo81Y8dDBaHLXArO8Wl9XaRZE Completed 302 Found in 5ms (ActiveRecord: 0.2ms)  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288233", "oauth_nonce"=>"QUU0HdhmYku6Od7YBL0479QjdEZ8kvJ4zL2hCsV40Q", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"KkQH19pdaoPV8zLyS8C8eQoOS0s="} Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471288233", "oauth_nonce"=>"QTn7hp19gOJmu0JNQLs1zVjdbgx4dEh6MYoi1L0EpY", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"hpeGCwyKzJt6FHVH7fOP6u5EYXQ="} Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.2ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 2ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) 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) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction Initializing LTI key and secret using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/ngupta/Documents/lti_provider_engine/spec/dummy/config/lti_xml.yml  (0.4ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.2ms) Completed 200 OK in 15ms (Views: 15.0ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#cookie_test as HTML Rendered /Users/ngupta/Documents/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb (0.1ms) Completed 200 OK in 1ms (Views: 1.0ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#configure as XML Completed 200 OK in 4ms (Views: 0.1ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471290348", "oauth_nonce"=>"jmxKbuPZuGgnBxHUVgFCgYipBJZ4gx5mt55towDOE", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"va6uNZi5AvtMZNvGVv6x7gyDLDk="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.9ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: jmxKbuPZuGgnBxHUVgFCgYipBJZ4gx5mt55towDOE\noauth_signature: va6uNZi5AvtMZNvGVv6x7gyDLDk=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471290348'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "jmxKbuPZuGgnBxHUVgFCgYipBJZ4gx5mt55towDOE"], ["created_at", "2016-08-15 19:45:48.902975"], ["updated_at", "2016-08-15 19:45:48.902975"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=jmxKbuPZuGgnBxHUVgFCgYipBJZ4gx5mt55towDOE Completed 302 Found in 45ms (ActiveRecord: 4.8ms) LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1  (0.3ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471290348", "oauth_nonce"=>"u4k0YQcs4FDCBBBN68xukEljpZ6BNacIkITElKzM0c", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"4Bkv5+LagLf59v2SDLGA3viEWVo="}  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("provider_params", "canvas_url", "nonce", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["provider_params", "---\nlaunch_presentation_return_url: http://test.canvas\nlti_message_type: basic-lti-launch-request\nlti_version: LTI-1p0\noauth_consumer_key: '12345'\noauth_nonce: u4k0YQcs4FDCBBBN68xukEljpZ6BNacIkITElKzM0c\noauth_signature: 4Bkv5+LagLf59v2SDLGA3viEWVo=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1471290348'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["canvas_url", "http://test.canvas"], ["nonce", "u4k0YQcs4FDCBBBN68xukEljpZ6BNacIkITElKzM0c"], ["created_at", "2016-08-15 19:45:48.936853"], ["updated_at", "2016-08-15 19:45:48.936853"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/cookie_test?nonce=u4k0YQcs4FDCBBBN68xukEljpZ6BNacIkITElKzM0c Completed 302 Found in 7ms (ActiveRecord: 0.3ms)  (0.3ms) rollback transaction  (0.1ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471290348", "oauth_nonce"=>"ZPzOrhkTaSE9k0OX7JnD4c6nNyMHdyrGqWwaRNvNrMM", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"mMF349Ry2if6r//cZHJSxjCRX/c="} Rendered text template (0.0ms) Completed 200 OK in 4ms (Views: 3.3ms | ActiveRecord: 0.0ms)  (0.0ms) rollback transaction  (0.0ms) begin transaction Processing by LtiProvider::LtiController#launch as HTML Parameters: {"oauth_consumer_key"=>"12345", "oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1471290348", "oauth_nonce"=>"SWPjyvqhhDPn0hvPUPRtfcPsZSMTdGeYFHmmlLuYkys", "oauth_version"=>"1.0", "custom_canvas_user_id"=>"1", "launch_presentation_return_url"=>"http://test.canvas", "launch_url"=>"http://test.host", "lti_message_type"=>"basic-lti-launch-request", "lti_version"=>"LTI-1p0", "oauth_signature"=>"+zgOkLZ06/Ma/aq90+eDoT334SI="} Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.0ms)  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:45:48.977153"], ["updated_at", "2016-08-15 19:45:48.977153"]]  (0.0ms) RELEASE SAVEPOINT active_record_1  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = ? [["created_at", "2016-08-15 19:35:48.978697"], ["updated_at", "2016-08-15 19:45:48.979075"], ["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:40:48.988173') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.1ms)  (0.4ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:45:48.991566"], ["updated_at", "2016-08-15 19:45:48.991566"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.2ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:40:48.995153') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.4ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 19ms (ActiveRecord: 0.6ms)  (0.9ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:45:49.019271"], ["updated_at", "2016-08-15 19:45:49.019271"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"abcd"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:40:49.022329') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "abcd"]]  (0.0ms) SAVEPOINT active_record_1 SQL (0.2ms) DELETE FROM "lti_provider_launches" WHERE "lti_provider_launches"."id" = ? [["id", 1]]  (0.1ms) RELEASE SAVEPOINT active_record_1 Redirected to http://test.host/ Completed 302 Found in 2ms (ActiveRecord: 0.4ms)  (0.0ms) SELECT COUNT(*) FROM "lti_provider_launches"  (0.5ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) SAVEPOINT active_record_1 SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "nonce", "provider_params", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["created_at", "2016-08-15 19:45:49.026842"], ["updated_at", "2016-08-15 19:45:49.026842"]]  (0.0ms) RELEASE SAVEPOINT active_record_1 Processing by LtiProvider::LtiController#consume_launch as HTML Parameters: {"nonce"=>"invalid"} LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" WHERE (created_at > '2016-08-15 19:40:49.030354') AND "lti_provider_launches"."nonce" = ? LIMIT 1 [["nonce", "invalid"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.4ms | ActiveRecord: 0.1ms)  (1.0ms) rollback transaction  (0.1ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction  (0.0ms) begin transaction  (0.2ms) rollback transaction  (0.1ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.1ms) rollback transaction  (0.0ms) begin transaction  (0.0ms) rollback transaction