Login

Caledorn

This is interesting. I enabled the log system before I went to sleep yesterday, and while the log file is filled with odd messages about "Starting turn XXXX", where the turn number is now up in the four-thousands (no idea what that is about, but it's probably normal, aka second counter or something), this is what happens when someone joins when another player is already in the game (I've removed most of the lines about starting new turn etc in the log, since that is redundant to this information):

Player 1 connects, gets assigned NetID 1, picks his Civ, enters his password, and then is added to the game in "turn slice 3983" - the game then creates the autosave, and sends that to the player (in this happy instance, the player in question is pindicator):

Code:
[9531.453] DBG: Accepting a new player!

 Assumed public address = 184.76.89.124:2056

 Assumed private address = 192.168.15.247:2056

[9531.453] DBG: Adding active connection-level player info for NetID 1

[9531.453] DBG: Setting NetID 1 PUBLIC address to 184.76.89.124:2056

[9531.453] DBG: Setting NetID 1 PRIVATE address to 192.168.15.247:2056

[9531.453] DBG: Sending welcome to NetID 1, assigning RandID 54534074!

[9531.468] DBG: Adding NetID 1 to Portal!

[9531.656] DBG: SYNCLOG: All Checked In for Turn 3950

[9531.656] DBG: SYNCLOG: STARTING TURN 3951

[9531.718] DBG: SYNCLOG: Received EndTurn for Player -1 (NetID 0) - Checking in for Turn 3951

[9531.843] DBG: Got NetworkReady from NetID 1

[9531.843] DBG: Checking if we're connect complete!  PeersReady=yes :: AlreadyComplete=yes

[9534.687] DBG: Got Verify Version message from NetID 1!

[9534.687] DBG: Sending Pick-yer-civ message to NetID 1

[479538.875] DBG: Received CivChoice message from NetID 1

[9538.875] DBG: Civ 7 already claimed!  Prompting NetID 1 for password

[9540.718] DBG: Received CivChoice message from NetID 1

[9540.718] DBG: Allowing NetID 1 to select Civ with AppID 7

[9541.015] DBG: SYNCLOG: Got civ chosen message on normal turn 3980

[9541.015] DBG: SYNCLOG: Executing HotJoin notice on turn 3980

[9541.015] DBG: SYNCLOG: Hot turn set to 3983

[9541.015] DBG: SYNCLOG: Checking in NetID 1 for turn 3980

[9541.015] DBG: SYNCLOG: Checking in NetID 1 for turn 3981

[9541.015] DBG: SYNCLOG: Checking in NetID 1 for turn 3982

[9541.015] DBG: SYNCLOG: Will add Player 7 on turn slice 3983

[9541.015] DBG: SYNCLOG: All Checked In for Turn 3980

[9541.015] DBG: SYNCLOG: STARTING TURN 3981

[9541.031] DBG: SYNCLOG: Received EndTurn for Player -1 (NetID 0) - Checking in for Turn 3982

[9541.281] DBG: SYNCLOG: All Checked In for Turn 3981

[9541.281] DBG: SYNCLOG: STARTING TURN 3982

[9541.281] DBG: SYNCLOG: Received EndTurn for Player -1 (NetID 0) - Checking in for Turn 3983

[9541.531] DBG: SYNCLOG: All Checked In for Turn 3982

[9541.531] DBG: SYNCLOG: STARTING TURN 3983

[9541.562] DBG: SYNCLOG: Received EndTurn for Player -1 (NetID 0) - Checking in for Turn 3984

[9541.562] DBG: SYNCLOG: Civ Chosen Message Execute

[9541.562] DBG: Received CivChosen Claim on AppID 7 from NetID 1

[9541.562] DBG: Sending pitboss info to NetID 1

[9541.562] DBG: Sending game info to NetID 1

[9541.562] DBG: Sending player info about NetID 1 to everyone

[9541.562] DBG: Sending player info about civ at slot 0 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 1 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 2 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 3 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 4 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 5 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 6 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 8 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 9 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 10 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 11 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 12 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 13 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 14 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 15 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 16 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 17 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 18 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 19 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 20 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 21 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 22 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 23 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 24 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 25 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 26 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 27 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 28 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 29 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 30 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 31 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 32 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 33 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 34 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 35 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 36 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 37 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 38 to NetID 1

[9541.562] DBG: Sending player info about civ at slot 39 to NetID 1

[9542.109] DBG: Sending Interim Messages to NetID 1

[9542.125] DBG: Sending Information about SaveFile "D:\Pitboss\2058-RBPB18\Saves\pitboss\auto\Recovery_pindicator.CivBeyondSwordSave" to NetID 1

