Closed Bug 1352893 Opened 7 years ago Closed 7 years ago

Subprocess getEnvironment fails with "malformed UTF-8 character sequence" on dbaron's machine

Categories

(Toolkit :: Async Tooling, defect)

Product:
Toolkit
Component:
Async Tooling
Platform:
All
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla55
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: mstange, Assigned: kmag)

References

Details

Attachments

(1 file)

Bug 1352893: Handle non-UTF-8 data in Unix environment variables.
59 bytes, text/x-review-board-request
mstange
: review+
Details 
Full error:

> A coding exception was thrown and uncaught in a Task.
> 
> Full message: TypeError: malformed UTF-8 character sequence at offset 0
> Full stack: getEnvironment@resource://gre/modules/subprocess/subprocess_unix.jsm:95:17
> getEnvironment@resource://gre/modules/Subprocess.jsm:131:5
> pathSearch@resource://gre/modules/Subprocess.jsm:154:37
> call/procPromise<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/system/child_process/subprocess.js:66:30
> TaskImpl_run@resource://gre/modules/Task.jsm:319:42
> TaskImpl@resource://gre/modules/Task.jsm:277:3
> asyncFunction@resource://gre/modules/Task.jsm:252:14
> Task_spawn@resource://gre/modules/Task.jsm:166:12
> call@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/system/child_process/subprocess.js:54:23
> initialize@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/system/child_process.js:45:14
> constructor@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/heritage.js:135:7
> spawn@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/system/child_process.js:156:10
> exports.getSymbolsFromNM/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/lib/nm-syms.js:117:16

This happens when the Gecko Profiler Add-on calls:

> child_process.spawn('nm', ['--demangle', libPath]);

It looks like there are invalid characters in one of the environment variables on this machine.

I've asked dbaron to run this code snippet in order to find out which one it is:

Cu.import("resource://gre/modules/ctypes.jsm");
for (var envp = ctypes.open("libc.so.6").declare("environ", ctypes.char.ptr.ptr); !envp.contents.isNull(); envp = envp.increment()) { try { envp.contents.readString(); } catch (e) { console.error(envp.contents.readStringReplaceMalformed()); } }


In any case, the loop at http://searchfox.org/mozilla-central/source/toolkit/modules/subprocess/subprocess_unix.jsm#94 should handle exceptions from readString() gracefully.
Comment on attachment 8853834 [details]
Bug 1352893: Handle non-UTF-8 data in Unix environment variables.

https://reviewboard.mozilla.org/r/125868/#review128336

That was fast!

I think this place also needs to check whether environment.PATH is a string or a typed array: http://searchfox.org/mozilla-central/rev/990055a4902952e038cc350c9ffe1ac426d1c943/toolkit/modules/subprocess/subprocess_unix.jsm#150

The other relevant use of options.environment that I can find is at http://searchfox.org/mozilla-central/rev/990055a4902952e038cc350c9ffe1ac426d1c943/toolkit/modules/subprocess/subprocess_worker_common.js#89 and I suspect ctypes.char.array() is able to deal with both strings and Uint8Arrays?
(In reply to Markus Stange [:mstange] from comment #2)
> I think this place also needs to check whether environment.PATH is a string
> or a typed array:
> http://searchfox.org/mozilla-central/rev/
> 990055a4902952e038cc350c9ffe1ac426d1c943/toolkit/modules/subprocess/
> subprocess_unix.jsm#150

Yeah, that had occurred to me, but I decided that if $PATH is not a valid
UTF-8 string, failing was probably the best option. Still, it's probably worth
doing more cleanly.

> The other relevant use of options.environment that I can find is at
> http://searchfox.org/mozilla-central/rev/
> 990055a4902952e038cc350c9ffe1ac426d1c943/toolkit/modules/subprocess/
> subprocess_worker_common.js#89 and I suspect ctypes.char.array() is able to
> deal with both strings and Uint8Arrays?

Yes, a typed array can be used for any value with a compatible ctypes array or
pointer type. Although, when we pass a string for those values, it gets
automatically null terminated, which is not the case for typed arrays, which
is a problem. The tests were only passing by luck.
Assignee: nobody → kmaglione+bmo
(In reply to Markus Stange [:mstange] from comment #0)
> I've asked dbaron to run this code snippet in order to find out which one it
> is:
> 
> Cu.import("resource://gre/modules/ctypes.jsm");
> for (var envp = ctypes.open("libc.so.6").declare("environ",
> ctypes.char.ptr.ptr); !envp.contents.isNull(); envp = envp.increment()) {
> try { envp.contents.readString(); } catch (e) {
> console.error(envp.contents.readStringReplaceMalformed()); } }

This code returns:
"force_s3tc_enable=true"
which presumably comes from:
https://searchfox.org/mozilla-central/rev/990055a4902952e038cc350c9ffe1ac426d1c943/gfx/gl/GLContextProviderGLX.cpp#74
but I don't see how it's malformed UTF-8.
Comment on attachment 8853834 [details]
Bug 1352893: Handle non-UTF-8 data in Unix environment variables.

https://reviewboard.mozilla.org/r/125868/#review128514

::: toolkit/modules/subprocess/subprocess_unix.jsm:81
(Diff revision 2)
>    static get WorkerClass() {
>      return UnixPromiseWorker;
>    }
>  }
>  
> +// Convert a nul-terminated char pointer into a sized char array, and then

nul -> null

Google gives more results for "null-terminated" than for "nul-terminated"

::: toolkit/modules/subprocess/subprocess_unix.jsm:82
(Diff revision 2)
>      return UnixPromiseWorker;
>    }
>  }
>  
> +// Convert a nul-terminated char pointer into a sized char array, and then
> +// convert that into a JS typed array.

