bridgewater-brunel.me.uk - Simutrans-Experimental - Pak128.Britain-Ex 0.9.1

[jamespetts]

I think that I have now found and fixed the bug causing instability: like many of these bugs, it was fixed by a single line of code, but tracking it down has taken a long time. What was happening was that, when a game was loaded, the city cars in the "unassigned" list (that is, not associated with a particular town) were deleted, but were not removed from that list, so that, when at the end of the month the list was checked to make sure that there were not too many city cars, memory locations that had already been deleted would be deleted again causing memory corruption and instability. My tests so far have shown the game to be stable with the fix applied.

[AP]

Fingers crossed, and many thanks James for the effort. 

[jamespetts]

Hmm - further testing shows that some heap corruption is still present in some cases, but it is not clear how often that this will occur or what effect that it might have on the server game.

I should also note that the error that I fixed was capable of causing desyncs as well as heap corruption.

[ӔO]

splendid news!

[Sarlock]

Wonderful!  Thank you for putting all those hours of frustrating bug hunting in to finding and squashing this one... hopefully it does the trick

[AP]

That is odd. I expected it to pick up any surplus, not steal everything.  Wonder why its done that?

Am running around today pretty busy, but will see if I can look at fixing it later tonight/tomorrow. Now I've built roads to the clothes shop I suppose I'll have to find another textile mill to pay for them instead.

Well I fixed it, but the server looks to have crashed and reverted at the end of May, so it was lost. If it can't be recovered, will try again tomorrow.

[jamespetts]

Server restarted with version 11.18. Error in the initial message concerning the pakset vesrion corrected (it had erroneously given the version as 0.9.0). A new note added concerning allowing access to other players if public roads and rivers are upgraded.

I hope that this version works rather better - sorry for the troubles before.

[VOLVO]

Ah.. people are making a large sum of profit while I already managed to bankrupt a company..

[jamespetts]

Ah.. people are making a large sum of profit while I already managed to bankrupt a company..

Don't worry about that - learn from your mistakes and have another go! That is what real life businesspeople do, after all...

[Sarlock]

How much of a resource drain are city cars?  There must be thousands on the map... some cities have 50+ city cars all circling around.  A quick guess puts it at an average of 20 cars per city x 400 cities = 8,000 city cars.  It actually could be significantly more than this, 8,000 is probably a conservative estimate.

[Junna]

Don't worry about that - learn from your mistakes and have another go! That is what real life businesspeople do, after all...

Though, how often was a railway company's entire infrastructure lost when the company went belly-up? I'm guessing it wasn't too frequent, except those times when the company was taken over by a competitor and the competing route was closed.

[AP]

Ah.. people are making a large sum of profit while I already managed to bankrupt a company..

I bankrupted my first one with 24h of starting. 

[ӔO]

Though, how often was a railway company's entire infrastructure lost when the company went belly-up? I'm guessing it wasn't too frequent, except those times when the company was taken over by a competitor and the competing route was closed.

IRL, some questionable companies would set up another company to fund a line. When the line was built, these companies would mysteriously go belly up and be bought at a nice discount by the parent railway company.

[jamespetts]

Though, how often was a railway company's entire infrastructure lost when the company went belly-up? I'm guessing it wasn't too frequent, except those times when the company was taken over by a competitor and the competing route was closed.

I do eventually plan to have a more sophisticated system of dealing with assets of insolvent companies.

[AP]

Anyone know what's up with the server game??? I just had several lines lose all their stops and waypoints for no reason, dozens of vehicles teleporting to depot. My lines 124 and 126 definitely affected. I just compared with a savegame from yesterday, the lines were definitely ok before.

Have logged off for fear of doing more damage!

[Sarlock]

I had that happen a few game years ago... all of my non-line convoys lost their stops and went to depot.  Only my lines remained intact.  It may have been related to adding access for other players, it happened around the same time.  I had this happen a month or two ago during a local game as well, I wasn't able to find out why it occurred.

It was a massive undertaking to reschedule everything.  My sympathies.

[VOLVO]

Anyone know what's up with the server game??? I just had several lines lose all their stops and waypoints for no reason, dozens of vehicles teleporting to depot. My lines 124 and 126 definitely affected. I just compared with a savegame from yesterday, the lines were definitely ok before.

Have logged off for fear of doing more damage!

It seems to happen when I play around the access button.. Sorry.
But the thing is that you seems to be using only one of my stops,
but other routes are affected too, so that's likely to be a bug.

I do eventually plan to have a more sophisticated system of dealing with assets of insolvent companies.

