Adding Logging

Initial portion of logging added to script. Check readme for new fields. This only includes about 50% logging at the moment.
jakewaldron · Jun 22, 2016 · 6b2c7a1 · 6b2c7a1
1 parent 896eacc
commit 6b2c7a1
Show file tree

Hide file tree

Showing 3 changed files with 115 additions and 13 deletions.
diff --git a/README.md b/README.md
@@ -99,6 +99,11 @@ The config file is in the scripts folder.  Before first run of the script, pleas
 * date_hours_back_to_search - Number of hours to search backwards
 * date_minutes_back_to_search - Number of minutes to search backwards
 
+#####Logging
+* logging_debug_level - Logging level (DEBUG, INFO, WARNING, ERROR, CRITICAL)
+* logging_file_location - Leave blank to use default location - logs folder where the script file resides
+* logging_retain_previous_logs - True to append to the log file or False to overwrite the log file on every run of the script.
+
 #####Plex API Authentication - This is only used for shared user emails currently
 * plex_username - Plex account username of the server
 * plex_password - Plex account password of the server

diff --git a/scripts/config.conf b/scripts/config.conf
@@ -14,6 +14,12 @@ date_days_back_to_search = 7
 date_hours_back_to_search = 0
 date_minutes_back_to_search = 0
 
+##Logging
+logging_debug_level = 'INFO'
+#Leave blank to use default location - logs folder where the script file resides
+logging_file_location = ''
+logging_retain_previous_logs = True
+
 ##Plex API Authentication (only used for shared user Emails right now)
 plex_username = ''
 plex_password = ''

diff --git a/scripts/plexEmail.py b/scripts/plexEmail.py
@@ -13,6 +13,8 @@
 import cloudinary.api
 import imghdr
 import time
+import logging
+import traceback
 from base64 import b64encode
 from collections import OrderedDict
 from datetime import date, timedelta
@@ -23,10 +25,19 @@
 from email.utils import formataddr
 from xml.etree.ElementTree import XML
 
-SCRIPT_VERSION = 'v0.8.4'
+SCRIPT_VERSION = 'v0.8.5'
 
 def replaceConfigTokens():
   ## The below code is for backwards compatibility
+  if ('logging_retain_previous_logs' not in config):
+    config['logging_retain_previous_logs'] = True
+
+  if ('logging_debug_level' not in config):
+    config['logging_debug_level'] = 'INFO'
+
+  if ('logging_file_location' not in config):
+    config['logging_file_location'] = ''
+
   if ('upload_cloudinary_api_secret' not in config):
     config['upload_cloudinary_api_secret'] = True
 
@@ -286,52 +297,75 @@ def convertToHumanReadable(valuesToConvert):
   return convertedValues
 
 def getSharedUserEmails():
+  logging.info('getSharedUserEmails: begin')
   emails = []
   if (config['plex_username'] == '' or config['plex_password'] == ''):
     return emails
 
   url = 'https://my.plexapp.com/users/sign_in.json'
+  logging.info('getSharedUserEmails: url = ' + url)
   base64string = 'Basic ' + base64.encodestring('%s:%s' % (config['plex_username'], config['plex_password'])).replace('\n', '')
   headers = {'Authorization': base64string, 'X-Plex-Client-Identifier': 'plexEmail'}
+  logging.debug('getSharedUserEmails: headers = ' + str(headers))
   response = requests.post(url, headers=headers)
+  logging.info('getSharedUserEmails: response = ' + str(response))
+  logging.info('getSharedUserEmails: response = ' + str(response.text))
   token = json.loads(response.text)['user']['authentication_token'];
+  logging.info('getSharedUserEmails: token = ' + token)
 
   url = 'https://plex.tv/pms/friends/all'
+  logging.info('getSharedUserEmails: url = ' + url)
   headers = {'Accept': 'application/json', 'X-Plex-Token': token}
+  logging.debug('getSharedUserEmails: headers = ' + str(headers))
   response = requests.get(url, headers=headers)
+  logging.info('getSharedUserEmails: response = ' + str(response))
+  logging.info('getSharedUserEmails: response = ' + str(response.text))
 
   parsed = XML(response.text.encode('ascii', 'ignore'))
   for elem in parsed:
     for name, value in sorted(elem.attrib.items()):
       if (name == 'email'):
+        logging.info('getSharedUserEmails: adding email - ' + value.lower())
         emails.append(value.lower())
-
+
+  logging.info('getSharedUserEmails: Returning shared emails')
+  logging.debug('getSharedUserEmails: email list - ' + ' '.join(emails))
   return emails
 
 def deleteImages():
+  logging.info('deleteImages: begin')
   folder = config['web_folder'] + config['web_path'] + os.path.sep + 'images' + os.path.sep
+  logging.info('deleteImages: deleting images from: ' + folder)
   for file in os.listdir(folder):
     if (file.endswith('.jpg')):
+      logging.debug('deleteImages: deleting image: ' + folder + file)
       os.remove(folder + file)
+  logging.info('deleteImages: end')
 
 def processImage(imageHash, thumb, mediaType, seasonIndex, episodeIndex):
+  logging.info('processImage: begin')
+  logging.info('processImage: imageHash = ' + imageHash + ' - thumb = ' + thumb + ' - mediaType = ' + mediaType + ' - seasonIndex = ' + str(seasonIndex) + ' - episodeIndex = ' + str(episodeIndex))
   thumbObj = {}
   imgLocation = ''
   if (not thumb or thumb == ''):
+    logging.info('processImage: thumb is either null or empty, returning no image')
     thumbObj['webImgPath'] = ''
     thumbObj['emailImgPath'] = ''
     return thumbObj
 
   if (thumb.find('http://') >= 0):
+    logging.info('processImage: thumb is already an externally hosted image')
     thumbObj['webImgPath'] = thumb
     thumbObj['emailImgPath'] = thumb
     return thumbObj
   else:
     if (thumb.find('media://') >= 0):
+      logging.info('processImage: thumb begins with media://')
       thumb = thumb[8:len(thumb)]
       imgName = thumb[thumb.rindex('/') + 1:thumb.rindex('.')] + hash
       imgLocation = config['plex_data_folder'] + 'Plex Media Server' + os.path.sep + 'Media' + os.path.sep + 'localhost' + os.path.sep + '' + thumb
     elif (thumb.find('upload://') >= 0):
+      logging.info('processImage: thumb begins with upload://')
       thumb = thumb[9:len(thumb)]
       category = thumb[0:thumb.index('/')]
       imgName = thumb[thumb.rindex('/') + 1:len(thumb)]
@@ -366,25 +400,42 @@ def processImage(imageHash, thumb, mediaType, seasonIndex, episodeIndex):
     webImgFullPath = config['web_domain'] + config['web_path'] + '/images/' + imgName + '.jpg'
     img = config['web_folder'] + config['web_path'] + os.path.sep + 'images' + os.path.sep + imgName + '.jpg'
 
+    logging.info('processImage: imgLocation = ' + imgLocation)
+    logging.info('processImage: webImgFullPath = ' + webImgFullPath)
+    logging.info('processImage: img = ' + img)
+
+
     cloudinaryURL = ''
     if ('upload_use_cloudinary' in config and config['upload_use_cloudinary']):
+      logging.info('processImage: Uploading to cloudinary')
       thumbObj['emailImgPath'] = webImgFullPath
       #imgurURL = uploadToImgur(imgLocation, imgName)
       cloudinaryURL = uploadToCloudinary(imgLocation)
     elif (config['web_enabled'] and config['email_use_web_images']):
+      logging.info('processImage: Hosting image on local web server')
       thumbObj['emailImgPath'] = webImgFullPath
     elif (os.path.isfile(imgLocation)):
+      logging.info('processImage: Attaching images to email')
       imgNames['Image_' + imgName] = imgLocation
       thumbObj['emailImgPath'] = 'cid:Image_' + imgName
     else:
+      logging.info('processImage: No email image')
       thumbObj['emailImgPath'] = ''
 
     if (cloudinaryURL != ''):
+      logging.info('processImage: Setting image paths to cloudinary')
       thumbObj['webImgPath'] = cloudinaryURL
       thumbObj['emailImgPath'] = cloudinaryURL
     elif (os.path.isfile(imgLocation) and config['web_enabled']):
-      shutil.copy(imgLocation, img)
-      thumbObj['webImgPath'] = 'images/' + imgName + '.jpg'
+      logging.info('processImage: Setting image paths to local and copying image to web folder')
+      try:
+        shutil.copy(imgLocation, img)
+      except EnvironmentError, e:
+        logging.warning('processImage: Failed to copy image - ' + e)
+        thumbObj['emailImgPath'] = ''
+        thumbObj['webImgPath'] = ''
+      else:
+        thumbObj['webImgPath'] = 'images/' + imgName + '.jpg'
     else:
       thumbObj['webImgPath'] = ''
 
@@ -411,16 +462,22 @@ def uploadToImgur(imgToUpload, nameOfUpload):
     return ''
 
 def uploadToCloudinary(imgToUpload):
+  logging.info('uploadToCloudinary: begin')
   if (os.path.isfile(imgToUpload)):
     if (os.path.islink(imgToUpload)):
       imgToUpload = os.path.realpath(imgToUpload)
     if (imghdr.what(imgToUpload)):
+      logging.info('uploadToCloudinary: start upload to cloudinary')
       response = cloudinary.uploader.upload(imgToUpload)
+      logging.info('uploadToCloudinary: response = ' + str(response))
       url = response['secure_url'] if (config['upload_cloudinary_use_https']) else response['url']
+      logging.info('uploadToCloudinary: url = ' + url)
       return url
     else:
+      logging.info('uploadToCloudinary: not an image')
       return ''
   else:
+    logging.info('uploadToCloudinary: file not located')
     return ''
 
 def containsnonasciicharacters(str):
@@ -762,6 +819,9 @@ def createWebHTML():
     </html>"""
 
   return htmlText
+
+def exceptionHandler(type, value, tb):
+  logging.error("Logging an uncaught exception", exc_info=(type, value, tb))
 
 #
 #
@@ -779,13 +839,9 @@ def createWebHTML():
 if ('version' in args and args['version']):
   print 'Script Version: ' + SCRIPT_VERSION
   sys.exit()
-
-testMode = False
-
+
 if ('configfile' in args):
   configFile = args['configfile']
-if ('test' in args):
-  testMode = args['test']
 
 if (not os.path.isfile(configFile)):
   print configFile + ' does not exist'
@@ -794,33 +850,60 @@ def createWebHTML():
 config = {}
 execfile(configFile, config)
 replaceConfigTokens()
+
+numeric_level = getattr(logging, config['logging_debug_level'], None)
+file_mode = 'a' if (config['logging_retain_previous_logs']) else 'w'
+if not isinstance(numeric_level, int):
+  numeric_level = getattr(logging, 'INFO')
+if not os.path.exists(os.path.dirname(os.path.realpath(sys.argv[0])) + os.path.sep + 'logs'):
+    os.makedirs(os.path.dirname(os.path.realpath(sys.argv[0])) + os.path.sep + 'logs')
+logging.basicConfig(level=numeric_level, format='%(asctime)s - %(levelname)s:%(message)s', filename=os.path.dirname(os.path.realpath(sys.argv[0])) + os.path.sep + 'logs' + os.path.sep + 'plexEmail.log', filemode=file_mode)
+
+sys.excepthook = exceptionHandler
+
+testMode = False
+
+if ('test' in args):
+  logging.info('Test flag found - setting script instance to test mode.')
+  testMode = args['test']
+else:
+  logging.info('Test flag not found.')
 
 if ('notice' in args and args['notice']):
+  logging.info('Notice passed in: ' + args['notice'])
   config['msg_notice'] = args['notice']
 
 if ('upload_use_cloudinary' in config and config['upload_use_cloudinary']):
-  cloudinary.config( 
+  logging.info('Setting Cloudinary config values')
+  cloudinary.config(
     cloud_name = config['upload_cloudinary_cloud_name'],
     api_key = config['upload_cloudinary_api_key'],
     api_secret = config['upload_cloudinary_api_secret'],
     upload_prefix = 'https://api.cloudinary.com' if ('upload_cloudinary_use_https' in config and config['upload_cloudinary_use_https']) else 'http://api.cloudinary.com'
   )
+  logging.debug('Cloudinary config: ' + str(cloudinary.config))
 
 plexWebLink = ''
 
 if (config['filter_include_plex_web_link']):
+  logging.info('Including Plex Web Link - Getting machine identifier from the DLNA DB')
   DLNA_DB_FILE = config['plex_data_folder'] + 'Plex Media Server' + os.path.sep + 'Plug-in Support' + os.path.sep + 'Databases' + os.path.sep + 'com.plexapp.dlna.db'
+  logging.info('DLNA_DB_FILE = ' + DLNA_DB_FILE)
 
   if (os.path.isfile(DLNA_DB_FILE)):
     con = sqlite3.connect(DLNA_DB_FILE)
     cur = con.cursor()    
     cur.execute('SELECT machine_identifier FROM remote_servers WHERE url LIKE "http://127.0.0.1%";')
     for row in cur:
       plexWebLink = 'http://plex.tv/web/app#!/server/' + row[0] + '/details/%2Flibrary%2Fmetadata%2F'
+      logging.info('plexWebLink = ' + plexWebLink)
+  else:
+    logging.warning(DLNA_DB_FILE + ' does not exist')
 
 DATABASE_FILE = config['plex_data_folder'] + 'Plex Media Server' + os.path.sep + 'Plug-in Support' + os.path.sep + 'Databases' + os.path.sep + 'com.plexapp.plugins.library.db'
 
 if (not os.path.isfile(DATABASE_FILE)):
+  logging.error(DATABASE_FILE + ' does not exist. Please make sure the plex_data_folder value is correct.')
   print DATABASE_FILE + ' does not exist. Please make sure the plex_data_folder value is correct.'
   sys.exit()
 
@@ -830,6 +913,7 @@ def createWebHTML():
 with con:
     libraryFilter = ''
     if (config['filter_libraries']):
+      logging.info('Getting IDs of libraries to filter')
       cur = con.cursor()
       cur.execute('SELECT id, name FROM library_sections;')
       for row in cur:
@@ -841,19 +925,26 @@ def createWebHTML():
             libraryFilter += ' AND MD.library_section_id != ' + str(row[0])
       if (libraryFilter != ''):
         libraryFilter += ') '
+      logging.debug('libraryFilter = ' + libraryFilter)
 
     dateSearch = 'datetime(\'now\', \'localtime\', \'-' + str(config['date_days_back_to_search']) + ' days\', \'-' + str(config['date_hours_back_to_search']) + ' hours\', \'-' + str(config['date_minutes_back_to_search']) + ' minutes\')'
+    logging.debug('dateSearch for DB query = ' + dateSearch)
 
+    dbQuery = "SELECT MD.id, MD.parent_id, MD.metadata_type, MD.title, MD.title_sort, MD.original_title, MD.rating, MD.tagline, MD.summary, MD.content_rating, MD.duration, MD.user_thumb_url, MD.tags_genre, MD.tags_director, MD.tags_star, MD.year, MD.hash, MD.[index], MD.studio, ME.duration, MD.originally_available_at FROM metadata_items MD LEFT OUTER JOIN media_items ME ON MD.id = ME.metadata_item_id WHERE added_at >= " + dateSearch + " AND metadata_type >= 1 AND metadata_type <= 10 " + libraryFilter + " ORDER BY title_sort;"
+    logging.info('Executing DB query: ' + dbQuery)
     cur = con.cursor()    
-    cur.execute("SELECT MD.id, MD.parent_id, MD.metadata_type, MD.title, MD.title_sort, MD.original_title, MD.rating, MD.tagline, MD.summary, MD.content_rating, MD.duration, MD.user_thumb_url, MD.tags_genre, MD.tags_director, MD.tags_star, MD.year, MD.hash, MD.[index], MD.studio, ME.duration, MD.originally_available_at FROM metadata_items MD LEFT OUTER JOIN media_items ME ON MD.id = ME.metadata_item_id WHERE added_at >= " + dateSearch + " AND metadata_type >= 1 AND metadata_type <= 10 " + libraryFilter + " ORDER BY title_sort;")
+    cur.execute(dbQuery)
 
     response = {};
+    logging.debug('Response:')
     for row in cur:
       response[row[0]] = {'id': row[0], 'parent_id': row[1], 'metadata_type': row[2], 'title': row[3], 'title_sort': row[4], 'original_title': row[5], 'rating': row[6], 'tagline': row[7], 'summary': row[8], 'content_rating': row[9], 'duration': row[10], 'user_thumb_url': row[11], 'tags_genre': row[12], 'tags_director': row[13], 'tags_star': row[14], 'year': row[15], 'hash': row[16], 'index': row[17], 'studio': row[18], 'real_duration': row[19], 'air_date': row[20]}
+      logging.debug(response[row[0]])    
 
     emailNotice = ''
     htmlNotice = ''
     if (config['msg_notice']):
+      logging.info('Generating html for the notice: ' + config['msg_notice'])
       emailNotice = """<br/>&nbsp;<div style="border: 1px solid; padding:15px 0px 15px 0px; background-repeat: no-repeat; background-position: 10px center; color: #00529B; background-color: #BDE5F8;font-family:Arial, Helvetica, sans-serif; font-size:20px; text-align: center;">""" + config['msg_notice'] + """</div><br/>&nbsp;"""
       htmlNotice = """<div class="container"><hr class="featurette-divider"><div class="info">""" + config['msg_notice'] + """</div>"""
     emailMovies = """<div class="headline" style="background: #FFF !important; padding-top: 0px !important;">
@@ -1521,7 +1612,7 @@ def createWebHTML():
           # songCount += 1
           # emailSongs += emailText
           # htmlSongs += htmlText
-        
+
     if ((movieCount > 0 and config['filter_show_movies']) or (showCount > 0 and config['filter_show_shows']) or (seasonCount > 0 and config['filter_show_seasons']) or (episodeCount > 0 and config['filter_show_episodes']) or (artistCount > 0 and config['filter_show_artists']) or (albumCount > 0 and config['filter_show_albums']) or (songCount > 0 and config['filter_show_songs'])):
       hasNewContent = True
     else:
@@ -1547,7 +1638,7 @@ def createWebHTML():
 
       #Remove duplicates by converting to a set
       config['email_to'] = set(config['email_to'])
-
+      
       emailCount = 0
       if (testMode):
         success = sendMail([config['email_from']])