Astro: events at midnight - help reading thread listing

Add-ons Bindings
, ,
1

I have a similar problem that other people have reported - astro binding firing my events at midnight. It had been working cleanly for some time, it’s started this behaviour recently. It’s not reliable.

I see on this thread: Astro-Binding: all events are triggered at the same time shortly after midnight, which in turn points to this ticket: https://github.com/openhab/openhab-addons/issues/6584, that the cause can be threads being tied up, either through other bindings or I presume rules or add ins.

I’ve run the suggested threads – locks --monitors, and piped the output to a file. To me it looks like I have a lot of threads tied up, but I actually don’t know how to read the output so it may be entirely normal. I also cannot easily see what’s tying the threads up - a lot of them look to me to be tied up in timers (wait nanos I assume means a timer), and I do use a lot of timers, but seems to me that timers shouldn’t mean I run out of threads, and they should all complete and exit reasonably rapidly (usually within a couple of hours) so they shouldn’t stack up.

Does anyone know this better than me and could give some pointers?

My fallback at the moment will be to add logic to my astro events that basically checks if we’re close to midnight, and then doesn’t run. And furthermore, that has a fallback at 8am and 9pm to check if the astro event has run, and do a failsafe turn on / off just in case.

Log from around midnight:

2020-11-04 23:59:45.113 [INFO ] [lipse.smarthome.model.script.weather] - numberRainArray:[7.620,  0.0,  0.0,  5.842,  22.352,  0.762,  0.0,  0.0,  0.0,  0.0,  0.0,  0.0,  0.0,  0.25
4,  0.508,  0.254,  0.0,  0.0,  0.0,  0.254,  0.254,  25.4,  13.716,  0.0,  0.0,  0.0,  3.81,  0.0,  0.0,  0.0] length:30
2020-11-04 23:59:45.304 [INFO ] [lipse.smarthome.model.script.weather] - numberRainList:[7.62, 0.0, 0.0, 5.842, 22.352, 0.762, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.254, 0.508, 0.254
, 0.0, 0.0, 0.0, 0.254, 0.254, 25.4, 13.716, 0.0, 0.0, 0.0, 3.81, 0.0, 0.0, 0.0] length:30
2020-11-04 23:59:45.315 [INFO ] [lipse.smarthome.model.script.weather] - strTemp:1.270, 7.62, 0.0, 0.0, 5.842, 22.352, 0.762, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.254, 0.508, 0.254,
 0.0, 0.0, 0.0, 0.254, 0.254, 25.4, 13.716, 0.0, 0.0, 0.0, 3.81, 0.0, 0.0
2020-11-05 00:00:04.737 [DEBUG] [.eclipse.smarthome.model.script.plug] - Running price calc
2020-11-05 00:00:05.838 [DEBUG] [.eclipse.smarthome.model.script.plug] - Leave fridges on, price of 94.26 is low enough
2020-11-05 00:00:05.850 [DEBUG] [.eclipse.smarthome.model.script.plug] - Finished running price calc
2020-11-05 00:00:30.550 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2020-11-05 00:00:30.626 [INFO ] [.eclipse.smarthome.model.script.plug] - Dawn start
2020-11-05 00:00:30.659 [INFO ] [.eclipse.smarthome.model.script.plug] - Dusk start
2020-11-05 00:00:30.739 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2020-11-05 00:10:04.318 [DEBUG] [.eclipse.smarthome.model.script.plug] - Running price calc
2020-11-05 00:10:05.675 [DEBUG] [.eclipse.smarthome.model.script.plug] - Leave fridges on, price of 117.54 is low enough
2020-11-05 00:10:05.724 [DEBUG] [.eclipse.smarthome.model.script.plug] - Finished running price calc
2020-11-05 00:20:04.498 [DEBUG] [.eclipse.smarthome.model.script.plug] - Running price calc

locks.txt (131.6 KB)

2

There are two ways to read this sentence. A Timer is only using a thread when it’s actually executing the code in the lambda. Are you saying that it’s sitting inside the lambda for a couple of hours or that the Timers are scheduled to run after a couple of hours but once they do run they exit within milliseconds?

If the former, than that is your problem. There are only 10 (I think) threads that can be executing at the same time out of the timer pool and Astro uses that same pool for it’s own timers. If the latter there isn’t enough information here to really help. All I can see is that the events occur and then the binding schedules the new timers for the new day.

3

The threads aren’t “busy waiting” - i.e. it’s not a sleep statement in my code, it’s a standard OpenHab timer scheduled to fire at a time. They are waiting for the timer to execute - so I had assumed that they don’t tie up a thread. But I see some threads in the attachment that are in “waitNano”, so I was wondering if the timer implementation itself ties up threads somehow blocked. If that’s not the case, then no timers aren’t the problem.

I do see lots of threads in http handling of various sorts. Is that normal, or is there something wrong?

When I look in the thread list closely I see lots of threads, but not a massive number doing the same thing that might indicate some sort of thread leak - and I don’t know what normal looks like. Is there anything in there that jumps out at you as being unusual? Failing that, what other information could I provide that would be useful?

