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
69.65k stars 28.82k forks source link

JVC_Projector error stop a script #116233

Closed sebiiiii closed 2 months ago

sebiiiii commented 2 months ago

The problem

Hi there I use a script to power on and off my HomeCinema i got an issue with shutdown. I want to shutdown kodi (ok), shutdown JPC Projector (ok) and switch off the powerplugs to avoid lights in night.

After the projector is off, I got this Error : Sensor sensor.jvc_projector_power_status provides state value ‹ ›, which is not in the list of options provided And the script stops here, my powerplugs and all other automations are not done. I try to put a "continue_on_error: true" but it does not affect anything.

I don't need the power_status sensor, as I made a temporisation, but still, I have this issue. Could it be fixed by modify the integration ?

Thanks

What version of Home Assistant Core has the issue?

core-2024.4.3

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

jvc_projector

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

alias: Éteindre le Home Cinéma
sequence:
  - service: kodi.call_method
    metadata: {}
    data:
      method: System.shutdown
    target:
      device_id: 65cac9d0c1020e57b5caff665e6aa8eb
  - delay:
      hours: 0
      minutes: 0
      seconds: 20
      milliseconds: 0
  - type: turn_off
    device_id: 56250fed24d872a601870db6fe5faf96
    entity_id: 99c0a8bb04236c8d85f9a1325a055d3b
    domain: switch
  - continue_on_error: true
    type: turn_off
    device_id: e8efa01d3c2444bdacd65d4f54cbdffe
    entity_id: 809dec7936e1180281dcb2c08a4585b6
    domain: remote
  - delay:
      hours: 0
      minutes: 2
      seconds: 0
      milliseconds: 0
  - type: turn_off
    device_id: f18d9abbb943d7ae8a0551420cd04ba9
    entity_id: 88c4b680a34ecc07eeac5cb1e93b06c1
    domain: switch
mode: single
icon: mdi:theater

Anything in the logs that might be useful for us?

No response

Additional information

No response

home-assistant[bot] commented 2 months ago

Hey there @steveeasley, @msavazzi, mind taking a look at this issue as it has been labeled with an integration (jvc_projector) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `jvc_projector` 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 jvc_projector` 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)

jvc_projector documentation jvc_projector source (message by IssueLinks)

sebiiiii commented 2 months ago

in strings.json I see

` "standby": "[%key:common::state::standby%]",

      "on": "[%key:common::state::on%]",

      "warming": "Warming",

      "cooling": "Cooling",

      "error": "Error"

`

I think the error occurs in cooling time. Maybe add "": "Unknown" is not a smart way,but it's the idea...

SteveEasley commented 2 months ago

I can't replicate this with my own DLA-RS2000 projector. I wonder if your projector has a power state not included in the library. In theory a state of "" should not be possible. It would be helpful to understand exactly whats happening. Would you mind enabling some logging?

Let your automation turn on the projector.

Turn on logging by going to Settings | Devices and Services, click the JVC integration, then click Enable debug logging.

Now run your turn off script.

Now view the logs by going to Settings | System | Logs, and click Load Full Logs (you may need refresh the logs a few times while the projector goes through its power down.

Now search for the string @\x89\x01PW. This is the projector's response to the power state query homeassistant sends.

The number following the above string is the power state at that moment. For instance in this log line

Received ref b'1' (b'@\x89\x01PW1\n')

The 1 following PW was the state (or in the b'1' part). Normally it would be one of the following values:

0 = STANDBY 1 = ON 2 = COOLING 3 = WARMING 4 = ERROR

The actual official values are documented as: image

If the library is returning a value of "" it would imply you have a power state > 4, or there is some error in the call.

SteveEasley commented 2 months ago

Here is my own log from where the projector goes from 2 (Cooling) to 0 (Standby)

2024-04-26 13:22:20.705 DEBUG (MainThread) [homeassistant.components.jvc_projector.coordinator] Finished fetching JVC Projector data in 0.020 seconds (success: True)
2024-04-26 13:22:25.686 DEBUG (MainThread) [jvcprojector.device] Connecting to 192.168.0.30
2024-04-26 13:22:25.703 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJ_OK'
2024-04-26 13:22:25.703 DEBUG (MainThread) [jvcprojector.device] Handshake sending 'PJREQ'
2024-04-26 13:22:25.708 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJACK'
2024-04-26 13:22:25.708 DEBUG (MainThread) [jvcprojector.device] Sending ref 'PW (b'?\x89\x01PW\n')'
2024-04-26 13:22:25.710 DEBUG (MainThread) [jvcprojector.device] Received ack b'\x06\x89\x01PW\n'
2024-04-26 13:22:25.710 DEBUG (MainThread) [jvcprojector.device] Received ref b'2' (b'@\x89\x01PW2\n')
2024-04-26 13:22:25.710 DEBUG (MainThread) [jvcprojector.device] Disconnected
2024-04-26 13:22:25.710 DEBUG (MainThread) [homeassistant.components.jvc_projector.coordinator] Finished fetching JVC Projector data in 0.025 seconds (success: True)
2024-04-26 13:22:30.686 DEBUG (MainThread) [jvcprojector.device] Connecting to 192.168.0.30
2024-04-26 13:22:30.700 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJ_OK'
2024-04-26 13:22:30.700 DEBUG (MainThread) [jvcprojector.device] Handshake sending 'PJREQ'
2024-04-26 13:22:30.702 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJACK'
2024-04-26 13:22:30.702 DEBUG (MainThread) [jvcprojector.device] Sending ref 'PW (b'?\x89\x01PW\n')'
2024-04-26 13:22:30.705 DEBUG (MainThread) [jvcprojector.device] Received ack b'\x06\x89\x01PW\n'
2024-04-26 13:22:30.705 DEBUG (MainThread) [jvcprojector.device] Received ref b'0' (b'@\x89\x01PW0\n')
sebiiiii commented 2 months ago

Thanks for helping me debug this. Here is the log with the error - I put the response before and the one after - It seems there is a timeout during a short time, then the JVC respond well.

2024-04-26 21:58:21.148 DEBUG (MainThread) [homeassistant.components.jvc_projector.coordinator] Finished fetching JVC Projector data in 0.560 seconds (success: True) 2024-04-26 21:58:26.589 DEBUG (MainThread) [jvcprojector.device] Connecting to 192.168.0.251 2024-04-26 21:58:26.593 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJ_OK' 2024-04-26 21:58:26.594 DEBUG (MainThread) [jvcprojector.device] Handshake sending 'PJREQ' 2024-04-26 21:58:26.596 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJACK' 2024-04-26 21:58:26.596 DEBUG (MainThread) [jvcprojector.device] Sending ref 'PW (b'?\x89\x01PW\n')' 2024-04-26 21:58:26.697 DEBUG (MainThread) [jvcprojector.device] Received ack b'\x06\x89\x01PW\n' 2024-04-26 21:58:26.697 DEBUG (MainThread) [jvcprojector.device] Received ref b'1' (b'@\x89\x01PW1\n') 2024-04-26 21:58:26.697 DEBUG (MainThread) [jvcprojector.device] Sending ref 'IP (b'?\x89\x01IP\n')' 2024-04-26 21:58:26.797 DEBUG (MainThread) [jvcprojector.device] Received ack b'\x06\x89\x01IP\n' 2024-04-26 21:58:26.797 DEBUG (MainThread) [jvcprojector.device] Received ref b'6' (b'@\x89\x01IP6\n') 2024-04-26 21:58:26.797 DEBUG (MainThread) [jvcprojector.device] Sending ref 'SC (b'?\x89\x01SC\n')' 2024-04-26 21:58:26.897 DEBUG (MainThread) [jvcprojector.device] Received ack b'\x06\x89\x01SC\n' 2024-04-26 21:58:26.897 DEBUG (MainThread) [jvcprojector.device] Received ref b'1' (b'@\x89\x01SC1\n') 2024-04-26 21:58:26.897 DEBUG (MainThread) [jvcprojector.device] Disconnected

2024-04-26 21:58:26.897 DEBUG (MainThread) [homeassistant.components.jvc_projector.coordinator] Finished fetching JVC Projector data in 0.308 seconds (success: True) 2024-04-26 21:58:29.518 DEBUG (MainThread) [jvcprojector.device] Connecting to 192.168.0.251 2024-04-26 21:58:29.522 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJ_OK' 2024-04-26 21:58:29.522 DEBUG (MainThread) [jvcprojector.device] Handshake sending 'PJREQ' 2024-04-26 21:58:29.525 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJACK' 2024-04-26 21:58:29.525 DEBUG (MainThread) [jvcprojector.device] Sending op 'PW0 (b'!\x89\x01PW0\n')' 2024-04-26 21:58:29.647 DEBUG (MainThread) [jvcprojector.device] Received ack b'\x06\x89\x01PW\n' 2024-04-26 21:58:29.647 DEBUG (MainThread) [jvcprojector.device] Sending ref 'PW (b'?\x89\x01PW\n')'

2024-04-26 21:58:44.649 WARNING (MainThread) [jvcprojector.device] Response timeout for 'PW'

2024-04-26 21:58:44.649 DEBUG (MainThread) [jvcprojector.device] Disconnected 2024-04-26 21:58:44.649 DEBUG (MainThread) [homeassistant.components.jvc_projector.coordinator] Finished fetching JVC Projector data in 15.002 seconds (success: True) 2024-04-26 21:58:44.653 ERROR (MainThread) [homeassistant.components.script.eteindre_le_home_cinema] Éteindre le Home Cinéma: Error executing script. Unexpected error for device at pos 4: Sensor sensor.jvc_projector_power_status provides state value '', which is not in the list of options provided Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 507, in _async_step await getattr(self, handler)() File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 753, in _async_device_step await device_action.async_call_action_from_config( File "/usr/src/homeassistant/homeassistant/components/device_automation/action.py", line 72, in async_call_action_from_config await platform.async_call_action_from_config(hass, config, variables, context) File "/usr/src/homeassistant/homeassistant/components/remote/device_action.py", line 36, in async_call_action_from_config await toggle_entity.async_call_action_from_config( File "/usr/src/homeassistant/homeassistant/components/device_automation/toggle_entity.py", line 124, in async_call_action_from_config await hass.services.async_call( File "/usr/src/homeassistant/homeassistant/core.py", line 2543, in async_call response_data = await coro ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2580, in _execute_service return await target(service_call) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 971, in entity_service_call single_response = await _handle_entity_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1043, in _handle_entity_call result = await task ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/jvc_projector/remote.py", line 82, in async_turn_off await self.coordinator.async_refresh() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 291, in async_refresh await self._async_refresh(log_failures=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 414, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 168, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 494, in _handle_coordinator_update self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 998, in async_write_ha_state self._async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1119, in _async_write_ha_state state, attr, capabilities, shadowed_attr = self.async_calculate_state() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1056, in async_calculate_state state = self._stringify_state(available) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1004, in _stringify_state if (state := self.state) is None: ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/sensor/init.py", line 642, in state raise ValueError( ValueError: Sensor sensor.jvc_projector_power_status provides state value '', which is not in the list of options provided 2024-04-26 21:58:44.672 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [281472326556736] Sensor sensor.jvc_projector_power_status provides state value '', which is not in the list of options provided Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service response = await hass.services.async_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2543, in async_call response_data = await coro ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2580, in _execute_service return await target(service_call) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/script/init.py", line 672, in _service_handler response = await self._async_start_run( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/script/init.py", line 630, in _async_start_run script_result = await coro ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/script/init.py", line 661, in _async_run return await self.script.async_run(script_vars, context) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1713, in async_run return await asyncio.shield(create_eager_task(run.async_run())) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 457, in async_run await self._async_step(log_exceptions=False) File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 509, in _async_step self._handle_exception( File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 562, in _handle_exception raise exception File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 507, in _async_step await getattr(self, handler)() File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 753, in _async_device_step await device_action.async_call_action_from_config( File "/usr/src/homeassistant/homeassistant/components/device_automation/action.py", line 72, in async_call_action_from_config await platform.async_call_action_from_config(hass, config, variables, context) File "/usr/src/homeassistant/homeassistant/components/remote/device_action.py", line 36, in async_call_action_from_config await toggle_entity.async_call_action_from_config( File "/usr/src/homeassistant/homeassistant/components/device_automation/toggle_entity.py", line 124, in async_call_action_from_config await hass.services.async_call( File "/usr/src/homeassistant/homeassistant/core.py", line 2543, in async_call response_data = await coro ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2580, in _execute_service return await target(service_call) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 971, in entity_service_call single_response = await _handle_entity_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1043, in _handle_entity_call result = await task ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/jvc_projector/remote.py", line 82, in async_turn_off await self.coordinator.async_refresh() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 291, in async_refresh await self._async_refresh(log_failures=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 414, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 168, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 494, in _handle_coordinator_update self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 998, in async_write_ha_state self._async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1119, in _async_write_ha_state state, attr, capabilities, shadowed_attr = self.async_calculate_state() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1056, in async_calculate_state state = self._stringify_state(available) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1004, in _stringify_state if (state := self.state) is None: ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/sensor/init.py", line 642, in state raise ValueError( ValueError: Sensor sensor.jvc_projector_power_status provides state value '', which is not in the list of options provided

2024-04-26 21:58:49.588 DEBUG (MainThread) [jvcprojector.device] Connecting to 192.168.0.251 2024-04-26 21:58:49.592 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJ_OK' 2024-04-26 21:58:49.592 DEBUG (MainThread) [jvcprojector.device] Handshake sending 'PJREQ' 2024-04-26 21:58:49.595 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJACK' 2024-04-26 21:58:49.595 DEBUG (MainThread) [jvcprojector.device] Sending ref 'PW (b'?\x89\x01PW\n')' 2024-04-26 21:58:49.608 DEBUG (MainThread) [jvcprojector.device] Received ack b'\x06\x89\x01PW\n' 2024-04-26 21:58:49.608 DEBUG (MainThread) [jvcprojector.device] Received ref b'2' (b'@\x89\x01PW2\n') 2024-04-26 21:58:49.609 DEBUG (MainThread) [jvcprojector.device] Disconnected 2024-04-26 21:58:49.609 DEBUG (MainThread) [homeassistant.components.jvc_projector.coordinator] Finished fetching JVC Projector data in 0.021 seconds (success: True)

SteveEasley commented 2 months ago

Thanks for the detail. Looks like the issue is your projector model doesn't like receiving request commands immediately after operation commands. I don't know show much delay would be enough, so starting out with 1sec in the above PR.

sebiiiii commented 1 month ago

Thanks @joostlek, 1 sec seems ok, it works now.