Connecting to database specified by database.yml  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d3595"]]  (17.4ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d39089"]]  (11.8ms) commit transaction WARNING: Can't mass-assign protected attributes: uid, name, permissions Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d3595"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 7.4ms (Views: 6.7ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d38196"]]  (13.5ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d37503"]]  (24.3ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d38196"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d38196' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "email" = 'user@domain.com', "name" = 'Joshua Marshall', "permissions" = '--- - signin - new permission ', "organisation_slug" = 'justice-league', "organisation_content_id" = 'aae1319e-5788-4677-998c-f1a53af528d0' WHERE "users"."id" = 3  (11.6ms) commit transaction Completed 200 OK in 20.4ms (ActiveRecord: 12.2ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 3]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d36528"]]  (11.1ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d35643"]]  (9.3ms) commit transaction WARNING: Can't mass-assign protected attributes: uid, name, permissions Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d36528"} Completed 403 Forbidden in 1.6ms (Views: 1.0ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d32812"]]  (12.4ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d35215"]]  (12.6ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'nonexistent-user' LIMIT 1 Completed 200 OK in 1.0ms (ActiveRecord: 0.2ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d34415"]]  (13.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d34354"]]  (12.6ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d34415"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d34415' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 't', "permissions" = '--- - signin ' WHERE "users"."id" = 9  (9.9ms) commit transaction Completed 200 OK in 12.9ms (ActiveRecord: 10.4ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 9]] User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' LIMIT 1 User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'user@example.com' LIMIT 1  (0.0ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", nil], ["email", "user@example.com"], ["name", "A Name"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["organisation_slug", "hmrc"], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "asd"]]  (9.6ms) commit transaction User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (11.3ms) commit transaction Started GET "/" for 127.0.0.1 at 2016-06-22 08:16:03 +0000 Processing by ExampleController#index as HTML Completed 200 OK in 2.1ms (Views: 1.7ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:03 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.9ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:03 +0000 Started GET "/auth/gds/callback?code=e685d39e7d65a438a93103bbd342528b792ed1f944e13873b420dfd5b19d49b2&state=99ba881af5d2047ce529ea7bdc9d560f3fae35a6b00631ad" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"e685d39e7d65a438a93103bbd342528b792ed1f944e13873b420dfd5b19d49b2", "state"=>"99ba881af5d2047ce529ea7bdc9d560f3fae35a6b00631ad"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1 User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "test@example-client.com"], ["name", "Test User"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "integration-uid"]]  (17.4ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 'f', "permissions" = '--- - signin ' WHERE "users"."id" = 12  (18.6ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 46.6ms (ActiveRecord: 37.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 2.6ms (Views: 0.5ms | ActiveRecord: 0.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0.9ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Started GET "/auth/gds/callback?code=d2b70e7165151d5992a113d0294011208c2afebf08074157c417cab50ba23fda&state=96a6ff1f8ebb9fb87fc0adcfaa5573f6789e9fb71a485ff0" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"d2b70e7165151d5992a113d0294011208c2afebf08074157c417cab50ba23fda", "state"=>"96a6ff1f8ebb9fb87fc0adcfaa5573f6789e9fb71a485ff0"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (26.3ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (15.6ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 66.4ms (ActiveRecord: 43.1ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 2.3ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Started GET "/auth/gds/callback?code=8444e6f8e7ff87ac3b9ee146a98b90d39c8fcd7e093e96fa2d28fcaa6e38ab3b&state=2925efc70e8b7d99a915e7259405f1ce52930dccd9a6d0d1" for 127.0.0.1 at 2016-06-22 08:16:16 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"8444e6f8e7ff87ac3b9ee146a98b90d39c8fcd7e093e96fa2d28fcaa6e38ab3b", "state"=>"2925efc70e8b7d99a915e7259405f1ce52930dccd9a6d0d1"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (16.3ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (29.7ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 55.4ms (ActiveRecord: 47.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 2.8ms (Views: 0.4ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Started GET "/auth/gds/callback?code=f14146e9752427e18f2c29b9c360c4ee60224b297c52c7a8fa36a9e28b904567&state=3f27166a94c9578f49c30981cc943f807c46f71b922e2d67" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"f14146e9752427e18f2c29b9c360c4ee60224b297c52c7a8fa36a9e28b904567", "state"=>"3f27166a94c9578f49c30981cc943f807c46f71b922e2d67"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (17.1ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (13.7ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 37.8ms (ActiveRecord: 31.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.7ms (Views: 0.4ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Started GET "/auth/gds/callback?code=6139faf8bdbae7f6a55251b390884455a099767d52a508f84a64271d53949448&state=b9b2a6ffb8f9d1b307285c363321d90b92d80290349b320c" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"6139faf8bdbae7f6a55251b390884455a099767d52a508f84a64271d53949448", "state"=>"b9b2a6ffb8f9d1b307285c363321d90b92d80290349b320c"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (23.8ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (22.7ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 53.6ms (ActiveRecord: 47.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 2.5ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Started GET "/auth/gds/callback?code=dd15a7aebb986a8fcecb6fb43dbd18d5a5e91388c1d0d5c91257142633aa5f60&state=9103ea2077dfc2b2a13aae213e8fd6ec513bcb902774cc58" for 127.0.0.1 at 2016-06-22 08:16:17 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"dd15a7aebb986a8fcecb6fb43dbd18d5a5e91388c1d0d5c91257142633aa5f60", "state"=>"9103ea2077dfc2b2a13aae213e8fd6ec513bcb902774cc58"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (8.8ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (9.3ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 25.2ms (ActiveRecord: 18.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.8ms (Views: 0.5ms | ActiveRecord: 0.2ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 't', "permissions" = '--- - signin ' WHERE "users"."id" = 12  (21.9ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Authenticating with gds_sso strategy Completed in 1.4ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Started GET "/auth/gds/callback?code=5da333730f298955acc44ed3217bb1ec1384b62268b9daec9dec79a1a97f8bcb&state=bf50738e29ecbb0629631bbf6f5cba416e1057daf24a004b" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"5da333730f298955acc44ed3217bb1ec1384b62268b9daec9dec79a1a97f8bcb", "state"=>"bf50738e29ecbb0629631bbf6f5cba416e1057daf24a004b"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (12.6ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 'f', "permissions" = '--- - signin ' WHERE "users"."id" = 12  (10.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 29.8ms (ActiveRecord: 23.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.4ms (Views: 0.2ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Started GET "/auth/gds/callback?code=77e4f826fcf6bec7d2a1c292c33df404dd27ed8970243df2d4ab48279c8fef1b&state=4dcff012644a5adf2ae0bdfa69f7ae04e0637ebc1c8d9787" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"77e4f826fcf6bec7d2a1c292c33df404dd27ed8970243df2d4ab48279c8fef1b", "state"=>"4dcff012644a5adf2ae0bdfa69f7ae04e0637ebc1c8d9787"} Authenticating with gds_sso strategy User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (18.2ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (16.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 44.6ms (ActiveRecord: 35.7ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.9ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:21:18 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.4ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:21:18 +0000 Started GET "/auth/gds/callback?code=e14a7202c9a8f50443bb19ff9dd81ebf7753076e646a073a7e7838829775918c&state=c82deba74001ba07bb3ace3aa51ae1a2299eb4d43f91c969" for 127.0.0.1 at 2016-06-23 04:21:18 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"e14a7202c9a8f50443bb19ff9dd81ebf7753076e646a073a7e7838829775918c", "state"=>"c82deba74001ba07bb3ace3aa51ae1a2299eb4d43f91c969"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (9.6ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (9.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 26.5ms (ActiveRecord: 19.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:21:18 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.9ms (Views: 0.2ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:18 +0000 Started GET "/auth/gds/callback?code=8905db99e7fc7c2fddbbdf91e6602fc5b0ebc2f4f1e0f187069cd33f08664604&state=400c09904fc82defb52fe481b4f62b4e47ecea625b97162c" for 127.0.0.1 at 2016-06-22 08:16:19 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"8905db99e7fc7c2fddbbdf91e6602fc5b0ebc2f4f1e0f187069cd33f08664604", "state"=>"400c09904fc82defb52fe481b4f62b4e47ecea625b97162c"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (21.6ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (14.6ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 43.9ms (ActiveRecord: 37.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:19 +0000 Processing by ExampleController#restricted as HTML User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 2.8ms (Views: 0.4ms | ActiveRecord: 0.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:11:19 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 3.0ms (Views: 0.6ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:19 +0000 Processing by ExampleController#restricted as JSON Completed in 28.8ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:19 +0000 Processing by ExampleController#restricted as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "disabled" = NULL, "permissions" = '--- - signin ' WHERE "users"."id" = 12  (25.8ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (32.1ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.5ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (38.7ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (26.4ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (30.7ms) commit transaction Completed 200 OK in 285.9ms (Views: 0.5ms | ActiveRecord: 157.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:19 +0000 Processing by ExampleController#restricted as JSON Completed in 26.9ms Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:19 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (14.6ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (13.0ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (14.0ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (18.7ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (18.0ms) commit transaction Completed 200 OK in 212.9ms (Views: 0.4ms | ActiveRecord: 81.5ms)  (0.2ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d34368"]]  (15.6ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d35790"]]  (13.7ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d34368"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.4ms) Completed 403 Forbidden in 8ms (Views: 7.8ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d37550"]]  (15.3ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d37062"]]  (34.6ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d37550"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d37550' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "email" = ?, "name" = ?, "organisation_content_id" = ?, "organisation_slug" = ?, "permissions" = ? WHERE "users"."id" = 3 [["email", "user@domain.com"], ["name", "Joshua Marshall"], ["organisation_content_id", "aae1319e-5788-4677-998c-f1a53af528d0"], ["organisation_slug", "justice-league"], ["permissions", "---\n- signin\n- new permission\n"]]  (18.7ms) commit transaction Completed 200 OK in 31ms (ActiveRecord: 19.4ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 3]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d39530"]]  (64.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d35117"]]  (25.3ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d39530"} Completed 403 Forbidden in 2ms (Views: 1.5ms | ActiveRecord: 0.0ms)  (0.2ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d35209"]]  (16.8ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d37562"]]  (14.5ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d35209"} User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d35209' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 7 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "t"]]  (17.3ms) commit transaction Completed 200 OK in 22ms (ActiveRecord: 18.2ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 7]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d34307"]]  (22.1ms) commit transaction  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d36132"]]  (22.5ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'nonexistent-user' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (ActiveRecord: 0.2ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' ORDER BY "users"."id" ASC LIMIT 1 User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'user@example.com' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "uid") VALUES (?, ?, ?, ?, ?, ?, ?) [["disabled", nil], ["email", "user@example.com"], ["name", "A Name"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["organisation_slug", "hmrc"], ["permissions", "---\n- signin\n"], ["uid", "asd"]]  (15.6ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 11 [["permissions", "---\n- signin\n"]]  (16.9ms) commit transaction Started GET "/" for 127.0.0.1 at 2016-06-22 08:16:44 +0000 Processing by ExampleController#index as HTML Completed 200 OK in 2ms (Views: 1.5ms | ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:44 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 9ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:44 +0000 Started GET "/auth/gds/callback?code=aac72f5f4561817bdb729f6f1ebd6391606832c145660d1feabaafd8c5eb68f3&state=90adba0e21957b61d12d395f229136f6b5352482b1fe5606" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"aac72f5f4561817bdb729f6f1ebd6391606832c145660d1feabaafd8c5eb68f3", "state"=>"90adba0e21957b61d12d395f229136f6b5352482b1fe5606"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1 User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' ORDER BY "users"."id" ASC LIMIT 1  (0.3ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "test@example-client.com"], ["name", "Test User"], ["permissions", "---\n- signin\n"], ["uid", "integration-uid"]]  (18.0ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "f"]]  (14.4ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 41ms (ActiveRecord: 33.7ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Started GET "/auth/gds/callback?code=c2db313e3bc62d907b0d7a94399287bc3dd363030b54c7341974305085fb67fb&state=5ff2702d89977e1c9c77eab9400def64ed69d224fb2e0fa2" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"c2db313e3bc62d907b0d7a94399287bc3dd363030b54c7341974305085fb67fb", "state"=>"5ff2702d89977e1c9c77eab9400def64ed69d224fb2e0fa2"} Authenticating with gds_sso strategy User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.5ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (15.4ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (15.7ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 41ms (ActiveRecord: 32.6ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Started GET "/auth/gds/callback?code=ede43e081174f3111b9273dbee40458cef41c788f3c7af6235c0f5f6429b6d8f&state=ab740cd29df540c238cca56c00282a94ebaf30b24279e180" for 127.0.0.1 at 2016-06-22 08:16:57 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"ede43e081174f3111b9273dbee40458cef41c788f3c7af6235c0f5f6429b6d8f", "state"=>"ab740cd29df540c238cca56c00282a94ebaf30b24279e180"} Authenticating with gds_sso strategy User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (32.2ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (16.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 58ms (ActiveRecord: 50.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Started GET "/auth/gds/callback?code=8079ec9a4b17e6996a9d6aa9a5649c957f422a934846cc4fb135d3cb2a11dff9&state=9f2c5f8b42e570764590e2c741ebdab854a1eae69baf031c" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"8079ec9a4b17e6996a9d6aa9a5649c957f422a934846cc4fb135d3cb2a11dff9", "state"=>"9f2c5f8b42e570764590e2c741ebdab854a1eae69baf031c"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (16.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (11.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 34ms (ActiveRecord: 28.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.4ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Started GET "/auth/gds/callback?code=83585304185b47f0435ecfbe0c58655948d01e4b29c6d478c40257afbe4427cf&state=ab93f81f29b710eb7359ddc684fee9c66fbbe36d7c1123ff" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"83585304185b47f0435ecfbe0c58655948d01e4b29c6d478c40257afbe4427cf", "state"=>"ab93f81f29b710eb7359ddc684fee9c66fbbe36d7c1123ff"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.2ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (17.3ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 39ms (ActiveRecord: 31.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Processing by ExampleController#restricted as HTML User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.7ms | ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:58 +0000 Started GET "/auth/gds/callback?code=9fad0fb3b5c007e67d304695db3e031c0e084db4bfe7158d7a96ee65639453cc&state=bdae6de2f2d7fc965ad9aa21d632a7cade94d4956543975e" for 127.0.0.1 at 2016-06-22 08:16:59 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"9fad0fb3b5c007e67d304695db3e031c0e084db4bfe7158d7a96ee65639453cc", "state"=>"bdae6de2f2d7fc965ad9aa21d632a7cade94d4956543975e"} Authenticating with gds_sso strategy User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (14.7ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 38ms (ActiveRecord: 29.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:59 +0000 Processing by ExampleController#restricted as HTML User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.7ms | ActiveRecord: 0.6ms) User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "t"]]  (53.5ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:59 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Authenticating with gds_sso strategy Completed in 2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:59 +0000 Started GET "/auth/gds/callback?code=425890eb972369183349be449436b122302c42a8a30ea4637e41d008cd034dc1&state=2884c1162537fcd60bb2c34d66f18743339beb6f9407beba" for 127.0.0.1 at 2016-06-22 08:16:59 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"425890eb972369183349be449436b122302c42a8a30ea4637e41d008cd034dc1", "state"=>"2884c1162537fcd60bb2c34d66f18743339beb6f9407beba"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (15.5ms) commit transaction  (0.2ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "f"]]  (12.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 36ms (ActiveRecord: 29.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:59 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:16:59 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:16:59 +0000 Started GET "/auth/gds/callback?code=a559ba55877e6173bf2d56ffe6099b89051c51d888dd23bbeb93447d0aa62aea&state=5b1d111bd81c9c30e71b8a6c0fb12f7527a4ae3c23ce004c" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"a559ba55877e6173bf2d56ffe6099b89051c51d888dd23bbeb93447d0aa62aea", "state"=>"5b1d111bd81c9c30e71b8a6c0fb12f7527a4ae3c23ce004c"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (11.3ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.6ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 33ms (ActiveRecord: 26.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.6ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:22:00 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:22:00 +0000 Started GET "/auth/gds/callback?code=4318c27d1c6846445576d5a29db529292ee443b435839aacd37237efc670a01b&state=23885c963f8e5c28d308909cfe278f25582c32a9a94dcf02" for 127.0.0.1 at 2016-06-23 04:22:00 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"4318c27d1c6846445576d5a29db529292ee443b435839aacd37237efc670a01b", "state"=>"23885c963f8e5c28d308909cfe278f25582c32a9a94dcf02"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.9ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (17.3ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 39ms (ActiveRecord: 32.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:22:00 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Started GET "/auth/gds/callback?code=58aa34214baa6653cc9c3c7bd049d7c65fa67aaaa8f8fc1f4898425c6bb62ed1&state=39f54890f04a887721497c911e70355ce7ad66433ebfc535" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"58aa34214baa6653cc9c3c7bd049d7c65fa67aaaa8f8fc1f4898425c6bb62ed1", "state"=>"39f54890f04a887721497c911e70355ce7ad66433ebfc535"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (35.9ms) commit transaction  (0.2ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (17.6ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 63ms (ActiveRecord: 54.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:12:00 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.6ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Processing by ExampleController#restricted as JSON Completed in 32ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Processing by ExampleController#restricted as JSON Completed in 21ms Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:17:00 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "disabled" = ?, "permissions" = ? WHERE "users"."id" = 12 [["disabled", nil], ["permissions", "---\n- signin\n"]]  (14.7ms) commit transaction User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (20.3ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (11.6ms) commit transaction User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (8.0ms) commit transaction Completed 200 OK in 162ms (Views: 0.5ms | ActiveRecord: 69.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:01 +0000 Processing by ExampleController#restricted as JSON User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (12.0ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (12.4ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.8ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (18.6ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (18.5ms) commit transaction Completed 200 OK in 188ms (Views: 0.6ms | ActiveRecord: 78.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:26 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 12ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:26 +0000 Started GET "/auth/gds/callback?code=277f32a034a92e04c467012425559d301ae3491acfdcc1fd8a2e8f710904948f&state=a126895ac77131a11ab183e9dca0aa628a790f340e83f6ae" for 127.0.0.1 at 2016-06-22 08:17:38 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"277f32a034a92e04c467012425559d301ae3491acfdcc1fd8a2e8f710904948f", "state"=>"a126895ac77131a11ab183e9dca0aa628a790f340e83f6ae"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]] User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "test@example-client.com"]]  (0.2ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "integration-uid"], ["email", "test@example-client.com"], ["name", "Test User"], ["permissions", "---\n- signin\n"]]  (23.1ms) commit transaction  (0.2ms) begin transaction SQL (0.4ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "f"], ["id", 1]]  (16.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 80ms (ActiveRecord: 41.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:38 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 9ms (Views: 5.6ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:38 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:38 +0000 Started GET "/auth/gds/callback?code=a1efade75fbdace0b9e187914ebae06bc92a9d699c42303207dd5ecc23b3e128&state=014c882d8196d6023ffb054819ffdc4ee7b1d0669d06e7a9" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"a1efade75fbdace0b9e187914ebae06bc92a9d699c42303207dd5ecc23b3e128", "state"=>"014c882d8196d6023ffb054819ffdc4ee7b1d0669d06e7a9"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 7ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.2ms) Started GET "/" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by ExampleController#index as HTML Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.6ms | ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Started GET "/auth/gds/callback?code=d34067d0319d80bff3c3816c4c88035548d0d783c714b0ad31ae43533f8e55a3&state=efb9d52cf48dc14e1e00ba5e78c444a1f04d13aacf4b3398" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"d34067d0319d80bff3c3816c4c88035548d0d783c714b0ad31ae43533f8e55a3", "state"=>"efb9d52cf48dc14e1e00ba5e78c444a1f04d13aacf4b3398"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 7ms (ActiveRecord: 0.6ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Started GET "/auth/gds/callback?code=8a6df280bfc8ae2da3b9014f5f774b80515769ce2a4edabddfaa2a9565fc2937&state=1fa59c1ac163f9f45fdb4baeaeaeab41db393791d4bacde6" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"8a6df280bfc8ae2da3b9014f5f774b80515769ce2a4edabddfaa2a9565fc2937", "state"=>"1fa59c1ac163f9f45fdb4baeaeaeab41db393791d4bacde6"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 7ms (ActiveRecord: 0.6ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Started GET "/auth/gds/callback?code=57d77397d6b6a6e56fc0ec1b48583296487e682f7d5bc7f403c2a8a59dfa49a9&state=5727d7956519ccf83155af18d04b1d54d569d2a9100b01fb" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"57d77397d6b6a6e56fc0ec1b48583296487e682f7d5bc7f403c2a8a59dfa49a9", "state"=>"5727d7956519ccf83155af18d04b1d54d569d2a9100b01fb"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.4ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 8ms (ActiveRecord: 0.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:39 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Started GET "/auth/gds/callback?code=d69c9368533b859149040f63b1a0b5e5d7109da2cf190258e9502921868a5f5c&state=bd1774e249b0806d630505ceb7e947df9a3511f813474f92" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"d69c9368533b859149040f63b1a0b5e5d7109da2cf190258e9502921868a5f5c", "state"=>"bd1774e249b0806d630505ceb7e947df9a3511f813474f92"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.2ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 9ms (ActiveRecord: 0.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.5ms | ActiveRecord: 0.2ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "test@example-client.com"]]  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 1]]  (15.0ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Authenticating with gds_sso strategy Completed in 2ms (ActiveRecord: 0.1ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Started GET "/auth/gds/callback?code=43a022b58a38b7b6d3a546b6bee57115c7f4d294a5ce6bf36bbbdf3956393d65&state=ea61b300b81882c163186d4a87188ec83d3067821a7a5fe4" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"43a022b58a38b7b6d3a546b6bee57115c7f4d294a5ce6bf36bbbdf3956393d65", "state"=>"ea61b300b81882c163186d4a87188ec83d3067821a7a5fe4"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "f"], ["id", 1]]  (11.9ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 18ms (ActiveRecord: 12.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Started GET "/auth/gds/callback?code=1494a1f4663c56bc95ca3e2a44d32993b30ec0a0aced049c9231120211615233&state=fce722e98c298f18750e197d45c538fca0e93e4778b8d92b" for 127.0.0.1 at 2016-06-22 08:17:40 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"1494a1f4663c56bc95ca3e2a44d32993b30ec0a0aced049c9231120211615233", "state"=>"fce722e98c298f18750e197d45c538fca0e93e4778b8d92b"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 6ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.6ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:22:41 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:22:41 +0000 Started GET "/auth/gds/callback?code=951a7b62f62406ccb0689f0a04b3deb0d7e36b1e2faa5ca553549180b24ed8fd&state=84235807fea6b94caacb6261f273ad15ffd9217520faa419" for 127.0.0.1 at 2016-06-23 04:22:41 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"951a7b62f62406ccb0689f0a04b3deb0d7e36b1e2faa5ca553549180b24ed8fd", "state"=>"84235807fea6b94caacb6261f273ad15ffd9217520faa419"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 6ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:22:41 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.1ms) Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Started GET "/auth/gds/callback?code=b8614a4dad6f8032e822d9cca078f0d0a6708e03d7d18957a52335e25036ecd7&state=65e0f93cf038c70ceb90a92bb7f65fffdd3090503ce1ccff" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"b8614a4dad6f8032e822d9cca078f0d0a6708e03d7d18957a52335e25036ecd7", "state"=>"65e0f93cf038c70ceb90a92bb7f65fffdd3090503ce1ccff"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 7ms (ActiveRecord: 0.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.6ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:12:41 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.5ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "disabled" = ? WHERE "users"."id" = ? [["disabled", nil], ["id", 1]]  (10.8ms) commit transaction User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Rendered text template (0.0ms) Completed 200 OK in 107ms (Views: 0.6ms | ActiveRecord: 12.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Processing by ExampleController#restricted as JSON Completed in 27ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Processing by ExampleController#restricted as JSON Completed in 27ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:41 +0000 Processing by ExampleController#restricted as JSON User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.2ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Rendered text template (0.1ms) Completed 200 OK in 134ms (Views: 0.8ms | ActiveRecord: 1.5ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "asd"]] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "user@example.com"]]  (0.1ms) begin transaction SQL (0.6ms) INSERT INTO "users" ("uid", "email", "name", "permissions", "organisation_slug", "organisation_content_id", "disabled") VALUES (?, ?, ?, ?, ?, ?, ?) [["uid", "asd"], ["email", "user@example.com"], ["name", "A Name"], ["permissions", "---\n- signin\n"], ["organisation_slug", "hmrc"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["disabled", nil]]  (15.0ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "asd"]]  (0.1ms) begin transaction  (0.2ms) commit transaction  (0.2ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d39125"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (23.2ms) commit transaction  (0.2ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d38619"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (23.8ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d39125"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.8ms) Completed 403 Forbidden in 8ms (Views: 6.5ms | ActiveRecord: 0.0ms)  (0.2ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d36028"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (15.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32569"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (14.3ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d36028"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d36028"]]  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "email" = ?, "name" = ?, "permissions" = ?, "organisation_slug" = ?, "organisation_content_id" = ? WHERE "users"."id" = ? [["email", "user@domain.com"], ["name", "Joshua Marshall"], ["permissions", "---\n- signin\n- new permission\n"], ["organisation_slug", "justice-league"], ["organisation_content_id", "aae1319e-5788-4677-998c-f1a53af528d0"], ["id", 5]]  (25.3ms) commit transaction Completed 200 OK in 31ms (ActiveRecord: 25.9ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 5]]  (0.2ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d36851"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (16.7ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d33890"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (13.9ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "nonexistent-user"]] Completed 200 OK in 2ms (ActiveRecord: 0.2ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32568"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (16.3ms) commit transaction  (0.2ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d33262"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (41.8ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d32568"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.5ms) Completed 403 Forbidden in 2ms (Views: 1.6ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d31801"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (13.5ms) commit transaction  (0.2ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32205"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (14.4ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d31801"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d31801"]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 11]]  (20.1ms) commit transaction Completed 200 OK in 24ms (ActiveRecord: 20.6ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 11]] Connecting to database specified by database.yml  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d32575"]]  (13.7ms) commit transaction  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d32530"]]  (16.9ms) commit transaction WARNING: Can't mass-assign protected attributes: uid, name, permissions Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d32575"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 9.5ms (Views: 8.8ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d31074"]]  (10.9ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d34592"]]  (15.6ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d31074"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d31074' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "remotely_signed_out" = 't', "permissions" = '--- - signin ' WHERE "users"."id" = 3  (21.6ms) commit transaction Completed 200 OK in 31.9ms (ActiveRecord: 22.3ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 3]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d39703"]]  (10.4ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d3777"]]  (7.3ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'nonexistent-user' LIMIT 1 Completed 200 OK in 1.8ms (ActiveRecord: 0.5ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d31957"]]  (34.4ms) commit transaction  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d37643"]]  (25.7ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d31957"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d31957' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "email" = 'user@domain.com', "name" = 'Joshua Marshall', "permissions" = '--- - signin - new permission ', "organisation_slug" = 'justice-league', "organisation_content_id" = 'aae1319e-5788-4677-998c-f1a53af528d0' WHERE "users"."id" = 7  (13.3ms) commit transaction Completed 200 OK in 17.6ms (ActiveRecord: 13.8ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 7]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d32426"]]  (21.6ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d37062"]]  (11.9ms) commit transaction WARNING: Can't mass-assign protected attributes: uid, name, permissions Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d32426"} Completed 403 Forbidden in 1.3ms (Views: 1.0ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:57 +0000 Processing by ExampleController#restricted as JSON Completed in 130.0ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:57 +0000 Processing by ExampleController#restricted as JSON Completed in 53.7ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:17:57 +0000 Processing by ExampleController#restricted as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1 User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", nil], ["email", "test@example-client.com"], ["name", "Test User"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "integration-uid"]]  (18.7ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (26.5ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (11.0ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.4ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (14.9ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 'f', "permissions" = '--- - signin ' WHERE "users"."id" = 11  (14.8ms) commit transaction Completed 200 OK in 276.5ms (Views: 3.6ms | ActiveRecord: 89.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:17:58 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (13.8ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (13.9ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (27.8ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (13.2ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (11.5ms) commit transaction Completed 200 OK in 189.7ms (Views: 0.4ms | ActiveRecord: 83.6ms) Started GET "/" for 127.0.0.1 at 2016-06-22 08:17:58 +0000 Processing by ExampleController#index as HTML Completed 200 OK in 0.6ms (Views: 0.3ms | ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:17:58 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:17:58 +0000 Started GET "/auth/gds/callback?code=62fc79eb733d3743d5ecb93a0a0fc8eeedcbb9c754d7346cb27e2a4d23ba1f09&state=ca49e46c0babf844935eb0b3dcf1fd10361ba6b7ffb1b8e4" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"62fc79eb733d3743d5ecb93a0a0fc8eeedcbb9c754d7346cb27e2a4d23ba1f09", "state"=>"ca49e46c0babf844935eb0b3dcf1fd10361ba6b7ffb1b8e4"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "disabled" = 'f', "permissions" = '--- - signin ' WHERE "users"."id" = 11  (22.6ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (17.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 46.3ms (ActiveRecord: 40.6ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 3.3ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Started GET "/auth/gds/callback?code=61448665bdc00e3c5a2b7902e60b246a37c9ceedca7075e3bd4dec16f0e666cb&state=3eef208a6710ddc331eb766b47930e456084a20e7e52c1c6" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"61448665bdc00e3c5a2b7902e60b246a37c9ceedca7075e3bd4dec16f0e666cb", "state"=>"3eef208a6710ddc331eb766b47930e456084a20e7e52c1c6"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (8.3ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (10.5ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 24.7ms (ActiveRecord: 19.6ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.8ms (Views: 0.3ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Started GET "/auth/gds/callback?code=8b351fbfca206f380e5317365eb34b5ba98f04874aeb816cc7bef609b762b9ea&state=530751ef565f79aae45bc6ff46914f318f399b0b66b973de" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"8b351fbfca206f380e5317365eb34b5ba98f04874aeb816cc7bef609b762b9ea", "state"=>"530751ef565f79aae45bc6ff46914f318f399b0b66b973de"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (21.8ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (16.6ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 44.8ms (ActiveRecord: 39.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.6ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Started GET "/auth/gds/callback?code=7872a387385367fc528483c097ecd2d6765f45e766b04cdab08885c2ad00b72c&state=1dc14d3db135c4a2f5a72d40b5176535fc8c88c6d3c1aa8b" for 127.0.0.1 at 2016-06-22 08:18:10 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"7872a387385367fc528483c097ecd2d6765f45e766b04cdab08885c2ad00b72c", "state"=>"1dc14d3db135c4a2f5a72d40b5176535fc8c88c6d3c1aa8b"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (13.1ms) commit transaction  (0.1ms) begin transaction  (0.4ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (13.0ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 32.5ms (ActiveRecord: 27.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.6ms (Views: 0.4ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Started GET "/auth/gds/callback?code=2e0b489c997c3e6d4c977b7039c17ac4de58571e4b11168eb4a61535a97fd66c&state=7b9f0cff84f4511860ef17d6e48ab9dcc2b287227e293d5d" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"2e0b489c997c3e6d4c977b7039c17ac4de58571e4b11168eb4a61535a97fd66c", "state"=>"7b9f0cff84f4511860ef17d6e48ab9dcc2b287227e293d5d"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (15.5ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (16.4ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 38.0ms (ActiveRecord: 32.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.5ms (Views: 0.4ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Started GET "/auth/gds/callback?code=dbb2f6545c1e5bc07c78134faa3a246f91bd78a7a2c2c3de1b5b8f6422c12583&state=68a6686b962f9af844550b982577b14c3ef0d6e004049c08" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"dbb2f6545c1e5bc07c78134faa3a246f91bd78a7a2c2c3de1b5b8f6422c12583", "state"=>"68a6686b962f9af844550b982577b14c3ef0d6e004049c08"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (9.0ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (8.0ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 23.1ms (ActiveRecord: 17.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.5ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:13:11 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.6ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Started GET "/auth/gds/callback?code=5ca92cef2c2a0252512da20f296debce0e2bd44298143aa7e7e3015ab4d8f755&state=75e4f14e39f796d357dcfe9a4d62c05949a7a224ddebcac2" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"5ca92cef2c2a0252512da20f296debce0e2bd44298143aa7e7e3015ab4d8f755", "state"=>"75e4f14e39f796d357dcfe9a4d62c05949a7a224ddebcac2"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (12.5ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (13.6ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 33.1ms (ActiveRecord: 27.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:11 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.9ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:23:11 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.7ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:23:11 +0000 Started GET "/auth/gds/callback?code=9751eae72718cc9fd6dc80fdefd4f76f0837e4e9b3958e5a2e48093830a1648f&state=ef40f931bbfdd521b1fe0dba09721b1ebf850ea199a7c7e2" for 127.0.0.1 at 2016-06-23 04:23:11 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"9751eae72718cc9fd6dc80fdefd4f76f0837e4e9b3958e5a2e48093830a1648f", "state"=>"ef40f931bbfdd521b1fe0dba09721b1ebf850ea199a7c7e2"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.4ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (16.5ms) commit transaction  (0.2ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (9.3ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 34.7ms (ActiveRecord: 27.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:23:12 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.8ms (Views: 0.2ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:12 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:12 +0000 Started GET "/auth/gds/callback?code=cf6b874c9fc15d2bfd86c11e17419bf3c7f39e945a0d37f05271ac107040d93d&state=99c27a6112eebc9c43ef4b7da06fe9d0e3037ba356a9fea7" for 127.0.0.1 at 2016-06-22 08:18:12 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"cf6b874c9fc15d2bfd86c11e17419bf3c7f39e945a0d37f05271ac107040d93d", "state"=>"99c27a6112eebc9c43ef4b7da06fe9d0e3037ba356a9fea7"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (11.7ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (16.0ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 33.9ms (ActiveRecord: 28.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:12 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.9ms (Views: 0.3ms | ActiveRecord: 0.3ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 't', "permissions" = '--- - signin ' WHERE "users"."id" = 11  (12.4ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:12 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Authenticating with gds_sso strategy Completed in 1.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:12 +0000 Started GET "/auth/gds/callback?code=1383c8de68c7fcb212044ce122e38d0f9490a09e80f65762dfcf02f184600364&state=f60201a9f2787b13af336ae7b2f0d05bbb7af6ba89c9a6cb" for 127.0.0.1 at 2016-06-22 08:18:12 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"1383c8de68c7fcb212044ce122e38d0f9490a09e80f65762dfcf02f184600364", "state"=>"f60201a9f2787b13af336ae7b2f0d05bbb7af6ba89c9a6cb"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 11  (12.7ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "remotely_signed_out" = 'f', "permissions" = '--- - signin ' WHERE "users"."id" = 11  (8.4ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 29.0ms (ActiveRecord: 22.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:12 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.7ms (Views: 0.3ms | ActiveRecord: 0.3ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' LIMIT 1 User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'user@example.com' LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", nil], ["email", "user@example.com"], ["name", "A Name"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["organisation_slug", "hmrc"], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "asd"]]  (11.2ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (10.4ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d38384"]]  (16.3ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d34459"]]  (20.3ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d38384"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 8ms (Views: 7.6ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d38214"]]  (16.6ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d39952"]]  (15.1ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d38214"} User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d38214' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "email" = ?, "name" = ?, "organisation_content_id" = ?, "organisation_slug" = ?, "permissions" = ? WHERE "users"."id" = 3 [["email", "user@domain.com"], ["name", "Joshua Marshall"], ["organisation_content_id", "aae1319e-5788-4677-998c-f1a53af528d0"], ["organisation_slug", "justice-league"], ["permissions", "---\n- signin\n- new permission\n"]]  (21.1ms) commit transaction Completed 200 OK in 34ms (ActiveRecord: 21.9ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 3]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d33912"]]  (22.3ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d36824"]]  (17.5ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d33912"} Completed 403 Forbidden in 2ms (Views: 1.4ms | ActiveRecord: 0.0ms)  (0.2ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d3761"]]  (17.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d35499"]]  (15.0ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'nonexistent-user' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (ActiveRecord: 0.3ms)  (0.2ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d37463"]]  (13.7ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d3220"]]  (26.5ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d37463"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d37463' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 9 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "t"]]  (19.6ms) commit transaction Completed 200 OK in 24ms (ActiveRecord: 20.4ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 9]] User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' ORDER BY "users"."id" ASC LIMIT 1 User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'user@example.com' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "uid") VALUES (?, ?, ?, ?, ?, ?, ?) [["disabled", nil], ["email", "user@example.com"], ["name", "A Name"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["organisation_slug", "hmrc"], ["permissions", "---\n- signin\n"], ["uid", "asd"]]  (24.0ms) commit transaction User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.5ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 11 [["permissions", "---\n- signin\n"]]  (21.8ms) commit transaction Started GET "/" for 127.0.0.1 at 2016-06-22 08:18:36 +0000 Processing by ExampleController#index as HTML Completed 200 OK in 2ms (Views: 1.5ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:36 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 9ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:36 +0000 Started GET "/auth/gds/callback?code=39aafc4b7d36ec50533367df8a087b1b7496aa7770d21d67d898b58263111b80&state=58084732fa66c8eccfc77ac3c9cce9a16279c8da0aec1cdb" for 127.0.0.1 at 2016-06-22 08:18:48 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"39aafc4b7d36ec50533367df8a087b1b7496aa7770d21d67d898b58263111b80", "state"=>"58084732fa66c8eccfc77ac3c9cce9a16279c8da0aec1cdb"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1 User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "test@example-client.com"], ["name", "Test User"], ["permissions", "---\n- signin\n"], ["uid", "integration-uid"]]  (16.3ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "f"]]  (12.4ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 37ms (ActiveRecord: 30.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:48 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 5ms (Views: 0.7ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:48 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:48 +0000 Started GET "/auth/gds/callback?code=ca8996cbeb1ce63c3f83d1e5b6ee0552f0aabc5e732e91675fe713debdd40f49&state=814daa7af02a618a60b3af1bcf90a8a35d0c3597efde2566" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"ca8996cbeb1ce63c3f83d1e5b6ee0552f0aabc5e732e91675fe713debdd40f49", "state"=>"814daa7af02a618a60b3af1bcf90a8a35d0c3597efde2566"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (25.6ms) commit transaction  (0.2ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.6ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 48ms (ActiveRecord: 40.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Started GET "/auth/gds/callback?code=d74ea48df4407343b8aa4ccb8b8a403f206b8f70848d911cd64ba3c49ef5ce72&state=69220e0886adf96ec8357f8d476c60e045a3ab8a96b1e8b1" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"d74ea48df4407343b8aa4ccb8b8a403f206b8f70848d911cd64ba3c49ef5ce72", "state"=>"69220e0886adf96ec8357f8d476c60e045a3ab8a96b1e8b1"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (14.3ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.7ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 32ms (ActiveRecord: 25.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by ExampleController#restricted as HTML User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 12ms (Views: 0.3ms | ActiveRecord: 0.5ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Started GET "/auth/gds/callback?code=175e733f9d743214486ad659f256684c1a20da5a1361a505ab829c35a4a40bd0&state=96d03aec0743cc98b7d97cc3a377678bfe137c9c4ffb4504" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"175e733f9d743214486ad659f256684c1a20da5a1361a505ab829c35a4a40bd0", "state"=>"96d03aec0743cc98b7d97cc3a377678bfe137c9c4ffb4504"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (11.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (9.2ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 29ms (ActiveRecord: 22.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:49 +0000 Started GET "/auth/gds/callback?code=42911dee60ced7bbd61782739f3062445e6a2aa002fa685505c68d61ff2906da&state=8257c535742f0c93f7a134dc88807d23f03332280097b171" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"42911dee60ced7bbd61782739f3062445e6a2aa002fa685505c68d61ff2906da", "state"=>"8257c535742f0c93f7a134dc88807d23f03332280097b171"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (22.8ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (12.4ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 43ms (ActiveRecord: 36.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Started GET "/auth/gds/callback?code=3f9b98bd865ecea887592bc3720af26d1bc3baf049f2a32a4723afec0a631b58&state=53954c048365d9641ac87172386fc2239be1b239e52690db" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"3f9b98bd865ecea887592bc3720af26d1bc3baf049f2a32a4723afec0a631b58", "state"=>"53954c048365d9641ac87172386fc2239be1b239e52690db"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.7ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 31ms (ActiveRecord: 25.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) User Load (0.7ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "t"]]  (14.3ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Authenticating with gds_sso strategy Completed in 2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Started GET "/auth/gds/callback?code=46803e210417c35deda0da7122766663d4200d0dbb1ceaf574769c90721b8bb8&state=a92bde3445c7b6524784c4523d09ec9ed19a32c048117d69" for 127.0.0.1 at 2016-06-22 08:18:50 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"46803e210417c35deda0da7122766663d4200d0dbb1ceaf574769c90721b8bb8", "state"=>"a92bde3445c7b6524784c4523d09ec9ed19a32c048117d69"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (36.5ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "f"]]  (12.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 57ms (ActiveRecord: 50.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Started GET "/auth/gds/callback?code=6528e15f18871fbb9d93afeaac3ddcd307e1b76a208211af2d289923fcdb8dec&state=4d0dcc69a6cc3242fc8589dd87ef6408c344ac7f4bbbc76e" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"6528e15f18871fbb9d93afeaac3ddcd307e1b76a208211af2d289923fcdb8dec", "state"=>"4d0dcc69a6cc3242fc8589dd87ef6408c344ac7f4bbbc76e"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (18.7ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.3ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 40ms (ActiveRecord: 33.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:23:51 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:23:51 +0000 Started GET "/auth/gds/callback?code=5773762f0415f7099c5c78f88015332018406bb17516a476833b61c58faead3d&state=82039c0f1b4239a21d702ffcc5b156b4f4cb649602d8dabe" for 127.0.0.1 at 2016-06-23 04:23:51 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"5773762f0415f7099c5c78f88015332018406bb17516a476833b61c58faead3d", "state"=>"82039c0f1b4239a21d702ffcc5b156b4f4cb649602d8dabe"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.4ms) commit transaction  (0.4ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (14.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 32ms (ActiveRecord: 25.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:23:51 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Started GET "/auth/gds/callback?code=5a9a7081edeb34f6dcf865bea3dca78dda0fd194d7c1aa7672034a0709cfbfe8&state=7dd6421f1cfa50ca980b9ee8487dd73e992d074d4569f295" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"5a9a7081edeb34f6dcf865bea3dca78dda0fd194d7c1aa7672034a0709cfbfe8", "state"=>"7dd6421f1cfa50ca980b9ee8487dd73e992d074d4569f295"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (15.2ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (11.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 36ms (ActiveRecord: 28.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:13:51 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 14ms (Views: 0.3ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by ExampleController#restricted as JSON Completed in 23ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:51 +0000 Processing by ExampleController#restricted as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "disabled" = ?, "permissions" = ? WHERE "users"."id" = 12 [["disabled", nil], ["permissions", "---\n- signin\n"]]  (14.2ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.0ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (15.4ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (9.5ms) commit transaction Completed 200 OK in 152ms (Views: 0.4ms | ActiveRecord: 65.6ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:18:52 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (12.7ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (16.0ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (24.2ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (19.5ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (16.0ms) commit transaction Completed 200 OK in 178ms (Views: 0.4ms | ActiveRecord: 91.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:18:52 +0000 Processing by ExampleController#restricted as JSON Completed in 24ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:08 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 11ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:08 +0000 Started GET "/auth/gds/callback?code=c1431920e1952afa0747fb3be2300f157b0ed89760b4c6a7657a08210551420d&state=ca2d827b17ed26aa1e2b648bed77b2e1eca4b0bf23423dd8" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"c1431920e1952afa0747fb3be2300f157b0ed89760b4c6a7657a08210551420d", "state"=>"ca2d827b17ed26aa1e2b648bed77b2e1eca4b0bf23423dd8"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]] User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "test@example-client.com"]]  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "integration-uid"], ["email", "test@example-client.com"], ["name", "Test User"], ["permissions", "---\n- signin\n"]]  (24.4ms) commit transaction  (0.1ms) begin transaction SQL (0.5ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "f"], ["id", 1]]  (26.9ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 89ms (ActiveRecord: 53.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.1ms) Completed 200 OK in 10ms (Views: 6.5ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Started GET "/auth/gds/callback?code=629d361b2df32813ac99a676a3c280c4cc669b5a9f63c70887c1b8c9d95aa55f&state=3ed063b56100fe42778b98afecd902e5da3b282159ad2d2f" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"629d361b2df32813ac99a676a3c280c4cc669b5a9f63c70887c1b8c9d95aa55f", "state"=>"3ed063b56100fe42778b98afecd902e5da3b282159ad2d2f"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.3ms) begin transaction  (0.2ms) commit transaction  (0.1ms) begin transaction  (0.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 10ms (ActiveRecord: 0.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 4ms (Views: 0.7ms | ActiveRecord: 0.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Started GET "/auth/gds/callback?code=00e798e6d104abef275f159864ecc5339d2136cd73248c9375263956bfba87d9&state=32e62097f867eef7bf17602e8372ad97d4372d293a9039ab" for 127.0.0.1 at 2016-06-22 08:19:20 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"00e798e6d104abef275f159864ecc5339d2136cd73248c9375263956bfba87d9", "state"=>"32e62097f867eef7bf17602e8372ad97d4372d293a9039ab"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.2ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 11ms (ActiveRecord: 0.7ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 5ms (Views: 0.7ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Started GET "/auth/gds/callback?code=dd5dc96fccc42607df8df2d06c556142163c3a1fcac50e1ff72c82da05ae4d49&state=8d6c476f78774461738fba50bb95be135e83d4c215581467" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"dd5dc96fccc42607df8df2d06c556142163c3a1fcac50e1ff72c82da05ae4d49", "state"=>"8d6c476f78774461738fba50bb95be135e83d4c215581467"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 6ms (ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.4ms | ActiveRecord: 0.1ms) Started GET "/" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by ExampleController#index as HTML Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.5ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Started GET "/auth/gds/callback?code=02ae39f470175e0c2d98f94fce809016078ff6aa689a62470a500aeeed22d1f9&state=cf50dd15fdc2a156eb4f5758e9b070201ce843e9351d44e4" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"02ae39f470175e0c2d98f94fce809016078ff6aa689a62470a500aeeed22d1f9", "state"=>"cf50dd15fdc2a156eb4f5758e9b070201ce843e9351d44e4"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 9ms (ActiveRecord: 0.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Started GET "/auth/gds/callback?code=371a9466ca6a4710043738b8a7bcd4ce33d5ee356069957abca19d19aa40fb44&state=209828e2057e45bfb9accb43d4692e8edf22ac4ea1319346" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"371a9466ca6a4710043738b8a7bcd4ce33d5ee356069957abca19d19aa40fb44", "state"=>"209828e2057e45bfb9accb43d4692e8edf22ac4ea1319346"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 12ms (ActiveRecord: 0.7ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:21 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.4ms | ActiveRecord: 0.2ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "test@example-client.com"]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 1]]  (9.7ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Authenticating with gds_sso strategy Completed in 2ms (ActiveRecord: 0.1ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Started GET "/auth/gds/callback?code=e9e5dd2fc48f041e12cc34b042cd7d35a5708a80004faa5329b8107ae89d2021&state=0ce32ac5f878bbc59c53bd5f6a2f40a890774384e4aedeb0" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"e9e5dd2fc48f041e12cc34b042cd7d35a5708a80004faa5329b8107ae89d2021", "state"=>"0ce32ac5f878bbc59c53bd5f6a2f40a890774384e4aedeb0"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "f"], ["id", 1]]  (9.0ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 18ms (ActiveRecord: 9.7ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Started GET "/auth/gds/callback?code=e3252c3d78da01c7b76e3b39613df94e060d439cb668725ee767a6081bd61f21&state=2ea0913f96a64cca292e9f3310e8b19e09763a434e35ea1f" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"e3252c3d78da01c7b76e3b39613df94e060d439cb668725ee767a6081bd61f21", "state"=>"2ea0913f96a64cca292e9f3310e8b19e09763a434e35ea1f"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 5ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:24:22 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:24:22 +0000 Started GET "/auth/gds/callback?code=ab58c37545da250e3e0476fb6520d0328aaac30e8ec99033aad80cbcd35255e6&state=a1db30e332bac2680f25f5b74e26a9692010ff18756ade09" for 127.0.0.1 at 2016-06-23 04:24:22 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"ab58c37545da250e3e0476fb6520d0328aaac30e8ec99033aad80cbcd35255e6", "state"=>"a1db30e332bac2680f25f5b74e26a9692010ff18756ade09"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 5ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:24:22 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Started GET "/auth/gds/callback?code=57e9394b27688fa6d46e163db93b03bd6b12693216b0f4b5fc28c30161f65fe6&state=220c8726b299f44e77fb2d5087328dcd2988c53ce3a42a6c" for 127.0.0.1 at 2016-06-22 08:19:22 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"57e9394b27688fa6d46e163db93b03bd6b12693216b0f4b5fc28c30161f65fe6", "state"=>"220c8726b299f44e77fb2d5087328dcd2988c53ce3a42a6c"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 6ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:23 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:14:23 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:23 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "disabled" = ? WHERE "users"."id" = ? [["disabled", nil], ["id", 1]]  (13.3ms) commit transaction User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.3ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Rendered text template (0.0ms) Completed 200 OK in 113ms (Views: 0.4ms | ActiveRecord: 14.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:23 +0000 Processing by ExampleController#restricted as JSON Completed in 34ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:23 +0000 Processing by ExampleController#restricted as JSON Completed in 24ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:23 +0000 Processing by ExampleController#restricted as JSON User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.2ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.0ms) begin transaction  (0.1ms) commit transaction Rendered text template (0.0ms) Completed 200 OK in 102ms (Views: 0.5ms | ActiveRecord: 1.3ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "asd"]] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "user@example.com"]]  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions", "organisation_slug", "organisation_content_id", "disabled") VALUES (?, ?, ?, ?, ?, ?, ?) [["uid", "asd"], ["email", "user@example.com"], ["name", "A Name"], ["permissions", "---\n- signin\n"], ["organisation_slug", "hmrc"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["disabled", nil]]  (11.6ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "asd"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32610"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (8.7ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d35419"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (9.7ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d32610"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.4ms) Completed 403 Forbidden in 4ms (Views: 3.7ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d31792"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (9.8ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d39328"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (26.1ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d31792"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d31792"]]  (0.2ms) begin transaction SQL (0.4ms) UPDATE "users" SET "email" = ?, "name" = ?, "permissions" = ?, "organisation_slug" = ?, "organisation_content_id" = ? WHERE "users"."id" = ? [["email", "user@domain.com"], ["name", "Joshua Marshall"], ["permissions", "---\n- signin\n- new permission\n"], ["organisation_slug", "justice-league"], ["organisation_content_id", "aae1319e-5788-4677-998c-f1a53af528d0"], ["id", 5]]  (11.4ms) commit transaction Completed 200 OK in 19ms (ActiveRecord: 12.1ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 5]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d37347"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (9.3ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d39557"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (9.2ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d37347"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.2ms) Completed 403 Forbidden in 1ms (Views: 0.9ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d34066"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (9.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32642"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (7.1ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "nonexistent-user"]] Completed 200 OK in 1ms (ActiveRecord: 0.1ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d35559"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (10.9ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d36349"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (6.6ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d35559"} User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d35559"]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 11]]  (11.4ms) commit transaction Completed 200 OK in 15ms (ActiveRecord: 11.8ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 11]] Connecting to database specified by database.yml User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' LIMIT 1 User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'user@example.com' LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", nil], ["email", "user@example.com"], ["name", "A Name"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["organisation_slug", "hmrc"], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "asd"]]  (44.1ms) commit transaction User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 1  (24.5ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d35172"]]  (15.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d38531"]]  (10.3ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d35172"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d35172' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 't', "permissions" = '--- - signin ' WHERE "users"."id" = 2  (11.7ms) commit transaction Completed 200 OK in 14.9ms (ActiveRecord: 12.1ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 2]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d3962"]]  (17.2ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d3147"]]  (10.8ms) commit transaction WARNING: Can't mass-assign protected attributes: uid, name, permissions Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d3962"} Completed 403 Forbidden in 7.7ms (Views: 7.1ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d36707"]]  (17.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d35142"]]  (11.9ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'nonexistent-user' LIMIT 1 Completed 200 OK in 1.1ms (ActiveRecord: 0.2ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d34729"]]  (12.8ms) commit transaction  (0.2ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d31934"]]  (12.6ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d34729"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d34729' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "email" = 'user@domain.com', "name" = 'Joshua Marshall', "permissions" = '--- - signin - new permission ', "organisation_slug" = 'justice-league', "organisation_content_id" = 'aae1319e-5788-4677-998c-f1a53af528d0' WHERE "users"."id" = 8  (11.4ms) commit transaction Completed 200 OK in 15.7ms (ActiveRecord: 11.9ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 8]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "a1s2d34190"]]  (9.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", false], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n- user_update_permission\n"], ["remotely_signed_out", nil], ["uid", "a1s2d37413"]]  (23.4ms) commit transaction WARNING: Can't mass-assign protected attributes: uid, name, permissions Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d34190"} Completed 403 Forbidden in 1.2ms (Views: 0.8ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:40 +0000 Processing by ExampleController#restricted as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1 User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "remotely_signed_out", "uid") VALUES (?, ?, ?, ?, ?, ?, ?, ?) [["disabled", nil], ["email", "test@example-client.com"], ["name", "Test User"], ["organisation_content_id", nil], ["organisation_slug", nil], ["permissions", "---\n- signin\n"], ["remotely_signed_out", nil], ["uid", "integration-uid"]]  (19.0ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (20.0ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (7.1ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (14.1ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 'f', "permissions" = '--- - signin ' WHERE "users"."id" = 12  (10.9ms) commit transaction Completed 200 OK in 403.9ms (Views: 2.3ms | ActiveRecord: 74.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:41 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (11.4ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (12.8ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (9.8ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (20.9ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (18.0ms) commit transaction Completed 200 OK in 167.8ms (Views: 0.4ms | ActiveRecord: 75.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:41 +0000 Processing by ExampleController#restricted as JSON Completed in 38.0ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:41 +0000 Processing by ExampleController#restricted as JSON Completed in 23.0ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:41 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:41 +0000 Started GET "/auth/gds/callback?code=dd975ad1bb910e438304e8b9ce587028381bf4527dbdfd6a8aec4e8a86efcd29&state=8eeb7b2c995a8b9b49d2b16cefd805151695cbd413eb9157" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"dd975ad1bb910e438304e8b9ce587028381bf4527dbdfd6a8aec4e8a86efcd29", "state"=>"8eeb7b2c995a8b9b49d2b16cefd805151695cbd413eb9157"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "disabled" = 'f', "permissions" = '--- - signin ' WHERE "users"."id" = 12  (19.4ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (8.5ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 37.2ms (ActiveRecord: 29.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 4.2ms (Views: 0.4ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.4ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Started GET "/auth/gds/callback?code=5243494a8494fdafa91397424adac94e81e168594b27bcd979796d699be78e7b&state=49a9b9784e9afc9bc1c25886b094f055702c04d6b6de385e" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"5243494a8494fdafa91397424adac94e81e168594b27bcd979796d699be78e7b", "state"=>"49a9b9784e9afc9bc1c25886b094f055702c04d6b6de385e"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (10.8ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (16.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 33.7ms (ActiveRecord: 28.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.9ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Started GET "/auth/gds/callback?code=c4a0bcd546e7e8c5094a078cb0297518934d7f293928a6ab264bb3d19c3f008d&state=41de7af6b2fef4c8a273a4fd14d283c4f43651bc3dfc8c7a" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"c4a0bcd546e7e8c5094a078cb0297518934d7f293928a6ab264bb3d19c3f008d", "state"=>"41de7af6b2fef4c8a273a4fd14d283c4f43651bc3dfc8c7a"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (11.6ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (11.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 29.4ms (ActiveRecord: 24.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.8ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by ExampleController#index as HTML Completed 200 OK in 0.9ms (Views: 0.5ms | ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:54 +0000 Started GET "/auth/gds/callback?code=de08f72872354d3197e61956ef1086245b13ee4f541e5148fda2ec0ab52f0abc&state=bda4c43ff037dba8afee1189715c8e3184380acb540d747e" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"de08f72872354d3197e61956ef1086245b13ee4f541e5148fda2ec0ab52f0abc", "state"=>"bda4c43ff037dba8afee1189715c8e3184380acb540d747e"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (46.6ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (15.7ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 69.2ms (ActiveRecord: 63.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 2.7ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Started GET "/auth/gds/callback?code=32861488f6d7b10a25cecde96e8e47cc6bb423074ceb10a0c97cfe58ce6207e5&state=589814f53149d2ee2528d456804aeeb315b3fffff79b66cd" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"32861488f6d7b10a25cecde96e8e47cc6bb423074ceb10a0c97cfe58ce6207e5", "state"=>"589814f53149d2ee2528d456804aeeb315b3fffff79b66cd"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (11.0ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (10.7ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 28.4ms (ActiveRecord: 22.6ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 2.6ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Started GET "/auth/gds/callback?code=cc94e99659a2b2dbd1b9e841bb1e905a6c4a42ba90f12cb6b3407722bb1c0704&state=ad933f7b66634037c40f5f5970c53a98cdbf549a7f04c661" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"cc94e99659a2b2dbd1b9e841bb1e905a6c4a42ba90f12cb6b3407722bb1c0704", "state"=>"ad933f7b66634037c40f5f5970c53a98cdbf549a7f04c661"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (10.8ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (54.9ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 73.3ms (ActiveRecord: 66.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 2.4ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:14:55 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.6ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.2ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:55 +0000 Started GET "/auth/gds/callback?code=135d3275a708a6d6e959360e1027b8643799afea802f8f7eb6fb608db2b41277&state=7679319fcbf9e74595e13d76c8f7eae1d7d96ec894756a37" for 127.0.0.1 at 2016-06-22 08:19:56 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"135d3275a708a6d6e959360e1027b8643799afea802f8f7eb6fb608db2b41277", "state"=>"7679319fcbf9e74595e13d76c8f7eae1d7d96ec894756a37"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (4.6ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (13.3ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (12.9ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 37.7ms (ActiveRecord: 31.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:56 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.7ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:24:56 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.5ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:24:56 +0000 Started GET "/auth/gds/callback?code=eb8d1119ac28f19c8418b5dd5f2d36a83d5e33e981b4b93dbadee759543ee7cc&state=a104870c43bb11365b4eddca8ab061552317df66faa75c96" for 127.0.0.1 at 2016-06-23 04:24:56 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"eb8d1119ac28f19c8418b5dd5f2d36a83d5e33e981b4b93dbadee759543ee7cc", "state"=>"a104870c43bb11365b4eddca8ab061552317df66faa75c96"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (11.9ms) commit transaction  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (7.7ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 25.9ms (ActiveRecord: 20.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:24:56 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.9ms (Views: 0.3ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:56 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0.3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:56 +0000 Started GET "/auth/gds/callback?code=fcdad7dc7f9dacbcba1269af25e3483b434d88e855b96c9fdc06eb8ca073b839&state=1bb2a83099bbe73d30221b3225fb1f7117aa94300eb44eb6" for 127.0.0.1 at 2016-06-22 08:19:56 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"fcdad7dc7f9dacbcba1269af25e3483b434d88e855b96c9fdc06eb8ca073b839", "state"=>"1bb2a83099bbe73d30221b3225fb1f7117aa94300eb44eb6"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (9.8ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (12.4ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 28.6ms (ActiveRecord: 23.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:56 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.6ms (Views: 0.3ms | ActiveRecord: 0.3ms) User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' LIMIT 1  (0.1ms) begin transaction  (0.2ms) UPDATE "users" SET "remotely_signed_out" = 't', "permissions" = '--- - signin ' WHERE "users"."id" = 12  (36.8ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:56 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Authenticating with gds_sso strategy Completed in 1.9ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:19:56 +0000 Started GET "/auth/gds/callback?code=b6e63f379b2010fdd38c2e4e6063987c5a95d71c314823a75fe1fc173b900382&state=65a3d1e0965fd6c74f24a425eb54fcf126f71475e73fad81" for 127.0.0.1 at 2016-06-22 08:19:57 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"b6e63f379b2010fdd38c2e4e6063987c5a95d71c314823a75fe1fc173b900382", "state"=>"65a3d1e0965fd6c74f24a425eb54fcf126f71475e73fad81"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' LIMIT 1  (0.0ms) begin transaction  (0.2ms) UPDATE "users" SET "permissions" = '--- - signin ' WHERE "users"."id" = 12  (11.9ms) commit transaction  (0.1ms) begin transaction  (0.3ms) UPDATE "users" SET "remotely_signed_out" = 'f', "permissions" = '--- - signin ' WHERE "users"."id" = 12  (8.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 26.7ms (ActiveRecord: 21.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:19:57 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' LIMIT 1 Completed 200 OK in 1.4ms (Views: 0.2ms | ActiveRecord: 0.2ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' ORDER BY "users"."id" ASC LIMIT 1 User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'user@example.com' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("disabled", "email", "name", "organisation_content_id", "organisation_slug", "permissions", "uid") VALUES (?, ?, ?, ?, ?, ?, ?) [["disabled", nil], ["email", "user@example.com"], ["name", "A Name"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["organisation_slug", "hmrc"], ["permissions", "---\n- signin\n"], ["uid", "asd"]]  (24.2ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'asd' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 1 [["permissions", "---\n- signin\n"]]  (28.8ms) commit transaction  (0.2ms) begin transaction SQL (0.5ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d3290"]]  (21.7ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d35757"]]  (14.3ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d3290"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 7ms (Views: 6.8ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d39192"]]  (16.2ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d31831"]]  (16.4ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d39192"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d39192' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "email" = ?, "name" = ?, "organisation_content_id" = ?, "organisation_slug" = ?, "permissions" = ? WHERE "users"."id" = 4 [["email", "user@domain.com"], ["name", "Joshua Marshall"], ["organisation_content_id", "aae1319e-5788-4677-998c-f1a53af528d0"], ["organisation_slug", "justice-league"], ["permissions", "---\n- signin\n- new permission\n"]]  (13.0ms) commit transaction Completed 200 OK in 17ms (ActiveRecord: 13.7ms) User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 4]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d38027"]]  (12.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d32326"]]  (19.3ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d38027"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'a1s2d38027' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 6 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "t"]]  (11.5ms) commit transaction Completed 200 OK in 15ms (ActiveRecord: 12.2ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 6]]  (0.2ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d35482"]]  (15.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d36293"]]  (12.2ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'nonexistent-user' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (ActiveRecord: 0.3ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"], ["uid", "a1s2d3744"]]  (17.6ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"], ["uid", "a1s2d36010"]]  (12.4ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d3744"} Completed 403 Forbidden in 2ms (Views: 1.4ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:21 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 8ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:21 +0000 Started GET "/auth/gds/callback?code=f30e497d7de938560af3939ebc336bdb39d139acc8afe45f270ab0d0684c7f62&state=d927fc0d28d0e42f271d982b4e89fc002c9cc5f5ddb430fa" for 127.0.0.1 at 2016-06-22 08:20:34 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"f30e497d7de938560af3939ebc336bdb39d139acc8afe45f270ab0d0684c7f62", "state"=>"d927fc0d28d0e42f271d982b4e89fc002c9cc5f5ddb430fa"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1 User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("email", "name", "permissions", "uid") VALUES (?, ?, ?, ?) [["email", "test@example-client.com"], ["name", "Test User"], ["permissions", "---\n- signin\n"], ["uid", "integration-uid"]]  (19.8ms) commit transaction  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "f"]]  (16.3ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 44ms (ActiveRecord: 37.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:34 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 4ms (Views: 1.6ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:34 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:34 +0000 Started GET "/auth/gds/callback?code=813938462028495e7cf946c763309d31452cda9f55d80de3f407d1d95eda2501&state=0f62bca1ab8da4b13bf83aba0a69a12c7e13cc6f8013abe9" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"813938462028495e7cf946c763309d31452cda9f55d80de3f407d1d95eda2501", "state"=>"0f62bca1ab8da4b13bf83aba0a69a12c7e13cc6f8013abe9"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (14.6ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (16.6ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 37ms (ActiveRecord: 32.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Started GET "/auth/gds/callback?code=d1eaaf1aaf665da4e33b8adaf0893c36ccdbf1ec70d104fb3b1630a2ffae9297&state=c1c57c86a6b0b6dda30454e7b13b7ecb9b18cc59d8d9e204" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"d1eaaf1aaf665da4e33b8adaf0893c36ccdbf1ec70d104fb3b1630a2ffae9297", "state"=>"c1c57c86a6b0b6dda30454e7b13b7ecb9b18cc59d8d9e204"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (11.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (20.4ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 38ms (ActiveRecord: 33.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.4ms) Started GET "/" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by ExampleController#index as HTML Completed 200 OK in 0ms (Views: 0.3ms | ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Started GET "/auth/gds/callback?code=7243038e9e396f9beaacc4c20d22c85a0cff07eeace0c417e4dca736e83cfa1a&state=1a9405a4ffcd2159f686e5aced2297b611cc70b0292764af" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"7243038e9e396f9beaacc4c20d22c85a0cff07eeace0c417e4dca736e83cfa1a", "state"=>"1a9405a4ffcd2159f686e5aced2297b611cc70b0292764af"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (7.9ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 24ms (ActiveRecord: 18.9ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:35 +0000 Started GET "/auth/gds/callback?code=cd4dca6cf33b118238a7d952470a321bed65dbabd654ab45d0503c483f155ebb&state=e92102cce064e90ff5a07649c367a69114b570d6a30751e6" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"cd4dca6cf33b118238a7d952470a321bed65dbabd654ab45d0503c483f155ebb", "state"=>"e92102cce064e90ff5a07649c367a69114b570d6a30751e6"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (9.2ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 25ms (ActiveRecord: 20.1ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Started GET "/auth/gds/callback?code=7e698df7579d5b29d94563f678edf4cca189a153e621f38f76f5f2d0ecbc29da&state=8a01d6150593511466016e6be5961bb2220812d3eab9bdef" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"7e698df7579d5b29d94563f678edf4cca189a153e621f38f76f5f2d0ecbc29da", "state"=>"8a01d6150593511466016e6be5961bb2220812d3eab9bdef"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (15.4ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (20.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 43ms (ActiveRecord: 37.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."email" = 'test@example-client.com' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "t"]]  (10.9ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Authenticating with gds_sso strategy Completed in 3ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Started GET "/auth/gds/callback?code=d6ae63dff85a1f20cb2b5fd74db24de7ddb3bfb96ecfefcf45200e87a72118e0&state=a5e252c5ca8625f34bb3d469a563d0932863ca80dab3b958" for 127.0.0.1 at 2016-06-22 08:20:36 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"d6ae63dff85a1f20cb2b5fd74db24de7ddb3bfb96ecfefcf45200e87a72118e0", "state"=>"a5e252c5ca8625f34bb3d469a563d0932863ca80dab3b958"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.5ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ?, "remotely_signed_out" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"], ["remotely_signed_out", "f"]]  (9.8ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 27ms (ActiveRecord: 21.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Started GET "/auth/gds/callback?code=f48260a353f603d271ffc9a8fb20b07e5a8efae7831ef8c60c58a0429b8c97c6&state=e29e3dbe49eda6b747881c8a4cfffab3e928c211d8ba9f2d" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"f48260a353f603d271ffc9a8fb20b07e5a8efae7831ef8c60c58a0429b8c97c6", "state"=>"e29e3dbe49eda6b747881c8a4cfffab3e928c211d8ba9f2d"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (9.9ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (9.9ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 28ms (ActiveRecord: 20.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:25:37 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:25:37 +0000 Started GET "/auth/gds/callback?code=0937919b54fb19be356ad341deaaf83d6821ffbe52c9e6479033942db7d8e47e&state=7c4c32f6e19b333caf82a61cac82dcd39868a2b0c33a0613" for 127.0.0.1 at 2016-06-23 04:25:37 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"0937919b54fb19be356ad341deaaf83d6821ffbe52c9e6479033942db7d8e47e", "state"=>"7c4c32f6e19b333caf82a61cac82dcd39868a2b0c33a0613"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.2ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.0ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 28ms (ActiveRecord: 21.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:25:37 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Started GET "/auth/gds/callback?code=2d6cf7f00b2f6c8462ff7bd6127f25e533ad730aa5ffb0f1f55ffe8415a932af&state=1451001e65634c4dbefcf23e51f3b2feded9106d7add6f89" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"2d6cf7f00b2f6c8462ff7bd6127f25e533ad730aa5ffb0f1f55ffe8415a932af", "state"=>"1451001e65634c4dbefcf23e51f3b2feded9106d7add6f89"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (7.6ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (16.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 31ms (ActiveRecord: 24.7ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 3ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:15:37 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' AND "users"."remotely_signed_out" = 'f' ORDER BY "users"."id" ASC LIMIT 1 Completed 200 OK in 4ms (Views: 0.4ms | ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:20:37 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "disabled" = ?, "permissions" = ? WHERE "users"."id" = 12 [["disabled", nil], ["permissions", "---\n- signin\n"]]  (14.6ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (16.2ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (13.7ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.4ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.4ms) commit transaction Completed 200 OK in 212ms (Views: 0.4ms | ActiveRecord: 68.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:38 +0000 Processing by ExampleController#restricted as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (14.4ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (10.0ms) commit transaction User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.1ms) begin transaction SQL (0.4ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (7.2ms) commit transaction User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."uid" = 'integration-uid' ORDER BY "users"."id" ASC LIMIT 1  (0.2ms) begin transaction SQL (0.3ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (11.7ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "permissions" = ? WHERE "users"."id" = 12 [["permissions", "---\n- signin\n"]]  (9.7ms) commit transaction Completed 200 OK in 166ms (Views: 0.5ms | ActiveRecord: 56.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:38 +0000 Processing by ExampleController#restricted as JSON Completed in 22ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:38 +0000 Processing by ExampleController#restricted as JSON Completed in 26ms Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:53 +0000 Processing by ExampleController#restricted as JSON User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]] User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "test@example-client.com"]]  (0.2ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions", "disabled") VALUES (?, ?, ?, ?, ?) [["uid", "integration-uid"], ["email", "test@example-client.com"], ["name", "Test User"], ["permissions", "---\n- signin\n"], ["disabled", nil]]  (63.6ms) commit transaction User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.2ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction SQL (0.6ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "f"], ["id", 1]]  (12.2ms) commit transaction Rendered text template (0.0ms) Completed 200 OK in 469ms (Views: 5.4ms | ActiveRecord: 79.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:54 +0000 Processing by ExampleController#restricted as JSON Completed in 36ms (ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:20:54 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.2ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Rendered text template (0.0ms) Completed 200 OK in 88ms (Views: 0.5ms | ActiveRecord: 1.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:54 +0000 Processing by ExampleController#restricted as JSON Completed in 27ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:20:54 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:20:54 +0000 Started GET "/auth/gds/callback?code=00ae7ebde4165ee33ed778f32c4b9d73994a75bec641dfaf3174dca6a5b46fe6&state=ab2341c717e356dbcb95b0dcb1e8a1374af77deb1fcefd58" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"00ae7ebde4165ee33ed778f32c4b9d73994a75bec641dfaf3174dca6a5b46fe6", "state"=>"ab2341c717e356dbcb95b0dcb1e8a1374af77deb1fcefd58"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "disabled" = ? WHERE "users"."id" = ? [["disabled", "f"], ["id", 1]]  (15.3ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 23ms (ActiveRecord: 16.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 4ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#index as HTML Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Started GET "/auth/gds/callback?code=6aeb0b8df2f279f2e6e1ccc5b982227170b744df6f20497d03be9198731de64e&state=b3975d2caa65076bf25abecc8976a34dcc298f3a31431cb5" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"6aeb0b8df2f279f2e6e1ccc5b982227170b744df6f20497d03be9198731de64e", "state"=>"b3975d2caa65076bf25abecc8976a34dcc298f3a31431cb5"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 6ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Started GET "/auth/gds/callback?code=a7d87c9a3295cc1aa8d15c1cb3d3b7aaab26acc288d1356be745792de1b98377&state=cb420d1d28e79f15e839fc0c7810c31bef25e611f1dd5b26" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"a7d87c9a3295cc1aa8d15c1cb3d3b7aaab26acc288d1356be745792de1b98377", "state"=>"cb420d1d28e79f15e839fc0c7810c31bef25e611f1dd5b26"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 5ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Started GET "/auth/gds/callback?code=ff78ca38f1251441f5b5ab97912ac3a93de8d5c69aa50b05188b6e531239ad0f&state=d0fbdf4daa99a24a0580a5e6fec83d710541606ee0be5e2b" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"ff78ca38f1251441f5b5ab97912ac3a93de8d5c69aa50b05188b6e531239ad0f", "state"=>"d0fbdf4daa99a24a0580a5e6fec83d710541606ee0be5e2b"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 7ms (ActiveRecord: 0.5ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.6ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Processing by ExampleController#this_requires_signin_permission as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:21:07 +0000 Started GET "/auth/gds/callback?code=c69064433e268f82c28bb42c49aebcf63e7d913e0477b4b37f9c648e58f2e3a7&state=7fa3ac4875476754aec7a70f621266dfcd4cf9b4c7e79b7b" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"c69064433e268f82c28bb42c49aebcf63e7d913e0477b4b37f9c648e58f2e3a7", "state"=>"7fa3ac4875476754aec7a70f621266dfcd4cf9b4c7e79b7b"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 6ms (ActiveRecord: 0.5ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Started GET "/auth/gds/callback?code=903fd7b4f023ed4f848e2b2c5baf88ebde360bb9017219ddcc77ee867ee188ca&state=9b23dee6f860fbbab2aacdb1e6727b6d5a05aa7997dff124" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"903fd7b4f023ed4f848e2b2c5baf88ebde360bb9017219ddcc77ee867ee188ca", "state"=>"9b23dee6f860fbbab2aacdb1e6727b6d5a05aa7997dff124"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 7ms (ActiveRecord: 0.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:16:08 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.5ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Started GET "/auth/gds/callback?code=2391a03fe4a366e834b08671f2d3847c9cc8d895db9dad09ae61b3ceddf6c335&state=b5c53358407da9fda9dfbe05cf51024b7e075504d2d08206" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"2391a03fe4a366e834b08671f2d3847c9cc8d895db9dad09ae61b3ceddf6c335", "state"=>"b5c53358407da9fda9dfbe05cf51024b7e075504d2d08206"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 5ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:26:08 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-23 04:26:08 +0000 Started GET "/auth/gds/callback?code=42f614befcbd80f847af606ba7d6be86e3411d81b8915970b6fffd9827ab667c&state=12848cba28b4d80f635ac9815f9a746f25249f88eb04715e" for 127.0.0.1 at 2016-06-23 04:26:08 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"42f614befcbd80f847af606ba7d6be86e3411d81b8915970b6fffd9827ab667c", "state"=>"12848cba28b4d80f635ac9815f9a746f25249f88eb04715e"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.2ms) begin transaction  (0.1ms) commit transaction  (0.3ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 9ms (ActiveRecord: 0.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-23 04:26:08 +0000 Processing by ExampleController#restricted as HTML User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.4ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 0ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:21:08 +0000 Started GET "/auth/gds/callback?code=a35e128d71df95cc735a0b8f3ae3b2cf6c283835c733f4cfa8624a2d07343e7e&state=efe2c7dac85dd7d876cb748a735a412811f4ce027eaa6ac1" for 127.0.0.1 at 2016-06-22 08:21:09 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"a35e128d71df95cc735a0b8f3ae3b2cf6c283835c733f4cfa8624a2d07343e7e", "state"=>"efe2c7dac85dd7d876cb748a735a412811f4ce027eaa6ac1"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 6ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:09 +0000 Processing by ExampleController#restricted as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 4ms (Views: 0.6ms | ActiveRecord: 0.3ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "test@example-client.com"]]  (0.1ms) begin transaction SQL (0.3ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 1]]  (14.7ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:09 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Authenticating with gds_sso strategy Completed in 2ms (ActiveRecord: 0.1ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-06-22 08:21:09 +0000 Started GET "/auth/gds/callback?code=99282d779e784a6116e3c13afac72842a60bf720ddd07beef715f3099d309c19&state=cf9b42f3728d57d5437f8e00423365989785bde768719c85" for 127.0.0.1 at 2016-06-22 08:21:09 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"99282d779e784a6116e3c13afac72842a60bf720ddd07beef715f3099d309c19", "state"=>"cf9b42f3728d57d5437f8e00423365989785bde768719c85"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "f"], ["id", 1]]  (15.7ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 22ms (ActiveRecord: 16.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-06-22 08:21:09 +0000 Processing by ExampleController#restricted as HTML User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"], ["remotely_signed_out", "f"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.1ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "asd"]] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "user@example.com"]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions", "organisation_slug", "organisation_content_id", "disabled") VALUES (?, ?, ?, ?, ?, ?, ?) [["uid", "asd"], ["email", "user@example.com"], ["name", "A Name"], ["permissions", "---\n- signin\n"], ["organisation_slug", "hmrc"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["disabled", nil]]  (12.7ms) commit transaction User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "asd"]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d37813"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (17.6ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d38678"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (20.2ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"nonexistent-user"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "nonexistent-user"]] Completed 200 OK in 1ms (ActiveRecord: 0.2ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d34291"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (14.7ms) commit transaction  (0.7ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d3886"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (18.2ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d34291"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 4ms (Views: 4.0ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d38624"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (19.6ms) commit transaction  (0.1ms) begin transaction SQL (0.4ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d33089"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (17.3ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d38624"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d38624"]]  (0.2ms) begin transaction SQL (0.3ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 7]]  (14.4ms) commit transaction Completed 200 OK in 20ms (ActiveRecord: 15.1ms) User Load (0.5ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 7]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d31376"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (20.2ms) commit transaction  (0.2ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32084"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (17.0ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d31376"} User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d31376"]]  (0.1ms) begin transaction SQL (0.5ms) UPDATE "users" SET "email" = ?, "name" = ?, "permissions" = ?, "organisation_slug" = ?, "organisation_content_id" = ? WHERE "users"."id" = ? [["email", "user@domain.com"], ["name", "Joshua Marshall"], ["permissions", "---\n- signin\n- new permission\n"], ["organisation_slug", "justice-league"], ["organisation_content_id", "aae1319e-5788-4677-998c-f1a53af528d0"], ["id", 9]]  (14.3ms) commit transaction Completed 200 OK in 23ms (ActiveRecord: 15.2ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 9]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d36048"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (15.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d38714"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (14.2ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d36048"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 2ms (Views: 1.4ms | ActiveRecord: 0.0ms)