API: System.InvalidOperationException

[JMessmer]

I have regular problems when deleting nodes from the database. As a result I often get error messages that are misleading.

Example code:

function onValueChanged()
	DebugM.printLogMessage("ct/scripts/ct_verbleibendeAktionen.lua, onValueChanged");
	local kEintrag = window.getDatabaseNode();
	local sZustand = kEintrag.getChild("zustand").getValue();
	if sZustand == "aktiv" then
		local nWert = getValue();
		local sWieLange = window.schalterWieLange.getValue();
		if nWert < 0 and sWieLange == "Aktionen bis Ende" then
			kEintrag.delete();
		elseif nWert <= 0 and sWieLange == "Aktionen bis Start" then
			window.schalterWieLange.setStringValue("");
		end
	end
	DebugM.printLogMessage("ct/scripts/ct_verbleibendeAktionen.lua, onValueChanged");
end

when kEintrag.delete() is executed I get this in the console:
[10/15/2020 1:03:49 PM] [<color="red">ERROR</color>] Script execution error: [string "ct/scripts/ct_verbleibendeAktionen.lua"]:25: attempt to index global 'DebugM' (a nil value)
[10/15/2020 1:03:49 PM] [<color="red">ERROR</color>] API: System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
at System.Collections.Generic.HashSet`1+Enumerator[T].MoveNext () [0x00013] in <351e49e2a5bf4fd6beabb458ce2255f3>:0
at EIJJCOALCOI.BFABFBJHIFB () [0x0001a] in <04de8efd8cf249c3877f523b5237cdf8>:0
at GACFJBABIAJ.IKEFKKCPJBE (JJEKLHKGKBN DOAIEANCHCB) [0x00043] in <04de8efd8cf249c3877f523b5237cdf8>:0
at EIJJCOALCOI.NCMBFOFNKCA (JJEKLHKGKBN DOAIEANCHCB) [0x00008] in <04de8efd8cf249c3877f523b5237cdf8>:0
at MOGENOKIDAK.ODJMHHAJJFL (GACFJBABIAJ BGPKLCGBHPD, System.Int32 BPJOANDLKAL) [0x0006b] in <04de8efd8cf249c3877f523b5237cdf8>:0
at GACFJBABIAJ.FPJKCDMKBIP (System.IntPtr MDMHFAEJKAB) [0x00018] in <04de8efd8cf249c3877f523b5237cdf8>:0

DebugM is our custom DebugManager. It is defined with the other scripts in the file base.xml
Usually the reason is the last statement executed before the DebugM statement.

In my opinion there are two bugs:
1. error message not correct
2. db node deletion is not working properly

[Moon Wizard]

This seems to be related to the deletion or addition of display controls for a database node during an onValueChanged event handler for a control pointing at the same node. It's very cyclical, and I wouldn't recommend that approach. I would either loosely bind the controls by monitoring onAdd/onUpdate/onDelete database events to perform your behaviors; or just not delete the database nodes within a record like that (i.e. delete the whole subtree or none), and instead just clear the value.

I'll look at shoring up the code to prevent the error, but it won't make the next release which is already queued.

Regards,
JPG

[JMessmer]

Thanks for looking at the error message, JPG.
Btw, I get the same error when in the file ct/scripts/ct_entry.lua on the function delete:

...
        -- Delete the database node and close the window
	local cList = windowlist;
	node.delete();

	-- Update list information (global subsection toggles)
	cList.onVisibilityToggle();
	cList.onEntrySectionToggle();

after node.delete() it says that cList is nil.

[Moon Wizard]

That bit of code is used in several rulesets; so I'm fairly certain it works as expected.

Is that code getting called multiple times in your ruleset? Add some debug strings to see what is happening...

JPG

[JMessmer]

The code is called only once. This is just one example of many where strange things are happening in my ruleset with FGU. In FGC is works fine.

I changed the code and added two Debug steps:

...
        -- Move to the next actor, if this CT entry is active
	if DB.getValue(node, "active", 0) == 1 then
		CombatManager2.nextActor();
	end

	-- Delete the database node and close the window
	local cList = windowlist;
	Debug.console("ct/scripts/ct_entry.lua, delete : node", node);
	node.delete();

	-- Update list information (global subsection toggles)
	Debug.console("ct/scripts/ct_entry.lua, delete : cList", cList);
	if cList then
		cList.onVisibilityToggle();
		cList.onEntrySectionToggle();
	end
	DebugM.printLogMessage("ct/scripts/ct_entry.lua, delete, Ende");

This is the output of the console:

[10/19/2020 8:17:16 AM] s'ct/scripts/ct_entry.lua, delete : node' | databasenode = { combattracker.list.id-00001 }
[10/19/2020 8:17:16 AM] scripts/manager_combat.lua, onDeleteCombatantEvent
[10/19/2020 8:17:16 AM] scripts/manager_targeting.lua, onCTEntryDeleted
[10/19/2020 8:17:16 AM] scripts/manager_combat.lua, getCombatantNodes
[10/19/2020 8:17:16 AM] scripts/manager_combat.lua, getCombatantNodes, Ende
[10/19/2020 8:17:16 AM] scripts/manager_targeting.lua, onCTEntryDeleted, Ende
[10/19/2020 8:17:16 AM] scripts/manager_token.lua, onCombatantDelete
[10/19/2020 8:17:16 AM] scripts/manager_combat.lua, getTokenFromCT
[10/19/2020 8:17:16 AM] scripts/manager_combat.lua, getTokenFromCT, Ende
[10/19/2020 8:17:16 AM] scripts/manager_token.lua, onCombatantDelete, Ende
[10/19/2020 8:17:16 AM] scripts/manager_combat.lua, onDeleteCombatantEvent, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/string_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/string_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] ct/scripts/ct_target_summary.lua, onClose
[10/19/2020 8:17:16 AM] ct/scripts/ct_target_summary.lua, onClose, Ende
[10/19/2020 8:17:16 AM] ct/scripts/ct_effect_summary.lua, onClose
[10/19/2020 8:17:16 AM] ct/scripts/ct_effect_summary.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] ct/scripts/ct_listeHandlungen.lua, onClose
[10/19/2020 8:17:16 AM] ct/scripts/ct_listeHandlungen.lua, onClose, Ende
[10/19/2020 8:17:16 AM] ct/scripts/ct_listeHandlungen.lua, onClose
[10/19/2020 8:17:16 AM] scripts/manager_combat2.lua, getHauptebeneCT
[10/19/2020 8:17:16 AM] scripts/manager_combat2.lua, getHauptebeneCT, Ende
[10/19/2020 8:17:16 AM] ct/scripts/ct_listeHandlungen.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/string_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/string_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] ct/scripts/ct_listeHandlungen.lua, onClose
[10/19/2020 8:17:16 AM] scripts/manager_combat2.lua, getHauptebeneCT
[10/19/2020 8:17:16 AM] scripts/manager_combat2.lua, getHauptebeneCT, Ende
[10/19/2020 8:17:16 AM] ct/scripts/ct_listeHandlungen.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/string_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/string_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose
[10/19/2020 8:17:16 AM] common/scripts/number_crosslink.lua, onClose, Ende
[10/19/2020 8:17:16 AM] [<color="red">ERROR</color>]  Script execution error: [string "ct/scripts/ct_entry.lua"]:114: attempt to index global 'Debug' (a nil value)
[10/19/2020 8:19:17 AM] desktop/scripts/characterlist.lua, onUserStateChange
[10/19/2020 8:19:17 AM] desktop/scripts/characterlist.lua, onUserStateChange, Ende

I checked the log and found no other occurence of "ct/scripts/ct_entry.lua, delete"
The behaviour is deterministic and happens when deleting a combatant in the CT.

I receive the same kind of error message when deleting an effect in the CT (1st post) via script. Or it happens when a player is leaving the game session.

[Moon Wizard]

The thing is that it doesn't happen in other rulesets; so there must be some unique order that you are calling the code in that is causing an issue.

* Are you saving references to windows to trigger events through script directly? Perhaps those windows are already deleted when you do that?
* Try using Debug.printstack() right before node.delete() to see what the call chain is; so you can see where the reference to a deleted object might be coming from.

FGC uses a lazy deletion mechanism which means that windows will hang around for an extra frame; whereas FGU was optimized to immediately remove deleted objects within the same frame for performance reasons.

Regards,
JPG

[JMessmer]

I totally agree, JPG, there must be a difference to other rulesets and also a logical reason for the problem. I only fail to see it yet.

Thanks for your suggestion with the stacktrace. However, I still don't see anything suspicious:

ct_entry.lua:

function delete()
	DebugM.printLogMessage("ct/scripts/ct_entry.lua, delete");
	local node = getDatabaseNode();
	if not node then
		close();
		DebugM.printLogMessage("ct/scripts/ct_entry.lua, delete, Ende - kein Knoten");
		return;
	end
	
	-- Remember node name
	local sNode = node.getNodeName();
	
	-- Clear any effects and wounds first, so that saves aren't triggered when initiative advanced
	effects.reset(false);
	
	-- Move to the next actor, if this CT entry is active
	if DB.getValue(node, "active", 0) == 1 then
		CombatManager2.nextActor();
	end

	-- Delete the database node and close the window
	local cList = windowlist;
	Debug.console("ct/scripts/ct_entry.lua, delete : node", node);
	Debug.printstack();
	node.delete();

	-- Update list information (global subsection toggles)
	Debug.printstack(); -- error happens here
	Debug.console("ct/scripts/ct_entry.lua, delete : cList", cList);
	if cList then
		cList.onVisibilityToggle();
		cList.onEntrySectionToggle();
	end
	DebugM.printLogMessage("ct/scripts/ct_entry.lua, delete, Ende");
end

console output:

[10/20/2020 2:20:16 PM] ct/scripts/ct_entry.lua, onMenuSelection
[10/20/2020 2:20:16 PM] ct/scripts/ct_entry.lua, delete
[10/20/2020 2:20:16 PM] ct/scripts/ct_effectlist.lua, reset
[10/20/2020 2:20:16 PM] ct/scripts/ct_effectlist.lua, reset, Ende
[10/20/2020 2:20:16 PM] s'ct/scripts/ct_entry.lua, delete : node' | databasenode = { combattracker.list.id-00001 }
[10/20/2020 2:20:16 PM] 
stack traceback:
	[string "ct/scripts/ct_entry.lua"]:111: in function 'delete'
	[string "ct/scripts/ct_entry.lua"]:83: in function <[string "ct/scripts/ct_entry.lua"]:80>
[10/20/2020 2:20:16 PM] scripts/manager_combat.lua, onDeleteCombatantEvent
[10/20/2020 2:20:16 PM] scripts/manager_targeting.lua, onCTEntryDeleted
[10/20/2020 2:20:16 PM] scripts/manager_combat.lua, getCombatantNodes
[10/20/2020 2:20:16 PM] scripts/manager_combat.lua, getCombatantNodes, Ende
[10/20/2020 2:20:16 PM] scripts/manager_targeting.lua, onCTEntryDeleted, Ende
[10/20/2020 2:20:16 PM] scripts/manager_token.lua, onCombatantDelete
[10/20/2020 2:20:16 PM] scripts/manager_combat.lua, getTokenFromCT
[10/20/2020 2:20:16 PM] scripts/manager_combat.lua, getTokenFromCT, Ende
[10/20/2020 2:20:16 PM] scripts/manager_token.lua, onCombatantDelete, Ende
[10/20/2020 2:20:16 PM] scripts/manager_combat.lua, onDeleteCombatantEvent, Ende
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose, Ende
[.. plenty of those number_crosslink-closes ..]
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose, Ende
[10/20/2020 2:20:16 PM] common/scripts/string_crosslink.lua, onClose
[10/20/2020 2:20:16 PM] common/scripts/string_crosslink.lua, onClose, Ende
[10/20/2020 2:20:16 PM] ct/scripts/ct_target_summary.lua, onClose
[10/20/2020 2:20:16 PM] ct/scripts/ct_target_summary.lua, onClose, Ende
[10/20/2020 2:20:16 PM] ct/scripts/ct_effect_summary.lua, onClose
[10/20/2020 2:20:16 PM] ct/scripts/ct_effect_summary.lua, onClose
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose, Ende
[10/20/2020 2:20:16 PM] ct/scripts/ct_listeHandlungen.lua, onClose
[10/20/2020 2:20:16 PM] ct/scripts/ct_listeHandlungen.lua, onClose, Ende
[10/20/2020 2:20:16 PM] ct/scripts/ct_aktionenBeiINI.lua, onClose
[10/20/2020 2:20:16 PM] scripts/manager_combat2.lua, getHauptebeneCT
[10/20/2020 2:20:16 PM] scripts/manager_combat2.lua, getHauptebeneCT, Ende
[10/20/2020 2:20:16 PM] s'ct/scripts/ct_aktionenBeiINI.lua, onClose : kHauptebeneCT' | databasenode = { combattracker.list.id-00001 }
[10/20/2020 2:20:16 PM] s'ct/scripts/ct_aktionenBeiINI.lua, onClose : kInitresultGewuerfelt' | databasenode = { combattracker.list.id-00001.initresultGewuerfelt }
[10/20/2020 2:20:16 PM] s'ct/scripts/ct_aktionenBeiINI.lua, onClose : nodeActionsOnINI' | nil
[10/20/2020 2:20:16 PM] ct/scripts/ct_aktionenBeiINI.lua, onClose, Ende
[10/20/2020 2:20:16 PM] ct/scripts/ct_aktionenBeiINI.lua, onClose
[10/20/2020 2:20:16 PM] scripts/manager_combat2.lua, getHauptebeneCT
[10/20/2020 2:20:16 PM] scripts/manager_combat2.lua, getHauptebeneCT, Ende
[10/20/2020 2:20:16 PM] s'ct/scripts/ct_aktionenBeiINI.lua, onClose : kHauptebeneCT' | databasenode = { combattracker.list.id-00001 }
[10/20/2020 2:20:16 PM] s'ct/scripts/ct_aktionenBeiINI.lua, onClose : kInitresultGewuerfelt' | databasenode = { combattracker.list.id-00001.initresultGewuerfelt }
[10/20/2020 2:20:16 PM] s'ct/scripts/ct_aktionenBeiINI.lua, onClose : nodeActionsOnINI' | nil
[10/20/2020 2:20:16 PM] ct/scripts/ct_aktionenBeiINI.lua, onClose, Ende
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose, Ende
[.. plenty of those number_crosslink-closes ..]
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose
[10/20/2020 2:20:16 PM] common/scripts/number_crosslink.lua, onClose, Ende
[10/20/2020 2:20:16 PM] [<color="red">ERROR</color>]  Script execution error: [string "ct/scripts/ct_entry.lua"]:115: attempt to index global 'Debug' (a nil value)

As for your 2nd question I think that I can say that there should not be any deleted object in the call sequence.
The 1st question is more difficult to answer. I have not been working on the ruleset alone. I am not aware of any references to windows. I think I should see a log entry of a function in the console if anything was being triggered. Since I don't see anything I doubt that there is any.
The error message is still misleading. Is there any way to tell what reference FGU is really missing or to give the stacktrace of the code at that point of time?

[Moon Wizard]

Currently, there is no way to generate a stack trace on error. However, inserting Debug.printstack just before the error line should do the same thing.

I would personally disable all the other Debug output events; as those are just confusing the issue and will fill the console log with unneeded information to resolve this issue.

It looks like some sort of event is registered in onCTEntryDeleted that is deleting the windowlist object that was saved off just prior to calling node.delete(). Perhaps your code is rebuilding the CT lists on a deleted entry?

Regards,
JPG

[JMessmer]

onCTEntryDeleted is part of the TargetManager, which is a copy of the code from CORE. This is not the reason, unfortunately.
I still don't understand why it is complaining about an object that actually exists "Debug".

Your assumption is, that the node is being deleted and at the same time or shortly after another process is trying to update the node, right? But this process is not visible in the log which makes it really hard to find.

[Moon Wizard]

No, my theory is that the windowlist that was saved off prior to the node deletion is itself getting deleted.

How does the CT work in your system? Does it remove or create window lists in the CT?

Regards,
JPG