search

mozilla / geckodriver

WebDriver for Firefox
https://firefox-source-docs.mozilla.org/testing/geckodriver/
Mozilla Public License 2.0
7.03k stars 1.51k forks source link

JSP cache control settings are ignored #2119

Closed NikaidoKota closed 11 months ago

NikaidoKota commented 1 year ago

System

Testcase

We use Selenide for multi-browser E2E testing, but we are experiencing problems in Firefox testing that do not occur in Chrome or Edge. When accessing a web page with 'Cache-Control: no-store' set in the header in the Firefox browser launched from Geckodriver, this setting does not seem to work and the exact same content is displayed on repeated visits. (content is out of date but not reloaded). When a test is performed by specifying a Firefox or Edge webdriver for this screen, the cache control appears to be correct, the cache is not used and new content is loaded each time. Also, when Firefox is started manually without Webdriver and access to the same web page is checked, the cache is not used and new content is loaded each time. Therefore, this problem only occurs in tests with Geckodriver and we would like to test the same behaviour with other browsers. Note that no specific errors have been detected when running this test.

whimboo commented 1 year ago

Could you please attach a trace-level log from geckodriver? Also some code snippet would be very welcome. Read more about reporting actionable bugs in our contribution guidelines.

NikaidoKota commented 1 year ago

Sorry for the delay in responding.

After raising the log level and checking the results, the following was written to the log file.

1686212808346   geckodriver INFO    Listening on 127.0.0.1:8196
1686212808899   mozrunner::runner   INFO    Running command: "C:\\Program Files\\Mozilla Firefox\\firefox.exe" "--marionette" "-no-remote" "-profile" "C:\\Users\\XXXXXX~1\\AppData\\Local\\Temp\\rust_mozprofileryIh7c"
console.warn: services.settings: Ignoring preference override of remote settings server
console.warn: services.settings: Allow by setting MOZ_REMOTE_SETTINGS_DEVTOOLS=1 in the environment
1686212809139   Marionette  INFO    Marionette enabled
Dynamically enable window occlusion 0
1686212809142   Marionette  INFO    Listening on port 51738
Read port: 51738
1686212809305   RemoteAgent WARN    TLS certificate errors will be ignored for this session
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\XXXXXX~1\\AppData\\Local\\Temp\\rust_mozprofileryIh7c\\search.json.mozlz4", (void 0)))
console.error: Region.sys.mjs: "Error fetching region" (new Error("TIMEOUT", "resource://gre/modules/Region.sys.mjs", 764))
console.error: Region.sys.mjs: "Failed to fetch region" (new Error("TIMEOUT", "resource://gre/modules/Region.sys.mjs", 416))
JavaScript error: http://localhost:8888/p/memberRegisterKzk/RW13M1040101?p01=00221&ssc=1234567890, line 517: ReferenceError: _satellite is not defined
console.error: ({})
console.warn: LoginRecipes: "Falling back to a synchronous message for: http://localhost:8888."
JavaScript error: http://localhost:8888/p/memberRegisterKzk/RW13M1040201;jsessionid=1aa7g67svvxnd1sd7u43vf5xmr, line 665: ReferenceError: _satellite is not defined
console.error: ({})
console.warn: LoginRecipes: "Falling back to a synchronous message for: http://localhost:8888."
JavaScript error: http://localhost:8888/p/memberRegisterKzk/RW13M1040301, line 418: ReferenceError: _satellite is not defined
console.error: ({})
console.error: (new TypeError("NetworkError: Network request failed", "resource://services-settings/Utils.jsm", 237))
JavaScript error: http://localhost:8888/p/memberRegisterKzk/RW13M1040101?p01=00221&ssc=1234567890, line 517: ReferenceError: _satellite is not defined
console.error: ({})
console.error: ({})
console.error: ({})
1686212842545   Marionette  INFO    Stopped listening on port 51738
Dynamically enable window occlusion 1
console.error: (new TypeError("NetworkError: Network request failed", "resource://services-settings/Utils.jsm", 237))
WARNING: A blocker encountered an error while we were waiting.
          Blocker:  Waiting for ping task
          Phase: TelemetryController: Waiting for pending ping activity
          State: (none)
WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.sys.mjs:10:28
_checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16

console.error: "TelemetryScheduler.shutdown - Already shut down"
WARNING: A blocker encountered an error while we were waiting.
          Blocker:  Waiting for ping task
          Phase: TelemetryController: Waiting for pending ping activity
          State: (none)
WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.sys.mjs:10:28
_checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16

WARNING: A blocker encountered an error while we were waiting.
          Blocker:  Waiting for ping task
          Phase: TelemetryController: Waiting for pending ping activity
          State: (none)
WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.sys.mjs:10:28
_checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16

WARNING: A blocker encountered an error while we were waiting.
          Blocker:  TelemetryController: shutting down
          Phase: profile-before-change-telemetry
          State: Error getting state: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange" at addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.sys.mjs:10:28
_checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16

WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
@resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
@resource://gre/modules/osfile.jsm:12:30
@resource://gre/modules/TelemetryStorage.sys.mjs:10:28
_checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16

JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[0x7FFA1932E0A4] ANOMALY: use of REX.w is meaningless (default operand size is 64)
[0x7FFA1932E0A4] ANOMALY: use of REX.w is meaningless (default operand size is 64)

However, almost the same log seems to be output when accessing pages where no problems occur.

As for the sample source code, since it contains confidential business information, we are considering whether a simplified sample can be created. We will add a note when this is possible.

whimboo commented 1 year ago

Hm, nothing in the log actually shows details about a navigation request. So it's not helpful for analysis. If you could come up with an example page that would be great. Does it work when you do the steps manually outside of automation?

Also I can see some JavaScript errors on the page all around ReferenceError: _satellite is not defined. But that's probably not related.

NikaidoKota commented 1 year ago

Does it work when you do the steps manually outside of automation?

Yes, it works well for non-automated access. No cache is used for access by Geckodriver. The page under verification is passed a value by submitting the value entered on the previous page. We receive this value and display it on this page as a submit result.

For example, if we manually launch and access Firefox and try to access the page being validated again by 'Reload' or 'Back' to a page with 'Cache-Control: no-store' set, access to the page being validated will fail and we will be directed to a 'Document is valid Expired' error page. In this E2E test, we want to check the transition to this error page using the 'Back' transition, but this does not work because the same content as the original screen is only displayed when using Geckodriver.

whimboo commented 1 year ago

@NikaidoKota could you please check if the page is maybe delivered from the BFCache when geckodriver is used?

You can do that by adding event listeners for pagehide and pageshow. Then check the persisted property of the event target. Also try to set Cache-Control: "no-cache, no-store, must-revalidate" which should basically disable bfcache completely.

NikaidoKota commented 1 year ago

The target page transitions were checked. This confirmed that BFcache was being used during page transitions. Also, the Cache-Control: "no-cache, no-store, must-revalidate" setting on the target page did not seem to work, and the setting not to use the BFcache was not effective. This is only the case with Geckodriver, as other browsers and webdrivers do not have this problem.

whimboo commented 1 year ago

Could you maybe provide a trace log with the relevant parts included so that it may be clearer what's wrong? If not I have to say that I really need a test case for that scenario.

whimboo commented 1 year ago

Oh, do you actually set no-store as HTTP header or via meta? Disabling bfcache will only work with the former.

NikaidoKota commented 1 year ago

Oh, do you actually set no-store as HTTP header or via meta? Disabling bfcache will only work with the former.

no-store in meta-tag. When Firefox was run manually, BFCache was controlled by this meta-tag setting. BFCache was never used. Does the fact that BFCache is not controlled by meta mean that it is a specification when using Geckodriver?

whimboo commented 1 year ago

There is nothing in Firefox which let no-store in a meta tag control the BFcache behavior. It might be better if a minimized testcase could be created so that we can check ourselves. Thanks.

whimboo commented 11 months ago

No further reply from reporter and no chance for us to reproduce. Closing as incomplete.