search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.64k stars 30.78k forks source link

Restoring the state of a Denon receiver after storing it in a scene doesn't work #107412

Closed rccoleman closed 9 months ago

rccoleman commented 10 months ago

The problem

I was helping someone on Discord who wanted to save and restore the state of a media_player receiver and found that I couldn't make it work as I expected it to. My goal was to use an on-the-fly scene to store the current state, change the volume, and have it restored when I turned on the scene I created. I can see all the right things happening, but the state restoration isn't having any effect.

What version of Home Assistant Core has the issue?

core-2024.1.2

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

denonavr

Link to integration documentation on our website

https://www.home-assistant.io/integrations/denonavr/

Diagnostics information

home-assistant_denonavr_2024-01-06T22-32-45.859Z.log

Example YAML snippet

test_volume:
  sequence:
    - service: scene.create
      data:
        scene_id: test_scene
        snapshot_entities:
          - media_player.denon_avr_x4400h
    - service: media_player.volume_set
      data:
        entity_id: media_player.denon_avr_x4400h
        volume_level: 0.30
    - delay: 10
    - service: scene.turn_on
      entity_id: scene.test_scene

Anything in the logs that might be useful for us?

2024-01-06 14:27:06.907 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script
2024-01-06 14:27:06.908 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service
2024-01-06 14:27:06.909 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Running script sequence
2024-01-06 14:27:06.909 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step call service
2024-01-06 14:27:06.911 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step call service
2024-01-06 14:27:06.913 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.3
2024-01-06 14:27:06.914 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step delay 0:00:10
2024-01-06 14:27:07.002 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MV30
2024-01-06 14:27:07.023 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MVMAX 98
2024-01-06 14:27:16.916 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step call service
2024-01-06 14:27:16.918 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.turn_on with {'entity_id': 'media_player.denon_avr_x4400h'}
2024-01-06 14:27:16.926 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.select_source with {'entity_id': 'media_player.denon_avr_x4400h', 'source': 'AppleTV'}
2024-01-06 14:27:16.927 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.select_sound_mode with {'entity_id': 'media_player.denon_avr_x4400h', 'sound_mode': 'STEREO'}
2024-01-06 14:27:16.928 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] reproduce: setting volume!
2024-01-06 14:27:16.928 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.volume_set with {'entity_id': 'media_player.denon_avr_x4400h', 'volume_level': 0.405}
2024-01-06 14:27:16.928 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.405
2024-01-06 14:27:16.929 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.volume_mute with {'entity_id': 'media_player.denon_avr_x4400h', 'is_volume_muted': False}
2024-01-06 14:27:16.934 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Stop script sequence: done

Additional information

I added some logs (all at the ERROR level) to see what was happening and it looks like everything is working as expected in HA, but the commands to restore the state in the denonavr package aren't being sent. You can see in the logs above where the command to set the volume is being sent when I manually call the service, but nothing is sent when the on-the-fly scene is turned on. I've tried it both with telnet enabled and without. Ignoring the ERROR-level logs that I added, I see no errors in the log when I run that script, but the volume stays at the level that I set in the explicit action step.

home-assistant[bot] commented 10 months ago

