Astro Binding Triggers Stop Working

BigGeorgeTx · November 19, 2021, 2:52am

I am running openHAB 3.1 Release Version on a Pi4B with openhabian.

The observed behavior is that channel triggers based on the Astro binding work for a day or two or more, but eventually stop working. There are no errors in the log, the events just don’t trigger. 100% of the time, an openHAB restart (systemctl restart openhab) eliminates the problem for a while.

Here is a rule that uses the trigger

rule "Turn on Exterior lighting using map transform for Echo at sunset end"
when Channel "astro:sun:local:set#event" triggered END 
then 
val formatter = java.time.format.DateTimeFormatter.ofPattern("yyyy-MM-dd")
val String TodayString2 = formatter.format(now())
val String SpecialLighting = transform("MAP","special_lighting_dates.map",TodayString2)
val String SpecialLighting_Alexa_Routine = transform("MAP","special_lighting_alexa_routine_names.map",SpecialLighting).replace("\"","") 
 
logInfo("exterior lights", TodayString2 + " " + SpecialLighting + " " + SpecialLighting_Alexa_Routine.toString)

EchoShowOffice_StartaRoutine.sendCommand( SpecialLighting_Alexa_Routine.toString )
end

I found several old discussions in the forum that referenced similar behavior.
The one that seemed most relevant (though I’m not an expert, so I’m guessing) is Openhab 2.4.0 stops updating - #2 by Bruce_Osborne

I followed the suggestion and tried the “threads --monitors --locks” command on the console. As advertised, it produced a lot of output.


"Karaf ssh console user openhab" Id=30267 in WAITING on lock=org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl@15876ad
    at java.base@11.0.12/java.lang.Object.wait(Native Method)
    at java.base@11.0.12/java.lang.Object.wait(Object.java:328)
    at org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl.start(CommandSessionImpl.java:802)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:300)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:169)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:149)
    at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:179)
    at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.doExecute(ConsoleSessionImpl.java:467)
    at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:407)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"pipe-threads --monitors --locks" Id=30268 in RUNNABLE
    at java.management@11.0.12/sun.management.ThreadImpl.dumpThreads0(Native Method)
    at java.management@11.0.12/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:521)
    at java.management@11.0.12/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:509)
    at org.apache.karaf.shell.commands.impl.ThreadsAction.execute(ThreadsAction.java:78)
    at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:84)
    at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:68)
    at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:86)
    at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:599)
    at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:526)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:415)
    at org.apache.felix.gogo.runtime.Pipe.doCall(Pipe.java:416)
    at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:229)
    at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:59)
    at java.base@11.0.12/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@1663442

"job controller 1" Id=30269 in WAITING on lock=java.util.concurrent.FutureTask@16b5b19
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
    at java.base@11.0.12/java.util.concurrent.FutureTask.awaitDone(FutureTask.java:447)
    at java.base@11.0.12/java.util.concurrent.FutureTask.get(FutureTask.java:190)
    at java.base@11.0.12/java.util.concurrent.AbstractExecutorService.invokeAll(AbstractExecutorService.java:247)
    at org.apache.felix.gogo.runtime.CommandSessionImpl$JobImpl.run(CommandSessionImpl.java:827)
    at java.base@11.0.12/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base@11.0.12/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@69713c

"session-1-thread-3" Id=30270 in TIMED_WAITING on lock=java.util.concurrent.SynchronousQueue$TransferStack@13a871c
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"session-1-thread-4" Id=30271 in TIMED_WAITING on lock=java.util.concurrent.SynchronousQueue$TransferStack@13a871c
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-discovery-663" Id=30294 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@1224e79
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1218)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-thingManager-1255" Id=30307 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@10a727b
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1218)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-thingManager-1256" Id=30309 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@10a727b
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1223)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-thingManager-1257" Id=30310 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@10a727b
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1218)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-thingManager-1258" Id=30315 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@10a727b
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1218)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-discovery-664" Id=30321 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@1224e79
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1218)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-common-961" Id=30322 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@eecba6
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1218)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-common-962" Id=30323 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@eecba6
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1218)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"OH-common-963" Id=30332 in TIMED_WAITING on lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@eecba6
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:1223)
    at java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:899)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"Common-Cleaner" Id=8 in TIMED_WAITING on lock=java.lang.ref.ReferenceQueue$Lock@571c80
    at java.base@11.0.12/java.lang.Object.wait(Native Method)
    at java.base@11.0.12/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
    at java.base@11.0.12/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:148)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)
    at java.base@11.0.12/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:134)

"Keep-Alive-Timer" Id=30336 in TIMED_WAITING
    at java.base@11.0.12/java.lang.Thread.sleep(Native Method)
    at java.base@11.0.12/sun.net.www.http.KeepAliveCache.run(KeepAliveCache.java:168)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)
    at java.base@11.0.12/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:134)

"process reaper" Id=30024 in TIMED_WAITING on lock=java.util.concurrent.SynchronousQueue$TransferStack@10ff154
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"process reaper" Id=30187 in TIMED_WAITING on lock=java.util.concurrent.SynchronousQueue$TransferStack@10ff154
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"process reaper" Id=30192 in TIMED_WAITING on lock=java.util.concurrent.SynchronousQueue$TransferStack@10ff154
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"process reaper" Id=30281 in TIMED_WAITING on lock=java.util.concurrent.SynchronousQueue$TransferStack@10ff154
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

"process reaper" Id=30282 in TIMED_WAITING on lock=java.util.concurrent.SynchronousQueue$TransferStack@10ff154
    at java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
    at java.base@11.0.12/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

I plan to try this command again when the trigger stops working and seeing if there is something different.

Thanks in advance for any suggestions.

Wolfgang_S · November 19, 2021, 6:17am

Everything else continues to work ? While astro binding triggers are not logged in the event logs you still have other events being logged ?

BigGeorgeTx · November 19, 2021, 1:46pm

Yes, everything else continues to work as expected, with lots of entries in the log. Just nothing for the astro events

rossko57 · November 19, 2021, 1:56pm

Astro relies on a lot of scheduled tasks. Have you any Items linked e.g. sunset time or suchlike? Astro runs just after midnight to set up the events for the day ahead, this doesn’t show up in openhab.log (but worth looking for errors) - but if you have linked static Items they’ll log a change in your events.log

BigGeorgeTx · November 19, 2021, 2:14pm

I do have a number of items linked to astro events. I see them update whether or not the channel triggers fire.

I was looking in the log around the time it should have fire.

I went back and looked at some DEBUG level logs at the time of the daily update from last month when I was trying to figure this out. It shows some activity that looks suspicious.

2021-10-04 12:52:37.558 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : BundleComponentActivator : ComponentHolder created.
2021-10-04 12:52:37.578 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : BundleComponentActivator : ComponentHolder created.
2021-10-04 12:52:37.583 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Dependency Manager created $000interface=org.openhab.core.scheduler.CronScheduler, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=0
2021-10-04 12:52:37.584 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Dependency Manager created $001interface=org.openhab.core.i18n.TimeZoneProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=1
2021-10-04 12:52:37.587 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Component created: DS=DS14, implementation=org.openhab.binding.astro.internal.AstroHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[binding.astro]
2021-10-04 12:52:37.588 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2021-10-04 12:52:37.590 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Component Properties: {}
2021-10-04 12:52:37.591 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Querying state disabled
2021-10-04 12:52:37.592 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Querying state disabled
2021-10-04 12:52:37.593 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Component can not be activated since it is in state disabled
2021-10-04 12:52:37.595 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory] : Querying state disabled
2021-10-04 12:52:37.596 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Updating target filters
2021-10-04 12:52:37.597 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : No change in target property for dependency $000: currently registered: false
2021-10-04 12:52:37.599 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] :  No existing service listener to unregister for dependency $000
2021-10-04 12:52:37.600 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Setting target property for dependency $000 to null
2021-10-04 12:52:37.601 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.scheduler.CronScheduler), initialReferenceFilter (objectClass=org.openhab.core.scheduler.CronScheduler)
2021-10-04 12:52:37.602 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $000 tracker reset (closed)
2021-10-04 12:52:37.604 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.scheduler.CronScheduler}={service.id=284, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.scheduler.CronSchedulerImpl, component.id=186} (enter)
2021-10-04 12:52:37.605 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2021-10-04 12:52:37.607 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.scheduler.CronScheduler}={service.id=284, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.scheduler.CronSchedulerImpl, component.id=186} (exit)
2021-10-04 12:52:37.608 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $000 tracker opened
2021-10-04 12:52:37.619 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : registering service listener for dependency $000
2021-10-04 12:52:37.620 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : No change in target property for dependency $001: currently registered: false
2021-10-04 12:52:37.622 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] :  No existing service listener to unregister for dependency $001
2021-10-04 12:52:37.623 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Setting target property for dependency $001 to null
2021-10-04 12:52:37.626 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : New service tracker for $001, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.i18n.TimeZoneProvider), initialReferenceFilter (objectClass=org.openhab.core.i18n.TimeZoneProvider)
2021-10-04 12:52:37.627 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $001 tracker reset (closed)
2021-10-04 12:52:37.633 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (enter)
2021-10-04 12:52:37.641 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $001 tracking 2 SingleStatic active: false trackerOpened: false optional: false
2021-10-04 12:52:37.642 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (exit)
2021-10-04 12:52:37.643 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : dm $001 tracker opened
2021-10-04 12:52:37.644 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : registering service listener for dependency $001
2021-10-04 12:52:37.645 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Changed state from disabled to unsatisfiedReference
2021-10-04 12:52:37.647 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Component enabled
2021-10-04 12:52:37.648 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : ActivateInternal
2021-10-04 12:52:37.670 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Querying state unsatisfiedReference
2021-10-04 12:52:37.671 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Querying state unsatisfiedReference
2021-10-04 12:52:37.672 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Activating component from state unsatisfiedReference
2021-10-04 12:52:37.674 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Querying state unsatisfiedReference
2021-10-04 12:52:37.675 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Querying state unsatisfiedReference
2021-10-04 12:52:37.677 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Changed state from unsatisfiedReference to satisfied
2021-10-04 12:52:37.678 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : registration change queue [registered]
2021-10-04 12:52:37.689 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Checking constructor public org.openhab.binding.astro.internal.AstroHandlerFactory(org.openhab.core.scheduler.CronScheduler,org.openhab.core.i18n.TimeZoneProvider)
2021-10-04 12:52:37.690 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : getReferenceClass: Looking for interface class org.openhab.core.scheduler.CronScheduler through loader of org.openhab.binding.astro.internal.AstroHandlerFactory
2021-10-04 12:52:37.691 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : getParameterClass: Found class org.openhab.core.scheduler.CronScheduler
2021-10-04 12:52:37.693 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : getReferenceClass: Looking for interface class org.openhab.core.i18n.TimeZoneProvider through loader of org.openhab.binding.astro.internal.AstroHandlerFactory
2021-10-04 12:52:37.694 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : getParameterClass: Found class org.openhab.core.i18n.TimeZoneProvider
2021-10-04 12:52:37.695 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Found constructor with 2 arguments : public org.openhab.binding.astro.internal.AstroHandlerFactory(org.openhab.core.scheduler.CronScheduler,org.openhab.core.i18n.TimeZoneProvider)
2021-10-04 12:52:37.696 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : This thread collected dependencies
2021-10-04 12:52:37.698 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : getService (single component manager) dependencies collected.
2021-10-04 12:52:37.711 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Querying state satisfied
2021-10-04 12:52:37.712 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Querying state satisfied
2021-10-04 12:52:37.713 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.scheduler.CronScheduler}={service.id=284, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.scheduler.CronSchedulerImpl, component.id=186}] service: [null]]]
2021-10-04 12:52:37.715 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]}] service: [null]]]
2021-10-04 12:52:37.725 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : getting activate: activate
2021-10-04 12:52:37.726 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Locating method activate in class org.openhab.binding.astro.internal.AstroHandlerFactory
2021-10-04 12:52:37.727 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Declared Method org.openhab.binding.astro.internal.AstroHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2021-10-04 12:52:37.729 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2021-10-04 12:52:37.730 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2021-10-04 12:52:37.731 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2021-10-04 12:52:37.734 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : invoked activate: activate
2021-10-04 12:52:37.735 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Set implementation object for component
2021-10-04 12:52:37.736 [DEBUG] [g.astro.internal.AstroHandlerFactory] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.AstroHandlerFactory(286)] : Changed state from satisfied to active
2021-10-04 12:52:37.740 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Dependency Manager created $000interface=org.openhab.core.i18n.LocationProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=0
2021-10-04 12:52:37.741 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Dependency Manager created $001interface=org.openhab.core.i18n.LocaleProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=1
2021-10-04 12:52:37.742 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Dependency Manager created $002interface=org.openhab.core.i18n.TranslationProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=2
2021-10-04 12:52:37.743 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Component created: DS=DS14, implementation=org.openhab.binding.astro.internal.discovery.AstroDiscoveryService, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[discovery.astro]
2021-10-04 12:52:37.744 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Component Services: scope=singleton, services=[org.openhab.core.config.discovery.DiscoveryService]
2021-10-04 12:52:37.745 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Component Properties: {}
2021-10-04 12:52:37.746 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Querying state disabled
2021-10-04 12:52:37.748 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Querying state disabled
2021-10-04 12:52:37.749 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Component can not be activated since it is in state disabled
2021-10-04 12:52:37.750 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService] : Querying state disabled
2021-10-04 12:52:37.751 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Updating target filters
2021-10-04 12:52:37.753 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : No change in target property for dependency $000: currently registered: false
2021-10-04 12:52:37.754 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] :  No existing service listener to unregister for dependency $000
2021-10-04 12:52:37.755 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Setting target property for dependency $000 to null
2021-10-04 12:52:37.757 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.i18n.LocationProvider), initialReferenceFilter (objectClass=org.openhab.core.i18n.LocationProvider)
2021-10-04 12:52:37.758 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $000 tracker reset (closed)
2021-10-04 12:52:37.761 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (enter)
2021-10-04 12:52:37.762 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2021-10-04 12:52:37.763 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (exit)
2021-10-04 12:52:37.765 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $000 tracker opened
2021-10-04 12:52:37.766 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : registering service listener for dependency $000
2021-10-04 12:52:37.767 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : No change in target property for dependency $001: currently registered: false
2021-10-04 12:52:37.768 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] :  No existing service listener to unregister for dependency $001
2021-10-04 12:52:37.769 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Setting target property for dependency $001 to null
2021-10-04 12:52:37.780 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : New service tracker for $001, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.i18n.LocaleProvider), initialReferenceFilter (objectClass=org.openhab.core.i18n.LocaleProvider)
2021-10-04 12:52:37.782 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle ```
 I will set the log level for the astro binding to DEBUG again and watch more closely and compare what I see when it is working after a reset to when it doesn't work again in the future.

Thanks for the guidance.

BigGeorgeTx · November 19, 2021, 2:14pm

Split log output due to maximum lines

org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $001 tracker reset (closed)
2021-10-04 12:52:37.784 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (enter)
2021-10-04 12:52:37.785 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $001 tracking 2 SingleStatic active: false trackerOpened: false optional: false
2021-10-04 12:52:37.787 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (exit)
2021-10-04 12:52:37.788 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $001 tracker opened
2021-10-04 12:52:37.789 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : registering service listener for dependency $001
2021-10-04 12:52:37.801 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : No change in target property for dependency $002: currently registered: false
2021-10-04 12:52:37.802 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] :  No existing service listener to unregister for dependency $002
2021-10-04 12:52:37.803 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Setting target property for dependency $002 to null
2021-10-04 12:52:37.804 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : New service tracker for $002, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.i18n.TranslationProvider), initialReferenceFilter (objectClass=org.openhab.core.i18n.TranslationProvider)
2021-10-04 12:52:37.805 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $002 tracker reset (closed)
2021-10-04 12:52:37.807 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $002 tracking 3 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (enter)
2021-10-04 12:52:37.809 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $002 tracking 3 SingleStatic active: false trackerOpened: false optional: false
2021-10-04 12:52:37.815 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $002 tracking 3 SingleStatic added {org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]} (exit)
2021-10-04 12:52:37.817 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : dm $002 tracker opened
2021-10-04 12:52:37.818 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : registering service listener for dependency $002
2021-10-04 12:52:37.819 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Changed state from disabled to unsatisfiedReference
2021-10-04 12:52:37.821 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Component enabled
2021-10-04 12:52:37.822 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : ActivateInternal
2021-10-04 12:52:37.823 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Querying state unsatisfiedReference
2021-10-04 12:52:37.825 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Querying state unsatisfiedReference
2021-10-04 12:52:37.826 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Activating component from state unsatisfiedReference
2021-10-04 12:52:37.827 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Querying state unsatisfiedReference
2021-10-04 12:52:37.828 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Querying state unsatisfiedReference
2021-10-04 12:52:37.829 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Changed state from unsatisfiedReference to satisfied
2021-10-04 12:52:37.830 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : registration change queue [registered]
2021-10-04 12:52:37.834 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Checking constructor public org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(org.openhab.core.i18n.LocationProvider,org.openhab.core.i18n.LocaleProvider,org.openhab.core.i18n.TranslationProvider,java.util.Map)
2021-10-04 12:52:37.835 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : getReferenceClass: Looking for interface class org.openhab.core.i18n.LocationProvider through loader of org.openhab.binding.astro.internal.discovery.AstroDiscoveryService
2021-10-04 12:52:37.836 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : getParameterClass: Found class org.openhab.core.i18n.LocationProvider
2021-10-04 12:52:37.837 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : getReferenceClass: Looking for interface class org.openhab.core.i18n.LocaleProvider through loader of org.openhab.binding.astro.internal.discovery.AstroDiscoveryService
2021-10-04 12:52:37.838 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : getParameterClass: Found class org.openhab.core.i18n.LocaleProvider
2021-10-04 12:52:37.839 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : getReferenceClass: Looking for interface class org.openhab.core.i18n.TranslationProvider through loader of org.openhab.binding.astro.internal.discovery.AstroDiscoveryService
2021-10-04 12:52:37.840 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : getParameterClass: Found class org.openhab.core.i18n.TranslationProvider
2021-10-04 12:52:37.841 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Found constructor with 4 arguments : public org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(org.openhab.core.i18n.LocationProvider,org.openhab.core.i18n.LocaleProvider,org.openhab.core.i18n.TranslationProvider,java.util.Map)
2021-10-04 12:52:37.842 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : This thread collected dependencies
2021-10-04 12:52:37.843 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : getService (single component manager) dependencies collected.
2021-10-04 12:52:37.844 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Querying state satisfied
2021-10-04 12:52:37.845 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Querying state satisfied
2021-10-04 12:52:37.846 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]}] service: [null]]]
2021-10-04 12:52:37.847 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]}] service: [null]]]
2021-10-04 12:52:37.849 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : For dependency $002, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.i18n.TranslationProvider, org.openhab.core.i18n.LocaleProvider, org.openhab.core.i18n.LocationProvider, org.openhab.core.i18n.TimeZoneProvider, org.openhab.core.i18n.UnitProvider}={location=30.093914214693438,-95.33740282058717, service.id=253, service.bundleid=154, service.scope=bundle, component.name=org.openhab.core.internal.i18n.I18nProviderImpl, language=en, service.config.label=Regional Settings, component.id=176, timezone=America/Chicago, service.config.category=system, region=US, service.config.description.uri=system:i18n, service.pid=[org.openhab.i18n, org.openhab.i18n]}] service: [null]]]
2021-10-04 12:52:37.880 [DEBUG] [rnal.discovery.AstroDiscoveryService] - Location has been changed from null to 30.093914214693438,-95.33740282058717: Creating new discovery results
2021-10-04 12:52:37.890 [DEBUG] [rnal.discovery.AstroDiscoveryService] - Scheduled astro location-changed job every 60 seconds
2021-10-04 12:52:37.891 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : getting activate: activate
2021-10-04 12:52:37.892 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Locating method activate in class org.openhab.binding.astro.internal.discovery.AstroDiscoveryService
2021-10-04 12:52:37.893 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Declared Method org.openhab.binding.astro.internal.discovery.AstroDiscoveryService.activate([interface org.osgi.service.component.ComponentContext]) not found
2021-10-04 12:52:37.894 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Locating method activate in class org.openhab.core.config.discovery.AbstractDiscoveryService
2021-10-04 12:52:37.895 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Declared Method org.openhab.core.config.discovery.AbstractDiscoveryService.activate([interface org.osgi.service.component.ComponentContext]) not found
2021-10-04 12:52:37.895 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Found activate method: protected void org.openhab.core.config.discovery.AbstractDiscoveryService.activate(java.util.Map)
2021-10-04 12:52:37.896 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.helper.ReadOnlyDictionary]
2021-10-04 12:52:37.898 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : invoked activate: activate
2021-10-04 12:52:37.899 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Set implementation object for component
2021-10-04 12:52:37.900 [DEBUG] [rnal.discovery.AstroDiscoveryService] - bundle org.openhab.binding.astro:3.1.0 (263)[org.openhab.binding.astro.internal.discovery.AstroDiscoveryService(287)] : Changed state from satisfied to active
2021-10-04 12:52:37.970 [DEBUG] [g.astro.internal.action.AstroActions] - Astro actions service instanciated
2021-10-04 12:52:38.049 [DEBUG] [o.internal.handler.AstroThingHandler] - Initializing thing astro:moon:local
2021-10-04 12:52:38.053 [DEBUG] [o.internal.handler.AstroThingHandler] - org.openhab.binding.astro.internal.config.AstroThingConfig@1e40ce9
2021-10-04 12:52:38.056 [DEBUG] [o.internal.handler.AstroThingHandler] - Restarting jobs for thing astro:moon:local
2021-10-04 12:52:38.057 [DEBUG] [o.internal.handler.AstroThingHandler] - Stopping scheduled jobs for thing astro:moon:local
2021-10-04 12:52:38.071 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled org.openhab.core.internal.scheduler.SchedulerImpl$ScheduledCompletableFutureRecurring@cb874a[Not completed, 2 dependents] at midnight
2021-10-04 12:52:38.148 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:local
2021-10-04 12:52:38.161 [DEBUG] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2021-10-04 12:52:38.465 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:moon:local/set#event/END in 19701817ms (at 2021-10-04T18:21:00)
2021-10-04 12:52:38.484 [DEBUG] [o.internal.handler.AstroThingHandler] - Thing astro:moon:local initialized ONLINE
2021-10-04 12:52:38.541 [DEBUG] [g.astro.internal.action.AstroActions] - Astro actions service instanciated
2021-10-04 12:52:38.614 [DEBUG] [o.internal.handler.AstroThingHandler] - Initializing thing astro:sun:local
2021-10-04 12:52:38.620 [DEBUG] [o.internal.handler.AstroThingHandler] - org.openhab.binding.astro.internal.config.AstroThingConfig@afeb9c
2021-10-04 12:52:38.623 [DEBUG] [o.internal.handler.AstroThingHandler] - Restarting jobs for thing astro:sun:local
2021-10-04 12:52:38.630 [DEBUG] [o.internal.handler.AstroThingHandler] - Stopping scheduled jobs for thing astro:sun:local
2021-10-04 12:52:38.650 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled org.openhab.core.internal.scheduler.SchedulerImpl$ScheduledCompletableFutureRecurring@15bcfbc[Not completed, 2 dependents] at midnight
2021-10-04 12:52:38.786 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:local
2021-10-04 12:52:38.840 [DEBUG] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2021-10-04 12:52:38.849 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/START in 22161152ms (at 2021-10-04T19:02:00)
2021-10-04 12:52:38.853 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/END in 22341148ms (at 2021-10-04T19:05:00)
2021-10-04 12:52:38.855 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/noon#event/START in 1101146ms (at 2021-10-04T13:11:00)
2021-10-04 12:52:38.864 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/noon#event/END in 1161136ms (at 2021-10-04T13:12:00)
2021-10-04 12:52:38.872 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/night#event/START in 27081130ms (at 2021-10-04T20:24:00)
2021-10-04 12:52:38.875 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/START in 25401125ms (at 2021-10-04T19:56:00)
2021-10-04 12:52:38.884 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/END in 27081117ms (at 2021-10-04T20:24:00)
2021-10-04 12:52:38.885 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/START in 23781115ms (at 2021-10-04T19:29:00)
2021-10-04 12:52:38.900 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/END in 25401100ms (at 2021-10-04T19:56:00)
2021-10-04 12:52:38.902 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/START in 22341098ms (at 2021-10-04T19:05:00)
2021-10-04 12:52:38.904 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/END in 23781096ms (at 2021-10-04T19:29:00)
2021-10-04 12:52:38.906 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/eveningNight#event/START in 27081094ms (at 2021-10-04T20:24:00)
2021-10-04 12:52:38.910 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/daylight#event/END in 22161090ms (at 2021-10-04T19:02:00)
2021-10-04 12:52:38.921 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/SUN_SET in 22161080ms (at 2021-10-04T19:02:00)
2021-10-04 12:52:38.924 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NIGHT in 27081077ms (at 2021-10-04T20:24:00)
2021-10-04 12:52:38.927 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/ASTRO_DUSK in 25401073ms (at 2021-10-04T19:56:00)
2021-10-04 12:52:38.929 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NAUTIC_DUSK in 23781071ms (at 2021-10-04T19:29:00)
2021-10-04 12:52:38.932 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/CIVIL_DUSK in 22341068ms (at 2021-10-04T19:05:00)
2021-10-04 12:52:38.937 [DEBUG] [o.internal.handler.AstroThingHandler] - Thing astro:sun:local initialized ONLINE
2021-10-04 12:52:39.015 [INFO ] [m

rossko57 · November 19, 2021, 2:23pm

sounds like Astro “master scheduler” is healthy then. This runs at bootup or about 5 seconds past midnight.

BigGeorgeTx · November 20, 2021, 4:19pm

for future reference, here are the openhab.log entries when everything is working:

2021-11-20 00:00:30.155 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:local
2021-11-20 00:00:30.163 [DEBUG] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2021-11-20 00:00:30.256 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/rise#event/START in 24689836ms (at 2021-11-20T06:52:00)
2021-11-20 00:00:30.257 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/rise#event/END in 24869743ms (at 2021-11-20T06:55:00)
2021-11-20 00:00:30.258 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/START in 62489742ms (at 2021-11-20T17:22:00)
2021-11-20 00:00:30.259 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/END in 62669741ms (at 2021-11-20T17:25:00)
2021-11-20 00:00:30.260 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/noon#event/START in 43709740ms (at 2021-11-20T12:09:00)
2021-11-20 00:00:30.261 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/noon#event/END in 43769739ms (at 2021-11-20T12:10:00)
2021-11-20 00:00:30.262 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/night#event/START in 67649738ms (at 2021-11-20T18:48:00)
2021-11-20 00:00:30.263 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/morningNight#event/START in -30263ms (at 2021-11-20T00:00:00)
2021-11-20 00:00:30.265 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/morningNight#event/END in 19709736ms (at 2021-11-20T05:29:00)
2021-11-20 00:00:30.266 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDawn#event/START in 19709735ms (at 2021-11-20T05:29:00)
2021-11-20 00:00:30.266 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDawn#event/END in 21449734ms (at 2021-11-20T05:58:00)
2021-11-20 00:00:30.267 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDawn#event/START in 21449733ms (at 2021-11-20T05:58:00)
2021-11-20 00:00:30.268 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDawn#event/END in 23189732ms (at 2021-11-20T06:27:00)
2021-11-20 00:00:30.269 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDawn#event/START in 23189731ms (at 2021-11-20T06:27:00)
2021-11-20 00:00:30.270 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDawn#event/END in 24689730ms (at 2021-11-20T06:52:00)
2021-11-20 00:00:30.272 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/START in 65909728ms (at 2021-11-20T18:19:00)
2021-11-20 00:00:30.273 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/END in 67649727ms (at 2021-11-20T18:48:00)
2021-11-20 00:00:30.274 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/START in 64169726ms (at 2021-11-20T17:50:00)
2021-11-20 00:00:30.275 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/END in 65909725ms (at 2021-11-20T18:19:00)
2021-11-20 00:00:30.276 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/START in 62669724ms (at 2021-11-20T17:25:00)
2021-11-20 00:00:30.277 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/END in 64169723ms (at 2021-11-20T17:50:00)
2021-11-20 00:00:30.278 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/eveningNight#event/START in 67649722ms (at 2021-11-20T18:48:00)
2021-11-20 00:00:30.279 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/daylight#event/START in 24869721ms (at 2021-11-20T06:55:00)
2021-11-20 00:00:30.280 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/daylight#event/END in 62489720ms (at 2021-11-20T17:22:00)
2021-11-20 00:00:30.281 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/SUN_RISE in 24689719ms (at 2021-11-20T06:52:00)
2021-11-20 00:00:30.282 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/SUN_SET in 62489718ms (at 2021-11-20T17:22:00)
2021-11-20 00:00:30.283 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NIGHT in 67649717ms (at 2021-11-20T18:48:00)
2021-11-20 00:00:30.284 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/DAYLIGHT in 24869716ms (at 2021-11-20T06:55:00)
2021-11-20 00:00:30.285 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/ASTRO_DAWN in 19709715ms (at 2021-11-20T05:29:00)
2021-11-20 00:00:30.285 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NAUTIC_DAWN in 21449715ms (at 2021-11-20T05:58:00)
2021-11-20 00:00:30.286 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/CIVIL_DAWN in 23189714ms (at 2021-11-20T06:27:00)
2021-11-20 00:00:30.287 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/ASTRO_DUSK in 65909713ms (at 2021-11-20T18:19:00)
2021-11-20 00:00:30.288 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NAUTIC_DUSK in 64169712ms (at 2021-11-20T17:50:00)
2021-11-20 00:00:30.289 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/CIVIL_DUSK in 62669712ms (at 2021-11-20T17:25:00)
2021-11-20 00:00:30.584 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:local
2021-11-20 00:00:30.586 [DEBUG] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2021-11-20 00:00:30.588 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:moon:local/rise#event/START in 66089412ms (at 2021-11-20T18:22:00)
2021-11-20 00:00:30.589 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:moon:local/set#event/END in 28649411ms (at 2021-11-20T07:58:00)
2021-11-20 00:00:30.591 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:moon:local/apogee#event/APOGEE in 72869409ms (at 2021-11-20T20:15:00)

BigGeorgeTx · November 21, 2021, 2:11pm

Once more, everything working

2021-11-21 00:00:30.154 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:local
2021-11-21 00:00:30.170 [DEBUG] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2021-11-21 00:00:30.171 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/rise#event/START in 24749829ms (at 2021-11-21T06:53:00)
2021-11-21 00:00:30.172 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/rise#event/END in 24929828ms (at 2021-11-21T06:56:00)
2021-11-21 00:00:30.174 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/START in 62489827ms (at 2021-11-21T17:22:00)
2021-11-21 00:00:30.175 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/END in 62609826ms (at 2021-11-21T17:24:00)
2021-11-21 00:00:30.176 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/noon#event/START in 43709824ms (at 2021-11-21T12:09:00)
2021-11-21 00:00:30.177 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/noon#event/END in 43769823ms (at 2021-11-21T12:10:00)
2021-11-21 00:00:30.178 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/night#event/START in 67649822ms (at 2021-11-21T18:48:00)
2021-11-21 00:00:30.180 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/morningNight#event/START in -30179ms (at 2021-11-21T00:00:00)
2021-11-21 00:00:30.181 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/morningNight#event/END in 19769819ms (at 2021-11-21T05:30:00)
2021-11-21 00:00:30.182 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDawn#event/START in 19769818ms (at 2021-11-21T05:30:00)
2021-11-21 00:00:30.183 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDawn#event/END in 21509817ms (at 2021-11-21T05:59:00)
2021-11-21 00:00:30.184 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDawn#event/START in 21509816ms (at 2021-11-21T05:59:00)
2021-11-21 00:00:30.185 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDawn#event/END in 23249815ms (at 2021-11-21T06:28:00)
2021-11-21 00:00:30.187 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDawn#event/START in 23249814ms (at 2021-11-21T06:28:00)
2021-11-21 00:00:30.188 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDawn#event/END in 24749813ms (at 2021-11-21T06:53:00)
2021-11-21 00:00:30.189 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/START in 65909811ms (at 2021-11-21T18:19:00)
2021-11-21 00:00:30.190 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/END in 67649810ms (at 2021-11-21T18:48:00)
2021-11-21 00:00:30.192 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/START in 64169809ms (at 2021-11-21T17:50:00)
2021-11-21 00:00:30.193 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/END in 65909808ms (at 2021-11-21T18:19:00)
2021-11-21 00:00:30.194 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/START in 62609807ms (at 2021-11-21T17:24:00)
2021-11-21 00:00:30.195 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/END in 64169806ms (at 2021-11-21T17:50:00)
2021-11-21 00:00:30.196 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/eveningNight#event/START in 67649805ms (at 2021-11-21T18:48:00)
2021-11-21 00:00:30.197 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/daylight#event/START in 24929803ms (at 2021-11-21T06:56:00)
2021-11-21 00:00:30.198 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/daylight#event/END in 62489802ms (at 2021-11-21T17:22:00)
2021-11-21 00:00:30.199 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Publish planet job astro:sun:local in 86369800ms (at 2021-11-21T23:59:59)
2021-11-21 00:00:30.200 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/SUN_RISE in 24749800ms (at 2021-11-21T06:53:00)
2021-11-21 00:00:30.201 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/SUN_SET in 62489799ms (at 2021-11-21T17:22:00)
2021-11-21 00:00:30.202 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NIGHT in 67649798ms (at 2021-11-21T18:48:00)
2021-11-21 00:00:30.203 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/DAYLIGHT in 24929797ms (at 2021-11-21T06:56:00)
2021-11-21 00:00:30.204 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/ASTRO_DAWN in 19769796ms (at 2021-11-21T05:30:00)
2021-11-21 00:00:30.205 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NAUTIC_DAWN in 21509796ms (at 2021-11-21T05:59:00)
2021-11-21 00:00:30.205 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/CIVIL_DAWN in 23249795ms (at 2021-11-21T06:28:00)
2021-11-21 00:00:30.206 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/ASTRO_DUSK in 65909794ms (at 2021-11-21T18:19:00)
2021-11-21 00:00:30.207 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NAUTIC_DUSK in 64169793ms (at 2021-11-21T17:50:00)
2021-11-21 00:00:30.208 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/CIVIL_DUSK in 62609792ms (at 2021-11-21T17:24:00)
2021-11-21 00:00:30.587 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:local
2021-11-21 00:00:30.591 [DEBUG] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2021-11-21 00:00:30.592 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:moon:local/rise#event/START in 68669408ms (at 2021-11-21T19:05:00)
2021-11-21 00:00:30.593 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:moon:local/set#event/END in 31889407ms (at 2021-11-21T08:52:00)

Now I will wait for it not to work.

BigGeorgeTx · December 18, 2021, 1:02am

A couple of weeks ago, I changed from the 3.1 release version to 3.2.5 Milestone version. I haven’t had any problems since then. If I do, I will report back.