stein unit tests fail with sqlalchemy.exc.NoSuchTableError: migration_tmp

FYI there is [1] now (since an hour), which is building atm.
The delta added is [2] to

The code that seems to be related and not working is not using a view, but who knows [3]
  self.append('ALTER TABLE %s RENAME TO migration_tmp' % table_name)
(If that is the right code at all, I need to check the package)

I first reproduced it locally with cinder as corey has shown.
it worked with 3.24 and got massive (not just this) errors with 3.26

Note: by enabling cosmic, disco and disco-proposed repos you can up and downgrade to all three.
Also useful [4] on how to run isolated tests of cinder.

Much more tests fail BTW, it seems all of the same class of tests fail. So maybe it is a DB setup issue with the new sqlite.

sqlite 3.24.0-1: works
sqlite 3.26.0-1: fails
sqlite 3.26.0-2: fails

So the next version is not a fix that will unblock us.
Also [5] changelog isn't pointing to anything obvious (I'm sure once we know it later it will be obvious).

We need to isolate the first fail as all others could be follow on issues.
So far it refused be isolated to a reasonable subset of tests.
But I didn't focus on that yet, I'll go back to 3.24 and try to shrink the set.

[1]: https://launchpad.net/ubuntu/+source/sqlite3/3.26.0-2
[2]: http://launchpadlibrarian.net/400530194/sqlite3_3.26.0-1_3.26.0-2.diff.gz
[3]: https://gitlab.cern.ch/cloud-infrastructure/rally/commit/3995f1fcd03b76f923637f39cc1b12f599fa61f6?expanded=1#21dac577876a8712e411fa71aa768fbd11a87883_108_0
[4]: https://docs.openstack.org/cinder/latest/contributor/testing.html
[5]: https://www.sqlite.org/changes.html

Hrm, this is not my homest of home turfs :-/
- tox based test calling (as mentioned upstream) blocks on pip install
- the python3-stestr based test fails to find resources when stripped

This works:
$ pkgos-dh_auto_test --no-py2 "cinder.tests.unit.api.contrib.test_volume_type_encryption.VolumeTypeEncryptionTest.test_create_volume_exists" 2>&1 | tee testlog-3.26.0-2.summary

Looking back I realized you seem to have adapted your Debian rules to call it rather similarly.

This works (and has a bit more unreadable debug data than the other call):

$PYTHON=python3.7 python3-stestr run --subunit "cinder.tests.unit.api.contrib.test_volume_type_encryption.VolumeTypeEncryptionTest.test_create_volume_exists" 2>&1 | tee testlog-3.26.0-2.details

Only in the good case I see this:
/usr/lib/python3/dist-packages/sqlalchemy/orm/evaluator.py:71: SAWarning: Evaluating non-mapped column expression 'updated_at' onto ORM instances; this is a deprecated use
    "UPDATE / DELETE expressions." % clause)

Maybe sqlite finally dropped this, but I'm not sure as this is a deprecation warning of python3-sqlalchemy and not sqlite3.

I then modified the test to fail in any case, that will spill more debug in the good case (if the test is good then it will only say ok).

That let me compare the info and warnings in the beginning between good/bad case:
The four INFO/WARNING on keystonemiddleware.auth_token, keystonemiddleware._common.config, keystonemiddleware.auth_token are the same in good and bad case.

The next entry in good case that is missing in the bad case is:
2018-12-07 09:13:42,744 INFO [cinder.rpc] Automatically selected cinder-scheduler objects version 1.37 as minimum service version.

As we knew from the logs already the issue is raised to "db_sync" at /usr/lib/python3/dist-packages/oslo_db/sqlalchemy/migration.py:81

that is:
test.py:setUp -> test.py::Database:__init__ -> db/migration.py:db_sync -> oslo_db/sqlalchemy/migration.py:81

The __init__ suppresses logging for tests, lets remove that and set it to STDERR.
        # Suppress logging for test runs
        migrate_logger = logging.getLogger('migrate')
        migrate_logger.setLevel(logging.DEBUG)
        handler = logging.StreamHandler(sys.stderr)
        handler.setLevel(logging.DEBUG)
        formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
        handler.setFormatter(formatter)
        migrate_logger.addHandler(handler)
But no useful insight by that.

