Author Topic: Improved Event Logging  (Read 3328 times)

0 Members and 1 Guest are viewing this topic.

Offline karajorma

  • King Louie - Jungle VIP
  • Administrator
  • 214
    • Karajorma's Freespace FAQ
Improved Event Logging
Those of you who look in the Diaspora Tech Help forum will have already seen this. I don't know if people have realised how helpful this will be so I'm going to post it here for testing.

This patch includes two changes to the way FS2_Open can write to the event.log. The first change (requested by Axem) allows you to ask the event log to snapshot the state of all events it's testing this frame. In a debug build you can do this simply by pressing ~ + Q. Unlike the other logging functions, you do not need to decide ahead of time what you want to write to the log. Any event which is tested in this frame will be written to the log. Events which are already true or false won't be tested and therefore won't appear.
 The second change is to give the FREDder another option (replacing the Always True one which never worked anyway) to write a state change. Basically this means that if you tell FS2 to log whenever an event comes true, the event log will also write out the state of the event in the previous frame, giving you something like this.

Code: [Select]
Event has changed state. Old state
Log True - Switch at mission time 4 seconds (4616 milliseconds)
when returned FALSE
key-pressed returned FALSE
false returned ALWAYS FALSE
New state
Log True - Switch at mission time 4 seconds (4683 milliseconds)
when returned TRUE
do-nothing returned TRUE
key-pressed returned TRUE
false returned ALWAYS FALSE

As you can see, at 4616 milliseconds, the event was false and at 4683 it was true. Both events have been written to the log so you can see what changed.
 You could do this before by logging both true and false but that was very messy.


Since the first change is likely to become an important tool for FREDders or people giving tech support so I'm going to write it up in a way that can easily be copied and pasted. #

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


How to take a snapshot of the events in the game.

If you are having problems with a mission, rather than asking for a debug log, you may be asked for a snapshotted event log. You can get hold of it like this.

1) If you are running a debug copy of FS2_Open, you can skip this step. Otherwise, enter the FS2_Open cheat code www.freespace2.com to activate cheat mode.
2) Wait until the problem occurs and then press ~ (Above space on most keyboards) and Q at the same time.
3) When you exit the game look in your Freespace2/Data folder for a file called event.log. If you are running a mod, you will find the file in Freespace2/Mod Name/Data instead. If you are running a game other than Freespace2 (Diaspora, TBP, etc) you will find the file in that game's data folder (e.g Diaspora/Data).
4) Post here on HLP and attach the log to your post.


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


The builds for testing with can be found here.


For the coders, here's the code. It needs a bit of a clean up since I'm working on my travel laptop, I doubt I'll bother with that until I get back home and can use my main PC.

Code: [Select]
Index: code/fred2/eventeditor.cpp
===================================================================
--- code/fred2/eventeditor.cpp (revision 9734)
+++ code/fred2/eventeditor.cpp (working copy)
@@ -61,12 +61,12 @@
  m_wave_id = -1;
  m_log_true = 0;
  m_log_false = 0;
- m_log_always_true = 0;
  m_log_always_false = 0;
  m_log_1st_repeat = 0;
  m_log_last_repeat = 0;
  m_log_1st_trigger = 0;
  m_log_last_trigger = 0;
+ m_log_state_change = 0;
 }
 
 void event_editor::DoDataExchange(CDataExchange* pDX)
@@ -90,12 +90,12 @@
  DDX_LBIndex(pDX, IDC_MESSAGE_LIST, m_cur_msg);
  DDX_Check(pDX, IDC_MISSION_LOG_TRUE, m_log_true);
  DDX_Check(pDX, IDC_MISSION_LOG_FALSE, m_log_false);
- DDX_Check(pDX, IDC_MISSION_LOG_ALWAYS_TRUE, m_log_always_true);
  DDX_Check(pDX, IDC_MISSION_LOG_ALWAYS_FALSE, m_log_always_false);
  DDX_Check(pDX, IDC_MISSION_LOG_1ST_REPEAT, m_log_1st_repeat);
  DDX_Check(pDX, IDC_MISSION_LOG_LAST_REPEAT, m_log_last_repeat);
  DDX_Check(pDX, IDC_MISSION_LOG_1ST_TRIGGER, m_log_1st_trigger);
  DDX_Check(pDX, IDC_MISSION_LOG_LAST_TRIGGER, m_log_last_trigger);
