Verify process start time when checking if postgres is running. (#549)

After a crash that doesn't clean up postmaster.pid there could be a new process with the same pid resulting in a false positive for is_running(), which will lead to all kinds of bad behavior.

Fixes #548

patroni/postgresql.py

@@ -17,7 +17,7 @@ from contextlib import contextmanager
 from patroni import call_self
 from patroni.callback_executor import CallbackExecutor
 from patroni.exceptions import PostgresConnectionException
-from patroni.utils import compare_values, parse_bool, parse_int, Retry, RetryFailedError, polling_loop
+from patroni.utils import compare_values, parse_bool, parse_int, Retry, RetryFailedError, polling_loop, int_or_none
 from six import string_types
 from six.moves.urllib.parse import quote_plus
 from threading import current_thread, Lock
@@ -727,7 +727,10 @@ class Postgresql(object):
         if not (self._version_file_exists() and os.path.isfile(self._postmaster_pid)):
             # XXX: This is dangerous in case somebody deletes the data directory while PostgreSQL is still running.
             return False
-        return self.is_pid_running(self.get_pid())
+
+        pidfile = self.read_pid_file()
+        return self._is_postmaster_pid_running(int_or_none(pidfile.get('pid')),
+                                               start_time=int_or_none(pidfile.get('start_time')))
 
     @_update_postmaster_info
     def read_pid_file(self):
@@ -774,13 +777,28 @@ class Postgresql(object):
         logger.info("postmaster info was cleaned.")
 
     @staticmethod
-    def is_pid_running(pid):
-        try:
-            if pid < 0:
-                pid = -pid
-            return pid > 0 and pid != os.getpid() and pid != os.getppid() and (os.kill(pid, 0) or True)
-        except Exception:
+    def _is_postmaster_pid_running(pid, start_time=None):
+        # Normalize pid handling missing values and negative pids from postmaster.pid
+        if not pid:
             return False
+        if pid < 0:
+            pid = -pid
+
+        try:
+            proc = psutil.Process(pid)
+        except psutil.NoSuchProcess:
+            return False
+
+        # If the process is Patroni or Patronis host process or Patronis child process then it's a false positive
+        my_pid = os.getpid()
+        if pid == my_pid or pid == os.getppid() or proc.parent() == my_pid:
+            return False
+
+        # If process start time differs by more than 3 seconds it's a false positive
+        if start_time is not None and abs(proc.create_time() - start_time) > 3:
+            return False
+
+        return True
 
     @property
     def cb_called(self):
@@ -845,7 +863,7 @@ class Postgresql(object):
                     # Garbage in the pid file
                     pass
 
-            if not self.is_pid_running(pid):
+            if not self._is_postmaster_pid_running(pid, start_time=initiated):
                 logger.error('postmaster is not running')
                 self.set_state('start failed')
                 return False
@@ -1010,7 +1028,7 @@ class Postgresql(object):
     def _wait_for_postmaster_stop(self, pid):
         # This wait loop differs subtly from pg_ctl as we check for both the pid file going
         # away and if the pid is running. This seems safer.
-        while pid == self.get_pid() and self.is_pid_running(pid):
+        while pid == self.get_pid() and self._is_postmaster_pid_running(pid):
             time.sleep(STOP_POLLING_INTERVAL)
 
     def _signal_postmaster_stop(self, mode):
@@ -1040,13 +1058,13 @@ class Postgresql(object):
                 return
             logger.warning("Could not send stop signal to PostgreSQL (error: {0})".format(e.errno))
 
-        while self.is_pid_running(pid):
+        while self._is_postmaster_pid_running(pid):
             time.sleep(STOP_POLLING_INTERVAL)
 
     def _wait_for_connection_close(self, pid):
         try:
             with self.connection().cursor() as cur:
-                while pid == self.get_pid() and self.is_pid_running(pid):  # Need a timeout here?
+                while pid == self.get_pid() and self._is_postmaster_pid_running(pid):  # Need a timeout here?
                     cur.execute("SELECT 1")
                     time.sleep(STOP_POLLING_INTERVAL)
         except psycopg2.Error:

patroni/utils.py

@@ -280,3 +280,11 @@ def polling_loop(timeout, interval=1):
         yield iteration
         iteration += 1
         time.sleep(interval)
+
+
+def int_or_none(val):
+    """Returns integer value of the parameter if convertible to int, None otherwise."""
+    try:
+        return int(val)
+    except (ValueError, TypeError):
+        return None

tests/test_postgresql.py

@@ -2,6 +2,7 @@ import errno
 import mock  # for the mock.call method, importing it without a namespace breaks python3
 import os
 import psycopg2
+import psutil
 import shutil
 import subprocess
 import unittest
@@ -238,17 +239,17 @@ class TestPostgresql(unittest.TestCase):
 
     @patch.object(Postgresql, 'pg_isready')
     @patch.object(Postgresql, 'read_pid_file')
-    @patch.object(Postgresql, 'is_pid_running')
+    @patch.object(Postgresql, '_is_postmaster_pid_running')
     @patch('patroni.postgresql.polling_loop', Mock(return_value=range(1)))
-    def test_wait_for_port_open(self, mock_is_pid_running, mock_read_pid_file, mock_pg_isready):
-        mock_is_pid_running.return_value = False
+    def test_wait_for_port_open(self, mock_is_postmaster_pid_running, mock_read_pid_file, mock_pg_isready):
+        mock_is_postmaster_pid_running.return_value = False
         mock_pg_isready.return_value = STATE_NO_RESPONSE
 
         # No pid file and postmaster death
         mock_read_pid_file.return_value = {}
         self.assertFalse(self.p.wait_for_port_open(42, 100., 1))
 
-        mock_is_pid_running.return_value = True
+        mock_is_postmaster_pid_running.return_value = True
 
         # timeout
         mock_read_pid_file.return_value = {'pid', 1}
@@ -289,7 +290,7 @@ class TestPostgresql(unittest.TestCase):
             self.assertFalse(self.p.stop())
             self.assertTrue(self.p.stop())
         with patch.object(Postgresql, '_signal_postmaster_stop', Mock(return_value=(123, None))):
-            with patch.object(Postgresql, 'is_pid_running', Mock(side_effect=[True, False, False])):
+            with patch.object(Postgresql, '_is_postmaster_pid_running', Mock(side_effect=[True, False, False])):
                 self.assertTrue(self.p.stop())
 
     def test_restart(self):
@@ -772,12 +773,13 @@ class TestPostgresql(unittest.TestCase):
             os.remove(pidfile)
         self.assertEquals(self.p.read_pid_file(), {})
 
-    @patch('os.kill')
-    def test_is_pid_running(self, mock_kill):
-        mock_kill.return_value = True
-        self.assertTrue(self.p.is_pid_running(-100))
-        self.assertFalse(self.p.is_pid_running(0))
-        self.assertFalse(self.p.is_pid_running(None))
+    @patch('psutil.Process')
+    def test_is_postmaster_pid_running(self, mock_psutil):
+        mock_proc = Mock()
+        mock_psutil.return_value = mock_proc
+        self.assertTrue(self.p._is_postmaster_pid_running(-100))
+        self.assertFalse(self.p._is_postmaster_pid_running(0))
+        self.assertFalse(self.p._is_postmaster_pid_running(None))
 
     def test_pick_sync_standby(self):
         cluster = Cluster(True, None, self.leader, 0, [self.me, self.other, self.leadermem], None,
@@ -855,20 +857,20 @@ class TestPostgresql(unittest.TestCase):
     @patch.object(Postgresql, '_signal_postmaster_stop', Mock(return_value=(123, None)))
     @patch.object(Postgresql, 'get_pid', Mock(return_value=123))
     @patch('time.sleep', Mock())
-    @patch.object(Postgresql, 'is_pid_running')
-    def test__wait_for_connection_close(self, mock_is_pid_running):
-        mock_is_pid_running.side_effect = [True, False, False]
+    @patch.object(Postgresql, '_is_postmaster_pid_running')
+    def test__wait_for_connection_close(self, mock_is_postmaster_pid_running):
+        mock_is_postmaster_pid_running.side_effect = [True, False, False]
         mock_callback = Mock()
         self.p.stop(on_safepoint=mock_callback)
 
-        mock_is_pid_running.side_effect = [True, False, False]
+        mock_is_postmaster_pid_running.side_effect = [True, False, False]
         with patch.object(MockCursor, "execute", Mock(side_effect=psycopg2.Error)):
             self.p.stop(on_safepoint=mock_callback)
 
     @patch.object(Postgresql, 'is_running', Mock(return_value=True))
     @patch.object(Postgresql, '_signal_postmaster_stop', Mock(return_value=(123, None)))
     @patch.object(Postgresql, 'get_pid', Mock(return_value=123))
-    @patch.object(Postgresql, 'is_pid_running', Mock(return_value=False))
+    @patch.object(Postgresql, '_is_postmaster_pid_running', Mock(return_value=False))
     @patch('psutil.Process')
     def test__wait_for_user_backends_to_close(self, mock_psutil):
         child = Mock()
@@ -878,8 +880,9 @@ class TestPostgresql(unittest.TestCase):
         self.p.stop(on_safepoint=mock_callback)
 
     @patch('os.kill', Mock(side_effect=[OSError(errno.ESRCH, ''), OSError]))
+    @patch('psutil.Process', Mock(side_effect=[psutil.NoSuchProcess]))
     @patch('time.sleep', Mock())
-    @patch.object(Postgresql, 'is_pid_running', Mock(side_effect=[True, False]))
+    @patch.object(Postgresql, '_is_postmaster_pid_running', Mock(side_effect=[True, False]))
     def test_terminate_starting_postmaster(self):
         self.p.terminate_starting_postmaster(123)
         self.p.terminate_starting_postmaster(123)