The actual exception is raised when trying this:
    migration = versioning_api.upgrade(engine, repository, version)
      engine Engine(sqlite://)
      repository /root/cinder-14.0.0~b1~git2018111617.4529b193d/cinder/db/sqlalchemy/migrate_repo
      version None

The path is a sqlalchemy database migration repository.
It exists after the test, but I'm not sure what we could do with it.

That code is of:
python3-migrate: /usr/lib/python3/dist-packages/migrate/versioning/api.py

This will call
 _migrate(url, repository, version, upgrade=True, err=err, **opts)
   url=engine
   repo = the path above

That all seems ok and matches the upper stack trace in the report, nointh too obvious on the way there.

BTW the definition of "migration_tmp" is from python3-migrate sqlite3 backend.
/usr/lib/python3/dist-packages/migrate/changeset/databases/sqlite.py
:99: self.append('ALTER TABLE %s RENAME TO migration_tmp' % table_name)
:107: self.append('DROP TABLE migration_tmp')
:133: 'SELECT %(cols)s from migration_tmp')%{'cols':columns}
:148: ' from migration_tmp'
:161: return 'INSERT INTO %(table_name)s SELECT * from migration_tmp'
:180: return 'INSERT INTO %(table_name)s SELECT * from migration_tmp'
:194: return 'INSERT INTO %(table_name)s SELECT * from migration_tmp'

Which is again openstack/sqlalchemy btw from https://github.com/openstack/sqlalchemy-migrate/commits/master

No new commit there that would fix it either.

Oh yeah sqlite uses special repository software - thanks :-/
But there is https://github.com/mackyle/sqlite/commits/master

I wrote a build and test script that worked against 3.24 and 3.26 from git confirming the results.

Kicking that in git bisect to hopefully be able to pick up some insight later on.

# git bisect start
# git bisect good version-3.24.0
# git bisect bad version-3.26.0
# git bisect run ~/bin/buildsqlite3.sh

The first commit built fine and tested as good, that seems ok'ish.
Walking away for now ...

$ cat #~/bin/buildsqlite3.sh
#!/bin/sh
set -ux
# See http://www.wtfpl.net/txt/copying for license details
# Creates a minimal manifest and manifest.uuid file so sqlite (and fossil) can build
testdir="/root/cinder-14.0.0~b1~git2018111617.4529b193d"
basedir=$(pwd)

# special bullshit for Fossil versioning system compat
git rev-parse --git-dir >/dev/null || exit 1
echo $(git log -1 --format=format:%H) > manifest.uuid
echo C $(cat manifest.uuid) > manifest
git log -1 --format=format:%ci%n | sed 's/ [-+].*$//;s/ /T/;s/^/D /' >> manifest

# get temp build dir
bdir=$(mktemp -d)
cd "${bdir}"

"${basedir}/configure" || exit 125
make -j || exit 125
make -j sqlite3.c || exit 125
make install || exit 125
# something did not install correctly
ls -laF /usr/local/lib/libsqlite3* || exit 125

# Test
cd "${testdir}"
export LD_LIBRARY_PATH=/usr/local/lib
pkgos-dh_auto_test --no-py2 "cinder.tests.unit.api.contrib.test_volume_type_encryption.VolumeTypeEncryptionTest.test_create_volume_exists"
rc=$?
unset LD_LIBRARY_PATH

# cleanup
# do not by accident test against older libs
rm -f /usr/local/lib/libsqlite3*
cd "${basedir}"
rm -rf "${bdir}"
git clean -f -x

# deliver actual test RC
exit ${rc};

