1774462 - Hit MOZ_CRASH(OOM) [@ mozilla::dom::indexedDB::Key::EncodeBinary]

Status: VERIFIED FIXED

(Core :: Storage: IndexedDB, defect, P3)

Description

[Jason Kratzer [:jkratzer]]

Testcase found while fuzzing mozilla-central rev b1ed2fa50612 (built with: --enable-debug --enable-fuzzing).

Testcase can be reproduced using the following commands:

$ pip install fuzzfetch grizzly-framework
$ python -m fuzzfetch --build b1ed2fa50612 --debug --fuzzing -n firefox
$ python -m grizzly.replay ./firefox/firefox testcase.html

Hit MOZ_CRASH(OOM) at /xpcom/base/nsDebugImpl.cpp:678

    ==170649==ERROR: UndefinedBehaviorSanitizer: SEGV on unknown address 0x000000000000 (pc 0x7ffb5a7d1ddb bp 0x7ffc61097cf0 sp 0x7ffc61097cf0 T170649)
    ==170649==The signal is caused by a WRITE memory access.
    ==170649==Hint: address points to the zero page.
        #0 0x7ffb5a7d1ddb in NS_ABORT_OOM(unsigned long) /xpcom/base/nsDebugImpl.cpp:678:3
        #1 0x7ffb5ed3163d in AllocFailed /builds/worker/workspace/obj-build/dist/include/nsTSubstring.h:1189:5
        #2 0x7ffb5ed3163d in GetMutableData /builds/worker/workspace/obj-build/dist/include/nsTSubstring.h:1021:7
        #3 0x7ffb5ed3163d in mozilla::Result<mozilla::Ok, nsresult> mozilla::dom::indexedDB::Key::EncodeAsString<unsigned char>(mozilla::Span<unsigned char const, 18446744073709551615ul>, unsigned char) /dom/indexedDB/Key.cpp:605:16
        #4 0x7ffb5ed2fde4 in mozilla::dom::indexedDB::Key::EncodeBinary(JSObject*, bool, unsigned char) /dom/indexedDB/Key.cpp:841:10
        #5 0x7ffb5ed2f53f in mozilla::dom::indexedDB::Key::EncodeJSValInternal(JSContext*, JS::Handle<JS::Value>, unsigned char, unsigned short) /dom/indexedDB/Key.cpp:439:14
        #6 0x7ffb5ed31cd0 in EncodeJSVal /dom/indexedDB/Key.cpp:544:10
        #7 0x7ffb5ed31cd0 in mozilla::dom::indexedDB::Key::SetFromJSVal(JSContext*, JS::Handle<JS::Value>) /dom/indexedDB/Key.cpp:897:17
        #8 0x7ffb5ed6f84e in mozilla::dom::IDBFactory::Cmp(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, mozilla::ErrorResult&) /dom/indexedDB/IDBFactory.cpp:445:23
        #9 0x7ffb5c7faa28 in mozilla::dom::IDBFactory_Binding::cmp(JSContext*, JS::Handle<JSObject*>, void*, JSJitMethodCallArgs const&) /builds/worker/workspace/obj-build/dom/bindings/IDBFactoryBinding.cpp:346:39
        #10 0x7ffb5d8ac3ac in bool mozilla::dom::binding_detail::GenericMethod<mozilla::dom::binding_detail::NormalThisPolicy, mozilla::dom::binding_detail::ThrowExceptions>(JSContext*, unsigned int, JS::Value*) /dom/bindings/BindingUtils.cpp:3272:13
        #11 0x7ffb62d42750 in CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) /js/src/vm/Interpreter.cpp:421:13
        #12 0x7ffb62d41f5a in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /js/src/vm/Interpreter.cpp:508:12
        #13 0x7ffb62d39376 in CallFromStack /js/src/vm/Interpreter.cpp:579:10
        #14 0x7ffb62d39376 in Interpret(JSContext*, js::RunState&) /js/src/vm/Interpreter.cpp:3325:16
        #15 0x7ffb62d30532 in js::RunScript(JSContext*, js::RunState&) /js/src/vm/Interpreter.cpp:390:13
        #16 0x7ffb62d41e56 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /js/src/vm/Interpreter.cpp:540:13
        #17 0x7ffb62d43488 in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) /js/src/vm/Interpreter.cpp:606:8
        #18 0x7ffb619f9ec1 in JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) /js/src/vm/CallAndConstruct.cpp:117:10
        #19 0x7ffb5d667600 in mozilla::dom::Function::Call(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, nsTArray<JS::Value> const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) /builds/worker/workspace/obj-build/dom/bindings/FunctionBinding.cpp:50:8
        #20 0x7ffb5c427b02 in void mozilla::dom::Function::Call<nsCOMPtr<nsIGlobalObject> >(nsCOMPtr<nsIGlobalObject> const&, nsTArray<JS::Value> const&, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JS::Realm*) /builds/worker/workspace/obj-build/dist/include/mozilla/dom/FunctionBinding.h:71:12
        #21 0x7ffb5c4278a4 in mozilla::dom::CallbackTimeoutHandler::Call(char const*) /dom/base/TimeoutHandler.cpp:167:29
        #22 0x7ffb5c1042c2 in nsGlobalWindowInner::RunTimeoutHandler(mozilla::dom::Timeout*, nsIScriptContext*) /dom/base/nsGlobalWindowInner.cpp:6411:38
        #23 0x7ffb5c4396ea in mozilla::dom::TimeoutManager::RunTimeout(mozilla::TimeStamp const&, mozilla::TimeStamp const&, bool) /dom/base/TimeoutManager.cpp:903:44
        #24 0x7ffb5c425400 in mozilla::dom::TimeoutExecutor::MaybeExecute() /dom/base/TimeoutExecutor.cpp:179:11
        #25 0x7ffb5c4259a9 in Notify /dom/base/TimeoutExecutor.cpp:246:5
        #26 0x7ffb5c4259a9 in non-virtual thunk to mozilla::dom::TimeoutExecutor::Notify(nsITimer*) /dom/base/TimeoutExecutor.cpp
        #27 0x7ffb5a92b40c in operator() /xpcom/threads/nsTimerImpl.cpp:656:44
        #28 0x7ffb5a92b40c in matchN<mozilla::Variant<nsTimerImpl::UnknownCallback, nsCOMPtr<nsITimerCallback>, nsCOMPtr<nsIObserver>, nsTimerImpl::FuncCallback, nsTimerImpl::ClosureCallback> &, (lambda at /xpcom/threads/nsTimerImpl.cpp:656:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:657:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:660:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:661:7)> /builds/worker/workspace/obj-build/dist/include/mozilla/Variant.h:309:16
        #29 0x7ffb5a92b40c in matchN<mozilla::Variant<nsTimerImpl::UnknownCallback, nsCOMPtr<nsITimerCallback>, nsCOMPtr<nsIObserver>, nsTimerImpl::FuncCallback, nsTimerImpl::ClosureCallback> &, (lambda at /xpcom/threads/nsTimerImpl.cpp:655:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:656:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:657:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:660:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:661:7)> /builds/worker/workspace/obj-build/dist/include/mozilla/Variant.h:318:14
        #30 0x7ffb5a92b40c in matchN<mozilla::Variant<nsTimerImpl::UnknownCallback, nsCOMPtr<nsITimerCallback>, nsCOMPtr<nsIObserver>, nsTimerImpl::FuncCallback, nsTimerImpl::ClosureCallback> &, (lambda at /xpcom/threads/nsTimerImpl.cpp:655:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:656:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:657:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:660:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:661:7)> /builds/worker/workspace/obj-build/dist/include/mozilla/Variant.h:902:12
        #31 0x7ffb5a92b40c in match<(lambda at /xpcom/threads/nsTimerImpl.cpp:655:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:656:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:657:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:660:7), (lambda at /xpcom/threads/nsTimerImpl.cpp:661:7)> /builds/worker/workspace/obj-build/dist/include/mozilla/Variant.h:857:12
        #32 0x7ffb5a92b40c in nsTimerImpl::Fire(int) /xpcom/threads/nsTimerImpl.cpp:654:22
        #33 0x7ffb5a8fcc7e in nsTimerEvent::Run() /xpcom/threads/TimerThread.cpp:263:11
        #34 0x7ffb5a91bead in mozilla::ThrottledEventQueue::Inner::ExecuteRunnable() /xpcom/threads/ThrottledEventQueue.cpp:254:22
        #35 0x7ffb5a918791 in mozilla::ThrottledEventQueue::Inner::Executor::Run() /xpcom/threads/ThrottledEventQueue.cpp:81:15
        #36 0x7ffb5a9197ee in mozilla::RunnableTask::Run() /xpcom/threads/TaskController.cpp:475:16
        #37 0x7ffb5a8f41c3 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /xpcom/threads/TaskController.cpp:788:26
        #38 0x7ffb5a8f2d73 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /xpcom/threads/TaskController.cpp:620:15
        #39 0x7ffb5a8f2fe3 in mozilla::TaskController::ProcessPendingMTTask(bool) /xpcom/threads/TaskController.cpp:398:36
        #40 0x7ffb5a91cfe9 in operator() /xpcom/threads/TaskController.cpp:127:37
        #41 0x7ffb5a91cfe9 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_1>::Run() /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:531:5
        #42 0x7ffb5a908a4f in nsThread::ProcessNextEvent(bool, bool*) /xpcom/threads/nsThread.cpp:1180:16
        #43 0x7ffb5a90f04d in NS_ProcessNextEvent(nsIThread*, bool) /xpcom/threads/nsThreadUtils.cpp:465:10
        #44 0x7ffb5b4d9404 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /ipc/glue/MessagePump.cpp:107:5
        #45 0x7ffb5b400637 in MessageLoop::RunInternal() /ipc/chromium/src/base/message_loop.cc:380:10
        #46 0x7ffb5b400542 in RunHandler /ipc/chromium/src/base/message_loop.cc:373:3
        #47 0x7ffb5b400542 in MessageLoop::Run() /ipc/chromium/src/base/message_loop.cc:355:3
        #48 0x7ffb5f644f38 in nsBaseAppShell::Run() /widget/nsBaseAppShell.cpp:150:27
        #49 0x7ffb61773d3b in XRE_RunAppShell() /toolkit/xre/nsEmbedFunctions.cpp:875:20
        #50 0x7ffb5b4da34a in mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /ipc/glue/MessagePump.cpp:235:9
        #51 0x7ffb5b400637 in MessageLoop::RunInternal() /ipc/chromium/src/base/message_loop.cc:380:10
        #52 0x7ffb5b400542 in RunHandler /ipc/chromium/src/base/message_loop.cc:373:3
        #53 0x7ffb5b400542 in MessageLoop::Run() /ipc/chromium/src/base/message_loop.cc:355:3
        #54 0x7ffb6177335c in XRE_InitChildProcess(int, char**, XREChildData const*) /toolkit/xre/nsEmbedFunctions.cpp:734:34
        #55 0x5595dc943f70 in content_process_main /browser/app/../../ipc/contentproc/plugin-container.cpp:57:28
        #56 0x5595dc943f70 in main /browser/app/nsBrowserApp.cpp:338:18
        #57 0x7ffb70ed4082 in __libc_start_main /build/glibc-SzIz7B/glibc-2.31/csu/../csu/libc-start.c:308:16
        #58 0x5595dc919d1c in _start (/home/jkratzer/builds/mc-debug/firefox-bin+0x15d1c) (BuildId: b2d1bcdab58cde437345acb5b623f21a6c1d4685)
    
    UndefinedBehaviorSanitizer can not provide additional info.
    SUMMARY: UndefinedBehaviorSanitizer: SEGV /xpcom/base/nsDebugImpl.cpp:678:3 in NS_ABORT_OOM(unsigned long)
    ==170649==ABORTING

