Event.async_track_point_in_time - problems when DST is active (was: Alert broken in 0.42)

As of 0.42 I’m finding that alerts fire continuously. For example if I set the following test alert, to tell me every 2 minutes that I’m home, it fires non-stop:

test:
  name: I am home
  entity_id: device_tracker.self_mobile
  state: 'home'
  repeat: 2
  can_acknowledge: True
  skip_first: True
  notifiers:
    - self

I’ve raised an issue about this, as I’m guessing I’m not alone.

(Edit: Of course, I meant 0.42, didn’t I :confused: )

So, it looks like a value of above 60 sets the repeat to seconds. At ten however I was flooded with about 140 alerts in under 2 minutes.

There is at least a workaround :wink:

Ok, so it looks like I’ve found the problem, which isn’t actually with the alert component. It’s with the basic async scheduling :confused:

I added some extra logging to alert.py:

@asyncio.coroutine
def _schedule_notify(self):
    """Schedule a notification."""
    delay = self._delay[self._next_delay]
    next_msg = datetime.now() + delay
    _LOGGER.info("Delay set to %s, next alert at %s", str(delay), str(next_msg))
    self._cancel = \
        event.async_track_point_in_time(self.hass, self._notify, next_msg)
    self._next_delay = min(self._next_delay + 1, len(self._delay) - 1)

With a repeat set at:

  repeat:
    - 10
    - 10
    - 70

I see:

17-03-27 19:26:25 INFO (MainThread) [homeassistant.components.alert] Alerting: I am home
17-03-27 19:26:25 INFO (MainThread) [homeassistant.components.alert] Delay set to 0:10:00, next alert at 2017-03-27 19:36:25.189171
17-03-27 19:26:41 INFO (MainThread) [homeassistant.components.alert] Alerting: I am home
17-03-27 19:26:41 INFO (MainThread) [homeassistant.components.alert] Delay set to 0:10:00, next alert at 2017-03-27 19:36:41.840656
17-03-27 19:26:42 INFO (MainThread) [homeassistant.components.alert] Alerting: I am home
17-03-27 19:26:42 INFO (MainThread) [homeassistant.components.alert] Delay set to 1:10:00, next alert at 2017-03-27 20:36:42.895546

You’ll note that at 19:26 it sets the next alert for 19:36, but still fires an alert 16 seconds later.

However, if I switch my timezone to Etc/UTC then scheduling works as expected.

I’ve raised an issue, hopefully @balloob (who seems to be the guru of the async code) will be able to identify what’s going on.

Just in case anybody else trips across this, it looks like if you set the TZ environment variable, in the process that starts HA, to your local timezone then the problem goes away. As my systems run UTC by default, that wasn’t the case for me. I modified the /etc/systemd/system/home-assistant.service file, to add the TZ variable:

[Unit]
Description=Home Assistant
After=network.target

[Service]
Type=simple
User=homeassistant
Environment="TZ=Europe/London"
ExecStart=/srv/homeassistant/homeassistant_venv/bin/hass -c "/home/homeassistant/.homeassistant"

[Install]
WantedBy=multi-user.target

Has anyone an idea how to do this in the docker image?
At the moment I disabled the whole alert component, since I receive to much messages on my phone.

A Google search for docker change timezone found a number of articles explaining how to do that.