Log a warning if an eventlistener enters the UNKNOWN state.

Refs #252
Refs #622

CHANGES.txt

@@ -28,6 +28,10 @@
   change caused the last start time of the process to be in the future.
   Thanks to Róbert Nagy, Sergey Leschenko, and samhair for the patches.
 
+- A warning is now logged if an eventlistener enters the UNKNOWN state,
+  which usually indicates a bug in the eventlistener.  Thanks to Steve
+  Winton and detailyang for reporting issues that led to this change.
+
 - Errors from the web interface are now logged at the ``ERROR`` level.
   Previously, they were logged at the ``TRACE`` level and easily
   missed.  Thanks to Thomas Güttler for reporting this issue.

supervisor/dispatchers.py

@@ -6,6 +6,7 @@ from supervisor.events import EventRejectedEvent
 from supervisor.events import ProcessLogStderrEvent
 from supervisor.events import ProcessLogStdoutEvent
 from supervisor.states import EventListenerStates
+from supervisor.states import getEventListenerStateDescription
 from supervisor import loggers
 
 def find_prefix_at_end(haystack, needle):
@@ -332,16 +333,12 @@ class PEventListenerDispatcher(PDispatcher):
                 # not enough info to make a decision
                 return
             elif data.startswith(self.READY_FOR_EVENTS_TOKEN):
-                msg = '%s: ACKNOWLEDGED -> READY' % procname
-                process.config.options.logger.debug(msg)
-                process.listener_state = EventListenerStates.READY
+                self._change_listener_state(EventListenerStates.READY)
                 tokenlen = self.READY_FOR_EVENTS_LEN
                 self.state_buffer = self.state_buffer[tokenlen:]
                 process.event = None
             else:
-                msg = '%s: ACKNOWLEDGED -> UNKNOWN' % procname
-                process.config.options.logger.debug(msg)
-                process.listener_state = EventListenerStates.UNKNOWN
+                self._change_listener_state(EventListenerStates.UNKNOWN)
                 self.state_buffer = ''
                 process.event = None
             if self.state_buffer:
@@ -351,10 +348,8 @@ class PEventListenerDispatcher(PDispatcher):
                 return
 
         elif state == EventListenerStates.READY:
-            # the process sent some spurious data, be a hardass about it
-            msg = '%s: READY -> UNKNOWN' % procname
-            process.config.options.logger.debug(msg)
-            process.listener_state = EventListenerStates.UNKNOWN
+            # the process sent some spurious data, be strict about it
+            self._change_listener_state(EventListenerStates.UNKNOWN)
             self.state_buffer = ''
             process.event = None
             return
@@ -374,10 +369,10 @@ class PEventListenerDispatcher(PDispatcher):
                 try:
                     self.resultlen = int(resultlen)
                 except ValueError:
-                    msg = ('%s: BUSY -> UNKNOWN (bad result line %r)'
-                           % (procname, result_line))
-                    process.config.options.logger.debug(msg)
-                    process.listener_state = EventListenerStates.UNKNOWN
+                    process.config.options.logger.warn(
+                        '%s: bad result line: %r' % (procname, result_line)
+                        )
+                    self._change_listener_state(EventListenerStates.UNKNOWN)
                     self.state_buffer = ''
                     notify(EventRejectedEvent(process, process.event))
                     process.event = None
@@ -406,22 +401,40 @@ class PEventListenerDispatcher(PDispatcher):
     def handle_result(self, result):
         process = self.process
         procname = process.config.name
+        logger = process.config.options.logger
 
         try:
             self.process.group.config.result_handler(process.event, result)
-            msg = '%s: BUSY -> ACKNOWLEDGED (processed)' % procname
-            process.listener_state = EventListenerStates.ACKNOWLEDGED
+            logger.debug('%s: event was processed' % procname)
+            self._change_listener_state(EventListenerStates.ACKNOWLEDGED)
         except RejectEvent:
-            msg = '%s: BUSY -> ACKNOWLEDGED (rejected)' % procname
-            process.listener_state = EventListenerStates.ACKNOWLEDGED
+            logger.warn('%s: event was rejected' % procname)
+            self._change_listener_state(EventListenerStates.ACKNOWLEDGED)
             notify(EventRejectedEvent(process, process.event))
         except:
-            msg = '%s: BUSY -> UNKNOWN' % procname
-            process.listener_state = EventListenerStates.UNKNOWN
+            logger.warn('%s: event caused an error' % procname)
+            self._change_listener_state(EventListenerStates.UNKNOWN)
             notify(EventRejectedEvent(process, process.event))
 
