Page 10 of 39

Re: Multiplayer slow game server

Posted: Thu Jun 13, 2019 9:07 am
by o01eg
The Silent One wrote: Thu Jun 13, 2019 8:57 am
o01eg wrote: Thu Jun 13, 2019 6:55 amCould you also try to enable trace log?
Here is the last couple of lines from the log (log itself is ~80mb):

Code: Select all

10:52:47.570459 [debug] client : TechTreeWnd.cpp:1427 : Tech Tree Layout Done
10:52:47.570459 [debug] client : TechTreeWnd.cpp:1899 : Tech List Box Populating
10:52:48.190018 [debug] client : TechTreeWnd.cpp:1914 : Tech List Box Populating Done,  Creation time = 619ms
10:52:48.190018 [debug] client : TechTreeWnd.cpp:1842 : Tech List Box Updating
10:52:48.209991 [debug] client : TechTreeWnd.cpp:1895 : Tech List Box Updating Done, Insertion time = 1 ms
10:52:48.209991 [debug] client : ResearchWnd.cpp:574 : ResearchWnd::UpdateQueue()
10:52:48.210989 [debug] client : DesignWnd.cpp:1110 : ShipDesignManager initializing.
10:52:48.337664 [debug] client : HumanClientApp.cpp:387 : HumanClientApp exited cleanly.
10:52:48.354606 [debug] client : Universe.cpp:161 : Reset id allocators with highest object id = -1 and highest design id = 370
10:52:48.354606 [error] client : chmain.cpp:316 : main() caught exception(std::exception): bad allocation
Did you create new designs for this game? It looks like you get exception in the design window.

Re: Multiplayer slow game server

Posted: Thu Jun 13, 2019 9:15 am
by The Silent One
Did you create new designs for this game? It looks like you get exception in the design window.
Definitely, no.

Re: Multiplayer slow game server

Posted: Thu Jun 13, 2019 7:53 pm
by o01eg
The Silent One wrote: Thu Jun 13, 2019 9:15 am
Did you create new designs for this game? It looks like you get exception in the design window.
Definitely, no.
Could you apply https://github.com/freeorion/freeorion/pull/2477 and https://github.com/freeorion/freeorion/pull/2478, enable trace log, and try to login again?

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 7:53 am
by Magnate
o01eg wrote: Thu Jun 13, 2019 6:18 am
Magnate wrote: Wed Jun 12, 2019 9:10 pm I've been using bbb72e1 since it came out with no problems, but tonight I have an error:

"Server cannot properly read messages from your client, most likely due to incompatible game versions."
I've got this error in log:

Code: Select all

snip
Same issue with UI data.
Interestingly, the turn processed fine despite the error. So although it crashed when I clicked submit orders, they were correctly submitted.

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 8:29 am
by The Silent One
o01eg wrote: Thu Jun 13, 2019 7:53 pmCould you apply https://github.com/freeorion/freeorion/pull/2477 and https://github.com/freeorion/freeorion/pull/2478, enable trace log, and try to login again?
Result is here:

Code: Select all

10:26:17.681200 {0x00004744} [debug] client : techtreewnd.cpp:1914 : Tech List Box Populating Done,  Creation time = 631ms
10:26:17.681200 {0x00004744} [debug] client : techtreewnd.cpp:1842 : Tech List Box Updating
10:26:17.705008 {0x00004744} [debug] client : techtreewnd.cpp:1895 : Tech List Box Updating Done, Insertion time = 2 ms
10:26:17.705008 {0x00004744} [debug] client : researchwnd.cpp:574 : ResearchWnd::UpdateQueue()
10:26:17.706000 {0x00004744} [debug] client : designwnd.cpp:1110 : ShipDesignManager initializing. New game false
10:26:17.792800 {0x00004744} [debug] client : humanclientapp.cpp:387 : HumanClientApp exited cleanly.
10:26:17.813632 {0x00004744} [debug] client : universe.cpp:161 : Reset id allocators with highest object id = -1 and highest design id = 370
10:26:17.813632 {0x00004744} [error] client : chmain.cpp:316 : main() caught exception(std::exception): bad allocation

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 8:52 am
by o01eg
The Silent One wrote: Fri Jun 14, 2019 8:29 am
o01eg wrote: Thu Jun 13, 2019 7:53 pmCould you apply https://github.com/freeorion/freeorion/pull/2477 and https://github.com/freeorion/freeorion/pull/2478, enable trace log, and try to login again?
Result is here:

Code: Select all

10:26:17.681200 {0x00004744} [debug] client : techtreewnd.cpp:1914 : Tech List Box Populating Done,  Creation time = 631ms
10:26:17.681200 {0x00004744} [debug] client : techtreewnd.cpp:1842 : Tech List Box Updating
10:26:17.705008 {0x00004744} [debug] client : techtreewnd.cpp:1895 : Tech List Box Updating Done, Insertion time = 2 ms
10:26:17.705008 {0x00004744} [debug] client : researchwnd.cpp:574 : ResearchWnd::UpdateQueue()
10:26:17.706000 {0x00004744} [debug] client : designwnd.cpp:1110 : ShipDesignManager initializing. New game false
10:26:17.792800 {0x00004744} [debug] client : humanclientapp.cpp:387 : HumanClientApp exited cleanly.
10:26:17.813632 {0x00004744} [debug] client : universe.cpp:161 : Reset id allocators with highest object id = -1 and highest design id = 370
10:26:17.813632 {0x00004744} [error] client : chmain.cpp:316 : main() caught exception(std::exception): bad allocation
Could you enable trace as shown in a picture https://freeorion.org/forum/viewtopic.p ... 135#p96135 and set FSM to trace as well, re-launch freeorion and provide here some more last lines from log?

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 9:28 am
by The Silent One

Code: Select all

