TS2015 - Scenario Scripting in LUA Part 2 - Debugging with LogMate

Continuing our series on using LUA scripts to enhance your Scenarios, I thought that it was prudent to cover how to debug your scripts as early as possible. That way, when things start going wrong (they will, trust me!) then you have the knowledge to figure out what's going on and then how to fix it.

Getting LogMate Running

Logging in Train Simulator is done via a tool called LogMate, we'll need to add some command line parameters to Train Simulator in order to enable this and set it up.

First, go to the in-game settings for Train Simulator and change it so that it's running in a window, this will make life much simpler. Once you've done that, close the game. Now go to the Steam Launcher, go to the Library and find Train Simulator. Right Click on it and select Properties.  Click "Set Launch options".

In the box that comes up, you need to type the following:

-LogMate -SetLuaFilters="All" -lua-debug-messages

It is important that you get all the capitalisation correct, if you make any mistakes it will not work.

Click OK and then the next time you launch the game, the LogMate window will open. It's important to note that while the LogMate window is open, the game is logging a lot and this will definitely slow the game down.  At any point, you can simply close the LogMate window to return the game to full performance (without logging of course) however to get it back again you must restart the game.

Once LogMate is running you will see a screen that looks like this:

The main part of the window is where logging will appear.

In the File menu there are a couple of options - Save Log and Clear Logs.  You can click "Save Log" to save everything out to disk, which will enable you to search it in another application such as Notepad++ much more easily.

Clear Logs is an option you will need to get used to using regularly.  As the game logs to LogMate, it will fill up - if you leave it too long, you'll find the game begins to slow to a crawl, once this happens it is quite hard to get it back again without simply closing it however if you keep pressing "clear log" this keeps everything moving relatively smoothly.  Find out how long it takes to fill up and then just keep an eye on it and clear it out before that happens.

Once you've started the game, LogMate will start receiving logging text, here's an example of what it might look like:

You can see that there's lots of complicated text in the logging, for the most part you can really just ignore a lot of the detail.  The aim here is going to be to look at your own logging rather than the in-game logging, and generally find anywhere it says "error" and see if it's something caused by your script.

Along the top you can see a number of new tabs have appeared, these help separate the logging in to various subsystems within the game, though for the most part I generally simply stick with the "All" tab.

Sending Log Text to LogMate

When you're testing debugging your script you are going to want to put in some simple logging to try and work out "did it get here?", "well, what's that value then?" and so forth.  With the help of this logging you can then work out what path the game took through your code and where the code went wrong.

Writing to LogMate is very easy:

print ("This is a line of logging")

You can also add variables, so let's take our OnEvent function and add some interesting logging:

function OnEvent(event)
  print ("OnEvent called - event is [" .. event .. "]")
  _G["OnEvent" .. event]();
end

You can see that the  two dots, "..", are used to allow us to append other things to the string in the "print" statement, including continuing on with the string.

Tip: Whenever printing a value, I like to always wrap it in brackets, that way I know for sure if the value has any extra characters like newlines in it, or if there's anything else generally of note.

You can also print numbers the same way:

function TestConditionOverspeed()
  speed = SysCall("PlayerEngine:GetSpeed")
  print ( "Player speed [" .. speed .. "] m/s")
end

As a general point of style, I would recommend including common information that helps gather your log entries together, so in an event handler perhaps always include the name of the event being handled, such as this:

function OnEventIntroText()
  print("OnEventIntroText() - Started")
  -- do some stuff
  print("OnEventIntroText() - Finished")
end

In this way you can simply do a search for "OnEventIntroText" in the log file later and you'll see all the lines of log that came out of that function.

Debugging Process

As a general process, when you're debugging you need to work methodically and not assume anything.  Prove all facts to ensure that you don't end up spending hours looking at a problem and not seeing it because you assumed "well it can't possibly be wrong here" - in most cases, that's exactly where the problem ultimately sits!