+    def _change_listener_state(self, new_state):
+        process = self.process
+        procname = process.config.name
+        old_state = process.listener_state
+
+        msg = '%s: %s -> %s' % (
+            procname,
+            getEventListenerStateDescription(old_state),
+            getEventListenerStateDescription(new_state)
+            )
         process.config.options.logger.debug(msg)
 
+        process.listener_state = new_state
+        if new_state == EventListenerStates.UNKNOWN:
+            msg = ('%s: has entered the UNKNOWN state and will no longer '
+                   'receive events, this usually indicates the process '
+                   'violated the eventlistener protocol' % procname)
+            process.config.options.logger.warn(msg)
+
 class PInputDispatcher(PDispatcher):
     """ Input (stdin) dispatcher """
     process = None # process which "owns" this dispatcher

supervisor/states.py

@@ -20,12 +20,9 @@ RUNNING_STATES = (ProcessStates.RUNNING,
                   ProcessStates.BACKOFF,
                   ProcessStates.STARTING)
 
-
-
 def getProcessStateDescription(code):
-    for statename in ProcessStates.__dict__:
-        if getattr(ProcessStates, statename) == code:
-            return statename
+    return _process_states_by_code.get(code)
+
 
 class SupervisorStates:
     FATAL = 2
@@ -34,9 +31,7 @@ class SupervisorStates:
     SHUTDOWN = -1
 
 def getSupervisorStateDescription(code):
-    for statename in SupervisorStates.__dict__:
-        if getattr(SupervisorStates, statename) == code:
-            return statename
+    return _supervisor_states_by_code.get(code)
 
 
 class EventListenerStates:
@@ -46,7 +41,17 @@ class EventListenerStates:
     UNKNOWN = 40 # the event listener is in an unknown state
 
 def getEventListenerStateDescription(code):
-    for statename in EventListenerStates.__dict__:
-        if getattr(EventListenerStates, statename) == code:
-            return statename
-
+    return _eventlistener_states_by_code.get(code)
+
+
+# below is an optimization for internal use in this module only
+def _names_by_code(states):
+    d = {}
+    for name in states.__dict__:
+        if not name.startswith('__'):
+            code = getattr(states, name)
+            d[code] = name
+    return d
+_process_states_by_code = _names_by_code(ProcessStates)
+_supervisor_states_by_code = _names_by_code(SupervisorStates)
+_eventlistener_states_by_code = _names_by_code(EventListenerStates)

supervisor/tests/test_dispatchers.py

@@ -770,6 +770,10 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(dispatcher.state_buffer, '')
         self.assertEqual(options.logger.data[0],
                          'process1: ACKNOWLEDGED -> UNKNOWN')
+        self.assertEqual(options.logger.data[1],
+                         'process1: has entered the UNKNOWN state and will '
+                         'no longer receive events, this usually indicates '
+                         'the process violated the eventlistener protocol')
         self.assertEqual(process.listener_state, EventListenerStates.UNKNOWN)
 
     def test_handle_listener_state_change_ready_to_unknown(self):
@@ -784,6 +788,10 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(dispatcher.state_buffer, '')
         self.assertEqual(options.logger.data[0],
                          'process1: READY -> UNKNOWN')
+        self.assertEqual(options.logger.data[1],
+                         'process1: has entered the UNKNOWN state and will '
+                         'no longer receive events, this usually indicates '
+                         'the process violated the eventlistener protocol')
         self.assertEqual(process.listener_state, EventListenerStates.UNKNOWN)
 
     def test_handle_listener_state_change_busy_to_insufficient(self):
@@ -815,7 +823,9 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(dispatcher.handle_listener_state_change(), None)
         self.assertEqual(dispatcher.state_buffer, 'abc')
         self.assertEqual(options.logger.data[0],
-                         'process1: BUSY -> ACKNOWLEDGED (processed)')
+                         'process1: event was processed')
+        self.assertEqual(options.logger.data[1],
+                         'process1: BUSY -> ACKNOWLEDGED')
         self.assertEqual(process.listener_state,
                          EventListenerStates.ACKNOWLEDGED)
 
