search

mvdwetering / huesyncbox

Custom integration for Home Assistant to control the Philips Hue Play HDMI Sync Box 4K or 8K
Apache License 2.0
113 stars 8 forks source link

Error "Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02" #24

Closed florie1706 closed 6 months ago

florie1706 commented 3 years ago

Describe the bug Somtimes when I use my automation (if hue syncbox is idle and tv is on then do hue syncbox sync_on) it does trigger but does not start the sync. In my log i have this

Logger: homeassistant.components.media_player
Source: helpers/entity_platform.py:692
Integration: Mediaplayer (documentation, issues)
First occurred: 16. September 2021, 06:51:50 (167 occurrences)
Last logged: 16:24:47

Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02

Expected behavior Send a sucessfull sync_on to the box

Environment Official docker image

mvdwetering commented 3 years ago

The Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 lines are kind of expected to happen occasionally. Typically the box returns an answer really fast (couple of milliseconds), but sometimes it seems busy and can take a bit longer. I get a couple of these a day on my setup.

I could make the poll interval longer again (it was lowered from 10 to 2 in the last update), but it would take longer for the integration to get in sync with the status of the box, which is a problem when building automations around it.

Seeing that line would only mean that the status of the integration will lag behind with ~2 seconds. So as long is it is not occurring around the time that the status of the box changes and your automation triggers it should not be an issue.

That being said, could you post your automation (the yaml) so I can try to reproduce it.

I would expect request errors to the box to be logged by HA since it is an Exception, but maybe that is not (always?) the case, I would need to examine that in more detail. It would really help if you could enable the aiohuesyncbox logging by adding or extending the section below in your configuration.yaml. And save it when the issue occurs. However it is really spammy as it logs each request to the box (which means every 2 seconds) and it prints quite a lot of data. But it is the only way to really see what is going on on the communication level.

logger:
  default: info
  logs:
    aiohuesyncbox: debug
florie1706 commented 3 years ago

Hi, thanks for your answer. I can do that, when I am back home. But I think the poll is correct every time. The automation triggers but the part which is not running is the action part of the automation. This is not working like every third time when using my Apple TV.

The automation looks like this:

- id: '1631614592237'
  alias: Hue Sync Box aktivieren
  description: ''
  trigger:
  - platform: device
    device_id: 785ee3ab566d77d792ae95122733ab3d
    domain: media_player
    entity_id: media_player.wozi
    type: idle
  - platform: device
    device_id: 785ee3ab566d77d792ae95122733ab3d
    domain: media_player
    entity_id: media_player.wozi
    type: idle
    for:
      hours: 0
      minutes: 0
      seconds: 10
      milliseconds: 0
  condition:
  - condition: device
    type: is_on
    device_id: b3830cd7396acef86861954a86840eb9
    entity_id: remote.wohnzimmer
    domain: remote
  action:
  - device_id: 785ee3ab566d77d792ae95122733ab3d
    domain: huesyncbox
    entity_id: media_player.wozi
    type: sync_on
  mode: restart
  max: 10

media_player.wozi = sync box remote.wohnzimmer = TV

I put a second trigger with a delay of 10 seconds as a workaround (to send the action a second time after 10 seconds if the first send did not went thru), that seems to work yesterday.

As I said before I think the action does not arrive at the sync box every time for me.

SkywiperSolutions commented 2 years ago

Any news on a permanent fix for this? Thanks!

sparsons99 commented 2 years ago

I get this issue a lot, It can be approximately every 30 seconds for periods, and then stops doing it for a while, then comes back again! It doesn't stop it working but it makes my log file somewhat busy!

Completely understand that it could very well be down to local network conditions (I have a lot of equipment on my network!) but would it be possible to add an option in a future version to change the poll interval if we want to? That way we can adjust it to something that works for us. I have no issue waiting 5-10 seconds for my lights to start syncing or change modes, but others may want it quicker. An option for the user to change this might be a way to solve this.

Thanks for the great component though, I was sending rest commands manually before and it was very hit and miss, this works so much better!!

mvdwetering commented 2 years ago

Ow, sorry for the late reply. I somehow missed the 20 sept response.

@sparsons99 Since I am using the standard SCAN_INTERVAL thing in HA you might be able to override it configuration.yaml as documented here https://www.home-assistant.io/docs/configuration/platform_options/#scan-interval Other option could be the "Disable polling" option introduced in HA 2021.6 (https://www.home-assistant.io/blog/2021/06/02/release-20216/#disable-polling-updates-on-any-integration) and manage your own update frequency.

