From: Jason Michalski Date: Mon, 7 Apr 2008 03:46:43 +0000 (-0500) Subject: Everything is loging with the logging module X-Git-Url: https://repo.or.cz/w/pyTivo.git/commitdiff_plain/ae39ac9f4d53ef3c57ac397c956f075cf52245e7 Everything is loging with the logging module Currently everything is always in debug mode --- diff --git a/beacon.py b/beacon.py index c322514..ed02aeb 100644 --- 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) diff --git a/config.py b/config.py index eadb710..c5af5cc 100644 --- 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 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()) diff --git a/httpserver.py b/httpserver.py index bc69488..6ea3a41 100644 --- a/httpserver.py +++ b/httpserver.py @@ -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 += '' + section + '
' - + 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 --- 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 diff --git a/plugins/admin/admin.py b/plugins/admin/admin.py index 7ff7935..7b33f0a 100644 --- a/plugins/admin/admin.py +++ b/plugins/admin/admin.py @@ -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.
The'+ \ ' previous 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 Soft Reset before these changes will take effect.'+\ '
The Admin 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): '
This most likely caused by an incorrect Media Access Key. Please return to the ToGo page and double check your Media Access Key.' +\ '
The ToGo 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() diff --git a/plugins/video/transcode.py b/plugins/video/transcode.py index 33743e9..882927a 100644 --- a/plugins/video/transcode.py +++ b/plugins/video/transcode.py @@ -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: diff --git a/plugins/video/video.py b/plugins/video/video.py index d66b4df..c119505 100644 --- a/plugins/video/video.py +++ b/plugins/video/video.py @@ -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') + diff --git a/plugins/webvideo/webvideo.py b/plugins/webvideo/webvideo.py index 710a4d1..6b3ab61 100644 --- a/plugins/webvideo/webvideo.py +++ b/plugins/webvideo/webvideo.py @@ -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) diff --git a/pyTivo.py b/pyTivo.py index 6a161c7..dbe4af5 100755 --- 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: