Fix for Local var name resolution issue following GC + concurrency

[greg-dove]

The changes specific in this branch were tested by developers who had experienced the problem and based on use over multiple days no longer experienced it.

Comments about/justification for the changes:
The symptom of the problem was a rare failure to find the correct type of a local var inside a function scope. Usually the first one worked, but others did not.

The assumption for how it occurs is:
1.Memory Pressure: A GC event clears the FunctionNode but leaves the FunctionScope intact.
2.Scope Reconnection: When the FileNode is re-parsed, it creates a new "shell" FunctionNode. The existing FunctionScope is reconnected to this new node.
3.The "Wipe": To ensure no stale data remains, the reconnection process explicitly wipes all local variable definitions from the scope.
4.The Failure: Under certain conditions, the compiler would attempt to resolve a name (look up a variable) after the wipe but before the function body was fully re-parsed. Because the scope was empty, the resolution would either return null (untyped) or incorrectly find something with the same name in an outer scope (e.g., a class member).

The general 'solution' is intended as a sort of "just-in-time" restoration of local definitions by ensuring that the act of asking for a definition triggers the re-parsing of the body if it is missing
Because it is so hard to repro, the sequence 1-4 above is still an assumed cause, which is why I need to wait for confirmation of it not happening any more from others who were seeing it more routinely than I did. But it does match the symptoms exactly, which makes me hopeful.

There is a new test included (NameResolutionAfterGCTest) that is intended to simulate something close to the above.

There are a few other changes in the branch - changes related to cache, and also (something I discovered as another 'rare' thing after the name lookup changes, when running regular royale framework build) to thread-safety with metatag Array - that might need more work/attention. So far I see no noticeable adverse effect to performance.
There are a few other minor changes I used during logging that I left in there as well.

[greg-dove]

As mentioned elsewhere, @joshtynjala, please feel free to reject this if you have a better way to address the problem....

[joshtynjala]

I'm having trouble reproducing the test failure. I copied only the changes necessary to make the test compile (changing a couple of things to public), and nothing else. While there is indeed a test failure, it does not seem to be related to the issue you are encountering.

In NodeReference.reconnectNode(), there's an assertion that is failing:

public void reconnectNode(IASNode node)
{
    assert node.contains(absoluteStart);
    nodeRef = new WeakReference<IASNode>(node);
}

The assertion fails because the newScopedNode absolute start position isn't getting initialized. Similar to how the parent needs to be manually initialized, we can manually initialize the absolute start position after manually initializing the parent:

((NodeBase)newScopedNode).setParent(newNode);
((NodeBase)newScopedNode).span(node.getScopedNode().getAbsoluteStart(), node.getScopedNode().getAbsoluteEnd(), -1, -1, -1, -1);

Once I add that one line, the test passes successfully.

For reference, I'm on Fedora Linux 44. OpenJDK 17.

[greg-dove]

@joshtynjala Sorry, please stand by. I guess I missed some things. I have been looking into this today but I'm out of time, so I will come back to it on Monday and keep you posted. I forgot about 'with and without' assertions, but there's obviously more to do for the test itself. I will work on that so it reliably fails on develop and passes in the branch (and I'll try to avoid the need for changes outside the test simply for testing purposes, by using reflection if it's possible)

[greg-dove]

@joshtynjala I think that latest test in the branch gets closer to what it should be doing. And you should be able to drop the same test (inside 'scopes' package in compiler.internal tests) and it should work (and fail) for the build in develop, with no other changes needed. I had to pair with AI on this, so it might be a little messed up :). I did also end up making some additional small tweaks in FunctionScope in the PR branch.

[joshtynjala]

// This also seems needed... Explicitly calling getScope() on the node
// ensures that on-demand parsing/restoration is executed,
// which is necessary for restoring local definitions after GC.
node.getScope();

I suspect that this line makes the test pass, but it probably doesn't affect the compiler's behavior outside of the test. It's basically calling your override of getScope() in the test, which manually adds the definition to the scope:

 ScopedBlockNode newScopedNode = new ScopedBlockNode() {
    @Override
    public ASScope getScope() {
        // This is the trigger!
        if (finalDefA != null) {
            finalScope.addDefinition(finalDefA);
        }
        return finalScope;
    }
};

However, I couldn't find any implementation of getScope() in the compiler that would also add definitions to the scope. They all basically just returned a member variable and did nothing else.

The test is nearly correct in the sense that the definitions need to be added to the scope before the final assert can pass. That's just not how the compiler would actually do it.

Regardless, I think that this helped me better understand what's going on. I still need to fill in some blanks, but I think that somewhere in the compiler, there's a missing call to the following method after a function body is re-parsed because that post-process step should be the actual place where the definitions get added to the scope.

runPostProcess(EnumSet.of(PostProcessStep.POPULATE_SCOPE), scope);

I will continue my investigation.

[joshtynjala]

I extracted a fix for a potential race condition from this PR and committed it: 6a02227

I'd be curious if the issue still reproduces in your real-world project (not the test) with just that change and nothing else from this PR. Given how intermittent the issue is, a race condition kind of makes sense.

[greg-dove]

Thanks for your time on this @joshtynjala. This was definitely a difficult thing to work on. Normally if I can find an error with a breakpoint, I can figure out things from there, but because this was not easily repro'ed it was something I had to approach as a theory and then try to test a 'fix' for that. And the 'fix' was heavily influenced by AI in this case, it didn't feel right because it was trying too much to work around things.
I will make a build with just your latest commit and ask others to test it this week, will update here with results when available. Fingers crossed!

[greg-dove]

@joshtynjala we swapped the compiler build using your latest develop code onto our CI machine - we had previously been running this with the patched compiler from the branch, and the problem was not observed with that build. So far, since swapping it out today, it has generated at least one build that continues to have the original problem. The problem is only "solved" by manually triggering the 'build and deploy' job a second time and crossing fingers (this usually does work though, it's just really difficult for QA when they are testing an 'unknown' bad build in the times when that happens).
So early feedback would suggest your commit alone is not sufficient to fix it. I'll keep you posted, but we might have to switch back to the branch build on our CI machine in the near term.

[joshtynjala]

So far, since swapping it out today, it has generated at least one build that continues to have the original problem.

Okay, I kind of figured that might be the case. Since a part of my change was in your branch, and it actually could cause a race condition when resolving symbols, I wanted to rule it out. Go ahead and return to your branch, and I'll keep playing around. I have some plans for messing with compiler internals in a way that might force it to reproduce more easily.

By the way, if you can share some output from when it fails, versus normally, I'd be curious to see the difference. Conceptually, I think that I understand, but seeing concrete output might change some of my assumptions.

Finally, is there any chance that everyone experiencing the issue (including your CI machine) is on the same operating system? Or is it a mix? If everyone's on the same OS, I'd like to test there too, just in case it doesn't reproduce as easily elsewhere. Thanks!

[greg-dove]

@joshtynjala I will try to pull some historical examples up tomorrow. But I can confirm we have seen this on both windows and mac

[greg-dove]

@joshtynjala, here are examples of the two sorts of issues (please see the 'comments' I added in the code excerpts):
Example1 finding the wrong identifier (external class scope instead of local var):

public function set scale(value:Number):void {
	_scale = value;
	/** irrelevant code excluded here  **/
	if (background) {
		/** irrelevant code excluded here  **/
		
		var pageItems:Array = getPageItems();
		var len:int = pageItems.length; //this seems to work
		for (var i:int = 0; i < len; i++) {
			var element:PageItemObject = pageItems[i]; //this works
			element.setZoom(value); //when the problem happens, this can be output as :this.element.setZoom(value) (the class scope is derived from UIBase, so 'element' is known at that level)
		}
		
		/** irrelevant code excluded here  **/
	} else {
		trace('failed to set scale on ',this)
	}	
}

Example 2 (I think) of finding no identifier/type (because the same name does not exist in parent scopes):

override public function prepareIdms():XML {
	/** irrelevant code excluded here  **/
	var xml:XML = shape.prepareIdms();
	/** irrelevant code excluded here  **/
	super.prepareIdms();

	var imageXML:XMLList;
	switch (type) { //type is a public var class member 
		case "ai":
		case "pdf":
			imageXML = xml.PDF; //correct output is  xml.child('PDF'), bad output when it happens is xml["PDF"];
			break;
		case "eps":
			imageXML = xml.EPS;//correct output is  xml.child('EPS'), bad output when it happens is xml["EPS"];
			break;
		/** pattern continues, output errors continue if they have already begun **/	
		
	} //switch/case ends
	imageXML.Properties.GraphicBounds.@Top = "0"; //this second variable also fails when the first one does, it outputs as imageXML["Properties"]["GraphicBounds"].setAttribute('Top', "0"); when it should output correctly as :imageXML.child('Properties').child('GraphicBounds').setAttribute('Top', "0"); 
	
	/** irrelevant code excluded here, problems continue  **/
	
	
	return xml;
}

Comments:
I think that when it happens, it likely happens for all local vars inside the function scope. But the problem only manifests when there is another equivalent name in an external scope, or there is some special handling of the properties or methods in the compiler based on the type (that is not being found).
So in many cases if a failed lookup is (for example) used in multiplication
var a:Number = 10;
var b:Number = 12 * a;
then I think neither the declaration of either nor the use of 'a' has any side effects. Perhaps if it happened in swf generation it might have some problems in the output... ? But we're only looking at js.
And if there was a call like:
var s:String = a.toFixed(2);
and lookup of 'a' failed, so 'Number' type was not known, then it would probably be output as var s = a['toFixed'](2); and it would still work.
The above is not 100% verified, just my current thinking.

I can send more details about the above I can probably send a good/bad build fileset privately to you - let me know. But those extractions are the basic types of comparisons...

[joshtynjala]

I think you're right that, often, there are no side effects, and the emitted JS is frequently correct even without resolving the definitions properly. If we're lucky, it's happening more often than we realized, and that'll make it easier to detect.

One thing that I took note of yesterday while I was trying to reproduce is the fact that MethodEmitter calls parseFunctionBody() on the FunctionNode, and parseFunctionBody() automatically calls runPostProcess() with the scope and all of the necessary PostProcessStep flags. I mentioned in an earlier comment that I thought that the runPostProcess() call was missing, but it doesn't seem to be. That makes me wonder if parseFunctionBody() might be returning early without detecting that the scope isn't populated.

[joshtynjala]

I think that I reproduced the issue a couple of times today while building the JS SWCs in royale-asjs. I added some code in FunctionNode.parseFunctionBody() to try to detect it.

In that method, there's an early return when the function body already has children: if (contents.getChildCount() > 0), and I added the code there.

In that case, I had it check if the body AST contains local variable declarations. If it does, it checks if any non-parameters have been added to the scope: if (!anyNonParametersInScope(contents) && hasLocalVars(contents)).

If no variables are in the scope, then the compiler is currently reproducing the issue.

Unfortunately, I ran hundreds of builds today, and it happened only twice. And I haven't quite figured out which data to output that might give me more clues, so other than confirming that I can reproduce, it wasn't very helpful. I really need to come up with a way to force it to reproduce more frequently.

Adding my current implementation of hasLocalVars(), which skips certain nodes that would be considered false positives.

private static boolean hasLocalVars(IASNode node)
{
    for (int i = 0; i < node.getChildCount(); i++)
    {
        IASNode child = node.getChild(i);
        if (child instanceof IVariableNode || child instanceof IVariableExpressionNode)
        {
            System.err.println("has local var: " + child);
            return true;
        }
        if (child instanceof IVariableExpressionNode)
        {
            System.err.println("has local var expression: " + child);
            return true;
        }
        if (child instanceof IFunctionObjectNode || child instanceof IFunctionNode)
        {
            // don't bother checking local functions
            continue;
        }
        if (child instanceof ICatchNode)
        {
            // catch has its own scope
            continue;
        }
        if (child.getChildCount() > 0 && hasLocalVars(child))
        {
            return true;
        }
    }
    return false;
}

[greg-dove]

It sounds like you're getting close, for sure. I can devote more time to this on Friday if there's anything more I can do to help. I am also quite keen to see the end of this.
re "Unfortunately, I ran hundreds of builds today, and it happened only twice" - that sounds about right to me. It is the most frustrating thing about this bug. I do think it might be more frequent with memory pressure causing GC, but this seems not as easy to force as I expected either (perhaps this might be related to use of 'Soft' references in caches instead of 'Weak' references, idk).
lmk if there's anything you want me to delve into on my Friday.

[joshtynjala]

Interesting. A SoftReference appears to be similar to a WeakReference, except that the GC will try to avoid collecting it if it has been accessed recently. So it might be easier to reproduce by temporarily replacing SoftReference with WeakReference.

[joshtynjala]

No luck reproducing at all today, unfortunately. Four full days digging into this wore me out, so I may need a little break before I dive in again.

I don’t really have any strong suggestions of things that you should try.

It seems that the function node has a body that has not been discarded, and the body contains local variables, but there are no definitions for those variables in the function scope.

When the old/stale definitions are removed from the scope when reconnecting the node, I wonder if hasBeenParsed might be incorrect sometimes. Maybe it also needs the check the ScopedBlockNode’s child count. If it is greater than 0, it probably shouldn’t remove the definitions from the scope.

As best I can tell, once the compiler starts emitting JS, it’s all single threaded. So if there’s a race condition, it’s happening somewhere before that.

[greg-dove]

I know what it's like! I had the same feeling, and have spent similar amounts of time on it the first time around.
I kept going today. I even went back to the develop commit before your last commit, just in case, trying to find a repro. I have had likewise another gruelling day on this, and no repro today.
But I discovered things like:-XX:SoftRefLRUPolicyMSPerMB=0 -verbose:gc as jvm args, which I was unfamiliar with. So I coupled those settings with low -Xmx to have GC triggered frequently.
SoftRefLRUPolicyMSPerMB=0 makes soft references behave as close as possible to weak references, without changing the code (but even so, they are still somewhat more persistent than real weak references).
Anyway, I will try again for a bit tomorrow morning...

[joshtynjala]

I've been able to reproduce this issue somewhat consistently today. I've found that when I build MXRoyaleBaseJS.swc, then specifically the getClassInfo() method on mx.utils.ObjectUtil has a tendency to be missing definitions for its local variables. It can still take dozens of builds, but at least I'm not going hours or days between reproductions.

I'm currently leaning toward a race condition between FunctionNode.parseFunctionBody() and the code that I added to FunctionScope.reconnectScopeNode() in commit 35eed62. That code is doing the correct thing, but it's not using thread synchronization, so I suspect that it may be removing local definitions after or at the same time that parseFunctionBody() adds them. I'm currently trying to see if I can reproduce in a way that confirms that this is indeed the case.

[joshtynjala]

Wrapping that code in the same lock as parseFunctionBody() does not help. The only other place that removes stuff from the cache is discardFunctionBody(), but that's also wrapped in the lock.

I'm not very familiar with what the compiler calls a "scope cache" and what exactly its purpose is. I haven't had to touch that part of the code before. However, I think that's the next place I want to investigate. Your PR adds a call to resetScopeCaches() when reconnecting a scope with a node, so maybe something is funky with the cache.

[Harbs]

Sounds fun... 🙈

Have you tried running this through different LLMs?

[joshtynjala]

Wrapping that code in the same lock as parseFunctionBody() does not help.

I spoke too soon! I decided to try one last minor tweak that included just a little more code in the locked section, and I think that may actually be what was needed. I started a script last night that built MXRoyaleBaseJS.swc in a repeated loop, and I let it run overnight. It's still going over 12 hours later without reproducing the issue. I'll try to commit it later, and you guys can give it a try.

[greg-dove]

Thanks for your persistence with this @joshtynjala, that sounds good... I'll see what you did for that tomorrow - and look forward to trying that!

[joshtynjala]

I confirm that I can still reproduce with the project that was shared with me privately.

Just recording a couple of pieces of additional context.

1. I am on Linux, and Greg mentioned above that it also reproduces on both Windows and macOS. So it definitely affects all operating systems.

2. If I modify the compiler to disable the definition caching system, it still reproduces.

DefinitionBase.setPerformanceCachingEnabled(false);

[joshtynjala]

Not only can I reproduce with the project shared with my privately, I can reproduce much more frequently with it.

I'm observing that all of the methods where the issue is reproducing on my machine contain at least one local function inside the method body. This catches my attention because discardFunctionBody() will not discard the body of a function that contains any local functions. That was not the case when the code was originally donated by Adobe, though. The requirement to keep function bodies that contain local function was introduced way back in the following commit from FlexJS 0.6.0 in 2015: f0ebbf0

What I think is happening:

1. discardFunctionBody() is called. The body is not discarded because it contains local functions.

2. Another thread is calling runPostProcess(EnumSet.of(PostProcessStep.POPULATE_SCOPE)), which creates a new FunctionScope. However, the set does not include PostProcessStep.RECONNECT_DEFINITIONS, which is what would make it populate the scope.

3. parseFunctionBody() is called. It returns early because the body contains children. There would be no children in Adobe's original code. In that case, they would be parsed, and then a second thing would happen: runPostProcess(EnumSet.of(PostProcessStep.CALCULATE_OFFSETS, PostProcessStep.POPULATE_SCOPE, PostProcessStep.RECONNECT_DEFINITIONS)) would be called. That would create a new FunctionScope and populate it.

I'm going to revisit the changes made in f0ebbf0 to hopefully make some helpful tweaks.

[greg-dove]

Hi Josh, that sounds like a good clue, at least for that scenario. But, unfortunately, I can confirm we have seen this occur inside methods that did not have local functions. And also in methods with or without loops (as another potential suspect). We have seen it inside regular methods and inside setters. It also does not appear to be completely random in terms of where it occurs, it can occur in the same places when it does occur. However the pattern does not seem obvious yet. There could perhaps be more than one thing here.
But it does sound like you have found something!

[joshtynjala]

It also does not appear to be completely random in terms of where it occurs, it can occur in the same places when it does occur.

In MXRoyaleBaseJS, it always happens in the same method (ObjectUtil.getClassInfo()) for me, so that makes sense.

[joshtynjala]

inside setters

I noticed that the code for emitting setters to JS is kind of complicated. Getters and setters get deferred to a later step that emits a combined defineProperties() call for all properties, unlike regular methods. There is also separate branches for [Bindable] stuff. I wonder if one of those branches misses parseFunctionBody() or something like that. Setters often don't have local variables, so this could be something that doesn't get noticed easily.

[joshtynjala]

I came up with an improved way to detect missing definitions in a function scope. I confirm that it is also detecting methods and setters that don't have local functions inside the body.

In the org.apache.royale.compiler.internal.codegen.as.ASEmitter Java class, add the following to the beginning of emitMethodScope():

public void emitMethodScope(IScopedNode node)
{
    IDefinitionNode nodeWithMissingDef = findNodesWithMissingDefinitions(node, node);
    if (nodeWithMissingDef != null)
    {
        throw new RuntimeException("*** missing definition for node: " + nodeWithMissingDef);
    }

It requires these two new methods to be added inside the same Java class:

private static IDefinitionNode findNodesWithMissingDefinitions(IASNode node, IScopedNode blockNode)
{
    for (int i = 0; i < node.getChildCount(); i++)
    {
        IASNode child = node.getChild(i);
        if (child instanceof IVariableNode)
        {
            IVariableNode varNode = (IVariableNode) child;
            if (!hasDefinitionInScopeForNode(varNode, blockNode))
            {
                return varNode;
            }
        }
        if (child instanceof IVariableExpressionNode)
        {
            IVariableExpressionNode varExprNode = (IVariableExpressionNode) child;
            IVariableNode varNode = varExprNode.getTargetVariable();
            if (!hasDefinitionInScopeForNode(varNode, blockNode))
            {
                return varNode;
            }
        }
        if (child instanceof IFunctionNode)
        {
            IFunctionNode funcNode = (IFunctionNode) child;
            if (!hasDefinitionInScopeForNode(funcNode, blockNode))
            {
                return funcNode;
            }
            // local function bodies have their own scope
            continue;
        }
        if (child instanceof IFunctionObjectNode)
        {
            // anonymous function bodies have their own scope
            continue;
        }
        if (child instanceof ICatchNode)
        {
            // catch has its own scope and will trigger false-positives
            continue;
        }
        if (child.getChildCount() > 0)
        {
            IDefinitionNode foundNode = findNodesWithMissingDefinitions(child, blockNode);
            if (foundNode != null)
            {
                return foundNode;
            }
        }
    }
    return null;
}

private static boolean hasDefinitionInScopeForNode(IDefinitionNode node, IScopedNode contents)
{
    IASScope sc = contents.getScope();
    Collection<IDefinition> ldfs = sc.getAllLocalDefinitions();
    for (IDefinition def : ldfs)
    {
        if (def instanceof IParameterDefinition)
        {
            continue;
        }
    
        if (def.getBaseName().equals(node.getName()))
        {
            return true;
        }
    }
    return false;
}

[joshtynjala]

Please give commit 2454b69 a try. Thanks!

[joshtynjala]

Please give commit 2454b69 a try. Thanks!

I compiled both MXRoyaleBaseJS and the project shared with me privately in a loop 1000+ times each over the course of many hours. I can't reproduce anymore. Without that commit, I could often reproduce in 10 builds or less using the code in this comment to detect it. Fingers crossed that this fixes it for you guys too!