MantisBT - Zandronum
View Issue Details
0003132Zandronum[All Projects] Bugpublic2017-05-10 16:042018-09-30 21:43
Cutman 
Torr Samaho 
urgentmajorrandom
closedfixed 
3.0-beta 
3.03.0 
0003132: P_PlayerThink errors on map change
We've been getting a lot of P_PlayerThink errors when a new map begins in MM8BDM. It used to happen before but very infrequently and usually when additional mods were run, but now it's happening way more than usual with even less players.

Trying to pinpint the issue is a pain. I've been slowly taking 8bdm apart to see what the problem is. I axed the scripts, DECORATE, skins, everything until just the maps remained, and even now I'm not sure if they are what is causing the bug.

It seems to happen always if you have a ton of bots on the server and change to a map (see the custom one below, it's UDMF and has no scripts). Hopefully reproducing this with bots is enough to figure out what is going on.
1. Download the wad. Host a server MAP01, deathmatch. No fraglimit yet.
2. Join the server, add a ton of bots. I'm talking like 50+. A lot of telefragging will be going on in MAP01 but don't worry about that.
3. Set the fraglimit to 1. SOMEONE will get it, and the game will start transitioning to MAP02 (the wad replaces MAP02 with a new empty map with DM starts).
4. When MAP02 starts you should get a flood of P_PlayerThink errors.
I must stress that this is not just happening with bots. With around 6 players in our 8BDM beta build it happens after every map change, even after taking out DECORATE and ACS.
No tags attached.
? unnamedtest.wad (31,696) 2017-05-10 16:04
https://zandronum.com/tracker/file_download.php?file_id=2107&type=bug
? cvartest.wad (3,688) 2017-05-11 22:34
https://zandronum.com/tracker/file_download.php?file_id=2109&type=bug
Issue History
2017-05-10 16:04CutmanNew Issue
2017-05-10 16:04CutmanFile Added: unnamedtest.wad
2017-05-11 01:30jdagenetNote Added: 0017620
2017-05-11 02:37EnsaladaDeTomateNote Added: 0017621
2017-05-11 02:48EnsaladaDeTomateNote Edited: 0017621bug_revision_view_page.php?bugnote_id=17621#r10581
2017-05-11 04:17jdagenetNote Added: 0017622
2017-05-11 10:59CutmanNote Added: 0017624
2017-05-11 18:29CutmanNote Added: 0017626
2017-05-11 18:30CutmanNote Edited: 0017626bug_revision_view_page.php?bugnote_id=17626#r10585
2017-05-11 22:01jdagenetNote Added: 0017627
2017-05-11 22:34WaTaKiDFile Added: cvartest.wad
2017-05-13 10:27Torr SamahoNote Added: 0017633
2017-05-13 10:28Torr SamahoAssigned To => Torr Samaho
2017-05-13 10:28Torr SamahoStatusnew => feedback
2017-05-13 10:28Torr SamahoTarget Version => 3.0
2017-05-13 10:46CutmanNote Added: 0017634
2017-05-13 10:46CutmanStatusfeedback => assigned
2017-05-13 10:52Torr SamahoNote Added: 0017635
2017-05-13 10:52Torr SamahoStatusassigned => feedback
2017-05-13 11:13CutmanNote Added: 0017637
2017-05-13 11:13CutmanStatusfeedback => assigned
2017-05-13 11:18Torr SamahoNote Added: 0017639
2017-05-13 11:21CutmanNote Added: 0017640
2017-05-13 11:32CutmanNote Added: 0017641
2017-05-13 12:36Torr SamahoNote Added: 0017643
2017-05-13 12:47CutmanNote Added: 0017645
2017-05-13 12:49CutmanNote Edited: 0017645bug_revision_view_page.php?bugnote_id=17645#r10592
2017-05-13 12:56CutmanNote Added: 0017647
2017-05-13 13:00Torr SamahoNote Added: 0017648
2017-05-13 14:43Torr SamahoNote Added: 0017650
2017-05-13 14:43Torr SamahoStatusassigned => needs testing
2017-05-13 14:49CutmanNote Added: 0017651
2017-05-13 14:56Torr SamahoNote Added: 0017653
2017-05-13 15:00CutmanNote Added: 0017654
2017-05-13 20:26Ru5tK1ngNote Added: 0017658
2017-05-13 20:26Ru5tK1ngStatusneeds testing => resolved
2017-05-13 20:26Ru5tK1ngResolutionopen => fixed
2017-05-13 20:26Ru5tK1ngFixed in Version => 3.0
2017-05-24 19:16CutmanNote Added: 0017756
2017-05-24 19:16CutmanStatusresolved => feedback
2017-05-24 19:16CutmanResolutionfixed => reopened
2017-05-24 19:29CutmanNote Edited: 0017756bug_revision_view_page.php?bugnote_id=17756#r10651
2017-05-24 19:30CutmanNote Edited: 0017756bug_revision_view_page.php?bugnote_id=17756#r10652
2017-05-25 01:17Ru5tK1ngNote Added: 0017757
2017-05-25 01:29CutmanNote Added: 0017758
2017-05-25 01:29CutmanStatusfeedback => assigned
2017-05-25 02:30Ru5tK1ngNote Added: 0017759
2017-05-25 02:43Ru5tK1ngNote Edited: 0017759bug_revision_view_page.php?rev_id=10654
2017-05-25 02:46Ru5tK1ngNote Deleted: 0017759
2017-05-25 19:37CutmanNote Added: 0017761
2017-05-25 20:45Ru5tK1ngNote Added: 0017762
2017-05-25 21:02CutmanNote Added: 0017763
2017-05-25 22:24Ru5tK1ngNote Added: 0017764
2017-05-27 09:16Torr SamahoNote Added: 0017767
2017-05-28 13:45Torr SamahoNote Added: 0017773
2017-05-28 16:09CutmanNote Added: 0017777
2017-06-05 00:09Ru5tK1ngNote Added: 0017799
2017-06-05 00:10Ru5tK1ngStatusassigned => needs testing
2017-06-06 16:49CutmanNote Added: 0017804
2017-06-06 18:43Torr SamahoNote Added: 0017805
2017-06-08 19:40DuskNote Added: 0017809
2017-06-08 19:40DuskNote Edited: 0017809bug_revision_view_page.php?bugnote_id=17809#r10676
2017-06-08 20:09CutmanNote Added: 0017810
2017-06-18 16:59Torr SamahoNote Added: 0017837
2017-06-22 02:47CutmanNote Added: 0017865
2017-06-22 06:07Torr SamahoNote Added: 0017867
2017-06-22 13:37CutmanNote Added: 0017871
2017-06-22 16:26Ru5tK1ngNote Added: 0017874
2017-06-22 17:25CutmanNote Added: 0017875
2017-06-24 13:05Torr SamahoNote Added: 0017893
2017-06-24 13:10CutmanNote Added: 0017894
2017-06-24 14:36Torr SamahoNote Added: 0017895
2017-06-24 14:48CutmanNote Added: 0017896
2017-06-24 15:02CutmanNote Added: 0017897
2017-06-24 17:41Torr SamahoNote Added: 0017899
2017-06-24 18:44CutmanNote Added: 0017900
2017-06-25 07:31Torr SamahoNote Added: 0017903
2017-06-25 17:37CutmanNote Added: 0017921
2017-06-25 20:09Torr SamahoNote Added: 0017928
2017-06-30 23:33Ru5tK1ngNote Added: 0017956
2017-06-30 23:33Ru5tK1ngStatusneeds testing => resolved
2017-06-30 23:33Ru5tK1ngResolutionreopened => fixed
2018-09-30 21:43Blzut3Statusresolved => closed

Notes
(0017620)
jdagenet   
2017-05-11 01:30   
I'm unable to reproduce this.
(0017621)
EnsaladaDeTomate   
2017-05-11 02:37   
(edited on: 2017-05-11 02:48)
I think this one is related to this aswell:'https://zandronum.com/tracker/view.php?id=2552 [^]'

(0017622)
jdagenet   
2017-05-11 04:17   
From reading that ticket it appears the problem was fixed at one point but resurfaced.
I find it strange that Cutman is able to reproduce it using the steps above but I get nothing. Makes me think it's something specific like the ini or maybe something else.
(0017624)
Cutman   
2017-05-11 10:59   
I just tried again using a fresh Zandronum folder and ini file. This time I managed to get it to happen by just doing changemap map01 in coop while the bots were in the game, didn't even need the wad file.

'http://imgur.com/a/J3Kd0 [^]'
(0017626)
Cutman   
2017-05-11 18:29   
(edited on: 2017-05-11 18:30)
FINALLY I found the culprit: CVARINFO. My trial and error had me stripping mm8bdm until there were only a few lumps left, but the bug went away when I took CVARINFO out of the pk3. I tried putting the lump on it's own into a wad for Doom2 and what do you know, the bug happened. Don't need bots this time (the bot issue may be unrelated).

'http://cutstuff.net/public/cvartest.wad [^]'

1. Download the file. Run Doom2 with it just to make sure the cvars enter the ini file (not sure if required).
2. Host a deathmatch server with cvartest.wad. Then have 6+ clients join the game (can be from your own machine).
3. Set the fraglimit to 1 and get a kill (or use changemap map02 on the server console).
4. The map will change and you should see some p_playerthink errors on one/some of your clients.

I am not sure if a specific custom cvar is causing the issue or if it's because there's a ton of them in this CVARINFO lump. Hopefully you guys can figure that out!

(0017627)
jdagenet   
2017-05-11 22:01   
Upon further testing, it appears that the number of CVARs in the CVARINFO lump contributes to the issue, not any one specific CVAR.

I doubt the type of CVAR has anything to do with it, the issue triggered for me using 68 "user int" type CVARs.
(0017633)
Torr Samaho   
2017-05-13 10:27   
I can't reproduce the problem under Windows with six local clients and a server started with
zandronum -file cvartest.wad -host +deathmatch 1 -nomonsters +fraglimit 1

Any other ideas how to reproduce this?
(0017634)
Cutman   
2017-05-13 10:46   
I was using: zandronum -deathmatch 1 -host 64 -file cvartest.wad

And changed the fraglimit in the server window, though that probably doesn't matter.

Here is the ini file I was using for both the server host and clients (started off as a blank one)'https://hastebin.com/utodewired.makefile [^]'
(0017635)
Torr Samaho   
2017-05-13 10:52   
No, even with that ini and changing the fraglimit in the server window, I can't reproduce the problem here with six local clients. Which Zandronum binary did you use?
(0017637)
Cutman   
2017-05-13 11:13   
The version number on the console is "v3.0-alpha (2.8pre-441-g458e1b1) 170416-0710", should be the same windows build listed on the website:'http://zandronum.com/downloads/testing/3.0/ZandroDev3.0-170416-0710windows.zip [^]'
(0017639)
Torr Samaho   
2017-05-13 11:18   
I can't reproduce the problem with that version either. Does it happen every time or do you need to try more than once? 0003132:0017626 sounds like it should happen always on at least on of the clients.
(0017640)
Cutman   
2017-05-13 11:21   
Yeah it happens every time for me, every client is getting some form of playerthink error. I'll upload a video of the whole process, maybe that will help.
(0017641)
Cutman   
2017-05-13 11:32   
'https://www.youtube.com/watch?v=C-hMyKCECi8 [^]' ignore the steps setting my max allowed ip addresses, that was just something I forgot after resetting my ini again.
(0017643)
Torr Samaho   
2017-05-13 12:36   
Still works fine for me, but I'm beginning to think that this has nothing to do with CVARINFO in particular, but is related to full updates that need more than one packet, which will happen for sure with the amount of user cvars you have, in combination with packet loss, which doesn't seem to happen on my machine under these circumstances, but may happen on your machine. Can you start one of the six clients with the extra option -debugfile and upload the resulting file "debug0.txt", which the client creates? Please also record a client side demo. Hopefully, the issue is reproducible when playing the demo.

On a side note, the problem in the video looks like only a cosmetic issue, i.e. you have a very short one time burst of warnings after a map change. The gameplay doesn't seem to be affected here since the warnings stop immediately.
(0017645)
Cutman   
2017-05-13 12:47   
(edited on: 2017-05-13 12:49)
Sure, but it's kinda ugly and happens every game. You might only get one bug report about this but fixing this will prevent me from getting tons of them later ;)

'https://hastebin.com/nosarapaqu.sql [^]'

Here's the debug file while I repeated the same process in the video.

Edit: Oops forgot the demo. Lemmie try that again.

(0017647)
Cutman   
2017-05-13 12:56   
'https://hastebin.com/vunomakuse.sql [^]'

'http://cutstuff.net/public/NEWDEMO.lmp [^]'
(0017648)
Torr Samaho   
2017-05-13 13:00   
Yeah, your debug file confirms that you have missing packets, so it's likely related to them. With your demo I also get the error messages. So this should be enough for me to investigate further what's happening.
(0017650)
Torr Samaho   
2017-05-13 14:43   
The error messages that could occur after a map change before the full snapshot was received should be fixed now.
(0017651)
Cutman   
2017-05-13 14:49   
If you need me specifically to test it, please provide a build.
(0017653)
Torr Samaho   
2017-05-13 14:56   
Here is a binary with the fix. Please check if it fixes the issue for you.
(0017654)
Cutman   
2017-05-13 15:00   
Testing using the same method, no error messages popped up on any of the clients. Seems to be fixed!
(0017658)
Ru5tK1ng   
2017-05-13 20:26   
Thanks for testing. Reopen if needed in the future.
(0017756)
Cutman   
2017-05-24 19:16   
(edited on: 2017-05-24 19:30)
We're not out of the woods yet I'm afraid, another related issue has popped up. Still related to CVARINFO or at least whatever CVARINFO is doing to cause it.

Some players cannot join servers correctly if other players are in the server (works fine for them if the server is empty). They get stuck on the console, can hear music but no gameplay happens their end. This only happens when this CVARINFO is loaded. Other players see them as live and in game and can even be killed (if auto join is enabled). This is what the user sees:'http://i.imgur.com/EX7pqkx.png [^]'

I went ahead and got them to test the build posted above too. Still no good. I hosted a server with the build, joined myself and had them join. They had the issue and recorded a demo file + used debugfile. Here are the results:

cvartest wad (NOTE: Changed slightly from the attached file):'http://cutstuff.net/public/cvartest.wad [^]'

debugfile:'https://pastebin.com/raw/HsjmauHx [^]'

demo file:'http://cutstuff.net/public/clausdemo.lmp [^]'

This is happening to handful of players, and should be looked into before the next public zandronum build.

Edit: If they join the server with zero players, then other players join in, they will get stuck on map change.

(0017757)
Ru5tK1ng   
2017-05-25 01:17   
So this new issue didn't occur until after torr fixed the P_PlayerThink errors? Or were you using an older build when it came up?
(0017758)
Cutman   
2017-05-25 01:29   
It happens in both the current public 3.0 build and the one Torr posted.
(0017761)
Cutman   
2017-05-25 19:37   
We tested older Zandronum builds too. It was fine up until this one, 170205-2117 'http://zandronum.com/downloads/testing/3.0/ZandroDev3.0-170205-2117windows.zip [^]'

By the way when I said a handful of people, that number is actually increasing a lot since 8bdm's new version release. I highly recommend a new zandronum build after getting to the bottom of this, as long as there's nothing else urgent that needs looking at.
(0017762)
Ru5tK1ng   
2017-05-25 20:45   
Can you try this build provided by watakid:'https://www.dropbox.com/s/85ze5s41su013gf/zandronum-3.0-r170122-1540-1fde0c6-windows.zip?dl=0 [^]'
(0017763)
Cutman   
2017-05-25 21:02   
Tested, it is working fine in that build.
(0017764)
Ru5tK1ng   
2017-05-25 22:24   
Then as suspected by wata and myself, the culprit is most likely:'https://bitbucket.org/Torr_Samaho/zandronum/commits/a8335806821b23c1d8565211a6e622d5b59918d2 [^]'
(0017767)
Torr Samaho   
2017-05-27 09:16   
I think I know what's happening: SERVERCOMMANDS_SetAllPlayerUserInfo and SERVERCOMMANDS_SetPlayerUserInfo are putting all information into one network packet, even if this leads to packets that exceeded the sv_maxpacketsize. We'll have to split this over multiple packets.
(0017773)
Torr Samaho   
2017-05-28 13:45   
Can you check if this fixes the issue?
(0017777)
Cutman   
2017-05-28 16:09   
That fixed it! Tested with LMS (round resetting) and map switching to make sure they could always get in.
(0017799)
Ru5tK1ng   
2017-06-05 00:09   
The following commits for that build were added:
'https://bitbucket.org/Torr_Samaho/zandronum/commits/19d89d1637b1c2965ca08b9370efe64aa01c9cce [^]'
'https://bitbucket.org/Torr_Samaho/zandronum/commits/beaf2601443cd83710fefe324a4ec97242e373e8 [^]'
'https://bitbucket.org/Torr_Samaho/zandronum/commits/befdc069426aa69a65f170f261c6591c38d51660 [^]'
(0017804)
Cutman   
2017-06-06 16:49   
Cool, hope you guys can get a new public build up soon. A lot of players (I've counted 8 so far) cannot play the game while this is happening. It sucks cause a lot of those CVARs aren't even used in multiplayer, and it's not like I can release a small patch wad file to remove them (as far as I know?)
(0017805)
Torr Samaho   
2017-06-06 18:43   
If you don't need the values in multiplayer, you could convert them to server cvars. With a user cvar, you have one separate value for each player. Unless you need that, you should be able to use server cvars.

The next build is planned as soon as we have taken care of 0003124.
(0017809)
Dusk   
2017-06-08 19:40   
Nice catch! I took and gave this one a bit of a refactor because I suspect that the math in that commit is going to break sometime.

'https://bitbucket.org/zandronum/zandronum-sandbox/commits/89336095880a6a47c1f9d67fd14df0deb68d6ce3 [^]'
'https://bitbucket.org/zandronum/zandronum-sandbox/commits/a7641eb196f015e2aa39b625ecc50fe546c0177f [^]'
'https://bitbucket.org/zandronum/zandronum-sandbox/commits/3c091d308689a477b14750c98cde13d1de09820a [^]'
'https://bitbucket.org/zandronum/zandronum-sandbox/commits/206242baeacd5c3638080086e452b4301fe8d8a8 [^]'

I gave this a run with a cvarinfo with 500 cvars and it appears to still work as intended. Can someone confirm?

(0017810)
Cutman   
2017-06-08 20:09   
Drop me a build if you would like me to test with the people who suffer with this issue.
(0017837)
Torr Samaho   
2017-06-18 16:59   
Dusk, thanks! I added your patches.
(0017865)
Cutman   
2017-06-22 02:47   
Sorry to be the bearer of bad news again but someone else is now having connection issues with 8bdm v5b with the latest public zandronum build (170618-1927). I had him test the cvartest.wad and as expected the culprit is the cvarinfo stuff. There is a difference here though, he truly just gets stuck in the requesting snapshot screen and doesn't even appear in game my end or hear music while in the console etc. In my server log I get the following message "Connect (v3.0-alpha): 24.3.40.196:10667
Unfinished connection from 24.3.40.196:10667 timed out."

I got him to do a logfile, not sure if it shows much information:'https://hastebin.com/ixoripaqiy.go [^]'
(0017867)
Torr Samaho   
2017-06-22 06:07   
Was this any better in the older build I posted, i.e. #17773? What is the value of sv_maxpacketsize on the server?
(0017871)
Cutman   
2017-06-22 13:37   
Sorry could you link that build again? sv_maxpacketsize was 1024 on the servers tested (both mine and TSPG servers)
(0017874)
Ru5tK1ng   
2017-06-22 16:26   
He means this build: 'http://www.mediafire.com/file/k77lwk52s55q5fm/ZandroDev3.0-LargeUserinfoFixTest.7z [^]'
(0017875)
Cutman   
2017-06-22 17:25   
We tried that build and the same issue happens, stuck on getting snapshot.
(0017893)
Torr Samaho   
2017-06-24 13:05   
And the problem with getting stuck at the snapshot happens with just cvartest.wad loaded (no other mods, doom2.wad as IWAD, map01) and vanishes if cvartest.wad is not loaded?
(0017894)
Cutman   
2017-06-24 13:10   
Yes, with vanilla Doom2 MAP01 he was able to connect fine. Including the wad he gets stuck at the snapshot.

Interestingly if the server hosted with the cvartest WAD and he didn't launch with it, it actually allowed him to connect and play just fine.
(0017895)
Torr Samaho   
2017-06-24 14:36   
Is his console just repeatedly saying "Authenticating level..." when he is stuck? Does it always happen or does it work sometimes? No other players need to be in the server to get stuck?
(0017896)
Cutman   
2017-06-24 14:48   
His console just says "Requesting Snapshot" endlessly. It works sometimes when the server is empty, but not always. If I was in the server at the time he couldn't ever connect while he was running the wad.
(0017897)
Cutman   
2017-06-24 15:02   
Quick update, two people are still having the issue still. The other person is the one who submitted ticket 0003069 as is most likely the same issue as that one.

'https://puu.sh/wt3Jw/a1b993a26c.png [^]'
(0017899)
Torr Samaho   
2017-06-24 17:41   
Turned out that there were problems with packet loss while joining the server. Please test if this fixes the issue.
(0017900)
Cutman   
2017-06-24 18:44   
It didn't. Same snapshot issue and "Unfinished connection from 24.3.40.196:10667 timed out." on my server.
(0017903)
Torr Samaho   
2017-06-25 07:31   
I found another issue. The client was still sending too large packets. Please check if this fixes the issue.
(0017921)
Cutman   
2017-06-25 17:37   
That fixed it, tested with both parties! They were able to connect properly. I also notice the server console got flooded with a bunch of CVARs and playerinfo.
(0017928)
Torr Samaho   
2017-06-25 20:09   
I'm glad to hear that it works! And sorry about the console flood. I added debug output to check whether the packet splitting still transfers the full user info.
(0017956)
Ru5tK1ng   
2017-06-30 23:33   
I spoke with cutman and he hasn't heard of any issues with his playerbase. I'll mark this as resolved, hopefully for good.