Errors on DB restore in Dev

I’ve been struggling for several days tying to get my live database restored onto my development machine (Arch) for some troubleshooting. I’ve tried using the docker dev container launched via ./bin/docker/boot_dev the local environment, but each time I run into issues with restore.

Everything except back and restore has been working fine…

Both on the local machine and in the container, I’ve tried:

  • Removing the entire postgres database and rebuilding
  • Creating a new empty user account and installing discourse from there
  • Running the restore job via the command line or via the web UI
  • Validated that the database can be restored onto another machine
  • Validated that the database can be restored onto docker production, but not docker dev or my local instance

I get different errors via the docker environment than via the local machine…

Currently the error I’m stuck on when running locally outside docker dev is:

[2018-10-28 01:39:53] EXCEPTION: /home/test/Dev/discourse/lib/backup_restore/restorer.rb:281:in `get_dumped_by_version': Failed to check version of pg_dump used to generate the dump file
gzip: -e.gz: No such file or directory
gzip: -- Dumped by pg_dump version.gz: No such file or directory
Full log of restore failure on local
[2018-10-28 01:39:52] 'ryan' has started the restore!
[2018-10-28 01:39:52] Marking restore as running...
[2018-10-28 01:39:52] Making sure /home/test/Dev/discourse/tmp/restores/default/2018-10-28-013952 exists...
[2018-10-28 01:39:52] Copying archive to tmp directory...
[2018-10-28 01:39:52] Unzipping archive, this may take a while...
[2018-10-28 01:39:53] No metadata file to extract.
[2018-10-28 01:39:53] Validating metadata...
[2018-10-28 01:39:53]   Current version: 20181010150631
[2018-10-28 01:39:53]   Restored version: 20180828065005
[2018-10-28 01:39:53] Extracting dump file...
[2018-10-28 01:39:53] EXCEPTION: /home/test/Dev/discourse/lib/backup_restore/restorer.rb:281:in `get_dumped_by_version': Failed to check version of pg_dump used to generate the dump file
gzip: -e.gz: No such file or directory
gzip: -- Dumped by pg_dump version.gz: No such file or directory

