flask_migrate.upgrade() during pytest test breaks logging

[OliverEvans96]

Hi there,

I've been really enjoying flask-migrate, but I've spent the last few hours on a very obscure bug related to logging during testing with pytest.

EDIT: I think this is probably a duplicate of #227, but I'll post it anyways because a solution should at least appear in the documentation of this repo.

Apologies in advanced if this is just due to my ignorance of python's logging system.

Description

It seems that if I run flask_migrate.upgrade() during a test, caplog does not receive logs from logging.info for the rest of the test, and those logs are therefore not shown if the test fails. This issue does not occur if I run the same code outside of a test.

Package versions

I'm using a clean conda env, with Python 3.7.7 on Arch Linux, only adding the following packages:

flask
flask-migrate
flask-sqlalchemy
psycopg2
pytest

This produces the following pip list

Package            Version            
------------------ -------------------
alembic            1.4.2              
attrs              19.3.0             
certifi            2020.4.5.1         
click              7.1.1              
Flask              1.1.2              
Flask-Migrate      2.5.3              
Flask-SQLAlchemy   2.4.1              
importlib-metadata 1.6.0              
itsdangerous       1.1.0              
Jinja2             2.11.2             
Mako               1.1.2              
MarkupSafe         1.1.1              
more-itertools     8.2.0              
packaging          20.3               
pip                20.0.2             
pluggy             0.13.1             
psycopg2           2.8.5              
py                 1.8.1              
pyparsing          2.4.7              
pytest             5.4.1              
python-dateutil    2.8.1              
python-editor      1.0.4              
setuptools         46.1.3.post20200330
six                1.14.0             
SQLAlchemy         1.3.16             
wcwidth            0.1.9              
Werkzeug           1.0.1              
wheel              0.34.2             
zipp               3.1.0 

Minimal working example

Code available at https://github.com/OliverEvans96/pytest-logging-bug

app.py

from flask import Flask
from flask_migrate import Migrate

import db_schema

# App config
app = Flask(__name__)
app.config['SQLALCHEMY_DATABASE_URI'] = 'postgresql://localhost/test_db'
app.config['SQLALCHEMY_TRACK_MODIFICATIONS'] = False

# Database
db_schema.db.init_app(app)
migrate = Migrate(app, db_schema.db)

db_schema.py

from flask_sqlalchemy import SQLAlchemy

db = SQLAlchemy()


class Task(db.Model):
    __tablename__ = 'tasks'

    # Columns
    id = db.Column(db.Integer, primary_key=True, unique=True, autoincrement=True)
    name = db.Column(db.String, nullable=False)
    description = db.Column(db.String, nullable=False)

app_test.py

import logging
import os

import flask_migrate
import pytest

from app import app

logging.basicConfig(level=logging.INFO)


@pytest.fixture()
def app_fixture():
    app.config['TESTING'] = True

    with app.app_context():
        yield


def test_logging(app_fixture, caplog):
    msg1 = "Before"
    logging.info(msg1)

    if os.getenv('DO_UPGRADE'):
        flask_migrate.upgrade()

    msg2 = "After"
    logging.info(msg2)
    assert [msg1, msg2] == [rec.message for rec in caplog.records]

Reproducing the issue:

psql postgres -c 'create database test_db;'

echo
echo "*** This will work ***"
pytest

echo
echo "*** This will not work ***"
flask db init
flask db migrate -m "Initial migration"
export DO_UPGRADE='true'
pytest

echo
echo "*** This won't work either ***"
pytest

echo
echo "*** This will work again ***"
export DO_UPGRADE=''
pytest

MWE Output

CREATE DATABASE

*** This will work ***
======================================= test session starts =======================================
platform linux -- Python 3.7.7, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /home/oliver/code/python/pytest-logging-bug
collected 1 item                                                                                  

app_test.py .                                                                               [100%]

======================================== 1 passed in 0.21s ========================================

*** This will not work ***
  Creating directory /home/oliver/code/python/pytest-logging-bug/migrations ...  done
  Creating directory /home/oliver/code/python/pytest-logging-bug/migrations/versions ...  done
  Generating /home/oliver/code/python/pytest-logging-bug/migrations/README ...  done
  Generating /home/oliver/code/python/pytest-logging-bug/migrations/alembic.ini ...  done
  Generating /home/oliver/code/python/pytest-logging-bug/migrations/env.py ...  done
  Generating /home/oliver/code/python/pytest-logging-bug/migrations/script.py.mako ...  done
  Please edit configuration/connection/logging settings in '/home/oliver/code/python/pytest-logging-
  bug/migrations/alembic.ini' before proceeding.
INFO  [alembic.runtime.migration] Context impl PostgresqlImpl.
INFO  [alembic.runtime.migration] Will assume transactional DDL.
INFO  [alembic.autogenerate.compare] Detected added table 'tasks'
  Generating /home/oliver/code/python/pytest-logging-
  bug/migrations/versions/20a337f6c148_initial_migration.py ...  done
