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

Bug #1807262 reported by Corey Bryant on 2018-12-06
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
sqlalchemy-migrate
Undecided
Unassigned
cinder (Ubuntu)
High
Unassigned
migrate (Ubuntu)
High
Unassigned
nova (Ubuntu)
High
Unassigned
sqlite3 (Ubuntu)
Undecided
Unassigned

Bug Description

Several tests that use sqlite fail with: "sqlalchemy.exc.NoSuchTableError: migration_tmp". I'm currently hitting this with nova and cinder packages in disco.

Note this started sometime after 11/19 when nova 2:19.0.0~b1~git2018111953.3e756ff674-0ubuntu1 was uploaded (and built successfully at the time).

After doing some digging this appears to occur with libsqlite3-0 3.26.0-1 but does not occur with libsqlite3-0 3.25.3-1. Here are some more details on that, shown by running a failing unit test from the cinder package: https://paste.ubuntu.com/p/hsnQFQD572/

Update: The test in the paste above also works successfully with libsqlite3-0 3.25.3-2.

summary: - stein unit test failures with libsqlite3-0 3.26.0-1
+ stein unit tests fail with sqlalchemy.exc.NoSuchTableError:
+ migration_tmp
description: updated
description: updated
Changed in cinder (Ubuntu):
status: New → Triaged
Changed in nova (Ubuntu):
status: New → Triaged
Changed in cinder (Ubuntu):
importance: Undecided → High
Changed in nova (Ubuntu):
importance: Undecided → High
description: updated

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?

Corey Bryant (corey.bryant) wrote :

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.

Laszlo Boszormenyi (gcs) wrote :

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):

Laszlo Boszormenyi (gcs) wrote :

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

Corey Bryant (corey.bryant) wrote :

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

Changed in migrate (Ubuntu):
status: New → Triaged
importance: Undecided → High
Changed in nova (Ubuntu):
status: Triaged → Invalid
Changed in cinder (Ubuntu):
status: Triaged → Invalid
Changed in sqlite3 (Ubuntu):
status: New → Invalid
Changed in nova (Ubuntu):
importance: High → Undecided
Changed in cinder (Ubuntu):
importance: High → Undecided
Corey Bryant (corey.bryant) wrote :

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.

Corey Bryant (corey.bryant) wrote :

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

Changed in cinder (Ubuntu):
status: Invalid → Triaged
importance: Undecided → High
Changed in nova (Ubuntu):
status: Invalid → Triaged
importance: Undecided → High
Launchpad Janitor (janitor) wrote :

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

Changed in migrate (Ubuntu):
status: Triaged → Fix Released
Launchpad Janitor (janitor) wrote :

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

Changed in nova (Ubuntu):
status: Triaged → Fix Released
Launchpad Janitor (janitor) wrote :

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

Changed in cinder (Ubuntu):
status: Triaged → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers