Adding a new ship design replaces an existing one instead

[l29ah]

Environment

• FreeOrion Version: b2112fe
• Operating System: Gentoo GNU/Linux
• Fetched as
  • Compiled from source

Description

Expected Result

Steps to reproduce

Have a shitload of designs, make a new one, click Add Finished Design, it will replace an existing one, including the build queues.

[swaqvalley]

I ran into this issue while acting as delegate for ThinkSome's empire in the current (ninth) multiplayer game, turn 68. I added a design while the empire was set to ready and it overwrote an existing design. I'm not entirely sure if this was caused because I had the empire set to ready or if I had just coincidentally run into the problem then. ThinkSome had been having this issue as well which is why I was delegating for him. I was unable to reproduce in a local multiplayer game.

I have attached the log, apologies for the length as I logged in and out many times to test different permutations to see if I could get the problem to go away. The following entries are of most interest:

11:05:32.106629 {0x00007f4d9eb5b000} [debug] IDallocator : IDAllocator.cpp:288 : Deserialize IDAllocator()  server id = -1 empire id = 8
11:05:32.106654 {0x00007f4d9eb5b000} [debug] IDallocator : IDAllocator.cpp:307 : Deserialized [empire = 8 next id = 33273, ]
11:05:32.106663 {0x00007f4d9eb5b000} [debug] IDallocator : IDAllocator.cpp:288 : Deserialize IDAllocator()  server id = -1 empire id = 8
11:05:32.106682 {0x00007f4d9eb5b000} [debug] IDallocator : IDAllocator.cpp:307 : Deserialized [empire = 8 next id = 32867, ]

11:05:32.109926 {0x00007f4d9eb5b000} [debug] client : ProductionWnd.cpp:1046 : ProductionWnd::UpdateQueue()
11:05:32.151463 {0x00007f4d9eb5b000} [error] client : DesignWnd.cpp:789 : DisplayedShipDesignManager::IsObsolete design id 33101 is unknown to the server

11:05:32.181121 {0x00007f4d9eb5b000} [debug] client : ResearchWnd.cpp:569 : ResearchWnd::UpdateQueue()
11:05:32.181466 {0x00007f4d9eb5b000} [debug] client : DesignWnd.cpp:1118 : ShipDesignManager initializing. New game false
11:05:32.181711 {0x00007f4d9eb5b000} [error] client : DesignWnd.cpp:924 : DisplayedShipDesignManager::Load part "AR_ZORTRIUM_PLATE" has an obsolete_ui_event_count = 51 which does not satisfy 0 < obsolete_ui_event_count < m_obsolete_ui_event_count = 51

11:05:32.429393 {0x00007f4d9eb5b000} [debug] client : Order.cpp:999 : ProductionQueueOrder place in queue: ProductionItem: BT_SHIP name: SkyFlood id: 33101  at index: -1
11:05:32.429431 {0x00007f4d9eb5b000} [debug] client : Order.cpp:1011 : ProductionQueueOrder removing item
11:05:32.429440 {0x00007f4d9eb5b000} [debug] client : Order.cpp:999 : ProductionQueueOrder place in queue: ProductionItem: BT_SHIP name: MaxFlood id: 33110  at index: -1
11:05:32.429481 {0x00007f4d9eb5b000} [debug] client : Order.cpp:1011 : ProductionQueueOrder removing item
11:05:32.429490 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33101 of an already-existing ShipDesign Efficiency
11:05:32.429496 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33101 of an already-existing ShipDesign Efficiency
11:05:32.429502 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33101 of an already-existing ShipDesign Efficiency
11:05:32.437381 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33110 of an already-existing ShipDesign MaxFlood
11:05:32.445358 {0x00007f4d9eb5b000} [debug] client : Order.cpp:999 : ProductionQueueOrder place in queue: ProductionItem: BT_SHIP name: SkyFlood id: 33119  at index: -1
11:05:32.445423 {0x00007f4d9eb5b000} [debug] client : Order.cpp:999 : ProductionQueueOrder place in queue: ProductionItem: BT_SHIP name: MaxFlood id: 33110  at index: -1
11:05:32.445461 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33101 of an already-existing ShipDesign Efficiency
11:05:32.445471 {0x00007f4d9eb5b000} [debug] client : Order.cpp:999 : ProductionQueueOrder place in queue: ProductionItem: BT_SHIP name: TestDesign id: 33101  at index: -1
11:05:32.445495 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33110 of an already-existing ShipDesign MaxFlood

11:05:32.453946 {0x00007f4d9eb5b000} [error] client : Order.cpp:1177 : Empire, 8, tried to remove a ShipDesign id = 33101 that the empire wasn't remembering
11:05:32.461881 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33101 of an already-existing ShipDesign Efficiency
11:05:32.461899 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33101 of an already-existing ShipDesign Efficiency
11:05:32.461907 {0x00007f4d9eb5b000} [error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33101 of an already-existing ShipDesign Efficiency

freeorion.log

[o01eg]

There is a server log https://freeorion-test.dedyn.io/FO0009-freeoriond.log

Can it be helpful?

[swaqvalley]

Does anyone know under what circumstances ShipDesignOrder::ExecuteImpl() would be called with m_create_new_design = true and m_design_id != INVALID_DESIGN_ID (in Order.cpp)? I've been looking through the code and I can't figure out what could possibly make that happen even though the error logs seem to indicate that it has.

[o01eg]

@swaqvalley Which log line you mean?

[swaqvalley]

The ones that say "[error] client : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 33101 of an already-existing ShipDesign Efficiency"

[o01eg]

It could be set such way from ShipDesignOrder::serialize.

[o01eg]

Maybe there is serialization inconsistency. Client creates new design, send order about it to the server, disconnects. Then client connects again, get order about new design from the server and deserializes it incorrectly.

[o01eg]

The server got same error:

2020-04-27 16:41:38.884371 {0x00007f72d3320740} [error] server : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 36860 of an already-existing ShipDesign AirSuperiority
2020-04-27 16:41:38.884401 {0x00007f72d3320740} [error] server : Order.cpp:1177 : Empire, 8, tried to remove a ShipDesign id = 29997 that the empire wasn't remembering
2020-04-27 16:41:38.884418 {0x00007f72d3320740} [error] server : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 36869 of an already-existing ShipDesign ThinkLots+
2020-04-27 16:41:38.884433 {0x00007f72d3320740} [error] server : Order.cpp:1186 : Empire, 8, tried to create a new ShipDesign with an id, 36878 of an already-existing ShipDesign FiveGuys
2020-04-27 16:41:38.884446 {0x00007f72d3320740} [error] server : Order.cpp:1177 : Empire, 8, tried to remove a ShipDesign id = 26561 that the empire wasn't remembering

[o01eg]

I suppose I got idea. When server sends orders back to the client they are executed. So client get back correct m_create_new_design == true and m_design_id == INVALID_DESIGN_ID, executes it,

freeorion/util/Order.cpp

Line 1206 in 7a1afa5

m_design_id = new_ship_design->ID();

sets new m_design_id and then it serialized to the server with m_create_new_design == true and m_design_id != INVALID_DESIGN_ID.

[geoffthemedio]

called with m_create_new_design = true and m_design_id != INVALID_DESIGN_ID

Normally the order is created by the client with INVALID_DESIGN_ID, and once it is executed on the client, the ID of the new design is saved in the order (https://github.com/freeorion/freeorion/blob/master/util/Order.cpp#L1206) and serialized and set to the server, where the order will be executed with that same design ID, so that what happens on the server is consistent with what happened on the client.

I don't know what happens if a client dis and reconnects after issuing such an order, though I don't see why there would be any difference with serialization in that case. Once the client executes the order and sends it to the server, the server can send it back to the client and it will still have the set m_design_id in it. The client could try to re-execute the order, but it should at most give a single error about that order's design ID already existing, not several errors about the same ID.

So it looks like the client tried to issue a series of new design orders, and they were all assigned the same ID for some reason...

[o01eg]

@geoffthemedio Can we add some more logs to see what was generated here?

[geoffthemedio]

...what was generated where?

[o01eg]

Design ID generated here.

Also what if his design ID collided with other empire's design ID?

[o01eg]

@geoffthemedio Should universe check in Universe::InsertShipDesignID if ship design ID already assigned?

[geoffthemedio]

Should universe check

It already does...
https://github.com/freeorion/freeorion/blob/master/universe/Universe.cpp#L440
https://github.com/freeorion/freeorion/blob/master/universe/IDAllocator.cpp#L146

Design ID generated here.

Generated where?

Also what if his design ID collided with other empire's design ID?

The ID Allocator should prevent that already: https://github.com/freeorion/freeorion/blob/master/universe/IDAllocator.h#L14

[o01eg]

The ID Allocator should prevent that already:

Could ID Allocators on the server and the client be desynchronized?

Generated where?

In

freeorion/universe/Universe.cpp

Line 433 in 6908c9e

return InsertShipDesignID(ship_design, boost::none, GenerateDesignID());

[o01eg]

I was unable to reproduce in a local multiplayer game.

@swaqvalley If issue related to sending ship design order back-forth between the server and the client you should try to re-connect to the server. Use option --network.server.unconn-human-empire-players.max 0 so the server continue the game when you disconnect.

[swaqvalley]

Thanks, @o01eg

Reproduction instructions!

1. Start server with: FreeOrionD.exe --hostless --network.server.unconn-human-empire-players.max 0
2. Start Free Orion -> Multi Player -> Join a game as Player -> Internet game at: localhost
3. Drop all AI so only player 1 remains
4. Start second Free Orion -> Multi Player -> Join a game as Player -> Internet game at: localhost
5. There should be two human players in the lobby, click Accept in one window and Start game in the other
6. Player 2: Click Design -> make Basic Large Hull with one armor -> Design Name "TestDesign" -> Add Finished Design
7. Player 2: Add TestDesign to build queue at homeworld
8. Both players: Click turn advance (now on Turn 2)
9. Player 2: Click turn advance
10. Player 2: Click Design -> make Basic Large Hull with two armors -> Design Name "TestDesign 2" -> Add Finished Design
11. Player 2: Resign (exit to menu)
12. Player 2: rejoin localhost multiplayer game (empire should not be set to ready now)
13. Player 2: Click Design -> make Basic Large Hull with three armors -> Design Name "TestDesign 3" -> Add Finished Design (note TestDesign 2 is missing and can't be remade)
14. Player 2: Add TestDesign 3 to build queue at homeworld
15. Both players: Click turn advance (now on Turn 3)
16. Build queue for Player 2 now has TestDesign and TestDesign 2 instead of TestDesign and TestDesign 3! Design window also removed TestDesign 3 and replaced it with TestDesign 2.

[swaqvalley]

I did some testing of PR #2913 and it is better but as @o01eg stated it doesn't solve the root of the issue and there is still some weirdness.

• Following the exact same steps for reproducing above I have to click to add "TestDesign 3" twice in order to get it to add. This design appears to work normally afterwards.
• The design with two armors still has the Add Finished Design button grayed out even though it is not in the list of finished designs. Making that design and clicking Rename Finished Design" will overwrite "TestDesign" but only in the finished designs list (build queue unaffected) and then afterwards the design with one armor can be recreated without issue. Design list and build queue appear to behave normally after this point.

[o01eg]

@swaqvalley Could you see what happened in the server and client logs?

[Vezzra]

I did some testing of PR #2913 and it is better but as @o01eg stated it doesn't solve the root of the issue and there is still some weirdness.

In that case we either need to reopen this issue, or open a separate one describing the actual root issue and the remaining "weirdness" (which would be my recommendation).

[swaqvalley]

@o01eg Logs from my last testing run attached. Nothing stands out to me. Ship names were d1, d2, d3 on Dummy empire and a1, a2, a3, a4 on swaq empire, if I recall correctly.
freeorion.log
freeoriond.log

[o01eg]

freeorion.log:

18:44:26.069283 {0x00007f8b4843ec00} [debug] client : Universe.cpp:175 : Reset id allocators with highest object id = -1 and highest design id = 1866
...
18:44:28.478326 {0x00007f8b4843ec00} [debug] IDallocator : IDAllocator.cpp:288 : Deserialize IDAllocator()  server id = -1 empire id = 1
18:44:28.478359 {0x00007f8b4843ec00} [debug] IDallocator : IDAllocator.cpp:307 : Deserialized [empire = 1 next id = 2023, ]
18:44:28.478372 {0x00007f8b4843ec00} [debug] IDallocator : IDAllocator.cpp:288 : Deserialize IDAllocator()  server id = -1 empire id = 1
18:44:28.478398 {0x00007f8b4843ec00} [debug] IDallocator : IDAllocator.cpp:307 : Deserialized [empire = 1 next id = 1866, ]
...
18:44:28.483820 {0x00007f8b4843ec00} [error] client : DesignWnd.cpp:789 : DisplayedShipDesignManager::IsObsolete design id 1866 is unknown to the server
...
18:44:47.963401 {0x00007f8b4843ec00} [error] client : Universe.cpp:446 : Ship design id 1866 already exists.
18:44:47.963442 {0x00007f8b4843ec00} [debug] client : Order.cpp:1207 : ShipDesignOrder::ExecuteImpl Create new ship design ID -1
18:44:47.963452 {0x00007f8b4843ec00} [error] client : Universe.cpp:2733 : SetEmpireKnowledgeOfShipDesign called with INVALID_DESIGN_ID
18:44:47.963465 {0x00007f8b4843ec00} [error] client : DesignWnd.cpp:687 : Ship design is invalid
...

I didn't find related errors in the server logs.

[o01eg]

Ship design 1866 was created before:

18:44:23.496798 {0x00007f8b4843ec00} [debug] client : Order.cpp:1207 : ShipDesignOrder::ExecuteImpl Create new ship design ID 1866

[geoffthemedio]

I did some testing of PR #2913 and it is better but as @o01eg stated it doesn't solve the root of the issue and there is still some weirdness.

In that case we either need to reopen this issue, or open a separate one describing the actual root issue and the remaining "weirdness" (which would be my recommendation).

@swaqvalley Can you open a new issue about the weirdness you mention?