+ DDX_Check(pDX, IDC_MISSION_LOG_STATE_CHANGE, m_log_state_change);
 
 
  // m_team == -1 maps to 2
@@ -900,8 +900,6 @@
  m_events[e].mission_log_flags |= MLF_SEXP_TRUE;
  if (m_log_false)
  m_events[e].mission_log_flags |= MLF_SEXP_FALSE;
- if (m_log_always_true)
- m_events[e].mission_log_flags |= MLF_SEXP_KNOWN_TRUE;
  if (m_log_always_false)
  m_events[e].mission_log_flags |= MLF_SEXP_KNOWN_FALSE;
  if (m_log_1st_repeat)
@@ -912,6 +910,8 @@
  m_events[e].mission_log_flags |= MLF_FIRST_TRIGGER_ONLY;
  if (m_log_last_trigger)
  m_events[e].mission_log_flags |= MLF_LAST_TRIGGER_ONLY;
+ if (m_log_state_change)
+ m_events[e].mission_log_flags |= MLF_STATE_CHANGE;
 
 
  // Search for item to update
@@ -1046,11 +1046,6 @@
  }else {
  m_log_false  = FALSE;
  }
- if (m_events[cur_event].mission_log_flags & MLF_SEXP_KNOWN_TRUE) {
- m_log_always_true  = TRUE;
- }else {
- m_log_always_true  = FALSE;
- }
  if (m_events[cur_event].mission_log_flags & MLF_SEXP_KNOWN_FALSE) {
  m_log_always_false  = TRUE;
  }else {
@@ -1076,6 +1071,11 @@
  }else {
  m_log_last_trigger  = FALSE;
  }
+ if (m_events[cur_event].mission_log_flags & MLF_STATE_CHANGE) {
+ m_log_state_change  = TRUE;
+ }else {
+ m_log_state_change  = FALSE;
+ }
 
  UpdateData(FALSE);
 }
Index: code/fred2/eventeditor.h
===================================================================
--- code/fred2/eventeditor.h (revision 9734)
+++ code/fred2/eventeditor.h (working copy)
@@ -73,12 +73,12 @@
  int m_last_message_node;
  int m_log_true;
  int m_log_false;
- int m_log_always_true;
  int m_log_always_false;
  int m_log_1st_repeat;
  int m_log_last_repeat;
  int m_log_1st_trigger;
  int m_log_last_trigger;
+ int m_log_state_change;
  //}}AFX_DATA
 
  CBitmap m_play_bm;
Index: code/fred2/fred.rc
===================================================================
--- code/fred2/fred.rc (revision 9734)
+++ code/fred2/fred.rc (working copy)
@@ -1284,7 +1284,7 @@
     CONTROL         "Last Repeat",IDC_MISSION_LOG_LAST_REPEAT,"Button",BS_AUTOCHECKBOX | WS_TABSTOP,97,410,55,10
     CONTROL         "First Trigger",IDC_MISSION_LOG_1ST_TRIGGER,"Button",BS_AUTOCHECKBOX | WS_TABSTOP,155,397,53,10
     CONTROL         "Last Trigger",IDC_MISSION_LOG_LAST_TRIGGER,"Button",BS_AUTOCHECKBOX | WS_TABSTOP,155,410,53,10
-    CONTROL         "Always True",IDC_MISSION_LOG_ALWAYS_TRUE,"Button",BS_AUTOCHECKBOX | WS_TABSTOP,37,397,55,10
+    CONTROL         "Log Previous",IDC_MISSION_LOG_STATE_CHANGE,"Button",BS_AUTOCHECKBOX | WS_TABSTOP,37,397,55,10
     CONTROL         "Always False",IDC_MISSION_LOG_ALWAYS_FALSE,"Button",BS_AUTOCHECKBOX | WS_TABSTOP,37,410,57,10
     LTEXT           "Log These States To The Event.log",IDC_STATIC,37,386,114,8
 END
Index: code/fred2/management.cpp
===================================================================
--- code/fred2/management.cpp (revision 9734)
+++ code/fred2/management.cpp (working copy)
@@ -325,7 +325,7 @@
  // NOTE : Fred should ALWAYS run in English. Otherwise it might swap in another language
  // when saving - which would cause inconsistencies when externalizing to tstrings.tbl via Exstr
  // trust me on this :)
- lcl_init(LCL_ENGLISH);
+ lcl_init(FS2_OPEN_DEFAULT_LANGUAGE);
 
  // Goober5000 - force init XSTRs (so they work, but only work in English, based on above comment)
  extern int Xstr_inited;
Index: code/fred2/resource.h
===================================================================
--- code/fred2/resource.h (revision 9734)
+++ code/fred2/resource.h (working copy)
@@ -1164,7 +1164,7 @@
 #define IDC_NEB_FAR_MULTIPLIER          1634
 #define IDC_MISSION_LOG_TRUE            1635
 #define IDC_MISSION_LOG_FALSE           1636
-#define IDC_MISSION_LOG_ALWAYS_TRUE     1637
+#define IDC_MISSION_LOG_STATE_CHANGE    1637
 #define IDC_MISSION_LOG_ALWAYS_FALSE    1638
 #define IDC_MISSION_LOG_1ST_REPEAT      1639
 #define IDC_MISSION_LOG_LAST_REPEAT     1640
Index: code/freespace2/freespace.cpp
===================================================================
--- code/freespace2/freespace.cpp (revision 9734)
+++ code/freespace2/freespace.cpp (working copy)
@@ -8378,14 +8378,6 @@
 // Language autodetection stuff
 //
 
-// this layout *must* match Lcl_languages in localize.cpp in order for the
-// correct language to be detected
-int Lang_auto_detect_checksums[LCL_NUM_LANGUAGES] = {
- 589986744, // English
- -1132430286, // German
- 0, // French
-};
-
 // default setting is "-1" to use registry setting with English as fall back
 // DO NOT change that default setting here or something uncouth might happen
 // in the localization code
@@ -8415,8 +8407,8 @@
  detect = NULL;
 
  // now compare the checksum/filesize against known #'s
- for (idx=0; idx<LCL_NUM_LANGUAGES; idx++) {
- if (Lang_auto_detect_checksums[idx] == (int)file_checksum) {
+ for (idx=0; idx < (int)Lcl_languages.size(); idx++) {
+ if (Lcl_languages[idx].checksum == (int)file_checksum) {
  mprintf(( "AutoLang: Language auto-detection successful...\n" ));
  return idx;
  }
Index: code/io/keycontrol.cpp
===================================================================
--- code/io/keycontrol.cpp (revision 9734)
+++ code/io/keycontrol.cpp (working copy)
@@ -634,6 +634,10 @@
  }
 
  switch (k) {
+ case KEY_DEBUGGED + KEY_Q:
+ Snapshot_all_events = true;
+ break;
+
  case KEY_DEBUGGED + KEY_H:
  hud_target_toggle_hidden_from_sensors();
  break;
Index: code/mission/missiongoals.cpp
===================================================================
--- code/mission/missiongoals.cpp (revision 9734)
+++ code/mission/missiongoals.cpp (working copy)
@@ -172,6 +172,7 @@
 int Num_goals = 0; // number of goals for this mission
 int Event_index = -1;  // used by sexp code to tell what event it came from
 bool Log_event = false;
+bool Snapshot_all_events = false;
 int Mission_goal_timestamp;
 
 mission_event Mission_events[MAX_MISSION_EVENTS];
@@ -919,8 +920,12 @@
 
  if (sindex >= 0) {
  Sexp_useful_number = 1;
- if (Mission_events[event].mission_log_flags != 0) {
+ if (Snapshot_all_events || Mission_events[event].mission_log_flags != 0) {
  Log_event = true;
+
+ Current_event_log_buffer = &Mission_events[event].event_log_buffer;
+ Current_event_log_variable_buffer = &Mission_events[event].event_log_variable_buffer;
+ Current_event_log_argument_buffer = &Mission_events[event].event_log_argument_buffer;
  }
  result = eval_sexp(sindex);
 
@@ -945,7 +950,7 @@
  }
  }
 
- if (Mission_events[event].mission_log_flags != 0) {
+ if ((Mission_events[event].mission_log_flags != 0) || Snapshot_all_events ){
  maybe_write_to_event_log(result);
  }
 
@@ -1094,7 +1099,7 @@
  std_multi_update_goals();
  }
 
- Log_event = false;
+ Snapshot_all_events = false;
 }
 
 // evaluate_primary_goals() will determine if the primary goals for a mission are complete
Index: code/mission/missiongoals.h
===================================================================
--- code/mission/missiongoals.h (revision 9734)
+++ code/mission/missiongoals.h (working copy)
@@ -12,6 +12,7 @@
 #ifndef _MISSIONGOAL_H
 #define _MISSIONGOAL_H
 
+#include "globalincs/pstypes.h"
 #include "globalincs/globals.h"
 
 struct ai_goal;
@@ -83,16 +84,17 @@
 #define MEF_DIRECTIVE_TEMP_TRUE (1 << 2) // this directive is temporarily true.
 #define MEF_USING_TRIGGER_COUNT (1 << 3) // Karajorma - use trigger count as well as repeat count to determine how many repeats this event has
 
-#define MAX_MISSION_EVENT_LOG_FLAGS 8 // this must be added if a mission log flag is added below
+#define MAX_MISSION_EVENT_LOG_FLAGS 9 // this must be changed if a mission log flag is added below
 
 #define MLF_SEXP_TRUE (1 << 0)
 #define MLF_SEXP_FALSE (1 << 1)
-#define MLF_SEXP_KNOWN_TRUE (1 << 2)
+//#define MLF_SEXP_KNOWN_TRUE (1 << 2)
 #define MLF_SEXP_KNOWN_FALSE (1 << 3)
 #define MLF_FIRST_REPEAT_ONLY (1 << 4)
 #define MLF_LAST_REPEAT_ONLY (1 << 5)
 #define MLF_FIRST_TRIGGER_ONLY (1 << 6)
-#define MLF_LAST_TRIGGER_ONLY (1 << 7)
+#define MLF_LAST_TRIGGER_ONLY (1 << 7)
+#define MLF_STATE_CHANGE (1 << 8)
 
 #define MLF_ALL_REPETITION_FLAGS (MLF_FIRST_REPEAT_ONLY | MLF_LAST_REPEAT_ONLY | MLF_FIRST_TRIGGER_ONLY | MLF_LAST_TRIGGER_ONLY)
 
@@ -113,7 +115,15 @@
  int satisfied_time; // this is used to temporarily mark the directive as satisfied when the event isn't (e.g. for a destroyed wave when there are more waves later)
  int born_on_date; // timestamp at which event was born
  int team; // for multiplayer games
+
+ // event log stuff
  int mission_log_flags; // flags that are used to determing which events are written to the log
+ SCP_vector<SCP_string> event_log_buffer;
+ SCP_vector<SCP_string> event_log_variable_buffer;
+ SCP_vector<SCP_string> event_log_argument_buffer;
+ SCP_vector<SCP_string> backup_log_buffer;
+ int previous_result; // result of previous evaluation of event
+
 } mission_event;
 
 extern int Num_mission_events;
@@ -121,6 +131,7 @@
 extern int Mission_goal_timestamp;
 extern int Event_index;  // used by sexp code to tell what event it came from
 extern bool Log_event;
+extern bool Snapshot_all_events;
 
 // prototypes
 void mission_init_goals( void );
Index: code/mission/missionparse.cpp
===================================================================
--- code/mission/missionparse.cpp (revision 9734)
+++ code/mission/missionparse.cpp (working copy)
@@ -315,12 +315,13 @@
 char *Mission_event_log_flags[MAX_MISSION_EVENT_LOG_FLAGS] = {
  "true",
  "false",
- "always true",
+ "always true", // disabled
  "always false",
  "first repeat",
  "last repeat",
  "first trigger",
  "last trigger",
+ "state change",
 };
 
 
Index: code/parse/sexp.cpp
===================================================================
--- code/parse/sexp.cpp (revision 9734)
+++ code/parse/sexp.cpp (working copy)
@@ -898,10 +898,9 @@
 #define SEXP_HUD_GAUGE_WARPOUT "warpout"
 
 // event log stuff
-SCP_vector<SCP_string> event_log_buffer;
-SCP_vector<SCP_string> event_log_variable_buffer;
-SCP_vector<SCP_string> event_log_argument_buffer;
-
+SCP_vector<SCP_string> *Current_event_log_buffer;
+SCP_vector<SCP_string> *Current_event_log_variable_buffer;
+SCP_vector<SCP_string> *Current_event_log_argument_buffer;
 // Goober5000 - arg_item class stuff, borrowed from sexp_list_item class stuff -------------
 void arg_item::add_data(char *str)
 {
@@ -8223,7 +8222,7 @@
  ptr = Sexp_applicable_argument_list.get_next();
  while(ptr != NULL) {
  // See if we have an argument.
- event_log_argument_buffer.push_back(ptr->text);
+ Current_event_log_argument_buffer->push_back(ptr->text);
  ptr = ptr->get_next();
  }
  }
@@ -21231,16 +21230,8 @@
  matches |= MLF_SEXP_FALSE;
  break;
 
- case SEXP_KNOWN_TRUE:
- matches |= MLF_SEXP_KNOWN_TRUE;
- break;
-
- case SEXP_KNOWN_FALSE:
- matches |= MLF_SEXP_KNOWN_FALSE;
- break;
-
  default:
- Int3(); // just for now. This shouldn't hit trunk!
+ Error(LOCATION, "SEXP has a value which isn't true or false.");
  }
 
  if (( result == SEXP_TRUE ) || (result == SEXP_KNOWN_TRUE)) {
@@ -21275,7 +21266,45 @@
  return matches;
 }
 
