grocy.execute_chore service doesn't use timezone correctly

[excalbian]

Describe the bug Chore execution is incorrect when called using the execute_chore service. It works as expected when tracked in Grocy, and the displayed time (next, last) in the sensors is correct.

Expected behavior When a chore is tracked with execute_chore the correct (current) time should be recorded.

To Reproduce Steps to reproduce the behavior:

1. Call the grocy.execute_chore service
2. Check the chore last execution (in Grocy, or through the integration)
3. Notice that the execution of the chore is not now (in my case, the inverse of GMT offset)

General information to help debugging:

What sensors do you have enabled? Are they working and/or what state are they in? Do you have the corresponding functions enabled in Grocy? All sensors enabled, and the corresponding functions in Grocy.

What is your installed versions of Home Assistant, Grocy and this integration? Home Assistant: 2022.9.6 Grocy: 3.3.1 (add-on: 0.18.2) Integration: 4.7.1 Edit: Note that this was captured using pygrocy 1.5.0 (from a local override of manifest.json)

How do you have Grocy installed? Add-on or external? Installed using the HA Add-on.

Have you added debugging to the log, and what does the log say? Relevant example from the logs:

2022-09-23 11:19:44.032 DEBUG (SyncWorker_13) [pygrocy.grocy_api_client] --> POST /chores/25/execute
2022-09-23 11:19:44.033 DEBUG (SyncWorker_13) [pygrocy.grocy_api_client] {'tracked_time': '2022-09-23T11:17:35.185320-05:00', 'skipped': False, 'done_by': 3}
2022-09-23 11:19:44.033 DEBUG (SyncWorker_13) [pygrocy.grocy_api_client] <-- 200 for /chores/25/execute
2022-09-23 11:19:44.033 DEBUG (SyncWorker_13) [pygrocy.grocy_api_client] b'{"id":"90","chore_id":"25","tracked_time":"2022-09-23 16:19:44","done_by_user_id":"3","row_created_timestamp":"2022-09-23 11:19:44","undone":"0","undone_timestamp":null,"skipped":"0"}'

JSON service data (if related to using a service)

{
        "chore_id": "25"
        "done_by": "3"
}

Additional context Add any other context about the problem here.

[excalbian]

I did some digging and found that even using the REST API browser within Grocy I could reproduce the issue. Which then led me to this issue in the Grocy repo where it's explained that Grocy API calls basically ignore time zones, so it seems the issue is the integration is trying to include the time zone (offset) in the tracked_time. 🕵️

[excalbian]

I was experiencing this issue (incorrect time zone) with the "latest" version (integration 4.5.1) and started changing things to the beta to try and fix it, which is when I finally reported this issue (and the log captured above). It seems like I was running pygrocy 1.5.0 (by editing requirements in custom_components/grocy/manifest.json) with integration 4.7.1 which didn't work. However, if I use pygrocy 1.4.1 with integration 4.7.1 (IE the way it shipped) the issue still presents, but the calls are slightly different (note the tracked time does not include timezone info):

2022-09-23 12:11:10.801 DEBUG (SyncWorker_10) [pygrocy.grocy_api_client] --> POST /chores/25/execute
2022-09-23 12:11:10.802 DEBUG (SyncWorker_10) [pygrocy.grocy_api_client] {'tracked_time': '2022-09-23T17:06:58.892222+00:00', 'skipped': False, 'done_by': 3}
2022-09-23 12:11:10.802 DEBUG (SyncWorker_10) [pygrocy.grocy_api_client] <-- 200 for /chores/25/execute
2022-09-23 12:11:10.802 DEBUG (SyncWorker_10) [pygrocy.grocy_api_client] b'{"id":"99","chore_id":"25","tracked_time":"2022-09-23 17:11:10","done_by_user_id":"3","row_created_timestamp":"2022-09-23 12:11:10","undone":"0","undone_timestamp":null,"skipped":"0"}'

Please let me know if there is more testing that would be helpful.

[excalbian]

I've created this issue in the upstream repo to discuss this further, since it seems that's where the fix will have to be made.

It looks like (from playing with the API directly) Grocy is expecting tracked_time to be in local time, specifically in the format YYYY-MM-DD hh:mm:ss. When it's not in that format, the value is ignored, the current time (in GMT!!) is used instead and this issue is the side-effect (at least when you're not in GMT 😉).

[excalbian]

@marcelvriend has created a pull request to pygrocy which fixes this issue. Once it's published (a new version of pygrocy released) it would be nice to update the manifest for the custom component to use that version.

I made this change to my manifest.json for the grocy custom component (custom_components/grocy/manifest.json), changing requirements from "pygrocy==1.4.1" to "git+https://github.com/SebRut/pygrocy.git@refs/pull/255/merge#pygrocy==1.5.1" (which will use the pull request version unless pygrocy 1.5.1 is available) that I'm not planning to revert (so I can benefit for now 😉).

[basedsquill]

Thanks for putting all of this together @excalbian, I thought I was going to go insane. For what it's worth to any future lurkers, the pull request has been merged into the develop branch, so you should use "git+https://github.com/SebRut/pygrocy.git@develop#pygrocy==1.5.1" instead of "git+https://github.com/SebRut/pygrocy.git@refs/pull/255/merge#pygrocy==1.5.1".