rails test broken if user is not postgres superuser on rails 6 (works on rails 5)

Lapizistik commented 3 years ago

Description

I try to use this gem on a fresh rails 6 project with an ordinary postgres database user (that has no superuser rights). I therefore add the postgis extension to the database via postgres template (see below). This works for development mode, but running rails test fails (sometimes the first run succeeds) with DRb::DRbRemoteError: PG::InsufficientPrivilege: ERROR: permission denied for table spatial_ref_sys (sometimes also for table ar_internal_metadata instead). Stopping or killing spring does not help.

The setup described below fails with rails 6.1.3 and 6.0.3.1. The identical setup works with rails 5.2.5 without errors. It also works for rails 6 if I use a superuser role.

This is my first time using activerecord-postgis-adapter and I am not an expert in how rails 6 runs tests (as far as I could see it creates at least 4 test databases using them in parallel?) so maybe I am doing something wrong?

Thanks for your work!

Setup

ruby version: 2.5 OS: debian buster postgresql: 11.11-0+deb10u1 postgis: 2.5.1+dfsg-1

postgres (psql)

First create a postgis template in postgres:

postgres=# CREATE DATABASE postgis_template;
postgres=# \c postgis_template
postgres=# CREATE EXTENSION postgis;
postgres=# CREATE EXTENSION postgis_topology;
postgres=# UPDATE pg_database SET datistemplate = TRUE WHERE datname = 'postgis_template';

And some user:

postgres=# CREATE USER testing with createdb;
postgres=# \password testing

rails (6.1.3)

Following the instructions in the README:

rails new test_6_1_3 --database=postgresql           # new rails project
cd test_6_1_3
edit config/database.yml                             # see below  
echo "gem 'activerecord-postgis-adapter'">>Gemfile   # add the gem
bundle install                                       # install it
rails generate controller Example index    # generate something to test
rails db:create                            # create the databases (gets postgis through postgis_template)
rails db:migrate
rails test                      # this one succeeds sometimes (could not find any deterministic behavior here)
rails test                      # this fails (with postgis as db adapter on rails 6)!

`config/database.yml`

default: &default
  adapter: postgis
  template: postgis_template
  encoding: unicode
  host: localhost
  username: testing
  password: ********
development:
  <<: *default
  database: test_6_1_3_development
test:
  <<: *default
  database: test_6_1_3_test

Logfiles

The log/test.log shows lots of

…
  TRANSACTION (0.1ms)  BEGIN
  TRANSACTION (0.2ms)  BEGIN
  TRANSACTION (0.1ms)  BEGIN
   (0.6ms)  ALTER TABLE "spatial_ref_sys" DISABLE TRIGGER ALL;ALTER TABLE "schema_migrations" DISABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" DISABLE TRIGGER ALL
   (0.6ms)  ALTER TABLE "spatial_ref_sys" DISABLE TRIGGER ALL;ALTER TABLE "schema_migrations" DISABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" DISABLE TRIGGER ALL
  TRANSACTION (0.1ms)  ROLLBACK
  TRANSACTION (0.2ms)  ROLLBACK
   (0.5ms)  TRUNCATE TABLE "spatial_ref_sys"
   (0.5ms)  TRUNCATE TABLE "spatial_ref_sys"
   (0.5ms)  ALTER TABLE "spatial_ref_sys" DISABLE TRIGGER ALL;ALTER TABLE "schema_migrations" DISABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" DISABLE TRIGGER ALL
  TRANSACTION (0.1ms)  ROLLBACK
…

And /var/log/postgresql/postgresql-11-main.log gives

