@Devs - my full crash log

[Lestradae]

I was following Ahruman's advice ...

One general crash testing tip, when there’s no indication of the cause: add a file called “logcontrol.plist” to your AddOns folder, with the following contents:Code:
{
_override = yes;
}

This will cause every possible log message to be written. Note that this will cause the log file to grow at a rate of several megabytes per minute, and quite likely slow your game down! But if the same message appears at the bottom each time, you might be closer to an actual cause.

Things in my log that I find interesting, perhaps some people have a look at it:

[dataCache.set.success]: Updated entry modification dates in cache "search path modification dates".
[dataCache.retrieve.failed]: Failed to retreive"dictionaries" cache object Config/descriptions.plist merge:basic -- no such cache.
[gnustep]: 2009-09-02 09:16:44.646 oolite[5660] could not convert to UTF8 string! bytes=0fea1c59 len=6

[dataCache.set.success]: Updated entry Config/descriptions.plist merge:basic in cache "dictionaries".
[dataCache.retrieve.failed]: Failed to retreive"ship registry" cache object ship data -- no such cache.
[dataCache.retrieve.failed]: Failed to retreive"ship registry" cache object player ships -- no such cache.

I got loads and loads of the following - yet the models are there! For example the "neomoray.dat". It's there.

[dataCache.retrieve.failed]: Failed to retreive"resolved paths" cache object Models/neomoray.dat -- no such cache.
[resourceManager.foundFile]: Found Models/neomoray.dat at ../AddOns/A - OSE Main Data WiP V0.68.02.oxp/Models/neomoray.dat
[dataCache.set.success]: Updated entry Models/neomoray.dat in cache "resolved paths".

Many more "can't find stuff" messages about stuff that is definitely there, like "tank001.png" or "front_metal.png" ...

[dataCache.set.success]: Updated entry ul_winga.dat/miss1tex.png in cache "synthesized shader materials".
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d739e28>{1: float uHullHeatLevel = [<ShipEntity 0x19412ec8> hullHeatLevel];}
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d739ee8>{0: int uDiffuseMap = 0;}
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d739f48>{2: float uTime = [<ShipEntity 0x19412ec8> timeElapsedSinceSpawn];}
[shader.uniform.unSet]: Did not set uniform "tex0"
[dataCache.retrieve.failed]: Failed to retrieve "synthesized shader materials" cache object ul_winga.dat/front_metal.png -- no such entry.
[dataCache.set.success]: Updated entry ul_winga.dat/front_metal.png in cache "synthesized shader materials".
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73a008>{1: float uHullHeatLevel = [<ShipEntity 0x19412ec8> hullHeatLevel];}
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73a0c8>{0: int uDiffuseMap = 0;}
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73a128>{2: float uTime = [<ShipEntity 0x19412ec8> timeElapsedSinceSpawn];}
[shader.uniform.unSet]: Did not set uniform "tex0"
[dataCache.retrieve.failed]: Failed to retrieve "octrees" cache object ul_winga.dat -- no such entry.
[dataCache.set.success]: Updated entry ul_winga.dat in cache "octrees".
[dataCache.retrieve.success]: Retrieved "resolved paths" cache object Scripts/oolite-default-ship-script.js.
[dataCache.retrieve.success]: Retrieved "compiled JavaScript scripts" cache object Resources/Scripts/oolite-default-ship-script.js.
[script.javaScript.load.success]: Loaded JavaScript OXP: "oolite-default-ship-script" 1.73 -- Standard script for ships.
[dataCache.retrieve.success]: Retrieved "AIs" cache object nullAI.plist.
[dataCache.retrieve.failed]: Failed to retrieve "OOMesh" cache object miss.dat -- no such entry.
[dataCache.retrieve.success]: Retrieved "resolved paths" cache object Models/miss.dat.
[dataCache.set.success]: Updated entry miss.dat in cache "OOMesh".
[dataCache.retrieve.failed]: Failed to retrieve "synthesized shader materials" cache object miss.dat/tank001.png -- no such entry.
[dataCache.set.success]: Updated entry miss.dat/tank001.png in cache "synthesized shader materials".
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73a488>{1: float uHullHeatLevel = [<ShipEntity 0x19413568> hullHeatLevel];}
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73a548>{0: int uDiffuseMap = 0;}
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73a5a8>{2: float uTime = [<ShipEntity 0x19413568> timeElapsedSinceSpawn];}
[shader.uniform.unSet]: Did not set uniform "tex0"
[dataCache.retrieve.failed]: Failed to retrieve "resolved paths" cache object Textures/tank001.png -- no such entry.
[resourceManager.foundFile]: Found Textures/tank001.png at ../AddOns/A - OSE Main Data WiP V0.68.02.oxp/Textures/tank001.png
[dataCache.set.success]: Updated entry Textures/tank001.png in cache "resolved paths".
[dataCache.retrieve.failed]: Failed to retrieve "synthesized shader materials" cache object miss.dat/hazard.png -- no such entry.
[textureLoader.asyncLoad]: Loading texture tank001.png
[dataCache.set.success]: Updated entry miss.dat/hazard.png in cache "synthesized shader materials".
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73ad88>{1: float uHullHeatLevel = [<ShipEntity 0x19413568> hullHeatLevel];}
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73aea8>{0: int uDiffuseMap = 0;}
[shader.uniform.set]: Set up uniform <OOShaderUniform 0x1d73af08>{2: float uTime = [<ShipEntity 0x19413568> timeElapsedSinceSpawn];}
[shader.uniform.unSet]: Did not set uniform "tex0"
[dataCache.retrieve.failed]: Failed to retrieve "resolved paths" cache object Textures/hazard.png -- no such entry.
[resourceManager.foundFile]: Found Textures/hazard.png at ../AddOns/A - OSE Main Data WiP V0.68.02.oxp/Textures/hazard.png
[dataCache.set.success]: Updated entry Textures/hazard.png in cache "resolved paths".
[dataCache.prune.recent textures]: Pruning cache "recent textures" - removing 11 entries
[textureLoader.asyncLoad]: Loading texture hazard.png

