script.reload while script is running

[dlashua]

Home Assistant release with the issue:

0.96.3

Last working Home Assistant release (if known):
Unknown

Operating environment (Hass.io/Docker/Windows/etc.):

arch | x86_64
dev | false
docker | true
hassio | false
os_name | Linux
python_version | 3.7.4
timezone | America/Chicago
version | 0.96.3
virtualenv | false

Component/platform:

script

Description of problem:
If script.reload is called while a script (with a delay) is running, that script breaks.

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

danielbed_sunrise:
  sequence:
    - service: light.turn_on
      data:
        entity_id:
          - light.danielbed_right
          - light.danielbed_left
        rgb_color: [255,0,0]
        brightness_pct: 1
        transition: 1
    - delay:
        seconds: 1
    - service: light.turn_on
      data_template:
        entity_id:
          - light.danielbed_right
          - light.danielbed_left
        rgb_color: [255,0,0]
        brightness_pct: 25
        transition: "{{ ((transition | int) * 60 / 4 * 2) | int }}"
    - delay:
        seconds: "{{ ((transition | int) * 60 / 4 * 2) | int }}"

Traceback (if applicable):

During script.reload:
2019-07-23 06:02:11 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/app/homeassistant/helpers/entity_platform.py", line 356, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: script.danielbed_sunrise

When attempting to call the script again:
2019-07-23 06:02:23 ERROR (MainThread) [homeassistant.components.automation] Error while executing automation automation.danielbed_start_sunrise. Unknown error for call_service at pos 1:
Traceback (most recent call last):
  File "/usr/src/app/homeassistant/components/automation/__init__.py", line 395, in action
    await script_obj.async_run(variables, context)
  File "/usr/src/app/homeassistant/helpers/script.py", line 131, in async_run
    await self._handle_action(action, variables, context)
  File "/usr/src/app/homeassistant/helpers/script.py", line 210, in _handle_action
    action, variables, context)
  File "/usr/src/app/homeassistant/helpers/script.py", line 299, in _async_call_service
    context=context
  File "/usr/src/app/homeassistant/helpers/service.py", line 89, in async_call_from_config
    domain, service_name, service_data, blocking=blocking, context=context)
  File "/usr/src/app/homeassistant/core.py", line 1150, in async_call
    self._execute_service(handler, service_call))
  File "/usr/src/app/homeassistant/core.py", line 1172, in _execute_service
    await handler.func(service_call)
  File "/usr/src/app/homeassistant/components/script/__init__.py", line 115, in service_handler
    if script.is_on:
AttributeError: 'NoneType' object has no attribute 'is_on'

Additional information:

Issue #15795 was closed because it is "stale", however, it is still an issue.

[ghost]

Hey there @home-assistant/core, mind taking a look at this issue as its been labeled with a integration (script) you are listed as a codeowner for? Thanks!

This is a automatic comment generated by codeowners-mention to help ensure issues and pull requests are seen by the right people.

[Santobert]

Still an issue with 0.99.0dev0

System Health

arch	x86_64
dev	true
docker	false
hassio	false
os_name	Linux
python_version	3.7.4
timezone	UTC
version	0.99.0.dev0
virtualenv	true

Example script:

dummy:
  sequence:
    - wait_template: "{{ is_state('binary_sensor.updater', 'on') }}"
      timeout: '00:05:00'
      continue_on_timeout: 'false'

Traceback when reloading scripts:

2019-09-09 21:34:14 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/home/tobi/workspace/home-assistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: script.dummy

Traceback when triggering the script after reloading:

2019-09-09 21:43:23 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139875006564560] 'NoneType' object has no attribute 'is_on'
Traceback (most recent call last):
  File "/home/tobi/workspace/home-assistant/homeassistant/components/websocket_api/commands.py", line 130, in handle_call_service
    connection.context(msg),
  File "/home/tobi/workspace/home-assistant/homeassistant/core.py", line 1234, in async_call
    await asyncio.shield(self._execute_service(handler, service_call))
  File "/home/tobi/workspace/home-assistant/homeassistant/core.py", line 1259, in _execute_service
    await handler.func(service_call)
  File "/home/tobi/workspace/home-assistant/homeassistant/components/script/__init__.py", line 139, in service_handler
    if script.is_on:
AttributeError: 'NoneType' object has no attribute 'is_on'

[hollow]

Same here with 0.100.x:

2019-10-23 08:14:25 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: script.entrance_gallery_off
2019-10-23 08:14:25 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: script.entrance_presence_controller

[rt400]

Same here with 0.101.3 :

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: script.keep_dashboard_running

[stale]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[Santobert]

Duplicate: #29493

[dlashua]

@Santobert this is not a duplicate. It is #29493 that is a duplicate of this Issue, since this issue was created first.

[Santobert]

@dlashua obviously. That's what I meant. Sorry for being imprecise 🙂

