Project config not loading for unit tests

[dce]

Description

I'm seeing a strange issue that I hope someone can help me out with.

I have a test suite that consists of some functional and unit tests. The functional tests reference some data loaded in from project.yaml and insert some records into the DB. The unit tests do not. This all works fine.

I've now added some new unit tests that reference a section and an entry type and create some entries. When I run the full suite, these tests error out, saying they can't find the section/entry type. (The functional tests continue to work properly.) When I run the unit tests only, it alternates between running properly and failing with the same error.

I've tried running with the -vvv option but it doesn't output any debugging info about how it's loading in the project configuration.

Steps to reproduce

1. Create a unit test that references a section defined in project.yaml
2. Run it

codeception.yml:

actor: Tester
paths:
    tests: tests
    log: tests/_output
    data: tests/_data
    support: tests/_support
    envs: tests/_envs
bootstrap: _bootstrap.php
params:
    - tests/.env
modules:
    config:
        \craft\test\Craft:
            configFile: 'tests/_craft/config/test.php'
            entryUrl: 'http://clientname.test/index.php'
            entryScript: ''
            projectConfig: {file: 'config/project.yaml', reset: false}
            migrations: []
            plugins: []
            cleanup: true
            transaction: true
            dbSetup: {clean: true, setupCraft: true}

Additional info

• Craft version: 3.3.15
• PHP version: 7.1.31
• Database driver & version: MariaDB 10.3.17
• Plugins & versions: Codeception v3.1.2

[gtettelaar]

Hmm weird... Can you share the unit.suite.yml and functional.suite.yml as well as your tests/_craft/config/general.php then I'll try to reproduce it on my side?

[dce]

tests/unit.suite.yml:

# Codeception Test Suite Configuration
#
# Suite for unit or integration tests.

actor: UnitTester
modules:
    enabled:
        - \craft\test\Craft
        - Asserts
        - \Helper\Unit
    step_decorators: ~

tests/functional.suite.yml:

# Codeception Test Suite Configuration
#
# Suite for functional tests
# Emulate web requests and make application process them
# Include one of framework modules (Symfony2, Yii2, Laravel5) to use it
# Remove this suite if you don't use frameworks

actor: FunctionalTester
modules:
    enabled:
        - \craft\test\Craft
        - \Helper\Functional
    step_decorators: ~

tests/_craft/config/general.php:

<?php
/**
 * General Configuration
 *
 * All of your system's general configuration settings go in here. You can see a
 * list of the available settings in vendor/craftcms/cms/src/config/GeneralConfig.php.
 *
 * @see \craft\config\GeneralConfig
 */

return [
    '*' => [
        'useProjectConfigFile' => true
    ]
];

As a note, this project was using Codeception 3.0 (not 3.1) when all the config files were generated. Thanks for taking a look!

[dce]

I'll also add that I recently had to add that reset: false to projectConfig after upgrading from 3.3.7 to 3.3.15, seemingly related to this commit. I'm also using dbSetup and not setupDb as specified in the docs. The source is ambiguous about which is correct.

Thanks again.

[dce]

Update: I converted my failing unit test file to functional tests and saw the same issue. Then I deleted my failing test and created a copy of my existing working functional test, and still see the same issue. So now I'm thinking the problem is having two different test files that depend on project.yaml settings.

[dce]

I'm now noticing there's no project.yaml in tests/_craft/config/ when the suite fails -- it's getting deleted as part of initialization and then a highly truncated version is added back in afterward. Still digging in.

[dce]

Dropping and creating my test database before each test run seems to fix the problem, though it still fails if I try to run the entire suite (functional + unit). If I drop and recreate between functional and unit it works.

[gtettelaar]

I'm now noticing there's no project.yaml in tests/_craft/config/ when the suite fails -- it's getting deleted as part of initialization and then a highly truncated version is added back in afterward. Still digging in.

@dce Based on this my gut is telling me there is something wrong with the project.yml file (Schema conflicts for example). In general because I'm not entirely sure what the problem is could you share your composer.lock, project.yml and the unit and functional test you are trying to run. You can send them via discord (@gieltettelaar - preferable) or Craft support (support@craftcms.com) then I can reproduce your exact running conditions. Thanks!

[angrybrad]

Probably also worth looking through your Craft storage/logs folder to see if any errors are being logged during the tests.

[dce]

