I've been dealing with a set of failures where a VCR-enabled test adds an additional record to my Projects table, and that record persists across additional tests, causing failures, rather than being rolled back at the end of the test. Specifically, I have 4 Projects created by my Rails fixtures, and then a test that includes a VCR cassette to add an additional project. That test always passes, but the database does not reset to the 4 projects afterwards.
Conveniently, the project is open source, so you can run it yourself. The bug can be seen on master at https://github.com/linuxfoundation/cii-best-practices-badge (checkout commit 048776f so as not to get a temporary workaround) . The test causing the problem is https://github.com/linuxfoundation/cii-best-practices-badge/blob/master/test/features/github_login_test.rb which (with a VCR cassette) logs into Github and fetches the list of public projects from a test user. It is using Capybara via the https://github.com/blowmage/minitest-rails-capybara gem.
When run with SEED=41779 rake test, the VCR-using test succeeds, but a later test fails because it counts 5 rather than 4 projects.
Here is the test log, where you can see that a ROLLBACK is called at the end but a SAVEPOINT was never specified at the beginning of the test.
---------------------------------------------------
GithubLoginTest: test_0001_Has link to GitHub Login
---------------------------------------------------
Started GET "/" for 127.0.0.1 at 2016-05-30 22:02:03 -0400
Processing by StaticPagesController#home as HTML
Rendered static_pages/home.html.erb within layouts/application (0.2ms)
Rendered layouts/_header.html.erb (0.5ms)
Rendered layouts/_footer.html.erb (1.3ms)
Completed 200 OK in 6ms (Views: 4.7ms | ActiveRecord: 0.0ms)
Started GET "/projects/new" for 127.0.0.1 at 2016-05-30 22:02:03 -0400
Processing by ProjectsController#new as HTML
Rendered sessions/new.html.erb (3.2ms)
Rendered projects/new.html.erb within layouts/application (8.6ms)
Rendered layouts/_header.html.erb (1.5ms)
Rendered layouts/_footer.html.erb (1.9ms)
Completed 200 OK in 28ms (Views: 25.0ms | ActiveRecord: 0.0ms)
Started POST "/auth/github" for 127.0.0.1 at 2016-05-30 22:02:03 -0400
Started GET "/auth/github/callback" for 127.0.0.1 at 2016-05-30 22:02:03 -0400
Processing by SessionsController#create as HTML
Parameters: {"provider"=>"github"}
[1m[36mUser Load (0.3ms)[0m [1mSELECT "users".* FROM "users" WHERE "users"."provider" = $1 AND "users"."uid" = $2 LIMIT 1[0m [["provider", "github"], ["uid", "12345"]]
[1m[35m (0.1ms)[0m BEGIN
[1m[36mSQL (0.5ms)[0m [1mINSERT INTO "users" ("provider", "uid", "name", "email", "nickname", "activated", "created_at", "updated_at", "activation_digest") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id"[0m [["provider", "github"], ["uid", "12345"], ["name", "CII Test"], ["email", "test@example.com"], ["nickname", "CIITheRobot"], ["activated", "t"], ["created_at", "2016-05-31 02:02:03.288717"], ["updated_at", "2016-05-31 02:02:03.288717"], ["activation_digest", "$2a$04$BhFbVTS54Yeeurh83VBmdOs.T30jvliDmEFIQ6/lMpnhpN7rGvVTW"]]
[1m[35m (0.3ms)[0m COMMIT
Redirected to http://127.0.0.1:31337/
[1m[36mUser Load (0.3ms)[0m [1mSELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1[0m [["id", 764040364]]
Completed 302 Found in 11ms (ActiveRecord: 1.5ms)
Started GET "/" for 127.0.0.1 at 2016-05-30 22:02:03 -0400
Processing by StaticPagesController#home as HTML
[1m[35mUser Load (0.2ms)[0m SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1 [["id", 764040364]]
Rendered static_pages/home.html.erb within layouts/application (0.2ms)
Rendered layouts/_header.html.erb (0.6ms)
Rendered layouts/_footer.html.erb (1.2ms)
Completed 200 OK in 6ms (Views: 4.3ms | ActiveRecord: 0.2ms)
Started GET "/projects/new" for 127.0.0.1 at 2016-05-30 22:02:03 -0400
Processing by ProjectsController#new as HTML
[1m[36mUser Load (0.2ms)[0m [1mSELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1[0m [["id", 764040364]]
Rendered shared/_error_messages.html.erb (0.6ms)
Rendered projects/new.html.erb within layouts/application (31.6ms)
Rendered layouts/_header.html.erb (1.0ms)
Rendered layouts/_footer.html.erb (1.8ms)
Completed 200 OK in 41ms (Views: 38.6ms | ActiveRecord: 0.2ms)
Started POST "/projects" for 127.0.0.1 at 2016-05-30 22:02:03 -0400
Processing by ProjectsController#create as HTML
Parameters: {"utf8"=>"✓", "project"=>{"repo_url"=>"https://github.com/ciitest/cii-best-practices-badge"}, "commit"=>"Submit GitHub Repository"}
[1m[35mUser Load (0.4ms)[0m SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1 [["id", 764040364]]
[1m[36mProject Exists (0.6ms)[0m [1mSELECT 1 AS one FROM "projects" WHERE "projects"."repo_url" = $1 LIMIT 1[0m [["repo_url", "https://github.com/ciitest/cii-best-practices-badge"]]
[1m[35m (0.2ms)[0m BEGIN
[1m[36mProject Exists (0.6ms)[0m [1mSELECT 1 AS one FROM "projects" WHERE "projects"."repo_url" = 'https://github.com/ciitest/cii-best-practices-badge' LIMIT 1[0m
[1m[35mSQL (1.0ms)[0m INSERT INTO "projects" ("repo_url", "user_id", "homepage_url", "name", "sites_https_status", "sites_https_justification", "repo_public_status", "repo_public_justification", "repo_track_status", "repo_track_justification", "repo_distributed_status", "repo_distributed_justification", "contribution_status", "contribution_justification", "discussion_status", "discussion_justification", "license_location_status", "license_location_justification", "release_notes_status", "release_notes_justification", "build_status", "build_justification", "build_common_tools_status", "build_common_tools_justification", "badge_percentage", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22, $23, $24, $25, $26, $27) RETURNING "id" [["repo_url", "https://github.com/ciitest/cii-best-practices-badge"], ["user_id", 764040364], ["homepage_url", "https://bestpractices.coreinfrastructure.org"], ["name", "Core Infrastructure Initiative Best Practices Badge"], ["sites_https_status", "Met"], ["sites_https_justification", "Given only https: URLs."], ["repo_public_status", "Met"], ["repo_public_justification", "Repository on GitHub, which provides public git repositories with URLs."], ["repo_track_status", "Met"], ["repo_track_justification", "Repository on GitHub, which uses git. git can track the changes, who made them, and when they were made."], ["repo_distributed_status", "Met"], ["repo_distributed_justification", "Repository on GitHub, which uses git. git is distributed."], ["contribution_status", "Met"], ["contribution_justification", "Non-trivial contribution file in repository: <https://github.com/ciitest/cii-best-practices-badge/blob/master/CONTRIBUTING.md>."], ["discussion_status", "Met"], ["discussion_justification", "GitHub supports discussions on issues and pull requests."], ["license_location_status", "Met"], ["license_location_justification", "Non-trivial license location file in repository: <https://github.com/ciitest/cii-best-practices-badge/blob/master/LICENSE>."], ["release_notes_status", "Met"], ["release_notes_justification", "Non-trivial release notes file in repository: <https://github.com/ciitest/cii-best-practices-badge/blob/master/CHANGELOG.md>."], ["build_status", "Met"], ["build_justification", "Non-trivial build file in repository: <https://github.com/ciitest/cii-best-practices-badge/blob/master/Rakefile>."], ["build_common_tools_status", "Met"], ["build_common_tools_justification", "Non-trivial build file in repository: <https://github.com/ciitest/cii-best-practices-badge/blob/master/Rakefile>."], ["badge_percentage", 15], ["created_at", "2016-05-31 02:02:03.602250"], ["updated_at", "2016-05-31 02:02:03.602250"]]
[1m[36mSQL (0.4ms)[0m [1mINSERT INTO "versions" ("event", "whodunnit", "created_at", "item_id", "item_type") VALUES ($1, $2, $3, $4, $5) RETURNING "id"[0m [["event", "create"], ["whodunnit", "764040364"], ["created_at", "2016-05-31 02:02:03.602250"], ["item_id", 980190963], ["item_type", "Project"]]
[1m[35m (0.5ms)[0m COMMIT
Redirected to http://127.0.0.1:31337/projects/980190963/edit
Completed 302 Found in 117ms (ActiveRecord: 4.3ms)
Started GET "/projects/980190963/edit" for 127.0.0.1 at 2016-05-30 22:02:03 -0400
Processing by ProjectsController#edit as HTML
Parameters: {"id"=>"980190963"}
[1m[36mUser Load (0.2ms)[0m [1mSELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1[0m [["id", 764040364]]
[1m[35mProject Load (0.7ms)[0m SELECT "projects".* FROM "projects" WHERE "projects"."id" = $1 ORDER BY "projects"."created_at" ASC LIMIT 1 [["id", 980190963]]
[1m[36mProject Exists (0.3ms)[0m [1mSELECT 1 AS one FROM "projects" WHERE "projects"."user_id" = $1 AND "projects"."id" = $2 LIMIT 1[0m [["user_id", 764040364], ["id", 980190963]]
Rendered projects/_details.html.erb (0.0ms)
Rendered shared/_error_messages.html.erb (0.0ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_status_chooser.html.erb (3.3ms)
Rendered projects/_status_chooser.html.erb (2.4ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_status_chooser.html.erb (3.9ms)
Rendered projects/_status_chooser.html.erb (3.3ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (3.2ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.5ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.5ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.4ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.7ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_status_chooser.html.erb (2.8ms)
Rendered projects/_status_chooser.html.erb (2.9ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.0ms)
Rendered projects/_status_chooser.html.erb (2.0ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.5ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.6ms)
Rendered projects/_status_chooser.html.erb (2.7ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_status_chooser.html.erb (2.1ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_status_chooser.html.erb (2.0ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.5ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_status_chooser.html.erb (2.0ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.0ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.1ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_status_chooser.html.erb (1.9ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.4ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (3.1ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_status_chooser.html.erb (4.6ms)
Rendered projects/_status_chooser.html.erb (3.6ms)
Rendered projects/_status_chooser.html.erb (3.1ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.6ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_status_chooser.html.erb (2.1ms)
Rendered projects/_status_chooser.html.erb (3.6ms)
Rendered projects/_status_chooser.html.erb (3.7ms)
Rendered projects/_status_chooser.html.erb (3.6ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (3.3ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.7ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.5ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_status_chooser.html.erb (2.1ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_status_chooser.html.erb (3.9ms)
Rendered projects/_status_chooser.html.erb (2.7ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_status_chooser.html.erb (4.0ms)
Rendered projects/_status_chooser.html.erb (2.8ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.5ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_status_chooser.html.erb (2.0ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_details.html.erb (0.1ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.6ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.4ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.2ms)
Rendered projects/_details.html.erb (0.0ms)
Rendered projects/_status_chooser.html.erb (2.3ms)
Rendered projects/_form.html.erb (202.1ms)
Rendered projects/edit.html.erb within layouts/application (202.6ms)
Rendered layouts/_header.html.erb (0.7ms)
Rendered layouts/_footer.html.erb (1.3ms)
Completed 200 OK in 214ms (Views: 207.2ms | ActiveRecord: 1.1ms)
Started GET "/users/764040364" for 127.0.0.1 at 2016-05-30 22:02:04 -0400
Processing by UsersController#show as HTML
Parameters: {"id"=>"764040364"}
[1m[35mUser Load (0.2ms)[0m SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1 [["id", 764040364]]
[1m[36mUser Load (0.7ms)[0m [1mSELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1[0m [["id", 764040364]]
[1m[35mProject Load (3.6ms)[0m SELECT "projects".* FROM "projects" WHERE "projects"."repo_url" IN ('https://github.com/ciitest/cii-best-practices-badge', 'https://github.com/ciitest/test-repo') ORDER BY "projects"."created_at" ASC
[1m[36mProject Load (1.1ms)[0m [1mSELECT "projects".* FROM "projects" WHERE "projects"."user_id" = $1 ORDER BY "projects"."created_at" ASC LIMIT 30 OFFSET 0[0m [["user_id", 764040364]]
[1m[35mProject Exists (0.3ms)[0m SELECT 1 AS one FROM "projects" WHERE "projects"."user_id" = $1 LIMIT 1 [["user_id", 764040364]]
Rendered projects/_table.html.erb (2.3ms)
Rendered users/show.html.erb within layouts/application (6.9ms)
Rendered layouts/_header.html.erb (1.1ms)
Rendered layouts/_footer.html.erb (1.1ms)
Completed 200 OK in 48ms (Views: 13.5ms | ActiveRecord: 5.9ms)
Started GET "/projects/980190963/badge" for 127.0.0.1 at 2016-05-30 22:02:04 -0400
Processing by ProjectsController#badge as SVG
Parameters: {"id"=>"980190963"}
[1m[36mUser Load (0.2ms)[0m [1mSELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1[0m [["id", 764040364]]
[1m[35mProject Load (0.8ms)[0m SELECT "projects".* FROM "projects" WHERE "projects"."id" = $1 ORDER BY "projects"."created_at" ASC LIMIT 1 [["id", 980190963]]
Rendered text template (0.0ms)
Sent data (0.7ms)
Completed 200 OK in 8ms (Views: 0.6ms | ActiveRecord: 1.0ms)
[1m[36m (0.3ms)[0m [1mROLLBACK[0m
[1m[35m (0.1ms)[0m BEGIN
----------------------------------------------
Contrast this with a later test that sets SAVEPOINT and ROLLBACK normally:
--------------------------------------------------------
ProjectStatTest: test_project_stat_matches_expect_values
--------------------------------------------------------
[1m[36m (0.0ms)[0m [1mSAVEPOINT active_record_1[0m
[1m[35m (0.0ms)[0m SELECT COUNT(*) FROM "projects" WHERE ("projects"."badge_percentage" >= 0)
[1m[36m (0.0ms)[0m [1mSELECT COUNT(*) FROM "projects" WHERE ("projects"."badge_percentage" >= 25)[0m
[1m[35m (0.0ms)[0m SELECT COUNT(*) FROM "projects" WHERE ("projects"."badge_percentage" >= 50)
[1m[36m (0.0ms)[0m [1mSELECT COUNT(*) FROM "projects" WHERE ("projects"."badge_percentage" >= 75)[0m
[1m[35m (0.0ms)[0m SELECT COUNT(*) FROM "projects" WHERE ("projects"."badge_percentage" >= 90)
[1m[36m (0.0ms)[0m [1mSELECT COUNT(*) FROM "projects" WHERE ("projects"."badge_percentage" >= 100)[0m
[1m[35m (0.0ms)[0m SELECT COUNT(*) FROM "projects" WHERE ("projects"."created_at" >= '2015-02-28 12:00:00.000000')
[1m[36m (0.0ms)[0m [1mSELECT COUNT(*) FROM "projects" WHERE ("projects"."updated_at" >= '2015-02-28 12:00:00.000000')[0m
[1m[35mSQL (0.0ms)[0m INSERT INTO "project_stats" ("created_at", "updated_at", "percent_ge_0", "percent_ge_25", "percent_ge_50", "percent_ge_75", "percent_ge_90", "percent_ge_100", "created_since_yesterday", "updated_since_yesterday") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10) RETURNING "id" [["created_at", "2015-03-01 12:00:00.000000"], ["updated_at", "2015-03-01 12:00:00.000000"], ["percent_ge_0", 5], ["percent_ge_25", 2], ["percent_ge_50", 2], ["percent_ge_75", 2], ["percent_ge_90", 1], ["percent_ge_100", 1], ["created_since_yesterday", 5], ["updated_since_yesterday", 0]]
[1m[36m (0.0ms)[0m [1mRELEASE SAVEPOINT active_record_1[0m
[1m[35m (0.1ms)[0m ROLLBACK
[1m[36m (0.1ms)[0m [1mBEGIN[0m
--------------------------------------------
Any ideas how to get this test to set a SAVEPOINT so that the ROLLBACK will succeed? I suspect I'm encounter a bug with VCR (which I filed at https://github.com/vcr/vcr/issues/586 ) but it's hard to be sure.
