how alembic reports errors (stack trace, or clean output with a "failed" message, etc)

[sqlalchemy-bot]

Migrated issue, originally created by Jonathan Herriott (@herriojr)

Edit: See comments for why this was moved to proposal as both cases actually failed.

There are two ways I run alembic, one is where I create a separate test database for my test cases and do the migrations for a set of test cases and then tear them down afterwards. I've run into an issue when doing an alter_column to rename some foreign keys, which work when I run it via command line, but in my tests it fails. Any attempt at fixing this seems to cause the command line to fail. This is all being done with MySQL.

op.alter_column('my_table', 'my_other_table_id', new_column_name='other_table_id')
# This fails when run with alembic.command.upgrade with
#  File "<string>", line 7, in alter_column
#  File "<string>", line 1, in <lambda>
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/alembic/util.py", line 322, in go
#    return fn(*arg, **kw)
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/alembic/operations.py", line #300, in alter_column
#    existing_autoincrement=existing_autoincrement
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/alembic/ddl/mysql.py", line 42, #in alter_column
#    else existing_autoincrement
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/alembic/ddl/mysql.py", line 71, #in __init__
#    "All MySQL ALTER COLUMN operations "
#CommandError: All MySQL ALTER COLUMN operations require the existing type.

So, then I try and follow the suggestions, and do the following:

op.alter_column('my_table', 'my_other_table_id', new_column_name='other_table_id', existing_type=sa.BigInteger, existing_nullable=False)
# This now fails for both my tests and for my command line upgrade
#  File "<string>", line 7, in alter_column
#  File "<string>", line 1, in <lambda>
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/alembic/util.py", line 322, in go
#    return fn(*arg, **kw)
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/alembic/operations.py", line #300, in alter_column
#    existing_autoincrement=existing_autoincrement
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/alembic/ddl/mysql.py", line 42, #in alter_column
#    else existing_autoincrement
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/alembic/ddl/impl.py", line 76, in _exec
#    conn.execute(construct, *multiparams, **params)
#  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 717, in execute
#    return meth(self, multiparams, params)
#  File "build/bdist.linux-x86_64/egg/sqlalchemy/sql/ddl.py", line 67, in #_execute_on_connection
#    return connection._execute_ddl(self, multiparams, params)
#  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 771, in _execute_ddl
#    compiled
#  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 927, in #_execute_context
#    context)
#  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 1076, in #_handle_dbapi_exception
#    exc_info
#  File "build/bdist.linux-x86_64/egg/sqlalchemy/util/compat.py", line 185, in #raise_from_cause
#    reraise(type(exception), exception, tb=exc_tb)
#  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 920, in #_execute_context
#    context)
#  File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/default.py", line 425, in do_execute
#    cursor.execute(statement, parameters)
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
#    self.errorhandler(self, exc, value)
#  File "/opt/virtualenv/tkey/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
#    raise errorclass, errorvalue
#OperationalError: (OperationalError) (1025, "Error on rename of './bc_paas_test/#sql-#377_42' to './bc_paas_test/account_charge' (errno: 150)") 'ALTER TABLE account_charge CHANGE sub_account_plan_id account_plan_id BIGINT NOT NULL' ()

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

per http://stackoverflow.com/questions/19668682/1025-error-on-rename-errno-150-in-mysql this rather poorly formed error seems to mean that your migration is referring to the wrong name, of the column or something. maybe the old column name. I don't see here where anything specific to Alembic is happening, if your migration script refers to a column that doesn't exist then it's going to fail.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

to debug this, I suggest you use pdb. if you do "import pdb; pdb.set_trace()" in your migration script, as this error happens it will drop you into a python console. then use op.get_bind() right there to run some test queries against the MySQL database to see what's there and what isn't.

[sqlalchemy-bot]

Jonathan Herriott (@herriojr) wrote:

Actually, with messing with it more, it appears that when I thought it was succeeding, it was failing. Since it was a single line failure, I guess I missed it. All I got was this:

All MySQL ALTER COLUMN operations require the existing type.

I think this is more of a usability issue due to my misunderstanding as previous issues I've had would actually throw some kind of stack trace -> it would be nice if there was an explicit "Migration Failed".

[sqlalchemy-bot]

Changes by Jonathan Herriott (@herriojr):

