Flask-migrate: flask_migrate.upgrade(directory=..) breaks logging

[roman-telepathy-ai]

On app start, we do migrations before the actual app gets running.
Procedure:

* create_app
* register extensions (DB, migrate, cache, ...)
* ping dependencies
* migrate
<<< HERE IS THE PROBLEM >>>
* start app

Note: do not worry why migration is done on every app start or about the concurrency during migration.

Problem:
before flask_migrate.upgrade(directory=..) call all loggers of the app are working well, after the call, none of logger can log anything. I check already all attributes of logger and its handler and they are unchanged.

When disabling the migration call, then logs works; with migration - after the call no logging at all.

E.g. _logger.info('released DB lock') at the bottom in the snippet is not logging anymore.

Snippet

            _logger.info('DB lock acquired')
            try:
                with _app.app_context():
                    flask_migrate.upgrade(directory=_migrate.directory)
            except Exception as e:
                _logger.error('DB upgrade failed %s :: %s' % (type(e), e))
                raise e
            finally:
                print('-release...')
                _lock.release()
                print('-releaseD!!!...')
                _logger.info('released DB lock')

Console

[2018-09-13 12:49:38,121] INFO: === perform DB upgrade
[2018-09-13 12:49:38,121] INFO: > migrations: /home/roman/repos/myrepo/server/pyserver/migrations
<logging.Logger object at 0x7f95bb734f98>
10
[<logging.StreamHandler object at 0x7f95bb748c88>, <logstash.handler_tcp.TCPLogstashHandler object at 0x7f95bb748320>]
[2018-09-13 12:49:38,121] INFO: DB lock acquired
INFO  [alembic.runtime.migration] Context impl SQLiteImpl.
INFO  [alembic.runtime.migration] Will assume non-transactional DDL.
-release...
-releaseD!!!...
<logging.Logger object at 0x7f95bb734f98>
10
[<logging.StreamHandler object at 0x7f95bb748c88>, <logstash.handler_tcp.TCPLogstashHandler object at 0x7f95bb748320>]
 * Tip: There are .env files present. Do "pip install python-dotenv" to use them.
 * Serving Flask app "microservice_datacollection" (lazy loading)
 * Environment: production
   WARNING: Do not use the development server in a production environment.
   Use a production WSGI server instead.
 * Debug mode: off

Any help is welcome!

thx, r

[roman-telepathy-ai]

the only solution to fix that was to assign a new logger with new handlers after migration call

[miguelgrinberg]

This extension does not alter the logging configuration in any way, but I suspect alembic might. You may be able to workaround it if you invoke the migrate command as an external sub-process.

[roman-telepathy-ai]

thx for reply.
as I said I have a workaround, not nice but works.

I will check alembic.

thx!

[jslay88]

It is alembic, but a fix can also be provided here as well.

Here are 4 options I would like to propose. Hopefully I can redeem myself from our previous logging interactions with socket.io :)

Option 1 (Probably the worst, but also flexible)

I have successfully added my own implementation to flask_migrate that seems to work as expected. It all stems from the init, the generated env.py, and how the configuration is passed to env.py. One big advantage here, is this provides the developer full control over the loggers they originally had, without them having to worry about modify/rebuilding alembic.ini. The only other caveat here, would be that they would then have to configure the logger for alembic explicitly. This actually may be the best solution because of this, as it gives full control back to the developer as they expect, but also may be confusing, because by default, you would lose the alembic output. This also would allow you to have alembic optionally configure the loggers, so that when it is being used by CLI, it could allow alembic to take over, vs being used within the app, the developer maintains control over the loggers.

Ref https://stackoverflow.com/questions/42427487/using-alembic-config-main-redirects-log-output

In the env.py files, I have added this @ ln # 17

if config.attributes.get('configure_logger', True):
    fileConfig(config.config_file_name)

And then to the init command and Migrate.get_config method

def init(directory=None, multidb=False, attributes=None):
...
    if attributes is not None:
        for k, v in attributes.items():
            config.attributes[k] = v

And the migrate, upgrade, etc commands

def upgrade(... attributes=None):
    config = current_app.extensions['migrate'].migrate.get_config(directory,
                                                                  x_arg=x_arg,
                                                                  attributes=attributes)

Then when calling the methods from your app, you provide a dict setting the option/attrib

init(directory=current_app.config['DB_MIGRATIONS'], attributes={
            'configure_logger': False
        })

Obviously this is not built up for dist or anything but Python3, but this is something that could be done to help provide the option for those that are using the methods directly within the app (such as apps that help provision the DB configuration and management from within the app). I just don't have time to fully flesh it out for a PR at the moment.

Option 2 (Better, but not best for all cases)

Alternatively, you could also modify alembic.ini for your install (or the templates for the module), and this would clear up the problem initially. Should also probably be mentioned in the documents and referenced to Alembic how to configure this ini. I know its not directly part of the project, but a mention and link would be useful here I think. As well as mentioning the fact that when you do use these methods in your application, that alembic will hijack your logging configuration.

[loggers]
keys = root,sqlalchemy,alembic,werkzeug

[logger_werkzeug]
level = INFO
handlers = console
qualname = werkzeug

This produces logs such as this

 * Serving Flask app "flask_project.app" (lazy loading)
 * Environment: production
   WARNING: This is a development server. Do not use it in a production deployment.
   Use a production WSGI server instead.
 * Debug mode: off
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
INFO  [alembic.runtime.migration] Context impl SQLiteImpl.
INFO  [alembic.runtime.migration] Will assume non-transactional DDL.
INFO  [alembic.env] No changes in schema detected.
INFO  [alembic.runtime.migration] Context impl SQLiteImpl.
INFO  [alembic.runtime.migration] Will assume non-transactional DDL.
INFO  [werkzeug] 127.0.0.1 - - [22/May/2019 22:16:12] "GET / HTTP/1.1" 200 -
INFO  [werkzeug] 127.0.0.1 - - [22/May/2019 22:16:12] "GET / HTTP/1.1" 200 -

Option 3 (Best for scalability, universal use, but prone to problems)

Maybe another option is adding a template_directory argument to the init command, so that we can specify our own template folder, and subsequently our own alembic.ini template, for alembic,?

def init(directory=None, multidb=False, template_directory=None):
    """Creates a new migration repository"""
    if directory is None:
        directory = current_app.extensions['migrate'].directory
    config = Config()
    config.set_main_option('script_location', directory)
    config.config_file_name = os.path.join(directory, 'alembic.ini')
    config = current_app.extensions['migrate'].\
        migrate.call_configure_callbacks(config)
    if template_directory is not None:
        command.init(config, directory, template_directory)
    elif multidb:
        command.init(config, directory, 'flask-multidb')
    else:
        command.init(config, directory, 'flask')

Option 4 (Non-standard for alembic)

Another option could be to remove the use of fileConfig all together, and within your env.py templates, you setup the alembic logger like a normal person :) (cause who knows what alembic was thinking with this approach).

Replace Line 17 and 18 in env.py templates with this and import sys

logger = logging.getLogger('alembic')
handler = logging.StreamHandler(stream=sys.stdout)
formatter = logging.Formatter('%(levelname)-5.5s [%(name)s] %(message)s')
handler.setFormatter(formatter)
logger.handlers = [handler]
logger.setLevel('INFO')

Conclusion

Maybe a combination of these solutions would be the best use case? Can have the option to keep alembic from trashing your logging configuration with the attributes, or can handle werkzeug by default here, and maybe even a few others? Such as uwsgi, guincorn, etc? There is no harm configuring a logger in alembic.ini if it doesn't exist. Also provides the developers using Flask-Migrate the option to handle their own templates for a full-scale application/deployment. I don't know. Just some ideas.

Additional Notes

Also, would be nice to get some sort of status from these commands, so that when we do use these methods internally with the app itself, we have a way to know what happened without parsing/intercepting logs from alembic. Not sure if this is even possible, as I don't know what alembic itself returns for you to return to us, the developers. I have dug into alembic enough for tonight. :)

It may even be advantageous to build a set of methods purpose built for being used as imported methods or potentially a purpose built class for handling flask_migrate in this manner.

[jslay88]

