Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[netatmo] Enhance RefreshCapability #16574

Merged
merged 18 commits into from Mar 29, 2024

Conversation

clinique
Copy link
Contributor

Refresh is no more done based on initial dataValidity but relative to lastSeen, so delay can evoluate to fill gaps.
Resolves #16502
Extracted from #16489
Current status of the RefreshCapability published in the thing properties.

@clinique clinique added the bug An unexpected problem or unintended behavior of an add-on label Mar 24, 2024
@clinique clinique self-assigned this Mar 24, 2024
@clinique clinique requested a review from lolodomo as a code owner March 24, 2024 19:05
@clinique
Copy link
Contributor Author

clinique commented Mar 24, 2024

@jlaur : this is ready for your review. Will require some tests

@jlaur jlaur added the additional testing preferred The change works for the pull request author. A test from someone else is preferred though. label Mar 24, 2024
@clinique clinique requested a review from jlaur March 24, 2024 20:26
@lolodomo
Copy link
Contributor

@clinique : conflict has to be resolved.

Signed-off-by: clinique <gael@lhopital.org>
Signed-off-by: clinique <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Rebased

Signed-off-by: clinique <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
@jlaur
Copy link
Contributor

jlaur commented Mar 25, 2024

this is ready for your review. Will require some tests

👍 I will start reviewing. Please let me know when you are done testing.

@clinique
Copy link
Contributor Author

this is ready for your review. Will require some tests

👍 I will start reviewing. Please let me know when you are done testing.

From my tests this seems good to me, you can give it a test

@jlaur
Copy link
Contributor

jlaur commented Mar 25, 2024

I just went through all possible states of weather station refresh, I think:

grep -E 'RefreshCapability|RefreshAutoCapability' /var/log/openhab/openhab.log | grep indoor_small_bathroom

Result:

2024-03-25 21:06:13.484 [DEBUG] [ler.capability.RefreshAutoCapability] - First data timestamp for 'netatmo:weather-station:home:indoor_small_bathroom' is 2024-03-25T20:03:58Z
2024-03-25 21:06:13.489 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 21:06:17.763 [DEBUG] [ler.capability.RefreshAutoCapability] - First data timestamp for 'netatmo:weather-station:home:indoor_small_bathroom' is 2024-03-25T20:03:58Z
2024-03-25 21:06:17.775 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 21:06:17.824 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 21:06:17.830 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 21:08:18.297 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 21:08:18.342 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 21:10:18.761 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 21:10:18.790 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 21:12:19.291 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 21:12:19.330 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 21:14:19.576 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' identified to be PT10M3S
2024-03-25 21:14:19.619 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT9M59.380979796S
2024-03-25 21:24:19.040 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT10M7.959360195S
2024-03-25 21:34:26.433 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT10M7.566498216S
2024-03-25 21:44:33.844 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT10M4.155349566S
2024-03-25 21:54:38.225 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT10M6.775225709S
2024-03-25 22:04:44.574 [DEBUG] [ler.capability.RefreshAutoCapability] - Data too old, 'netatmo:weather-station:home:indoor_small_bathroom' going back to probing (data age: PT10M17.57394234S)
2024-03-25 22:04:44.575 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:06:45.029 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:06:45.088 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:08:45.418 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:08:45.462 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:10:45.729 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:10:45.756 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:12:46.114 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:12:46.184 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:14:46.499 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:14:46.550 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:16:46.937 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:16:46.980 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:18:47.363 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:18:47.419 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:20:47.758 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:20:47.789 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:22:48.347 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:22:48.388 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:24:48.706 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:24:48.760 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:26:49.143 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:26:49.200 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:28:49.549 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:28:49.593 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:30:49.923 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:30:49.969 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:32:50.329 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:32:50.359 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:34:50.726 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:34:50.772 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:36:50.911 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:36:50.953 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:38:51.276 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:38:51.319 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:40:51.654 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:40:51.698 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:42:52.000 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:42:52.027 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:44:52.316 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:44:52.358 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:46:52.544 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:46:52.582 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:48:52.956 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:48:52.983 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:50:53.291 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:50:53.318 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:52:53.638 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:52:53.690 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT2M
2024-03-25 22:54:54.037 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' not yet found, reference timestamp unchanged
2024-03-25 22:54:54.081 [DEBUG] [handler.capability.RefreshCapability] - Thing 'netatmo:weather-station:home:indoor_small_bathroom' is not ONLINE, using special refresh interval
2024-03-25 22:54:54.085 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT15M
2024-03-25 23:09:54.394 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' identified to be PT1H11M55S
2024-03-25 23:09:54.403 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT1H8M37.597113242S
2024-03-25 23:09:58.706 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT1H8M33.293451152S
2024-03-25 23:09:58.710 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT1H8M33.289230918S
2024-03-25 23:09:58.711 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT1H8M33.288876024S
2024-03-26 00:18:32.095 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refreshed, next one in PT1H10M31.904467741S

Some of the first log lines seems repeated, which is a bit confusing. I don't know if it's caused by the mayhem when starting the binding with two weather stations and many additional modules. I unplugged the main module indoor_small_bathroom around 22. This increased the polling frequency to every two minutes for as long as it was offline until after one hour where it then gave up and decreased it to every 15 minutes. When it finally came online again, it seems like a miscalculation took place, since it now changed frequency to more than one hour.

Perhaps it could be further fine-tuned even more with exponential backoff, distinguishing between different types of HTTP error codes vs. just old timestamps and what-not. But besides the miscalculation mentioned, overall it seems much better than before, so looks like a nice improvement! 👍

Copy link
Contributor

@jlaur jlaur left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One minor optional proposal.

@jlaur
Copy link
Contributor

jlaur commented Mar 25, 2024

2024-03-25 23:09:54.394 [DEBUG] [ler.capability.RefreshAutoCapability] - Data validity period for 'netatmo:weather-station:home:indoor_small_bathroom' identified to be PT1H11M55S

When it finally came online again, it seems like a miscalculation took place, since it now changed frequency to more than one hour.

Some additional details for completeleness:

Main module:

"last_status_store": 1711404382,

(23:06:22 CET/local time)

Additional modules:

"last_seen": 1711404333,
"last_seen": 1711404333,
"last_seen": 1711404333,
"last_seen": 1711404333,

(23:05:33 CET/local time)

@clinique
Copy link
Contributor Author

@jlaur : I think I'm going to change my approach on this. It's a pitty to be searching a delay that we know : weather-station and home-coach refreshes on a 10' rythm - this is given. The only thing we've got to do is align as close as possible to the actual lastSeen timestamp.
In opposition to home Things that must be refreshed on a given frenquency but are event driven.

@jlaur
Copy link
Contributor

jlaur commented Mar 26, 2024

@jlaur : I think I'm going to change my approach on this. It's a pitty to be searching a delay that we know : weather-station and home-coach refreshes on a 10' rythm - this is given. The only thing we've got to do is align as close as possible to the actual lastSeen timestamp. In opposition to home Things that must be refreshed on a given frenquency but are event driven.

True. A few notes though:

  • Although it's been like that for years, Netatmo could change this with a firmware upgrade. But I guess we can still hardcode the interval and sacrifice a bit of auto-adjustment in order to gain simplicity. Perhaps we should consider adding the 10 minutes as a binding configuration parameter, so it would be possible to adapt without code changes and binding distribution in case Netatmo actually does change something?
  • We should call a bit too late rather than a bit too early (before data is available). It's better to have data 15 seconds too late than 9:45 too late. 🙂 I believe it's already like this now.
  • We still need a policy for handling missing data when expected - i.e. when main module is disconnected.

@clinique
Copy link
Contributor Author

@jlaur : I think I'm going to change my approach on this. It's a pitty to be searching a delay that we know : weather-station and home-coach refreshes on a 10' rythm - this is given. The only thing we've got to do is align as close as possible to the actual lastSeen timestamp. In opposition to home Things that must be refreshed on a given frenquency but are event driven.

True. A few notes though:

  • Although it's been like that for years, Netatmo could change this with a firmware upgrade. But I guess we can still hardcode the interval and sacrifice a bit of auto-adjustment in order to gain simplicity. Perhaps we should consider adding the 10 minutes as a binding configuration parameter, so it would be possible to adapt without code changes and binding distribution in case Netatmo actually does change something?
  • We should call a bit too late rather than a bit too early (before data is available). It's better to have data 15 seconds too late than 9:45 too late. 🙂 I believe it's already like this now.
  • We still need a policy for handling missing data when expected - i.e. when main module is disconnected.

Yes, my plan is to add refreshInterval defaulted to 10mn to weather-station and home-coach Thing config parameters. So no change but adjustable if something changes on Netatmo side. The same way it is done for home. The difference is that I'll keep the logic to adjust to lastSeen and also keep DEFAULT_DELAY of 15s. The only modification in this logic is interval will be given. So regarding disconnection and module OFFLINE it will stay as is.

Removed interval guessing logic.

Signed-off-by: clinique <gael@lhopital.org>
Signed-off-by: clinique <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
@clinique
Copy link
Contributor Author

@jlaur: you're ready to go.

@clinique clinique requested a review from jlaur March 26, 2024 17:24
@jlaur
Copy link
Contributor

jlaur commented Mar 26, 2024

you're ready to go.

Here we go with a new test session including commit 13 tracking one of my two weather stations (having four childs):

grep -h -E 'executeUri|RefreshCapability|RefreshAutoCapability|Netatmo_SmallBathroom_LastSeen' /var/log/openhab/openhab.log /var/log/openhab/events.log | sort | grep -E 'indoor_small_bathroom|LastSeen|46&get_favorites=false'

Filtered logs (system started around 18:32, main module taken offline after 18:41, online again before 19:55:

2024-03-26 18:32:26.408 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 18:32:28.829 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M32.171373382S
2024-03-26 18:32:28.852 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from NULL to 2024-03-26T18:30:46.000+0100
2024-03-26 18:32:30.832 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 18:32:30.833 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 18:32:30.834 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 18:32:30.836 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 18:32:32.949 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 18:32:33.264 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M27.73622853S
2024-03-26 18:32:33.270 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M27.729331901S
2024-03-26 18:41:00.276 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 18:41:00.634 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT10M5.365561089S
2024-03-26 18:41:00.826 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from 2024-03-26T18:30:46.000+0100 to 2024-03-26T18:40:51.000+0100
2024-03-26 18:51:05.641 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 18:51:06.814 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 18:51:06.817 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 18:53:06.825 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 18:53:07.263 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 18:53:07.264 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 18:55:07.271 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 18:55:07.824 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 18:55:07.826 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 18:57:07.830 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 18:57:08.345 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 18:57:08.347 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 18:59:08.352 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 18:59:08.759 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 18:59:08.761 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:01:08.766 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:01:09.174 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:01:09.175 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:03:38.647 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:03:39.052 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:03:39.054 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:05:39.061 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:05:39.454 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:05:39.455 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:07:39.462 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:07:39.894 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:07:39.900 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:09:39.907 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:09:40.294 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:09:40.301 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:11:40.308 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:11:40.676 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:11:40.677 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:13:40.684 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:13:41.101 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:13:41.103 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:15:41.111 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:15:41.617 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:15:41.619 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:17:41.625 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:17:42.002 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:17:42.003 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:19:42.010 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:19:42.408 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:19:42.409 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:21:42.414 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:21:42.777 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:21:42.780 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:23:42.786 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:23:43.276 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:23:43.277 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:25:43.280 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:25:43.643 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:25:43.644 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:27:43.651 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:27:44.032 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:27:44.033 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:29:44.040 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:29:44.385 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:29:44.387 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:31:44.393 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:31:44.715 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:31:44.716 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:33:44.721 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:33:45.331 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:33:45.333 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:35:45.341 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:35:45.886 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:35:45.888 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:37:45.894 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:37:46.342 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:37:46.344 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:39:46.350 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:39:46.741 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 19:39:46.743 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-26 19:41:46.750 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:41:47.165 [DEBUG] [handler.capability.RefreshCapability] - Thing 'netatmo:weather-station:home:indoor_small_bathroom' is not ONLINE, using special refresh interval
2024-03-26 19:41:47.166 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT15M
2024-03-26 19:56:47.171 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:56:47.535 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from 2024-03-26T18:40:51.000+0100 to 2024-03-26T19:54:59.000+0100
2024-03-26 19:56:47.538 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M26.461975271S
2024-03-26 19:56:49.540 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 19:56:49.540 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 19:56:49.541 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 19:56:49.542 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 19:56:51.546 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:56:51.837 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.162465998S
2024-03-26 19:56:51.878 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.121552732S
2024-03-26 19:56:51.895 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.104573003S
2024-03-26 20:05:13.910 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 20:05:14.836 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT10M4.163196406S
2024-03-26 20:05:14.843 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from 2024-03-26T19:54:59.000+0100 to 2024-03-26T20:05:04.000+0100

In general it looks good - it succeeds in getting fresh values only ~10 seconds after they seems available, so that's good. It starts doing 2 minute polling when updates are missing, and then 15 minutes after one hour. It resumes normla 10 minute polling when online again.

However, from the logs a few questions.

First, this series of events looks a bit strange to me and results in two calls right after each other:

2024-03-26 19:56:47.171 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:56:47.535 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from 2024-03-26T18:40:51.000+0100 to 2024-03-26T19:54:59.000+0100
2024-03-26 19:56:47.538 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M26.461975271S
2024-03-26 19:56:49.540 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 19:56:49.540 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 19:56:49.541 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 19:56:49.542 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-26 19:56:51.546 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-26 19:56:51.837 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.162465998S
2024-03-26 19:56:51.878 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.121552732S
2024-03-26 19:56:51.895 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.104573003S
  • Why does it log "next refresh in PT2S" four times right after logging "next refresh in PT8M26.461975271S" (which seems correct)?
  • Why do we end up with two calls?

The same happened initially in the beginning of the logs. This was after restarting openHAB, so without anything lingering.

This in itself also looks a bit strange:

2024-03-26 19:56:51.837 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.162465998S
2024-03-26 19:56:51.878 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.121552732S
2024-03-26 19:56:51.895 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.104573003S

Can it have anything to do with additional modules?

Copy link
Contributor

@jlaur jlaur left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks! A few small comments and clarifications needed.

@jlaur
Copy link
Contributor

jlaur commented Mar 26, 2024

Not for this PR, just sharing a finding - when simulating an HTTP error:

2024-03-26 22:36:36.939 [TRACE] [mo.internal.handler.ApiBridgeHandler] -  -returned: code [503 Service Unavailable]
2024-03-26 22:36:36.951 [WARN ] [handler.capability.WeatherCapability] - Error retrieving weather data '46': 
2024-03-26 22:36:36.953 [DEBUG] [l.handler.capability.CacheCapability] - MeasureCapability requesting fresh data for netatmo:indoor:home:indoor_small_bathroom:indoor_office
2024-03-26 22:36:36.954 [DEBUG] [l.handler.capability.CacheCapability] - MeasureCapability requesting fresh data for netatmo:outdoor:home:indoor_small_bathroom:outdoor_shed
2024-03-26 22:36:36.955 [DEBUG] [l.handler.capability.CacheCapability] - MeasureCapability requesting fresh data for netatmo:indoor:home:indoor_small_bathroom:indoor_alva
2024-03-26 22:36:36.955 [DEBUG] [l.handler.capability.CacheCapability] - MeasureCapability requesting fresh data for netatmo:indoor:home:indoor_small_bathroom:indoor_linus
2024-03-26 22:36:37.008 [INFO ] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-26 22:36:37.009 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M

Then shortly after caused by another module:

2024-03-26 22:37:51.086 [DEBUG] [l.handler.capability.CacheCapability] - MeasureCapability requesting fresh data for netatmo:weather-station:home:indoor
2024-03-26 22:37:51.089 [DEBUG] [l.handler.capability.CacheCapability] - WeatherCapability requesting fresh data for netatmo:weather-station:home:indoor
2024-03-26 22:37:51.090 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=32&get_favorites=false 

Handling of such HTTP error should be at account bridge level. If we decide to wait a certain time after an error, this should apply to all devices.

@clinique
Copy link
Contributor Author

In general it looks good - it succeeds in getting fresh values only ~10 seconds after they seems available, so that's good. It starts doing 2 minute polling when updates are missing, and then 15 minutes after one hour. It resumes normla 10 minute polling when online again.

However, from the logs a few questions.

  • Why does it log "next refresh in PT2S" four times right after logging "next refresh in PT8M26.461975271S" (which seems correct)?

These refresh requests are triggered by child modules going ONLINE. This is not great but should only happen on the first "going-ONLINE" event of a child.

  • Why do we end up with two calls?

We end up with two call because the timing of the two requests is not covered by the cache.
Currently the cache is valid for two seconds - but with the new behaviour I think this could be improved because we know from the beginning the dataValidity. It wasn't the case previously. I will think of this.

The same happened initially in the beginning of the logs. This was after restarting openHAB, so without anything lingering.

This in itself also looks a bit strange:

2024-03-26 19:56:51.837 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.162465998S
2024-03-26 19:56:51.878 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.121552732S
2024-03-26 19:56:51.895 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT8M22.104573003S

Can it have anything to do with additional modules?

Yes, same as above. I think I can adress it.

Avoid expiring if an expiring process is already ongoing
Avoid rescheduling is a schedule already exists in the same time frame

Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
@jlaur
Copy link
Contributor

jlaur commented Mar 27, 2024

Yes, same as above. I think I can adress it.

Just to be sure, are you working on addressing this, or is it already fully addressed?

I still see a bit of duplicated log lines, but did not observe duplicated API calls so far:

2024-03-27 19:21:56.402 [DEBUG] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-27 19:21:56.404 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-27 19:23:56.412 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-27 19:23:56.829 [DEBUG] [handler.capability.RefreshCapability] - Thing 'netatmo:weather-station:home:indoor_small_bathroom' is not ONLINE, using special refresh interval
2024-03-27 19:23:56.833 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT15M
2024-03-27 19:38:56.841 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-27 19:38:57.183 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT9M26.817185829S
2024-03-27 19:38:57.205 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from 2024-03-27T18:23:09.000+0100 to 2024-03-27T19:38:09.000+0100
2024-03-27 19:38:59.186 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-27 19:38:59.186 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-27 19:39:01.223 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT9M22.776677884S
2024-03-27 19:39:01.239 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refresh as already pending roughly as the same time, will not reschedule
2024-03-27 19:48:33.413 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-27 19:48:33.794 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT9M46.206279266S
2024-03-27 19:48:33.887 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from 2024-03-27T19:38:09.000+0100 to 2024-03-27T19:48:05.000+0100

@jlaur
Copy link
Contributor

jlaur commented Mar 27, 2024

@lolodomo - ready for you to review also. I have tested several iterations, and it general it looks much better than before. I have only tested weather station functionality, but the changes apply to other modules as well. There is still one clarification needed here: #16574 (comment). Besides this, and this question: #16574 (comment) - LGTM.

I'm leaving tomorrow morning for a small Easter holiday in Germany, so won't be able to test again until Monday evening at the earliest. Thanks for all the effort put into this, @clinique.

@clinique
Copy link
Contributor Author

Yes, same as above. I think I can adress it.

Just to be sure, are you working on addressing this, or is it already fully addressed?

I still see a bit of duplicated log lines, but did not observe duplicated API calls so far:

2024-03-27 19:21:56.402 [DEBUG] [ler.capability.RefreshAutoCapability] - netatmo:weather-station:home:indoor_small_bathroom did not update data in expected time, return to probing
2024-03-27 19:21:56.404 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2M
2024-03-27 19:23:56.412 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-27 19:23:56.829 [DEBUG] [handler.capability.RefreshCapability] - Thing 'netatmo:weather-station:home:indoor_small_bathroom' is not ONLINE, using special refresh interval
2024-03-27 19:23:56.833 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT15M
2024-03-27 19:38:56.841 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-27 19:38:57.183 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT9M26.817185829S
2024-03-27 19:38:57.205 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from 2024-03-27T18:23:09.000+0100 to 2024-03-27T19:38:09.000+0100
2024-03-27 19:38:59.186 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-27 19:38:59.186 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT2S
2024-03-27 19:39:01.223 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT9M22.776677884S
2024-03-27 19:39:01.239 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' refresh as already pending roughly as the same time, will not reschedule
2024-03-27 19:48:33.413 [DEBUG] [mo.internal.handler.ApiBridgeHandler] - executeUri GET  https://api.netatmo.com/api/getstationsdata?device_id=46&get_favorites=false
2024-03-27 19:48:33.794 [DEBUG] [handler.capability.RefreshCapability] - 'netatmo:weather-station:home:indoor_small_bathroom' next refresh in PT9M46.206279266S
2024-03-27 19:48:33.887 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Netatmo_SmallBathroom_LastSeen' changed from 2024-03-27T19:38:09.000+0100 to 2024-03-27T19:48:05.000+0100

Yes, this one is still present : child module requesting their parent to give fresh data when they come ONLINE. Note that it will only happen at startup. I prefer not do changes here because it can have side effects on Security/Energy side and I'd like to keep this PR as lean as possible. This behaviour was already present before this PR so this is not a change.

…ues.

Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Copy link
Contributor

@jlaur jlaur left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From phone now, hard to read README diffs, but noticed default value added. 🙂

bundles/org.openhab.binding.netatmo/README.md Outdated Show resolved Hide resolved
Signed-off-by: gael@lhopital.org <gael@lhopital.org>
Copy link
Contributor

@jlaur jlaur left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@lolodomo lolodomo added rebuild Triggers Jenkins PR build and removed rebuild Triggers Jenkins PR build labels Mar 28, 2024
Copy link
Contributor

@lolodomo lolodomo left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, thank you

@lolodomo lolodomo merged commit b6e3b81 into openhab:main Mar 29, 2024
3 checks passed
@lolodomo lolodomo added this to the 4.2 milestone Mar 29, 2024
@clinique clinique deleted the netatmo_refresh_review branch March 29, 2024 08:14
@lolodomo
Copy link
Contributor

@jlaur : I hope I did not merge too fast. As you approved, I first think it was fine for you. But now, I am asking myself if you would like to continue testing before the merge...

@jlaur
Copy link
Contributor

jlaur commented Mar 29, 2024

@jlaur : I hope I did not merge too fast. As you approved, I first think it was fine for you. But now, I am asking myself if you would like to continue testing before the merge...

No, it's fine, I approved because my tests were successful. 😉

@openhab-bot
Copy link
Collaborator

This pull request has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/netatmo-bridge-offline-99-of-time/149168/28

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
additional testing preferred The change works for the pull request author. A test from someone else is preferred though. bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[netatmo] Update time not synchronized with new weather data
4 participants