Hey there @ol-iver, @starkillerog, mind taking a look at this issue as it has been labeled with an integration (denonavr) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `denonavr` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign denonavr` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)

denonavr documentation denonavr source (message by IssueLinks)

rccoleman commented 10 months ago

Curiouser and Curiouser. It's sending the telnet command, but it just doesn't "take" when sent as part of a state restoration.

2024-01-06 15:01:32.935 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script
2024-01-06 15:01:32.936 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service
2024-01-06 15:01:32.939 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Running script sequence
2024-01-06 15:01:32.939 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step call service
2024-01-06 15:01:32.942 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step call service
2024-01-06 15:01:32.945 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.3
2024-01-06 15:01:32.945 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Computed volume -50.0
2024-01-06 15:01:32.945 ERROR (MainThread) [homeassistant.components.denonavr.media_player] About to call
2024-01-06 15:01:32.945 ERROR (MainThread) [denonavr.volume] denonavr: setting volume to -50.0
2024-01-06 15:01:32.945 ERROR (MainThread) [denonavr.api] Sending command='MV30'
2024-01-06 15:01:32.945 ERROR (MainThread) [denonavr.volume] denonavr: after setting volume success=True
2024-01-06 15:01:32.946 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step delay 0:00:10
2024-01-06 15:01:33.046 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MV30
2024-01-06 15:01:33.066 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MVMAX 98
2024-01-06 15:01:42.948 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step call service
2024-01-06 15:01:42.951 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.turn_on with {'entity_id': 'media_player.denon_avr_x4400h'}
2024-01-06 15:01:42.951 ERROR (MainThread) [denonavr.api] Sending command='ZMON'
2024-01-06 15:01:42.952 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.select_source with {'entity_id': 'media_player.denon_avr_x4400h', 'source': 'AppleTV'}
2024-01-06 15:01:42.953 ERROR (MainThread) [denonavr.api] Sending command='ZMON'
2024-01-06 15:01:42.954 ERROR (MainThread) [denonavr.api] Sending command='SIDVD'
2024-01-06 15:01:42.954 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.select_sound_mode with {'entity_id': 'media_player.denon_avr_x4400h', 'sound_mode': 'STEREO'}
2024-01-06 15:01:42.955 ERROR (MainThread) [denonavr.api] Sending command='MSSTEREO'
2024-01-06 15:01:42.956 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] reproduce: setting volume!
2024-01-06 15:01:42.956 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.volume_set with {'entity_id': 'media_player.denon_avr_x4400h', 'volume_level': 0.555}
2024-01-06 15:01:42.956 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.555
2024-01-06 15:01:42.956 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Computed volume -24.499999999999993
2024-01-06 15:01:42.956 ERROR (MainThread) [homeassistant.components.denonavr.media_player] About to call
2024-01-06 15:01:42.956 ERROR (MainThread) [denonavr.volume] denonavr: setting volume to -24.5
2024-01-06 15:01:42.957 ERROR (MainThread) [denonavr.api] Sending command='MV55'
2024-01-06 15:01:42.958 ERROR (MainThread) [denonavr.volume] denonavr: after setting volume success=True
2024-01-06 15:01:42.958 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.volume_mute with {'entity_id': 'media_player.denon_avr_x4400h', 'is_volume_muted': False}
2024-01-06 15:01:42.959 ERROR (MainThread) [denonavr.api] Sending command='MUOFF'
2024-01-06 15:01:42.962 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Stop script sequence: done
2024-01-06 15:02:03.561 DEBUG (MainThread) [denonavr.api] 192.168.1.225: Sending keep alive
2024-01-06 15:02:03.647 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: PWON
2024-01-06 15:02:15.643 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MV305
2024-01-06 15:02:15.664 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MVMAX 98
2024-01-06 15:03:03.563 DEBUG (MainThread) [denonavr.api] 192.168.1.225: Sending keep alive
2024-01-06 15:03:03.660 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: PWON
2024-01-06 15:03:05.256 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script
2024-01-06 15:03:05.257 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service
2024-01-06 15:03:05.257 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.55
2024-01-06 15:03:05.257 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Computed volume -24.999999999999993
2024-01-06 15:03:05.257 ERROR (MainThread) [homeassistant.components.denonavr.media_player] About to call
2024-01-06 15:03:05.258 ERROR (MainThread) [denonavr.volume] denonavr: setting volume to -25.0
2024-01-06 15:03:05.258 ERROR (MainThread) [denonavr.api] Sending command='MV55'
2024-01-06 15:03:05.258 ERROR (MainThread) [denonavr.volume] denonavr: after setting volume success=True
2024-01-06 15:03:05.528 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MV55
2024-01-06 15:03:05.556 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MVMAX 98
2024-01-06 15:04:03.564 DEBUG (MainThread) [denonavr.api] 192.168.1.225: Sending keep alive
2024-01-06 15:04:03.666 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: PWON

See where it tries to restore the state, and where the volume level didn't actually change

media_player.volume_set with {'entity_id': 'media_player.denon_avr_x4400h', 'volume_level': 0.555}
2024-01-06 15:01:42.956 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.555
2024-01-06 15:01:42.956 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Computed volume -24.499999999999993
2024-01-06 15:01:42.956 ERROR (MainThread) [homeassistant.components.denonavr.media_player] About to call
2024-01-06 15:01:42.956 ERROR (MainThread) [denonavr.volume] denonavr: setting volume to -24.5
2024-01-06 15:01:42.957 ERROR (MainThread) [denonavr.api] Sending command='MV55'
2024-01-06 15:01:42.958 ERROR (MainThread) [denonavr.volume] denonavr: after setting volume success=True
2024-01-06 15:01:42.958 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.volume_mute with {'entity_id': 'media_player.denon_avr_x4400h', 'is_volume_muted': False}
2024-01-06 15:01:42.959 ERROR (MainThread) [denonavr.api] Sending command='MUOFF'
2024-01-06 15:01:42.962 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Stop script sequence: done
2024-01-06 15:02:03.561 DEBUG (MainThread) [denonavr.api] 192.168.1.225: Sending keep alive
2024-01-06 15:02:03.647 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: PWON
2024-01-06 15:02:15.643 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MV305

And then where I set it manually from the media_player.volume_set service call:

2024-01-06 15:03:05.256 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script
2024-01-06 15:03:05.257 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service
2024-01-06 15:03:05.257 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.55
2024-01-06 15:03:05.257 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Computed volume -24.999999999999993
2024-01-06 15:03:05.257 ERROR (MainThread) [homeassistant.components.denonavr.media_player] About to call
2024-01-06 15:03:05.258 ERROR (MainThread) [denonavr.volume] denonavr: setting volume to -25.0
2024-01-06 15:03:05.258 ERROR (MainThread) [denonavr.api] Sending command='MV55'
2024-01-06 15:03:05.258 ERROR (MainThread) [denonavr.volume] denonavr: after setting volume success=True
2024-01-06 15:03:05.528 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MV55
2024-01-06 15:03:05.556 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MVMAX 98
2024-01-06 15:04:03.564 DEBUG (MainThread) [denonavr.api] 192.168.1.225: Sending keep alive
2024-01-06 15:04:03.666 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: PWON

The API returns "True" in both cases, but it's not actually looking at the result of the command, just that the telnet connection is up and supposedly functional. My current theory is that some of the commands take time to complete, like the first one that turns the receiver on, and the rest are just ignored. Perhaps we need to wait for a response to the telnet command before returning and proceeding?

Sure enough, if I add a 5s delay after calling each service during the state restore, it works:

2024-01-06 15:28:18.606 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.3
2024-01-06 15:28:18.606 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Computed volume -50.0
2024-01-06 15:28:18.606 ERROR (MainThread) [homeassistant.components.denonavr.media_player] About to call
2024-01-06 15:28:18.606 ERROR (MainThread) [denonavr.volume] denonavr: setting volume to -50.0
2024-01-06 15:28:18.606 ERROR (MainThread) [denonavr.api] Sending command='MV30'
2024-01-06 15:28:18.607 ERROR (MainThread) [denonavr.volume] denonavr: after setting volume success=True
2024-01-06 15:28:18.612 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step delay 0:00:10
2024-01-06 15:28:18.717 ERROR (MainThread) [denonavr.api] Data received: data=b'MV30\r'
2024-01-06 15:28:18.717 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MV30
2024-01-06 15:28:18.738 ERROR (MainThread) [denonavr.api] Data received: data=b'MVMAX 98\r'
2024-01-06 15:28:18.738 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MVMAX 98
2024-01-06 15:28:28.613 INFO (MainThread) [homeassistant.components.script.test_volume] test_volume: Executing step call service
2024-01-06 15:28:28.620 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.turn_on with {'entity_id': 'media_player.denon_avr_x4400h'}
2024-01-06 15:28:28.622 ERROR (MainThread) [denonavr.api] Sending command='ZMON'
2024-01-06 15:28:28.694 INFO (SyncWorker_5) [homeassistant.loader] Loaded unifiprotect from homeassistant.components.unifiprotect
2024-01-06 15:28:28.694 INFO (SyncWorker_9) [homeassistant.loader] Loaded rainforest_eagle from homeassistant.components.rainforest_eagle
2024-01-06 15:28:28.694 INFO (SyncWorker_1) [homeassistant.loader] Loaded nest from homeassistant.components.nest
2024-01-06 15:28:33.624 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.select_source with {'entity_id': 'media_player.denon_avr_x4400h', 'source': 'AppleTV'}
2024-01-06 15:28:33.625 ERROR (MainThread) [denonavr.api] Sending command='ZMON'
2024-01-06 15:28:33.627 ERROR (MainThread) [denonavr.api] Sending command='SIDVD'
2024-01-06 15:28:38.630 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.select_sound_mode with {'entity_id': 'media_player.denon_avr_x4400h', 'sound_mode': 'STEREO'}
2024-01-06 15:28:38.630 ERROR (MainThread) [denonavr.api] Sending command='MSSTEREO'
2024-01-06 15:28:43.632 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] reproduce: setting volume!
2024-01-06 15:28:43.632 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.volume_set with {'entity_id': 'media_player.denon_avr_x4400h', 'volume_level': 0.455}
2024-01-06 15:28:43.632 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Setting volume to 0.455
2024-01-06 15:28:43.632 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Computed volume -34.5
2024-01-06 15:28:43.632 ERROR (MainThread) [homeassistant.components.denonavr.media_player] About to call
2024-01-06 15:28:43.632 ERROR (MainThread) [denonavr.volume] denonavr: setting volume to -34.5
2024-01-06 15:28:43.632 ERROR (MainThread) [denonavr.api] Sending command='MV45'
2024-01-06 15:28:43.634 ERROR (MainThread) [denonavr.volume] denonavr: after setting volume success=True
2024-01-06 15:28:43.953 ERROR (MainThread) [denonavr.api] Data received: data=b'MV45\rMVMAX 98\r'
2024-01-06 15:28:43.953 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MV45
2024-01-06 15:28:43.953 DEBUG (MainThread) [denonavr.api] Incoming Telnet message: MVMAX 98
2024-01-06 15:28:48.634 ERROR (MainThread) [homeassistant.components.media_player.reproduce_state] Calling media_player.volume_mute with {'entity_id': 'media_player.denon_avr_x4400h', 'is_volume_muted': False}
2024-01-06 15:28:48.635 ERROR (MainThread) [denonavr.api] Sending command='MUOFF'
2024-01-06 15:28:53.639 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Stop script sequence: done

Unfortunately, I don't see any responses coming in until the volume is set, so I don't know how we'll know when the receiver is ready to handle new commands.

rccoleman commented 10 months ago

I narrowed it down to setting the sound mode, and adding a 2 second delay at that point seems to allow successive commands to succeed. This is all in the denonavr package.

    async def async_set_sound_mode(self, sound_mode: str) -> None:                  
        """                
        Set sound_mode of device.                                        

        Valid values depend on the device and should be taken from
        "sound_mode_list".                  
        """              
        if sound_mode == ALL_ZONE_STEREO:
            await self._async_set_all_zone_stereo(True)              
            return

        if self.sound_mode == ALL_ZONE_STEREO:   
            await self._async_set_all_zone_stereo(False)
        # For selection of sound mode other names then at receiving sound modes
        # have to be used                                          
        # Therefore source mapping is needed to get sound_mode                   
        # Create command URL and send command via HTTP GET
        command_url = self._device.urls.command_sel_sound_mode + sound_mode
        telnet_command = (            
            self._device.telnet_commands.command_sel_sound_mode + sound_mode
        )                           
        # sent command                 
        success = self._device.telnet_api.send_commands(telnet_command)
        if not success:                   
            await self._device.api.async_get_command(command_url)
        await asyncio.sleep(2)

1 second is too little, 2 seconds delay seems to do it. I do hear the receiver go silent for a bit when changing the sound mode (even to the same setting that it's already on), so it seems like it's taking time to reconfigure things. The only required delay mentioned in the Denon API spec is 1s after PWON, so I don't see any official need to wait there.