Bug with timers

[Eric Walch]

Yesterday Oolite crashed while playing Lave Academy. Looking at the code I now think there must be a bug with timers in Oolite itself.

What happened:
The oxp sets up a buoy with a repeating timer:

Code: Select all

this.playerScanTimer = new Timer(this, this.rangeCheck, 0, 1);

Than I got a the message: "Pilot test expired, please return to the Academy." and Oolite almost immediately crashed after showing this message. At this moment the code uses the remove() command to remove the buoy with the ship-script that contained the timer. About the same time the script generatet the error

Code: Select all

Oolite [script.javaScript.exception.206] OOJavaScriptEngine.m:136: ***** JavaScript exception: Error: Vector3D.distanceTo: Could not construct vector from parameters (undefined) -- expected Vector, Entity or array of three numbers.
Oolite [script.javaScript.exception.206] OOJavaScriptEngine.m:147:       /Applications/Games/Oolite/AddOns/Lave Academy 1.00.oxp/Scripts/laveAcademy_pilotCircuitBuoy.js, line 29.

in the log. line 29 reads as:

Code: Select all

this.buoyDistance = player.ship.position.distanceTo(this.ship.position);

This line looks correct to me so I get the feeling the timer fired at a moment this.ship didn't exist anymore.

This leaded to an Oolite crash with crashlog

Code: Select all

Thread 0 Crashed:
0   libobjc.A.dylib                	0x90a4aca0 _objc_trap + 0
1   libobjc.A.dylib                	0x90a4ac14 _objc_error + 76
2   libobjc.A.dylib                	0x90a4aba4 __objc_error + 64
3   org.aegidian.oolite            	0x000f1990 -[OODebugMonitor(Private) jsEngine:context:error:stackSkip:withMessage:] + 260 (crt.c:355)
4   org.aegidian.oolite            	0x00059874 ReportJSError + 588 (crt.c:355)
5   org.aegidian.oolite            	0x001382bc js_ReportUncaughtException + 540 (crt.c:355)
6   org.aegidian.oolite            	0x00180934 JS_CallFunction + 96 (crt.c:355)
7   org.aegidian.oolite            	0x000599cc -[OOJavaScriptEngine callJSFunction:forObject:argc:argv:result:] + 80 (crt.c:355)
8   org.aegidian.oolite            	0x000edd0c -[OOJSTimer timerFired] + 112 (crt.c:355)
9   org.aegidian.oolite            	0x000eca48 +[OOScriptTimer updateTimers] + 168 (crt.c:355)
10  org.aegidian.oolite            	0x00075a24 -[PlayerEntity update:] + 116 (crt.c:355)
11  org.aegidian.oolite            	0x000386f0 -[Universe update:] + 1968 (crt.c:355)
12  org.aegidian.oolite            	0x0000eddc -[GameController doPerformGameTick] + 136 (crt.c:355)
13  com.apple.Foundation           	0x92be8e88 __NSFireTimer + 116
14  com.apple.CoreFoundation       	0x907f2390 __CFRunLoopDoTimer + 184
15  com.apple.CoreFoundation       	0x907ded08 __CFRunLoopRun + 1680
16  com.apple.CoreFoundation       	0x907de2bc CFRunLoopRunSpecific + 268
17  com.apple.HIToolbox            	0x9329db20 RunCurrentEventLoopInMode + 264
18  com.apple.HIToolbox            	0x9329d12c ReceiveNextEventCommon + 244
19  com.apple.HIToolbox            	0x9329d020 BlockUntilNextEventMatchingListInMode + 96
20  com.apple.AppKit               	0x937a2bc4 _DPSNextEvent + 384
21  com.apple.AppKit               	0x937a2888 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 116
22  com.apple.AppKit               	0x9379edcc -[NSApplication run] + 472
23  com.apple.AppKit               	0x9388f974 NSApplicationMain + 452
24  org.aegidian.oolite            	0x000025f4 _start + 340 (crt.c:272)
25  org.aegidian.oolite            	0x0000249c start + 60

Although I think the fault is not in the crashlog but happened because it executed code of a removed script.

[Eric Walch]

I have in UPS also one ship with a timer in its script. I remember I had some problems back then when I added it and solved it by stopping the timer in the death actions and on docking. Now I added the ship by the console and also used the remove action on that ship. No problem.
Than removed the line that stops the timer on shipDied(). Now I had similar result as with the academy: Oolite crashes. As extra info I now see the message: Hostile BOA killed by null by means of energy damage. This message is generated by the shipDied() function. After that message the the timer seems to be running.

Code: Select all

Oolite [UPS-Courier] OOJSGlobal.m:165: Hostile BOA killed by null by means of energy damage
Oolite [script.javaScript.exception.206] OOJavaScriptEngine.m:136: ***** JavaScript exception: Error: Vector3D.distanceTo: Could not construct vector from parameters ([object Ship]) -- expected Vector, Entity or array of three numbers.
Oolite [script.javaScript.exception.206] OOJavaScriptEngine.m:147:       /Applications/Games/Oolite/AddOns/UPS-courier v1.5.2.oxp/Scripts/upsBoa.js, line 59.

Code: Select all

Thread 0 Crashed:
0   libobjc.A.dylib                	0x90a410f8 objc_msgSend + 24
1   org.aegidian.oolite            	0x000f1990 -[OODebugMonitor(Private) jsEngine:context:error:stackSkip:withMessage:] + 260 (crt.c:355)
2   org.aegidian.oolite            	0x00059874 ReportJSError + 588 (crt.c:355)
3   org.aegidian.oolite            	0x001382bc js_ReportUncaughtException + 540 (crt.c:355)
4   org.aegidian.oolite            	0x00180934 JS_CallFunction + 96 (crt.c:355)
5   org.aegidian.oolite            	0x000599cc -[OOJavaScriptEngine callJSFunction:forObject:argc:argv:result:] + 80 (crt.c:355)
6   org.aegidian.oolite            	0x000edd0c -[OOJSTimer timerFired] + 112 (crt.c:355)
7   org.aegidian.oolite            	0x000eca48 +[OOScriptTimer updateTimers] + 168 (crt.c:355)
8   org.aegidian.oolite            	0x00075a24 -[PlayerEntity update:] + 116 (crt.c:355)
9   org.aegidian.oolite            	0x000386f0 -[Universe update:] + 1968 (crt.c:355)
10  org.aegidian.oolite            	0x0000eddc -[GameController doPerformGameTick] + 136 (crt.c:355)
11  com.apple.Foundation           	0x92be8e88 __NSFireTimer + 116
12  com.apple.CoreFoundation       	0x907f2390 __CFRunLoopDoTimer + 184
13  com.apple.CoreFoundation       	0x907ded08 __CFRunLoopRun + 1680
14  com.apple.CoreFoundation       	0x907de2bc CFRunLoopRunSpecific + 268
15  com.apple.HIToolbox            	0x9329db20 RunCurrentEventLoopInMode + 264
16  com.apple.HIToolbox            	0x9329d12c ReceiveNextEventCommon + 244
17  com.apple.HIToolbox            	0x9329d020 BlockUntilNextEventMatchingListInMode + 96
18  com.apple.AppKit               	0x937a2bc4 _DPSNextEvent + 384
19  com.apple.AppKit               	0x937a2888 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 116
20  com.apple.AppKit               	0x9379edcc -[NSApplication run] + 472
21  com.apple.AppKit               	0x9388f974 NSApplicationMain + 452
22  org.aegidian.oolite            	0x000025f4 _start + 340 (crt.c:272)
23  org.aegidian.oolite            	0x0000249c start + 60

------
Than I added

Code: Select all

this.checkPlayer = function()
{
	if(this.ship && !this.ship.isValid) {log(this.name, "ERROR detected, this.ship undefined");return;}

in my timer function. After killing the ship by the remove() I see in the log.

Code: Select all

Oolite [UPS-Courier] OOJSGlobal.m:165: Hostile BOA killed by null by means of energy damage
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [shipRegistry.selection.profile] Universe.m:2853: Hit slow path in ship selection for role "police", having selected ship "quaestor". Now 10 of 232 on slow path (4.310345%).
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined
Oolite [upsBoa] OOJSGlobal.m:165: ERROR detected, this.ship undefined

No crash this time but the timer really keeps running when the ship has died. Even when I jumped to another system the timer kept running.

----

As a last check I did not kill the ship but just jumped to an other system. The timer still logged its messages into the log file. It kept active!

This also means that my last UPS version can crash Oolite when the player jumps out of the system during the boa mission.!

----
Even worse, I can't kill the timer anymore after jumping out. I tried:

Code: Select all

this.checkPlayer = function()
{
	if(this.ship && !this.ship.isValid) 
	{
		log(this.name, "ERROR detected, this.ship is undefined");
		if(this.checkPlayerTimer) delete this.checkPlayerTimer	
		return;
	}

But the timer keeps running. this.checkPlayerTimer is not true anymore but the underlying timer is still doing its job.

[Eric Walch]

It was mentioned above: repeating timers have a bug. Oolite does not remove them automatically. For a world script that is no problem as that script is always there. But for a ship script that becomes a problem when the ship is removed. It leaded to crashes on my machine.

I had this on a mac and Svengali just tested it on windows. There the timer stayed also active.
With current Oolite we need to explicit stop the timer before the ship is removed. Depending on what the ship does that is in: this.shipDied(), this.shipDocked(), this.shipWillEnterWormhole()

Leaves the situation were the player jumps to an other system. This we currently cant catch but the ship is removed and not valid anymore. This being invalid can be caught within the timer function itself. See next example code:

Code: Select all

this.shipSpawned = function()
{
	this.shipTimer = new Timer(this, this.testTimer, 10, 10)
    delete this.shipSpawned;
}

this.testTimer = function()
{
	if(this.ship && !this.ship.isValid) 
	{
		log(this.name, "ERROR detected; Timer fired but this.ship is undefined");
		if(this.shipTimer) {this.shipTimer.stop(); delete this.shipTimer}
		return;
	}
	// here goes your timer code.
}

This code seems to work. So when you insist on repeating timers in ships scripts use a similar code to catch this bug and silence the timer.

[Kaks]

Very good points!

Maybe I'm being over cautious here, but I'd check an extra condition: namely, where it says:

Code: Select all

if(this.ship && !this.ship.isValid) 

I would write

Code: Select all

if(!this.ship || this.ship && !this.ship.isValid) 

just to make sure we've covered every single possibility...

[JensAyton]

Code: Select all

if(!this.ship || this.ship && !this.ship.isValid) 

just to make sure we've covered every single possibility...

Or equivalently, if (!this.ship || !this.ship.isValid).

Note: my position on the timer issue is that it’s not a bug that timers don’t automatically stop, since they aren’t inherently connected to the ship or the ship script, although Oolite should be able to detect that situation and at the very least not crash. It is a bug that there’s no general cleanup event (e.g. shipRemoved()) for ships becoming invalid.

[Kaks]

I've added the example above to the timers reference page, so hopefully this timer 'feature' won't catch other OXP makers by surprise.

[Eric Walch]

I've added the example above to the timers reference page, so hopefully this timer 'feature' won't catch other OXP makers by surprise.

One other good cleanup moment is when playerWillEnterWitchspace fires for NPC ships that are not yet dead.

But to be foolproof I now placed my repeating timers in the wordScript itself. e.g. for my addition of ore processor the scooped sprinters start a timer placed in the mainscript. A bit more work in programming but it gives me a better feeling after all those crashes.