Should probably mention here that the array does not include the null terminator

::: toolkit/modules/subprocess/test/xpcshell/test_subprocess.js:723
(Diff revision 2)
> +    // Use TextDecoder rather than a string with a \xff escape, since
> +    // the latter will automatically be normalized to valid UTF-8.

Oops.
Attachment #8853834 - Flags: review?(mstange) → review+
(In reply to David Baron :dbaron: ⌚️UTC-7 from comment #5)
> (In reply to Markus Stange [:mstange] from comment #0)
> > I've asked dbaron to run this code snippet in order to find out which one it
> > is:
> > 
> > Cu.import("resource://gre/modules/ctypes.jsm");
> > for (var envp = ctypes.open("libc.so.6").declare("environ",
> > ctypes.char.ptr.ptr); !envp.contents.isNull(); envp = envp.increment()) {
> > try { envp.contents.readString(); } catch (e) {
> > console.error(envp.contents.readStringReplaceMalformed()); } }
> 
> This code returns:
> "force_s3tc_enable=true"
> which presumably comes from:
> https://searchfox.org/mozilla-central/rev/
> 990055a4902952e038cc350c9ffe1ac426d1c943/gfx/gl/GLContextProviderGLX.cpp#74
> but I don't see how it's malformed UTF-8.

Huh. I don't understand what could be happening here. Kris, any ideas?
I pasted the string from my text editor into the web console and inspected the char codes, they're all < 128 and the length is 22, like you'd expect. So I don't think anybody smuggled zero-width spaces or other funny business into it.
No, that's pretty weird. The only thing I can think of is memory corruption causing an invalid byte to wind up in there somewhere, and get dropped during the lossy conversion. Maybe try logging the result of ptrToUint8Array from my patch rather than readStringReplaceMalformed? Sorry, I'm on a bus right now, or I'd give you a pastable snippet.
https://hg.mozilla.org/integration/mozilla-inbound/rev/de7a6af789d8b0f32fa51a9877989ccc1418b557
Bug 1352893: Handle non-UTF-8 data in Unix environment variables. r=mstange
OK, after looking at the console more closely:  the force_s3tc_enable=true was the result of the expression, not the console.error() output.  The actual console.error output was a bunch of garbage data!

Cu.import("resource://gre/modules/ctypes.jsm");
for (var envp = ctypes.open("libc.so.6").declare("environ", ctypes.char.ptr.ptr); !envp.contents.isNull(); envp = envp.increment()) { try { envp.contents.readString(); } catch (e) { console.log("Exception: \nreplaceMalformed: ", envp.contents.readStringReplaceMalformed(), "\n uint8array: ", new Uint8Array(ctypes.cast(envp, ctypes.unsigned_char.array(200).ptr).contents)); } }

Exception: 
replaceMalformed:  @Blw����~lw��� �g���//////////////////////////////// 
 uint8array:  Uint8Array [ 200, 206, 177, 122, 160, 127, 0, 0, 125, 7, 190 more… ] 

"force_s3tc_enable=true"
(But it also looks like I only see the error some of the time -- so the other times I only get the result of the expression, and no logging at all.)
For what it's worth, this doesn't actually fix the profiler problem that I'm not getting symbols.

I do get fewer error messages now, though.

The messages for libxul are now:

[starting] reading existing symbol dump for library libxul.so 855015EE8D563E4B2E00CB39C4A950790 from the objdir
attempting to read sym file for library libxul.so 855015EE8D563E4B2E00CB39C4A950790 at /home/dbaron/crashreporter-symbols/libxul.so/855015EE8D563E4B2E00CB39C4A950790/libxul.so.sym
[failure] reading existing symbol dump for library libxul.so 855015EE8D563E4B2E00CB39C4A950790 from the objdir
(new Error("", (void 0)))
fetching symbol dump for library libxul.so 855015EE8D563E4B2E00CB39C4A950790 from http://symbols.mozilla.org/libxul.so/855015EE8D563E4B2E00CB39C4A950790/libxul.so.sym
[starting] requesting symbols for library libxul.so 855015EE8D563E4B2E00CB39C4A950790 from the symbol server
fetching symbol dump for library   from http://symbols.mozilla.org///.sym
[starting] requesting symbols for library   from the symbol server
There should be more libxul.so messages below the excerpt you posted. It only gets interesting once the fetch to symbols.mozilla.org fails, because at that point we fall back to running nm.
The remaining libxul.so messages are:

[failure] requesting symbols for library libxul.so 855015EE8D563E4B2E00CB39C4A950790 from the symbol server
(new Error("got error status 404", "resource://gre/modules/commonjs/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/lib/symbol-store.js", 95))
[starting] dumping symbols for library libxul.so 855015EE8D563E4B2E00CB39C4A950790 located at /home/dbaron/bin/running-firefox/libxul.so using nm
https://hg.mozilla.org/mozilla-central/rev/de7a6af789d8
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox55: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Let's continue discussing the symbolication failure in https://github.com/devtools-html/Gecko-Profiler-Addon/issues/38 .
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: