improved timer: logging, better error recovery
authorFelix Domke <tmbinc@elitedvb.net>
Sun, 15 Jan 2006 12:10:46 +0000 (12:10 +0000)
committerFelix Domke <tmbinc@elitedvb.net>
Sun, 15 Jan 2006 12:10:46 +0000 (12:10 +0000)
RecordTimer.py
timer.py

index 2234bfc..e375c9f 100644 (file)
@@ -11,7 +11,7 @@ from Screens.MessageBox import MessageBox
 from Screens.SubserviceSelection import SubserviceSelection
 import NavigationInstance
 
-from Tools.XMLTools import elementsWithTag
+from Tools.XMLTools import elementsWithTag, mergeText
 from ServiceReference import ServiceReference
 
 # ok, for descriptions etc we have:
@@ -30,6 +30,7 @@ def parseEvent(ev):
        eit = ev.getEventId()
        return (begin, end, name, description, eit)
 
+# please do not translate log messages
 class RecordTimerEntry(timer.TimerEntry):
        def __init__(self, serviceref, begin, end, name, description, eit):
                timer.TimerEntry.__init__(self, int(begin), int(end))
@@ -37,17 +38,25 @@ class RecordTimerEntry(timer.TimerEntry):
                assert isinstance(serviceref, ServiceReference)
                
                self.service_ref = serviceref
-               
                self.eit = eit
-               
                self.dontSave = False
                self.name = name
                self.description = description
                self.timer = None
                self.record_service = None
-               self.wantStart = False
-               self.prepareOK = False
                
+               self.log_entries = []
+               self.resetState()
+       
+       def log(self, code, msg):
+               self.log_entries.append((int(time.time()), code, msg))
+               print "[TIMER]", msg
+       
+       def resetState(self):
+               self.state = self.StateWaiting
+               self.first_try_prepare = True
+               self.timeChanged()
+       
        def calculateFilename(self):
                service_name = self.service_ref.getServiceName()
 #              begin_date = datetime.fromtimestamp(begin).strf...
@@ -59,71 +68,109 @@ class RecordTimerEntry(timer.TimerEntry):
                print "description: ", self.description
 
                self.Filename = Directories.getRecordingFilename(service_name)
+               self.log(0, "Filename calculated as: '%s'" % self.Filename)
                #begin_date + " - " + service_name + description)
-               
        
        def tryPrepare(self):
                self.calculateFilename()
                self.record_service = NavigationInstance.instance.recordService(self.service_ref)
                if self.record_service == None:
+                       self.log(1, "'record service' failed")
                        return False
                else:
-                       if self.record_service.prepare(self.Filename + ".ts"):
+                       prep_res = self.record_service.prepare(self.Filename + ".ts")
+                       if prep_res:
+                               self.log(2, "'prepare' failed: error %d" % prep_res)
                                self.record_service = None
                                return False
 
-                       f = open(self.Filename + ".ts.meta", "w")
-                       f.write(str(self.service_ref) + "\n")
-                       f.write(self.name + "\n")
-                       f.write(self.description + "\n")
-                       f.write(str(self.begin) + "\n")
-                       del f
+                       self.log(3, "prepare ok, writing meta information to %s" % self.Filename)
+                       try:
+                               f = open(self.Filename + ".ts.meta", "w")
+                               f.write(str(self.service_ref) + "\n")
+                               f.write(self.name + "\n")
+                               f.write(self.description + "\n")
+                               f.write(str(self.begin) + "\n")
+                               f.close()
+                       except:
+                               self.log(4, "failed to write meta information")
                        return True
 
-       def activate(self, event):
-               if event == self.EventPrepare:
-                       self.prepareOK = False
+       def do_backoff(self):
+               if self.backoff == 0:
+                       self.backoff = 5
+               else:
+                       self.backoff *= 2
+                       if self.backoff > 100:
+                               self.backoff = 100
+               self.log(10, "backoff: retry in %d seconds" % self.backoff)
+
+       def activate(self):
+               next_state = self.state + 1
+               self.log(5, "activating state %d" % next_state)
+               
+               if next_state == self.StatePrepared:
                        if self.tryPrepare():
