Added basic logging (using logger.py from Sick Beard)

README

@@ -1,28 +0,0 @@
-#############################
-# Installation and Notes
-############################
-
-This is a pretty early release of a third-party add-on for SABnzbd.
-
-To run it, just double-click the headphones.py file (in Windows) or launch a terminal, cd into the Headphones directory and run 'python headphones.py' (it takes -q and -d as optional arguments). 
-
-If you run into any issues while upgrading, try dumping your config.ini file and starting over. I'll fix this so any future settings changes will just be added to your existing file.
-
-There are still a few things that I'm working on:
-
--Post-processing doesn't work yet. Just use the categories setting with SABnzbd to customize your final download directory.
-
--Settings changes require a restart. I think this has something to do with how configobj caches its data, but I'm not sure.
-
--Importing your itunes library takes a long time. That's because for each artist, it tries to find all of their releases before moving on to the next artist. I might stagger how the info gets added, i.e. first it adds all the artists, then it goes back and adds all of their release information.
-
--There are a lot of "duplicates" showing up under albums. MusicBrainz (the music database I'm using) has a 'release groups' category and a 'releases' category. Release Groups are basically albums, but within each release group there are a lot of different versions of albums (US releases, British Releases, re-releases, etc). In order to get track information, I had to use the 'release' category, and by doing so Headphones might add a few different releases for any given release group. I'll change this so it only adds "the best" release out of any given release group.
-
--"Snatched" downloads don't change status to "Downloaded". I'm keeping a database of snatched downloads, but since post-processing doesn't work yet, I didn't want to change the status until the app knows for sure that the album has downloaded.
-
--If you currently have an album, it won't show up as "Had" or "Downloaded" under albums. This is just because Headphones is more of a download manager and less of a library manager - also if you only had one song off an album, I don't want to mark it as having the whole album.
-
-
-If you run into any more issues, visit http://github.com/rembo10/headphones and report an issue. This is free software so feel free to use it/modify it as you wish. The code is messy, but it works :-)
-
-If you have any ideas for the next release, also make sure to post that here!

headphones.py

@@ -6,6 +6,7 @@ from configobj import ConfigObj
 from configcreate import configCreate
 import webbrowser
 import webServer
+import logger
 import time
 from threadtools import threadtool
 import os
@@ -16,6 +17,7 @@ import os
 
 FULL_PATH = os.path.dirname(os.path.abspath(__file__))
 config_file = os.path.join(FULL_PATH, 'config.ini')
+LOG_DIR = os.path.join(FULL_PATH, 'logs')
 
 
 if os.path.exists(config_file):
@@ -25,6 +27,13 @@ else:
 
 settings = ConfigObj(config_file)['General']
 
+if not os.access(LOG_DIR, os.F_OK):
+	try:
+		os.makedirs(LOG_DIR, 0744)
+	except:
+		print 'Unable to create log dir, logging to screen only'
+
+
 
 def serverstart():  
 
@@ -33,9 +42,12 @@ def serverstart():
 	parser.add_option("-q", "--quiet", action="store_true", dest="quiet")
 	
 	(options, args) = parser.parse_args()
+
+	consoleLogging=True
 	
 	if options.quiet or options.daemonize:
 		cherrypy.config.update({'log.screen': False})
+		consoleLogging=False
 
 	cherrypy.config.update({
 			'server.thread_pool': 10,
@@ -78,6 +90,8 @@ def serverstart():
 	#Start threads
 	threadtool(cherrypy.engine).subscribe()
 	cherrypy.engine.timeout_monitor.unsubscribe()
+
+	logger.sb_log_instance.initLogging(consoleLogging=consoleLogging)
 	
 	
 	def browser():
@@ -91,7 +105,7 @@ def serverstart():
 	if settings['launch_browser'] == '1':
 		cherrypy.engine.subscribe('start', browser, priority=90)
 	
-	
+	logger.log(u"Starting Headphones on port:" + settings['http_port'])
 	cherrypy.quickstart(webServer.Headphones(), config = conf)
 	
 

itunesimport.py

@@ -8,12 +8,14 @@ import time
 import os
 import sqlite3
 from headphones import FULL_PATH
+import logger
 
 database = os.path.join(FULL_PATH, 'headphones.db')
 
 
 def itunesImport(pathtoxml):
 	if os.path.splitext(pathtoxml)[1] == '.xml':
+		logger.log(u"Loading xml file from"+ pathtoxml)
 		pl = XMLLibraryParser(pathtoxml)
 		l = Library(pl.dictionary)
 		lst = []
@@ -23,12 +25,15 @@ def itunesImport(pathtoxml):
 		artistlist = [f for f in rawlist if f != None]
 	else:
 		rawlist = os.listdir(pathtoxml)
-		exclude = ['.ds_store', 'various artists']
+		logger.log(u"Loading artists from directory:" +pathtoxml)
+		exclude = ['.ds_store', 'various artists', 'untitled folder', 'va']
 		artistlist = [f for f in rawlist if f.lower() not in exclude]
 	for name in artistlist:
+		logger.log(u"Querying MusicBrainz for: "+name)
 		time.sleep(1)
 		artistResults = ws.Query().getArtists(ws.ArtistFilter(string.replace(name, '&', '%38'), limit=1))		
 		for result in artistResults:
+			logger.log(u"Found best match: "+result.artist.name+". Gathering album information...")
 			time.sleep(1)
 			artistid = u.extractUuid(result.artist.id)
 			inc = ws.ArtistIncludes(releases=(m.Release.TYPE_OFFICIAL, m.Release.TYPE_ALBUM), ratings=False, releaseGroups=False)
@@ -41,7 +46,7 @@ def itunesImport(pathtoxml):
 			c.execute('SELECT ArtistID from artists')
 			artistlist = c.fetchall()
 			if any(artistid in x for x in artistlist):
-				pass
+				logger.log(result.artist.name + u" is already in the database, skipping")
 			else:
 				c.execute('INSERT INTO artists VALUES( ?, ?, ?, CURRENT_DATE, ?)', (artistid, artist.name, artist.sortName, 'Active'))
 				for release in artist.getReleases():
@@ -69,6 +74,6 @@ def itunesImport(pathtoxml):
 							conn.commit()
 
 						else:
-							pass
+							logger.log(results.title + u" is not a US release. Skipping for now")
 		
 			c.close()

logger.py

@@ -0,0 +1,177 @@
+# Author: Nic Wolfe <nic@wolfeden.ca>
+# URL: http://code.google.com/p/sickbeard/
+#
+# This file is part of Sick Beard.
+#
+# Sick Beard is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# Sick Beard is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with Sick Beard.  If not, see <http://www.gnu.org/licenses/>.
+
+from __future__ import with_statement 
+
+import os
+import threading
+
+import headphones
+
+import logging
+
+
+# number of log files to keep
+NUM_LOGS = 3
+
+# log size in bytes
+LOG_SIZE = 10000000 # 10 megs
+
+ERROR = logging.ERROR
+WARNING = logging.WARNING
+MESSAGE = logging.INFO
+DEBUG = logging.DEBUG
+
+reverseNames = {u'ERROR': ERROR,
+                u'WARNING': WARNING,
+                u'INFO': MESSAGE,
+                u'DEBUG': DEBUG}
+
+class SBRotatingLogHandler(object):
+
+    def __init__(self, log_file, num_files, num_bytes):
+        self.num_files = num_files
+        self.num_bytes = num_bytes
+        
+        self.log_file = log_file
+        self.cur_handler = None
+
+        self.writes_since_check = 0
+
+        self.log_lock = threading.Lock()
+
+    def initLogging(self, consoleLogging=True):
+    
+        self.log_file = os.path.join(headphones.LOG_DIR, self.log_file)
+    
+        self.cur_handler = self._config_handler()
+    
+        logging.getLogger('headphones').addHandler(self.cur_handler)
+    
+        # define a Handler which writes INFO messages or higher to the sys.stderr
+        if consoleLogging:
+            console = logging.StreamHandler()
+    
+            console.setLevel(logging.INFO)
+    
+            # set a format which is simpler for console use
+            console.setFormatter(logging.Formatter('%(asctime)s %(levelname)s::%(message)s', '%H:%M:%S'))
+    
+            # add the handler to the root logger
+            logging.getLogger('headphones').addHandler(console)
+    
+        logging.getLogger('headphones').setLevel(logging.DEBUG)
+
+    def _config_handler(self):
+        """
+        Configure a file handler to log at file_name and return it.
+        """
+    
+        file_handler = logging.FileHandler(self.log_file)
+        file_handler.setLevel(logging.DEBUG)
+        file_handler.setFormatter(logging.Formatter('%(asctime)s %(levelname)-8s %(message)s', '%b-%d %H:%M:%S'))
+        return file_handler
+
+    def _log_file_name(self, i):
+        """
+        Returns a numbered log file name depending on i. If i==0 it just uses logName, if not it appends
+        it to the extension (blah.log.3 for i == 3)
+        
+        i: Log number to ues
+        """
+        return self.log_file + ('.' + str(i) if i else '')
+    
+    def _num_logs(self):
+        """
+        Scans the log folder and figures out how many log files there are already on disk
+        
+        Returns: The number of the last used file (eg. mylog.log.3 would return 3). If there are no logs it returns -1
+        """
+        cur_log = 0
+        while os.path.isfile(self._log_file_name(cur_log)):
+            cur_log += 1
+        return cur_log - 1
+    
+    def _rotate_logs(self):
+        
+        sb_logger = logging.getLogger('headphones')
+        
+        # delete the old handler
+        if self.cur_handler:
+            self.cur_handler.flush()
+            self.cur_handler.close()
+            sb_logger.removeHandler(self.cur_handler)
+    
+        # rename or delete all the old log files
+        for i in range(self._num_logs(), -1, -1):
+            cur_file_name = self._log_file_name(i)
+            try:
+                if i >= NUM_LOGS:
+                    os.remove(cur_file_name)
+                else:
+                    os.rename(cur_file_name, self._log_file_name(i+1))
+            except WindowsError:
+                pass
+        
+        # the new log handler will always be on the un-numbered .log file
+        new_file_handler = self._config_handler()
+        
+        self.cur_handler = new_file_handler
+        
+        sb_logger.addHandler(new_file_handler)
+
+    def log(self, toLog, logLevel=MESSAGE):
+    
+        with self.log_lock:
+    
+            # check the size and see if we need to rotate
+            if self.writes_since_check >= 10:
+                if os.path.isfile(self.log_file) and os.path.getsize(self.log_file) >= LOG_SIZE:
+                    self._rotate_logs()
+                self.writes_since_check = 0
+            else:
+                self.writes_since_check += 1
+    
+            meThread = threading.currentThread().getName()
+            message = meThread + u" :: " + toLog
+        
+            out_line = message.encode('utf-8')
+        
+            sb_logger = logging.getLogger('headphones')
+    
+            try:
+                if logLevel == DEBUG:
+                    sb_logger.debug(out_line)
+                elif logLevel == MESSAGE:
+                    sb_logger.info(out_line)
+                elif logLevel == WARNING:
+                    sb_logger.warning(out_line)
+                elif logLevel == ERROR:
+                    sb_logger.error(out_line)
+            
+                    # add errors to the UI logger
+                    #classes.ErrorViewer.add(classes.UIError(message))
+                else:
+                    sb_logger.log(logLevel, out_line)
+            except ValueError:
+                pass
+
+sb_log_instance = SBRotatingLogHandler('headphones.log', NUM_LOGS, LOG_SIZE)
+
+def log(toLog, logLevel=MESSAGE):
+    sb_log_instance.log(toLog, logLevel)

searcher.py

@@ -6,6 +6,7 @@ import string
 import feedparser
 import sqlite3
 import re
+import logger
 
 
 config = ConfigObj(config_file)
@@ -54,6 +55,8 @@ def searchNZB(albumid=None):
 		term1 = re.sub('[\.\-]', ' ', '%s %s %s' % (clname, clalbum, year)).encode('utf-8')
 		term = string.replace(term1, '"', '')
 		
+		logger.log(u"Searching for "+term+" since it was marked as wanted")
+		
 		resultlist = []
 		
 		if nzbmatrix == '1':
@@ -78,7 +81,7 @@ def searchNZB(albumid=None):
 						}
 						
 			searchURL = "http://rss.nzbmatrix.com/rss.php?" + urllib.urlencode(params)
-			
+			logger.log(u"Parsing results from "+searchURL)
 			d = feedparser.parse(searchURL)
 			
 			for item in d.entries:
@@ -88,9 +91,13 @@ def searchNZB(albumid=None):
 					size = int(item.links[1]['length'])
 					if size < maxsize:
 						resultlist.append((title, size, url))
+						logger.log(u"Found " + title +" : " + url + " (Size: " + size + ")")
+					else:
+						logger.log(title + u" is larger than the maxsize for this category, skipping. (Size: " + size+")", logger.WARNING)
+						
 				
 				except:
-					print '''No results found'''
+					logger.log(u"No results found", logger.WARNING)
 			
 		if newznab == '1':
 		
@@ -109,6 +116,7 @@ def searchNZB(albumid=None):
 						}
 		
 			searchURL = newznab_host + '/api?' + urllib.urlencode(params)
+			logger.log(u"Parsing results from "+searchURL)
 			
 			d = feedparser.parse(searchURL)
 			
@@ -119,9 +127,12 @@ def searchNZB(albumid=None):
 					size = int(item.links[1]['length'])
 					if size < maxsize:
 						resultlist.append((title, size, url))
+						logger.log(u"Found " + title +" : " + url + " (Size: " + size + ")")
+					else:
+						logger.log(title + u" is larger than the maxsize for this category, skipping. (Size: " + size+")", logger.WARNING)
 				
 				except:
-					print '''No results found'''
+					logger.log(u"No results found", logger.WARNING)
 					
 		if nzbsorg == '1':
 		
@@ -142,6 +153,7 @@ def searchNZB(albumid=None):
 		
 			searchURL = 'https://secure.nzbs.org/rss.php?' + urllib.urlencode(params)
 			
+			logger.log(u"Parsing results from "+searchURL)
 			d = feedparser.parse(searchURL)
 			
 			for item in d.entries:
@@ -151,13 +163,18 @@ def searchNZB(albumid=None):
 					size = int(item.links[1]['length'])
 					if size < maxsize:
 						resultlist.append((title, size, url))
+						logger.log(u"Found " + title +" : " + url + " (Size: " + size + ")")
+					else:
+						logger.log(title + u" is larger than the maxsize for this category, skipping. (Size: " + size +")", logger.WARNING)
+						
 				
 				except:
-					print '''No results found'''
+					logger.log(u"No results found", logger.WARNING)
 		
 		if len(resultlist):	
 			bestqual = sorted(resultlist, key=lambda title: title[1], reverse=True)[0]
 		
+			logger.log(bestqual[0] + u" seems to be the best quality at: " + bestqual[1])
 			downloadurl = bestqual[2]
 				
 			linkparams = {}
@@ -176,8 +193,13 @@ def searchNZB(albumid=None):
 			linkparams["name"] = downloadurl
 				
 			saburl = 'http://' + sab_host + '/sabnzbd/api?' + urllib.urlencode(linkparams)
-		
-			urllib.urlopen(saburl)
+			logger.log(u"Sending link to SABNZBD: " + saburl)
+			
+			try:
+				urllib.urlopen(saburl)
+				
+			except:
+				logger.log(u"Unable to send link. Are you sure the host address is correct?", logger.ERROR)
 				
 			c.execute('UPDATE albums SET status = "Snatched" WHERE AlbumID="%s"' % albums[2])
 			c.execute('CREATE TABLE IF NOT EXISTS snatched (AlbumID, Title TEXT, Size INTEGER, URL TEXT, DateAdded TEXT, Status TEXT)')

templates.py

@@ -3,7 +3,7 @@ _header = '''
 	<head>
 		<title>Headphones</title>
 		<link rel="stylesheet" type="text/css" href="data/css/style.css" />
-		<link rel="icon" type="image/png" href="data/images/headphoneslogo.png" />
+		<link rel="icon" type="image/x-icon" href="data/images/favicon.ico" /> 
 		<link rel="apple-touch-icon" href="data/images/headphoneslogo.png" />
 	</head>
 	<body>

updater.py

@@ -5,11 +5,13 @@ import musicbrainz2.utils as u
 import sqlite3
 import time
 
+import logger
+
 def dbUpdate():
 
 	conn=sqlite3.connect(database)
 	c=conn.cursor()
-	c.execute('SELECT ArtistID from artists WHERE Status="Active"')
+	c.execute('SELECT ArtistID, ArtistName from artists WHERE Status="Active"')
 	
 	activeartists = c.fetchall()
 	
@@ -18,6 +20,8 @@ def dbUpdate():
 	while i < len(activeartists):
 			
 		artistid = activeartists[i][0]
+		artistname = activeartists[i][1]
+		logger.log(u"Updating album information for artist: " + artistname)
 		
 		c.execute('SELECT AlbumID from albums WHERE ArtistID="%s"' % artistid)
 		albumlist = c.fetchall()
@@ -37,6 +41,8 @@ def dbUpdate():
 				if event.country == 'US':
 					
 					if any(releaseid in x for x in albumlist):
+					
+						logger.log(results.title + " already exists in the database. Updating ASIN, Release Date, Tracks")
 						
 						c.execute('UPDATE albums SET AlbumASIN="%s", ReleaseDate="%s" WHERE AlbumID="%s"' % (results.asin, results.getEarliestReleaseDate(), u.extractUuid(results.id)))
 		
@@ -46,6 +52,7 @@ def dbUpdate():
 						
 					else:
 						
+						logger.log(u"New album found! Adding "+results.title+"to the database...")
 						c.execute('INSERT INTO albums VALUES( ?, ?, ?, ?, ?, CURRENT_DATE, ?, ?)', (artistid, results.artist.name, results.title, results.asin, results.getEarliestReleaseDate(), u.extractUuid(results.id), 'Skipped'))
 						conn.commit()
 						c.execute('SELECT ReleaseDate, DateAdded from albums WHERE AlbumID="%s"' % u.extractUuid(results.id))
@@ -65,7 +72,7 @@ def dbUpdate():
 							conn.commit()
 						
 				else:
-					pass
+					logger.log(results.title + " is not a US release. Skipping it for now")
 		i += 1
 	
 	conn.commit()

webServer.py

@@ -12,6 +12,7 @@ import sqlite3
 import sys
 import configobj
 from headphones import FULL_PATH, config_file
+import logger
 
 database = os.path.join(FULL_PATH, 'headphones.db')
 
@@ -23,6 +24,7 @@ class Headphones:
 		page.append(templates._nav)
 		#Display Database if it exists:
 		if os.path.exists(database):
+			logger.log(u"Loading artists from the database...")
 			conn=sqlite3.connect(database)
 			c=conn.cursor()
 			c.execute('SELECT ArtistName, ArtistID, Status from artists order by ArtistSortName collate nocase')
@@ -162,6 +164,7 @@ class Headphones:
 		else:
 			artistResults = ws.Query().getArtists(ws.ArtistFilter(string.replace(name, '&', '%38'), limit=8))
 			if len(artistResults) == 0:
+				logger.log("No results found for" + name)
 				page.append('''No results!<a class="blue" href="/">Go back</a>''')
 				
 			elif len(artistResults) > 1:
@@ -172,6 +175,7 @@ class Headphones:
 				return page
 			else:
 				for result in artistResults:
+					logger.log(u"Found one artist matching your search term: " + result.artist, result.id)
 					artist = result.artist
 					raise cherrypy.HTTPRedirect("/addArtist?artistid=%s" % u.extractUuid(artist.id))
 		
@@ -202,10 +206,12 @@ class Headphones:
 		if any(artistid in x for x in artistlist):
 			page = [templates._header]
 			page.append('''%s has already been added. Go <a href="/">back</a>.''' % artist.name)
+			logger.log(artist.name + u" is already in the database!", logger.WARNING)
 			c.close()
 			return page
 		
 		else:
+			logger.log(u"Adding " + artist.name + " to the database.")
 			c.execute('INSERT INTO artists VALUES( ?, ?, ?, CURRENT_DATE, ?)', (artistid, artist.name, artist.sortName, 'Active'))
 			
 			for release in artist.getReleases():
@@ -216,11 +222,13 @@ class Headphones:
 				
 				for event in results.releaseEvents:
 					if event.country == 'US':
+						logger.log(u"Now adding album: " + results.title+ " to the database")
 						c.execute('INSERT INTO albums VALUES( ?, ?, ?, ?, ?, CURRENT_DATE, ?, ?)', (artistid, results.artist.name, results.title, results.asin, results.getEarliestReleaseDate(), u.extractUuid(results.id), 'Skipped'))
 						c.execute('SELECT ReleaseDate, DateAdded from albums WHERE AlbumID="%s"' % u.extractUuid(results.id))
 						latestrelease = c.fetchall()
 						
 						if latestrelease[0][0] > latestrelease[0][1]:
+							logger.log(results.title + u" is an upcoming album. Setting its status to 'Wanted'...")
 							c.execute('UPDATE albums SET Status = "Wanted" WHERE AlbumID="%s"' % u.extractUuid(results.id))
 						else:
 							pass
@@ -228,7 +236,7 @@ class Headphones:
 						for track in results.tracks:
 							c.execute('INSERT INTO tracks VALUES( ?, ?, ?, ?, ?, ?, ?, ?)', (artistid, results.artist.name, results.title, results.asin, u.extractUuid(results.id), track.title, track.duration, u.extractUuid(track.id)))
 					else:
-						pass
+						logger.log(results.title + " is not a US release. Skipping it for now", logger.DEBUG)
 			
 			conn.commit()
 			c.close()
@@ -241,6 +249,7 @@ class Headphones:
 	def pauseArtist(self, ArtistID):
 		conn=sqlite3.connect(database)
 		c=conn.cursor()
+		logger.log(u"Pausing artist: " + ArtistID)
 		c.execute('UPDATE artists SET status = "Paused" WHERE ArtistId="%s"' % ArtistID)
 		conn.commit()
 		c.close()
@@ -251,6 +260,7 @@ class Headphones:
 	def resumeArtist(self, ArtistID):
 		conn=sqlite3.connect(database)
 		c=conn.cursor()
+		logger.log(u"Resuming artist: " + ArtistID)
 		c.execute('UPDATE artists SET status = "Active" WHERE ArtistId="%s"' % ArtistID)
 		conn.commit()
 		c.close()
@@ -261,6 +271,7 @@ class Headphones:
 	def deleteArtist(self, ArtistID):
 		conn=sqlite3.connect(database)
 		c=conn.cursor()
+		logger.log(u"Deleting all traces of artist: " + ArtistID)
 		c.execute('''DELETE from artists WHERE ArtistID="%s"''' % ArtistID)
 		c.execute('''DELETE from albums WHERE ArtistID="%s"''' % ArtistID)
 		c.execute('''DELETE from tracks WHERE ArtistID="%s"''' % ArtistID)
@@ -274,6 +285,7 @@ class Headphones:
 	def queueAlbum(self, AlbumID, ArtistID):
 		conn=sqlite3.connect(database)
 		c=conn.cursor()
+		logger.log(u"Marking album: " + AlbumID + "as wanted...")
 		c.execute('UPDATE albums SET status = "Wanted" WHERE AlbumID="%s"' % AlbumID)
 		conn.commit()
 		c.close()
@@ -287,6 +299,7 @@ class Headphones:
 	def unqueueAlbum(self, AlbumID, ArtistID):
 		conn=sqlite3.connect(database)
 		c=conn.cursor()
+		logger.log(u"Marking album: " + AlbumID + "as skipped...")
 		c.execute('UPDATE albums SET status = "Skipped" WHERE AlbumID="%s"' % AlbumID)
 		conn.commit()
 		c.close()