[2018-10-28 01:39:53] /home/test/Dev/discourse/lib/discourse.rb:29:in `execute_command'
/home/test/Dev/discourse/lib/backup_restore/restorer.rb:281:in `get_dumped_by_version'
/home/test/Dev/discourse/lib/backup_restore/restorer.rb:291:in `can_restore_into_different_schema?'
/home/test/Dev/discourse/lib/backup_restore/restorer.rb:59:in `run'
/home/test/Dev/discourse/lib/backup_restore/backup_restore.rb:167:in `block in start!'
/home/test/Dev/discourse/lib/backup_restore/backup_restore.rb:164:in `fork'
/home/test/Dev/discourse/lib/backup_restore/backup_restore.rb:164:in `start!'
/home/test/Dev/discourse/lib/backup_restore/backup_restore.rb:23:in `restore!'
/home/test/Dev/discourse/app/controllers/admin/backups_controller.rb:118:in `restore'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/abstract_controller/base.rb:194:in `process_action'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/callbacks.rb:132:in `run_callbacks'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/usr/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168:in `instrument'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/usr/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/abstract_controller/base.rb:134:in `process'
/usr/lib/ruby/gems/2.5.0/gems/actionview-5.2.0/lib/action_view/rendering.rb:32:in `process'
/usr/lib/ruby/gems/2.5.0/gems/rack-mini-profiler-1.0.0/lib/mini_profiler/profiling_methods.rb:104:in `block in profile_method'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal.rb:191:in `dispatch'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_controller/metal.rb:252:in `dispatch'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/routing/mapper.rb:18:in `block in <class:Constraints>'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/routing/mapper.rb:48:in `serve'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/journey/router.rb:35:in `each'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/journey/router.rb:35:in `serve'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/routing/route_set.rb:840:in `call'
/usr/lib/ruby/gems/2.5.0/gems/rack-protection-2.0.3/lib/rack/protection/frame_options.rb:31:in `call'
/home/test/Dev/discourse/lib/middleware/omniauth_bypass_middleware.rb:24:in `call'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/tempfile_reaper.rb:15:in `call'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/conditional_get.rb:38:in `call'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/head.rb:12:in `call'
/home/test/Dev/discourse/lib/content_security_policy.rb:18:in `call'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:232:in `context'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:226:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/usr/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/migration.rb:559:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/usr/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/callbacks.rb:98:in `run_callbacks'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/lib/ruby/gems/2.5.0/gems/better_errors-2.4.0/lib/better_errors/middleware.rb:84:in `protected_app_call'
/usr/lib/ruby/gems/2.5.0/gems/better_errors-2.4.0/lib/better_errors/middleware.rb:79:in `better_errors_call'
/usr/lib/ruby/gems/2.5.0/gems/better_errors-2.4.0/lib/better_errors/middleware.rb:57:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/usr/lib/ruby/gems/2.5.0/gems/logster-1.2.11/lib/logster/middleware/reporter.rb:31:in `call'
/usr/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/rack/logger.rb:38:in `call_app'
/usr/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/rack/logger.rb:28:in `call'
/home/test/Dev/discourse/config/initializers/100-quiet_logger.rb:16:in `call'
/home/test/Dev/discourse/config/initializers/100-silence_logger.rb:29:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/method_override.rb:22:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/lib/ruby/gems/2.5.0/gems/actionpack-5.2.0/lib/action_dispatch/middleware/static.rb:127:in `call'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/sendfile.rb:111:in `call'
/home/test/Dev/discourse/lib/middleware/missing_avatars.rb:21:in `call'
/home/test/Dev/discourse/lib/middleware/turbo_dev.rb:34:in `call'
/usr/lib/ruby/gems/2.5.0/gems/rack-mini-profiler-1.0.0/lib/mini_profiler/profiler.rb:285:in `call'
/usr/lib/ruby/gems/2.5.0/gems/message_bus-2.1.6/lib/message_bus/rack/middleware.rb:63:in `call'
/usr/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/engine.rb:524:in `call'
/usr/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/railtie.rb:190:in `public_send'
/usr/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/railtie.rb:190:in `method_missing'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/urlmap.rb:68:in `block in call'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `each'
/usr/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/gems/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:606:in `process_client'
/usr/lib/ruby/gems/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:701:in `worker_loop'
/usr/lib/ruby/gems/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:549:in `spawn_missing_workers'
/usr/lib/ruby/gems/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:142:in `start'
/usr/lib/ruby/gems/2.5.0/gems/unicorn-5.4.0/bin/unicorn:126:in `<top (required)>'
/home/test/Dev/discourse/bin/unicorn:48:in `load'
/home/test/Dev/discourse/bin/unicorn:48:in `<main>'
[2018-10-28 01:39:53] Trying to rollback...
[2018-10-28 01:39:53] There was no need to rollback
[2018-10-28 01:39:53] Cleaning stuff up...
[2018-10-28 01:39:53] Removing tmp '/home/test/Dev/discourse/tmp/restores/default/2018-10-28-013952' directory...
[2018-10-28 01:39:53] Unpausing sidekiq...
[2018-10-28 01:39:53] Marking restore as finished...
[2018-10-28 01:39:53] Notifying 'ryan' of the end of the restore...
[2018-10-28 01:40:00] Finished!

When trying to run the database restore inside of docker dev, I’m getting stuck at:

Migrating the database...
EXCEPTION: PG::InsufficientPrivilege: ERROR:  permission denied for relation schema_migrations
: SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Partial log of restore failure on docker dev

CREATE INDEX
CREATE INDEX
CREATE INDEX
Migrating the database…
EXCEPTION: PG::InsufficientPrivilege: ERROR:  permission denied for relation schema_migrations
: SELECT “schema_migrations”.“version” FROM “schema_migrations” ORDER BY “schema_migrations”.“vers
ion” ASC
/usr/local/lib/ruby/gems/2.5.0/gems/rack-mini-profiler-1.0.0/lib/patches/db/pg.rb:92:in async_exe c' /usr/local/lib/ruby/gems/2.5.0/gems/rack-mini-profiler-1.0.0/lib/patches/db/pg.rb:92:in async_exe
c’
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/connection_adapters/postg
resql_adapter.rb:603:in block (2 levels) in exec_no_cache' /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies/interlock. rb:48:in block in permit_concurrent_loads’
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/concurrency/share_lock.
rb:187:in yield_shares' /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies/interlock. rb:47:in permit_concurrent_loads’
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/connection_adapters/postg
resql_adapter.rb:602:in block in exec_no_cache' /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/connection_adapters/abstr act_adapter.rb:579:in block (2 levels) in log’
/usr/local/lib/ruby/2.5.0/monitor.rb:226:in mon_synchronize' /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/connection_adapters/abstr act_adapter.rb:578:in block in log’
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumen
ter.rb:23:in instrument' /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/connection_adapters/abstr act_adapter.rb:569:in log’
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/connection_adapters/postg
resql_adapter.rb:601:in exec_no_cache' /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/connection_adapters/postg resql_adapter.rb:588:in execute_and_clear’
/src/lib/freedom_patches/fast_pluck.rb:39:in select_raw' /src/lib/freedom_patches/fast_pluck.rb:59:in pluck’
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/schema_migration.rb:48:in
all_versions' /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/migration.rb:1059:in get
_all_versions’
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/migration.rb:1066:in cur rent_version' /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/migration.rb:1012:in mig
rate’
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/tasks/database_tasks.rb:1
72:in migrate' /src/lib/migration/safe_migrate.rb:50:in migrate’
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.0/lib/active_record/railties/databases.rake:6
0:in block (2 levels) in &lt;main&gt;' /usr/local/lib/ruby/gems/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:271:in block in execute’
/usr/local/lib/ruby/gems/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:271:in each' /usr/local/lib/ruby/gems/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:271:in execute’
/usr/local/lib/ruby/gems/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:213:in block in invoke_with_call _chain' /usr/local/lib/ruby/2.5.0/monitor.rb:226:in mon_synchronize’
/usr/local/lib/ruby/gems/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:193:in invoke_with_call_chain' /usr/local/lib/ruby/gems/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:182:in invoke’
/src/lib/backup_restore/restorer.rb:395:in migrate_database' /src/lib/backup_restore/restorer.rb:70:in run’
script/discourse:136:in restore' /usr/local/lib/ruby/gems/2.5.0/gems/thor-0.19.4/lib/thor/command.rb:27:in run’
/usr/local/lib/ruby/gems/2.5.0/gems/thor-0.19.4/lib/thor/invocation.rb:126:in invoke_command' /usr/local/lib/ruby/gems/2.5.0/gems/thor-0.19.4/lib/thor.rb:369:in dispatch’
/usr/local/lib/ruby/gems/2.5.0/gems/thor-0.19.4/lib/thor/base.rb:444:in start' script/discourse:277:in <main>’
Trying to rollback…
Rolling back…
Cleaning stuff up…
Removing tmp ‘/src/tmp/restores/default/2018-10-27-195635’ directory…
Unpausing sidekiq…
Disabling readonly mode…
Marking restore as finished…
Notifying ‘system’ of the end of the restore…
Finished!
[FAILED]
Restore done.

Did you rename the backup file?

1 Like

Thanks for the suggestion.
I didn’t rename the file, but to be certain I downloaded the backup again, repeat the restore process, and get the exact same errors as before, so it’s definitely not a file name issue.
I was also able to restore the exact same file (matching md5sum) on a non-Arch image…


Checking inside lib/backup_restore/restorer.rb -> def get_dumped_by_version I see:

        File.extname(@dump_filename) == '.gz' ? 'zgrep' : 'grep',

On Arch, we have:

zgrep --version
zgrep (gzip) 1.9

And on Ubuntu we have:

zgrep --version
zgrep (gzip) 1.6

It turns out there’s an update in zgrep 1.9…

zgrep -m1 mysite-net-2018-10-28-065449-v20180828065005.tar.gz -e '-- Dumped by pg_dump version
'
gzip: -e.gz: No such file or directory
gzip: -- Dumped by pg_dump version.gz: No such file or directory
 % echo $?
2

Vs zgrep 1.6:

zgrep -m1 mysite-net-2018-10-28-065449-v20180828065005.tar.gz -e '-- Dumped by pg_dump version'
ryan@rybuntuvm:~/discourse/public/backups/default$ echo $?
1
2 Likes