Matrix Games Forums

Forums  Register  Login  Photo Gallery  Member List  Search  Calendars  FAQ 

My Profile  Inbox  Address Book  My Subscription  My Forums  Log Out

Coder Diary #15 -- Logging

 
View related threads: (in this forum | in all forums)

Logged in as: Guest
Users viewing this topic: none
  Printable Version
All Forums >> [Current Games From Matrix.] >> [World War II] >> John Tiller's Campaign Series >> Coder Diary #15 -- Logging Page: [1]
Login
Message << Older Topic   Newer Topic >>
Coder Diary #15 -- Logging - 1/4/2014 9:47:47 PM   
berto


Posts: 17250
Joined: 3/13/2002
From: metro Chicago, Illinois, USA
Status: online

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



    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:



    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...

    < Message edited by berto -- 1/5/2014 4:29:46 AM >


    _____________________________

  • Post #: 1
    RE: Coder Diary #15 -- Logging - 1/4/2014 11:05:07 PM   
    junk2drive


    Posts: 12907
    Joined: 6/27/2002
    From: Arizona West Coast
    Status: offline
    quote:


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


    I ordered a new video card in anticipation. Are we there yet?

    (in reply to berto)
    Post #: 2
    RE: Coder Diary #15 -- Logging - 1/5/2014 8:24:10 AM   
    lecrop


    Posts: 246
    Joined: 4/14/2009
    Status: offline
    An essential improvement

    _____________________________


    (in reply to junk2drive)
    Post #: 3
    RE: Coder Diary #15 -- Logging - 1/5/2014 8:25:22 AM   
    Crossroads


    Posts: 14394
    Joined: 7/5/2009
    Status: offline

    quote:

    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

    quote:

    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 | CS: East Front 1939-1941 IN-THE-WORKS
    CS: Middle East 1948-1985 Fully reimaged v2.0 available now!

    (in reply to berto)
    Post #: 4
    RE: Coder Diary #15 -- Logging - 1/5/2014 2:06:11 PM   
    wings7


    Posts: 4608
    Joined: 8/11/2003
    From: Phoenix, Arizona
    Status: offline
    Thank you!

    Patrick

    (in reply to Crossroads)
    Post #: 5
    Page:   [1]
    All Forums >> [Current Games From Matrix.] >> [World War II] >> John Tiller's Campaign Series >> Coder Diary #15 -- Logging Page: [1]
    Jump to:





    New Messages No New Messages
    Hot Topic w/ New Messages Hot Topic w/o New Messages
    Locked w/ New Messages Locked w/o New Messages
     Post New Thread
     Reply to Message
     Post New Poll
     Submit Vote
     Delete My Own Post
     Delete My Own Thread
     Rate Posts


    Forum Software © ASPPlayground.NET Advanced Edition 2.4.5 ANSI

    0.109