Partially out of sync client. What do?

Post Reply
Bastrabun
Member
Posts: 211
Joined: Mon Nov 04, 2019 19:48

Partially out of sync client. What do?

by Bastrabun » Post

A player of mine just got a strange issue. His client did not load the area, did not show the items I dropped and when I changed the time of day, his sky did not update. He could harvest crops in his client, but after he logged in those were gone. When I sent him a chat message, it was displayed on his client. I was on the same server and had no such issues.

He was streaming on twitch, so I could see what his client was doing. The server is heavy with mods, but had a lag of less than 0.3 at this time. The server is linux debian 5.2.0 and runs on postgresql, the client was also the official 5.2.0

Neither he nor me saw strange things happening in the logs, at least no errors beyond INFO. No error, no nothing. On his third attempt I told him to log in not with the DNS name, but with the servers IPv4 address. Before, he connected with an IPv6 address, after he ALSO logged in with an IPv6 address, a different one though that looked like this: [::ffff:123.123.123.123] I made the last 4 numbers up, but it resembled an IPv4 address disguised as IPv6. No clue if that may or may not have something to do with the issue.

Can anyone explain the odd behaviour or - better - provide a solution? Do I ned to change something on the server? Does he need to change something on the client?
Whatever I say is CC0

User avatar
jas
Member
Posts: 593
Joined: Mon Jul 24, 2017 18:15
IRC: Freenode
Location: IRC

Re: Partially out of sync client. What do?

by jas » Post

You said you saw it on video? Is there a reason you didn't want to share?

Bastrabun
Member
Posts: 211
Joined: Mon Nov 04, 2019 19:48

Re: Partially out of sync client. What do?

by Bastrabun » Post

Good point. It was a stream, so it didn't occur to me that twitch saves those videos if you tell it to. Here is it: https://www.twitch.tv/videos/640423516

He enters the server around 01:38:00

After that, we go sightseeing for a while. We start o the airship, dies from a rat, walks back to the airport, goes exploring the public gardens, while _I_ get killed by a rat. I assign him a plot inside the city, then we ride down into the mine, where after some climbing, the issues start:

A first, probably unrelated crash happens at 01:53:55

At 01:58:18 I drop him a tool, which he successfully picks up. It shows up in his inventory and he can use it.

At 01:58:40 I drop him some torches, which he tries to pick up but can't. He sees them, I see them, but he can't interact with them. I see him on my client trying to pick them up, in his stream my chat messages appear. After that, he briefly goes through some debugging screens, if something relevant is hidden there you may need to halt the picture.

At 02:00:34 he tries to dig mushrooms. They do disappear on his client, but are not placed in his inventory.

At 02:01:30 He starts writing a message in the public chat, as soon as he hits enter I see his message.

At 02:02:10 He starts entering a chatcommand to go back to spawn. On my client it looks like he goes back to spawn. On his client it looks like nothing is happening at all. This spawn command is done via a player_object:set_pos() When I move my avatar in the cave, he can see my movements in his client and my chat. HIS movements are also executed, but near the spawn.

At 02:02:34 he tries to enter the command again. But sees nothing happening on his client.

At 02:03:10 he starts moving around in the cave on his client, while I can see him moving around near the spawn. I try to catch him and write him a signpost, but since I can judge his position only by the stream (which is not that far behind as most other streams are), I am unable to place the signpost properly

At 02:04:20 he starts to relog.

At 02:05:45 he is back in the game and near the spawn. He kills a chicken for food, so he can interact with the environment again.

At 02:05:32 I toss him some torches which he picks up. I fail at giving him something to eat quick enough, so he dies :D

((Outrageous, at 02:07:25 he wins the race towards his plots despite me trying to cheat! :P ))

More sightseeing occurs, the harbour this time. We decide to boat into the wilderness, where the second incident occurs.

At 02:22:30 he starts digging carrots, the appear in his inventory and disappear from the field.

At 02:23:18 he tries to replant. The first carrot is planted, but the others look like they aren't. Later (02:24:02) you can see them magically reappear, but only the first some.

At around 02:24:48 the rest of those carrots appear. Agen, he tries to plant a carrot to a patch that is not taken, but it also doesn't appear.

At 02:25:15 I toss him a sword, which he doesn't see on his client and when I change the ingame time to morning, it does not do anything on his side. On my client and on my own stream I can see daylight.

At 02:26:26 he brings up debug stuff again, but I have no clue what these values mean. He also opens the profiler stuff, but same here, I can only guess what most of those values are about. Maybe you can make any sense of them.

At 02:29:50 he rearrenges a bones block in his inventory, you can see it magically switch back to its previous position about 10 seconds later.

