Restore from backup fails

[zenmonkeykstop]

Description

During testing of 0.10.0~rc2 on prod VMs, I created a server backup, ran ./manage.py reset on the app server to nuke the database, and tried to restore from the backup. This failed with the error text below:

fatal: [app]: FAILED! => {"ansible_job_id": "863470588110.4013", "changed": true, "cmd": ["/tmp/restore.py", "/tmp/sd-backup-2018-10-16--03-18-02.tar.gz"], "delta": "0:00:08.723426", "end": "2018-10-16 03:20:49.675663", "finished": 1, "msg": "non-zero return code", "rc": 1, "start": "2018-10-16 03:20:40.952237", "stderr": "+ set -o pipefail\n+ case \"$1\" in\n+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop\n+ mkdir -p /var/lib/securedrop/\n+ chmod 0700 /var/lib/securedrop/\n+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop\n+ mkdir -p /var/lib/securedrop/tmp\n+ chmod 0700 /var/lib/securedrop/tmp\n+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop\n+ mkdir -p /var/lib/securedrop/store\n+ chmod 0700 /var/lib/securedrop/store\n+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop\n+ mkdir -p /var/lib/securedrop/keys\n+ chmod 0700 /var/lib/securedrop/keys\n+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop\n+ mkdir -p /var/lib/securedrop/backups\n+ chmod 0700 /var/lib/securedrop/backups\n+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop\n+ mkdir -p /var/www/securedrop\n+ chmod 0700 /var/www/securedrop\n+ chown -R www-data:www-data /var/lib/securedrop /var/www/securedrop\n+ pip install --no-index --find-links=/var/securedrop/wheelhouse --upgrade -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt\n+ chown -R www-data:www-data /var/www/securedrop\n+ chown www-data:www-data /var/www/journalist.wsgi\n+ chown www-data:www-data /var/www/source.wsgi\n+ a2dissite 000-default\n+ a2dissite default-ssl\n+ service apache2 stop\n+ '[' -e /etc/apparmor.d/disable/usr.sbin.apache2 ']'\n+ aa-enforce /etc/apparmor.d/usr.sbin.tor\n+ aa-enforce /etc/apparmor.d/usr.sbin.apache2\n+ permit_wsgi_authorization\n+ journalist_conf=/etc/apache2/sites-available/journalist.conf\n+ grep -qP '^WSGIPass
Authorization' /etc/apache2/sites-available/journalist.conf\n+ service apache2 restart\n+ rm -fr /var/www/securedrop/static/gen/journalist.js /var/www/securedrop/static/gen/source.js\n+ '[' -n 0.10.0~rc2 ']'\n+ '[' 0.10.0~rc2 = 0.3 ']'\n+ chmod u+w /var/www/securedrop/static/i/logo.png\n+ grep -qE 'MACs\\s.*hmac-sha1' /etc/ssh/sshd_config\n+ database_migration\n+ database_dir=/var/lib/securedrop\n+ database_file=/var/lib/securedrop/db.sqlite\n+ '[' '!' -e /var/lib/securedrop/db.sqlite ']'\n+ cd /var/www/securedrop/\n++ alembic current\nINFO  [alembic.runtime.migration] Context impl SQLiteImpl.\nINFO  [alembic.runtime.migration] Will assume non-transactional DDL.\n+ '[' -z '' ']'\n++ sqlite3 /var/lib/securedrop/db.sqlite .tables\n+ sqlite_tables='alembic_version           replies                   submissions             \njournalist_login_attempt  source_stars            \njournalists               sources                 '\n+ grep -q journalists\n+ echo 'alembic_version           replies                   submissions             \njournalist_login_attempt  source_stars            \njournalists               sources                 '\n+ alembic stamp 15ac9509fc68\nINFO  [alembic.runtime.migration] Context impl SQLiteImpl.\nINFO  [alembic.runtime.migration] Will assume non-transactional DDL.\nINFO  [alembic.runtime.migration] Running stamp_revision  -> 15ac9509fc68\n++ date +%Y-%m-%d-%H-%M-%S\n+ db_backup=/var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite\n+ grep -q '(head)'\n+ alembic current\nINFO  [alembic.runtime.migration] Context impl SQLiteImpl.\nINFO  [alembic.runtime.migration] Will assume non-transactional DDL.\n+ cp /var/lib/securedrop/db.sqlite /var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite\n+ alembic upgrade head\nINFO  [alembic.runtime.migration] Context impl SQLiteImpl.\nINFO  [alembic.runtime.migration] Will assume non-transactional DDL.\nINFO  [alembic.runtime.migration] Running upgrade 15ac9509fc68 -> faac8092c123, enable security 
pragmas\nINFO  [alembic.runtime.migration] Running upgrade faac8092c123 -> 3d91d6948753, Create source UUID column\nTraceback (most recent call last):\n  File \"/usr/local/bin/alembic\", line 11, in <module>\n    sys.exit(main())\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/config.py\", line 486, in main\n    CommandLine(prog=prog).main(argv=argv)\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/config.py\", line 480, in main\n    self.run_cmd(cfg, options)\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/config.py\", line 463, in run_cmd\n    **dict((k, getattr(options, k, None)) for k in kwarg)\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/command.py\", line 254, in upgrade\n    script.run_env()\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/script/base.py\", line 427, in run_env\n    util.load_python_file(self.dir, 'env.py')\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/util/pyfiles.py\", line 81, in load_python_file\n    module = load_module_py(module_id, path)\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/util/compat.py\", line 141, in load_module_py\n    mod = imp.load_source(module_id, path, fp)\n  File \"alembic/env.py\", line 82, in <module>\n    run_migrations_online()\n  File \"alembic/env.py\", line 76, in run_migrations_online\n    context.run_migrations()\n  File \"<string>\", line 8, in run_migrations\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/runtime/environment.py\", line 836, in run_migrations\n    self.get_context().run_migrations(**kw)\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/runtime/migration.py\", line 330, in run_migrations\n    step.migration_fn(**kw)\n  File \"/var/www/securedrop/alembic/versions/3d91d6948753_create_source_uuid_column.py\", line 26, in upgrade\n    op.add_column('sources_tmp', sa.Column('uuid', sa.String(length=36)))\n  File \"<string>\", line 8, in add_column\n  File \"<string>\", line 3, in add_column\n  File \"/usr/local/l
ib/python2.7/dist-packages/alembic/operations/ops.py\", line 1565, in add_column\n    return operations.invoke(op)\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/operations/base.py\", line 319, in invoke\n    return fn(self, operation)\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/operations/toimpl.py\", line 123, in add_column\n    schema=schema\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/ddl/impl.py\", line 172, in add_column\n    self._exec(base.AddColumn(table_name, column, schema=schema))\n  File \"/usr/local/lib/python2.7/dist-packages/alembic/ddl/impl.py\", line 118, in _exec\n    return conn.execute(construct, *multiparams, **params)\n  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 948, in execute\n    return meth(self, multiparams, params)\n  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/ddl.py\", line 68, in _execute_on_connection\n    return connection._execute_ddl(self, multiparams, params)\n  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 1009, in _execute_ddl\n    compiled\n  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 1200, in _execute_context\n    context)\n  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 1413, in _handle_dbapi_exception\n    exc_info\n  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py\", line 203, in raise_from_cause\n    reraise(type(exception), exception, tb=exc_tb, cause=cause)\n  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 1193, in _execute_context\n    context)\n  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py\", line 507, in do_execute\n    cursor.execute(statement, parameters)\nsqlalchemy.exc.OperationalError: (sqlite3.OperationalError) duplicate column name: uuid [SQL: u'ALTER TABLE sources_tmp ADD COLUMN uuid VARCHAR(36)'] (Background on this error at: http
://sqlalche.me/e/e3q8)\n+ echo 'Error migrating database: Backup saved to /var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite'\nError migrating database: Backup saved to /var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite\n+ return 1\nTraceback (most recent call last):\n  File \"/tmp/restore.py\", line 53, in <module>\n    main()\n  File \"/tmp/restore.py\", line 49, in main\n    subprocess.check_call(['dpkg-reconfigure', 'securedrop-app-code'])\n  File \"/usr/lib/python2.7/subprocess.py\", line 540, in check_call\n    raise CalledProcessError(retcode, cmd)\nsubprocess.CalledProcessError: Command '['dpkg-reconfigure', 'securedrop-app-code']' returned non-zero exit status 1", "stderr_lines": ["+ set -o pipefail", "+ case \"$1\" in", "+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop", "+ mkdir -p /var/lib/securedrop/", "+ chmod 0700 /var/lib/securedrop/", "+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop", "+ mkdir -p /var/lib/securedrop/tmp", "+ chmod 0700 /var/lib/securedrop/tmp", "+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop", "+ mkdir -p /var/lib/securedrop/store", "+ chmod 0700 /var/lib/securedrop/store", "+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop", "+ mkdir -p /var/lib/securedrop/keys", "+ chmod 0700 /var/lib/securedrop/keys", "+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop", "+ mkdir -p /var/lib/securedrop/backups", "+ chmod 0700 /var/lib/securedrop/backups", "+ for dir in '/var/lib/securedrop/{,tmp,store,keys,backups}' /var/www/securedrop", "+ mkdir -p /var/www/securedrop", "+ chmod 0700 /var/www/securedrop", "+ chown -R www-data:www-data /var/lib/securedrop /var/www/securedrop", "+ pip install --no-index --find-links=/var/securedrop/wheelhouse --upgrade -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt", "+ chown -R www-data:www-data /var/www/securedrop",
 "+ chown www-data:www-data /var/www/journalist.wsgi", "+ chown www-data:www-data /var/www/source.wsgi", "+ a2dissite 000-default", "+ a2dissite default-ssl", "+ service apache2 stop", "+ '[' -e /etc/apparmor.d/disable/usr.sbin.apache2 ']'", "+ aa-enforce /etc/apparmor.d/usr.sbin.tor", "+ aa-enforce /etc/apparmor.d/usr.sbin.apache2", "+ permit_wsgi_authorization", "+ journalist_conf=/etc/apache2/sites-available/journalist.conf", "+ grep -qP '^WSGIPassAuthorization' /etc/apache2/sites-available/journalist.conf", "+ service apache2 restart", "+ rm -fr /var/www/securedrop/static/gen/journalist.js /var/www/securedrop/static/gen/source.js", "+ '[' -n 0.10.0~rc2 ']'", "+ '[' 0.10.0~rc2 = 0.3 ']'", "+ chmod u+w /var/www/securedrop/static/i/logo.png", "+ grep -qE 'MACs\\s.*hmac-sha1' /etc/ssh/sshd_config", "+ database_migration", "+ database_dir=/var/lib/securedrop", "+ database_file=/var/lib/securedrop/db.sqlite", "+ '[' '!' -e /var/lib/securedrop/db.sqlite ']'", "+ cd /var/www/securedrop/", "++ alembic current", "INFO  [alembic.runtime.migration] Context impl SQLiteImpl.", "INFO  [alembic.runtime.migration] Will assume non-transactional DDL.", "+ '[' -z '' ']'", "++ sqlite3 /var/lib/securedrop/db.sqlite .tables", "+ sqlite_tables='alembic_version           replies                   submissions             ", "journalist_login_attempt  source_stars            ", "journalists               sources                 '", "+ grep -q journalists", "+ echo 'alembic_version           replies                   submissions             ", "journalist_login_attempt  source_stars            ", "journalists               sources                 '", "+ alembic stamp 15ac9509fc68", "INFO  [alembic.runtime.migration] Context impl SQLiteImpl.", "INFO  [alembic.runtime.migration] Will assume non-transactional DDL.", "INFO  [alembic.runtime.migration] Running stamp_revision  -> 15ac9509fc68", "++ date +%Y-%m-%d-%H-%M-%S", "+ db_backup=/var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite",
 "+ grep -q '(head)'", "+ alembic current", "INFO  [alembic.runtime.migration] Context impl SQLiteImpl.", "INFO  [alembic.runtime.migration] Will assume non-transactional DDL.", "+ cp /var/lib/securedrop/db.sqlite /var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite", "+ alembic upgrade head", "INFO  [alembic.runtime.migration] Context impl SQLiteImpl.", "INFO  [alembic.runtime.migration] Will assume non-transactional DDL.", "INFO  [alembic.runtime.migration] Running upgrade 15ac9509fc68 -> faac8092c123, enable security pragmas", "INFO  [alembic.runtime.migration] Running upgrade faac8092c123 -> 3d91d6948753, Create source UUID column", "Traceback (most recent call last):", "  File \"/usr/local/bin/alembic\", line 11, in <module>", "    sys.exit(main())", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/config.py\", line 486, in main", "    CommandLine(prog=prog).main(argv=argv)", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/config.py\", line 480, in main", "    self.run_cmd(cfg, options)", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/config.py\", line 463, in run_cmd", "    **dict((k, getattr(options, k, None)) for k in kwarg)", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/command.py\", line 254, in upgrade", "    script.run_env()", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/script/base.py\", line 427, in run_env", "    util.load_python_file(self.dir, 'env.py')", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/util/pyfiles.py\", line 81, in load_python_file", "    module = load_module_py(module_id, path)", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/util/compat.py\", line 141, in load_module_py", "    mod = imp.load_source(module_id, path, fp)", "  File \"alembic/env.py\", line 82, in <module>", "    run_migrations_online()", "  File \"alembic/env.py\", line 76, in run_migrations_online", "    context.run_migrations()", "  File \"<string>\", line 8, in run_migrations", "  File \"/u
sr/local/lib/python2.7/dist-packages/alembic/runtime/environment.py\", line 836, in run_migrations", "    self.get_context().run_migrations(**kw)", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/runtime/migration.py\", line 330, in run_migrations", "    step.migration_fn(**kw)", "  File \"/var/www/securedrop/alembic/versions/3d91d6948753_create_source_uuid_column.py\", line 26, in upgrade", "    op.add_column('sources_tmp', sa.Column('uuid', sa.String(length=36)))", "  File \"<string>\", line 8, in add_column", "  File \"<string>\", line 3, in add_column", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/operations/ops.py\", line 1565, in add_column", "    return operations.invoke(op)", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/operations/base.py\", line 319, in invoke", "    return fn(self, operation)", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/operations/toimpl.py\", line 123, in add_column", "    schema=schema", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/ddl/impl.py\", line 172, in add_column", "    self._exec(base.AddColumn(table_name, column, schema=schema))", "  File \"/usr/local/lib/python2.7/dist-packages/alembic/ddl/impl.py\", line 118, in _exec", "    return conn.execute(construct, *multiparams, **params)", "  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 948, in execute", "    return meth(self, multiparams, params)", "  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/ddl.py\", line 68, in _execute_on_connection", "    return connection._execute_ddl(self, multiparams, params)", "  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 1009, in _execute_ddl", "    compiled", "  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 1200, in _execute_context", "    context)", "  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 1413, in _handle_dbapi_exception", "    exc_i
nfo", "  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py\", line 203, in raise_from_cause", "    reraise(type(exception), exception, tb=exc_tb, cause=cause)", "  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py\", line 1193, in _execute_context", "    context)", "  File \"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py\", line 507, in do_execute", "    cursor.execute(statement, parameters)", "sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) duplicate column name: uuid [SQL: u'ALTER TABLE sources_tmp ADD COLUMN uuid VARCHAR(36)'] (Background on this error at: http://sqlalche.me/e/e3q8)", "+ echo 'Error migrating database: Backup saved to /var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite'", "Error migrating database: Backup saved to /var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite", "+ return 1", "Traceback (most recent call last):", "  File \"/tmp/restore.py\", line 53, in <module>", "    main()", "  File \"/tmp/restore.py\", line 49, in main", "    subprocess.check_call(['dpkg-reconfigure', 'securedrop-app-code'])", "  File \"/usr/lib/python2.7/subprocess.py\", line 540, in check_call", "    raise CalledProcessError(retcode, cmd)", "subprocess.CalledProcessError: Command '['dpkg-reconfigure', 'securedrop-app-code']' returned non-zero exit status 1"], "stdout": " * Restarting web server apache2\n   ...done.\n * Reloading tor daemon configuration...\n   ...done.\nIgnoring indexes: https://pypi.python.org/simple/\nRequirement already up-to-date: alembic==0.9.9 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 7))\nRequirement already up-to-date: argon2-cffi==18.1.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 8))\nRequirement already up-to-date: asn1crypto==0.24.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/
www/securedrop/requirements/securedrop-app-code-requirements.txt (line 9))\nRequirement already up-to-date: babel==2.5.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 10))\nRequirement already up-to-date: cffi==1.11.5 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 11))\nRequirement already up-to-date: click==6.7 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 12))\nRequirement already up-to-date: cryptography==2.0.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 13))\nRequirement already up-to-date: cssmin==0.2.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 14))\nRequirement already up-to-date: enum34==1.1.6 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 15))\nRequirement already up-to-date: flask-assets==0.12 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 16))\nRequirement already up-to-date: flask-babel==0.11.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 17))\nRequirement already up-to-date: flask-sqlalchemy==2.3.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 18))\nRequirement already up-to-date: flask-wtf==0.14.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 19))\nRequirement already up-to-date: flask==1.0.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/sec
uredrop/requirements/securedrop-app-code-requirements.txt (line 20))\nRequirement already up-to-date: gnupg==2.3.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 21))\nRequirement already up-to-date: idna==2.6 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 22))\nRequirement already up-to-date: ipaddress==1.0.22 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 23))\nRequirement already up-to-date: itsdangerous==0.24 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 24))\nRequirement already up-to-date: jinja2==2.10 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 25))\nRequirement already up-to-date: jsmin==2.2.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 26))\nRequirement already up-to-date: mako==1.0.7 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 27))\nRequirement already up-to-date: markupsafe==1.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 28))\nRequirement already up-to-date: passlib==1.7.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 29))\nRequirement already up-to-date: psutil==5.4.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 30))\nRequirement already up-to-date: pycparser==2.18 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/secur
edrop-app-code-requirements.txt (line 31))\nRequirement already up-to-date: pyotp==2.2.6 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 32))\nRequirement already up-to-date: python-dateutil==2.7.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 33))\nRequirement already up-to-date: python-editor==1.0.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 34))\nRequirement already up-to-date: pytz==2017.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 35))\nRequirement already up-to-date: qrcode==5.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 36))\nRequirement already up-to-date: redis==2.10.6 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 37))\nRequirement already up-to-date: rq==0.10.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 38))\nRequirement already up-to-date: scrypt==0.8.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 39))\nRequirement already up-to-date: sh==1.12.14 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 40))\nRequirement already up-to-date: six==1.11.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 41))\nRequirement already up-to-date: sqlalchemy==1.2.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-require
ments.txt (line 42))\nRequirement already up-to-date: typing==3.6.4 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 43))\nRequirement already up-to-date: webassets==0.12.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 44))\nRequirement already up-to-date: werkzeug==0.14.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 45))\nRequirement already up-to-date: wtforms==2.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 46))\nCleaning up...\nSite 000-default already disabled\nSite default-ssl already disabled\n * Stopping web server apache2\n * \nSetting /etc/apparmor.d/usr.sbin.tor to enforce mode.\nSetting /etc/apparmor.d/usr.sbin.apache2 to enforce mode.\n * Restarting web server apache2\n   ...done.", "stdout_lines": [" * Restarting web server apache2", "   ...done.", " * Reloading tor daemon configuration...", "   ...done.", "Ignoring indexes: https://pypi.python.org/simple/", "Requirement already up-to-date: alembic==0.9.9 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 7))", "Requirement already up-to-date: argon2-cffi==18.1.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 8))", "Requirement already up-to-date: asn1crypto==0.24.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 9))", "Requirement already up-to-date: babel==2.5.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 10))", "Requirement already up-to-date: cffi==1.11.5 in /usr/local
/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 11))", "Requirement already up-to-date: click==6.7 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 12))", "Requirement already up-to-date: cryptography==2.0.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 13))", "Requirement already up-to-date: cssmin==0.2.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 14))", "Requirement already up-to-date: enum34==1.1.6 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 15))", "Requirement already up-to-date: flask-assets==0.12 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 16))", "Requirement already up-to-date: flask-babel==0.11.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 17))", "Requirement already up-to-date: flask-sqlalchemy==2.3.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 18))", "Requirement already up-to-date: flask-wtf==0.14.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 19))", "Requirement already up-to-date: flask==1.0.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 20))", "Requirement already up-to-date: gnupg==2.3.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 21))", "Requirement already up-to-date: idna==2.6 
in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 22))", "Requirement already up-to-date: ipaddress==1.0.22 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 23))", "Requirement already up-to-date: itsdangerous==0.24 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 24))", "Requirement already up-to-date: jinja2==2.10 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 25))", "Requirement already up-to-date: jsmin==2.2.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 26))", "Requirement already up-to-date: mako==1.0.7 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 27))", "Requirement already up-to-date: markupsafe==1.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 28))", "Requirement already up-to-date: passlib==1.7.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 29))", "Requirement already up-to-date: psutil==5.4.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 30))", "Requirement already up-to-date: pycparser==2.18 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 31))", "Requirement already up-to-date: pyotp==2.2.6 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 32))", "Requirement already up-to-date: python-dateuti
l==2.7.2 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 33))", "Requirement already up-to-date: python-editor==1.0.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 34))", "Requirement already up-to-date: pytz==2017.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 35))", "Requirement already up-to-date: qrcode==5.3 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 36))", "Requirement already up-to-date: redis==2.10.6 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 37))", "Requirement already up-to-date: rq==0.10.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 38))", "Requirement already up-to-date: scrypt==0.8.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 39))", "Requirement already up-to-date: sh==1.12.14 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 40))", "Requirement already up-to-date: six==1.11.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 41))", "Requirement already up-to-date: sqlalchemy==1.2.0 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 42))", "Requirement already up-to-date: typing==3.6.4 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 43))", "Requirement already up-to-date: webassets==0.
12.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 44))", "Requirement already up-to-date: werkzeug==0.14.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 45))", "Requirement already up-to-date: wtforms==2.1 in /usr/local/lib/python2.7/dist-packages (from -r /var/www/securedrop/requirements/securedrop-app-code-requirements.txt (line 46))", "Cleaning up...", "Site 000-default already disabled", "Site default-ssl already disabled", " * Stopping web server apache2", " * ", "Setting /etc/apparmor.d/usr.sbin.tor to enforce mode.", "Setting /etc/apparmor.d/usr.sbin.apache2 to enforce mode.", " * Restarting web server apache2", "   ...done."]}