[9542.125] DBG: SYNCLOG: Executing hot join message (type=23, sender=0) on hot turn 3983

[9545.343] DBG: Received file ack from NetID 1

[9545.343] DBG: Transferring SaveFile "D:\Pitboss\2058-RBPB18\Saves\pitboss\auto\Recovery_pindicator.CivBeyondSwordSave" to NetID 1!

[9545.343] DBG: FILE TRANSFER TO NETID 1:

   Sending first 1024 of 1241464 bytes of file to be written to "C:\Users\Jon\Documents\My Games\Beyond the Sword\Saves\multi\auto\Recovery_pindicator.CivBeyondSwordSave"

Now, look what happens when another player is attempting to connect while pindicator is connected (note that pindicator has not received his full savegame file yet when the second player connects, so the completion of the file transfer happens while player 2 is trying to connect:

And that same player tries to connect one more time, after pindicator is actually in the game:

Code:
[9674.921] DBG: A computer at 24.21.120.77:2056 is attempting to connect to us

[9675.171] DBG: Accepting a new player!

 Assumed public address = 24.21.120.77:2056

 Assumed private address = 192.168.1.4:2056

[9675.171] DBG: Adding active connection-level player info for NetID 2

[9675.171] DBG: Setting NetID 2 PUBLIC address to 24.21.120.77:2056

[9675.171] DBG: Setting NetID 2 PRIVATE address to 192.168.1.4:2056

[9675.171] DBG: Sending welcome to NetID 2, assigning RandID 683279139!

[9675.187] DBG: Adding NetID 2 to Portal!

[9675.406] DBG: Got a NAT Cookie request for RandID 54534074 (NetID 1)

[9675.406] DBG: Instigating NAT Connection with Cookie 1511073903

[9675.406] DBG: Sending NAT Cookie Response to player ID 2: Cookie=1511073903

[9675.406] DBG: Sending NAT Cookie Command to player ID 1: Cookie=1511073903

****[9684.796] WRN: Our connection to NetID 2 was closed remotely****

****[9684.796] DBG: Removing connection-level player info for NetID 2 (state=2)****

[9684.812] DBG: SYNCLOG: Got remove player message on normal turn 4022

[9684.812] DBG: SYNCLOG: Sending HotDrop notice for turn 4024

[9684.812] DBG: SYNCLOG: Received EndTurn for Player 7 (NetID 1) - Checking in for Turn 4022

[9684.812] DBG: SYNCLOG: Executing HotDrop notice on turn 4022

[9684.812] DBG: SYNCLOG: Hot turn set to 4025

[9684.812] DBG: SYNCLOG: Checking in NetID 2 for turn 4022

[9684.812] DBG: SYNCLOG: Checking in NetID 2 for turn 4023

[9684.812] DBG: SYNCLOG: Checking in NetID 2 for turn 4024

****[9684.812] DBG: SYNCLOG: Will remove NetID 2 on turn slice 4025****

[9684.812] DBG: SYNCLOG: All Checked In for Turn 4022

[9684.812] DBG: SYNCLOG: STARTING TURN 4023

[9684.828] DBG: SYNCLOG: Received EndTurn for Player -1 (NetID 0) - Checking in for Turn 4024

[9685.078] DBG: SYNCLOG: All Checked In for Turn 4023

[9685.078] DBG: SYNCLOG: STARTING TURN 4024

[9685.078] DBG: SYNCLOG: Received EndTurn for Player -1 (NetID 0) - Checking in for Turn 4025

[9685.078] DBG: SYNCLOG: Received EndTurn for Player 7 (NetID 1) - Checking in for Turn 4023

[9685.328] DBG: SYNCLOG: All Checked In for Turn 4024

[9685.328] DBG: SYNCLOG: STARTING TURN 4025

[9685.343] DBG: SYNCLOG: Received EndTurn for Player -1 (NetID 0) - Checking in for Turn 4026

****[9685.343] DBG: SYNCLOG: Executing RemovePlayer NetID 2, TurnSlice 4025 - Sender 0!****

****[9685.343] DBG: Removing NetID 2 from Portal!****

[9685.343] DBG: Checking if we're connect complete!  PeersReady=yes :: AlreadyComplete=yes

The same thing happens both times. Pitboss creates a NAT cookie for each player, attempts to negotiate those cookies with NetID 1 and 2, and then eventually proceeds to give up and think the remote computer has dropped the connection (I put 4 asterisks on each side of those lines).

One interesting tidbit is that the connections happen on port 2056, and not 2058. This is because the civilization4.ini file contains a line that specifies what port to use, which I obviously have changed for each Pitboss. Now, that is something that hasn't changed - i.e. all players who were able to connect simultaneously earlier still did their connection on port 2056, so that is not the issue at hand. However, what makes it interesting is what happens with the game that I have hosted on port 2056, which I would like to figure out - do players who attempt to connect to that game run into bouncing off players who are connected to the Pitboss I am hosting on port 2058? Would removing the game on port 2056 (moving it to a different port that is) help solve the issue?

If anyone spots something interesting in those logs btw, do tell. That's why I shared them.

spacetyrantxenu · July 31st, 2014, 07:55

This game is massive, multiplayer, and online. Queues to log into MMOGs aren't unheard of. The next step is that this game goes free to play and gets totally ruined, right?

Caledorn · July 31st, 2014, 08:01

(July 31st, 2014, 07:55)spacetyrantxenu Wrote: This game is massive, multiplayer, and online. Queues to log into MMOGs aren't unheard of. The next step is that this game goes free to play and gets totally ruined, right?

Lol!

novice · July 31st, 2014, 08:13

(July 31st, 2014, 08:01)Caledorn Wrote:
(July 31st, 2014, 07:55)spacetyrantxenu Wrote: This game is massive, multiplayer, and online. Queues to log into MMOGs aren't unheard of. The next step is that this game goes free to play and gets totally ruined, right?

Lol!

or Dota.

spacetyrantxenu

Caledorn I missed your last post since we posted at the same time.

One question, when you enabled logging was it per pitboss instance or is it for all games? Because I'd be curious to see the logging for the game hosted on port 2056. Like you said, if there's any impact on that game from the frequent logins in pb18 maybe it would be helpful to move the larger game to the default port (2056) and see what that does? If there's a change in the logging information maybe that will give us something to go on. noidea

Caledorn · July 31st, 2014, 09:05

(July 31st, 2014, 08:54)spacetyrantxenu Wrote: Caledorn I missed your last post since we posted at the same time.

One question, when you enabled logging was it per pitboss instance or is it for all games? Because I'd be curious to see the logging for the game hosted on port 2056. Like you said, if there's any impact on that game from the frequent logins in pb18 maybe it would be helpful to move the larger game to the default port (2056) and see what that does? If there's a change in the logging information maybe that will give us something to go on.

Logging was enabled in this Pitboss only. The problem with the game on port 2056 is that it only receives logins one time per day or so, and the players who do connect to it spends a long time logged in because it's the CFC ISDG, which is in a perpetual state of end game war by now. The turn rate there is horrid as a result.

Moving PB18 to port 2056 is a possibility to test. I can do so later today.

Caledorn · July 31st, 2014, 09:16

I just had another thought too. To eliminate the server as the cause, I can also move the game to a different computer inside my LAN.

Again, I need at least two people who know they have been connected to the game simultaneously before that are available to test together with me before I test anything, preferably with Google Hangouts so we can keep in touch interactively.

Boldly Going Nowhere · July 31st, 2014, 09:17

(July 31st, 2014, 09:05)Caledorn Wrote:
(July 31st, 2014, 08:54)spacetyrantxenu Wrote: Caledorn I missed your last post since we posted at the same time.

One question, when you enabled logging was it per pitboss instance or is it for all games? Because I'd be curious to see the logging for the game hosted on port 2056. Like you said, if there's any impact on that game from the frequent logins in pb18 maybe it would be helpful to move the larger game to the default port (2056) and see what that does? If there's a change in the logging information maybe that will give us something to go on.

Logging was enabled in this Pitboss only. The problem with the game on port 2056 is that it only receives logins one time per day or so, and the players who do connect to it spends a long time logged in because it's the CFC ISDG, which is in a perpetual state of end game war by now. The turn rate there is horrid as a result.

Moving PB18 to port 2056 is a possibility to test. I can do so later today.

You should do everyone a favor and just kill the ISDG. That's probably the cause of our problem anyway. troll

spacetyrantxenu · July 31st, 2014, 09:21

Uh. It's far more likely we're causing problems with that game since there's so many people connecting to 18.

Anyway, I've been able to connect to most people in the past, I don't specifically remember who (if anyone) I couldn't connect to previously. I can try logging in at some point (working from home FTW) if you'll let me know when you need me to, Caledorn.

Advisory to any hypothetical war time adversaries: if you haven't played and I log in ahead of you, I'm NOT playing my turn out of order, just logging in to test connecting. No double moves intended or undertaken. bang

Boldly Going Nowhere · July 31st, 2014, 10:07

FYI, I'm hanging out in game (paused) while Xenu and Cal sort through some troubleshooting. When they decide I'm no longer helpful I'll unpause and log out. I'll post here when that happens.

Navigation

Extra Menu

About us