11:27:35.000200 {0x00000870} [trace] client : message.cpp:872 : ExtractGameStartMessage orders deserialization time 34
11:27:35.343455 {0x00000870} [trace] client : message.cpp:876 : ExtractGameStartMessage UI data true deserialization time 377
11:27:35.343455 {0x00000870} [trace] client : message.cpp:880 : ExtractGameStartMessage save state false deserialization time 377
11:27:35.343455 {0x00000870} [trace] client : message.cpp:886 : ExtractGameStartMessage galaxy setup data deserialization time 377
11:27:35.343455 {0x00000870} [debug] FSM : humanclientfsm.cpp:854 : Extracted GameStart message for turn: 24 with empire: 4
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:145 : Setting Rules from Strings:
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_ALLOW_CONCEDE : 1
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_BUILDING_COST_FACTOR : 0.5
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_CHEAP_AND_FAST_BUILDING_PRODUCTION : 0
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_CHEAP_AND_FAST_SHIP_PRODUCTION : 0
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_CHEAP_AND_FAST_TECH_RESEARCH : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_CONCEDE_COLONIES_THRESHOLD : 9999
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_ENABLE_EXPERIMENTORS : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_ENABLE_SUPER_TESTER : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_ASTEROIDS : 3
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_GASGIANT : 6
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_HUGE : 5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_LARGE : 4
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_MEDIUM : 3
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_SMALL : 2
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_TINY : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_NUM_COMBAT_ROUNDS : 3
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_ONLY_ALLIANCE_WIN : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_PRODUCTION_QUEUE_FRONTLOAD_FACTOR : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_PRODUCTION_QUEUE_TOPPING_UP_FACTOR : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_RESEED_PRNG_SERVER : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_HULL_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_PART_BASED_UPKEEP : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_PART_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_SPEED_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_STRUCTURE_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHOW_DETAILED_EMPIRES_DATA : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_STARLANES_EVERYWHERE : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_STOCKPILE_IMPORT_LIMITED : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_TECH_COST_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_TEST_STRING : PLAYER
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_THRESHOLD_HUMAN_PLAYER_WIN : 2
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:165 : After Setting Rules:
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_STARLANES_EVERYWHERE : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_RESEED_PRNG_SERVER : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_ENABLE_EXPERIMENTORS : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_STOCKPILE_IMPORT_LIMITED : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_CHEAP_AND_FAST_SHIP_PRODUCTION : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_PRODUCTION_QUEUE_FRONTLOAD_FACTOR : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_PRODUCTION_QUEUE_TOPPING_UP_FACTOR : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_SPEED_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_CONCEDE_COLONIES_THRESHOLD : 9999
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_STRUCTURE_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_CHEAP_AND_FAST_BUILDING_PRODUCTION : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_CHEAP_AND_FAST_TECH_RESEARCH : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_NUM_COMBAT_ROUNDS : 3
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_BUILDING_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_TECH_COST_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_HULL_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_THRESHOLD_HUMAN_PLAYER_WIN : 2
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_TEST_STRING : PLAYER
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_PART_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_ENABLE_SUPER_TESTER : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_ONLY_ALLIANCE_WIN : 1
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_PART_BASED_UPKEEP : 1
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_TINY : 1
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_SMALL : 2
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_MEDIUM : 3
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_LARGE : 4
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_HUGE : 5
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_ASTEROIDS : 3
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_GASGIANT : 6
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_ALLOW_CONCEDE : 1
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHOW_DETAILED_EMPIRES_DATA : 0
11:27:35.344943 {0x00000870} [trace] client : cuicontrols.cpp:1918 : SetStockpileCost:  update values
11:27:35.344943 {0x00000870} [trace] client : cuicontrols.cpp:1925 : SetStockpileCost:  set name
11:27:35.344943 {0x00000870} [trace] client : cuicontrols.cpp:1932 : SetStockpileCost:  done.
11:27:35.344943 {0x00000870} [debug] client : productionwnd.cpp:1057 : ProductionWnd::UpdateQueue()
11:27:35.357841 {0x00000870} [debug] client : techtreewnd.cpp:1362 : Tech Tree Layout Preparing Tech Data
11:27:35.508136 {0x00000870} [debug] client : techtreewnd.cpp:1385 : Tech Tree Layout Doing Graph Layout
11:27:35.508136 {0x00000870} [debug] client : techtreelayout.cpp:208 : TechTreeLayout::DoLayout creating placeholder nodes...
11:27:35.508136 {0x00000870} [debug] client : techtreewnd.cpp:1392 : Tech Tree Layout Creating Panels
11:27:35.508593 {0x00000870} [debug] client : techtreewnd.cpp:1427 : Tech Tree Layout Done
11:27:35.508593 {0x00000870} [debug] client : techtreewnd.cpp:1899 : Tech List Box Populating
11:27:35.978801 {0x00000870} [debug] client : techtreewnd.cpp:1914 : Tech List Box Populating Done,  Creation time = 470ms
11:27:35.978801 {0x00000870} [debug] client : techtreewnd.cpp:1842 : Tech List Box Updating
11:27:36.002634 {0x00000870} [debug] client : techtreewnd.cpp:1895 : Tech List Box Updating Done, Insertion time = 0 ms
11:27:36.002634 {0x00000870} [debug] client : researchwnd.cpp:574 : ResearchWnd::UpdateQueue()
11:27:36.003601 {0x00000870} [debug] client : designwnd.cpp:1110 : ShipDesignManager initializing. New game false
11:27:36.003601 {0x00000870} [trace] FSM : humanclientfsm.cpp:865 : Restoring UI data from save data...
11:27:36.084448 {0x00000870} [trace] FSM : humanclientfsm.cpp:830 : (HumanClientFSM) ~WaitingForGameStart
11:27:36.084448 {0x00000870} [trace] FSM : humanclientfsm.cpp:621 : (HumanClientFSM) ~PlayingGame
11:27:36.084448 {0x00000870} [debug] client : humanclientapp.cpp:387 : HumanClientApp exited cleanly.
11:27:36.102800 {0x00000870} [debug] client : universe.cpp:161 : Reset id allocators with highest object id = -1 and highest design id = 370
11:27:36.102800 {0x00000870} [error] client : chmain.cpp:316 : main() caught exception(std::exception): bad allocation

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 9:37 am
by o01eg
The Silent One wrote: Fri Jun 14, 2019 9:28 am

Code: Select all

