(35.9ms) CREATE TABLE "users" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar NOT NULL, "uid" varchar NOT NULL, "email" varchar NOT NULL, "remotely_signed_out" boolean, "permissions" text, "organisation_slug" varchar, "organisation_content_id" varchar, "disabled" boolean DEFAULT 'f')   (12.9ms) CREATE TABLE "schema_migrations" ("version" varchar NOT NULL)  (0.1ms) select sqlite_version(*)  (31.3ms) CREATE UNIQUE INDEX "unique_schema_migrations" ON "schema_migrations" ("version") 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.2ms) 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]]  (28.9ms) 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.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d35531"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (14.3ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d35203"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (11.2ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d35531"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 9ms (Views: 8.5ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d34549"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (37.0ms) commit transaction  (0.2ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d34041"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (25.5ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d34549"} User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d34549"]]  (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", 4]]  (14.2ms) commit transaction Completed 200 OK in 20ms (ActiveRecord: 14.7ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 4]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d38988"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (26.7ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d35119"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (10.9ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d38988"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.1ms) Completed 403 Forbidden in 1ms (Views: 0.6ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d39922"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (9.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d3547"], ["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"=>"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", "a1s2d35459"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (10.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d34974"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (10.4ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d35459"} User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d35459"]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 10]]  (32.2ms) commit transaction Completed 200 OK in 35ms (ActiveRecord: 32.6ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 10]] Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:28 +0000 Processing by ExampleController#restricted as JSON Completed in 126ms (ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:28 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]] User Load (0.1ms) 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) 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]]  (22.7ms) commit transaction User Load (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.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 SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "f"], ["id", 12]]  (20.5ms) commit transaction Rendered text template (0.0ms) Completed 200 OK in 238ms (Views: 1.5ms | ActiveRecord: 44.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:28 +0000 Processing by ExampleController#restricted as JSON Completed in 18ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:28 +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.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 77ms (Views: 0.4ms | ActiveRecord: 1.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:28 +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-11-25 13:43:28 +0000 Started GET "/auth/gds/callback?code=0406dfb10516969c1d7102990e91b9550ed0e008047d796666d1ec39a2eaab84&state=3ee46c89f5795b1b78505adce93de7186356f53217a16f0f" for 127.0.0.1 at 2016-11-25 13:43:40 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"0406dfb10516969c1d7102990e91b9550ed0e008047d796666d1ec39a2eaab84", "state"=>"3ee46c89f5795b1b78505adce93de7186356f53217a16f0f"} Authenticating with gds_sso strategy User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "disabled" = ? WHERE "users"."id" = ? [["disabled", "f"], ["id", 12]]  (14.3ms) 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 20ms (ActiveRecord: 14.9ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:40 +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.3ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:40 +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-11-25 13:43:40 +0000 Started GET "/auth/gds/callback?code=fb325e6a959f5b4ceb5f764cc26ce406d4b9cc94eed40f9fa08ddddc0a15cdd5&state=89f87e3d60b0acb5331152ca5ab604dba94898cbcb0a9f2c" for 127.0.0.1 at 2016-11-25 13:43:40 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"fb325e6a959f5b4ceb5f764cc26ce406d4b9cc94eed40f9fa08ddddc0a15cdd5", "state"=>"89f87e3d60b0acb5331152ca5ab604dba94898cbcb0a9f2c"} Authenticating with gds_sso strategy User Load (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  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 5ms (ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:40 +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 2ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:40 +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-11-25 13:43:40 +0000 Started GET "/auth/gds/callback?code=711606807dc7895ccb50ecf6d9c24d870400cac80b29f2b478be367053266b80&state=5ef7eedc4153066bb139dd97e198fc8c0c47f7f24c6ad82a" for 127.0.0.1 at 2016-11-25 13:43:40 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"711606807dc7895ccb50ecf6d9c24d870400cac80b29f2b478be367053266b80", "state"=>"5ef7eedc4153066bb139dd97e198fc8c0c47f7f24c6ad82a"} Authenticating with gds_sso strategy User Load (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  (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-11-25 13:43: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"]] Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:40 +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-11-25 13:43:40 +0000 Started GET "/auth/gds/callback?code=c7121cd1cea22a0d021cbdb4beef41fbeddc85b6bb0b8fd7268230456d5a573d&state=5eed248724c469fac15036a056c5d65e577790d7fe7b1e69" for 127.0.0.1 at 2016-11-25 13:43:40 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"c7121cd1cea22a0d021cbdb4beef41fbeddc85b6bb0b8fd7268230456d5a573d", "state"=>"5eed248724c469fac15036a056c5d65e577790d7fe7b1e69"} Authenticating with gds_sso strategy User Load (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  (0.1ms) begin transaction  (0.2ms) 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-11-25 13:43: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"]] Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/" for 127.0.0.1 at 2016-11-25 13:43:40 +0000 Processing by ExampleController#index as HTML Rendered text template (0.0ms) Completed 200 OK in 0ms (Views: 0.3ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:40 +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-11-25 13:43:40 +0000 Started GET "/auth/gds/callback?code=e273b6559260f3bd87eb3087e91a591c7902f3a7d089611b83811612afe110d7&state=b3fa9d11984ff8b4842f4e48662dd782783279dc6b99696b" for 127.0.0.1 at 2016-11-25 13:43:41 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"e273b6559260f3bd87eb3087e91a591c7902f3a7d089611b83811612afe110d7", "state"=>"b3fa9d11984ff8b4842f4e48662dd782783279dc6b99696b"} Authenticating with gds_sso strategy User Load (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  (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-11-25 13:43: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.5ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:41 +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-11-25 13:43:41 +0000 Started GET "/auth/gds/callback?code=c6a66a12344832afab9212d4e958f24b8afc11e916094fcd85c2e3f0a2c19ed0&state=ea7fb51110108ccc0bae549b117fdd085f59962ee2574d55" for 127.0.0.1 at 2016-11-25 13:43:41 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"c6a66a12344832afab9212d4e958f24b8afc11e916094fcd85c2e3f0a2c19ed0", "state"=>"ea7fb51110108ccc0bae549b117fdd085f59962ee2574d55"} Authenticating with gds_sso strategy User Load (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  (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-11-25 13:43: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 1ms (Views: 0.3ms | ActiveRecord: 0.1ms) User Load (0.1ms) 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.1ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 12]]  (32.1ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43: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"]] Authenticating with gds_sso strategy Completed in 1ms (ActiveRecord: 0.1ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-11-25 13:43:41 +0000 Started GET "/auth/gds/callback?code=91b37d0ce383321139a08eca982c84913d700302e93332efe20934390b11cefb&state=e31feeb10724049b767acdeb26b0e740815c99b933970a73" for 127.0.0.1 at 2016-11-25 13:43:41 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"91b37d0ce383321139a08eca982c84913d700302e93332efe20934390b11cefb", "state"=>"e31feeb10724049b767acdeb26b0e740815c99b933970a73"} 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", 12]]  (76.4ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 83ms (ActiveRecord: 77.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43: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.4ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43: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-11-25 13:43:41 +0000 Started GET "/auth/gds/callback?code=3b99a00462a1dfe651f70163d62ebf212b8f2f1efd089c2a86ff37db4246ea63&state=5244721127270573b884a62a75f352bbc73b9ff910a58055" for 127.0.0.1 at 2016-11-25 13:43:42 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"3b99a00462a1dfe651f70163d62ebf212b8f2f1efd089c2a86ff37db4246ea63", "state"=>"5244721127270573b884a62a75f352bbc73b9ff910a58055"} 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/restricted Completed 302 Found in 7ms (ActiveRecord: 0.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:42 +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-11-26 09:48:42 +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-11-26 09:48:42 +0000 Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:42 +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-11-25 13:43:42 +0000 Started GET "/auth/gds/callback?code=f28e50fefafb715670f3ddf85ead5a9fdf3164e254f40725781643754a7bd72e&state=e4fef793d433c8cbf96ea7ed2e6ce7c7a60a08a8947785ca" for 127.0.0.1 at 2016-11-25 13:43:42 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"f28e50fefafb715670f3ddf85ead5a9fdf3164e254f40725781643754a7bd72e", "state"=>"e4fef793d433c8cbf96ea7ed2e6ce7c7a60a08a8947785ca"} Authenticating with gds_sso strategy User Load (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  (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-11-25 13:43:42 +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-11-26 09:38:42 +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 1ms (Views: 0.2ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:42 +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-11-25 13:43:42 +0000 Started GET "/auth/gds/callback?code=6f7d011b37482536e90ab3d297ba7577b3e4b6db2297f06d1da2b0af5e7cd630&state=79f487227727059b4a1f1f3c11e85c063f4c80673f1c91b2" for 127.0.0.1 at 2016-11-25 13:43:42 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"6f7d011b37482536e90ab3d297ba7577b3e4b6db2297f06d1da2b0af5e7cd630", "state"=>"79f487227727059b4a1f1f3c11e85c063f4c80673f1c91b2"} Authenticating with gds_sso strategy User Load (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  (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-11-25 13:43:42 +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-11-26 09:48:42 +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-11-26 09:48:42 +0000 Started GET "/auth/gds/callback?code=88adb4c72e3a5a871dc1ba32021f4e7d210e6fac394e386579b5d9f1c3fdd553&state=4fea53313bf70e131656e8dd79083d763d4332b7e17cf8d2" for 127.0.0.1 at 2016-11-26 09:48:42 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"88adb4c72e3a5a871dc1ba32021f4e7d210e6fac394e386579b5d9f1c3fdd553", "state"=>"4fea53313bf70e131656e8dd79083d763d4332b7e17cf8d2"} 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-11-26 09:48:42 +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)  (29.8ms) CREATE TABLE "users" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar NOT NULL, "uid" varchar NOT NULL, "email" varchar NOT NULL, "remotely_signed_out" boolean, "permissions" text, "organisation_slug" varchar, "organisation_content_id" varchar, "disabled" boolean DEFAULT 'f')  (17.4ms) CREATE TABLE "ar_internal_metadata" ("key" varchar NOT NULL PRIMARY KEY, "value" varchar, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL) ActiveRecord::InternalMetadata Load (0.2ms) SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? LIMIT ? [["key", :environment], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES (?, ?, ?, ?) [["key", "environment"], ["value", "test"], ["created_at", 2016-11-25 13:43:49 UTC], ["updated_at", 2016-11-25 13:43:49 UTC]]  (17.1ms) commit transaction  (12.4ms) CREATE TABLE "schema_migrations" ("version" varchar NOT NULL PRIMARY KEY) ActiveRecord::InternalMetadata Load (0.2ms) SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? LIMIT ? [["key", :environment], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "asd"], ["LIMIT", 1]] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT ? [["email", "user@example.com"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions", "organisation_slug", "organisation_content_id", "disabled") VALUES (?, ?, ?, ?, ?, ?, ?) [["name", "A Name"], ["uid", "asd"], ["email", "user@example.com"], ["permissions", "---\n- signin\n"], ["organisation_slug", "hmrc"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["disabled", nil]]  (50.4ms) commit transaction User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "asd"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d37643"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (29.4ms) commit transaction  (0.1ms) begin transaction SQL (1.8ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d34253"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (26.6ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d37643"} Rendering /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.2ms) Completed 403 Forbidden in 9ms (Views: 8.7ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d39074"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (12.7ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d36182"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (34.5ms) 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 ? [["uid", "nonexistent-user"], ["LIMIT", 1]] Completed 200 OK in 1ms (ActiveRecord: 0.1ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d38554"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (18.3ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d39994"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (29.3ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d38554"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "a1s2d38554"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", true], ["id", 6]]  (47.6ms) commit transaction Completed 200 OK in 52ms (ActiveRecord: 48.0ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ? [["id", 6], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d39438"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (32.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d32962"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (22.7ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d39438"} Rendering /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.1ms) Completed 403 Forbidden in 1ms (Views: 0.9ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d32517"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (42.2ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d32395"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (59.3ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d32517"} User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "a1s2d32517"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) 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", 10]]  (41.8ms) commit transaction Completed 200 OK in 47ms (ActiveRecord: 42.3ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ? [["id", 10], ["LIMIT", 1]] Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:50 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 9ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-11-25 13:43:50 +0000 Started GET "/auth/gds/callback?code=20e5974b28bfda5733c3cf3ee87d0f8ac998ae732db51dcbd2cc21f94db3a7ca&state=89a9ffe6907fbf149376136993a1a3dd5fe6d97223b5fa83" for 127.0.0.1 at 2016-11-25 13:43:50 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"20e5974b28bfda5733c3cf3ee87d0f8ac998ae732db51dcbd2cc21f94db3a7ca", "state"=>"89a9ffe6907fbf149376136993a1a3dd5fe6d97223b5fa83"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]] User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT ? [["email", "test@example-client.com"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Test User"], ["uid", "integration-uid"], ["email", "test@example-client.com"], ["permissions", "---\n- signin\n"]]  (14.9ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", false], ["id", 12]]  (30.0ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 52ms (ActiveRecord: 45.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:50 +0000 Processing by ExampleController#restricted as HTML User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 5ms (Views: 2.2ms | ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:50 +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-11-25 13:43:50 +0000 Started GET "/auth/gds/callback?code=d9fce11583aecbac87e2f6d47bb6e16808e7975493bdf51cfff2486ed0c3ee6f&state=a314d62a587f324f4677a42240877eeafb1aa2868a6e8add" for 127.0.0.1 at 2016-11-25 13:43:51 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"d9fce11583aecbac87e2f6d47bb6e16808e7975493bdf51cfff2486ed0c3ee6f", "state"=>"a314d62a587f324f4677a42240877eeafb1aa2868a6e8add"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 5ms (ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:51 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-25 13:43:51 +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-11-25 13:43:51 +0000 Started GET "/auth/gds/callback?code=6e3eb4fa26ff4b043ec518a09c79e706aa089ed45f288298c49a230e5351d616&state=0c61be3bded0f5f657cd3d29653417788c385768c992d61d" for 127.0.0.1 at 2016-11-25 13:43:51 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"6e3eb4fa26ff4b043ec518a09c79e706aa089ed45f288298c49a230e5351d616", "state"=>"0c61be3bded0f5f657cd3d29653417788c385768c992d61d"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (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.6ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:51 +0000 Processing by ExampleController#this_requires_signin_permission as HTML User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.3ms) Started GET "/" for 127.0.0.1 at 2016-11-25 13:43:51 +0000 Processing by ExampleController#index as HTML Rendering text template Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.6ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:51 +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-11-25 13:43:51 +0000 Started GET "/auth/gds/callback?code=fc3efc5ff3e6060cea9e71bb6e6f3e4a80fc3d949453918978e3f2438d96aa76&state=8841e8604f5e521c89e68560267b5ac26804f9f55030e105" for 127.0.0.1 at 2016-11-25 13:43:51 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"fc3efc5ff3e6060cea9e71bb6e6f3e4a80fc3d949453918978e3f2438d96aa76", "state"=>"8841e8604f5e521c89e68560267b5ac26804f9f55030e105"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:51 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-25 13:43:51 +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-11-25 13:43:51 +0000 Started GET "/auth/gds/callback?code=37e4f12f3139b7f09ca5138a666348adbe2de9fef12018724e8c9b4599e50f1b&state=d0de14ea6a33f30df7db5659413a176dfc1e367582af40f6" for 127.0.0.1 at 2016-11-25 13:43:51 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"37e4f12f3139b7f09ca5138a666348adbe2de9fef12018724e8c9b4599e50f1b", "state"=>"d0de14ea6a33f30df7db5659413a176dfc1e367582af40f6"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:51 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:51 +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-11-25 13:43:51 +0000 Started GET "/auth/gds/callback?code=6c9bfeb102f4e0e1120398cfc1c1c31cba3f4cb3f85ff8ae0385a0f0e995ce04&state=9093f73a23bcecce0e2c374cdbf37f0108cae9bbc6754520" for 127.0.0.1 at 2016-11-25 13:43:52 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"6c9bfeb102f4e0e1120398cfc1c1c31cba3f4cb3f85ff8ae0385a0f0e995ce04", "state"=>"9093f73a23bcecce0e2c374cdbf37f0108cae9bbc6754520"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:52 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-26 09:38:52 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-25 13:43:52 +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-11-25 13:43:52 +0000 Started GET "/auth/gds/callback?code=c63978b042d97f8a745efc08a3432c13a07692fbedbc4079044b7844dff0d7e8&state=6c8246395eb6eb3393b389ac551e2522b7d8e70684d8f22e" for 127.0.0.1 at 2016-11-25 13:43:52 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"c63978b042d97f8a745efc08a3432c13a07692fbedbc4079044b7844dff0d7e8", "state"=>"6c8246395eb6eb3393b389ac551e2522b7d8e70684d8f22e"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:52 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-26 09:48:52 +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-11-26 09:48:52 +0000 Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:52 +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-11-25 13:43:52 +0000 Started GET "/auth/gds/callback?code=5229ba82ef286c3fde70ffe4fbef3a21d7c703461e48c72ddee14bcb62071076&state=333d26dd26654d38e2a6868b68a341568167fec3d698aa6e" for 127.0.0.1 at 2016-11-25 13:43:52 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"5229ba82ef286c3fde70ffe4fbef3a21d7c703461e48c72ddee14bcb62071076", "state"=>"333d26dd26654d38e2a6868b68a341568167fec3d698aa6e"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:52 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-26 09:48:52 +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-11-26 09:48:52 +0000 Started GET "/auth/gds/callback?code=f05a8b4e9102c7eba4fcfcf26b7e9524a7d172427b7765b328cd52a0f107cd38&state=1f8e53a7b16af9400f9234ee26b862d0a56e7b78e8e8b39b" for 127.0.0.1 at 2016-11-26 09:48:52 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"f05a8b4e9102c7eba4fcfcf26b7e9524a7d172427b7765b328cd52a0f107cd38", "state"=>"1f8e53a7b16af9400f9234ee26b862d0a56e7b78e8e8b39b"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-26 09:48:52 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.5ms | ActiveRecord: 0.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:52 +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-11-25 13:43:52 +0000 Started GET "/auth/gds/callback?code=7e818e1c5c01ac8cd30f5b96e84dcb6e0c72ed8b51e4d25ed4db93c9171ca963&state=a14348956a612958a57fd91a9a5624bdf87c587d20624e33" for 127.0.0.1 at 2016-11-25 13:43:52 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"7e818e1c5c01ac8cd30f5b96e84dcb6e0c72ed8b51e4d25ed4db93c9171ca963", "state"=>"a14348956a612958a57fd91a9a5624bdf87c587d20624e33"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (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-11-25 13:43:53 +0000 Processing by ExampleController#restricted as HTML User Load (0.7ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? AND "users"."remotely_signed_out" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.5ms | ActiveRecord: 0.7ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT ? [["email", "test@example-client.com"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", true], ["id", 12]]  (20.1ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:53 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Authenticating with gds_sso strategy Completed in 2ms (ActiveRecord: 0.2ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-11-25 13:43:53 +0000 Started GET "/auth/gds/callback?code=5e28167f5be69dda4b0fe3984973b050e9bd032d369589588e6aeda3d3a5c0e1&state=997f9516ea7ec6ebfe79b80b62812c32aaa75d4a2db1015f" for 127.0.0.1 at 2016-11-25 13:43:53 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"5e28167f5be69dda4b0fe3984973b050e9bd032d369589588e6aeda3d3a5c0e1", "state"=>"997f9516ea7ec6ebfe79b80b62812c32aaa75d4a2db1015f"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction  (0.1ms) begin transaction SQL (0.5ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", false], ["id", 12]]  (27.5ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 34ms (ActiveRecord: 28.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:53 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:43:53 +0000 Processing by ExampleController#this_requires_signin_permission as JSON User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "disabled" = ? WHERE "users"."id" = ? [["disabled", nil], ["id", 12]]  (20.6ms) commit transaction User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Rendering text template Rendered text template (0.0ms) Completed 200 OK in 99ms (Views: 0.6ms | ActiveRecord: 22.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:53 +0000 Processing by ExampleController#restricted as JSON User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.3ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Rendering text template Rendered text template (0.0ms) Completed 200 OK in 80ms (Views: 0.4ms | ActiveRecord: 1.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:53 +0000 Processing by ExampleController#restricted as JSON Completed in 18ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:53 +0000 Processing by ExampleController#restricted as JSON Completed in 16ms (ActiveRecord: 0.0ms)  (200.3ms) CREATE TABLE "users" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar NOT NULL, "uid" varchar NOT NULL, "email" varchar NOT NULL, "remotely_signed_out" boolean, "permissions" text, "organisation_slug" varchar, "organisation_content_id" varchar, "disabled" boolean DEFAULT 'f')   (164.7ms) CREATE TABLE "schema_migrations" ("version" varchar NOT NULL)  (0.4ms) select sqlite_version(*)  (138.1ms) CREATE UNIQUE INDEX "unique_schema_migrations" ON "schema_migrations" ("version")  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d31425"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (158.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d39436"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (132.1ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d31425"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 9ms (Views: 8.9ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d36156"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (226.6ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d37890"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (177.0ms) 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 6ms (ActiveRecord: 0.2ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d38533"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (126.1ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d36126"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (124.6ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d38533"} User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d38533"]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "t"], ["id", 5]]  (125.8ms) commit transaction Completed 200 OK in 130ms (ActiveRecord: 126.2ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 5]]  (0.1ms) begin transaction SQL (0.1ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32438"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (184.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32890"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (250.4ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d32438"} Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.1ms) Completed 403 Forbidden in 1ms (Views: 0.5ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d32914"], ["email", "old@domain.com"], ["name", "Moshua Jarshall"], ["permissions", "---\n- signin\n"]]  (85.4ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "a1s2d33322"], ["email", "ssopushuser@legit.com"], ["name", "SSO Push user"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (121.6ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d32914"} User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "a1s2d32914"]]  (0.1ms) begin transaction SQL (0.2ms) 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]]  (83.7ms) commit transaction Completed 200 OK in 88ms (ActiveRecord: 84.1ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 9]] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "asd"]] User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT 1 [["email", "user@example.com"]]  (0.1ms) begin transaction SQL (0.2ms) 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]]  (66.5ms) 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 Started GET "/" for 127.0.0.1 at 2016-11-25 13:43:59 +0000 Processing by ExampleController#index as HTML Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 1.0ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:43:59 +0000 Processing by ExampleController#restricted as HTML Authenticating with gds_sso strategy Completed in 9ms (ActiveRecord: 0.0ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-11-25 13:43:59 +0000 Started GET "/auth/gds/callback?code=f26bab61e3821688dbabf19d7350ce7439de62c6234faac4c5576e87a30d76a4&state=3c86a804ac28c20971241bd0f80807ffe7d57bc37cf6bb9d" for 127.0.0.1 at 2016-11-25 13:44:00 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"f26bab61e3821688dbabf19d7350ce7439de62c6234faac4c5576e87a30d76a4", "state"=>"3c86a804ac28c20971241bd0f80807ffe7d57bc37cf6bb9d"} Authenticating with gds_sso strategy User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]] User Load (0.1ms) 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) INSERT INTO "users" ("uid", "email", "name", "permissions") VALUES (?, ?, ?, ?) [["uid", "integration-uid"], ["email", "test@example-client.com"], ["name", "Test User"], ["permissions", "---\n- signin\n"]]  (252.9ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", "f"], ["id", 12]]  (246.9ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 507ms (ActiveRecord: 500.6ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:00 +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) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:00 +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-11-25 13:44:00 +0000 Started GET "/auth/gds/callback?code=55112b3e0436989f0cc684e21124051dc9a0c4985ba5bd0c0a3377079f728642&state=9f2d78f675b870239ed1b7178276eedfd6c16aaea1d543e4" for 127.0.0.1 at 2016-11-25 13:44:00 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"55112b3e0436989f0cc684e21124051dc9a0c4985ba5bd0c0a3377079f728642", "state"=>"9f2d78f675b870239ed1b7178276eedfd6c16aaea1d543e4"} 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-11-25 13:44:01 +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-11-25 13:44:01 +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-11-25 13:44:01 +0000 Started GET "/auth/gds/callback?code=97fe3c4a409a4abe1419ac55c829f11c81aafe6b9d2c649676c180aee5c24750&state=e48e84d3df03d4468e1ab954d55b0486b92fb3e20c979a6f" for 127.0.0.1 at 2016-11-25 13:44:01 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"97fe3c4a409a4abe1419ac55c829f11c81aafe6b9d2c649676c180aee5c24750", "state"=>"e48e84d3df03d4468e1ab954d55b0486b92fb3e20c979a6f"} 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 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:01 +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 1ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:01 +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-11-25 13:44:01 +0000 Started GET "/auth/gds/callback?code=b720f5c47ad488aa3c2aa6a9c40b0d98685c585dd69abf70b5a096e9b027a5ec&state=e3797714256bd03d1b17dd097aba01c38ca2d39b404009fa" for 127.0.0.1 at 2016-11-25 13:44:01 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"b720f5c47ad488aa3c2aa6a9c40b0d98685c585dd69abf70b5a096e9b027a5ec", "state"=>"e3797714256bd03d1b17dd097aba01c38ca2d39b404009fa"} 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 5ms (ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:01 +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 2ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:01 +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-11-25 13:44:01 +0000 Started GET "/auth/gds/callback?code=1c66b2bc93853363593ce073ddc618681ff20b2bc038e1326e99088b0a7bb8ae&state=644fa6b26ac85fcbeaf539b0a3b42bdc98118ee7ad3a0fb0" for 127.0.0.1 at 2016-11-25 13:44:01 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"1c66b2bc93853363593ce073ddc618681ff20b2bc038e1326e99088b0a7bb8ae", "state"=>"644fa6b26ac85fcbeaf539b0a3b42bdc98118ee7ad3a0fb0"} Authenticating with gds_sso strategy User Load (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  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:01 +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 1ms (Views: 0.3ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:01 +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-11-25 13:44:01 +0000 Started GET "/auth/gds/callback?code=0eef37849744379db73f6df0c3a9c1ab11cc6c0454e8ec59f6c624edc9a3d83d&state=3fac31e26fef953d07e1ea1a622e890654fcd4be2be1971f" for 127.0.0.1 at 2016-11-25 13:44:01 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"0eef37849744379db73f6df0c3a9c1ab11cc6c0454e8ec59f6c624edc9a3d83d", "state"=>"3fac31e26fef953d07e1ea1a622e890654fcd4be2be1971f"} Authenticating with gds_sso strategy User Load (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  (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-11-25 13:44:01 +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-11-26 09:49:01 +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-11-26 09:49:01 +0000 Started GET "/auth/gds/callback?code=4a535912bbaf726c29f2ba86838fa2508865787d2c2f97a34de60fc2db09577d&state=e2593e5b8190f1f67f5bb52ed37c69f96671e51442786701" for 127.0.0.1 at 2016-11-26 09:49:02 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"4a535912bbaf726c29f2ba86838fa2508865787d2c2f97a34de60fc2db09577d", "state"=>"e2593e5b8190f1f67f5bb52ed37c69f96671e51442786701"} 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.3ms) 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.7ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-26 09:49:02 +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.1ms) Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.1ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:02 +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-11-25 13:44:02 +0000 Started GET "/auth/gds/callback?code=9f1f0a040a9a52aafc0f018f32e878ebe193a739f6da233a6d5ac70832085d5b&state=3e8d2364176666119009c02519aca7cdcd154c763e9e7f98" for 127.0.0.1 at 2016-11-25 13:44:02 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"9f1f0a040a9a52aafc0f018f32e878ebe193a739f6da233a6d5ac70832085d5b", "state"=>"3e8d2364176666119009c02519aca7cdcd154c763e9e7f98"} Authenticating with gds_sso strategy User Load (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  (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-11-25 13:44:02 +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-11-26 09:49:02 +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-11-26 09:49:02 +0000 Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:02 +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-11-25 13:44:02 +0000 Started GET "/auth/gds/callback?code=e6182dd9a8a4c90de0bc3778feda841b03003ec8a1f0dcaed046d030468b0709&state=745b5439b70881cd8057544a5f32d6541adef54c55dd5ad2" for 127.0.0.1 at 2016-11-25 13:44:02 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"e6182dd9a8a4c90de0bc3778feda841b03003ec8a1f0dcaed046d030468b0709", "state"=>"745b5439b70881cd8057544a5f32d6541adef54c55dd5ad2"} 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-11-25 13:44:02 +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-11-26 09:39:02 +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-11-25 13:44:02 +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-11-25 13:44:02 +0000 Started GET "/auth/gds/callback?code=ac6ea4384f64b9ff95c2684f4337e55fa0175f6b72600ca38778264694814fb3&state=23e2e2d01dfa08ccb5ed2fc4e734a847a5e11b7236ccf6e9" for 127.0.0.1 at 2016-11-25 13:44:02 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"ac6ea4384f64b9ff95c2684f4337e55fa0175f6b72600ca38778264694814fb3", "state"=>"23e2e2d01dfa08ccb5ed2fc4e734a847a5e11b7236ccf6e9"} 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-11-25 13:44:02 +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 1ms (Views: 0.3ms | ActiveRecord: 0.1ms) User Load (0.1ms) 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", 12]]  (164.2ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:03 +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-11-25 13:44:03 +0000 Started GET "/auth/gds/callback?code=63614c1ec3e831218c836cd59d6e2831e1001797e39509a7acae36083adab320&state=8d27838d7bb70a65ce13441a30b11400f817e91f9886cb7b" for 127.0.0.1 at 2016-11-25 13:44:03 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"63614c1ec3e831218c836cd59d6e2831e1001797e39509a7acae36083adab320", "state"=>"8d27838d7bb70a65ce13441a30b11400f817e91f9886cb7b"} 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", 12]]  (163.5ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 169ms (ActiveRecord: 164.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:03 +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-11-25 13:44:03 +0000 Processing by ExampleController#restricted as JSON Completed in 18ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:03 +0000 Processing by ExampleController#restricted as JSON User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT 1 [["uid", "integration-uid"]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "disabled" = ? WHERE "users"."id" = ? [["disabled", nil], ["id", 12]]  (190.5ms) commit transaction User Load (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 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 261ms (Views: 0.3ms | ActiveRecord: 191.8ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:03 +0000 Processing by ExampleController#restricted as JSON Completed in 16ms (ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:03 +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.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 69ms (Views: 0.3ms | ActiveRecord: 1.0ms)  (134.4ms) CREATE TABLE "users" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar NOT NULL, "uid" varchar NOT NULL, "email" varchar NOT NULL, "remotely_signed_out" boolean, "permissions" text, "organisation_slug" varchar, "organisation_content_id" varchar, "disabled" boolean DEFAULT 'f')  (115.1ms) CREATE TABLE "ar_internal_metadata" ("key" varchar NOT NULL PRIMARY KEY, "value" varchar, "created_at" datetime NOT NULL, "updated_at" datetime NOT NULL) ActiveRecord::InternalMetadata Load (0.2ms) SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? LIMIT ? [["key", :environment], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES (?, ?, ?, ?) [["key", "environment"], ["value", "test"], ["created_at", 2016-11-25 13:44:07 UTC], ["updated_at", 2016-11-25 13:44:07 UTC]]  (157.5ms) commit transaction  (70.9ms) CREATE TABLE "schema_migrations" ("version" varchar NOT NULL PRIMARY KEY) ActiveRecord::InternalMetadata Load (0.2ms) SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? LIMIT ? [["key", :environment], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:08 +0000 Processing by ExampleController#restricted as JSON User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT ? [["email", "test@example-client.com"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("name", "uid", "email", "permissions", "disabled") VALUES (?, ?, ?, ?, ?) [["name", "Test User"], ["uid", "integration-uid"], ["email", "test@example-client.com"], ["permissions", "---\n- signin\n"], ["disabled", nil]]  (154.1ms) commit transaction User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (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", false], ["id", 1]]  (131.7ms) commit transaction Rendering text template Rendered text template (0.0ms) Completed 200 OK in 390ms (Views: 3.6ms | ActiveRecord: 288.2ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:08 +0000 Processing by ExampleController#restricted as JSON Completed in 25ms (ActiveRecord: 0.0ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:08 +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 ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction CACHE (0.0ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Rendering text template Rendered text template (0.0ms) Completed 200 OK in 91ms (Views: 0.4ms | ActiveRecord: 1.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:08 +0000 Processing by ExampleController#restricted as JSON Completed in 18ms (ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44: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-11-25 13:44:08 +0000 Started GET "/auth/gds/callback?code=c0a84b9848298a9f262a09a67e03b82a3ddb2e11d32349af67a134f2a8c1df54&state=785ca430b12fe07e5ebbd5d2576cf8d9adaaec586d9b8741" for 127.0.0.1 at 2016-11-25 13:44:08 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"c0a84b9848298a9f262a09a67e03b82a3ddb2e11d32349af67a134f2a8c1df54", "state"=>"785ca430b12fe07e5ebbd5d2576cf8d9adaaec586d9b8741"} Authenticating with gds_sso strategy User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "disabled" = ? WHERE "users"."id" = ? [["disabled", false], ["id", 1]]  (104.4ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 109ms (ActiveRecord: 104.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:09 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 3ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:09 +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-11-25 13:44:09 +0000 Started GET "/auth/gds/callback?code=bf76d7f035ac8073a3a23d377ad10f341fd99cb317858d7c202b232a4fbf8ee8&state=4c6e9f8c2ab2cf114c8af1aa29e839c88763904579134b18" for 127.0.0.1 at 2016-11-25 13:44:09 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"bf76d7f035ac8073a3a23d377ad10f341fd99cb317858d7c202b232a4fbf8ee8", "state"=>"4c6e9f8c2ab2cf114c8af1aa29e839c88763904579134b18"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:09 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:09 +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-11-25 13:44:09 +0000 Started GET "/auth/gds/callback?code=3a117361caf80c06abc97a5c61eeef6d1b530ab6838b74848703417769f377df&state=37ba9999028828876033494d9ef60de447771819b102f542" for 127.0.0.1 at 2016-11-25 13:44:09 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"3a117361caf80c06abc97a5c61eeef6d1b530ab6838b74848703417769f377df", "state"=>"37ba9999028828876033494d9ef60de447771819b102f542"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/this_requires_signin_permission Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/this_requires_signin_permission" for 127.0.0.1 at 2016-11-25 13:44:09 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-25 13:44:09 +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-11-25 13:44:09 +0000 Started GET "/auth/gds/callback?code=b7eae245485328e121e9325ae16ed83aa90f00cecccb5a12e8e16d96602811f0&state=6e18b7da44b64322b9feebfd747f8ab38f8b988ce94a6d66" for 127.0.0.1 at 2016-11-25 13:44:09 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"b7eae245485328e121e9325ae16ed83aa90f00cecccb5a12e8e16d96602811f0", "state"=>"6e18b7da44b64322b9feebfd747f8ab38f8b988ce94a6d66"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:09 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-25 13:44:09 +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-11-25 13:44:09 +0000 Started GET "/auth/gds/callback?code=2b981d35b8370b19479ffec3ca76bfbce2e8e96b5625373767de621054930664&state=c20b030e32057395dc69e18b12c5590d943a9c21c905e5fe" for 127.0.0.1 at 2016-11-25 13:44:10 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"2b981d35b8370b19479ffec3ca76bfbce2e8e96b5625373767de621054930664", "state"=>"c20b030e32057395dc69e18b12c5590d943a9c21c905e5fe"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:10 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.2ms) Started GET "/" for 127.0.0.1 at 2016-11-25 13:44:10 +0000 Processing by ExampleController#index as HTML Rendering text template Rendered text template (0.0ms) Completed 200 OK in 0ms (Views: 0.3ms | ActiveRecord: 0.0ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:10 +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-11-25 13:44:10 +0000 Started GET "/auth/gds/callback?code=a64ee593600313a329104a3a301b885c4de72ca20bbe395c228a31d5637084ac&state=75e9cc0fb0abcde491c545a4ba1f08a2bf1d3c680c80d08d" for 127.0.0.1 at 2016-11-25 13:44:10 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"a64ee593600313a329104a3a301b885c4de72ca20bbe395c228a31d5637084ac", "state"=>"75e9cc0fb0abcde491c545a4ba1f08a2bf1d3c680c80d08d"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:10 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.2ms) User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT ? [["email", "test@example-client.com"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", true], ["id", 1]]  (165.7ms) commit transaction Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:10 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Authenticating with gds_sso strategy Completed in 2ms (ActiveRecord: 0.2ms) Started GET "/auth/gds" for 127.0.0.1 at 2016-11-25 13:44:10 +0000 Started GET "/auth/gds/callback?code=199a427dacb6ebb4bf71a3f78b261a7f56023326646be791b959f8facbd9674f&state=9c1046561c80184c37b0816b5b556aaae34b9472253dc571" for 127.0.0.1 at 2016-11-25 13:44:10 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"199a427dacb6ebb4bf71a3f78b261a7f56023326646be791b959f8facbd9674f", "state"=>"9c1046561c80184c37b0816b5b556aaae34b9472253dc571"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (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", false], ["id", 1]]  (127.2ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 133ms (ActiveRecord: 127.9ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:10 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:10 +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-11-25 13:44:10 +0000 Started GET "/auth/gds/callback?code=ba207418b730acd401f90e2ab7767fea110b029de02e40b28b4f5cfb6229a568&state=a58aef958e400d846df3c30d2ac822763d9b1af234c5ae37" for 127.0.0.1 at 2016-11-25 13:44:11 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"ba207418b730acd401f90e2ab7767fea110b029de02e40b28b4f5cfb6229a568", "state"=>"a58aef958e400d846df3c30d2ac822763d9b1af234c5ae37"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:11 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-26 09:49:11 +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-11-26 09:49:11 +0000 Started GET "/auth/gds/callback?code=ba733aaa5e6f5cfd68f43b6d4dcac0b56dc9a824902757b03989f0333dd4929c&state=ab9b252c55e0213badba6ab4d9edd9ea658515cd496c6793" for 127.0.0.1 at 2016-11-26 09:49:11 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"ba733aaa5e6f5cfd68f43b6d4dcac0b56dc9a824902757b03989f0333dd4929c", "state"=>"ab9b252c55e0213badba6ab4d9edd9ea658515cd496c6793"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 12ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-26 09:49:11 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-25 13:44:11 +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-11-25 13:44:11 +0000 Started GET "/auth/gds/callback?code=cadac2fc142b359cec8bce949fe53f95466e5f47dc876f961f2588ae806888a0&state=43710693a55e9165b8307f7c12d7a9fdd4cc03b5a63281ed" for 127.0.0.1 at 2016-11-25 13:44:11 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"cadac2fc142b359cec8bce949fe53f95466e5f47dc876f961f2588ae806888a0", "state"=>"43710693a55e9165b8307f7c12d7a9fdd4cc03b5a63281ed"} Authenticating with gds_sso strategy User Load (0.4ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.5ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:11 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.3ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-26 09:49:11 +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-11-26 09:49:11 +0000 Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:11 +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-11-25 13:44:11 +0000 Started GET "/auth/gds/callback?code=e97c1923e96ebde4a13a7f6c5bac17afdacae87a877be9cf19b2dacb2bbf008b&state=bbf26cdc855f5873a40f06c8f4806ce2de391f64600ef839" for 127.0.0.1 at 2016-11-25 13:44:11 +0000 Processing by AuthenticationsController#callback as HTML Parameters: {"code"=>"e97c1923e96ebde4a13a7f6c5bac17afdacae87a877be9cf19b2dacb2bbf008b", "state"=>"bbf26cdc855f5873a40f06c8f4806ce2de391f64600ef839"} Authenticating with gds_sso strategy User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "integration-uid"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.1ms) commit transaction Redirected to http://www.example-client.com/restricted Completed 302 Found in 4ms (ActiveRecord: 0.4ms) Started GET "/restricted" for 127.0.0.1 at 2016-11-25 13:44:11 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template 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-11-26 09:39:11 +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 ? [["uid", "integration-uid"], ["remotely_signed_out", false], ["LIMIT", 1]] Rendering text template Rendered text template (0.0ms) Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.2ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d39"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (107.7ms) commit transaction  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d38982"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (136.9ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d39"} Rendering /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.3ms) Completed 403 Forbidden in 8ms (Views: 6.9ms | ActiveRecord: 0.0ms)  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d36889"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (87.2ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d31361"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (83.9ms) commit transaction Processing by Api::UserController#update as HTML Parameters: {"uid"=>"a1s2d36889"} User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "a1s2d36889"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) 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", 4]]  (70.7ms) commit transaction Completed 200 OK in 76ms (ActiveRecord: 71.2ms) User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ? [["id", 4], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d34414"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (100.0ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d33706"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (81.0ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d34414"} User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "a1s2d34414"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) UPDATE "users" SET "remotely_signed_out" = ? WHERE "users"."id" = ? [["remotely_signed_out", true], ["id", 6]]  (165.0ms) commit transaction Completed 200 OK in 169ms (ActiveRecord: 165.5ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ? [["id", 6], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d37344"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (92.8ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d36432"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (129.2ms) 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 ? [["uid", "nonexistent-user"], ["LIMIT", 1]] Completed 200 OK in 2ms (ActiveRecord: 0.1ms)  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "Moshua Jarshall"], ["uid", "a1s2d33449"], ["email", "old@domain.com"], ["permissions", "---\n- signin\n"]]  (144.5ms) commit transaction  (0.1ms) begin transaction SQL (0.2ms) INSERT INTO "users" ("name", "uid", "email", "permissions") VALUES (?, ?, ?, ?) [["name", "SSO Push user"], ["uid", "a1s2d32843"], ["email", "ssopushuser@legit.com"], ["permissions", "---\n- signin\n- user_update_permission\n"]]  (164.9ms) commit transaction Processing by Api::UserController#reauth as HTML Parameters: {"uid"=>"a1s2d33449"} Rendering /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised Rendered /home/jenkins/workspace/govuk_gds_sso/app/views/authorisations/unauthorised.html.erb within layouts/unauthorised (0.1ms) Completed 403 Forbidden in 2ms (Views: 0.6ms | ActiveRecord: 0.0ms) User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "asd"], ["LIMIT", 1]] User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."email" = ? ORDER BY "users"."id" ASC LIMIT ? [["email", "user@example.com"], ["LIMIT", 1]]  (0.1ms) begin transaction SQL (0.3ms) INSERT INTO "users" ("name", "uid", "email", "permissions", "organisation_slug", "organisation_content_id", "disabled") VALUES (?, ?, ?, ?, ?, ?, ?) [["name", "A Name"], ["uid", "asd"], ["email", "user@example.com"], ["permissions", "---\n- signin\n"], ["organisation_slug", "hmrc"], ["organisation_content_id", "67a2b78d-eee3-45b3-80e2-792e7f71cecc"], ["disabled", nil]]  (273.2ms) commit transaction User Load (0.1ms) SELECT "users".* FROM "users" WHERE "users"."uid" = ? ORDER BY "users"."id" ASC LIMIT ? [["uid", "asd"], ["LIMIT", 1]]  (0.1ms) begin transaction  (0.3ms) commit transaction