RuntimeException when loading a saved game

[allyourcodearebelongtous]

After saving a game (regardless whether to a save slot or normal) and restarting with a saved game following rror message gets displayed:

2020/04/02 18:19:03
[WUI] showError(you hit a bug! please report at openwig.googlecode.com and i'll fix it for you!
java.lang.RuntimeException: attempted index of non-table: null

stack trace: at @E:/webtempfiles/1d57e8f5-d1a5-4892-9b83-50b0c4c06716/_cartridge-new.enc:1244)

Reproduce as follows:

• quit a cartridge
• save the game
• restart the cartridge
• load from saved game

The messages is displayed every time a cartridge is started from a saved game. It is dsplayed only a short fraction of a second but is still displayed when you quit the cartridge. The message is generated in cz.matejcik.openwig.Engine.stacktrace().

I think it originates from Engine line 210 when calling restoreGame(). I don't think restoreGame does throw an IOException, as this would have resulted in a different message.

WhereYouGo version 2020.03.08

[bekuno]

Is this behavior only on a special cartridge?
This seems reproducible, isn't it?
Which Android version has the device?
Are you able to debug with AS and your Android device?

[allyourcodearebelongtous]

I didn't test with other cartridges, I admit. "Reverse Wherigo" from -Waldmeister- works fine, also another cartridge I downloaded just now.

I used Android 8 and the cartridge "Die Prüfung der Magier". The error message can be reproduced every time when loading a savegame of this cartridge.

I'll try and see if I can debug this with AS - alas I fear that I will enter rocky paths when entering the LUA part.

[bekuno]

No fear, it is all java.
It uses a java port for lua - kahlua: https://github.com/krka/kahlua .
It is a fork directly integrated in openWIG.

As info, the migration to kahlua2 was never finished.

[allyourcodearebelongtous]

I managed to connect to my device. It was just as easy as when I joined Google Dev Camp quite a few years ago. 😉 I am sure that the cartridge is the problem. I know the owner so I could ask for the source. Maybe the obfuscation is to be blamed. Am 3. April 2020 14:12:26 MESZ schrieb Bernd <[email protected]>:

…

No fear, it is all java. It uses a java port for lua - kahlua: https://github.com/krka/kahlua . It is a fork directly integrated in openWIG. As info, the migration to kahlua2 was never finished. -- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: #8 (comment)

[allyourcodearebelongtous]

I contacted the cartridge owner and received the urwigo project yesterday. Commencing debug initialization sequence... zehn... neun... acht... sieben... sechs... fünnef...

[allyourcodearebelongtous]

... and now the result:
If there are more than two active tasks (regardless if they are displayed or not) the RuntimeException regarding cartidge-new.enc is thrown when restoring a cartridge. I don't know whether this is only when playing Urwigo cartridges or if this is a general wherigo problem.

[allyourcodearebelongtous]

After a long series of tests I have to refine my last answer - which is obviously not correct. At least there were some circumstances that made it seem so. Shame on me.

I have created a skeleton Wherigo cartridge using Urwigo which crashes after reloading a saved game (regardless whether saved to a savegame slot or just normal backup saving after quitting a running game).

The cartridge consists of just one task, When the cartridge is started, the task changes to "completed". inside the cartridges onStart() event. When starting a new game everything works just as expected, no error message is shown - so I think kahlua isn't broken.

The Urwigo project is attached as a text file which can [easily be renamed to "Crash.urwigo" and] opened with Urwigo for test purposes. It is reduced to the very spot where the error occurs when restoring the saved state. The issue occurs when openwig tries to read (or does it execute?) the LUA source line 316 of the compiled (!) LUA code which reads "objCrash.Active = false". I am very confused why this happens while RESTORING a saved cartridge, because executing this line obviously does not crash.

Update: Made some minor changes so that the cartridge starts inside Urwigo emulator as well as using WhereYouGo. I also added a dummy task that stays active and displayed for some reasons not regarding the issue, just to run as expected in Urwigo emulator. The links below reflect those changes.

@bekuno: could you dive into this? My knowledge of openwig is very limited. There are a few issues in openwig referring to this problem. Especially this one:

Issue #245
[...]If you exit the game, save the current game and restart from the saved game, a java runtime
exception occurs.[...]

Here are some files to reproduce the error:
Project file created by Urwigo: Crash.urwigo
Example image, drop it in the Urwigo project folder: logo.jpg
LUA source code inside ZIP file generated by Urwigo with "Build package (gwz)" _cartridge.lua

[allyourcodearebelongtous]

Here's what I debugged so far. I was using a cartridge created by Earwigo this time. The GWC file shows the same behaviour which means that it is not a Urwigo problem. The cartridge was compiled online by the Groundspeak wherigo compiler - the LUA code for OnSetComplete in this case resides in line 266 (see below).

Savegame.java uses deserializeLuaTable() to read the saved state of the cartridge. After a lot of deserializing it reads the LUA code for the function OnSetComplete, which seems to be OK. Right after that I think it reaches the point of reading the saved state of the task which is "Complete".

