53004 - Prototype local vars get GC'd twice

Status: VERIFIED INVALID

(Core :: JavaScript Engine, defect, P3)

Description

[Jon Smirl]

Running XPConnect standalone with a JS component, see attachments.
Component.prototype has a var newseed that is causing the problem
When running the component I recieve this error, which is excepted and not part 
of the bug:
[Exception... "[JavaScript Error: "cAttr has no properties" {file: "d:\testdll\c
omponents\welcome.js" line: 28}] [px7IChain::parseURI]"  nsresult: "0x80570021 (
NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "<unknown>"  data: yes]

After receiving this error I exit the app. During exit the string in newseed is 
GC'd twice. First as part of the destruction of the Component object and second 
as a string. At least I think this is what is happening. The XPCOM component 
properly made a copy before returning the string.

Attachment 1 [details] [diff] causes the GC failure.
Attachment 2 [details] [diff] Moving the vars from the prototype to file scope makes the problem 
go away.

GC is occuring in _PRI_DetachThread and the destructor for XPConnect

Comment 1

[Jon Smirl]

Attachment: var in prototype def, causes gc problem on exit

Comment 2

[Jon Smirl]

Attachment: mov vars to file scope, gc problem goes away

Comment 3

[Jon Smirl]

Using XPCONNECT standalone from CVS as of 9/15

Comment 4

[Phil Schwartau]

cc'ing Brendan, jband, and Patrick - 

Comment 5

[Jon Smirl]

I've worked on this for two more hours and I'm sure I don't know what is really 
going on. This may be a race between two threads GCing at the same time. I 
still can't explain why changing the var locations makes it go away.

If I leave the vars in the procedures and set them all to null before returning 
the problem goes away too. 

Comment 6

[Brendan Eich [:brendan]]

Reassigning to shaver, leaving unconfirmed for now.

If GC is running, all JS API usage must be within resuests (JS_BeginRequest and
JS_EndRequest must bracket the API call batches).

/be

Comment 7

[Brendan Eich [:brendan]]

Jon, I don't know if GC has anything to do with the problems you're seeing.  Do
you have debugging printfs or even GC_MARK_DEBUG enabled?  What evidence do you
have of things being GC'd "twice"?  (Mark and sweep GC may find multiple strong
ref paths to a live thing, but it will sweep and finalize each dead thing, i.e.
garbage, exactly once).

/be

Comment 8

[Jon Smirl]

I have a watch set on the string (not the JS Wrapper) in question. It exists 
when I enter _PRI_DetachThread and it starts the final GC. During the GC an 
object is collected which causes the string to be freed. GC then later tries to 
collect the string via a JSString but it is already gone. The string is a 
returned string from XPCOM. I don't know enough about JS to tell what JSObject 
is being freed. JS is not double freeing a JS object that I can tell, it's my 
string that is getting double freed. It looks like two JS objects are pointing 
to the same string.

I'm about 70% sure this is a problem in the JS engine since I can make it go 
away by changing where the variables are defined. If I was not copying the 
return string properly moving the variables wouldn't make it go away.

I also think it is likely that it is related to the fact that JS threw an error 
while executing the component. I can run the same component (fixed to remove 
the error - my QI return was broken) without problem.

I'm not doing any begin/end pairs, I rely on XPConnect for that and a context. 
My app is not aware that the component has been implemented in Javascript.

Comment 9

[Brendan Eich [:brendan]]

> I have a watch set on the string (not the JS Wrapper) in question.

Debugger watch or data breakpoint?  Or JS watchpoing?

> It exists 
> when I enter _PRI_DetachThread and it starts the final GC. During the GC an 
> object is collected which causes the string to be freed.

You mean, neither the object nor the string that it refers to via one of its 
properties is marked by the GC, so both are swept and finalized?

> GC then later tries
> to collect the string via a JSString but it is already gone.

The GC sweeps once, from "front to back", so it won't finalize anything more 
than once.  Please say exactly what you observed that you are describing here 
with words like "tries to collect" and "already gone".  Can you also please 
verify via cx->runtime->gcNumber that you're observing the same GC run?

> The string is a
> returned string from XPCOM. I don't know enough about JS to tell what JSObject 
> is being freed. JS is not double freeing a JS object that I can tell,

The JS GC doesn't and really can't double-free anything.  Mark and sweep has a 
few advantages!

> it's my
> string that is getting double freed.

