1v1 Ladder false scores

[SynThiicQ]

Hi

Arkansas and me (SynThiicQ) were playing a 1v1 Ladder Match. But our scores were false. I'll post the replay.
So we were both playing Aeon on Fields of Isis. It turned out to be a draw but I as still alive in the replay.

Some logs: from c:\ProgramData\FAForever\logs

Code: Select all

code: 0
2013-01-01 13:04:51,595 INFO     faf.fa               Checking FA for: ladder1v1 and map None
2013-01-01 13:04:51,596 INFO     faf.fa               Updating FA for mod: ladder1v1, version None
2013-01-01 13:04:52,203 INFO     faf.fa               Writing fa_path.lua config file.
2013-01-01 13:04:52,237 INFO     faf.games            Starting Ranked Search as /aeon, port: 6112
2013-01-01 13:04:52,239 INFO     faf.client           Outgoing JSON Message: {"state": "start", "mod": "ladder1v1", "command": "game_matchmaking", "faction": "/aeon", "gameport": 6112}
2013-01-01 13:04:52,411 INFO     faf.client           Handling game_launch via JSON {u'uid': 525379, u'args': [u'/players 2', u'/team 1'], u'mapname': u'scmp_015', u'reason': u'ranked', u'command': u'game_launch', u'mod': u'ladder1v1'}
2013-01-01 13:04:52,411 INFO     faf.fa               Updating FA for map: scmp_015
2013-01-01 13:04:52,411 INFO     faf.fa               Map is available.
2013-01-01 13:04:52,411 INFO     faf.fa               Running FA with info: {'recorder': u'SynThiicQ', 'game_time': 1357041892.412, 'uid': 525379, 'version_info': {'lobby': '0.7.591'}, 'featured_mod': u'ladder1v1'}
2013-01-01 13:04:52,411 INFO     faf.fa               Running FA via command: "C:\ProgramData\FAForever\bin\ForgedAlliance.exe" /players 2 /team 1 /aeon /mean 1674.11 /deviation 50.5166 /init init_ladder1v1.lua /savereplay gpgnet://localhost/525379/SynThiicQ.SCFAreplay /nobugreport /gpgnet 127.0.0.1:52199
2013-01-01 13:04:52,460 INFO     faf.client           FA has launched in an attached process.
2013-01-01 13:04:52,460 DEBUG    faf.games            Stopping Ranked Search
2013-01-01 13:04:52,460 INFO     faf.client           Outgoing JSON Message: {"state": "stop", "command": "game_matchmaking", "mod": "ladder1v1"}
2013-01-01 13:04:58,822 DEBUG    faf.fa.relayserver   incoming connection to relay server...
2013-01-01 13:04:58,823 INFO     faf.fa.relayer       FA connected locally.
2013-01-01 13:04:58,823 INFO     faf.fa.relayer       FA will use local port 50306
2013-01-01 13:04:58,823 INFO     faf.fa.relayer       UDP relay port 6112
2013-01-01 13:04:58,865 DEBUG    faf.fa.relayer       faf server faforever.com:7001
2013-01-01 13:05:13,880 INFO     faf.client           port used : 6112
2013-01-01 13:05:32,799 INFO     faf.fa               Game Info Complete: {u'num_players': 2, u'mapname': u'scmp_015', 'uid': 525379, 'version_info': {'lobby': '0.7.591'}, 'game_time': 1357041897.251026, u'game_type': 0, u'host': u'SynThiicQ', u'teams': {u'1': [u'SynThiicQ'], u'2': [u'Arkansas']}, u'access': u'public', u'state': u'playing', u'options': [], u'command': u'game_info', 'featured_mod': u'ladder1v1', u'title': u'SynThiicQ Vs Arkansas', 'recorder': u'SynThiicQ', u'quality': 0.6278882634248244, u'max_players': 12, 'complete': True}
2013-01-01 13:05:34,953 INFO     faf.fa.replayrecorder FA connected locally.
2013-01-01 13:05:34,989 DEBUG    faf.fa.replayrecorder internet replay server faforever.com:15000
2013-01-01 13:05:34,989 INFO     faf.fa.replayrecorder Stripping prefix 'P/525379/SynThiicQ.SCFAreplay ' from replay.
2013-01-01 13:12:59,039 INFO     faf.fa.replayrecorder FA disconnected locally.
2013-01-01 13:12:59,039 INFO     faf.fa.replayrecorder Found Complete Replay Info
2013-01-01 13:12:59,039 INFO     faf.fa.replayrecorder Writing local replay as C:\ProgramData\FAForever\replays\525379-SynThiicQ.fafreplay, containing 95345 bytes of replay data.
2013-01-01 13:12:59,042 INFO     faf.fa.replayrecorder closing replay file
2013-01-01 13:12:59,043 DEBUG    faf.fa.replayrecorder destructor entered
2013-01-01 13:12:59,043 INFO     faf.fa.relayer       FA disconnected locally.
2013-01-01 13:12:59,043 INFO     faf.fa.relayer       remove relay
2013-01-01 13:12:59,043 DEBUG    faf.fa.relayer       destructor called
2013-01-01 13:12:59,911 INFO     faf.client           FA has finished with exit code: 0