Steps to Reproduce

• Install SecureDrop 0.10.0~rc2 on prod VMs
• run the backup procedure as documented
• run ./manage.py reset on the app server
• run the restore procedure as documented

Environment

Candidate version: 0.10.0~rc2
Tails version: 3.9.1
Instance hardware: prod VMs

Expected Behavior

Server config and DB are restored without error

Actual Behavior

Restore fails with the errors above

Comments

Attached copy of sqlite db backup referenced in the first error message.

2018-10-16-03-20-48-db.sqlite.zip

It looks like it's related to the uuid column:

sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) duplicate column name: uuid [SQL: u'ALTER TABLE sources_tmp ADD COLUMN uuid VARCHAR(36)'] (Background on this error at: http://sqlalche.me/e/e3q8)
+ echo 'Error migrating database: Backup saved to /var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite'
Error migrating database: Backup saved to /var/lib/securedrop/backups/2018-10-16-03-20-48-db.sqlite
+ return 1

[zenmonkeykstop]

Replicated without the ./manage.py reset step, failed with same error

[zenmonkeykstop]

FWIW, this was not reproducible on a fresh 0.10.0-rc2 install on 2014 Mac Minis.

[heartsucker]

Root problem is that the backup is stamped at the wrong migration version:

$ sqlite3 2018-10-16-03-20-48-db.sqlite "select * from alembic_version;"
15ac9509fc68

The revision 15ac9509fc68 is for the init migration (namely 15ac9509fc68_init.py). This means we're stamping a database at the wrong revision somewhere and then attempting to apply the migrations on top of it.

[heartsucker]

I cannot reproduce this on release/0.10.0 or develop. My steps were:

1. make clean
2. make build-debs
3. vagrant up /staging/
   1. Check alembic_revision
4. Run securedrop-backup.yml
   1. Check alembic_revision
5. Run securedrop-restore.yml
   1. Check alembic_revision

In every case when I checked the alembic revision, it was f2833ac34bb6 as expected.

[heartsucker]

Wait hold up. Just realized that the zip you provided was the zipped backup pre revision that the postinst creates in order to prevent everything from getting totally ruined*. How did you manage to backup from that?

* this line in postinst

db_backup="/var/lib/securedrop/backups/$(date +%Y-%m-%d-%H-%M-%S)-db.sqlite"

[heartsucker]

Ok wait never mind again. That just got grabbed by the backup script because it was in /var/lib/securedrop.

I'm pretty sure this bit in postinst is the culprit.

        if ! echo "$sqlite_tables" | grep -q journalists; then
            log_the_shit UPGRADE HEAD
            # This is a fresh install, run the full migrations.
            alembic upgrade head
        else
            log_the_shit STAMP
            # This is an old install, so mark that the schema is up to date
            # as of the version of migration 15ac9509fc68_init.py when we first
            # started version controlling the database.
            alembic stamp 15ac9509fc68
        fi

But I'm not sure how the check is failing. I don't like the amount of the really tricky logic in postinst that is written in bash tbh, and I wonder if we should rewrite it in Python.

[zenmonkeykstop]

Also not reproducible in Mac Mini upgrade testing, either with a 0.9.1 -> 0.10.0 backup or a 0.10.0 -> 0.10.0 backup.

[redshiftzero]

@heartsucker you mentioned "flakiness" in sprint planning, can you expand on exactly which logic you think is flaky? Is it this line? (flakiness there will cause us to enter the code you point out in postinst, which would cause the database to get incorrectly stamped at 15ac9509fc68)

I just want to make sure we agree that this logic is solid prior to closing this issue even though we're having trouble reproducing. Obviously, any flakiness in database migrations is very high priority to resolve.

[heartsucker]

Both lines 38 and 41 would have to fail for very bad things to happen. I used flake because we got an error once somehow, but can't reproduce (the initial problem that cause this ticket to be opened). I don't think those lines are going to break in any non-totally-borked-OS situations, but I guess I like ironclad. monadic error handling and not this whole bash ¯\_(ツ)_/¯ thing.

Which is to say. I think this is robust enough to warrant closing the ticket. If I thought that above if/fi bit was flaky, I would have said something before we merged it in.

I just hate this about bash.

heartsucker@pythagoras:~$ set -e
heartsucker@pythagoras:~$ : $(echo 'wat' && false; echo 'lol')
heartsucker@pythagoras:~$ echo $?
0
heartsucker@pythagoras:~$ echo $x
wat lol

The error from false gets swallowed in that subshell.

[redshiftzero]

great, agreed @heartsucker. And since multiple testers can't reproduce and looking at a long-running (since 0.8) prod test instance (@emkll just did this) confirms the database is at the expected revision, I'm closing this.