Add new logging infrastructure

This PR includes:
- A predefined set of log_levels: Quiet, Info, Verbose, Debug
- Default log_level is 'Info'

addon.py

@@ -28,6 +28,8 @@ def router(params_string):
 
     kodi_wrapper = kodiwrapper.KodiWrapper(_ADDON_HANDLE, _ADDON_URL, addon)
 
+    kodi_wrapper.log_notice('Path: ' + _ADDON_URL, 'Verbose')
+
     if action == actions.CLEAR_COOKIES:
         from resources.lib.vrtplayer import tokenresolver
         token_resolver = tokenresolver.TokenResolver(kodi_wrapper)

resources/lib/kodiwrappers/kodiwrapper.py

@@ -11,18 +11,25 @@
 except ImportError:
     from urllib import urlencode
 
-sort_methods = {
-    # 'date': xbmcplugin.SORT_METHOD_DATE,
-    'dateadded': xbmcplugin.SORT_METHOD_DATEADDED,
-    'duration': xbmcplugin.SORT_METHOD_DURATION,
-    'episode': xbmcplugin.SORT_METHOD_EPISODE,
-    # 'genre': xbmcplugin.SORT_METHOD_GENRE,
-    'label': xbmcplugin.SORT_METHOD_LABEL_IGNORE_THE,
-    # 'none': xbmcplugin.SORT_METHOD_UNSORTED,
+sort_methods = dict(
+    # date=xbmcplugin.SORT_METHOD_DATE,
+    dateadded=xbmcplugin.SORT_METHOD_DATEADDED,
+    duration=xbmcplugin.SORT_METHOD_DURATION,
+    episode=xbmcplugin.SORT_METHOD_EPISODE,
+    # genre=xbmcplugin.SORT_METHOD_GENRE,
+    label=xbmcplugin.SORT_METHOD_LABEL_IGNORE_THE,
+    # none=xbmcplugin.SORT_METHOD_UNSORTED,
     # FIXME: We would like to be able to sort by unprefixed title (ignore date/episode prefix)
-    # 'title': xbmcplugin.SORT_METHOD_TITLE_IGNORE_THE,
-    'unsorted': xbmcplugin.SORT_METHOD_UNSORTED,
-}
+    # title=xbmcplugin.SORT_METHOD_TITLE_IGNORE_THE,
+    unsorted=xbmcplugin.SORT_METHOD_UNSORTED,
+)
+
+log_levels = dict(
+    Quiet=0,
+    Info=1,
+    Verbose=2,
+    Debug=3,
+)
 
 
 def has_socks():
@@ -44,6 +51,7 @@ def __init__(self, handle, url, addon):
         self._url = url
         self._addon = addon
         self._addon_id = addon.getAddonInfo('id')
+        self._max_log_level = log_levels.get(self.get_setting('max_log_level'), 3)
 
     def show_listing(self, list_items, sort='unsorted', ascending=True, content_type=None, cache=True):
         import xbmcgui
@@ -114,7 +122,7 @@ def play(self, video):
         subtitles_visible = self.get_setting('showsubtitles') == 'true'
         # Separate subtitle url for hls-streams
         if subtitles_visible and video.subtitle_url is not None:
-            self.log_notice('subtitle ' + video.subtitle_url)
+            self.log_notice('Subtitle URL: ' + video.subtitle_url)
             play_item.setSubtitles([video.subtitle_url])
 
         xbmcplugin.setResolvedUrl(self._handle, True, listitem=play_item)
@@ -133,7 +141,7 @@ def set_locale(self):
             # NOTE: This only works if the platform supports the Kodi configured locale
             locale.setlocale(locale.LC_ALL, locale_lang)
         except Exception as e:
-            self.log_notice(e)
+            self.log_notice(e, 'Verbose')
 
     def get_localized_string(self, string_id):
         return self._addon.getLocalizedString(string_id)
@@ -241,10 +249,11 @@ def delete_path(self, path):
         import xbmcvfs
         return xbmcvfs.delete(path)
 
-    def log_notice(self, message):
+    def log_notice(self, message, log_level='Info'):
         ''' Log info messages to Kodi '''
-        xbmc.log(msg='[%s] %s' % (self._addon_id, message), level=xbmc.LOGNOTICE)
+        if log_levels.get(log_level, 0) <= self._max_log_level:
+            xbmc.log(msg='[%s] %s' % (self._addon_id, message), level=xbmc.LOGNOTICE)
 
-    def log_error(self, message):
+    def log_error(self, message, log_level='Info'):
         ''' Log error messages to Kodi '''
         xbmc.log(msg='[%s] %s' % (self._addon_id, message), level=xbmc.LOGERROR)

resources/lib/vrtplayer/streamservice.py

@@ -32,6 +32,7 @@ def __init__(self, kodi_wrapper, token_resolver):
         self._license_url = None
 
     def _get_license_url(self):
+        self._kodi_wrapper.log_notice('URL get: ' + self._VUPLAY_API_URL, 'Verbose')
         self._license_url = json.loads(urlopen(self._VUPLAY_API_URL).read()).get('drm_providers', dict()).get('widevine', dict()).get('la_url')
 
     def _create_settings_dir(self):
@@ -98,6 +99,7 @@ def _get_api_data(self, video):
     def _webscrape_api_data(self, video_url):
         '''Scrape api data from VRT NU html page'''
         from bs4 import BeautifulSoup, SoupStrainer
+        self._kodi_wrapper.log_notice('URL get: ' + video_url, 'Verbose')
         html_page = urlopen(video_url).read()
         strainer = SoupStrainer('div', {'class': 'cq-dd-vrtvideo'})
         soup = BeautifulSoup(html_page, 'html.parser', parse_only=strainer)
@@ -147,6 +149,7 @@ def _get_video_json(self, api_data):
         if playertoken:
             api_url = api_data.media_api_url + '/videos/' + api_data.publication_id + \
                 api_data.video_id + '?vrtPlayerToken=' + playertoken + '&client=' + api_data.client
+            self._kodi_wrapper.log_notice('URL get: ' + api_url, 'Verbose')
             try:
                 video_json = json.loads(urlopen(api_url).read())
             except HTTPError as e:
@@ -200,7 +203,7 @@ def get_stream(self, video, retry=False, api_data=None):
                 return self._select_stream(stream_dict, vudrm_token)
 
             if video_json.get('code') in ('INCOMPLETE_ROAMING_CONFIG', 'INVALID_LOCATION'):
-                self._kodi_wrapper.log_notice(video_json.get('message'))
+                self._kodi_wrapper.log_error(video_json.get('message'))
                 roaming_xvrttoken = self.token_resolver.get_xvrttoken(True)
                 if not retry and roaming_xvrttoken is not None:
                     # Delete cached playertokens
@@ -234,22 +237,22 @@ def _select_stream(self, stream_dict, vudrm_token):
         protocol = None
         if vudrm_token and self._can_play_drm and self._kodi_wrapper.get_setting('usedrm') == 'true':
             protocol = 'mpeg_dash drm'
-            self._kodi_wrapper.log_notice('protocol: ' + protocol)
+            self._kodi_wrapper.log_notice('Protocol: ' + protocol)
             stream_url = self._try_get_drm_stream(stream_dict, vudrm_token)
 
         if vudrm_token and stream_url is None:
             protocol = 'hls_aes'
-            self._kodi_wrapper.log_notice('protocol: ' + protocol)
+            self._kodi_wrapper.log_notice('Protocol: ' + protocol)
             stream_url = streamurls.StreamURLS(*self._select_hls_substreams(stream_dict[protocol])) if protocol in stream_dict else None
 
         if self._kodi_wrapper.has_inputstream_adaptive_installed() and stream_url is None:
             protocol = 'mpeg_dash'
-            self._kodi_wrapper.log_notice('protocol: ' + protocol)
+            self._kodi_wrapper.log_notice('Protocol: ' + protocol)
             stream_url = streamurls.StreamURLS(stream_dict[protocol], use_inputstream_adaptive=True) if protocol in stream_dict else None
 
         if stream_url is None:
             protocol = 'hls'
-            self._kodi_wrapper.log_notice('protocol: ' + protocol)
+            self._kodi_wrapper.log_notice('Protocol: ' + protocol)
             # No if-else statement because this is the last resort stream selection
             stream_url = streamurls.StreamURLS(*self._select_hls_substreams(stream_dict[protocol]))
 
@@ -267,6 +270,7 @@ def _select_hls_substreams(self, master_hls_url):
         if any(x in master_hls_url for x in ('.ism/', '.isml/')) and bandwidth_limit == 0:
             import re
             base_url = master_hls_url.split('.m3u8')[0]
+            self._kodi_wrapper.log_notice('URL get: ' + master_hls_url, 'Verbose')
             m3u8 = urlopen(master_hls_url).read()
 
             # Get audio uri

resources/lib/vrtplayer/tokenresolver.py

@@ -75,6 +75,7 @@ def get_cookie_from_cookiejar(cookiename, cookiejar):
 
     def _get_new_playertoken(self, path, token_url, headers):
         import json
+        self._kodi_wrapper.log_notice('URL post: ' + token_url, 'Verbose')
         req = Request(token_url, data='', headers=headers)
         playertoken = json.loads(urlopen(req).read())
         json.dump(playertoken, open(path, 'w'))
@@ -92,10 +93,10 @@ def _get_cached_token(self, path, token_name):
             now = datetime.now(dateutil.tz.tzlocal())
             exp = dateutil.parser.parse(token.get('expirationDate'))
             if exp > now:
-                self._kodi_wrapper.log_notice('Got cached token')
+                self._kodi_wrapper.log_notice('Got cached token', 'Verbose')
                 cached_token = token.get(token_name)
             else:
-                self._kodi_wrapper.log_notice('Cached token deleted')
+                self._kodi_wrapper.log_notice('Cached token deleted', 'Info')
                 self._kodi_wrapper.delete_path(path)
         return cached_token
 
@@ -112,6 +113,7 @@ def _get_new_xvrttoken(self, path, get_roaming_token):
             APIKey=self._API_KEY,
             targetEnv='jssdk',
         )
+        self._kodi_wrapper.log_notice('URL post: ' + self._LOGIN_URL, 'Verbose')
         req = Request(self._LOGIN_URL, data=urlencode(data))
         logon_json = json.loads(urlopen(req).read())
         token = None
@@ -125,7 +127,8 @@ def _get_new_xvrttoken(self, path, get_roaming_token):
                 email=cred.username,
             )
             headers = {'Content-Type': 'application/json', 'Cookie': login_cookie}
-            req = Request(self._TOKEN_GATEWAY_URL, json.dumps(payload), headers)
+            self._kodi_wrapper.log_notice('URL post: ' + self._TOKEN_GATEWAY_URL, 'Verbose')
+            req = Request(self._TOKEN_GATEWAY_URL, data=json.dumps(payload), headers=headers)
             cookie_data = urlopen(req).info().getheader('Set-Cookie').split('X-VRT-Token=')[1].split('; ')
             xvrttoken = TokenResolver._create_token_dictionary_from_urllib(cookie_data)
             if get_roaming_token:
@@ -157,13 +160,15 @@ def _get_roaming_xvrttoken(self, xvrttoken):
         cookie_value = 'X-VRT-Token=' + xvrttoken.get('X-VRT-Token')
         headers = {'Cookie': cookie_value}
         opener = build_opener(NoRedirection, ProxyHandler(self._proxies))
+        self._kodi_wrapper.log_notice('URL post: ' + url, 'Verbose')
         req = Request(url, headers=headers)
         req_info = opener.open(req).info()
         cookie_value += '; state=' + req_info.getheader('Set-Cookie').split('state=')[1].split('; ')[0]
         url = req_info.getheader('Location')
         url = opener.open(url).info().getheader('Location')
         headers = {'Cookie': cookie_value}
         if url is not None:
+            self._kodi_wrapper.log_notice('URL post: ' + url, 'Verbose')
             req = Request(url, headers=headers)
             cookie_data = opener.open(req).info().getheader('Set-Cookie').split('X-VRT-Token=')[1].split('; ')
             roaming_xvrttoken = TokenResolver._create_token_dictionary_from_urllib(cookie_data)

resources/lib/vrtplayer/tvguide.py

@@ -92,6 +92,7 @@ def show_tvguide(self, params):
             dateobj = dateutil.parser.parse(date)
             datelong = dateobj.strftime(self._kodi_wrapper.get_localized_datelong())
             api_url = dateobj.strftime(self.VRT_TVGUIDE)
+            self._kodi_wrapper.log_notice('URL get: ' + api_url, 'Verbose')
             schedule = json.loads(urlopen(api_url).read())
             name = channel
             try:

resources/lib/vrtplayer/vrtapihelper.py

@@ -41,7 +41,7 @@ def get_tvshow_items(self, category=None, channel=None):
             params['facets[programBrands]'] = channel
 
         api_url = self._VRTNU_SUGGEST_URL + '?' + urlencode(params)
-        # tvshows = requests.get(api_url, proxies=self._proxies).json()
+        self._kodi_wrapper.log_notice('URL get: ' + api_url, 'Verbose')
         tvshows = json.loads(urlopen(api_url).read())
         tvshow_items = []
         for tvshow in tvshows:
@@ -98,7 +98,7 @@ def get_episode_items(self, path=None, page=None):
                 'facets[programBrands]': '[een,canvas,sporza,vrtnws,vrtnxt,radio1,radio2,klara,stubru,mnm]',
             }
             api_url = self._VRTNU_SEARCH_URL + '?' + urlencode(params)
-            # api_json = requests.get(api_url, proxies=self._proxies).json()
+            self._kodi_wrapper.log_notice('URL get: ' + api_url, 'Verbose')
             api_json = json.loads(urlopen(api_url).read())
             episode_items, sort, ascending = self._map_to_episode_items(api_json.get('results', []), titletype='recent')
 
@@ -112,7 +112,7 @@ def get_episode_items(self, path=None, page=None):
                 api_url = self._VRTNU_SEARCH_URL + '?' + urlencode(params)
             else:
                 api_url = path
-            # api_json = requests.get(api_url, proxies=self._proxies).json()
+            self._kodi_wrapper.log_notice('URL get: ' + api_url, 'Verbose')
             api_json = json.loads(urlopen(api_url).read())
 
             episodes = api_json.get('results', [{}])

resources/lib/vrtplayer/vrtplayer.py

@@ -12,37 +12,6 @@
     from urllib2 import build_opener, install_opener, ProxyHandler, urlopen
 
 
-def get_categories(proxies=None):
-    from bs4 import BeautifulSoup, SoupStrainer
-    response = urlopen('https://www.vrt.be/vrtnu/categorieen/')
-    tiles = SoupStrainer('a', {'class': 'nui-tile'})
-    soup = BeautifulSoup(response.read(), 'html.parser', parse_only=tiles)
-
-    categories = []
-    for tile in soup.find_all(class_='nui-tile'):
-        categories.append(dict(
-            id=tile.get('href').split('/')[-2],
-            thumbnail=get_category_thumbnail(tile),
-            name=get_category_title(tile),
-        ))
-
-    return categories
-
-
-def get_category_thumbnail(element):
-    from resources.lib.vrtplayer import statichelper
-    raw_thumbnail = element.find(class_='media').get('data-responsive-image', 'DefaultGenre.png')
-    return statichelper.add_https_method(raw_thumbnail)
-
-
-def get_category_title(element):
-    from resources.lib.vrtplayer import statichelper
-    found_element = element.find('h3')
-    if found_element is not None:
-        return statichelper.strip_newlines(found_element.contents[0])
-    return ''
-
-
 class VRTPlayer:
 
     def __init__(self, kodi_wrapper, api_helper):
@@ -187,7 +156,7 @@ def play(self, params):
 
     def __get_category_menu_items(self):
         try:
-            categories = get_categories(self._proxies)
+            categories = self.get_categories(self._proxies)
         except Exception:
             categories = []
 
@@ -205,3 +174,34 @@ def __get_category_menu_items(self):
                                                           art_dict=dict(thumb=thumbnail, icon='DefaultGenre.png', fanart=thumbnail),
                                                           video_dict=dict(plot='[B]%s[/B]' % category.get('name'), studio='VRT')))
         return category_items
+
+    def get_categories(self, proxies=None):
+        from bs4 import BeautifulSoup, SoupStrainer
+        self._kodi_wrapper.log_notice('URL get: https://www.vrt.be/vrtnu/categorieen/', 'Verbose')
+        response = urlopen('https://www.vrt.be/vrtnu/categorieen/')
+        tiles = SoupStrainer('a', {'class': 'nui-tile'})
+        soup = BeautifulSoup(response.read(), 'html.parser', parse_only=tiles)
+
+        categories = []
+        for tile in soup.find_all(class_='nui-tile'):
+            categories.append(dict(
+                id=tile.get('href').split('/')[-2],
+                thumbnail=self.get_category_thumbnail(tile),
+                name=self.get_category_title(tile),
+            ))
+
+        return categories
+
+    @staticmethod
+    def get_category_thumbnail(element):
+        from resources.lib.vrtplayer import statichelper
+        raw_thumbnail = element.find(class_='media').get('data-responsive-image', 'DefaultGenre.png')
+        return statichelper.add_https_method(raw_thumbnail)
+
+    @staticmethod
+    def get_category_title(element):
+        from resources.lib.vrtplayer import statichelper
+        found_element = element.find('h3')
+        if found_element is not None:
+            return statichelper.strip_newlines(found_element.contents[0])
+        return ''

resources/settings.xml

@@ -18,6 +18,6 @@
         <setting label="30041" type="action" id="adaptive_settings" option="close" action="Addon.OpenSettings(inputstream.adaptive)" enable="System.HasAddon(inputstream.adaptive)"/>
         <!-- setting label="30042" type="action" id="widevine_install" option="close" action="RunPlugin(plugin://plugin.video.vrt.nu?action=installwidevine)" enable="System.HasAddon(script.module.inputstreamhelper)"/ -->
         <setting label="30048" type="action" id="clear_tokens" action="RunPlugin(plugin://plugin.video.vrt.nu/?action=clearcookies)"/>
-        <setting label="30049" type="select" id="log_level" values="Info|Verbose|Debug" default="Info"/>
+        <setting label="30049" type="select" id="max_log_level" values="Quiet|Info|Verbose|Debug" default="Info"/>
     </category>
 </settings>

test/vrtplayertests.py

@@ -98,12 +98,14 @@ def test_get_tvshows(self):
     def test_categories_scraping(self):
         ''' Test to ensure our hardcoded categories conforms to scraped categories '''
         # Remove thumbnails from scraped categories first
-        categories = [dict(id=c['id'], name=c['name']) for c in vrtplayer.get_categories()]
+        vrt_player = vrtplayer.VRTPlayer(self._kodi_wrapper, self._api_helper)
+        categories = [dict(id=c['id'], name=c['name']) for c in vrt_player.get_categories()]
         self.assertEqual(categories, CATEGORIES)
 
     def test_random_tvshow_episodes(self):
         ''' Rest episode from a random tvshow in a random category '''
-        categories = vrtplayer.get_categories()
+        vrt_player = vrtplayer.VRTPlayer(self._kodi_wrapper, self._api_helper)
+        categories = vrt_player.get_categories()
         self.assertTrue(categories)
 
         category = random.choice(categories)