Autolog Confusion

[EmperorFool]

Hey team and anyone else interested in Autolog.

Does Autolog really work? Specifically, do the things it says you did on turn X show up after the header line for turn X?

I'm adding logging of Reminders and here's what I'm seeing:

[B]--> Load Game[/B]
Logging by BUG Mod 1.0 (BtS 3.13)
------------------------------------------------
[u][b]Turn 19/330 (2860 BC) [14-Oct-2007 15:13:08][/b][/u]
[B]--> Turn 19[/B]
[B]--> Create Reminder "Testing"[/B]
Reminder: On Turn 20, Testing
[B]--> Hit "End Turn" Button[/B]
Reminder: Testing

[b]IBT:[/b]

[u][b]Turn 20/330 (2800 BC) [14-Oct-2007 15:15:06][/b][/u]
[B]--> Turn 20[/B]
[B]--> Hit "Yes" (Show Reminder Next Turn)[/B]
[B]--> Hit "End Turn" Button[/B]
 Reminder: Testing
[color="Green"]Tech learned: The Wheel[/color]

[b]IBT:[/b]

[u][b]Turn 21/330 (2740 BC) [14-Oct-2007 15:16:50][/b][/u]
[B]--> Turn 21[/B]

Note that the timestamps show up after the reminders. The reason is that reminders trigger in onBeginPlayerTurn while the timestamps trigger in onEndGameTurn. The really weird part is that Civ4 fires events in this order:

1. Player's turn begins
2. Player's turn ends
3. Game turn ends

That's at the end of the events as your turn starts. It's odd. In any case, I'm kinda sick of it right now, so if anyone has any thoughts on making it better, I'm all ears.

The downside right now is that you see Reminders for this turn before the timestamp for this turn, just like you see Techs being discovered. With Techs, though, you really do discover them on your previous turn, after you hit Enter but before other players go.

Oh well, I'm over it for now.

</rant>

 

[Psyringe]

In the BUG options, on the "Logging" tab, there's on option determining whether the player's first turn is regarded as turn 0 or turn 1. It defaults to 0. If the Reminders treat the first turn as turn 1, then this might be the source of the problem?

 

[ruff_hi]

The date/time stamp is set at the end of the prior turn ... its a pain but Civ4's onBeginGameTurn (or similar) event has never been reliable. If you look at the turn counter being used, you will notice a '+1' (or '-1', cannot remember which).

 

[EmperorFool]

Sorry, I wasn't clear. It's not the turn # that is the problem. It's that because Reminders trigger in onBeginPlayerTurn, they are written to the log before the stuff that triggers in onEndGameTurn, which fires at the end of the beginning of the player's turn.

To clarify, this is what I'd expect, stating with loading a game.

1. ...player takes their turn...
2. Player discovers techs
   
3. Player's turn 1 ends
4. Turn 1 ends
5. Turn 2 begins
6. Player's turn 2 begins
7. ...player takes their turn...
8. Player's turn 2 ends
9. Turn 2 ends

Instead, this is what I'm seeing

1. ...player takes their turn...
2. Player discovers techs
3. Turn 2 begins
4. Player's turn 2 begins
5. Player's turn 2 ends
6. Turn 2 ends
   
7. ...player takes their turn...

I'll have to play around with it some more. Maybe I'll create an event logger to just write out which events happen when.

For now, reminders are logged at the wrong time. One way to fix it might be to log the reminders in onEndGameTurn so they appear after the timestamp.

 

[EmperorFool]

So I wrote an event trace logger, and it's stranger than I originally thought. Here is a new game. I stripped the multiple AI turns down to a single AI.

17:21:27:   0 (-4000): Start Game
17:21:30:   0 (-4000): PreSave Game
17:21:30:   0 (-4000): Save Game
[B]MY TURN[/B]
17:22:05:   0 (-4000): Begin Turn 0 for hawkeye (0)
17:22:05:   0 (-4000): End Turn   0 for hawkeye (0)
17:22:06:   0 (-4000): Begin Turn 0 for Gilgamesh (1)
17:22:06:   0 (-4000): End Turn   0 for Gilgamesh (1)
...
17:22:08:   0 (-4000): Begin Turn 0 for Barbarian (18)
17:22:08:   0 (-4000): End Turn   0 for Barbarian (18)
17:22:08:   0 (-4000): Begin Turn 0
17:22:08:   0 (-4000): End Turn   0
[B]MY TURN[/B]
17:22:19:   1 (-3975): Begin Turn 1 for hawkeye (0)
17:22:19:   1 (-3975): End Turn   1 for hawkeye (0)
17:22:19:   1 (-3975): Begin Turn 1 for Gilgamesh (1)
17:22:19:   1 (-3975): End Turn   1 for Gilgamesh (1)
...
17:22:19:   1 (-3975): Begin Turn 1 for Barbarian (18)
17:22:19:   1 (-3975): End Turn   1 for Barbarian (18)
17:22:19:   1 (-3975): Begin Turn 1
17:22:19:   1 (-3975): End Turn   1
[B]MY TURN[/B]

Notice that the game turn is begun and ended after all the player turns go. So clearly Player Turns are not part of a large encompassing Game Turn. Instead, the Game Turn is just like a Player Turn for the game, and it happens at the end of all Player Turns for each Turn #. I don't know what happens during the Game Turn, though.

To compare, here's a new game on the Earth map so I'm not the first player. Again, multiple AI turns are compressed.

