search

bruxy70 / Garbage-Collection

šŸ—‘ Custom Home Assistant sensor for scheduling garbage collection (or other regularly re-occurring events - weekly on given days, semi-weekly or monthly)
MIT License
382 stars 90 forks source link

Race condition at HA start between the "holidays" and "garbage_collection" integrations #409

Closed rccoleman closed 2 years ago

rccoleman commented 2 years ago

Before you submit a new bug report, please check that

Describe the bug

I noticed over the last weekend that the July 4th holiday on Monday in the US didn't move my Monday garbage collection to Tuesday as expected, so I enabled debug and tried to get to the bottom of it. It looks like there's a potential race condition between the holidays integration and this one where the garbage_collection_loaded event can be fired before the holiday list is populated by the holidays integration, causing the move_on_holiday blueprint to run with an empty list and do nothing useful. The issue seems very timing-dependent, and is most likely to happen following an HA update when requirements are being installed. Once everything is installed and the boot process settles down from run to run, everything is updated/moved as expected.

It's difficult to reproduce and I'm trying to capture logs of the situation, but it happened again earlier today with the release of 2022.7.0b4. I added some of my own logging to the move_on_holiday.yaml blueprint and monitored the HA logs and clearly saw that the blueprint automation was running before the holidays integration had populated its holidays attribute, and the automation was running with a blank one. In the failing case, the following lines:

2022-07-05 12:08:47 DEBUG (MainThread) [custom_components.holidays.calendar] (Holidays) Calling update
2022-07-05 12:08:47 DEBUG (MainThread) [custom_components.holidays.calendar] (Holidays) Country Holidays with parameters: country: US, subdivision: CA, obser
2022-07-05 12:08:47 DEBUG (MainThread) [custom_components.holidays.calendar] (Holidays) Found these holidays:
  2021-01-01: New Year's Day                                                                     
  2021-05-31: Memorial Day                                                        
  2021-07-04: Independence Day                                                      
  2021-07-05: Independence Day (Observed)
...

came after the garbage_collection integration had its update method called and fired the event for the blueprint automation, and my additional logging showed that the holidays attribute was blank when the automation ran. I toyed with added holidays as a dependency for garbage_collection in the manifest and it worked properly on the next boot, but then it still worked fine after removing it. It didn't look like it was doing the required sequencing based on the logs anyway.

There are probably a few ways to address this, but I wanted to get this report in while I think about the best thing to do.

Configuration

I have two instances, but this is the one that should have moved the date from Monday to Tuesday yesterday:

{
  "home_assistant": {
    "installation_type": "Home Assistant OS",
    "version": "2022.7.0b4",
    "dev": false,
    "hassio": true,
    "virtualenv": false,
    "python_version": "3.10.5",
    "docker": true,
    "arch": "x86_64",
    "timezone": "America/Los_Angeles",
    "os_name": "Linux",
    "os_version": "5.15.45",
    "supervisor": "2022.06.2",
    "host_os": "Home Assistant OS 8.2",
    "docker_version": "20.10.14",
    "chassis": "vm",
    "run_as_root": true
  },
  "custom_components": {
    "audiconnect": {
      "version": "2021.1.1",
      "requirements": [
        "beautifulsoup4"
      ]
    },
    "keymaster": {
      "version": "v0.0.80",
      "requirements": []
    },
    "alexa_media": {
      "version": "4.0.3",
      "requirements": [
        "alexapy==1.26.1",
        "packaging>=20.3",
        "wrapt>=1.12.1"
      ]
    },
    "plex_recently_added": {
      "version": "0.3.8",
      "requirements": []
    },
    "pfsense": {
      "version": "0.1.0",
      "requirements": [
        "mac-vendor-lookup>=0.1.11"
      ]
    },
    "pirateweather": {
      "version": "0.1.0",
      "requirements": [
        "python-forecastio==1.4.0"
      ]
    },
    "config_check": {
      "version": "0.1.1",
      "requirements": []
    },
    "garbage_collection": {
      "version": "4.7.8",
      "requirements": [
        "python-dateutil>=2.8.2"
      ]
    },
    "aarlo": {
      "version": "0.7.2b8",
      "requirements": [
        "unidecode",
        "cloudscraper>=1.2.58",
        "paho-mqtt"
      ]
    },
    "hacs": {
      "version": "1.25.5",
      "requirements": [
        "aiogithubapi>=22.2.4"
      ]
    },
    "openei": {
      "version": "0.1.7",
      "requirements": [
        "python-openei==0.1.17"
      ]
    },
    "lamarzocco": {
      "version": "0.7.5",
      "requirements": [
        "lmdirect==0.8.0"
      ]
    },
    "pyscript": {
      "version": "1.3.3",
      "requirements": [
        "croniter==1.3.4",
        "watchdog==2.1.6"
      ]
    },
    "holidays": {
      "version": "1.7.4",
      "requirements": [
        "python-dateutil>=2.8.2",
        "holidays>=0.13"
      ]
    },
    "channels_dvr_recently_recorded": {
      "version": "0.0.1",
      "requirements": [
        "python-dateutil"
      ]
    }
  },
  "integration_manifest": {
    "domain": "garbage_collection",
    "name": "Garbage Collection",
    "version": "4.7.8",
    "documentation": "https://github.com/bruxy70/Garbage-Collection/",
    "issue_tracker": "https://github.com/bruxy70/Garbage-Collection/issues",
    "iot_class": "calculated",
    "dependencies": [],
    "config_flow": true,
    "codeowners": [
      "@bruxy70"
    ],
    "requirements": [
      "python-dateutil>=2.8.2"
    ],
    "is_built_in": false
  },
  "data": {
    "entity_id": "sensor.landscape",
    "state": 0,
    "attributes": {
      "next_date": "2022-07-05T00:00:00-07:00",
      "days": 0,
      "last_collection": null,
      "last_updated": "2022-07-05T12:08:49.729709-07:00",
      "device_class": "garbage_collection__schedule"
    },
    "config_entry": {
      "entry_id": "bb44f1daee574e2687eb2086e502b91b",
      "version": 5,
      "domain": "garbage_collection",
      "title": "Landscape",
      "data": {
        "unique_id": "53a90107-3d4c-4d8b-9339-e2775b9c6efc",
        "frequency": "every-n-days",
        "icon_normal": "mdi:pine-tree",
        "icon_today": "mdi:calendar-check",
        "icon_tomorrow": "mdi:calendar-arrow-right",
        "verbose_format": "on {date}, in {days} days",
        "date_format": "%d-%b-%Y",
        "first_month": "jan",
        "last_month": "dec",
        "period": 14,
        "first_date": "2020-07-06",
        "manual_update": true
      },
      "options": {},
      "pref_disable_new_entities": false,
      "pref_disable_polling": false,
      "source": "user",
      "unique_id": null,
      "disabled_by": null
    }
  }
}

Debug logs

Initial setup of the holidays integration:

2022-07-05 12:21:11 INFO (MainThread) [homeassistant.setup] Setting up holidays                                                                                                                                                      
2022-07-05 12:21:11 INFO (MainThread) [homeassistant.setup] Setup of domain holidays took 0.0 seconds

Initial setup of the garbage_collection integration:

2022-07-05 12:21:20 INFO (MainThread) [homeassistant.setup] Setting up garbage_collection                                                                                                                                            
2022-07-05 12:21:20 INFO (MainThread) [homeassistant.setup] Setup of domain garbage_collection took 0.0 seconds                                                                                                                      
2022-07-05 12:21:20 DEBUG (MainThread) [custom_components.garbage_collection] Setting Recycling (every-n-days) from ConfigFlow                                                                                                       
2022-07-05 12:21:20 DEBUG (MainThread) [custom_components.garbage_collection] Setting Landscape (every-n-days) from ConfigFlow
2022-07-05 12:21:20 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.garbage_collection                                                                                                                         
2022-07-05 12:21:20 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.garbage_collection
2022-07-05 12:21:20 DEBUG (MainThread) [custom_components.garbage_collection.sensor] Creating garbage_collection calendar                                                                                                            
2022-07-05 12:21:20 INFO (MainThread) [homeassistant.components.calendar] Setting up calendar.garbage_collection

The garbage_collection integration updates & fires the event to kick off the blueprint automation:

2022-07-05 12:21:40 INFO (MainThread) [custom_components.hacs] Stage changed: HacsStage.RUNNING                                                                                                                                      
2022-07-05 12:21:40 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Recycling) Calling update                                                                                                                      
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Recycling) Dates loaded, firing a garbage_collection_loaded event                                                                              
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Landscape) Calling update                                                                                                                      
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Landscape) Dates loaded, firing a garbage_collection_loaded event

As the automation iterates through the holiday list, you can see it come across 2022-07-04, which is a holiday:

2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.recycling_holidays] Recycling Holidays: Repeating Iterate through the dates: Iteration 40 of 78 with item: '2022-07-11'
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.landscape_holidays] Landscape Holidays: Repeating Iterate through the dates: Iteration 40 of 78 with item: '2022-07-04'
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.recycling_holidays] Recycling Holidays: Iterate through the dates: Running automation actions
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.recycling_holidays] Recycling Holidays: Iterate through the dates: Executing step call service
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.landscape_holidays] Landscape Holidays: Iterate through the dates: Running automation actions
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.landscape_holidays] Landscape Holidays: Iterate through the dates: Executing step call service
2022-07-05 12:21:41 ERROR (MainThread) [homeassistant.components.system_log.external] [calendar.holidays] Checking Date: 2022-07-11 Loaded? True {'next_date': None, 'next_holiday': None, 'last_updated': None, 'holidays': {}, 'device_class': 'holidays__schedule', 'icon': 'mdi:calendar-blank', 'friendly_name': 'Holidays'}
2022-07-05 12:21:41 ERROR (MainThread) [homeassistant.components.system_log.external] [calendar.holidays] Checking Date: 2022-07-04 Loaded? True {'next_date': None, 'next_holiday': None, 'last_updated': None, 'holidays': {}, 'device_class': 'holidays__schedule', 'icon': 'mdi:calendar-blank', 'friendly_name': 'Holidays'}
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.recycling_holidays] Recycling Holidays: Iterate through the dates: Test condition Is this date a public holiday?: False
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.landscape_holidays] Landscape Holidays: Iterate through the dates: Test condition Is this date a public holiday?: False

I added some debug there to indicate that the "holidays" attributes exists ("Loaded? True"), but the attribute itself is blank ('holidays': {}). Sure enough, the last line determines that July 4 is not a holiday.

Later, after the automation finishes, I finally get this:

2022-07-05 12:21:41 ERROR (MainThread) [homeassistant.components.system_log.external] [calendar.holidays] Checking Date: 2023-12-25 Loaded? True {'next_date': None, 'next_holiday': None, 'last_updated': None, 'holidays': {}, 'device_class': 'holidays__schedule', 'icon': 'mdi:calendar-blank', 'friendly_name': 'Holidays'}
2022-07-05 12:21:41 ERROR (MainThread) [homeassistant.components.system_log.external] [calendar.holidays] Checking Date: 2023-12-18 Loaded? True {'next_date': None, 'next_holiday': None, 'last_updated': None, 'holidays': {}, 'device_class': 'holidays__schedule', 'icon': 'mdi:calendar-blank', 'friendly_name': 'Holidays'}
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.recycling_holidays] Recycling Holidays: Iterate through the dates: Test condition Is this date a public holiday?: False
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.landscape_holidays] Landscape Holidays: Iterate through the dates: Test condition Is this date a public holiday?: False
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.recycling_holidays] Recycling Holidays: Executing step Update the garbage_collection entity
2022-07-05 12:21:41 INFO (MainThread) [homeassistant.components.automation.landscape_holidays] Landscape Holidays: Executing step Update the garbage_collection entity
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection] called update_state for sensor.recycling
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Recycling) Looking for next collection
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Recycling) next_date (2022-07-11), today (2022-07-05)
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Recycling) Found next collection date: 11-Jul-2022, that is in 6 days
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection] called update_state for sensor.landscape
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Landscape) Looking for next collection
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Landscape) next_date (2022-07-18), today (2022-07-05)
2022-07-05 12:21:41 DEBUG (MainThread) [custom_components.garbage_collection.sensor] (Landscape) Found next collection date: 18-Jul-2022, that is in 13 days
2022-07-05 12:21:42 DEBUG (MainThread) [custom_components.holidays.calendar] (Holidays) Calling update
2022-07-05 12:21:42 DEBUG (MainThread) [custom_components.holidays.calendar] (Holidays) Country Holidays with parameters: country: US, subdivision: CA, observed: True
2022-07-05 12:21:42 DEBUG (MainThread) [custom_components.holidays.calendar] (Holidays) Found these holidays: 
  2021-01-01: New Year's Day
  2021-05-31: Memorial Day
  2021-07-04: Independence Day
  2021-07-05: Independence Day (Observed)
  2021-09-06: Labor Day
  2021-11-25: Thanksgiving
  2021-11-26: Day After Thanksgiving
  2021-12-24: Christmas Day (Observed)
  2021-12-25: Christmas Day
  2021-12-31: New Year's Day (Observed)
  2022-01-01: New Year's Day
  2022-05-30: Memorial Day
  2022-07-04: Independence Day
  2022-09-05: Labor Day
  2022-11-24: Thanksgiving
  2022-11-25: Day After Thanksgiving
  2022-12-25: Christmas Day
  2022-12-26: Christmas Day (Observed)
  2023-01-01: New Year's Day
  2023-01-02: New Year's Day (Observed)
  2023-05-29: Memorial Day
  2023-07-04: Independence Day
  2023-09-04: Labor Day
  2023-11-23: Thanksgiving
  2023-11-24: Day After Thanksgiving
  2023-12-25: Christmas Day
2022-07-05 12:21:42 DEBUG (MainThread) [custom_components.holidays.calendar] (Holidays) Looking for next collection
2022-07-05 12:21:42 DEBUG (MainThread) [custom_components.holidays.calendar] (Holidays) next_date (2022-09-05), today (2022-07-05)

Now, the "holidays" attribute is finally populated, but it's too late for the automation.

bruxy70 commented 2 years ago

Thanks. That will not be an easy one šŸ˜Š

rccoleman commented 2 years ago

Yeah, I puzzled over it for a while yesterday and couldn't come up with a clean solution. I started with an automation that triggers on an update to the holidays calendar to force an update for the garbage_collection sensor, but there are a lot of gates in way to prevent updates for which the state didn't change. The custom "update_state" service skips the event.

Maybe listening for a custom event in garbage_collection that's sent by holidays when it updates? Or listening for homeassistant_started in garbage_collection, although I don't know whether that happens late enough.

bruxy70 commented 2 years ago

I can't make garbage_collection depending on holidays, many people don't use this integration. I wonder why the list of holidays is empty - I thought it should get the list from the last update. So even garbage collection triggers the event before holidays get updated, it should get the list anyhow. It does not change. Other option is to wait for the holidays update in the automation blueprint?

rccoleman commented 2 years ago

It definitely starts empty at startup every time and is then populated. Maybe also derive from RestoreEntity and populate the state & attributes with async_get_last_state and async_get_last_extra_data? That way, you can probably populate once at setup and whenever the config changes, but have the state & attributes available when the entities are added to hass.

It looks like you use that in garbage_collection, but not in holidays.

bruxy70 commented 2 years ago

All right, try the Holidays beta 1.8.0b1. I did not Manage to restore the whole calendar with its entities, but I am loading at least the list of holidays that is used by the blueprint. The calendar is refreshed shortly after anyhow. So this should do. To test, you might want to restart twice (after the first restart it might not store the state as it will still be a standard entity).

rccoleman commented 2 years ago

Excellent, testing now! I can clearly see the saved state in core.restore_state, so at least that part is working.

bruxy70 commented 2 years ago

If this is solved by tne new release, please close it. Thanks.

rccoleman commented 2 years ago

It looks like it's working based on my limited testing, so I'll close it. Thanks for the quick turnaround!