At 02:30:20 He relogs again

At 02:31:32 He tries to dig a potato, which works. It is placed in his inventory. he checks his inventory and you can see the bones block he rearranged at 02:29:50 magically appears in the inventoryposition he dragged it to, not in the position we saw it go back to 10 seconds later.

More sightseeing occurs, we ride down and up the public mine again, then higher up to the planetarium level and down again.

Third incident

At 02:47:24 he tries to open a trapdoor. At first I thought he had just misslicked somehow.

At 02:47:37 you can see me descending the ladder - with my avatar cut in half by the closed trapdoor. On my client I had opened the trapdoor, on his it had stayed shut. He then tries to open it again, to no avail.

At 02:48:31 We're back at his plot, where half the world won't load. The entities do, the blocks don't. On my client it's totally fine, I figure it's some network or cache related problem, I ask him to connect to the IP instead to rule out DNS problems.

At 02:50:00 he relogs, everything back to normal, first still with the DNS name

At 02:52:30 he relogs with the IP address.

We discontinue the experiements for the moment, the next day he logs in and plays for a while without problems. One thing we didn't do while those sync problems happened: We didn't restart his client. Maybe that did the trick?

He also posted me the debug.txt of his client. Nothing extraordinary in there, as far as I can see. Here it is: https://paste.ofcode.org/b8FsUXkFQwEyNTPk7bV9v3
Whatever I say is CC0

User avatar
Krock
Developer
Posts: 4649
Joined: Thu Oct 03, 2013 07:48
GitHub: SmallJoker
Location: Switzerland
Contact:

Re: Partially out of sync client. What do?

by Krock » Post

There were some networking changes in the more recent 5.3.0-dev version - does it change anything? See Builds forum, and Ubuntu PPA for recent builds.
Look, I programmed a bug for you. >> Mod Search Engine << - Mods by Krock - DuckDuckGo mod search bang: !mtmod <keyword here>

Bastrabun
Member
Posts: 211
Joined: Mon Nov 04, 2019 19:48

Re: Partially out of sync client. What do?

by Bastrabun » Post

Neither of us used a 5.3.0-dev client or server, we were on 5.2.0

This strange behaviour only occured three times in a row now, today we weren't able to reproduce the issue. We didn't try too hard though.

Is there anything that helps me fight it or helps you identify the cause? Like a lower logging level or whatever values we can read out of the client or server?
Whatever I say is CC0

User avatar
jas
Member
Posts: 593
Joined: Mon Jul 24, 2017 18:15
IRC: Freenode
Location: IRC

Re: Partially out of sync client. What do?

by jas » Post

Thank you for that writeup, I look forward to watching the video

sfan5
Moderator
Posts: 4094
Joined: Wed Aug 24, 2011 09:44
GitHub: sfan5
IRC: sfan5
Location: Germany

Re: Partially out of sync client. What do?

by sfan5 » Post

Permanent desyncs like this can be caused by lost packets when the server sends way too many, due to mods that weren't written with performance in mind. (relevant issue)

You can test this by joining the server using a recent 5.3.0-dev client with the --verbose flag on the command line.
Every 30 seconds the client will print statistics that look like this:

Code: Select all

2020-06-06 20:55:21: INFO[Main]: Client packetcounter (30s): sum=27 avg=0.9/s
2020-06-06 20:55:21: INFO[Main]: cmd 41 (TOCLIENT_TIME_OF_DAY) count 6
2020-06-06 20:55:21: INFO[Main]: cmd 63 (TOCLIENT_PLAY_SOUND) count 9
[...]
If you see more than 20/s when standing still, the reason should be investigated.
Though it isn't as clear cut as this since e.g. TOCLIENT_BLOCKDATA is not a problem and the initial burst when joining is not an issue either.
Mods: Mesecons | WorldEdit | Nuke & Minetest builds for Windows (32-bit & 64-bit)

User avatar
jas
Member
Posts: 593
Joined: Mon Jul 24, 2017 18:15
IRC: Freenode
Location: IRC

Re: Partially out of sync client. What do?

by jas » Post

Thank you very much for the invaluable information!

Edit: How about

Code: Select all

45: INFO[Main]: cmd 50 (TOCLIENT_ACTIVE_OBJECT_MESSAGES) count 307
Is that bad?

Bastrabun
Member
Posts: 211
Joined: Mon Nov 04, 2019 19:48

Re: Partially out of sync client. What do?

by Bastrabun » Post

So you say it is a server/mod issue, but I can gauge it with a 5.3.0 client? Here we go.

Running about the whole map screaming:

Code: Select all

Line 13999: 2020-06-07 04:56:39: INFO[Main]: Client packetcounter (30s): sum=827 avg=27.5667/s
Line 14415: 2020-06-07 04:57:09: INFO[Main]: Client packetcounter (30s): sum=1464 avg=48.8/s
Line 15873: 2020-06-07 04:57:39: INFO[Main]: Client packetcounter (30s): sum=1291 avg=43.0333/s
Line 16800: 2020-06-07 04:58:09: INFO[Main]: Client packetcounter (30s): sum=879 avg=29.3/s
Line 16899: 2020-06-07 04:58:39: INFO[Main]: Client packetcounter (30s): sum=584 avg=19.4667/s
Standing still, no other players nearby, nothing going on in my vicinity:

Code: Select all

Line 16969: 2020-06-07 04:59:09: INFO[Main]: Client packetcounter (30s): sum=510 avg=17/s
Line 17052: 2020-06-07 04:59:39: INFO[Main]: Client packetcounter (30s): sum=529 avg=17.6333/s
Line 17163: 2020-06-07 05:00:09: INFO[Main]: Client packetcounter (30s): sum=522 avg=17.4/s
Line 17276: 2020-06-07 05:00:39: INFO[Main]: Client packetcounter (30s): sum=541 avg=18.0333/s
Line 17366: 2020-06-07 05:01:09: INFO[Main]: Client packetcounter (30s): sum=516 avg=17.2/s
Line 17451: 2020-06-07 05:01:39: INFO[Main]: Client packetcounter (30s): sum=520 avg=17.3333/s
Line 17518: 2020-06-07 05:02:09: INFO[Main]: Client packetcounter (30s): sum=529 avg=17.6333/s
Line 17608: 2020-06-07 05:02:39: INFO[Main]: Client packetcounter (30s): sum=522 avg=17.4/s
Line 17697: 2020-06-07 05:03:09: INFO[Main]: Client packetcounter (30s): sum=531 avg=17.7/s
Line 17766: 2020-06-07 05:03:39: INFO[Main]: Client packetcounter (30s): sum=711 avg=23.7/s
Line 17854: 2020-06-07 05:04:09: INFO[Main]: Client packetcounter (30s): sum=575 avg=19.1667/s
I used the #153592024 win64 flavour of https://gitlab.com/minetest/minetest/pipelines (for my future reference at position 2138,14.5,1304)

Let's say I want to find out which mod is responsible for the too many packets. I assume, this could help me?

Code: Select all

2020-06-07 05:06:39: INFO[Main]: Client packetcounter (30s): sum=670 avg=22.3333/s
2020-06-07 05:06:39: INFO[Main]: cmd 32 (TOCLIENT_BLOCKDATA) count 343
2020-06-07 05:06:39: INFO[Main]: cmd 41 (TOCLIENT_TIME_OF_DAY) count 6
2020-06-07 05:06:39: INFO[Main]: cmd 49 (TOCLIENT_ACTIVE_OBJECT_REMOVE_ADD) count 1
2020-06-07 05:06:39: INFO[Main]: cmd 50 (TOCLIENT_ACTIVE_OBJECT_MESSAGES) count 256
2020-06-07 05:06:39: INFO[Main]: cmd 63 (TOCLIENT_PLAY_SOUND) count 9
2020-06-07 05:06:39: INFO[Main]: cmd 75 (TOCLIENT_HUDCHANGE) count 50
2020-06-07 05:06:39: INFO[Main]: cmd 76 (TOCLIENT_HUD_SET_FLAGS) count 5
Is there a --evenmoreverbose flag I could use to find out, which mod is responsible for 343 TOCLIENT_BLOCKDATA? Or 256 TOCLIENT_ACTIVE_OBJECT_MESSAGES?

If not, it's the old "disable half the mods, see if the problem persists" game or is there any other magic?
Whatever I say is CC0

sfan5
Moderator
Posts: 4094
Joined: Wed Aug 24, 2011 09:44
GitHub: sfan5
IRC: sfan5
Location: Germany

Re: Partially out of sync client. What do?

by sfan5 » Post

jas wrote:
Sun Jun 07, 2020 01:43
[...] Is that bad?
Not really no.
The number of active object messages depends on how many players and/or mobs are nearby, 10/s isn't terribly much.
Bastrabun wrote:
Sun Jun 07, 2020 03:12
Standing still, no other players nearby, nothing going on in my vicinity:
An average of 17 is quite high when there is nothing going on and nobody nearby.
Bastrabun wrote:
Sun Jun 07, 2020 03:12
Let's say I want to find out which mod is responsible for the too many packets. I assume, this could help me?