... these ...

[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: OOMesh after drawing <OOMesh 0x2eb8f48>{"griff_worm.dat", 264 vertices, 434 faces, radius: 22.0259 m smooth: NO}

Crash happened when coming out of my (fifth) witchjump, second savegame:

[script.debug.trace.testCondition.testResult]: Result: NO
[script.trace.plist.run]: Running script "Stations_owned_show_CAD"
[script.debug.trace.testCondition]: scriptTestCondition ["Stations_owned_show_CAD"]: "mission_playerstation_CAD equal 1"
[script.debug.trace.testCondition.testValues]: ..... comparing nil (from mission_playerstation_CAD) to "1" with operator equal
[script.debug.trace.testCondition.testResult]: Result: NO
[script.debug.trace.testCondition]: scriptTestCondition ["Stations_owned_show_CAD"]: "mission_playerstation_CAD undefined"
[script.debug.trace.testCondition.testValues]: ..... comparing nil (from mission_playerstation_CAD) to "" with operator undefined
[script.debug.trace.testCondition.testResult]: Result: YES
[script.debug.trace.scriptAction]: script action: "clearMissionDescription"
[script.trace.plist.run]: Running script "Stations_owned_income_HAB"
[script.debug.trace.testCondition]: scriptTestCondition ["Stations_owned_income_HAB"]: "status_string equal STATUS_EXITING_WITCHSPACE"
[script.debug.trace.testCondition.testValues]: ..... comparing "STATUS_DOCKED" (from status_string) to "STATUS_EXITING_WITCHSPACE" with operator equal
[script.debug.trace.testCondition.testResult]: Result: NO
[script.trace.plist.run]: Running script "Stations_owned_legal_JBE"
[script.debug.trace.testCondition]: scriptTestCondition ["Stations_owned_legal_JBE"]: "status_string equal STATUS_EXITING_WITCHSPACE"
[script.debug.trace.testCondition.testValues]: ..... comparing "STATUS_DOCKED" (from status_string) to "STATUS_EXITING_WITCHSPACE" with operator equal
[script.debug.trace.testCondition.testResult]: Result: NO
[script.trace.plist.run]: Running script "Stations_owned_show_CAE"
[script.debug.trace.testCondition]: scriptTestCondition ["Stations_owned_show_CAE"]: "mission_playerstation_CAE equal 1"
[script.debug.trace.testCondition.testValues]: ..... comparing nil (from mission_playerstation_CAE) to "1" with operator equal
[script.debug.trace.testCondition.testResult]: Result: NO
[script.debug.trace.testCondition]: scriptTestCondition ["Stations_owned_show_CAE"]: "mission_playerstation_CAE undefined"
[script.debug.trace.testCondition.testValues]: ..... comparing nil (from mission_playerstation_CAE) to "" with operator undefined
[script.debug.trace.testCondition.testResult]: Result: YES
[script.debug.trace.scriptAction]: script action: "clearMissionDescription"
[script.trace.plist.run]: Running script "INRAPatrols1"
[script.debug.trace.testCondition]: scriptTestCondition ["INRAPatrols1"]: "status_string equal STATUS_EXITING_WITCHSPACE"
[script.debug.trace.testCondition.testValues]: ..... comparing "STATUS_DOCKED" (from status_string) to "STATUS_EXITING_WITCHSPACE" with operator equal
[script.debug.trace.testCondition.testResult]: Result: NO
[script.trace.plist.run]: Running script "Stations_owned_income_HAC"
[script.debug.trace.testCondition]: scriptTestCondition ["Stations_owned_income_HAC"]: "status_string equal STATUS_EXITING_WITCHSPACE"
[script.debug.trace.testCondition.testValues]: ..... comparing "STATUS_DOCKED" (from status_string) to "STATUS_EXITING_WITCHSPACE" with operator equal
[script.debug.trace.testCondition.testResult]: Result: NO
[script.trace.plist.run]: Running script "Stations_owned_legal_JBF"
[script.debug.trace.testCondition]: scriptTestCondition ["Stations_owned_legal_JBF"]: "status_string equal STATUS_EXITING_WITCHSPACE"
[script.debug.trace.testCondition.testValues]: ..... comparing "STATUS_DOCKED" (from status_string) to "STATUS_EXITING_WITCHSPACE" with operator equal
[script.debug.trace.testCondition.testResult]: Result: NO
[dataCache.willWrite]: About to write data cache.

This is the end of the 115MB logfile ...

Also found these:

[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: SkyEntity after drawing <SkyEntity 0x12ec93d0>{ID: 599 position: (13555.7, 5873.1, 40699.7) scanClass: CLASS_NO_DRAW status: STATUS_EFFECT}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: SkyEntity after drawing <SkyEntity 0x12ec93d0>{ID: 599 position: (13566.3, 5876.62, 40794.9) scanClass: CLASS_NO_DRAW status: STATUS_EFFECT}
[dataCache.retrieve.success]: Retrieved "AIs" cache object dockingAI.plist.
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: SkyEntity after drawing <SkyEntity 0x12ec93d0>{ID: 599 position: (13577.7, 5880.43, 40897. scanClass: CLASS_NO_DRAW status: STATUS_EFFECT}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: SkyEntity after drawing <SkyEntity 0x12ec93d0>{ID: 599 position: (13588.3, 5883.96, 40992.9) scanClass: CLASS_NO_DRAW status: STATUS_EFFECT}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: SkyEntity after drawing <SkyEntity 0x12ec93d0>{ID: 599 position: (13598.3, 5887.29, 41083) scanClass: CLASS_NO_DRAW status: STATUS_EFFECT}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: SkyEntity after drawing <SkyEntity 0x12ec93d0>{ID: 599 position: (13608.6, 5890.72, 41175.6) scanClass: CLASS_NO_DRAW status: STATUS_EFFECT}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: SkyEntity after drawing <SkyEntity 0x12ec93d0>{ID: 599 position: (13620.3, 5894.63, 41281) scanClass: CLASS_NO_DRAW status: STATUS_EFFECT}
[rendering.opengl.error]: OpenGL error: "Ungültiger Enumerant." (0x500), context: SkyEntity after drawing <SkyEntity 0x12ec93d0>{ID: 599 position: (13630.6, 5898.06, 41373.7) scanClass: CLASS_NO_DRAW status: STATUS_EFFECT}

Last thing to mention, I test-bought a player station - but the log shows no mention of "[playerBoughtEquipment]: Player has bought equipment:" - player stations are equipment pieces which are removed after buying and a mission variable set instead.

The station showed up correctly on my missions list (they are shown there, you have an X station in the Y system in galactic sector Z) - but the popup-screen that should happen there also didn't happen. I think that one is a bug introduced with the newest Oolite 1.73 - because while testing this on trunk, this always worked.

Hope to get any wiser due to the info snippets here

L

[Svengali]

I'm not a dev, but the only relevant thing seems to be

[gnustep]: 2009-09-02 09:16:44.646 oolite[5660] could not convert to UTF8 string! bytes=0fea1c59 len=6

There seem to be a problem with one of your installed oxps. But this is usually there even if you don't use the _override key.

The other things are the usual stuff, saying that Oolite allocates mem or loads things into mem, if not done before. The invalid Enumerant is well known - I've seen it first in v1.65+1.69 when I've used a OpenGL-Debugger the first time. It's in all version until that time and does not crash the game. The message itself has changed a bit after v1.71 (or v1.72), because GL_HINT seems to be enabled now.

EDIT: Why are you creating >200 scripts for your stations?

I don't think that anything posted is related to the crashes, so you know that procedure. Pick oxps, throw them in/out and find the bad boy.

[JensAyton]

I got loads and loads of the following - yet the models are there! For example the "neomoray.dat". It's there.

The “not found” messages refer quite specifically to not finding things in caches. http://en.wikipedia.org/wiki/Cache

I'm not a dev, but the only relevant thing seems to be

[gnustep]: 2009-09-02 09:16:44.646 oolite[5660] could not convert to UTF8 string! bytes=0fea1c59 len=6

There seem to be a problem with one of your installed oxps. But this is usually there even if you don't use the _override key.

Actually, I believe that’s a bona fide Oolite bug. It doesn’t happen to me, though. In any case, it shouldn’t be related to the crashes.

The last line in the log, dataCache.willWrite, was introduced because 1.69 was apparently crashing when writing log files. Since then I haven’t been able to correlate any crashes to log files, so I disabled the message by default for 1.73. Thus it makes perfect sense that it should be coming back to haunt us…

[another_commander]

In any case, I believe the correct course of action here is:
1. See if crashes occur without OXPs. If they do, then
2. Start from the top of the log and correct the errors as they appear. I think the first one is the UTF-8 one, which I believe is caused by a standard DOS format file that contains extended ASCII characters. This file has to be located and either have its problem fixed or its container OXP removed completely.
3. Once a log without errors coming from OXPs has been produced, THEN we can start troubleshooting properly what is going wrong. Otherwise, it is impossible to know if errors come from the code or from OXPs, unless in generally rare, obvious cases.

[Lestradae]

The last line in the log, dataCache.willWrite, was introduced because 1.69 was apparently crashing when writing log files. Since then I haven’t been able to correlate any crashes to log files, so I disabled the message by default for 1.73. Thus it makes perfect sense that it should be coming back to haunt us…

Does that mean that Oolite writing the log file could be a reason for the crashes?

That would be easy to test, if it was possible to deactivate the log file completely as an experiment. Is that possible?

I will test without oxps, too. In the past this has also lead to crashes - but it took much longer until they happened without oxps.

[Thargoid]

If it's any help, I'm also getting a UTF8 log error, which I've narrowed down to Random Hits 1.3.5.

Now going to look into which specific file (to fix it), and also check with LB if he knows which file it is and whether I'm up to date with it.

Now updated to 1.3.6 and that's cleared it. Is your RH up to date?

[Eric Walch]

If it's any help, I'm also getting a UTF8 log error, which I've narrowed down to Random Hits 1.3.5.

That was a long known bug. When remembering well it was an ü character in the descriptions.plist. That problem didn't occur on the mac as the mac just skipped the whole plist so you immediately knew RH had a problem.

[Thargoid]

Now you mention it I do recall, I just hadn't put 2 & 2 together to this case. But Lestradae is also reporting a UTF8 error in his log above.

[Lestradae]

I did have RH 1.3.5 - upgrading now.

Still, everyone says that is not the reason for the crash - and I seem to recall that at the end of my log file, after crashing, there often was the line ...

Code: Select all

[dataCache.willWrite]: About to write data cache.

I always assumed Oolite wrote that into my log due to just having terminated. Never got the idea it could have been the other way around

[JensAyton]

The last line in the log, dataCache.willWrite, was introduced because 1.69 was apparently crashing when writing log files. Since then I haven’t been able to correlate any crashes to log files, so I disabled the message by default for 1.73. Thus it makes perfect sense that it should be coming back to haunt us…

Does that mean that Oolite writing the log file could be a reason for the crashes?

That would be easy to test, if it was possible to deactivate the log file completely as an experiment. Is that possible?

No. What does the log file have to do with anything?

It could mean that there’s corrupt data in the cache. Not writing the cache would stop the crash from happening when it does, but it would still crash eventually.

[Lestradae]

It could mean that there’s corrupt data in the cache. Not writing the cache would stop the crash from happening when it does, but it would still crash eventually.

Please take into account my skills (?) in this when answering: How do I identify that probably corrupt data aka how do I search for it?



L

[Kaks]

Please take into account my skills (?) in this when answering: How do I identify that probably corrupt data aka how do I search for it?

A corrupt cache means, more or less, that some of the stuff the program expects to find at a specific location is not actually there. It's all part of the big Memory Management Conspiracy (TM pending), and it's kind of the flip side of memory leaks.

To even begin to search for it, you'll need to install and learn the ins and outs of gdb, or have a major insight in the workings of the cache handling code, not the simplest part of Oolite (or any other substantial program) code base.