New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Fix: getaddrinfo/UDP blocking locks up whole game #9013
Conversation
Is this in addition to #9001, or instead of ? |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Assuming you tested this, looks good to me.
...rebase? :> |
I indeed tested it myself by introducing a sleep just before the getaddrinfo call, but it would be nice to get it tested by Berbe in the "broken" Docker environment we used for figuring out the cause of his problems. |
cc @Berbe for testing please :) |
…nd when another thread is busy do not attempt to process the packets of that socket
…ooting part of the documentation
ad4abda
to
e542423
Compare
I rebased this work onto Server advertisement happened while a client was connected without loss of connection. I guess @rubidium42's work did the trick (provided thorough tests are made). Good job! Excerpt of 1.11.0 & udp-blocking server's outputdbg: [net] Starting dedicated version 1.11.0
dbg: [net] [core] starting network...
dbg: [net] [udp] initializing listeners
dbg: [net] [core] network online, multiplayer available
dbg: [net] Detected broadcast addresses:
dbg: [net] 0) <IP #1>
[2021-04-11 21:11:04] OpenTTD Game Console Revision 7 - 1.11.0
[2021-04-11 21:11:04] ------------------------------------
[2021-04-11 21:11:04] use "help" for more information
[2021-04-11 21:11:04]
[2021-04-11 21:11:04] dbg: [net] [udp] closed listeners
[2021-04-11 21:11:04] dbg: [net] [udp] initializing listeners
[2021-04-11 21:11:04] dbg: [net] [udp] closed listeners
[2021-04-11 21:11:04] dbg: [net] [udp] initializing listeners
[2021-04-11 21:11:04] dbg: [net] starting listeners for clients
[2021-04-11 21:11:04] dbg: [net] [tcp] listening on IPv4 port 0.0.0.0:3982 (IPv4)
[2021-04-11 21:11:04] dbg: [net] [tcp] listening on IPv6 port [::]:3982 (IPv6)
[2021-04-11 21:11:04] dbg: [net] starting listeners for incoming server queries
[2021-04-11 21:11:04] dbg: [net] [udp] listening on IPv4 port 0.0.0.0:3982 (IPv4)
[2021-04-11 21:11:04] dbg: [net] [udp] listening on IPv6 port [::]:3982 (IPv6)
[2021-04-11 21:11:04] dbg: [net] [udp] advertising to master server
[2021-04-11 21:11:04] dbg: [net] [udp] listening on IPv4 port 0.0.0.0:0 (IPv4)
[2021-04-11 21:11:04] dbg: [net] [udp] listening on IPv6 port [::]:0 (IPv6)
[2021-04-11 21:11:05] dbg: [net] Generating map, please wait...
[2021-04-11 21:11:05] dbg: [net] Map generation percentage complete: 5
[2021-04-11 21:11:05] dbg: [net] Map generation percentage complete: 10
[2021-04-11 21:11:06] dbg: [net] Map generation percentage complete: 15
[2021-04-11 21:11:07] dbg: [net] Map generation percentage complete: 20
[2021-04-11 21:11:07] dbg: [net] Map generation percentage complete: 25
[2021-04-11 21:11:07] dbg: [net] Map generation percentage complete: 30
[2021-04-11 21:11:07] dbg: [net] Map generation percentage complete: 35
[2021-04-11 21:11:08] dbg: [net] Map generation percentage complete: 40
[2021-04-11 21:11:08] dbg: [net] Map generation percentage complete: 45
[2021-04-11 21:11:08] dbg: [net] Map generation percentage complete: 50
[2021-04-11 21:11:08] dbg: [net] Map generation percentage complete: 55
[2021-04-11 21:11:09] dbg: [net] Map generation percentage complete: 60
[2021-04-11 21:11:09] dbg: [net] Map generation percentage complete: 65
[2021-04-11 21:11:09] dbg: [net] Map generation percentage complete: 70
[2021-04-11 21:11:09] dbg: [net] Map generation percentage complete: 75
[2021-04-11 21:11:09] dbg: [net] Map generation percentage complete: 80
[2021-04-11 21:11:09] dbg: [net] Map generation percentage complete: 85
[2021-04-11 21:11:09] dbg: [net] Map generation percentage complete: 90
[2021-04-11 21:11:09] dbg: [net] getaddrinfo for hostname "master.openttd.org", port 3978, address family IPv4 and socket type tcp took 5 seconds
[2021-04-11 21:11:09] dbg: [net] this is likely an issue in the DNS name resolver's configuration causing it to time out
[2021-04-11 21:11:10] dbg: [net] Map generation percentage complete: 99
[2021-04-11 21:11:10] dbg: [net] Map generated, starting game
[2021-04-11 21:11:10] dbg: [net] Network revision name is '1.11.0'
[2021-04-11 21:11:10] *** Game paused (number of players)
[2021-04-11 21:11:11] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:11] dbg: [net] [server] Client connected from <IP #2> on frame 43
[2021-04-11 21:11:11] dbg: [net] Closed client connection 2
[2021-04-11 21:11:12] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:12] dbg: [net] [server] Client connected from <IP #2> on frame 77
[2021-04-11 21:11:13] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:14] *** Player has joined the game (Client #3)
[2021-04-11 21:11:14] *** Player has started a new company (#1)
[2021-04-11 21:11:14] *** Game unpaused (number of players)
[2021-04-11 21:11:14] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:14] dbg: [net] [udp] advertising to master server
[2021-04-11 21:11:15] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:16] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:17] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:18] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:19] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:20] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:20] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:21] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:22] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:23] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:24] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:24] dbg: [net] [udp] advertising to master server
[2021-04-11 21:11:24] dbg: [net] [udp] advertising to the master server is failing
[2021-04-11 21:11:24] dbg: [net] [udp] we are not receiving the session key from the server
[2021-04-11 21:11:25] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:26] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:27] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:28] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:29] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:29] dbg: [net] [udp] please allow udp packets from [master.openttd.org]:3978 to you to be delivered
[2021-04-11 21:11:29] dbg: [net] [udp] please allow udp packets from you to [master.openttd.org]:3978 to be delivered
[2021-04-11 21:11:30] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:31] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:32] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:33] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:34] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:35] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:36] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:37] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:38] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:39] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:40] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:41] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:42] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:43] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:44] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:44] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:11:45] dbg: [net] [udp] received new session key from master server (IPv4)
[2021-04-11 21:11:45] dbg: [net] [udp] received new session key from master server (IPv4)
[2021-04-11 21:11:45] dbg: [net] [udp] received new session key from master server (IPv6)
[2021-04-11 21:11:45] dbg: [net] [udp] received new session key from master server (IPv6)
[2021-04-11 21:11:45] dbg: [net] [udp] received new session key from master server (IPv6)
[2021-04-11 21:26:24] dbg: [net] [udp] advertising to master server
[2021-04-11 21:26:25] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:26] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:27] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:28] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:29] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:30] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:31] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:32] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:33] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:34] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:34] dbg: [net] [udp] advertising to master server
[2021-04-11 21:26:35] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:36] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:37] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:38] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:39] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:40] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:41] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:42] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:43] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:44] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:44] dbg: [net] [udp] advertising to master server
[2021-04-11 21:26:44] dbg: [net] [udp] advertising to the master server is failing
[2021-04-11 21:26:44] dbg: [net] [udp] we are not receiving the acknowledgement from the server
[2021-04-11 21:26:44] dbg: [net] [udp] this usually means that the master server cannot reach us
[2021-04-11 21:26:44] dbg: [net] [udp] please allow udp and tcp packets to port 3982 to be delivered
[2021-04-11 21:26:44] dbg: [net] [udp] please allow udp and tcp packets from port 3982 to be delivered
[2021-04-11 21:26:45] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:46] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:46] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:47] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:48] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:49] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:50] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:51] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:52] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:53] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:54] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:55] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:56] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:57] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:58] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:26:59] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:00] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:01] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:02] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:03] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:04] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:05] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:06] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:07] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:08] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:09] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:10] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:10] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:11] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:12] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:13] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:14] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:15] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:16] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:17] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:18] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:19] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:20] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:21] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:22] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:23] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:24] dbg: [net] [udp] Master background UDP loop processing appears to be blocked. Your OS may be low on UDP send buffers.
[2021-04-11 21:27:25] dbg: [net] [udp] advertising on master server successful (IPv4)
[2021-04-11 21:27:25] dbg: [net] [udp] advertising on master server successful (IPv4)
[2021-04-11 21:27:25] dbg: [net] [udp] advertising on master server successful (IPv4)
[2021-04-11 21:27:25] dbg: [net] [udp] advertising on master server successful (IPv6)
[2021-04-11 21:27:25] dbg: [net] [udp] advertising on master server successful (IPv6)
[2021-04-11 21:27:25] dbg: [net] [udp] advertising on master server successful (IPv6) |
Motivation / Problem
That getaddrinfo timing out/taking a long time for the advertising blocks the whole GameLoop. Consequently the server does not reply quickly enough to the master server for the advertising to sporadically fail, but more importantly other clients connected using UDP will be booted.
Description
Firstly nielsm's solution (see #9001) is taken, but with some (significant) changes.
Closes #9001
Fixes #8878
Limitations
Closing a server or unadvertising will still need to wait for the getaddrinfo resolving to complete, and actually it needs to wait until it has resolved for each socket it wants to send on. Similarly the unadvertise will still be blocky due to the same underlying getaddrinfo timeout.
Checklist for review
Some things are not automated, and forgotten often. This list is a reminder for the reviewers.