Changeset 471:078b9eb64535

Timestamp:

08/28/08 17:22:48 (4 months ago)

Author:

Brian Warner <warner@allmydata.com>

branch:

default

Message:

logging: combine multiple overlapping Incidents into a single one. Helps with #85.

Files:

• ChangeLog (modified) (1 diff)
• doc/logging.xhtml (modified) (1 diff)
• foolscap/logging/incident.py (modified) (3 diffs)
• foolscap/logging/interfaces.py (modified) (1 diff)
• foolscap/logging/log.py (modified) (3 diffs)
• foolscap/test/test_logging.py (modified) (2 diffs)

ChangeLog

@@ -1 +1 @@
-2008-08-28  Brian Warner  <warner@lothar.com>
+
+        * foolscap/logging/log.py (FoolscapLogger.declare_incident):
+        combine overlapping incidents, by passing new triggers to an
+        existing reporter instead of creating a new one. Helps with #85.
+        * foolscap/logging/incident.py (IncidentReporter.new_trigger): new
+        method to add subsequent triggers to an existing reporter. This
+        doesn't do anything yet. It should be improved to record the other
+        triggers in a trailer (since it's too late to add it to the
+        header). Every triggering event will make it into an incident
+        somewhere, but the report-file analysis tools may not know how to
+        pay attention to the subsequent triggers.
+        * foolscap/logging/interfaces.py (IIncidentReporter.new_trigger): same
+        * foolscap/test/test_logging.py (Incidents.test_overlapping): test it
+        * doc/logging.xhtml: mention incident-coalescing
-
-        * foolscap/logging/log.py: add bridge-foolscap-logs-to-twisted

doc/logging.xhtml

@@ -480 +480 @@
-logging code should capture the otherwise-ordinary events performed by this
-recovery code.</p>
+
+<p>Overlapping incidents will be combined: if an incident reporter is already
+active when the qualifier sees a new triggering event, that event is just
+added to the existing reporter.</p>
-
-<p>The incident reporter can be overridden as well, by calling

foolscap/logging/incident.py

@@ -61 +61 @@
-        self.logger = logger
-        self.tubid_s = tubid_s
+        self.active = True
+
+    def is_active(self):
+        return self.active
-
-    def format_time(self, when):
@@ -106 +110 @@
-
-        if self.TRAILING_DELAY is None:
+            self.active = False
-            eventually(self.finished_recording)
-        else:
@@ -127 +132 @@
-        self.stop_recording()
-
+    def new_trigger(self, ev):
+        # it is too late to add this to the header. We could add it to a
+        # trailer, though.
+        pass
+
-    def stop_recording(self):
-        self.still_recording = False
+        self.active = False
-        if self.timer.active():
-            self.timer.cancel()

foolscap/logging/interfaces.py

@@ -129 +129 @@
-    def incident_declared(triggering_event):
-        """This is called when an Incident needs to be recorded."""
+    def new_trigger(triggering_event):
+        """This is called when a triggering event occurs while an incident is
+        already being reported. If the event happened later, it would trigger
+        a new incident. Since it overlapped with the existing incident, it
+        will just be added to that incident.
+
+        The triggering event will also be reported through the usual
+        event-publish-subscribe mechanism. This method is provided to give
+        the reporter the opportunity to mark the event somehow, for the
+        benefit of incident-file analysis tools.
+        """
+    def is_active():
+        """Returns True if the reporter is still running. While in this
+        state, new Incident triggers will be passed to the existing reporter
+        instead of causing a new Incident to be declared. This will tend to
+        coalesce back-to-back problems into a single Incident."""
+

foolscap/logging/log.py

@@ -54 +54 @@
-        self.active_incident_qualifier = None
-        self.incident_reporter_factory = IncidentReporter
-s = weakref.WeakKeyDictionary()
+_weakref = None
-        self.incidents_declared = 0
-        self.incidents_recorded = 0
@@ -250 +250 @@
-    def declare_incident(self, triggering_event):
-        self.incidents_declared += 1
+        ir = self.get_active_incident_reporter()
+        if ir:
+            ir.new_trigger(triggering_event)
+            return
-        if self.logdir: # just in case
-            ir = self.incident_reporter_factory(self.logdir, self, "local")
-s[ir] = None
-
+_weakref = weakref.ref(ir)
+ # this takes a few seconds
-
-    def incident_recorded(self, filename, name, trigger):
@@ -265 +269 @@
-        for o in self._immediate_incident_observers:
-            o(name, trigger)
+
+    def get_active_incident_reporter(self):
+        if self.active_incident_reporter_weakref:
+            ir = self.active_incident_reporter_weakref()
+            if ir and ir.is_active():
+                return ir
+        return None
-
-    def setLogPort(self, logport):

foolscap/test/test_logging.py

@@ -229 +229 @@
-        l.msg("3-trigger", level=log.BAD)
-        self.failUnlessEqual(l.incidents_declared, 1)
-Equal(len(l.active_incident_reporters), 1
+(l.get_active_incident_reporter()
-        # at this point, the uncompressed logfile should be present, and it
-        # should contain all the events up to and including the trigger
@@ -307 +307 @@
-            self.failUnlessEqual(events[-1]["d"]["message"], "6")
-        d.addCallback(_check)
+        return d
+
+    def test_overlapping(self):
+        l = log.FoolscapLogger()
+        l.setLogDir("logging/Incidents/overlapping")
+        got_logdir = l.logdir
+        self.failUnlessEqual(got_logdir,
+                             os.path.abspath("logging/Incidents/overlapping"))
+        d = defer.Deferred()
+        def _go(name, trigger):
+            d.callback( (name, trigger) )
+        l.addImmediateIncidentObserver(_go)
+        l.setIncidentReporterFactory(ImpatientReporter)
+        l.msg("1")
+        l.msg("2-trigger", level=log.BAD)
+        self.failUnlessEqual(l.incidents_declared, 1)
+        self.failUnless(l.get_active_incident_reporter())
+        l.msg("3-trigger", level=log.BAD)
+        self.failUnlessEqual(l.incidents_declared, 2)
+        self.failUnless(l.get_active_incident_reporter())
+
+        def _check(res):
+            self.failUnlessEqual(l.incidents_recorded, 1)
+            self.failUnlessEqual(len(l.recent_recorded_incidents), 1)
+            # at this point, the logfile should be present, and it should
+            # contain all the events up to and including both triggers
+
+            files = os.listdir(got_logdir)
+            self.failUnlessEqual(len(files), 1)
+            events = self._read_logfile(os.path.join(got_logdir, files[0]))
+
+            self.failUnlessEqual(len(events), 1+3)
+            self.failUnlessEqual(events[0]["header"]["trigger"]["message"],
+                                 "2-trigger")
+            self.failUnlessEqual(events[1]["d"]["message"], "1")
+            self.failUnlessEqual(events[2]["d"]["message"], "2-trigger")
+            self.failUnlessEqual(events[3]["d"]["message"], "3-trigger")
+        d.addCallback(_check)
+
-        return d
-