5.3.3 fixture order wrong with 'trylast'

[lhupfeldt]

Test fails randomly during setup because of bad fixture order after upgrading to 5.3.3.
A fixture marked 'trylast' is being called too early.
It fails randomly only about 50% of the time.
Test run stable with 5.3.2 and 5.3.4.

Example attached (reduced from some complex database setup).
Note that the example also uses dynamically generated fixtures, I'm not sure if this is part of the issue.
fixture_order.zip

Output from a run failed because of fixture called too early:

-*- mode: compilation; default-directory: "~/src/fixture_order/" -*-
Compilation started at Wed Jan 22 23:46:53

nox
nox > Running session fixture_order-3.7
nox > Re-using existing virtual environment at .nox/fixture_order-3-7.
nox > pip install pytest==5.3.3
nox > pip freeze
attrs==19.3.0
importlib-metadata==1.4.0
more-itertools==8.1.0
packaging==20.0
pluggy==0.13.1
py==1.8.1
pyparsing==2.4.6
pytest==5.3.3
six==1.14.0
wcwidth==0.1.8
zipp==2.0.0
nox > pytest 
============================================================================== test session starts ==============================================================================
platform linux -- Python 3.7.6, pytest-5.3.3, py-1.8.1, pluggy-0.13.1
rootdir: /home/lhn/src/fixture_order, inifile: pytest.ini, testpaths: test
collected 1 item                                                                                                                                                                

test/order_test.py E                                                                                                                                                      [100%]

==================================================================================== ERRORS =====================================================================================
______________________________________________________________ ERROR at setup of test_using_try_last_local_fixture ______________________________________________________________

conn = <conftest.Connection object at 0x7f1af6443f10>, table = 'dummy_table'

    def copy_csv_file(conn, table):
        """Copy a csv file to a table."""
    
        print(f'DUMMY copy_csv_file(({conn}, {table})')
        if conn.get_dsn_parameters()['dbname'] in _TRIGGERS_CREATED:
>           raise Exception("Oops wrong fixture order, 'copy_csv_file' called after 'create_triggers'!")
E           Exception: Oops wrong fixture order, 'copy_csv_file' called after 'create_triggers'!