2021-04-02 19:59:00.416 CEST [20203] testing@test_6_0_3_test-0 FATAL:  database "test_6_0_3_test-0" does not exist
2021-04-02 19:59:00.418 CEST [20208] testing@test_6_0_3_test-1 FATAL:  database "test_6_0_3_test-1" does not exist
2021-04-02 19:59:00.420 CEST [20213] testing@test_6_0_3_test-2 FATAL:  database "test_6_0_3_test-2" does not exist
2021-04-02 19:59:00.422 CEST [20215] testing@test_6_0_3_test-3 FATAL:  database "test_6_0_3_test-3" does not exist
2021-04-02 19:59:07.678 CEST [20321] testing@test_6_0_3_test-1 ERROR:  must be owner of table spatial_ref_sys
2021-04-02 19:59:07.678 CEST [20321] testing@test_6_0_3_test-1 STATEMENT:  ALTER TABLE "spatial_ref_sys" DISABLE TRIGGER ALL;ALTER TABLE "schema_migrations" DISABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" DISABLE TRIGGER ALL
2021-04-02 19:59:07.678 CEST [20320] testing@test_6_0_3_test-0 ERROR:  must be owner of table spatial_ref_sys
2021-04-02 19:59:07.678 CEST [20320] testing@test_6_0_3_test-0 STATEMENT:  ALTER TABLE "spatial_ref_sys" DISABLE TRIGGER ALL;ALTER TABLE "schema_migrations" DISABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" DISABLE TRIGGER ALL
2021-04-02 19:59:07.679 CEST [20321] testing@test_6_0_3_test-1 ERROR:  permission denied for table spatial_ref_sys
2021-04-02 19:59:07.679 CEST [20321] testing@test_6_0_3_test-1 STATEMENT:  TRUNCATE TABLE "spatial_ref_sys"
2021-04-02 19:59:07.679 CEST [20320] testing@test_6_0_3_test-0 ERROR:  permission denied for table spatial_ref_sys
2021-04-02 19:59:07.679 CEST [20320] testing@test_6_0_3_test-0 STATEMENT:  TRUNCATE TABLE "spatial_ref_sys"
2021-04-02 19:59:07.681 CEST [20322] testing@test_6_0_3_test-2 ERROR:  must be owner of table spatial_ref_sys
2021-04-02 19:59:07.681 CEST [20322] testing@test_6_0_3_test-2 STATEMENT:  ALTER TABLE "spatial_ref_sys" DISABLE TRIGGER ALL;ALTER TABLE "schema_migrations" DISABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" DISABLE TRIGGER ALL
2021-04-02 19:59:07.683 CEST [20322] testing@test_6_0_3_test-2 ERROR:  permission denied for table spatial_ref_sys
2021-04-02 19:59:07.683 CEST [20322] testing@test_6_0_3_test-2 STATEMENT:  TRUNCATE TABLE "spatial_ref_sys"
2021-04-02 19:59:07.687 CEST [20323] testing@test_6_0_3_test-3 ERROR:  must be owner of table spatial_ref_sys
2021-04-02 19:59:07.687 CEST [20323] testing@test_6_0_3_test-3 STATEMENT:  ALTER TABLE "spatial_ref_sys" DISABLE TRIGGER ALL;ALTER TABLE "schema_migrations" DISABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" DISABLE TRIGGER ALL
2021-04-02 19:59:07.689 CEST [20323] testing@test_6_0_3_test-3 ERROR:  permission denied for table spatial_ref_sys
2021-04-02 19:59:07.689 CEST [20323] testing@test_6_0_3_test-3 STATEMENT:  TRUNCATE TABLE "spatial_ref_sys"

keithdoggett commented 3 years ago

Thanks for the detailed issue! I think the issue you're having is that rails test will reset the entire test database after a run (hence why it works the first time, but not the second). You can see this because it is trying to TRUNCATE each table to clear it. I'm not sure if this is new in rails 6, but you'll likely need to run the tests with a user that can modify the spatial_ref_sys table.

Another option could be to find a way to ignore this table when resetting the database for tests, I'm not sure if this is possible off the top of my head, but I can look into it in a little bit.

mjy commented 3 years ago

@keithdoggett here is what we do, I think this addresses the need:

https://github.com/SpeciesFileGroup/taxonworks/blob/development/spec/spec_helper.rb#L103

Lapizistik commented 3 years ago

Thanks a lot for your quick reply.

I understand that resetting the database causes the problem. AFAIK rails 5 should also do this and there the test works many times, so something is different here.

I found something else: If I replace

rails generate controller Example index    # generate something to test

with

rails generate model Example name:string

I do not get any error on rails test any more, so model tests are fine (and there the database also gets reset). There is something weird going on with controller/view tests. (So if someone knows where to ask on the rails side this would be helpful I think.)

