Counting in-transit goods is off

[A.Badger]

Platform: Fedora 25 Linux x86_64
Version: simutrans nightly downlaoded on 20170228
Pakset: pak128.britain-ex-nightly also downloaded on 20170228
Savefile: https://toshio.fedorapeople.org/simutrans/counting-of-in-transit.sve

Counting of in-transit goods seems to be off.

* First open the save.  In the top right corner of the map you should have a cattle farm, dairy, with a dock each and a junction dock in between.  Narrowboat, "Milk 1", runs from the farm to the Junction.  A second narrowboat "Milk 2" carries milk from the junction to the dairy.

* The bug occurs in how much milk the game thinks is in-transit.  We'll want to watch how much milk is being carried by "Milk 1" to the Junction vs how much milk shows up at the junction and is loaded onto "Milk 2".  We'll also want to watch how much milk, the dairy believes is in-transit to it.

* At the beginning make sure you have a window open for the two ships, the three docks, the cattle farm, and the dairy.
  * Unrelated UI bug: When I save this game, I have a window open for each of these.  When I load the game, some of the windows are missing.  For this save, I'm consistently missing the Dairy and Milk 2.  If I try to open Milk 2 via the Line Management window or clicking on it in the map, the game instead moves the cattle Farm window to the top.  If I click on the cattle farm in the map, the game opens a second instance of the Cattle Farm Window.  I have to close the Cattle Farm window and then I can open a window for Milk 2.  I think that when saving or loading, the game is assigning the wrong object to the same window.  (So in this case, it doesn't open a window for the Milk 2 narrowboat because it thinks the window for cattle farm is for Milk 2).

* In the beginning, the cattle farm should be sending milk to the dock.  It doesn't immediately become visible at the dock but we can watch the dairy to observe that whenever the cattle farm ships 10 milk to the dock, the dairy's in-transit number goes up by 10.

* As soon as the cattle farm dumps its milk to the dock but before the milk is visible in either the dock or loaded onto Milk 1, save the game.

* Load from this new saved game.

* Open the dairy window and note that the dairy is now displaying 0 in-transit.

* Carefully watch how much milk is dumped from the cattle farm before the milk is loaded onto Milk 1.  As soon as Milk 1 is loaded, immediately pause the game.  You should see that Milk 1 has 30 crates of milk but only 20 crates have been dumped from the dairy to the dock since the reload.  The dairy is recording that 20 crates of milk are in transit.  That means these thirty milk are the original 30 dumped before the game was reloaded and which the dairy has forgotten about.

* Having too few goods recorded in-transit allows the cattle farm to produce more milk (for this save, the dairy allows 40 and we now have an additional 30 since the dairy doesn't know about them).  This leads to the player making more boats to transport that milk.  When the game loses track of how much is in transit again, it leads to an even higher amount of goods being produced and put into transit.  This eventually leads to a massive amount of goods being sold prematurely, allowing the player to make a large amount of money off of the transactions.

* Note1: this miscounting appears to not necessarily need a save and reload but I'm unsure precisely how to reproduce it as easily without involving save and reload.  Once the count is off, creating more ships to haul milk in this setup (I have a total of six) and letting them run for a while eventually increases the amount that the in-transit numbers are undercounted.

* Note2: in addition to this bug, there's another problem that exacerbates this.  If you put more ships into service hauling milk, let the game run for a while and then look at the dairy's in-transit numbers, you'll eventually see that it thinks a negative amount of milk is in-transit.  The in-transit number should never be less than 0.  If the game enforced that then this problem would occassionally self-correct.

[jamespetts]

Thank you very much for this detailed report. I am nearly finished with the bus re-scaling project in the pakset, and once that is done, I will be able to look at this and the other bug reports that have been made recently.

[jamespetts]

I have been looking at this to-day, and I have pushed what I think is a fix for the main problem. The problem occurred because the in-transit percentage was re-calculated every time that the game was loaded, but goods in the process of being transferred were omitted. I have now allowed the in-transit amounts simply to be loaded unaltered from the saved game file, which should prevent this from occurring.

I have not, however, been able to reproduce the problem that you describe at "note 2": can you state with greater precision the circumstances necessary to reproduce this specific error? (It is possible that this is simply a consequence of the first error: goods that were not counted in transit because they were transferring when a game was loaded might reduce the in-transit counter when they finally arrive, resulting in a negative number).

[A.Badger]

Yeah, I'm not 100% sure if I can make the in-transit numbers go negative if the first bug is fixed either.  I'll give it a try and report back (I'm running nightlies instead of compiling my own so there will be a delay while I wait for the nightly to pick up your fix.)

[A.Badger]

Well, it can still go negative: https://toshio.fedorapeople.org/simutrans/screenshot-negative-in-transit.png but it is harder to provoke now.  In this example, I hooked up three cattle farms to a single dairy in 1750.  I put two barges (the 50t variety) at each cattle farm and had them wait for 100% load.  The barges ended up amassing 80 churns of milk but none of them had 50t so none of them went to the dairy.  I then paused the game and changed all of the lines to wait for 10% load.  When I unpaused all of the barges went to the dairy.  Soon after (perhaps before the last barge had arrived, though) another barge took off with 10 churns.  By the time all the barges had unloaded, I was able to take this screenshot with -10 churns in-transit to the dairy.

[jamespetts]

Thank you for that. Would you be able to upload a saved game in which you can reproduce this reliably so that I can track it down more easily? I should be very grateful.

[A.Badger]

Okay, this is much harder to make happen reliably.  I'm not 100% certain of what variables are still important for causing this but I do have a before and after save that shows it.

Savegame BEFORE: https://toshio.fedorapeople.org/simutrans/counting-of-in-transit-part2.sve
Savegame AFTER: https://toshio.fedorapeople.org/simutrans/counting-of-in-transit-part3.sve

If you open savegame AFTER and hit Pause immediately, you'll see that it has hit -70 in-transit by July.

Steps to reproduce from save game BEFORE:

* Load game
* Pause game
* Make sure you have the dairy window open so you can watch the in transit numbers.
* Open the line management window.
* Edit all seven lines (6 from farms to the junction[2 ships a piece].  1 from the junction to the dairy[8 ships])  so that the first stop on each line has a minimum load setting of 10% instead of 100%.
* Unpause the game.
* The save game starts in March.  When I tested, the first convoy in April was the first time I saw a negative number.  (Unsure if the first of the month is a red herring).
* It progressed very slowly at first but seemed to speed up as time went on.  (I saw -20 in April, -30 near the end of May, -50 near the end of June, -70 in the first half of July).

[jamespetts]

Thank you very much for your reply here, and apologies for not having the chance to look at this earlier. You asked whether anything should be tested in a new game: this is an example of something that it would be helpful in a new game, as it is possible in theory at least for incorrect data saved by older versions of the game before the bug was fixed to stay around for quite a while. If this problem can be reproduced in a newly created game, then we know for sure that this really is still a problem in the code, not just legacy corrupt data.

[A.Badger]

Excellent.  My last save games for this bug ( https://toshio.fedorapeople.org/simutrans/counting-of-in-transit-part2.sve and
https://toshio.fedorapeople.org/simutrans/counting-of-in-transit-part3.sve ) were made with fresh saves.  So they should be untainted from any prior data.

[A.Badger]

Hey James, here's a PR that appears to mitigate the negative in-transit: https://github.com/jamespetts/simutrans-extended/pull/48  I'm still not sure why in-transit can become negative so in some ways this is treating the symptom rather than the cause.  I do think it's a worthwhile mitigation, though.  The in-transit count appears to become inaccurate the more deliveries are being made (in a short time?).  So once the count goes negative, the rate at which it strays from the truth accelerates.  This mitigation puts a clamp on that acceleration.

You might want to spit out a debug message (not sure the convention to do that in the simutrans codebase) whenever we trigger "current_in_transit_amt < menge" in case you ever want to track down the root cause in the future.

[jamespetts]

Thank you very much for that. I have a bit of a backlog at present (I have been very busy at work this week), so I will get around to looking into this issue when I have a moment. Thank you very much for the patch.

[A.Badger]

I have a tiny bit more information about the root cause (not enough for me to diagnose and fix but maybe enough for you to find something).  I'll describe the specific case that I've observed but the counting error may be more general.  In my current game I have a 50t barge delivering iron ore to an intermediate station where a larger ship (a brig) is waiting.  The barge has 50t of iron ore on it but once it makes its delivery, the brig has 70t of iron ore.  Taking a look at the iron ore dock, all of the barges shipping ore, and the brig's manifest I have a total of 160t in-transit at this point but the ironworks that's expecting the ore only records 140t.

So what appears to be happening is that at some point in either unloading from the barge to the dock or loading from the dock to the brig, an extra 20t of ore is being introduced erroneously which the ironworks is unaware of it.

Here's a save game where you can watch this in action: https://toshio.fedorapeople.org/simutrans/counting-error-boat-horse-33.sve

* Sorry for the cluttered screen (this is an in-progress game rather than a specific test case) and larger save file (I switched to zipped xml save games for easier debugging).  Here's what you should be looking for once you open the save game:

* (32) Boat Horse has just delivered its 50t of cargo and (10) Brig now has 70t of iron ore instead of the expected 50t.  (This was the very first delivery of iron ore on this map).
* (33) Boat Horse is a few minutes away from the quay and is expected to also deliver 50t of iron ore.
* (33) Boat Horse pulls into the quay and unloads its 50t of iron ore
* A little while later (by 1:28:46 December) (10) Brig has 140t of iron ore instead of the expected 120t.

[jamespetts]

Thank you very much for looking into this in detail. Unfortunately, I am having great trouble making your link work, as, whenever I try to click on it, it crashes my browser with what seems to be an enormous memory leak. Is there some other way that you could send that file to me, perhaps?

[A.Badger]

Ugh.  Apparently if you have a gzipped xml file (which is all that the xml_zipped simutrans save format is), browsers may automatically decompress the data and then attempt to display it.  I've switched back to save format zipped and here's a new copy of the save game: https://toshio.fedorapeople.org/simutrans/counting-error-boat-horse-33-take-2.sve

If that doesn't work, PM me where to send the file and I'll email it to you.

[jamespetts]

Ahh, that is much better - I can download this now. Thank you very much.

[A.Badger]

This is still a problem with e1a8a0c

* Used a self-compiled checkout of https://github.com/jamespetts/simutrans-extended/commit/e1a8a0c294203287badaf827b260f98efa61ac
* Rechecked with a fresh game that replicated the setup I had here: http://forum.simutrans.com/index.php?topic=16804.msg160136#msg160136

Confirmed that the root of the problem seems to be that the destination industry properly records the number of goods that are initially loaded onto the transports from the source industry but when the transport gets to the intermediate stop more goods end up on the second leg of the route than were loaded at the original source industry.

[jamespetts]

Thank you very much: I think that I have managed to fix this now. This seems to have been caused by a faulty iterator sometimes repeating the same item in the list, thus adding the same ware packet twice. I have fixed this by checking to make sure that the item is unique at each iteration, which seems to work in my brief testing.

I should be grateful if you could confirm that this has been fixed. Thank you.

[A.Badger]

Looks good!  I tested a self compiled https://github.com/jamespetts/simutrans-extended/commit/9397eaa947efeeff7505fdca0ba85a7991e374b4 and could not get the problem to recur.  Tested wih all of the save games uploaded to this thread.

Thanks James!