Closed Bug 1810074 Opened 2 years ago Closed 2 years ago

console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.js", 334))

Categories

(Firefox :: Remote Settings Client, defect)

Product:
Firefox
Component:
Remote Settings Client
Platform:
x86_64
Linux
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1812040

People

(Reporter: ishikawa, Unassigned)

References

Details

Attachments

(1 file)

output from egrep -a "(Polling for changes failed|TEST_START|TEST_END)" /FF-NEW/log1520-mochitest.txt
3.28 KB, text/plain
Details

I am testing C-C TB locally under Debian GNU/Linux.
Since December 2022, I have noticed the errors of the following form, during my local testing.

07:57.83 GECKO(6141) console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.js", 334))

This is a relative newcomer. I have only observed it since December 2022. (not that I run mochitest often enough. Due to the long timeout during testing, I am discouraged to do so, and run it maybe once a month now.
Regarding long timeout there is a related entry, bug 1802401 comment 4.

Anyway, the "Polling for changes failed" comes from
the following line in C-C.
https://searchfox.org/comm-central/source/mozilla/services/settings/remote-settings.js#334

"Unexpected content-type" is thrown from the following line:
https://searchfox.org/comm-central/source/mozilla/services/settings/Utils.jsm#407

const ct = response.headers.get("Content-Type");
if (!is404FromCustomServer && (!ct || !ct.includes("application/json"))) {
throw new Error(Unexpected content-type "${ct}");

Comparing the code and the log suggests that whatever returns the header did not return "application/json" data, but "test/plain;charset=US-ASCII". This should be a clear enough hint.

I hope this information leads to the root cause and hopefully a solution.

I filed this for testing infrastructure because I suspect that the testing framework does not properly set the fake server data or something which C-C TB expects during testing.
If this is not the case, please feel free to change the component, etc.

I am attaching an excerpt from a local log where the errors were produced.
The output from the following command:
egrep -a "(Polling for changes failed|TEST_START|TEST_END)" /FF-NEW/log1520-mochitest.txt
"-a" was necessary since the log now spews out strange 8-bit characters which egrep under LC_ALL=C regards as binary data. So I tell egrep to regard the input as text file by using "-a".

I am a bit surprised that sometimes the error is recorded AFTER TEST_END and the next TEST_START is recorded.

Summary: onsole.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.js", 334)) → console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.js", 334))
See Also: → 1811110

Also observed in bug 1824808.

See Also: → 1824808

As noted in bug 1824808 also, this seems to trigger some hung state and thus we see TIMEOUT error eventually.
Very annoying during local testing since I am trying to extend the max timeout value to a large value accommodate valgrind testing for C-C TB testing.

Per bug 1824808 it's not TB specific, should we move this bug to somewhere else?

https://searchfox.org/mozilla-central/rev/a5da23c8c9c1151dcdf0ca34b3cfd0a4d0fc3b48/services/settings/Utils.sys.mjs#398

Component: Testing Infrastructure → Remote Settings Client
Product: Thunderbird → Firefox

