SCI Logging
Originally posted on the SCI Programming Forums by Gumby.
I'm pleased to announce that the first version of SCI Logging has been hacked together & uploaded to the fan games page.
It essentially logs all the necessary events (all user interaction) that is required for a 'automated replay' of a game. Useful for testing & troubleshooting and should hopefully work for an automated walkthrough of a game. Ultimately, I'd like to create automated testing functionality where a recorded log file could be coupled with a file containing expected responses from the game.
Unfortunately I had to make extensive changes to the template game to make this work, too many to list here but here's an overview. I created a new script (LogEvent.sc) which is responsible for the heavy lifting, reading and writing events to/from a log file. For logging events, the calls are pretty much all wired into the User.sc and Controls.sc script. For replaying logs, the replay command is called in the doit() method in the Main.sc. Logging is enable/disabled in the init() method of the Main.sc script. Please see the commented/uncommented sections, you'll be able to spot them pretty easily.
Here's the included log file in the game (poorly formatted - it's a fixed width of 115 characters or so):
Ticks: 00000051 Event: gameLClick X: 201 Y: 083 Key: Msg:
Ticks: 00000054 Event: openPrint X: Y: Key: Msg: Initial Print
Ticks: 00000202 Event: closePrint X: Y: Key: Msg:
Ticks: 00000202 Event: openPrint X: Y: Key: Msg: Print #2
Ticks: 00000349 Event: closePrint X: Y: Key: Msg:
Ticks: 00000409 Event: keyMove X: Y: Key: $4d00 Msg:
Ticks: 00000529 Event: parseOpen X: Y: Key: Msg: Enter Input:
Ticks: 00000607 Event: parseClose X: Y: Key: Msg: look
Ticks: 00000608 Event: openPrint X: Y: Key: Msg: I see nothing
Ticks: 00000882 Event: closePrint X: Y: Key: Msg:
Ticks: 00000990 Event: keyMove X: Y: Key: $4800 Msg:
Ticks: 00001242 Event: keyMove X: Y: Key: $4800 Msg:
Ticks: 00001260 Event: leftClick X: 160 Y: 100 Key: Msg:
Initial tests are very promising. The only thing of concern is to make sure that your game runs quickly enough to log & replay the events at the correct tick count. If your game is laggy (like 120 Below Zero), you'll need to change your DosBox speed settings to address this. Tick counts are the Achilles Heel of this entire project. Right now it does not perform a 'perfect replay', but it is quite close - within one or two ticks.
I'm pretty happy with the result, though I'm sure it needs additional testing & feedback. I learned a lot about event handling, especially with regard to the print and parser events.
Okay, here's a stab at how you need to modify your own game to support log/replay functionality. First, download the SCI Logging demo game and put the LogEvent.sc script into your game /src directory. Then modify the following files accordingly.
game.sh
// Add the following defines
(define LOGEVENT_SCRIPT 970)
// all the different possible log events
(define EVENT_LEFTCLICK 0)
(define EVENT_RIGHTCLICK 1)
(define EVENT_KEYMOVE 2)
(define EVENT_PARSEOPEN 3)
(define EVENT_CLOSEPRINT 4)
(define EVENT_OPENPRINT 5)
(define EVENT_GAMEKEY 6)
(define EVENT_GAMELEFTCLICK 7)
(define EVENT_GAMERIGHTCLICK 8)
(define EVENT_PARSECLOSE 9)
// the 3 log actions
(define NO_LOG 0)
(define SAVE_LOG 1)
(define REPLAY_LOG 2)
Controls.sc
// Include the LogEvent script near the top:
(use "logevent")
// Change your Dialog class doit() method to be this (changes highlighted):
(method (doit pItem)
(var hEvent, isClaimed, editControl)
= busy TRUE
= editControl FALSE
(self:eachElementDo(#init))
(if(theItem)
(send theItem:select(FALSE))
)
(if(paramTotal and pItem)
= theItem pItem
)(else
= theItem (self:firstTrue(#checkState TRUE))
)
(if(theItem)
(send theItem:select(TRUE))
)
= isClaimed FALSE
(while((not isClaimed))
(if (== gLogAction REPLAY_LOG)
// Queue up events until we get a parser close or close print event (should just be the next event in the log)
(if (<> gEventEvent EVENT_PARSECLOSE and <> gEventEvent EVENT_CLOSEPRINT)
= gEventClaimed TRUE
QueueEvent()
)
// wait until we should close this window
(if (>= GetTime() gEventTicks)
// it's been closed, get out of the loop
= isClaimed TRUE
break
)
)
(self:eachElementDo(#cycle))
= hEvent (Event:new())
GlobalToLocal(hEvent)
= isClaimed (self:handleEvent(hEvent))
(send hEvent:dispose())
(self:check)
(if( (== isClaimed -1) or (not busy) )
= isClaimed FALSE
= editControl TRUE
EditControl(theItem 0)
break
)
Wait(1)
)
= busy FALSE
// Log the close print event, as long as this is not an EditPrint window
(if (== gLogAction SAVE_LOG and == editControl TRUE)
LogEvent(hEvent "closePrint" )
)
return(isClaimed)
)
// Make the Dialog class dispose method look like this:
(method (dispose)
(if(== self gPrintDlg)
SetPort(gOldPort)
= gPrintDlg NULL
= gOldPort NULL
)
(if(window)
(send window:dispose())
)
= window NULL
= theItem NULL
(super:dispose())
// When the print window is destroyed, load up the next event
(if (== gLogAction REPLAY_LOG)
= gEventClaimed TRUE
QueueEvent()
)
)
// Add this code before the send to hDText in the Print() procedure
// Logs when either the parser window is opened or a print dialog is opened
(if (== gLogAction SAVE_LOG)
(= dummyEvent Event:new())
(if(== STRINGS_EQUAL StrCmp(@msgBuf "Enter Input:"))
LogEvent(dummyEvent "parseOpen" @msgBuf)
)(else
LogEvent(dummyEvent "openPrint" @msgBuf)
)
)
(send hDText:
text(@msgBuf)
moveTo(4 4)
font(gDefaultFont)
setSize()
)
// Further down in the Print() procedure, before the open call:
// Queue up the next event (which should be a CLOSEPRINT event)
(if (== gLogAction REPLAY_LOG and == gEventEvent EVENT_OPENPRINT)
= gEventClaimed TRUE
QueueEvent()
)
(send hDialog:open(moveToX moveToY))
User.sc
// Again, include the LogEvent script
(use "logevent")
// Change the getinput method to look like this:
(method (getInput pEvent)
(var prevSound, strLen)
(if(<> (send pEvent:type) evKEYBOARD)
= inputStr 0
)
// this allows for replaying the typed text into the input window
(if (== gEventEvent EVENT_PARSEOPEN and == gLogAction REPLAY_LOG)
= gEventClaimed TRUE
QueueEvent() // parser close
StrCpy(@inputStr @gEventMsg)
(send pEvent:message(@gEventMsg)) // set the input in input box (from parser close event)
)(else
(if(<> (send pEvent:message) echo)
Format(@inputStr "%c" (send pEvent:message))
)
)
= prevSound (Sound:pause(blocks))
= strLen EditPrint(@inputStr maxInputLen prompt #at x y)
(Sound:pause(prevSound))
return(strLen)
)
// And the handleEvent method:
(method (handleEvent pEvent)
(var evType, origKey)
(if(send pEvent:type)
= gUserEvent pEvent
= evType (send pEvent:type)
= origKey (send pEvent:message) // get the original key input, prior to it being manipulated in mapKeyToDir
(if(mapKeyToDir)
MapKeyToDir(pEvent)
)
(if(TheMenuBar)
(TheMenuBar:handleEvent(pEvent evType))
)
GlobalToLocal(pEvent)
(if(not (send pEvent:claimed))
(send gGame:handleEvent(pEvent evType))
)
(if(controls and (not (send pEvent:claimed))
and (send gCast:contains(alterEgo)))
(send alterEgo:handleEvent(pEvent))
)
// logs ego events (mouse clicks and keyboard movements
(if((send pEvent:claimed) and == gLogAction SAVE_LOG)
(send pEvent:message(origKey))
LogEvent(pEvent "ego")
)
(if(canInput and not(send pEvent:claimed))
(if( (== (send pEvent:message) echo) or (<= $20 (send pEvent:message)) and (<= (send pEvent:message) 255))
(if( (self:getInput(pEvent)))
// logs the closing of the parser
(if (== gLogAction SAVE_LOG)
LogEvent(pEvent "parseClose" @inputStr)
)
(if(Parse(@inputStr pEvent))
(send pEvent:type(evSAID))
(self:said(pEvent))
)
)
)
)
// for handling the titlescreen events
(if (== canInput FALSE and not(send pEvent:claimed) and == gLogAction SAVE_LOG)
LogEvent(pEvent "game")
)
)
= gUserEvent NULL
)
Main.sc
// Include logevent again:
(use "logevent")
// Add these local variables:
// Logging variables
gLogLineSize = 116
gLogAction = NO_LOG
gLogFileName[50]
gEventTicks
gEventEvent
gEventX
gEventY
gEventKey
gEventMsg[51]
gLogFileHandle
gEventClaimed = TRUE
// At the bottom of the init() method in the Game instance, add ONE of the following code blocks,
// depending whether you want to log events or replay a log file:
// for logging events
= gLogAction SAVE_LOG
Format(@gLogFileName "logs\\log%d" Abs(GetTime(gtTIME_OF_DAY)))
= gLogFileHandle FOpen(@gLogFileName fOPENFAIL)
// for replaying events
= gLogAction REPLAY_LOG
StrCpy(@gLogFileName "logs\\LOG19736") // change this to the log file of your choice
= gLogFileHandle FOpen(@gLogFileName fOPENCREATE)
= gEventEvent -1
= gEventTicks -1
// At the bottom of the doit() in your Game instance, add this:
// enables replaying of the log
(if (== gLogAction REPLAY_LOG)
ReplayLog()
)
