Lost In a soup of logs :S

CraigDubya · June 19, 2020, 7:23pm

Hi, I’m hoping someone could point me in the direction of gaining more relevant information from my system to enable others to help with my problem. As far as I’m aware I hadn’t changed anything, then all of a sudden my logs started to go crazy and everything from paperui to basicui started to get very intermittent.

20:18:00.101 [INFO ] [.internal.service.FeaturesServiceImpl] - No deployment change.
20:18:00.106 [INFO ] [.internal.service.FeaturesServiceImpl] - Stopping bundles:
20:18:00.110 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.io.openhabcloud/2.5.5
20:18:00.130 [INFO ] [.io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
20:18:00.155 [INFO ] [.io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 05df193b-8601-4a14-9420-0a2535dea638, base URL = http://localhost:8080)
20:18:00.181 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.rest.optimize/2.5.0
20:18:00.202 [INFO ] [.internal.service.FeaturesServiceImpl] -   javax.ws.rs-api/2.0.1
20:18:00.218 [INFO ] [.internal.service.FeaturesServiceImpl] -   com.eclipsesource.jaxrs.publisher/5.3.1.201602281253
20:18:00.433 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Unbinding bundle: [com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [19]]
20:18:00.437 [INFO ] [ice.jetty.internal.HttpServiceContext] - ServletContext service already removed
20:18:00.442 [INFO ] [e.jetty.server.handler.ContextHandler] - Stopped HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [19], contextID=default]}
20:18:00.456 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.ui.iconset.classic/2.5.5
20:18:00.501 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.ui.habpanel/2.5.5
20:18:00.528 [INFO ] [bpanel.internal.HABPanelDashboardTile] - Stopped HABPanel
20:18:00.533 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Unbinding bundle: [org.openhab.ui.habpanel_2.5.5 [265]]
20:18:00.542 [INFO ] [e.jetty.server.handler.ContextHandler] - Stopped HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.5.5 [265], contextID=default]}
20:18:00.602 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.ui.basic/2.5.5
20:18:00.673 [INFO ] [.basic.internal.servlet.WebAppServlet] - Stopped Basic UI
20:18:00.714 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Unbinding bundle: [org.openhab.ui.basic_2.5.5 [264]]
20:18:00.722 [INFO ] [e.jetty.server.handler.ContextHandler] - Stopped HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.5 [264], contextID=custom]}
20:18:00.734 [INFO ] [e.jetty.server.handler.ContextHandler] - Stopped HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.5 [264], contextID=custom]}
20:18:00.758 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.ui.icon/2.5.0
20:18:00.793 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Unbinding bundle: [org.openhab.core.ui.icon_2.5.0 [191]]
20:18:00.803 [INFO ] [e.jetty.server.handler.ContextHandler] - Stopped HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core.ui.icon_2.5.0 [191], contextID=default]}
20:18:00.832 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.rest.voice/2.5.0
20:18:00.842 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sensor_CPUTemp changed from 73.1 to 73.6
20:18:00.856 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.rest.sse/2.5.0
20:18:00.883 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.rest.sitemap/2.5.0
20:18:00.916 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.rest.core/2.5.0
20:18:01.105 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.rest.audio/2.5.0
20:18:01.131 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.io.rest/2.5.0
20:18:01.186 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.openhab.core.id/2.5.0
20:18:01.203 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.jersey.media.jersey-media-sse/2.22.2
20:18:01.218 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.jersey.media.jersey-media-multipart/2.22.2
20:18:01.230 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.jersey.core.jersey-server/2.22.2
20:18:01.269 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.jersey.core.jersey-common/2.22.2
20:18:01.298 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.jersey.core.jersey-client/2.22.2
20:18:01.311 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.jersey.containers.jersey-container-servlet-core/2.22.2
20:18:01.324 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.jersey.containers.jersey-container-servlet/2.22.2
20:18:01.333 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.hk2.utils/2.4.0.b34
20:18:01.345 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.hk2.locator/2.4.0.b34
20:18:01.357 [INFO ] [.internal.service.FeaturesServiceImpl] -   org.glassfish.hk2.api/2.4.0.b34
20:18:01.408 [INFO ] [.internal.service.FeaturesServiceImpl] - Refreshing bundles:
20:18:01.413 [INFO ] [.internal.service.FeaturesServiceImpl] -     com.eclipsesource.jaxrs.publisher/5.3.1.201602281253 (Wired to org.glassfish.jersey.core.jersey-common/2.22.2 which is being refreshed)
20:18:01.417 [INFO ] [.internal.service.FeaturesServiceImpl] -     javax.ws.rs-api/2.0.1 (Wired to org.glassfish.jersey.core.jersey-server/2.22.2 which is being refreshed)
20:18:01.420 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.hk2.api/2.4.0.b34 (Wired to org.glassfish.hk2.utils/2.4.0.b34 which is being refreshed)
20:18:01.424 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.hk2.locator/2.4.0.b34 (Wired to org.glassfish.hk2.api/2.4.0.b34 which is being refreshed)
20:18:01.429 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.hk2.utils/2.4.0.b34 (Should be wired to: org.eclipse.osgi/3.12.100.v20180210-1608 (through [org.glassfish.hk2.utils/2.4.0.b34] osgi.wiring.package; filter:="(osgi.wiring.package=javax.annotation)"))
20:18:01.433 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.jersey.containers.jersey-container-servlet/2.22.2 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.436 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.jersey.containers.jersey-container-servlet-core/2.22.2 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.440 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.jersey.core.jersey-client/2.22.2 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.443 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.jersey.core.jersey-common/2.22.2 (Wired to org.glassfish.hk2.utils/2.4.0.b34 which is being refreshed)
20:18:01.446 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.jersey.core.jersey-server/2.22.2 (Wired to org.glassfish.hk2.utils/2.4.0.b34 which is being refreshed)
20:18:01.450 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.jersey.media.jersey-media-multipart/2.22.2 (Wired to org.glassfish.jersey.core.jersey-common/2.22.2 which is being refreshed)
20:18:01.453 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.glassfish.jersey.media.jersey-media-sse/2.22.2 (Wired to org.glassfish.jersey.core.jersey-common/2.22.2 which is being refreshed)
20:18:01.456 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.id/2.5.0 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.459 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.io.rest/2.5.0 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.463 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.io.rest.audio/2.5.0 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.466 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.io.rest.core/2.5.0 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.469 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.io.rest.optimize/2.5.0 (Wired to com.eclipsesource.jaxrs.publisher/5.3.1.201602281253 which is being refreshed)
20:18:01.473 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.io.rest.sitemap/2.5.0 (Wired to org.glassfish.jersey.media.jersey-media-sse/2.22.2 which is being refreshed)
20:18:01.477 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.io.rest.sse/2.5.0 (Wired to org.glassfish.jersey.media.jersey-media-sse/2.22.2 which is being refreshed)
20:18:01.480 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.io.rest.voice/2.5.0 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.483 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.core.ui.icon/2.5.0 (Wired to javax.ws.rs-api/2.0.1 which is being refreshed)
20:18:01.487 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.io.openhabcloud/2.5.5 (Wired to org.openhab.core.id/2.5.0 which is being refreshed)
20:18:01.490 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.ui.basic/2.5.5 (Wired to org.openhab.core.io.rest.sitemap/2.5.0 which is being refreshed)
20:18:01.494 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.ui.habpanel/2.5.5 (Wired to org.openhab.core.io.rest/2.5.0 which is being refreshed)
20:18:01.497 [INFO ] [.internal.service.FeaturesServiceImpl] -     org.openhab.ui.iconset.classic/2.5.5 (Wired to org.openhab.core.ui.icon/2.5.0 which is being refreshed)
20:18:01.870 [INFO ] [smarthome.event.ItemStateChangedEvent] - Storage_Available changed from 6036 to 6035
20:18:02.956 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Available changed from 132 to 131
20:18:02.990 [INFO ] [smarthome.event.ItemStateChangedEvent] - Storage_Available changed from 6035 to 6036
20:18:03.028 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sensor_CPUTemp changed from 73.6 to 74.1
20:18:03.032 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Used changed from 794 to 795
20:18:03.046 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [19]] to http service
20:18:04.050 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Available changed from 131 to 132
20:18:04.055 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Available_Percent changed from 14.2 to 14.3
20:18:04.058 [INFO ] [smarthome.event.ItemStateChangedEvent] - Storage_Available changed from 6036 to 6035
20:18:04.078 [INFO ] [smarthome.event.ItemStateChangedEvent] - Storage_Used changed from 8957 to 8958
20:18:04.086 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Used_Percent changed from 85.8 to 85.7
20:18:04.100 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Used changed from 795 to 794
20:18:04.810 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
20:18:04.815 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [19], contextID=default], with context-name:
20:18:04.820 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering JasperInitializer
20:18:04.873 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [19], contextID=default]}
20:18:05.109 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Available_Percent changed from 14.3 to 14.2
20:18:05.122 [INFO ] [smarthome.event.ItemStateChangedEvent] - Storage_Available changed from 6035 to 6036
20:18:05.158 [INFO ] [smarthome.event.ItemStateChangedEvent] - Storage_Used changed from 8958 to 8957
20:18:05.174 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Used_Percent changed from 85.7 to 85.8
20:18:07.276 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sensor_CPUTemp changed from 74.1 to 73.6
20:18:07.828 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core.ui.icon_2.5.0 [191]] to http service
20:18:07.849 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
20:18:07.975 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.core.ui.icon_2.5.0 [191], contextID=default], with context-name:
20:18:07.981 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering JasperInitializer
20:18:08.069 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core.ui.icon_2.5.0 [191], contextID=default]}
20:18:08.446 [INFO ] [.io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 05df193b-8601-4a14-9420-0a2535dea638, base URL = http://localhost:8080)
20:18:08.448 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sensor_CPUTemp changed from 73.6 to 74.1
20:18:08.978 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.basic_2.5.5 [264]] to http service
20:18:09.021 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
20:18:09.027 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.5 [264], contextID=custom], with context-name:
20:18:09.034 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering JasperInitializer
20:18:09.243 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.5 [264], contextID=custom]}
20:18:09.312 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
20:18:09.319 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.5 [264], contextID=custom], with context-name:
20:18:09.326 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering JasperInitializer
20:18:09.470 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Available changed from 132 to 131
20:18:09.542 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sensor_CPUTemp changed from 74.1 to 75.2
20:18:09.541 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.basic_2.5.5 [264], contextID=custom]}
20:18:09.562 [INFO ] [smarthome.event.ItemStateChangedEvent] - Memory_Used changed from 794 to 795
20:18:09.562 [INFO ] [rd.internal.element.ServletWebElement] - Ignoring servlet [1668] without valid alias or url patterns property.
20:18:09.645 [INFO ] [rvice.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.ui.habpanel_2.5.5 [265]] to http service
20:18:09.678 [INFO ] [org.ops4j.pax.web.utils.ClassPathUtil] - Ignoring bundle scan for /META-INF/services javax.servlet.ServletContainerInitializer.
20:18:09.685 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering context DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.5.5 [265], contextID=default], with context-name:
20:18:09.692 [INFO ] [ice.jetty.internal.HttpServiceContext] - registering JasperInitializer
20:18:09.863 [INFO ] [org.quartz.core.QuartzScheduler      ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
20:18:10.038 [INFO ] [e.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.5.5 [265], contextID=default]}
20:18:10.048 [INFO ] [bpanel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
20:18:10.173 [INFO ] [.internal.service.FeaturesServiceImpl] - Done.

rlkoshak · June 19, 2020, 9:29pm

There are no errors in those logs. It looks like it’s a mix of events.log and openhab.log. By appearances it looks like it shows OH stopping and then starting back up again. There is nothing in these logs that indicate an error is occurring.

To simplify the logs a bit, just look in openhab.log. That will leave out all the ItemStateChangeEvent log entries coming from the SystemInfo binding (I assume). But, as I said, there are no errors here and no indication why it keep starting and stopping.

Are you running off of an SD card? I’ve seen behavior like this on systems where the SD card is failing.

What version of OH are your running? Some of these log statements are not familiar to me.

Have you recently upgraded OH? Some add-ons have moved or been removed and if you’ve not adjusted your configs as described in the release notes this behavior has been reported.

CraigDubya · June 20, 2020, 9:01am

Thanks for your reply Rich. I suspected an SD card failure. I’ve upgraded from 2.5.3-1 to 2.5.5-1 and back…and then back again. I think I’m lost because I was suffering from the Amazon echo binding issue that others have been reporting, which I think was fixed with the workaround .jar that someone kindly supplied.
I’m actually going to switch from a raspberry pi 3 with SD card to a raspberry pi 4 with usb boot from HDD, as I’m sure that an SD card system wouldn’t like the amount of persists that I plan to use.
I’ll get cracking with the pi 4 setup and report back here once done.

Thanks again for your input

Felix_Schneider · June 20, 2020, 9:30am

Get an SSD! I got one for my pi4 with 120gb for like 20€. They are so much faster, smaller, lighter and silent. It’s worth the investment.

CraigDubya · June 20, 2020, 10:12am

Sorry, that’s what I meant

CraigDubya · June 21, 2020, 7:47pm

Well, I said I would report back here.

I have made the change over to a Raspberry Pi 4 with USB boot on SSD (Well a Sandisk Extreme Pro).

I wrestled with the OOM errors from the amazon echo control binding and, thanks to others on here, managed to fix that.

Then I had to re-learn how to connect my MQTT home made power sockets.

Most of the other bindings were fairly straight forward to set up, and my items files, rules files and sitemap file etc transferred across without issue.

Then I had a headache with the MySensors binding (although I think it was permission rights to the USB ports that was the problem). Anyways, somehow I managed to get that working, which means that I am pretty much back up and running… and no SD card to corrupt

system · August 2, 2020, 11:47am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.