Pantheon Community

Help diagnose CircleCI Behat test failures

We’ve been experiencing regular, but sporadic, false failures in our CircleCI Behat tests that we can’t explain.

A recent example occurred during this CircleCI job: https://circleci.com/gh/eGovPDX/portlandor/11758#tests/containers/3 Simply running the CircleCI test again resulted in a successful job: https://circleci.com/gh/eGovPDX/portlandor/11760

As you can see, there were three Behat test failures during this job. When a false failure occurs, it usually happens with these three same tests. There’s a database exception in the Drupal dblog at 6:50pm corresponding to the third Behat failure:

Drupal\Core\Database\DatabaseExceptionWrapper: SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array ( ) in Drupal\Core\Entity\Sql\SqlContentEntityStorage->delete() (line 792 of /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorage.php).

But there’s nothing to indicate why the first test failed. The artifact screenshot captured by the failure seems to suggest that a previous Behat command that logs in a user didn’t successfully finish or timed out. So when the following Behat command ran it loaded the page as an anonymous user and therefore the test failed because certain page elements (i.e. a “members link” that only appears for authenticated users) were not present.

We have our Behat “login” and “wait for page to load” commands configured to wait for 60 seconds before timing out.

Any ideas what’s causing this or suggestions as to how to further troubleshoot this issue?

Our php-fpm-error.log does show some slow php requests at this time corresponding to the failed tests:

4856 [10-Apr-2020 01:47:37] WARNING: [pool www] child 29486, script '/srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php' (request: "GET /index.php?pass-reset-token=va2jh6nzFdmGgwrW6EixbotEPYwnUN6QjnHyDprqUE_EntKrKRCHc-DzmwYxOfHV7HtfxKs4ZQ") executing too slow (5.071651 sec), logging
4857 [10-Apr-2020 01:47:37] NOTICE: child 29486 stopped for tracing
4858 [10-Apr-2020 01:47:37] NOTICE: about to trace 29486
4859 [10-Apr-2020 01:47:37] NOTICE: finished trace of 29486
4860 [10-Apr-2020 01:47:42] WARNING: [pool www] child 3102, script '/srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php' (request: "GET /index.php?pass-reset-token=HxEaUh98CQOjywaAgSXlkPSpFPh2Zffz5WoQrax6UBkgVD8O9Dr9cMocO8wp_DUb3_oI3GHUZA") executing too slow (6.339952 sec), logging
4861 [10-Apr-2020 01:47:42] NOTICE: child 3102 stopped for tracing
4862 [10-Apr-2020 01:47:42] NOTICE: about to trace 3102
4863 [10-Apr-2020 01:47:42] NOTICE: finished trace of 3102
4864 [10-Apr-2020 01:47:49] WARNING: [pool www] child 3121, script '/srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php' (request: "GET /index.php") executing too slow (5.094347 sec), logging
4865 [10-Apr-2020 01:47:49] NOTICE: child 3121 stopped for tracing
4866 [10-Apr-2020 01:47:49] NOTICE: about to trace 3121
4867 [10-Apr-2020 01:47:49] NOTICE: finished trace of 3121
4868 [10-Apr-2020 01:48:09] WARNING: [pool www] child 29541, script '/srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php' (request: "GET /index.php") executing too slow (5.685654 sec), logging
4869 [10-Apr-2020 01:48:09] NOTICE: child 29541 stopped for tracing
4870 [10-Apr-2020 01:48:09] NOTICE: about to trace 29541
4871 [10-Apr-2020 01:48:09] NOTICE: finished trace of 29541
4872 [10-Apr-2020 01:48:34] WARNING: [pool www] child 3102, script '/srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php' (request: "GET /index.php") executing too slow (6.069105 sec), logging
4873 [10-Apr-2020 01:48:34] NOTICE: child 3102 stopped for tracing
4874 [10-Apr-2020 01:48:34] NOTICE: about to trace 3102
4875 [10-Apr-2020 01:48:34] NOTICE: finished trace of 3102

Our php-slow.log shows this for the slow requests during this time:

66772 [10-Apr-2020 01:47:37]  [pool www] pid 29486
66773 script_filename = /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php
66774 [0x00007efcc4821650] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Statement.php:59
66775 [0x00007efcc4821590] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Connection.php:634
66776 [0x00007efcc48214a0] query() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Driver/mysql/Connection.php:357
66777 [0x00007efcc48213e0] query() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Query/Upsert.php:106
66778 [0x00007efcc4821300] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/DatabaseBackend.php:273
66779 [0x00007efcc4821210] doSetMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/DatabaseBackend.php:193
66780 [0x00007efcc4821170] setMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/DatabaseBackend.php:181
66781 [0x00007efcc48210c0] set() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/ChainedFastBackend.php:180
66782 [0x00007efcc4821020] set() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/UseCacheBackendTrait.php:71
66783 [0x00007efcc4820f80] cacheSet() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/EntityFieldManager.php:654
66784 [0x00007efcc4820ea0] getExtraFields() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/modules/layout_builder/src/Plugin/Derivative/ExtraFieldBlockDeriver.php:99
66785 [0x00007efcc4820d20] getDerivativeDefinitions() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Component/Plugin/Discovery/DerivativeDiscoveryDecorator.php:101
66786 [0x00007efcc4820c10] getDerivatives() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Component/Plugin/Discovery/DerivativeDiscoveryDecorator.php:87
66787 [0x00007efcc4820ba0] getDefinitions() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Plugin/DefaultPluginManager.php:284
66788 [0x00007efcc4820ae0] findDefinitions() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Plugin/DefaultPluginManager.php:175
66789 [0x00007efcc4820a70] getDefinitions() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Component/Plugin/Discovery/DiscoveryCachedTrait.php:22
66790 [0x00007efcc48209f0] getDefinition() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Plugin/Factory/ContainerFactory.php:16
66791 [0x00007efcc4820940] createInstance() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Component/Plugin/PluginManagerBase.php:76
66792 [0x00007efcc48208a0] createInstance() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Plugin/DefaultSingleLazyPluginCollection.php:62
66793 [0x00007efcc48207b0] initializePlugin() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/modules/block/src/BlockPluginCollection.php:57
66794 [10-Apr-2020 01:47:42]  [pool www] pid 3102
66795 script_filename = /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php
66796 [0x00007efcc4825390] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Statement.php:59
66797 [0x00007efcc48252d0] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Connection.php:634
66798 [0x00007efcc48251e0] query() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Driver/mysql/Connection.php:357
66799 [0x00007efcc4825120] query() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Query/Upsert.php:106
66800 [0x00007efcc4825040] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/DatabaseBackend.php:273
66801 [0x00007efcc4824f50] doSetMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/DatabaseBackend.php:193
66802 [0x00007efcc4824eb0] setMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/DatabaseBackend.php:181
66803 [0x00007efcc4824e00] set() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Routing/RouteProvider.php:234
66804 [0x00007efcc4824d10] preLoadRoutes() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Routing/RouteProvider.php:249
66805 [0x00007efcc4824c70] getRoutesByNames() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Routing/RouteProvider.php:206
66806 [0x00007efcc4824be0] getRouteByName() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Routing/UrlGenerator.php:426
66807 [0x00007efcc4824b50] getRoute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Routing/UrlGenerator.php:130
66808 [0x00007efcc4824ab0] getPathFromRoute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Render/MetadataBubblingUrlGenerator.php:68
66809 [0x00007efcc4824a30] getPathFromRoute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Url.php:791
66810 [0x00007efcc48249d0] getInternalPath() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Utility/LinkGenerator.php:135
66811 [0x00007efcc48248d0] generate() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Render/Element/Link.php:95
66812 [0x00007efcc4824810] preRenderLink() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Security/DoTrustedCallbackTrait.php:100
66813 [0x00007efcc48247a0] call_user_func_array() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Security/DoTrustedCallbackTrait.php:100
66814 [0x00007efcc4824690] doTrustedCallback() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Render/Renderer.php:781
66815 [0x00007efcc48245e0] doCallback() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Render/Renderer.php:372
66816 [10-Apr-2020 01:47:49]  [pool www] pid 3121
66817 script_filename = /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php
66818 [0x00007efcc4820b40] create() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorage.php:403
66819 [0x00007efcc4820aa0] getCustomTableMapping() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorageSchema.php:213
66820 [0x00007efcc48209e0] getTableMapping() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorageSchema.php:273
66821 [0x00007efcc4820910] requiresFieldStorageSchemaChanges() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorage.php:1482
66822 [0x00007efcc4820890] requiresFieldStorageSchemaChanges() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/EntityDefinitionUpdateManager.php:388
66823 [0x00007efcc48207f0] requiresFieldStorageSchemaChanges() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/EntityDefinitionUpdateManager.php:337
66824 [0x00007efcc48206c0] getChangeList() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/EntityDefinitionUpdateManager.php:129
66825 [0x00007efcc48205b0] getChangeSummary() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/modules/system/system.install:827
66826 [0x00007efcc481fda0] system_requirements() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Extension/ModuleHandler.php:403
66827 [0x00007efcc481fd30] call_user_func_array() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Extension/ModuleHandler.php:403
66828 [0x00007efcc481fc40] invokeAll() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/modules/system/src/SystemManager.php:111
66829 [0x00007efcc481fbc0] listRequirements() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/modules/system/src/Controller/SystemInfoController.php:49
66830 [0x00007efcc481fb50] status() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php:123
66831 [0x00007efcc481fae0] call_user_func_array() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php:123
66832 [0x00007efcc481fa60] Drupal\Core\EventSubscriber\{closure}() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Render/Renderer.php:573
66833 [0x00007efcc481f9b0] executeInRenderContext() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php:124
66834 [0x00007efcc481f8f0] wrapControllerExecutionInRenderContext() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php:97
66835 [0x00007efcc481f870] Drupal\Core\EventSubscriber\{closure}() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/vendor/symfony/http-kernel/HttpKernel.php:151
66836 [0x00007efcc481f790] handleRaw() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/vendor/symfony/http-kernel/HttpKernel.php:68
66837 [0x00007efcc481f6e0] handle() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/StackMiddleware/Session.php:57
66838 [10-Apr-2020 01:48:09]  [pool www] pid 29541
66839 script_filename = /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php
66840 [0x00007efcc4821560] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Statement.php:59
66841 [0x00007efcc48214a0] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Connection.php:634
66842 [0x00007efcc48213b0] query() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Driver/mysql/Connection.php:357
66843 [0x00007efcc48212f0] query() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/DatabaseBackend.php:113
66844 [0x00007efcc48211f0] getMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Cache/ChainedFastBackend.php:165
66845 [0x00007efcc48210f0] getMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/CachedStorage.php:87
66846 [0x00007efcc4820fa0] readMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/ConfigFactory.php:165
66847 [0x00007efcc4820e90] doLoadMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/ConfigFactory.php:136
66848 [0x00007efcc4820e20] loadMultiple() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/Entity/Query/Query.php:212
66849 [0x00007efcc4820c90] loadRecords() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/Entity/Query/Query.php:82
66850 [0x00007efcc4820ba0] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/modules/field/field.module:181
66851 [0x00007efcc4820ae0] field_entity_field_storage_info() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Extension/ModuleHandler.php:392
66852 [0x00007efcc4820a70] call_user_func_array() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Extension/ModuleHandler.php:392
66853 [0x00007efcc48209c0] invoke() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/EntityFieldManager.php:572
66854 [0x00007efcc48208d0] buildFieldStorageDefinitions() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/EntityFieldManager.php:448
66855 [0x00007efcc48207f0] getFieldStorageDefinitions() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/EntityDefinitionUpdateManager.php:315
66856 [0x00007efcc48206c0] getChangeList() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Entity/EntityDefinitionUpdateManager.php:129
66857 [0x00007efcc48205b0] getChangeSummary() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/modules/system/system.install:827
66858 [0x00007efcc481fda0] system_requirements() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Extension/ModuleHandler.php:403
66859 [0x00007efcc481fd30] call_user_func_array() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Extension/ModuleHandler.php:403
66860 [10-Apr-2020 01:48:34]  [pool www] pid 3102
66861 script_filename = /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web//index.php
66862 [0x00007efcc4820700] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Statement.php:59
66863 [0x00007efcc4820640] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Connection.php:634
66864 [0x00007efcc4820550] query() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Driver/mysql/Connection.php:357
66865 [0x00007efcc4820490] query() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Driver/mysql/Insert.php:32
66866 [0x00007efcc48203b0] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Database/Query/Merge.php:373
66867 [0x00007efcc48202e0] execute() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/DatabaseStorage.php:150
66868 [0x00007efcc4820230] doWrite() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/DatabaseStorage.php:123
66869 [0x00007efcc48201a0] write() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/StorageCopyTrait.php:33
66870 [0x00007efcc48200c0] replaceStorageContents() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Config/ImportStorageTransformer.php:117
66871 [0x00007efcc4820030] transform() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/modules/config/src/Form/ConfigSync.php:210
66872 [0x00007efcc481fe80] buildForm() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Form/FormBuilder.php:520
66873 [0x00007efcc481fe10] call_user_func_array() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Form/FormBuilder.php:520
66874 [0x00007efcc481fd30] retrieveForm() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Form/FormBuilder.php:277
66875 [0x00007efcc481fc10] buildForm() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Controller/FormController.php:91
66876 [0x00007efcc481fb50] getContentResult() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php:123
66877 [0x00007efcc481fae0] call_user_func_array() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php:123
66878 [0x00007efcc481fa60] Drupal\Core\EventSubscriber\{closure}() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/Render/Renderer.php:573
66879 [0x00007efcc481f9b0] executeInRenderContext() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php:124
66880 [0x00007efcc481f8f0] wrapControllerExecutionInRenderContext() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/web/core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php:97
66881 [0x00007efcc481f870] Drupal\Core\EventSubscriber\{closure}() /srv/bindings/adf2370486c74f65a56b1d8205029bf8/code/vendor/symfony/http-kernel/HttpKernel.php:151

I’ve been looking at the nginx logs during our test failures and I’m having a hard time understanding the remote IP addresses. At first I thought they corresponded to the CircleCI containers running our tests because we use 5 containers and there were 5 IP addresses. But I tried changing a job to only use 2 containers and the resulting log actually had 6 IP addresses.

What do these addresses correspond to?

382 35.239.160.90 - - [16/Apr/2020:15:59:56 +0000 "GET /user/reset/63/1587052794/JlKrTcWf-dqalpd7-Tc600skt0fMidgCs4oEH20x7zI/login HTTP/1.1 302 8600 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.601 "34.207.239.125, 34.207.239.125"
385 35.238.226.159 - - [16/Apr/2020:15:59:55 +0000 "GET /user/reset/63/1587052794/JlKrTcWf-dqalpd7-Tc600skt0fMidgCs4oEH20x7zI/login HTTP/1.1 301 5 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.006 "34.207.239.125"
388 104.198.178.229 - - [16/Apr/2020:15:59:56 +0000 "GET /marty-member/edit?pass-reset-token=0UWJBzxVRgik5UouBASJ63Glm0d9Yr8a9MQgZIN_NjqpPBWdX9Y00v4VOJs53W_oe7g5yUOAEg HTTP/1.1 200 13750 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.492 "34.207.239.125, 34.207.239.125"
575 35.238.226.159 - - [16/Apr/2020:16:00:28 +0000 "GET /user/reset/62/1587052826/uTnN-Eo9Ov7F53FFR0VnCYXlNkiUx0Gy9WcyPQjcUgI/login HTTP/1.1 302 8592 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.624 "34.235.89.136, 34.235.89.136"
581 35.238.226.159 - - [16/Apr/2020:16:01:00 +0000 "GET /powr HTTP/1.1 200 14626 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 3.352 "34.207.239.125, 34.207.239.125"
597 35.193.191.119 - - [16/Apr/2020:16:01:02 +0000 "GET /powr/node/create HTTP/1.1 200 12143 "https://powr-2199-portlandor.pantheonsite.io/powr" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.454 "34.207.239.125, 34.207.239.125"
606 35.225.194.20 - - [16/Apr/2020:16:01:05 +0000 "GET /powr/content/create/group_node%3Apage HTTP/1.1 200 22024 "https://powr-2199-portlandor.pantheonsite.io/powr/node/create" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.784 "34.207.239.125, 34.207.239.125"
636 104.198.178.229 - - [16/Apr/2020:16:00:29 +0000 "GET /ally-admin/edit?pass-reset-token=LWnf6LVtCfDWwpVunRfGEfY6UPZfkqBSusQgogAp-tM6ISIa-ItMYIZ2BouBQ4vw8JN5brpp5A HTTP/1.1 200 13743 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.535 "34.235.89.136, 34.235.89.136"
678 35.193.191.119 - - [16/Apr/2020:16:01:14 +0000 "GET /powr/test-page HTTP/1.1 200 12009 "https://powr-2199-portlandor.pantheonsite.io/powr/content/create/group_node%3Apage" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 2.203 "34.207.239.125, 34.207.239.125"
695 35.225.194.20 - - [16/Apr/2020:16:01:25 +0000 "GET /user/reset/63/1587052883/ALOAPfXVSRnzmx3TCn86QBq1jzmALzW-HK37Iv_Dsmg/login HTTP/1.1 302 8600 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.460 "34.207.239.125, 34.207.239.125"
697 35.202.83.3 - - [16/Apr/2020:16:01:26 +0000 "GET /marty-member/edit?pass-reset-token=ZpqRUkcie0gN-TtmW3T8cFzXrPIvz2LgXFxrHQ6gs98i4ZV6wXC4qXnldnXctj0YJRlYq51tiw HTTP/1.1 200 13755 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.843 "34.207.239.125, 34.207.239.125"
739 35.239.160.90 - - [16/Apr/2020:16:01:56 +0000 "GET /user/reset/1/1587052915/T58h-iolrl08ratcUguJcDrkHCiwvUhoVuQrnn0-hik/login HTTP/1.1 302 8592 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.404 "34.235.89.136, 34.235.89.136"
740 35.193.191.119 - - [16/Apr/2020:16:01:57 +0000 "GET /superadmin/edit?pass-reset-token=gP0HPRaHGzfDmDbFZJvS_Vx_jznmXfxFVJT53bw9CXYORXiL8iHjMGIIEtS3taYP3AZzqfJSsQ HTTP/1.1 200 41768 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.448 "34.235.89.136, 34.235.89.136"
855 104.198.178.229 - - [16/Apr/2020:16:02:22 +0000 "GET /user/reset/63/1587052941/W5GcYCDweSOyYq0pl_bZo1u80WEFfXTfal9d3QyUlvE/login HTTP/1.1 301 5 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.020 "34.235.89.136"
856 104.198.178.229 - - [16/Apr/2020:16:02:23 +0000 "GET /user/reset/63/1587052941/W5GcYCDweSOyYq0pl_bZo1u80WEFfXTfal9d3QyUlvE/login HTTP/1.1 302 8600 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.436 "34.235.89.136, 34.235.89.136"
867 35.239.160.90 - - [16/Apr/2020:16:02:24 +0000 "GET /marty-member/edit?pass-reset-token=KVgbmyGQtDR7dR-o6auvUe4OeGNcA-P3dRO5Inn4iTbDFdFsAwWSfhHvwlwGDEIrELK-rZ_4Yg HTTP/1.1 200 13746 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.802 "34.235.89.136, 34.235.89.136"
877 104.198.178.229 - - [16/Apr/2020:16:02:27 +0000 "GET /powr/test-page HTTP/1.1 200 11903 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.478 "34.207.239.125, 34.207.239.125"
881 35.202.83.3 - - [16/Apr/2020:16:02:29 +0000 "GET /powr/test-page/edit HTTP/1.1 200 22128 "https://powr-2199-portlandor.pantheonsite.io/powr/test-page" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.303 "34.207.239.125, 34.207.239.125"
950 35.202.83.3 - - [16/Apr/2020:16:02:33 +0000 "GET /powr/test-page/delete HTTP/1.1 200 11204 "https://powr-2199-portlandor.pantheonsite.io/powr/test-page/edit" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.135 "34.207.239.125, 34.207.239.125"
972 104.198.178.229 - - [16/Apr/2020:16:03:26 +0000 "GET /powr HTTP/1.1 200 14621 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.645 "34.235.89.136, 34.235.89.136"
978 35.225.194.20 - - [16/Apr/2020:16:03:28 +0000 "GET /powr/media/create HTTP/1.1 200 12183 "https://powr-2199-portlandor.pantheonsite.io/powr" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.806 "34.235.89.136, 34.235.89.136"
994 35.238.226.159 - - [16/Apr/2020:16:03:31 +0000 "GET /powr/content/create/group_media%3Avideo HTTP/1.1 200 16929 "https://powr-2199-portlandor.pantheonsite.io/powr/media/create" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.475 "34.235.89.136, 34.235.89.136"
1026 104.198.178.229 - - [16/Apr/2020:16:03:38 +0000 "GET /powr/media HTTP/1.1 200 19403 "https://powr-2199-portlandor.pantheonsite.io/powr/content/create/group_media%3Avideo" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 3.482 "34.235.89.136, 34.235.89.136"
1069 35.202.83.3 - - [16/Apr/2020:16:03:50 +0000 "GET /user/reset/63/1587053028/pCTzw1K6_RNlVVKCyzjtml8KpVleVd7qUXr-U10ZunQ/login HTTP/1.1 302 8600 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.428 "34.235.89.136, 34.235.89.136"
1071 35.202.83.3 - - [16/Apr/2020:16:04:52 +0000 "GET /powr HTTP/1.1 200 14628 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.031 "34.235.89.136, 34.235.89.136"
1075 104.198.178.229 - - [16/Apr/2020:16:03:51 +0000 "GET /marty-member/edit?pass-reset-token=e2hbMmyLyT1Fh9GDnHTmHPHBRqTMZuQzwtLZAWAWxoThPlVGreqbR3U8hSM-I1mgprH0y8-MuA HTTP/1.1 200 13744 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.737 "34.235.89.136, 34.235.89.136"
1081 35.193.191.119 - - [16/Apr/2020:16:04:54 +0000 "GET /powr/media HTTP/1.1 200 19284 "https://powr-2199-portlandor.pantheonsite.io/powr" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 0.694 "34.235.89.136, 34.235.89.136"
1116 35.239.160.90 - - [16/Apr/2020:16:04:56 +0000 "GET /powr/videos/test-video HTTP/1.1 200 11443 "https://powr-2199-portlandor.pantheonsite.io/powr/media" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36" 1.072 "34.235.89.136, 34.235.89.136"

We finally figured out this was being caused by a race condition when two CircleCI containers both attempted to log in the same user at the exact same time. Each container executes drush uli and loads the login link at the same time. Whichever request gets processed first logs the user in and redirects to /[username]/edit. This invalidates the other login link, so when it gets processed it redirects the user to /user/password with this error message:

You have tried to use a one-time login link that has either been used or is no longer valid. Please request a new one using the form below.

1 Like

Thanks for sharing the fix with the community! I saw your post a few days back but wasn’t sure on a solution.

You might want to take a look at this orb which lets you limit concurrent jobs. We use it to make sure only one job pushes our docs to the production environment at a time.

Thanks for the suggestion. Although in our case, it wasn’t a problem of concurrent jobs, it was caused by a single job that uses parallelism to run multiple tests at the same time. We want to retain the parallelism because it makes the job complete much quicker.

To fix it, we just put in a little check into our login code that checks for a failed login attempt and retries it again if it fails. This appears to have solved our problem.