From 8a6e44c53a3fb23ca87645fdfad73652a202b905 Mon Sep 17 00:00:00 2001 From: Felix Domke Date: Sun, 15 Jan 2006 12:10:46 +0000 Subject: [PATCH] improved timer: logging, better error recovery --- RecordTimer.py | 182 ++++++++++++++++++++++++++++++++----------------- timer.py | 89 ++++++++++++++++-------- 2 files changed, 178 insertions(+), 93 deletions(-) diff --git a/RecordTimer.py b/RecordTimer.py index 2234bfc3..e375c9f2 100644 --- a/RecordTimer.py +++ b/RecordTimer.py @@ -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 diff --git a/timer.py b/timer.py index 87ecfa93..c8e78549 100644 --- 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]) -- 2.30.2