+void current_log_to_backup_log_buffer()
+{
+ Mission_events[Event_index].backup_log_buffer.clear();
+ if (!(Mission_events[Event_index].mission_log_flags & MLF_STATE_CHANGE)){
+ return;
+ }
 
+ for (int i = 0; i < (int)Current_event_log_buffer->size(); i++) {
+ Mission_events[Event_index].backup_log_buffer.push_back(Current_event_log_buffer->at(i));
+ }
+}
+
+void maybe_write_previous_event_to_log(int result)
+{
+ mission_event *this_event = &Mission_events[Event_index];
+
+ // if the old log is empty, all we do is record the result for the next evaluation
+ // the old log should only be empty at mission start
+ if (this_event->backup_log_buffer.empty()) {
+ this_event->previous_result = result;
+ return;
+ }
+
+ // if there's no change in state, we don't write the previous state to the log
+ if ((this_event->mission_log_flags & MLF_STATE_CHANGE) && (result == this_event->previous_result)) {
+ return;
+ }
+
+ log_string(LOGFILE_EVENT_LOG, "Event has changed state. Old state");
+ while (!this_event->backup_log_buffer.empty()) {
+ log_string(LOGFILE_EVENT_LOG, this_event->backup_log_buffer.back().c_str());
+ this_event->backup_log_buffer.pop_back();
+ }
+ log_string(LOGFILE_EVENT_LOG, "New state");
+
+ // backup the current buffer as this may be a repeating event
+ current_log_to_backup_log_buffer();
+}
+
 /**
 * Checks the mission logs flags for this event and writes to the log if this has been asked for
 */
@@ -21284,8 +21313,12 @@
  char buffer [256];
 
  int mask = generate_event_log_flags_mask(result);
- if (!(mask &=  Mission_events[Event_index].mission_log_flags)) {
- event_log_buffer.clear();
+ sprintf(buffer, "%s at mission time %d seconds (%d milliseconds)", Mission_events[Event_index].name, f2i(Missiontime), f2i((longlong)Missiontime * 1000));
+ Current_event_log_buffer->push_back(buffer);
+
+ if (!Snapshot_all_events && (!(mask &=  Mission_events[Event_index].mission_log_flags))) {
+ current_log_to_backup_log_buffer();
+ Current_event_log_buffer->clear();
  return;
  }
 
@@ -21294,18 +21327,16 @@
  Mission_events[Event_index].mission_log_flags &= ~(MLF_FIRST_REPEAT_ONLY | MLF_FIRST_TRIGGER_ONLY) ;
  }
 