Savegame:deserializeLuaTable()
[...]
	Savegame[340] table.rawset("OnSetComplete", LuaClosure "function @E:/webtempfiles/34414473-e787-4b84-8ffb-b661c7fcd04e/_cartridge.enc:266")
	Savegame[340] table.rawset("Complete", Boolean "true");
??->		EventTable[131] setItem("Complete", Boolean "true")
			Task[35] callEvent("OnSetComplete", null);
				EventTable[112] Engine.state.call(LuaClosure "function @E:/webtempfiles/34414473-e787-4b84-8ffb-b661c7fcd04e/_cartridge.enc:266, this, param, null);
					LuaState[1136] int nReturnValues = call(argslen);
						LuaState[217] luaMainloop();
							LuaState[359] tableSet(aObj, key, value);
--> aObj null, key "Active", value "false"

In the call of tableSet() aObj is null, consequently in LuaState.java line 1213 the following assertion fails:

BaseLib.luaAssert(metaOp != null, "attempted index of non-table");

I am quite sure that, while reading the saved state, openwig gets confused and runs LUA code instead continuing reading the saved file.

The call of table.rawset() in Savegame.java should not run setItem() which in turn runs callEvent().

Here's some code from EventTable.java:

public void rawset(Object key, Object value) {
		// TODO unify rawset/setItem
		if (key instanceof String) {
			setItem((String) key, value);
		}
		table.rawset(key, value);
		Engine.log("PROP: " + toString() + "." + key + " is set to " + (value == null ? "nil" : value.toString()), Engine.LOG_PROP);
	}

The TODO tag does sound a bit like unfinished code. The last entry about openwig on matejcik's techblog is

openwig news
Version 0.3.92 is underway.
Biggest spectacle of this is cartridge saving and loading. A few moments ago i have successfully stored and restored a game of Wherigo Player Tutorial.

I think the feature of restoring from a saved game is quite shiny and new, maybe it leads to the aforementioned problem, but definitely should not lead to actually running cartridge code.

Could someone (@Lineflyer, @matejcik, @biylda) who is able to understand, verify and correct the problem dig into the details?

[allyourcodearebelongtous]

My humble suggestion to the problem described in the above comment:

Savegame.java: call of table.rawset() with additional parameter:

	public LuaTable deserializeLuaTable (DataInputStream in, LuaTable table)
	throws IOException {
		level++;
		while (true) {
			byte next = in.readByte();
			if (next == LUATABLE_END) break;
			if (debug) for (int i = 0; i < level; i++) debug("  ");
			Object key = restoreValue(in, null);
			if (debug) debug(" : ");
			Object value = restoreValue(in, table.rawget(key));
			if (debug) debug("\n");
			table.rawset(key, value, true);
		}
		level--;
		return table;
	}

and additionally refactoring the methods in EventTable.java:

	public void rawset(Object key, Object value) {
		rawset(key, value, false);
	}

	public void rawset(Object key, Object value, boolean justdeserialize) {
		// TODO unify rawset/setItem
		if (!justdeserialize && key instanceof String) {
			setItem((String) key, value);
		}
		table.rawset(key, value);
		Engine.log("PROP: " + toString() + "." + key + " is set to " + (value == null ? "nil" : value.toString()), Engine.LOG_PROP);
	}

This should hopefully do the trick.

[allyourcodearebelongtous]

created Pull Request #10

[matejcik]

What a catch! this must have existed ever since OnSet* methods were implemented. Good job on debugging this.

The reason for this is actually here:

	public void serialize (DataOutputStream out) throws IOException {
		Engine.instance.savegame.storeValue(table, out);
	}

	public void deserialize (DataInputStream in) throws IOException {
		Engine.instance.savegame.restoreValue(in, this);
		//setTable(table);
	}

when serializing, the table is serialized, but when deserializing, it's this. It should be table again, in a perfect world.

Of course there is a reason for using this, which is that we want to call setItem for everything. Because that's how you update the instance variables, e.g., if you restore the table with Visible set, we need to call rawset -> setItem, where this.visible is set to the appropriate value.

Which is also why your PR #10 is incorrect: it breaks this functionality.

A slightly better fix would be something like:

private boolean isDeserializing = false;

public void deserialize(...) {
    isDeserializing = true;
    savegame.restoreValue(in, this);
    isDeserializing = false;
}

public void callEvent(...) {
    if (isDeserializing) return;
    // ...
}

an actually correct fix is to change restoreValue(in, this) to restoreValue(in, table), and then change code of EventTable and all its subclasses, so that the internal variables are set there.
As in:

public void deserialize(...) {
    savegame.restoreValue(in, table);
    visible = table.rawget("Visible");
    active = table.rawget("Active");
    // etc...
}

and do this for all subclasses.

---

Of course, the reason we have setItem in the first place is for performance; on J2ME phones I didn't want to do a hashtable lookup for what could have been a property access.
This haven't actually been a performance hit for about ten years now, so you could as well throw away much of setItem and look for table.rawget("Visible") whenever you need the visible property, etc. :)

[allyourcodearebelongtous]

I have rewritten the code in EventTable.java as suggested by matejcik (see "A slightly better fix" above). Pull Request is underway.
I did not want to break existing code by refactoring the suggested "actual correct fix".
Corresponding Pull Request #11