@gtettelaar I'll see what would be involved in sending the code over. It's for a (quite security-conscious) client.

@angrybrad anything in particular I should grep for? I'm not seeing much of anything in phperrors.log, and the various console.log/console.log.N have a ton of SQL logging in them.

[angrybrad]

@dce [error] and possibly [warning] would be a good starting point.

[dce]

Definitely seeing a LOT of:

tests/_craft/storage/logs/console.log.5:2019-11-18 18:49:51 [-][-][-][warning][craft\db\mysql\Schema::releaseSavepoint] Tried to release a savepoint, but it does not exist: SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT LEVEL1 does not exist

[angrybrad]

Interesting... is there a stack trace leading up to it?

[dce]

Seems to roughly all follow this pattern (let me know if more of the log would be helpful but it's seemingly just more SQL):

tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][info][yii\db\Command::execute] INSERT INTO `craft_fields` (`uid`, `groupId`, `name`, `handle`, `context`, `instructions`, `searchable`, `translationMethod`, `translationKeyFormat`, `type`, `settings`, `dateCreated`, `dateUpdated`) VALUES ('3189a8a1-49d0-4d07-acaa-e01aa29ac5b0', NULL, 'Text', 'text', 'matrixBlockType:4e12652c-8fc2-4e79-bfc5-e75e37ad8c80', '', 1, 'none', NULL, 'craft\\redactor\\Field', '{\"redactorConfig\":\"Standard.json\",\"purifierConfig\":\"\",\"cleanupHtml\":true,\"removeInlineStyles\":\"1\",\"removeEmptyTags\":\"1\",\"removeNbsp\":\"1\",\"purifyHtml\":\"1\",\"columnType\":\"text\",\"availableVolumes\":\"*\",\"availableTransforms\":\"*\"}', '2019-11-18 18:50:12', '2019-11-18 18:50:12')
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][profile begin][yii\db\Command::execute] INSERT INTO `craft_fields` (`uid`, `groupId`, `name`, `handle`, `context`, `instructions`, `searchable`, `translationMethod`, `translationKeyFormat`, `type`, `settings`, `dateCreated`, `dateUpdated`) VALUES ('3189a8a1-49d0-4d07-acaa-e01aa29ac5b0', NULL, 'Text', 'text', 'matrixBlockType:4e12652c-8fc2-4e79-bfc5-e75e37ad8c80', '', 1, 'none', NULL, 'craft\\redactor\\Field', '{\"redactorConfig\":\"Standard.json\",\"purifierConfig\":\"\",\"cleanupHtml\":true,\"removeInlineStyles\":\"1\",\"removeEmptyTags\":\"1\",\"removeNbsp\":\"1\",\"purifyHtml\":\"1\",\"columnType\":\"text\",\"availableVolumes\":\"*\",\"availableTransforms\":\"*\"}', '2019-11-18 18:50:12', '2019-11-18 18:50:12')
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][profile end][yii\db\Command::execute] INSERT INTO `craft_fields` (`uid`, `groupId`, `name`, `handle`, `context`, `instructions`, `searchable`, `translationMethod`, `translationKeyFormat`, `type`, `settings`, `dateCreated`, `dateUpdated`) VALUES ('3189a8a1-49d0-4d07-acaa-e01aa29ac5b0', NULL, 'Text', 'text', 'matrixBlockType:4e12652c-8fc2-4e79-bfc5-e75e37ad8c80', '', 1, 'none', NULL, 'craft\\redactor\\Field', '{\"redactorConfig\":\"Standard.json\",\"purifierConfig\":\"\",\"cleanupHtml\":true,\"removeInlineStyles\":\"1\",\"removeEmptyTags\":\"1\",\"removeNbsp\":\"1\",\"purifyHtml\":\"1\",\"columnType\":\"text\",\"availableVolumes\":\"*\",\"availableTransforms\":\"*\"}', '2019-11-18 18:50:12', '2019-11-18 18:50:12')
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][trace][yii\db\Transaction::commit] Release savepoint 1
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][info][yii\db\Command::execute] RELEASE SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][profile begin][yii\db\Command::execute] RELEASE SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][profile end][yii\db\Command::execute] RELEASE SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5:2019-11-18 18:50:12 [-][-][-][warning][craft\db\mysql\Schema::releaseSavepoint] Tried to release a savepoint, but it does not exist: SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT LEVEL1 does not exist