I am planning to do some work on the integration during the upcoming holidays and will take a look at this.

However it would really help to get some logging of the traffic to the syncbox so if one of you could temporarily enable the logging by adding the section below to configuration.yaml and reproduce the issue that would help a lot. It helps me to see if the box returns an error, there is a timeout or maybe something else.

logger:
  default: info
  logs:
    huesyncbox: debug
    aiohuesyncbox: debug
sparsons99 commented 2 years ago

@mvdwetering thank you for the suggestions, will have a look at those. Happy to test the logging. Will try it now and let you know what happens. Probably won't take long in my case!

As an example, this is what I see frequently in my log file:

2021-12-14 19:54:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:55:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:55:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:56:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:56:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:57:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:57:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:58:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:58:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:59:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 19:59:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:00:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:00:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:01:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:01:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:02:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:02:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:03:22 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:03:52 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02

Not sure if that is entirely useful, although odd that it is exactly 30 seconds each time!

sparsons99 commented 2 years ago

Ok, so I enabled logging and got this:

2021-12-14 20:49:29 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_192.168.86.47:443/api/v1, None 2021-12-14 20:49:29 INFO (MainThread) [charset_normalizer] ascii passed initial chaos probing. Mean measured chaos is 0.000000 % 2021-12-14 20:49:29 INFO (MainThread) [charset_normalizer] ascii should target any language(s) of ['Latin Based'] 2021-12-14 20:49:29 INFO (MainThread) [charset_normalizer] We detected language [('English', 1.0), ('Dutch', 1.0), ('Indonesian', 1.0)] using ascii 2021-12-14 20:49:29 INFO (MainThread) [charset_normalizer] ascii is most likely the one. Stopping the process. 2021-12-14 20:49:31 WARNING (MainThread) [homeassistant.components.media_player] Updating huesyncbox media_player took longer than the scheduled update interval 0:00:02 2021-12-14 20:49:32 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] 200, {"device":{"name":"Sync Box","deviceType":"HSB1","uniqueId":"C42996017DAC","apiLevel":7,"firmwareVersion":"1.7.4","buildNumber":681947148,"termsAgreed":true,"wifiState":"wan","ipAddress":"192.168.86.47","wifi":{"ssid":"Elmo","strength":3},"lastCheckedUpdate":"2021-12-14T10:00:23Z","updatableBuildNumber":696280590,"updatableFirmwareVersion":"1.8.3","update":{"autoUpdateEnabled":false,"autoUpdateTime":10},"ledMode":1,"action":"none","pushlink":"idle","capabilities":{"maxIrCodes":24,"maxPresets":16},"beta":false},"hue":{"bridgeUniqueId":"001788FFFE66CECE","bridgeIpAddress":"192.168.86.215","groupId":"216616cb-1ad0-4bca-9f61-f0f67e7cac16","groups":{"b2a8d4dd-282c-44d2-9652-6e9aaec0617d":{"name":"Living Room","numLights":1,"active":false},"61704bf9-869a-4332-b26f-43afce5c8d52":{"name":"Living room plus portable","numLights":7,"active":false},"216616cb-1ad0-4bca-9f61-f0f67e7cac16":{"name":"Living Room all","numLights":5,"active":false},"d36ff657-c7b5-492a-99d8-c5f9a572e9c1":{"name":"House","numLights":10,"active":false},"4db20ebb-de75-4ef2-ad1a-a748fbcd955a":{"name":"Back Garden beds","numLights":3,"active":false}},"connectionState":"connected"},"execution":{"mode":"passthrough","syncActive":false,"hdmiActive":true,"hdmiSource":"input1","hueTarget":"216616cb-1ad0-4bca-9f61-f0f67e7cac16","brightness":189,"lastSyncMode":"video","video":{"intensity":"moderate","backgroundLighting":false},"game":{"intensity":"intense","backgroundLighting":false},"music":{"intensity":"high","palette":"melancholicEnergetic"},"preset":null},"hdmi":{"input1":{"name":"Sky","type":"generic","status":"linked","lastSyncMode":"video"},"input2":{"name":"Chromecast","type":"generic","status":"plugged","lastSyncMode":"video"},"input3":{"name":"HDMI 3","type":"generic","status":"unplugged","lastSyncMode":"video"},"input4":{"name":"HDMI 4","type":"generic","status":"unplugged","lastSyncMode":"video"},"output":{"name":"HDMI Out","type":"generic","status":"linked","lastSyncMode":"video"},"contentSpecs":"3840 x 2160 @ 50000 - SDR","videoSyncSupported":true,"audioSyncSupported":false},"behavior":{"inactivePowersave":20,"cecPowersave":1,"usbPowersave":1,"hpdInputSwitch":1,"hpdOutputEnableMs":1500,"arcBypassMode":0,"forceDoviNative":0,"input1":{"cecInputSwitch":1,"linkAutoSync":0,"hdrMode":0},"input2":{"cecInputSwitch":1,"linkAutoSync":0,"hdrMode":0},"input3":{"cecInputSwitch":1,"linkAutoSync":0,"hdrMode":0},"input4":{"cecInputSwitch":1,"linkAutoSync":0,"hdrMode":0}},"ir":{"defaultCodes":true,"scan":{"scanning":false,"code":null,"codes":[]},"codes":{}},"registrations":{"2":{"appName":"Google","instanceName":"001788FFFE66CECE","role":"user","verified":true,"lastUsed":"2021-12-11T08:16:29Z","created":"2020-10-17T12:23:08Z"},"3":{"appName":"Home Assistant","instanceName":"Home","role":"user","verified":false,"lastUsed":"2021-12-14T20:49:32Z","created":"2021-01-24T18:16:57Z"},"4":{"appName":"Hue Sync Android","instanceName":"o1s","role":"user","verified":true,"lastUsed":"2021-12-11T21:37:55Z","created":"2021-10-09T17:48:09Z"},"1":{"appName":"curl","instanceName":"steveparsons99","role":"user","verified":false,"lastUsed":"2021-12-14T20:49:03Z","created":"2020-04-02T20:45:46Z"},"0":{"appName":"Hue Sync Android","instanceName":"beyond1","role":"admin","verified":true,"lastUsed":"2021-10-09T13:58:10Z","created":"2019-12-15T15:06:43Z"}},"presets":{}} 2021-12-14 20:49:32 INFO (MainThread) [charset_normalizer] ascii passed initial chaos probing. Mean measured chaos is 0.000000 % 2021-12-14 20:49:32 INFO (MainThread) [charset_normalizer] ascii should target any language(s) of ['Latin Based'] 2021-12-14 20:49:32 INFO (MainThread) [charset_normalizer] We detected language [('English', 1.0), ('Dutch', 1.0), ('Italian', 1.0)] using ascii 2021-12-14 20:49:32 INFO (MainThread) [charset_normalizer] ascii is most likely the one. Stopping the process. 2021-12-14 20:49:33 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_192.168.86.47:443/api/v1, None 2021-12-14 20:49:33 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] 200, {"device":{"name":"Sync Box","deviceType":"HSB1","uniqueId":"C42996017DAC","apiLevel":7,"firmwareVersion":"1.7.4","buildNumber":681947148,"termsAgreed":true,"wifiState":"wan","ipAddress":"192.168.86.47","wifi":{"ssid":"Elmo","strength":3},"lastCheckedUpdate":"2021-12-14T10:00:23Z","updatableBuildNumber":696280590,"updatableFirmwareVersion":"1.8.3","update":{"autoUpdateEnabled":false,"autoUpdateTime":10},"ledMode":1,"action":"none","pushlink":"idle","capabilities":{"maxIrCodes":24,"maxPresets":16},"beta":false},"hue":{"bridgeUniqueId":"001788FFFE66CECE","bridgeIpAddress":"192.168.86.215","groupId":"216616cb-1ad0-4bca-9f61-f0f67e7cac16","groups":{"b2a8d4dd-282c-44d2-9652-6e9aaec0617d":{"name":"Living Room","numLights":1,"active":false},"61704bf9-869a-4332-b26f-43afce5c8d52":{"name":"Living room plus portable","numLights":7,"active":false},"216616cb-1ad0-4bca-9f61-f0f67e7cac16":{"name":"Living Room all","numLights":5,"active":false},"d36ff657-c7b5-492a-99d8-c5f9a572e9c1":{"name":"House","numLights":10,"active":false},"4db20ebb-de75-4ef2-ad1a-a748fbcd955a":{"name":"Back Garden beds","numLights":3,"active":false}},"connectionState":"connected"},"execution":{"mode":"passthrough","syncActive":false,"hdmiActive":true,"hdmiSource":"input1","hueTarget":"216616cb-1ad0-4bca-9f61-f0f67e7cac16","brightness":189,"lastSyncMode":"video","video":{"intensity":"moderate","backgroundLighting":false},"game":{"intensity":"intense","backgroundLighting":false},"music":{"intensity":"high","palette":"melancholicEnergetic"},"preset":null},"hdmi":{"input1":{"name":"Sky","type":"generic","status":"linked","lastSyncMode":"video"},"input2":{"name":"Chromecast","type":"generic","status":"plugged","lastSyncMode":"video"},"input3":{"name":"HDMI 3","type":"generic","status":"unplugged","lastSyncMode":"video"},"input4":{"name":"HDMI 4","type":"generic","status":"unplugged","lastSyncMode":"video"},"output":{"name":"HDMI Out","type":"generic","status":"linked","lastSyncMode":"video"},"contentSpecs":"3840 x 2160 @ 50000 - SDR","videoSyncSupported":true,"audioSyncSupported":false},"behavior":{"inactivePowersave":20,"cecPowersave":1,"usbPowersave":1,"hpdInputSwitch":1,"hpdOutputEnableMs":1500,"arcBypassMode":0,"forceDoviNative":0,"input1":{"cecInputSwitch":1,"linkAutoSync":0,"hdrMode":0},"input2":{"cecInputSwitch":1,"linkAutoSync":0,"hdrMode":0},"input3":{"cecInputSwitch":1,"linkAutoSync":0,"hdrMode":0},"input4":{"cecInputSwitch":1,"linkAutoSync":0,"hdrMode":0}},"ir":{"defaultCodes":true,"scan":{"scanning":false,"code":null,"codes":[]},"codes":{}},"registrations":{"2":{"appName":"Google","instanceName":"001788FFFE66CECE","role":"user","verified":true,"lastUsed":"2021-12-11T08:16:29Z","created":"2020-10-17T12:23:08Z"},"3":{"appName":"Home Assistant","instanceName":"Home","role":"user","verified":false,"lastUsed":"2021-12-14T20:49:33Z","created":"2021-01-24T18:16:57Z"},"4":{"appName":"Hue Sync Android","instanceName":"o1s","role":"user","verified":true,"lastUsed":"2021-12-11T21:37:55Z","created":"2021-10-09T17:48:09Z"},"1":{"appName":"curl","instanceName":"steveparsons99","role":"user","verified":false,"lastUsed":"2021-12-14T20:49:32Z","created":"2020-04-02T20:45:46Z"},"0":{"appName":"Hue Sync Android","instanceName":"beyond1","role":"admin","verified":true,"lastUsed":"2021-10-09T13:58:10Z","created":"2019-12-15T15:06:43Z"}},"presets":{}}