I observe the following issues.
If I run C-C mochitest comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js locally with the DEBUG version of C-C TB create (under linux), we see this error re[prted jear after a test error is noticed
and this error is printed, and eventually, we get a timeout which is very annoying.

I printed the server URL from which this response is returned and found that the server seems to be fakeserver created for tests that require server.
And I think I know why it fails here sometimes.
The failure occurs when the server has no data to return as JSON data.
Instead of returning "{ }" a valid JSON which I think would work here,
the fake server returns no data at all. That is no data part in the response.
This seems to cause the fake server to return text/plain;charset=US-ASCII without any data at all.
I think we should make this fake server to return " { } " (I inserted a space for readability between { and } by the way.)
and use json as return data type. (Or simply accpet text/plain; charset=US-ASCII as valid because the json parser reads through the text data anyway.).
Someone in the know ought to take a look at the fakeserver code when it is used in the test context.

I modified the source code in Utils.sys.jsm to ignore the change of data type and print the data as string, but then
JSON reader aborted immediately because it saw EOF at the initial position. Thus, I conclude there was no data at all in this situation.

From the longer excerpt below, I think this part shows the crux of the issue.

00:12.66 INFO Sending free/busy response for mailto:mochitest@example.com
00:33.54 GECKO(34649) [WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
00:33.55 GECKO(34649) console.error: "Server setup for the following error."
00:33.55 GECKO(34649) console.error: "lazy.Utils.SERVER_URL: data:,#remote-settings-dummy/v1" 
00:33.55 GECKO(34649) console.error: (new Error("Polling for changes failed: Server error data:,#remote-settings-dummy/v1/buckets/monitor/collections/changes/changeset?_expected=0 200 OK: \"JSON.parse: unexpected end of data at line 1 column 1 of the JSON data\".", "resource://services-settings/remote-settings.sys.mjs", 326))
  1. From the strange URL "data:,#remote-settings-dummy/v1", I immediately see that this is observed with a fakeserver for testing.
  2. Server response was 200 meaning it returns data successfully.
    "data:,#remote-settings-dummy/v1/buckets/monitor/collections/changes/changeset?_expected=0 200 "
    I wonder what this "?_expected=0" is doing here. Maybe it instructs the fakeserver not to return any data as part of the test?
  3. When I changed code so that the data is parsed anyway ignoring the data type (I think it IS the octet stream the json parser was looking at.), the json reader fails immediately because it saw the EOF at the beginning.
    "JSON.parse: unexpected end of data at line 1 column 1 of the JSON data".

Either the server is buggy or the code to handle this situation in Utils.sys.jsm is buggy and not ready to handle this situation or both.
Or maybe the test driver to set up the fakeserver for this test is not quite correct.

The following is how I modified the code to dump the above.

# HG changeset patch
# User ISHIKAWA, Chiaki <ishikawa@yk.rim.or.jp>
# Parent  73e8c68b58cb68e665b4a8051b290ef95bdece2e
To debug json vs text return type

diff --git a/services/settings/Utils.sys.mjs b/services/settings/Utils.sys.mjs
--- a/services/settings/Utils.sys.mjs
+++ b/services/settings/Utils.sys.mjs
@@ -389,21 +389,25 @@ export var Utils = {
     if (response.status >= 500) {
       throw new Error(`Server error ${response.status} ${response.statusText}`);
     }
 
     const is404FromCustomServer =
       response.status == 404 &&
       Services.prefs.prefHasUserValue("services.settings.server");
 
-    const ct = response.headers.get("Content-Type");
-    if (!is404FromCustomServer && (!ct || !ct.includes("application/json"))) {
-      throw new Error(`Unexpected content-type "${ct}"`);
+    if (is404FromCustomServer) {
+      throw new Error(`response was 404: ` +  Services.prefs.prefHasUserValue("services.settings.server"));
     }
 
+    // const ct = response.headers.get("Content-Type");  I basically ignored the type check.
+    // if (!ct || !ct.includes("application/json")) {
+    //  throw new Error(`Unexpected content-type "${ct}"`);
+    // }
+
     let payload;
     try {
       payload = await response.json();  // This is where the error from json parser was thrown.
     } catch (e) {
       payload = e.message;
     }
 
     if (!payload.hasOwnProperty("changes")) {
diff --git a/services/settings/remote-settings.sys.mjs b/services/settings/remote-settings.sys.mjs
--- a/services/settings/remote-settings.sys.mjs
+++ b/services/settings/remote-settings.sys.mjs
@@ -316,16 +316,18 @@ function remoteSettingsFunction() {
         reportStatus = lazy.UptakeTelemetry.STATUS.UNKNOWN_ERROR;
       }
       await lazy.UptakeTelemetry.report(
         TELEMETRY_COMPONENT,
         reportStatus,
         pollTelemetryArgs
       );
       // No need to go further.
+      console.error('Server setup for the following error.');
+      console.error('lazy.Utils.SERVER_URL: ' + lazy.Utils.SERVER_URL);
       throw new Error(`Polling for changes failed: ${e.message}.`);
     }
 
     const {
       serverTimeMillis,
       changes,
       currentEtag,
       backoffSeconds,

Longer log excerpt from the run of mochitest comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js

...
00:12.47 PASS 1 == 1 - 
00:12.47 PASS 0 == 0 - 
00:12.47 INFO Sending free/busy response for mailto:mochitest@example.com
00:12.50 FAIL 1 == 0 - {"filename":"chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js","name":"checkFreeBusy","sourceId":648,"lineNumber":99,"columnNumber":12,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js","name":null,"sourceId":648,"lineNumber":129,"columnNumber":11,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":603,"lineNumber":1131,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":603,"lineNumber":1203,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":603,"lineNumber":1345,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":603,"lineNumber":1120,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":630,"lineNumber":1056,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:129:11\nasync*handleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"checkFreeBusy@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:99:12\nasync*@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:129:11\nasync*handleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}}
Stack trace:
chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:checkFreeBusy:99
chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:null:129
chrome://mochikit/content/browser-test.js:handleTask:1131
chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1203
chrome://mochikit/content/browser-test.js:Tester_execTest:1345
chrome://mochikit/content/browser-test.js:nextTest/<:1120
chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1056
00:12.50 PASS 5 == 5 - 
00:12.62 GECKO(34649) [Parent 34649, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/generic/nsFrameSelection.cpp:1711
00:12.65 GECKO(34649) [Parent 34649, Main Thread] WARNING: NS_ENSURE_TRUE(parentPresShell) failed: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/PresShell.cpp:6685
00:12.66 PASS attendees list matches what was expected - ["mochitest@example.com","test@example.com",""] deepEqual ["mochitest@example.com","test@example.com",""] - 
00:12.66 PASS empty attendee input should have focus - [object HTMLInputElement] == [object HTMLInputElement] - 
00:12.66 PASS 1 == 1 - 
00:12.66 PASS 0 == 0 - 
00:12.66 INFO Sending free/busy response for mailto:mochitest@example.com
00:33.54 GECKO(34649) [WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
00:33.55 GECKO(34649) console.error: "Server setup for the following error."
00:33.55 GECKO(34649) console.error: "lazy.Utils.SERVER_URL: data:,#remote-settings-dummy/v1"
00:33.55 GECKO(34649) console.error: (new Error("Polling for changes failed: Server error data:,#remote-settings-dummy/v1/buckets/monitor/collections/changes/changeset?_expected=0 200 OK: \"JSON.parse: unexpected end of data at line 1 column 1 of the JSON data\".", "resource://services-settings/remote-settings.sys.mjs", 326))
00:34.04 GECKO(34649) NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7fc1dc002f38
00:37.66 GECKO(34649) NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7fc1600156e8
_read(): after the while now 1687373681.4026525
_read(): after the while timed_out True
_read(): after the while timeout= 1687373681.3826582
_read(): after the while output_timeout= 1687376116.1952815
_read(): Timeout occurred, but should ignored for valgrind run?
_read(): stdout_reader= <Thread(ProcessReaderStdout-/NEW-SSD/moz-obj-dir/objdir-tb3/dist/bin/thunderbird, started daemon 139887400318656)>, stderr_reader=None
calling timeoutHandler(): timeout=  3700.0
calling timeoutHandler(): proc=  <mozprocess.processhandler.ProcessHandlerMixin object at 0x7f3a36d12cd0>
calling timeoutHandler(): utilityPath=  /NEW-SSD/moz-obj-dir/objdir-tb3/dist/bin
calling timeoutHandler(): debuggerInfo=  None
calling timeoutHandler(): browserProcessId=  None
calling timeoutHandler(): processLog=  /COMM-CENTRAL/TMP-DIR/tmp08e6a50gpidlog
  File "/usr/lib/python3.11/threading.py", line 995, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.11/threading.py", line 1038, in _bootstrap_inner
    self.run()

I think the long timeout I experience is related to "Sending free/busy response for mailto:mochitest@example.com".
But first thing first.
I want this bugzillla resolved first.

I believe the nature of the problem has become much clearer now.

There once was a deadlock issue reported before this was observed.
See bug 1811110. But it has not been observed since, and so that could be a red herring.
(I was asked if THAT bug could be closed and am going to say yes. We would have seen the same error, THIS bugzilla is so frequent and tied to that deadlock issue. But we have not seen it.

I thought I posted something like this before. Obviously, I failed to hit the submit button.

(In reply to ISHIKAWA, Chiaki from comment #9)

I observe the following issues.
... omission ...
I think the long timeout I experience is related to "Sending free/busy response for mailto:mochitest@example.com".
But first thing first.
I want this bugzillla resolved first.

I believe the nature of the problem has become much clearer now.

My idea for fix.

Whatever the lower data handling mechanism used by the fakeserver, under the condition of "no data" (0-length data) to return, seems to fall back on ""text/plain;charset=US-ASCII" as data type. That is not incorrect strictly speaking since there is no data at all.
However, this throws off codes that rely on receiving json data.

The fakeserver or whatever should return

{
}

instead of returning code 200 and does not serve anything (basically 0-length data)
when the fakeserver wanted to return something to signal no JSON data exists.

Or json data parser, the receiving side, needs to be modified to handle the situation.
(We have to handle the no data (0-length data) case specially.

Now why there is a situation to serve no data (0-length data) is another issue. It could well be related to real bugs.

I think the signature may have changed slightly? I'm seeing the log spam look like:

 0:05.25 GECKO(2665078) 1698195660130   Marionette      DEBUG   1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]                                                                                  
 0:05.26 GECKO(2665078) 1698195660135   Marionette      DEBUG   Waiting for initial application window                                                                                                                
 0:05.66 GECKO(2665078) console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))                                                      
 0:05.66 GECKO(2665078) [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt                                                                                                                       
 0:05.67 GECKO(2665078) console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))                                                      
 0:05.67 GECKO(2665078) console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))                                                      
 0:05.75 GECKO(2665078) console.error: ({})                                                                                                                                                                           
 0:06.51 GECKO(2665078) console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))                                                      
 0:06.51 GECKO(2665078) console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))                                                      
 0:06.51 GECKO(2665078) console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))                                                      
 0:06.51 GECKO(2665078) console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))                                                      
 0:06.51 GECKO(2665078) console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