@@ -836,7 +846,9 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(dispatcher.handle_listener_state_change(), None)
         self.assertEqual(dispatcher.state_buffer, 'abc')
         self.assertEqual(options.logger.data[0],
-                         'process1: BUSY -> ACKNOWLEDGED (rejected)')
+                         'process1: event was rejected')
+        self.assertEqual(options.logger.data[1],
+                         'process1: BUSY -> ACKNOWLEDGED')
         self.assertEqual(process.listener_state,
                          EventListenerStates.ACKNOWLEDGED)
 
@@ -859,7 +871,13 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(dispatcher.handle_listener_state_change(), None)
         self.assertEqual(dispatcher.state_buffer, '')
         self.assertEqual(options.logger.data[0],
-                'process1: BUSY -> UNKNOWN (bad result line \'bogus data\')')
+                "process1: bad result line: 'bogus data'")
+        self.assertEqual(options.logger.data[1],
+                'process1: BUSY -> UNKNOWN')
+        self.assertEqual(options.logger.data[2],
+                         'process1: has entered the UNKNOWN state and will '
+                         'no longer receive events, this usually indicates '
+                         'the process violated the eventlistener protocol')
         self.assertEqual(process.listener_state,
                          EventListenerStates.UNKNOWN)
         self.assertEqual(events[0].process, process)
@@ -882,9 +900,15 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(dispatcher.handle_listener_state_change(), None)
         self.assertEqual(dispatcher.state_buffer, '')
         self.assertEqual(options.logger.data[0],
-                         'process1: BUSY -> ACKNOWLEDGED (processed)')
+                         'process1: event was processed')
         self.assertEqual(options.logger.data[1],
+                         'process1: BUSY -> ACKNOWLEDGED')
+        self.assertEqual(options.logger.data[2],
                          'process1: ACKNOWLEDGED -> UNKNOWN')
+        self.assertEqual(options.logger.data[3],
+                         'process1: has entered the UNKNOWN state and will '
+                         'no longer receive events, this usually indicates '
+                         'the process violated the eventlistener protocol')
         self.assertEqual(process.listener_state,
                          EventListenerStates.UNKNOWN)
 
@@ -912,8 +936,10 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(len(L), 0)
         self.assertEqual(process.listener_state,
                          EventListenerStates.ACKNOWLEDGED)
-        result = options.logger.data[0]
-        self.assertTrue(result.endswith('BUSY -> ACKNOWLEDGED (processed)'))
+        self.assertEqual(options.logger.data[0],
+                         'process1: event was processed')
+        self.assertEqual(options.logger.data[1],
+                         'process1: BUSY -> ACKNOWLEDGED')
 
     def test_handle_result_rejectevent(self):
         from supervisor.events import subscribe
@@ -941,8 +967,10 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(L[0].__class__, events.EventRejectedEvent)
         self.assertEqual(process.listener_state,
                          EventListenerStates.ACKNOWLEDGED)
-        result = options.logger.data[0]
-        self.assertTrue(result.endswith('BUSY -> ACKNOWLEDGED (rejected)'))
+        self.assertEqual(options.logger.data[0],
+                         'process1: event was rejected')
+        self.assertEqual(options.logger.data[1],
+                         'process1: BUSY -> ACKNOWLEDGED')
 
     def test_handle_result_exception(self):
         from supervisor.events import subscribe
@@ -970,8 +998,14 @@ class PEventListenerDispatcherTests(unittest.TestCase):
         self.assertEqual(L[0].__class__, events.EventRejectedEvent)
         self.assertEqual(process.listener_state,
                          EventListenerStates.UNKNOWN)
-        result = options.logger.data[0]
-        self.assertTrue(result.endswith('BUSY -> UNKNOWN'))
+        self.assertEqual(options.logger.data[0],
+                         'process1: event caused an error')
+        self.assertEqual(options.logger.data[1],
+                         'process1: BUSY -> UNKNOWN')
+        self.assertEqual(options.logger.data[2],
+                         'process1: has entered the UNKNOWN state and will '
+                         'no longer receive events, this usually indicates '
+                         'the process violated the eventlistener protocol')
 
     def test_handle_error(self):
         options = DummyOptions()

supervisor/tests/test_process.py

@@ -36,7 +36,8 @@ class SubprocessTests(unittest.TestCase):
         from supervisor.states import ProcessStates
         from supervisor.process import getProcessStateDescription
         for statename, code in ProcessStates.__dict__.items():
-            self.assertEqual(getProcessStateDescription(code), statename)
+            if isinstance(code, int):
+                self.assertEqual(getProcessStateDescription(code), statename)
 
     def test_ctor(self):
         options = DummyOptions()