Calling behave with multiple feature files causes exponential runtime increase in print(msg) in base_case.py in line 15475 (seleniumbase 4.18.1)

[alexkallai]

Used versions:
seleniumbase 4.18.1
colorama 0.4.6

Disclaimer: we are using Seleniumbase with some modifications using monkeypatching, so it's not 100% this issue is reproducible with the stock version, but the changed functions don't seem to relate to this issue

Bug description:

On Windows 10 and Windows 11 if we call behave with multiple feature files, at the end of the scenario in tearDown there are exponentially increasing times when printing the message, e.g.: " ❌ Scenario Failed! (Skipping remaining steps:)"
The issue occurs with colorama 0.4.6, and it's not occurring with colorama 0.4.5

The measured function in the debug print section is the print(msg) in base_case.py in line 15475:
tearDown (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\seleniumbase\fixtures\base_case.py:15475)

Debug print:
Scenario 1: time: 0.0 Scenario Passed!
Scenario 2: time: 0.0 Scenario Passed!
Scenario 3: time: 0.0024292469024658203 Scenario Passed!
Scenario 4: time: 0.001993417739868164 Scenario Failed! (Skipping remaining steps:)
Scenario 5: time: 0.0065212249755859375 Scenario Passed!
Scenario 6: time: 0.016805648803710938 Scenario Passed!
Scenario 7: time: 0.017581701278686523 Scenario Passed!
Scenario 8: time: 0.011757373809814453 Scenario Passed!
Scenario 9: time: 0.021941423416137695 Scenario Passed!
Scenario 10: time: 0.053227901458740234 Scenario Passed!
Scenario 11: time: 0.09075689315795898 Scenario Passed!
Scenario 12: time: 0.158768892288208 Scenario Passed!
Scenario 13: time: 0.32082366943359375 Scenario Passed!
Scenario 14: time: 0.6395654678344727 Scenario Passed!
Scenario 15: time: 1.3170313835144043 Scenario Passed!
Scenario 16: time: 2.5952649116516113 Scenario Passed!
Scenario 17: time: 5.473366022109985 Scenario Passed!
Scenario 18: time: 10.67004919052124 Scenario Failed! (Skipping remaining steps:)
Scenario 19: time: 22.595618724822998 Scenario Passed!
Scenario 20: time: 45.32230567932129 Scenario Passed!

This is how we run tests:
behave
{ABS_PATH}\suite_ConfigurationPage\tst_311_ShareFunction\test.feature
{ABS_PATH}\suite_ConfigurationPage\tst_337_SortingOfConfigurations\test.feature
{ABS_PATH}\suite_ConfigurationPage\tst_339_ListPageSearch\test.feature
{ABS_PATH}\suite_ConfigurationPage\tst_341_ListPageSearchAndTag\test.feature
{ABS_PATH}\suite_ConfigurationPage\tst_372_ListPageShowFavorites\test.feature
{ABS_PATH}\suite_General\tst_688_Snackbar_design\test.feature
{ABS_PATH}\suite_General\tst_702_404Error\test.feature
{ABS_PATH}\suite_General\tst_704_404Error_German\test.feature
{ABS_PATH}\suite_LoginPage\tst_327_Logout\test.feature
{ABS_PATH}\suite_LoginPage\tst_349_RedirectToRequestedURL\test.feature
{ABS_PATH}\suite_LoginPage\tst_421_LoginWithExternalCreds\test.feature
{ABS_PATH}\suite_PlayerPage\tst_295_PlayerPageOpens\test.feature
{ABS_PATH}\suite_PlayerPage\tst_370_AddRemoveButton\test.feature
{ABS_PATH}\suite_PlayerPage\tst_530_ResourceError\test.feature
{ABS_PATH}\suite_PlayerPage\tst_570_AddComment\test.feature
{ABS_PATH}\suite_PlayerPage\tst_571_LikeComment\test.feature
{ABS_PATH}\suite_PlayerPage\tst_573_ViewOlderComments\test.feature
{ABS_PATH}\suite_PlayerPage\tst_575_PasteText\test.feature
{ABS_PATH}\suite_PlayerPage\tst_582_SelectInputField\test.feature
{ABS_PATH}\suite_PlayerPage\tst_600_FileSizeLimit\test.feature
{ABS_PATH}\suite_PlayerPage\tst_601_AllowedExtensions\test.feature
{ABS_PATH}\suite_PlayerPage\tst_604_HashMatch\test.feature
{ABS_PATH}\suite_PlayerPage\tst_607_UploadBySelection\test.feature
{ABS_PATH}\suite_PlayerPage\tst_609_DeleteFiles\test.feature
{ABS_PATH}\suite_PlayerPage\tst_641_CommentSectionBehavior\test.feature
{ABS_PATH}\suite_PlayerPage\tst_663_Description\test.feature
{ABS_PATH}\suite_PlayerPage\tst_667_Tag\test.feature
{ABS_PATH}\suite_PlayerPage\tst_783_AddCommentAndReload\test.feature
"-D browser=chrome"
"-D demo "
"-D demo-sleep=0.3 "
"-D highlights=2"
"-D maximize"
"-D rs"
"-D dashboard --junit"

Example call stack: -> note the really deep colorama call stack
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:179)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
reset_all (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:189)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:182)
write (c:\Python311\Lib\site-packages\colorama\ansitowin32.py:47)
tearDown (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\seleniumbase\fixtures\base_case.py:15475)
after_scenario (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\seleniumbase\behave\behave_sb.py:1321)
after_scenario (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\common-seleniumbase\lib\bddUtil\environment_hook.py:67)
run_hook (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave\runner.py:545)
run (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave\model.py:758)
run (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave\model.py:321)
run_model (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave\runner.py:626)
run_with_paths (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave\runner.py:824)
run (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave\runner.py:804)
run_behave (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave_main_.py:127)
main (d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave_main_.py:183)
(d:\GIT\CloudAutomationSeleniumbase_experiments\CloudAutomationSeleniumbase\venv\Lib\site-packages\behave_main_.py:187)
_run_code (c:\Python311\Lib\runpy.py:88)
_run_module_as_main (c:\Python311\Lib\runpy.py:198)

[mdmintz]

Looks like colorama just added a new method for this exact scenario:

tartley/colorama#352 - colorama.just_fix_windows_console()

That means I can probably fix the issue by swapping colorama.init(autoreset=True) with that (Windows-only), such as https://github.com/seleniumbase/SeleniumBase/blob/v4.18.1/seleniumbase/fixtures/base_case.py#L15481C25-L15481C54

I can probably ship that fix in the next release, 4.19.2, expected later today.

[alexkallai]

Thanks, I can test the fix next week if you'd like some feedback :)

[mdmintz]

This was resolved in 4.19.2 - https://github.com/seleniumbase/SeleniumBase/releases/tag/v4.19.2