How to enable verbosity on “alembic upgrade head”?

[doi zece]

n one of the python projects I'm working on we are using alembic to handle the DB migration scripts. Lately he had an incident when container ,in which alembic upgrade head is running, got stucked ( by some locks on the DB set the the runtime app) and eventually timed out without giving any details of what was going on. Finally we managed to get access to prod DB (which under normal circumstances we are not allow to access. this is something imposed by our cloudops team, for security reasons). So in order to eas our debugging process, i would like to enable verbose mode when calling "alembic upgrade head", this without having to add a tone of logs on top of the migration scripts.

I found that --verbose flag is accepted for some alembic operations, but for some reasons "alembic upgrade head" doesn't allow it.

usage: alembic [-h] [-c CONFIG] [-n NAME] [-x X] [--raiseerr] {branches,current,downgrade,edit,heads,history,init,list_templates,merge,revision,show,stamp,upgrade} ... alembic: error: unrecognized arguments: --verbose

This is the call generating the error above: alembic upgrade head --verbose

Any idea on how I can enable verbosity on upgrade?

Thanks

[Mike Bayer]

the --verbose flag is only used for a command like "alembic history" to provide more detail.    to see Alembic doing its work you want to enable logging.  in the ini file (see https://alembic.sqlalchemy.org/en/latest/tutorial.html#editing-the-ini-file) you want to set [logger_sqlalchemy] level to INFO or DEBUG.  this will show you every SQL statement emitted which should give you an idea of the one that is hanging.   DROP TABLE is a likely culprit as many databases won't allow this if there are open transactions accessing that table.

--

You received this message because you are subscribed to the Google Groups "sqlalchemy-alembic" group.

To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy-alem...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/sqlalchemy-alembic/64462a6a-2d12-491d-b613-e9b4ba9b7ffb%40googlegroups.com.

[doi zece]

I've tried that already but with no success.  I also tried to change the alembic version (move to the latest one) as initially i was on a 0.8.x . Still no luck.

The only way that i manage to make it print someting in the console was to add print statement in the script.   

This is the current state of my alembic.ini file relevant to alembic  configuration:

[alembic]

script_location = bolt/core/db/migrations

[loggers]

keys = root,tornado,server,sqlalchemy,alembic,httpclient,cookies

[handlers]

keys = file,http,console

[formatters]

keys = detailed

[handler_console]

class = StreamHandler

args = (sys.stdout,)

formatter = detailed

level = NOTSET

[handler_file]

class = FileHandler

args = ('server.log',)

formatter = detailed

level = NOTSET

[handler_http]

class = FileHandler

args = ('http.log',)

formatter = detailed

level = NOTSET

[logger_root]

level = DEBUG

propagate = 0

handlers = file, console

[logger_tornado]

level = DEBUG

qualname = tornado

propagate = 0

handlers = file, console

[logger_sqlalchemy]

level = WARN

handlers = file, console

qualname = sqlalchemy.engine

[logger_alembic]

level = INFO

handlers = file, console

qualname = alembic

[logger_httpclient]

level = INFO

qualname = tornado.curl_httpclient

handlers = http, console

[logger_server]

level = DEBUG

qualname = webserver

propagate = 0

handlers = file, console

[logger_cookies]

level = CRITICAL

qualname = cookies

propagate = 0

handlers = file, console

[formatter_detailed]

format = [%(name)s] %(asctime)-15s %(levelname)s %(module)s:%(lineno)d: %(message)s

To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy-alembic+unsub...@googlegroups.com.

[doi zece]

OK I managed to get some logging (it seems my alembic env.py was missing the fileConfig(config.config_file_name)). But still I'm not getting what i want.

Basically i want a long entry for every single operation in the migration script. And this, if possible, without having to add log statements all over the place. Is that possible ? 

[Mike Bayer]

SQL logging will render all the SQL being emitted which should be enough to see everything the script is doing against the database.  that is, if you ran op.alter_column(), you'd see "ALTER COLUMN..." in the log.  not sure what else you are looking to see.

do you think you're having a deadlock in Python and not against the database?   there's no good way to debug that without using something like pdb or embedding print statements.  that's a very unusual kind of issue in a tool like alembic and there are no known issues which could cause this. 

On Thu, Feb 27, 2020, at 1:12 PM, doi zece wrote:

OK I managed to get some logging (it seems my alembic env.py was missing the fileConfig(config.config_file_name)). But still I'm not getting what i want.

Basically i want a long entry for every single operation in the migration script. And this, if possible, without having to add log statements all over the place. Is that possible ? 

--

You received this message because you are subscribed to the Google Groups "sqlalchemy-alembic" group.

To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy-alem...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/sqlalchemy-alembic/b0dc3a7e-cb00-456c-9e51-51dc56294380%40googlegroups.com.

[doi zece]

Yes I want to see the SQLs hitting the DB. The initial issue I've mentioned got resolved. What I'm trying now is to generate more logs, so that it will be easier for me to investigate future similar issues.

 

When you say "SQL logging will render all the SQL"  you mean i have to configure a new logger for this ?  like [logger_sql]  ?

With the configuration I've posted i only get this:

[alembic.runtime.migration] 2020-02-27 18:32:26,177 INFO migration:154: Context impl PostgresqlImpl.

[alembic.runtime.migration] 2020-02-27 18:32:26,177 INFO migration:154: Context impl PostgresqlImpl.

[alembic.runtime.migration] 2020-02-27 18:32:26,179 INFO migration:161: Will assume transactional DDL.

[alembic.runtime.migration] 2020-02-27 18:32:26,179 INFO migration:161: Will assume transactional DDL.

[ldap3] 2020-02-27 18:32:26,315 INFO log:205: ldap3 library initialized - logging emitted with loglevel set to DEBUG - available detail levels are: OFF, ERROR, BASIC, PROTOCOL, NETWORK, EXTENDED - sensitive data will be hidden

[alembic.runtime.migration] 2020-02-27 18:32:26,493 INFO migration:513: Running upgrade 37e3e5e7e950 -> 23397de1f39e, test

[alembic.runtime.migration] 2020-02-27 18:32:26,493 INFO migration:513: Running upgrade 37e3e5e7e950 -> 23397de1f39e, test

[alembic.runtime.migration] 2020-02-27 18:32:26,516 DEBUG migration:750: update 37e3e5e7e950 to 23397de1f39e

[alembic.runtime.migration] 2020-02-27 18:32:26,516 DEBUG migration:750: update 37e3e5e7e950 to 23397de1f39e

[root@mixvm server]# 

for this upgrade script:

def upgrade():

    # ### commands auto generated by Alembic - please adjust! ###

    op.create_table('test',

                    sa.Column('id', sa.Integer(), nullable=False),

                    sa.Column('language', sa.String(length=7), nullable=False),

                    sa.Column('created_at', postgresql.TIMESTAMP(), autoincrement=False, nullable=True),

                    sa.PrimaryKeyConstraint('id')

                    )

    op.execute("""

        INSERT INTO test (language) VALUES ('en_us');

    """)

    # ### end Alembic commands ###

I would like to see a log entry for the create table and one for the insert.

On Thursday, February 27, 2020 at 1:20:27 PM UTC-5, Mike Bayer wrote:

SQL logging will render all the SQL being emitted which should be enough to see everything the script is doing against the database.  that is, if you ran op.alter_column(), you'd see "ALTER COLUMN..." in the log.  not sure what else you are looking to see.

do you think you're having a deadlock in Python and not against the database?   there's no good way to debug that without using something like pdb or embedding print statements.  that's a very unusual kind of issue in a tool like alembic and there are no known issues which could cause this. 

On Thu, Feb 27, 2020, at 1:12 PM, doi zece wrote:

OK I managed to get some logging (it seems my alembic env.py was missing the fileConfig(config.config_file_name)). But still I'm not getting what i want.

Basically i want a long entry for every single operation in the migration script. And this, if possible, without having to add log statements all over the place. Is that possible ? 

--

You received this message because you are subscribed to the Google Groups "sqlalchemy-alembic" group.

To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy-alembic+unsub...@googlegroups.com.

[doi zece]

Oh, found my problem. The sqlalchemy log level was not set properly for me to get the SQLs.

Thanks for your support.

[Mike Bayer]

On Thu, Feb 27, 2020, at 1:39 PM, doi zece wrote:

Yes I want to see the SQLs hitting the DB. The initial issue I've mentioned got resolved. What I'm trying now is to generate more logs, so that it will be easier for me to investigate future similar issues.

 

When you say "SQL logging will render all the SQL"  you mean i have to configure a new logger for this ?  like [logger_sql]  ?

With the configuration I've posted i only get this:

Logging is working however you don't appear to have enabled SQLAlchemy logging, as mentioned previously use INFO in logger_sqlalchemy:

[logger_sqlalchemy]
level = INFO
handlers =
qualname = sqlalchemy.engine

To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy-alem...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/sqlalchemy-alembic/2a0c7215-c551-472b-be83-cf15f34bb118%40googlegroups.com.