Undefined messageClass in log(this.x,this.y) causes CTD.

[Capt. Murphy]

Hi,

This one should be easy to reproduce. Tested on 1.76 and current trunk on Win 7 and Win XP machines.

Attempting to use the command log(this.x,this.y) (whether from script or debug console) when this.x is undefined causes a crash to desktop 100% of the time.

log(this.x) when this.x is undefined does not result in a crash, but no log message or error message is produced.

edit to add:

log(x,y,z) shouldn't be valid syntax according to the wiki, but does produce a log entry, unless y or z is undefined in which case it throws a JS exception. I think it should throw an syntax error in all cases as the correct syntax should be log(x,y+","+z)

[Eric Walch]

This one should be easy to reproduce.

Yes, easy to reproduce and to fix.

Adding following check in the logging code:

Code: Select all

if (messageClass == nil) messageClass = kOOLogDebugMessage;

Fixes the CTD

But maybe one of the other devs think it should throw also a warning instead of just using the default message class?

[Switeck]

What I mentioned here:
https://bb.oolite.space/viewtopic.ph ... 30#p163017
"If I'm using this.weaveX (local variable) and get a NaN location for a Thargoid, even attempting log(this.weaveX); (or similar command) in the same .js script causes the game to crash to desktop!"

I'm also seeing cases where the log command like this don't seem to work:
log("log this",this.x,this.y);

Should the first entry in the log before a comma (,) always be a number?

[Commander McLane]

Should the first entry in the log before a comma (,) always be a number?

