I just wanted to report that I updated to build #3404 and this is the first time I had a clean boot immediately after the upgrade since January. Kudos to all involved!
The only remaining nagging issue is still periodically and without any pattern I can discern yet the log config file gets set to an empty file still.
I’ve set up a cron watchdog that runs once a minute and sends me an email when it sees the file has changed to be an empty file and restores a backup. So far the only pattern I can see is that it seems to happen on the hour, but I think that’s because I screwed up the cron job (I was using 0 * * * * which I just realized on writing it here means minute 0 of the hour instead of every minute, doh!). But I’ve had it happen several times on one day and several days with no events. I’ll report when I can find out more.
For the curious, the script is:
#!/bin/bash
sendmail=/usr/sbin/sendmail
file=/srv/openhab/userdata/etc/org.ops4j.pax.logging.cfg
actualsize=$(wc -c <"$file")
dt=$(date)
if [ $actualsize -eq 0 ]; then
echo $file is zero length at $dt, restoring
email='rlkoshak@gmail.com'
to='To: '$email'\n'
from='From: '$email'\n'
subject='Subject: logger config zero length\n\n'
body=$dt
msg=${to}${from}${subject}${body}
echo -e "$msg" | $sendmail $email
cp $file.bak $file
fi
It assumes you have sendmail or something similar installed and configured (I use msmtp).
The crontab is:
* * * * * /home/rich/logfilewatcher.sh
I’m sure there are better ways to set up a watchdog on a file but this was quick and easy.
That’s a good idea. I’ll have to remember to do it again after a restart of the container because I believe the container runs a fix permissions on startup. It’s been a couple days since it last did it so who know how long it’ll take, if this even shows anything.
Edit: I can’t say if it’s the root cause but after making the file read only and going away for a bit I’m seeing the following spamming the log.
> 2023-04-12 12:52:33.774 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'sensor-status-detection' failed: org.osgi.service.cm.ReadOnlyConfigurationException: Configuration org.ops4j.pax.logging is read-only
However, that’s probably caused by a rogue rule where I had
which of course is going to want to write to the logging config (though I would have expected it to only care about log4j2.xml, not the pax config file. But it might point us in the right direction.
This rogue rule I have runs a lot (at least once per second, often more). I wonder if the rule triggers while it’s trying to set the logging level from a previous run if it gets interrupted and fails before it can rewrite the ops config file (which it shouldn’t be trying to write in the first place but that’s probably a question for Karaf, not us.
BTW: @florian-h05, the new search capability in the Developer Sidebar worked fantastically well to find all the rules where I have this line (I usually have it commented out).
When I install 4.0.0.202304130415 │ openHAB Add-ons :: Bundles :: Transformation Service :: RegEx
I get the following:
2023-04-13 15:46:11.693 [ERROR] [e.script.ScriptTransformationService] - bundle org.openhab.core.automation.module.script:4.0.0.202304100309 (160)[org.openhab.core.automation.module.script.ScriptTransformationService(95)] : The unsetScriptEngineFactory method has thrown an exception
java.lang.IndexOutOfBoundsException: Index 0 out of bounds for length 0
at jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:64) ~[?:?]
at jdk.internal.util.Preconditions.outOfBoundsCheckIndex(Preconditions.java:70) ~[?:?]
at jdk.internal.util.Preconditions.checkIndex(Preconditions.java:266) ~[?:?]
at java.util.Objects.checkIndex(Objects.java:359) ~[?:?]
at java.util.ArrayList.get(ArrayList.java:427) ~[?:?]
at java.util.Collections$UnmodifiableList.get(Collections.java:1347) ~[?:?]
at org.openhab.core.automation.module.script.internal.ScriptEngineFactoryHelper.getPreferredMimeType(ScriptEngineFactoryHelper.java:62) ~[?:?]
at org.openhab.core.automation.module.script.ScriptTransformationService.unsetScriptEngineFactory(ScriptTransformationService.java:275) ~[?:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:245) ~[?:?]
at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[?:?]
at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:687) ~[?:?]
at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:531) ~[?:?]
at org.apache.felix.scr.impl.inject.methods.BindMethod.invoke(BindMethod.java:42) ~[?:?]
at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:2212) ~[?:?]
at org.apache.felix.scr.impl.manager.DependencyManager.close(DependencyManager.java:1948) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:430) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:165) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.ungetService(SingleComponentManager.java:1043) ~[?:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$2.run(ServiceFactoryUse.java:273) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$2.run(ServiceFactoryUse.java:1) ~[org.eclipse.osgi-3.18.0.jar:?]
at java.security.AccessController.doPrivileged(AccessController.java:318) ~[?:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryUngetService(ServiceFactoryUse.java:270) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.ungetService(ServiceFactoryUse.java:167) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.ungetService(ServiceConsumer.java:53) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.ungetService(ServiceRegistrationImpl.java:632) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.ungetService(ServiceRegistry.java:613) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.framework.BundleContextImpl.ungetService(BundleContextImpl.java:703) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.apache.felix.scr.impl.manager.SingleRefPair.safeUngetService(SingleRefPair.java:109) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleRefPair.ungetServiceObjects(SingleRefPair.java:74) ~[?:?]
at org.apache.felix.scr.impl.manager.DependencyManager$AbstractCustomizer.ungetService(DependencyManager.java:231) ~[?:?]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:416) ~[?:?]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:304) ~[?:?]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1258) ~[?:?]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1152) ~[?:?]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:1012) ~[?:?]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1192) ~[?:?]
at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:116) ~[?:?]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:123) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:961) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:937) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:874) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:241) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:952) ~[?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:915) ~[?:?]
at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:140) ~[?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:994) ~[?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:844) ~[?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:825) ~[?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:589) ~[?:?]
at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:722) ~[?:?]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:492) ~[?:?]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:652) ~[?:?]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:74) ~[?:?]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:490) ~[?:?]
at org.apache.felix.scr.impl.AbstractExtender$1.run(AbstractExtender.java:216) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at org.apache.felix.scr.impl.AbstractExtender.destroyExtension(AbstractExtender.java:238) ~[?:?]
at org.apache.felix.scr.impl.AbstractExtender.bundleChanged(AbstractExtender.java:132) ~[?:?]
at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:255) ~[?:?]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:949) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:229) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:138) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:130) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:217) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:499) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.container.Module.doStop(Module.java:658) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.container.Module.stop(Module.java:521) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:472) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.apache.karaf.features.internal.service.BundleInstallSupportImpl.stopBundle(BundleInstallSupportImpl.java:171) ~[?:?]
at org.apache.karaf.features.internal.service.FeaturesServiceImpl.stopBundle(FeaturesServiceImpl.java:1165) ~[?:?]
at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:783) ~[?:?]
at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1069) ~[?:?]
at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:1004) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
at java.lang.Thread.run(Thread.java:833) ~[?:?]
openHAB then restarts but the GUI etc does not run properly, so requires an additional restart to get back to running.
When this happened earlier, I actually lost/corrupted the automation_rules.json and I battled to get a running system, which is why I know it happens each time from a running state.
If I uninstall and re-install again, it does not seem to happen?
I have tested a couple of times on a “test” machine on Windows 11
I’m experimenting with the new support for defining transformations in the UI.
Once you create a transformation in the UI: Settings → Transformations take note of the UID. This ID will likely follow this format:
config:<transform type>:<name>:<language>
where <transform> is the name of the transform to use (e.g. map, js, jinja, etc.), <name> is your what you provided, and <language> is an optional two letter code for the spoken language (not programming language (e.g. en, de, etc.).
For example, I’ve a map transform I use to translate the three possible LWT messages to the online/offline status for the MQTT Thing. It’s ID is config:map:waveplus.
When using that transform in various places, you must use the full ID in place of what we used to be the filename. So for example, if you had MAP(waveplus.map) or if in the MQTT or HTTP add-ons MAP:waveplus.map you would use MAP(config:map:waveplus) or in the MQTT or HTTP add-ons MAP:config:map:waveplus.
It took me a bit to work that out.
Also, be aware that my understanding is the interface to SCRIPT has changed and now it uses the language as the ID. This means as long as one of the JS add-ons are installed, the original JS(myfile.js) will continue to work so users will not need to update their syntax to work with OH 4.
That’s a good summary, and yes, JS is back and as long as you don’t use any language features that are available in Nashorn but not in Graal (I must admit, I’m not even sure if such a feature exists), all profiles and transformations will work.
Given the nature of transformations and the lack of openHAB injecting a bunch of stuff into them like it does with rules, I’m comfortable saying that any JS transform written for Nashorn will work with GraalVM unchanged.
Ideally we should be able to just say MAP(waveplus) orMAP(config:waveplus) (to differentiate from file resource) but that would just create confusion I guess.
I am currently working on adjusting the transformation editor to recent core changes (SCRIPT transformation) and I took the chance to add a note to the transformation editor that says:
Tip: Use JINJA(config:jinja:jinja) for Item state transformations. and provides a clipboard icon to directly copy JINJA(…) to clipboard.
I’m up and running on #3455 and I’m starting to see periodically a new warning from rrd4j.
2023-05-11 09:41:31.054 [WARN ] [d4j.internal.RRD4jPersistenceService] - Could not persist 'Dads_Motion_Timeout' to rrd4j database: Bad sample time: 1683819690. Last update time was 1683819690, at least one second step is require
Now, this could be related to a time problem. When I rebuilt my VM recently OH was running for a little bit using the wrong timezone. I’ve since fixed that problem but there was likely some data stored with a bad timestamp because of that. I only mention that in case it’s relevant.
However, the Item it’s complaining about above was never saved when the timezone was bad. So this warning is not caused by the timezone issue.
Also, what’s weird is that the sample time and last update time are the same.
The warning doesn’t occur every time the Item changes or every time the state is persisted. I can’t quite find the pattern. I can say that the warning above occurred the very first time the Item received a non-NULL state but not anytime after that (so far).
But I’ve updated other Items from NULL to another state and not received the warning.
This might be related to the latest refactoring to prevent performance problems in persistence. It would be great if you could come up with a way to reproduce that (a good chance, like 1 out of 10 would be sufficient).
I confirm I saw the same appearing from time to time since some days. As stated by @J-N-K , I suspected it to be related to persistance refactoring that took place past week.
Yes, working on something. Maybe if I can set up a loop to spam a test Item with changes I can force it.
I’m now on #3459 which seems to now have the new units and I’m fighting some weirdness there. Apparently Bq/m³ isn’t supported anymore (I’d rather use pCi/L anyway but that’s never been supported)?
It also doesn’t like my date time format string pattern for Number:Time Items any more.
2023-05-12 08:08:37.892 [ERROR] [rg.openhab.core.types.util.UnitUtils] - Unknown unit from pattern: %1$tH:%1$tM:%1$tS
If possible it would be nice if that error from UnitUtils would report the Item name too, though I’ve only got one Item that do this so I know what Item it is. Others might not be so lucky. Though you can use the developer sidebar now to search in metadata so searching for “%1$tH:%1$tM:%1$tS” will find the Items with that pattern in metadata.
I’m also seeing errors from some units that should be a problem, like:
2023-05-12 08:15:47.898 [ERROR] [rg.openhab.core.types.util.UnitUtils] - Unknown unit from pattern: ॰F
I’ve not tried the upgrade cli tool yet though. I did add Bq/m³ as a new unit metadata just to see what would happen and it still doesn’t like it.
More to follow once I run the upgrade tool to see what happens.
What dimension do you use for Bq/m3? I don’t think we have something that fits „specific activity“. In that case you can use a plain number item and put the unit in the state description (but lose UoM support),
If that is a common use-case, we can add a dimension for that.
Regarding the Fahrenheit error: it seems the the character before the F is not correct. Can you check that?
It was never listed as being officially supported but I tried it once just to see if it would work given units like W/m² exist in the docs. Surprisingly it seemed to work!
Note, they way I’ve implemented it was:
Added Bq/m³ as the unit in the MQTT Channel Config.
- id: radon_st
channelTypeUID: mqtt:number
label: Short Term Radon Average
description: ""
configuration:
stateTopic: waveplus_bridge/basement/radon_st
unit: Bq/m³
Set the State Description Pattern to %.0f Bq/m³.
I tried to add a transform to convert it to pCi/L but found that unit isn’t supported at all. I essentially did it the same as described above but Bq is the only supported unit for Radioactivity and it wasn’t important enough to me to file an issue. It’s just kind of annoying that the AirThings Wave+ shows in the app pCi/L but actually reports over the BTLE Bq/m³ for some reason.
I’ll definitely find a workaround, even if it’s to just revert to a unitless Number and just use the State Description (at which point I’ll add back in that transform).
But I might not be the only person using a slightly off the books unit that used to work but may no longer work.
I live over granite. As granite decomposes it releases radon which can cause lung cancer if the levels are high enough for long enough (before mitigation we were seeing levels around 4 pCi/l/100 Bq/m³. I have radon detectors to help keep track of the level and ensure that our mitigation is working (it’s basically a fan that sucks the air from under the foundation and vents it above the roof) and OH alerts me if there’s a problem.
A quick question about the upgrade tool. Does OH need to be stopped before running it or can it work on a running OH instance? I’ll add a note to the docs either way.