From what code?  Callstack, please -- also, we really need to see more of your 
code to diagnose this.

> It looks like two JS objects are pointing 
> to the same string.

Via properties, I take it.  That's a fine thing, easily expressed in JS as well 
as achievable from C or C++ (consider var s="hi"; var o1={p:s}, o2={p:s}).

> I'm about 70% sure this is a problem in the JS engine since I can make it go 
> away by changing where the variables are defined. If I was not copying the
> return string properly moving the variables wouldn't make it go away.

I have no idea where this bug is.  We need to see the data you're observing, and 
also your code.

> I also think it is likely that it is related to the fact that JS threw an
> error while executing the component. I can run the same component (fixed to
> remove the error - my QI return was broken) without problem.

Ok, where was the error thrown?  What was the stack?

> I'm not doing any begin/end pairs, I rely on XPConnect for that and a context. 
> My app is not aware that the component has been implemented in Javascript.

Good, that's kosher now that jband has fixed XPConnect.

/be

Comment 10

[Jon Smirl]

Attachment: Current version of JS component (ver1)

Comment 11

[Jon Smirl]

Using the attached ver1 of the js component, I've altered the passed in XPCOM 
object (handler) to not support the interface requested. This will cause a JS 
exception to be thrown when accessed. I don't see the GC problem unless the 
error is thrown and the assignments to null are commented out (as they are in 
the attachment).

** NOTE: This report will only be printed in DEBUG builds.**
* Call to xpconnect wrapped JSObject produced this error:  *
[Exception... "[JavaScript Error: "this.handler has no properties" {file: "d:\te
stdll\components\welcome.js" line: 90}] [px7IChain::parseURI]"  nsresult: "0x805
70021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "<unknown>"  data
: yes]

Stack trace from the second free of the string that caused to problem. I'll get 
the stack trace from the first free but it will take some more time. Everytime 
I hit this bug I have to reboot windows.

