From e197208d3e05433db9e3e478f58af7b3e8262bbb Mon Sep 17 00:00:00 2001 From: angelblue05 Date: Sun, 24 Jul 2016 22:39:40 -0500 Subject: [PATCH] 2.2.17 (#50) * Add temporary setting to disable external subs for direct stream * Fix crash when sleeping/waking up device * Use the logging module. Moved logging to it's own file. * Version bump 2.2.17 * Update README.md --- README.md | 90 ++++++++-------- addon.xml | 2 +- changelog.txt | 4 + contextmenu.py | 19 ++-- default.py | 21 ++-- resources/lib/api.py | 15 ++- resources/lib/artwork.py | 48 +++++---- resources/lib/clientinfo.py | 16 +-- resources/lib/connect.py | 50 ++++----- resources/lib/downloadutils.py | 70 ++++++------- resources/lib/embydb_functions.py | 14 +-- resources/lib/entrypoint.py | 36 ++++--- resources/lib/image_cache_thread.py | 14 +-- resources/lib/initialsetup.py | 58 ++++++----- resources/lib/itemtypes.py | 148 +++++++++++++------------- resources/lib/kodidb_functions.py | 43 ++++---- resources/lib/kodimonitor.py | 39 ++++--- resources/lib/librarysync.py | 154 ++++++++++++++-------------- resources/lib/loghandler.py | 73 +++++++++++++ resources/lib/musicutils.py | 26 +++-- resources/lib/playbackutils.py | 48 ++++----- resources/lib/player.py | 65 ++++++------ resources/lib/playlist.py | 40 ++++---- resources/lib/playutils.py | 53 +++++----- resources/lib/read_embyserver.py | 36 +++---- resources/lib/userclient.py | 85 +++++++-------- resources/lib/utils.py | 92 ++++++----------- resources/lib/videonodes.py | 18 ++-- resources/lib/websocket_client.py | 37 +++---- resources/settings.xml | 1 + service.py | 60 +++++++---- 31 files changed, 780 insertions(+), 695 deletions(-) create mode 100644 resources/lib/loghandler.py diff --git a/README.md b/README.md index 59b8de90..a9fdc034 100644 --- a/README.md +++ b/README.md @@ -1,52 +1,60 @@ -### Welcome to Emby for Kodi +# Welcome to Emby for Kodi **A whole new way to manage and view your media library.** The Emby addon for Kodi combines the best of Kodi - ultra smooth navigation, beautiful UIs and playback of any file under the sun, and Emby - the most powerful fully open source multi-client media metadata indexer and server. -**What does it do?** +### Download and installation -With the old MediaBrowser addon for Kodi we have a couple of issues because you browse your media as a "video addon": -- 3rd party addons such as NextAired, remote apps etc. won't work -- Speed: when browsing the data has to be retrieved from the server. Especially on slower devices this can take too much time. -- All kinds of workaround were needed to get the best experience on Kodi clients +View this short [Youtube video](https://youtu.be/IaecDPcXI3I?t=119) to give you a better idea of the general process. -The new Emby addon synchronizes your media on your Emby server to the native Kodi database. Because we use the native Kodi database with this new approach the above limitations are gone! You can browse your media full speed and all other Kodi addons will be able to "see" your media. +1. Install the Emby repository for Kodi, from the repo install the Emby addon. +2. Within a few seconds you should be prompted for your server-details (or auto discovered). If not, try to restart Kodi +3. Once you're succesfully authenticated to your Emby server, the initial sync will start. +4. The first sync of the Emby server to local Kodi database may take some time depending on your device and library size. +5. Once the full sync is done, you can browse your media in Kodi, syncs will be automatically done in the background. -**What is currently supported ?** +### Our Wiki -We're still in beta stage of development. Currently these features are working: -- Movies -- Sets -- TV Shows -- MusicVideos -- Full sync at first run (import), background syncs configurable by the user in the addonsetting. The current default is that it will do a full sync on the background every couple of minutes. -- Deletions are supported: Items that are deleted on the Emby server will be deleted on the Kodi database. Deletions done from the Kodi client TO the Emby server is only supported if you enable file deletions in the Kodi settings. An additional warning will be diaplayed if you really want to remove the item from the Emby server. +If you need additional information on Emby for Kodi, check out our [wiki](https://github.com/MediaBrowser/plugin.video.emby/wiki). + +### What does Emby for Kodi do? + +The Emby addon synchronizes your media on your Emby server to the native Kodi database. Because we use the native Kodi database, you can browse your media full speed and all other Kodi addons will be able to "see" your media. You can also use any Kodi skin you'd like! + +### IMPORTANT NOTES + +- If you require help, post to our [Emby-Kodi forums](http://emby.media/community/index.php?/forum/99-kodi/) for faster replies. +- To achieve direct play, you will need to ensure your Emby library paths point to network paths (e.g: "\\\\server\Media\Movies"). See the [Emby wiki](https://github.com/MediaBrowser/Wiki/wiki/Path%20Substitution) for additional information. +- **The addon is not (and will not be) compatible with the MySQL database replacement in Kodi.** In fact, Emby takes over the point of having a MySQL database because it acts as a "man in the middle" for your entire media library. +- Emby for Kodi is currently not compatible with Kodi's Video Extras addon unless native playback mode is used. **Deactivate Video Extras if content start randomly playing.** + +### What is currently supported? + +Emby for Kodi is constantly being worked on. The following features are currently provided: + +- Library types available: + + Movies + + Sets + + TV Shows + + Music Videos + + Music +- Emby for Kodi context menu: + + Mark content as favorite + + Refresh content + + Delete content +- Direct play and transcode - Watched state/resume status sync: This is a 2-way synchronisation. Any watched state or resume status will be instantly (within seconds) reflected to or from Kodi and the server. -- Possibility to copy Theme Music locally for use with the TVTunes addon -- Possibility to copy ExtraFanart (rotating backgrounds) across for use with skins that support it +- Copy Theme Music locally for use with the TV Tunes addon +- Copy ExtraFanart (rotating backgrounds) across for use with skins that support it +- Offer to delete content after playback +- and more... -**To get started with the Emby addon for Kodi, first follow these guides to set up Emby and Kodi:** +### What is being worked on +Have a look at our [Trello board](https://trello.com/b/qBJ49ka4/emby-for-kodi) to follow our progress. -1. To prevent any conflicts, remove the "old" MediaBrowser addon from your Kodi setup. -2. If you were using a modded skin for the MediaBrowser addon, make sure to set it in "normal Kodi mode" or just install the unmodded version of the skin. -3. Install the MediaBrowser/Emby BETA repository for Kodi, from the repo install the Emby addon. -4. Within a few seconds you should be prompted for your server-details (or auto discovered). If not, try to restart Kodi -5. Once you're succesfully authenticated to your Emby server, the initial sync will start. -6. The first sync of the Emby server to local Kodi database may take some time. On a powerful machine and fast network, expect around 15-45 minutes. On a slow machine (such as a Raspberry Pi) the first sync may take up to two hours. -7. Once the full sync is done, you can browse your media in Kodi, syncs will be automatically done in the background. - - -**Known Issues:** -- Windows users: Kodi Helix 14.2 RC1 required - other versions will result in errors with recently added items etc. - -**Important note about MySQL database in kodi** - -The addon is not (and will not be) compatible with the MySQL database replacement in Kodi. In fact, Emby takes over the point of having a MySQL database because it acts as a "man in the middle" for your entire media library. - -**Important note about user collections/nodes** - -Emby has the ability to create custom nodes/folders for your Media, such as having a seperate folder for your "Kids Movies" etc. In Kodi this isn't supported, you just have "movies" or "tvshows". But... Kodi let's you create your own playlists and tags to get this same experience. During the sync the foldernode from the Emby server is added to the movies that are imported. In Kodi you can browse to Movie library --> tags and you will have a filtered result that points at your custom node. If you have a skin that let's you create any kind of shortcut on the homescreen you can simply create a shortcut to that tag. Another possibility is to create a "smart playlist" with Kodi and set it to show the content of a certain tag. - -At this point, please hold on to your feature requests and report bugs only. - -Report bugs or any usefull feedback on the forums +### Known Issues +Solutions to the following issues are unlikely due to Kodi limitations. +- Chapter images are missing unless native playback mode is used. +- Certain add-ons that depend on seeing where your content is located will not work unless native playback mode is selected. +- External subtitles (in separate files, e.g. mymovie.srt) can be used, but it is impossible to label them correctly unless direct playing +- Kodi only accepts direct paths for music content unlike the video library. Your Emby music library path will need to be formatted appropriately to work in Kodi (e.g: "\\\\server\Music\Album\song.ext"). See the [Emby wiki](https://github.com/MediaBrowser/Wiki/wiki/Path%20Substitution) for additional information. diff --git a/addon.xml b/addon.xml index 08000cf0..746cc7b4 100644 --- a/addon.xml +++ b/addon.xml @@ -1,7 +1,7 @@ diff --git a/changelog.txt b/changelog.txt index a9282f60..70d0235c 100644 --- a/changelog.txt +++ b/changelog.txt @@ -1,3 +1,7 @@ +version 2.2.17 +- Fix crash when device wakes up +- Add option to disable external subs for direct stream - under add-on settings > playback + version 2.2.16 - Fix strptime error - Temporary fix for database being locked diff --git a/contextmenu.py b/contextmenu.py index b690fd8f..454c7387 100644 --- a/contextmenu.py +++ b/contextmenu.py @@ -2,6 +2,7 @@ ################################################################################################# +import logging import os import sys import urlparse @@ -27,8 +28,14 @@ import read_embyserver as embyserver import embydb_functions as embydb import kodidb_functions as kodidb import musicutils as musicutils -from utils import Logging, settings, language as lang, kodiSQL -log = Logging('ContextMenu').log +from utils import settings, language as lang, kodiSQL + +################################################################################################# + +import loghandler + +loghandler.config() +log = logging.getLogger("EMBY.contextmenu") ################################################################################################# @@ -50,7 +57,7 @@ if __name__ == '__main__': elif xbmc.getCondVisibility("Container.Content(pictures)"): itemType = "picture" else: - log("ItemType is unknown.") + log.info("ItemType is unknown.") if (not kodiId or kodiId == "-1") and xbmc.getInfoLabel("ListItem.Property(embyid)"): itemId = xbmc.getInfoLabel("ListItem.Property(embyid)") @@ -67,7 +74,7 @@ if __name__ == '__main__': pass - log("Found ItemId: %s ItemType: %s" % (itemId, itemType), 1) + log.info("Found ItemId: %s ItemType: %s" % (itemId, itemType)) if itemId: dialog = xbmcgui.Dialog() @@ -157,11 +164,11 @@ if __name__ == '__main__': 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) delete = False if delete: - log("Deleting request: %s" % itemId, 0) + log.info("Deleting request: %s" % itemId) emby.deleteItem(itemId) xbmc.sleep(500) 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 34596c2f..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,15 +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.error("=== Bad status response: %s ===" % r.status_code) r.raise_for_status() ##### EXCEPTIONS ##### @@ -296,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: @@ -329,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.", @@ -344,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 16baa487..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() @@ -195,10 +197,15 @@ class KodiMonitor(xbmc.Monitor): finally: embycursor.close()''' + elif method == "System.OnSleep": + # Connection is going to sleep + log.info("Marking the server as offline. System.OnSleep activated.") + window('emby_online', value="sleep") elif method == "System.OnWake": # Allow network to wake up xbmc.sleep(10000) + window('emby_online', value="false") window('emby_onWake', value="true") diff --git a/resources/lib/librarysync.py b/resources/lib/librarysync.py index d5608a19..4c7ff088 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,11 +807,11 @@ 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) if incSyncIndicator != -1 and totalUpdates > incSyncIndicator: # Only present dialog if we are going to process items pDialog = self.progressDialog('Incremental sync') + log.info("incSyncIndicator=" + str(incSyncIndicator) + " totalUpdates=" + str(totalUpdates)) process = { @@ -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..b576e078 --- /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 4da87f27..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,12 +12,16 @@ import xbmcplugin import api import artwork -import clientinfo import downloadutils import playutils as putils import playlist import read_embyserver as embyserver -from utils import Logging, window, settings, language as lang +import shutil +from utils import window, settings, language as lang + +################################################################################################# + +log = logging.getLogger("EMBY."+__name__) ################################################################################################# @@ -26,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') @@ -49,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) @@ -72,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 ################ @@ -86,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 @@ -114,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) @@ -137,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 @@ -154,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) @@ -168,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() @@ -184,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") @@ -195,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): @@ -228,7 +228,7 @@ class PlaybackUtils(): # Append external subtitles to stream playmethod = window('%s.playmethod' % embyitem) # Only for direct stream - if playmethod in ("DirectStream"): + if playmethod in ("DirectStream") and settings('enableExternalSubs') == "true": # Direct play automatically appends external subtitles = self.externalSubs(playurl) listitem.setSubtitles(subtitles) 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 d08e00ae..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__) ################################################################################################## @@ -23,7 +28,7 @@ class UserClient(threading.Thread): # Borg - multiple instances, shared state _shared_state = {} - stopClient = False + stop_thread = False auth = True retry = 0 @@ -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 @@ -328,24 +329,24 @@ class UserClient(threading.Thread): else: # Manual login, user is hidden password = dialog.input( - heading="%s %s" % (lang(33008), username), + heading="%s %s" % (lang(33008), username.decode('utf-8')), option=xbmcgui.ALPHANUM_HIDE_INPUT) sha1 = hashlib.sha1(password) sha1 = sha1.hexdigest() # 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,12 +426,12 @@ 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 - if self.stopClient == True: + if self.stop_thread == True: # If stopping the client didn't work break @@ -439,8 +440,8 @@ class UserClient(threading.Thread): break self.doUtils.stopSession() - log("##===---- UserClient Stopped ----===##", 0) + log.warn("##===---- UserClient Stopped ----===##") def stopClient(self): # When emby for kodi terminates - self.stopClient = True \ No newline at end of file + self.stop_thread = True \ No newline at end of file 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/resources/settings.xml b/resources/settings.xml index 91006dbb..25e8b247 100644 --- a/resources/settings.xml +++ b/resources/settings.xml @@ -54,6 +54,7 @@ + diff --git a/service.py b/service.py index 9d79adfd..d70dd2b4 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( @@ -231,7 +235,19 @@ class Service(): sound=False) self.server_online = False - + + elif window('emby_online') == "sleep": + # device going to sleep + if self.websocket_running: + ws.stopClient() + ws = wsc.WebSocket_Client() + self.websocket_running = False + + if self.library_running: + library.stopThread() + library = librarysync.LibrarySync() + self.library_running = False + else: # Server is online if not self.server_online: @@ -249,7 +265,7 @@ 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 @@ -278,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')) +log.warn("Delaying emby startup by: %s sec..." % delay) -xbmc.log("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