At the moment the only real info I have is that the Astro events are firing straight after midnight, timezone settings look fine, and some people have reported that threads can be the issue. That’s a guess, not a diagnosis, so if there’s logging I can turn on or something I can check or provide, I’d be happy to do so.

And sorry, failed to provide version information. 4.2.2, running on a pi3 (or 4, can’t recall), and my bindings are Astro, Homematic, GPIO, TP-Link, Homematic, BigAssFans. I also have Openhabcloud, and Language Server, and a couple of UIs.

4

I couldn’t say one way or the other for sure but it seems reasonable that there could be lots of threads handling HTTP requests. Every REST call is a separate request.

I don’t have enough insight into OH internals to offer any suggestions or to say whether what you are seeing is reasonable or not.

There is no OH version 4.2.2. Do you mean 2.4.4? The latest release is 2.5.10 and OH 3 is in testing release 2.

5

I guess you have rules listening. May we see actual Astro events from your events.log? Although I doubt they’ll enlighten much more.

6

Ah. That’s what I get from the version command in the console. It’s probably Karaf version. From dpkg I can see I have 2.5.0~M1-1. Is there a way to understand whether that’s 2.5.10 - i.e. an openhab version command somewhere? Apt tells me there’s no new version available.

On Astro events:

2020-11-05 00:00:30.585 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered START
2020-11-05 00:00:30.591 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered END
2020-11-05 00:00:30.601 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDawn#event triggered START
2020-11-05 00:00:30.619 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered END
2020-11-05 00:00:30.631 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered START
2020-11-05 00:00:30.633 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered START
2020-11-05 00:00:30.636 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered END
2020-11-05 00:00:30.639 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDawn#event triggered END
2020-11-05 00:00:30.642 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered END
2020-11-05 00:00:30.645 [vent.ChannelTriggeredEvent] - astro:moon:local:set#event triggered END
2020-11-05 00:00:30.647 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered START
2020-11-05 00:00:30.653 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered END
2020-11-05 00:00:30.659 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2020-11-05 00:00:30.662 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered END
2020-11-05 00:00:30.667 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered END
2020-11-05 00:00:30.669 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered START
2020-11-05 00:00:30.671 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered START
2020-11-05 00:00:30.673 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered END
2020-11-05 00:00:30.677 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered START
2020-11-05 00:00:30.682 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered END
2020-11-05 00:00:30.684 [vent.ChannelTriggeredEvent] - astro:sun:local:eveningNight#event triggered START
2020-11-05 00:00:30.689 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered END
2020-11-05 00:00:30.693 [vent.ChannelTriggeredEvent] - astro:moon:local:rise#event triggered START
2020-11-05 00:00:30.696 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered START
2020-11-05 00:00:30.700 [vent.ChannelTriggeredEvent] - astro:sun:local:night#event triggered START
2020-11-05 00:00:30.709 [ome.event.ItemCommandEvent] - Item 'swInsectZapper' received command OFF
2020-11-05 00:00:30.736 [ome.event.ItemCommandEvent] - Item 'swInsectZapper' received command ON
2020-11-05 00:00:30.773 [nt.ItemStatePredictedEvent] - swInsectZapper predicted to become UNDEF
2020-11-05 00:00:30.797 [nt.ItemStatePredictedEvent] - swInsectZapper predicted to become UNDEF
2020-11-05 00:00:30.829 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered START
2020-11-05 00:00:30.859 [vent.ItemStateChangedEvent] - dateTimeDawnStart changed from 2020-11-04T05:37:00.000+1300 to 2020-11-05T05:36:00.000+1300
2020-11-05 00:00:30.863 [vent.ItemStateChangedEvent] - dateTimeDuskStart changed from 2020-11-04T19:54:00.000+1300 to 2020-11-05T19

Actually interesting, but I don’t know if it offers insight into what’s going on. I didn’t know there was an events log. :slight_smile:

7

I think that means what it says. M1 would be a pre-release milestone. How shall I put it, no-one’s going to very interested now … you should move on to a real release, pref 2.5.10

8

OK, I’m getting it via apt. Apt says there’s not a new version available. Should I be pushing to a testing release instead? It seems to me that must be the current version from a stable viewpoint?

9

See openHAB on Linux | openHAB. Pay particular attention to the three different releases and how those three have different repos to configure in apt.

You are running a version of OH almost a year old. And IIRC there was in fact a bug in the Astro binding that has been fixed in that time.

No, you are on the Testing Release branch. You missed out on the actual release of 2.5 and all of the subsequent point releases since then. You want to be running out of the Stable Release repo.

1 Like
10

Ah, brilliant. Thanks, I’ll take a look.

11

OK, actually I was on stable, but the key had cycled so it wasn’t downloading any new packages from that repo. I thought it was complaining about openhab 1 so was ignoring the message, but it was actually openhab2. 2.5.10-1 on the way, and I’ll see whether that fixes the issue. Thanks for your help.

12

Looks to have worked this morning. I’ll mark this as solved, although I note it has in the past sometimes worked for a few days then stopped. I can see the Astro logs look different than before, so I presume there’s been some re-engineering under the hood.

1 Like