What about the infrastructure being take over by the government(even though it's bankrupt...)
and others have to pay a fee to use the belly-up infrastructure?

Also a company take-over system sound fun too.

[AP]

But the thing is that you seems to be using only one of my stops,

Which stop?? I wasn't aware I was using any stops other than my own.  Is it a stop that has been built on a tile I previously used as a waypoint?

[VOLVO]

Which stop?? I wasn't aware I was using any stops other than my own.  Is it a stop that has been built on a tile I previously used as a waypoint?

Berryington Promenade Street dock
Your (110) Timber to west seems to be using my stop..
It might be.. But when I first built the stop there is no other route serving the stop (the station property)

[Sarlock]

What is the server load like now?  I am starting to get more disconnects/desynchs from the game and it is becoming less responsive to new construction (sometimes it's a 5 second wait between doing something and seeing it happen).

[ӔO]

I can still get 25x in fast forward, although that is a long cry from 400x in 1752.

[AP]

Berryington Promenade Street dock
Your (110) Timber to west seems to be using my stop..
It might be.. But when I first built the stop there is no other route serving the stop (the station property)

Yes, it's right by the river mouth, I had a waypoint on that tile.

Am also having the slight lag issues...


Am I the only one who thinks this whole canals-for-passenger-traffic thing is getting a bit silly? 

[jamespetts]

The CPU load is currently 36.7%, so it is doubtful that the CPU load is causing the issue. Lag is likely to be caused when the server runs more quickly than the client, or there are network latency issues; if the client runs faster than the server, this will result in a desync, and although the code is meant to keep the client going no faster than the server, this may not happen when the server is under very severe strain.

[Sarlock]

I can still get 25x on my local copy as well.

It may be related to our relative distance in the world, given that I am half a world away from the server.  I imagine that as the map gains in complexity there will be more and more data sent between client and server which may impact on desynch issues.  How much of a drain do you figure private cars are?  There are thousands on the map... and I'd imagine that that data has to be sent on a regular basis from server to client.

[jamespetts]

The amount of data sent, except when saving and loading, is actually quite limited: for any given saved game (run in online mode), the game is essentially deterministic (the random seed is shared, so even things based on random number generation will be the same between client and server). Most of the data sent are regular check packets to ensure that the client and server remain in sync, and, of course, any commands or chat messages sent by any player have to be propagated.

[Sarlock]

Ah, interesting.  I didn't realize that it was built in that fashion.  So the movement of city cars is generated locally but kept synchronized with other players by using the same random number seed.  Good to know.

Many of my desynchs seem to happen while I am constructing new projects.  I build something, wait 5+ seconds for a response of the build from the server and then build the next thing.  If I queue up several projects in a row before I receive confirmation of the first one, I almost always desynch.

[jamespetts]

Ahh, that sort of desync could well be caused by latency - I think that you need to wait for one command to complete before executing the next.

[Sarlock]

I do.  If I don't it's a guaranteed desynch. 

Ping time to server is 150ms... not huge, I wouldn't think it would cause desynchs, especially if the amount of data transferred is small.

[AP]

Could it be a PC speed issue? My PC isn't the newest... which didn't give me concern until now but the map is quickly getting filled with activity, I wonder if it will be an issue going forward.

[jamespetts]

If your computer is too slow, you will lag behind the server, and so get increasing latency the longer that you are connected.

[Sarlock]

My computer can easily handle the map... and still accelerates to near 30x in offline play.  It seems far more likely to desynch when I'm building things, setting schedules, etc.  If I am just passively watching the game, it does desynch now and then but not nearly as often.

[jamespetts]

Interaction desyncs seem more common than passive desyncs generally - I believe that this is the case in Standard, too.

[TurfIt]

I connected just to take a look, my client timing is being jerked all over the place by erratic time check packets from the server. I highly doubt I would be able to maintain connection if anyone else was online performing any commands; My client is frequently hundreds of ms ahead of the server. I've never seen this before - log example:

Code Select Expand


Message: NWC_CHECK: time difference to server 5
Warning: karte_t::interactive: sync_step=576768  server=[rand=1903003556 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971487] client=[rand=1903003556 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971487]
Message: network_command_t::rdwr: read packet_id=9, client_id=0
Warning: network_check_activity(): received cmd id=9 nwc_check_t from socket[468]
Message: NWC_CHECK: time difference to server -1075
Warning: karte_t::interactive: sync_step=576775  server=[rand=3362342101 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971486] client=[rand=3362342101 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971486]
Message: network_command_t::rdwr: read packet_id=9, client_id=0
Warning: network_check_activity(): received cmd id=9 nwc_check_t from socket[468]
Message: NWC_CHECK: time difference to server 218
Message: network_command_t::rdwr: read packet_id=9, client_id=0
Warning: network_check_activity(): received cmd id=9 nwc_check_t from socket[468]
Message: NWC_CHECK: time difference to server 414
Message: network_command_t::rdwr: read packet_id=9, client_id=0
Warning: network_check_activity(): received cmd id=9 nwc_check_t from socket[468]
Message: NWC_CHECK: time difference to server 628
Message: network_command_t::rdwr: read packet_id=9, client_id=0
Warning: network_check_activity(): received cmd id=9 nwc_check_t from socket[468]
Message: NWC_CHECK: time difference to server 840
Warning: karte_t::interactive: sync_step=576780  server=[rand=42489301 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971485] client=[rand=42489301 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971485]
Warning: karte_t::interactive: sync_step=576785  server=[rand=734433582 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971482] client=[rand=734433582 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971482]
Warning: karte_t::interactive: sync_step=576790  server=[rand=2510892483 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971481] client=[rand=2510892483 halt=1 line=1 cnvy=1025 ind_dns_prop=3816 act_ind_dens=6928 traffic=1971481] 

The karte_t::interactive message should always immediately follow the NWC_CHECK: message.
And the sync_step= value should be spaced based on the servers server_frames_between_checks and frames_per_second setting. There should never be timing checks 5 syncs apart, and never a consistent 5 like that.
I also note the erroneous NWC_CHECKS are always spaced ~200ms apart.
I have verified with Wireshark that my client is indeed receiving these NWC_CHECK messages inappropriately. And in ~200ms spaced bursts.
A local test server runs things just fine. No timing anomalies seen by clients.

Can you check the packets being sent by the server? confirm these bursts of NWC_CHECKs.
Can you provide the simuconf.tab from the server? with the default settings, I can't duplicate locally.
I really have no clue what could be causing this.



There's also some other errors showing in the client log for the game:

Code Select Expand


Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
<snip thousands and thousands of these>

ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
<and hundreds of these>

Warning: sint64 convoi_t::calc_revenue: Average speed (23) for (null) exceeded maximum speed (977488149); falling back to overall average
Warning: sint64 convoi_t::calc_revenue: Average speed (23) for (null) exceeded maximum speed (977488149); falling back to overall average
Warning: sint64 convoi_t::calc_revenue: Average speed (23) for (null) exceeded maximum speed (977488149); falling back to overall average
<and just a few of these>

not likely relevant to the sync issue, but still errors.

[jamespetts]

Thank you very much for this analysis: this is most useful. Here is a link to the base simuconf.tab - do you need the pakset simuconf.tab, too? It is unaltered from the default for Pak128.Britian-Ex.

How do I go about checking the packets being sent by the server?

As to the client errors/warnings, the duplicate hashes, are, if I recall correctly, not necessarily erroneous, as I do recall writing some code which would put values into a hashtable in the expectation that there might be a duplicate. The calc_revenue problems I have found somewhat intractable, which is why we have the workaround of the overall average (in some cases, this might be related to integer overflows). The middle of these errors is not one with which I am familiar, and it is not immediately obvious whether this is an indication of the programme not acting correctly.

In any event, thank you again for testing this - this is much appreciated. I should be most interested in any comments on the simuconf.tab file and how to check the packets.

[TurfIt]

I just repeated the test locally with your server config. No timing issues encountered, as expected since the values aren't that far off default.

Why change server_frames_ahead? The default should be fine, or even reduced. You're adding an extra 170ms latency to every client, even if they don't need it. If clients are ending up with 'execute in past' desyncs, they should adjust additional_client_frames_behind instead. That way clients with good connections aren't penalized.

server_frames_between_checks = 256 is the default, but IMHO way too long. At 12 fps that's 21s between checks, a client could run way ahead in that time... I would drop that to 24-48 frames. A time check packet is a mere 98 bytes, times the number of connected clients, even once second, is still a bandwidth pittance.

I presume you changed server_frames_per_step to reduce CPU load? A setting of 5 and 12 fps is equivalent to 2.4 simloops. Offline the simloops target is 5.0. 2.4 isn't horrible, but things would be more responsive if you put frames_per_step back to 3 or 4. At the cost of extra CPU load of course.

For checking packets, try Wireshark or Tshark, or even good 'ole tcpdump would do.

Also, if any other players could post their logs  ( simu.log after running 'simutrans-experimental -debug 3 -log' ), that could confirm it's not just me seeing this. I can't 100% rule out something with my internet connection, although I had a steady 111-113ms ping to the server the whole time during my test.