-                               self.prepareOK = True
-                       else:
-                               # error.
+                               self.log(6, "prepare ok, waiting for begin")
+                               # fine. it worked, resources are allocated.
+                               self.next_activation = self.begin
+                               self.backoff = 0
+                               return True
+                       
+                       self.log(7, "prepare failed")
+                       if self.first_try_prepare:
+                               self.first_try_prepare = False
                                if config.recording.asktozap.value == 0:
+                                       self.log(8, "asking user to zap away")
                                        Notifications.AddNotificationWithCallback(self.failureCB, MessageBox, _("A timer failed to record!\nDisable TV and try again?\n"))
                                else: # zap without asking
+                                       self.log(9, "zap without asking")
                                        self.failureCB(True)
-               elif event == self.EventStart:
-                       if self.prepareOK:
-                               self.record_service.start()
-                               print "timer started!"
-                       else:
-                               print "prepare failed, thus start failed, too."
-                               self.wantStart = True
-               elif event == self.EventEnd or event == self.EventAbort:
-                       self.wantStart = False
-                       if self.prepareOK:
-                               self.record_service.stop()
-                               self.record_service = None
-                               
-                               print "Timer successfully ended"
-                       else:
-                               print "prepare failed, thus nothing was recorded."
 
-       def abort():
-               # fixme
-               pass
+                       self.do_backoff()
+                       # retry
+                       self.start_prepare = time.time() + self.backoff
+                       return False
+               elif next_state == self.StateRunning:
+                       self.log(11, "start recording")
+                       record_res = self.record_service.start()
+                       
+                       if record_res:
+                               self.log(13, "start record returned %d" % record_res)
+                               self.do_backoff()
+                               # retry
+                               self.begin = time.time() + self.backoff
+                               return False
+                       
+                       return True
+               elif next_state == self.StateEnded:
+                       self.log(12, "stop recording")
+                       self.record_service.stop()
+                       self.record_service = None
+                       return True
+
+       def getNextActivation(self):
+               if self.state == self.StateEnded:
+                       return self.end
+               
+               next_state = self.state + 1
+               
+               return {self.StatePrepared: self.start_prepare, 
+                               self.StateRunning: self.begin, 
+                               self.StateEnded: self.end }[next_state]
 
        def failureCB(self, answer):
                if answer == True:
+                       self.log(13, "ok, zapped away")
                        #NavigationInstance.instance.stopUserServices()
-                       print "[RecordTimer] zapping to", self.service_ref
                        NavigationInstance.instance.playService(self.service_ref.ref)
-                       self.activate(self.EventPrepare)
-
-                       if self.wantStart:
-                               print "post-activating record"
-                               self.activate(self.EventStart)
                else:
-                       print "user killed record"
+                       self.log(14, "user didn't want to zap away, record will probably fail")
+
+       def timeChanged(self):
+               self.start_prepare = self.begin - self.prepare_time
+               self.backoff = 0
+               self.log(15, "record time changed, start prepare is now: %s" % time.ctime(self.start_prepare))
 
 def createTimer(xml):
        begin = int(xml.getAttribute("begin"))
@@ -136,6 +183,13 @@ def createTimer(xml):
        #filename = xml.getAttribute("filename").encode("utf-8")
        entry = RecordTimerEntry(serviceref, begin, end, name, description, eit)
        entry.repeated = int(repeated)
+       
+       for l in elementsWithTag(xml.childNodes, "log"):
+               time = int(l.getAttribute("time"))
+               code = int(l.getAttribute("code"))
+               msg = mergeText(l.childNodes).strip()
+               entry.log_entries.append((time, code, msg))
+       
        return entry
 
 class RecordTimer(timer.Timer):
@@ -148,7 +202,7 @@ class RecordTimer(timer.Timer):
                        self.loadTimer()
                except IOError:
                        print "unable to load timers from file!"