======================================= test session starts =======================================
platform linux -- Python 3.7.7, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /home/oliver/code/python/pytest-logging-bug
collected 1 item                                                                                  

app_test.py F                                                                               [100%]

============================================ FAILURES =============================================
__________________________________________ test_logging ___________________________________________

app_fixture = None, caplog = <_pytest.logging.LogCaptureFixture object at 0x7f6eeaf74050>

    def test_logging(app_fixture, caplog):
        msg1 = "Before"
        logging.info(msg1)
    
        if os.getenv('DO_UPGRADE'):
            flask_migrate.upgrade()
    
        msg2 = "After"
        logging.info(msg2)
>       assert [msg1, msg2] == [rec.message for rec in caplog.records]
E       AssertionError: assert ['Before', 'After'] == ['Before']
E         Left contains one more item: 'After'
E         Use -v to get the full diff

app_test.py:32: AssertionError
-------------------------------------- Captured stderr call ---------------------------------------
INFO:root:Before
INFO  [alembic.runtime.migration] Context impl PostgresqlImpl.
INFO  [alembic.runtime.migration] Will assume transactional DDL.
INFO  [alembic.runtime.migration] Running upgrade  -> 20a337f6c148, Initial migration
---------------------------------------- Captured log call ----------------------------------------
INFO     root:app_test.py:25 Before
===================================== short test summary info =====================================
FAILED app_test.py::test_logging - AssertionError: assert ['Before', 'After'] == ['Before']
======================================== 1 failed in 0.28s ========================================

*** This won't work either ***
======================================= test session starts =======================================
platform linux -- Python 3.7.7, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /home/oliver/code/python/pytest-logging-bug
collected 1 item                                                                                  

app_test.py F                                                                               [100%]

============================================ FAILURES =============================================
__________________________________________ test_logging ___________________________________________

app_fixture = None, caplog = <_pytest.logging.LogCaptureFixture object at 0x7fb467acf090>

    def test_logging(app_fixture, caplog):
        msg1 = "Before"
        logging.info(msg1)
    
        if os.getenv('DO_UPGRADE'):
            flask_migrate.upgrade()
    
        msg2 = "After"
        logging.info(msg2)
>       assert [msg1, msg2] == [rec.message for rec in caplog.records]
E       AssertionError: assert ['Before', 'After'] == ['Before']
E         Left contains one more item: 'After'
E         Use -v to get the full diff

app_test.py:32: AssertionError
-------------------------------------- Captured stderr call ---------------------------------------
INFO:root:Before
INFO  [alembic.runtime.migration] Context impl PostgresqlImpl.
INFO  [alembic.runtime.migration] Will assume transactional DDL.
---------------------------------------- Captured log call ----------------------------------------
INFO     root:app_test.py:25 Before
===================================== short test summary info =====================================
FAILED app_test.py::test_logging - AssertionError: assert ['Before', 'After'] == ['Before']
======================================== 1 failed in 0.27s ========================================

*** This will work again ***
======================================= test session starts =======================================
platform linux -- Python 3.7.7, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /home/oliver/code/python/pytest-logging-bug
collected 1 item                                                                                  

app_test.py .                                                                               [100%]

======================================== 1 passed in 0.21s ========================================

Any help would be appreciated. I've opened the same issue on the pytest repo at pytest-dev/pytest#7103. I'll be very curious to know what's going on here.

Thanks,
Oliver

[miguelgrinberg]

Alembic was designed as a stand-alone tool. It reads all the logging options from the alembic.ini file. These options override whatever logging configuration your own application or test environment set.

There are several solutions

• run the migrate command as a subprocess
• modify env.py in your migrations directory to not call fileConfig, which does the logging configuration
• modify env.py or alembic.ini to match your logging configuration
• re-apply your preferred logging configuration after the call to migrate() returns.

[OliverEvans96]

@miguelgrinberg - I really appreciate the quick and thorough response. In my case, running migrate() as a subprocess is the easiest solution:

app_test.py

@@ -1,3 +1,4 @@
+import concurrent.futures as cf
 import logging
 import os
 
@@ -22,7 +23,8 @@ def test_logging(app_fixture, caplog):
     logging.info(msg1)
 
     if os.getenv('DO_UPGRADE'):
-        flask_migrate.upgrade()
+        with cf.ProcessPoolExecutor() as pool:
+            pool.submit(flask_migrate.upgrade)
 
     msg2 = "After"
     logging.info(msg2)

I've submitted a PR for your consideration that adds a note to the docs based on your response.

[andyDoucette]

For anyone who runs into this again. @OliverEvans96's fix didn't work for me, but this did:

1. Look for an env.py file in your migrations directory.
2. Comment out the line fileConfig(config.config_file_name)

Credit goes to this documentation.

Note The default env.py file included with Alembic’s environment templates will also read from the logging sections [logging], [handlers] etc. If the configuration file in use does not contain logging directives, please remove the fileConfig() directive within the generated env.py file to prevent it from attempting to configure logging.

[arthurvanduynhoven]

Another work around is to just re-enable the logger..

current_app.logger.disabled = False