git bisect start
# good: [cbb6e4f7de0115395269860fed18d56beb7ac2bb] Version 3.24.0
git bisect good cbb6e4f7de0115395269860fed18d56beb7ac2bb
# bad: [d4f098763eb4fd12a99497340e2f589b37234676] Version 3.26.0
git bisect bad d4f098763eb4fd12a99497340e2f589b37234676
# good: [bf92c08976ad16818be09a6941995bfbf43858f0] Add the "atrc" test program to the Makefiles. Fix a typo in the instructions in the header comment of the atrc program.
git bisect good bf92c08976ad16818be09a6941995bfbf43858f0
# good: [ab747c198137c2890b16c2e28afa0d447bcfe8a2] Minor simplification: In OP_ParseSchema, read the p1 register once.
git bisect good ab747c198137c2890b16c2e28afa0d447bcfe8a2
# good: [43172f4b080b5f9f8563b8df351dc742afe21bb0] Eponymous virtual tables appear to exist in all schemas. This is an alternative and improved fix to the eponymous virtual table in trigger problem that was previously addressed by checkin [1fa74930ab56171e].
git bisect good 43172f4b080b5f9f8563b8df351dc742afe21bb0
# bad: [e504cfa1878e1d3253e6ff03b33156db2c99c931] Improvements to the CSV virtual table.
git bisect bad e504cfa1878e1d3253e6ff03b33156db2c99c931
# bad: [910531f62a723fec548be99fa7dd71888d07d5e7] Merge fixes from trunk.
git bisect bad 910531f62a723fec548be99fa7dd71888d07d5e7
# good: [fba76ed87c26c84fb14277efd80ac774533bc92a] Merge the permutations fix from trunk.
git bisect good fba76ed87c26c84fb14277efd80ac774533bc92a
# good: [6436da628906b028a2e15c273ff03f7984310111] Improved documentation for SQLITE_DBCONFIG_DEFENSIVE. Add a NEVER() macro on an unreachable branch.
git bisect good 6436da628906b028a2e15c273ff03f7984310111
# good: [eb689e572223191847e3ed3140902d0d309d04d4] Fix for ticket [787fa716be3a7f650cac]
git bisect good eb689e572223191847e3ed3140902d0d309d04d4
# bad: [3cab37c2f2261ccca632a1843b8baeccdecd110d] Fix invalid use of unprotected sqlite3_value objects in the sqldiff utility, when using the --changeset option.
git bisect bad 3cab37c2f2261ccca632a1843b8baeccdecd110d
# bad: [2defce45c5670e0258374eeb2e293fcf6f82bddd] When a table is renamed using "ALTER TABLE RENAME TO", update any REFERENCES clauses that refer to the table, unless "PRAGMA legacy_alter_table" is true and "PRAGMA foreign_keys" is set to false (i.e. so that when "PRAGMA legacy_alter_table" is set behaviour is still compatible with versions 3.24 and earlier).
git bisect bad 2defce45c5670e0258374eeb2e293fcf6f82bddd
# first bad commit: [2defce45c5670e0258374eeb2e293fcf6f82bddd] When a table is renamed using "ALTER TABLE RENAME TO", update any REFERENCES clauses that refer to the table, unless "PRAGMA legacy_alter_table" is true and "PRAGMA foreign_keys" is set to false (i.e. so that when "PRAGMA legacy_alter_table" is set behaviour is still compatible with versions 3.24 and earlier).

=> https://github.com/mackyle/sqlite/commit/2defce45c5670e0258374eeb2e293fcf6f82bddd

quoting; ... so that when "PRAGMA legacy_alter_table" is set behaviour is still compatible with versions 3.24 and earlier).

WTH where would/should we set that PRAGMA?
I think that would be in sqlalchemy's sqlite backend?

Coreybc can you take over from here?

Christian, thanks for all the digging! I just ran a successful test against sqlite 3.26.0-2 package rebuilt with 2defce45c5670e0258374eeb2e293fcf6f82bddd reverted. That's the only change I made and it seems to resolve the issue. Now to figure out if that patch is fine and we really need to update PRAGMAs to enable legacy usage or if there is a bug upstream.

It's 'PRAGMA legacy_alter_table = ON' and the following change in src:migrate (0.11.0 version) might do the trick.

@@ -9,6 +9,7 @@ except ImportError: # Python 2
     from UserDict import DictMixin
 from copy import copy
 import re
+import sqlite3

 from sqlalchemy.databases import sqlite as sa_base
 from sqlalchemy.schema import ForeignKeyConstraint
@@ -96,6 +97,10 @@ class SQLiteHelper(SQLiteCommon):
             if omit_constraints is None or cons.name not in omit_constraints
         ])

+ tup = sqlite3.sqlite_version_info
+ if tup[0] > 3 or (tup[0] == 3 and tup[1] >= 26):
+ self.append('PRAGMA legacy_alter_table = ON')
+ self.execute()
         self.append('ALTER TABLE %s RENAME TO migration_tmp' % table_name)
         self.execute()

@@ -106,6 +111,9 @@ class SQLiteHelper(SQLiteCommon):
         self.execute()
         self.append('DROP TABLE migration_tmp')
         self.execute()
+ if tup[0] > 3 or (tup[0] == 3 and tup[1] >= 26):
+ self.append('PRAGMA legacy_alter_table = OFF')
+ self.execute()

     def visit_column(self, delta):
         if isinstance(delta, DictMixin):

Indentation is messed up during the post, but easy to correct if you see the source of the migrate/changeset/databases/sqlite.py file.