Comment 1

[Jason Kratzer [:jkratzer]]

Attachment: Testcase

Comment 2

[Bugmon [:jkratzer for issues]]

Bugmon Analysis
Verified bug as reproducible on mozilla-central 20220615214908-0e44540919cd.
Unable to bisect testcase (Testcase reproduces on start build!):

Start: b7d44f6d500311bc4f0f889dbd924f790368ca5b (20210617042731)
End: b1ed2fa50612451f8f39fc84c5f64af62cf7fe3a (20220615093700)
BuildFlags: BuildFlags(asan=False, tsan=False, debug=True, fuzzing=True, coverage=False, valgrind=False, no_opt=False, fuzzilli=False, nyx=False)

Comment 3

[Jens Stutte [:jstutte]]

Not sure if we could do much here. We OOM on nsCString.GetMutable. IIUC the testcase wants to indexedDB.cmp two keys based on a 2GB array.

It is not 100% clear to me if the OOM is just random (in the sense of low total memory of the machine) or if we hit a hard boundary somewhere inside our string libraries (I'd assume a 2G long String would be a reasonable limit).

In any case I think we would fail to effectively use such long keys to store something anyways (due to IPC message size limits and such), so we might want to have some reasonable "this value can be safely used as a key" check everywhere we can receive values meant to be keys?

Comment 4

[Jens Stutte [:jstutte]]

So IIUC bug 1371484 introduced a check UINT32_MAX - 2 < uintptr_t(aInput.Length()). Instead the nsCString maximum has been recently limited by int32_t, it seems. We should probably align our check also here.

Still this limit feels somewhat gigantic for keys, but from a short read I cannot find any hint in the spec about maximum key lengths, so we should probably do our best here. Note that in this specific cmp case nothing is sent via IPC, I assume, so it would probably even work.

Comment 5

[Jens Stutte [:jstutte]]

Attachment: Bug 1774462 - Limit maximum key length to INT32_MAX. r?#dom-storage-reviewers

Comment 6

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1741665

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1424e1ec0927
Limit maximum key length to INT32_MAX. r=dom-storage-reviewers,jesup

Comment 8

[Marian-Vasile Laza]

Backed out changeset 1424e1ec0927 (Bug 1774462) for causing bustages on Key.obj.
Backout link
Push with failures <--> B
Failure Log
Also X1 Failure Log

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/01cef4e1c0f0
Limit maximum key length to INT32_MAX. r=dom-storage-reviewers,jesup

Comment 10

[Marian-Vasile Laza]

Backed out changeset 01cef4e1c0f0 (Bug 1774462) for causing xpcshell failures on test_keys.js.
Backout link
Push with failures <--> X2
Failure Log

Comment 11

[Jens Stutte [:jstutte]]

(In reply to Marian-Vasile Laza from comment #10)

Backed out changeset 01cef4e1c0f0 (Bug 1774462) for causing xpcshell failures on test_keys.js.
Backout link
Push with failures <--> X2
Failure Log

Interesting. We run the same test once as mochitest via dom/indexedDB/test/test_keys.html and once as xpcshell-test dom/indexedDB/test/unit/test_keys.js. The first succeeds, the second fails with a weird python encoding error. And it fails also locally under linux.

Comment 12

[Jens Stutte [:jstutte]]

Uhm, the same test is also failing on central for me (without my patch). This looks like some regression in our test harness?

Comment 13

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #12)

Uhm, the same test is also failing on central for me (without my patch). This looks like some regression in our test harness?

Check in treeherder on central: https://treeherder.mozilla.org/jobs?repo=try&revision=5e24dd4b2695a9c02bfc2992530af9cdc201d31b seems to work instead. All very weird.

Comment 14

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #13)

(In reply to Jens Stutte [:jstutte] from comment #12)

Uhm, the same test is also failing on central for me (without my patch). This looks like some regression in our test harness?

Check in treeherder on central: https://treeherder.mozilla.org/jobs?repo=try&revision=5e24dd4b2695a9c02bfc2992530af9cdc201d31b seems to work instead. All very weird.

Now it is getting even weirder. I ran a system update on my arch machine during the weekend, and coming back today now the test passes. The failures came from runxpcshelltests.py, it seems we receive a \0x80 char and are unable to transform it inside python. I can only assume that something inside our python test harness is/was broken?

Sorry for the noise, my bad (I disabled the problematic test output)

Comment 15

[Jens Stutte [:jstutte]]

So the test definitely tries to write out characters to the log that are beyond normal ASCII codes (and this was also the case before my changes). It seems, that depending on our python and logging environment this might or might not cause problems. I attach a patch here that tries to suppress the problem at log-line level, but I have the gut feeling we should do something already in the test to avoid those characters.

Asking Henri for advice as you know much about encodings.

Comment 16

[Jens Stutte [:jstutte]]

Attachment: Bug 1774462 - Suppress surrogate characters in log lines if we use six.PY3. r?davehunt

Comment 17

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #15)

Asking Henri for advice as you know much about encodings.

For example I am wondering if there should be a better place to do the right thing already when writing JS strings to stdout ?

Comment 18

[Henri Sivonen (:hsivonen)]

I'll try to figure out what output path we take for xpcshell-test. The failure is on Windows, so we may have a case where we encode output according to the Windows legacy code page while Python still expects UTF-8 like elsewhere.

Comment 19

[Henri Sivonen (:hsivonen)]

https://searchfox.org/mozilla-central/source/ipc/testshell/XPCShellEnvironment.cpp uses JS_EncodeStringToLatin1. Unless there is some context where we deliberately use print/dump from there to output binary data, switching to JS_EncodeStringToUTF8 should help.

Comment 20

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #19)

https://searchfox.org/mozilla-central/source/ipc/testshell/XPCShellEnvironment.cpp uses JS_EncodeStringToLatin1. Unless there is some context where we deliberately use print/dump from there to output binary data, switching to JS_EncodeStringToUTF8 should help.

Bug 1794401.

Comment 21

[Jens Stutte [:jstutte]]

Thanks. After some testing with different combinations, it seems to me that we need both the patch from bug 1794401 (after which the test passes but still prints some error message about surrogates to stderr) and D158929 (which sanitizes the surrogates).

And I think we need a new bug that improves the test itself in order to not even try to write out unprintable characters to the log in the first place (at the best they will show up as <?>).

Comment 22

[Jens Stutte [:jstutte]]

FWIW: https://treeherder.mozilla.org/jobs?repo=try&revision=add183f82f79fd2b869be279f7cf565759121016

Comment 23

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #22)

FWIW: https://treeherder.mozilla.org/jobs?repo=try&revision=add183f82f79fd2b869be279f7cf565759121016

There is one interesting message in a log:

[task 2022-10-11T08:11:36.652Z] 08:11:36     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_scripting_persistAcrossSessions.js | test_multiple_extensions_and_scripts - [test_multiple_extensions_and_scripts : 165] expected a single 'script-1.js' js file - Expected: ["script-1.js"], Actual: ["script-1.js"] - true == true
[task 2022-10-11T08:11:36.652Z] 08:11:36     INFO -  mozlog.structuredlog: Failure calling log handler:
[task 2022-10-11T08:11:36.685Z] 08:11:36     INFO -  Traceback (most recent call last):
[task 2022-10-11T08:11:36.685Z] 08:11:36     INFO -    File "Z:\task_166546432437419\build\venv\lib\site-packages\mozlog\structuredlog.py", line 294, in _handle_log
[task 2022-10-11T08:11:36.695Z] 08:11:36     INFO -      handler(data)
[task 2022-10-11T08:11:36.695Z] 08:11:36     INFO -    File "Z:\task_166546432437419\build\venv\lib\site-packages\mozlog\handlers\base.py", line 94, in __call__
[task 2022-10-11T08:11:36.695Z] 08:11:36     INFO -      self.stream.write(formatted)
[task 2022-10-11T08:11:36.695Z] 08:11:36     INFO -    File "c:\mozilla-build\python3\lib\encodings\cp1252.py", line 19, in encode
[task 2022-10-11T08:11:36.696Z] 08:11:36     INFO -      return codecs.charmap_encode(input,self.errors,encoding_table)[0]
[task 2022-10-11T08:11:36.696Z] 08:11:36     INFO -  UnicodeEncodeError: 'charmap' codec can't encode character '\ufffd' in position 244: character maps to <undefined>

which seems to indicate that under Windows we write the log file not as UTF-8 but as cp1252 ? Then we should probably make sure that we use the stream's encoding if present instead of directly using "utf-8" as constant string?

Comment 24

[Henri Sivonen (:hsivonen)]

(In reply to Jens Stutte [:jstutte] from comment #23)

(In reply to Jens Stutte [:jstutte] from comment #22)

FWIW: https://treeherder.mozilla.org/jobs?repo=try&revision=add183f82f79fd2b869be279f7cf565759121016

There is one interesting message in a log:

[task 2022-10-11T08:11:36.652Z] 08:11:36     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_scripting_persistAcrossSessions.js | test_multiple_extensions_and_scripts - [test_multiple_extensions_and_scripts : 165] expected a single 'script-1.js' js file - Expected: ["script-1.js"], Actual: ["script-1.js"] - true == true
[task 2022-10-11T08:11:36.652Z] 08:11:36     INFO -  mozlog.structuredlog: Failure calling log handler:
[task 2022-10-11T08:11:36.685Z] 08:11:36     INFO -  Traceback (most recent call last):
[task 2022-10-11T08:11:36.685Z] 08:11:36     INFO -    File "Z:\task_166546432437419\build\venv\lib\site-packages\mozlog\structuredlog.py", line 294, in _handle_log
[task 2022-10-11T08:11:36.695Z] 08:11:36     INFO -      handler(data)
[task 2022-10-11T08:11:36.695Z] 08:11:36     INFO -    File "Z:\task_166546432437419\build\venv\lib\site-packages\mozlog\handlers\base.py", line 94, in __call__
[task 2022-10-11T08:11:36.695Z] 08:11:36     INFO -      self.stream.write(formatted)
[task 2022-10-11T08:11:36.695Z] 08:11:36     INFO -    File "c:\mozilla-build\python3\lib\encodings\cp1252.py", line 19, in encode
[task 2022-10-11T08:11:36.696Z] 08:11:36     INFO -      return codecs.charmap_encode(input,self.errors,encoding_table)[0]
[task 2022-10-11T08:11:36.696Z] 08:11:36     INFO -  UnicodeEncodeError: 'charmap' codec can't encode character '\ufffd' in position 244: character maps to <undefined>

which seems to indicate that under Windows we write the log file not as UTF-8 but as cp1252 ? Then we should probably make sure that we use the stream's encoding if present instead of directly using "utf-8" as constant string?

It's probably less trouble to make it UTF-8 on all platforms instead of keeping Windows different.

Comment 25

[Jens Stutte [:jstutte]]

(In reply to Henri Sivonen (:hsivonen) from comment #24)

It's probably less trouble to make it UTF-8 on all platforms instead of keeping Windows different.

Not sure, it is not too difficult to paper over this for now (see my updated patch here, which takes the wanted encoding from the output stream). AFAICS in some cases we are just relying on the system's locale (which might have any sort of funny side effect for people running things on exotic configurations) and I agree that it would be far better to make things explicit (at least) and hopefully UTF-8 (best) everywhere. IIUC, Microsoft has plans for UTF-8 to become the default for the system locale, too, but is moving very slowly here. Setting just the system's locale to use UTF-8 on the CI could help to some extent, but people running things locally might still be fooled. Having things independent from the system's locale would be the best, but I can imagine that there are many pitfalls in getting there (like command line tools used to parse and convert log files and such that would need to find the right environment, but I ignore the architecture of treeherder here).

Please note also, that these messages do not prevent the tests from running successfully, they just bloat the logs. They are probably a sign of tests trying to print out things that no human will be ever able to read anyways, so there might be even value in leaving them (that would not make the entire patch obsolete, just the suppressing of the UnicodeEncodeError when actually writing to the stream).

For now I just want to land my other patch and have some paper-over fix here...

Comment 26

[Dave Hunt [:davehunt] [he/him] ⌚BST]

I've reviewed the patch, but not sure what else is being asked for here? I haven't worked on mozlog for years, and don't have a strong opinion on making all platforms UTF-8, though it does sound like a reasonable thing to do, for consistency. Perhaps @ahal has some thoughts on this, but their needinfo requests are currently blocked.

Comment 27

[Jens Stutte [:jstutte]]

Thanks for your patience! I don't think we want to sort out the bigger questions here now. I'd just need a rubber stamp on the latest changes of the patch D158929 in order to move forward. I am happy to file a follow up bug to discuss the general UTF-8 everywhere thing.

Comment 28

[Dave Hunt [:davehunt] [he/him] ⌚BST]

(In reply to Jens Stutte [:jstutte] from comment #27)

Thanks for your patience! I don't think we want to sort out the bigger questions here now. I'd just need a rubber stamp on the latest changes of the patch D158929 in order to move forward. I am happy to file a follow up bug to discuss the general UTF-8 everywhere thing.

Sorry @jstutte I didn't notice the update to the patch. It looks good to me.

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d84cad727397
Suppress surrogate characters in log lines if we use six.PY3. r=davehunt
https://hg.mozilla.org/integration/autoland/rev/98b981aedf23
Limit maximum key length to INT32_MAX. r=dom-storage-reviewers,jesup

Comment 30

[Norisz Fay [:noriszfay]]

Backed out for causing python related failures

Backout link

Push with failures

Failure log

P.S: There's also this xpcshell failure.

Comment 31

[Jens Stutte [:jstutte]]

Great, so the linux python environment differs here from Windows...

Comment 32

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #31)

Great, so the linux python environment differs here from Windows...

io.text_encoding: New in version 3.10.

Comment 33

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #32)

(In reply to Jens Stutte [:jstutte] from comment #31)

Great, so the linux python environment differs here from Windows...

io.text_encoding: New in version 3.10.

(another good reason why we want https://mozilla-hub.atlassian.net/browse/FFXP-2088)

Comment 34

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ee137407c8b4
Suppress surrogate characters in log lines if we use six.PY3. r=davehunt
https://hg.mozilla.org/integration/autoland/rev/adfa13e465e6
Limit maximum key length to INT32_MAX. r=dom-storage-reviewers,jesup

Comment 35

[Narcis Beleuzu [:NarcisB]]

Backed out for xpcshell failure on test_keys.js

Backout link: https://hg.mozilla.org/integration/autoland/rev/5bb2dcca5bb3b5e0c067419c19c987c7a6a3a410
Log link: https://treeherder.mozilla.org/logviewer?job_id=393215158&repo=autoland&lineNumber=2533

Comment 36

[Jens Stutte [:jstutte]]

(In reply to Narcis Beleuzu [:NarcisB] from comment #35)

Backed out for xpcshell failure on test_keys.js

Backout link: https://hg.mozilla.org/integration/autoland/rev/5bb2dcca5bb3b5e0c067419c19c987c7a6a3a410
Log link: https://treeherder.mozilla.org/logviewer?job_id=393215158&repo=autoland&lineNumber=2533

Oh, that is finally not an encoding problem, phew! The test allocates a huge amount of memory for a key and under 32 Bit OS this will fail. Let's see how to workaround this...

Comment 37

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2b30d35e67c2
Suppress surrogate characters in log lines if we use six.PY3. r=davehunt
https://hg.mozilla.org/integration/autoland/rev/1c9af14b559f
Limit maximum key length to INT32_MAX. r=dom-storage-reviewers,jesup

Comment 38

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/2b30d35e67c2
https://hg.mozilla.org/mozilla-central/rev/1c9af14b559f

Comment 39

[Bugmon [:jkratzer for issues]]

Bugmon Analysis
Verified bug as fixed on rev mozilla-central 20221014215500-0bf2cd2f9e73.
Removing bugmon keyword as no further action possible. Please review the bug and re-add the keyword for further analysis.