OH3 events.log stays empty

[brononius (Ben)]

Just tried an update from 2.5.11 to 3 on Ubuntu 20.10. Based on the topic 'Guide: OH3 using APT". I’ve also purged all old stuff. At first sight, everything went fine. Update went without issues, openhab is started.

Openhab.log is giving updates as usual.
But events.log stay empty?

I downloaded the deb-package seperately, and restored the files in /var/lib/openhab/etc/*, but after restarting openhab, it stays empty.

My items seem to be working (knx, zwave nodes are acting as expected). But my rules aren’t reacting as well. But guess this is something else. First thing to get in order are the logs to debug…

Some info:

 /var/log/openhab/
-rw-r--r-- 1 openhab openhab      0 Dec 23 15:44 events.log
-rw-r--r-- 1 openhab openhab  32024 Dec 23 16:17 openhab.log

bundle:list
START LEVEL 100 , List Threshold: 50
 ID │ State  │ Lvl │ Version                 │ Name
────┼────────┼─────┼─────────────────────────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
 22 │ Active │  80 │ 2.10.3                  │ Jackson-annotations
 23 │ Active │  80 │ 2.10.3                  │ Jackson-core
 24 │ Active │  80 │ 2.10.3                  │ jackson-databind
 25 │ Active │  80 │ 2.10.3                  │ Jackson-dataformat-YAML
 26 │ Active │  80 │ 2.10.3                  │ Jackson datatype: JSR310
 27 │ Active │  80 │ 2.8.2.v20180104-1110    │ Gson: Google Json Library for Java
 28 │ Active │  80 │ 27.1.0.jre              │ Guava: Google Core Libraries for Java
 29 │ Active │  80 │ 1.0.1                   │ Guava InternalFutureFailureAccess and InternalFutures
 30 │ Active │  80 │ 3.0.0.v201312141243     │ Google Guice (No AOP)
 31 │ Active │  80 │ 4.8.35.v20190528-1517   │ ClassGraph
 32 │ Active │  80 │ 2.1.0                   │ swagger-annotations
 33 │ Active │  80 │ 2.1.0                   │ swagger-core
 34 │ Active │  80 │ 2.1.0                   │ swagger-integration
 35 │ Active │  80 │ 2.1.0                   │ swagger-jaxrs2
 36 │ Active │  80 │ 2.1.0                   │ swagger-models
 38 │ Active │  80 │ 3.5.6                   │ JmDNS
 39 │ Active │  80 │ 1.0.0                   │ Units of Measurement API
 41 │ Active │  80 │ 1.1.0.Final             │ Bean Validation API
 43 │ Active │  80 │ 0.5.10                  │ Jollyday
 44 │ Active │  80 │ 3.2.0.v201101311130     │ ANTLR Runtime
 45 │ Active │  80 │ 1.0.1                   │ Apache Aries JAX-RS Specification API
 46 │ Active │  80 │ 1.0.9                   │ Apache Aries JAX-RS Whiteboard
 48 │ Active │  80 │ 3.11.0                  │ Apache Commons Lang
 57 │ Active │  80 │ 4.2.7                   │ Apache Karaf :: OSGi Services :: Event
 68 │ Active │  80 │ 1.0.0.2                 │ Apache ServiceMix :: Bundles :: javax.inject
 72 │ Active │  80 │ 1.3.0.1                 │ Apache ServiceMix :: Specs :: Annotation API 1.3
 73 │ Active │  80 │ 2.3.0.3                 │ Apache ServiceMix :: Specs :: JAXWS API 2.3
 76 │ Active │  80 │ 4.14.0                  │ Apache XBean OSGI Bundle Utilities
 77 │ Active │  80 │ 4.14.0                  │ Apache XBean :: Classpath Resource Finder
 78 │ Active │  80 │ 0.7.0                   │ jose4j
 79 │ Active │  80 │ 2.17.0.v20190920-0401   │ EMF Common
 80 │ Active │  80 │ 2.20.0.v20190920-0401   │ EMF Ecore
 81 │ Active │  80 │ 2.14.0.v20190528-0725   │ EMF Change Model
 82 │ Active │  80 │ 2.16.0.v20190528-0725   │ EMF XML/XMI Persistence
 83 │ Active │  80 │ 3.10.400.v20190516-1504 │ Common Eclipse Runtime
112 │ Active │  80 │ 0.9.0.v20200229-1009    │ org.eclipse.lsp4j
113 │ Active │  80 │ 0.9.0.v20200229-1009    │ org.eclipse.lsp4j.jsonrpc
114 │ Active │  80 │ 2.23.0.v20200831-0723   │ Xtend Runtime Library
115 │ Active │  80 │ 2.23.0.v20200831-0723   │ Xtend Macro Interfaces
116 │ Active │  80 │ 2.23.0.v20200831-0730   │ Xtext
117 │ Active │  80 │ 2.23.0.v20200831-0745   │ Xtext Common Types
118 │ Active │  80 │ 2.23.0.v20200831-0730   │ Xtext IDE Core
119 │ Active │  80 │ 2.23.0.v20200831-0730   │ Xtext Utility
120 │ Active │  80 │ 2.23.0.v20200831-0745   │ Xbase Model
121 │ Active │  80 │ 2.23.0.v20200831-0745   │ Xbase Generic IDE Services
122 │ Active │  80 │ 2.23.0.v20200831-0723   │ Xbase Runtime Library
124 │ Active │  80 │ 7.1.0                   │ org.objectweb.asm
126 │ Active │  80 │ 7.1.0                   │ org.objectweb.asm.commons
127 │ Active │  80 │ 7.1.0                   │ org.objectweb.asm.tree
128 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Core
129 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Audio
130 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: JAAS Authentication
131 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: OAuth2Client
132 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Automation
133 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Automation Media Modules
134 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Automation Script Modules
135 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Automation Script RuleSupport
136 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Automation REST API
137 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Binding XML
138 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration Core
139 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration Discovery
140 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration mDNS Discovery
141 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration Dispatcher
142 │ Active │  75 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration XML
143 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Ephemeris
144 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: ID
145 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Console
146 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Console for OSGi runtime Karaf
147 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: HTTP Interface
148 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: HTTP Interface Authentication
150 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Monitor
151 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Network I/O
152 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: REST Interface
153 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Audio REST Interface
154 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Authentication Support for the REST Interface
155 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: REST Interface :: Core
156 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: REST mDNS Announcer
157 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Sitemap REST Interface
158 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: SSE Interface
159 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: REST Interface :: Swagger 1
160 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: UI REST Interface
161 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Voice REST Interface
162 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: mDNS Service
163 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Karaf Integration
164 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Core
165 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Items
166 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Item IDE
167 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Items Runtime
168 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Language Server
169 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Persistence
170 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Persistence IDE
171 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Persistence Runtime
172 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Rules
173 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Rule IDE
174 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Rules Runtime
175 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Script
176 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Script IDE
177 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Script Runtime
178 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Sitemap
179 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Sitemap IDE
180 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Sitemap Runtime
181 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Thing
182 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Thing IDE
183 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Model Thing Runtime
184 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Persistence
185 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Semantics
186 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: JSON Storage
187 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Thing
188 │ Active │  75 │ 3.0.0                   │ openHAB Core :: Bundles :: Thing XML
189 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Transformation Service
190 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: UI
191 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: UI Icon Support
192 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Voice
193 │ Active │  80 │ 3.0.0                   │ openHAB UI :: Bundles :: Main UI
200 │ Active │  80 │ 1.0.0.201802012106      │ org.osgi:org.osgi.service.jaxrs
201 │ Active │  80 │ 1.1.0.201802012106      │ org.osgi:org.osgi.util.function
202 │ Active │  80 │ 1.1.0.201802012106      │ org.osgi:org.osgi.util.promise
203 │ Active │  80 │ 1.5.0                   │ ThreeTen-Extra
204 │ Active │  80 │ 1.26.0                  │ SnakeYAML
205 │ Active │  80 │ 1.0.3                   │ Units of Measurement Common Library
206 │ Active │  80 │ 1.0.10                  │ Units of Measurement Implementation for Java SE
207 │ Active │  80 │ 1.4.13                  │ XStream Core
208 │ Active │  80 │ 2.20                    │ Dagger
209 │ Active │  80 │ 1.1.2                   │ hivemq-mqtt-client
210 │ Active │  80 │ 5.5.0                   │ jna
211 │ Active │  80 │ 5.5.0                   │ jna-platform
212 │ Active │  80 │ 1.6.2                   │ JavaMail API
213 │ Active │  80 │ 4.1.42.Final            │ Netty/Buffer
214 │ Active │  80 │ 4.1.42.Final            │ Netty/Codec
215 │ Active │  80 │ 4.1.42.Final            │ Netty/Codec/HTTP
216 │ Active │  80 │ 4.1.42.Final            │ Netty/Common
217 │ Active │  80 │ 4.1.42.Final            │ Netty/Handler
218 │ Active │  80 │ 4.1.42.Final            │ Netty/Resolver
219 │ Active │  80 │ 4.1.42.Final            │ Netty/Transport
220 │ Active │  80 │ 4.1.42.Final            │ Netty/Transport/Native/Epoll
221 │ Active │  80 │ 4.1.42.Final            │ Netty/Transport/Native/Unix/Common
222 │ Active │  80 │ 2.2.5                   │ rxjava
223 │ Active │  80 │ 1.0.0                   │ IO.Socket Engine Client
224 │ Active │  80 │ 1.0.0                   │ IO.Socket Socket Client
225 │ Active │  80 │ 20180813.0.0            │ JSON in Java
226 │ Active │  80 │ 5.2.1                   │ nrjavaserial
227 │ Active │  80 │ 1.10.0                  │ Apache Commons Codec
228 │ Active │  80 │ 2.2.0                   │ Commons IO
229 │ Active │  80 │ 2.6                     │ Commons Lang
230 │ Active │  80 │ 3.6.0                   │ Apache Commons Net
231 │ Active │  80 │ 4.5.5                   │ Apache Apache HttpClient OSGi bundle
232 │ Active │  80 │ 4.4.9                   │ Apache Apache HttpCore OSGi bundle
233 │ Active │  80 │ 3.8.1.1                 │ Apache ServiceMix :: Bundles :: okhttp
234 │ Active │  80 │ 1.13.0.1                │ Apache ServiceMix :: Bundles :: okio
235 │ Active │  80 │ 2.0.0                   │ Californium (Cf) Core
236 │ Active │  80 │ 2.0.0                   │ Californium (Cf) Element Connector
237 │ Active │  80 │ 2.0.0                   │ Californium (Cf) OSGi
238 │ Active │  80 │ 2.0.0                   │ Scandium (Sc) Core
239 │ Active │  80 │ 2.1.2                   │ Java Concurrency Tools Core Library
240 │ Active │  80 │ 2.5.2                   │ JUPnP Library
241 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Astro Binding
242 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Bosch Indego Binding
243 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Chromecast Binding
244 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Denon / Marantz Binding
245 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: DMX Binding
246 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Doorbird Binding
247 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Exec Binding
248 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Gardena Binding
249 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: HTTP Binding
250 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: IpCamera Binding
251 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: KNX Binding
252 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: LG webOS Binding
253 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Mail Binding
254 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: MQTT Broker Binding
255 │ Active │  81 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: MQTT Things and Channels
256 │ Active │  82 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: MQTT HomeAssistant Convention
257 │ Active │  82 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: MQTT Homie Convention
258 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Netatmo Binding
259 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Network Binding
260 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: NTP Binding
261 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: OpenWeatherMap Binding
262 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Pushover Binding
263 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Seneye Binding
264 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: SNMP Binding
265 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: SolarEdge Binding
266 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Spotify Binding
267 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Systeminfo Binding
268 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: TRÅDFRI Binding
269 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: WiFiLED Binding
270 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: ZoneMinder Binding
271 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: ZWave Binding
272 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration UPnP Discovery
273 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration USB-Serial Discovery
274 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration USB-Serial Discovery for Linux using sysfs scanning
275 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Configuration Serial
276 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: MQTT Transport
277 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Serial Transport
278 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Serial Transport for RXTX
279 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: Serial Transport for RFC2217
280 │ Active │  80 │ 3.0.0                   │ openHAB Core :: Bundles :: UPnP Transport
281 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: IO :: openHAB Cloud Connector
282 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Persistence Service :: InfluxDB
283 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Persistence Service :: MapDB
284 │ Active │  80 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Persistence Service :: RRD4j
285 │ Active │  75 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Transformation Service :: Exec
286 │ Active │  75 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Transformation Service :: JavaScript
287 │ Active │  75 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Transformation Service :: JSonPath
288 │ Active │  75 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Transformation Service :: Map
289 │ Active │  75 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Transformation Service :: RegEx
290 │ Active │  75 │ 3.0.0                   │ openHAB Add-ons :: Bundles :: Transformation Service :: Scale
291 │ Active │  80 │ 3.0.0                   │ openHAB UI :: Bundles :: Basic UI
292 │ Active │  80 │ 3.0.0                   │ openHAB UI :: Bundles :: HABPanel UI
293 │ Active │  80 │ 3.0.0                   │ openHAB UI :: Bundles :: Icon Set :: Classic
294 │ Active │  80 │ 1.0.2                   │ reactive-streams

Any idea where I should look?

ps this is a clone of my 2.5 machine. So no problem to startover.

[rlkoshak (Rich Koshak)]

What is the contents of your userdata/etc/log4j.xml file? There was a problem there at one point. I assume you are installing the release?

When you say “restored [useradata]/etc” do you mean you copied your OH 2 etc files over the ones installed by OH 3? If so that won’t work for everything. In particular the package names moved which impacts a lot of those settings. For logging, the config moved from org.ops4j.yadda.yadda.yadda.log4j.cfg to the previously mentioned log4j.xml.

Finally, you may not even need events.log. In MainUI there is a developer’s sidebar (if your screen is wide enough hit alt-shift-d to open it). There is an event stream there which you can filter by event type down to just certain Items you want to watch, or let it show you all the events of all types as they occur. In fact it’s a little more useful than events.log as it will show you updates and events.log will not.

[brononius (Ben)]

I’ve tried 3 things:

1. Normal update from OH2 to OH3
2. Copied the old cfg files from my OH2 working installation in the new one.
3. And copied the original cfg files from the install packaged (download openhab and unzipped with dpkg-deb -x).

This is the current content for log4jx.xml:

<?xml version="1.0" encoding="UTF-8" standalone="no"?><Configuration>

	<Appenders>
		<!-- Console appender not used by default (see Root logger AppenderRefs) -->
		<Console name="STDOUT">
			<PatternLayout pattern="%d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
		</Console>

		<!-- Rolling file appender -->
		<RollingFile fileName="${sys:openhab.logdir}/openhab.log" filePattern="${sys:openhab.logdir}/openhab.log.%i" name="LOGFILE">
			<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
			<Policies>
				<OnStartupTriggeringPolicy/>
				<SizeBasedTriggeringPolicy size="16 MB"/>
			</Policies>
		</RollingFile>

		<!-- Event log appender -->
		<RollingRandomAccessFile fileName="${sys:openhab.logdir}/events.log" filePattern="${sys:openhab.logdir}/events.log.%i" name="EVENT">
			<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
			<Policies>
				<OnStartupTriggeringPolicy/>
				<SizeBasedTriggeringPolicy size="16 MB"/>
			</Policies>
		</RollingRandomAccessFile>

		<!-- Audit file appender -->
		<RollingRandomAccessFile fileName="${sys:openhab.logdir}/audit.log" filePattern="${sys:openhab.logdir}/audit.log.%i" name="AUDIT">
			<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
			<Policies>
				<OnStartupTriggeringPolicy/>
				<SizeBasedTriggeringPolicy size="8 MB"/>
			</Policies>
		</RollingRandomAccessFile>

		<!-- OSGi appender -->
		<PaxOsgi filter="*" name="OSGI"/>
	</Appenders>

	<Loggers>
		<!-- Root logger configuration -->
		<Root level="WARN">
			<AppenderRef ref="LOGFILE"/>
			<AppenderRef ref="OSGI"/>
		</Root>

		<!-- Karaf Shell logger -->
		<Logger level="OFF" name="org.apache.karaf.shell.support">
			<AppenderRef ref="STDOUT"/>
		</Logger>

		<!-- Security audit logger -->
		<Logger additivity="false" level="INFO" name="org.apache.karaf.jaas.modules.audit">
			<AppenderRef ref="AUDIT"/>
		</Logger>

		<!-- openHAB specific logger configuration -->

		<Logger level="INFO" name="org.openhab"/>

		<Logger level="ERROR" name="openhab.event.ItemStateEvent"/>
		<Logger level="ERROR" name="openhab.event.ItemAddedEvent"/>
		<Logger level="ERROR" name="openhab.event.ItemRemovedEvent"/>
		<Logger level="ERROR" name="openhab.event.ItemChannelLinkAddedEvent"/>
		<Logger level="ERROR" name="openhab.event.ItemChannelLinkRemovedEvent"/>
		<Logger level="ERROR" name="openhab.event.ThingStatusInfoEvent"/>
		<Logger level="ERROR" name="openhab.event.ThingAddedEvent"/>
		<Logger level="ERROR" name="openhab.event.ThingUpdatedEvent"/>
		<Logger level="ERROR" name="openhab.event.ThingRemovedEvent"/>
		<Logger level="ERROR" name="openhab.event.InboxUpdatedEvent"/>
		<Logger level="ERROR" name="openhab.event.RuleStatusInfoEvent"/>
		<Logger level="ERROR" name="openhab.event.RuleAddedEvent"/>
		<Logger level="ERROR" name="openhab.event.RuleRemovedEvent"/>
		<Logger level="ERROR" name="openhab.event.StartlevelEvent"/>
		<Logger level="ERROR" name="openhab.event.AddonEvent"/>

		<Logger additivity="false" level="INFO" name="openhab.event">
			<AppenderRef ref="EVENT"/>
			<AppenderRef ref="OSGI"/>
		</Logger>

		<Logger level="ERROR" name="javax.jmdns"/>
		<Logger level="ERROR" name="org.jupnp"/>

		<!-- This suppresses all Maven download issues from the log when doing feature installations -->
		<!-- as we are logging errors ourselves in a nicer way anyhow. -->
		<Logger level="ERROR" name="org.ops4j.pax.url.mvn.internal.AetherBasedResolver"/>

		<!-- Filters known issues of pax-web (issue link to be added here). -->
		<!-- Can be removed once the issues are resolved in an upcoming version. -->
		<Logger level="OFF" name="org.ops4j.pax.web.pax-web-runtime"/>

		<!-- Filters known issues of lsp4j, see -->
		<!-- https://github.com/eclipse/smarthome/issues/4639 -->
		<!-- https://github.com/eclipse/smarthome/issues/4629 -->
		<!-- https://github.com/eclipse/smarthome/issues/4643 -->
		<!-- Can be removed once the issues are resolved in an upcoming version. -->
		<Logger level="OFF" name="org.eclipse.lsp4j"/>

		<!-- Filters warnings for events that could not be delivered to a disconnected client. -->
		<Logger level="ERROR" name="org.apache.cxf.jaxrs.sse.SseEventSinkImpl"/>

		<!-- Filters known issues of KarServiceImpl, see -->
		<!-- https://github.com/openhab/openhab-distro/issues/519#issuecomment-351944506 -->
		<!-- Can be removed once the issues are resolved in an upcoming version. -->
		<Logger level="ERROR" name="org.apache.karaf.kar.internal.KarServiceImpl"/>

		<!-- Filters warnings about unavailable ciphers when JCE is not installed, see -->
		<!-- https://github.com/openhab/openhab-distro/issues/999 -->
		<Logger level="ERROR" name="org.apache.karaf.shell.ssh.SshUtils"/>

		<!-- Filters known issues of javax.mail, see -->
		<!-- https://github.com/openhab/openhab-addons/issues/5530 -->
		<Logger level="ERROR" name="javax.mail"/>

		<!-- Added by Karaf to prevent debug logging loops, see -->
		<!-- https://issues.apache.org/jira/browse/KARAF-5559 -->
		<Logger level="WARN" name="org.apache.sshd"/>
	</Loggers>

</Configuration>root@doornroosje:/var/lib/openhab/etc# more log4j2.xml 
<?xml version="1.0" encoding="UTF-8" standalone="no"?><Configuration>

	<Appenders>
		<!-- Console appender not used by default (see Root logger AppenderRefs) -->
		<Console name="STDOUT">
			<PatternLayout pattern="%d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
		</Console>

		<!-- Rolling file appender -->
		<RollingFile fileName="${sys:openhab.logdir}/openhab.log" filePattern="${sys:openhab.logdir}/openhab.log.%i" name="LOGFILE">
			<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
			<Policies>
				<OnStartupTriggeringPolicy/>
				<SizeBasedTriggeringPolicy size="16 MB"/>
			</Policies>
		</RollingFile>

		<!-- Event log appender -->
		<RollingRandomAccessFile fileName="${sys:openhab.logdir}/events.log" filePattern="${sys:openhab.logdir}/events.log.%i" name="EVENT">
			<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
			<Policies>
				<OnStartupTriggeringPolicy/>
				<SizeBasedTriggeringPolicy size="16 MB"/>
			</Policies>
		</RollingRandomAccessFile>

		<!-- Audit file appender -->
		<RollingRandomAccessFile fileName="${sys:openhab.logdir}/audit.log" filePattern="${sys:openhab.logdir}/audit.log.%i" name="AUDIT">
			<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
			<Policies>
				<OnStartupTriggeringPolicy/>
				<SizeBasedTriggeringPolicy size="8 MB"/>
			</Policies>
		</RollingRandomAccessFile>

		<!-- OSGi appender -->
		<PaxOsgi filter="*" name="OSGI"/>
	</Appenders>

	<Loggers>
		<!-- Root logger configuration -->
		<Root level="WARN">
			<AppenderRef ref="LOGFILE"/>
			<AppenderRef ref="OSGI"/>
		</Root>

		<!-- Karaf Shell logger -->
		<Logger level="OFF" name="org.apache.karaf.shell.support">
			<AppenderRef ref="STDOUT"/>
		</Logger>

		<!-- Security audit logger -->
		<Logger additivity="false" level="INFO" name="org.apache.karaf.jaas.modules.audit">
			<AppenderRef ref="AUDIT"/>
		</Logger>

		<!-- openHAB specific logger configuration -->

		<Logger level="INFO" name="org.openhab"/>

		<Logger level="ERROR" name="openhab.event.ItemStateEvent"/>
		<Logger level="ERROR" name="openhab.event.ItemAddedEvent"/>
		<Logger level="ERROR" name="openhab.event.ItemRemovedEvent"/>
		<Logger level="ERROR" name="openhab.event.ItemChannelLinkAddedEvent"/>
		<Logger level="ERROR" name="openhab.event.ItemChannelLinkRemovedEvent"/>
		<Logger level="ERROR" name="openhab.event.ThingStatusInfoEvent"/>
		<Logger level="ERROR" name="openhab.event.ThingAddedEvent"/>
		<Logger level="ERROR" name="openhab.event.ThingUpdatedEvent"/>
		<Logger level="ERROR" name="openhab.event.ThingRemovedEvent"/>
		<Logger level="ERROR" name="openhab.event.InboxUpdatedEvent"/>
		<Logger level="ERROR" name="openhab.event.RuleStatusInfoEvent"/>
		<Logger level="ERROR" name="openhab.event.RuleAddedEvent"/>
		<Logger level="ERROR" name="openhab.event.RuleRemovedEvent"/>
		<Logger level="ERROR" name="openhab.event.StartlevelEvent"/>
		<Logger level="ERROR" name="openhab.event.AddonEvent"/>

		<Logger additivity="false" level="INFO" name="openhab.event">
			<AppenderRef ref="EVENT"/>
			<AppenderRef ref="OSGI"/>
		</Logger>

		<Logger level="ERROR" name="javax.jmdns"/>
		<Logger level="ERROR" name="org.jupnp"/>

		<!-- This suppresses all Maven download issues from the log when doing feature installations -->
		<!-- as we are logging errors ourselves in a nicer way anyhow. -->
		<Logger level="ERROR" name="org.ops4j.pax.url.mvn.internal.AetherBasedResolver"/>

		<!-- Filters known issues of pax-web (issue link to be added here). -->
		<!-- Can be removed once the issues are resolved in an upcoming version. -->
		<Logger level="OFF" name="org.ops4j.pax.web.pax-web-runtime"/>

		<!-- Filters known issues of lsp4j, see -->
		<!-- https://github.com/eclipse/smarthome/issues/4639 -->
		<!-- https://github.com/eclipse/smarthome/issues/4629 -->
		<!-- https://github.com/eclipse/smarthome/issues/4643 -->
		<!-- Can be removed once the issues are resolved in an upcoming version. -->
		<Logger level="OFF" name="org.eclipse.lsp4j"/>

		<!-- Filters warnings for events that could not be delivered to a disconnected client. -->
		<Logger level="ERROR" name="org.apache.cxf.jaxrs.sse.SseEventSinkImpl"/>

		<!-- Filters known issues of KarServiceImpl, see -->
		<!-- https://github.com/openhab/openhab-distro/issues/519#issuecomment-351944506 -->
		<!-- Can be removed once the issues are resolved in an upcoming version. -->
		<Logger level="ERROR" name="org.apache.karaf.kar.internal.KarServiceImpl"/>

		<!-- Filters warnings about unavailable ciphers when JCE is not installed, see -->
		<!-- https://github.com/openhab/openhab-distro/issues/999 -->
		<Logger level="ERROR" name="org.apache.karaf.shell.ssh.SshUtils"/>

		<!-- Filters known issues of javax.mail, see -->
		<!-- https://github.com/openhab/openhab-addons/issues/5530 -->
		<Logger level="ERROR" name="javax.mail"/>

		<!-- Added by Karaf to prevent debug logging loops, see -->
		<!-- https://issues.apache.org/jira/browse/KARAF-5559 -->
		<Logger level="WARN" name="org.apache.sshd"/>
	</Loggers>

</Configuration>

And my original org.ops4j.pax.logging.cfg

# Common pattern layout for appenders
#log4j2.pattern = %d{ISO8601} | %-5p | %-16t | %-32c{1} | %X{bundle.id} - %X{bundle.name} - %X{bundle.version} | %m%n

# Root logger
log4j2.rootLogger.level = WARN
log4j2.rootLogger.appenderRefs = out, osgi
log4j2.rootLogger.appenderRef.out.ref = LOGFILE
log4j2.rootLogger.appenderRef.osgi.ref = OSGI

# Karaf Shell logger
log4j2.logger.shell.name = org.apache.karaf.shell.support
log4j2.logger.shell.level = OFF
log4j2.logger.shell.appenderRefs = stdout
log4j2.logger.shell.appenderRef.stdout.ref = STDOUT

# Security audit logger
log4j2.logger.audit.name = org.apache.karaf.jaas.modules.audit
log4j2.logger.audit.level = INFO
log4j2.logger.audit.additivity = false
log4j2.logger.audit.appenderRefs = audit
log4j2.logger.audit.appenderRef.audit.ref = AUDIT

# openHAB specific logger configuration

log4j2.logger.openhab.name = org.openhab
log4j2.logger.openhab.level = INFO

log4j2.logger.smarthome.name = org.eclipse.smarthome
log4j2.logger.smarthome.level = INFO

log4j2.logger.smarthomeItemStateEvent.name = smarthome.event.ItemStateEvent
log4j2.logger.smarthomeItemStateEvent.level = ERROR
log4j2.logger.smarthomeItemAddedEvent.name = smarthome.event.ItemAddedEvent
log4j2.logger.smarthomeItemAddedEvent.level = ERROR
log4j2.logger.smarthomeItemRemovedEvent.name = smarthome.event.ItemRemovedEvent
log4j2.logger.smarthomeItemRemovedEvent.level = ERROR
log4j2.logger.smarthomeThingStatusInfoEvent.name = smarthome.event.ThingStatusInfoEvent
log4j2.logger.smarthomeThingStatusInfoEvent.level = ERROR
log4j2.logger.smarthomeThingAddedEvent.name = smarthome.event.ThingAddedEvent
log4j2.logger.smarthomeThingAddedEvent.level = ERROR
log4j2.logger.smarthomeThingRemovedEvent.name = smarthome.event.ThingRemovedEvent
log4j2.logger.smarthomeThingRemovedEvent.level = ERROR
log4j2.logger.smarthomeInboxUpdatedEvent.name = smarthome.event.InboxUpdatedEvent
log4j2.logger.smarthomeInboxUpdatedEvent.level = ERROR

log4j2.logger.events.name = smarthome.event
log4j2.logger.events.level = INFO
log4j2.logger.events.additivity = false
log4j2.logger.events.appenderRefs = event
log4j2.logger.events.appenderRef.event.ref = EVENT
log4j2.logger.events.appenderRef.osgi.ref = OSGI

log4j2.logger.jupnp.name = org.jupnp
log4j2.logger.jupnp.level = ERROR

log4j2.logger.jmdns.name = javax.jmdns
log4j2.logger.jmdns.level = ERROR

log4j2.logger.paperui.name = org.openhab.ui.paper
log4j2.logger.paperui.level = WARN
log4j2.logger.paperuiint.name = org.openhab.ui.paper.internal
log4j2.logger.paperuiint.level = INFO

# This suppresses all Maven download issues from the log when doing feature installations
# as we are logging errors ourselves in a nicer way anyhow.
log4j2.logger.paxurl.name = org.ops4j.pax.url.mvn.internal.AetherBasedResolver
log4j2.logger.paxurl.level = ERROR

# Filters known issues of pax-web (issue link to be added here).
# Can be removed once the issues are resolved in an upcoming version.
log4j2.logger.paxweb.name = org.ops4j.pax.web.pax-web-runtime
log4j2.logger.paxweb.level = OFF

# Filters known issues of lsp4j, see
# https://github.com/eclipse/smarthome/issues/4639
# https://github.com/eclipse/smarthome/issues/4629
# https://github.com/eclipse/smarthome/issues/4643
# Can be removed once the issues are resolved in an upcoming version.
log4j2.logger.lsp4j.name = org.eclipse.lsp4j
log4j2.logger.lsp4j.level = OFF

# Filters known issues of KarServiceImpl, see
# https://github.com/openhab/openhab-distro/issues/519#issuecomment-351944506
# Can be removed once the issues are resolved in an upcoming version.
log4j2.logger.karservice.name = org.apache.karaf.kar.internal.KarServiceImpl
log4j2.logger.karservice.level = ERROR

# Filters known issues of javax.mail, see
# https://github.com/openhab/openhab2-addons/issues/5530
log4j2.logger.javaxmail.name = javax.mail
log4j2.logger.javaxmail.level = ERROR

# Appenders configuration

# Console appender not used by default (see log4j2.rootLogger.appenderRefs)
log4j2.appender.console.type = Console
log4j2.appender.console.name = STDOUT
log4j2.appender.console.layout.type = PatternLayout
log4j2.appender.console.layout.pattern = %d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n

# Rolling file appender
log4j2.appender.out.type = RollingRandomAccessFile
log4j2.appender.out.name = LOGFILE
log4j2.appender.out.fileName = ${openhab.logdir}/openhab.log
log4j2.appender.out.filePattern = ${openhab.logdir}/openhab.log.%i
log4j2.appender.out.immediateFlush = true
log4j2.appender.out.append = true
log4j2.appender.out.layout.type = PatternLayout
log4j2.appender.out.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j2.appender.out.policies.type = Policies
log4j2.appender.out.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.out.policies.size.size = 16MB

# Event log appender
log4j2.appender.event.type = RollingRandomAccessFile
log4j2.appender.event.name = EVENT
log4j2.appender.event.fileName = ${openhab.logdir}/events.log
log4j2.appender.event.filePattern = ${openhab.logdir}/events.log.%i
log4j2.appender.event.immediateFlush = true
log4j2.appender.event.append = true
log4j2.appender.event.layout.type = PatternLayout
log4j2.appender.event.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-26.26c] - %m%n
log4j2.appender.event.policies.type = Policies
log4j2.appender.event.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.event.policies.size.size = 16MB

# Audit file appender
log4j2.appender.audit.type = RollingRandomAccessFile
log4j2.appender.audit.name = AUDIT
log4j2.appender.audit.fileName = ${openhab.logdir}/audit.log
log4j2.appender.audit.filePattern = ${openhab.logdir}/audit.log.%i
log4j2.appender.audit.append = true
log4j2.appender.audit.layout.type = PatternLayout
log4j2.appender.audit.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j2.appender.audit.policies.type = Policies
log4j2.appender.audit.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.audit.policies.size.size = 8MB

# OSGi appender
log4j2.appender.osgi.type = PaxOsgi
log4j2.appender.osgi.name = OSGI
log4j2.appender.osgi.filter = *
log4j2.logger.org_apache_sshd.level = ERROR
log4j2.logger.org_apache_sshd.name = org.apache.sshd
log4j2.logger.298.level = OFF
log4j2.logger.298.name = 298
log4j2.logger.org_openhab_binding_zwave.level = INFO
log4j2.logger.org_openhab_binding_zwave.name = org.openhab.binding.zwave
log4j2.logger.org_openhab_transform_exec.name = org.openhab.transform.exec
log4j2.logger.org_openhab_binding_gardena.name = org.openhab.binding.gardena
log4j2.logger.org_openhab_binding_seneye.level = INFO
log4j2.logger.org_openhab_binding_seneye.name = org.openhab.binding.seneye
log4j2.logger.org_openhab_binding_ipcamera.name = org.openhab.binding.ipcamera
log4j2.logger.211.level = OFF
log4j2.logger.211.name = 211
log4j2.logger.zwave-binding.level = DEBUG
log4j2.logger.zwave-binding.name = zwave-binding
log4j2.logger.304.level = DEFAULT
log4j2.logger.304.name = 304
log4j2.logger.org_openhab_persistence_influxdb.name = org.openhab.persistence.influxdb
log4j2.logger.222.level = OFF
log4j2.logger.222.name = 222
log4j2.logger.301.level = OFF
log4j2.logger.301.name = 301
log4j2.logger.org_openhab_binding_ipcamera.level = ERROR
log4j2.logger.org_openhab_binding_gardena.level = ERROR
log4j2.logger.340.level = DEBUG
log4j2.logger.340.name = 340
log4j2.logger.org_openhab_binding_homeconnect.level = ERROR
log4j2.logger.org_openhab_binding_homeconnect.name = org.openhab.binding.homeconnect

The logs are working ‘fine’ in the GUI interface as you described. But I prefer the good old cli way of working.

ps my rules aren’t working either. A simple test-button rule is not reacting. I can find it through the developper tool (items and rules), but it doesn’t log anything.
I just tried to add also a rule over the new GUI, and i’m getting errors like “Creation of the rule is refused: null”.
So I guess that my problem is bigger then just the log file.

[wborn (Wouter Born)]

See:

OH 3 no longer writes in "event.log"

There’s also a etc/org.ops4j.pax.logging.cfg file that should only contain the line: org.ops4j.pax.logging.log4j2.config.file=${karaf.etc}/log4j2.xml If you have rejected during the upgrade the suggested changes to that file by the package manager, then you may have also broken your logging configuration.

[brononius (Ben)]

At first sight, this is correct:

cat /var/lib/openhab/etc/org.ops4j.pax.logging.cfg

org.ops4j.pax.logging.log4j2.config.file=${karaf.etc}/log4j2.xml

ls -l /var/lib/openhab/etc/org.ops4j.pax.logging.cfg

-rw-r--r-- 1 openhab openhab 65 Dec 23 16:18 /var/lib/openhab/etc/org.ops4j.pax.logging.cfg

ls -l /var/lib/

...
drwxr-xr-x 20 openhab   openhab   4096 Dec 23 15:44 openhab
...

ls -l /var/log/

...
drwxr-xr-x  2 openhab   openhab    4096 Dec 24 08:37 openhab
...

Does these files handle events.log and openhab.log at the same time? I find it strange that openhab.log is working, and events.log not.

[wborn (Wouter Born)]

The org.ops4j.pax.logging.cfg tells PAX Logging to use log4j2.xml for configuring the logging.

The configuration in log4j2.xml is then used for constructing the EVENTS appender:

openhab/openhab-distro/blob/8554a73216e9251535f03d51d38a17a902393443/distributions/openhab/src/main/resources/userdata/etc/log4j2.xml#L18-L25

Which is used for appending all openhab.events logging:

openhab/openhab-distro/blob/8554a73216e9251535f03d51d38a17a902393443/distributions/openhab/src/main/resources/userdata/etc/log4j2.xml#L77-L80

Did you also try restarting openHAB?

[brononius (Ben)]

Several restarts have been done, the machine was fe down last night since I returned to 2.5.

I just did a complete new clone, and installation/upgrade. I’ve answered Y to everything. And I’m getting the same end result. items are working, openhab.log is working, event.log is not, and rules aren’t working.

See hereby the installation steps:

root@doornroosje:/openhab# sudo apt update
Hit:1 http://be.archive.ubuntu.com/ubuntu groovy InRelease
Get:2 http://be.archive.ubuntu.com/ubuntu groovy-updates InRelease [110 kB]                                                                                  
Get:3 http://be.archive.ubuntu.com/ubuntu groovy-backports InRelease [101 kB]                                                                                
Ign:4 https://dl.bintray.com/openhab/apt-repo2 stable InRelease                                                              
Get:5 http://be.archive.ubuntu.com/ubuntu groovy-security InRelease [110 kB]
Ign:6 http://repos.azulsystems.com/ubuntu stable InRelease                                           
Get:7 https://dl.bintray.com/openhab/apt-repo2 stable Release [6051 B]
Hit:8 http://repos.azulsystems.com/ubuntu stable Release                    
Hit:9 https://repos.azul.com/zulu/deb stable InRelease
Fetched 327 kB in 2s (156 kB/s)
Reading package lists... Done
Building dependency tree       
Reading state information... Done
All packages are up to date.
root@doornroosje:/openhab# apt install openhab
Reading package lists... Done
Building dependency tree       
Reading state information... Done
The following packages will be REMOVED:
  openhab2
The following NEW packages will be installed:
  openhab
0 upgraded, 1 newly installed, 1 to remove and 0 not upgraded.
Need to get 83.2 MB of archives.
After this operation, 829 kB disk space will be freed.
Do you want to continue? [Y/n] y
Get:1 https://dl.bintray.com/openhab/apt-repo2 stable/main amd64 openhab all 3.0.0-1 [83.2 MB]
Fetched 83.2 MB in 5s (16.8 MB/s)  
(Reading database ... 114244 files and directories currently installed.)
Removing openhab2 (2.5.11-1) ...
Selecting previously unselected package openhab.
(Reading database ... 113022 files and directories currently installed.)
Preparing to unpack .../openhab_3.0.0-1_all.deb ...
Unpacking openhab (3.0.0-1) ...
Setting up openhab (3.0.0-1) ...

Configuration file '/etc/openhab/services/runtime.cfg'
 ==> File on system created by you or by a script.
 ==> File also in package provided by package maintainer.
   What would you like to do about it ?  Your options are:
    Y or I  : install the package maintainer's version
    N or O  : keep your currently-installed version
      D     : show the differences between the versions
      Z     : start a shell to examine the situation
 The default action is to keep your current version.
*** runtime.cfg (Y/I/N/O/D/Z) [default=N] ? Y
Installing new version of config file /etc/openhab/services/runtime.cfg ...

Configuration file '/var/lib/openhab/etc/org.ops4j.pax.logging.cfg'
 ==> File on system created by you or by a script.
 ==> File also in package provided by package maintainer.
   What would you like to do about it ?  Your options are:
    Y or I  : install the package maintainer's version
    N or O  : keep your currently-installed version
      D     : show the differences between the versions
      Z     : start a shell to examine the situation
 The default action is to keep your current version.
*** org.ops4j.pax.logging.cfg (Y/I/N/O/D/Z) [default=N] ? Y
Installing new version of config file /var/lib/openhab/etc/org.ops4j.pax.logging.cfg ...

Configuration file '/var/lib/openhab/etc/users.properties'
 ==> File on system created by you or by a script.
 ==> File also in package provided by package maintainer.
   What would you like to do about it ?  Your options are:
    Y or I  : install the package maintainer's version
    N or O  : keep your currently-installed version
      D     : show the differences between the versions
      Z     : start a shell to examine the situation
 The default action is to keep your current version.
*** users.properties (Y/I/N/O/D/Z) [default=N] ? Y
Installing new version of config file /var/lib/openhab/etc/users.properties ...

Configuration file '/var/lib/openhab/etc/keystore'
 ==> File on system created by you or by a script.
 ==> File also in package provided by package maintainer.
   What would you like to do about it ?  Your options are:
    Y or I  : install the package maintainer's version
    N or O  : keep your currently-installed version
      D     : show the differences between the versions
      Z     : start a shell to examine the situation
 The default action is to keep your current version.
*** keystore (Y/I/N/O/D/Z) [default=N] ? Y
Installing new version of config file /var/lib/openhab/etc/keystore ...
[openHAB] Previous 2.x install detected, making necessary changes
[openHAB] Performing post-update tasks for version 3.0.0:
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/i18n.config to /var/lib/openhab/config/org/openhab/i18n.config
  Replacing: String org.eclipse.smarthome.i18n to org.openhab.i18n in file /var/lib/openhab/config/org/openhab/i18n.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/persistence.config to /var/lib/openhab/config/org/openhab/persistence.config
  Replacing: String org.eclipse.smarthome.persistence to org.openhab.persistence in file /var/lib/openhab/config/org/openhab/persistence.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/audio.config to /var/lib/openhab/config/org/openhab/audio.config
  Replacing: String org.eclipse.smarthome.audio to org.openhab.audio in file /var/lib/openhab/config/org/openhab/audio.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/voice.config to /var/lib/openhab/config/org/openhab/voice.config
  Replacing: String org.eclipse.smarthome.voice to org.openhab.voice in file /var/lib/openhab/config/org/openhab/voice.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/inbox.config to /var/lib/openhab/config/org/openhab/inbox.config
  Replacing: String org.eclipse.smarthome.inbox to org.openhab.inbox in file /var/lib/openhab/config/org/openhab/inbox.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/links.config to /var/lib/openhab/config/org/openhab/links.config
  Replacing: String org.eclipse.smarthome.links to org.openhab.links in file /var/lib/openhab/config/org/openhab/links.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/folder.config to /var/lib/openhab/config/org/openhab/folder.config
  Replacing: String org.eclipse.smarthome.folder to org.openhab.folder in file /var/lib/openhab/config/org/openhab/folder.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/threadpool.config to /var/lib/openhab/config/org/openhab/threadpool.config
  Replacing: String org.eclipse.smarthome.threadpool to org.openhab.threadpool in file /var/lib/openhab/config/org/openhab/threadpool.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/autoupdate.config to /var/lib/openhab/config/org/openhab/autoupdate.config
  Replacing: String org.eclipse.smarthome.autoupdate to org.openhab.autoupdate in file /var/lib/openhab/config/org/openhab/autoupdate.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/chart.config to /var/lib/openhab/config/org/openhab/chart.config
  Replacing: String org.eclipse.smarthome.chart to org.openhab.chart in file /var/lib/openhab/config/org/openhab/chart.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/lsp.config to /var/lib/openhab/config/org/openhab/lsp.config
  Replacing: String org.eclipse.smarthome.lsp to org.openhab.lsp in file /var/lib/openhab/config/org/openhab/lsp.config
  Moving:   From /var/lib/openhab/config/org/eclipse/smarthome/network.config to /var/lib/openhab/config/org/openhab/network.config
  Replacing: String org.eclipse.smarthome.network to org.openhab.network in file /var/lib/openhab/config/org/openhab/network.config
  Replacing: String org.eclipse.smarthome.core to org.openhab.core in file /var/lib/openhab/jsondb/automation_rules.json
  Replacing: String org.eclipse.smarthome to org.openhab.core in file /var/lib/openhab/jsondb/automation_rules.json
  Moving:   From /var/lib/openhab/jsondb/org.eclipse.smarthome.config.discovery.DiscoveryResult.json to /var/lib/openhab/jsondb/org.openhab.core.config.discovery.DiscoveryResult.json
  Replacing: String org.eclipse.smarthome.core to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.config.discovery.DiscoveryResult.json
  Replacing: String org.eclipse.smarthome to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.config.discovery.DiscoveryResult.json
  Moving:   From /var/lib/openhab/jsondb/org.eclipse.smarthome.core.items.Item.json to /var/lib/openhab/jsondb/org.openhab.core.items.Item.json
  Replacing: String org.eclipse.smarthome.core to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.items.Item.json
  Replacing: String org.eclipse.smarthome to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.items.Item.json
  Moving:   From /var/lib/openhab/jsondb/org.eclipse.smarthome.core.items.Metadata.json to /var/lib/openhab/jsondb/org.openhab.core.items.Metadata.json
  Replacing: String org.eclipse.smarthome.core to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.items.Metadata.json
  Replacing: String org.eclipse.smarthome to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.items.Metadata.json
  Moving:   From /var/lib/openhab/jsondb/org.eclipse.smarthome.core.thing.link.ItemChannelLink.json to /var/lib/openhab/jsondb/org.openhab.core.thing.link.ItemChannelLink.json
  Replacing: String org.eclipse.smarthome.core to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.thing.link.ItemChannelLink.json
  Replacing: String org.eclipse.smarthome to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.thing.link.ItemChannelLink.json
  Moving:   From /var/lib/openhab/jsondb/org.eclipse.smarthome.core.thing.Thing.json to /var/lib/openhab/jsondb/org.openhab.core.thing.Thing.json
  Replacing: String org.eclipse.smarthome.core to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.thing.Thing.json
  Replacing: String org.eclipse.smarthome to org.openhab.core in file /var/lib/openhab/jsondb/org.openhab.core.thing.Thing.json
  Deleting File: /var/lib/openhab/jsondb/org.eclipse.smarthome.core.thing.link.ItemThingLink.json
  Deleting Directory: /var/lib/openhab/config/org/eclipse/smarthome
  Deleting Directory: /var/lib/openhab/habmin
  Deleting Directory: /var/lib/openhab/config/com/eclipsesource
[openHAB] Please use the following commands to launch openHAB on a system restart.
            sudo /bin/systemctl daemon-reload
            sudo /bin/systemctl enable openhab.service

[openHAB] You can start openHAB manually by executing the command:
            sudo /bin/systemctl start openhab.service

Processing triggers for systemd (246.6-1ubuntu1) ...
root@doornroosje:/openhab# sudo /bin/systemctl daemon-reload
root@doornroosje:/openhab# sudo /bin/systemctl enable openhab.service
Created symlink /etc/systemd/system/multi-user.target.wants/openhab.service → /lib/systemd/system/openhab.service.
root@doornroosje:/openhab# sudo /bin/systemctl start openhab.service
root@doornroosje:/openhab# sudo /bin/systemctl status openhab.service
● openhab.service - openHAB - empowering the smart home
     Loaded: loaded (/lib/systemd/system/openhab.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 2020-12-24 10:29:13 CET; 5s ago
       Docs: https://www.openhab.org/docs/
             https://community.openhab.org
   Main PID: 5924 (java)
      Tasks: 64 (limit: 19130)
     Memory: 183.0M
     CGroup: /system.slice/openhab.service
             └─5924 /usr/bin/java -XX:-UsePerfData -Dopenhab.home=/usr/share/openhab -Dopenhab.conf=/etc/openhab -Dopenhab.runtime=/usr/share/openhab/runtime -Dopenhab.userdata=/var/lib/open>

Dec 24 10:29:13 doornroosje systemd[1]: Started openHAB - empowering the smart home.

The files are being created, but events.log stays empty. openhab.log is working as expected.
ls -l /var/log/openhab/

total 64
-rwxr-xr-x 1 openhab openhab     0 Dec 21 15:29 Readme.txt
-rw-r--r-- 1 openhab openhab     0 Dec 24 10:29 audit.log
-rw-r--r-- 1 openhab openhab     0 Dec 24 10:29 events.log
-rw-r--r-- 1 openhab openhab 58456 Dec 24 10:36 openhab.log

[wborn (Wouter Born)]

OK looks good to me. You also need some items that change from one state to another, otherwise events.log also remains empty because there is nothing to log.

[brononius (Ben)]

I’ve got 2165 items, so changes enough.

The GUI developper tool shows/streams nicely all changes.
But the events.log stays empty.

And I can work with direct items (buttons, lights…). So most binding/things/items are loaded.
But not over/through rules.

I’m getting somethings an error, not sure if it’s linked with this?

2020-12-24 10:46:22.851 [ERROR] [rg.apache.cxf.jaxrs.utils.JAXRSUtils] - Problem with writing the data, class org.openhab.core.io.rest.Stream2JSONInputStream, ContentType: application/json
2020-12-24 10:46:22.859 [WARN ] [ache.cxf.phase.PhaseInterceptorChain] - Interceptor for {http://resources.internal.rest.io.core.openhab.org/}SystemInfoResource has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Closed
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleWriteException(JAXRSOutInterceptor.java:396) ~[bundleFile:1.0.9]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:272) ~[bundleFile:1.0.9]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleWriteException(JAXRSOutInterceptor.java:398) ~[bundleFile:1.0.9]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:272) ~[bundleFile:1.0.9]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.processResponse(JAXRSOutInterceptor.java:122) ~[bundleFile:1.0.9]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleMessage(JAXRSOutInterceptor.java:84) ~[bundleFile:1.0.9]
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
	at org.apache.cxf.interceptor.OutgoingChainInterceptor.handleMessage(OutgoingChainInterceptor.java:90) [bundleFile:1.0.9]
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
	at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [bundleFile:1.0.9]
	at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:267) [bundleFile:1.0.9]
	at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) [bundleFile:1.0.9]
	at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) [bundleFile:1.0.9]
	at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) [bundleFile:1.0.9]
	at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:216) [bundleFile:1.0.9]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:301) [bundleFile:1.0.9]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:225) [bundleFile:1.0.9]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) [bundleFile:3.1.0]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:276) [bundleFile:1.0.9]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:544) [bundleFile:9.4.20.v20190813]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [bundleFile:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1581) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1307) [bundleFile:9.4.20.v20190813]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) [bundleFile:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:482) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1549) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1204) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [bundleFile:9.4.20.v20190813]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [bundleFile:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.Server.handle(Server.java:494) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:374) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]
	at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.eclipse.jetty.io.EofException: Closed
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:492) ~[bundleFile:9.4.20.v20190813]
	at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:51) ~[bundleFile:1.0.9]
	at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:60) ~[bundleFile:1.0.9]
	at org.openhab.core.io.rest.core.internal.GsonMessageBodyWriter.writeTo(GsonMessageBodyWriter.java:84) ~[?:?]
	at org.openhab.core.io.rest.core.internal.MediaTypeExtension.writeTo(MediaTypeExtension.java:84) ~[?:?]
	at org.apache.cxf.jaxrs.utils.JAXRSUtils.writeMessageBody(JAXRSUtils.java:1451) ~[bundleFile:1.0.9]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:246) ~[bundleFile:1.0.9]
	... 50 more

[wborn (Wouter Born)]

@brononius

I’ve got 2165 items, so changes enough.

Yes then there should definitely be some events to log!

You should also see the item state changes when you follow the logging on the Console with: log:tail

It should also report the following applied logging configuration:

openhab> log:list
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ WARN
javax.jmdns                                        │ ERROR
javax.mail                                         │ ERROR
openhab.event                                      │ INFO
openhab.event.AddonEvent                           │ ERROR
openhab.event.InboxUpdatedEvent                    │ ERROR
openhab.event.ItemAddedEvent                       │ ERROR
openhab.event.ItemChannelLinkAddedEvent            │ ERROR
openhab.event.ItemChannelLinkRemovedEvent          │ ERROR
openhab.event.ItemRemovedEvent                     │ ERROR
openhab.event.ItemStateEvent                       │ ERROR
openhab.event.RuleAddedEvent                       │ ERROR
openhab.event.RuleRemovedEvent                     │ ERROR
openhab.event.RuleStatusInfoEvent                  │ ERROR
openhab.event.StartlevelEvent                      │ ERROR
openhab.event.ThingAddedEvent                      │ ERROR
openhab.event.ThingRemovedEvent                    │ ERROR
openhab.event.ThingStatusInfoEvent                 │ ERROR
openhab.event.ThingUpdatedEvent                    │ ERROR
org.apache.cxf.jaxrs.sse.SseEventSinkImpl          │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.ssh.SshUtils                │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ WARN
org.eclipse.lsp4j                                  │ OFF
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF

[brononius (Ben)]

A bit the same result. In karaf, just getting the openhab.log messages. But nothing event related.

And my loglist from karaf:

openhab> 
log:list
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ WARN
javax.jmdns                                        │ ERROR
javax.mail                                         │ ERROR
openhab.event                                      │ INFO
openhab.event.AddonEvent                           │ ERROR
openhab.event.InboxUpdatedEvent                    │ ERROR
openhab.event.ItemAddedEvent                       │ ERROR
openhab.event.ItemChannelLinkAddedEvent            │ ERROR
openhab.event.ItemChannelLinkRemovedEvent          │ ERROR
openhab.event.ItemRemovedEvent                     │ ERROR
openhab.event.ItemStateEvent                       │ ERROR
openhab.event.RuleAddedEvent                       │ ERROR
openhab.event.RuleRemovedEvent                     │ ERROR
openhab.event.RuleStatusInfoEvent                  │ ERROR
openhab.event.StartlevelEvent                      │ ERROR
openhab.event.ThingAddedEvent                      │ ERROR
openhab.event.ThingRemovedEvent                    │ ERROR
openhab.event.ThingStatusInfoEvent                 │ ERROR
openhab.event.ThingUpdatedEvent                    │ ERROR
org.apache.cxf.jaxrs.sse.SseEventSinkImpl          │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.ssh.SshUtils                │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ WARN
org.eclipse.lsp4j                                  │ OFF
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF

And this is fe the developpers view:

[wborn (Wouter Born)]

That all looks fine.

It could also be a bug in the implementation of the OH3 start levels (openhab-core#1914).

In OH3 it will only start logging when active, see:

openhab/openhab-core/blob/ce95ed191e60da9c176047958f7f1bff1133912a/bundles/org.openhab.core.io.monitor/src/main/java/org/openhab/core/io/monitor/internal/EventLogger.java#L71-L78

So you could enable trace logging to see if the event passes through that logger.trace statement, e.g.

log:set trace openhab.event.ItemStateChangedEvent

If it shows the trace logging but not the info logging, it is most likely not active.

[brononius (Ben)]

@wborn

So you could enable trace logging to see if the event passes through that logger.trace statement, e.g.

log:set trace openhab.event.ItemStateChangedEvent

This generate logs in karaf and in events.log.
fe

11:35:47.828 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1426","oldType":"Decimal","oldValue":"1401"}'
11:35:48.829 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecB/statechanged' with payload: '{"type":"Decimal","value":"49117827","oldType":"Decimal","oldValue":"49117826"}'
11:35:48.839 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1433","oldType":"Decimal","oldValue":"1426"}'
11:35:49.828 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1426","oldType":"Decimal","oldValue":"1433"}'
11:35:50.230 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/GSM_Kwak_Time/statechanged' with payload: '{"type":"Decimal","value":"142.0","oldType":"Decimal","oldValue":"200.0"}'
11:35:50.844 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1407","oldType":"Decimal","oldValue":"1426"}'
11:35:51.828 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecB/statechanged' with payload: '{"type":"Decimal","value":"49117828","oldType":"Decimal","oldValue":"49117827"}'
11:35:51.838 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1384","oldType":"Decimal","oldValue":"1407"}'
11:35:52.826 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1383","oldType":"Decimal","oldValue":"1384"}'
11:35:53.836 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1371","oldType":"Decimal","oldValue":"1383"}'
11:35:54.828 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecB/statechanged' with payload: '{"type":"Decimal","value":"49117829","oldType":"Decimal","oldValue":"49117828"}'
11:35:54.838 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1365","oldType":"Decimal","oldValue":"1371"}'
11:35:55.827 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1372","oldType":"Decimal","oldValue":"1365"}'
11:35:56.831 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecB/statechanged' with payload: '{"type":"Decimal","value":"49117830","oldType":"Decimal","oldValue":"49117829"}'
11:35:56.838 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1361","oldType":"Decimal","oldValue":"1372"}'
11:35:57.826 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/fluksoElecA/statechanged' with payload: '{"type":"Decimal","value":"1369","oldType":"Decimal","oldValue":"1361"}'
11:35:58.447 [TRACE] [openhab.event.ItemStateChangedEvent  ] - Received event of type 'ItemStateChangedEvent' under the topic 'openhab/items/Waterput2a/statechanged' with payload: '{"type":"Decimal","value":"8.88","oldType":"Decimal","oldValue":"8.9"}'

[wborn (Wouter Born)]

What might help is to see if and when it reaches each start level when openHAB is started.

That can be seen after enabling the following debug logging:

log:set debug org.openhab.core.service

You probably want to disable the previous trace logging before restarting openHAB.

[brononius (Ben)]

I just gave it a try. N

log:list | grep core

org.openhab.core.service                           │ DEBUG

And after a restart of the service, this is my log.
I’ve erased some lines regarding item states and so. That’s a problem I need to tackle afterwards (I think).
It seems it won’t go further then “Reached start level 30”? Not sure what this means, but I’ve seen topics with level 80 and so?

root@doornroosje:/openhab# more log/openhab.log

2020-12-24 13:32:10.332 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Brussels'.
2020-12-24 13:32:10.362 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '50.91986260326823,3.644909913782613'.
2020-12-24 13:32:10.366 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'nl_BE'.
2020-12-24 13:32:10.368 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2020-12-24 13:32:10.574 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 10
2020-12-24 13:32:16.034 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'systeminfo.items'
2020-12-24 13:32:16.622 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ledstrips.items'
<knip> Loading items & rules </knip>
2020-12-24 13:33:14.163 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'speedtest.rules'
2020-12-24 13:33:15.321 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'speedtest.rules', using it anyway:
The constructor Float(String) is deprecated
The constructor Float(String) is deprecated
The constructor Float(String) is deprecated
2020-12-24 13:33:15.336 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'servers.rules'
2020-12-24 13:33:18.737 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-24 13:33:24.191 [INFO ] [org.openhab.ui.internal.UIService   ] - Started UI on port 8080
2020-12-24 13:33:24.868 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:moon:local every 300 seconds
2020-12-24 13:33:25.105 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:local every 300 seconds
2020-12-24 13:33:25.109 [WARN ] [rg.openhab.core.io.net.exec.ExecUtil] - Failed to execute commandLine '[arping, --help]'
2020-12-24 13:33:25.198 [WARN ] [rg.openhab.core.io.net.exec.ExecUtil] - Failed to execute commandLine '[arping, --help]'
2020-12-24 13:33:25.315 [INFO ] [ternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
2020-12-24 13:33:25.734 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 20
2020-12-24 13:33:25.863 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'openweathermap:onecall:9eb2bc5c:local' to inbox.
2020-12-24 13:33:25.895 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'openweathermap:onecall-history:9eb2bc5c:local' to inbox.
2020-12-24 13:33:26.526 [WARN ] [iscovery.TradfriDiscoveryParticipant] - Discovered Tradfri gateway doesn't have an IP address: [ServiceInfoImpl@612224172 name: 'gw-d44da43c1dd9._coap._udp.local
.' address: '(null):0' status: 'DNS: doornroosje-oniria-be.local. [doornroosje.oniria.be/192.168.222.10] state: probing 1 task: null', has NO data
        gw-d44da43c1dd9._coap._udp.local.: ]
2020-12-24 13:33:26.554 [ERROR] [rg.apache.cxf.jaxrs.utils.JAXRSUtils] - Problem with writing the data, class org.openhab.core.io.rest.Stream2JSONInputStream, ContentType: application/json
2020-12-24 13:33:26.628 [WARN ] [ache.cxf.phase.PhaseInterceptorChain] - Interceptor for {http://internal.id.core.openhab.org/}UUIDResource has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Closed
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleWriteException(JAXRSOutInterceptor.java:396) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:272) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleWriteException(JAXRSOutInterceptor.java:398) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:272) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.processResponse(JAXRSOutInterceptor.java:122) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleMessage(JAXRSOutInterceptor.java:84) ~[bundleFile:1.0.9]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
        at org.apache.cxf.interceptor.OutgoingChainInterceptor.handleMessage(OutgoingChainInterceptor.java:90) [bundleFile:1.0.9]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
        at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [bundleFile:1.0.9]
        at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:267) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:216) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:301) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:225) [bundleFile:1.0.9]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) [bundleFile:3.1.0]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:276) [bundleFile:1.0.9]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:544) [bundleFile:9.4.20.v20190813]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [bundleFile:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1581) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1307) [bundleFile:9.4.20.v20190813]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) [bundleFile:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:482) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1549) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1204) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [bundleFile:9.4.20.v20190813]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [bundleFile:?]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.Server.handle(Server.java:494) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:374) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.eclipse.jetty.io.EofException: Closed
        at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:492) ~[bundleFile:9.4.20.v20190813]
        at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:51) ~[bundleFile:1.0.9]
        at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:60) ~[bundleFile:1.0.9]
        at org.openhab.core.io.rest.core.internal.GsonMessageBodyWriter.writeTo(GsonMessageBodyWriter.java:84) ~[?:?]
        at org.openhab.core.io.rest.core.internal.MediaTypeExtension.writeTo(MediaTypeExtension.java:84) ~[?:?]
        at org.apache.cxf.jaxrs.utils.JAXRSUtils.writeMessageBody(JAXRSUtils.java:1451) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:246) ~[bundleFile:1.0.9]
        ... 45 more
2020-12-24 13:33:27.202 [WARN ] [amera.internal.onvif.OnvifConnection] - Binding could not determin the cameras current PTZ location. Not all cameras respond to GetStatus requests.
2020-12-24 13:33:27.361 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
        at org.openhab.binding.boschindego.internal.handler.BoschIndegoHandler.getStatusFromCommand(BoschIndegoHandler.java:205) ~[?:?]
        at org.openhab.binding.boschindego.internal.handler.BoschIndegoHandler.poll(BoschIndegoHandler.java:114) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2020-12-24 13:33:27.505 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid 4a6e3ef7-5d29-49cb-8c53-4ffe66908e10
2020-12-24 13:33:27.524 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.168.111.39' with clientid 1b95f2d1-9b28-4db0-9fe5-0863a0fbbd15
2020-12-24 13:33:27.770 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'snuffel' with clientid 9aac6aa1-42d5-48f6-8512-d58786e6c3ba
<knip>invalid states of items </knip>
2020-12-24 13:33:30.670 [ERROR] [org.openhab.core.items.GenericItem  ] - Tried to set invalid state 5140871.0 (DecimalType) on item Deur_Hobbitaire_LUDS of type StringItem, ignoring it
2020-12-24 13:33:30.714 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 30
2020-12-24 13:33:31.000 [ERROR] [org.openhab.core.items.GenericItem  ] - Tried to set invalid state 36593001 (DecimalType) on item Kogelkraan_Kelder_LUDS of type StringItem, ignoring it
2020-12-24 13:33:31.085 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2020-12-24 13:33:31.269 [ERROR] [org.openhab.core.items.GenericItem  ] - Tried to set invalid state 480869.0 (DecimalType) on item Sch_Beweging1_LUDS of type StringItem, ignoring it
2020-12-24 13:33:31.317 [ERROR] [org.openhab.core.items.GenericItem  ] - Tried to set invalid state 6704241.0 (DecimalType) on item Deur_Inkom_LUDS of type StringItem, ignoring it
<knip>invalid states of items </knip>
2020-12-24 13:33:37.833 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
2020-12-24 13:33:38.076 [WARN ] [.googletts.internal.GoogleTTSService] - Missing client id configuration to access Google Cloud TTS API.
2020-12-24 13:33:38.078 [WARN ] [.googletts.internal.GoogleTTSService] - Missing client secret configuration to access Google Cloud TTS API.
2020-12-24 13:33:38.801 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'tradfri:0820:gwd44da43c1dd9:65539' to inbox.
2020-12-24 13:33:38.838 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'tradfri:0820:gwd44da43c1dd9:65543' to inbox.
2020-12-24 13:33:41.564 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2020-12-24 13:33:41.565 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2020-12-24 13:33:41.605 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2020-12-24 13:33:41.605 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
<knip>some old/new (?) zwave itemss </knip>
2020-12-24 13:33:51.991 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:2f4ef5d0:node40' to inbox.
2020-12-24 13:33:52.138 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:30038385:node20' to inbox.
2020-12-24 13:33:52.143 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:2f4ef5d0:node65' to inbox.
2020-12-24 13:33:52.144 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:30038385:node38' to inbox.
2020-12-24 13:33:52.145 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:30038385:node43' to inbox.
2020-12-24 13:33:52.143 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:2f4ef5d0:node65' to inbox.
2020-12-24 13:33:52.144 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:30038385:node38' to inbox.
2020-12-24 13:33:52.145 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:30038385:node43' to inbox.
2020-12-24 13:33:52.150 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:2f4ef5d0:node48' to inbox.
2020-12-24 13:35:09.913 [WARN ] [ore.io.rest.auth.internal.AuthFilter] - Unauthorized API request: Invalid Basic authentication credentials
2020-12-24 13:35:41.097 [WARN ] [ore.io.rest.auth.internal.AuthFilter] - Unauthorized API request: Invalid Basic authentication credentials
2020-12-24 13:35:41.097 [WARN ] [ore.io.rest.auth.internal.AuthFilter] - Unauthorized API request: Invalid Basic authentication credentials
2020-12-24 13:35:59.093 [WARN ] [nx.internal.client.AbstractKNXClient] - Giving up reading datapoint 3/1/121, the number of maximum retries (3) is reached.
2020-12-24 13:36:09.162 [WARN ] [nx.internal.client.AbstractKNXClient] - Giving up reading datapoint 3/1/120, the number of maximum retries (3) is reached.
2020-12-24 13:36:19.231 [WARN ] [nx.internal.client.AbstractKNXClient] - Giving up reading datapoint 3/1/119, the number of maximum retries (3) is reached.
2020-12-24 13:36:29.301 [WARN ] [nx.internal.client.AbstractKNXClient] - Giving up reading datapoint 3/1/118, the number of maximum retries (3) is reached.
2020-12-24 13:38:26.600 [ERROR] [rg.apache.cxf.jaxrs.utils.JAXRSUtils] - Problem with writing the data, class org.openhab.core.io.rest.Stream2JSONInputStream, ContentType: application/json
2020-12-24 13:38:26.605 [WARN ] [ache.cxf.phase.PhaseInterceptorChain] - Interceptor for {http://internal.id.core.openhab.org/}UUIDResource has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Closed
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleWriteException(JAXRSOutInterceptor.java:396) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:272) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleWriteException(JAXRSOutInterceptor.java:398) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:272) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.processResponse(JAXRSOutInterceptor.java:122) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleMessage(JAXRSOutInterceptor.java:84) ~[bundleFile:1.0.9]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
        at org.apache.cxf.interceptor.OutgoingChainInterceptor.handleMessage(OutgoingChainInterceptor.java:90) [bundleFile:1.0.9]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [bundleFile:1.0.9]
        at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [bundleFile:1.0.9]
        at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:267) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:216) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:301) [bundleFile:1.0.9]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:225) [bundleFile:1.0.9]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) [bundleFile:3.1.0]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:276) [bundleFile:1.0.9]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:544) [bundleFile:9.4.20.v20190813]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [bundleFile:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1581) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1307) [bundleFile:9.4.20.v20190813]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) [bundleFile:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:482) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1549) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1204) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [bundleFile:9.4.20.v20190813]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [bundleFile:?]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.Server.handle(Server.java:494) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:374) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.eclipse.jetty.io.EofException: Closed
        at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:492) ~[bundleFile:9.4.20.v20190813]
        at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:51) ~[bundleFile:1.0.9]
        at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:60) ~[bundleFile:1.0.9]
        at org.openhab.core.io.rest.core.internal.GsonMessageBodyWriter.writeTo(GsonMessageBodyWriter.java:84) ~[?:?]
        at org.openhab.core.io.rest.core.internal.MediaTypeExtension.writeTo(MediaTypeExtension.java:84) ~[?:?]
        at org.apache.cxf.jaxrs.utils.JAXRSUtils.writeMessageBody(JAXRSUtils.java:1451) ~[bundleFile:1.0.9]
        at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:246) ~[bundleFile:1.0.9]
        ... 50 more      ```

[wborn (Wouter Born)]

@brononius

Not sure what this means, but I’ve seen topics with level 80 and so?

Yes it should go through all of the levels as defined in openhab#1914:

14:38:56.370 [DEBUG] [penhab.core.service.StartLevelService] - Reached start level 10
14:38:58.702 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
14:38:59.432 [INFO ] [org.openhab.ui.internal.UIService    ] - Started UI on port 8080
14:38:59.540 [INFO ] [hab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
14:39:01.372 [DEBUG] [penhab.core.service.StartLevelService] - Reached start level 20
14:39:06.374 [DEBUG] [penhab.core.service.StartLevelService] - Reached start level 30
14:39:06.375 [DEBUG] [penhab.core.service.StartLevelService] - Reached start level 40
14:39:06.375 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
14:39:11.374 [DEBUG] [penhab.core.service.StartLevelService] - Reached start level 50
14:39:11.376 [DEBUG] [penhab.core.service.StartLevelService] - Reached start level 70
14:39:11.377 [DEBUG] [penhab.core.service.StartLevelService] - Reached start level 80
14:39:11.379 [DEBUG] [penhab.core.service.StartLevelService] - Reached start level 100

The EventLogger only becomes active when level 40 is reached. Maybe you can test disabling some add-ons/rules to see if one is the culprit? If that doesn’t help posting a thread dump could show if a thread is being blocked somehow. Maybe @Kai has more tricks to debug such issues.

[brononius (Ben)]

OK, will remove some things from my setup:

1. I removed all my items, things, rules, persistence and service files.(except the cloudconnector).

2. I went into the GUI, and removed all bindings, transforms, misc… (except the cloudconnector).

3. I restarted the openhab server, but came to the same result (start level 30).
   In the GUI, I noticed that still some items/things were there. Through the GUI, I couldn’t delete them (Unsupported request method DELETE)

4. So I did a openhab-cli clean-cache. But items still in there?

5. After complete reboot of the machine, but still no luck.

Output of the last log: output.log (113.8 KB)

[brononius (Ben)]

After copying back the service/ephemeris.cfg and service/runtime.cfg, I’m getting a cleaner output:
But still stuck somewhere after 30.

==> log/openhab.log <==
2020-12-24 15:46:11.328 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '50.91986260326823,3.644909913782613'.
2020-12-24 15:46:11.330 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'nl_BE'.
2020-12-24 15:46:11.332 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2020-12-24 15:46:11.492 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 10
2020-12-24 15:46:17.537 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2020-12-24 15:46:20.505 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-12-24 15:46:21.505 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 20
2020-12-24 15:46:21.508 [DEBUG] [enhab.core.service.StartLevelService] - Reached start level 30
2020-12-24 15:46:23.169 [INFO ] [org.openhab.ui.internal.UIService   ] - Started UI on port 8080
2020-12-24 15:46:24.398 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = e9651dab-fec3-4d2b-964d-a24e2144610f, base URL = http://localhost:8080)

I’ve also removed the cloud connecter. But this didn’t solved it as well.

[tyler]

Hi! Been following this thread is it has mirrored the symptoms I’ve been experiencing exactly. namely,

• Events.log stays empty
• During Startup OpenHAB never seems to make it past “start level 30”

I was also experiencing an issue where trying to add in a rule through the UI would result in a “null” error.

I found something that might help. After following a lot of the troubleshooting steps above (remove old text config files, restart, etc.), I found that the /var/lib/openhab/jsondb/automation_rules.json file had a lot of data in there, while in the UI there were no rules listed. I checked the contents of that file and found what appeared to be a lot of the rules that I had attempted to make through the UI that had never “succeeded”. After doing these steps it seems to be working better:

1. Stop Open HAB service

2. Removed the automation rules file

3. Renamed the backups folder to oldBackups (jut in case I still needed that later, but to prevent OpenHAB from auto-restoring an old corrupted backup)

4. Started the OpenHAB service again

   sudo systemctl stop openhab
   sudo rm /var/lib/openhab/jsondb/automation_rules.json
   sudo mv /var/lib/openhab/jsondb/backups /var/lib/openhab/jsondb/oldBackups
   sudo systemctl start openhab

Now, OpenHAB reached start level 100 and I can create rules in the UI again. I haven’t fully tested everything, but it seems like it’s working better than before.

Hopefully this will help you out @brononius

[wborn (Wouter Born)]

@tyler

, I found that the /var/lib/openhab/jsondb/automation_rules.json file had a lot of data in there, while in the UI there were no rules listed.

Thanks for your input @tyler! Do you know how to reproduce that? It would be nice if we can prevent the broken rules from entering the file and make the core more robust so it logs some errors instead of not properly starting.