17:26:16:   0 (-4000): Start Game
17:26:22:   0 (-4000): PreSave Game
17:26:22:   0 (-4000): Save Game
17:26:22:   0 (-4000): Begin Turn 0 for Hatshepsut (0)
17:26:22:   0 (-4000): End Turn   0 for Hatshepsut (0)
...
17:26:22:   0 (-4000): Begin Turn 0 for Alexander (3)
17:26:22:   0 (-4000): End Turn   0 for Alexander (3)
[B]MY TURN[/B]
17:27:16:   0 (-4000): Begin Turn 0 for hawkeye (4)
17:27:16:   0 (-4000): End Turn   0 for hawkeye (4)
17:27:16:   0 (-4000): Begin Turn 0 for Cyrus (5)
17:27:16:   0 (-4000): End Turn   0 for Cyrus (5)
...
17:27:16:   0 (-4000): Begin Turn 0 for Barbarian (18)
17:27:16:   0 (-4000): End Turn   0 for Barbarian (18)
17:27:16:   0 (-4000): Begin Turn 0
17:27:16:   0 (-4000): End Turn   0
17:27:16:   1 (-3960): Begin Turn 1 for Hatshepsut (0)
17:27:16:   1 (-3960): End Turn   1 for Hatshepsut (0)
...
17:27:16:   1 (-3960): Begin Turn 1 for Alexander (3)
17:27:16:   1 (-3960): End Turn   1 for Alexander (3)
[B]MY TURN[/B]

As you can see, your Player Turn consistently comes after your actual interactive moves. Thus, there's no event telling us that the player is about to make their moves.

Here's the code for the class if anyone wants to play around with it. Save it and then hook it into CvCustomEventManager just like all the other event managers.

Spoiler EventTraceManager.py :

## EventTraceManager
## Copyright 2007 BUG Mod Team
##
## author: EmperorFool
##
## Logs all game/turn-related events to a trace log for understanding events.

from CvPythonExtensions import *
import CvPath
import CvUtil
import os.path
import time

gc = CyGlobalContext()

class EventTraceManager:

    def __init__(self, eventManager):

        EventTrace(eventManager)

class EventTrace:

    def __init__(self, eventManager, *args, **kwargs):
        eventManager.addEventHandler("OnLoad", self.onLoadGame)
        eventManager.addEventHandler("OnSave", self.onSaveGame)
        eventManager.addEventHandler("OnPreSave", self.onPreSave)
        eventManager.addEventHandler("GameStart", self.onGameStart)
        eventManager.addEventHandler("GameEnd", self.onGameEnd)
        eventManager.addEventHandler("BeginGameTurn", self.onBeginGameTurn)
        eventManager.addEventHandler("EndGameTurn", self.onEndGameTurn)
        eventManager.addEventHandler("BeginPlayerTurn", self.onBeginPlayerTurn)
        eventManager.addEventHandler("EndPlayerTurn", self.onEndPlayerTurn)
        eventManager.addEventHandler("endTurnReady", self.onEndTurnReady)

        self.eventMgr = eventManager

    def logEvent(self, event):
        #CyInterface().addImmediateMessage(event, "")
        
        game = gc.getGame()
        turn = game.getElapsedGameTurns()
        year = game.getGameTurnYear()
        ts = time.strftime("%H:%M:%S")
        
        msg = "%s: %3d (%d): %s\n" % (ts, turn, year, event)
        
        log = open(os.path.join(CvPath.userDir, "EventTrace.log"), 'a')
        log.write(msg)
        log.close()
    
    def onLoadGame(self, argsList):
        self.logEvent("Load Game")

    def onPreSave(self, argsList):
        self.logEvent("PreSave Game")
    
    def onSaveGame(self, argsList):
        self.logEvent("Save Game")
        return ""

    
    def onGameStart(self, argsList):
        self.logEvent("Start Game")

    def onGameEnd(self, argsList):
        self.logEvent("End Game")


    def onBeginGameTurn(self, argsList):
        iGameTurn = argsList[0]
        self.logEvent("Begin Turn %d" % iGameTurn)

    def onEndGameTurn(self, argsList):
        iGameTurn = argsList[0]
        self.logEvent("End Turn   %d" % iGameTurn)


    def onBeginPlayerTurn(self, argsList):
        iGameTurn, iPlayer = argsList
        szPlayer = gc.getPlayer(iPlayer).getName()
        self.logEvent("Begin Turn %d for %s (%d)" % (iGameTurn, szPlayer, iPlayer))

    def onEndPlayerTurn(self, argsList):
        iGameTurn, iPlayer = argsList
        szPlayer = gc.getPlayer(iPlayer).getName()
        self.logEvent("End Turn   %d for %s (%d)" % (iGameTurn, szPlayer, iPlayer))

    def onEndTurnReady(self, argsList):
        iGameTurn = argsList[0]
        self.logEvent("End Turn Ready %d" % iGameTurn)

 

[ruff_hi]

what event were you thinking of using to log the reminder event? Or is that what you are looking for? Why not put the reminder check just after the part that posts the turn header (game end turn from memory but 1 turn ahead). You would obviously need to check for any reminders that will pop next turn.

 

[EmperorFool]

As it is now, the reminders are triggered in onBeginPlayerTurn. If I move it to onEndGameTurn it should work okay. I'm just trying to keep things separate so that ReminderEventManager does the logging of reminders. There's no need for it to be this way; it just makes more sense like that to me.

Okay, it works now.

 

[alerum68]

FINALLY! That little bit have made writing the turn logs up very confusing. Good job EF.

BTW - Your signature line still points to the original BUG thread.... how about an update?

 

[EmperorFool]

Thanks, I forgot about my sig. It's updated.

When you say it's been confusing, by "it" are you talking about the reminders in the autolog? Because I just added that! Or are you talking about something else. All I changed was where reminders get logged.

 

[alerum68]

I've had problems with the autologger since it was first released. It doesn't seem to log things in the proper order, but thought it was just me.