Reproduce seemingly ungraceful shutdown

error_log.txt

@@ -0,0 +1,43 @@
+# To reproduce this:
+# $ virtualenv venv
+# $ ./venv/bin/python ./setup.py install
+# $ ./venv/bin/pip install requests
+
+# Then start the server:
+# $ ./venv/bin/python ./examples/standalone_app.py
+# Make note of the PID
+
+# In a different terminal start hammering the server:
+# $ ./venv/bin/python ./hammer.py
+# OR $ ./venv/bin/python ./hammer2.py
+
+# In yet a different terminal:
+# $ kill PID_HERE
+
+[2016-10-05 12:33:12 +0000] [24020] [INFO] Starting gunicorn 19.6.0
+[2016-10-05 12:33:12 +0000] [24020] [INFO] Listening at: http://0.0.0.0:8080 (24020)
+[2016-10-05 12:33:12 +0000] [24020] [INFO] Using worker: sync
+[2016-10-05 12:33:12 +0000] [24028] [INFO] Booting worker with pid: 24028
+handling request ...
+[2016-10-05 12:33:35 +0000] [24020] [INFO] Arbiter: Received signal 15
+[2016-10-05 12:33:35 +0000] [24020] [INFO] Handling signal: term
+[2016-10-05 12:33:35 +0000] [24020] [INFO] Arbiter: Handle SIGTERM
+[2016-10-05 12:33:35 +0000] [24020] [INFO] gracefully closing socket ...
+handling request ...
+[2016-10-05 12:33:36 +0000] [24020] [INFO] waiting before gracefully closing socket, 0
+handling request ...
+[2016-10-05 12:33:37 +0000] [24020] [INFO] waiting before gracefully closing socket, 1
+handling request ...
+[2016-10-05 12:33:38 +0000] [24020] [INFO] waiting before gracefully closing socket, 2
+[2016-10-05 12:33:38 +0000] [24020] [INFO] all server sockets should be closed by now
+[2016-10-05 12:33:38 +0000] [24020] [INFO] killing workers ...
+[2016-10-05 12:33:38 +0000] [24020] [INFO] killing workers in 3 ...
+handling request ...
+[2016-10-05 12:33:39 +0000] [24020] [INFO] killing workers in 2 ...
+handling request ...
+[2016-10-05 12:33:41 +0000] [24020] [INFO] killing workers in 1 ...
+[2016-10-05 12:33:41 +0000] [24020] [INFO] killing workers ... GO
+[2016-10-05 12:33:41 +0000] [24028] [INFO] Worker calling sys.exit(0) (pid: 24028)
+[2016-10-05 12:33:41 +0000] [24028] [INFO] Worker exiting (pid: 24028)
+[2016-10-05 12:33:41 +0000] [24020] [INFO] Arbiter: Handle SIGCHLD
+[2016-10-05 12:33:41 +0000] [24020] [INFO] Shutting down: Master

examples/standalone_app.py

@@ -11,15 +11,18 @@
 from __future__ import unicode_literals
 
 import multiprocessing
+import random
+import sys
+import time
+import uuid
 
 import gunicorn.app.base
-
 from gunicorn.six import iteritems
 
-
 def number_of_workers():
     return (multiprocessing.cpu_count() * 2) + 1
 
+resp = str(uuid.uuid4())
 
 def handler_app(environ, start_response):
     response_body = b'Works fine'
@@ -30,8 +33,12 @@ def handler_app(environ, start_response):
     ]
 
     start_response(status, response_headers)
+    sys.stdout.write('handling request ...\n')
+    sys.stdout.flush()
+    time.sleep(0.1 * random.random()) # do some work
 
-    return [response_body]
+    global resp
+    return [resp]
 
 
 class StandaloneApplication(gunicorn.app.base.BaseApplication):
@@ -53,7 +60,7 @@ def load(self):
 
 if __name__ == '__main__':
     options = {
-        'bind': '%s:%s' % ('127.0.0.1', '8080'),
-        'workers': number_of_workers(),
+        'bind': '%s:%s' % ('0.0.0.0', '8080'),
+        'workers': 1,
     }
     StandaloneApplication(handler_app, options).run()

gunicorn/arbiter.py

@@ -176,6 +176,7 @@ def init_signals(self):
         signal.signal(signal.SIGCHLD, self.handle_chld)
 
     def signal(self, sig, frame):
+        self.log.info('Arbiter: Received signal %d' % (sig))
         if len(self.SIG_QUEUE) < 5:
             self.SIG_QUEUE.append(sig)
             self.wakeup()
@@ -228,6 +229,7 @@ def run(self):
 
     def handle_chld(self, sig, frame):
         "SIGCHLD handling"
+        self.log.info("Arbiter: Handle SIGCHLD")
         self.reap_workers()
         self.wakeup()
 
@@ -243,15 +245,18 @@ def handle_hup(self):
 
     def handle_term(self):
         "SIGTERM handling"
+        self.log.info("Arbiter: Handle SIGTERM")
         raise StopIteration
 
     def handle_int(self):
         "SIGINT handling"
+        self.log.info("Arbiter: Handle SIGINT")
         self.stop(False)
         raise StopIteration
 
     def handle_quit(self):
         "SIGQUIT handling"
+        self.log.info("Arbiter: Handle SIGQUIT")
         self.stop(False)
         raise StopIteration
 
@@ -278,6 +283,7 @@ def handle_usr1(self):
         SIGUSR1 handling.
         Kill all workers by sending them a SIGUSR1
         """
+        self.log.info("Arbiter: Handle SIGUSR1")
         self.log.reopen_files()
         self.kill_workers(signal.SIGUSR1)
 
@@ -288,6 +294,7 @@ def handle_usr2(self):
         master without affecting old workers. Use this to do live
         deployment with the ability to backout a change.
         """
+        self.log.info("Arbiter: Handle SIGUSR2")
         self.reexec()
 
     def handle_winch(self):
@@ -367,14 +374,24 @@ def stop(self, graceful=True):
 
         if self.reexec_pid == 0 and self.master_pid == 0:
             for l in self.LISTENERS:
+                self.log.info('gracefully closing socket ...')
+                for i in range(3):
+                    time.sleep(1)
+                    self.log.info('waiting before gracefully closing socket, %d' % (i))
                 l.close()
+            self.log.info('all server sockets should be closed by now')
 
         self.LISTENERS = []
         sig = signal.SIGTERM
         if not graceful:
             sig = signal.SIGQUIT
         limit = time.time() + self.cfg.graceful_timeout
         # instruct the workers to exit
+        self.log.info('killing workers ...')
+        for i in range(3):
+            time.sleep(i)
+            self.log.info('killing workers in %d ...' % (3-i))
+        self.log.info('killing workers ... GO')
         self.kill_workers(sig)
         # wait until the graceful timeout
         while self.WORKERS and time.time() < limit:
@@ -555,6 +572,7 @@ def spawn_worker(self):
             self.log.info("Booting worker with pid: %s", worker_pid)
             self.cfg.post_fork(self, worker)
             worker.init_process()
+            self.log.info("Worker calling sys.exit(0) (pid: %s)", worker_pid)
             sys.exit(0)
         except SystemExit:
             raise

hammer.py

@@ -0,0 +1,29 @@
+#!./venv/bin/python
+
+from __future__ import print_function
+import requests
+import sys
+import signal
+from sets import Set
+from collections import OrderedDict
+
+if __name__=="__main__":
+    print('hammer.py running ...')
+    ok = 0
+    items = OrderedDict()
+    while True:
+        try:
+            response = requests.get('http://localhost:8080/')
+            if len(response.text) == 36:
+                ok += 1
+                if response.text not in items.keys():
+                    items[response.text] = 0
+                items[response.text] += 1
+            else:
+                print('incorrect response, was', response.text)
+                raise ValueError('Incorrect response', response.text)
+        except:
+            raise
+        finally:
+            sys.stdout.write("\rOK: %d. %s" % (ok, ", ".join(["%s: %d" % (k, v) for (k, v) in items.items()])))
+            sys.stdout.flush()

hammer2.py

@@ -0,0 +1,14 @@
+#!/usr/bin/env python
+
+from __future__ import print_function
+import os
+
+if __name__=="__main__":
+    while True:
+        ret = os.system('curl http://localhost:8080/')
+        if ret == 0:
+            pass
+        else:
+            print(ret)
+            break
+    print('exiting')