Sorry if the formatting isn't great!

I had a look through and don't think any of the above info is particularly sensitive, but if you think it isn't best posted in here, then by all means take a copy and let me know and I'll delete the post!

sparsons99 commented 2 years ago

Me again! Just as a further update, I amended the poll interval to 5 seconds last night and I haven't had a single issue since. Appreciate that may not work for everyone, but potentially waiting 3 seconds longer for my lights to start syncing is not really an issue for me!

florie1706 commented 2 years ago

@sparsons99 What is your setting for that? Can you post it here. I have the same issue

sparsons99 commented 2 years ago

@florie1706 to be honest I just amended the config\custom_components\huesyncbox\media_player.py file as I couldn't find an easy way to do it.

Line 62 - SCAN_INTERVAL = timedelta(seconds=5)

This isn't the best way to do it as any updates to the component will overwrite this setting, but I did it mainly just to test it, and it's a very quick tweak to redo after an update if needed!

florie1706 commented 2 years ago

Thanks, that is what I needed for testing ;)

mvdwetering commented 6 months ago

I am cleaning up old issues and see that this was still open. Since it is very old I will post a summary of the current state and close it.

In the just released v2.1.0 errors are only logged when multiple consecutive requests fail, so that should reduce the logspam. Also meanwhile the polling interval has changed to 3 seconds instead of 2 (that was with v2.0.0)

And last, if someone still wants to change the interval I would suggest to do it the official way by disabling the "Enable polling for updates" option in the System Options of the integration. Then create an automation that triggers the updates on an interval to your liking. Basically like descibed here for the Ping integration but choose an entity from this integration (just one, not all, they will update together on every update)