Thanks a lot again!

keithdoggett commented 3 years ago

Thanks @mjy for that! @Lapizistik were you able to try that suggestion? If that doesn't work can you take a look at the test logs for either version 5 or the model tests and see if the table cleaning commands are different than what you posted above? I'm confused about how model tests are working, but controller tests aren't so maybe this will help us see what's going on.

Lapizistik commented 3 years ago

Thanks @mjy for that! @Lapizistik were you able to try that suggestion?

I did not try this (thanks to @mjy nevertheless!) as

the suggestion works with RSpec (and AFAIK plain rails 6 has minitest build in)
the suggestion uses DatabaseCleaner (I assume the gem) which is not part of plain rails 6

I assume I could work around the bug by using DatabaseCleaner but I tried to stay on plain rails 6 for investigating the bug. (I'll provide the test logs soon.)

mjy commented 3 years ago

@Lapizistik Sorry for the confusion, indeed this is gem related code. I think we'd like to ultimately simplify in your direction so I'm curious where this will go.

Lapizistik commented 3 years ago

And here the log files.

I wrote a small shell script to automatically setup the rails project and run the tests (it assumes that a postgis_template exists, as described above): apa-test.zip (github does not like shellscripts, so I had to zip it)

I run it with different parameters:

Rails 6, with controller:

./apa-test.sh rails6c >rails6c.log 2>&1

rails6c.log rails6c/log/test.log

Rails 6, with model:

TYPE=M ./apa-test.sh rails6m >rails6m.log 2>&1

rails6m.log rails6m/log/test.log

Rails 5, with controller:

RAILS_VERSION=_5.2.5_ ./apa-test.sh rails5c >rails5c.log 2>&1

rails5c.log rails5m/log/test.log

keithdoggett commented 3 years ago

@Lapizistik thanks a lot for all this. I'll have some time soon to try to repro this and figure out what's going on. I looked through this gem and spatial_ref_sys is only used in the database setup tasks and ignore_tables for the SchemaDumper.

These lines from rails6c.log in the stacktrace are probably the root cause of the issue

    /var/lib/gems/2.5.0/gems/activerecord-6.1.3.1/lib/active_record/connection_adapters/abstract/database_statements.rb:198:in `truncate_tables'
    /var/lib/gems/2.5.0/gems/activerecord-6.1.3.1/lib/active_record/connection_adapters/abstract/query_cache.rb:22:in `truncate_tables'
    /var/lib/gems/2.5.0/gems/activerecord-6.1.3.1/lib/active_record/tasks/database_tasks.rb:221:in `truncate_tables'
    /var/lib/gems/2.5.0/gems/activerecord-6.1.3.1/lib/active_record/tasks/database_tasks.rb:368:in `reconstruct_from_schema'
    /var/lib/gems/2.5.0/gems/activerecord-6.1.3.1/lib/active_record/test_databases.rb:17:in `block in create_and_load_schema'
    /var/lib/gems/2.5.0/gems/activerecord-6.1.3.1/lib/active_record/test_databases.rb:14:in `each'
    /var/lib/gems/2.5.0/gems/activerecord-6.1.3.1/lib/active_record/test_databases.rb:14:in `create_and_load_schema'

I'll take a look at these methods soon and see if there's a way to ignore the postgis specific tables from this.

keithdoggett commented 3 years ago

@Lapizistik I made this modification (https://github.com/rgeo/activerecord-postgis-adapter/commit/074506fd1a4d19b455628845bc573c8d1ba59644) I'm pretty sure it will work across all 6.x versions, but I only tested this off the master branch so it's 6.1.x compatible. If you could give it a try that would be great.

Lapizistik commented 3 years ago

@keithdoggett I tried your modification gem 'activerecord-postgis-adapter', git: 'https://github.com/rgeo/activerecord-postgis-adapter.git', branch: 'ignore-srs-truncate', the tests work fine. I don't know whether there are any side-effects I am not aware of.

Thaks a lot again!

Klaus

keithdoggett commented 3 years ago

Fixed by #341

rgeo / activerecord-postgis-adapter