Use python logging interface

plugin.py

@@ -2,11 +2,12 @@
 """ Addon entry point """
 
 from __future__ import absolute_import, division, unicode_literals
-from resources.lib import kodiwrapper
+from resources.lib import kodiwrapper, kodilogging
 from xbmcaddon import Addon
 
 # Reinitialise ADDON every invocation to fix an issue that settings are not fresh.
 kodiwrapper.ADDON = Addon()
+kodilogging.ADDON = Addon()
 
 if __name__ == '__main__':
  import sys

resources/lib/kodilogging.py

@@ -0,0 +1,51 @@
+# -*- coding: utf-8 -*-
+"""Log handler for Kodi"""
+
+from __future__ import absolute_import, division, unicode_literals
+
+import logging
+
+import xbmc
+import xbmcaddon
+
+ADDON = xbmcaddon.Addon()
+
+
+class KodiLogHandler(logging.StreamHandler):
+ """ A log handler for Kodi """
+
+ def __init__(self):
+ logging.StreamHandler.__init__(self)
+ formatter = logging.Formatter("[{}] [%(name)s] %(message)s".format(ADDON.getAddonInfo("id")))
+ self.setFormatter(formatter)
+
+ def emit(self, record):
+ """ Emit a log message """
+ levels = {
+ logging.CRITICAL: xbmc.LOGFATAL,
+ logging.ERROR: xbmc.LOGERROR,
+ logging.WARNING: xbmc.LOGWARNING,
+ logging.INFO: xbmc.LOGNOTICE,
+ logging.DEBUG: xbmc.LOGDEBUG,
+ logging.NOTSET: xbmc.LOGNONE,
+ }
+
+ # Map DEBUG level to LOGNOTICE if debug logging setting has been activated
+ # This is for troubleshooting only
+ if ADDON.getSetting('debug_logging') == 'true':
+ levels[logging.DEBUG] = xbmc.LOGNOTICE
+
+ try:
+ xbmc.log(self.format(record), levels[record.levelno])
+ except UnicodeEncodeError:
+ xbmc.log(self.format(record).encode('utf-8', 'ignore'), levels[record.levelno])
+
+ def flush(self):
+ """ Flush the messages """
+
+
+def config():
+ """ Setup the logger with this handler """
+ logger = logging.getLogger()
+ logger.addHandler(KodiLogHandler())
+ logger.setLevel(logging.DEBUG)

resources/lib/kodiwrapper.py

@@ -3,13 +3,16 @@
 
 from __future__ import absolute_import, division, unicode_literals
 
+import logging
 from contextlib import contextmanager
 
 import xbmc
 import xbmcaddon
 import xbmcplugin
 from xbmcgui import DialogProgress
 
+_LOGGER = logging.getLogger('kodiwrapper')
+
 SORT_METHODS = dict(
  unsorted=xbmcplugin.SORT_METHOD_UNSORTED,
  label=xbmcplugin.SORT_METHOD_LABEL_IGNORE_FOLDERS,
@@ -22,13 +25,6 @@
  'unsorted', 'label'
 ]
 
-LOG_DEBUG = xbmc.LOGDEBUG
-LOG_INFO = xbmc.LOGINFO
-LOG_NOTICE = xbmc.LOGNOTICE
-LOG_WARNING = xbmc.LOGWARNING
-LOG_ERROR = xbmc.LOGERROR
-LOG_FATAL = xbmc.LOGFATAL
-
 ADDON = xbmcaddon.Addon()
 
 
@@ -113,8 +109,6 @@ def __init__(self, addon=None):
  self._url = None
  self._addon_name = ADDON.getAddonInfo('name')
  self._addon_id = ADDON.getAddonInfo('id')
- self._global_debug_logging = self.get_global_setting('debug.showloginfo') # Returns a boolean
- self._debug_logging = self.get_setting_as_bool('debug_logging')
  self._cache_path = self.get_userdata_path() + 'cache/'
 
  def url_for(self, name, *args, **kwargs):
@@ -332,7 +326,7 @@ def set_locale(self):
  except Exception as exc: # pylint: disable=broad-except
  if locale_lang == 'en_gb':
  return True
- self.log("Your system does not support locale '{locale}': {error}", LOG_DEBUG, locale=locale_lang, error=exc)
+ _LOGGER.debug("Your system does not support locale '%s': %s", locale_lang, exc)
  return False
 
  @staticmethod
@@ -391,7 +385,7 @@ def get_cache(self, key, ttl=None):
  try:
  import json
  value = json.load(fdesc)
- self.log('Fetching {file} from cache', file=fullpath)
+ _LOGGER.debug('Fetching %s from cache', fullpath)
  return value
  except (ValueError, TypeError):
  return None
@@ -407,7 +401,7 @@ def set_cache(self, key, data):
  fullpath = self._cache_path + '.'.join(key)
  with self.open_file(fullpath, 'w') as fdesc:
  import json
- self.log('Storing to cache as {file}', file=fullpath)
+ _LOGGER.debug('Storing to cache as %s', fullpath)
  json.dump(data, fdesc)
 
  def invalidate_cache(self, ttl=None):
@@ -528,16 +522,18 @@ def listdir(path):
  from xbmcvfs import listdir
  return listdir(path)
 
- def mkdir(self, path):
+ @staticmethod
+ def mkdir(path):
  """ Create a directory (using xbmcvfs) """
  from xbmcvfs import mkdir
- self.log("Create directory '{path}'.", LOG_DEBUG, path=path)
+ _LOGGER.debug("Create directory '%s'", path)
  return mkdir(path)
 
- def mkdirs(self, path):
+ @staticmethod
+ def mkdirs(path):
  """ Create directory including parents (using xbmcvfs) """
  from xbmcvfs import mkdirs
- self.log("Recursively create directory '{path}'.", LOG_DEBUG, path=path)
+ _LOGGER.debug("Recursively create directory '%s'", path)
  return mkdirs(path)
 
  @staticmethod
@@ -561,35 +557,23 @@ def stat_file(path):
  from xbmcvfs import Stat
  return Stat(path)
 
- def delete_file(self, path):
+ @staticmethod
+ def delete_file(path):
  """ Remove a file (using xbmcvfs) """
  from xbmcvfs import delete
- self.log("Delete file '{path}'.", LOG_DEBUG, path=path)
+ _LOGGER.debug("Delete file '%s'", path)
  return delete(path)
 
- def container_refresh(self):
+ @staticmethod
+ def container_refresh():
  """ Refresh the current container """
- self.log('Execute: Container.Refresh', LOG_DEBUG)
+ _LOGGER.debug('Execute: Container.Refresh')
  xbmc.executebuiltin('Container.Refresh')
 
  def end_of_directory(self):
  """ Close a virtual directory, required to avoid a waiting Kodi """
  xbmcplugin.endOfDirectory(handle=self._handle, succeeded=False, updateListing=False, cacheToDisc=False)
 
- def log(self, message, log_level=LOG_INFO, **kwargs):
- """ Log info messages to Kodi """
- if not self._debug_logging and log_level in [LOG_DEBUG, LOG_INFO]:
- # Don't log debug and info messages when we haven't activated it.
- return
- if self._debug_logging and log_level in [LOG_DEBUG, LOG_INFO]:
- # Log debug and info messages as LOG_NOTICE if we've explicitly enabled it.
- log_level = LOG_NOTICE
- if kwargs:
- import string
- message = string.Formatter().vformat(message, (), SafeDict(**kwargs))
- message = '[{addon}] {message}'.format(addon=self._addon_id, message=message)
- xbmc.log(msg=from_unicode(message), level=log_level)
-
  def has_credentials(self):
  """ Whether the add-on has credentials filled in """
  return bool(self.get_setting('username') and self.get_setting('password'))
@@ -612,7 +596,7 @@ def notify(self, sender, message, data):
  data=data,
  ))
  if result.get('result') != 'OK':
- self.log('Failed to send notification: {error}', LOG_ERROR, error=result.get('error').get('message'))
+ _LOGGER.error('Failed to send notification: %s', result.get('error').get('message'))
  return False
  return True
 
