dendy icon indicating copy to clipboard operation
dendy copied to clipboard
verified publisher icon maxpoletaev

Speed difference causes desync

Open matthewperiut opened this issue 1 year ago • 11 comments

I tried running and connecting with a macos server and a windows client compiled from latest source as of this comment. It works windows to windows and mac to mac, but across operating systems something seems to not work?

goroutine 1 [running, locked to thread]:
github.com/maxpoletaev/dendy/netplay.(*Netplay).handleMessage(0xc0000ca0e0?, {0x0, 0x0, 0x4000000, {{0x0, 0x0, 0x0}, 0x0}})
        C:/Users/matthewperiut/Documents/dendy/netplay/handlers.go:30 +0x24e
github.com/maxpoletaev/dendy/netplay.(*Netplay).HandleMessages(0xc0000ca0e0)
        C:/Users/matthewperiut/Documents/dendy/netplay/netplay.go:138 +0xe5
main.runAsClient({0xf17488, 0xc000064708}, 0xc0000000c0, 0xc00017e000)
        C:/Users/matthewperiut/Documents/dendy/cmd/dendy/client.go:167 +0xad1
main.main()
        C:/Users/matthewperiut/Documents/dendy/cmd/dendy/main.go:169 +0xae5
        ```

matthewperiut avatar Dec 02 '24 11:12 matthewperiut

Interesting - I'm honestly surprised it works at all! 😄 I've only tested it once in a cross-OS setup with mac-to-linux and it worked fine. Would you happen to have the full stacktrace? The snippet you attached only shows the state of one goroutine, but it is not possible to tell where exactly it failed.

maxpoletaev avatar Dec 02 '24 11:12 maxpoletaev

I looked more closely - line handlers.go:30 refers to an unknown message type being received by one of the sides. Strange. I don't have access to a Windows machine, so I could use some help

  • Does this happen 100% of the time when you run it?
  • Are you playing over a local network or the internet?
  • Are you connecting peers directly or through the relay server?​​​​​​​​​​​​​​​​

maxpoletaev avatar Dec 02 '24 18:12 maxpoletaev

I'm trying to run my copy of micromages, and I wanted to hop on with a couple buddies. I downloaded the latest built binary and tried running it. I was on MacOS, Dany was on Windows, and Tel was on Linux. Tel's Linux copy was crashing when connecting to the macos server (directly, port forwarding) plus micro mages had nasty bugs with the emulator.

I tried cloning and compiling and that fixed emulation issues, but now connecting seems to not be working. I set up a relay server on my home server, and even there the same issue was happening, but ultimately I think specifically on windows there is an issue in the net code.

I'm going to test quickly connecting on the latest build between linux and macos to confirm. This occurs on the local network too between two windows machines, as well as over the internet between two windows machines.

matthewperiut avatar Dec 02 '24 21:12 matthewperiut

Additionally weirdly enough, between the same machine using 127.0.0.1 (loopback) it works on windows.

matthewperiut avatar Dec 02 '24 21:12 matthewperiut

It totally works between linux and macos, meanwhile any user trying to join on the game on windows has the error log, once I boot back into windows I'll copy the entire log.

matthewperiut avatar Dec 02 '24 22:12 matthewperiut

shock, it happened here too, I believe it has to do with the save file that is made

[matthewperiut@arch bin]$ ./dendy -connect="192.168.1.159:5555" -nocrt ./mm.nes 
 ____                 _
|  _ \  ___ _ __   __| |_   _
| | | |/ _ \ '_ \ / _` | | | |
| |_| |  __/ | | | (_| | |_| |
|____/ \___|_| |_|\__,_|\__, |
                        |___/
[INFO] loading rom file: ./mm.nes
[INFO] loaded rom: mapper:0 crc32:4E6B9078
[INFO] starting client mode
INFO: AUDIO: Device initialized successfully
INFO:     > Backend:       miniaudio / PulseAudio
INFO:     > Format:        32-bit IEEE Floating Point -> 16-bit Signed Integer
INFO:     > Channels:      2 -> 2
INFO:     > Sample rate:   48000 -> 48000
INFO:     > Periods size:  3600
INFO: STREAM: Initialized successfully (44100 Hz, 32 bit, Mono)
[INFO] connecting to 192.168.1.159:5555 (tcp)...
[INFO] connected to server: 192.168.1.159:5555
[INFO] starting game...
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
panic: failed to restore checkpoint: saved state mismatch (probably different roms)

goroutine 1 [running, locked to thread]:
github.com/maxpoletaev/dendy/netplay.(*Game).rollback(0xc0000aeb60, 0xc0001120c0)
	/home/matthewperiut/Documents/dendy/netplay/game.go:247 +0xb3
github.com/maxpoletaev/dendy/netplay.(*Game).processDelayedInput(0xc0000aeb60, {0x758c20?, 0xc0ff41a060?, 0x9f5040?})
	/home/matthewperiut/Documents/dendy/netplay/game.go:340 +0x10d
github.com/maxpoletaev/dendy/netplay.(*Game).RunFrame(0xc0000aeb60, {0x0?, 0x0?, 0x9f5040?})
	/home/matthewperiut/Documents/dendy/netplay/game.go:220 +0x31
github.com/maxpoletaev/dendy/netplay.(*Netplay).RunFrame(0xc0000c21c0, {0xc000200000?, 0x132d587c?, 0x9f5040?})
	/home/matthewperiut/Documents/dendy/netplay/netplay.go:189 +0x25
main.runAsClient({0x800d88, 0xc00006a0c8}, 0xc0000000c0, 0xc0000d4000)
	/home/matthewperiut/Documents/dendy/cmd/dendy/client.go:168 +0xaf6
main.main()
	/home/matthewperiut/Documents/dendy/cmd/dendy/main.go:169 +0xae5

matthewperiut avatar Dec 02 '24 22:12 matthewperiut

Yeah... I'm not really sure it worked at least once

[matthewperiut@arch bin]$ ./dendy -connect="192.168.1.159:5555" -nocrt ./mm.nes 
 ____                 _
|  _ \  ___ _ __   __| |_   _
| | | |/ _ \ '_ \ / _` | | | |
| |_| |  __/ | | | (_| | |_| |
|____/ \___|_| |_|\__,_|\__, |
                        |___/
[INFO] loading rom file: ./mm.nes
[INFO] loaded rom: mapper:0 crc32:4E6B9078
[INFO] starting client mode
INFO: AUDIO: Device initialized successfully
INFO:     > Backend:       miniaudio / PulseAudio
INFO:     > Format:        32-bit IEEE Floating Point -> 16-bit Signed Integer
INFO:     > Channels:      2 -> 2
INFO:     > Sample rate:   48000 -> 48000
INFO:     > Periods size:  3600
INFO: STREAM: Initialized successfully (44100 Hz, 32 bit, Mono)
[INFO] connecting to 192.168.1.159:5555 (tcp)...
[INFO] connected to server: 192.168.1.159:5555
[INFO] starting game...
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[WARN] recv buffer is full, blocking
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
[INFO] dropping message from old generation: 0
panic: unknown message type: 0

goroutine 1 [running, locked to thread]:
github.com/maxpoletaev/dendy/netplay.(*Netplay).handleMessage(0xc0001481c0?, {0x0, 0x24000000, 0x9557fd, {{0x0, 0x0, 0x0}, 0x0}})
	/home/matthewperiut/Documents/dendy/netplay/handlers.go:30 +0x24e
github.com/maxpoletaev/dendy/netplay.(*Netplay).HandleMessages(0xc0001481c0)
	/home/matthewperiut/Documents/dendy/netplay/netplay.go:138 +0xe5
main.runAsClient({0x800d88, 0xc0001240c0}, 0xc000150000, 0xc000164000)
	/home/matthewperiut/Documents/dendy/cmd/dendy/client.go:167 +0xad7
main.main()
	/home/matthewperiut/Documents/dendy/cmd/dendy/main.go:169 +0xae5

(macos server, linux client)

matthewperiut avatar Dec 02 '24 22:12 matthewperiut

I removed the panic code to see what was going on, and turns out that for some reason the game can run at extremely high FPS on one of them, and the other runs at a different FPS, and they run at different speeds, which causes the state to differ greatly.

matthewperiut avatar Dec 05 '24 03:12 matthewperiut

Ok, it may not be refresh rate, but its some sort of function of speed that is messing up, here's my demo video (removed panic from code)

https://github.com/user-attachments/assets/f4df6327-4784-40fb-b54e-2c390fc5ffc3

matthewperiut avatar Dec 05 '24 03:12 matthewperiut

I just tested and it isn't exclusive to this game, it also occurs in super mario bros. Note that when playing on singleplayer on the emulator the speed works, additionally the issue persists regardless of refresh rate.

https://github.com/user-attachments/assets/153094d9-48b6-486e-a550-56ce2461e814

matthewperiut avatar Dec 05 '24 03:12 matthewperiut

Oh, that's a good clue! Something must be off with the lag compensation code. Thanks for the provided info (and the vids) - really appreciate it! I'll take a closer look today

maxpoletaev avatar Dec 05 '24 06:12 maxpoletaev