Author Topic: Using the Event Log to find bugs in your missions  (Read 3344 times)

0 Members and 1 Guest are viewing this topic.

Offline karajorma

  • King Louie - Jungle VIP
  • Administrator
  • 214
    • Karajorma's Freespace FAQ
Using the Event Log to find bugs in your missions
A while back I added a new feature to FRED to make it easier to figure out why events in a mission don't work.



You may have noticed these tickboxes appear in FRED but not know how to use them. Since I've added an explanation to the Diaspora FREDdocs, I figured I should submit it here too for those of you who haven't read through them (Although you probably should if you want to FRED, they're useful even if you have no interest in Diaspora).

------------------------------------------------------------

Debugging is one of the most time consuming and confusing aspects of mission design. Very often you'll have a good idea what SEXPs you think you need in order to make an event but when you run the game you find the event doesn't trigger correctly, or triggers too soon, or doesn't trigger at all. So you go back to FRED and look at the offending events but you're stuck, you can't see anything wrong with your logic, the event looks correct. At this point you have two choices. You can figure out why your event isn't working and fix the problem, or you can tinker with the mission until you find something that works. Many FREDers choose to do the latter. It can definitely be quicker at times but the problem with this attitude is that you don't learn why the previous SEXP didn't work. The result is that it's easy to fall into a pattern of deciding that certain SEXPs are cursed or don't work when in fact it's simply the case that you used them incorrectly.

A better solution is to avoid this kind of superstition and try to figure out why the event isn't working instead of changing it. Those of us FREDders who also are coders will often turn to the coding tools we have and use these to see step by step what the code is doing. This is undoubtedly the most powerful tool a mission designer has at their disposale but for those of us who aren't coders, or who wish to try something else first, there is another tool you can use.

When it comes to debugging missions, the event.log is possibly one of the most powereful tools you have available. Every time the game runs it will write a log to the Diaspora/<Your Currently Active Mod>/data folder (so by default you'll find it in Diaspora/data). The log is a simple text file which can be opened with notepad or the like. By default the log is completely empty apart from the names of any missions that were played. If you want to actually log something, you need to tell the game what you want to log. So let's look at some common problems and how the debug log can be used to help you.



The event log is controlled by the Log These States To The Event Log tickboxes in the events editor. You can turn on as many or as few of these as you wish. If a flag is set, the mission writes to the log every time it tests an event and finds it to be in that state. So if you tick the true box the mission will write to the log when the event triggers. If you set false then the mission will write to the log every time the mission tests the event but doesn't trigger. I'll be giving you examples of some events that don't work correctly and showing how the event log can allow you to quickly narrow down which SEXP is the one causing the problem.

My Event Triggers Too Early!



Suppose we have an event like this one which we are having issues with. The event is supposed to go off at a certain time in the mission but instead is happening near the start of the mission and you can't see why. The event.log can show you what's going on there.Simply tick the True option and run the mission. When you play the game the events.log will be written to as soon as the event triggers. When you quit the mission, you can then look at the event.log and you'll now see output that looks like this.

Code: [Select]
02/03 10:58:54~   FS2_Open Mission Log - Opened


Mission Learning Curve loaded.

Event: Persephone In Range at mission time 99 seconds (99053 milliseconds)
when returned TRUE
clear-goals returned TRUE
and returned TRUE
is-event-incomplete returned TRUE
< returned TRUE
distance returned 399

Let's look at this in a bit more detail. The first two lines simply tell us that we've started the log and loaded the mission. The next line tells us which event we are looking at. After that we get a line which tells us that the when SEXP returned true. Since this is the top level trigger the event also returned true. We only ticked the true box, so this result is not surprising.

Due to the way the SEXP code works, the rest of the log is not in the same order as in FRED. First you'll get a list of the action operators that actually do things in the mission, and then you'll get a list of the SEXPs that were actually involved in deciding whether or not to trigger the SEXP. So the next SEXP we see in the log is the clear-goals SEXP. Action operators should always return TRUE so we can ignore this one.

Finally we get to the real meat of the event. We can see that the distance between the ships was 399, and the "Going after Basestar 2" event was still incomplete, which lead to the event triggering. So now we know what we did wrong, either the two ships are closer than we thought early in the mission, or the "Going after Basestar 2" event still hasn't triggered 99 seconds into the mission, even though we expected it would. Either way, we're much closer to solving the problem.


My Event Doesn't Trigger!



In this case we have a fairly simple event that isn't triggering. When the Bolitho is at 50% the mission should trigger the event. But in the few tests the FREDder has noticed that even when the Bolitho is destroyed the event still hasn't triggered. More advanced FREDders have already figured out why, but let's pretend we're still confused. You can solve this by using the False option. The log this produces is very long (the event evaluates to false every single frame. So you'll get around 60 entries for every second you play the game!). But we only really need to look at two of the entries to see what the problem is. Basically we'd scroll down until we find the entry that includes "hits-left returned 50" and see why the event didn't trigger then.

When we try this, we see that there is no such entry.

Code: [Select]
........
Event: Bolitho Damaged at mission time 65 seconds (65233 milliseconds)
when returned FALSE
= returned FALSE
hits-left returned 54

Event: Bolitho Damaged at mission time 65 seconds (65297 milliseconds)
when returned FALSE
= returned FALSE
hits-left returned 48
.........

and it's easy to see what the problem is. The Bolitho was hit by something that knocked it from 54% to 48% in one hit. It never passed through 50% so as far as the game is concerned there is no reason to ever trigger this event. This is actually the reason most FREDders will tell you to always test if the hull is less than 51% rather than equal to 50.



How To Use The Other Flags.

The other flags are fairly easy to understand if you've grasped how the first two work. First Repeat will trigger the first time a repeating event is triggered. It's basically the same as using True without the clutter of all the other repeats writing to the log. Last Repeat works in the same way but only records the last triggering of the event. Using both together is good if the event triggers but something is going wrong with it between first and last repeat. First Trigger and Last Trigger are the same but use Trigger Count instead of Repeat Count. Log Previous State tells the log to output the state of the event in this frame and the previous frame. This is very useful when you have a multipart trigger and you are trying to figure out which part of it was the last one to turn true.


How To Use The Snapshot Key

One other useful feature is the ability to record all the SEXPs tested this frame to the event log. Of course, this will result in a very long log entry if you have a big mission but it is very useful when casually playing a mission if you spot a bug. Pressing the snapshot key writes the state of all your events to the log allowing you to look over it after the game has finished. You can snapshot the mission as many times as you want (although you will end up with huge log files if you do it often!) so that you can compare the state of the mission at various times. At time of writing, snapshotting requires that you are running a debug build of the game, or have entered the cheat code (type "freespace2.com" in mission). Press ~O to snapshot. 
Karajorma's Freespace FAQ. It's almost like asking me yourself.

[ Diaspora ] - [ Seeds Of Rebellion ] - [ Mind Games ]

 

Offline Goober5000

  • HLP Loremaster
  • 214
    • Goober5000 Productions
Re: Using the Event Log to find bugs in your missions
:yes:

This ought to be added to the wiki.

 

Offline Parias

  • 27
Re: Using the Event Log to find bugs in your missions
This is freaking awesome, and sounds like it will be insanely useful. Thank you so much for putting the effort into this  - it sounds like it'll help us all save immense amounts of time.

 

Offline karajorma

  • King Louie - Jungle VIP
  • Administrator
  • 214
    • Karajorma's Freespace FAQ
Re: Using the Event Log to find bugs in your missions
:yes:

This ought to be added to the wiki.

I figured I'd get some feedback from those who have and haven't used the event.log and see if it is useful to them first.
Karajorma's Freespace FAQ. It's almost like asking me yourself.

[ Diaspora ] - [ Seeds Of Rebellion ] - [ Mind Games ]

 

Offline Parias

  • 27
Re: Using the Event Log to find bugs in your missions
Wow, this just helped me big time. I've been busy trying to integrate Admiral MS' ship save/load script into my co-op mod to emulate Red Alert functionality, but was running into problems with a complex series of Conditional Operators to try and determine if a player is alive or not (saving a player ship when he's dead and then loading it afterwards literally blasts the player from the session and fires him instantly to debrief, while others stay in the game - my concept is to be nice and just let the player get a fresh default ship in the next mission if he happened to run out of respawns in the prior one).

I had something that basically multi-eval'd the script if the ship in question "is-player", AND if he was alive (a "not" check on is-destroyed-delay)... or to run the script if is-player returned false (as I don't care about AI ships obviously). However for some reason it kept running the script no matter what.

Flipping on the event logging flags in FRED and reviewing event.log after showed there was some kind of logic error in the is-destroyed-delay bit of the OR branch of my Event which caused it to always come back false. The log actually showed that is-destroyed-delay always seemed to come back as "CAN'T EVALUATE". I'm not sure if I was somehow using it wrong, or if there's a weird condition that causes this in network games for player ships... I also see from the code it's supposed to return 'false' anyways in this state, but this seemed to be messing up the expecting conditional handling regardless (I need to spend more time looking into why this was).

In any case, this finding prompted me to switch to the is-in-mission SEXP and use the raw return from that instead. Worked like a charm. So, thanks for this! I still wasted like 3 hours trying to figure this problem out, but it wouldn't been much longer without this kind of look as to what was actually going on under the hood.

 

Offline karajorma

  • King Louie - Jungle VIP
  • Administrator
  • 214
    • Karajorma's Freespace FAQ
Re: Using the Event Log to find bugs in your missions
Looking at the code, you'll get a SEXP_CANT_EVAL if you use is-destroyed-delay for a ship or wing that hasn't arrived yet. Not sure why you're getting that for a ship that is found present by is-in-mission but I suspect the same thing you do, something in the player ship code.
Karajorma's Freespace FAQ. It's almost like asking me yourself.

[ Diaspora ] - [ Seeds Of Rebellion ] - [ Mind Games ]

 

Offline AdmiralRalwood

  • 211
  • The Cthulhu programmer himself!
    • Skype
    • Steam
    • Twitter
Re: Using the Event Log to find bugs in your missions
For SEXP_CANT_EVAL to be returned from is-destroyed-delay, that requires sexp_query_has_yet_to_arrive() to return 1. This can happen if the ship is part of a wing with the WF_NEVER_EXISTED flag or a total_arrived_count of 0, presumably neither of which would be true of the player, which leaves only ship_query_state() returning -1. ship_query_state() only returns -1 if name is NULL (which should trigger an assertion; did you try it in a debug build, and if so, did you trigger a "name != NULL" assertion?) or mission_parse_get_arrival_ship() evaluates to anything boolean true. mission_parse_get_arrival_ship() returns NULL unless a case-insensitive string comparison shows that its name is in the Ship_arrival_list. I'm guessing, at the moment, that something about multiplayer is putting currently-present ships on the Ship_arrival_list for one reason or another, and this is causing the is-destroyed-delay SEXP to think they haven't arrived yet, even when they have.

All of this is supposition due to a lack of knowledge of how multiplayer works, unfortunately. Another possibility, if you didn't try it in a debug build (or did and triggered the assertion), is that it may be calling ship_query_state(NULL) for some reason.
Ph'nglui mglw'nafh Codethulhu GitHub wgah'nagl fhtagn.

schrödinbug (noun) - a bug that manifests itself in running software after a programmer notices that the code should never have worked in the first place.

When you gaze long into BMPMAN, BMPMAN also gazes into you.

"I am one of the best FREDders on Earth" -General Battuta

<Aesaar> literary criticism is vladimir putin

<MageKing17> "There's probably a reason the code is the way it is" is a very dangerous line of thought. :P
<MageKing17> Because the "reason" often turns out to be "nobody noticed it was wrong".
(the very next day)
<MageKing17> this ****ing code did it to me again
<MageKing17> "That doesn't really make sense to me, but I'll assume it was being done for a reason."
<MageKing17> **** ME
<MageKing17> THE REASON IS PEOPLE ARE STUPID
<MageKing17> ESPECIALLY ME

<MageKing17> God damn, I do not understand how this is breaking.
<MageKing17> Everything points to "this should work fine", and yet it's clearly not working.
<MjnMixael> 2 hours later... "God damn, how did this ever work at all?!"
(...)
<MageKing17> so
<MageKing17> more than two hours
<MageKing17> but once again we have reached the inevitable conclusion
<MageKing17> How did this code ever work in the first place!?

<@The_E> Welcome to OpenGL, where standards compliance is optional, and error reporting inconsistent

<MageKing17> It was all working perfectly until I actually tried it on an actual mission.

<IronWorks> I am useful for FSO stuff again. This is a red-letter day!
* z64555 erases "Thursday" and rewrites it in red ink

<MageKing17> TIL the entire homing code is held up by shoestrings and duct tape, basically.

 

Offline procdrone

  • Formerly TheHound
  • 29
  • Balance breaker! Thats me!
    • Steam
Re: Using the Event Log to find bugs in your missions
:yes:

This ought to be added to the wiki.

I figured I'd get some feedback from those who have and haven't used the event.log and see if it is useful to them first.

I never use those, or the event.log, but most of the errors are traceable without it. Maybe in future Ill find some use for it... but until now... simple event logic is enough for me.
--Did it! It's RELEASED! VeniceMirror Thread--

 

Offline Parias

  • 27
Re: Using the Event Log to find bugs in your missions
Cool, thanks for the feedback - this might be branching off into a separate discussion, but just to prove I'm not insane I took some time tonight to repro this in a test lab, and I think this behavior makes a bit of sense from what you've described.

I set up a dummy mission with the following event:

Code: [Select]
$Formula: ( every-time
   ( not
      ( is-destroyed-delay 0 "Alpha 2" )
   )
   ( send-message
      "#Command"
      "High"
      "Alpha 2 is alive!"
   )
)

Basically - "so long as Alpha 2 isn't destroyed, spam a ton of send-message events".. This works as expected in a network game if Alpha 2 is not occupied by a player. Messages will repeatedly appear until I blow him up, and then they stop (after a short delay - send-message in conjunction with every-time probably isn't the best test for this since it generates a backlog that takes awhile to work through). Event.log shows the following transition when Alpha 2 blows up:

Code: [Select]
Event: Do the thing at mission time 10 seconds (10543 milliseconds)
every-time returned NOT A NUMBER
send-message returned TRUE
not returned TRUE
is-destroyed-delay returned FALSE

Event: Do the thing at mission time 10 seconds (10558 milliseconds)
every-time returned NOT A NUMBER
not returned ALWAYS FALSE
is-destroyed-delay returned ALWAYS TRUE

So, "is-destroyed-delay" for Alpha 2 changes from "False" to "Always True". My "not" check then changes to "always false", and the messages stop accordingly.

However, if I then throw a player into Alpha 2's seat, the messages will continue rolling indefinitely. And here's what's happening instead:

Code: [Select]
Event: Do the thing at mission time 13 seconds (13740 milliseconds)
every-time returned NOT A NUMBER
send-message returned TRUE
not returned TRUE
is-destroyed-delay returned FALSE

Event: Do the thing at mission time 13 seconds (13759 milliseconds)
every-time returned NOT A NUMBER
send-message returned TRUE
not returned TRUE
is-destroyed-delay returned CAN'T EVALUATE

"is-destroyed-delay" changes from "False" to "Can't evaluate" when a player-occupied Alpha 2 is destroyed. The problem is that since this is still technically "False", my "not" bit still returns true. The condition is satisfied even though Alpha 2 is destroyed, and the associated SEXP continues rolling.

Ultimately then "is-destroyed-delay" doesn't work for a player-controlled ship because it'll just technically come up False either way.

I ran this through a debug build but didn't see any asserts / crashes. I'm not sure yet if I really want to make a bigger deal out of this issue, especially since "is-in-mission" seems to work just fine instead, but maybe there could be bigger implications from this? If I see further issues, I'll throw a debugger in there and check the bits you described AdmiralRalwood.

Again though, this does show that the event logging can be pretty useful, even beyond just basic mission debugging :D

 

Offline karajorma

  • King Louie - Jungle VIP
  • Administrator
  • 214
    • Karajorma's Freespace FAQ
Re: Using the Event Log to find bugs in your missions
I suspect I know the cause for this. It might seem strange but the is-destroyed-delay SEXP works by checking what is written into the mission log. In a multiplayer game press F4 after player 2 blows up and see what is written there. I suspect that it is different from what happens if a player is in the ship, and that difference is causing the difference in what you see happening in the mission.
Karajorma's Freespace FAQ. It's almost like asking me yourself.

[ Diaspora ] - [ Seeds Of Rebellion ] - [ Mind Games ]

 

Offline AdmiralRalwood

  • 211
  • The Cthulhu programmer himself!
    • Skype
    • Steam
    • Twitter
Re: Using the Event Log to find bugs in your missions
I suspect I know the cause for this. It might seem strange but the is-destroyed-delay SEXP works by checking what is written into the mission log. In a multiplayer game press F4 after player 2 blows up and see what is written there. I suspect that it is different from what happens if a player is in the ship, and that difference is causing the difference in what you see happening in the mission.
The mission log not containing the right entries won't cause a return value of SEXP_CANT_EVAL; I enumerated the possibilities for SEXP_CANT_EVAL getting returned here (and Parias's last post ruled out ship_query_state() getting called with a NULL argument).
Ph'nglui mglw'nafh Codethulhu GitHub wgah'nagl fhtagn.

schrödinbug (noun) - a bug that manifests itself in running software after a programmer notices that the code should never have worked in the first place.

When you gaze long into BMPMAN, BMPMAN also gazes into you.

"I am one of the best FREDders on Earth" -General Battuta

<Aesaar> literary criticism is vladimir putin

<MageKing17> "There's probably a reason the code is the way it is" is a very dangerous line of thought. :P
<MageKing17> Because the "reason" often turns out to be "nobody noticed it was wrong".
(the very next day)
<MageKing17> this ****ing code did it to me again
<MageKing17> "That doesn't really make sense to me, but I'll assume it was being done for a reason."
<MageKing17> **** ME
<MageKing17> THE REASON IS PEOPLE ARE STUPID
<MageKing17> ESPECIALLY ME

<MageKing17> God damn, I do not understand how this is breaking.
<MageKing17> Everything points to "this should work fine", and yet it's clearly not working.
<MjnMixael> 2 hours later... "God damn, how did this ever work at all?!"
(...)
<MageKing17> so
<MageKing17> more than two hours
<MageKing17> but once again we have reached the inevitable conclusion
<MageKing17> How did this code ever work in the first place!?

<@The_E> Welcome to OpenGL, where standards compliance is optional, and error reporting inconsistent

<MageKing17> It was all working perfectly until I actually tried it on an actual mission.

<IronWorks> I am useful for FSO stuff again. This is a red-letter day!
* z64555 erases "Thursday" and rewrites it in red ink

<MageKing17> TIL the entire homing code is held up by shoestrings and duct tape, basically.