test/conftest.py:46: Exception
----------------------------------------------------------------------------- Captured stdout setup -----------------------------------------------------------------------------
DUMMY - session autouse2 - seems to increase likelyhood of wrong order?
fixture(session): test_db_server
DUMMY create schema and load functions, roles, types
DUMMY clean_db_cli_runner(<conftest.Connection object at 0x7f1af6443ad0>)
Create triggers because test 'test_using_try_last_local_fixture' uses database connection.
DUMMY create_triggers(<conftest.Connection object at 0x7f1af6443f10>)
Executing table load fixture: dbdata1
DUMMY copy_csv_file((<conftest.Connection object at 0x7f1af6443f10>, dummy_table)
=============================================================================== 1 error in 0.03s ================================================================================

Output from run using 5.3.4 with correct fixture invocation order (explicitly failed to show setup):

-*- mode: compilation; default-directory: "~/src/fixture_order/" -*-
Compilation started at Wed Jan 22 23:40:13

nox
nox > Running session fixture_order-3.7
nox > Re-using existing virtual environment at .nox/fixture_order-3-7.
nox > pip install pytest==5.3.4
nox > pip freeze
attrs==19.3.0
importlib-metadata==1.4.0
more-itertools==8.1.0
packaging==20.0
pluggy==0.13.1
py==1.8.1
pyparsing==2.4.6
pytest==5.3.4
six==1.14.0
wcwidth==0.1.8
zipp==2.0.0
nox > pytest 
============================================================================== test session starts ==============================================================================
platform linux -- Python 3.7.6, pytest-5.3.4, py-1.8.1, pluggy-0.13.1
rootdir: /home/lhn/src/fixture_order, inifile: pytest.ini, testpaths: test
collected 1 item                                                                                                                                                                

test/order_test.py F                                                                                                                                                      [100%]

=================================================================================== FAILURES ====================================================================================
_______________________________________________________________________ test_using_try_last_local_fixture _______________________________________________________________________

clean_db_cli_runner = None, _local_fixture_requiring_the_same_code_as_hook_called_now = None

    def test_using_try_last_local_fixture(
            clean_db_cli_runner, _local_fixture_requiring_the_same_code_as_hook_called_now):
>       assert False
E       assert False

test/order_test.py:12: AssertionError
----------------------------------------------------------------------------- Captured stdout setup -----------------------------------------------------------------------------
DUMMY - session autouse2 - seems to increase likelyhood of wrong order?
fixture(session): test_db_server
DUMMY create schema and load functions, roles, types
DUMMY clean_db_cli_runner(<conftest.Connection object at 0x7ff6bf295450>)
Executing table load fixture: dbdata1
DUMMY copy_csv_file((<conftest.Connection object at 0x7ff6bf2953d0>, dummy_table)
Executing table load fixture: dbdata2
DUMMY copy_csv_file((<conftest.Connection object at 0x7ff6bf2953d0>, dummy_table)
Executing table load fixture: dbdata3
DUMMY copy_csv_file((<conftest.Connection object at 0x7ff6bf2953d0>, dummy_table)
Create triggers because test 'test_using_try_last_local_fixture' uses database connection.
DUMMY create_triggers(<conftest.Connection object at 0x7ff6bf2953d0>)
DUMMY some setup code which requires the create_register_triggers fixture to have been called...
Running setup hook
Setup hook: 'create_triggers' because of fixture 'test_db_server'
Create triggers because test 'postgres' uses database connection.
DUMMY create_triggers(<conftest.Connection object at 0x7ff6bf295410>)
--------------------------------------------------------------------------- Captured stdout teardown ----------------------------------------------------------------------------
DUMMMY close <conftest.Connection object at 0x7ff6bf2953d0>
fixture(session): test_db_server - finalizer
=============================================================================== 1 failed in 0.02s ===============================================================================

[nicoddemus]

Thanks @lhupfeldt for taking the time to report and produce a MWE.

This is definitely related to #6492, although it might provide new clues if this is a problem in pytest or wrong assumptions.

cc @SalmonMode

[SalmonMode]

@lhupfeldt @nicoddemus As far as I can tell, this is the result of non-deterministic fixture order, which isn't a bug on pytest's end. In the example provided, the fixtures are defined in such a way that linearization isn't possible in a consistent way, so the order they occur in is up to the whims of python at that point. This is what's causing the intermittent errors vs failures.

I saw two variations when running pytest 5.3.3 with the --setup-plan flag. Here's the first:

order_test.py 
SETUP    S session_autouse2
SETUP    S test_db_server
      SETUP    C clean_schema_db (fixtures used: test_db_server)
        SETUP    F clean_db_cli_runner (fixtures used: clean_schema_db)
        SETUP    F create_register_triggers (fixtures used: clean_schema_db)
        SETUP    F dbdata1 (fixtures used: clean_schema_db)
        SETUP    F dbdata2 (fixtures used: dbdata1)
        SETUP    F dbdata3 (fixtures used: dbdata2)
        SETUP    F _local_fixture_requiring_the_same_code_as_hook_called_now (fixtures used: clean_db_cli_runner, create_register_triggers, dbdata3)
        order_test.py::test_using_try_last_local_fixture (fixtures used: _local_fixture_requiring_the_same_code_as_hook_called_now, clean_db_cli_runner, clean_schema_db, create_register_triggers, dbdata1, dbdata2, dbdata3, request, session_autouse2, test_db_server)
        TEARDOWN F _local_fixture_requiring_the_same_code_as_hook_called_now
        TEARDOWN F dbdata3
        TEARDOWN F dbdata2
        TEARDOWN F dbdata1
        TEARDOWN F create_register_triggers
        TEARDOWN F clean_db_cli_runner
      TEARDOWN C clean_schema_db
TEARDOWN S test_db_server
TEARDOWN S session_autouse2

And here's the other:

order_test.py 
SETUP    S session_autouse2
SETUP    S test_db_server
      SETUP    C clean_schema_db (fixtures used: test_db_server)
        SETUP    F clean_db_cli_runner (fixtures used: clean_schema_db)
        SETUP    F dbdata1 (fixtures used: clean_schema_db)
        SETUP    F dbdata2 (fixtures used: dbdata1)
        SETUP    F dbdata3 (fixtures used: dbdata2)
        SETUP    F create_register_triggers (fixtures used: clean_schema_db)
        SETUP    F _local_fixture_requiring_the_same_code_as_hook_called_now (fixtures used: clean_db_cli_runner, create_register_triggers, dbdata3)
        order_test.py::test_using_try_last_local_fixture (fixtures used: _local_fixture_requiring_the_same_code_as_hook_called_now, clean_db_cli_runner, clean_schema_db, create_register_triggers, dbdata1, dbdata2, dbdata3, request, session_autouse2, test_db_server)
        TEARDOWN F _local_fixture_requiring_the_same_code_as_hook_called_now
        TEARDOWN F create_register_triggers
        TEARDOWN F dbdata3
        TEARDOWN F dbdata2
        TEARDOWN F dbdata1
        TEARDOWN F clean_db_cli_runner
      TEARDOWN C clean_schema_db
TEARDOWN S test_db_server
TEARDOWN S session_autouse2

Notice how create_register_triggers shifts before and after the dbdata1, dbdata2, and dbdata3 fixtures between the two plans.

The only way you'll get the failure instead of the error is if create_register_triggers happens after the dbdataN fixtures. To ensure this, create_register_triggers should be sure to request dbdata3 in its arguments so that the order is deterministic.

[nicoddemus]

@SalmonMode thanks for digging in!

As far as I can tell, this is the result of non-deterministic fixture order, which isn't a bug on pytest's end.

But why this behavior only happens in 5.3.3 and not other versions? Is there anything that can be changed in the provided code to avoid this difference?

[blueyed]

Is this related to bab4dd0? (or just something similar)

[SalmonMode]

@blueyed and @MarcSchmitzer found an issue elsewhere that could have been exacerbating the non-determinism in that sets are not iterated over in the same order they are added to (#6512 (comment) and bab4dd0). In general though, changing the sets back to lists in the part of pytest that's relevant won't guarantee a fix for the issue presented in this example code.

To fix it for sure, any fixture that depends on another fixture being completed before it runs should request the fixture it depends on. So if fixture A needs fixture B to be done before fixture A starts, then fixture A should request fixture B.

[nicoddemus]

Is this related to bab4dd0? (or just something similar)

Applying that change over 5.3.3 then I always get the same --setup-plan, so this explains why 5.3.3 was producing non-deterministic results.

To fix it for sure, any fixture that depends on another fixture being completed before it runs should request the fixture it depends on.

I agree, but in any case bab4dd0 turned that process at least deterministic. 👍

[lhupfeldt]

Maybe I misunderstood the meaning of 'trylast' but I thought that should ensure the order I has before 5.3.3. If that is not the case then another feature is really needed for this. I will be mostly offline for some days so replys will be slow.

…

On Fri, 24 Jan 2020, 00:29 Bruno Oliveira, ***@***.***> wrote: Is this related to bab4dd0 <bab4dd0>? (or just something similar) Applying that change over 5.3.3 then I always get the same --setup-plan, so this might explain why 5.3.3 was producing non-deterministic results. To fix it for sure, any fixture that depends on another fixture being completed before it runs should request the fixture it depends on. I agree, but in any case bab4dd0 <bab4dd0> turned that process at least deterministic. 👍 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6540?email_source=notifications&email_token=AAMCZSOJ4CAGXFHHRQ5OG3DQ7IR4DA5CNFSM4KKN2Y62YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJZHEQA#issuecomment-577925696>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAMCZSINQMPNUSBZY6GRFUTQ7IR4DANCNFSM4KKN2Y6Q> .

[SalmonMode]

@lhupfeldt trylast means you want pytest to use that instance of that hook last out of all the other instances of that hook, but it will still happen when that hook is supposed to happen, which is predetermined. It doesn't mean it will act as the last fixture to run before the test (which sounds like it may be what you're trying to do?).

If that's what you want, then you just need to make sure you define a fixture which requests the last of your generated fixtures (since they seem to happen in sequence), and have the first of your generated fixtures request the other, normal fixtures in the scope that's relevant.

Or you could rely on scope itself, e.g. make a single test file for a single test case, then have all fixtures be for the module scope level, and then, make the fixture you want to happen last have a class scope level. This approach would work at different scopes too.

[nicoddemus]

@SalmonMode is correct, if there's an implicit ordering required, it is best to make that order explicit.

Either way, it seems bab4dd0 at least makes this deterministic and we should produce a test with implicit dependencies which fails without bab4dd0, so that at least we will know if we ever break this order again in the future (rather than having users finding this out).

[blueyed]

@nicoddemus #6554.

[nicoddemus]

Thanks, that's what I meant. 👍

[lhupfeldt]

@SalmonMode I took a look at my code and just realized that 'trylast' is on the hook only, not on the 'create_register_triggers' fixture. What I want is to have trylast functionality there as well. My actual test suite is not as simple as the example. I have multiple independent sets of dbdata loading fixtures, all generated from comments embedded in SQL files. To model the behaviour which I saw in pre 5.3.3 using fixture dependencies, would mean that every addition/removal of a dbdata load fixture might require an update of the 'create_register_triggers' fixture. The only reasonable solution wold then be to also generate that dynamically. Another reasonable assumption about evaluation order of independent fixtures, could be that fixtures given later in parameter list are invoked later. Was this what was happening before 5.3.3?

…

On Fri, 24 Jan 2020, 19:43 Bruno Oliveira, ***@***.***> wrote: Thanks, that's what I meant. 👍 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#6540?email_source=notifications&email_token=AAMCZSMV23GZ62525VS3XSTQ7MZFBA5CNFSM4KKN2Y62YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ3WWNY#issuecomment-578251575>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAMCZSJSB4LA63HPMBJV7I3Q7MZFBANCNFSM4KKN2Y6Q> .