@@ -638,49 +622,49 @@ def waitForPlayBack(self, url=None, time_out=30): # pylint: disable=invalid-nam
  :type url: str
  :type time_out: int
  """
- self._kodi.log("Player: Waiting for playback", LOG_DEBUG)
+ _LOGGER.debug("Player: Waiting for playback")
  if self.__is_url_playing(url):
  self.__playBackEventsTriggered = True
- self._kodi.log("Player: Already Playing", LOG_DEBUG)
+ _LOGGER.debug("Player: Already Playing")
  return True
 
  for i in range(0, int(time_out / self.__pollInterval)):
  if self.__monitor.abortRequested():
- self._kodi.log("Player: Abort requested (%s)" % i * self.__pollInterval, LOG_DEBUG)
+ _LOGGER.debug("Player: Abort requested (%s)" % i * self.__pollInterval)
  return False
 
  if self.__is_url_playing(url):
- self._kodi.log("Player: PlayBack started (%s)" % i * self.__pollInterval, LOG_DEBUG)
+ _LOGGER.debug("Player: PlayBack started (%s)" % i * self.__pollInterval)
  return True
 
  if self.__playPlayBackEndedEventsTriggered:
- self._kodi.log("Player: PlayBackEnded triggered while waiting for start.", LOG_WARNING)
+ _LOGGER.warning("Player: PlayBackEnded triggered while waiting for start.")
  return False
 
  self.__monitor.waitForAbort(self.__pollInterval)
- self._kodi.log("Player: Waiting for an abort (%s)" % i * self.__pollInterval, LOG_DEBUG)
+ _LOGGER.debug("Player: Waiting for an abort (%s)", i * self.__pollInterval)
 
- self._kodi.log("Player: time-out occurred waiting for playback (%s)" % time_out, LOG_WARNING)
+ _LOGGER.warning("Player: time-out occurred waiting for playback (%s)", time_out)
  return False
 
  def onAVStarted(self): # pylint: disable=invalid-name
  """ Will be called when Kodi has a video or audiostream """
- self._kodi.log("Player: [onAVStarted] called", LOG_DEBUG)
+ _LOGGER.debug("Player: [onAVStarted] called")
  self.__playback_started()
 
  def onPlayBackEnded(self): # pylint: disable=invalid-name
  """ Will be called when [Kodi] stops playing a file """
- self._kodi.log("Player: [onPlayBackEnded] called", LOG_DEBUG)
+ _LOGGER.debug("Player: [onPlayBackEnded] called")
  self.__playback_stopped()
 
  def onPlayBackStopped(self): # pylint: disable=invalid-name
  """ Will be called when [user] stops Kodi playing a file """
- self._kodi.log("Player: [onPlayBackStopped] called", LOG_DEBUG)
+ _LOGGER.debug("Player: [onPlayBackStopped] called")
  self.__playback_stopped()
 
  def onPlayBackError(self): # pylint: disable=invalid-name
  """ Will be called when playback stops due to an error. """
- self._kodi.log("Player: [onPlayBackError] called", LOG_DEBUG)
+ _LOGGER.debug("Player: [onPlayBackError] called")
  self.__playback_stopped()
 
  def __playback_stopped(self):
@@ -700,18 +684,18 @@ def __is_url_playing(self, url):
  :rtype: bool
  """
  if not self.isPlaying():
- self._kodi.log("Player: Not playing", LOG_DEBUG)
+ _LOGGER.debug("Player: Not playing")
  return False
 
  if not self.__playBackEventsTriggered:
- self._kodi.log("Player: Playing but the Kodi events did not yet trigger", LOG_DEBUG)
+ _LOGGER.debug("Player: Playing but the Kodi events did not yet trigger")
  return False
 
  # We are playing
  if url is None or url.startswith("plugin://"):
- self._kodi.log("Player: No valid URL to check playback against: %s" % url, LOG_DEBUG)
+ _LOGGER.debug("Player: No valid URL to check playback against: %s", url)
  return True
 
  playing_file = self.getPlayingFile()
