search

minetest / serverlist

The global Minetest server list server
GNU Lesser General Public License v2.1
52 stars 28 forks source link

Getting Apache mod_wsgi to work with `master-server` #38

Closed Tyler-2 closed 3 years ago

Tyler-2 commented 3 years ago

I have an instance of master-server running in Apache on a server at 192.168.10.2. My DNS server (also at 192.168.10.2) redirect requests for servers.minetest.net to `192.168.10.2.

My Minetest servers (Also running on 192.168.10.2) are able to register themselves at startup with the master server, and I see them in the server list. After 5 minutes, I can see them trying to update their server listing entry. However, they end up dropping off the list after the 350 seconds "stale" timer expires.

I've been unable to debug this and figure out the cause, and I've followed the code through to where finishRequestAsync is called... but I can't quite follow the object oriented bits.

I'm guessing that the removal of this from the server list has something to do with the IP... But I can't tell why.

sfan5 commented 3 years ago

I have an instance of master-server running in Apache on a server at 192.168.10.2.

With uwsgi as suggested in the README I assume?

After 5 minutes, I can see them trying to update their server listing entry

What exactly does "trying" here mean? Do they get a 202 status code? Do you see the connection check happening (maybe in the log)?

Tyler-2 commented 3 years ago

With uwsgi as suggested in the README I assume?

In Apache I'm using mod_wsgi, and a config that looks like this:

# cat /etc/apache2/sites-enabled/minetest-master.conf 
<VirtualHost *:80>

    ServerName servers.minetest.net
    ServerAlias servers.minetest.net
    ServerAdmin admin@admindomain.net

    DocumentRoot /var/games/minetest-server/master-server

    Alias /static /var/games/minetest-server/master-server/static

    LogLevel Debug 

    WSGIScriptAlias / /var/games/minetest-server/master-server/server.py
    WSGICallableObject app

    <Directory /var/games/minetest-server/master-server>
    <IfVersion < 2.4>
        Order allow,deny
        Allow from all
    </IfVersion>
    <IfVersion >= 2.4>
        Require all granted
    </IfVersion>
    </Directory>

</VirtualHost>

Trying as in... I see this at START:

==> /var/log/apache2/error.log <==
[Thu Jul 16 20:20:21.590346 2020] [authz_core:debug] [pid 8782:tid 2962183200] mod_authz_core.c(820): [client 192.168.10.2:51666] AH01626: authorization result of Require all granted: granted
[Thu Jul 16 20:20:21.590426 2020] [authz_core:debug] [pid 8782:tid 2962183200] mod_authz_core.c(820): [client 192.168.10.2:51666] AH01626: authorization result of <RequireAny>: granted
[Thu Jul 16 20:20:21.590534 2020] [authz_core:debug] [pid 8782:tid 2962183200] mod_authz_core.c(820): [client 192.168.10.2:51666] AH01626: authorization result of Require all granted: granted
[Thu Jul 16 20:20:21.590554 2020] [authz_core:debug] [pid 8782:tid 2962183200] mod_authz_core.c(820): [client 192.168.10.2:51666] AH01626: authorization result of <RequireAny>: granted
[Thu Jul 16 20:20:21.599636 2020] [wsgi:error] [pid 8782:tid 2800739360] [2020-07-16 20:20:21,599] WARNING in server: Unable to get GeoIP Continent data for 192.168.10.2.

==> /var/log/apache2/other_vhosts_access.log <==
servers.minetest.net:80 192.168.10.2 - - [16/Jul/2020:20:20:21 -0400] "POST /announce HTTP/1.1" 202 204 "-" "Minetest/5.2.0 (Linux/4.19.118-v7l+ armv7l)"

And then it shows correctly in the JSON / server browser...

And then 5 minutes later when I expect an UPDATE:

==> /var/log/apache2/error.log <==
[Thu Jul 16 20:25:22.067174 2020] [authz_core:debug] [pid 8781:tid 2945397792] mod_authz_core.c(820): [client 192.168.10.2:51984] AH01626: authorization result of Require all granted: granted
[Thu Jul 16 20:25:22.067332 2020] [authz_core:debug] [pid 8781:tid 2945397792] mod_authz_core.c(820): [client 192.168.10.2:51984] AH01626: authorization result of <RequireAny>: granted
[Thu Jul 16 20:25:22.067546 2020] [authz_core:debug] [pid 8781:tid 2945397792] mod_authz_core.c(820): [client 192.168.10.2:51984] AH01626: authorization result of Require all granted: granted
[Thu Jul 16 20:25:22.067600 2020] [authz_core:debug] [pid 8781:tid 2945397792] mod_authz_core.c(820): [client 192.168.10.2:51984] AH01626: authorization result of <RequireAny>: granted
[Thu Jul 16 20:25:22.073243 2020] [deflate:debug] [pid 8781:tid 2945397792] mod_deflate.c(856): [client 192.168.10.2:51984] AH01384: Zlib: Compressed 27 to 35 : URL /announce

==> /var/log/apache2/other_vhosts_access.log <==
servers.minetest.net:80 192.168.10.2 - - [16/Jul/2020:20:25:22 -0400] "POST /announce HTTP/1.1" 200 274 "-" "Minetest/5.2.0 (Linux/4.19.118-v7l+ armv7l)"

At this point it doesn't immediately go away... but after ~30~ 50 seconds have passed, the next time something hits server.py, the server is removed from the master list. The server meanwhile keeps hitting the "master server" every 5 minutes and never re-appears until the server is restarted.

Since it looks to me like server.py essentially handles the UPDATE and START the same way... The only things that come to mind are:

If you think it'd be valuable to skip Apache and run it in the development server version I'll try that, but I had kind of assumed WSGI is WSGI and it wouldn't make sense for Apache to be acting differently on a START versus an UPDATE, since it doesn't know the difference and the queries are pretty much the same.

Tyler-2 commented 3 years ago

I'm currently checking to see if it happens when run with the development version / invoking server.py directly..

Tyler-2 commented 3 years ago 
192.168.10.2 - - [16/Jul/2020 21:17:47] "POST /announce HTTP/1.1" 202 -
[2020-07-16 21:17:47,789] WARNING in server: Unable to get GeoIP Continent data for 192.168.10.2.
[2020-07-16 21:22:48,240] WARNING in server: Unable to get GeoIP Continent data for 192.168.10.2.
192.168.10.2 - - [16/Jul/2020 21:22:48] "POST /announce HTTP/1.1" 202 -
[2020-07-16 21:27:48,609] WARNING in server: Unable to get GeoIP Continent data for 192.168.10.2.
192.168.10.2 - - [16/Jul/2020 21:27:48] "POST /announce HTTP/1.1" 202 -
[2020-07-16 21:32:48,954] WARNING in server: Unable to get GeoIP Continent data for 192.168.10.2.
192.168.10.2 - - [16/Jul/2020 21:32:48] "POST /announce HTTP/1.1" 202 -

Aaaaand it seems like the UPDATE works. Note the 202 status. Hmmmm... What does a START versus an UPDATE POST look like? That's really curious because I know that the server.py is getting run with the UPDATE posts... and I know that it is getting at least through to the point of that finishRequestAsync call.

sfan5 commented 3 years ago

Sounds like those oddities are due to mod_wsgi, but I couldn't tell you what it does different compared to uwsgi (possibly running multiple independent processes of the code?).

Tyler-2 commented 3 years ago

Will troubleshoot this and see if I can't figure out what options cause this.

Tyler-2 commented 3 years ago

Here's what the Apache master-server is telling the minetest server: (Note I added the IP/port to the output to try to figure out why it couldn't find it)

But what's interesting is that the server is still in the server list there... so... I'm trying to understand the class where the server lookups are happening, as I suspect something wrong with the old lookup.

Tyler-2 commented 3 years ago

I'm wondering if maybe the server list is meant to be persisted in memory, and not read from the server list file as I initially assumed... if that's the case, I think the current config basically spawns and destroys the .py with each request. I've configured mod_wsgi to run in daemon mode now, to see if that fixes it.

Tyler-2 commented 3 years ago

That does seem to have done the trick.

Tyler-2 commented 3 years ago

Submitted https://github.com/minetest/master-server/pull/40 in case you want to reflect this in docs.