Alembic 1.6.x hangs with 100% CPU usage

[silenius]

Describe the bug

~/code/projects/riparias/ alembic -c dev.ini upgrade heads
2021-05-17 13:24:05,775 INFO  [sqlalchemy.engine.base.Engine][MainThread] select version()
2021-05-17 13:24:05,775 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,780 INFO  [sqlalchemy.engine.base.Engine][MainThread] select current_schema()
2021-05-17 13:24:05,780 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,784 INFO  [sqlalchemy.engine.base.Engine][MainThread] SELECT CAST('test plain returns' AS VARCHAR(60)) AS anon_1
2021-05-17 13:24:05,784 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,786 INFO  [sqlalchemy.engine.base.Engine][MainThread] SELECT CAST('test unicode returns' AS VARCHAR(60)) AS anon_1
2021-05-17 13:24:05,787 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,788 INFO  [sqlalchemy.engine.base.Engine][MainThread] show standard_conforming_strings
2021-05-17 13:24:05,788 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,796 INFO  [sqlalchemy.engine.base.Engine][MainThread] BEGIN (implicit)
2021-05-17 13:24:05,798 INFO  [sqlalchemy.engine.base.Engine][MainThread] select relname from pg_class c join pg_namespace n on n.oid=c.relnamespace where pg_catalog.pg_table_is_visible(c.oid) and relname=%(name)s
2021-05-17 13:24:05,798 INFO  [sqlalchemy.engine.base.Engine][MainThread] {'name': 'alembic_version'}
2021-05-17 13:24:05,802 INFO  [sqlalchemy.engine.base.Engine][MainThread] select relname from pg_class c join pg_namespace n on n.oid=c.relnamespace where pg_catalog.pg_table_is_visible(c.oid) and relname=%(name)s
2021-05-17 13:24:05,802 INFO  [sqlalchemy.engine.base.Engine][MainThread] {'name': 'alembic_version'}
2021-05-17 13:24:05,806 INFO  [sqlalchemy.engine.base.Engine][MainThread] 
CREATE TABLE alembic_version (
        version_num VARCHAR(32) NOT NULL, 
        CONSTRAINT alembic_version_pkc PRIMARY KEY (version_num)
)


2021-05-17 13:24:05,806 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}

then it hangs with 100% CPU usage.
On the PosgreSQL side the query is in an "idle in transaction".

This is the alembic section in my dev.ini file:

[alembic]
script_location = riparias/alembic
file_template = %%(year)d%%(month).2d%%(day).2d_%%(rev)s_%%(slug)s
version_locations = amnesia:alembic/versions amnesia_multilingual:alembic/versions riparias/alembic/versions

Expected behavior

~/code/projects/riparias/ pip install alembic==1.5.8                                                                                           
Collecting alembic==1.5.8                                                                                                                     
  Using cached alembic-1.5.8-py2.py3-none-any.whl (159 kB)                                                                                    
Requirement already satisfied: Mako in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from alembic==1.5.8) (1.1.4)
Requirement already satisfied: SQLAlchemy>=1.3.0 in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from alembic==1.5.8) (1.3.24)
Requirement already satisfied: python-dateutil in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from alembic==1.5.8) (2.8.1)
Requirement already satisfied: python-editor>=0.3 in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from alembic==1.5.8) (1.0.4)
Requirement already satisfied: MarkupSafe>=0.9.2 in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from Mako->alembic==1.5.8) (2.0.0)
Requirement already satisfied: six>=1.5 in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from python-dateutil->alembic==1.5.8) (1.11.0)
Installing collected packages: alembic                                                                                                        
  Attempting uninstall: alembic                                   
    Found existing installation: alembic 1.6.2                         
    Uninstalling alembic-1.6.2:                                        
      Successfully uninstalled alembic-1.6.2                           
Successfully installed alembic-1.5.8                                   