[dce]

grep -ir "SAVEPOINT LEVEL1" --before 2 --after 2 tests/_craft/storage/logs/ looks like this (over and over):

--
tests/_craft/storage/logs/console.log.5-ORDER BY `fields`.`name`, `fields`.`handle`
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][trace][yii\db\Transaction::begin] Set savepoint 1
tests/_craft/storage/logs/console.log.5:2019-11-18 18:50:12 [-][-][-][info][yii\db\Command::execute] SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5:2019-11-18 18:50:12 [-][-][-][profile begin][yii\db\Command::execute] SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5:2019-11-18 18:50:12 [-][-][-][profile end][yii\db\Command::execute] SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][info][yii\db\Command::query] SELECT *
tests/_craft/storage/logs/console.log.5-FROM `craft_fields`
--
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][profile end][yii\db\Command::execute] INSERT INTO `craft_fields` (`uid`, `groupId`, `name`, `handle`, `context`, `instructions`, `searchable`, `translationMethod`, `translationKeyFormat`, `type`, `settings`, `dateCreated`, `dateUpdated`) VALUES ('946aeb51-974c-4e8a-97f5-bc581a7a8269', NULL, 'Width', 'width', 'matrixBlockType:4e12652c-8fc2-4e79-bfc5-e75e37ad8c80', '', 0, 'none', NULL, 'rias\\widthfieldtype\\fields\\Width', '{\"options\":{\"1/6\":\"\",\"1/5\":\"\",\"1/4\":\"\",\"1/3\":\"\",\"2/5\":\"\",\"1/2\":\"1\",\"3/5\":\"\",\"2/3\":\"\",\"3/4\":\"\",\"4/5\":\"\",\"5/6\":\"\",\"full\":\"1\"},\"default\":\"full\"}', '2019-11-18 18:50:12', '2019-11-18 18:50:12')
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][trace][yii\db\Transaction::commit] Release savepoint 1
tests/_craft/storage/logs/console.log.5:2019-11-18 18:50:12 [-][-][-][info][yii\db\Command::execute] RELEASE SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5:2019-11-18 18:50:12 [-][-][-][profile begin][yii\db\Command::execute] RELEASE SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5:2019-11-18 18:50:12 [-][-][-][profile end][yii\db\Command::execute] RELEASE SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5:2019-11-18 18:50:12 [-][-][-][warning][craft\db\mysql\Schema::releaseSavepoint] Tried to release a savepoint, but it does not exist: SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT LEVEL1 does not exist
tests/_craft/storage/logs/console.log.5:The SQL being executed was: RELEASE SAVEPOINT LEVEL1
tests/_craft/storage/logs/console.log.5-2019-11-18 18:50:12 [-][-][-][info][yii\db\Command::query] SELECT `fields`.`id`, `fields`.`dateCreated`, `fields`.`dateUpdated`, `fields`.`groupId`, `fields`.`name`, `fields`.`handle`, `fields`.`context`, `fields`.`instructions`, `fields`.`translationMethod`, `fields`.`translationKeyFormat`, `fields`.`type`, `fields`.`settings`, `fields`.`uid`, `fields`.`searchable`
tests/_craft/storage/logs/console.log.5-FROM `craft_fields` `fields`
--

[davist11]

@angrybrad I'm working on the same project as @dce and still seeing some sort of race condition or intermittent issue with the project config not fully being loaded before the tests run. Ex:

$teamSection = Craft::$app->sections->getSectionByHandle('team');

Sometimes that returns null and sometimes it correctly returns the Section model.

Our temporary solution is to drop and create the DB before running the tests, and that seems to solve the problem. But from our config, it seems like that should happen already with the dbSetup option right?

modules:
    config:
        \craft\test\Craft:
            configFile: 'tests/_craft/config/test.php'
            entryUrl: 'http://clientname.test/index.php'
            entryScript: ''
            projectConfig: {file: 'config/project.yaml', reset: false}
            migrations: []
            plugins: []
            cleanup: true
            transaction: true
            dbSetup: {clean: true, setupCraft: true}

Also worth nothing that we are using dbSetup and not setupDb as specified in the docs. The source is ambiguous about which is correct.

Let us know if there is any additional info we can provide to try and get to the bottom of this. Thanks!

[elblasto]

Same problem here