I would recommend having a debug line at the start of OnEvent to log each event as it is fired.  Don't log at the top of TestCondition unless necessary as this will badly spam the log file, use it to prove you're getting the right conditions to check and then remove the log entry again.

I would also recommend logging each event that you handle, so if you're using the function-based method I recommend in the first part of this tutorial, then a line of log at the top of each of those functions will prove it got in to the right function that you were expecting it to.

If you are reading any values from controllers or as the returns from other function calls perhaps to get the player engine speed or signal states etc then it's worth logging those values out.

At various decision points in your code where you have "if/then/else" type statements, you could log the variables that you're checking before the IF statement and then log inside each of the "then" or "else" sections so that you can trace through where it actually ended up going.

Debugging is an investigative process and one that will take time to really get to grips with. 

Imagine that there's an invisible person running through your code and you're trying to figure out what he's doing.  Any time that invisible person steps on a "print" statement you can get a line of log - and therefore by being clever about where you put these print statements you can build up a picture of where he went and why he went there.  Using this information you are then well armed to correct any errors and make him go where you want!

Here's a quick example:

function TestCondition(condition)
  if (condition == "OverspedCondition") then
    speed = SysCall("PlayerEngine:GetSpeed");
    if (speed < 4.47) then
      DisplayRecordedMessage("Overspeed1");
      SysCall ( "ScenarioManager:TriggerDeferredEvent", "starttoofastcheck2", 5 );
      return CONDITION_SUCCEEDED;
    end
  return CONDITION_NOT_YET_MET;
end

This function has problems, it's there to detect when we exceed 10mph but nothing is happening, so let's put some debug in and try to find out why.

First step - let's check  TestCondition and if we're detecting the condition correctly.  Since this is a spammy log entry we'll just do that first, the new function looks like this:

function TestCondition(condition)
  print ( "TestCondition() - Condition[" .. condition .. "]")
  if (condition == "OverspedCondition") then
    speed = SysCall("PlayerEngine:GetSpeed");
    if (speed < 4.47) then
      DisplayRecordedMessage("Overspeed1");
      SysCall ( "ScenarioManager:TriggerDeferredEvent", "starttoofastcheck2", 5 );
      return CONDITION_SUCCEEDED;
    end
  return CONDITION_NOT_YET_MET;
end

When we run it in LogMate, save the log file after our test and then open it in Notepad, if we search for "TestCondition" we see:

TestCondition() - Condition[OverspeedCondition]
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]

(etc)

So we can see two conditions are being fired, which is what i'd expect in my scenario script, but I still can't see a problem so let's check the IF statement.  We'll leave the existing "print" statement in place.

function TestCondition(condition)
  print ( "TestCondition() - Condition[" .. condition .. "]")
  if (condition == "OverspedCondition") then
    print ( "TestCondition() - Checking for the overspeed condition")
    speed = SysCall("PlayerEngine:GetSpeed");
    if (speed < 4.47) then
      DisplayRecordedMessage("Overspeed1");
      SysCall ( "ScenarioManager:TriggerDeferredEvent", "starttoofastcheck2", 5 );
      return CONDITION_SUCCEEDED;
    end
  return CONDITION_NOT_YET_MET;
end

So, now we've got two log entries - one happens each time TestCondition is called and the other confirms we're in our specific check for overspeed.

When we run it, this is what we end up with in the log:

TestCondition() - Condition[OverspeedCondition]
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]

Hmm, that looks remarkably familiar and it proves we're not getting in to our overspeed check code.  This means that the "if" statement is what's wrong and we can now pull out our microscope and find out why.  Having done that, I realise that I've mis-spelled the condition name in the "if" statement!  Let's correct that and re-run.

TestCondition() - Condition[OverspeedCondition]
TestCondition() - Checking for the overspeed condition
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Checking for the overspeed condition
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Checking for the overspeed condition
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Checking for the overspeed condition
TestCondition() - Condition[StoppedCondition]
TestCondition() - Condition[OverspeedCondition]
TestCondition() - Checking for the overspeed condition