- if (event_log_buffer.empty()) {
- return;
+ if (Mission_events[Event_index].mission_log_flags & MLF_STATE_CHANGE) {
+ maybe_write_previous_event_to_log(result);
  }
 
- sprintf(buffer, "%s at mission time %d seconds (%d milliseconds)", Mission_events[Event_index].name, f2i(Missiontime), f2i((longlong)Missiontime * 1000));
-
- log_string(LOGFILE_EVENT_LOG, buffer);
- while (!event_log_buffer.empty()) {
- log_string(LOGFILE_EVENT_LOG, event_log_buffer.back().c_str());
- event_log_buffer.pop_back();
+ while (!Current_event_log_buffer->empty()) {
+ log_string(LOGFILE_EVENT_LOG, Current_event_log_buffer->back().c_str());
+ Current_event_log_buffer->pop_back();
  }
  log_string(LOGFILE_EVENT_LOG, "");
+
 }
 
 /**
@@ -21348,6 +21379,10 @@
 */
 void add_to_event_log_buffer(int op_num, int result)
 {
+ Assertion ((Current_event_log_buffer != NULL) &&
+ (Current_event_log_variable_buffer != NULL)&&
+ (Current_event_log_argument_buffer != NULL), "Attempting to write to a non-existent log buffer");
+
  if (op_num == -1) {
  nprintf(("SEXP", "ERROR: op_num function returned %i, this should not happen. Contact a coder.\n", op_num));
  return; //How does this happen?
@@ -21371,28 +21406,28 @@
  tmp.append(Sexp_replacement_arguments.back());
  }
 
- if (!event_log_argument_buffer.empty()) {
+ if (!Current_event_log_argument_buffer->empty()) {
  tmp.append(" for the following arguments");
- while (!event_log_argument_buffer.empty()) {
+ while (!Current_event_log_argument_buffer->empty()) {
  tmp.append("\n");
- tmp.append(event_log_argument_buffer.back().c_str());
- event_log_argument_buffer.pop_back();
+ tmp.append(Current_event_log_argument_buffer->back().c_str());
+ Current_event_log_argument_buffer->pop_back();
  }
  }
 
- if (!event_log_variable_buffer.empty()) {
+ if (!Current_event_log_variable_buffer->empty()) {
  tmp.append("\nVariables:\n");
- while (!event_log_variable_buffer.empty()) {
- tmp.append(event_log_variable_buffer.back().c_str());
- event_log_variable_buffer.pop_back();
+ while (!Current_event_log_variable_buffer->empty()) {
+ tmp.append(Current_event_log_variable_buffer->back().c_str());
+ Current_event_log_variable_buffer->pop_back();
  tmp.append("[");
- tmp.append(event_log_variable_buffer.back().c_str());
- event_log_variable_buffer.pop_back();
+ tmp.append(Current_event_log_variable_buffer->back().c_str());
+ Current_event_log_variable_buffer->pop_back();
  tmp.append("]");
  }
  }
 
- event_log_buffer.push_back(tmp);
+ Current_event_log_buffer->push_back(tmp);
 }
 
 /**
@@ -27086,8 +27121,8 @@
  Assert(Sexp_variables[sexp_variable_index].type & SEXP_VARIABLE_SET);
 
  if (Log_event) {
- event_log_variable_buffer.push_back(Sexp_variables[sexp_variable_index].text);
- event_log_variable_buffer.push_back(Sexp_variables[sexp_variable_index].variable_name);
+ Current_event_log_variable_buffer->push_back(Sexp_variables[sexp_variable_index].text);
+ Current_event_log_variable_buffer->push_back(Sexp_variables[sexp_variable_index].variable_name);
  }
 
  return Sexp_variables[sexp_variable_index].text;
Index: code/parse/sexp.h
===================================================================
--- code/parse/sexp.h (revision 9734)
+++ code/parse/sexp.h (working copy)
@@ -1079,6 +1079,12 @@
 
 extern SCP_vector<int> Current_sexp_operator;
 
+
+// event log stuff
+extern SCP_vector<SCP_string> *Current_event_log_buffer;
+extern SCP_vector<SCP_string> *Current_event_log_variable_buffer;
+extern SCP_vector<SCP_string> *Current_event_log_argument_buffer;
+
 extern void init_sexp();
 extern int alloc_sexp(char *text, int type, int subtype, int first, int rest);
 extern int find_free_sexp();
Karajorma's Freespace FAQ. It's almost like asking me yourself.

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