Force logging

requirements.txt

@@ -4,4 +4,5 @@ polib
 pillow
 Kodistubs~=21.0.0
 urllib3
+kodi-addon-checker
 

script.service.hue/addon.xml

@@ -1,9 +1,9 @@
-<addon id="script.service.hue" name="Hue Service" provider-name="zim514" version="2.0.5">
+<addon id="script.service.hue" name="Hue Service" provider-name="zim514" version="2.0.6~alpha3">
     <requires>
         <import addon="xbmc.python" version="3.0.0"/>
-        <import addon="script.module.requests" version="2.27.1"/>
+        <import addon="script.module.requests" version="2.31.0"/>
         <import addon="script.module.pil"/>
-        <import addon="script.module.pyrollbar" version="0.15.2"/>
+        <import addon="script.module.pyrollbar" version="0.16.3"/>
     </requires>
     <extension point="xbmc.service" name="service.hue" library="service.py"/>
     <extension point="xbmc.python.pluginsource" library="plugin.py">

script.service.hue/resources/lib/__init__.py

@@ -13,6 +13,7 @@
 import xbmcvfs
 
 STRDEBUG = False  # Show string ID in UI
+FORCEDEBUGLOG = True # Force output of debug logs regardless of Kodi logging setting #TODO: Change to false before shipping
 TIMEOUT = 1 # requests default timeout
 MAX_RETRIES = 7
 NOTIFICATION_THRESHOLD = 2

script.service.hue/resources/lib/ambigroup.py

@@ -13,7 +13,7 @@
 
 from . import ADDON, MINIMUM_COLOR_DISTANCE, imageprocess, lightgroup
 from . import PROCESS_TIMES, reporting, AMBI_RUNNING
-from .kodiutils import notification
+from .kodiutils import notification, log
 from .language import get_string as _
 from .lightgroup import STATE_STOPPED, STATE_PAUSED, STATE_PLAYING, VIDEO
 from .rgbxy import Converter, ColorHelper  # https://github.com/benknight/hue-python-rgb-converter
@@ -55,45 +55,45 @@ def __init__(self, light_group_id, settings_monitor, bridge):
                         light = {L: {'gamut': gamut, 'prev_xy': (0, 0), "index": index}}
                         self.ambi_lights.update(light)
                         index = index + 1
-            xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] Lights: {self.ambi_lights}")
+            log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] Lights: {self.ambi_lights}")
         # convert MS to seconds
 
     def onAVStarted(self):
         self.state = STATE_PLAYING
         self.last_media_type = self._playback_type()
         enabled = getattr(self.settings_monitor, f"group{self.light_group_id}_enabled", False)
 
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] onPlaybackStarted. Group enabled: {enabled}, Bridge connected: {self.bridge.connected}, mediaType: {self.media_type}")
+        log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] onPlaybackStarted. Group enabled: {enabled}, Bridge connected: {self.bridge.connected}, mediaType: {self.media_type}")
 
         if not enabled or not self.bridge.connected:
             return
 
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] onPlaybackStarted. media_type: {self.media_type} == playback_type: {self._playback_type()}")
+        log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] onPlaybackStarted. media_type: {self.media_type} == playback_type: {self._playback_type()}")
         if self.media_type == self._playback_type() and self._playback_type() == VIDEO:
             try:
                 self.video_info_tag = self.getVideoInfoTag()
             except (AttributeError, TypeError) as x:
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup{self.light_group_id}: OnAV Started: Can't read infoTag")
+                log(f"[SCRIPT.SERVICE.HUE] AmbiGroup{self.light_group_id}: OnAV Started: Can't read infoTag")
                 reporting.process_exception(x)
         else:
             self.video_info_tag = None
 
         if self.activation_check.validate():
-            xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] Running Play action")
+            log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] Running Play action")
 
             # Start the Ambi loop
             ambi_loop_thread = Thread(target=self._ambi_loop, name="_ambi_loop", daemon=True)
             ambi_loop_thread.start()
 
     def onPlayBackStopped(self):
         # always stop ambilight even if group is disabled or it'll run forever
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] In ambiGroup[{self.light_group_id}], onPlaybackStopped()")
+        log(f"[SCRIPT.SERVICE.HUE] In ambiGroup[{self.light_group_id}], onPlaybackStopped()")
         self.state = STATE_STOPPED
         AMBI_RUNNING.clear()
 
     def onPlayBackPaused(self):
         # always stop ambilight even if group is disabled or it'll run forever
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] In ambiGroup[{self.light_group_id}], onPlaybackPaused()")
+        log(f"[SCRIPT.SERVICE.HUE] In ambiGroup[{self.light_group_id}], onPlaybackPaused()")
         self.state = STATE_PAUSED
         AMBI_RUNNING.clear()
 
@@ -102,7 +102,7 @@ def _ambi_loop(self):
         executor = ThreadPoolExecutor(max_workers=len(self.ambi_lights) * 2)
         cap = xbmc.RenderCapture()
         cap_image = bytes
-        xbmc.log("[SCRIPT.SERVICE.HUE] _ambiLoop started")
+        log("[SCRIPT.SERVICE.HUE] _ambiLoop started")
         aspect_ratio = cap.getAspectRatio()
 
         # These settings require restarting ambilight video to update:
@@ -116,7 +116,7 @@ def _ambi_loop(self):
         capture_size_y = int(capture_size_x / aspect_ratio)
         expected_capture_size = capture_size_x * capture_size_y * 4  # size * 4 bytes - RGBA
 
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] aspect_ratio: {aspect_ratio}, Capture Size: ({capture_size_x}, {capture_size_y}), expected_capture_size: {expected_capture_size}")
+        log(f"[SCRIPT.SERVICE.HUE] aspect_ratio: {aspect_ratio}, Capture Size: ({capture_size_x}, {capture_size_y}), expected_capture_size: {expected_capture_size}")
 
         cap.capture(capture_size_x, capture_size_y)  # start the capture process https://github.com/xbmc/xbmc/pull/8613#issuecomment-165699101
 
@@ -129,14 +129,14 @@ def _ambi_loop(self):
                 cap_image = cap.getImage()  # timeout to wait for OS in ms, default 1000
 
                 if cap_image is None or len(cap_image) < expected_capture_size:
-                    xbmc.log("[SCRIPT.SERVICE.HUE] capImage is none or < expected. captured: {}, expected: {}".format(len(cap_image), expected_capture_size))
+                    log("[SCRIPT.SERVICE.HUE] capImage is none or < expected. captured: {}, expected: {}".format(len(cap_image), expected_capture_size))
                     self.settings_monitor.waitForAbort(0.25)  # pause before trying again
                     continue  # no image captured, try again next iteration
                 image = Image.frombytes("RGBA", (capture_size_x, capture_size_y), bytes(cap_image), "raw", "BGRA", 0, 1)  # Kodi always returns a BGRA image.
 
             except ValueError:
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] capImage: {len(cap_image)}")
-                xbmc.log("[SCRIPT.SERVICE.HUE] Value Error")
+                log(f"[SCRIPT.SERVICE.HUE] capImage: {len(cap_image)}")
+                log("[SCRIPT.SERVICE.HUE] Value Error")
                 self.settings_monitor.waitForAbort(0.25)
                 continue  # returned capture is smaller than expected, but this happens when player is stopping so fail silently. give up this loop.
 
@@ -150,9 +150,9 @@ def _ambi_loop(self):
 
         if not self.settings_monitor.abortRequested():  # ignore writing average process time if Kodi is shutting down
             average_process_time = self._perf_average(PROCESS_TIMES)
-            xbmc.log(f"[SCRIPT.SERVICE.HUE] Average process time: {average_process_time}")
+            log(f"[SCRIPT.SERVICE.HUE] Average process time: {average_process_time}")
             ADDON.setSettingString("average_process_time", str(average_process_time))
-            xbmc.log("[SCRIPT.SERVICE.HUE] _ambiLoop stopped")
+            log("[SCRIPT.SERVICE.HUE] _ambiLoop stopped")
 
     def _update_hue_rgb(self, r, g, b, light, bri, transition_time):
         gamut = self.ambi_lights[light].get('gamut')
@@ -192,22 +192,22 @@ def _update_hue_rgb(self, r, g, b, light, bri, transition_time):
             if response is not None:
                 self.ambi_lights[light].update(prev_xy=xy)
             elif response == 429 or response == 500:
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] _update_hue_rgb: {response}: Too Many Requests. Aborting request.")
+                log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] _update_hue_rgb: {response}: Too Many Requests. Aborting request.")
                 self.bridge_capacity_error()
                 notification(_("Hue Service"), _("Bridge overloaded, stopping ambilight"), icon=xbmcgui.NOTIFICATION_ERROR)
             elif response == 404:
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] Not Found")
+                log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] Not Found")
                 AMBI_RUNNING.clear()
                 notification(header=_("Hue Service"), message=_(f"ERROR: Light not found, it may have been deleted"), icon=xbmcgui.NOTIFICATION_ERROR)
                 AMBI_RUNNING.clear()  # shut it down
             else:
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] RequestException Hue call fail")
+                log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] RequestException Hue call fail")
                 AMBI_RUNNING.clear()  # shut it down
                 reporting.process_exception(response)
 
     def bridge_capacity_error(self):
         self.capacity_error_count = self.capacity_error_count + 1  # increment counter
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] Bridge capacity error count: {self.capacity_error_count}")
+        log(f"[SCRIPT.SERVICE.HUE] AmbiGroup[{self.light_group_id}] Bridge capacity error count: {self.capacity_error_count}")
         if self.capacity_error_count > 50 and self.settings_monitor.show500errors:
             AMBI_RUNNING.clear()  # shut it down
             stop_showing_error = xbmcgui.Dialog().yesno(_("Hue Bridge over capacity"), _("The Hue Bridge is over capacity. Increase refresh rate or reduce the number of Ambilights."), yeslabel=_("Do not show again"), nolabel=_("Ok"))
@@ -220,7 +220,7 @@ def _get_light_gamut(bridge, light):
         gamut = "C"  # default
         light_data = bridge.make_api_request("GET", f"light/{light}")
         if light_data == 404:
-            xbmc.log(f"[SCRIPT.SERVICE.HUE] _get_light_gamut: Light[{light}] not found or ID invalid")
+            log(f"[SCRIPT.SERVICE.HUE] _get_light_gamut: Light[{light}] not found or ID invalid")
             return 404
         elif light_data is not None and 'data' in light_data:
             for item in light_data['data']:
@@ -258,7 +258,7 @@ def _get_and_save_light_states(self):
                 }
             return states
         else:
-            xbmc.log(f"[SCRIPT.SERVICE.HUE] Failed to get light states.")
+            log(f"[SCRIPT.SERVICE.HUE] Failed to get light states.")
             return None
 
     def _resume_all_light_states(self, states):
@@ -278,6 +278,6 @@ def _resume_all_light_states(self, states):
                 data["color_temperature"] = {"mirek": state['color_temperature']}
             response = self.bridge.make_api_request('PUT', f'lights/{light_id}', json=data)
             if response is not None:
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] Light[{light_id}] state resumed successfully.")
+                log(f"[SCRIPT.SERVICE.HUE] Light[{light_id}] state resumed successfully.")
             else:
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] Failed to resume Light[{light_id}] state.")
+                log(f"[SCRIPT.SERVICE.HUE] Failed to resume Light[{light_id}] state.")

script.service.hue/resources/lib/core.py

@@ -13,7 +13,7 @@
 from . import ADDON, AMBI_RUNNING, BRIDGE_SETTINGS_CHANGED
 from . import lightgroup, ambigroup, settings
 from .hue import Hue
-from .kodiutils import notification, cache_set, cache_get
+from .kodiutils import notification, cache_set, cache_get, log
 from .language import get_string as _
 
 
@@ -41,40 +41,40 @@ def __init__(self, settings_monitor):
         }
 
     def handle_command(self, command, *args):
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] Started with {command}, Python: {sys.version}")
+        log(f"[SCRIPT.SERVICE.HUE] Started with {command}, Python: {sys.version}")
         command_func = self.commands.get(command)
 
         if command_func:
             command_func(*args)
         else:
-            xbmc.log(f"[SCRIPT.SERVICE.HUE] Unknown command: {command}")
+            log(f"[SCRIPT.SERVICE.HUE] Unknown command: {command}")
             raise RuntimeError(f"Unknown Command: {command}")
 
     def discover(self):
         bridge = Hue(self.settings_monitor, discover=True)
         if bridge.connected:
-            xbmc.log("[SCRIPT.SERVICE.HUE] Found bridge. Opening settings.")
+            log("[SCRIPT.SERVICE.HUE] Found bridge. Opening settings.")
             ADDON.openSettings()
 
         else:
-            xbmc.log("[SCRIPT.SERVICE.HUE] No bridge found. Opening settings.")
+            log("[SCRIPT.SERVICE.HUE] No bridge found. Opening settings.")
             ADDON.openSettings()
 
     def scene_select(self, light_group, action):
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] sceneSelect: light_group: {light_group}, action: {action}")
+        log(f"[SCRIPT.SERVICE.HUE] sceneSelect: light_group: {light_group}, action: {action}")
         bridge = Hue(self.settings_monitor)
         if bridge.connected:
             bridge.configure_scene(light_group, action)
         else:
-            xbmc.log("[SCRIPT.SERVICE.HUE] No bridge found. sceneSelect cancelled.")
+            log("[SCRIPT.SERVICE.HUE] No bridge found. sceneSelect cancelled.")
             notification(_("Hue Service"), _("Check Hue Bridge configuration"))
 
     def ambi_light_select(self, light_group):
         bridge = Hue(self.settings_monitor)
         if bridge.connected:
             bridge.configure_ambilights(light_group)
         else:
-            xbmc.log("[SCRIPT.SERVICE.HUE] No bridge found. Select ambi lights cancelled.")
+            log("[SCRIPT.SERVICE.HUE] No bridge found. Select ambi lights cancelled.")
             notification(_("Hue Service"), _("Check Hue Bridge configuration"))
 
 