[pnbruckner]

I'm working on some new scripting features and became aware of this issue. I added new tests to check for it, and sure enough, they fail. Here is the results of one that tests the scenario described in this issue:

DEBUG:homeassistant.core:Bus:Handling <Event call_service[L]: domain=script, service=test, service_data=>
DEBUG:homeassistant.core:Bus:Handling <Event script_started[L]: name=test, entity_id=script.test>
INFO:homeassistant.components.script.test:test: Running script
INFO:homeassistant.components.script.test:test: Executing step delay 0:00:05
DEBUG:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=script.test, old_state=<state script.test=off; last_triggered=None, can_cancel=True, friendly_name=test @ 2020-02-25T13:43:07.785686+00:00>, new_state=<state script.test=on; last_triggered=2020-02-25T13:43:07.787285+00:00, can_cancel=True, last_action=delay 0:00:05, friendly_name=test @ 2020-02-25T13:43:07.787711+00:00>>
DEBUG:homeassistant.core:Bus:Handling <Event call_service[L]: domain=script, service=reload, service_data=>
DEBUG:homeassistant.core:Bus:Handling <Event service_removed[L]: domain=script, service=test>
DEBUG:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=script.test, old_state=<state script.test=on; last_triggered=2020-02-25T13:43:07.787285+00:00, can_cancel=True, last_action=delay 0:00:05, friendly_name=test @ 2020-02-25T13:43:07.787711+00:00>, new_state=None>
DEBUG:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=script.test, old_state=None, new_state=<state script.test=off; last_triggered=2020-02-25T13:43:07.787285+00:00, can_cancel=True, last_action=delay 0:00:05, friendly_name=test @ 2020-02-25T13:43:07.791010+00:00>>
DEBUG:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=script, service=test>
ERROR:homeassistant.core:Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/home/phil/repos/home-assistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: script.test
DEBUG:homeassistant.core:Bus:Handling <Event call_service[L]: domain=script, service=test, service_data=>
ERROR:homeassistant.core:Error executing service <ServiceCall script.test (c:2cb5e9f6709d4553a713a626923a2d63)>
Traceback (most recent call last):
  File "/home/phil/repos/home-assistant/homeassistant/core.py", line 1242, in _safe_execute
    await self._execute_service(handler, service_call)
  File "/home/phil/repos/home-assistant/homeassistant/core.py", line 1257, in _execute_service
    await handler.func(service_call)
  File "/home/phil/repos/home-assistant/homeassistant/components/script/__init__.py", line 238, in service_handler
    if script.is_on:
AttributeError: 'NoneType' object has no attribute 'is_on'

I'm pretty sure I know what the problem is and will address it as part of the scripting improvements.

[pnbruckner]

For "the record", there were four bugs:

1. The script helper (homeassistant.helpers.script.Script) was delaying the call to the change_listener passed into it by using hass.async_add_job, even if it was a callback which could be called directly.
2. The script integration (homeassistant.components.script.ScriptEntity) was using self.async_ha_update_state as the change_listener when it could have used self.async_ha_write_state. The former is a coroutine function, the latter is a callback.
3. The entity platform's method to add entities (homeassistant.helpers.entity_platform.EntityPlatform.async_add_entities) was not propagating exceptions from its _async_add_entity method (since it was ignoring the returned values from the await asyncio.wait(tasks) call.)
4. The script integration was not checking if adding an entity failed before registering it as a service.

The first two resulted in a delayed state update, causing the script's entity ID being added back to the state machine. (You can see this as the second state_changed event in the log after the reload service was called and the service was removed.)

That caused the first exception (homeassistant.exceptions.HomeAssistantError: Entity id already exists: script.test.)

The third bug prevented that exception from being propagated to the script integration.

The fourth bug meant that the script integration registered a service for a script that wasn't properly loaded. (Of course, the previous bug prevented it from knowing the script wasn't properly loaded, even if it had been "listening" for it.)

That caused the second exception (AttributeError: 'NoneType' object has no attribute 'is_on'.)

[Mariusthvdb]

Hi Phil,

Following your progress in the script domain closely, and am impressed. Hope scripting wil get even better.
Please let me quickly ask if what you have discovered could (remotely) be related to the fact the last_triggered of the scripts isn't logged/recorded past restarts?

Just filed this issue, but thought a quick question would be allowed in this thread..

if not, never mind, and thanks again.

[pnbruckner]

I think that's a separate issue.

[pnbruckner]

@dlashua @Santobert @hollow @rt400

I believe this issue should be resolved now. Some other changes addressed items 1 & 2 in my description above, which should be enough to allow running scripts to be properly stopped so the reload can succeed. Can you verify the issue has been resolved for you?

[Santobert]

I can't reproduce the issue with 0.111.2. Thanks @pnbruckner !
I will close this issue now