[darksky] thing is not updating / no data refresh

I have set up and configured the binding and created things and items. The initial data load works just fine, so I think my setup is complete. But no matter what I choose for the update interval, data will never be refreshed. Also with setting the log to DEBUG for the bundle, the karaf console shows just nothing after the initial load. So it seems that the update will just never be triggered.

Any additional configuration required to make periodic updates work?

Version used: openHAB and addon on 2.5.1
Operating System and version: Raspbian Stretch

How can anyone answer this question without seeing the configuration you’ve used?

Hehe, point taken. I am unsure what kind of information would help you since PaperUI does all the configuration and, as mentioned before, the initial data load works just fine.

So here is the bridge configuration part from /var/lib/openhab2/jsondb/org.eclipse.smarthome.core.thing.Thing.json

  "darksky:weather-api:DarkSkyAccount": {
    "class": "org.eclipse.smarthome.core.thing.internal.BridgeImpl",
    "value": {
      "label": "Dark Sky Konto",
      "channels": [],
      "configuration": {
        "properties": {
          "apikey": "---redacted---",
          "refreshInterval": 5,
          "language": "de"
        }
      },
      "properties": {},
      "uid": {
        "segments": [
          "darksky",
          "weather-api",
          "DarkSkyAccount"
        ]
      },
      "thingTypeUID": {
        "segments": [
          "darksky",
          "weather-api"
        ]
      }
    }
  }

The weather info part starts as follows

  "darksky:weather-and-forecast:weatherSTR": {
    "class": "org.eclipse.smarthome.core.thing.internal.ThingImpl",
    "value": {
      "label": "Wetterinformationen",
      "bridgeUID": {
        "segments": [
          "darksky",
          "weather-api",
          "DarkSkyAccount"
        ]
      },
      "channels": [
        {
          "acceptedItemType": "DateTime",
          "kind": "STATE",
          "uid": {
            "segments": [
              "darksky",
              "weather-and-forecast",
              "weatherSTR",
              "current#time-stamp"
            ]
          },
          "channelTypeUID": {
            "segments": [
              "darksky",
              "time-stamp"
            ]
          },
          "label": "Letzte Messung",
          "description": "Zeigt den Zeitpunkt der letzten Messung an.",
...

and ends after a while with

          "label": "Vorhergesagter Ozon-Wert",
          "description": "Zeigt den vorhergesagten Ozon-Wert an.",
          "configuration": {
            "properties": {}
          },
          "properties": {},
          "defaultTags": []
        }
      ],
      "configuration": {
        "properties": {
          "numberOfAlerts": 0,
          "forecastDays": 1,
          "location": "48.784354,9.181409",
          "forecastHours": 12
        }
      },
      "properties": {},
      "uid": {
        "segments": [
          "darksky",
          "weather-and-forecast",
          "weatherSTR"
        ]
      },
      "thingTypeUID": {
        "segments": [
          "darksky",
          "weather-and-forecast"
        ]
      }
    }
  },

Pulling the last update into an item shows the date of the first data load (or restart of openHAB or the binding) but never updates.

DateTime weatherUpdate          "last weather update [%1$td.%1$tm.%1$tY %1$tH:%1$tM:%1$tS]" <time>          { channel="darksky:weather-and-forecast:weatherSTR:current#time-stamp" }

Any idea on that? Any additional information that I can provide?

Thanks!

Put the logging for the binding into TRACE mode and check the log output for errors.

There are no errors in the log…

when I restart the binding, I get

openhab> log:tail
21:22:01.545 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Initialize DarkSkyWeatherAndForecastHandler handler 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.555 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Rebuilding thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.566 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Rebuilding hourly forecast channel groups.
21:22:01.577 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours13' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.591 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours14' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.605 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours15' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.615 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours16' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.626 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours17' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.638 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours18' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.649 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours19' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.658 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours20' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.668 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours21' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.678 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours22' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.686 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours23' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.696 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastHours24' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.705 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Rebuilding daily forecast channel groups.
21:22:01.715 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastTomorrow' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.723 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastDay1' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.731 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastDay2' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.740 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastDay3' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.749 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastDay4' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.757 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastDay5' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.766 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastDay6' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:01.774 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Removing channel group 'forecastDay7' from thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:02.112 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - No weather data available to update channel 'time-stamp' of group 'current'.
21:22:02.117 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - No weather data available to update channel 'sunset' of group 'current'.
21:22:02.115 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - No weather data available to update channel 'sunrise' of group 'current'.
21:22:02.112 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - No weather data available to update channel 'icon' of group 'current'.
21:22:16.456 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update weather and forecast data of thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:16.487 [TRACE] [internal.connection.DarkSkyConnection] - Dark Sky request: URL = 'https://api.darksky.net/forecast/---redacted---/48.784354,9.181409?exclude=minutely%2Cflags&units=si&lang=de'
21:22:17.089 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update weather and forecast data of thing 'darksky:weather-and-forecast:weatherSTR'.
21:22:17.214 [TRACE] [internal.connection.DarkSkyConnection] - Dark Sky response: status = 200, content = '{"latitude":48.784354,"longitude":9.181409,"timezone":"Europe/Berlin","currently":{"time":1580588537,"summary":"Überwiegend bewölkt","icon":"partly-cloudy-night",...
21:22:17.301 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'time-stamp' of group 'current' with new state '2020-02-01T21:22:17.000+0100'.
21:22:17.313 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'time-stamp' of group 'current' with new state '2020-02-01T21:22:17.000+0100'.
21:22:17.313 [DEBUG] [sky.internal.utils.ByteArrayFileCache] - Reading file 'f302283b14b5f27a609323afc05add3b.png' from cache
21:22:17.324 [DEBUG] [sky.internal.utils.ByteArrayFileCache] - Reading file 'f302283b14b5f27a609323afc05add3b.png' from cache
21:22:17.332 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'icon' of group 'current' with new state 'raw type (image/png): 5729 bytes'.
21:22:17.341 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'icon' of group 'current' with new state 'raw type (image/png): 5729 bytes'.
21:22:17.356 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'sunrise' of group 'current' with new state '2020-02-01T07:55:00.000+0100'.
21:22:17.364 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'sunrise' of group 'current' with new state '2020-02-01T07:55:00.000+0100'.
21:22:17.367 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'sunset' of group 'current' with new state '2020-02-01T17:21:00.000+0100'.
21:22:17.377 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'sunset' of group 'current' with new state '2020-02-01T17:21:00.000+0100'.