11:27:35.000200 {0x00000870} [trace] client : message.cpp:872 : ExtractGameStartMessage orders deserialization time 34
11:27:35.343455 {0x00000870} [trace] client : message.cpp:876 : ExtractGameStartMessage UI data true deserialization time 377
11:27:35.343455 {0x00000870} [trace] client : message.cpp:880 : ExtractGameStartMessage save state false deserialization time 377
11:27:35.343455 {0x00000870} [trace] client : message.cpp:886 : ExtractGameStartMessage galaxy setup data deserialization time 377
11:27:35.343455 {0x00000870} [debug] FSM : humanclientfsm.cpp:854 : Extracted GameStart message for turn: 24 with empire: 4
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:145 : Setting Rules from Strings:
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_ALLOW_CONCEDE : 1
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_BUILDING_COST_FACTOR : 0.5
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_CHEAP_AND_FAST_BUILDING_PRODUCTION : 0
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_CHEAP_AND_FAST_SHIP_PRODUCTION : 0
11:27:35.343455 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_CHEAP_AND_FAST_TECH_RESEARCH : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_CONCEDE_COLONIES_THRESHOLD : 9999
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_ENABLE_EXPERIMENTORS : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_ENABLE_SUPER_TESTER : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_ASTEROIDS : 3
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_GASGIANT : 6
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_HUGE : 5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_LARGE : 4
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_MEDIUM : 3
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_SMALL : 2
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_HABITABLE_SIZE_TINY : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_NUM_COMBAT_ROUNDS : 3
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_ONLY_ALLIANCE_WIN : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_PRODUCTION_QUEUE_FRONTLOAD_FACTOR : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_PRODUCTION_QUEUE_TOPPING_UP_FACTOR : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_RESEED_PRNG_SERVER : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_HULL_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_PART_BASED_UPKEEP : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_PART_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_SPEED_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHIP_STRUCTURE_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_SHOW_DETAILED_EMPIRES_DATA : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_STARLANES_EVERYWHERE : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_STOCKPILE_IMPORT_LIMITED : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_TECH_COST_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_TEST_STRING : PLAYER
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:147 :   RULE_THRESHOLD_HUMAN_PLAYER_WIN : 2
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:165 : After Setting Rules:
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_STARLANES_EVERYWHERE : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_RESEED_PRNG_SERVER : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_ENABLE_EXPERIMENTORS : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_STOCKPILE_IMPORT_LIMITED : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_CHEAP_AND_FAST_SHIP_PRODUCTION : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_PRODUCTION_QUEUE_FRONTLOAD_FACTOR : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_PRODUCTION_QUEUE_TOPPING_UP_FACTOR : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_SPEED_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_CONCEDE_COLONIES_THRESHOLD : 9999
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_STRUCTURE_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_CHEAP_AND_FAST_BUILDING_PRODUCTION : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_CHEAP_AND_FAST_TECH_RESEARCH : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_NUM_COMBAT_ROUNDS : 3
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_BUILDING_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_TECH_COST_FACTOR : 1
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_HULL_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_THRESHOLD_HUMAN_PLAYER_WIN : 2
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_TEST_STRING : PLAYER
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_PART_COST_FACTOR : 0.5
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_ENABLE_SUPER_TESTER : 0
11:27:35.343956 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_ONLY_ALLIANCE_WIN : 1
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHIP_PART_BASED_UPKEEP : 1
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_TINY : 1
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_SMALL : 2
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_MEDIUM : 3
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_LARGE : 4
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_HUGE : 5
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_ASTEROIDS : 3
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_HABITABLE_SIZE_GASGIANT : 6
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_ALLOW_CONCEDE : 1
11:27:35.344446 {0x00000870} [debug] client : gamerules.cpp:167 :   RULE_SHOW_DETAILED_EMPIRES_DATA : 0
11:27:35.344943 {0x00000870} [trace] client : cuicontrols.cpp:1918 : SetStockpileCost:  update values
11:27:35.344943 {0x00000870} [trace] client : cuicontrols.cpp:1925 : SetStockpileCost:  set name
11:27:35.344943 {0x00000870} [trace] client : cuicontrols.cpp:1932 : SetStockpileCost:  done.
11:27:35.344943 {0x00000870} [debug] client : productionwnd.cpp:1057 : ProductionWnd::UpdateQueue()
11:27:35.357841 {0x00000870} [debug] client : techtreewnd.cpp:1362 : Tech Tree Layout Preparing Tech Data
11:27:35.508136 {0x00000870} [debug] client : techtreewnd.cpp:1385 : Tech Tree Layout Doing Graph Layout
11:27:35.508136 {0x00000870} [debug] client : techtreelayout.cpp:208 : TechTreeLayout::DoLayout creating placeholder nodes...
11:27:35.508136 {0x00000870} [debug] client : techtreewnd.cpp:1392 : Tech Tree Layout Creating Panels
11:27:35.508593 {0x00000870} [debug] client : techtreewnd.cpp:1427 : Tech Tree Layout Done
11:27:35.508593 {0x00000870} [debug] client : techtreewnd.cpp:1899 : Tech List Box Populating
11:27:35.978801 {0x00000870} [debug] client : techtreewnd.cpp:1914 : Tech List Box Populating Done,  Creation time = 470ms
11:27:35.978801 {0x00000870} [debug] client : techtreewnd.cpp:1842 : Tech List Box Updating
11:27:36.002634 {0x00000870} [debug] client : techtreewnd.cpp:1895 : Tech List Box Updating Done, Insertion time = 0 ms
11:27:36.002634 {0x00000870} [debug] client : researchwnd.cpp:574 : ResearchWnd::UpdateQueue()
11:27:36.003601 {0x00000870} [debug] client : designwnd.cpp:1110 : ShipDesignManager initializing. New game false
11:27:36.003601 {0x00000870} [trace] FSM : humanclientfsm.cpp:865 : Restoring UI data from save data...
11:27:36.084448 {0x00000870} [trace] FSM : humanclientfsm.cpp:830 : (HumanClientFSM) ~WaitingForGameStart
11:27:36.084448 {0x00000870} [trace] FSM : humanclientfsm.cpp:621 : (HumanClientFSM) ~PlayingGame
11:27:36.084448 {0x00000870} [debug] client : humanclientapp.cpp:387 : HumanClientApp exited cleanly.
11:27:36.102800 {0x00000870} [debug] client : universe.cpp:161 : Reset id allocators with highest object id = -1 and highest design id = 370
11:27:36.102800 {0x00000870} [error] client : chmain.cpp:316 : main() caught exception(std::exception): bad allocation
There is 100% UI data issue too.

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 11:18 am
by Morlic
Win10, compiled from latest master.
Tried to log in a few times using Magnate as player name. First try, FreeOrion crashed with