@@ -88,7 +88,7 @@ def __init__(self, settings_monitor):
         cache_set("service_enabled", True)
 
     def run(self):
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] Starting Hue Service, Python: {sys.version}")
+        log(f"[SCRIPT.SERVICE.HUE] Starting Hue Service, Python: {sys.version}")
         self.light_groups = self.initialize_light_groups()
         self.timers = Timers(self.settings_monitor, self.bridge, self)
 
@@ -131,7 +131,7 @@ def run(self):
             if self.settings_monitor.waitForAbort(1):
                 break
 
-        xbmc.log("[SCRIPT.SERVICE.HUE] Abort requested...")
+        log("[SCRIPT.SERVICE.HUE] Abort requested...")
 
     def initialize_light_groups(self):
         # Initialize light groups
@@ -143,7 +143,7 @@ def initialize_light_groups(self):
 
     def activate(self):
         # Activates play action as appropriate for all groups. Used at sunset and when service is re-enabled via Actions.
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] Activating scenes")
+        log(f"[SCRIPT.SERVICE.HUE] Activating scenes")
 
         for g in self.light_groups:
             if ADDON.getSettingBool(f"group{g.light_group_id}_enabled"):
@@ -157,7 +157,7 @@ def _process_action(self):
         if action:
             action_action = action[0]
             action_light_group_id = int(action[1]) - 1
-            xbmc.log(f"[SCRIPT.SERVICE.HUE] Action command: {action}, action_action: {action_action}, action_light_group_id: {action_light_group_id}")
+            log(f"[SCRIPT.SERVICE.HUE] Action command: {action}, action_action: {action_action}, action_light_group_id: {action_light_group_id}")
 
             # Run the action
             self.light_groups[action_light_group_id].run_action(action_action)
@@ -186,18 +186,18 @@ def stop(self):
     def _run_morning(self):
         cache_set("daytime", True)
         self.bridge.update_sunset()
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] run_morning(): new sunset: {self.bridge.sunset}")
+        log(f"[SCRIPT.SERVICE.HUE] run_morning(): new sunset: {self.bridge.sunset}")
 
     def _run_sunset(self):
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] in run_sunset(): Sunset. ")
+        log(f"[SCRIPT.SERVICE.HUE] in run_sunset(): Sunset. ")
         cache_set("daytime", False)
         if self.settings_monitor.force_on_sunset:
             self.hue_service.activate()
 
 
     def _set_daytime(self):
         now = datetime.now()
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] _set_daytime(): Morning Time: {self.morning_time}, Now: {now.time()}, bridge.sunset: {self.bridge.sunset}, Sunset offset: {self.settings_monitor.sunset_offset}")
+        log(f"[SCRIPT.SERVICE.HUE] _set_daytime(): Morning Time: {self.morning_time}, Now: {now.time()}, bridge.sunset: {self.bridge.sunset}, Sunset offset: {self.settings_monitor.sunset_offset}")
 
         # Convert self.bridge.sunset to a datetime object by combining it with today's date
         sunset_datetime = datetime.combine(datetime.today(), self.bridge.sunset)
@@ -211,7 +211,7 @@ def _set_daytime(self):
         else:
             daytime = False
         cache_set("daytime", daytime)
-        xbmc.log(f"[SCRIPT.SERVICE.HUE] in _set_daytime(): Sunset with offset: {sunset_with_offset}, Daytime: {daytime} ")
+        log(f"[SCRIPT.SERVICE.HUE] in _set_daytime(): Sunset with offset: {sunset_with_offset}, Daytime: {daytime} ")
 
     def _task_loop(self):
 
@@ -229,18 +229,18 @@ def _task_loop(self):
 
             if time_to_sunset <= 0 or time_to_sunset > time_to_morning:
                 # Morning is next
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] Timers: Morning is next. wait_time: {time_to_morning}")
+                log(f"[SCRIPT.SERVICE.HUE] Timers: Morning is next. wait_time: {time_to_morning}")
                 if self.settings_monitor.waitForAbort(time_to_morning):
                     break
                 self._run_morning()
 
             else:
                 # Sunset is next
-                xbmc.log(f"[SCRIPT.SERVICE.HUE] Timers: Sunset is next. wait_time: {time_to_sunset}")
+                log(f"[SCRIPT.SERVICE.HUE] Timers: Sunset is next. wait_time: {time_to_sunset}")
                 if self.settings_monitor.waitForAbort(time_to_sunset):
                     break
                 self._run_sunset()
-        xbmc.log("[SCRIPT.SERVICE.HUE] Timers stopped")
+        log("[SCRIPT.SERVICE.HUE] Timers stopped")
 
     @staticmethod
     def _time_until(current, target):