• added labels: low priority

[sqlalchemy-bot]

Changes by Jonathan Herriott (@herriojr):

• edited description

[sqlalchemy-bot]

Changes by Jonathan Herriott (@herriojr):

• removed labels: bug
• added labels: feature

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

im confused. you ran migrations, and the whole thing threw a stack trace, right? how exactly is that confused with a success? alembic, when confronted with an error like that, gives up, throws a trace, ends what it's doing, complains loudly. It's not easy to miss. unless you're squashing the exception, in which case, I'd recommend not to do that :).

[sqlalchemy-bot]

Jonathan Herriott (@herriojr) wrote:

In the case of running it via command line, it did not throw a stack trace, it just gave that one line message. In the case of alembic.command.upgrade, it is fine in terms of error response -> I got a big old stack trace, however, in the case of command line, I did not. I have an unmodified (beyond pointing to my models) env.py with the following mako

"""${message}

Revision ID: ${up_revision}
Revises: ${down_revision}
Create Date: ${create_date}

"""

# revision identifiers, used by Alembic.
revision = ${repr(up_revision)}
down_revision = ${repr(down_revision)}

from alembic import op

import sqlalchemy as sa
import sqlalchemy.sql.expression as sa_expr
${imports if imports else ""}


def upgrade():
    schema_upgrades()
    fixture_upgrades()


def schema_upgrades():
    ${upgrades if upgrades else "pass"}


def fixture_upgrades():
    """Add any optional fixture upgrade migrations here!"""
    pass


def downgrade():
    fixture_downgrades()
    schema_downgrades()


def schema_downgrades():
    ${downgrades if downgrades else "pass"}


def fixture_downgrades():
    """Add any optional fixture downgrade migrations here!"""
    pass

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

can you paste exactly what it looks like when you run the command in your terminal and the output? at the top of this issue I see a whole stack trace with python comment markers.

[sqlalchemy-bot]

Jonathan Herriott (@herriojr) wrote:

Sorry for all the confusion. It shows:

INFO  [alembic.migration] Running upgrade ...
...
INFO  [alembic.migration] Running upgrade 43089f2231f0 -> 313c76ff2889, empty message
All MySQL ALTER COLUMN operations require the existing type.

Ellipses were added for brevity.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

OK that is not what I'm reproducing here. There's nothing that catches exceptions and turns it into just a single message. I just added a bogus migration command to a test env here. This is the full output (with ellipses again):

#!

$ python -m alembic.config upgrade head
INFO  [alembic.migration] Context impl PostgresqlImpl.
INFO  [alembic.migration] Will assume transactional DDL.
INFO  [alembic.migration] Running upgrade 47bed260c052 -> 59c1afc792c1, rev two
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/runpy.py", line 162, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/runpy.py", line 72, in _run_code
    exec code in run_globals
  File "/Users/classic/dev/alembic/alembic/config.py", line 301, in <module>
    main()

   [ ... about 30 more lines]

  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 947, in _execute_context
    context)
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/engine/default.py", line 435, in do_execute
    cursor.execute(statement, parameters)
sqlalchemy.exc.ProgrammingError: (ProgrammingError) relation "my_tablee" does not exist
 'ALTER TABLE my_tablee ADD COLUMN col3 BOOLEAN' {}

so, it seems perhaps your environment is squashing the stack trace here.

now it wouldn't be a terrible thing to have nicer output for failures and send this stack trace to a log file and all that but I don't know if I want to get into that right now, I always find it off-putting when a tool like Sphinx tells me to "see file /tmp/xyz.txt" for a stack trace. Alembic's normal behavior right now is to just barf it out like any other python script.

[sqlalchemy-bot]

Changes by Michael Bayer (@zzzeek):

• changed title from "Differences in alembic.command.upgrade(config "hea" to "how alembic reports errors (stack trace or clean o"

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

oh, I see, you're talking specifically about the CommandError, not the error you got from MySQL, right?

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

• When a run of Alembic command line fails due to CommandError,
  the output now prefixes the string with "FAILED:", and the error
  is also written to the log output using log.error().
  fixes how alembic reports errors (stack trace, or clean output with a "failed" message, etc) #209

→ 42b109c

[sqlalchemy-bot]

Changes by Michael Bayer (@zzzeek):

• changed status to closed