search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.06k stars 29.72k forks source link

Gardena 1889 clock sync #121687

Open adam-kulagowski opened 1 month ago

adam-kulagowski commented 1 month ago

The problem

The HA changes the the time of Gardena 1889 after phone connection was performed.

I live in TZ Europe/Warsaw. Currently its (due to daylight) GMT+2.

I have proper TZ set in HA UI: Screenshot 2024-07-10 at 16-53-28 Settings – Home Assistant

However always after I connect using using phone to my Gardena 1889, in logs of HA (after it takes over) I see the following info:

2024-07-10 16:49:16.168 DEBUG (MainThread) [gardena_bluetooth.client] Connected to 30:AF:7E:D5:XX:XX
[...]
2024-07-10 16:49:20.644 WARNING (MainThread) [gardena_bluetooth.client] Updating time on device to match local time delta was 1:59:59.457449
2024-07-10 16:49:27.078 DEBUG (MainThread) [gardena_bluetooth.client] Disconnecting from 30:AF:7E:D5:XX:XX
2024-07-10 16:50:21.828 DEBUG (MainThread) [gardena_bluetooth.client] Connecting to 30:AF:7E:D5:XX:XX

The only case when the time does not change is when I set my time to GMT+4.

My Android phone has also correct timezone set. All clocks:

What version of Home Assistant Core has the issue?

2024.7.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Gardena Bluetooth

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

How to reproduce:
- disable device in Gardena Bluetooth integration
- connect to device using phone
- after connection was performed, disable phone bluetooth
- enable device in HA
- observe the logs using `tail -f home-assistant.log|grep gardena_bluetooth.client`

Additional information

I'm using the latest FW: 1.7.23.29 on my Gardena 1889-20 I'm connecting to Gardena using ESPhome BT proxy

adam-kulagowski commented 1 month ago

I did some debugging on my own, changed in client.py python code accordingly:

   202      async def update_timestamp(self, now: datetime):
   203          try:
   204              timestamp = await self.read_char(DeviceConfiguration.unix_timestamp)
   205          except CharacteristicNoAccess:
   206              LOGGER.debug("No timestamp defined for device")
   207              return
   208          LOGGER.debug("RAW timestamp from device: %s", timestamp) 
   209          timestamp = timestamp.replace(tzinfo=now.tzinfo)
   210          LOGGER.debug("TZted timestamp from device: %s", timestamp)
   211          LOGGER.debug("NOW timestamp %s", now) 
   212          LOGGER.debug("TBW timestamp %s", now.replace(tzinfo=None))

And with that logging enabled I redid steps to reproduce the issue:

First attempt:

Local time: 11 Jul 2024, 10:51:25 CEST

With GMT+2 set on the phone, after time was synced w/ phone:

2024-07-11 10:52:31.443 DEBUG (MainThread) [gardena_bluetooth.client] RAW timestamp from device: 2024-07-11 12:52:31
2024-07-11 10:52:31.443 DEBUG (MainThread) [gardena_bluetooth.client] TZted timestamp from device: 2024-07-11 12:52:31+02:00
2024-07-11 10:52:31.443 DEBUG (MainThread) [gardena_bluetooth.client] NOW timestamp 2024-07-11 10:52:31.373236+02:00
2024-07-11 10:52:31.443 DEBUG (MainThread) [gardena_bluetooth.client] TBW timestamp 2024-07-11 10:52:31.373236
2024-07-11 10:52:31.444 WARNING (MainThread) [gardena_bluetooth.client] Updating time on device to match local time delta was 1:59:59.626764

Second attempt

Local time: 11 Jul 2024, 10:55:22 CEST

With GMT+0 set on the phone, after time was synced w/ phone:

2024-07-11 10:56:38.845 DEBUG (MainThread) [gardena_bluetooth.client] RAW timestamp from device: 2024-07-11 10:56:39
2024-07-11 10:56:38.846 DEBUG (MainThread) [gardena_bluetooth.client] TZted timestamp from device: 2024-07-11 10:56:39+02:00
2024-07-11 10:56:38.846 DEBUG (MainThread) [gardena_bluetooth.client] NOW timestamp 2024-07-11 10:56:38.742259+02:00
2024-07-11 10:56:38.846 DEBUG (MainThread) [gardena_bluetooth.client] TBW timestamp 2024-07-11 10:56:38.742259
2024-07-11 10:56:38.846 DEBUG (MainThread) [gardena_bluetooth.client] No need to update timestamp local time delta was 0:00:00.257741

After that I downloaded Bluetooth capture from Android phone:

Those events are from before HA events mentioned above.

In first attempt there was Read request & Write request:

Local time: 11 Jul 2024, 10:51:25 CEST

Read Request: 2e9d8f66 (raw value received from Gardena) Converted to timestamp: 1720687918 Converted to GMT: Thursday, July 11, 2024 8:51:58 AM Converted to my time zone: Thursday, July 11, 2024 10:51:58 AM GMT+02:00 DST

Note: It looks OK, as before this attempt, time was synced to Gardena via Homeassistant.

Write Request: 4fb98f66 (raw value sent to Gardena) Converted to timestamp: 1720695119 Converted to GMT: Thursday, July 11, 2024 10:51:59 AM Converted to my time zone: Thursday, July 11, 2024 12:51:59 PM GMT+02:00 DST

Note: App is writing local time directly to the device.

In the second attempt there was only read request

Read Request: 229e8f66 (raw value received from Gardena) Converted to timestamp: 1720688162 Converted to GMT: Thursday, July 11, 2024 8:56:02 AM Converted to my time zone: Thursday, July 11, 2024 10:56:02 AM GMT+02:00 DST

Summary

It seems that Gardena writes local time to the device. But in HA we are expecting GMT+0. Since I'm short on time (I'll have some spare time in Aug) I had to end my debugging at this point.