- self._kodi.log("Player: Checking \n'%s' vs \n'%s'" % (url, playing_file), LOG_DEBUG)
+ _LOGGER.debug("Player: Checking \n'%s' vs \n'%s'", url, playing_file)
  return url == playing_file

resources/lib/modules/authentication.py

@@ -3,10 +3,14 @@
 
 from __future__ import absolute_import, division, unicode_literals
 
+import logging
+
 from resources.lib.kodiwrapper import TitleItem, to_unicode
 from resources.lib.vtmgo.vtmgo import VtmGo, ApiUpdateRequired
 from resources.lib.vtmgo.vtmgoauth import InvalidLoginException, LoginErrorException
 
+_LOGGER = logging.getLogger('authentication')
+
 
 class Authentication:
  """ Code responsible for the Authentication """
@@ -56,7 +60,7 @@ def select_profile(self, key=None):
  # Save the selected profile
  if key:
  profile = [x for x in profiles if x.key == key][0]
- self._kodi.log('Setting profile to %s' % profile)
+ _LOGGER.debug('Setting profile to %s', profile)
  self._kodi.set_setting('profile', '%s:%s' % (profile.key, profile.product))
  self._kodi.set_setting('profile_name', profile.name)
 

resources/lib/modules/catalog.py

@@ -3,11 +3,15 @@
 
 from __future__ import absolute_import, division, unicode_literals
 
-from resources.lib.kodiwrapper import TitleItem, LOG_ERROR
+import logging
+
+from resources.lib.kodiwrapper import TitleItem
 from resources.lib.modules import CHANNELS
 from resources.lib.modules.menu import Menu
 from resources.lib.vtmgo.vtmgo import VtmGo, UnavailableException, CACHE_PREVENT, ApiUpdateRequired
 
+_LOGGER = logging.getLogger('catalog')
+
 
 class Catalog:
  """ Menu code related to the catalog """
@@ -29,7 +33,7 @@ def show_catalog(self):
  return
 
  except Exception as ex: # pylint: disable=broad-except
- self._kodi.log("%s" % ex, LOG_ERROR)
+ _LOGGER.error("%s", ex)
  self._kodi.show_ok_dialog(message="%s" % ex)
  return
 
@@ -57,7 +61,7 @@ def show_catalog_category(self, category=None):
  return
 
  except Exception as ex: # pylint: disable=broad-except
- self._kodi.log("%s" % ex, LOG_ERROR)
+ _LOGGER.error("%s", ex)
  self._kodi.show_ok_dialog(message="%s" % ex)
  return
 
@@ -80,7 +84,7 @@ def show_catalog_channel(self, channel):
  return
 
  except Exception as ex: # pylint: disable=broad-except
- self._kodi.log("%s" % ex, LOG_ERROR)
+ _LOGGER.error("%s", ex)
  self._kodi.show_ok_dialog(message="%s" % ex)
  return
 
@@ -187,7 +191,7 @@ def show_recommendations(self):
  return
 
  except Exception as ex: # pylint: disable=broad-except
- self._kodi.log("%s" % ex, LOG_ERROR)
+ _LOGGER.error("%s", ex)
  self._kodi.show_ok_dialog(message="%s" % ex)
  return
 
@@ -215,7 +219,7 @@ def show_recommendations_category(self, category):
  return
 
  except Exception as ex: # pylint: disable=broad-except
- self._kodi.log("%s" % ex, LOG_ERROR)
+ _LOGGER.error("%s", ex)
  self._kodi.show_ok_dialog(message="%s" % ex)
  return
 
@@ -240,7 +244,7 @@ def show_mylist(self):
  return
 
  except Exception as ex: # pylint: disable=broad-except
- self._kodi.log("%s" % ex, LOG_ERROR)
+ _LOGGER.error("%s", ex)
  self._kodi.show_ok_dialog(message="%s" % ex)
  return
 
@@ -278,7 +282,7 @@ def show_continuewatching(self):
  return
 
  except Exception as ex: # pylint: disable=broad-except
- self._kodi.log("%s" % ex, LOG_ERROR)
+ _LOGGER.error("%s", ex)
  self._kodi.show_ok_dialog(message="%s" % ex)
  return