Code: Select all

2020-06-07 05:06:39: INFO[Main]: Client packetcounter (30s): sum=670 avg=22.3333/s
2020-06-07 05:06:39: INFO[Main]: cmd 32 (TOCLIENT_BLOCKDATA) count 343
2020-06-07 05:06:39: INFO[Main]: cmd 41 (TOCLIENT_TIME_OF_DAY) count 6
2020-06-07 05:06:39: INFO[Main]: cmd 49 (TOCLIENT_ACTIVE_OBJECT_REMOVE_ADD) count 1
2020-06-07 05:06:39: INFO[Main]: cmd 50 (TOCLIENT_ACTIVE_OBJECT_MESSAGES) count 256
2020-06-07 05:06:39: INFO[Main]: cmd 63 (TOCLIENT_PLAY_SOUND) count 9
2020-06-07 05:06:39: INFO[Main]: cmd 75 (TOCLIENT_HUDCHANGE) count 50
2020-06-07 05:06:39: INFO[Main]: cmd 76 (TOCLIENT_HUD_SET_FLAGS) count 5
Is there a --evenmoreverbose flag I could use to find out, which mod is responsible for 343 TOCLIENT_BLOCKDATA? Or 256 TOCLIENT_ACTIVE_OBJECT_MESSAGES?