Better, we're now getting in to the "if" statement, but what happened when I ran it was that I immediately got told I was overspeeding even though I hadn't moved yet.  So let's find out what's happening there.  Now that we're know we're in the "if" statement, i'm going to comment that logging out, that way we can easily put it back if we want but for the time being it's out of our way.

function TestCondition(condition)
  -- print ( "TestCondition() - Condition[" .. condition .. "]")
  if (condition == "OverspeedCondition") then
    -- print ( "TestCondition() - Checking for the overspeed condition")
    speed = SysCall("PlayerEngine:GetSpeed");
    print ( "TestCondition() - Overspeed - Speed[" .. speed .. "]")
    if (speed < 4.47) then
      print ( "TestCondition() - Overspeed - We are going too fast!")
      DisplayRecordedMessage("Overspeed1");
      SysCall ( "ScenarioManager:TriggerDeferredEvent", "starttoofastcheck2", 5 );
      return CONDITION_SUCCEEDED;
    end
  return CONDITION_NOT_YET_MET;
end

In our updated function, we are now reporting the speed of the loco that was returned to the script from the game, and then reporting if we got in to the "if" statement once we reached overspeed.  Let's run it and see what we get.

TestCondition() - Overspeed - Speed[0.01235532]
TestCondition() - Overspeed - We are going too fast!

Wait, hang on, even though the speed was definitely very low, we still succeeded that IF statement and got in to the overspeed code!  We need to scrutinise that IF statement, and upon doing so we realise that what it currently reads is "if the current speed is LESS than 4.47 meters per second", oops.  Once that is fixed, the script is now running correctly.
Closing Notes
Debugging is something that is going to take time to learn how to do so stick with it, once you get the hang of it you will be able to quickly work out what is happening and identify the many causes of problems that might be haunting you in your script.

Another tool I recommend for analysing log files that you've saved is Log Expert, which you can get for free here: http://www.log-expert.de/

To use LogExpert, run LogMate as normal to get the log file and save it out.  Then run LogExpert.

Drag Drop the log file you saved on to it and it will log in to a tab which you can browse and search as normal.  Where LogExpert really comes in to its own however is Filtering and Highlighting.

On the View/Navigate menu, select Filter and a new section will appear in the bottom half.

In the "Text Filter " field you can type parts of your log entries - this is where having good common logging will really help.  E.g. it's here you could type "TestCondition" from the example above, and see precisely every thing in the log file that contains that phrase.  If you want to get more complex, learn Regular Expressions (not for the faint of heart, but very powerful) and you can even type Regular Expressions in this field to search based on a complex search string by ticking the "regex" field.

To do highlighting, which can make navigating complex logs much easier than trying to search specific things out, click on the Options menu and then select Highlighting and Triggers.

In the "Search string" field, type in the phrase you want to pick out (this can be a regular expression too if you want).  Choose a foreground and background colour in the bottom left and then click the Add button in the middle section.  When you click OK, anything in the log that contains this text will now be highlighted.

Highlighting is great for many reasons - it may be that you want to look for a variety of things but for various reasons can't search, perhaps you want to see around the entry more and get more context for the entry.  Perhaps the lines you're finding are good at marking the start of something and you just want to then read the log - once it's highlighted you can simply scroll through and you'll find it very easy to quickly pick out the highlights and navigate the log file.

Finally, when your scenario is working well make sure you go back and either remove or at least comment out all of your debug.  Leaving debug in can cause a performance slow-down even if the player isn't running LogMate.

Hope that was useful, it was long and detailed but I wanted to cover everything needed to debug your scripts - you'll be coming back to this article as you get more proficient at scripting scenarios and run in to more challenges where things don't quite work, so don't worry if it doesn't all make sense just yet.

I'd love to hear your feedback in comments and don't forget to follow the blog to make sure you find out about future articles - there are quite a few planned in this series!