~/code/projects/riparias/ alembic -c dev.ini upgrade heads                                                                                     
2021-05-17 13:27:35,420 INFO  [sqlalchemy.engine.base.Engine][MainThread] select version()                                                                                                                                                                                                  
2021-05-17 13:27:35,421 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}                                                                  
2021-05-17 13:27:35,425 INFO  [sqlalchemy.engine.base.Engine][MainThread] select current_schema()                                                                                                                                                                                           
2021-05-17 13:27:35,426 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}                                                                  
2021-05-17 13:27:35,429 INFO  [sqlalchemy.engine.base.Engine][MainThread] SELECT CAST('test plain returns' AS VARCHAR(60)) AS anon_1
2021-05-17 13:27:35,429 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}                                                                  
2021-05-17 13:27:35,431 INFO  [sqlalchemy.engine.base.Engine][MainThread] SELECT CAST('test unicode returns' AS VARCHAR(60)) AS anon_1
2021-05-17 13:27:35,432 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}         
2021-05-17 13:27:35,432 INFO  [sqlalchemy.engine.base.Engine][MainThread] show standard_conforming_strings                                                                                                                                                                                  
2021-05-17 13:27:35,433 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:35,441 INFO  [sqlalchemy.engine.base.Engine][MainThread] BEGIN (implicit)
2021-05-17 13:27:35,442 INFO  [sqlalchemy.engine.base.Engine][MainThread] select relname from pg_class c join pg_namespace n on n.oid=c.relnamespace where pg_catalog.pg_table_is_visible(c.oid) and relname=%(name)s
2021-05-17 13:27:35,443 INFO  [sqlalchemy.engine.base.Engine][MainThread] {'name': 'alembic_version'}
2021-05-17 13:27:35,447 INFO  [sqlalchemy.engine.base.Engine][MainThread] select relname from pg_class c join pg_namespace n on n.oid=c.relnamespace where pg_catalog.pg_table_is_visible(c.oid) and relname=%(name)s
2021-05-17 13:27:35,447 INFO  [sqlalchemy.engine.base.Engine][MainThread] {'name': 'alembic_version'}                                         
2021-05-17 13:27:35,451 INFO  [sqlalchemy.engine.base.Engine][MainThread] 
CREATE TABLE alembic_version (                                         
        version_num VARCHAR(32) NOT NULL,                                                                                                     
        CONSTRAINT alembic_version_pkc PRIMARY KEY (version_num)
)                                                                      
                                                                                                                                              
                                                                                                                                                                                                                                                                                            
2021-05-17 13:27:35,451 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}                                                                  
===>>> Executing  /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/amnesia/alembic/sql/upgrade/20191022_e025de45166e_init.sql                                                                                                                                               

(...)