Another issue I am running into, is that if there are any errors, the @catch_errors calls sys.exit(1) and prevents us from being able to do anything of handling of our own sorts. If anything, (even in CLI), this should not happen when you may expect the function to be imported as a module (such as documentation says we can). You should just call raise and let python re-raise the exception. If it is CLI, you make a CLI function, or make an arg that we can handle errors on our own.

This is very close to where developers can properly do things entirely through flask_migrate and their flask application, and leave CLI there for when things hit the fan. Effectively, I am trying to have to app manage the upgrades and provide a front end for doing so to make managing the application in the wild much easier. To do this, I will obviously need to be able to detect when there are issues on my own, and handle accordingly. And currently, I would have to build the config object for alembic (which flask_migrate does a great job of abstracting), and handle alembic directly. But it would be beneficial (I think), for flask_migrate to be able to be more flexible in these instances for a full-scale application solution. Like I said, very close already.

[miguelgrinberg]

@jslay88 why is it a problem to create your migration repository using one of the two provided templates and then make the modifications to alembic.ini and/or env.py that suit your needs? This is an infrequent operation that is done at the start of a project, these templated files are supposed to be a starting point, it is okay to make changes to them.

I would be okay with a new option to specify a custom template directory, I guess. It seems overkill to me, but I would accept such a feature, specially if there is also a way to copy one of the stock templates. Maybe something like:

$ flask db template /path/to/templates/my-flask-template
$ flask db template --multidb /path/to/templates/my-flask-multidb-template
$ flask db init --template /path/to/templates/my-flask-template

But once again, it seems overkill. Much easier to create the repository then make the changes to your files manually!

[jslay88]

As I've stated before, it gives the developer control.

I don't want to distribute an application, and then have to have them go and manually build out a config, and subsequently run a bunch of additional CLI commands that I can programmatically handle. This isn't just a case of running init command. This is about being able to programmatically control flask_migrate from within the application, and be able to return useful/actionable information. Right now, it doesn't do any of that at the programattic level for developers. I have no capability of knowing the state or lifecycle of my DB and migrations from within my app, and that alone seems like it should be improved.

There are tons of applications that have a "first run" interface. Asking 10,000+ people to manually do something when you can simplify and increase the consistency and reliability of a shipped product. This is just engineering 101.

The current condition flask_migrate sits in, poses a lot of limitations and barriers to the developer, which can be solved with a few code changes, and even potentially help them make things a bit easier. The reason it seems like such a small use case, is because most developers that end up doing something like this, they likely would abandon trying to use flask_migrate due to the barriers previously mentioned.

This is all about giving the developer more options, with little to no impact on this project as a whole. All 4 options I suggest would have little/no impact on existing users, but can increase the flexibility of the porject as a whole b

The fact that alembic hi-jacks your loggers, and you can make a slight code change to help in this situation, makes sense to me. Because now to get around that, I have to go through a whole series of not great solutions to eliminate those barriers.

[miguelgrinberg]

I don't want to distribute an application, and then have to have them go and manually build out a config, and subsequently run a bunch of additional CLI commands that I can programmatically handle.

If you distribute an application you will ship a migration repository with it, you will not ask your users to build one. What am I missing here?

[jslay88]

Nevermind. I give up. Already said this is more than just about init. Apparently everything I have already said has no weight. Let's just keep things difficult and impossible to manage a life cycle from within the application. Makes more sense. Not like any other application does this or is common practice.

Didn't expect this much resistance to simple changes that could improve flexibility for developers and increase the capabilities of the module. Guess that is not important. I can just fork it and make the changes for myself and move on. But I figured I would post what I have discovered and a selection of simple changes to work around these issues.

But let's just keep calling sys.exit(1) in the middle of other developers applications instead of allowing the developer to actually handle things. We don't need to worry about how developers may actually use this module. Only your use case matters, right?

[aabounegm]

I was just facing this issue and spent more than 3 hours straight trying to fix it. At the end, I found that the root cause is the fileConfig line in env.py mentioned by @jslay88 in Option 1. However, the very simple solution that I finally reached is to change this line to fileConfig(config.config_file_name, disable_existing_loggers=False). The last argument is True by default for historical reasons, and now my loggers remain. Also, I moved my logging.config.dictConfig call below the upgrade call to override with my own config.