Coder Diary #15 -- Logging

John Tiller's Campaign Series exemplifies tactical war-gaming at its finest by bringing you the entire collection of TalonSoft's award-winning campaign series. Containing TalonSoft's West Front, East Front, and Rising Sun platoon-level combat series, as well as all of the official add-ons and expansion packs, the Matrix Edition allows players to dictate the events of World War II from the tumultuous beginning to its climatic conclusion. We are working together with original programmer John Tiller to bring you this updated edition.

Moderators: Jason Petho, Peter Fisla, asiaticus, dogovich

Post Reply
User avatar
berto
Posts: 21461
Joined: Wed Mar 13, 2002 1:15 am
Location: metro Chicago, Illinois, USA
Contact:

Coder Diary #15 -- Logging

Post by berto »


Coder Diary #15 -- Logging


The Campaign Series -- for the Lead Programmer (me), it's not all fun and games. Too little gaming, too much coding, in fact. [:(]

But coding is fun in its geeky sort of way too. [:)]

I have spoken elsewhere of the need for "fixing the many, many foundational issues in the JTCS code."

One of those issues? Logging. In the legacy code, there is no formal logging. What little logging we have is quite rudimentary, very ad hoc.

I need to fix that. Why is it so important?

[*]For tech support.

Up until now, if a player (or Dev Team member) experiences a crash, or some other error, the Dev Team members have to play guessing games, rely on hunches, suggest experiments ("try this", "try that"). As the Lead Coder, I have all manner of logging and debugging available to me. But in the release code, there has been effectively none. Something goes wrong on the end-user, player's end, and it's anybody's guess.

[*]For debugging.

As I said, I have all manner of debugging tools and techniques available to me. In addition to the traditional types of debugging in Microsoft Visual Studio 2008 (my development IDE) -- breakpoints, single stepping through the code, traces, variable inspection and on-the-fly modification, asserts, etc. -- I employ many different non-traditional debug and QA tools and techniques outside the VS IDE -- at the Cygwin (or even Linux) command line, combining dozens of handy Unix-like utilities, else writing custom, often one-off scripts in Awk, Perl, or the Bash shell.

But in many situations, nothing beats having a full-featured, flexible logging facility built into the release code, to monitor and analyze variables and program execution as (or after) the code runs. In many circumstances, run-time logging is the right tool for the job.

[*]For empirical testing.

I have written some code to perform some algorithm. Does it work as intended? Let's log key variables and note important guide posts as the game (or editor) executes. During run time, else post mortem, look at the audit trail. Seeing is believing. The proof is in the pudding.

How does it work? (Warning: A bit of techno stuff follows. Ignore and just skim through as you wish.)

[techno stuff begins]

I have coded two new functions

[*]logreturn(), to log (and perhaps report real-time in a pop-up message box) some error condition or something of interest. After the entry logging (and maybe message box), the function returns to its caller and the program resumes execution.
[*]logexit(), to log (and perhaps report real-time in a pop-up message box) some error condition or something of interest. After the entry logging (and maybe message box), the program terminates. Doesn't crash; rather, it's a controlled exit, with the reason for the exit logged (and perhaps reported real-time in a pop-up).

I have implemented a new in-game PDF file reader facility (using the Open Source Sumatra PDF Reader) to access the CS Manual. If for some reason the CS Manual has gone missing, you would see a pop-up like this

Image

and, logged in engine.log, something like this

2014-01-01 11:08:03 ef.exe: [WARNING ID 100] ../Manuals/CS-Manual-[LIGHT].pdf not found