home-assistant[bot] commented 1 month ago

Hey there @elupus, mind taking a look at this issue as it has been labeled with an integration (gardena_bluetooth) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `gardena_bluetooth` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign gardena_bluetooth` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)

gardena_bluetooth documentation gardena_bluetooth source (message by IssueLinks)

elupus commented 1 month ago

I was looking at your tests here again. Something is weird here. When you set your phone to +2, and the local time was 10:51 CET (utc+2), the phone reported a un-timezoned time of 12:54. If it indeed does store things in local time, the untimezoned time should match the local time. Instead it looks to be 4 hours offset from utc?

adam-kulagowski commented 1 month ago

I'll redo tests tomorrow and post my results here if possible with pcaps files.

adam-kulagowski commented 1 month ago

Part I - HA

Methodology

  1. set TZ in Homeassistant UI and read local time
  2. enable Gardena integration
  3. watch how it syncs in log
  4. disable Gardena integration
  5. read the value from 98bd0b13-0b0e-421a-84e5-ddbf75dc6de4 using nRF Connect Android APP
  6. convert HEX to timestamp, use https://www.unixtimestamp.com/ to get time+date

Results

Homeassistant GMT+2 Time: 09:55:49 Raw value from Gardena 1889: 6E-7A-B4-66 Gardena 1889 time: 8/8/2024, 9:57:34 AM

Homeassistant GMT+0 Time: 08:07:45 Raw value from Gardena 1889: 53-61-B4-66 Gardena 1889 time: 8/8/2024, 8:10:46 AM

Homeassistant GMT+1 Time: 09:14:55 Raw value from Gardena 1889: B4-70-B4-66 Gardena 1889 time: 8/8/2024, 9:16:04 AM

Conclusion: HA integration writes local time

Part II - Phone + native Gardena App

Methodology

  1. set TZ in phone settings and read local time
  2. launch Gardena app and let it sync
  3. read the value from 98bd0b13-0b0e-421a-84e5-ddbf75dc6de4 using nRF Connect Android APP
  4. convert HEX to timestamp, use https://www.unixtimestamp.com/ to get time+date

Results

Phone GMT+0 Time: 8:20 Raw value from Gardena 1889: 25-9c-b4-66 Gardena 1889 time: 8/8/2024, 12:21:25 PM

Phone GMT+1 Time: 9:22 Raw value from Gardena 1889:89-9c-b4-66 Gardena 1889 time: 8/8/2024, 12:23:05 PM

Phone GMT+2 Time: 10:23 Raw value from Gardena 1889: E8-9c-b4-66 Gardena 1889 time: 8/8/2024, 12:24:40 PM

Conclusion: Native App writes always GMT+4 ?

At this point I'm stumbled what to do next. Ideally we should store GMT+4 to the device to avoid collisions but it looks like a bug on Gardena side and I'm not sure if this behavior is local to my part of EU. @elupus could You confirm this behavior on Your side?

adam-kulagowski commented 1 month ago

I've also created ticket in Gardena Zendesk #2245193 but I'm not getting my hopes up.

elupus commented 1 month ago

I tried connecting with android to the device yesterday. But it refused. Think it is limited to two clients maybe. So would need to factory reset it (dont want to right now)

I do recall that i did see some such weird timestamp adjustment in the past.

From what i can tell from the app it does seem to write timezone adjusted value.

It does look strange tough if it is fixed. Did you fully restart your app (maybe even phone) between changing timezone?

adam-kulagowski commented 1 month ago

I'll try to reboot phone - and post my findings. That's a good point - I didn't thought on that.

Somehow I'm able to connect to my Gardena device w/o any issues (and w/o reset in process) but I need to disable Gardena integration in HA first, then wait a few seconds.

adam-kulagowski commented 1 month ago

@elupus You were right. Reboot provides more data:

Methodology

  1. set TZ in phone settings
  2. reboot
  3. read local time
  4. launch Gardena app and let it sync
  5. read the value from 98bd0b13-0b0e-421a-84e5-ddbf75dc6de4 using nRF Connect Android APP
  6. convert HEX to timestamp, use https://www.unixtimestamp.com/ to get time+date

Results

Phone GMT+0 Time: 9:54 Raw value from Gardena 1889: d2-95-b4-66 Gardena 1889 time: 8/8/2024, 11:54:26 AM

Phone GMT+1 Time: 11:31 Raw value from Gardena 1889: ae-ac-b4-66 Gardena 1889 time: 8/8/2024, 1:31:58 PM

Phone GMT+2 Time: 12:34 Raw value from Gardena 1889: 69-bb-b4-66 Gardena 1889 time: 8/8/2024, 2:34:49 PM

Phone GMT+3 Time: 13:37 Raw value from Gardena 1889: 2f-ca-b4-66 Gardena 1889 time: 8/8/2024, 3:37:51 PM

Conclusion: Gardena App writes to the 1889 device time shifted +2 ?

I'll update Gardena ticket w/ my findings.

elupus commented 1 month ago

So weird... I dont know what to make of it. I cant see anything of this shenanigans in the official app.

elupus commented 1 month ago

What is somewhat weird is that it is a unix time. Which by definition should be un UTC/GMT time. But it does something strange since it is in some type of local time.

adam-kulagowski commented 1 month ago

Gardena is a German company, which sits in GMT+2 (currently due to DST) - so +2 might related if their application code is bad :stuck_out_tongue:

As the time is hidden in official app and if the scheduled operation are also shifted (which seems to be a case), no one will ever encounter this issue unless start playing w/ HASS.

I'm really curios what will be Your findings.

I've found similar issue here https://github.com/home-assistant/core/issues/101450 but I'm pretty sure You are aware of it already.