I understand that it's recommended that the first entry should be the script's (or OXP's) name, in order to match the log information to the relevant script/OXP. Examples:

Code: Select all

log("Anarchies", this.myVariable);

log("randomshipnames", "A ship with role '" + ship.primaryRole + "' was christened '" + this.randomName + "'.");

will lead to

Code: Select all

09:22:03:476 [Anarchies]: 3.6249673

14:18:26.096 [randomshipnames]: A ship with role 'pirate' was christened 'Cold Rumour'.

in latest.log. This allows the reader to match a cryptic log entry (like in the first example) at least to an OXP. Otherwise the non-sensical number would be practically useless as an information.

[another_commander]

But maybe one of the other devs think it should throw also a warning instead of just using the default message class?

Recommendation for fix - OOJSGlobal.m, insert below line 242:

Code: Select all

if (EXPECT_NOT(messageClass == nil))
{
	messageClass = [NSString stringWithString:@"<Undefined Message Class>"];
}

This way you get both a log entry and a clear indication that something was not as defined as it should be.

[JensAyton]

But maybe one of the other devs think it should throw also a warning instead of just using the default message class?

Recommendation for fix - OOJSGlobal.m, insert below line 242:

Bzzt! The correct fix is to change OOStringFromJSValue to OOStringFromJSValueEvenIfNull so that JS null and undefined values are stringified according to normal JavaScript rules. Obviously. :-p (The actual message components end up getting stringified this way already.)

[Eric Walch]

log(x,y,z) shouldn't be valid syntax according to the wiki, but does produce a log entry, unless y or z is undefined in which case it throws a JS exception. I think it should throw an syntax error in all cases as the correct syntax should be log(x,y+","+z)

The wiki only mentions one message parameter, but the code is explicit written to accept more than one message strings and writes all messages in the log, separated by a comma. Probably the wiki must be updated here and not the code.

I understand that it's recommended that the first entry should be the script's (or OXP's) name, in order to match the log information to the relevant script/OXP. Examples:

Code: Select all

09:22:03:476 [Anarchies]: 3.6249673

Its up to the author what entry is used, but I also think it should be the script name or oxp name so that everyone can immediate link the output to a certain file or oxp. Specially when you want feedback from users it should be a name they also can link to your work.
NB on the mac debug console it is easy to change the kind of prefix that is used for logging. Select 'Log preferences" from the debug menu and you can select to also add/leave out the time stamp or the messageClass.

But maybe one of the other devs think it should throw also a warning instead of just using the default message class?

Recommendation for fix - OOJSGlobal.m, insert below line 242:

Bzzt! The correct fix is to change OOStringFromJSValue to OOStringFromJSValueEvenIfNull so that JS null and undefined values are stringified according to normal JavaScript rules. Obviously. :-p (The actual message components end up getting stringified this way already.)

At least both methods are better than my first idea that would only log to the console and nothing to the log.
And I now see that we already had a method that handles a null conversion to 'undefined' string and there is no need for further testing for null.

[JensAyton]

The wiki only mentions one message parameter, but the code is explicit written to accept more than one message strings and writes all messages in the log, separated by a comma. Probably the wiki must be updated here and not the code.

This is a sort of deliberate hidden feature. Building your own strings in JS is the recommended approach, but I wanted it to do something at least vaguely useful even if you happened to use it wrong. Crashing for undefined/null message classes obviously doesn’t qualify.

Its up to the author what entry is used, but I also think it should be the script name or oxp name so that everyone can immediate link the output to a certain file or oxp. Specially when you want feedback from users it should be a name they also can link to your work.

I don’t think a recommendation has been stated before, but it’s definitely a good idea to include the OXP name. Have you ever been annoyed by a log message whose source you couldn’t easily identify? Don’t annoy your users in the same way.

If you have a lot of logging, it can be a good idea to use strings like oxpname.somethingHappened, so you can enable and disable them independently.

NB on the mac debug console it is easy to change the kind of prefix that is used for logging. Select 'Log preferences" from the debug menu

Equivalently, console.setDisplayMessagesInClass("oxpname.somethingHappened", true/false). This is temporary; permanent settings can be made in logcontrol.plist.

And I now see that we already had a method that handles a null conversion to 'undefined' string and there is no need for further testing for null.

The functions for dealing with JS/NS string conversions are a mess. :-/ This is partly because they were originally written to handle specific use cases, but mostly because I didn’t understand JavaScript well back when we started using it.

[Switeck]

The wiki only mentions one message parameter, but the code is explicit written to accept more than one message strings and writes all messages in the log, separated by a comma. Probably the wiki must be updated here and not the code.

This is a sort of deliberate hidden feature. Building your own strings in JS is the recommended approach, but I wanted it to do something at least vaguely useful even if you happened to use it wrong. Crashing for undefined/null message classes obviously doesn’t qualify.

I presume you mean building your own strings in the sense of something like this:

Code: Select all

this.logoutput = "OXP name: variable check "+var1+" , "+var2+" , "+var3;
log(this.logoutput);

My concern is if var1 or the other variables happen to be undefined, null, NaN, or whatever...are we going to run into any hidden problems (like log(this.x,this.y) has in v1.76) with the string creation itself?
Or should I test that myself?

[Capt. Murphy]

:

Code: Select all

this.logoutput = "OXP name: variable check "+var1+" , "+var2+" , "+var3;
log(this.logoutput);

More like this - your example is building the big string as the messageClass. This example uses the script header defined this.name as the messageClass and a concatenated string as the message.

log(this.name,"Variable check - var1:"+var1+", var2:"+var2+", var3:"+var3)

This works with undefined values - the string concatenation functions handle them fine and will output "undefined" for an undefined variable.

This also got me thinking about logging functions in shipScripts, as using this.name as a messageClass in this context makes it difficult to know which entity is producing the log entry if there are multiple entities with the same shipScript active in the ooniverse. This can cause confusion in the interpretation of log output (I think this happened when Thargoid was debugging the early version of Swarm.oxp).

It would be handy if there was a this.ship.entityID which returned a unique identifier as you get when AI logging is enabled, and could be used as the messageClass - maybe like this log(this.name + ", Entity:"+this.ship.entityID,messageString) - when using logging to debug shipScripts. Or is there another property already available that I haven't thought of?

[Commander McLane]

It would be handy if there was a this.ship.entityID which returned a unique identifier as you get when AI logging is enabled, and could be used as the messageClass - maybe like this log(this.name + ", Entity:"+this.ship.entityID,messageString) - when using logging to debug shipScripts. Or is there another property already available that I haven't thought of?

I don't think that the entity ID would be particularly useful. It's just a three-digit-number that Oolite assigns to each entity in order of its creation. So there is no connection between the ID and any useful information about the ship itself. this.ship.name would be vastly more useful in my opinion.

[Eric Walch]

I don't think that the entity ID would be particularly useful. It's just a three-digit-number that Oolite assigns to each entity in order of its creation. So there is no connection between the ID and any useful information about the ship itself. this.ship.name would be vastly more useful in my opinion.

entity.ID was deprecated since 1.74 and is no longer available to scripts for the reason you mention. At any time they are unique, but when a ship dies, the same number may be re-issued to a new ship.
I think Capt. Murphy means entityPersonality. That is a bigger, random number. Ship.name is not useful as they probably will also be the same when you add 10 of the same ships in the universe and they all add logging lines.

[Commander McLane]

I don't think that the entity ID would be particularly useful. It's just a three-digit-number that Oolite assigns to each entity in order of its creation. So there is no connection between the ID and any useful information about the ship itself. this.ship.name would be vastly more useful in my opinion.

entity.ID was deprecated since 1.74 and is no longer available to scripts for the reason you mention. At any time they are unique, but when a ship dies, the same number may be re-issued to a new ship.
I think Capt. Murphy means entityPersonality. That is a bigger, random number. Ship.name is not useful as they probably will also be the same when you add 10 of the same ships in the universe and they all add logging lines.

My thinking was: A ship creator builds a logging feature into his newest creation an ships the OXP with this logging feature. I install the OXP, find some loggings in my log and want to contact the OXP creator about them. The entityPersonality is of no use at all, because it's unique to my current game. If the OXP creator fires up his game and spawns one of his ships, it will have a totally different entityPersonality. Besides, the entityPersonality, which is just a long number, tells me nothing about which ship created the log entry in the first place, which OXP it is from, and who I should contact about it. But if the name is logged I can easily find out that the "Rhinoceros" was created by "Commander Big Five" and can PM him about it.

[Switeck]

Should the first entry in the log before a comma (,) always be a number?

I understand that it's recommended that the first entry should be the script's (or OXP's) name, in order to match the log information to the relevant script/OXP.
...
This allows the reader to match a cryptic log entry (like in the first example) at least to an OXP. Otherwise the non-sensical number would be practically useless as an information.

Ok, on to my example code:

Code: Select all

this.startUp = function()
{
	testCounter = 0;
}

this.shipWillLaunchFromStation = function ()
{
	testCounter = 0;
};

this.shipExitedWitchspace = function ()
{
	testCounter++;
	log(testCounter);
	player.commsMessage(testCounter+" = testCounter",6);
};

The log(testCounter); never logged anything to latest.log.
So I replaced that with log(testCounter+" = testCounter"); ...and still nothing was logged!
But this worked:
log(0,testCounter+" = testCounter");
...to which I ask why?!

[Eric Walch]

So I replaced that with log(testCounter+" = testCounter"); ...and still nothing was logged!
But this worked:
log(0,testCounter+" = testCounter");
...to which I ask why?!

That is because with only one parameter there is no messageClass defined and the log() method defaults the following messageClass: script.debug.message This class inherits the settings from the metaclass: scriptDebugOn
In logControl.plist you can define what classes must be logged. I think scriptDebugOn is off by default. Setting it to yes will give you output to the logfile.

But when you define your own messageClass, it is probably not defined in logControl and than it will be logged. If you want you can even suppress logging for your messageClasses by adding then to logControl.plist . And as Ahruman mentions a few message above you can also set the logging on the fly. e.g. typing:

Code: Select all

console.setDisplayMessagesInClass("script.debug.message", true)

in the console will make sure you get logging from log() commands without a massageClass defined, no matter how it was defined in logcontrol.plist. (At least during the current session)

Adding a '0' in front just makes that you create a messageClass '0'. Than a more descriptive name is more useful. I normally use 'this.name' so that I don't have to think about a name and the scriptname is used. When the logs are also mend for user feedback a more descriptive name could be better.

But I agree, to be really useful this should al be documented or most is forgotten in a few weeks from now.
I now added some additional info with the log() command in the wiki.