Here is the code that calls the logreturn() function to log, and report, the "error":

} else if (!FileExists (_csmanual)) {
logreturn(APPLOG, true, LOG_WARNING, ERRID_FILE_NOT_FOUND, __FILE__, __LINE__, fnnam, "%s not found", _csmanual);

As you can see, I have categorized this as a WARNING -- a nuisance, but not quite at the level of a serious ERROR.

Here is something rather more serious: What if the Roads3d.bmp file has gone missing?

You would see this:

Image

And this

2014-01-04 09:37:02 ef.exe: [ERROR ID 100] (bitmapdd.cpp, line 23, XCBitmapDD::XCBitmapDD()) C:\Games\Matrix Games\John Tiller's Campaign Series\East Front\Roads3d.bmp not found
2014-01-04 09:37:05 ef.exe: [ERROR ID 4] (bitmapdd.cpp, line 64, XCBitmapDD::BitmapSurface()) Failure to create bitmap surface: C:\Games\Matrix Games\John Tiller's Campaign Series\East Front\Roads3d.bmp

in the engine.log file, but also in the error.log file. In the new logging system, there are the standard log files

[*]engine.log
[*]edit.log
[*]edmap.log
[*]edorg.log
[*]frontend.log
[*]ai.log

and for really serious errors

[*]error.log

WARNINGs (also NOTICEs and INFOs and miscellaneous lesser categories) appear in the first set of log files. ERRORs are logged to both engine.log (etc.) and error.log. engine.log etc. are zeroed out with each new game engine run, so only record ERRORs etc. for that one EXE run. error.log is cumulative; errors will accumulate for all EXEs, from one EXE run to another. error.log will only zero out and start over if you choose to make it so.

Here is the code that calls the logreturn() function to log, and report, the "Roads3d.bmp not found" error:

if ((hbm = (HBITMAP) LoadImage (AfxGetInstanceHandle (), filename, IMAGE_BITMAP, 0, 0, LR_LOADFROMFILE|LR_CREATEDIBSECTION)) == NULL)
/* logexit */ logreturn(ERRLOG, false, LOG_ERROR, ERRID_FILE_NOT_FOUND, __FILE__, __LINE__, fnnam, "%s not found", filename);
else
logreturn(APPLOG, false, LOG_INFO, ERRID_INFO, __FILE__, __LINE__, fnnam, "%s loaded", filename);

(Note that I have in place, commented out, a "logexit", as a reminder that maybe in future I might want to elevate this to something so important as to warrant a game exit. Note also that, if Roads3d.bmp is found, I log that INFO.

Here is the code that calls the logreturn() function to log, and report, the "Failure to create bitmap surface" error (see the log entry above):

HRESULT ret = CreateSurface (dd, bm.bmWidth, bm.bmHeight);
if (ret != DD_OK) {
Stringg error = MsgNoSurface;
if (filename != 0)
error += filename;
// MessageBox (0, error, MsgDirectDraw, MB_OK);
logreturn(ERRLOG, true, LOG_ERROR, ERRID_ERROR, __FILE__, __LINE__, fnnam, "%s", error);
}

[patience ...]

Here is a final example of a logreturn() call

logreturn(APPLOG, false, LOG_DEBUG, ERRID_DEBUG, __FILE__, __LINE__, fnnam, "current turn %d, base visibility %d, delta %d, adjusted visibility %d", _current_turn, visibility, delta, visibility+delta);

in this case, for empirical validation testing, to log some Visibility data (for the much hated, but still retained, Variable Visibility optional rule).

If you are a C/C++/... coder, you might have noticed something: logreturn() & logexit() have the flexibility of printf(), sprintf(), fprintf(), etc. in that one can specify an arbitrarily simple or complex format string with zero to many arguments. It is great to have such flexibility! (If you are a C/C++/... coder, you would understand. [;)])

What are all of these ERRIDs? They are defined in the file errid.h:

// errid.h -- error IDs

#ifndef _ERRID_H
#define _ERRID_H

#define ERRID_DEBUG 0
#define ERRID_INFO 1
#define ERRID_NOTICE 2
#define ERRID_WARNING 3
#define ERRID_ERROR 4

#define ERRID_FILE_NOT_FOUND 100
#define ERRID_FILE_CREATE_ERROR 101
#define ERRID_FILE_OPEN_ERROR 102
#define ERRID_FILE_CLOSE_ERROR 103
#define ERRID_FILE_STAT_ERROR 104
#define ERRID_FILE_REMOVE_ERROR 105
#define ERRID_FILE_RENAME_ERROR 106
#define ERRID_FILE_READ_ERROR 107
#define ERRID_FILE_WRITE_ERROR 108
#define ERRID_FILE_TELL_ERROR 109
#define ERRID_FILE_SEEK_ERROR 110

#define ERRID_DATA_ERROR 200

#endif

As you can see, for now, as a beginning, we mainly just log and report file-related ERRORs. Over time, I will expand this (and probably redo the numbering) to categorize all types of errors -- not just "file not found", but any ERROR or item of interest imaginable (or at least worth logging).

[techno stuff ends]

So what's this to you?

[*]We can provide you tech support more effectively.

Say your game crashes because some vital file (e.g., weapon.pdx) is missing. Or rather, before it would have crashed, but now (er, soon, when you get the update release) it "controlled exits". But as it does that, it gives you a pop-up message reporting the error. You can also go looking in engine.log or error.log as you wish.

Or maybe you go here to the Forum to complain. And our response will be: "Did you look in the engine.log & error.log first? Do they give you a clue? If not, zip them up and post them here at the Forum. We'll take a look ourselves. (And probably, hopefully, spot the problem in an instant.)"

See how much better tech support will be? No more guessing games, no more hunches. If we have done this right (and as we extend this logging facility in future), the logs will tell the tale!

[*]We can develop a better game.

Quite recently, I had to recode the Variable Visibility optional rule. (No comment, please.) I figured I had done it right, but to make sure, I added some logreturn() calls, then ran some automated test trials (see here and here) via

for t in 1 2 3 4 5 6 7 8 9 10; do ./ef.exe -W -T varvistest3.scn; egrep "start|delta|exit" engine.log >> testvvt3.log; done

then looked at the log files. I saw results like these:

Robert@roberto /cygdrive/c/Games/Matrix Games/John Tiller's Campaign Series/East Front
$ egrep "start|delta|exit" testvvt3.log
2014-01-03 16:44:00 ef.exe: [INFO ID 1] ef.exe startup
2014-01-03 16:44:55 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 2, base visibility 3, delta 0, adjusted visibility 3
2014-01-03 16:45:51 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 3, base visibility 3, delta 1, adjusted visibility 4
2014-01-03 16:46:25 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 4, base visibility 3, delta 1, adjusted visibility 4
2014-01-03 16:47:05 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 5, base visibility 3, delta 0, adjusted visibility 3
2014-01-03 16:47:57 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 6, base visibility 3, delta 0, adjusted visibility 3
2014-01-03 16:48:58 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 7, base visibility 3, delta -1, adjusted visibility 2
2014-01-03 16:49:34 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 8, base visibility 3, delta 0, adjusted visibility 3
2014-01-03 16:50:20 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 9, base visibility 3, delta 1, adjusted visibility 4
2014-01-03 16:51:15 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 10, base visibility 3, delta 1, adjusted visibility 4
2014-01-03 16:52:01 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 11, base visibility 3, delta 1, adjusted visibility 4
2014-01-03 16:53:01 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 12, base visibility 3, delta 1, adjusted visibility 4
2014-01-03 16:53:57 ef.exe: [INFO ID 1] ef.exe exit
2014-01-03 16:53:58 ef.exe: [INFO ID 1] ef.exe startup
2014-01-03 16:54:54 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 2, base visibility 3, delta 1, adjusted visibility 4
2014-01-03 16:55:48 ef.exe: [DEBUG ID 0] (forces.cpp, line 4294, Forces::VaryVisibility()) current turn 3, base visibility 3, delta 1, adjusted visibility 4
...

At first, I didn't like what I saw. I saw this or that goof, or anomaly, or overlooked gotcha, or the patterns just didn't seem right. Back to recoding, then testing, then log file inspecting; then more recoding, then more testing, more log file inspecting; ...; until I was finally satisfied with the results. My code not only looked good; it ran good.

See how much better the game development and end product will be?

This new logging facility will be of inestimable value as we add new features, revise the UI, improve the A/I, ..., bug fix.

You are probably not a programmer geek and you might think that this new logging facility means little to you. But trust me: it means a lot, even if you never consciously realize it! (If it's not clear: Under normal circumstances, you can ignore the log files. But they'll be there if you or we ever need them.)

There's more I could report. We are working furiously, aiming to meet the stated deadline for the upgrade release. I have imposed a feature freeze. From now until the end of the month, it's bug fixing, testing, testing, testing, and All QA All the Time.

Entering the home stretch. It won't be long now.

Until the next time...
Campaign Series Legion https://cslegion.com/
Campaign Series Lead Coder https://www.matrixgames.com/forums/view ... hp?f=10167
Panzer Campaigns, Panzer Battles Lead Coder https://wargameds.com
User avatar
junk2drive
Posts: 12856
Joined: Thu Jun 27, 2002 7:27 am
Location: Arizona West Coast

RE: Coder Diary #15 -- Logging

Post by junk2drive »

Entering the home stretch. It won't be long now.

I ordered a new video card in anticipation. Are we there yet?
Conflict of Heroes "Most games are like checkers or chess and some have dice and cards involved too. This game plays like checkers but you think like chess and the dice and cards can change everything in real time."
lecrop
Posts: 404
Joined: Tue Apr 14, 2009 12:49 pm

RE: Coder Diary #15 -- Logging

Post by lecrop »

An essential improvement
User avatar
Crossroads
Posts: 17498
Joined: Sun Jul 05, 2009 8:57 am

RE: Coder Diary #15 -- Logging

Post by Crossroads »

ORIGINAL: berto

Quite recently, I had to recode the Variable Visibility optional rule. (No comment, please.) I figured I had done it right, but to make sure, I added some logreturn() calls, then ran some automated test trials (see here and here) via

No comment? Quite the opposite! Well done for fixing yet another little legacy bug from the system [&o]
ORIGINAL: berto
You are probably not a programmer geek and you might think that this new logging facility means little to you. But trust me: it means a lot, even if you never consciously realize it! (If it's not clear: Under normal circumstances, you can ignore the log files. But they'll be there if you or we ever need them.)

They can be very useful for scenario designers as well. With the new logging framework in place, I was able to find out the EF was missing one particular *.BIT file for a Russian unit. While nothing major perhaps, the missing file has been added to the system, and next time you encounter the particular unit you will see it highlighted when selected.

So this is something useful for the modders as well, when you perhaps add new units and perhaps miss one of the many moving parts that make the data part of the game.

Remember: Game engine code + data = JTCS. Many crashes are result of corrupt data, not corrupt game code.
Visit us at: Campaign Series Legion
---
CS: Vietnam 1948-1967 < Available now
CS: Middle East 1948-1985 2.0 < 3.0 In the works
User avatar
wings7
Posts: 4586
Joined: Mon Aug 11, 2003 4:59 am
Location: Phoenix, Arizona

RE: Coder Diary #15 -- Logging

Post by wings7 »

Thank you! [&o]

Patrick
Please come and join and befriend me at the great Steam portal! There are quite a few Matrix/Slitherine players on Steam! My member page: http://steamcommunity.com/profiles/76561197988402427
Post Reply

Return to “John Tiller's Campaign Series”