Duplicate of this bug: 1863136
Duplicate of this bug: 1861311

Perhaps at least logging the URL here together may allow actual debugging?

Duplicate of this bug: 1841738
Duplicate of this bug: 1837341
Duplicate of this bug: 1844942
Duplicate of this bug: 1851046
Duplicate of this bug: 1860201
Duplicate of this bug: 1863231
Duplicate of this bug: 1863198

Duping forward to bug 1812040, as that has more technical information and explorations from the team about the issues.

Status: NEW → RESOLVED
Closed: 2 years ago
Duplicate of bug: 1812040
Flags: needinfo?(mathieu)
Resolution: --- → DUPLICATE
No longer duplicate of this bug: 1863136
No longer duplicate of this bug: 1861311
No longer duplicate of this bug: 1841738
No longer duplicate of this bug: 1837341
No longer duplicate of this bug: 1844942
No longer duplicate of this bug: 1851046
No longer duplicate of this bug: 1860201
No longer duplicate of this bug: 1863231
No longer duplicate of this bug: 1863198

(In reply to Mark Banner (:standard8) from comment #27)

Duping forward to bug 1812040, as that has more technical information and explorations from the team about the issues.

*** This bug has been marked as a duplicate of bug 1812040 ***

Thank you for taking care of this strange issue.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: