diff --git a/default.py b/default.py index 03a338fc..9d9c098b 100644 --- a/default.py +++ b/default.py @@ -2,6 +2,7 @@ ################################################################################################# +import logging import os import sys import urlparse @@ -21,8 +22,14 @@ sys.path.append(_base_resource) import entrypoint import utils -from utils import Logging, window, language as lang -log = Logging('Default').log +from utils import window, language as lang + +################################################################################################# + +import loghandler + +loghandler.config() +log = logging.getLogger("EMBY.default") ################################################################################################# @@ -37,7 +44,7 @@ class Main(): # Parse parameters base_url = sys.argv[0] params = urlparse.parse_qs(sys.argv[2][1:]) - log("Parameter string: %s" % sys.argv[2], 0) + log.warn("Parameter string: %s" % sys.argv[2]) try: mode = params['mode'][0] itemid = params.get('id') @@ -113,7 +120,7 @@ class Main(): # Server is not online, do not run the sync xbmcgui.Dialog().ok(heading=lang(29999), line1=lang(33034)) - log("Not connected to the emby server.", 1) + log.warn("Not connected to the emby server.") return if window('emby_dbScan') != "true": @@ -126,7 +133,7 @@ class Main(): else: lib.fullSync(repair=True) else: - log("Database scan is already running.", 1) + log.warn("Database scan is already running.") elif mode == "texturecache": import artwork @@ -137,6 +144,6 @@ class Main(): if __name__ == "__main__": - log('plugin.video.emby started', 1) + log.info('plugin.video.emby started') Main() - log('plugin.video.emby stopped', 1) \ No newline at end of file + log.info('plugin.video.emby stopped') \ No newline at end of file diff --git a/resources/lib/api.py b/resources/lib/api.py index e5641e52..0d7332b5 100644 --- a/resources/lib/api.py +++ b/resources/lib/api.py @@ -4,8 +4,12 @@ ################################################################################################## -import clientinfo -from utils import Logging, settings +import logging +from utils import settings + +################################################################################################## + +log = logging.getLogger("EMBY."+__name__) ################################################################################################## @@ -13,17 +17,10 @@ from utils import Logging, settings class API(): def __init__(self, item): - - global log - log = Logging(self.__class__.__name__).log # item is the api response self.item = item - self.clientinfo = clientinfo.ClientInfo() - self.addonName = self.clientinfo.getAddonName() - - def getUserData(self): # Default favorite = False diff --git a/resources/lib/artwork.py b/resources/lib/artwork.py index f2cd0a32..4b0124f7 100644 --- a/resources/lib/artwork.py +++ b/resources/lib/artwork.py @@ -3,6 +3,7 @@ ################################################################################################# import json +import logging import requests import os import urllib @@ -12,11 +13,14 @@ import xbmc import xbmcgui import xbmcvfs -import clientinfo import image_cache_thread -from utils import Logging, window, settings, language as lang, kodiSQL +from utils import window, settings, language as lang, kodiSQL -################################################################################################# +################################################################################################## + +log = logging.getLogger("EMBY."+__name__) + +################################################################################################## class Artwork(): @@ -32,16 +36,10 @@ class Artwork(): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - - self.clientinfo = clientinfo.ClientInfo() - self.addonName = self.clientinfo.getAddonName() - self.enableTextureCache = settings('enableTextureCache') == "true" self.imageCacheLimitThreads = int(settings('imageCacheLimit')) self.imageCacheLimitThreads = int(self.imageCacheLimitThreads * 5) - log("Using Image Cache Thread Count: %s" % self.imageCacheLimitThreads, 1) + log.info("Using Image Cache Thread Count: %s" % self.imageCacheLimitThreads) if not self.xbmc_port and self.enableTextureCache: self.setKodiWebServerDetails() @@ -175,14 +173,14 @@ class Artwork(): line1=lang(33042)): return - log("Doing Image Cache Sync", 1) + log.info("Doing Image Cache Sync") pdialog = xbmcgui.DialogProgress() pdialog.create(lang(29999), lang(33043)) # ask to rest all existing or not if dialog.yesno(lang(29999), lang(33044)): - log("Resetting all cache data first.", 1) + log.info("Resetting all cache data first.") # Remove all existing textures first path = xbmc.translatePath('special://thumbnails/').decode('utf-8') @@ -215,7 +213,7 @@ class Artwork(): cursor.execute("SELECT url FROM art WHERE media_type != 'actor'") # dont include actors result = cursor.fetchall() total = len(result) - log("Image cache sync about to process %s images" % total, 1) + log.info("Image cache sync about to process %s images" % total) cursor.close() count = 0 @@ -236,7 +234,7 @@ class Artwork(): cursor.execute("SELECT url FROM art") result = cursor.fetchall() total = len(result) - log("Image cache sync about to process %s images" % total, 1) + log.info("Image cache sync about to process %s images" % total) cursor.close() count = 0 @@ -252,14 +250,14 @@ class Artwork(): count += 1 pdialog.update(100, "%s %s" % (lang(33046), len(self.imageCacheThreads))) - log("Waiting for all threads to exit", 1) + log.info("Waiting for all threads to exit") while len(self.imageCacheThreads): for thread in self.imageCacheThreads: if thread.isFinished: self.imageCacheThreads.remove(thread) pdialog.update(100, "%s %s" % (lang(33046), len(self.imageCacheThreads))) - log("Waiting for all threads to exit: %s" % len(self.imageCacheThreads), 1) + log.info("Waiting for all threads to exit: %s" % len(self.imageCacheThreads)) xbmc.sleep(500) pdialog.close() @@ -282,13 +280,13 @@ class Artwork(): self.imageCacheThreads.append(newThread) return else: - log("Waiting for empty queue spot: %s" % len(self.imageCacheThreads), 2) + log.info("Waiting for empty queue spot: %s" % len(self.imageCacheThreads)) xbmc.sleep(50) def cacheTexture(self, url): # Cache a single image url to the texture cache if url and self.enableTextureCache: - log("Processing: %s" % url, 2) + log.debug("Processing: %s" % url) if not self.imageCacheLimitThreads: # Add image to texture cache by simply calling it at the http endpoint @@ -406,7 +404,7 @@ class Artwork(): except TypeError: # Add the artwork cacheimage = True - log("Adding Art Link for kodiId: %s (%s)" % (kodiId, imageUrl), 2) + log.debug("Adding Art Link for kodiId: %s (%s)" % (kodiId, imageUrl)) query = ( ''' @@ -427,8 +425,8 @@ class Artwork(): # Delete current entry before updating with the new one self.deleteCachedArtwork(url) - log("Updating Art url for %s kodiId: %s (%s) -> (%s)" - % (imageType, kodiId, url, imageUrl), 1) + log.info("Updating Art url for %s kodiId: %s (%s) -> (%s)" + % (imageType, kodiId, url, imageUrl)) query = ' '.join(( @@ -472,21 +470,21 @@ class Artwork(): cachedurl = cursor.fetchone()[0] except TypeError: - log("Could not find cached url.", 1) + log.info("Could not find cached url.") except OperationalError: - log("Database is locked. Skip deletion process.", 1) + log.info("Database is locked. Skip deletion process.") else: # Delete thumbnail as well as the entry thumbnails = xbmc.translatePath("special://thumbnails/%s" % cachedurl).decode('utf-8') - log("Deleting cached thumbnail: %s" % thumbnails, 1) + log.info("Deleting cached thumbnail: %s" % thumbnails) xbmcvfs.delete(thumbnails) try: cursor.execute("DELETE FROM texture WHERE url = ?", (url,)) connection.commit() except OperationalError: - log("Issue deleting url from cache. Skipping.", 2) + log.debug("Issue deleting url from cache. Skipping.") finally: cursor.close() diff --git a/resources/lib/clientinfo.py b/resources/lib/clientinfo.py index d5550388..7fd485e3 100644 --- a/resources/lib/clientinfo.py +++ b/resources/lib/clientinfo.py @@ -2,6 +2,7 @@ ################################################################################################# +import logging import os from uuid import uuid4 @@ -9,9 +10,13 @@ import xbmc import xbmcaddon import xbmcvfs -from utils import Logging, window, settings +from utils import window, settings -################################################################################################# +################################################################################################## + +log = logging.getLogger("EMBY."+__name__) + +################################################################################################## class ClientInfo(): @@ -19,9 +24,6 @@ class ClientInfo(): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.addon = xbmcaddon.Addon() self.addonName = self.getAddonName() @@ -88,14 +90,14 @@ class ClientInfo(): GUID = xbmcvfs.File(GUID_file) clientId = GUID.read() if not clientId: - log("Generating a new deviceid...", 1) + log.info("Generating a new deviceid...") clientId = str("%012X" % uuid4()) GUID = xbmcvfs.File(GUID_file, 'w') GUID.write(clientId) GUID.close() - log("DeviceId loaded: %s" % clientId, 1) + log.info("DeviceId loaded: %s" % clientId) window('emby_deviceId', value=clientId) return clientId \ No newline at end of file diff --git a/resources/lib/connect.py b/resources/lib/connect.py index 87dbc2e1..aa3082a7 100644 --- a/resources/lib/connect.py +++ b/resources/lib/connect.py @@ -7,7 +7,7 @@ import requests import logging import clientinfo -from utils import Logging, window +from utils import window ################################################################################################## @@ -15,7 +15,8 @@ from utils import Logging, window from requests.packages.urllib3.exceptions import InsecureRequestWarning, InsecurePlatformWarning requests.packages.urllib3.disable_warnings(InsecureRequestWarning) requests.packages.urllib3.disable_warnings(InsecurePlatformWarning) -#logging.getLogger('requests').setLevel(logging.WARNING) + +log = logging.getLogger("EMBY."+__name__) ################################################################################################## @@ -25,7 +26,6 @@ class ConnectUtils(): # Borg - multiple instances, shared state _shared_state = {} clientInfo = clientinfo.ClientInfo() - addonName = clientInfo.getAddonName() # Requests session c = None @@ -34,26 +34,23 @@ class ConnectUtils(): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.__dict__ = self._shared_state def setUserId(self, userId): # Reserved for userclient only self.userId = userId - log("Set connect userId: %s" % userId, 2) + log.debug("Set connect userId: %s" % userId) def setServer(self, server): # Reserved for userclient only self.server = server - log("Set connect server: %s" % server, 2) + log.debug("Set connect server: %s" % server) def setToken(self, token): # Reserved for userclient only self.token = token - log("Set connect token: %s" % token, 2) + log.debug("Set connect token: %s" % token) def startSession(self): @@ -71,7 +68,7 @@ class ConnectUtils(): if self.sslclient is not None: verify = self.sslclient except: - log("Could not load SSL settings.", 1) + log.info("Could not load SSL settings.") # Start session self.c = requests.Session() @@ -81,13 +78,13 @@ class ConnectUtils(): self.c.mount("http://", requests.adapters.HTTPAdapter(max_retries=1)) self.c.mount("https://", requests.adapters.HTTPAdapter(max_retries=1)) - log("Requests session started on: %s" % self.server, 1) + log.info("Requests session started on: %s" % self.server) def stopSession(self): try: self.c.close() - except Exception as e: - log("Requests session could not be terminated: %s" % e, 1) + except Exception: + log.warn("Requests session could not be terminated") def getHeader(self, authenticate=True): @@ -101,7 +98,7 @@ class ConnectUtils(): 'Content-type': 'application/x-www-form-urlencoded; charset=UTF-8', 'Accept': "application/json" } - log("Header: %s" % header, 1) + log.info("Header: %s" % header) else: token = self.token @@ -113,14 +110,14 @@ class ConnectUtils(): 'X-Application': "Kodi/%s" % version, 'X-Connect-UserToken': token } - log("Header: %s" % header, 1) + log.info("Header: %s" % header) return header def doUrl(self, url, data=None, postBody=None, rtype="GET", parameters=None, authenticate=True, timeout=None): - log("=== ENTER connectUrl ===", 2) + log.debug("=== ENTER connectUrl ===") default_link = "" @@ -207,25 +204,25 @@ class ConnectUtils(): verify=verifyssl) ##### THE RESPONSE ##### - log(r.url, 1) - log(r, 1) + log.info(r.url) + log.info(r) if r.status_code == 204: # No body in the response - log("====== 204 Success ======", 1) + log.info("====== 204 Success ======") elif r.status_code == requests.codes.ok: try: # UNICODE - JSON object r = r.json() - log("====== 200 Success ======", 1) - log("Response: %s" % r, 1) + log.info("====== 200 Success ======") + log.info("Response: %s" % r) return r except: if r.headers.get('content-type') != "text/html": - log("Unable to convert the response for: %s" % url, 1) + log.info("Unable to convert the response for: %s" % url) else: r.raise_for_status() @@ -236,8 +233,7 @@ class ConnectUtils(): pass except requests.exceptions.ConnectTimeout as e: - log("Server timeout at: %s" % url, 0) - log(e, 1) + log.warn("Server timeout at: %s" % url) except requests.exceptions.HTTPError as e: @@ -253,11 +249,9 @@ class ConnectUtils(): pass except requests.exceptions.SSLError as e: - log("Invalid SSL certificate for: %s" % url, 0) - log(e, 1) + log.warn("Invalid SSL certificate for: %s" % url) except requests.exceptions.RequestException as e: - log("Unknown error connecting to: %s" % url, 0) - log(e, 1) + log.warn("Unknown error connecting to: %s" % url) return default_link \ No newline at end of file diff --git a/resources/lib/downloadutils.py b/resources/lib/downloadutils.py index ac8bd9ab..47a5db59 100644 --- a/resources/lib/downloadutils.py +++ b/resources/lib/downloadutils.py @@ -10,7 +10,7 @@ import xbmc import xbmcgui import clientinfo -from utils import Logging, window, settings +from utils import window, settings ################################################################################################## @@ -18,7 +18,8 @@ from utils import Logging, window, settings from requests.packages.urllib3.exceptions import InsecureRequestWarning, InsecurePlatformWarning requests.packages.urllib3.disable_warnings(InsecureRequestWarning) requests.packages.urllib3.disable_warnings(InsecurePlatformWarning) -#logging.getLogger('requests').setLevel(logging.WARNING) + +log = logging.getLogger("EMBY."+__name__) ################################################################################################## @@ -36,38 +37,35 @@ class DownloadUtils(): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.__dict__ = self._shared_state def setUsername(self, username): # Reserved for userclient only self.username = username - log("Set username: %s" % username, 2) + log.debug("Set username: %s" % username) def setUserId(self, userId): # Reserved for userclient only self.userId = userId - log("Set userId: %s" % userId, 2) + log.debug("Set userId: %s" % userId) def setServer(self, server): # Reserved for userclient only self.server = server - log("Set server: %s" % server, 2) + log.debug("Set server: %s" % server) def setToken(self, token): # Reserved for userclient only self.token = token - log("Set token: %s" % token, 2) + log.debug("Set token: %s" % token) def setSSL(self, ssl, sslclient): # Reserved for userclient only self.sslverify = ssl self.sslclient = sslclient - log("Verify SSL host certificate: %s" % ssl, 2) - log("SSL client side certificate: %s" % sslclient, 2) + log.debug("Verify SSL host certificate: %s" % ssl) + log.debug("SSL client side certificate: %s" % sslclient) def postCapabilities(self, deviceId): @@ -92,11 +90,11 @@ class DownloadUtils(): ) } - log("Capabilities URL: %s" % url, 2) - log("Postdata: %s" % data, 2) + log.debug("Capabilities URL: %s" % url) + log.debug("Postdata: %s" % data) self.downloadUrl(url, postBody=data, action_type="POST") - log("Posted capabilities to %s" % self.server, 2) + log.debug("Posted capabilities to %s" % self.server) # Attempt at getting sessionId url = "{server}/emby/Sessions?DeviceId=%s&format=json" % deviceId @@ -105,11 +103,11 @@ class DownloadUtils(): sessionId = result[0]['Id'] except (KeyError, TypeError): - log("Failed to retrieve sessionId.", 1) + log.info("Failed to retrieve sessionId.") else: - log("Session: %s" % result, 2) - log("SessionId: %s" % sessionId, 1) + log.debug("Session: %s" % result) + log.info("SessionId: %s" % sessionId) window('emby_sessionId', value=sessionId) # Post any permanent additional users @@ -117,8 +115,7 @@ class DownloadUtils(): if additionalUsers: additionalUsers = additionalUsers.split(',') - log("List of permanent users added to the session: %s" - % additionalUsers, 1) + log.info("List of permanent users added to the session: %s" % additionalUsers) # Get the user list from server to get the userId url = "{server}/emby/Users?format=json" @@ -155,7 +152,7 @@ class DownloadUtils(): if self.sslclient is not None: verify = self.sslclient except: - log("Could not load SSL settings.", 1) + log.info("Could not load SSL settings.") # Start session self.s = requests.Session() @@ -165,13 +162,13 @@ class DownloadUtils(): self.s.mount("http://", requests.adapters.HTTPAdapter(max_retries=1)) self.s.mount("https://", requests.adapters.HTTPAdapter(max_retries=1)) - log("Requests session started on: %s" % self.server, 1) + log.info("Requests session started on: %s" % self.server) def stopSession(self): try: self.s.close() - except: - log("Requests session could not be terminated.", 1) + except Exception: + log.warn("Requests session could not be terminated.") def getHeader(self, authenticate=True): @@ -210,7 +207,7 @@ class DownloadUtils(): def downloadUrl(self, url, postBody=None, action_type="GET", parameters=None, authenticate=True): - log("===== ENTER downloadUrl =====", 2) + log.debug("===== ENTER downloadUrl =====") session = requests kwargs = {} @@ -267,12 +264,12 @@ class DownloadUtils(): }) ##### THE RESPONSE ##### - log(kwargs, 2) + log.debug(kwargs) r = self._requests(action_type, session, **kwargs) if r.status_code == 204: # No body in the response - log("====== 204 Success ======", 2) + log.debug("====== 204 Success ======") # Read response to release connection r.content @@ -280,16 +277,16 @@ class DownloadUtils(): try: # UNICODE - JSON object r = r.json() - log("====== 200 Success ======", 2) - log("Response: %s" % r, 2) + log.debug("====== 200 Success ======") + log.debug("Response: %s" % r) return r except: if r.headers.get('content-type') != "text/html": - log("Unable to convert the response for: %s" % url, 1) + log.info("Unable to convert the response for: %s" % url) else: # Bad status code - log("=== Bad status response: %s ===" % r.status_code, -1) + log.error("=== Bad status response: %s ===" % r.status_code) r.raise_for_status() ##### EXCEPTIONS ##### @@ -297,13 +294,11 @@ class DownloadUtils(): except requests.exceptions.ConnectionError as e: # Make the addon aware of status if window('emby_online') != "false": - log("Server unreachable at: %s" % url, 0) - log(e, 2) + log.warn("Server unreachable at: %s" % url) window('emby_online', value="false") except requests.exceptions.ConnectTimeout as e: - log("Server timeout at: %s" % url, 0) - log(e, 1) + log.warn("Server timeout at: %s" % url) except requests.exceptions.HTTPError as e: @@ -330,7 +325,7 @@ class DownloadUtils(): elif status not in ("401", "Auth"): # Tell userclient token has been revoked. window('emby_serverStatus', value="401") - log("HTTP Error: %s" % e, 0) + log.warn("HTTP Error: %s" % e) xbmcgui.Dialog().notification( heading="Error connecting", message="Unauthorized.", @@ -345,12 +340,10 @@ class DownloadUtils(): pass except requests.exceptions.SSLError as e: - log("Invalid SSL certificate for: %s" % url, 0) - log(e, 1) + log.warn("Invalid SSL certificate for: %s" % url) except requests.exceptions.RequestException as e: - log("Unknown error connecting to: %s" % url, 0) - log(e, 1) + log.warn("Unknown error connecting to: %s" % url) return default_link diff --git a/resources/lib/embydb_functions.py b/resources/lib/embydb_functions.py index 73e808d8..9220fa5d 100644 --- a/resources/lib/embydb_functions.py +++ b/resources/lib/embydb_functions.py @@ -2,12 +2,14 @@ ################################################################################################# +import logging from sqlite3 import OperationalError -import clientinfo -from utils import Logging +################################################################################################## -################################################################################################# +log = logging.getLogger("EMBY."+__name__) + +################################################################################################## class Embydb_Functions(): @@ -15,14 +17,8 @@ class Embydb_Functions(): def __init__(self, embycursor): - global log - log = Logging(self.__class__.__name__).log - self.embycursor = embycursor - self.clientInfo = clientinfo.ClientInfo() - self.addonName = self.clientInfo.getAddonName() - def getViews(self): diff --git a/resources/lib/entrypoint.py b/resources/lib/entrypoint.py index ba4ffe22..e532e5e2 100644 --- a/resources/lib/entrypoint.py +++ b/resources/lib/entrypoint.py @@ -3,6 +3,7 @@ ################################################################################################# import json +import logging import os import sys import urlparse @@ -24,8 +25,11 @@ import playlist import playbackutils as pbutils import playutils import api -from utils import Logging, window, settings, language as lang -log = Logging('Entrypoint').log +from utils import window, settings, language as lang + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -43,7 +47,7 @@ def resetAuth(): heading=lang(30132), line1=lang(33050)) if resp: - log("Reset login attempts.", 1) + log.info("Reset login attempts.") window('emby_serverStatus', value="Auth") else: xbmc.executebuiltin('Addon.OpenSettings(plugin.video.emby)') @@ -121,12 +125,12 @@ def resetDeviceId(): window('emby_deviceId', clear=True) deviceId = clientinfo.ClientInfo().getDeviceId(reset=True) except Exception as e: - log("Failed to generate a new device Id: %s" % e, 1) + log.error("Failed to generate a new device Id: %s" % e) dialog.ok( heading=lang(29999), line1=lang(33032)) else: - log("Successfully removed old deviceId: %s New deviceId: %s" % (deviceId_old, deviceId), 1) + log.info("Successfully removed old deviceId: %s New deviceId: %s" % (deviceId_old, deviceId)) dialog.ok( heading=lang(29999), line1=lang(33033)) @@ -153,7 +157,7 @@ def deleteItem(): elif xbmc.getCondVisibility('Container.Content(pictures)'): itemType = "picture" else: - log("Unknown type, unable to proceed.", 1) + log.info("Unknown type, unable to proceed.") return embyconn = utils.kodiSQL('emby') @@ -165,7 +169,7 @@ def deleteItem(): try: itemId = item[0] except TypeError: - log("Unknown itemId, unable to proceed.", 1) + log.error("Unknown itemId, unable to proceed.") return if settings('skipContextMenu') != "true": @@ -173,7 +177,7 @@ def deleteItem(): heading=lang(29999), line1=lang(33041)) if not resp: - log("User skipped deletion for: %s." % itemId, 1) + log.info("User skipped deletion for: %s." % itemId) return embyserver.Read_EmbyServer().deleteItem(itemId) @@ -257,7 +261,7 @@ def addUser(): return # Subtract any additional users - log("Displaying list of users: %s" % users) + log.info("Displaying list of users: %s" % users) resp = dialog.select("Add user to the session", users) # post additional user if resp > -1: @@ -272,7 +276,7 @@ def addUser(): time=1000) except: - log("Failed to add user to session.") + log.error("Failed to add user to session.") dialog.notification( heading=lang(29999), message=lang(33068), @@ -328,7 +332,7 @@ def getThemeMedia(): tvtunes = xbmcaddon.Addon(id="script.tvtunes") tvtunes.setSetting('custom_path_enable', "true") tvtunes.setSetting('custom_path', library) - log("TV Tunes custom path is enabled and set.", 1) + log.info("TV Tunes custom path is enabled and set.") else: # if it does not exist this will not work so warn user # often they need to edit the settings first for it to be created. @@ -474,7 +478,7 @@ def refreshPlaylist(): sound=False) except Exception as e: - log("Refresh playlists/nodes failed: %s" % e, 1) + log.error("Refresh playlists/nodes failed: %s" % e) dialog.notification( heading=lang(29999), message=lang(33070), @@ -516,7 +520,7 @@ def BrowseContent(viewname, browse_type="", folderid=""): break if viewname is not None: - log("viewname: %s - type: %s - folderid: %s - filter: %s" %(viewname.decode('utf-8'), browse_type.decode('utf-8'), folderid.decode('utf-8'), filter_type.decode('utf-8'))) + log.info("viewname: %s - type: %s - folderid: %s - filter: %s" %(viewname.decode('utf-8'), browse_type.decode('utf-8'), folderid.decode('utf-8'), filter_type.decode('utf-8'))) #set the correct params for the content type #only proceed if we have a folderid if folderid: @@ -1049,7 +1053,7 @@ def getExtraFanArt(embyId,embyPath): if embyId: #only proceed if we actually have a emby id - log("Requesting extrafanart for Id: %s" % embyId, 0) + log.info("Requesting extrafanart for Id: %s" % embyId) # We need to store the images locally for this to work # because of the caching system in xbmc @@ -1078,7 +1082,7 @@ def getExtraFanArt(embyId,embyPath): xbmcvfs.copy(backdrop, fanartFile) count += 1 else: - log("Found cached backdrop.", 2) + log.debug("Found cached backdrop.") # Use existing cached images dirs, files = xbmcvfs.listdir(fanartDir) for file in files: @@ -1089,7 +1093,7 @@ def getExtraFanArt(embyId,embyPath): url=fanartFile, listitem=li) except Exception as e: - log("Error getting extrafanart: %s" % e, 0) + log.error("Error getting extrafanart: %s" % e) # Always do endofdirectory to prevent errors in the logs xbmcplugin.endOfDirectory(int(sys.argv[1])) \ No newline at end of file diff --git a/resources/lib/image_cache_thread.py b/resources/lib/image_cache_thread.py index fdf63d63..ffed967b 100644 --- a/resources/lib/image_cache_thread.py +++ b/resources/lib/image_cache_thread.py @@ -2,10 +2,13 @@ ################################################################################################# -import threading +import logging import requests +import threading -from utils import Logging +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -22,9 +25,6 @@ class image_cache_thread(threading.Thread): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - threading.Thread.__init__(self) @@ -44,7 +44,7 @@ class image_cache_thread(threading.Thread): def run(self): - log("Image Caching Thread Processing: %s" % self.urlToProcess, 2) + log.debug("Image Caching Thread Processing: %s" % self.urlToProcess) try: response = requests.head( @@ -56,5 +56,5 @@ class image_cache_thread(threading.Thread): # We don't need the result except: pass - log("Image Caching Thread Exited", 2) + log.debug("Image Caching Thread Exited") self.isFinished = True \ No newline at end of file diff --git a/resources/lib/initialsetup.py b/resources/lib/initialsetup.py index da0a5108..032affb1 100644 --- a/resources/lib/initialsetup.py +++ b/resources/lib/initialsetup.py @@ -3,6 +3,7 @@ ################################################################################################# import json +import logging import socket import xbmc @@ -12,7 +13,11 @@ import xbmcaddon import clientinfo import downloadutils import userclient -from utils import Logging, settings, language as lang, passwordsXML +from utils import settings, language as lang, passwordsXML + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -22,9 +27,6 @@ class InitialSetup(): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.addonId = clientinfo.ClientInfo().getAddonId() self.doUtils = downloadutils.DownloadUtils().downloadUrl self.userClient = userclient.UserClient() @@ -37,20 +39,20 @@ class InitialSetup(): ##### SERVER INFO ##### - log("Initial setup called.", 2) + log.debug("Initial setup called.") server = self.userClient.getServer() if server: - log("Server is already set.", 2) + log.debug("Server is already set.") return - log("Looking for server...", 2) + log.debug("Looking for server...") server = self.getServerDetails() - log("Found: %s" % server, 2) + log.debug("Found: %s" % server) try: prefix, ip, port = server.replace("/", "").split(":") - except: # Failed to retrieve server information - log("getServerDetails failed.", 1) + except Exception: # Failed to retrieve server information + log.error("getServerDetails failed.") xbmc.executebuiltin('Addon.OpenSettings(%s)' % addonId) return else: @@ -60,7 +62,7 @@ class InitialSetup(): line2="%s %s" % (lang(30169), server)) if server_confirm: # Correct server found - log("Server is selected. Saving the information.", 1) + log.info("Server is selected. Saving the information.") settings('ipaddress', value=ip) settings('port', value=port) @@ -68,20 +70,20 @@ class InitialSetup(): settings('https', value="true") else: # User selected no or cancelled the dialog - log("No server selected.", 1) + log.info("No server selected.") xbmc.executebuiltin('Addon.OpenSettings(%s)' % addonId) return ##### USER INFO ##### - log("Getting user list.", 1) + log.info("Getting user list.") result = self.doUtils("%s/emby/Users/Public?format=json" % server, authenticate=False) if result == "": - log("Unable to connect to %s" % server, 1) + log.info("Unable to connect to %s" % server) return - log("Response: %s" % result, 2) + log.debug("Response: %s" % result) # Process the list of users usernames = [] users_hasPassword = [] @@ -95,14 +97,14 @@ class InitialSetup(): name = "%s (secure)" % name users_hasPassword.append(name) - log("Presenting user list: %s" % users_hasPassword, 1) + log.info("Presenting user list: %s" % users_hasPassword) user_select = dialog.select(lang(30200), users_hasPassword) if user_select > -1: selected_user = usernames[user_select] - log("Selected user: %s" % selected_user, 1) + log.info("Selected user: %s" % selected_user) settings('username', value=selected_user) else: - log("No user selected.", 1) + log.info("No user selected.") xbmc.executebuiltin('Addon.OpenSettings(%s)' % addonId) return @@ -114,7 +116,7 @@ class InitialSetup(): nolabel=lang(33036), yeslabel=lang(33037)) if directPaths: - log("User opted to use direct paths.", 1) + log.info("User opted to use direct paths.") settings('useDirectPaths', value="1") # ask for credentials @@ -122,14 +124,14 @@ class InitialSetup(): heading=lang(30517), line1= lang(33038)) if credentials: - log("Presenting network credentials dialog.", 1) + log.info("Presenting network credentials dialog.") passwordsXML() musicDisabled = dialog.yesno( heading=lang(29999), line1=lang(33039)) if musicDisabled: - log("User opted to disable Emby music library.", 1) + log.info("User opted to disable Emby music library.") settings('enableMusic', value="false") else: # Only prompt if the user didn't select direct paths for videos @@ -138,12 +140,12 @@ class InitialSetup(): heading=lang(29999), line1=lang(33040)) if musicAccess: - log("User opted to direct stream music.", 1) + log.info("User opted to direct stream music.") settings('streamMusic', value="true") def getServerDetails(self): - log("Getting Server Details from Network", 1) + log.info("Getting Server Details from Network") MULTI_GROUP = ("", 7359) MESSAGE = "who is EmbyServer?" @@ -157,15 +159,15 @@ class InitialSetup(): sock.setsockopt(socket.SOL_IP, socket.IP_MULTICAST_LOOP, 1) sock.setsockopt(socket.IPPROTO_IP, socket.SO_REUSEADDR, 1) - log("MultiGroup : %s" % str(MULTI_GROUP), 2) - log("Sending UDP Data: %s" % MESSAGE, 2) + log.debug("MultiGroup : %s" % str(MULTI_GROUP)) + log.debug("Sending UDP Data: %s" % MESSAGE) sock.sendto(MESSAGE, MULTI_GROUP) try: data, addr = sock.recvfrom(1024) # buffer size is 1024 bytes - log("Received Response: %s" % data) - except: - log("No UDP Response") + log.info("Received Response: %s" % data) + except Exception: + log.error("No UDP Response") return None else: # Get the address diff --git a/resources/lib/itemtypes.py b/resources/lib/itemtypes.py index 934efcee..7438c83f 100644 --- a/resources/lib/itemtypes.py +++ b/resources/lib/itemtypes.py @@ -2,6 +2,7 @@ ################################################################################################## +import logging import urllib from ntpath import dirname from datetime import datetime @@ -18,9 +19,13 @@ import embydb_functions as embydb import kodidb_functions as kodidb import read_embyserver as embyserver import musicutils -from utils import Logging, window, settings, language as lang, kodiSQL +from utils import window, settings, language as lang, kodiSQL -################################################################################################## +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) + +################################################################################################# class Items(object): @@ -28,9 +33,6 @@ class Items(object): def __init__(self, embycursor, kodicursor): - global log - log = Logging(self.__class__.__name__).log - self.embycursor = embycursor self.kodicursor = kodicursor @@ -79,7 +81,7 @@ class Items(object): if total == 0: return False - log("Processing %s: %s" % (process, items), 1) + log.info("Processing %s: %s" % (process, items)) if pdialog: pdialog.update(heading="Processing %s: %s items" % (process, total)) @@ -171,7 +173,7 @@ class Items(object): 'remove': items_process.remove } else: - log("Unsupported itemtype: %s." % itemtype, 1) + log.info("Unsupported itemtype: %s." % itemtype) actions = {} if actions.get(process): @@ -202,7 +204,7 @@ class Items(object): if musicconn is not None: # close connection for special types - log("Updating music database.", 1) + log.info("Updating music database.") musicconn.commit() musiccursor.close() @@ -282,11 +284,11 @@ class Movies(Items): movieid = emby_dbitem[0] fileid = emby_dbitem[1] pathid = emby_dbitem[2] - log("movieid: %s fileid: %s pathid: %s" % (movieid, fileid, pathid), 1) + log.info("movieid: %s fileid: %s pathid: %s" % (movieid, fileid, pathid)) except TypeError: update_item = False - log("movieid: %s not found." % itemid, 2) + log.info("movieid: %s not found." % itemid) # movieid kodicursor.execute("select coalesce(max(idMovie),0) from movie") movieid = kodicursor.fetchone()[0] + 1 @@ -300,12 +302,12 @@ class Movies(Items): except TypeError: # item is not found, let's recreate it. update_item = False - log("movieid: %s missing from Kodi, repairing the entry." % movieid, 1) + log.info("movieid: %s missing from Kodi, repairing the entry." % movieid) if not viewtag or not viewid: # Get view tag from emby viewtag, viewid, mediatype = self.emby.getView_embyId(itemid) - log("View tag found: %s" % viewtag, 2) + log.debug("View tag found: %s" % viewtag) # fileId information checksum = API.getChecksum() @@ -348,7 +350,7 @@ class Movies(Items): try: trailer = "plugin://plugin.video.emby/trailer/?id=%s&mode=play" % result[0]['Id'] except IndexError: - log("Failed to process local trailer.", 1) + log.info("Failed to process local trailer.") trailer = None else: # Try to get the youtube trailer @@ -360,7 +362,7 @@ class Movies(Items): try: trailerId = trailer.rsplit('=', 1)[1] except IndexError: - log("Failed to process trailer: %s" % trailer, 1) + log.info("Failed to process trailer: %s" % trailer) trailer = None else: trailer = "plugin://plugin.video.youtube/play/?video_id=%s" % trailerId @@ -397,7 +399,7 @@ class Movies(Items): ##### UPDATE THE MOVIE ##### if update_item: - log("UPDATE movie itemid: %s - Title: %s" % (itemid, title), 1) + log.info("UPDATE movie itemid: %s - Title: %s" % (itemid, title)) # Update the movie entry query = ' '.join(( @@ -417,7 +419,7 @@ class Movies(Items): ##### OR ADD THE MOVIE ##### else: - log("ADD movie itemid: %s - Title: %s" % (itemid, title), 1) + log.info("ADD movie itemid: %s - Title: %s" % (itemid, title)) # Add path pathid = self.kodi_db.addPath(path) @@ -527,10 +529,10 @@ class Movies(Items): try: movieid = emby_dbitem[0] except TypeError: - log("Failed to add: %s to boxset." % movie['Name'], 1) + log.info("Failed to add: %s to boxset." % movie['Name']) continue - log("New addition to boxset %s: %s" % (title, movie['Name']), 1) + log.info("New addition to boxset %s: %s" % (title, movie['Name'])) self.kodi_db.assignBoxset(setid, movieid) # Update emby reference emby_db.updateParentId(itemid, setid) @@ -541,7 +543,7 @@ class Movies(Items): # Process removals from boxset for movie in process: movieid = current[movie] - log("Remove from boxset %s: %s" % (title, movieid)) + log.info("Remove from boxset %s: %s" % (title, movieid)) self.kodi_db.removefromBoxset(movieid) # Update emby reference emby_db.updateParentId(movie, None) @@ -566,7 +568,7 @@ class Movies(Items): try: movieid = emby_dbitem[0] fileid = emby_dbitem[1] - log("Update playstate for movie: %s fileid: %s" % (item['Name'], fileid), 1) + log.info("Update playstate for movie: %s fileid: %s" % (item['Name'], fileid)) except TypeError: return @@ -582,7 +584,7 @@ class Movies(Items): resume = API.adjustResume(userdata['Resume']) total = round(float(runtime), 6) - log("%s New resume point: %s" % (itemid, resume)) + log.debug("%s New resume point: %s" % (itemid, resume)) self.kodi_db.addPlaystate(fileid, resume, total, playcount, dateplayed) emby_db.updateReference(itemid, checksum) @@ -598,7 +600,7 @@ class Movies(Items): kodiid = emby_dbitem[0] fileid = emby_dbitem[1] mediatype = emby_dbitem[4] - log("Removing %sid: %s fileid: %s" % (mediatype, kodiid, fileid), 1) + log.info("Removing %sid: %s fileid: %s" % (mediatype, kodiid, fileid)) except TypeError: return @@ -624,7 +626,7 @@ class Movies(Items): kodicursor.execute("DELETE FROM sets WHERE idSet = ?", (kodiid,)) - log("Deleted %s %s from kodi database" % (mediatype, itemid), 1) + log.info("Deleted %s %s from kodi database" % (mediatype, itemid)) class MusicVideos(Items): @@ -664,11 +666,11 @@ class MusicVideos(Items): mvideoid = emby_dbitem[0] fileid = emby_dbitem[1] pathid = emby_dbitem[2] - log("mvideoid: %s fileid: %s pathid: %s" % (mvideoid, fileid, pathid), 1) + log.info("mvideoid: %s fileid: %s pathid: %s" % (mvideoid, fileid, pathid)) except TypeError: update_item = False - log("mvideoid: %s not found." % itemid, 2) + log.info("mvideoid: %s not found." % itemid) # mvideoid kodicursor.execute("select coalesce(max(idMVideo),0) from musicvideo") mvideoid = kodicursor.fetchone()[0] + 1 @@ -682,12 +684,12 @@ class MusicVideos(Items): except TypeError: # item is not found, let's recreate it. update_item = False - log("mvideoid: %s missing from Kodi, repairing the entry." % mvideoid, 1) + log.info("mvideoid: %s missing from Kodi, repairing the entry." % mvideoid) if not viewtag or not viewid: # Get view tag from emby viewtag, viewid, mediatype = self.emby.getView_embyId(itemid) - log("View tag found: %s" % viewtag, 2) + log.debug("View tag found: %s" % viewtag) # fileId information checksum = API.getChecksum() @@ -743,7 +745,7 @@ class MusicVideos(Items): ##### UPDATE THE MUSIC VIDEO ##### if update_item: - log("UPDATE mvideo itemid: %s - Title: %s" % (itemid, title), 1) + log.info("UPDATE mvideo itemid: %s - Title: %s" % (itemid, title)) # Update path query = "UPDATE path SET strPath = ? WHERE idPath = ?" @@ -769,7 +771,7 @@ class MusicVideos(Items): ##### OR ADD THE MUSIC VIDEO ##### else: - log("ADD mvideo itemid: %s - Title: %s" % (itemid, title), 1) + log.info("ADD mvideo itemid: %s - Title: %s" % (itemid, title)) # Add path query = ' '.join(( @@ -869,9 +871,9 @@ class MusicVideos(Items): try: mvideoid = emby_dbitem[0] fileid = emby_dbitem[1] - log( + log.info( "Update playstate for musicvideo: %s fileid: %s" - % (item['Name'], fileid), 1) + % (item['Name'], fileid)) except TypeError: return @@ -901,7 +903,7 @@ class MusicVideos(Items): mvideoid = emby_dbitem[0] fileid = emby_dbitem[1] pathid = emby_dbitem[2] - log("Removing mvideoid: %s fileid: %s" % (mvideoid, fileid, pathid), 1) + log.info("Removing mvideoid: %s fileid: %s" % (mvideoid, fileid, pathid)) except TypeError: return @@ -927,7 +929,7 @@ class MusicVideos(Items): kodicursor.execute("DELETE FROM path WHERE idPath = ?", (pathid,)) self.embycursor.execute("DELETE FROM emby WHERE emby_id = ?", (itemid,)) - log("Deleted musicvideo %s from kodi database" % itemid, 1) + log.info("Deleted musicvideo %s from kodi database" % itemid) class TVShows(Items): @@ -991,7 +993,7 @@ class TVShows(Items): API = api.API(item) if settings('syncEmptyShows') == "false" and not item.get('RecursiveItemCount'): - log("Skipping empty show: %s" % item['Name'], 1) + log.info("Skipping empty show: %s" % item['Name']) return # If the item already exist in the local Kodi DB we'll perform a full item update # If the item doesn't exist, we'll add it to the database @@ -1002,11 +1004,11 @@ class TVShows(Items): try: showid = emby_dbitem[0] pathid = emby_dbitem[2] - log("showid: %s pathid: %s" % (showid, pathid), 1) + log.info("showid: %s pathid: %s" % (showid, pathid)) except TypeError: update_item = False - log("showid: %s not found." % itemid, 2) + log.info("showid: %s not found." % itemid) kodicursor.execute("select coalesce(max(idShow),0) from tvshow") showid = kodicursor.fetchone()[0] + 1 @@ -1019,7 +1021,7 @@ class TVShows(Items): except TypeError: # item is not found, let's recreate it. update_item = False - log("showid: %s missing from Kodi, repairing the entry." % showid, 1) + log.info("showid: %s missing from Kodi, repairing the entry." % showid) # Force re-add episodes after the show is re-created. force_episodes = True @@ -1027,7 +1029,7 @@ class TVShows(Items): if viewtag is None or viewid is None: # Get view tag from emby viewtag, viewid, mediatype = emby.getView_embyId(itemid) - log("View tag found: %s" % viewtag, 2) + log.debug("View tag found: %s" % viewtag) # fileId information checksum = API.getChecksum() @@ -1076,7 +1078,7 @@ class TVShows(Items): ##### UPDATE THE TVSHOW ##### if update_item: - log("UPDATE tvshow itemid: %s - Title: %s" % (itemid, title), 1) + log.info("UPDATE tvshow itemid: %s - Title: %s" % (itemid, title)) # Update the tvshow entry query = ' '.join(( @@ -1094,7 +1096,7 @@ class TVShows(Items): ##### OR ADD THE TVSHOW ##### else: - log("ADD tvshow itemid: %s - Title: %s" % (itemid, title), 1) + log.info("ADD tvshow itemid: %s - Title: %s" % (itemid, title)) # Add top path toppathid = self.kodi_db.addPath(toplevelpath) @@ -1165,7 +1167,7 @@ class TVShows(Items): if force_episodes: # We needed to recreate the show entry. Re-add episodes now. - log("Repairing episodes for showid: %s %s" % (showid, title), 1) + log.info("Repairing episodes for showid: %s %s" % (showid, title)) all_episodes = emby.getEpisodesbyShow(itemid) self.added_episode(all_episodes['Items'], None) @@ -1214,11 +1216,11 @@ class TVShows(Items): episodeid = emby_dbitem[0] fileid = emby_dbitem[1] pathid = emby_dbitem[2] - log("episodeid: %s fileid: %s pathid: %s" % (episodeid, fileid, pathid), 1) + log.info("episodeid: %s fileid: %s pathid: %s" % (episodeid, fileid, pathid)) except TypeError: update_item = False - log("episodeid: %s not found." % itemid, 2) + log.info("episodeid: %s not found." % itemid) # episodeid kodicursor.execute("select coalesce(max(idEpisode),0) from episode") episodeid = kodicursor.fetchone()[0] + 1 @@ -1232,7 +1234,7 @@ class TVShows(Items): except TypeError: # item is not found, let's recreate it. update_item = False - log("episodeid: %s missing from Kodi, repairing the entry." % episodeid, 1) + log.info("episodeid: %s missing from Kodi, repairing the entry." % episodeid) # fileId information checksum = API.getChecksum() @@ -1256,7 +1258,7 @@ class TVShows(Items): seriesId = item['SeriesId'] except KeyError: # Missing seriesId, skip - log("Skipping: %s. SeriesId is missing." % itemid, 1) + log.error("Skipping: %s. SeriesId is missing." % itemid) return False season = item.get('ParentIndexNumber') @@ -1294,7 +1296,7 @@ class TVShows(Items): try: showid = show[0] except TypeError: - log("Skipping: %s. Unable to add series: %s." % (itemid, seriesId)) + log.error("Skipping: %s. Unable to add series: %s." % (itemid, seriesId)) return False seasonid = self.kodi_db.addSeason(showid, season) @@ -1331,7 +1333,7 @@ class TVShows(Items): ##### UPDATE THE EPISODE ##### if update_item: - log("UPDATE episode itemid: %s - Title: %s" % (itemid, title), 1) + log.info("UPDATE episode itemid: %s - Title: %s" % (itemid, title)) # Update the movie entry if self.kodiversion in (16, 17): @@ -1365,7 +1367,7 @@ class TVShows(Items): ##### OR ADD THE EPISODE ##### else: - log("ADD episode itemid: %s - Title: %s" % (itemid, title), 1) + log.info("ADD episode itemid: %s - Title: %s" % (itemid, title)) # Add path pathid = self.kodi_db.addPath(path) @@ -1468,9 +1470,9 @@ class TVShows(Items): kodiid = emby_dbitem[0] fileid = emby_dbitem[1] mediatype = emby_dbitem[4] - log( + log.info( "Update playstate for %s: %s fileid: %s" - % (mediatype, item['Name'], fileid), 1) + % (mediatype, item['Name'], fileid)) except TypeError: return @@ -1487,7 +1489,7 @@ class TVShows(Items): resume = API.adjustResume(userdata['Resume']) total = round(float(runtime), 6) - log("%s New resume point: %s" % (itemid, resume)) + log.debug("%s New resume point: %s" % (itemid, resume)) self.kodi_db.addPlaystate(fileid, resume, total, playcount, dateplayed) if not self.directpath and not resume: @@ -1525,7 +1527,7 @@ class TVShows(Items): pathid = emby_dbitem[2] parentid = emby_dbitem[3] mediatype = emby_dbitem[4] - log("Removing %s kodiid: %s fileid: %s" % (mediatype, kodiid, fileid), 1) + log.info("Removing %s kodiid: %s fileid: %s" % (mediatype, kodiid, fileid)) except TypeError: return @@ -1615,14 +1617,14 @@ class TVShows(Items): self.removeShow(parentid) emby_db.removeItem_byKodiId(parentid, "tvshow") - log("Deleted %s: %s from kodi database" % (mediatype, itemid), 1) + log.info("Deleted %s: %s from kodi database" % (mediatype, itemid)) def removeShow(self, kodiid): kodicursor = self.kodicursor self.artwork.deleteArtwork(kodiid, "tvshow", kodicursor) kodicursor.execute("DELETE FROM tvshow WHERE idShow = ?", (kodiid,)) - log("Removed tvshow: %s." % kodiid, 2) + log.debug("Removed tvshow: %s." % kodiid) def removeSeason(self, kodiid): @@ -1630,7 +1632,7 @@ class TVShows(Items): self.artwork.deleteArtwork(kodiid, "season", kodicursor) kodicursor.execute("DELETE FROM seasons WHERE idSeason = ?", (kodiid,)) - log("Removed season: %s." % kodiid, 2) + log.debug("Removed season: %s." % kodiid) def removeEpisode(self, kodiid, fileid): @@ -1639,7 +1641,7 @@ class TVShows(Items): self.artwork.deleteArtwork(kodiid, "episode", kodicursor) kodicursor.execute("DELETE FROM episode WHERE idEpisode = ?", (kodiid,)) kodicursor.execute("DELETE FROM files WHERE idFile = ?", (fileid,)) - log("Removed episode: %s." % kodiid, 2) + log.debug("Removed episode: %s." % kodiid) class Music(Items): @@ -1713,7 +1715,7 @@ class Music(Items): artistid = emby_dbitem[0] except TypeError: update_item = False - log("artistid: %s not found." % itemid, 2) + log.debug("artistid: %s not found." % itemid) ##### The artist details ##### lastScraped = datetime.now().strftime('%Y-%m-%d %H:%M:%S') @@ -1740,13 +1742,13 @@ class Music(Items): ##### UPDATE THE ARTIST ##### if update_item: - log("UPDATE artist itemid: %s - Name: %s" % (itemid, name), 1) + log.info("UPDATE artist itemid: %s - Name: %s" % (itemid, name)) # Update the checksum in emby table emby_db.updateReference(itemid, checksum) ##### OR ADD THE ARTIST ##### else: - log("ADD artist itemid: %s - Name: %s" % (itemid, name), 1) + log.info("ADD artist itemid: %s - Name: %s" % (itemid, name)) # safety checks: It looks like Emby supports the same artist multiple times. # Kodi doesn't allow that. In case that happens we just merge the artist entries. artistid = self.kodi_db.addArtist(name, musicBrainzId) @@ -1794,7 +1796,7 @@ class Music(Items): albumid = emby_dbitem[0] except TypeError: update_item = False - log("albumid: %s not found." % itemid, 2) + log.debug("albumid: %s not found." % itemid) ##### The album details ##### lastScraped = datetime.now().strftime('%Y-%m-%d %H:%M:%S') @@ -1825,13 +1827,13 @@ class Music(Items): ##### UPDATE THE ALBUM ##### if update_item: - log("UPDATE album itemid: %s - Name: %s" % (itemid, name), 1) + log.info("UPDATE album itemid: %s - Name: %s" % (itemid, name)) # Update the checksum in emby table emby_db.updateReference(itemid, checksum) ##### OR ADD THE ALBUM ##### else: - log("ADD album itemid: %s - Name: %s" % (itemid, name), 1) + log.info("ADD album itemid: %s - Name: %s" % (itemid, name)) # safety checks: It looks like Emby supports the same artist multiple times. # Kodi doesn't allow that. In case that happens we just merge the artist entries. albumid = self.kodi_db.addAlbum(name, musicBrainzId) @@ -1964,7 +1966,7 @@ class Music(Items): albumid = emby_dbitem[3] except TypeError: update_item = False - log("songid: %s not found." % itemid, 2) + log.debug("songid: %s not found." % itemid) ##### The song details ##### checksum = API.getChecksum() @@ -2019,7 +2021,7 @@ class Music(Items): ##### UPDATE THE SONG ##### if update_item: - log("UPDATE song itemid: %s - Title: %s" % (itemid, title), 1) + log.info("UPDATE song itemid: %s - Title: %s" % (itemid, title)) # Update path query = "UPDATE path SET strPath = ? WHERE idPath = ?" @@ -2042,7 +2044,7 @@ class Music(Items): ##### OR ADD THE SONG ##### else: - log("ADD song itemid: %s - Title: %s" % (itemid, title), 1) + log.info("ADD song itemid: %s - Title: %s" % (itemid, title)) # Add path pathid = self.kodi_db.addPath(path) @@ -2055,27 +2057,27 @@ class Music(Items): # Verify if there's an album associated. album_name = item.get('Album') if album_name: - log("Creating virtual music album for song: %s." % itemid, 1) + log.info("Creating virtual music album for song: %s." % itemid) albumid = self.kodi_db.addAlbum(album_name, API.getProvider('MusicBrainzAlbum')) emby_db.addReference("%salbum%s" % (itemid, albumid), albumid, "MusicAlbum_", "album") else: # No album Id associated to the song. - log("Song itemid: %s has no albumId associated." % itemid, 1) + log.error("Song itemid: %s has no albumId associated." % itemid) return False except TypeError: # No album found. Let's create it - log("Album database entry missing.", 1) + log.info("Album database entry missing.") emby_albumId = item['AlbumId'] album = emby.getItem(emby_albumId) self.add_updateAlbum(album) emby_dbalbum = emby_db.getItem_byId(emby_albumId) try: albumid = emby_dbalbum[0] - log("Found albumid: %s" % albumid, 1) + log.info("Found albumid: %s" % albumid) except TypeError: # No album found, create a single's album - log("Failed to add album. Creating singles.", 1) + log.info("Failed to add album. Creating singles.") kodicursor.execute("select coalesce(max(idAlbum),0) from album") albumid = kodicursor.fetchone()[0] + 1 if self.kodiversion == 16: @@ -2257,7 +2259,7 @@ class Music(Items): try: kodiid = emby_dbitem[0] mediatype = emby_dbitem[4] - log("Update playstate for %s: %s" % (mediatype, item['Name']), 1) + log.info("Update playstate for %s: %s" % (mediatype, item['Name'])) except TypeError: return @@ -2296,7 +2298,7 @@ class Music(Items): try: kodiid = emby_dbitem[0] mediatype = emby_dbitem[4] - log("Removing %s kodiid: %s" % (mediatype, kodiid), 1) + log.info("Removing %s kodiid: %s" % (mediatype, kodiid)) except TypeError: return @@ -2364,7 +2366,7 @@ class Music(Items): # Remove artist self.removeArtist(kodiid) - log("Deleted %s: %s from kodi database" % (mediatype, itemid), 1) + log.info("Deleted %s: %s from kodi database" % (mediatype, itemid)) def removeSong(self, kodiId): diff --git a/resources/lib/kodidb_functions.py b/resources/lib/kodidb_functions.py index 86981e7b..9b7aca14 100644 --- a/resources/lib/kodidb_functions.py +++ b/resources/lib/kodidb_functions.py @@ -2,15 +2,19 @@ ################################################################################################## +import logging + import xbmc import api import artwork import clientinfo -from utils import Logging -################################################################################################## +################################################################################################# +log = logging.getLogger("EMBY."+__name__) + +################################################################################################# class Kodidb_Functions(): @@ -18,9 +22,6 @@ class Kodidb_Functions(): def __init__(self, cursor): - - global log - log = Logging(self.__class__.__name__).log self.cursor = cursor @@ -151,7 +152,7 @@ class Kodidb_Functions(): query = "INSERT INTO country(country_id, name) values(?, ?)" self.cursor.execute(query, (country_id, country)) - log("Add country to media, processing: %s" % country, 2) + log.debug("Add country to media, processing: %s" % country) finally: # Assign country to content query = ( @@ -185,7 +186,7 @@ class Kodidb_Functions(): query = "INSERT INTO country(idCountry, strCountry) values(?, ?)" self.cursor.execute(query, (idCountry, country)) - log("Add country to media, processing: %s" % country, 2) + log.debug("Add country to media, processing: %s" % country) finally: # Only movies have a country field @@ -230,7 +231,7 @@ class Kodidb_Functions(): query = "INSERT INTO actor(actor_id, name) values(?, ?)" self.cursor.execute(query, (actorid, name)) - log("Add people to media, processing: %s" % name, 2) + log.debug("Add people to media, processing: %s" % name) finally: # Link person to content @@ -300,7 +301,7 @@ class Kodidb_Functions(): query = "INSERT INTO actors(idActor, strActor) values(?, ?)" self.cursor.execute(query, (actorid, name)) - log("Add people to media, processing: %s" % name, 2) + log.debug("Add people to media, processing: %s" % name) finally: # Link person to content @@ -460,7 +461,7 @@ class Kodidb_Functions(): query = "INSERT INTO genre(genre_id, name) values(?, ?)" self.cursor.execute(query, (genre_id, genre)) - log("Add Genres to media, processing: %s" % genre, 2) + log.debug("Add Genres to media, processing: %s" % genre) finally: # Assign genre to item @@ -505,7 +506,7 @@ class Kodidb_Functions(): query = "INSERT INTO genre(idGenre, strGenre) values(?, ?)" self.cursor.execute(query, (idGenre, genre)) - log("Add Genres to media, processing: %s" % genre, 2) + log.debug("Add Genres to media, processing: %s" % genre) finally: # Assign genre to item @@ -564,7 +565,7 @@ class Kodidb_Functions(): query = "INSERT INTO studio(studio_id, name) values(?, ?)" self.cursor.execute(query, (studioid, studio)) - log("Add Studios to media, processing: %s" % studio, 2) + log.debug("Add Studios to media, processing: %s" % studio) finally: # Assign studio to item query = ( @@ -595,7 +596,7 @@ class Kodidb_Functions(): query = "INSERT INTO studio(idstudio, strstudio) values(?, ?)" self.cursor.execute(query, (studioid, studio)) - log("Add Studios to media, processing: %s" % studio, 2) + log.debug("Add Studios to media, processing: %s" % studio) finally: # Assign studio to item if "movie" in mediatype: @@ -726,7 +727,7 @@ class Kodidb_Functions(): self.cursor.execute(query, (kodiid, mediatype)) # Add tags - log("Adding Tags: %s" % tags, 2) + log.debug("Adding Tags: %s" % tags) for tag in tags: self.addTag(kodiid, tag, mediatype) @@ -748,7 +749,7 @@ class Kodidb_Functions(): except TypeError: # Create the tag, because it does not exist tag_id = self.createTag(tag) - log("Adding tag: %s" % tag, 2) + log.debug("Adding tag: %s" % tag) finally: # Assign tag to item @@ -777,7 +778,7 @@ class Kodidb_Functions(): except TypeError: # Create the tag tag_id = self.createTag(tag) - log("Adding tag: %s" % tag, 2) + log.debug("Adding tag: %s" % tag) finally: # Assign tag to item @@ -813,7 +814,7 @@ class Kodidb_Functions(): query = "INSERT INTO tag(tag_id, name) values(?, ?)" self.cursor.execute(query, (tag_id, name)) - log("Create tag_id: %s name: %s" % (tag_id, name), 2) + log.debug("Create tag_id: %s name: %s" % (tag_id, name)) else: # Kodi Helix query = ' '.join(( @@ -833,13 +834,13 @@ class Kodidb_Functions(): query = "INSERT INTO tag(idTag, strTag) values(?, ?)" self.cursor.execute(query, (tag_id, name)) - log("Create idTag: %s name: %s" % (tag_id, name), 2) + log.debug("Create idTag: %s name: %s" % (tag_id, name)) return tag_id def updateTag(self, oldtag, newtag, kodiid, mediatype): - log("Updating: %s with %s for %s: %s" % (oldtag, newtag, mediatype, kodiid), 2) + log.debug("Updating: %s with %s for %s: %s" % (oldtag, newtag, mediatype, kodiid)) if self.kodiversion in (15, 16, 17): # Kodi Isengard, Jarvis, Krypton @@ -856,7 +857,6 @@ class Kodidb_Functions(): except Exception as e: # The new tag we are going to apply already exists for this item # delete current tag instead - log("Exception: %s" % e, 1) query = ' '.join(( "DELETE FROM tag_link", @@ -880,7 +880,6 @@ class Kodidb_Functions(): except Exception as e: # The new tag we are going to apply already exists for this item # delete current tag instead - log("Exception: %s" % e, 1) query = ' '.join(( "DELETE FROM taglinks", @@ -941,7 +940,7 @@ class Kodidb_Functions(): def createBoxset(self, boxsetname): - log("Adding boxset: %s" % boxsetname, 2) + log.debug("Adding boxset: %s" % boxsetname) query = ' '.join(( "SELECT idSet", diff --git a/resources/lib/kodimonitor.py b/resources/lib/kodimonitor.py index 6ba9e76d..66e0b661 100644 --- a/resources/lib/kodimonitor.py +++ b/resources/lib/kodimonitor.py @@ -3,6 +3,7 @@ ################################################################################################# import json +import logging import xbmc import xbmcgui @@ -11,7 +12,11 @@ import clientinfo import downloadutils import embydb_functions as embydb import playbackutils as pbutils -from utils import Logging, window, settings, kodiSQL +from utils import window, settings, kodiSQL + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -21,23 +26,20 @@ class KodiMonitor(xbmc.Monitor): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.clientInfo = clientinfo.ClientInfo() self.addonName = self.clientInfo.getAddonName() self.doUtils = downloadutils.DownloadUtils() - log("Kodi monitor started.", 1) + log.info("Kodi monitor started.") def onScanStarted(self, library): - log("Kodi library scan %s running." % library, 2) + log.debug("Kodi library scan %s running." % library) if library == "video": window('emby_kodiScan', value="true") def onScanFinished(self, library): - log("Kodi library scan %s finished." % library, 2) + log.debug("Kodi library scan %s finished." % library) if library == "video": window('emby_kodiScan', clear=True) @@ -62,14 +64,14 @@ class KodiMonitor(xbmc.Monitor): currentLog = settings('logLevel') if window('emby_logLevel') != currentLog: # The log level changed, set new prop - log("New log level: %s" % currentLog, 1) + log.info("New log level: %s" % currentLog) window('emby_logLevel', value=currentLog) def onNotification(self, sender, method, data): doUtils = self.doUtils if method not in ("Playlist.OnAdd"): - log("Method: %s Data: %s" % (method, data), 1) + log.info("Method: %s Data: %s" % (method, data)) if data: data = json.loads(data,'utf-8') @@ -82,7 +84,7 @@ class KodiMonitor(xbmc.Monitor): kodiid = item['id'] item_type = item['type'] except (KeyError, TypeError): - log("Item is invalid for playstate update.", 1) + log.info("Item is invalid for playstate update.") else: if ((settings('useDirectPaths') == "1" and not item_type == "song") or (item_type == "song" and settings('enableMusic') == "true")): @@ -94,11 +96,11 @@ class KodiMonitor(xbmc.Monitor): try: itemid = emby_dbitem[0] except TypeError: - log("No kodiId returned.", 1) + log.info("No kodiId returned.") else: url = "{server}/emby/Users/{UserId}/Items/%s?format=json" % itemid result = doUtils.downloadUrl(url) - log("Item: %s" % result, 2) + log.debug("Item: %s" % result) playurl = None count = 0 @@ -130,7 +132,7 @@ class KodiMonitor(xbmc.Monitor): kodiid = item['id'] item_type = item['type'] except (KeyError, TypeError): - log("Item is invalid for playstate update.", 1) + log.info("Item is invalid for playstate update.") else: # Send notification to the server. embyconn = kodiSQL('emby') @@ -140,7 +142,7 @@ class KodiMonitor(xbmc.Monitor): try: itemid = emby_dbitem[0] except TypeError: - log("Could not find itemid in emby database.", 1) + log.info("Could not find itemid in emby database.") else: # Stop from manually marking as watched unwatched, with actual playback. if window('emby_skipWatched%s' % itemid) == "true": @@ -151,10 +153,10 @@ class KodiMonitor(xbmc.Monitor): url = "{server}/emby/Users/{UserId}/PlayedItems/%s?format=json" % itemid if playcount != 0: doUtils.downloadUrl(url, action_type="POST") - log("Mark as watched for itemid: %s" % itemid, 1) + log.info("Mark as watched for itemid: %s" % itemid) else: doUtils.downloadUrl(url, action_type="DELETE") - log("Mark as unwatched for itemid: %s" % itemid, 1) + log.info("Mark as unwatched for itemid: %s" % itemid) finally: embycursor.close() @@ -197,7 +199,7 @@ class KodiMonitor(xbmc.Monitor): elif method == "System.OnSleep": # Connection is going to sleep - log("Marking the server as offline. System.OnSleep activating.", 1) + log.info("Marking the server as offline. System.OnSleep activated.") window('emby_online', value="sleep") elif method == "System.OnWake": diff --git a/resources/lib/librarysync.py b/resources/lib/librarysync.py index d5608a19..72277fa0 100644 --- a/resources/lib/librarysync.py +++ b/resources/lib/librarysync.py @@ -2,6 +2,7 @@ ################################################################################################## +import logging import sqlite3 import threading from datetime import datetime, timedelta, time @@ -20,10 +21,13 @@ import kodidb_functions as kodidb import read_embyserver as embyserver import userclient import videonodes -from utils import Logging, window, settings, language as lang +from utils import window, settings, language as lang ################################################################################################## +log = logging.getLogger("EMBY."+__name__) + +################################################################################################## class LibrarySync(threading.Thread): @@ -43,9 +47,6 @@ class LibrarySync(threading.Thread): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.__dict__ = self._shared_state self.monitor = xbmc.Monitor() @@ -65,7 +66,7 @@ class LibrarySync(threading.Thread): dialog = xbmcgui.DialogProgressBG() dialog.create("Emby for Kodi", title) - log("Show progress dialog: %s" % title, 2) + log.debug("Show progress dialog: %s" % title) return dialog @@ -85,7 +86,7 @@ class LibrarySync(threading.Thread): for plugin in result: if plugin['Name'] == "Emby.Kodi Sync Queue": - log("Found server plugin.", 2) + log.debug("Found server plugin.") completed = self.fastSync() break @@ -105,7 +106,7 @@ class LibrarySync(threading.Thread): lastSync = "2010-01-01T00:00:00Z" lastSyncTime = utils.convertDate(lastSync) - log("Last sync run: %s" % lastSyncTime, 1) + log.info("Last sync run: %s" % lastSyncTime) # get server RetentionDateTime result = self.doUtils("{server}/emby/Emby.Kodi.SyncQueue/GetServerDateTime?format=json") @@ -115,11 +116,11 @@ class LibrarySync(threading.Thread): retention_time = "2010-01-01T00:00:00Z" retention_time = utils.convertDate(retention_time) - log("RetentionDateTime: %s" % retention_time, 1) + log.info("RetentionDateTime: %s" % retention_time) # if last sync before retention time do a full sync if retention_time > lastSyncTime: - log("Fast sync server retention insufficient, fall back to full sync", 1) + log.info("Fast sync server retention insufficient, fall back to full sync") return False params = {'LastUpdateDT': lastSync} @@ -136,11 +137,11 @@ class LibrarySync(threading.Thread): } except (KeyError, TypeError): - log("Failed to retrieve latest updates using fast sync.", 1) + log.error("Failed to retrieve latest updates using fast sync.") return False else: - log("Fast sync changes: %s" % result, 1) + log.info("Fast sync changes: %s" % result) for action in processlist: self.triage_items(action, processlist[action]) @@ -158,14 +159,14 @@ class LibrarySync(threading.Thread): except Exception as e: # If the server plugin is not installed or an error happened. - log("An exception occurred: %s" % e, 1) + log.error("An exception occurred: %s" % e) time_now = datetime.utcnow()-timedelta(minutes=overlap) lastSync = time_now.strftime('%Y-%m-%dT%H:%M:%SZ') - log("New sync time: client time -%s min: %s" % (overlap, lastSync), 1) + log.info("New sync time: client time -%s min: %s" % (overlap, lastSync)) else: lastSync = (server_time - timedelta(minutes=overlap)).strftime('%Y-%m-%dT%H:%M:%SZ') - log("New sync time: server time -%s min: %s" % (overlap, lastSync), 1) + log.info("New sync time: server time -%s min: %s" % (overlap, lastSync)) finally: settings('LastIncrementalSync', value=lastSync) @@ -185,20 +186,20 @@ class LibrarySync(threading.Thread): while kodidb_scan: - log("Kodi scan is running. Waiting...", 1) + log.info("Kodi scan is running. Waiting...") kodidb_scan = window('emby_kodiScan') == "true" if self.shouldStop(): - log("Commit unsuccessful. Sync terminated.", 1) + log.info("Commit unsuccessful. Sync terminated.") break if self.monitor.waitForAbort(1): # Abort was requested while waiting. We should exit - log("Commit unsuccessful.", 1) + log.info("Commit unsuccessful.") break else: connection.commit() - log("Commit successful.", 1) + log.info("Commit successful.") def fullSync(self, manualrun=False, repair=False): # Only run once when first setting up. Can be run manually. @@ -268,8 +269,8 @@ class LibrarySync(threading.Thread): self.dbCommit(kodiconn) embyconn.commit() elapsedTime = datetime.now() - startTime - log("SyncDatabase (finished %s in: %s)" - % (itemtype, str(elapsedTime).split('.')[0]), 1) + log.info("SyncDatabase (finished %s in: %s)" + % (itemtype, str(elapsedTime).split('.')[0])) else: # Close the Kodi cursor kodicursor.close() @@ -296,8 +297,8 @@ class LibrarySync(threading.Thread): musicconn.commit() embyconn.commit() elapsedTime = datetime.now() - startTime - log("SyncDatabase (finished music in: %s)" - % (str(elapsedTime).split('.')[0]), 1) + log.info("SyncDatabase (finished music in: %s)" + % (str(elapsedTime).split('.')[0])) musiccursor.close() if pDialog: @@ -363,7 +364,7 @@ class LibrarySync(threading.Thread): if view['type'] == "mixed": sorted_views.append(view['name']) sorted_views.append(view['name']) - log("Sorted views: %s" % sorted_views, 1) + log.info("Sorted views: %s" % sorted_views) # total nodes for window properties self.vnodes.clearProperties() @@ -423,7 +424,7 @@ class LibrarySync(threading.Thread): else: # Unable to find a match, add the name to our sorted_view list sorted_views.append(foldername) - log("Couldn't find corresponding grouped view: %s" % sorted_views, 1) + log.info("Couldn't find corresponding grouped view: %s" % sorted_views) # Failsafe try: @@ -439,7 +440,7 @@ class LibrarySync(threading.Thread): current_tagid = view[2] except TypeError: - log("Creating viewid: %s in Emby database." % folderid, 1) + log.info("Creating viewid: %s in Emby database." % folderid) tagid = kodi_db.createTag(foldername) # Create playlist for the video library if (foldername not in playlists and @@ -458,12 +459,12 @@ class LibrarySync(threading.Thread): emby_db.addView(folderid, foldername, viewtype, tagid) else: - log(' '.join(( + log.debug(' '.join(( "Found viewid: %s" % folderid, "viewname: %s" % current_viewname, "viewtype: %s" % current_viewtype, - "tagid: %s" % current_tagid)), 2) + "tagid: %s" % current_tagid))) # View is still valid try: @@ -474,7 +475,7 @@ class LibrarySync(threading.Thread): # View was modified, update with latest info if current_viewname != foldername: - log("viewid: %s new viewname: %s" % (folderid, foldername), 1) + log.info("viewid: %s new viewname: %s" % (folderid, foldername)) tagid = kodi_db.createTag(foldername) # Update view with new info @@ -542,7 +543,7 @@ class LibrarySync(threading.Thread): window('Emby.nodes.total', str(totalnodes)) # Remove any old referenced views - log("Removing views: %s" % current_views, 1) + log.info("Removing views: %s" % current_views) for view in current_views: emby_db.removeView(view) @@ -554,7 +555,7 @@ class LibrarySync(threading.Thread): views = emby_db.getView_byType('movies') views += emby_db.getView_byType('mixed') - log("Media folders: %s" % views, 1) + log.info("Media folders: %s" % views) ##### PROCESS MOVIES ##### for view in views: @@ -589,7 +590,7 @@ class LibrarySync(threading.Thread): count += 1 movies.add_update(embymovie, view['name'], view['id']) else: - log("Movies finished.", 2) + log.debug("Movies finished.") ##### PROCESS BOXSETS ##### @@ -616,7 +617,7 @@ class LibrarySync(threading.Thread): count += 1 movies.add_updateBoxset(boxset) else: - log("Boxsets finished.", 2) + log.debug("Boxsets finished.") return True @@ -627,7 +628,7 @@ class LibrarySync(threading.Thread): mvideos = itemtypes.MusicVideos(embycursor, kodicursor) views = emby_db.getView_byType('musicvideos') - log("Media folders: %s" % views, 1) + log.info("Media folders: %s" % views) for view in views: @@ -664,7 +665,7 @@ class LibrarySync(threading.Thread): count += 1 mvideos.add_update(embymvideo, viewName, viewId) else: - log("MusicVideos finished.", 2) + log.debug("MusicVideos finished.") return True @@ -676,7 +677,7 @@ class LibrarySync(threading.Thread): views = emby_db.getView_byType('tvshows') views += emby_db.getView_byType('mixed') - log("Media folders: %s" % views, 1) + log.info("Media folders: %s" % views) for view in views: @@ -722,7 +723,7 @@ class LibrarySync(threading.Thread): pdialog.update(percentage, message="%s - %s" % (title, episodetitle)) tvshows.add_updateEpisode(episode) else: - log("TVShows finished.", 2) + log.debug("TVShows finished.") return True @@ -763,7 +764,7 @@ class LibrarySync(threading.Thread): process[itemtype][1](embyitem) else: - log("%s finished." % itemtype, 2) + log.debug("%s finished." % itemtype) return True @@ -784,7 +785,7 @@ class LibrarySync(threading.Thread): itemids.append(item['ItemId']) items = itemids - log("Queue %s: %s" % (process, items), 1) + log.info("Queue %s: %s" % (process, items)) processlist[process].extend(items) def incrementalSync(self): @@ -806,7 +807,7 @@ class LibrarySync(threading.Thread): incSyncIndicator = int(settings('incSyncIndicator')) totalUpdates = len(self.addedItems) + len(self.updateItems) + len(self.userdataItems) + len(self.removeItems) - log("incSyncIndicator=" + str(incSyncIndicator) + " totalUpdates=" + str(totalUpdates), 1) + log.info("incSyncIndicator=" + str(incSyncIndicator) + " totalUpdates=" + str(totalUpdates)) if incSyncIndicator != -1 and totalUpdates > incSyncIndicator: # Only present dialog if we are going to process items @@ -859,7 +860,7 @@ class LibrarySync(threading.Thread): if update_embydb: update_embydb = False - log("Updating emby database.", 1) + log.info("Updating emby database.") embyconn.commit() self.saveLastSync() @@ -868,7 +869,7 @@ class LibrarySync(threading.Thread): self.forceLibraryUpdate = False self.dbCommit(kodiconn) - log("Updating video library.", 1) + log.info("Updating video library.") window('emby_kodiScan', value="true") xbmc.executebuiltin('UpdateLibrary(video)') @@ -881,7 +882,7 @@ class LibrarySync(threading.Thread): def compareDBVersion(self, current, minimum): # It returns True is database is up to date. False otherwise. - log("current: %s minimum: %s" % (current, minimum), 1) + log.info("current: %s minimum: %s" % (current, minimum)) currMajor, currMinor, currPatch = current.split(".") minMajor, minMinor, minPatch = minimum.split(".") @@ -906,6 +907,7 @@ class LibrarySync(threading.Thread): "Library sync thread has exited! " "You should restart Kodi now. " "Please report this on the forum.")) + log.exception(e) raise def run_internal(self): @@ -914,7 +916,7 @@ class LibrarySync(threading.Thread): startupComplete = False - log("---===### Starting LibrarySync ###===---", 0) + log.warn("---===### Starting LibrarySync ###===---") while not self.monitor.abortRequested(): @@ -932,12 +934,12 @@ class LibrarySync(threading.Thread): uptoDate = self.compareDBVersion(currentVersion, minVersion) if not uptoDate: - log("Database version out of date: %s minimum version required: %s" - % (currentVersion, minVersion), 0) + log.warn("Database version out of date: %s minimum version required: %s" + % (currentVersion, minVersion)) resp = dialog.yesno(lang(29999), lang(33022)) if not resp: - log("Database version is out of date! USER IGNORED!", 0) + log.warn("Database version is out of date! USER IGNORED!") dialog.ok(lang(29999), lang(33023)) else: utils.reset() @@ -952,11 +954,11 @@ class LibrarySync(threading.Thread): videoDb = utils.getKodiVideoDBPath() if not xbmcvfs.exists(videoDb): # Database does not exists - log( + log.error( "The current Kodi version is incompatible " "with the Emby for Kodi add-on. Please visit " "https://github.com/MediaBrowser/Emby.Kodi/wiki " - "to know which Kodi versions are supported.", 0) + "to know which Kodi versions are supported.") dialog.ok( heading=lang(29999), @@ -964,13 +966,13 @@ class LibrarySync(threading.Thread): break # Run start up sync - log("Database version: %s" % settings('dbCreatedWithVersion'), 0) - log("SyncDatabase (started)", 1) + log.warn("Database version: %s" % settings('dbCreatedWithVersion')) + log.info("SyncDatabase (started)") startTime = datetime.now() librarySync = self.startSync() elapsedTime = datetime.now() - startTime - log("SyncDatabase (finished in: %s) %s" - % (str(elapsedTime).split('.')[0], librarySync), 1) + log.info("SyncDatabase (finished in: %s) %s" + % (str(elapsedTime).split('.')[0], librarySync)) # Only try the initial sync once per kodi session regardless # This will prevent an infinite loop in case something goes wrong. startupComplete = True @@ -984,32 +986,32 @@ class LibrarySync(threading.Thread): # Set in kodimonitor.py window('emby_onWake', clear=True) if window('emby_syncRunning') != "true": - log("SyncDatabase onWake (started)", 0) + log.info("SyncDatabase onWake (started)") librarySync = self.startSync() - log("SyncDatabase onWake (finished) %s" % librarySync, 0) + log.info("SyncDatabase onWake (finished) %s" % librarySync) if self.stop_thread: # Set in service.py - log("Service terminated thread.", 2) + log.debug("Service terminated thread.") break if self.monitor.waitForAbort(1): # Abort was requested while waiting. We should exit break - log("###===--- LibrarySync Stopped ---===###", 0) + log.warn("###===--- LibrarySync Stopped ---===###") def stopThread(self): self.stop_thread = True - log("Ending thread...", 2) + log.debug("Ending thread...") def suspendThread(self): self.suspend_thread = True - log("Pausing thread...", 0) + log.debug("Pausing thread...") def resumeThread(self): self.suspend_thread = False - log("Resuming thread...", 0) + log.debug("Resuming thread...") class ManualSync(LibrarySync): @@ -1032,7 +1034,7 @@ class ManualSync(LibrarySync): views = emby_db.getView_byType('movies') views += emby_db.getView_byType('mixed') - log("Media folders: %s" % views, 1) + log.info("Media folders: %s" % views) # Pull the list of movies and boxsets in Kodi try: @@ -1079,7 +1081,7 @@ class ManualSync(LibrarySync): # Only update if movie is not in Kodi or checksum is different updatelist.append(itemid) - log("Movies to update for %s: %s" % (viewName, updatelist), 1) + log.info("Movies to update for %s: %s" % (viewName, updatelist)) embymovies = self.emby.getFullItems(updatelist) total = len(updatelist) del updatelist[:] @@ -1121,7 +1123,7 @@ class ManualSync(LibrarySync): updatelist.append(itemid) embyboxsets.append(boxset) - log("Boxsets to update: %s" % updatelist, 1) + log.info("Boxsets to update: %s" % updatelist) total = len(updatelist) if pdialog: @@ -1145,13 +1147,13 @@ class ManualSync(LibrarySync): if kodimovie not in all_embymoviesIds: movies.remove(kodimovie) else: - log("Movies compare finished.", 1) + log.info("Movies compare finished.") for boxset in all_kodisets: if boxset not in all_embyboxsetsIds: movies.remove(boxset) else: - log("Boxsets compare finished.", 1) + log.info("Boxsets compare finished.") return True @@ -1162,7 +1164,7 @@ class ManualSync(LibrarySync): mvideos = itemtypes.MusicVideos(embycursor, kodicursor) views = emby_db.getView_byType('musicvideos') - log("Media folders: %s" % views, 1) + log.info("Media folders: %s" % views) # Pull the list of musicvideos in Kodi try: @@ -1202,7 +1204,7 @@ class ManualSync(LibrarySync): # Only update if musicvideo is not in Kodi or checksum is different updatelist.append(itemid) - log("MusicVideos to update for %s: %s" % (viewName, updatelist), 1) + log.info("MusicVideos to update for %s: %s" % (viewName, updatelist)) embymvideos = self.emby.getFullItems(updatelist) total = len(updatelist) del updatelist[:] @@ -1229,7 +1231,7 @@ class ManualSync(LibrarySync): if kodimvideo not in all_embymvideosIds: mvideos.remove(kodimvideo) else: - log("MusicVideos compare finished.", 1) + log.info("MusicVideos compare finished.") return True @@ -1241,7 +1243,7 @@ class ManualSync(LibrarySync): views = emby_db.getView_byType('tvshows') views += emby_db.getView_byType('mixed') - log("Media folders: %s" % views, 1) + log.info("Media folders: %s" % views) # Pull the list of tvshows and episodes in Kodi try: @@ -1288,7 +1290,7 @@ class ManualSync(LibrarySync): # Only update if movie is not in Kodi or checksum is different updatelist.append(itemid) - log("TVShows to update for %s: %s" % (viewName, updatelist), 1) + log.info("TVShows to update for %s: %s" % (viewName, updatelist)) embytvshows = self.emby.getFullItems(updatelist) total = len(updatelist) del updatelist[:] @@ -1332,7 +1334,7 @@ class ManualSync(LibrarySync): # Only update if movie is not in Kodi or checksum is different updatelist.append(itemid) - log("Episodes to update for %s: %s" % (viewName, updatelist), 1) + log.info("Episodes to update for %s: %s" % (viewName, updatelist)) embyepisodes = self.emby.getFullItems(updatelist) total = len(updatelist) del updatelist[:] @@ -1357,13 +1359,13 @@ class ManualSync(LibrarySync): if koditvshow not in all_embytvshowsIds: tvshows.remove(koditvshow) else: - log("TVShows compare finished.", 1) + log.info("TVShows compare finished.") for kodiepisode in all_kodiepisodes: if kodiepisode not in all_embyepisodesIds: tvshows.remove(kodiepisode) else: - log("Episodes compare finished.", 1) + log.info("Episodes compare finished.") return True @@ -1429,7 +1431,7 @@ class ManualSync(LibrarySync): if all_kodisongs.get(itemid) != API.getChecksum(): # Only update if songs is not in Kodi or checksum is different updatelist.append(itemid) - log("%s to update: %s" % (data_type, updatelist), 1) + log.info("%s to update: %s" % (data_type, updatelist)) embyitems = self.emby.getFullItems(updatelist) total = len(updatelist) del updatelist[:] @@ -1450,15 +1452,15 @@ class ManualSync(LibrarySync): if kodiartist not in all_embyartistsIds and all_kodiartists[kodiartist] is not None: music.remove(kodiartist) else: - log("Artist compare finished.", 1) + log.info("Artist compare finished.") for kodialbum in all_kodialbums: if kodialbum not in all_embyalbumsIds: music.remove(kodialbum) else: - log("Albums compare finished.", 1) + log.info("Albums compare finished.") for kodisong in all_kodisongs: if kodisong not in all_embysongsIds: music.remove(kodisong) else: - log("Songs compare finished.", 1) + log.info("Songs compare finished.") return True \ No newline at end of file diff --git a/resources/lib/loghandler.py b/resources/lib/loghandler.py new file mode 100644 index 00000000..616ea1b9 --- /dev/null +++ b/resources/lib/loghandler.py @@ -0,0 +1,73 @@ +# -*- coding: utf-8 -*- + +################################################################################################## + +import logging +import xbmc + +from utils import window + +################################################################################################## + + +def config(): + + logger = logging.getLogger('EMBY') + logger.addHandler(LogHandler()) + logger.setLevel(logging.DEBUG) + + +class LogHandler(logging.StreamHandler): + + def __init__(self): + + logging.StreamHandler.__init__(self) + self.setFormatter(MyFormatter()) + + def emit(self, record): + + if self._getLogLevel(record.levelno): + try: + xbmc.log(self.format(record)) + except UnicodeEncodeError: + xbmc.log(self.format(record).encode('utf-8')) + + def _getLogLevel(self, level): + + levels = { + logging.ERROR: 0, + logging.WARNING: 0, + logging.INFO: 1, + logging.DEBUG: 2, + } + try: + logLevel = int(window('emby_logLevel')) + except ValueError: + logLevel = 0 + + return logLevel >= levels[level] + + +class MyFormatter(logging.Formatter): + + def __init__(self, fmt="%(name)s -> %(message)s"): + + logging.Formatter.__init__(self, fmt) + + def format(self, record): + + # Save the original format configured by the user + # when the logger formatter was instantiated + format_orig = self._fmt + + # Replace the original format with one customized by logging level + if record.levelno in (logging.DEBUG, logging.ERROR): + self._fmt = '%(name)s -> %(levelname)s:: %(message)s' + + # Call the original formatter class to do the grunt work + result = logging.Formatter.format(self, record) + + # Restore the original format configured by the user + self._fmt = format_orig + + return result \ No newline at end of file diff --git a/resources/lib/musicutils.py b/resources/lib/musicutils.py index b89c12da..1f5bd9e9 100644 --- a/resources/lib/musicutils.py +++ b/resources/lib/musicutils.py @@ -2,6 +2,7 @@ ################################################################################################# +import logging import os import xbmc @@ -14,8 +15,11 @@ from mutagen import id3 import base64 import read_embyserver as embyserver -from utils import Logging, window -log = Logging('MusicTools').log +from utils import window + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -25,7 +29,7 @@ def getRealFileName(filename, isTemp=False): #get the filename path accessible by python if possible... if not xbmcvfs.exists(filename): - log("File does not exist! %s" % filename, 0) + log.warn("File does not exist! %s" % filename) return (False, "") #if we use os.path method on older python versions (sunch as some android builds), we need to pass arguments as string @@ -102,7 +106,7 @@ def getAdditionalSongTags(embyid, emby_rating, API, kodicursor, emby_db, enablei elif file_rating is None and not currentvalue: return (emby_rating, comment, False) - log("getAdditionalSongTags --> embyid: %s - emby_rating: %s - file_rating: %s - current rating in kodidb: %s" %(embyid, emby_rating, file_rating, currentvalue)) + log.info("getAdditionalSongTags --> embyid: %s - emby_rating: %s - file_rating: %s - current rating in kodidb: %s" %(embyid, emby_rating, file_rating, currentvalue)) updateFileRating = False updateEmbyRating = False @@ -181,7 +185,7 @@ def getSongTags(file): hasEmbeddedCover = False isTemp,filename = getRealFileName(file) - log( "getting song ID3 tags for " + filename) + log.info( "getting song ID3 tags for " + filename) try: ###### FLAC FILES ############# @@ -215,14 +219,14 @@ def getSongTags(file): #POPM rating is 0-255 and needs to be converted to 0-5 range if rating > 5: rating = (rating / 255) * 5 else: - log( "Not supported fileformat or unable to access file: %s" %(filename)) + log.info( "Not supported fileformat or unable to access file: %s" %(filename)) #the rating must be a round value rating = int(round(rating,0)) except Exception as e: #file in use ? - log("Exception in getSongTags %s" % e,0) + log.error("Exception in getSongTags %s" % e) rating = None #remove tempfile if needed.... @@ -244,7 +248,7 @@ def updateRatingToFile(rating, file): xbmcvfs.copy(file, tempfile) tempfile = xbmc.translatePath(tempfile).decode("utf-8") - log( "setting song rating: %s for filename: %s - using tempfile: %s" %(rating,file,tempfile)) + log.info( "setting song rating: %s for filename: %s - using tempfile: %s" %(rating,file,tempfile)) if not tempfile: return @@ -261,7 +265,7 @@ def updateRatingToFile(rating, file): audio.add(id3.POPM(email="Windows Media Player 9 Series", rating=calcrating, count=1)) audio.save() else: - log( "Not supported fileformat: %s" %(tempfile)) + log.info( "Not supported fileformat: %s" %(tempfile)) #once we have succesfully written the flags we move the temp file to destination, otherwise not proceeding and just delete the temp #safety check: we check the file size of the temp file before proceeding with overwite of original file @@ -272,14 +276,14 @@ def updateRatingToFile(rating, file): xbmcvfs.delete(file) xbmcvfs.copy(tempfile,file) else: - log( "Checksum mismatch for filename: %s - using tempfile: %s - not proceeding with file overwite!" %(rating,file,tempfile)) + log.info( "Checksum mismatch for filename: %s - using tempfile: %s - not proceeding with file overwite!" %(rating,file,tempfile)) #always delete the tempfile xbmcvfs.delete(tempfile) except Exception as e: #file in use ? - log("Exception in updateRatingToFile %s" %e,0) + log.error("Exception in updateRatingToFile %s" % e) \ No newline at end of file diff --git a/resources/lib/playbackutils.py b/resources/lib/playbackutils.py index f4cdd8b9..f089195a 100644 --- a/resources/lib/playbackutils.py +++ b/resources/lib/playbackutils.py @@ -3,6 +3,7 @@ ################################################################################################# import json +import logging import sys import xbmc @@ -11,13 +12,16 @@ import xbmcplugin import api import artwork -import clientinfo import downloadutils import playutils as putils import playlist import read_embyserver as embyserver import shutil -from utils import Logging, window, settings, language as lang +from utils import window, settings, language as lang + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -27,14 +31,9 @@ class PlaybackUtils(): def __init__(self, item): - global log - log = Logging(self.__class__.__name__).log - self.item = item self.API = api.API(self.item) - self.clientInfo = clientinfo.ClientInfo() - self.addonName = self.clientInfo.getAddonName() self.doUtils = downloadutils.DownloadUtils().downloadUrl self.userid = window('emby_currUser') @@ -50,7 +49,7 @@ class PlaybackUtils(): listitem = xbmcgui.ListItem() playutils = putils.PlayUtils(self.item) - log("Play called.", 1) + log.info("Play called.") playurl = playutils.getPlayUrl() if not playurl: return xbmcplugin.setResolvedUrl(int(sys.argv[1]), False, listitem) @@ -73,9 +72,9 @@ class PlaybackUtils(): introsPlaylist = False dummyPlaylist = False - log("Playlist start position: %s" % startPos, 2) - log("Playlist plugin position: %s" % currentPosition, 2) - log("Playlist size: %s" % sizePlaylist, 2) + log.debug("Playlist start position: %s" % startPos) + log.debug("Playlist plugin position: %s" % currentPosition) + log.debug("Playlist size: %s" % sizePlaylist) ############### RESUME POINT ################ @@ -87,11 +86,11 @@ class PlaybackUtils(): if not propertiesPlayback: window('emby_playbackProps', value="true") - log("Setting up properties in playlist.", 1) + log.info("Setting up properties in playlist.") if not homeScreen and not seektime and window('emby_customPlaylist') != "true": - log("Adding dummy file to playlist.", 2) + log.debug("Adding dummy file to playlist.") dummyPlaylist = True playlist.add(playurl, listitem, index=startPos) # Remove the original item from playlist @@ -115,14 +114,14 @@ class PlaybackUtils(): if not resp: # User selected to not play trailers getTrailers = False - log("Skip trailers.", 1) + log.info("Skip trailers.") if getTrailers: for intro in intros['Items']: # The server randomly returns intros, process them. introListItem = xbmcgui.ListItem() introPlayurl = putils.PlayUtils(intro).getPlayUrl() - log("Adding Intro: %s" % introPlayurl, 1) + log.info("Adding Intro: %s" % introPlayurl) # Set listitem and properties for intros pbutils = PlaybackUtils(intro) @@ -138,7 +137,7 @@ class PlaybackUtils(): if homeScreen and not seektime and not sizePlaylist: # Extend our current playlist with the actual item to play # only if there's no playlist first - log("Adding main item to playlist.", 1) + log.info("Adding main item to playlist.") self.pl.addtoPlaylist(dbid, self.item['Type'].lower()) # Ensure that additional parts are played after the main item @@ -155,7 +154,7 @@ class PlaybackUtils(): additionalListItem = xbmcgui.ListItem() additionalPlayurl = putils.PlayUtils(part).getPlayUrl() - log("Adding additional part: %s" % partcount, 1) + log.info("Adding additional part: %s" % partcount) # Set listitem and properties for each additional parts pbutils = PlaybackUtils(part) @@ -169,13 +168,13 @@ class PlaybackUtils(): if dummyPlaylist: # Added a dummy file to the playlist, # because the first item is going to fail automatically. - log("Processed as a playlist. First item is skipped.", 1) + log.info("Processed as a playlist. First item is skipped.") return xbmcplugin.setResolvedUrl(int(sys.argv[1]), False, listitem) # We just skipped adding properties. Reset flag for next time. elif propertiesPlayback: - log("Resetting properties playback flag.", 2) + log.debug("Resetting properties playback flag.") window('emby_playbackProps', clear=True) #self.pl.verifyPlaylist() @@ -185,7 +184,7 @@ class PlaybackUtils(): if window('emby_%s.playmethod' % playurl) == "Transcode": # Filter ISO since Emby does not probe anymore if self.item.get('VideoType') == "Iso": - log("Skipping audio/subs prompt, ISO detected.", 1) + log.info("Skipping audio/subs prompt, ISO detected.") else: playurl = playutils.audioSubsPref(playurl, listitem) window('emby_%s.playmethod' % playurl, value="Transcode") @@ -196,18 +195,18 @@ class PlaybackUtils(): ############### PLAYBACK ################ if homeScreen and seektime and window('emby_customPlaylist') != "true": - log("Play as a widget item.", 1) + log.info("Play as a widget item.") self.setListItem(listitem) xbmcplugin.setResolvedUrl(int(sys.argv[1]), True, listitem) elif ((introsPlaylist and window('emby_customPlaylist') == "true") or (homeScreen and not sizePlaylist)): # Playlist was created just now, play it. - log("Play playlist.", 1) + log.info("Play playlist.") xbmc.Player().play(playlist, startpos=startPos) else: - log("Play as a regular item.", 1) + log.info("Play as a regular item.") xbmcplugin.setResolvedUrl(int(sys.argv[1]), True, listitem) def setProperties(self, playurl, listitem): diff --git a/resources/lib/player.py b/resources/lib/player.py index dfefa0ec..1fd19135 100644 --- a/resources/lib/player.py +++ b/resources/lib/player.py @@ -3,6 +3,7 @@ ################################################################################################# import json +import logging import xbmc import xbmcgui @@ -11,7 +12,11 @@ import clientinfo import downloadutils import kodidb_functions as kodidb import websocket_client as wsc -from utils import Logging, window, settings, language as lang +from utils import window, settings, language as lang + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -28,18 +33,14 @@ class Player(xbmc.Player): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.__dict__ = self._shared_state self.clientInfo = clientinfo.ClientInfo() - self.addonName = self.clientInfo.getAddonName() self.doUtils = downloadutils.DownloadUtils().downloadUrl self.ws = wsc.WebSocket_Client() self.xbmcplayer = xbmc.Player() - log("Starting playback monitor.", 2) + log.debug("Starting playback monitor.") def GetPlayStats(self): @@ -63,7 +64,7 @@ class Player(xbmc.Player): except: pass if count == 5: # try 5 times - log("Cancelling playback report...", 1) + log.info("Cancelling playback report...") break else: count += 1 @@ -80,12 +81,12 @@ class Player(xbmc.Player): xbmc.sleep(200) itemId = window("emby_%s.itemid" % currentFile) if tryCount == 20: # try 20 times or about 10 seconds - log("Could not find itemId, cancelling playback report...", 1) + log.info("Could not find itemId, cancelling playback report...") break else: tryCount += 1 else: - log("ONPLAYBACK_STARTED: %s itemid: %s" % (currentFile, itemId), 0) + log.info("ONPLAYBACK_STARTED: %s itemid: %s" % (currentFile, itemId)) # Only proceed if an itemId was found. embyitem = "emby_%s" % currentFile @@ -98,7 +99,7 @@ class Player(xbmc.Player): customseek = window('emby_customPlaylist.seektime') if window('emby_customPlaylist') == "true" and customseek: # Start at, when using custom playlist (play to Kodi from webclient) - log("Seeking to: %s" % customseek, 1) + log.info("Seeking to: %s" % customseek) self.xbmcplayer.seekTime(int(customseek)/10000000.0) window('emby_customPlaylist.seektime', clear=True) @@ -185,7 +186,7 @@ class Player(xbmc.Player): if mapping: # Set in playbackutils.py - log("Mapping for external subtitles index: %s" % mapping, 2) + log.debug("Mapping for external subtitles index: %s" % mapping) externalIndex = json.loads(mapping) if externalIndex.get(str(indexSubs)): @@ -203,7 +204,7 @@ class Player(xbmc.Player): # Post playback to server - log("Sending POST play started: %s." % postdata, 2) + log.debug("Sending POST play started: %s." % postdata) self.doUtils(url, postBody=postdata, action_type="POST") # Ensure we do have a runtime @@ -211,7 +212,7 @@ class Player(xbmc.Player): runtime = int(runtime) except ValueError: runtime = self.xbmcplayer.getTotalTime() - log("Runtime is missing, Kodi runtime: %s" % runtime, 1) + log.info("Runtime is missing, Kodi runtime: %s" % runtime) # Save data map for updates and position calls data = { @@ -228,7 +229,7 @@ class Player(xbmc.Player): } self.played_info[currentFile] = data - log("ADDING_FILE: %s" % self.played_info, 1) + log.info("ADDING_FILE: %s" % self.played_info) # log some playback stats '''if(itemType != None): @@ -247,7 +248,7 @@ class Player(xbmc.Player): def reportPlayback(self): - log("reportPlayback Called", 2) + log.debug("reportPlayback Called") # Get current file currentFile = self.currentFile @@ -345,7 +346,7 @@ class Player(xbmc.Player): if mapping: # Set in PlaybackUtils.py - log("Mapping for external subtitles index: %s" % mapping, 2) + log.debug("Mapping for external subtitles index: %s" % mapping) externalIndex = json.loads(mapping) if externalIndex.get(str(indexSubs)): @@ -365,13 +366,13 @@ class Player(xbmc.Player): # Report progress via websocketclient postdata = json.dumps(postdata) - log("Report: %s" % postdata, 2) + log.debug("Report: %s" % postdata) self.ws.sendProgressUpdate(postdata) def onPlayBackPaused(self): currentFile = self.currentFile - log("PLAYBACK_PAUSED: %s" % currentFile, 2) + log.debug("PLAYBACK_PAUSED: %s" % currentFile) if self.played_info.get(currentFile): self.played_info[currentFile]['paused'] = True @@ -381,7 +382,7 @@ class Player(xbmc.Player): def onPlayBackResumed(self): currentFile = self.currentFile - log("PLAYBACK_RESUMED: %s" % currentFile, 2) + log.debug("PLAYBACK_RESUMED: %s" % currentFile) if self.played_info.get(currentFile): self.played_info[currentFile]['paused'] = False @@ -391,7 +392,7 @@ class Player(xbmc.Player): def onPlayBackSeek(self, time, seekOffset): # Make position when seeking a bit more accurate currentFile = self.currentFile - log("PLAYBACK_SEEK: %s" % currentFile, 2) + log.debug("PLAYBACK_SEEK: %s" % currentFile) if self.played_info.get(currentFile): position = self.xbmcplayer.getTime() @@ -401,16 +402,16 @@ class Player(xbmc.Player): def onPlayBackStopped(self): # Will be called when user stops xbmc playing a file - log("ONPLAYBACK_STOPPED", 2) + log.debug("ONPLAYBACK_STOPPED") window('emby_customPlaylist', clear=True) window('emby_customPlaylist.seektime', clear=True) window('emby_playbackProps', clear=True) - log("Clear playlist properties.", 1) + log.info("Clear playlist properties.") self.stopAll() def onPlayBackEnded(self): # Will be called when xbmc stops playing a file - log("ONPLAYBACK_ENDED", 2) + log.debug("ONPLAYBACK_ENDED") window('emby_customPlaylist.seektime', clear=True) self.stopAll() @@ -419,15 +420,15 @@ class Player(xbmc.Player): if not self.played_info: return - log("Played_information: %s" % self.played_info, 1) + log.info("Played_information: %s" % self.played_info) # Process each items for item in self.played_info: data = self.played_info.get(item) if data: - log("Item path: %s" % item, 2) - log("Item data: %s" % data, 2) + log.debug("Item path: %s" % item) + log.debug("Item data: %s" % data) runtime = data['runtime'] currentPosition = data['currentPosition'] @@ -448,8 +449,8 @@ class Player(xbmc.Player): percentComplete = 0 markPlayedAt = float(settings('markPlayed')) / 100 - log("Percent complete: %s Mark played at: %s" - % (percentComplete, markPlayedAt), 1) + log.info("Percent complete: %s Mark played at: %s" + % (percentComplete, markPlayedAt)) # Send the delete action to the server. offerDelete = False @@ -467,16 +468,16 @@ class Player(xbmc.Player): resp = xbmcgui.Dialog().yesno(lang(30091), lang(33015), autoclose=120000) if resp: url = "{server}/emby/Items/%s?format=json" % itemid - log("Deleting request: %s" % itemid, 1) + log.info("Deleting request: %s" % itemid) self.doUtils(url, action_type="DELETE") else: - log("User skipped deletion.", 1) + log.info("User skipped deletion.") self.stopPlayback(data) # Stop transcoding if playMethod == "Transcode": - log("Transcoding for %s terminated." % itemid, 1) + log.info("Transcoding for %s terminated." % itemid) deviceId = self.clientInfo.getDeviceId() url = "{server}/emby/Videos/ActiveEncodings?DeviceId=%s" % deviceId self.doUtils(url, action_type="DELETE") @@ -485,7 +486,7 @@ class Player(xbmc.Player): def stopPlayback(self, data): - log("stopPlayback called", 2) + log.debug("stopPlayback called") itemId = data['item_id'] currentPosition = data['currentPosition'] diff --git a/resources/lib/playlist.py b/resources/lib/playlist.py index 1f0819b6..6f40fa71 100644 --- a/resources/lib/playlist.py +++ b/resources/lib/playlist.py @@ -3,17 +3,21 @@ ################################################################################################# import json +import logging import xbmc import xbmcgui import xbmcplugin -import clientinfo import playutils import playbackutils import embydb_functions as embydb import read_embyserver as embyserver -from utils import Logging, window, settings, language as lang, kodiSQL +from utils import window, settings, language as lang, kodiSQL + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -23,12 +27,6 @@ class Playlist(): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - - self.clientInfo = clientinfo.ClientInfo() - self.addonName = self.clientInfo.getAddonName() - self.userid = window('emby_currUser') self.server = window('emby_server%s' % self.userid) @@ -45,8 +43,8 @@ class Playlist(): playlist = xbmc.PlayList(xbmc.PLAYLIST_VIDEO) playlist.clear() - log("---*** PLAY ALL ***---", 1) - log("Items: %s and start at: %s" % (itemids, startat), 1) + log.info("---*** PLAY ALL ***---") + log.info("Items: %s and start at: %s" % (itemids, startat)) started = False window('emby_customplaylist', value="true") @@ -62,14 +60,14 @@ class Playlist(): mediatype = embydb_item[4] except TypeError: # Item is not found in our database, add item manually - log("Item was not found in the database, manually adding item.", 1) + log.info("Item was not found in the database, manually adding item.") item = self.emby.getItem(itemid) self.addtoPlaylist_xbmc(playlist, item) else: # Add to playlist self.addtoPlaylist(dbid, mediatype) - log("Adding %s to playlist." % itemid, 1) + log.info("Adding %s to playlist." % itemid) if not started: started = True @@ -84,8 +82,8 @@ class Playlist(): embycursor = embyconn.cursor() emby_db = embydb.Embydb_Functions(embycursor) - log("---*** ADD TO PLAYLIST ***---", 1) - log("Items: %s" % itemids, 1) + log.info("---*** ADD TO PLAYLIST ***---") + log.info("Items: %s" % itemids) player = xbmc.Player() playlist = xbmc.PlayList(xbmc.PLAYLIST_VIDEO) @@ -103,7 +101,7 @@ class Playlist(): # Add to playlist self.addtoPlaylist(dbid, mediatype) - log("Adding %s to playlist." % itemid, 1) + log.info("Adding %s to playlist." % itemid) self.verifyPlaylist() embycursor.close() @@ -126,17 +124,17 @@ class Playlist(): else: pl['params']['item'] = {'file': url} - log(xbmc.executeJSONRPC(json.dumps(pl)), 2) + log.debug(xbmc.executeJSONRPC(json.dumps(pl))) def addtoPlaylist_xbmc(self, playlist, item): playurl = playutils.PlayUtils(item).getPlayUrl() if not playurl: # Playurl failed - log("Failed to retrieve playurl.", 1) + log.info("Failed to retrieve playurl.") return - log("Playurl: %s" % playurl) + log.info("Playurl: %s" % playurl) listitem = xbmcgui.ListItem() playbackutils.PlaybackUtils(item).setProperties(playurl, listitem) @@ -160,7 +158,7 @@ class Playlist(): else: pl['params']['item'] = {'file': url} - log(xbmc.executeJSONRPC(json.dumps(pl)), 2) + log.debug(xbmc.executeJSONRPC(json.dumps(pl))) def verifyPlaylist(self): @@ -174,7 +172,7 @@ class Playlist(): 'playlistid': 1 } } - log(xbmc.executeJSONRPC(json.dumps(pl)), 2) + log.debug(xbmc.executeJSONRPC(json.dumps(pl))) def removefromPlaylist(self, position): @@ -189,4 +187,4 @@ class Playlist(): 'position': position } } - log(xbmc.executeJSONRPC(json.dumps(pl)), 2) \ No newline at end of file + log.debug(xbmc.executeJSONRPC(json.dumps(pl))) \ No newline at end of file diff --git a/resources/lib/playutils.py b/resources/lib/playutils.py index 0674be71..3375af55 100644 --- a/resources/lib/playutils.py +++ b/resources/lib/playutils.py @@ -2,6 +2,7 @@ ################################################################################################# +import logging import sys import xbmc @@ -9,7 +10,11 @@ import xbmcgui import xbmcvfs import clientinfo -from utils import Logging, window, settings, language as lang +from utils import window, settings, language as lang + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -19,12 +24,8 @@ class PlayUtils(): def __init__(self, item): - global log - log = Logging(self.__class__.__name__).log - self.item = item self.clientInfo = clientinfo.ClientInfo() - self.addonName = self.clientInfo.getAddonName() self.userid = window('emby_currUser') self.server = window('emby_server%s' % self.userid) @@ -37,19 +38,19 @@ class PlayUtils(): if (self.item.get('Type') in ("Recording", "TvChannel") and self.item.get('MediaSources') and self.item['MediaSources'][0]['Protocol'] == "Http"): # Play LiveTV or recordings - log("File protocol is http (livetv).", 1) + log.info("File protocol is http (livetv).") playurl = "%s/emby/Videos/%s/stream.ts?audioCodec=copy&videoCodec=copy" % (self.server, self.item['Id']) window('emby_%s.playmethod' % playurl, value="Transcode") elif self.item.get('MediaSources') and self.item['MediaSources'][0]['Protocol'] == "Http": # Only play as http, used for channels, or online hosting of content - log("File protocol is http.", 1) + log.info("File protocol is http.") playurl = self.httpPlay() window('emby_%s.playmethod' % playurl, value="DirectStream") elif self.isDirectPlay(): - log("File is direct playing.", 1) + log.info("File is direct playing.") playurl = self.directPlay() playurl = playurl.encode('utf-8') # Set playmethod property @@ -57,14 +58,14 @@ class PlayUtils(): elif self.isDirectStream(): - log("File is direct streaming.", 1) + log.info("File is direct streaming.") playurl = self.directStream() # Set playmethod property window('emby_%s.playmethod' % playurl, value="DirectStream") elif self.isTranscoding(): - log("File is transcoding.", 1) + log.info("File is transcoding.") playurl = self.transcoding() # Set playmethod property window('emby_%s.playmethod' % playurl, value="Transcode") @@ -89,7 +90,7 @@ class PlayUtils(): # Requirement: Filesystem, Accessible path if settings('playFromStream') == "true": # User forcing to play via HTTP - log("Can't direct play, play from HTTP enabled.", 1) + log.info("Can't direct play, play from HTTP enabled.") return False videotrack = self.item['MediaSources'][0]['Name'] @@ -109,23 +110,23 @@ class PlayUtils(): '2': 720, '3': 1080 } - log("Resolution is: %sP, transcode for resolution: %sP+" - % (resolution, res[transcodeH265]), 1) + log.info("Resolution is: %sP, transcode for resolution: %sP+" + % (resolution, res[transcodeH265])) if res[transcodeH265] <= resolution: return False canDirectPlay = self.item['MediaSources'][0]['SupportsDirectPlay'] # Make sure direct play is supported by the server if not canDirectPlay: - log("Can't direct play, server doesn't allow/support it.", 1) + log.info("Can't direct play, server doesn't allow/support it.") return False location = self.item['LocationType'] if location == "FileSystem": # Verify the path if not self.fileExists(): - log("Unable to direct play.", 1) - log(self.directPlay(), 1) + log.info("Unable to direct play.") + log.info(self.directPlay()) xbmcgui.Dialog().ok( heading=lang(29999), line1=lang(33011), @@ -167,18 +168,18 @@ class PlayUtils(): # Convert path to direct play path = self.directPlay() - log("Verifying path: %s" % path, 1) + log.info("Verifying path: %s" % path) if xbmcvfs.exists(path): - log("Path exists.", 1) + log.info("Path exists.") return True elif ":" not in path: - log("Can't verify path, assumed linux. Still try to direct play.", 1) + log.info("Can't verify path, assumed linux. Still try to direct play.") return True else: - log("Failed to find file.", 1) + log.info("Failed to find file.") return False def isDirectStream(self): @@ -200,8 +201,8 @@ class PlayUtils(): '2': 720, '3': 1080 } - log("Resolution is: %sP, transcode for resolution: %sP+" - % (resolution, res[transcodeH265]), 1) + log.info("Resolution is: %sP, transcode for resolution: %sP+" + % (resolution, res[transcodeH265])) if res[transcodeH265] <= resolution: return False @@ -213,7 +214,7 @@ class PlayUtils(): # Verify the bitrate if not self.isNetworkSufficient(): - log("The network speed is insufficient to direct stream file.", 1) + log.info("The network speed is insufficient to direct stream file.") return False return True @@ -237,10 +238,10 @@ class PlayUtils(): try: sourceBitrate = int(self.item['MediaSources'][0]['Bitrate']) except (KeyError, TypeError): - log("Bitrate value is missing.", 1) + log.info("Bitrate value is missing.") else: - log("The add-on settings bitrate is: %s, the video bitrate required is: %s" - % (settings, sourceBitrate), 1) + log.info("The add-on settings bitrate is: %s, the video bitrate required is: %s" + % (settings, sourceBitrate)) if settings < sourceBitrate: return False diff --git a/resources/lib/read_embyserver.py b/resources/lib/read_embyserver.py index 15fe2d7a..f2d241a9 100644 --- a/resources/lib/read_embyserver.py +++ b/resources/lib/read_embyserver.py @@ -2,11 +2,16 @@ ################################################################################################# +import logging + import xbmc -import clientinfo import downloadutils -from utils import Logging, window, settings, kodiSQL +from utils import window, settings, kodiSQL + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -18,11 +23,6 @@ class Read_EmbyServer(): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - - self.clientInfo = clientinfo.ClientInfo() - self.addonName = self.clientInfo.getAddonName() self.doUtils = downloadutils.DownloadUtils().downloadUrl self.userId = window('emby_currUser') @@ -211,7 +211,7 @@ class Read_EmbyServer(): items['TotalRecordCount'] = total except TypeError: # Failed to retrieve - log("%s:%s Failed to retrieve the server response." % (url, params), 2) + log.debug("%s:%s Failed to retrieve the server response." % (url, params)) else: index = 0 @@ -253,27 +253,27 @@ class Read_EmbyServer(): # Something happened to the connection if not throttled: throttled = True - log("Throttle activated.", 1) + log.info("Throttle activated.") if jump == highestjump: # We already tried with the highestjump, but it failed. Reset value. - log("Reset highest value.", 1) + log.info("Reset highest value.") highestjump = 0 # Lower the number by half if highestjump: throttled = False jump = highestjump - log("Throttle deactivated.", 1) + log.info("Throttle deactivated.") else: jump = int(jump/4) - log("Set jump limit to recover: %s" % jump, 2) + log.debug("Set jump limit to recover: %s" % jump) retry = 0 while window('emby_online') != "true": # Wait server to come back online if retry == 5: - log("Unable to reconnect to server. Abort process.", 1) + log.info("Unable to reconnect to server. Abort process.") return items retry += 1 @@ -301,7 +301,7 @@ class Read_EmbyServer(): increment = 10 jump += increment - log("Increase jump limit to: %s" % jump, 1) + log.info("Increase jump limit to: %s" % jump) return items def getViews(self, mediatype="", root=False, sortedlist=False): @@ -318,7 +318,7 @@ class Read_EmbyServer(): try: items = result['Items'] except TypeError: - log("Error retrieving views for type: %s" % mediatype, 2) + log.debug("Error retrieving views for type: %s" % mediatype) else: for item in items: @@ -462,7 +462,7 @@ class Read_EmbyServer(): items['TotalRecordCount'] = total except TypeError: # Failed to retrieve - log("%s:%s Failed to retrieve the server response." % (url, params), 2) + log.debug("%s:%s Failed to retrieve the server response." % (url, params)) else: index = 1 @@ -550,9 +550,9 @@ class Read_EmbyServer(): url = "{server}/emby/Users/{UserId}/FavoriteItems/%s?format=json" % itemid doUtils(url, action_type="DELETE") else: - log("Error processing user rating.", 1) + log.info("Error processing user rating.") - log("Update user rating to emby for itemid: %s | favourite: %s" % (itemid, favourite), 1) + log.info("Update user rating to emby for itemid: %s | favourite: %s" % (itemid, favourite)) def refreshItem(self, itemid): diff --git a/resources/lib/userclient.py b/resources/lib/userclient.py index 09cae9fa..37282efb 100644 --- a/resources/lib/userclient.py +++ b/resources/lib/userclient.py @@ -3,6 +3,7 @@ ################################################################################################## import hashlib +import logging import threading import xbmc @@ -13,7 +14,11 @@ import xbmcvfs import artwork import clientinfo import downloadutils -from utils import Logging, window, settings, language as lang +from utils import window, settings, language as lang + +################################################################################################## + +log = logging.getLogger("EMBY."+__name__) ################################################################################################## @@ -39,13 +44,9 @@ class UserClient(threading.Thread): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.__dict__ = self._shared_state self.addon = xbmcaddon.Addon() - self.addonName = clientinfo.ClientInfo().getAddonName() self.doUtils = downloadutils.DownloadUtils() threading.Thread.__init__(self) @@ -63,7 +64,7 @@ class UserClient(threading.Thread): username = settings('username') if not username: - log("No username saved.", 2) + log.debug("No username saved.") return "" return username @@ -88,17 +89,17 @@ class UserClient(threading.Thread): if not s_userId: # Save access token if it's missing from settings settings('userId%s' % username, value=w_userId) - log("Returning userId from WINDOW for username: %s UserId: %s" - % (username, w_userId), 2) + log.debug("Returning userId from WINDOW for username: %s UserId: %s" + % (username, w_userId)) return w_userId # Verify the settings elif s_userId: - log("Returning userId from SETTINGS for username: %s userId: %s" - % (username, s_userId), 2) + log.debug("Returning userId from SETTINGS for username: %s userId: %s" + % (username, s_userId)) return s_userId # No userId found else: - log("No userId saved for username: %s." % username, 1) + log.info("No userId saved for username: %s." % username) def getServer(self, prefix=True): @@ -117,7 +118,7 @@ class UserClient(threading.Thread): server = host + ":" + port if not host: - log("No server information saved.", 2) + log.debug("No server information saved.") return False # If https is true @@ -144,17 +145,17 @@ class UserClient(threading.Thread): if not s_token: # Save access token if it's missing from settings settings('accessToken', value=w_token) - log("Returning accessToken from WINDOW for username: %s accessToken: %s" - % (username, w_token), 2) + log.debug("Returning accessToken from WINDOW for username: %s accessToken: %s" + % (username, w_token)) return w_token # Verify the settings elif s_token: - log("Returning accessToken from SETTINGS for username: %s accessToken: %s" - % (username, s_token), 2) + log.debug("Returning accessToken from SETTINGS for username: %s accessToken: %s" + % (username, s_token)) window('emby_accessToken%s' % username, value=s_token) return s_token else: - log("No token found.", 1) + log.info("No token found.") return "" def getSSLverify(self): @@ -210,7 +211,7 @@ class UserClient(threading.Thread): if result == False: # Access is restricted, set in downloadutils.py via exception - log("Access is restricted.", 1) + log.info("Access is restricted.") self.HasAccess = False elif window('emby_online') != "true": @@ -218,7 +219,7 @@ class UserClient(threading.Thread): pass elif window('emby_serverStatus') == "restricted": - log("Access is granted.", 1) + log.info("Access is granted.") self.HasAccess = True window('emby_serverStatus', clear=True) xbmcgui.Dialog().notification(lang(29999), lang(33007)) @@ -283,12 +284,12 @@ class UserClient(threading.Thread): # If there's no settings.xml if not hasSettings: - log("No settings.xml found.", 1) + log.info("No settings.xml found.") self.auth = False return # If no user information elif not server or not username: - log("Missing server information.", 1) + log.info("Missing server information.") self.auth = False return # If there's a token, load the user @@ -298,9 +299,9 @@ class UserClient(threading.Thread): if result == False: pass else: - log("Current user: %s" % self.currUser, 1) - log("Current userId: %s" % self.currUserId, 1) - log("Current accessToken: %s" % self.currToken, 2) + log.info("Current user: %s" % self.currUser) + log.info("Current userId: %s" % self.currUserId) + log.debug("Current accessToken: %s" % self.currToken) return ##### AUTHENTICATE USER ##### @@ -320,7 +321,7 @@ class UserClient(threading.Thread): option=xbmcgui.ALPHANUM_HIDE_INPUT) # If password dialog is cancelled if not password: - log("No password entered.", 0) + log.warn("No password entered.") window('emby_serverStatus', value="Stop") self.auth = False return @@ -335,17 +336,17 @@ class UserClient(threading.Thread): # Authenticate username and password data = {'username': username, 'password': sha1} - log(data, 2) + log.debug(data) url = "%s/emby/Users/AuthenticateByName?format=json" % server result = self.doUtils.downloadUrl(url, postBody=data, action_type="POST", authenticate=False) try: - log("Auth response: %s" % result, 1) + log.info("Auth response: %s" % result) accessToken = result['AccessToken'] except (KeyError, TypeError): - log("Failed to retrieve the api key.", 1) + log.info("Failed to retrieve the api key.") accessToken = None if accessToken is not None: @@ -354,20 +355,20 @@ class UserClient(threading.Thread): "%s %s!" % (lang(33000), self.currUser.decode('utf-8'))) settings('accessToken', value=accessToken) settings('userId%s' % username, value=result['User']['Id']) - log("User Authenticated: %s" % accessToken, 1) + log.info("User Authenticated: %s" % accessToken) self.loadCurrUser(authenticated=True) window('emby_serverStatus', clear=True) self.retry = 0 else: - log("User authentication failed.", 1) + log.error("User authentication failed.") settings('accessToken', value="") settings('userId%s' % username, value="") dialog.ok(lang(33001), lang(33009)) # Give two attempts at entering password if self.retry == 2: - log("Too many retries. " - "You can retry by resetting attempts in the addon settings.", 1) + log.info("Too many retries. " + "You can retry by resetting attempts in the addon settings.") window('emby_serverStatus', value="Stop") dialog.ok(lang(33001), lang(33010)) @@ -376,13 +377,13 @@ class UserClient(threading.Thread): def resetClient(self): - log("Reset UserClient authentication.", 1) + log.info("Reset UserClient authentication.") if self.currToken is not None: # In case of 401, removed saved token settings('accessToken', value="") window('emby_accessToken%s' % self.getUserId(), clear=True) self.currToken = None - log("User token has been removed.", 1) + log.info("User token has been removed.") self.auth = True self.currUser = None @@ -390,7 +391,7 @@ class UserClient(threading.Thread): def run(self): monitor = xbmc.Monitor() - log("----===## Starting UserClient ##===----", 0) + log.warn("----===## Starting UserClient ##===----") while not monitor.abortRequested(): @@ -425,8 +426,8 @@ class UserClient(threading.Thread): # The status Stop is for when user cancelled password dialog. if server and username and status != "Stop": # Only if there's information found to login - log("Server found: %s" % server, 2) - log("Username found: %s" % username, 2) + log.debug("Server found: %s" % server) + log.debug("Username found: %s" % username) self.auth = True @@ -439,7 +440,7 @@ class UserClient(threading.Thread): break self.doUtils.stopSession() - log("##===---- UserClient Stopped ----===##", 0) + log.warn("##===---- UserClient Stopped ----===##") def stopClient(self): # When emby for kodi terminates diff --git a/resources/lib/utils.py b/resources/lib/utils.py index 079c9514..db01fd35 100644 --- a/resources/lib/utils.py +++ b/resources/lib/utils.py @@ -5,6 +5,7 @@ import cProfile import inspect import json +import logging import pstats import sqlite3 import StringIO @@ -19,46 +20,13 @@ import xbmcaddon import xbmcgui import xbmcvfs +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) + ################################################################################################# # Main methods -class Logging(object): - - - def __init__(self, title=""): - - self.title = title - - def _getLogLevel(self, level): - - try: - logLevel = int(window('emby_logLevel')) - except ValueError: - logLevel = 0 - - return logLevel >= level - - def _printMsg(self, title, msg): - - try: - xbmc.log("%s -> %s" % (title, msg)) - except UnicodeEncodeError: - xbmc.log("%s -> %s" % (title, msg.encode('utf-8'))) - - def log(self, msg, level=1): - - extra = "" - if level == -1: - # Error mode - extra = "::ERROR" - - if self._getLogLevel(level): - self._printMsg("EMBY %s%s" % (self.title, extra), msg) - -# Initiate class for utils.py document logging -log = Logging('Utils').log - - def window(property, value=None, clear=False, window_id=10000): # Get or set window property WINDOW = xbmcgui.Window(window_id) @@ -143,7 +111,7 @@ def querySQL(query, args=None, cursor=None, conntype=None): if cursor is None: if conntype is None: - log("New connection type is missing.", 1) + log.info("New connection type is missing.") return result else: manualconn = True @@ -153,7 +121,7 @@ def querySQL(query, args=None, cursor=None, conntype=None): attempts = 0 while attempts < 3: try: - log("Query: %s Args: %s" % (query, args), 2) + log.debug("Query: %s Args: %s" % (query, args)) if args is None: result = cursor.execute(query) else: @@ -161,22 +129,22 @@ def querySQL(query, args=None, cursor=None, conntype=None): break # Query successful, break out of while loop except sqlite3.OperationalError as e: if "database is locked" in e: - log("%s...Attempt: %s" % (e, attempts), 0) + log.warn("%s...Attempt: %s" % (e, attempts)) attempts += 1 xbmc.sleep(1000) else: - log("Error sqlite3: %s" % e, 0) + log.error(e) if manualconn: cursor.close() raise except sqlite3.Error as e: - log("Error sqlite3: %s" % e, 0) + log.error(e) if manualconn: cursor.close() raise else: failed = True - log("FAILED // Query: %s Args: %s" % (query, args), 1) + log.info("FAILED // Query: %s Args: %s" % (query, args)) if manualconn: if failed: @@ -185,7 +153,7 @@ def querySQL(query, args=None, cursor=None, conntype=None): connection.commit() cursor.close() - log(result, 2) + log.debug(result) return result ################################################################################################# @@ -219,7 +187,7 @@ def setScreensaver(value): } } result = xbmc.executeJSONRPC(json.dumps(query)) - log("Toggling screensaver: %s %s" % (value, result), 1) + log.info("Toggling screensaver: %s %s" % (value, result)) def convertDate(date): try: @@ -300,7 +268,7 @@ def profiling(sortby="cumulative"): s = StringIO.StringIO() ps = pstats.Stats(pr, stream=s).sort_stats(sortby) ps.print_stats() - log(s.getvalue(), 1) + log.info(s.getvalue()) return result @@ -321,7 +289,7 @@ def reset(): window('emby_shouldStop', value="true") count = 10 while window('emby_dbScan') == "true": - log("Sync is running, will retry: %s..." % count) + log.info("Sync is running, will retry: %s..." % count) count -= 1 if count == 0: dialog.ok(language(29999), language(33085)) @@ -335,7 +303,7 @@ def reset(): deleteNodes() # Wipe the kodi databases - log("Resetting the Kodi video database.", 0) + log.warn("Resetting the Kodi video database.") connection = kodiSQL('video') cursor = connection.cursor() cursor.execute('SELECT tbl_name FROM sqlite_master WHERE type="table"') @@ -348,7 +316,7 @@ def reset(): cursor.close() if settings('enableMusic') == "true": - log("Resetting the Kodi music database.", 0) + log.warn("Resetting the Kodi music database.") connection = kodiSQL('music') cursor = connection.cursor() cursor.execute('SELECT tbl_name FROM sqlite_master WHERE type="table"') @@ -361,7 +329,7 @@ def reset(): cursor.close() # Wipe the emby database - log("Resetting the Emby database.", 0) + log.warn("Resetting the Emby database.") connection = kodiSQL('emby') cursor = connection.cursor() cursor.execute('SELECT tbl_name FROM sqlite_master WHERE type="table"') @@ -378,7 +346,7 @@ def reset(): # Offer to wipe cached thumbnails resp = dialog.yesno(language(29999), language(33086)) if resp: - log("Resetting all cached artwork.", 0) + log.warn("Resetting all cached artwork.") # Remove all existing textures first path = xbmc.translatePath("special://thumbnails/").decode('utf-8') if xbmcvfs.exists(path): @@ -414,7 +382,7 @@ def reset(): addondir = xbmc.translatePath(addon.getAddonInfo('profile')).decode('utf-8') dataPath = "%ssettings.xml" % addondir xbmcvfs.delete(dataPath) - log("Deleting: settings.xml", 1) + log.info("Deleting: settings.xml") dialog.ok(heading=language(29999), line1=language(33088)) xbmc.executebuiltin('RestartApp') @@ -488,11 +456,11 @@ def passwordsXML(): for path in paths: if path.find('.//from').text == "smb://%s/" % credentials: paths.remove(path) - log("Successfully removed credentials for: %s" % credentials, 1) + log.info("Successfully removed credentials for: %s" % credentials) etree.ElementTree(root).write(xmlpath) break else: - log("Failed to find saved server: %s in passwords.xml" % credentials, 1) + log.info("Failed to find saved server: %s in passwords.xml" % credentials) settings('networkCreds', value="") xbmcgui.Dialog().notification( @@ -541,7 +509,7 @@ def passwordsXML(): # Add credentials settings('networkCreds', value="%s" % server) - log("Added server: %s to passwords.xml" % server, 1) + log.info("Added server: %s to passwords.xml" % server) # Prettify and write to file try: indent(root) @@ -569,7 +537,7 @@ def playlistXSP(mediatype, tagname, viewid, viewtype="", delete=False): # Create the playlist directory if not xbmcvfs.exists(path): - log("Creating directory: %s" % path, 1) + log.info("Creating directory: %s" % path) xbmcvfs.mkdirs(path) # Only add the playlist if it doesn't already exists @@ -577,7 +545,7 @@ def playlistXSP(mediatype, tagname, viewid, viewtype="", delete=False): if delete: xbmcvfs.delete(xsppath) - log("Successfully removed playlist: %s." % tagname, 1) + log.info("Successfully removed playlist: %s." % tagname) return @@ -585,11 +553,11 @@ def playlistXSP(mediatype, tagname, viewid, viewtype="", delete=False): itemtypes = { 'homevideos': "movies" } - log("Writing playlist file to: %s" % xsppath, 1) + log.info("Writing playlist file to: %s" % xsppath) try: f = xbmcvfs.File(xsppath, 'w') except: - log("Failed to create playlist: %s" % xsppath, 1) + log.info("Failed to create playlist: %s" % xsppath) return else: f.write( @@ -603,7 +571,7 @@ def playlistXSP(mediatype, tagname, viewid, viewtype="", delete=False): '' % (itemtypes.get(mediatype, mediatype), plname, tagname)) f.close() - log("Successfully added playlist: %s" % tagname, 1) + log.info("Successfully added playlist: %s" % tagname) def deletePlaylists(): @@ -625,10 +593,10 @@ def deleteNodes(): try: shutil.rmtree("%s%s" % (path, dir.decode('utf-8'))) except: - log("Failed to delete directory: %s" % dir.decode('utf-8'), 0) + log.warn("Failed to delete directory: %s" % dir.decode('utf-8')) for file in files: if file.decode('utf-8').startswith('emby'): try: xbmcvfs.delete("%s%s" % (path, file.decode('utf-8'))) except: - log("Failed to file: %s" % file.decode('utf-8'), 0) \ No newline at end of file + log.warn("Failed to delete file: %s" % file.decode('utf-8')) \ No newline at end of file diff --git a/resources/lib/videonodes.py b/resources/lib/videonodes.py index bf1d20f4..6873487c 100644 --- a/resources/lib/videonodes.py +++ b/resources/lib/videonodes.py @@ -2,6 +2,7 @@ ################################################################################################# +import logging import shutil import xml.etree.ElementTree as etree @@ -9,9 +10,12 @@ import xbmc import xbmcaddon import xbmcvfs -import clientinfo import utils -from utils import Logging, window, language as lang +from utils import window, language as lang + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -21,12 +25,6 @@ class VideoNodes(object): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - - clientInfo = clientinfo.ClientInfo() - self.addonName = clientInfo.getAddonName() - self.kodiversion = int(xbmc.getInfoLabel('System.BuildVersion')[:2]) @@ -79,7 +77,7 @@ class VideoNodes(object): for file in files: xbmcvfs.delete(nodepath + file) - log("Sucessfully removed videonode: %s." % tagname, 1) + log.info("Sucessfully removed videonode: %s." % tagname) return # Create index entry @@ -364,7 +362,7 @@ class VideoNodes(object): def clearProperties(self): - log("Clearing nodes properties.", 1) + log.info("Clearing nodes properties.") embyprops = window('Emby.nodes.total') propnames = [ diff --git a/resources/lib/websocket_client.py b/resources/lib/websocket_client.py index 87d1e012..db0f8c00 100644 --- a/resources/lib/websocket_client.py +++ b/resources/lib/websocket_client.py @@ -3,6 +3,7 @@ ################################################################################################# import json +import logging import threading import websocket @@ -14,9 +15,13 @@ import downloadutils import librarysync import playlist import userclient -from utils import Logging, window, settings, language as lang +from utils import window, settings, language as lang -################################################################################################# +################################################################################################## + +log = logging.getLogger("EMBY."+__name__) + +################################################################################################## class WebSocket_Client(threading.Thread): @@ -29,15 +34,11 @@ class WebSocket_Client(threading.Thread): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.__dict__ = self._shared_state self.monitor = xbmc.Monitor() self.doUtils = downloadutils.DownloadUtils() self.clientInfo = clientinfo.ClientInfo() - self.addonName = self.clientInfo.getAddonName() self.deviceId = self.clientInfo.getDeviceId() self.librarySync = librarysync.LibrarySync() @@ -46,7 +47,7 @@ class WebSocket_Client(threading.Thread): def sendProgressUpdate(self, data): - log("sendProgressUpdate", 2) + log.debug("sendProgressUpdate") try: messageData = { @@ -55,10 +56,10 @@ class WebSocket_Client(threading.Thread): } messageString = json.dumps(messageData) self.client.send(messageString) - log("Message data: %s" % messageString, 2) + log.debug("Message data: %s" % messageString) except Exception as e: - log("Exception: %s" % e, 1) + log.exception(e) def on_message(self, ws, message): @@ -69,7 +70,7 @@ class WebSocket_Client(threading.Thread): if messageType not in ('SessionEnded'): # Mute certain events - log("Message: %s" % message, 1) + log.info("Message: %s" % message) if messageType == "Play": # A remote control play command has been sent from the server. @@ -118,10 +119,10 @@ class WebSocket_Client(threading.Thread): seekto = data['SeekPositionTicks'] seektime = seekto / 10000000.0 action(seektime) - log("Seek to %s." % seektime, 1) + log.info("Seek to %s." % seektime) else: action() - log("Command: %s completed." % command, 1) + log.info("Command: %s completed." % command) window('emby_command', value="true") @@ -254,7 +255,7 @@ class WebSocket_Client(threading.Thread): self.librarySync.refresh_views = True def on_close(self, ws): - log("Closed.", 2) + log.debug("Closed.") def on_open(self, ws): self.doUtils.postCapabilities(self.deviceId) @@ -264,7 +265,7 @@ class WebSocket_Client(threading.Thread): # Server is offline pass else: - log("Error: %s" % error, 2) + log.debug("Error: %s" % error) def run(self): @@ -281,7 +282,7 @@ class WebSocket_Client(threading.Thread): server = server.replace('http', "ws") websocket_url = "%s?api_key=%s&deviceId=%s" % (server, token, self.deviceId) - log("websocket url: %s" % websocket_url, 1) + log.info("websocket url: %s" % websocket_url) self.client = websocket.WebSocketApp(websocket_url, on_message=self.on_message, @@ -289,7 +290,7 @@ class WebSocket_Client(threading.Thread): on_close=self.on_close) self.client.on_open = self.on_open - log("----===## Starting WebSocketClient ##===----", 0) + log.warn("----===## Starting WebSocketClient ##===----") while not self.monitor.abortRequested(): @@ -301,10 +302,10 @@ class WebSocket_Client(threading.Thread): # Abort was requested, exit break - log("##===---- WebSocketClient Stopped ----===##", 0) + log.warn("##===---- WebSocketClient Stopped ----===##") def stopClient(self): self.stopWebsocket = True self.client.close() - log("Stopping thread.", 1) \ No newline at end of file + log.info("Stopping thread.") \ No newline at end of file diff --git a/service.py b/service.py index 13a9d1f0..f88b5c32 100644 --- a/service.py +++ b/service.py @@ -2,6 +2,7 @@ ################################################################################################# +import logging import os import sys import time @@ -30,7 +31,14 @@ import librarysync import player import videonodes import websocket_client as wsc -from utils import Logging, window, settings, language as lang +from utils import window, settings, language as lang + +################################################################################################# + +import loghandler + +loghandler.config() +log = logging.getLogger("EMBY.service") ################################################################################################# @@ -49,9 +57,6 @@ class Service(): def __init__(self): - global log - log = Logging(self.__class__.__name__).log - self.clientInfo = clientinfo.ClientInfo() self.addonName = self.clientInfo.getAddonName() logLevel = userclient.UserClient().getLogLevel() @@ -61,12 +66,12 @@ class Service(): window('emby_kodiProfile', value=xbmc.translatePath('special://profile')) # Initial logging - log("======== START %s ========" % self.addonName, 0) - log("Platform: %s" % (self.clientInfo.getPlatform()), 0) - log("KODI Version: %s" % xbmc.getInfoLabel('System.BuildVersion'), 0) - log("%s Version: %s" % (self.addonName, self.clientInfo.getVersion()), 0) - log("Using plugin paths: %s" % (settings('useDirectPaths') == "0"), 0) - log("Log Level: %s" % logLevel, 0) + log.warn("======== START %s ========" % self.addonName) + log.warn("Platform: %s" % (self.clientInfo.getPlatform())) + log.warn("KODI Version: %s" % xbmc.getInfoLabel('System.BuildVersion')) + log.warn("%s Version: %s" % (self.addonName, self.clientInfo.getVersion())) + log.warn("Using plugin paths: %s" % (settings('useDirectPaths') == "0")) + log.warn("Log Level: %s" % logLevel) # Reset window props for profile switch properties = [ @@ -108,8 +113,8 @@ class Service(): if window('emby_kodiProfile') != kodiProfile: # Profile change happened, terminate this thread and others - log("Kodi profile was: %s and changed to: %s. Terminating old Emby thread." - % (kodiProfile, window('emby_kodiProfile')), 1) + log.info("Kodi profile was: %s and changed to: %s. Terminating old Emby thread." + % (kodiProfile, window('emby_kodiProfile'))) break @@ -151,9 +156,8 @@ class Service(): kplayer.reportPlayback() lastProgressUpdate = datetime.today() - except Exception as e: - log("Exception in Playback Monitor Service: %s" % e, 1) - pass + except Exception: + log.exception("Exception in Playback Monitor Service") else: # Start up events self.warn_auth = True @@ -192,7 +196,7 @@ class Service(): if (user.currUser is None) and self.warn_auth: # Alert user is not authenticated and suppress future warning self.warn_auth = False - log("Not authenticated yet.", 1) + log.info("Not authenticated yet.") # User access is restricted. # Keep verifying until access is granted @@ -221,7 +225,7 @@ class Service(): # Server is offline. # Alert the user and suppress future warning if self.server_online: - log("Server is offline.", 1) + log.info("Server is offline.") window('emby_online', value="false") xbmcgui.Dialog().notification( @@ -235,13 +239,11 @@ class Service(): elif window('emby_online') == "sleep": # device going to sleep if self.websocket_running: - log("Stop websocket thread") ws.stopClient() ws = wsc.WebSocket_Client() self.websocket_running = False if self.library_running: - log("Stop library thread") library.stopThread() library = librarysync.LibrarySync() self.library_running = False @@ -263,12 +265,11 @@ class Service(): sound=False) self.server_online = True - log("Server is online and ready.", 1) + log.info("Server is online and ready.") window('emby_online', value="true") # Start the userclient thread if not self.userclient_running: - log("Start user thread") self.userclient_running = True user.start() @@ -293,14 +294,14 @@ class Service(): if self.websocket_running: ws.stopClient() - log("======== STOP %s ========" % self.addonName, 0) + log.warn("======== STOP %s ========" % self.addonName) # Delay option delay = int(settings('startupDelay')) -xbmc.log("Delaying emby startup by: %s sec..." % delay) +log.info("Delaying emby startup by: %s sec..." % delay) if delay and xbmc.Monitor().waitForAbort(delay): # Start the service - xbmc.log("Abort requested while waiting. Emby for kodi not started.") + log.warn("Abort requested while waiting. Emby for kodi not started.") else: Service().ServiceEntryPoint() \ No newline at end of file