Automations triggered at wrong time

My automation are triggering 2h and 38m too late (not exactly every time, but always at least 2 hours late)

I checked timezone settings, it is correct
date command in Terminal addon, returns correct value (current time in my timezone)
date command in the os shell over ssh, returns time in utc, but still correct

{{now()}}
{{utcnow()}}

return correct value

I have HA installed on a CM4, no RTC, but time is correct so i don’t think that is the problem

Tried restarting HA from the UI, and also completely unplugging RPi, but it didn’t help

If i create new automation, and make it run in a few minutes, it does run at correct time

Anyone has any idea what is happening

Same problem here. Not all the automations are affected. The problem arised after the supervisor updated to 2024.04.0

I now even tried adding RTC to my Pi, and the problem persists

Haven’t read or heard of anything like that in the past, and I’m here for a while.

Can you post the automation trace? In the pic you posted the three dot menu in the upper right corner and then “Download Trace”.

And preferably the automation YAML.

This is just fishing, I have no idea, what’s happening here, sorry. :slight_smile:

2 Likes

Automation YAML

alias: Close cover in the morning
description: ""
trigger:
  - platform: time
    at: "07:00:00"
condition: []
action:
  - service: cover.set_cover_position
    target:
      area_id: bedroom
      device_id: cf64f3079ef03a29d458a9993f6074e4
    data:
      position: 26
mode: single

Trace

{
  "trace": {
    "last_step": "action/0",
    "run_id": "a2ef173464bdd6a0f6ccbb827fc886ff",
    "state": "stopped",
    "script_execution": "finished",
    "timestamp": {
      "start": "2024-04-24T06:41:34.257606+00:00",
      "finish": "2024-04-24T06:41:34.295691+00:00"
    },
    "domain": "automation",
    "item_id": "1713083324644",
    "trigger": "time",
    "trace": {
      "trigger/0": [
        {
          "path": "trigger/0",
          "timestamp": "2024-04-24T06:41:34.257935+00:00",
          "changed_variables": {
            "this": {
              "entity_id": "automation.close_cover_in_the_morning",
              "state": "on",
              "attributes": {
                "id": "1713083324644",
                "last_triggered": "2024-04-23T07:26:10.926248+00:00",
                "mode": "single",
                "current": 0,
                "friendly_name": "Close cover in the morning"
              },
              "last_changed": "2024-04-23T15:34:39.314363+00:00",
              "last_reported": "2024-04-23T15:34:39.314875+00:00",
              "last_updated": "2024-04-23T15:34:39.314363+00:00",
              "context": {
                "id": "01HW5SGGYJ5R2W6CPTSCNXZNJX",
                "parent_id": null,
                "user_id": null
              }
            },
            "trigger": {
              "id": "0",
              "idx": "0",
              "alias": null,
              "platform": "time",
              "now": "2024-04-24T08:41:34.256814+02:00",
              "description": "time",
              "entity_id": null
            }
          }
        }
      ],
      "action/0": [
        {
          "path": "action/0",
          "timestamp": "2024-04-24T06:41:34.259685+00:00",
          "changed_variables": {
            "context": {
              "id": "01HW7DD4HHAT2ZDFSGD471DHPE",
              "parent_id": null,
              "user_id": null
            }
          },
          "result": {
            "params": {
              "domain": "cover",
              "service": "set_cover_position",
              "service_data": {
                "position": 26,
                "area_id": [
                  "bedroom"
                ],
                "device_id": [
                  "cf64f3079ef03a29d458a9993f6074e4"
                ]
              },
              "target": {
                "area_id": [
                  "bedroom"
                ],
                "device_id": [
                  "cf64f3079ef03a29d458a9993f6074e4"
                ]
              }
            },
            "running_script": false
          }
        }
      ]
    },
    "config": {
      "id": "1713083324644",
      "alias": "Close cover in the morning",
      "description": "",
      "trigger": [
        {
          "platform": "time",
          "at": "07:00:00"
        }
      ],
      "condition": [],
      "action": [
        {
          "service": "cover.set_cover_position",
          "target": {
            "area_id": "bedroom",
            "device_id": "cf64f3079ef03a29d458a9993f6074e4"
          },
          "data": {
            "position": 26
          }
        }
      ],
      "mode": "single"
    },
    "blueprint_inputs": null,
    "context": {
      "id": "01HW7DD4HHAT2ZDFSGD471DHPE",
      "parent_id": null,
      "user_id": null
    }
  },
  "logbookEntries": [
    {
      "name": "Close cover in the morning",
      "message": "triggered by time",
      "source": "time",
      "entity_id": "automation.close_cover_in_the_morning",
      "context_id": "01HW7DD4HHAT2ZDFSGD471DHPE",
      "when": 1713940894.2584062,
      "domain": "automation"
    },
    {
      "when": 1713940894.424212,
      "state": "closing",
      "entity_id": "cover.sp2pm_roletnaprozor",
      "context_event_type": "automation_triggered",
      "context_domain": "automation",
      "context_name": "Close cover in the morning",
      "context_message": "triggered by time",
      "context_source": "time",
      "context_entity_id": "automation.close_cover_in_the_morning"
    },
    {
      "when": 1713940894.87606,
      "state": "open",
      "entity_id": "cover.sp2pm_roletnaprozor",
      "context_event_type": "automation_triggered",
      "context_domain": "automation",
      "context_name": "Close cover in the morning",
      "context_message": "triggered by time",
      "context_source": "time",
      "context_entity_id": "automation.close_cover_in_the_morning"
    }
  ]
}

Did you figure this out? Timing on my automations is wildly inaccurate as well even when the time appears to be correct.

I noticed in the trace, the timestamps are all UTC time (00:00), but the trigger “now” time is +02:00. That feels like a tell to me, but I’m not sure what, tbh.

No unfortunately, still same issue

Not sure, but i noticed that time in ha os (host) is in utc, and ha docker is in utc+2, but also no idea if that means anything

Wait… are you running HA Container by chance? If so, in your docker compose (command line), can you add the following and see if it helps?

environment:
  TZ: <your timezone>

(If you’re not running Container, then I’m still at a loss here lol)

I am not running container “manually”
What i meant is, when i do date using “terminal” add-on, i get time in my tz (+2), when i run date from ssh shell directly to host, i get utc time

Same problem here… Super annoying

I also have automations start at random time.
See what I’ve found:

~ $ date
Fri Nov  8 09:12:24 EET 2024
~ $ docker exec -t hassio_supervisor date
Fri Nov  8 07:12:27 UTC 2024

I’m ussing hassio image for raspberry pi.
Not sure which container is the one responsible for the schedule though…

I assume you have not found a solution, I am have having a very similar issue.

I have looked at my HA os logs - and it seems to be getting NTP. But it also seems to be syncing more then once a day ---- like every second it is saying it is out of sync.

I am running HA as a VM on VMware on windows 10.

Following