For full forever.log file: http://pastebin.com/qkCYjyRT

If you need more files / logs just ask i'll upload them.

Thanks in advance !

[Ze_PilOt]

Too old. The new logging feature was not in place yet.

Please repost them if it happens again (and it will).

[SynThiicQ]

ok I will

[vnucik]

I won 1v1 and it reads draw....it happened maybe second time (i dont care but now it could be good to appoint my first desperate victory so heres log )
"ProcessNatPacket", "chuncks": ["86.81.147.233:9103", "/ASKREPLY Houwitzer"]}
2013-01-02 19:54:00,796 INFO faf.fa.relayer reading socket from FA
2013-01-02 19:54:00,796 INFO faf.fa.relayer Command received from FA : {"action": "GameState", "chuncks": ["Launching"]}
2013-01-02 19:54:07,280 INFO faf.fa Game Info Complete: {u'num_players': 2, u'mapname': u'scmp_007', 'uid': 529201, 'version_info': {'lobby': '0.7.592'}, 'game_time': 1357152756.667904, u'game_type': 0, u'host': u'Houwitzer', u'teams': {u'1': [u'Houwitzer'], u'2': [u'Kukox']}, u'access': u'public', u'state': u'playing', u'options': [], u'command': u'game_info', 'featured_mod': u'ladder1v1', u'title': u'Houwitzer Vs Kukox', 'recorder': u'Kukox', u'quality': 0.6415698323170651, u'max_players': 12, 'complete': True}
2013-01-02 19:54:16,953 INFO faf.fa.replayrecorder FA connected locally.
2013-01-02 19:54:17,030 DEBUG faf.fa.replayrecorder internet replay server faforever.com:15000
2013-01-02 19:54:17,030 INFO faf.fa.replayrecorder Stripping prefix 'P/529201/Kukox.SCFAreplay ' from replay.
2013-01-02 20:22:15,015 INFO faf.fa.relayer reading socket from FA
2013-01-02 20:22:15,015 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [1, "score 0"]}
2013-01-02 20:22:15,015 INFO faf.fa.relayer reading socket from FA
2013-01-02 20:22:15,015 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [2, "score 1"]}
2013-01-02 20:22:19,733 INFO faf.fa.relayer reading socket from FA
2013-01-02 20:22:19,733 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [1, "defeat -1"]}
2013-01-02 20:22:19,905 INFO faf.fa.relayer reading socket from FA
2013-01-02 20:22:19,905 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [2, "score 1"]}
2013-01-02 20:22:22,546 INFO faf.fa.relayer reading socket from FA
2013-01-02 20:22:22,546 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [1, "defeat -1"]}
2013-01-02 20:22:22,562 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [2, "score 1"]}
2013-01-02 20:22:26,937 INFO faf.fa.relayer reading socket from FA
2013-01-02 20:22:26,937 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [2, "victory 6"]}
2013-01-02 20:22:27,000 INFO faf.fa.relayer reading socket from FA
2013-01-02 20:22:27,000 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [2, "score 6"]}
2013-01-02 20:23:11,375 INFO faf.fa.replayrecorder FA disconnected locally.
2013-01-02 20:23:11,375 INFO faf.fa.replayrecorder Waiting for replay transmission to finish: 3 bytes
2013-01-02 20:23:11,405 INFO faf.fa.replayrecorder Found Complete Replay Info
2013-01-02 20:23:11,405 INFO faf.fa.replayrecorder Writing local replay as C:\Documents and Settings\All Users\FAForever\replays\529201-Kukox.fafreplay, containing 371144 bytes of replay data.
2013-01-02 20:23:11,421 INFO faf.fa.replayrecorder closing replay file
2013-01-02 20:23:11,437 DEBUG faf.fa.replayrecorder destructor entered
2013-01-02 20:23:22,592 INFO faf.fa.relayer FA disconnected locally.
2013-01-02 20:23:22,592 INFO faf.fa.relayer remove relay
2013-01-02 20:23:22,592 DEBUG faf.fa.relayer destructor called
2013-01-02 20:23:24,250 INFO faf.client FA has finished with exit code: 0
2013-01-02 20:23:59,421 INFO faf.client Outgoing JSON Message: {"type": "ladder_maps", "command": "stats"}
2013-01-02 20:24:05,578 INFO faf.client Outgoing JSON Message: {"league": 2, "type": "league_table", "command": "stats"}
2013-01-02 20:24:06,155 INFO faf.client Outgoing JSON Message: {"league": 1, "type": "league_table", "command": "stats"}
2013-01-02 20:24:16,875 INFO faf.client Outgoing JSON Message: {"league": 2, "type": "league_table", "command": "
entire log: http://pastebin.com/N4Nv57a5

[vnucik]

sorry just deleted double post

[Ze_PilOt]

Thanks, that's really, really helpful.

[Ze_PilOt]

I'm currently outputting an insane amount of log for debugging this.

You really need to give me game ID as soon as possible.

[Patton]

i had this happen for the second time today. how do i find game ID?

2013-01-02 18:00:27,417 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:00:27,417 INFO faf.fa.relayer Command received from FA : {"action": "GameState", "chuncks": ["Launching"]}
2013-01-02 18:00:32,282 INFO faf.fa Game Info Complete: {u'num_players': 2, u'mapname': u'scmp_031', 'uid': 530662, 'version_info': {'lobby': '0.7.592'}, 'game_time': 1357178401.302911, u'game_type': 0, u'host': u'Patton_rocks', u'teams': {u'1': [u'Patton_rocks'], u'2': [u'YOYO']}, u'access': u'public', u'state': u'playing', u'options': [], u'command': u'game_info', 'featured_mod': u'ladder1v1', u'title': u'Patton_rocks Vs YOYO', 'recorder': u'Patton_rocks', u'quality': 0.9598104105085286, u'max_players': 12, 'complete': True}
2013-01-02 18:00:33,224 INFO faf.fa.replayrecorder FA connected locally.
2013-01-02 18:00:33,394 DEBUG faf.fa.replayrecorder internet replay server faforever.com:15000
2013-01-02 18:00:33,394 INFO faf.fa.replayrecorder Stripping prefix 'P/530662/Patton_rocks.SCFAreplay ' from replay.
2013-01-02 18:00:42,986 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:00:42,986 INFO faf.fa.relayer Command received from FA : {"action": "Bottleneck", "chuncks": ["readiness", "1", "15743", "5678.4"]}
2013-01-02 18:00:46,311 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:00:46,311 INFO faf.fa.relayer Command received from FA : {"action": "BottleneckCleared", "chuncks": []}
2013-01-02 18:24:00,507 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:00,507 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [1, "score 1"]}
2013-01-02 18:24:00,509 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:00,509 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [2, "score 0"]}
2013-01-02 18:24:00,509 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [3, "score 0"]}
2013-01-02 18:24:00,510 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:00,510 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [4, "score 0"]}
2013-01-02 18:24:03,642 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:03,642 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [2, "defeat -1"]}
2013-01-02 18:24:03,687 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:03,687 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [1, "score 1"]}
2013-01-02 18:24:03,688 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:03,688 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [3, "score 0"]}
2013-01-02 18:24:03,688 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [4, "score 0"]}
2013-01-02 18:24:05,792 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:05,793 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [2, "defeat -1"]}
2013-01-02 18:24:05,793 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [1, "score 1"]}
2013-01-02 18:24:05,793 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [3, "score 0"]}
2013-01-02 18:24:05,793 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [4, "score 0"]}
2013-01-02 18:24:09,990 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:09,990 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [1, "victory 6"]}
2013-01-02 18:24:10,012 INFO faf.fa.relayer reading socket from FA
2013-01-02 18:24:10,012 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [1, "score 6"]}
2013-01-02 18:24:10,013 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [3, "score 0"]}
2013-01-02 18:24:10,013 INFO faf.fa.relayer Command received from FA : {"action": "GameResult", "chuncks": [4, "score 0"]}
2013-01-02 18:24:12,562 INFO faf.fa.replayrecorder FA disconnected locally.
2013-01-02 18:24:12,562 INFO faf.fa.replayrecorder Waiting for replay transmission to finish: 3 bytes
2013-01-02 18:24:12,569 INFO faf.fa.replayrecorder Found Complete Replay Info
2013-01-02 18:24:12,569 INFO faf.fa.replayrecorder Writing local replay as C:\ProgramData\FAForever\replays\530662-Patton_rocks.fafreplay, containing 325949 bytes of replay data.
2013-01-02 18:24:12,582 INFO faf.fa.replayrecorder closing replay file
2013-01-02 18:24:12,584 DEBUG faf.fa.replayrecorder destructor entered
2013-01-02 18:24:39,213 INFO faf.fa.relayer FA disconnected locally.
2013-01-02 18:24:39,213 INFO faf.fa.relayer remove relay
2013-01-02 18:24:39,213 DEBUG faf.fa.relayer destructor called
2013-01-02 18:24:41,727 INFO faf.client FA has finished with exit code: 0

[rootbeer23]

i had this happen for the second time today. how do i find game ID?

hover over the replay in Replays/Local Archive with your mouse pointer.

[Ze_PilOt]

FA is sending the correct info to FAF.
FAF is probably sending them correctly to the server.

The server never got these.

Ie. in your game, you have a bottleneck issue ({"action": "BottleneckCleared", "chuncks": []})

I see it in the logs : Patton_rocks.530662.ladder1v1 action : {"action": "BottleneckCleared", "chuncks": []}

But after that, nothing, but no disconnection from your lobby either.

That action was emitted at 18:00:46,311 from you.
For the server, it was 03:00:20,046

The disconnection from you was at 18:24:39,213
The server recorded at 03:24:15,438

So all this is correct, it's just some datas missing in the middle for no apparent reason.

The most probably cause is that your router stop considering the socket to the server as valid because of a long period of inactivity, while not completely closing it.

It will implement a keepAlive function in the relay server to counter it.