spec/dummy/log/test.log in lti_provider_engine-0.0.3 vs spec/dummy/log/test.log in lti_provider_engine-0.0.4

- old
+ new

@@ -3766,5 +3766,1793 @@  (0.0ms) begin transaction  (0.0ms) rollback transaction Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml Connecting to database specified by database.yml +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +  (0.2ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML + Rendered /Users/simon/Instructure/projects/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb within layouts/lti_provider/application (0.1ms) +Completed 200 OK in 24.8ms (Views: 24.6ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.5ms (Views: 0.4ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:48:44.109428') LIMIT 1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.9ms) 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 6.7ms (ActiveRecord: 1.0ms) +  (1.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:48:44.121891') LIMIT 1 +  (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 1.5ms (ActiveRecord: 0.3ms) +  (0.0ms) 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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 02:48:44.127554') LIMIT 1 +Completed 200 OK in 2.0ms (Views: 1.5ms | ActiveRecord: 0.1ms) +  (0.4ms) rollback transaction +  (0.1ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.3ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 02:43:44.134824', "updated_at" = '2014-10-11 02:53:44.135291', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:48:44.138137') LIMIT 1 +Completed 200 OK in 0.9ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (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"=>"1412996024", "oauth_nonce"=>"GzlSZShK0BiNjwTxkRIvNsYO9GQspwpsK95gCNLPdQ", "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"=>"mT9Xtkw9l4mEzMlI4wtkYi/HjSM="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00], ["nonce", "GzlSZShK0BiNjwTxkRIvNsYO9GQspwpsK95gCNLPdQ"], ["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: GzlSZShK0BiNjwTxkRIvNsYO9GQspwpsK95gCNLPdQ\noauth_signature: mT9Xtkw9l4mEzMlI4wtkYi/HjSM=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996024'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=GzlSZShK0BiNjwTxkRIvNsYO9GQspwpsK95gCNLPdQ +Completed 302 Found in 25.2ms (ActiveRecord: 0.4ms) +  (0.6ms) 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"=>"1412996024", "oauth_nonce"=>"V8klNkpBGo03TW2a5fFiAFpF473iWiNBIfYWVMloN4", "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"=>"/1svsmr2mLteooLDLjwUBhD+eFI="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00], ["nonce", "V8klNkpBGo03TW2a5fFiAFpF473iWiNBIfYWVMloN4"], ["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: V8klNkpBGo03TW2a5fFiAFpF473iWiNBIfYWVMloN4\noauth_signature: /1svsmr2mLteooLDLjwUBhD+eFI=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996024'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:53:44 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=V8klNkpBGo03TW2a5fFiAFpF473iWiNBIfYWVMloN4 +Completed 302 Found in 3.8ms (ActiveRecord: 0.4ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" 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"=>"1412996024", "oauth_nonce"=>"GgsANpKuOgMBDe0w4rDFvFoY7JyucRRNYRaXMyMZBQ", "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"=>"uDpyK90V7amVowjXrBKnXyMiGm4="} +Completed 200 OK in 1.1ms (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"=>"1412996024", "oauth_nonce"=>"vgbCIrwrYQyDC6vZacl51KQQYZAvCoMOmyrQhOlNNUk", "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"=>"2mauehUmLwuSf+8nJ136AV6t5Kw="} +Completed 200 OK in 0.8ms (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 1.5ms (Views: 0.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.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.0ms) rollback transaction +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +  (0.2ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML + Rendered /Users/simon/Instructure/projects/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb within layouts/lti_provider/application (0.1ms) +Completed 200 OK in 27.9ms (Views: 27.7ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.5ms (Views: 0.4ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:49:26.505850') LIMIT 1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.7ms) 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 6.5ms (ActiveRecord: 0.8ms) +  (1.1ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:49:26.518080') LIMIT 1 +  (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 1.5ms (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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.2ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 02:44:26.523246', "updated_at" = '2014-10-11 02:54:26.523567', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:49:26.525693') LIMIT 1 +Completed 200 OK in 2.2ms (Views: 1.5ms | ActiveRecord: 0.1ms) +  (0.5ms) rollback transaction +  (0.1ms) begin transaction +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 02:49:26.535412') LIMIT 1 +Completed 200 OK in 0.9ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (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"=>"1412996066", "oauth_nonce"=>"N7IDeClFOI228qXWVblHeNsOpIdmwRLFWAXPBCh6E40", "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"=>"1Uf21nNO9D+99TFeC46CIjUr7x4="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00], ["nonce", "N7IDeClFOI228qXWVblHeNsOpIdmwRLFWAXPBCh6E40"], ["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: N7IDeClFOI228qXWVblHeNsOpIdmwRLFWAXPBCh6E40\noauth_signature: 1Uf21nNO9D+99TFeC46CIjUr7x4=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996066'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=N7IDeClFOI228qXWVblHeNsOpIdmwRLFWAXPBCh6E40 +Completed 302 Found in 3.0ms (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"=>"1412996066", "oauth_nonce"=>"7HyCQqZJ1fuYsnSIlJLYSPNkAIDm3Ccl952CAne9Q", "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"=>"KWZ3WuV7MYVqCIuGljSEmn+o89k="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00], ["nonce", "7HyCQqZJ1fuYsnSIlJLYSPNkAIDm3Ccl952CAne9Q"], ["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: 7HyCQqZJ1fuYsnSIlJLYSPNkAIDm3Ccl952CAne9Q\noauth_signature: KWZ3WuV7MYVqCIuGljSEmn+o89k=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996066'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:54:26 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=7HyCQqZJ1fuYsnSIlJLYSPNkAIDm3Ccl952CAne9Q +Completed 302 Found in 2.9ms (ActiveRecord: 0.3ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" 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"=>"1412996066", "oauth_nonce"=>"OrjEqByfBiYObJLaBeaxS13o7VRdj0LFhfum4UxE", "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"=>"1iATkkJkRI/BeZfcCR+LJQDGtJo="} +Completed 200 OK in 0.7ms (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"=>"1412996066", "oauth_nonce"=>"N6yAvJumtqfIdq1tLYvi4MON5liyWQqo5wEsMgy8gIM", "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"=>"jHsNTmFHPLoHMsOvEnrQXh5Msmg="} +Completed 200 OK in 1.3ms (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 1.1ms (Views: 0.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.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.0ms) begin transaction +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) rollback transaction +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +  (0.2ms) begin transaction +Processing by LtiProvider::LtiController#launch as HTML + Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1412996187", "oauth_nonce"=>"jRamWYxaCsRPnWreHTuUGkmeGflwg7GBqKVwfcjKM", "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"=>"cpMsiX9/DB4vYUcjXV53xWN6eU0="} + Rendered text template (0.0ms) +Completed 200 OK in 31.5ms (Views: 25.5ms | ActiveRecord: 1.4ms) +  (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"=>"1412996187", "oauth_nonce"=>"I3EVwD0U5syXND98MFm2j8hV7KMoUXcEXt57WuTnrTE", "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"=>"V4vLLdDY6NsGLQWcTXYX+XcQcro="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00], ["nonce", "I3EVwD0U5syXND98MFm2j8hV7KMoUXcEXt57WuTnrTE"], ["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: I3EVwD0U5syXND98MFm2j8hV7KMoUXcEXt57WuTnrTE\noauth_signature: V4vLLdDY6NsGLQWcTXYX+XcQcro=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996187'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=I3EVwD0U5syXND98MFm2j8hV7KMoUXcEXt57WuTnrTE +Completed 302 Found in 6.3ms (ActiveRecord: 3.2ms) +  (1.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"=>"1412996187", "oauth_nonce"=>"37wL4RvhYPacJUjd8gTpQkQpscZZoHsD0xKdjIvSyE", "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"=>"SlMRgUffSkC2v5vNQyIFAakIvAo="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00], ["nonce", "37wL4RvhYPacJUjd8gTpQkQpscZZoHsD0xKdjIvSyE"], ["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: 37wL4RvhYPacJUjd8gTpQkQpscZZoHsD0xKdjIvSyE\noauth_signature: SlMRgUffSkC2v5vNQyIFAakIvAo=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996187'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=37wL4RvhYPacJUjd8gTpQkQpscZZoHsD0xKdjIvSyE +Completed 302 Found in 2.9ms (ActiveRecord: 0.3ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" LIMIT 1 +  (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"=>"1412996187", "oauth_nonce"=>"tb9oH617YMJX2iYLthADAEhtneNuZvfsD8O4XP5HEQ", "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"=>"ocb2FPh8VcrQEGXchZBLnUGYOd8="} +Completed 200 OK in 1.1ms (Views: 0.2ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1.2ms (Views: 1.0ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.7ms (Views: 0.5ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.9ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 02:46:27.726489', "updated_at" = '2014-10-11 02:56:27.726848', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:51:27.729938') LIMIT 1 +Completed 200 OK in 2.8ms (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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:51:27.737422') LIMIT 1 +  (0.0ms) 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 3.4ms (ActiveRecord: 0.4ms) +  (0.4ms) rollback transaction +  (0.1ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:51:27.747094') LIMIT 1 +  (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 1.9ms (ActiveRecord: 0.4ms) +  (0.0ms) 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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:56:27 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 02:51:27.753608') LIMIT 1 +Completed 200 OK in 0.8ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#configure as XML +Completed 200 OK in 26.5ms (Views: 0.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/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +  (0.2ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML + Rendered /Users/simon/Instructure/projects/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb within layouts/lti_provider/application (0.2ms) +Completed 200 OK in 7.0ms (Views: 6.8ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.6ms (Views: 0.5ms | 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"=>"1412996237", "oauth_nonce"=>"K8Blo7QyQG6RGZPqHAH0kcq3hu8dyE1aEGC6NuPIc", "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"=>"CwYkcxtnriH7ZcpkN1kGW0CJc4Y="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00], ["nonce", "K8Blo7QyQG6RGZPqHAH0kcq3hu8dyE1aEGC6NuPIc"], ["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: K8Blo7QyQG6RGZPqHAH0kcq3hu8dyE1aEGC6NuPIc\noauth_signature: CwYkcxtnriH7ZcpkN1kGW0CJc4Y=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996237'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=K8Blo7QyQG6RGZPqHAH0kcq3hu8dyE1aEGC6NuPIc +Completed 302 Found in 35.2ms (ActiveRecord: 27.5ms) +  (1.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"=>"1412996237", "oauth_nonce"=>"ErczkKq93r92xHONcCLSU7lHMshQFfIAMp2DoWZA", "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"=>"rICpZtli6W/Gl8SSd0THzCH+8PI="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00], ["nonce", "ErczkKq93r92xHONcCLSU7lHMshQFfIAMp2DoWZA"], ["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: ErczkKq93r92xHONcCLSU7lHMshQFfIAMp2DoWZA\noauth_signature: rICpZtli6W/Gl8SSd0THzCH+8PI=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996237'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=ErczkKq93r92xHONcCLSU7lHMshQFfIAMp2DoWZA +Completed 302 Found in 3.9ms (ActiveRecord: 0.5ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" LIMIT 1 +  (0.5ms) rollback transaction +  (0.1ms) begin transaction +Processing by LtiProvider::LtiController#launch as HTML + Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1412996237", "oauth_nonce"=>"I7O8rtajzt7QdNfLEUfD6h3R7nO8qpR5X7HwVfhJ4", "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"=>"EChxOtm97BkprmCvPAyDXs+6tj8="} +Completed 200 OK in 2.7ms (Views: 1.9ms | 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"=>"1412996237", "oauth_nonce"=>"af6PrLAVW38u15mHQK6w2F0P4jjJnlRrd43m8xnYP0", "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"=>"CgHhCUTSksuVTEjOn2wu0k9l4uc="} +Completed 200 OK in 1.6ms (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 1.3ms (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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:52:17.682452') LIMIT 1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.7ms) 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 6.3ms (ActiveRecord: 0.8ms) +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:52:17.693427') LIMIT 1 +  (0.0ms) 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 2.2ms (ActiveRecord: 0.4ms) +  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches"  +  (0.5ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.2ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 02:47:17.700446', "updated_at" = '2014-10-11 02:57:17.700809', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:52:17.703164') LIMIT 1 +Completed 200 OK in 0.8ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:57:17 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 02:52:17.709485') LIMIT 1 +Completed 200 OK in 1.0ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.4ms) 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/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +  (0.4ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML + Rendered /Users/simon/Instructure/projects/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb within layouts/lti_provider/application (0.1ms) +Completed 200 OK in 6.4ms (Views: 6.2ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.7ms (Views: 0.6ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#configure as XML +Completed 200 OK in 1.5ms (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"=>"1412996303", "oauth_nonce"=>"6UoM014A2oR3C7ZzkIps9ZFQ5G8VtAQac1Jnq011kE", "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"=>"9j5QXrXmlcOGdjQZZrLprSahIH4="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.7ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00], ["nonce", "6UoM014A2oR3C7ZzkIps9ZFQ5G8VtAQac1Jnq011kE"], ["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: 6UoM014A2oR3C7ZzkIps9ZFQ5G8VtAQac1Jnq011kE\noauth_signature: 9j5QXrXmlcOGdjQZZrLprSahIH4=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996303'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=6UoM014A2oR3C7ZzkIps9ZFQ5G8VtAQac1Jnq011kE +Completed 302 Found in 13.3ms (ActiveRecord: 5.2ms) +  (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"=>"1412996303", "oauth_nonce"=>"OBr9QU1bsvtPdNiHOluP1DNGkxB1EM2TCyCfz9AkbR4", "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"=>"A0mQQOAHV0gopnn09c7TtVdHRwU="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.6ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00], ["nonce", "OBr9QU1bsvtPdNiHOluP1DNGkxB1EM2TCyCfz9AkbR4"], ["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: OBr9QU1bsvtPdNiHOluP1DNGkxB1EM2TCyCfz9AkbR4\noauth_signature: A0mQQOAHV0gopnn09c7TtVdHRwU=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996303'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=OBr9QU1bsvtPdNiHOluP1DNGkxB1EM2TCyCfz9AkbR4 +Completed 302 Found in 3.9ms (ActiveRecord: 0.6ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" 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"=>"1412996303", "oauth_nonce"=>"BM3QNxUfGlnHJP2iZM6OGFMuGwIAx7bkpnUlccoUjk", "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"=>"UN8x8He3DHrWqvHU0y1HOgmCA/M="} +Completed 200 OK in 2.9ms (Views: 1.9ms | 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"=>"1412996303", "oauth_nonce"=>"gwwZF4LlEIWhc9tPZwSbrdIJYEiYwiwCbK9HJvGjNH8", "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"=>"qL6wCfJL+HW1SVCPFly/s9n01Y8="} +Completed 200 OK in 1.6ms (Views: 0.3ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.1ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:53:23.879365') LIMIT 1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.8ms) 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 5.9ms (ActiveRecord: 0.9ms) +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:53:23.889283') LIMIT 1 +  (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 1.5ms (ActiveRecord: 0.3ms) +  (0.0ms) SELECT COUNT(*) FROM "lti_provider_launches"  +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.2ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 02:48:23.894034', "updated_at" = '2014-10-11 02:58:23.894375', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:53:23.896668') LIMIT 1 +Completed 200 OK in 0.8ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 02:58:23 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 02:53:23.901398') LIMIT 1 +Completed 200 OK in 0.8ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.3ms) 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.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 +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +  (0.2ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 02:58:21.607277') LIMIT 1 + Rendered text template (0.0ms) +Completed 200 OK in 9.3ms (Views: 6.2ms | ActiveRecord: 0.1ms) +  (1.1ms) rollback transaction +  (0.1ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:58:21.624362') LIMIT 1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.8ms) 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 5.0ms (ActiveRecord: 0.9ms) +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:58:21.634356') LIMIT 1 +  (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 1.8ms (ActiveRecord: 0.3ms) +  (0.0ms) 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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.2ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 02:53:21.639698', "updated_at" = '2014-10-11 03:03:21.640018', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 02:58:21.642343') LIMIT 1 +Completed 200 OK in 1.0ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1.4ms (Views: 1.1ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.6ms (Views: 0.5ms | 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"=>"1412996601", "oauth_nonce"=>"jQJRSDDDZYRFhhvfwl97M4IlRjl9yAsUjRsVl3ebIw", "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"=>"lBb72gvEqFL3UodKu12xnX9U9Ho="} +Completed 200 OK in 1.5ms (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"=>"1412996601", "oauth_nonce"=>"oJiPlMllYp6mXe18emUAAyq8HdsiBWubAGQiLAd2U", "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"=>"WjWsf1fN23pPR/RZezs+x7WjX5s="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00], ["nonce", "oJiPlMllYp6mXe18emUAAyq8HdsiBWubAGQiLAd2U"], ["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: oJiPlMllYp6mXe18emUAAyq8HdsiBWubAGQiLAd2U\noauth_signature: WjWsf1fN23pPR/RZezs+x7WjX5s=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996601'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=oJiPlMllYp6mXe18emUAAyq8HdsiBWubAGQiLAd2U +Completed 302 Found in 2.8ms (ActiveRecord: 0.4ms) +  (0.5ms) 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"=>"1412996601", "oauth_nonce"=>"1JAdrzo22oKfsIOgwP6msfaUNnGnbzA4w0HRKvIFw", "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"=>"UOD8WoDbNPUy7+yg4NyaheICStk="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.6ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00], ["nonce", "1JAdrzo22oKfsIOgwP6msfaUNnGnbzA4w0HRKvIFw"], ["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: 1JAdrzo22oKfsIOgwP6msfaUNnGnbzA4w0HRKvIFw\noauth_signature: UOD8WoDbNPUy7+yg4NyaheICStk=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996601'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:03:21 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=1JAdrzo22oKfsIOgwP6msfaUNnGnbzA4w0HRKvIFw +Completed 302 Found in 5.1ms (ActiveRecord: 0.7ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" LIMIT 1 +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#launch as HTML + Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1412996601", "oauth_nonce"=>"9wHnVg94Bcv1AVNNsZDWAfRnDcc5Tcbs2WTtFQ2rFh0", "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"=>"etQeKcB1n3/6zBZgPwDk9eAMJJI="} +Completed 200 OK in 0.7ms (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 1.2ms (Views: 0.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/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +  (0.3ms) 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 +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#launch as HTML + Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1412996973", "oauth_nonce"=>"F2ZJ7j635tSdQP2yww0tklTWkABiwN9eEtB4fl3w", "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"=>"zIT6mCdhj0zL0B7mmH2Kd38ocho="} + Rendered text template (0.0ms) +Completed 200 OK in 7.2ms (Views: 6.5ms | 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"=>"1412996973", "oauth_nonce"=>"YV2r7GEuL9sNXig2mbWgttRuZILmtI6R7AQtUoA", "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"=>"VTJxoIntvO5TvSWgEco2o0ErKJk="} +  (0.1ms) SAVEPOINT active_record_1 + SQL (3.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00], ["nonce", "YV2r7GEuL9sNXig2mbWgttRuZILmtI6R7AQtUoA"], ["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: YV2r7GEuL9sNXig2mbWgttRuZILmtI6R7AQtUoA\noauth_signature: VTJxoIntvO5TvSWgEco2o0ErKJk=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996973'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=YV2r7GEuL9sNXig2mbWgttRuZILmtI6R7AQtUoA +Completed 302 Found in 7.0ms (ActiveRecord: 3.5ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" LIMIT 1 +  (1.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"=>"1412996973", "oauth_nonce"=>"pXYXTd2jvVoNPnL1AAqo5BEzTqc6dGrpRAVKp9ylIw", "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"=>"9yKSmwKRtUz9BvBTI8JgY7Bt5QY="} +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.5ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00], ["nonce", "pXYXTd2jvVoNPnL1AAqo5BEzTqc6dGrpRAVKp9ylIw"], ["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: pXYXTd2jvVoNPnL1AAqo5BEzTqc6dGrpRAVKp9ylIw\noauth_signature: 9yKSmwKRtUz9BvBTI8JgY7Bt5QY=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412996973'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=pXYXTd2jvVoNPnL1AAqo5BEzTqc6dGrpRAVKp9ylIw +Completed 302 Found in 5.3ms (ActiveRecord: 0.6ms) +  (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"=>"1412996973", "oauth_nonce"=>"Seny52UD68aDiRQmJTYpMBi9VARNoc49hEvDcOlQQA", "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"=>"/2x6yDIGENsenGCdcKg3WSgMvXw="} +Completed 200 OK in 1.3ms (Views: 0.2ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.1ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1.9ms (Views: 1.6ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.7ms (Views: 0.6ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#configure as XML +Completed 200 OK in 1.3ms (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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.7ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 02:59:33.794349', "updated_at" = '2014-10-11 03:09:33.794726', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:04:33.798180') LIMIT 1 +Completed 200 OK in 3.7ms (Views: 0.3ms | ActiveRecord: 0.1ms) +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:04:33.806785') LIMIT 1 +  (0.0ms) 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 3.1ms (ActiveRecord: 0.4ms) +  (0.0ms) 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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:04:33.813758') LIMIT 1 +  (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 1.4ms (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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:09:33 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 03:04:33.818949') LIMIT 1 +Completed 200 OK in 0.8ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.4ms) rollback transaction +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.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.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 +Processing by LtiProvider::LtiController#configure as XML +Completed 200 OK in 1.1ms (Views: 0.1ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:14:05 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:14:05 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.9ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 03:04:05.752141', "updated_at" = '2014-10-11 03:14:05.752496', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:09:05.755907') LIMIT 1 +Completed 200 OK in 28.5ms (Views: 25.7ms | ActiveRecord: 0.1ms) +  (1.0ms) rollback transaction +  (0.1ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:14:05 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:14:05 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 03:09:05.791752') LIMIT 1 +Completed 200 OK in 1.0ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:14:05 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:14:05 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:09:05.797173') LIMIT 1 +  (0.0ms) 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 3.8ms (ActiveRecord: 0.4ms) +  (0.0ms) 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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:14:05 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:14:05 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:09:05.805315') LIMIT 1 +  (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 1.6ms (ActiveRecord: 0.3ms) +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1.3ms (Views: 1.1ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.7ms (Views: 0.5ms | 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 +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +  (0.3ms) 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.1ms) 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 1.1ms (Views: 0.1ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 6.2ms (Views: 6.1ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 3.8ms (Views: 3.7ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 03:09:26.169594') LIMIT 1 +Completed 200 OK in 4.9ms (Views: 1.4ms | ActiveRecord: 0.1ms) +  (0.9ms) rollback transaction +  (0.1ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.7ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 03:04:26.180055', "updated_at" = '2014-10-11 03:14:26.180499', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:09:26.184032') LIMIT 1 +Completed 200 OK in 0.9ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:09:26.190336') LIMIT 1 +  (0.0ms) 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 4.2ms (ActiveRecord: 0.4ms) +  (0.0ms) 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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:09:26.198838') LIMIT 1 +  (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 1.4ms (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"=>"1412997266", "oauth_nonce"=>"UWGbqGGRptx0Yh4zs7aKEnSYU0omq555DLEjQBYjsk", "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"=>"aVunKw9WL7OWa6KlxI/F2FIKUa0="} +Completed 200 OK in 1.4ms (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"=>"1412997266", "oauth_nonce"=>"gifRXok3FKOhwqD7IY3NoeDBrQ8uYfyM6wPkiEjKjc", "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"=>"VejLF2G7rLd9EETk8sh6v8rxJac="} +Completed 200 OK in 0.7ms (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"=>"1412997266", "oauth_nonce"=>"4YK09uiM04ODfLmslxf7wvSPoRoG5HaOsY0rZnIzN4", "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"=>"YUbAC48zzKrSCwOp1Hc7CxBcVg4="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.5ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00], ["nonce", "4YK09uiM04ODfLmslxf7wvSPoRoG5HaOsY0rZnIzN4"], ["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: 4YK09uiM04ODfLmslxf7wvSPoRoG5HaOsY0rZnIzN4\noauth_signature: YUbAC48zzKrSCwOp1Hc7CxBcVg4=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412997266'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=4YK09uiM04ODfLmslxf7wvSPoRoG5HaOsY0rZnIzN4 +Completed 302 Found in 4.4ms (ActiveRecord: 0.5ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" LIMIT 1 +  (0.6ms) 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"=>"1412997266", "oauth_nonce"=>"q568AvlvL7t0dfPZLnIUBmNsbQ4MYhG8ddkn8Kczwc", "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"=>"ct9xGwDykza5C+CCPfg6Sv3G7+I="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00], ["nonce", "q568AvlvL7t0dfPZLnIUBmNsbQ4MYhG8ddkn8Kczwc"], ["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: q568AvlvL7t0dfPZLnIUBmNsbQ4MYhG8ddkn8Kczwc\noauth_signature: ct9xGwDykza5C+CCPfg6Sv3G7+I=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412997266'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:14:26 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=q568AvlvL7t0dfPZLnIUBmNsbQ4MYhG8ddkn8Kczwc +Completed 302 Found in 3.2ms (ActiveRecord: 0.4ms) +  (0.5ms) rollback transaction +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.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.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 +Processing by LtiProvider::LtiController#configure as XML +Completed 200 OK in 1.2ms (Views: 0.1ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (3.0ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 +  (0.8ms) UPDATE "lti_provider_launches" SET "created_at" = '2014-10-11 03:07:27.358650', "updated_at" = '2014-10-11 03:17:27.359046', "provider_params" = '--- +custom_canvas_course_id: 1 +custom_canvas_user_id: 2 +tool_consumer_instance_guid: 123abc +' WHERE "lti_provider_launches"."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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:12:27.362411') LIMIT 1 +Completed 200 OK in 28.2ms (Views: 25.6ms | ActiveRecord: 0.1ms) +  (0.6ms) rollback transaction +  (0.1ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:12:27.397798') LIMIT 1 +  (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 4.7ms (ActiveRecord: 0.5ms) +  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches" +  (0.5ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'abcd' AND (created_at > '2014-10-11 03:12:27.407898') LIMIT 1 +  (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 1.6ms (ActiveRecord: 0.3ms) +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00]] +  (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 "lti_provider_launches"."nonce" = 'invalid' AND (created_at > '2014-10-11 03:12:27.413211') LIMIT 1 +Completed 200 OK in 0.7ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#launch as HTML + Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1412997447", "oauth_nonce"=>"NbQ5uijqDR1tE7nTmkg0ZsKLV8jSEFY5UGX5WWCee2s", "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"=>"o9ja3Cqh7apWuz+P7IhHvDa4Ylw="} +Completed 200 OK in 0.9ms (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"=>"1412997447", "oauth_nonce"=>"q71e3BZz9MJ10YvnkkQr6dosOZ5uJ47jHLoGuYhV4I", "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"=>"qVq2BpDYwtNMjqzM3cqYgFlKOLw="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00], ["nonce", "q71e3BZz9MJ10YvnkkQr6dosOZ5uJ47jHLoGuYhV4I"], ["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: q71e3BZz9MJ10YvnkkQr6dosOZ5uJ47jHLoGuYhV4I\noauth_signature: qVq2BpDYwtNMjqzM3cqYgFlKOLw=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412997447'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=q71e3BZz9MJ10YvnkkQr6dosOZ5uJ47jHLoGuYhV4I +Completed 302 Found in 2.8ms (ActiveRecord: 0.4ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" LIMIT 1 +  (0.4ms) 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"=>"1412997447", "oauth_nonce"=>"j8PaXgowMAGAC9M0ARTfYEbC5EYxEuEHP2saeeGyIG8", "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"=>"Mu8h0BWPbNbIhaq9T10TKRaa8nE="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00], ["nonce", "j8PaXgowMAGAC9M0ARTfYEbC5EYxEuEHP2saeeGyIG8"], ["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: j8PaXgowMAGAC9M0ARTfYEbC5EYxEuEHP2saeeGyIG8\noauth_signature: Mu8h0BWPbNbIhaq9T10TKRaa8nE=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412997447'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:17:27 UTC +00:00]] +  (0.1ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=j8PaXgowMAGAC9M0ARTfYEbC5EYxEuEHP2saeeGyIG8 +Completed 302 Found in 3.8ms (ActiveRecord: 0.4ms) +  (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"=>"1412997447", "oauth_nonce"=>"OPG97DS02VudFPCIntKc6uzzNYOxVd0D5khpZzj6OE", "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"=>"PxX69NaKvVYue/jrhgDZi6FuSS4="} +Completed 200 OK in 1.1ms (Views: 0.2ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1.2ms (Views: 1.0ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 0.5ms (Views: 0.4ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +  (0.3ms) 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.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 +Processing by LtiProvider::LtiController#configure as XML +Completed 200 OK in 1ms (Views: 0.1ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 8ms (Views: 8.3ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1ms (Views: 0.6ms | 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"=>"1412998760", "oauth_nonce"=>"ipBW6sAoOQBButYCQar8D4oxrfaFKANDof2v163HMqI", "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"=>"QSZm/QZenW4oSLwNUmpIUGsW7Nk="} +Completed 200 OK in 2ms (Views: 1.3ms | 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"=>"1412998760", "oauth_nonce"=>"sivpkcwIZHEWPeisdhmTMh1aKyltVg5HK9Pc5cRazk", "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"=>"08vh3dWMEfodc8UG2JcrTqYQbc4="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (26.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:39:20 UTC +00:00], ["nonce", "sivpkcwIZHEWPeisdhmTMh1aKyltVg5HK9Pc5cRazk"], ["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: sivpkcwIZHEWPeisdhmTMh1aKyltVg5HK9Pc5cRazk\noauth_signature: 08vh3dWMEfodc8UG2JcrTqYQbc4=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412998760'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:39:20 UTC +00:00]] +  (0.1ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=sivpkcwIZHEWPeisdhmTMh1aKyltVg5HK9Pc5cRazk +Completed 302 Found in 30ms (ActiveRecord: 26.3ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1 +  (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"=>"1412998760", "oauth_nonce"=>"89viYH9ztPf8BQF4y9uaKBO2yifhaR1LQ3v5vZqZvU", "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"=>"T/u6e/LdKRnDeEGsSLiJ3wYDMQo="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:39:20 UTC +00:00], ["nonce", "89viYH9ztPf8BQF4y9uaKBO2yifhaR1LQ3v5vZqZvU"], ["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: 89viYH9ztPf8BQF4y9uaKBO2yifhaR1LQ3v5vZqZvU\noauth_signature: T/u6e/LdKRnDeEGsSLiJ3wYDMQo=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412998760'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:39:20 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=89viYH9ztPf8BQF4y9uaKBO2yifhaR1LQ3v5vZqZvU +Completed 302 Found in 4ms (ActiveRecord: 0.4ms) +  (0.5ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#launch as HTML + Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1412998760", "oauth_nonce"=>"OO9mxEVp0hL6AIfRu1lgOYfGjbJmYLH8w7aoaVS1XSg", "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"=>"T2HREqu1Gx2rwDXhd4KkpLNYyL4="} +Completed 200 OK in 1ms (Views: 0.2ms | 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.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) rollback transaction +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +  (0.3ms) 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.0ms) begin transaction +Processing by LtiProvider::LtiController#launch as HTML + Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1412998850", "oauth_nonce"=>"4uoOqswLqUbdxbeNtYoU2BIAHGHEBYsPAdZHxeZWs", "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"=>"epMlS5+dwOiOjaFTa+edyHgLq98="} + Rendered text template (0.0ms) +Completed 200 OK in 8ms (Views: 6.8ms | 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"=>"1412998850", "oauth_nonce"=>"vzRyuX1PIEHHOMsBuu6Q92NNMv0M0eBKd5O3XZe7w", "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"=>"5BJQhh1KMfCfPEADgvjdUH/n2r8="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (25.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00], ["nonce", "vzRyuX1PIEHHOMsBuu6Q92NNMv0M0eBKd5O3XZe7w"], ["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: vzRyuX1PIEHHOMsBuu6Q92NNMv0M0eBKd5O3XZe7w\noauth_signature: 5BJQhh1KMfCfPEADgvjdUH/n2r8=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412998850'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=vzRyuX1PIEHHOMsBuu6Q92NNMv0M0eBKd5O3XZe7w +Completed 302 Found in 29ms (ActiveRecord: 25.2ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1 +  (0.9ms) 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"=>"1412998850", "oauth_nonce"=>"AB9ouncShFB7D8YnFSZW8OGcRqWxE6qCBb56VdChc8", "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"=>"hDPTLzlNUCjVqVcZXBG1T4/PswU="} +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00], ["nonce", "AB9ouncShFB7D8YnFSZW8OGcRqWxE6qCBb56VdChc8"], ["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: AB9ouncShFB7D8YnFSZW8OGcRqWxE6qCBb56VdChc8\noauth_signature: hDPTLzlNUCjVqVcZXBG1T4/PswU=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412998850'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=AB9ouncShFB7D8YnFSZW8OGcRqWxE6qCBb56VdChc8 +Completed 302 Found in 4ms (ActiveRecord: 0.3ms) +  (0.5ms) 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"=>"1412998850", "oauth_nonce"=>"cFPLwPVjWW7Ph0WSullMYKGBcWtuvY8cHaZgqkws9w", "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"=>"aOa74HUIuxMeD0m1asXoR5c71GY="} +Completed 200 OK in 1ms (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 4ms (Views: 0.2ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 2ms (Views: 1.6ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1ms (Views: 0.4ms | ActiveRecord: 0.0ms) +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.8ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "updated_at" = ?, "provider_params" = ? WHERE "lti_provider_launches"."id" = 1 [["created_at", Sat, 11 Oct 2014 03:30:50 UTC +00:00], ["updated_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"]] +  (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 > '2014-10-11 03:35:50.211343') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +Completed 200 OK in 3ms (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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00]] +  (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 > '2014-10-11 03:35:50.218815') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +  (0.0ms) 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 4ms (ActiveRecord: 0.5ms) +  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches" +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00]] +  (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 > '2014-10-11 03:35:50.228066') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.5ms) 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 4ms (ActiveRecord: 0.9ms) +  (0.4ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", Sat, 11 Oct 2014 03:40:50 UTC +00:00]] +  (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 > '2014-10-11 03:35:50.236208') AND "lti_provider_launches"."nonce" = 'invalid' LIMIT 1 +Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.5ms) rollback transaction +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +  (0.3ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML + Rendered /Users/simon/Instructure/projects/lti_provider_engine/app/views/lti_provider/lti/cookie_test.html.erb within layouts/lti_provider/application (0.2ms) +Completed 200 OK in 38ms (Views: 37.7ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1ms (Views: 0.5ms | 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"=>"1412999031", "oauth_nonce"=>"m5smpJNh8fA6HJTVSuGM8sOkUgeaCN6AxkSyJur0oiE", "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"=>"iYD254IaLVrjnm81OR8BZPomMyY="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.5ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", "2014-10-11 03:43:51.132244"], ["nonce", "m5smpJNh8fA6HJTVSuGM8sOkUgeaCN6AxkSyJur0oiE"], ["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: m5smpJNh8fA6HJTVSuGM8sOkUgeaCN6AxkSyJur0oiE\noauth_signature: iYD254IaLVrjnm81OR8BZPomMyY=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412999031'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", "2014-10-11 03:43:51.132244"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=m5smpJNh8fA6HJTVSuGM8sOkUgeaCN6AxkSyJur0oiE +Completed 302 Found in 15ms (ActiveRecord: 1.9ms) +  (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"=>"1412999031", "oauth_nonce"=>"m5yidBHiBBN747hU4ATg0TzKtQc85sjuhk8dtY3oqC4", "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"=>"ouxrlmuvk+z2NvGgI+srs19C42Q="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", "2014-10-11 03:43:51.145076"], ["nonce", "m5yidBHiBBN747hU4ATg0TzKtQc85sjuhk8dtY3oqC4"], ["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: m5yidBHiBBN747hU4ATg0TzKtQc85sjuhk8dtY3oqC4\noauth_signature: ouxrlmuvk+z2NvGgI+srs19C42Q=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1412999031'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", "2014-10-11 03:43:51.145076"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=m5yidBHiBBN747hU4ATg0TzKtQc85sjuhk8dtY3oqC4 +Completed 302 Found in 3ms (ActiveRecord: 0.2ms) + LtiProvider::Launch Load (0.1ms) SELECT "lti_provider_launches".* FROM "lti_provider_launches" ORDER BY "lti_provider_launches"."id" ASC LIMIT 1 +  (0.6ms) rollback transaction +  (0.1ms) begin transaction +Processing by LtiProvider::LtiController#launch as HTML + Parameters: {"oauth_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1412999031", "oauth_nonce"=>"H3QYGgG6M1XWQyYqSVYycNpG12pbfggn2WYCpgPg", "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"=>"6TSQ4AcDrUVY4ds0FZZ+dT0c4pg="} +Completed 200 OK in 3ms (Views: 2.0ms | 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"=>"1412999031", "oauth_nonce"=>"Z1Y8qQvsOCydB1ZGuQ25GoNgemPBX4cc3GPuvxfyQ", "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"=>"MeFxo4WnGFfiQEDPj8+cWh51F20="} +Completed 200 OK in 1ms (Views: 0.2ms | 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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-10-11 03:43:51.201020"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-10-11 03:43:51.201020"]] +  (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 > '2014-10-11 03:38:51.204050') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.8ms) 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 10ms (ActiveRecord: 1.0ms) +  (0.5ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-10-11 03:43:51.216605"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-10-11 03:43:51.216605"]] +  (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 > '2014-10-11 03:38:51.219530') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +  (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 3ms (ActiveRecord: 0.6ms) +  (0.1ms) 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", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-10-11 03:43:51.225774"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-10-11 03:43:51.225774"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "provider_params" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = 1 [["created_at", "2014-10-11 03:33:51.227478"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-10-11 03:43:51.227679"]] +  (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 > '2014-10-11 03:38:51.229999') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +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.1ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-10-11 03:43:51.232680"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-10-11 03:43:51.232680"]] +  (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 > '2014-10-11 03:38:51.234753') AND "lti_provider_launches"."nonce" = 'invalid' LIMIT 1 +Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.3ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#configure as XML +Completed 200 OK in 1ms (Views: 0.1ms | 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.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/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +Connecting to database specified by database.yml +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +  (0.3ms) 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.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.1ms) begin transaction +  (0.0ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#configure as XML +Completed 200 OK in 1ms (Views: 0.1ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 36ms (Views: 36.2ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.1ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1ms (Views: 0.8ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.5ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-11-25 19:53:51.718111"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-11-25 19:53:51.718111"]] +  (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 > '2014-11-25 19:48:51.723954') AND "lti_provider_launches"."nonce" = 'invalid' LIMIT 1 +Completed 200 OK in 9ms (Views: 1.5ms | ActiveRecord: 0.1ms) +  (0.6ms) rollback transaction +  (0.1ms) begin transaction +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-11-25 19:53:51.736084"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-11-25 19:53:51.736084"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.8ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "provider_params" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = 1 [["created_at", "2014-11-25 19:43:51.738197"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-11-25 19:53:51.738454"]] +  (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 > '2014-11-25 19:48:51.741653') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.7ms) rollback transaction +  (0.0ms) begin transaction +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-11-25 19:53:51.745786"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-11-25 19:53:51.745786"]] +  (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 > '2014-11-25 19:48:51.749247') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +  (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 34ms (ActiveRecord: 0.6ms) +  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches" +  (0.8ms) rollback transaction +  (0.1ms) begin transaction +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-11-25 19:53:51.787408"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\n"], ["updated_at", "2014-11-25 19:53:51.787408"]] +  (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 > '2014-11-25 19:48:51.791571') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +  (0.0ms) 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 3ms (ActiveRecord: 0.5ms) +  (0.7ms) 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"=>"1416945231", "oauth_nonce"=>"hgFwAeeIt4Il98g9Ru2xSk9qtubRTcs8kHYdK50Fo", "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"=>"wu7VF0qIfJhsB/iun/E6m95mBGg="} +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_signature_method"=>"HMAC-SHA1", "oauth_timestamp"=>"1416945231", "oauth_nonce"=>"tOvhJwkzVSMccAKhXkn2uiEIpihCNCgM5qwaaF5KHs", "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"=>"TILAcnLOrFCPo4g1o+HVnYbnjkE="} +Completed 200 OK in 1ms (Views: 0.2ms | 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"=>"1416945231", "oauth_nonce"=>"5YfCfBxxOY0KQUYZuZobArjUzxSf20z4eAZwoD8QB8", "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"=>"+hPLRfRgaXVwmm0GGynGxuOIkLo="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", "2014-11-25 19:53:51.819444"], ["nonce", "5YfCfBxxOY0KQUYZuZobArjUzxSf20z4eAZwoD8QB8"], ["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: 5YfCfBxxOY0KQUYZuZobArjUzxSf20z4eAZwoD8QB8\noauth_signature: +hPLRfRgaXVwmm0GGynGxuOIkLo=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1416945231'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", "2014-11-25 19:53:51.819444"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=5YfCfBxxOY0KQUYZuZobArjUzxSf20z4eAZwoD8QB8 +Completed 302 Found in 4ms (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.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"=>"1416945231", "oauth_nonce"=>"MZk5scWUWPPnyax5DdvHxAEz88tnvxgmVFZK60zOziE", "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"=>"8IVA09/a2UzP0cQt6dfKQXd3P2k="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", "2014-11-25 19:53:51.828930"], ["nonce", "MZk5scWUWPPnyax5DdvHxAEz88tnvxgmVFZK60zOziE"], ["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: MZk5scWUWPPnyax5DdvHxAEz88tnvxgmVFZK60zOziE\noauth_signature: 8IVA09/a2UzP0cQt6dfKQXd3P2k=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1416945231'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", "2014-11-25 19:53:51.828930"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=MZk5scWUWPPnyax5DdvHxAEz88tnvxgmVFZK60zOziE +Completed 302 Found in 4ms (ActiveRecord: 0.3ms) +  (0.5ms) rollback transaction +Initializing LTI key and secret using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti.yml +Initializing LTI XML config using configuration in /Users/simon/Instructure/projects/lti_provider_engine/spec/dummy/config/lti_xml.yml +  (0.3ms) 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.1ms) 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 1ms (Views: 0.1ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 37ms (Views: 37.0ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.0ms) begin transaction +Processing by LtiProvider::LtiController#cookie_test as HTML +Completed 200 OK in 1ms (Views: 1.0ms | ActiveRecord: 0.0ms) +  (0.1ms) rollback transaction +  (0.1ms) begin transaction +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.4ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-11-25 19:55:44.315678"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["updated_at", "2014-11-25 19:55:44.315678"]] +  (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 > '2014-11-25 19:50:44.322850') AND "lti_provider_launches"."nonce" = 'invalid' LIMIT 1 +Completed 200 OK in 8ms (Views: 1.2ms | ActiveRecord: 0.1ms) +  (0.9ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-11-25 19:55:44.333440"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["updated_at", "2014-11-25 19:55:44.333440"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.9ms) UPDATE "lti_provider_launches" SET "created_at" = ?, "provider_params" = ?, "updated_at" = ? WHERE "lti_provider_launches"."id" = 1 [["created_at", "2014-11-25 19:45:44.335403"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["updated_at", "2014-11-25 19:55:44.335642"]] +  (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 > '2014-11-25 19:50:44.338866') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.1ms) +  (0.6ms) rollback transaction +  (0.0ms) begin transaction +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-11-25 19:55:44.342255"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["updated_at", "2014-11-25 19:55:44.342255"]] +  (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 > '2014-11-25 19:50:44.345490') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +  (0.0ms) 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 30ms (ActiveRecord: 0.5ms) +  (0.1ms) SELECT COUNT(*) FROM "lti_provider_launches" +  (0.7ms) rollback transaction +  (0.0ms) begin transaction +  (0.1ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://canvas"], ["created_at", "2014-11-25 19:55:44.378753"], ["nonce", "abcd"], ["provider_params", "---\ncustom_canvas_course_id: 1\ncustom_canvas_user_id: 2\ntool_consumer_instance_guid: 123abc\next_roles: student\n"], ["updated_at", "2014-11-25 19:55:44.378753"]] +  (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 > '2014-11-25 19:50:44.382118') AND "lti_provider_launches"."nonce" = 'abcd' LIMIT 1 +  (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 2ms (ActiveRecord: 0.4ms) +  (0.6ms) 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"=>"1416945344", "oauth_nonce"=>"qkjr2snuEmgy37j01QGv3R4POfE4evZkY5QDvbAC7o", "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"=>"MJf6bU5jYltvp6M1BOL6i7jlK9M="} +Completed 200 OK in 2ms (Views: 0.2ms | 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"=>"1416945344", "oauth_nonce"=>"Qnwm8qGIcTLsyM0PNJOT0EtFYbLjcWSRQn7WYu9hE0", "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"=>"r8XzLH5iq9HDOr/Mbcf6Oji1YhI="} +Completed 200 OK in 1ms (Views: 0.3ms | 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"=>"1416945344", "oauth_nonce"=>"D2bsTX4WLWncEwPH1TA2AEgDuSl1rdEjvcebQcftVI", "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"=>"KqgEpAx+d1crRLgH6jC7oVWdB98="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.3ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", "2014-11-25 19:55:44.406498"], ["nonce", "D2bsTX4WLWncEwPH1TA2AEgDuSl1rdEjvcebQcftVI"], ["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: D2bsTX4WLWncEwPH1TA2AEgDuSl1rdEjvcebQcftVI\noauth_signature: KqgEpAx+d1crRLgH6jC7oVWdB98=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1416945344'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", "2014-11-25 19:55:44.406498"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=D2bsTX4WLWncEwPH1TA2AEgDuSl1rdEjvcebQcftVI +Completed 302 Found in 4ms (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.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"=>"1416945344", "oauth_nonce"=>"ZGPvV4gwXerMzzlENVRfU6RmPM1mrt45rb99TBaE", "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"=>"f4XaeXYBH/+moYOlOdFXoQ5gKMA="} +  (0.0ms) SAVEPOINT active_record_1 + SQL (0.2ms) INSERT INTO "lti_provider_launches" ("canvas_url", "created_at", "nonce", "provider_params", "updated_at") VALUES (?, ?, ?, ?, ?) [["canvas_url", "http://test.canvas"], ["created_at", "2014-11-25 19:55:44.415862"], ["nonce", "ZGPvV4gwXerMzzlENVRfU6RmPM1mrt45rb99TBaE"], ["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: ZGPvV4gwXerMzzlENVRfU6RmPM1mrt45rb99TBaE\noauth_signature: f4XaeXYBH/+moYOlOdFXoQ5gKMA=\noauth_signature_method: HMAC-SHA1\noauth_timestamp: '1416945344'\noauth_version: '1.0'\ncustom_canvas_user_id: '1'\n"], ["updated_at", "2014-11-25 19:55:44.415862"]] +  (0.0ms) RELEASE SAVEPOINT active_record_1 +Redirected to http://test.host/cookie_test?nonce=ZGPvV4gwXerMzzlENVRfU6RmPM1mrt45rb99TBaE +Completed 302 Found in 3ms (ActiveRecord: 0.3ms) +  (0.4ms) rollback transaction