-                       
+
        def isRecording(self):
                isRunning = False
                for timer in self.timer_list:
@@ -178,14 +232,23 @@ class RecordTimer(timer.Timer):
                        t = doc.createTextNode("\t")
                        root_element.appendChild(t)
                        t = doc.createElement('timer')
-                       t.setAttribute("begin", str(timer.begin))
-                       t.setAttribute("end", str(timer.end))
+                       t.setAttribute("begin", str(int(timer.begin)))
+                       t.setAttribute("end", str(int(timer.end)))
                        t.setAttribute("serviceref", str(timer.service_ref))
                        t.setAttribute("repeated", str(timer.repeated))                 
                        t.setAttribute("name", timer.name)
                        t.setAttribute("description", timer.description)
                        t.setAttribute("eit", str(timer.eit))
                        
+                       for time, code, msg in timer.log_entries:
+                               t.appendChild(doc.createTextNode("\t\t"))
+                               l = doc.createElement('log')
+                               l.setAttribute("time", str(time))
+                               l.setAttribute("code", str(code))
+                               l.appendChild(doc.createTextNode(msg))
+                               t.appendChild(l)
+                               t.appendChild(doc.createTextNode("\n"))
+
                        root_element.appendChild(t)
                        t = doc.createTextNode("\n")
                        root_element.appendChild(t)
@@ -194,8 +257,9 @@ class RecordTimer(timer.Timer):
                doc.writexml(file)
                file.write("\n")
                file.close()
-       
+
        def record(self, entry):
+               entry.timeChanged()
                print "[Timer] Record " + str(entry)
                entry.Timer = self
                self.addTimerEntry(entry)
@@ -203,23 +267,15 @@ class RecordTimer(timer.Timer):
        def removeEntry(self, entry):
                print "[Timer] Remove " + str(entry)
                
+               # avoid re-enqueuing
                entry.repeated = False
 
-               if entry.state == timer.TimerEntry.StateRunning:
-                       print "remove running timer."
-                       entry.end = time.time()
+               # abort timer.
+               # this sets the end time to current time, so timer will be stopped.
+               entry.abort()
+               
+               if entry.state != entry.StateEnded:
                        self.timeChanged(entry)
-               elif entry.state != timer.TimerEntry.StateEnded:
-                       entry.activate(timer.TimerEntry.EventAbort)
-                       self.timer_list.remove(entry)
-
-                       self.calcNextActivation()
-                       print "timer did not yet start - removing"
-
-                       # the timer was aborted, and removed.
-                       return
-               else:
-                       print "timer did already end - doing nothing."
                
                print "state: ", entry.state
                print "in processed: ", entry in self.processed_timers
index 87ecfa9..c8e7854 100644 (file)
--- a/timer.py
+++ b/timer.py
@@ -3,15 +3,10 @@ import time
 from enigma import *
 
 class TimerEntry:
-       EventPrepare = 0
-       EventStart   = 1
-       EventEnd     = 2
-       EventAbort   = 3
-       
-       StateWait    = 0
-       StatePrepare = 1
-       StateRunning = 2
-       StateEnded   = 3
+       StateWaiting  = 0
+       StatePrepared = 1
+       StateRunning  = 2
+       StateEnded    = 3
        
        def __init__(self, begin, end):
                self.begin = begin
@@ -19,10 +14,11 @@ class TimerEntry:
                self.end = end
                self.state = 0
                self.resetRepeated()
+               self.backoff = 0
                
        def resetRepeated(self):
                self.repeated = int(0)
-               
+
        def setRepeated(self, day):
                self.repeated |= (2 ** day)
                print "Repeated: " + str(self.repeated)
@@ -58,22 +54,34 @@ class TimerEntry:
                                self.begin += 86400
                                self.end += 86400
 
-       def getTime(self):
-               if self.state == self.StateWait:
-                       return self.begin - self.prepare_time
-               elif self.state == self.StatePrepare:
-                       return self.begin
-               else:
-                       return self.end 
-       
        def __lt__(self, o):