Afterwards just nothing. Should there be a timer job be started or something that triggers the update?

It seems a little odd that there are two updates of everything for the one dataset obtained. Sure you do not have near duplicate Things?

I do not use Darksky but I would expect to see an announcement of a job schedule, yes. You would think that would be down to
"refreshInterval": 5,
I think I’d want it longer than 5 minutes,but that does seem to be above the minimums permitted.

Yep, probably.

Try uninstalling the existing binding and then drop this one into the addons folder.

Should provide a bit more debug output for a couple of possible failure scenarios.

Thanks for your support on this, highly appreciated! Unforunately, no changes yet. The binding is now on version 2.5.2.202002020121 but behaviour is still the same. Also no additional hints in the log.

As @rossko57 has mentioned, the updates appear twice in the log which seems strange to me. Also with the new version. So I removed both things (account and forecast) from my configuration, restarted openHAB and recreated them from scratch. But still the same. Both things appear only once in smarthome:things list but I still have two log entries for the channel update. Does that give any hint?

“Fun” fact: I set up a test environment on a VM with what seems to me the exact same configuration and it all works perfectly there. I cannot see any differences in the configuration.

Is there any way to see/debug the timer that is being set to trigger the update?

No. One update comes from this:

Rebuilding hourly forecast channel groups.

And one from this:

Rebuilding daily forecast channel groups.
1 Like

If you have the debugging set up correctly, you should see one of these messages when the refresh is scheduled (items in [] are replaced by real values, of course)

Schedule job for '[channel]' in [delay] s (at '[date]').

Or you should see this one (only if you’re using my build):

Not scheduling job for channel '[channel]'. Delay = [delay]

Well, I see the scheduling jobs for the respective channels


15:22:04.186 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'icon' of group 'current' with new state 'raw type (image/png): 6747 bytes'.
15:22:04.190 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'icon' of group 'current' with new state 'raw type (image/png): 6747 bytes'.
15:22:04.200 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Not scheduling job for channel 'current#sunrise-event'. Delay = -26884
15:22:04.206 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Not scheduling job for channel 'current#sunrise-event'. Delay = -26884
15:22:04.206 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'sunrise' of group 'current' with new state '2020-02-02T07:54:00.000+0100'.
15:22:04.212 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'sunrise' of group 'current' with new state '2020-02-02T07:54:00.000+0100'.
15:22:04.218 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Schedule job for 'current#sunset-event' in 7256 s (at '2020-02-02T17:23:00').
15:22:04.229 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'sunset' of group 'current' with new state '2020-02-02T17:23:00.000+0100'.
15:22:04.235 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Update channel 'sunset' of group 'current' with new state '2020-02-02T17:23:00.000+0100'.

But this is not the schedule job for pulling new data, right?

Oh, and on the test system, I also see the events only once in the log…

15:22:04.200 [DEBUG] [dler.DarkSkyWeatherAndForecastHandler] - Not scheduling job for channel 'current#sunrise-event'. Delay = -26884

Well, I thought that line was for pulling new data, but no, it looks like you’re right and it’s just for updating a channel…

Are you seeing this message?

Initialize Dark Sky API handler '[id]'.

Here’s the message that indicates the new data pull is scheduled:

Start refresh job at interval [interval] min.

Yes, both are there


20:03:49.199 [DEBUG] [ky.internal.handler.DarkSkyAPIHandler] - Initialize Dark Sky API handler 'darksky:weather-api:DarkSkyAccount'.
20:03:49.207 [DEBUG] [ky.internal.handler.DarkSkyAPIHandler] - Start refresh job at interval 5 min.

It just seems that this refresh job never gets triggered.

OK, after some debugging and fiddling, it seems to me that this all happened because I had a zigbee thing in my system that got stuck during removal. It looks like this kind of blocked the scheduling stuff in openHAB and therefore the darksky binding did not refresh. Not a good explanation, I know, but after I force removed the zigbee thing, it all works now.

Thanks for your support!