Defect #42200
closed
InlineAutocompleteSystemTest login test fails randomly
Added by Katsuya HIDAKA about 1 month ago. Updated 27 days ago.
0%
Description
Currently, the following test in the log_user method within InlineAutocompleteSystemTest fails randomly.
def log_user(login, password)
visit '/my/page'
assert_equal '/login', current_path # <== Here
within('#login-form form') do
fill_in 'username', :with => login
...
end
Failure: InlineAutocompleteSystemTest#test_inline_autocompletion_of_wiki_page_links [test/application_system_test_case.rb:71]: Expected: "/login" Actual: "/my/page" bin/rails test test/system/inline_autocomplete_test.rb:144
https://github.com/hidakatsuya/redmine/actions/runs/13014082081/job/36298727579
This test failure mainly occurs in the InlineAutocompleteSystemTest test, but it can also occur in other tests.
Files
Updated by Katsuya HIDAKA about 1 month ago
- File 0001-Fix-random-failures-in-InlineAutocompleteTest-due-to-interference-from-requests-in-the-previous-test.patch 0001-Fix-random-failures-in-InlineAutocompleteTest-due-to-interference-from-requests-in-the-previous-test.patch added
- File 0002-Add-missing-assertions-to-InlineAutocompleteTest.patch 0002-Add-missing-assertions-to-InlineAutocompleteTest.patch added
I have identified the cause of the random failures in InlineAutocompleteSystemTest and will explain the details, the root cause, and the solution.
Currently, there are two distinct failure patterns in InlineAutocompleteSystemTest:
- Login test failure
Failure: InlineAutocompleteSystemTest#test_inline_autocompletion_of_wiki_page_links [test/application_system_test_case.rb:71]: Expected: "/login" Actual: "/my/page" bin/rails test test/system/inline_autocomplete_test.rb:138
- StaleElementReferenceError during autocomplete assertion
Error: InlineAutocompleteSystemTest#test_inline_autocomplete_for_users_on_issues_bulk_edit_show_autocomplete: Selenium::WebDriver::Error::StaleElementReferenceError: stale element reference: stale element not found in the current frame (Session info: chrome=131.0.6778.204); For documentation on this error, please visit: https://www.selenium.dev/documentation/webdriver/troubleshooting/errors#stale-element-reference-exception test/system/inline_autocomplete_test.rb:207:in `block in test_inline_autocomplete_for_users_on_issues_bulk_edit_show_autocomplete' test/system/inline_autocomplete_test.rb:205:in `test_inline_autocomplete_for_users_on_issues_bulk_edit_show_autocomplete' bin/rails test test/system/inline_autocomplete_test.rb:198
Both failures occur because asynchronous requests to AutoCompleteController from a preceding test case interfere with the subsequent test.
For example, if test_inline_autocomplete_for_issues_should_escape_html_elements is followed by another test, that test may fail:
def test_inline_autocomplete_for_issues_should_escape_html_elements
issue = Issue.generate!(subject: 'This issue has a <select> element', project_id: 1, tracker_id: 1)
log_user('jsmith', 'jsmith')
visit 'projects/1/issues/new'
fill_in 'Description', :with => '#This'
within('.tribute-container') do
assert page.has_text? "Bug ##{issue.id}: This issue has a <select> element"
end
end
In fill_in 'Description', :with => '#This', each character is entered one by one, triggering an asynchronous request to AutoCompleteController at each step. The assertion assert page.has_text? "Bug ##{issue.id}: This issue has a <select> element" passes as soon as the "#" character is entered, completing the test. However, the remaining characters ("This") are still input, sending four more asynchronous requests to AutoCompleteController, which may interfere with the next test.
- Login test failure
While I haven’t conducted a detailed analysis, this likely occurs because the login session from the previous test is being restored. - StaleElementReferenceError
This happens because the asynchronous responses from the previous test’s AutoCompleteController requests modify the current test’s DOM.
To address this, I have attached a patch that resets the session for each test case in InlineAutocompleteTest. This ensures that asynchronous requests from the previous test are discarded, keeping the test environment clean.
Additionally, although not directly related to this issue, I have included a second patch to add missing assertions.
Updated by Katsuya HIDAKA about 1 month ago
After applying these patches, I confirmed that all tests, including system tests, pass.
https://github.com/hidakatsuya/redmine/actions/runs/13100707980
Updated by Go MAEDA about 1 month ago
- Category set to Code cleanup/refactoring
- Target version set to 5.1.7
Setting the target version to 5.1.7.
Updated by Massimo Rossello about 1 month ago
Since the problem may happen in multiple other tests, wouldn't it be a more generic solution to put a reset_session! directly into log_user ?
Updated by Katsuya HIDAKA about 1 month ago
Thank you for your comment.
Unfortunately, this problem cannot be solved by reset_session!. I will explain the reason in the following comment.
Updated by Katsuya HIDAKA about 1 month ago
- File 0001-v2-Fix-random-failures-in-InlineAutocompleteTest-due-to-interference-from-requests-in-the-previous-test.patch 0001-v2-Fix-random-failures-in-InlineAutocompleteTest-due-to-interference-from-requests-in-the-previous-test.patch added
I realized that the patch 0001 attached in #note-1 is not the best solution to this problem. I am attaching another patch (V2) with a different solution for 0001.
The original patch 0001 (referred to as V1) has two problems:
- It does not solve the StaleElementReferenceError.
Even if the 0001 (V1) patch is applied, a StaleElementReferenceError may still occur in InlineAutocompleteTest. - The test is incomplete.
As explained in #note-1, although "#This" is being entered, the test passes when the first "#" is entered. In other words, in the current test, the result is evaluated without waiting for the completion of all autocomplete request processing that occurs when "#This" is entered. I don't think this is an appropriate test.
In patch V2, I will modify the test code so that the assertion is performed after the completion of all autocomplete processing for the entered value. As a result, this problem can be solved by avoiding the execution of the next test while leaving requests in progress.
As will be clear in the next comment, Capybara should wait for the requests to complete, but it seems that it is not able to capture the completion of some requests, at least in the InlineAutocomplete test. This is the same even when the reset_sessions! method is explicitly used.
Updated by Katsuya HIDAKA about 1 month ago
To provide supporting evidence for the suspected cause described in #note-1 , I created a reproduction code (not 100%) for this problem and actually observed the previous test requests interfering with subsequent tests.
- Reproduction code
https://github.com/hidakatsuya/redmine/compare/master...hidakatsuya:redmine:login-test-failure#diff-072e3b90cde849d28013a0e307e27782804923873ef5658e6d7c05ae3c686d8b - Test results
https://github.com/hidakatsuya/redmine/actions/runs/13214702048/job/36898361906
The following is an excerpt and formatted version of the test result log.
test_1 result (enter "#abcdefghijkl"):
InlineAutocompleteSystemTest#test_1 = request: GET /my/page (HTTP_COOKIE=...) request: GET /login?back_url=http%3A%2F%2F127.0.0.1%3A44235%2Fmy%2Fpage (HTTP_COOKIE=...) request: POST /login (HTTP_COOKIE=...) (snip) request: GET /issues/auto_complete?project_id=ecookbook&q= (HTTP_COOKIE=_redmine_session=WU42TUpI...) request: GET /issues/auto_complete?project_id=ecookbook&q=a (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (1) ["/issues/auto_complete?project_id=ecookbook&q="] request: GET /issues/auto_complete?project_id=ecookbook&q=ab (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (2) ["/issues/auto_complete?project_id=ecookbook&q=", "/issues/auto_complete?project_id=ecookbook&q=a"] request: GET /issues/auto_complete?project_id=ecookbook&q=abc (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (3) ["/issues/auto_complete?project_id=ecookbook&q=", "/issues/auto_complete?project_id=ecookbook&q=a", "/issues/auto_complete?project_id=ecookbook&q=ab"] request: GET /issues/auto_complete?project_id=ecookbook&q=abcdef (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (3) ["/issues/auto_complete?project_id=ecookbook&q=a", "/issues/auto_complete?project_id=ecookbook&q=ab", "/issues/auto_complete?project_id=ecookbook&q=abc"] request: GET /issues/auto_complete?project_id=ecookbook&q=abcdefg (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (3) ["/issues/auto_complete?project_id=ecookbook&q=ab", "/issues/auto_complete?project_id=ecookbook&q=abc", "/issues/auto_complete?project_id=ecookbook&q=abcdef"] Capybara::Session#reset! called request: GET /issues/auto_complete?project_id=ecookbook&q=abcdefgh (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (3) ["/issues/auto_complete?project_id=ecookbook&q=ab", "/issues/auto_complete?project_id=ecookbook&q=abcdef", "/issues/auto_complete?project_id=ecookbook&q=abcdefg"] request: GET /issues/auto_complete?project_id=ecookbook&q=abcdefghi (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (3) ["/issues/auto_complete?project_id=ecookbook&q=abcdef", "/issues/auto_complete?project_id=ecookbook&q=abcdefg", "/issues/auto_complete?project_id=ecookbook&q=abcdefgh"] Capybara::Server#wait_for_pending_requests called request: GET /issues/auto_complete?project_id=ecookbook&q=abcdefghij (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (3) ["/issues/auto_complete?project_id=ecookbook&q=abcdefg", "/issues/auto_complete?project_id=ecookbook&q=abcdefgh", "/issues/auto_complete?project_id=ecookbook&q=abcdefghi"] request: GET /issues/auto_complete?project_id=ecookbook&q=abcdefghijk (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (3) ["/issues/auto_complete?project_id=ecookbook&q=abcdefgh", "/issues/auto_complete?project_id=ecookbook&q=abcdefghi", "/issues/auto_complete?project_id=ecookbook&q=abcdefghij"] request: GET /issues/auto_complete?project_id=ecookbook&q=abcdefghijkl (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (3) ["/issues/auto_complete?project_id=ecookbook&q=abcdefgh", "/issues/auto_complete?project_id=ecookbook&q=abcdefghij", "/issues/auto_complete?project_id=ecookbook&q=abcdefghijk"] pending_requests? = false
test_2 result:
InlineAutocompleteSystemTest#test_2 = ... request: GET /my/page (HTTP_COOKIE=_redmine_session=cGhWTktW...) request: GET /issues/auto_complete?project_id=ecookbook&q=abcde (HTTP_COOKIE=_redmine_session=WU42TUpI...) request: GET /issues/auto_complete?project_id=ecookbook&q=abcd (HTTP_COOKIE=_redmine_session=WU42TUpI...) pending_requests = (1) ["/issues/auto_complete?project_id=ecookbook&q=abcde"] ... Failure: InlineAutocompleteSystemTest#test_2 [test/application_system_test_case.rb:71]: Expected: "/login" Actual: "/my/page"
The following can be seen from the above results:
- Autocomplete requests are sent one character at a time.
- The process of waiting for Capybara's pending requests is executed: Capybara::Session#wait_for_pending_requests
- The requests from test_1 are processed in test_2, and the session value is the same as in test_1 (perhaps this is the cause of the login_user failure?).