Forums

uWSGI restarts killing my Bottle app

Hi,

I have a very simple Bottle web app in https://src.dot-eth0.sh that only has two routes that always respond with redirections. It runs perfectly fine when I reload it, but after some time the UWSGi process is restarted (I presume by a scheduled task of yours) and then my app isn't restarted with it. From that point on, every request is redirected to https://localhost/, which is not what my app does, until I reload it.

Can you check it out, please?

Sorry, my autocorrect changed UWSGi to Using and I can't correct the thread title.

[admin: fixed title]

Where do the redirects point to?

There isn't anything on our end that would ever redirect to localhost.

Hi Conrad,

This is the response I get when my app is working normally, only the relevant headers:

$ curl -si https://src.dot-eth0.sh/scripts/pythonanywhere/renew-letsencrypt.sh
HTTP/1.1 303 See Other
Server: openresty/1.9.15.1
Location: https://gitlab.com/ethernet.zero/scripts-public/raw/master/pythonanywhere/renew-letsencrypt.sh
X-Clacks-Overhead: GNU Terry Pratchett

But when uWSGI restarts itself, the response changes:

$ curl -si https://src.dot-eth0.sh/scripts/pythonanywhere/renew-letsencrypt.sh
HTTP/1.1 301 Moved Permanently
Server: openresty/1.9.15.1
Location: https://localhost/
X-Clacks-Overhead: GNU Terry Pratchett

I have no idea where that location comes from, since my app only defines two routes and both redirect to GitLab URLs. This happens after uWSGI restarts itself and it works fine again when I explicitly click the Reload button.

Here's an excerpt of the access.log file. I had a hourly cronjob making requests to the app just in case it was restarted for inactivity. As you can see here, as soon as the uWSGI process is restarted the response changes from a 303 to a 301:

34.207.109.238 - - [20/Jul/2018:04:50:33 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.001
34.207.109.238 - - [20/Jul/2018:05:50:22 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.001
34.207.109.238 - - [20/Jul/2018:06:50:21 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.014
34.207.109.238 - - [20/Jul/2018:07:50:22 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.004
34.207.109.238 - - [20/Jul/2018:08:50:23 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.008
34.207.109.238 - - [20/Jul/2018:09:50:22 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.005
34.207.109.238 - - [20/Jul/2018:10:50:23 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.004
34.207.109.238 - - [20/Jul/2018:11:50:26 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.002
34.207.109.238 - - [20/Jul/2018:12:50:25 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.083
34.207.109.238 - - [20/Jul/2018:13:50:21 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 303 0 "-" "curl/7.47.0" "34.207.109.238" response-time=0.002
34.207.109.238 - - [20/Jul/2018:14:50:24 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.031
34.207.109.238 - - [20/Jul/2018:15:50:23 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.026
34.207.109.238 - - [20/Jul/2018:16:50:21 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.017
34.207.109.238 - - [20/Jul/2018:17:50:20 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.025
34.207.109.238 - - [20/Jul/2018:18:50:21 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.019
34.207.109.238 - - [20/Jul/2018:19:50:24 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.016
34.207.109.238 - - [20/Jul/2018:20:50:21 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.010
34.207.109.238 - - [20/Jul/2018:21:50:22 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.028
34.207.109.238 - - [20/Jul/2018:22:50:23 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.006
34.207.109.238 - - [20/Jul/2018:23:50:26 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.014
34.207.109.238 - - [21/Jul/2018:00:50:24 +0000] "GET /scripts/pythonanywhere/renew-letsencrypt.sh HTTP/1.1" 301 191 "-" "curl/7.47.0" "34.207.109.238" response-time=0.003

May it be that clicking the Reload button picks up the correct uWSGI config file but when uWSGI restarts itself it loses track of what config file to load?

I just created a webapp here that redirects to google and I can't seem to get it to fail in the way you described. Will keep monitoring it.

In the meantime, I would suggest:

  1. logging the redirect url right before the redirect, to see if somehow our server is changing it leaves your stack, or if somehow your url is being changed within your code
  2. bottle has a redirect() where you specify the status code etc. If you hard code the status code to be say 302 etc, does this still result in a 302, 302, 302... etc and then 301?

I've added a print() right before the redirection, enabled debug mode and set the HTTP redirect code explicitly to a 302. I'll wait and see if and when it starts spewing the wrong redirects again. I'll keep you informed.

Thanks for your help!

By the way, this is the code of my app. It's really simple:

from bottle import default_app, route, redirect, request, debug

SCRIPTS_URL = "https://gitlab.com/ethernet.zero/scripts-public/raw/master/"
PROJECTS_URL = "https://gitlab.com/ethernet.zero/"

def redirect_to(url):
    if request.query_string != '':
        url += "?" + request.query_string
    print("{} -> {}".format(request.url, url))
    redirect(url, code=302)


@route('/scripts/<path:path>')
def script(path):
    redirect_to(SCRIPTS_URL + path)


@route('/projects/<repo:path>')
def project(repo):
    redirect_to(PROJECTS_URL + repo)


debug(True)
application = default_app()

The uWSGI config file is the default one.

Well, there we go. The server log shows these last entries and then there isn't anything else:

2018-07-23 17:44:14 https://src.dot-eth0.sh/scripts/pythonanywhere/renew-letsencrypt.sh -> https://gitlab.com/ethernet.zero/scripts-public/raw/master/pythonanywhere/renew-letsencrypt.sh
2018-07-23 17:46:54 https://src.dot-eth0.sh/scripts/pythonanywhere/renew-letsencrypt.sh -> https://gitlab.com/ethernet.zero/scripts-public/raw/master/pythonanywhere/renew-letsencrypt.sh
2018-07-24 00:13:48 ...brutally killing workers...
2018-07-24 00:13:53 Tue Jul 24 00:13:53 2018 - received message 0 from emperor
2018-07-24 00:14:35 uwsgi_master_manage_emperor()/read(): Bad file descriptor [core/emperor.c line 2427]
2018-07-24 00:14:35 lost connection with my emperor !!!
2018-07-24 00:14:35 chdir(): No such file or directory [core/uwsgi.c line 1590]
2018-07-24 00:14:35 VACUUM: unix socket /var/sockets/src.dot-eth0.sh/socket removed.

And sure enough, making a request to my web app redirects to https://localhost/:

$ curl -si https://src.dot-eth0.sh/scripts/pythonanywhere/renew-letsencrypt.sh
HTTP/1.1 301 Moved Permanently
Server: openresty/1.9.15.1
Date: Tue, 24 Jul 2018 07:00:04 GMT
Content-Type: text/html                               
Content-Length: 191
Connection: keep-alive
Location: https://localhost/                   
X-Clacks-Overhead: GNU Terry Pratchett

<html>                                                             
<head><title>301 Moved Permanently</title></head>
<body bgcolor="white">                                                           
<center><h1>301 Moved Permanently</h1></center>
<hr><center>openresty/1.9.15.1</center>
</body>       
</html>

But now something weird happened: I made a request to a nonexistent URL and the server returned this response:

$ curl -si https://src.dot-eth0.sh/doesnt/matter/what/i/put/here
HTTP/1.1 302 Found
Server: openresty/1.9.15.1
Date: Tue, 24 Jul 2018 07:05:05 GMT
Content-Type: text/html; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Vary: Cookie
X-Frame-Options: SAMEORIGIN
Location: https://src.dot-eth0.sh/doesnt/matter/what/i/put/here
Set-Cookie: sessionid=l4auaq5t80p3pz7o7pk1y7ua64vgswxr; expires=Tue, 07-Aug-2018 07:05:05 GMT; httponly; Max-Age=1209600; Path=/
X-Clacks-Overhead: GNU Terry Pratchett

(Note that here it's trying to redirect to itself)

And right after that, everything is back to normal except for absolutely nothing being written to the logs:

$ curl -si https://src.dot-eth0.sh/doesnt/matter/what/i/put/here
HTTP/1.1 404 Not Found
Server: openresty/1.9.15.1
Date: Tue, 24 Jul 2018 07:05:59 GMT
Content-Type: text/html; charset=UTF-8
Content-Length: 780
Connection: keep-alive
Vary: Accept-Encoding


    <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
    <html>
        <head>
            <title>Error: 404 Not Found</title>
            <style type="text/css">
              html {background-color: #eee; font-family: sans;}
              body {background-color: #fff; border: 1px solid #ddd;
                    padding: 15px; margin: 15px;}
              pre {background-color: #eee; border: 1px solid #ddd; padding: 5px;}
            </style>
        </head>
        <body>
            <h1>Error: 404 Not Found</h1>
            <p>Sorry, the requested URL <tt>&#039;https://src.dot-eth0.sh/doesnt/matter/what/i/put/here&#039;</tt>
               caused an error:</p>
            <pre>Not found: &#039;/doesnt/matter/what/i/put/here&#039;</pre>
        </body>
    </html>

(Notice also that this is exactly the same request as above and it now returns a correct 404 response)

$ curl -si https://src.dot-eth0.sh/scripts/pythonanywhere/renew-letsencrypt.sh
HTTP/1.1 302 Found
Server: openresty/1.9.15.1
Date: Tue, 24 Jul 2018 07:06:08 GMT
Content-Type: text/html; charset=UTF-8
Content-Length: 0
Connection: keep-alive
Location: https://gitlab.com/ethernet.zero/scripts-public/raw/master/pythonanywhere/renew-letsencrypt.sh
X-Clacks-Overhead: GNU Terry Pratchett

Now that's a really weird and unstable behavior. Does any of this ring a bell?

OK, I think we've tracked it down :-) There's definitely a bug in our setup, and we'll need to work out how to fix it -- it's quite deep in the internals of the system.

As you worked out, this is happening when your website has been moved from server to server. When that happens, it's just shut down on the old server, and the next incoming hit on the new server will wake it up there.

The bug is that if the request that wakes up the website contains the string "/pythonanywhere" then it will try to redirect to http://localhost/.

Many thanks for the following up on this and helping us to work it out. It might take a little while to get a fix in -- it's deep enough in the webserver configuration that we need to be careful not to break anything else -- but we'll be working on it.

Oh boy! What a sneaky bug! (^_^)

I'm so glad that we caught that issue. Now that you found the bug I can wait for you to squish it, so it's okay if it's not a quick and immediate fix.

Thanks a lot!

No problem, thanks for pointing out the bug! It looks like your site will only ever run on one of two specific servers in our current configuration (either web2 or web3) so I've applied a patch to both of those that should fix the bug, then moved the site back and forth a few times to make sure. It looks like everything worked, and your site and the others on those servers are working OK. We'll leave that in place until next Monday, and if all is still well then we'll push the patch over to all of the other servers.

Please do let us know if you see the problem come back in the meantime.

Great, thanks! I'll keep you informed.

It's been two days without the app ever failing even once. Looks like the patch worked perfectly.

Thanks again!

Excellent -- thanks for confirming! We'll roll it out to the other servers next week, I think.