__crtMessageBoxA(const char * 0x01c4b8b8, const char * 0x102579a0 `string', 
unsigned int 0x00012012) line 65
CrtMessageWindow(int 0x00000002, const char * 0x102571f4 `string', const char * 
0x01c4c9ec, const char * 0x00000000, const char * 0x01c4ea10) line 520 + 22 
bytes
_CrtDbgReport(int 0x00000002, const char * 0x102571f4 `string', int 0x0000041a, 
const char * 0x00000000, const char * 0x102570e4 `string') line 419 + 76 bytes
_free_dbg_lk(void * 0x00a27b80, int 0x00000001) line 1050 + 74 bytes
_free_dbg(void * 0x00a27b80, int 0x00000001) line 1001 + 13 bytes
free(void * 0x00a27b80) line 956 + 11 bytes
JS_free(JSContext * 0x00a0d8f0, void * 0x00a27b80) line 1376 + 10 bytes
js_FinalizeString(JSContext * 0x00a0d8f0, JSString * 0x0092afc0) line 2336 + 16 
bytes
js_GC(JSContext * 0x00a0d8f0, unsigned int 0x00000000) line 1003 + 11 bytes
js_ForceGC(JSContext * 0x00a0d8f0) line 711 + 11 bytes
js_DestroyContext(JSContext * 0x00a0d8f0, int 0x00000002) line 219 + 9 bytes
JS_DestroyContext(JSContext * 0x00a0d8f0) line 801 + 11 bytes
xpcPerThreadData::Cleanup() line 225 + 13 bytes
xpcPerThreadData::~xpcPerThreadData() line 235
xpcPerThreadData::`scalar deleting destructor'(unsigned int 0x00000001) + 15 
bytes
xpc_ThreadDataDtorCB(void * 0x00a00610) line 352 + 28 bytes
_PR_DestroyThreadPrivate(PRThread * 0x009b5e70) line 244 + 16 bytes
_PR_CleanupThread(PRThread * 0x009b5e70) line 45 + 9 bytes
_PRI_DetachThread() line 1489 + 9 bytes
DllMain(HINSTANCE__ * 0x30000000, unsigned long 0x00000003, void * 0x00000000) 
line 51
_DllMainCRTStartup(void * 0x30000000, unsigned long 0x00000003, void * 
0x00000000) line 273 + 17 bytes
KERNEL32! bff7c00d()
KERNEL32! bff87d50()

Comment 12

[Jon Smirl]

I have found this cause of this. This is a bug in my code. The XPCOM component 
passed into the JS component as 'this->req' kept a reference to the string when 
it shouldn't have. During the JS GC at exit, the JS wrapper for 'this->req' was 
deleted freeing the XPCOM object request and causing the string to 
inappropriately be freed. Later when JS freed it's copy of the string it was 
already gone and the error results.

When debugging this I could tell that the string was being freed once when a JS 
object was destroyed (the wrapper for 'this->req') and once when it was 
supposed to be freed, the JS string. When I finally figured out what the JS 
object was wrapping I was able to look at my code and find the inappropriate 
reference. Complicating this was the fact the string was built by the utility 
object and the bad reference was from the request object.

Moving the JS variables around changed the order in which the objects were 
destroyed and masked the true bug.

Comment 13

[John Bandhauer]

Jon,

This is not a very satisfying explanation of the problem. Unless you are 
explicitly calling JS_GetStringBytes or JS_GetStringChars your native code 
should never have access to the same pointer that JS is using for the string 
character data. Or, does your native code get at the JSString struct?

OR, does your interface use the evil [shared] attribute? *That* would explain 
this.

Comment 14

[Jon Smirl]

In my XPCOM component I recorded the address of an 'in' parameter passed in by 
JS and then proceeded to delete it when my component was destroyed. I should 
have made a copy of it first.

Here's a trace of the guilty component, note that the string at 0xA27B80 is the 
same string that is freed by Javascript in the other trace.

memset() line 108
30000000()
_free_dbg(void * 0x00a27b80, int 0x00000001) line 1001 + 13 bytes
free(void * 0x00a27b80) line 956 + 11 bytes
operator delete(void * 0x00a27b80) line 7 + 9 bytes
ApacheRequest::~ApacheRequest() line 53 + 23 bytes
ApacheRequest::`scalar deleting destructor'(unsigned int 0x00000001) + 22 bytes
Request::Release(Request * const 0x00dc1fd0) line 16 + 129 bytes
nsXPCWrappedNative::~nsXPCWrappedNative() line 398 + 27 bytes
nsXPCWrappedNative::`scalar deleting destructor'(unsigned int 0x00000001) + 15 
bytes
nsXPCWrappedNative::Release(nsXPCWrappedNative * const 0x00a24230) line 71 + 31 
bytes
nsXPCWrappedNative::JSObjectFinalized(JSContext * 0x00a0d8f0, JSObject * 
0x0092cf18) line 96
WrappedNative_Finalize(JSContext * 0x00a0d8f0, JSObject * 0x0092cf18) line 781
js_FinalizeObject(JSContext * 0x00a0d8f0, JSObject * 0x0092cf18) line 1592 + 
114 bytes
js_GC(JSContext * 0x00a0d8f0, unsigned int 0x00000000) line 1003 + 11 bytes
js_ForceGC(JSContext * 0x00a0d8f0) line 711 + 11 bytes
js_DestroyContext(JSContext * 0x00a0d8f0, int 0x00000002) line 219 + 9 bytes
JS_DestroyContext(JSContext * 0x00a0d8f0) line 801 + 11 bytes
xpcPerThreadData::Cleanup() line 225 + 13 bytes
xpcPerThreadData::~xpcPerThreadData() line 235
xpcPerThreadData::`scalar deleting destructor'(unsigned int 0x00000001) + 15 
bytes
xpc_ThreadDataDtorCB(void * 0x00a00610) line 352 + 28 bytes
_PR_DestroyThreadPrivate(PRThread * 0x009b5e20) line 244 + 16 bytes
_PR_CleanupThread(PRThread * 0x009b5e20) line 45 + 9 bytes
_PRI_DetachThread() line 1489 + 9 bytes
DllMain(HINSTANCE__ * 0x30000000, unsigned long 0x00000003, void * 0x00000000) 
line 51
_DllMainCRTStartup(void * 0x30000000, unsigned long 0x00000003, void * 
0x00000000) line 273 + 17 bytes
KERNEL32! bff7c00d()
KERNEL32! bff87d50()

Comment 15

[John Bandhauer]

I see. It was a simple breaking of the xpcom rules regarding lifetime of 'in' 
params. I can't think of any reasonable way to protect people from shooting 
themselves in the foot that way. Nor can I think of a simple way to 
automatically point out the error.

Marking this INVALID.

Comment 16

[Phil Schwartau]

Marking Verified -