If not, it's the old "disable half the mods, see if the problem persists" game or is there any other magic?
You mostly don't need to worry about TOCLIENT_BLOCKDATA since that's the engine sending you the world contents (unless it's a mod causing these to be sent more often than they usually would).
TOCLIENT_ACTIVE_OBJECT_MESSAGES is much more interesting here, I can't think of a reason there should be that many when you're standing still and there's nothing going on.

Unfortunately more debugging code will have to be added to make sense of these. The "disable mods until it goes away" approach is always possible as a last resort.
Mods: Mesecons | WorldEdit | Nuke & Minetest builds for Windows (32-bit & 64-bit)

sfan5
Moderator
Posts: 4094
Joined: Wed Aug 24, 2011 09:44
GitHub: sfan5
IRC: sfan5
Location: Germany

Re: Partially out of sync client. What do?

by sfan5 » Post

I've written some extra debug code in a branch.
Github even produces Windows builds but doesn't let you download without singing up, so you can use this link: https://0x0.st/iVM7.zip

Every 30 seconds the client will additionally print an "Object packetcounter" (don't forget the --verbose flag).
The table provides insight into what is inside the TOCLIENT_ACTIVE_OBJECT_MESSAGES packets, it is grouped by local player/player/type of entity.
High values here can again be cause for concern, but note that AO_CMD_UPDATE_POSITION can be ignored (it's not a problem).
Bastrabun wrote:
Sun Jun 07, 2020 03:12
Is there a --evenmoreverbose flag I could use to find out, which mod is responsible for [...]?
In general it's most useful if you just paste the whole table here. There is no direct way to determine which mod did what, but the more debug info the easier it gets to search for the culprit.
Mods: Mesecons | WorldEdit | Nuke & Minetest builds for Windows (32-bit & 64-bit)

Bastrabun
Member
Posts: 211
Joined: Mon Nov 04, 2019 19:48

Re: Partially out of sync client. What do?

by Bastrabun » Post

I let the client run for a while on the same spot as before. In other spots, I got readings of more than 123/s

Here's a paste of the worst part: https://pastebin.com/PGchLFLA

Here's a paste of the least worse part: https://pastebin.com/RSxdqFQt

Here's some previews:

Code: Select all

2020-06-09 01:16:53: INFO[Main]: Client packetcounter (30s): sum=498 avg=16.6/s
2020-06-09 01:16:53: INFO[Main]: cmd 32 (TOCLIENT_BLOCKDATA) count 337
2020-06-09 01:16:53: INFO[Main]: cmd 41 (TOCLIENT_TIME_OF_DAY) count 6
2020-06-09 01:16:53: INFO[Main]: cmd 50 (TOCLIENT_ACTIVE_OBJECT_MESSAGES) count 84
2020-06-09 01:16:53: INFO[Main]: cmd 63 (TOCLIENT_PLAY_SOUND) count 9
2020-06-09 01:16:53: INFO[Main]: cmd 75 (TOCLIENT_HUDCHANGE) count 56
2020-06-09 01:16:53: INFO[Main]: cmd 76 (TOCLIENT_HUD_SET_FLAGS) count 6
2020-06-09 01:16:53: INFO[Main]: Object packetcounter:
2020-06-09 01:16:53: INFO[Main]: <mesh: dolphin.b3d>: sum=55
2020-06-09 01:16:53: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 55
2020-06-09 01:16:53: INFO[Main]: <mesh: fishy.b3d>: sum=825
2020-06-09 01:16:53: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 825
2020-06-09 01:16:53: INFO[Main]: <mesh: skinsdb_3d_armor_character_5.b3d>: sum=57
2020-06-09 01:16:53: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 1
2020-06-09 01:16:53: INFO[Main]:   cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 56
2020-06-09 01:16:53: INFO[Main]: Local player: sum=28
2020-06-09 01:16:53: INFO[Main]:   cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 28
2020-06-09 01:16:54: INFO[Main]: Client: avg_rtt=0.026

Code: Select all

2020-06-08 23:19:36: INFO[Main]: Client packetcounter (30s): sum=3703 avg=123.433/s
2020-06-08 23:19:36: INFO[Main]: cmd 32 (TOCLIENT_BLOCKDATA) count 324
2020-06-08 23:19:36: INFO[Main]: cmd 41 (TOCLIENT_TIME_OF_DAY) count 6
2020-06-08 23:19:36: INFO[Main]: cmd 49 (TOCLIENT_ACTIVE_OBJECT_REMOVE_ADD) count 1
2020-06-08 23:19:36: INFO[Main]: cmd 50 (TOCLIENT_ACTIVE_OBJECT_MESSAGES) count 286
2020-06-08 23:19:36: INFO[Main]: cmd 70 (TOCLIENT_SPAWN_PARTICLE) count 2991
2020-06-08 23:19:36: INFO[Main]: cmd 75 (TOCLIENT_HUDCHANGE) count 55
2020-06-08 23:19:36: INFO[Main]: cmd 76 (TOCLIENT_HUD_SET_FLAGS) count 5
2020-06-08 23:19:36: INFO[Main]: cmd 79 (TOCLIENT_SET_SKY) count 7
2020-06-08 23:19:36: INFO[Main]: cmd 84 (TOCLIENT_CLOUD_PARAMS) count 7
2020-06-08 23:19:36: INFO[Main]: cmd 90 (TOCLIENT_SET_SUN) count 7
2020-06-08 23:19:36: INFO[Main]: cmd 91 (TOCLIENT_SET_MOON) count 7
2020-06-08 23:19:36: INFO[Main]: cmd 92 (TOCLIENT_SET_STARS) count 7
2020-06-08 23:19:36: INFO[Main]: Object packetcounter:
2020-06-08 23:19:36: INFO[Main]: <mesh: petz_butterfly.b3d>: sum=39
2020-06-08 23:19:36: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 39
2020-06-08 23:19:36: INFO[Main]: <mesh: petz_chicken.b3d>: sum=120
2020-06-08 23:19:36: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 110
2020-06-08 23:19:36: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 10
2020-06-08 23:19:36: INFO[Main]: <mesh: skinsdb_3d_armor_character_5.b3d>: sum=281
2020-06-08 23:19:36: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 176
2020-06-08 23:19:36: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 21
2020-06-08 23:19:36: INFO[Main]:   cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 84
2020-06-08 23:19:36: INFO[Main]: Local player: sum=28
2020-06-08 23:19:36: INFO[Main]:   cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 28
2020-06-08 23:19:36: INFO[Main]: GenericCAO::addToScene(): mesh
Whatever I say is CC0

sfan5
Moderator
Posts: 4094
Joined: Wed Aug 24, 2011 09:44
GitHub: sfan5
IRC: sfan5
Location: Germany

Re: Partially out of sync client. What do?

by sfan5 » Post

2020-06-08 23:25:36: INFO[Main]: cmd 70 (TOCLIENT_SPAWN_PARTICLE) count 2542
^ This is definitely excessive. You should find out which mod keeps spawning so many particles.

2020-06-08 23:25:06: INFO[Main]: cmd 75 (TOCLIENT_HUDCHANGE) count 71
^ Likely not a problem, but this is also a bit high. Depends on the exact use of HUD.

2020-06-08 23:25:06: INFO[Main]: cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 81
^ Unless movement characteristics (gravity, sprinting, ...) change very rapidly, this number is also a bit high.
Shouldn't be causing any serious trouble though, so looking into this is low priority.
Mods: Mesecons | WorldEdit | Nuke & Minetest builds for Windows (32-bit & 64-bit)

Bastrabun
Member
Posts: 211
Joined: Mon Nov 04, 2019 19:48

Re: Partially out of sync client. What do?

by Bastrabun » Post

Particles:
I assume I found one of the culprits, "weather_pack" after going through all the mods that spawn particles (). After I disabled it, the particles dropped by a lot. I took a look at the mod, where it spawns the particles and had no idea why it would have so many particles around even when there was no weather at all. Aren't particles supposed to ... go away with time and not send over and over again? Other than that I cannot explain so many particles even when there are none onscreen. Maybe someone else can make some sense of it, here's where I got the mod from: https://gitlab.com/zombiebot/weather_pack

Hud:
We use a stamina mod, areas and xp_redo, those keep updating the HUD quite often. As far as I understood, all the other mods only use the HUD on occasion, like woodcutting, email, worldedit and the party-mod. Pipeworks also has a hud change thing going on for a fake plaer, which I do not understand. I searched for "hud_change" in all my mods, or should I go for other search terms, too?

Physics:

We use 3d armor, petz, emote and ts_furniture and stamina, who all do set_physics_override and we have pova for making them work together. I assume its not just those that cause so many physics updates?

While weather_pack is disabled, I can report only half a success. In my test-position I still have as much as 22 packets per second when standing still:

Code: Select all

2020-06-10 10:48:22: INFO[Main]: Client packetcounter (30s): sum=662 avg=22.0667/s
2020-06-10 10:48:22: INFO[Main]: cmd 32 (TOCLIENT_BLOCKDATA) count 336
2020-06-10 10:48:22: INFO[Main]: cmd 41 (TOCLIENT_TIME_OF_DAY) count 6
2020-06-10 10:48:22: INFO[Main]: cmd 50 (TOCLIENT_ACTIVE_OBJECT_MESSAGES) count 256
2020-06-10 10:48:22: INFO[Main]: cmd 63 (TOCLIENT_PLAY_SOUND) count 9
2020-06-10 10:48:22: INFO[Main]: cmd 75 (TOCLIENT_HUDCHANGE) count 50
2020-06-10 10:48:22: INFO[Main]: cmd 76 (TOCLIENT_HUD_SET_FLAGS) count 5
2020-06-10 10:48:22: INFO[Main]: Object packetcounter:
2020-06-10 10:48:22: INFO[Main]: <mesh: skinsdb_3d_armor_character_5.b3d>: sum=56
2020-06-10 10:48:22: INFO[Main]:   cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 56
2020-06-10 10:48:22: INFO[Main]: <mesh: water_life_jellyfish.b3d>: sum=228
2020-06-10 10:48:22: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 228
2020-06-10 10:48:22: INFO[Main]: Local player: sum=28
2020-06-10 10:48:22: INFO[Main]:   cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 28
Most packets I could catch now is 50 packets per second, when I took the rollercoaster ride around our marketplace.

Code: Select all

2020-06-10 09:24:50: INFO[Main]: Client packetcounter (30s): sum=1488 avg=49.6/s
2020-06-10 09:24:50: INFO[Main]: cmd 32 (TOCLIENT_BLOCKDATA) count 106
2020-06-10 09:24:50: INFO[Main]: cmd 33 (TOCLIENT_ADDNODE) count 329
2020-06-10 09:24:50: INFO[Main]: cmd 34 (TOCLIENT_REMOVENODE) count 224
2020-06-10 09:24:50: INFO[Main]: cmd 41 (TOCLIENT_TIME_OF_DAY) count 6
2020-06-10 09:24:50: INFO[Main]: cmd 49 (TOCLIENT_ACTIVE_OBJECT_REMOVE_ADD) count 234
2020-06-10 09:24:50: INFO[Main]: cmd 50 (TOCLIENT_ACTIVE_OBJECT_MESSAGES) count 470
2020-06-10 09:24:50: INFO[Main]: cmd 63 (TOCLIENT_PLAY_SOUND) count 26
2020-06-10 09:24:50: INFO[Main]: cmd 64 (TOCLIENT_STOP_SOUND) count 25
2020-06-10 09:24:50: INFO[Main]: cmd 71 (TOCLIENT_ADD_PARTICLESPAWNER) count 6
2020-06-10 09:24:50: INFO[Main]: cmd 75 (TOCLIENT_HUDCHANGE) count 56
2020-06-10 09:24:50: INFO[Main]: cmd 76 (TOCLIENT_HUD_SET_FLAGS) count 6
2020-06-10 09:24:50: INFO[Main]: Object packetcounter:
2020-06-10 09:24:50: INFO[Main]: <mesh: 3d_armor_entity.obj>: sum=7
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 2
2020-06-10 09:24:50: INFO[Main]:   cmd 5 (AO_CMD_UPDATE_ARMOR_GROUPS) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 8 (AO_CMD_ATTACH_TO) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 12 (AO_CMD_SET_ANIMATION_SPEED) count 1
2020-06-10 09:24:50: INFO[Main]: <mesh: carts_cart.b3d>: sum=443
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 334
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 109
2020-06-10 09:24:50: INFO[Main]: <mesh: petz_butterfly.b3d>: sum=9
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 8
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 1
2020-06-10 09:24:50: INFO[Main]: <mesh: petz_calf.b3d>: sum=37
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 29
2020-06-10 09:24:50: INFO[Main]:   cmd 5 (AO_CMD_UPDATE_ARMOR_GROUPS) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 4
2020-06-10 09:24:50: INFO[Main]:   cmd 8 (AO_CMD_ATTACH_TO) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 12 (AO_CMD_SET_ANIMATION_SPEED) count 1
2020-06-10 09:24:50: INFO[Main]: <mesh: petz_chicken.b3d>: sum=28
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 25
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 3
2020-06-10 09:24:50: INFO[Main]: <mesh: petz_hamster.b3d>: sum=201
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 4
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 169
2020-06-10 09:24:50: INFO[Main]:   cmd 5 (AO_CMD_UPDATE_ARMOR_GROUPS) count 4
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 16
2020-06-10 09:24:50: INFO[Main]:   cmd 8 (AO_CMD_ATTACH_TO) count 4
2020-06-10 09:24:50: INFO[Main]:   cmd 12 (AO_CMD_SET_ANIMATION_SPEED) count 4
2020-06-10 09:24:50: INFO[Main]: <mesh: petz_lamb.b3d>: sum=7
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 6
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 1
2020-06-10 09:24:50: INFO[Main]: <mesh: petz_rat.b3d>: sum=18
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 16
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 2
2020-06-10 09:24:50: INFO[Main]: <mesh: petz_turtle.b3d>: sum=13
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 12
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 1
2020-06-10 09:24:50: INFO[Main]: <mesh: signs_lib_standard_sign_entity_wall.obj>: sum=8
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 3
2020-06-10 09:24:50: INFO[Main]:   cmd 5 (AO_CMD_UPDATE_ARMOR_GROUPS) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 8 (AO_CMD_ATTACH_TO) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 12 (AO_CMD_SET_ANIMATION_SPEED) count 1
2020-06-10 09:24:50: INFO[Main]: <mesh: signs_lib_standard_sign_entity_yard.obj>: sum=7
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 2
2020-06-10 09:24:50: INFO[Main]:   cmd 5 (AO_CMD_UPDATE_ARMOR_GROUPS) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 8 (AO_CMD_ATTACH_TO) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 12 (AO_CMD_SET_ANIMATION_SPEED) count 1
2020-06-10 09:24:50: INFO[Main]: <mesh: skinsdb_3d_armor_character_5.b3d>: sum=28
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 27
2020-06-10 09:24:50: INFO[Main]: <upright_sprite: [combine:156x18:30,3=font_metro_0047.png:43,3=font_metro_0065.png:53,3=font_metro_0074.png:60,3=font_metro_0020.png:70,3=font_metro_0061.png:79,3=font_metro_0020.png:89,3=font_metro_0070.png:99,3=font_metro_006c.png:104,3=font_metro_006f.p
2020-06-10 09:24:50: INFO[Main]: ng:114,3=font_metro_0074.png:121,3=font_metro_0021.png^[colorize:#000>: sum=7
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 2
2020-06-10 09:24:50: INFO[Main]:   cmd 5 (AO_CMD_UPDATE_ARMOR_GROUPS) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 6 (AO_CMD_SET_ANIMATION) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 8 (AO_CMD_ATTACH_TO) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 12 (AO_CMD_SET_ANIMATION_SPEED) count 1
2020-06-10 09:24:50: INFO[Main]: <upright_sprite: [combine:48x48:0,-144=ontime_clocks_needle_h48.png:0,-384=ontime_clocks_needle_m48.png^[colorize:#FF0>: sum=1
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]: <upright_sprite: [combine:48x48:0,-144=ontime_clocks_needle_h48.png:0,-480=ontime_clocks_needle_m48.png^[colorize:#FF0>: sum=2
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 1
2020-06-10 09:24:50: INFO[Main]: <upright_sprite: [combine:48x48:0,-144=ontime_clocks_needle_h48.png:0,-528=ontime_clocks_needle_m48.png^[colorize:#FF0>: sum=2
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 1
2020-06-10 09:24:50: INFO[Main]: <upright_sprite: [combine:48x48:0,-192=ontime_clocks_needle_h48.png:0,-0=ontime_clocks_needle_m48.png^[colorize:#FF0>: sum=2
2020-06-10 09:24:50: INFO[Main]:   cmd 0 (AO_CMD_SET_PROPERTIES) count 1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 1
2020-06-10 09:24:50: INFO[Main]: <upright_sprite: [combine:48x48:0,-192=ontime_clocks_needle_h48.png:0,-48=ontime_clocks_needle_m48.png^[colorize:#FF0>: sum=1
2020-06-10 09:24:50: INFO[Main]:   cmd 1 (AO_CMD_UPDATE_POSITION) count 1
2020-06-10 09:24:50: INFO[Main]: Local player: sum=27
2020-06-10 09:24:50: INFO[Main]:   cmd 9 (AO_CMD_SET_PHYSICS_OVERRIDE) count 27
May I ask, why it is a problem of more or less than 20 packets when standing still, while I had no adverse effects at 150+ ? How many can the client take on before it goes awry?
Whatever I say is CC0

sfan5
Moderator
Posts: 4094
Joined: Wed Aug 24, 2011 09:44
GitHub: sfan5
IRC: sfan5
Location: Germany

Re: Partially out of sync client. What do?

by sfan5 » Post

Bastrabun wrote:
Wed Jun 10, 2020 08:53
Particles:
I assume I found one of the culprits, "weather_pack" after going through all the mods that spawn particles (). After I disabled it, the particles dropped by a lot. I took a look at the mod, where it spawns the particles and had no idea why it would have so many particles around even when there was no weather at all. Aren't particles supposed to ... go away with time and not send over and over again? Other than that I cannot explain so many particles even when there are none onscreen. Maybe someone else can make some sense of it, here's where I got the mod from: https://gitlab.com/zombiebot/weather_pack
I tested this in singleplayer could reproduce the high particle counts when enabling any weather (e.g. snow).
The reason is that the mod spawns every snow particle individually instead of using particlespawners.
Bastrabun wrote:
Wed Jun 10, 2020 08:53
Hud: [...]

Physics: [...]
Honestly I just mentioned these for completeness, you do not have to worry about the packet counts and investigate these.
Bastrabun wrote:
Wed Jun 10, 2020 08:53
May I ask, why it is a problem of more or less than 20 packets when standing still, while I had no adverse effects at 150+ ? How many can the client take on before it goes awry?
There is no hard limit of ~20, 150 or anything similar, the client can handle hundreds of packets per second just fine. However high packet counts are an indirect indicator for possible issues.

The network stack delivers all* packets in order and without losing them.
As it is the case on the internet, sometimes packets get lost and newer packets cannot be processed until it arrives. It takes some time for the packet to get resent and if in the meantime there are e.g. 300 new packets** in the queue, each of them needs to get delivered too.
While I haven't debugged this, my suspicion is that the the network stack never manages to catch up with packet delivery and you then get a permanent one-sided (server -> client) network desync.

* For e.g. position updates (AO_CMD_UPDATE_POSITION) this whole issue is avoided by allowing out-of-order & unreliable delivery. The idea is that if a position update is lost a new one will come soon and compensate it.
** Temporary spikes are not a problem, but a constant spam of packets poses a problem.
Mods: Mesecons | WorldEdit | Nuke & Minetest builds for Windows (32-bit & 64-bit)

Bastrabun
Member
Posts: 211
Joined: Mon Nov 04, 2019 19:48

Re: Partially out of sync client. What do?

by Bastrabun » Post

You may be right, I have a boatload of messages like this one in the logs, while the package count looked more reasonable:

2020-07-01 03:52:30: INFO[Main]: Client packetcounter (30s): sum=443 avg=14.7667/s

2020-07-01 03:52:32: VERBOSE[ConnectionSend]: con(14/14)RE-SENDING timed-out RELIABLE to 1234:5678:9012:3456::1(t/o=0.132): from_peer_id=14, channel=0, seqnum=129
[...]
2020-07-01 03:53:28: VERBOSE[ConnectionSend]: con(14/14)RE-SENDING timed-out RELIABLE to 1234:5678:9012:3456::1(t/o=0.132): from_peer_id=14, channel=0, seqnum=135
[...]
2020-07-01 03:53:30: VERBOSE[ConnectionSend]: con(14/14)RE-SENDING timed-out RELIABLE to 1234:5678:9012:3456::1(t/o=0.132): from_peer_id=14, channel=2, seqnum=906

Starting line 95296 and ending line 104146, which means ~8850 messages like these and then disconnect due to timeout. Is there anything I can do to get the packages back in line?
Whatever I say is CC0

Post Reply

Who is online

Users browsing this forum: No registered users and 4 guests