Laszlo, I just tested with the updates you posted in comment #8 and it works. \o/

Laszlo, that fix seems reasonable. Do you want to push on getting that into migrate and uploaded to Debian or would you like one of us to handle it? Thanks again for the quick responses on this.

I've moved ahead with an upstream PR and will be uploading to Ubuntu shortly with a patch/bug to Debian.

Upstream PR: https://review.openstack.org/#/c/623564/

This bug was fixed in the package migrate - 0.11.0-3ubuntu1

---------------
migrate (0.11.0-3ubuntu1) disco; urgency=medium

  * d/p/use-legacy-alter-sqlite.patch: Cherry-picked from upstream
    gerrit review (https://review.openstack.org/#/c/623564/) to ensure
    compatability with sqlite >= 3.26 (LP: #1807262).

 -- Corey Bryant <email address hidden> Fri, 07 Dec 2018 14:16:59 -0500

This bug was fixed in the package nova - 2:19.0.0~b1~git2018120609.c9dca64fa6-0ubuntu1

---------------
nova (2:19.0.0~b1~git2018120609.c9dca64fa6-0ubuntu1) disco; urgency=medium

  * d/tests/control, d/tests/nova-daemons: Switch to using mysql-server
    databases in autopkgtests.
  * New upstream snapshot for OpenStack Stein.
  * d/control: Ensure python3-migrate version is compatable with sqlite>=3.26
    (LP: #1807262).

 -- Corey Bryant <email address hidden> Thu, 06 Dec 2018 09:31:17 -0500

This bug was fixed in the package cinder - 2:14.0.0~b1~git2018120609.2cd694046-0ubuntu1

---------------
cinder (2:14.0.0~b1~git2018120609.2cd694046-0ubuntu1) disco; urgency=medium

  * d/tests/control, d/tests/cinder-daemons, d/tests/cinder-volume: Switch to
    using mysql-server databases in autopkgtests.
  * New upstream snapshot for OpenStack Stein.
  * d/control: Align (Build-)Depends with upstream.
  * d/control: Ensure python3-migrate version is compatable with sqlite>=3.26
    (LP: #1807262).

 -- Corey Bryant <email address hidden> Thu, 06 Dec 2018 09:27:58 -0500

For what it's worth, I'm seeing this issue on Fedora 29 too with SQLite 3.26.0. Downgrading to 3.24.0 resolves things. Time to get some movement on that patch.

Steps to reproduce using a Fedora container, courtesy of sean-k-mooney.

#create fedora29 docker container or use a fedora 29 host
sudo docker run --rm -it fedora bash
# recreate bug
yum install -y tox git python2-devel libffi-devel make gcc
cd ~
git clone http://github.com/openstack/nova
cd nova/
tox -e py27 -- test_create_fails_instance
#passes
dnf list --installed | grep sqlite
# shoudl be using 3.24
dnf install -y sqlite
tox -e py27 -- test_create_fails_instance
# fails

Reviewed: https://review.openstack.org/623564
Committed: https://git.openstack.org/cgit/openstack/sqlalchemy-migrate/commit/?id=231a4d2ae9f8496cfc8eea2e6bb8186a0dd602f9
Submitter: Zuul
Branch: master

commit 231a4d2ae9f8496cfc8eea2e6bb8186a0dd602f9
Author: Corey Bryant <email address hidden>
Date: Fri Dec 7 13:49:20 2018 -0500

    Use legacy_alter_table ON in sqlite recreate_table

    Use "PRAGMA legacy_alter_table = ON" with sqlite >= 3.26 when
    using "ALTER TABLE RENAME TO migration_tmp" to maintain legacy
    behavior.

    As of sqlite version 3.26, when a table is renamed using
    "ALTER TABLE RENAME TO", REFERENCES clauses that refer to the
    table will be updated. To maintain legacy (3.24 and earlier)
    behavior, "PRAGMA legacy_alter_table" can be set to true and
    "PRAGMA foreign_keys" can be set to false. [1]

    [1] https://www.sqlite.org/src/info/ae9638e9c0ad0c36

    Thanks to "László Böszörményi (GCS)" <email address hidden> for
    providing the code for this patch, which has since been
    slightly modified.

    Change-Id: I539988ab2ad6df6c8f423ecec15364ad8fcc7267
    Closes-Bug: 1807262

This issue was fixed in the openstack/sqlalchemy-migrate 0.12.0 release.