Code: Select all

13:04:53.632383 {0x00003160} [error] client : chmain.cpp:316 : main() caught exception(std::exception): bad allocation

Tried to reconnect with log level set to Trace but actually managed to get into the game without issues.

Restarted FreeOrion again and tried to log in once more. From now on I'm getting a black screen after trying to connect: The FSM is stuck at WaitingForMPJoinAck.

Code: Select all

13:09:24.319316 {0x00002f60} [debug] log : loggerwithoptionsdb.cpp:105 : Configure log source "network" from optionsDB using threshold trace
13:09:24.319316 {0x00002f60} [debug] network : clientnetworking.cpp:349 : Attempt to connect to server at one of these addresses:
13:09:24.377338 {0x00002f60} [debug] network : clientnetworking.cpp:351 :   tcp::resolver::iterator host_name: freeorion-lt.dedyn.io  address: 147.135.99.147  port: 12346
13:09:24.539789 {0x00002f60} [trace] network : clientnetworking.cpp:496 : ClientNetworking::HandleConnection : connected
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:375 : Connected to server at host_name: freeorion-lt.dedyn.io  address: 147.135.99.147  port: 12346
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:399 : Connecting to server took 221 ms.
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:402 : ConnectToServer() : starting networking thread
13:09:24.540790 {0x00002f60} [trace] network : clientnetworking.cpp:476 : ClientNetworking::SendMessage() : sending message Message: JOIN_GAME "<?xml version="1.0" encoding="UTF-8" standalone="yes" ?>
<!DOCTYPE boost_serialization>
<boost_serialization signature="serialization::archive" version="16">
<player_name>Magnate</player_name>
<client_type>1</client_type>
<client_version_string>v0.4.8+ EnhanceLogMessage [build 2019-06-14.e0b80ce] MSVC 2017</client_version_string>
<cookie>82fa66b9-d586-4dc6-8c2c-ab76572c87ec</cookie>
</boost_serialization>

"

13:09:24.540790 {0x00002f60} [trace] FSM : humanclientfsm.cpp:149 : (HumanClientFSM) IntroMenu.JoinMPGameRequested
13:09:24.540790 {0x00002f60} [trace] FSM : humanclientfsm.cpp:133 : (HumanClientFSM) ~IntroMenu
13:09:24.540790 {0x00002f60} [trace] FSM : humanclientfsm.cpp:332 : (HumanClientFSM) WaitingForMPJoinAck

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 11:30 am
by Oberlus
Does this happen when both server and client use boost 1.65.1 from the start of the game?
It might be a bug in libboost 1.65.1+, see this.

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 11:31 am
by o01eg
Morlic wrote: Fri Jun 14, 2019 11:18 am Win10, compiled from latest master.
Tried to log in a few times using Magnate as player name. First try, FreeOrion crashed with

Code: Select all

13:04:53.632383 {0x00003160} [error] client : chmain.cpp:316 : main() caught exception(std::exception): bad allocation

Tried to reconnect with log level set to Trace but actually managed to get into the game without issues.

Restarted FreeOrion again and tried to log in once more. From now on I'm getting a black screen after trying to connect: The FSM is stuck at WaitingForMPJoinAck.

Code: Select all

13:09:24.319316 {0x00002f60} [debug] log : loggerwithoptionsdb.cpp:105 : Configure log source "network" from optionsDB using threshold trace
13:09:24.319316 {0x00002f60} [debug] network : clientnetworking.cpp:349 : Attempt to connect to server at one of these addresses:
13:09:24.377338 {0x00002f60} [debug] network : clientnetworking.cpp:351 :   tcp::resolver::iterator host_name: freeorion-lt.dedyn.io  address: 147.135.99.147  port: 12346
13:09:24.539789 {0x00002f60} [trace] network : clientnetworking.cpp:496 : ClientNetworking::HandleConnection : connected
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:375 : Connected to server at host_name: freeorion-lt.dedyn.io  address: 147.135.99.147  port: 12346
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:399 : Connecting to server took 221 ms.
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:402 : ConnectToServer() : starting networking thread
13:09:24.540790 {0x00002f60} [trace] network : clientnetworking.cpp:476 : ClientNetworking::SendMessage() : sending message Message: JOIN_GAME "<?xml version="1.0" encoding="UTF-8" standalone="yes" ?>
<!DOCTYPE boost_serialization>
<boost_serialization signature="serialization::archive" version="16">
<player_name>Magnate</player_name>
<client_type>1</client_type>
<client_version_string>v0.4.8+ EnhanceLogMessage [build 2019-06-14.e0b80ce] MSVC 2017</client_version_string>
<cookie>82fa66b9-d586-4dc6-8c2c-ab76572c87ec</cookie>
</boost_serialization>

"

13:09:24.540790 {0x00002f60} [trace] FSM : humanclientfsm.cpp:149 : (HumanClientFSM) IntroMenu.JoinMPGameRequested
13:09:24.540790 {0x00002f60} [trace] FSM : humanclientfsm.cpp:133 : (HumanClientFSM) ~IntroMenu
13:09:24.540790 {0x00002f60} [trace] FSM : humanclientfsm.cpp:332 : (HumanClientFSM) WaitingForMPJoinAck
I don't see strange things the server log:

Code: Select all

2019-06-14 11:06:18.058856 [debug] FSM : ServerFSM.cpp:2740 : (ServerFSM) PlayingGame::JoinGame message received
2019-06-14 11:06:18.058867 [debug] server : Message.cpp:896 : ExtractJoinGameMessageData() from  client type 32767
2019-06-14 11:06:18.058937 [debug] server : ServerFSM.cpp:2754 : PlayingGame.JoinGame Try to login player Magnate with cookie: 82fa66b9-d586-4dc6-8c2c-ab76572c87ec
2019-06-14 11:06:18.058974 [debug] server : ServerFSM.cpp:518 : ServerFSM.EstablishPlayer Assign new player id 1
2019-06-14 11:06:18.058983 [trace] network : ServerNetworking.cpp:157 : PlayerConnection(@ 0x55c9f44782d0)::EstablishPlayer(1, Magnate, 1, )
2019-06-14 11:06:18.058990 [debug] server : ServerFSM.cpp:530 : ServerFSM.EstablishPlayer player Magnate get cookie: 82fa66b9-d586-4dc6-8c2c-ab76572c87ec
2019-06-14 11:06:18.070831 [debug] server : Building.cpp:407 : BuildingTypeManager checksum: 4916521
2019-06-14 11:06:18.071013 [debug] server : Field.cpp:226 : FieldTypeManager checksum: 7794237
2019-06-14 11:06:18.071128 [debug] server : Field.cpp:226 : FieldTypeManager checksum: 2061208
2019-06-14 11:06:18.071231 [debug] server : Field.cpp:226 : FieldTypeManager checksum: 8041779
2019-06-14 11:06:18.071633 [debug] server : Field.cpp:226 : FieldTypeManager checksum: 2424510
2019-06-14 11:06:18.072031 [debug] server : Field.cpp:226 : FieldTypeManager checksum: 2416347
2019-06-14 11:06:18.072082 [debug] server : Field.cpp:226 : FieldTypeManager checksum: 6092622
2019-06-14 11:06:18.084369 [debug] server : ShipDesign.cpp:776 : HullTypeManager checksum: 8001017
2019-06-14 11:06:18.090553 [debug] server : ShipDesign.cpp:265 : PartTypeManager checksum: 8722648
2019-06-14 11:06:18.091397 [debug] server : ShipDesign.cpp:1550 : PredefinedShipDesignManager checksum: 877965
2019-06-14 11:06:18.148868 [debug] server : Species.cpp:632 : SpeciesManager checksum: 1510427
2019-06-14 11:06:18.153837 [debug] server : Tech.cpp:716 : TechManager checksum: 2634808
2019-06-14 11:06:18.154072 [debug] python : <string>:3 : Python current directory set to /usr/share/games/freeorion/default/python/chat
2019-06-14 11:06:18.154185 [info] python : chat.py:75 : Chat : [[PLAYER_ENTERED_GAME,Magnate]] <freeorion.GGColor object at 0x7f81ec121440>
2019-06-14 11:06:18.491721 [debug] FSM : ServerFSM.cpp:2701 : (ServerFSM) PlayingGame.EstablishPlayer at 17WaitingForTurnEnd]
2019-06-14 11:06:18.491827 [debug] server : ServerApp.cpp:1572 : ServerApp::GetPlayerInfoMap: Compiling PlayerInfo for each player
2019-06-14 11:06:18.499989 [debug] server : SerializeUniverse.cpp:65 : Universe::serialize : Getting gamestate data
2019-06-14 11:06:18.500244 [debug] server : Universe.cpp:3045 : GetEmpireKnownObjectsToSerialize
2019-06-14 11:06:18.500498 [debug] server : SerializeUniverse.cpp:84 : Universe::serialize : serializing universe width: 566.827
2019-06-14 11:06:18.503250 [debug] server : SerializeUniverse.cpp:89 : Universe::serialize : serializing 78 ship designs
2019-06-14 11:06:18.504963 [debug] server : SerializeUniverse.cpp:98 : Universe::serialize : serializing empire object visibility for 1, 1, 1, 1 empires
2019-06-14 11:06:18.517205 [debug] server : SerializeUniverse.cpp:113 : Universe::serialize : serializing 101 objects
2019-06-14 11:06:18.517273 [debug] server : SerializeUniverse.cpp:119 : Universe::serialize : serializing 30 destroyed object ids
2019-06-14 11:06:18.517296 [debug] server : SerializeUniverse.cpp:126 : Universe::serialize : serializing empire known objects for 0 empires
2019-06-14 11:06:18.517308 [debug] server : SerializeUniverse.cpp:132 : Universe::serialize : serializing id allocator version = 1
2019-06-14 11:06:18.517320 [debug] IDallocator : IDAllocator.cpp:288 : Serialize IDAllocator()  server id = -1 empire id = 1
2019-06-14 11:06:18.517370 [debug] IDallocator : IDAllocator.cpp:346 : Serialized [empire = 1 next id = 2295, ]
2019-06-14 11:06:18.517386 [debug] IDallocator : IDAllocator.cpp:288 : Serialize IDAllocator()  server id = -1 empire id = 1
2019-06-14 11:06:18.517423 [debug] IDallocator : IDAllocator.cpp:346 : Serialized [empire = 1 next id = 2296, ]
2019-06-14 11:06:18.517464 [debug] server : SerializeUniverse.cpp:164 : Universe::serialize : serializing done
2019-06-14 11:06:18.517476 [debug] server : SerializeUniverse.cpp:167 : Universe::serialize : Cleaning up temporary data
2019-06-14 11:06:18.517495 [debug] server : SerializeUniverse.cpp:184 : Universe::serialize done
2019-06-14 11:06:26.518906 [trace] network : ServerNetworking.cpp:301 : Server received message from player id: 1 of type Request combat logs and size 406
2019-06-14 11:06:26.518983 [debug] FSM : ServerFSM.cpp:2664 : (ServerFSM) PlayingGame::RequestCombatLogs message received
2019-06-14 11:06:26.519141 [debug] server : ServerApp.cpp:973 : UpdateCombatLogs returning 10 logs to player 1
2019-06-14 11:08:01.687085 [trace] network : ServerNetworking.cpp:737 : ServerNetworking::DisconnectImpl : disconnecting player 1
2019-06-14 11:08:01.687164 [debug] FSM : ServerFSM.cpp:305 : ServerFSM::HandleNonLobbyDisconnection : Lost connection to player #1, named "Magnate".
2019-06-14 11:08:01.687176 [warn] FSM : ServerFSM.cpp:322 : Player #1, named "Magnate"quit before empire was eliminated.
2019-06-14 11:08:01.687387 [debug] python : <string>:3 : Python current directory set to /usr/share/games/freeorion/default/python/chat
2019-06-14 11:08:01.687508 [info] python : chat.py:75 : Chat : [[PLAYER_LEFT_GAME,Magnate]] <freeorion.GGColor object at 0x7f81ec121440>
2019-06-14 11:25:21.887438 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player
2019-06-14 11:25:21.887583 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player
2019-06-14 11:25:21.887658 [trace] network : ServerNetworking.cpp:301 : Server received message from player id: -1 of type Join Game and size 410

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 12:15 pm
by Morlic
o01eg wrote: Fri Jun 14, 2019 11:31 am I don't see strange things the server log:
Is it expected that there is no notification when a client establishes connection to the server?
Because there is no indication my client actually connected to the server at xx:09:24 whereas my logs indicate otherwise:

Code: Select all

13:09:24.539789 {0x00002f60} [trace] network : clientnetworking.cpp:496 : ClientNetworking::HandleConnection : connected
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:375 : Connected to server at host_name: freeorion-lt.dedyn.io  address: 147.135.99.147  port: 12346
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:399 : Connecting to server took 221 ms.

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 12:32 pm
by o01eg
Morlic wrote: Fri Jun 14, 2019 12:15 pm
o01eg wrote: Fri Jun 14, 2019 11:31 am I don't see strange things the server log:
Is it expected that there is no notification when a client establishes connection to the server?
Because there is no indication my client actually connected to the server at xx:09:24 whereas my logs indicate otherwise:

Code: Select all

13:09:24.539789 {0x00002f60} [trace] network : clientnetworking.cpp:496 : ClientNetworking::HandleConnection : connected
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:375 : Connected to server at host_name: freeorion-lt.dedyn.io  address: 147.135.99.147  port: 12346
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:399 : Connecting to server took 221 ms.
There were only:

Code: Select all

2019-06-14 11:57:53.657439 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player
2019-06-14 11:57:53.657508 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player
2019-06-14 11:57:53.837372 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player
2019-06-14 11:57:53.951670 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player
2019-06-14 12:14:10.537719 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player
2019-06-14 12:14:10.648692 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player
2019-06-14 12:30:25.389614 [trace] network : ServerNetworking.cpp:727 : ServerNetworking::AcceptConnection : connected to new player

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 3:07 pm
by Morlic
My times in logs are GMT+2 btw.

Not sure where to start troubleshooting this. Seems like my client thinks it is connected whereas server does not recognize it. Any ideas for what to try?

Just to be sure, are IP and port correctly resolved?

Code: Select all

13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:375 : Connected to server at host_name: freeorion-lt.dedyn.io  address: 147.135.99.147  port: 12346
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:399 : Connecting to server took 221 ms.

Re: Multiplayer slow game server

Posted: Fri Jun 14, 2019 4:52 pm
by o01eg
Morlic wrote: Fri Jun 14, 2019 3:07 pm My times in logs are GMT+2 btw.

Not sure where to start troubleshooting this. Seems like my client thinks it is connected whereas server does not recognize it. Any ideas for what to try?

Just to be sure, are IP and port correctly resolved?

Code: Select all

13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:375 : Connected to server at host_name: freeorion-lt.dedyn.io  address: 147.135.99.147  port: 12346
13:09:24.539789 {0x00002f60} [debug] network : clientnetworking.cpp:399 : Connecting to server took 221 ms.
Yes, this is a correct IP. Maybe I should log IPs to see if it was your connection. The public server even crashed when catch some non-FreeOrion data: https://github.com/freeorion/freeorion/issues/2052