-               return self.getTime() < o.getTime()
+               return self.getNextActivation() < o.getNextActivation()
        
-       def activate(self, event):
-               print "[timer.py] timer %s got activated (%d)!" % (self.description, event)
+       # must be overridden
+       def activate(self):
+               pass
+               
+       # can be overridden
+       def timeChanged(self):
+               pass
 
-class Timer:
+       # check if a timer entry must be skipped
+       def shouldSkip(self):
+               return self.end <= time.time() and self.state == TimerEntry.StateWaiting
 
+       def abort(self):
+               self.end = time.time()
+               
+               # in case timer has not yet started, but gets aborted (so it's preparing),
+               # set begin to now.
+               if self.begin > self.end:
+                       self.begin = self.end
+       
+       # must be overridden!
+       def getNextActivation():
+               pass
+
+class Timer:
        # the time between "polls". We do this because
        # we want to account for time jumps etc.
        # of course if they occur <100s before starting,
@@ -95,13 +103,17 @@ class Timer:
                
                self.calcNextActivation()
        
+       def stateChanged(self, entry):
+               pass
+       
        def addTimerEntry(self, entry, noRecalc=0):
                entry.processRepeated()
 
                # when the timer has not yet started, and is already passed,
                # don't go trough waiting/running/end-states, but sort it
                # right into the processedTimers.
-               if entry.end <= time.time() and entry.state == TimerEntry.StateWait:
+               if entry.shouldSkip() or entry.state == TimerEntry.StateEnded:
+                       print "already passed, skipping"
                        bisect.insort(self.processed_timers, entry)
                        entry.state = TimerEntry.StateEnded
                else:
@@ -123,7 +135,7 @@ class Timer:
                        self.processed_timers = [ ]
                        for x in tl:
                                # simulate a "waiting" state to give them a chance to re-occure
-                               x.state = TimerEntry.StateWaiting
+                               x.resetState()
                                self.addTimerEntry(x, noRecalc=1)
                
                self.processActivation()
@@ -133,35 +145,52 @@ class Timer:
                
                # calculate next activation point
                if len(self.timer_list):
-                       w = self.timer_list[0].getTime()
+                       w = self.timer_list[0].getNextActivation()
                        if w < min:
                                min = w
                
                self.setNextActivation(min)
        
        def timeChanged(self, timer):
+               timer.timeChanged()
                self.timer_list.remove(timer)
 
                self.addTimerEntry(timer)
        
        def doActivate(self, w):
-               w.activate(w.state)
                self.timer_list.remove(w)
                
-               w.state += 1
+               # when activating a timer which has already passed,
+               # simply abort the timer. don't run trough all the stages.
+               if w.shouldSkip():
+                       w.abort()
+                       bisect.insort(self.processed_timers, w)
+               else:
+                       # when active returns true, this means "accepted".
+                       # otherwise, the current state is kept.
+                       # the timer entry itself will fix up the delay then.
+                       if w.activate():
+                               w.state += 1
+
+               # did this timer reached the last state?
                if w.state < TimerEntry.StateEnded:
+                       # no, sort it into active list
                        bisect.insort(self.timer_list, w)
                else:
-                       if (w.repeated != 0):
+                       # yes. Process repeated, and re-add.
+                       if not w.repeated:
                                w.processRepeated()
-                               w.state = TimerEntry.StateWait
+                               w.state = TimerEntry.StateWaiting
                                self.addTimerEntry(w)
                        else:
                                bisect.insort(self.processed_timers, w)
+               
+               self.stateChanged(w)
 
        def processActivation(self):
+               print "It's now ", time.strftime("%c", time.localtime(time.time()))
                t = int(time.time()) + 1
                
                # we keep on processing the first entry until it goes into the future.
-               while len(self.timer_list) and self.timer_list[0].getTime() < t:
+               while len(self.timer_list) and self.timer_list[0].getNextActivation() < t:
                        self.doActivate(self.timer_list[0])