alttpo / sni

SNES Interface with gRPC API
MIT License
46 stars 12 forks source link

Left alone for a while, SNI eats up RetroArch's port and gets stuck #9

Closed strotlog closed 2 years ago

strotlog commented 2 years ago

Repro steps: 1) Use SNI 2) Use SNI+RetroArch (not sure if required) 3) Leave SNI open, and RetroArch closed for several hours

SNI log:

2022/03/31 11:37:45.261946 retroarch: > VERSION
2022/03/31 11:37:45.337896 retroarch: detect: detector[0]: read udp 127.0.0.1:55346->127.0.0.1:55355: i/o timeout
2022/03/31 11:37:47.257316 retroarch: > VERSION
2022/03/31 11:37:47.332267 retroarch: detect: detector[0]: read udp 127.0.0.1:55347->127.0.0.1:55355: i/o timeout
2022/03/31 11:37:49.252733 retroarch: > VERSION
2022/03/31 11:37:49.328415 retroarch: detect: detector[0]: read udp 127.0.0.1:55348->127.0.0.1:55355: i/o timeout
2022/03/31 11:37:51.261325 retroarch: > VERSION
2022/03/31 11:37:51.336714 retroarch: detect: detector[0]: read udp 127.0.0.1:55349->127.0.0.1:55355: i/o timeout
2022/03/31 11:37:53.200460 retroarch: > VERSION
2022/03/31 11:37:53.271612 retroarch: detect: detector[0]: read udp 127.0.0.1:55350->127.0.0.1:55355: i/o timeout
2022/03/31 11:37:55.262420 retroarch: > VERSION
2022/03/31 11:37:55.337442 retroarch: detect: detector[0]: read udp 127.0.0.1:55351->127.0.0.1:55355: i/o timeout
2022/03/31 11:37:55.568016 usb2snes: 192.168.1.143:57548: client sent unexpected websocket frame opcode 0xa
2022/03/31 11:37:57.271204 retroarch: > VERSION
2022/03/31 11:37:57.345492 retroarch: detect: detector[0]: read udp 127.0.0.1:55352->127.0.0.1:55355: i/o timeout
2022/03/31 11:37:59.263482 retroarch: > VERSION
2022/03/31 11:37:59.338003 retroarch: detect: detector[0]: read udp 127.0.0.1:55353->127.0.0.1:55355: i/o timeout
2022/03/31 11:38:01.259643 retroarch: > VERSION
2022/03/31 11:38:01.336547 retroarch: detect: detector[0]: read udp 127.0.0.1:55354->127.0.0.1:55355: i/o timeout
2022/03/31 11:38:03.259278 retroarch: > VERSION
2022/03/31 11:38:03.260372 retroarch: < VERSION
2022/03/31 11:38:03.261289 retroarch: detect: detector[0]: expected integer

netstat shows SNI listening on UDP port 55355 from this point onwards. This port number must have been chosen next after 55354 as SNI's UDP source port.

SNI is stuck in this state.

Potentially this is even a bug in golang itself? I don't really know, but most programs would never want to accidentally talk to themselves when they say "connect me to localhost:port". Here, random source port 55355 == specified destination port on the same host. We end up with the UDP pipe localhost:55355 <=> localhost:55355.

SNI believes it's talking to RetroArch and consumes RetroArch's UDP port of 55355 indefinitely. Workaround is to restart SNI.

JamesDunne commented 2 years ago

Technically this is a bug in retroarch for picking a bad port number to listen on. 55355 in the dynamic range of ports (49152 to 65535) that clients are free to pick from to bind their receiving end to.

Perhaps this could be fixed by not using the bind() mechanism? I'll have to look into it.

strotlog commented 2 years ago

Repro rate data:

strotlog commented 2 years ago

For whatever reason, I've been experiencing this issue pretty quickly lately while making code tweaks. Today's SNI log shows that there were only 4 minutes 37 seconds between my closing RetroArch and SNI becoming unusable due to talking to itself on port 55355. I'll upgrade to the latest SNI version just in case.

JamesDunne commented 2 years ago

Alright I'll look into it

strotlog commented 2 years ago

New record: repro 59 seconds after the last good response from RetroArch. SNI 0.0.82 this time.

JamesDunne commented 2 years ago

Should be fixed in v0.0.84

strotlog commented 2 years ago

0.0.84 has gone 72 hours with no 'expected integer' self-talk error. Many thanks!