Time-based triggers using wrong time

Configuration
1

I’m using HA on an arch linux machine, and yesterday after a power outage I restarted the device and all my time-based automations have started activating at the wrong times. However, the system clock is correct and HA even reports that the time based trigger was at the wrong time, so I don’t understand why it would trigger it. To clarify that last statement, here’s a trace from one such automation:

image
image1441×561 19.7 KB

It reports that this happened at 4:24am despite the config clearly indicating it should happen at 9pm. It’s weird that it isn’t even a time zone error, because then it’d be exactly n hours off. And yes, I can confirm 100% that this was not me manually running the automation tasks, as evidenced by the logbook entries:

image
image1442×546 24.5 KB

(If it was manually triggered, it’d say the node wasn’t tracked).

2

Copy-paste the following into the Template Editor and confirm it’s reporting the correct local time.

{{ now() }}
3

Doing that does report the correct local time.

4

Post the automation’s trace file.

5
trace automation.turn_guy_s_lights_off_at_9pm 2023-08-28T09_24_51.244207+00_00.json 
{
  "trace": {
    "last_step": "action/1",
    "run_id": "3d978b274b5ac8f49f6286154313384d",
    "state": "stopped",
    "script_execution": "finished",
    "timestamp": {
      "start": "2023-08-28T09:24:51.244207+00:00",
      "finish": "2023-08-28T09:24:53.314352+00:00"
    },
    "domain": "automation",
    "item_id": "1692228273514",
    "trigger": "time",
    "trace": {
      "trigger/0": [
        {
          "path": "trigger/0",
          "timestamp": "2023-08-28T09:24:51.244277+00:00",
          "changed_variables": {
            "this": {
              "entity_id": "automation.turn_guy_s_lights_off_at_9pm",
              "state": "on",
              "attributes": {
                "id": "1692228273514",
                "last_triggered": "2023-08-28T05:09:37.835433+00:00",
                "mode": "single",
                "current": 0,
                "friendly_name": "Turn Guy's lights off at 9pm"
              },
              "last_changed": "2023-08-27T15:34:48.486837+00:00",
              "last_updated": "2023-08-28T05:09:39.962160+00:00",
              "context": {
                "id": "01H8X8R9DBSZKQ4G58HY0P7M71",
                "parent_id": "01H8X8R9DACRP5YG9TMRY3PPV1",
                "user_id": null
              }
            },
            "trigger": {
              "id": "0",
              "idx": "0",
              "alias": null,
              "platform": "time",
              "now": "2023-08-28T04:24:51.243767-05:00",
              "description": "time",
              "entity_id": null
            }
          }
        }
      ],
      "action/0": [
        {
          "path": "action/0",
          "timestamp": "2023-08-28T09:24:51.247647+00:00",
          "changed_variables": {
            "context": {
              "id": "01H8XQBKXCR6QJQVN087A8A5HX",
              "parent_id": null,
              "user_id": null
            }
          },
          "result": {
            "params": {
              "domain": "switch",
              "service": "turn_off",
              "service_data": {},
              "target": {
                "entity_id": [
                  "switch.guys_light_1_switch"
                ]
              }
            },
            "running_script": false
          }
        }
      ],
      "action/1": [
        {
          "path": "action/1",
          "timestamp": "2023-08-28T09:24:52.262042+00:00",
          "result": {
            "params": {
              "domain": "switch",
              "service": "turn_off",
              "service_data": {},
              "target": {
                "entity_id": [
                  "switch.guys_light_2_switch_2"
                ]
              }
            },
            "running_script": false
          }
        }
      ]
    },
    "config": {
      "id": "1692228273514",
      "alias": "Turn Guy's lights off at 9pm",
      "description": "",
      "trigger": [
        {
          "platform": "time",
          "at": "21:00:00"
        }
      ],
      "condition": [],
      "action": [
        {
          "service": "switch.turn_off",
          "data": {},
          "target": {
            "entity_id": "switch.guys_light_1_switch"
          }
        },
        {
          "service": "switch.turn_off",
          "data": {},
          "target": {
            "entity_id": "switch.guys_light_2_switch_2"
          }
        }
      ],
      "mode": "single"
    },
    "blueprint_inputs": null,
    "context": {
      "id": "01H8XQBKXCR6QJQVN087A8A5HX",
      "parent_id": null,
      "user_id": null
    }
  },
  "logbookEntries": [
    {
      "name": "Turn Guy's lights off at 9pm",
      "message": "triggered by time",
      "source": "time",
      "entity_id": "automation.turn_guy_s_lights_off_at_9pm",
      "context_id": "01H8XQBKXCR6QJQVN087A8A5HX",
      "when": 1693214691.244428,
      "domain": "automation"
    }
  ]
}
6

this evening the automations seemed to work at the correct time. Not sure exactly what’s going on, but I think it fixed itself.

7

FWIW I’m having the exact same issue. My wife nearly killed me because a light in our bedroom came on 2 hours late, after she put the baby down. I’m hoping it resolves itself tomorrow. My guess is that something happened with the scheduler as a result of the power outage.