`2021-05-17 13:27:35,502 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:36,414 INFO  [sqlalchemy.engine.base.Engine][MainThread] INSERT INTO alembic_version (version_num) VALUES ('e025de45166e') RETURNING alembic_version.version_num
2021-05-17 13:27:36,414 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
===>>> Executing  /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/amnesia_multilingual/alembic/sql/upgrade/20200827_d9af39cf38ae_create_multilingual_branch.sql

(...)

2021-05-17 13:27:36,556 INFO  [sqlalchemy.engine.base.Engine][MainThread] UPDATE alembic_version SET version_num='d9af39cf38ae' WHERE alembic_version.version_num = 'e025de45166e'
2021-05-17 13:27:36,557 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
===>>> Executing  /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/amnesia/alembic/sql/upgrade/20210503_32b12866f6a2_permissions.sql
2021-05-17 13:27:36,562 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:36,569 INFO  [sqlalchemy.engine.base.Engine][MainThread] INSERT INTO alembic_version (version_num) VALUES ('32b12866f6a2') RETURNING alembic_version.version_num
2021-05-17 13:27:36,570 INFO  [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:36,571 INFO  [sqlalchemy.engine.base.Engine][MainThread] COMMIT

To Reproduce

Not sure.. but I'm using the following pattern in my versions/ path:

from pathlib import Path
from alembic import op
import sqlalchemy as sa


# revision identifiers, used by Alembic.
revision = 'e025de45166e'
down_revision = None
branch_labels = ('amnesiacms', )
depends_on = None

migration_path = Path(__file__)
migration_sql_path = migration_path.parent.parent / 'sql'
migration_sql_file = migration_path.with_suffix('.sql').name

upgrade_sql = migration_sql_path / 'upgrade' / migration_sql_file
downgrade_sql = migration_sql_path / 'downgrade' / migration_sql_file

def upgrade():
    print('===>>> Executing ', upgrade_sql)
    with open(upgrade_sql, 'r') as fp:
        op.execute(fp.read())

def downgrade():
    print('===>>> Executing ', downgrade_sql)
    with open(downgrade_sql, 'r') as fp:
        op.execute(fp.read())

Error

No errors, the process hangs at 100% CPU and the query stays in idle in transaction on the PostgreSQL side.

Versions.

• OS: FreeBSD 12.2-RELEASE
• Python: 3.7.9
• Alembic: 1.6.2
• SQLAlchemy: 1.3.24
• Database: PostgreSQL 13
• DBAPI: psycopg2 2.8.5

Additional context

Have a nice day!

[simonbowly]

Thanks for reporting - are you able to share the revision tree somehow?

Also, does

alembic upgrade --sql base:heads

hang in 1.6.x or produce valid SQL output?

[silenius]

alembic upgrade --sql base:heads hangs too:

~/code/projects/riparias/ alembic -c dev.ini upgrade --sql base:heads
BEGIN;

^CTraceback (most recent call last):
  File "/usr/home/julien/code/venvs/riparias/bin/alembic", line 8, in <module>
    sys.exit(main())
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/config.py", line 559, in main
    CommandLine(prog=prog).main(argv=argv)
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/config.py", line 553, in main
    self.run_cmd(cfg, options)
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/config.py", line 533, in run_cmd
    **dict((k, getattr(options, k, None)) for k in kwarg)
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/command.py", line 294, in upgrade
    script.run_env()
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/script/base.py", line 490, in run_env
    util.load_python_file(self.dir, "env.py")
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/util/pyfiles.py", line 97, in load_python_file
    module = load_module_py(module_id, path)
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/util/compat.py", line 182, in load_module_py
    spec.loader.exec_module(module)
  File "<frozen importlib._bootstrap_external>", line 728, in exec_module
  File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
  File "riparias/alembic/env.py", line 56, in <module>
    run_migrations_offline()
  File "riparias/alembic/env.py", line 30, in run_migrations_offline
    context.run_migrations()
  File "<string>", line 8, in run_migrations
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/runtime/environment.py", line 813, in run_migrations
    self.get_context().run_migrations(**kw)
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/runtime/migration.py", line 549, in run_migrations
    for step in self._migrations_fn(heads, self):
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/command.py", line 283, in upgrade
    return script._upgrade_revs(revision, rev)
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/script/base.py", line 365, in _upgrade_revs
    revs = list(revs)
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/script/revision.py", line 714, in iterate_revisions
    for node in self._topological_sort(revisions, heads):
  File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/script/revision.py", line 846, in _topological_sort
    for check_head_index, ancestors in enumerate(ancestors_by_idx):
KeyboardInterrupt

This is the history on 1.5.8 (the command hangs on 1.6.2):

~/code/projects/riparias/ alembic -c dev.ini history
e025de45166e (e025de45166e) -> 32b12866f6a2 (amnesiacms) (head), permissions
<base> (e025de45166e) -> d9af39cf38ae (multilingual) (head), create multilingual branch
<base> -> e025de45166e (amnesiacms), init

[silenius]

I don't know if it can help, but the full alembic/ are available from https://github.com/silenius/amnesia/tree/dev/amnesia/alembic for the amnesiacms branch and from https://github.com/silenius/amnesia_multilingual/tree/dev/amnesia_multilingual/alembic for the multilingual branch

[simonbowly]

Awesome, thanks. Looks like it's somehow related to repeating an identifier in depends_on that's already the down_revision for that script (like below). I think it's not needed to repeat the dependency but alembic should handle it. Will look into it!

revision = '32b12866f6a2'
down_revision = 'e025de45166e'
branch_labels = None
depends_on = 'e025de45166e'

[silenius]

Ah, I see .. it's strange indeed to have the same identifier for a depends_on and a down_revision, it should be a mistake on my side I think..

Thank you for your quick reply and explanations

[silenius]

I can confirm that with:

diff --git a/amnesia/alembic/versions/20210503_32b12866f6a2_permissions.py b/amnesia/alembic/versions/20210503_32b12866f6a2_permissions.py
index 998cd5c..0560e3e 100644
--- a/amnesia/alembic/versions/20210503_32b12866f6a2_permissions.py
+++ b/amnesia/alembic/versions/20210503_32b12866f6a2_permissions.py
@@ -14,7 +14,7 @@ import sqlalchemy as sa
 revision = '32b12866f6a2'
 down_revision = 'e025de45166e'
 branch_labels = None
-depends_on = 'e025de45166e'
+depends_on = None
 
 migration_path = Path(__file__)
 migration_sql_path = migration_path.parent.parent / 'sql'

it works with 1.6.2

[simonbowly]

Great! Glad that worked, thanks for raising this.

@CaselIT I noticed the bug occurs only when depends_on = 'e025de45166e', and not when depends_on = ('e025de45166e',). Should this give a warning or error here or just handle it transparently (as previous versions evidently did)?

[CaselIT]

Thanks for looking into it @simonbowly

I'm not actually sure if both versions are allowed. cc @zzzeek

[zzzeek]

I would say let's warn, so that things dont break but people are encouraged to repair it. thanks for looking into it!

[zzzeek]

@simonbowly did you want me to look at this or do you have something you're planning?

[CaselIT]

I wanted to ask the same thing.

Also, I was thinking that I'm not sure we should warn for this if it's a string. I mean down_revision behalves the same, it can be None, a string or a tuple of strings