Everything is loging with the logging module
authorJason Michalski <armooo@armooo.net>
Mon, 7 Apr 2008 03:46:43 +0000 (6 22:46 -0500)
committerJason Michalski <armooo@armooo.net>
Mon, 7 Apr 2008 03:46:43 +0000 (6 22:46 -0500)
Currently everything is always in debug mode

beacon.py
config.py
debug.py [deleted file]
httpserver.py
mind.py
plugins/admin/admin.py
plugins/video/transcode.py
plugins/video/video.py
plugins/webvideo/webvideo.py
pyTivo.py

index c322514..ed02aeb 100644 (file)
--- a/beacon.py
+++ b/beacon.py
@@ -11,7 +11,7 @@ class Beacon:
     def add_service(self, service):
         self.services.append(service)
         self.send_beacon()
-        
+
     def format_services(self):
         return ';'.join(self.services)
 
index eadb710..c5af5cc 100644 (file)
--- a/config.py
+++ b/config.py
@@ -61,8 +61,15 @@ def get169Setting(tsn):
 
 def getShares(tsn=''):
     shares = [(section, dict(config.items(section)))
-              for section in config.sections()
-              if not(section.startswith('_tivo_') or section == 'Server')]
+                for section in config.sections()
+                if not (
+                    section.startswith('_tivo_')
+                    or section in ('Server', 'loggers', 'handlers', 'formatters')
+                    or section.startswith('logger_')
+                    or section.startswith('handler_')
+                    or section.startswith('formatter_')
+                )
+    ]
 
     if config.has_section('_tivo_' + tsn):
         if config.has_option('_tivo_' + tsn, 'shares'):
@@ -314,7 +321,7 @@ def getVideoFPS(tsn = None):
         return config.get('Server', 'video_fps')
     except NoOptionError:
         return None
-    
+
 def getVideoCodec(tsn = None):
     if tsn and config.has_section('_tivo_' + tsn):
         try:
diff --git a/debug.py b/debug.py
deleted file mode 100644 (file)
index fbb9e7c..0000000
--- a/debug.py
+++ /dev/null
@@ -1,48 +0,0 @@
-import ConfigParser, os, re, sys
-import config
-import datetime 
-
-p = os.path.dirname(__file__)
-
-def debug_write(srcMod, fnAttr, data):
-    if config.getDebug(0).lower() == 'true':
-        debug_out = []
-        modname=srcMod.split('.')[-1]
-        debug_out.append(modname+'.'+fnAttr[1]+' ['+fnAttr[0]+'] ')
-        for x in data:
-            debug_out.append(str(x))
-        fpath = p
-        fname = []
-        fname.append('debug')
-        if not config.getDebug(1) == '' or not config.getDebug(2) == '':
-            if os.path.isdir(config.getDebug(1)):
-                fpath = config.getDebug(1)
-            fname.append(os.path.split(os.path.dirname(__file__))[-1])
-            if config.getDebug(2).lower() == 'split': 
-                fname.append(modname)
-        fname.append('txt')
-        fdebug = open(os.path.join(fpath, '.'.join(fname)), 'a')
-        fdebug.write(' '.join(debug_out)+'\n')
-        print '___'+' '.join(debug_out)
-        fdebug.close()
-
-def fn_attr():
-    "returns name of calling function and line number"
-    return sys._getframe(1).f_code.co_name, str(sys._getframe(1).f_lineno)
-
-def print_conf(srcMod, fnAttr):
-    if config.getDebug(0).lower() == 'true':
-        debug_write(srcMod, fnAttr, ['********************************************************']) 
-        debug_write(srcMod, fnAttr, ['**  Begin pyTivo Session:', datetime.datetime.today(), ' **']) 
-        debug_write(srcMod, fnAttr, ['********************************************************']) 
-        debug_write(srcMod, fnAttr, ['----- begin pyTivo.conf -----'])
-        conf = open(os.path.join(p, 'pyTivo.conf'))
-        for line in conf.readlines():
-            if line.strip().startswith('#'):
-                continue
-            if len(line.strip()) != 0:
-                debug_write(srcMod, fnAttr, [line.strip()])
-        conf.close()
-        debug_write(srcMod, fnAttr, ['------- end pyTivo.conf -----'])
-
-print_conf(__name__, fn_attr())
index bc69488..6ea3a41 100644 (file)
@@ -6,7 +6,7 @@ from Cheetah.Template import Template
 from plugin import GetPlugin
 import config
 from xml.sax.saxutils import escape
-from debug import debug_write, fn_attr
+import logging
 
 SCRIPTDIR = os.path.dirname(__file__)
 
@@ -45,7 +45,7 @@ class TivoHTTPHandler(BaseHTTPServer.BaseHTTPRequestHandler):
         tsn = self.headers.getheader('TiVo_TCD_ID', self.headers.getheader('tsn', ''))
         ip = self.address_string()
         self.tivos[tsn] = ip
-               
+
         basepath = unquote_plus(self.path).split('/')[1]
 
         ## Get File
@@ -72,7 +72,7 @@ class TivoHTTPHandler(BaseHTTPServer.BaseHTTPRequestHandler):
             if command == "QueryContainer" and \
                (not query.has_key('Container') or query['Container'][0] == '/'):
                 self.root_container()
-                return 
+                return
 
             if query.has_key('Container'):
                 # Dispatch to the container plugin
@@ -87,7 +87,7 @@ class TivoHTTPHandler(BaseHTTPServer.BaseHTTPRequestHandler):
                         else:
                             break
 
-        # If we made it here it means we couldn't match the request to 
+        # If we made it here it means we couldn't match the request to
         # anything.
         self.unsupported(query)
 
@@ -134,21 +134,20 @@ class TivoHTTPHandler(BaseHTTPServer.BaseHTTPRequestHandler):
             if settings.get('type') == 'video':
                 t.shares += '<a href="TiVoConnect?Command=QueryContainer&Container=' + section\
                     + '">' +  section + '</a><br/>'
-        
+
         self.wfile.write(t)
         self.end_headers()
 
     def unsupported(self, query):
         if hack83 and 'Command' in query and 'Filter' in query:
-            debug_write(__name__, fn_attr(), ['Unsupported request,',
-                         'checking to see if it is video.'])
+            logger = logging.getLogger('pyTivo.hack83')
+
+            logger.debug('Unsupported request checking to see if it is video.')
             command = query['Command'][0]
             plugin = GetPlugin('video')
             if ''.join(query['Filter']).find('video') >= 0 and \
                hasattr(plugin, command):
-                debug_write(__name__, fn_attr(), ['Unsupported request,',
-                             'yup it is video',
-                             'send to video plugin for it to sort out.'])
+                logger.debug('Unsupported request yup it is video send to video plugin for it to sort out.')
                 method = getattr(plugin, command)
                 method(self, query)
                 return
diff --git a/mind.py b/mind.py
index 86a9134..761b963 100644 (file)
--- a/mind.py
+++ b/mind.py
@@ -7,6 +7,7 @@ import time
 import warnings
 import itertools
 import config
+import logging
 
 try:
     import xml.etree.ElementTree as ElementTree
@@ -25,14 +26,13 @@ if 'ElementTree' not in locals():
 else:
 
     class Mind:
-        def __init__(self, username, password, debug=False):
+        def __init__(self, username, password):
+            self.__logger = logging.getLogger('pyTivo.mind')
             self.__username = username
             self.__password = password
 
-            self.__debug = debug
-
             self.__cj = cookielib.CookieJar()
-            self.__opener = urllib2.build_opener(urllib2.HTTPSHandler(debuglevel=1), urllib2.HTTPCookieProcessor(self.__cj))
+            self.__opener = urllib2.build_opener(urllib2.HTTPCookieProcessor(self.__cj))
 
             self.__login()
 
@@ -120,11 +120,6 @@ else:
 
             return results
 
-        def __log(self, message):
-            if self.__debug:
-                print message
-                print
-
         def __login(self):
 
             data = {
@@ -144,7 +139,7 @@ else:
             except:
                 pass
 
-            self.__log('__login\n%s' % (data))
+            self.__logger.debug('__login\n%s' % (data))
 
         def __bodyOfferModify(self, data):
             """Create an offer"""
@@ -157,7 +152,7 @@ else:
 
             xml = ElementTree.parse(result).find('.')
 
-            self.__log('__bodyOfferModify\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
+            self.__logger.debug('__bodyOfferModify\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
 
             if xml.findtext('state') != 'complete':
                 raise Exception(ElementTree.tostring(xml))
@@ -190,7 +185,7 @@ else:
 
             xml = ElementTree.parse(result).find('.')
 
-            self.__log('__subscribe\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
+            self.__logger.debug('__subscribe\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
 
             return xml
 
@@ -207,7 +202,7 @@ else:
 
             xml = ElementTree.parse(result).find('.')
 
-            self.__log('bodyOfferSchedule\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
+            self.__logger.debug('bodyOfferSchedule\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
 
             return xml
 
@@ -225,7 +220,7 @@ else:
             xml = ElementTree.parse(result).find('.')
 
 
-            self.__log('__pcBodySearch\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
+            self.__logger.debug('__pcBodySearch\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
 
             return [id.text for id in xml.findall('pcBody/pcBodyId')]
 
@@ -243,7 +238,7 @@ else:
             xml = ElementTree.parse( result ).find('.')
             collection_id = xml.findtext('collectionId')
 
-            self.__log('__collectionIdSearch\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
+            self.__logger.debug('__collectionIdSearch\n%s\n\n%sg' % (data, ElementTree.tostring(xml)))
 
             return collection_id
 
@@ -264,7 +259,7 @@ else:
 
             xml = ElementTree.parse(result).find('.')
 
-            self.__log('__pcBodySearch\n%s\n\n%s' % (data, ElementTree.tostring(xml)))
+            self.__logger.debug('__pcBodySearch\n%s\n\n%s' % (data, ElementTree.tostring(xml)))
 
             return xml
 
@@ -284,7 +279,7 @@ else:
 
             xml = ElementTree.parse(result).find('.')
 
-            self.__log('__bodyXmppInfoGe\n%s\n\n%s' % (data, ElementTree.tostring(xml)))
+            self.__logger.debug('__bodyXmppInfoGe\n%s\n\n%s' % (data, ElementTree.tostring(xml)))
 
             return xml
 
@@ -352,7 +347,7 @@ def getMind():
     if not username or not password:
        raise Exception("tivo_username and tivo_password required")
 
-    m = Mind(username, password, True)
+    m = Mind(username, password)
 
     return m
 
index 7ff7935..7b33f0a 100644 (file)
@@ -8,7 +8,7 @@ from urllib import unquote_plus, quote, unquote
 from urlparse import urlparse
 from xml.sax.saxutils import escape
 from lrucache import LRUCache
-import debug
+import logging
 
 SCRIPTDIR = os.path.dirname(__file__)
 
@@ -34,7 +34,7 @@ class Admin(Plugin):
             last_page = query['last_page'][0]
         else:
             last_page = 'Admin'
-        
+
         subcname = query['Container'][0]
         cname = subcname.split('/')[0]
         handler.send_response(200)
@@ -47,9 +47,8 @@ class Admin(Plugin):
                  'file and all changed should now be in effect. <br> The'+ \
                  '<a href="/TiVoConnect?Command='+ last_page +'&Container='+ cname +'"> previous</a> page will reload in 3 seconds.'
         handler.wfile.write(t)
-        debug.debug_write(__name__, debug.fn_attr(), ['The pyTivo Server has been soft reset.'])
-        debug.print_conf(__name__, debug.fn_attr())
-    
+        logging.getLogger('pyTivo.admin').info('The pyTivo Server has been soft reset.')
+
     def Admin(self, handler, query):
         #Read config file new each time in case there was any outside edits
         config = ConfigParser.ConfigParser()
@@ -62,7 +61,7 @@ class Admin(Plugin):
                     shares_data.append((section, dict(config.items(section, raw=True))))
                 elif config.get(section,'type').lower() != 'admin':
                     shares_data.append((section, dict(config.items(section, raw=True))))
-        
+
         subcname = query['Container'][0]
         cname = subcname.split('/')[0]
         handler.send_response(200)
@@ -92,12 +91,12 @@ class Admin(Plugin):
                     new_value = query[key][0]
                     continue
                 if query[key][0] == " ":
-                    config.remove_option(section, option)                      
+                    config.remove_option(section, option)
                 else:
                     config.set(section, option, query[key][0])
         if not(new_setting == ' ' and new_value == ' '):
             config.set('Server', new_setting, new_value)
-           
+
         sections = query['Section_Map'][0].split(']')
         sections.pop() #last item is junk
         for section in sections:
@@ -118,7 +117,7 @@ class Admin(Plugin):
                         new_value = query[key][0]
                         continue
                     if query[key][0] == " ":
-                        config.remove_option(query[ID][0], option)                      
+                        config.remove_option(query[ID][0], option)
                     else:
                         config.set(query[ID][0], option, query[key][0])
             if not(new_setting == ' ' and new_value == ' '):
@@ -141,7 +140,7 @@ class Admin(Plugin):
                  'However you will need to do a <b>Soft Reset</b> before these changes will take effect.'+\
                  '<br> The <a href="/TiVoConnect?Command=Admin&Container='+ cname +'"> Admin</a> page will reload in 10 seconds.'
         handler.wfile.write(t)
-        
+
     def NPL(self, handler, query):
         shows_per_page = 50 #Change this to alter the number of shows returned per page
         subcname = query['Container'][0]
@@ -196,7 +195,7 @@ class Admin(Plugin):
                                  '<br>This most likely caused by an incorrect Media Access Key.  Please return to the ToGo page and double check your Media Access Key.' +\
                                  '<br> The <a href="/TiVoConnect?Command=NPL&Container='+ cname + '"> ToGo</a> page will reload in 20 seconds.'
                         handler.wfile.write(t)
-                        return 
+                        return
                     tivo_cache[theurl]['thepage'] = handle.read()
                     tivo_cache[theurl]['thepage_time'] = time.time()
             else: #not in cache
@@ -255,7 +254,7 @@ class Admin(Plugin):
                                         + str((int(entry['Duration'])%(60*60*1000))/(60*1000)).zfill(2) + ':' \
                                         + str((int(entry['Duration'])/1000)%60).zfill(2)
                     entry['CaptureDate'] = time.strftime("%b %d, %Y", time.localtime(int(entry['CaptureDate'], 16)))
-                            
+
                 data.append(entry)
         else:
             data = []
@@ -358,7 +357,7 @@ class Admin(Plugin):
             status[theurl] = {'running':True, 'error':'', 'rate':'', 'finished':False}
 
             thread.start_new_thread(Admin.get_tivo_file, (self, theurl, password, tivoIP, outfile))
-            
+
             handler.send_response(200)
             handler.end_headers()
             t = Template(file=os.path.join(SCRIPTDIR,'templates', 'redirect.tmpl'))
@@ -382,9 +381,9 @@ class Admin(Plugin):
     def ToGoStop(self, handler, query):
         parse_url = urlparse(str(query['Url'][0]))
         theurl = 'http://' + parse_url[1].split(':')[0] + parse_url[2] + "?" + parse_url[4]
-        
+
         status[theurl]['running'] = False
-        
+
         subcname = query['Container'][0]
         cname = subcname.split('/')[0]
         handler.send_response(200)
@@ -404,7 +403,7 @@ class Admin(Plugin):
         if 'tivo_mak' in query:
             config.set(query['Container'][0], 'tivo_mak', query['tivo_mak'][0])
         if 'togo_path' in query:
-            config.set(query['Container'][0], 'togo_path', query['togo_path'][0])                 
+            config.set(query['Container'][0], 'togo_path', query['togo_path'][0])
         f = open(config_file_path, "w")
         config.write(f)
         f.close()
index 33743e9..882927a 100644 (file)
@@ -1,6 +1,8 @@
 import subprocess, shutil, os, re, sys, ConfigParser, time, lrucache, math
 import config
-from debug import debug_write, fn_attr
+import logging
+
+logger = logging.getLogger('pyTivo.video.transcode')
 
 info_cache = lrucache.LRUCache(1000)
 videotest = os.path.join(os.path.dirname(__file__), 'videotest.mpg')
@@ -26,12 +28,12 @@ if mswindows:
 
 def output_video(inFile, outFile, tsn=''):
     if tivo_compatable(inFile, tsn):
-        debug_write(__name__, fn_attr(), [inFile, ' is tivo compatible'])
+        logger.debug('%s is tivo compatible' % inFile)
         f = file(inFile, 'rb')
         shutil.copyfileobj(f, outFile)
-        f.close() 
+        f.close()
     else:
-        debug_write(__name__, fn_attr(), [inFile, ' is not tivo compatible'])
+        logger.debug('%s is not tivo compatible' % inFile)
         transcode(inFile, outFile, tsn)
 
 def transcode(inFile, outFile, tsn=''):
@@ -53,9 +55,8 @@ def transcode(inFile, outFile, tsn=''):
     cmd_string = config.getFFmpegTemplate(tsn) % settings
 
     cmd = [ffmpeg_path(), '-i', inFile] + cmd_string.split()
-    print 'transcoding to tivo model '+tsn[:3]+' using ffmpeg command:'
-    print ' '.join(cmd)
-    debug_write(__name__, fn_attr(), ['ffmpeg command is ', ' '.join(cmd)])
+    logging.debug('transcoding to tivo model '+tsn[:3]+' using ffmpeg command:')
+    logging.debug(' '.join(cmd))
     ffmpeg = subprocess.Popen(cmd, stdout=subprocess.PIPE)
     try:
         shutil.copyfileobj(ffmpeg.stdout, outFile)
@@ -138,15 +139,15 @@ def select_aspect(inFile, tsn = ''):
 
     type, width, height, fps, millisecs, kbps, akbps, acodec, afreq, vpar =  video_info(inFile)
 
-    debug_write(__name__, fn_attr(), ['tsn:', tsn])
+    logging.debug('tsn: %s' % tsn)
 
     aspect169 = config.get169Setting(tsn)
 
-    debug_write(__name__, fn_attr(), ['aspect169:', aspect169])
+    logging.debug('aspect169:%s' % aspect169)
 
     optres = config.getOptres(tsn)
 
-    debug_write(__name__, fn_attr(), ['optres:', optres])
+    logging.debug('optres:%s' % optres)
 
     if optres:
         optHeight = config.nearestTivoHeight(height)
@@ -160,7 +161,7 @@ def select_aspect(inFile, tsn = ''):
     ratio = (width*100)/height
     rheight, rwidth = height/d, width/d
 
-    debug_write(__name__, fn_attr(), ['File=', inFile, ' Type=', type, ' width=', width, ' height=', height, ' fps=', fps, ' millisecs=', millisecs, ' ratio=', ratio, ' rheight=', rheight, ' rwidth=', rwidth, ' TIVO_HEIGHT=', TIVO_HEIGHT, 'TIVO_WIDTH=', TIVO_WIDTH])
+    logger.debug(' '.join(['File=', inFile, ' Type=', type, ' width=', width, ' height=', height, ' fps=', fps, ' millisecs=', millisecs, ' ratio=', ratio, ' rheight=', rheight, ' rwidth=', rwidth, ' TIVO_HEIGHT=', TIVO_HEIGHT, 'TIVO_WIDTH=', TIVO_WIDTH]))
 
     multiplier16by9 = (16.0 * TIVO_HEIGHT) / (9.0 * TIVO_WIDTH)
     multiplier4by3  =  (4.0 * TIVO_HEIGHT) / (3.0 * TIVO_WIDTH)
@@ -182,16 +183,16 @@ def select_aspect(inFile, tsn = ''):
             return []
         # else, resize video.
     if (rwidth, rheight) in [(4, 3), (10, 11), (15, 11), (59, 54), (59, 72), (59, 36), (59, 54)]:
-        debug_write(__name__, fn_attr(), ['File is within 4:3 list.'])
+        logger.debug('File is within 4:3 list.')
         return ['-aspect', '4:3', '-s', str(TIVO_WIDTH) + 'x' + str(TIVO_HEIGHT)]
     elif ((rwidth, rheight) in [(16, 9), (20, 11), (40, 33), (118, 81), (59, 27)]) and aspect169:
-        debug_write(__name__, fn_attr(), ['File is within 16:9 list and 16:9 allowed.'])
+        logger.debug('File is within 16:9 list and 16:9 allowed.')
         return ['-aspect', '16:9', '-s', str(TIVO_WIDTH) + 'x' + str(TIVO_HEIGHT)]
     else:
         settings = []
         #If video is wider than 4:3 add top and bottom padding
         if (ratio > 133): #Might be 16:9 file, or just need padding on top and bottom
-            if aspect169 and (ratio > 135): #If file would fall in 4:3 assume it is supposed to be 4:3 
+            if aspect169 and (ratio > 135): #If file would fall in 4:3 assume it is supposed to be 4:3
                 if (ratio > 177):#too short needs padding top and bottom
                     endHeight = int(((TIVO_WIDTH*height)/width) * multiplier16by9)
                     settings.append('-aspect')
@@ -205,7 +206,7 @@ def select_aspect(inFile, tsn = ''):
                         topPadding = ((TIVO_HEIGHT - endHeight)/2)
                         if topPadding % 2:
                             topPadding -= 1
-                        
+
                         settings.append('-padtop')
                         settings.append(str(topPadding))
                         bottomPadding = (TIVO_HEIGHT - endHeight) - topPadding
@@ -214,7 +215,7 @@ def select_aspect(inFile, tsn = ''):
                     else:   #if only very small amount of padding needed, then just stretch it
                         settings.append('-s')
                         settings.append(str(TIVO_WIDTH) + 'x' + str(TIVO_HEIGHT))
-                    debug_write(__name__, fn_attr(), ['16:9 aspect allowed, file is wider than 16:9 padding top and bottom', ' '.join(settings)])
+                    logger.debug('16:9 aspect allowed, file is wider than 16:9 padding top and bottom\n%s' % ' '.join(settings))
                 else: #too skinny needs padding on left and right.
                     endWidth = int((TIVO_HEIGHT*width)/(height*multiplier16by9))
                     settings.append('-aspect')
@@ -237,7 +238,7 @@ def select_aspect(inFile, tsn = ''):
                     else: #if only very small amount of padding needed, then just stretch it
                         settings.append('-s')
                         settings.append(str(TIVO_WIDTH) + 'x' + str(TIVO_HEIGHT))
-                    debug_write(__name__, fn_attr(), ['16:9 aspect allowed, file is narrower than 16:9 padding left and right\n', ' '.join(settings)])
+                    logger.debug('16:9 aspect allowed, file is narrower than 16:9 padding left and right\n%s' % ' '.join(settings))
             else: #this is a 4:3 file or 16:9 output not allowed
                 settings.append('-aspect')
                 settings.append('4:3')
@@ -251,7 +252,7 @@ def select_aspect(inFile, tsn = ''):
                     topPadding = ((TIVO_HEIGHT - endHeight)/2)
                     if topPadding % 2:
                         topPadding -= 1
-                    
+
                     settings.append('-padtop')
                     settings.append(str(topPadding))
                     bottomPadding = (TIVO_HEIGHT - endHeight) - topPadding
@@ -260,7 +261,7 @@ def select_aspect(inFile, tsn = ''):
                 else:   #if only very small amount of padding needed, then just stretch it
                     settings.append('-s')
                     settings.append(str(TIVO_WIDTH) + 'x' + str(TIVO_HEIGHT))
-                debug_write(__name__, fn_attr(), ['File is wider than 4:3 padding top and bottom\n', ' '.join(settings)])
+                logging.debug('File is wider than 4:3 padding top and bottom\n%s' %  ' '.join(settings))
 
             return settings
         #If video is taller than 4:3 add left and right padding, this is rare. All of these files will always be sent in
@@ -288,8 +289,8 @@ def select_aspect(inFile, tsn = ''):
                 settings.append('-s')
                 settings.append(str(TIVO_WIDTH) + 'x' + str(TIVO_HEIGHT))
 
-            debug_write(__name__, fn_attr(), ['File is taller than 4:3 padding left and right\n', ' '.join(settings)])
-            
+            logger.debug_write('File is taller than 4:3 padding left and right\n%s' % ' '.join(settings))
+
             return settings
 
 def tivo_compatable(inFile, tsn = ''):
@@ -298,73 +299,71 @@ def tivo_compatable(inFile, tsn = ''):
     #print type, width, height, fps, millisecs, kbps, akbps, acodec
 
     if (inFile[-5:]).lower() == '.tivo':
-        debug_write(__name__, fn_attr(), ['TRUE, ends with .tivo.', inFile])
+        logger.debug('TRUE, ends with .tivo. %s' % inFile)
         return True
 
     if not type == 'mpeg2video':
         #print 'Not Tivo Codec'
-        debug_write(__name__, fn_attr(), ['FALSE, type', type, 'not mpeg2video.', inFile])
+        logger.debug('FALSE, type %s not mpeg2video. %s' % (type, inFile))
         return False
 
     if os.path.splitext(inFile)[-1].lower() in ('.ts', '.mpv'):
-        debug_write(__name__, fn_attr(), ['FALSE, ext', os.path.splitext(inFile)[-1],\
-                'not tivo compatible.', inFile])
+        logger.debug('FALSE, ext %s not tivo compatible. %s' % (os.path.splitext(inFile)[-1], inFile))
         return False
 
     if acodec == 'dca':
-        debug_write(__name__, fn_attr(), ['FALSE, acodec', acodec, ', not supported.', inFile])
+        logger.debug('FALSE, acodec %s not supported. %s' % (acodec, inFile))
         return False
 
     if acodec != None:
         if not akbps or int(akbps) > config.getMaxAudioBR(tsn):
-            debug_write(__name__, fn_attr(), ['FALSE,', akbps, 'kbps exceeds max audio bitrate.', inFile])
+            logger.debug('FALSE, %s kbps exceeds max audio bitrate. %s' % (akbps, inFile))
             return False
 
     if kbps != None:
         abit = max('0', akbps)
         if int(kbps)-int(abit) > config.strtod(config.getMaxVideoBR())/1000:
-            debug_write(__name__, fn_attr(), ['FALSE,', kbps, 'kbps exceeds max video bitrate.', inFile])
+            logger.debug('FALSE, %s kbps exceeds max video bitrate. %s' % (kbps, inFile))
             return False
     else:
-        debug_write(__name__, fn_attr(), ['FALSE,', kbps, 'kbps not supported.', inFile])
+        logger.debug('FALSE, %s kbps not supported. %s' % (kbps, inFile))
         return False
 
     if config.isHDtivo(tsn):
         if vpar != 1.0:
             if config.getPixelAR(0):
                 if vpar != None or config.getPixelAR(1) != 1.0:
-                    debug_write(__name__, fn_attr(), ['FALSE,', vpar, 'not correct PAR,', inFile])
+                    logger.debug('FALSE, %s not correct PAR, %s' % (vpar, inFile))
                     return False
-        debug_write(__name__, fn_attr(), ['TRUE, HD Tivo detected, skipping remaining tests', inFile])
+        logger.debug('TRUE, HD Tivo detected, skipping remaining tests %s' % inFile)
         return True
 
     if not fps == '29.97':
         #print 'Not Tivo fps'
-        debug_write(__name__, fn_attr(), ['FALSE,', fps, 'fps, should be 29.97.', inFile])
+        logger.debug('FALSE, %s fps, should be 29.97. %s' % (fps, inFile))
         return False
 
     for mode in supportedModes:
         if (mode[0], mode[1]) == (width, height):
-            #print 'Is TiVo!'
-            debug_write(__name__, fn_attr(), ['TRUE,', width, 'x', height, 'is valid.', inFile])
+            logger.debug('TRUE, %s x %s is valid. %s' % (width, height, inFile))
             return True
     #print 'Not Tivo dimensions'
-    debug_write(__name__, fn_attr(), ['FALSE,', width, 'x', height, 'not in supported modes.', inFile])
+    logger.debug('FALSE, %s x %s not in supported modes. %s' % (width, height, inFile))
     return False
 
 def video_info(inFile):
     mtime = os.stat(inFile).st_mtime
     if inFile != videotest:
         if inFile in info_cache and info_cache[inFile][0] == mtime:
-            debug_write(__name__, fn_attr(), ['CACHE HIT!', inFile])
+            logging.debug('CACHE HIT! %s' % inFile)
             return info_cache[inFile][1]
 
     if (inFile[-5:]).lower() == '.tivo':
         info_cache[inFile] = (mtime, (True, True, True, True, True, True, True, True, True, True))
-        debug_write(__name__, fn_attr(), ['VALID, ends in .tivo.', inFile])
+        logger.debug('VALID, ends in .tivo. %s' % inFile)
         return True, True, True, True, True, True, True, True, True, True
 
-    cmd = [ffmpeg_path(), '-i', inFile ] 
+    cmd = [ffmpeg_path(), '-i', inFile ]
     ffmpeg = subprocess.Popen(cmd, stderr=subprocess.PIPE, stdout=subprocess.PIPE, stdin=subprocess.PIPE)
 
     # wait 10 sec if ffmpeg is not back give up
@@ -372,14 +371,14 @@ def video_info(inFile):
         time.sleep(.05)
         if not ffmpeg.poll() == None:
             break
-    
+
     if ffmpeg.poll() == None:
         kill(ffmpeg.pid)
         info_cache[inFile] = (mtime, (None, None, None, None, None, None, None, None, None, None))
         return None, None, None, None, None, None, None, None, None, None
 
     output = ffmpeg.stderr.read()
-    debug_write(__name__, fn_attr(), ['ffmpeg output=', output])
+    logging.debug('ffmpeg output=%s' % output)
 
     rezre = re.compile(r'.*Video: ([^,]+),.*')
     x = rezre.search(output)
@@ -387,7 +386,7 @@ def video_info(inFile):
         codec = x.group(1)
     else:
         info_cache[inFile] = (mtime, (None, None, None, None, None, None, None, None, None, None))
-        debug_write(__name__, fn_attr(), ['failed at video codec'])
+        logging.debug('failed at video codec')
         return None, None, None, None, None, None, None, None, None, None
 
     rezre = re.compile(r'.*Video: .+, (\d+)x(\d+)[, ].*')
@@ -397,7 +396,7 @@ def video_info(inFile):
         height = int(x.group(2))
     else:
         info_cache[inFile] = (mtime, (None, None, None, None, None, None, None, None, None, None))
-        debug_write(__name__, fn_attr(), ['failed at width/height'])
+        logger.debug('failed at width/height')
         return None, None, None, None, None, None, None, None, None, None
 
     rezre = re.compile(r'.*Video: .+, (.+) (?:fps|tb).*')
@@ -406,7 +405,7 @@ def video_info(inFile):
         fps = x.group(1)
     else:
         info_cache[inFile] = (mtime, (None, None, None, None, None, None, None, None, None, None))
-        debug_write(__name__, fn_attr(), ['failed at fps'])
+        logging.debug('failed at fps')
         return None, None, None, None, None, None, None, None, None, None
 
     # Allow override only if it is mpeg2 and frame rate was doubled to 59.94
@@ -415,12 +414,12 @@ def video_info(inFile):
         rezre = re.compile(r'.*film source: 29.97.*')
         x = rezre.search(output.lower() )
         if x:
-            debug_write(__name__, fn_attr(), ['film source: 29.97 setting fps to 29.97'])
+            logger.debug('film source: 29.97 setting fps to 29.97')
             fps = '29.97'
         else:
             # for build 8047:
             rezre = re.compile(r'.*frame rate differs from container frame rate: 29.97.*')
-            debug_write(__name__, fn_attr(), ['Bug in VideoReDo'])
+            logger.debug('Bug in VideoReDo')
             x = rezre.search(output.lower() )
             if x:
                 fps = '29.97'
@@ -439,7 +438,7 @@ def video_info(inFile):
         kbps = x.group(1)
     else:
         kbps = None
-        debug_write(__name__, fn_attr(), ['failed at kbps'])
+        logger.debug('failed at kbps')
 
     #get audio bitrate of source for tivo compatibility test.
     rezre = re.compile(r'.*Audio: .+, (.+) (?:kb/s).*')
@@ -448,7 +447,7 @@ def video_info(inFile):
         akbps = x.group(1)
     else:
         akbps = None
-        debug_write(__name__, fn_attr(), ['failed at akbps'])
+        logger.debug('failed at akbps')
 
     #get audio codec of source for tivo compatibility test.
     rezre = re.compile(r'.*Audio: ([^,]+),.*')
@@ -457,7 +456,7 @@ def video_info(inFile):
         acodec = x.group(1)
     else:
         acodec = None
-        debug_write(__name__, fn_attr(), ['failed at acodec'])
+        logger.debug('failed at acodec')
 
     #get audio frequency of source for tivo compatibility test.
     rezre = re.compile(r'.*Audio: .+, (.+) (?:Hz).*')
@@ -466,7 +465,7 @@ def video_info(inFile):
         afreq = x.group(1)
     else:
         afreq = None
-        debug_write(__name__, fn_attr(), ['failed at afreq'])
+        logger.debug('failed at afreq')
 
     #get par.
     rezre = re.compile(r'.*Video: .+PAR ([0-9]+):([0-9]+) DAR [0-9:]+.*')
@@ -475,9 +474,10 @@ def video_info(inFile):
         vpar = float(x.group(1))/float(x.group(2))
     else:
         vpar = None
+
     info_cache[inFile] = (mtime, (codec, width, height, fps, millisecs, kbps, akbps, acodec, afreq, vpar))
-    debug_write(__name__, fn_attr(), ['Codec=', codec, ' width=', width, ' height=', height, ' fps=', fps, ' millisecs=', millisecs, ' kbps=', kbps, ' akbps=', akbps, ' acodec=', acodec, ' afreq=', afreq, ' par=', vpar])
+    logger.debug('Codec=%s width=%s height=%s fps=%s millisecs=%s kbps=%s akbps=%s acodec=%s afreq=%s par=%s' %
+        (codec, width, height, fps, millisecs, kbps, akbps, acodec, afreq, vpar))
     return codec, width, height, fps, millisecs, kbps, akbps, acodec, afreq, vpar
 
 def video_check(inFile, cmd_string):
@@ -494,11 +494,11 @@ def supported_format(inFile):
     if video_info(inFile)[0]:
         return True
     else:
-        debug_write(__name__, fn_attr(), ['FALSE, file not supported', inFile])
+        logger.debug('FALSE, file not supported %s' % inFile)
         return False
 
 def kill(pid):
-    debug_write(__name__, fn_attr(), ['killing pid=', str(pid)])
+    loger.debug('killing pid=%s' % str(pid))
     if mswindows:
         win32kill(pid)
     else:
index d66b4df..c119505 100644 (file)
@@ -9,7 +9,7 @@ from datetime import datetime, timedelta
 import config
 import time
 import mind
-from debug import debug_write, fn_attr
+import logging
 
 SCRIPTDIR = os.path.dirname(__file__)
 
@@ -22,7 +22,7 @@ except:
     extensions = None
 
 if config.getHack83():
-    debug_write(__name__, fn_attr(), ['Hack83 is enabled.'])
+    logging.getLogger('pyTivo.hack83').info('Hack83 is enabled.')
 
 class Video(Plugin):
 
@@ -45,8 +45,9 @@ class Video(Plugin):
             return transcode.supported_format(full_path)
 
     def hack(self, handler, query, subcname):
-        debug_write(__name__, fn_attr(), ['new request ------------------------'])
-        debug_write(__name__, fn_attr(), ['TiVo request is: \n', query])
+        logger = logging.getLogger('pyTivo.hack83')
+        logger.debug('new request ------------------------')
+        logger.debug('TiVo request is: \n%s' % query)
         queryAnchor = ''
         rightAnchor = ''
         leftAnchor = ''
@@ -54,8 +55,7 @@ class Video(Plugin):
 
         # not a tivo
         if not tsn:
-            debug_write(__name__, fn_attr(), ['this was not a TiVo request.',
-                         'Using default tsn.'])
+            logger.debug('this was not a TiVo request. Using default tsn.')
             tsn = '123456789'
 
         # this breaks up the anchor item request into seperate parts
@@ -68,14 +68,13 @@ class Video(Plugin):
                 # This is a file
                 queryAnchor = queryAnchor.split('/', 1)[-1]
             leftAnchor, rightAnchor = queryAnchor.rsplit('/', 1)
-            debug_write(__name__, fn_attr(), ['queryAnchor: ', queryAnchor,
-                         ' leftAnchor: ', leftAnchor,
-                         ' rightAnchor: ', rightAnchor])
+            logger.debug('queryAnchor:%s \n leftAnchor:%s\n rightAnchor: %s' %
+                            (queryAnchor, leftAnchor, rightAnchor))
         try:
             path, state = self.request_history[tsn]
         except KeyError:
             # Never seen this tsn, starting new history
-            debug_write(__name__, fn_attr(), ['New TSN.'])
+            logger.debug('New TSN.')
             path = []
             state = {}
             self.request_history[tsn] = (path, state)
@@ -83,7 +82,7 @@ class Video(Plugin):
             state['page'] = ''
             state['time'] = int(time.time()) + 1000
 
-        debug_write(__name__, fn_attr(), ['our saved request is: \n', state['query']])
+        logger.debug('our saved request is: \n%s' % state['query'])
 
         current_folder = subcname.split('/')[-1]
 
@@ -92,19 +91,17 @@ class Video(Plugin):
 
         # 1. at the root - This request is always accurate
         if len(subcname.split('/')) == 1:
-            debug_write(__name__, fn_attr(), ['we are at the root.',
-                         'Saving query, Clearing state[page].'])
+            logger.debug('we are at the root. Saving query, Clearing state[page].')
             path[:] = [current_folder]
             state['query'] = query
             state['page'] = ''
             return query, path
 
         # 2. entering a new folder
-        # If there is no AnchorItem in the request then we must be 
+        # If there is no AnchorItem in the request then we must be
         # entering a new folder.
         if 'AnchorItem' not in query:
-            debug_write(__name__, fn_attr(), ['we are entering a new folder.',
-                         'Saving query, setting time, setting state[page].'])
+            logger.debug('we are entering a new folder. Saving query, setting time, setting state[page].')
             path[:] = subcname.split('/')
             state['query'] = query
             state['time'] = int(time.time())
@@ -119,63 +116,59 @@ class Video(Plugin):
         # 3. Request a page after pyTivo sent a 302 code
         # we know this is the proper page
         if ''.join(query['AnchorItem']) == 'Hack8.3':
-            debug_write(__name__, fn_attr(), ['requested page from 302 code.',
-                         'Returning saved query.'])
+            logger.debug('requested page from 302 code. Returning saved query.')
             return state['query'], path
 
         # 4. this is a request for a file
         if 'ItemCount' in query and int(''.join(query['ItemCount'])) == 1:
-            debug_write(__name__, fn_attr(), ['requested a file'])
+            logger.debug('requested a file')
             # Everything in this request is right except the container
             query['Container'] = ['/'.join(path)]
             state['page'] = ''
             return query, path
 
-        # All remaining requests could be a second erroneous request for 
-        # each of the following we will pause to see if a correct 
+        # All remaining requests could be a second erroneous request for
+        # each of the following we will pause to see if a correct
         # request is coming right behind it.
 
-        # Sleep just in case the erroneous request came first this 
+        # Sleep just in case the erroneous request came first this
         # allows a proper request to be processed first
-        debug_write(__name__, fn_attr(), ['maybe erroneous request, sleeping.'])
+        logger.debug('maybe erroneous request, sleeping.')
         time.sleep(.25)
 
         # 5. scrolling in a folder
-        # This could be a request to exit a folder or scroll up or down 
+        # This could be a request to exit a folder or scroll up or down
         # within the folder
         # First we have to figure out if we are scrolling
         if 'AnchorOffset' in query:
-            debug_write(__name__, fn_attr(), ['Anchor offset was in query.',
-                         'leftAnchor needs to match ', '/'.join(path)])
+            logger.debug('Anchor offset was in query. leftAnchor needs to match %s' % '/'.join(path))
             if leftAnchor == str('/'.join(path)):
                 debug_write(__name__, fn_attr(), ['leftAnchor matched.'])
                 query['Container'] = ['/'.join(path)]
-                files, total, start = self.get_files(handler, query, 
+                files, total, start = self.get_files(handler, query,
                                                      self.video_file_filter)
-                debug_write(__name__, fn_attr(), ['saved page is= ', state['page'],
-                             ' top returned file is= ', files[0]])
+                logger.debug('saved page is=%s top returned file is= %s' % (state['page'], files[0]))
                 # If the first file returned equals the top of the page
                 # then we haven't scrolled pages
                 if files[0] != str(state['page']):
-                    debug_write(__name__, fn_attr(), ['this is scrolling within a folder.'])
+                    logger.debug('this is scrolling within a folder.')
                     state['page'] = files[0]
-                    return query, path               
+                    return query, path
 
-        # The only remaining options are exiting a folder or this is a 
+        # The only remaining options are exiting a folder or this is a
         # erroneous second request.
 
         # 6. this an extraneous request
-        # this came within a second of a valid request; just use that 
+        # this came within a second of a valid request; just use that
         # request.
         if (int(time.time()) - state['time']) <= 1:
-            debug_write(__name__, fn_attr(), ['erroneous request, send a 302 error'])
+            logger.debug('erroneous request, send a 302 error')
             return None, path
 
         # 7. this is a request to exit a folder
         # this request came by itself; it must be to exit a folder
         else:
-            debug_write(__name__, fn_attr(), ['over 1 second,',
-                         'must be request to exit folder'])
+            logger.debug('over 1 second must be request to exit folder')
             path.pop()
             state['query'] = {'Command': query['Command'],
                               'SortOrder': query['SortOrder'],
@@ -185,8 +178,7 @@ class Video(Plugin):
             return None, path
 
         # just in case we missed something.
-        debug_write(__name__, fn_attr(), ['ERROR, should not have made it here. ',
-                     'Trying to recover.'])
+        logger.debug('ERROR, should not have made it here Trying to recover.')
         return state['query'], path
 
     def send_file(self, handler, container, name):
@@ -333,16 +325,15 @@ class Video(Plugin):
         # If you are running 8.3 software you want to enable hack83
         # in the config file
         if config.getHack83():
-            print '=' * 73
+            logger = logging.getLogger('pyTivo.hack83')
+            logger.debug('=' * 73)
             query, hackPath = self.hack(handler, query, subcname)
             hackPath = '/'.join(hackPath)
-            print 'Tivo said:', subcname, '|| Hack said:', hackPath
-            debug_write(__name__, fn_attr(), ['Tivo said: ', subcname, ' || Hack said: ',
-                         hackPath])
+            logger.debug('Tivo said: %s || Hack said: %s' % (subcname, hackPath))
             subcname = hackPath
 
             if not query:
-                debug_write(__name__, fn_attr(), ['sending 302 redirect page'])
+                logger.debug('sending 302 redirect page')
                 handler.send_response(302)
                 handler.send_header('Location ', 'http://' +
                                     handler.headers.getheader('host') +
index 710a4d1..6b3ab61 100644 (file)
@@ -14,6 +14,7 @@ import urlparse
 import urllib
 import xml.etree.ElementTree as ElementTree
 import Queue
+import logging
 
 CLASS_NAME = 'WebVideo'
 
@@ -23,6 +24,7 @@ class WebVideo(Video):
     CONTENT_TYPE = 'x-not-for/tivo'
 
     def init(self):
+        self.__logger = logging.getLogger('pyTivo.webvideo')
         self.work_queue = Queue.Queue()
         self.download_thread_num = 1
         self.in_progress = {}
@@ -40,15 +42,18 @@ class WebVideo(Video):
         cl=xmpp.Client(
             server=xmpp_info['server'],
             port=xmpp_info['port'],
+            debug=[],
         )
-
+        self.__logger.debug('Connecting to %s:%s' % (xmpp_info['server'], xmpp_info['port']))
         cl.connect()
         cl.RegisterHandler('message', self.processMessage)
+        self.__logger.debug('Loging in as %s/pyTivo' % xmpp_info['username'])
         cl.auth(user=jid.getNode(), password=config.getTivoPassword(), resource='pyTivo')
 
         cl.sendInitPresence(requestRoster=0)
 
         for user_name in xmpp_info['presence_list']:
+            self.__logger.debug('Sending presence to %s' % user_name)
             jid=xmpp.protocol.JID(user_name)
             cl.sendPresence(jid)
 
@@ -66,7 +71,8 @@ class WebVideo(Video):
         while client.Process():
             pass
 
-    def processMessage(self, sess,mess):
+    def processMessage(self, sess, mess):
+        self.__logger.debug('Got message\n %s' % mess.getBody())
         xmpp_action = ElementTree.fromstring(mess.getBody())
 
         method_name = 'xmpp_' + xmpp_action.findtext('action').lower()
@@ -83,6 +89,7 @@ class WebVideo(Video):
         try:
             for request in m.getDownloadRequests():
                 if not request['bodyOfferId'] in self.in_progress:
+                    self.__logger.debug('Adding request to queue, %s' % request)
                     self.in_progress[request['bodyOfferId']] = True
                     self.work_queue.put(request)
         finally:
@@ -96,7 +103,7 @@ class WebVideo(Video):
             for share_name, settings in config.getShares():
                 if settings['type'] == 'webvideo':
                     break
-
+            self.__logger.debug('Processing request: %s' % data)
 
             path = settings['path']
             file_name = os.path.join(path, '%s-%s' % (data['bodyOfferId'] ,data['url'].split('/')[-1]))
@@ -117,7 +124,7 @@ class WebVideo(Video):
             data['duration'] = file_info['duration'] / 1000
             data['size'] = file_info['size']
 
-            print data
+            self.__logger.debug('Complete request: %s' % data)
 
             m = mind.getMind()
             m.completeDownloadRequest(data)
@@ -128,19 +135,32 @@ class WebVideo(Video):
             finally:
                 self.in_progress_lock.release()
 
-
     def downloadFile(self, url, file_path):
-        print 'downloading %s to %s' % (url, file_path)
+        self.__logger.info('Downloading %s to %s' % (url, file_path))
 
         outfile = open(file_path, 'awb')
         size = os.path.getsize(file_path)
         r = urllib2.Request(url)
         if size:
             r.add_header('Range', 'bytes=%s-' % size)
-        infile = urllib2.urlopen(r)
+
+        try:
+            infile = urllib2.urlopen(r)
+        except urllib2.HTTPError, e:
+            if not e.code == 416:
+                raise
+            infile = urllib2.urlopen(url)
+            if int(infile.info()['Content-Length']) == size:
+                self.__logger.debug('File was alraedy done. %s' % url)
+                return
+            else:
+                self.__logger.debug('File was not done byut could not resume. %s' % url)
+                outfile.close()
+                outfile = open(file_path, 'wb')
+
         shutil.copyfileobj(infile, outfile, 8192)
 
-        print 'done downloading %s to %s' % (url, file_path)
+        self.__logger.info('Done downloading %s to %s' % (url, file_path))
 
     def send_file(self, handler, container, name):
         Video.send_file(self, handler, container, name)
@@ -149,5 +169,6 @@ class WebVideo(Video):
         path = urllib.unquote(o[2])
         file_path = container['path'] + path[len(name) + 1:]
         if os.path.exists(file_path):
+            self.__logger.info('Deleting file %s' % file_path)
             os.unlink(file_path)
 
index 6a161c7..dbe4af5 100755 (executable)
--- a/pyTivo.py
+++ b/pyTivo.py
@@ -1,5 +1,8 @@
 #!/usr/bin/env python
 
+import logging
+logging.basicConfig(level=logging.DEBUG)
+
 import beacon, httpserver, os, sys
 import config
 from plugin import GetPlugin
@@ -36,7 +39,8 @@ b.start()
 if 'listen' in config.getBeaconAddresses():
     b.listen()
 
-print 'pyTivo is ready.'
+logging.getLogger('pyTivo').info('pyTivo is ready.')
+
 try:
     httpd.serve_forever()
 except KeyboardInterrupt: