Startup Rule is triggered/fires multiple times not only on Start

  • Platform information:
    • Hardware: _ Raspberry Pi 3 Model B Rev 1.2_
  • OS: Raspbian GNU/Linux 8 (jessie)
    • Java Runtime Environment: (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
    • openHAB version: openHAB 2.3.0-1 (Release Build) / OH 2.4.0.M4
    • Bindings:Astro, AVM, EXEC, MQTT, Network, NTP, Samsung, Sonos, Weather (binding-weather1 - 1.12.0), MapDB-Persitence
    • Transformations: exec, Javascript, JSONPATH, Map, RegEx, Scale

On Startup the Rule below should run:

val String filename = "startup-rules"
rule "Look for Raspi_Office is online"

when
		System started
		
	then
		logInfo (filename, "CPU TEMP " + "Line 1: " + CPU_RasPi_Temp_num )		// Test-Switch
		logInfo (filename, "CPU TEMP " + "Line 2: " + CPU_RasPi_Temp )				// Test-Switch
end
/*		createTimer(now.plusSeconds(180), [|
		if (RasPi_online.state == OFF  && CPU_RasPi_Temp_num.state != 0)
		{		
				CPU_RasPi_Temp_num.postUpdate(0)
				logInfo (filename, "Raspi ist offline " + ":" + " " + CPU_RasPi_Temp_num)
		}
		else {
				logInfo (filename, "Raspi ist online oder 0 ")
		}
		logInfo (filename, "Raspberry-Status ist " + ": " + CPU_RasPi_Temp_num)
		])
		
end
*/

I have marked out the tail of the Rule only to see how often the Rule is triggered on Start and when running. This Rule should look if another Raspberry is running and online and if not it should initialize the item"CPU_RasPi_Temp_num" with Zero. In this Version it only gives a LogInfo.

  • Items related:
// System temperatures
Group  Chart_Sys_Temp (Home)
//Number Chart_Sys_Temp_Period "Periode" (Home)

String CPU_Temp 				"OH2_CPU Temp-String [%s °C]"		<temperature>	(Chart_Sys_Temp)		{ channel="exec:command:cpu_temp:output"}
Number CPU_Temp_num				"CPU-OH2-Pi Temperatur [%.1f °C]"	<temperature>	(Chart_Sys_Temp)

String CPU_RasPi_Temp 				"RasPi_CPU Temp-String [%s °C]"		<temperature>	(Chart_Sys_Temp)		{ channel="exec:command:cpu_raspi_temp:output"}
Number CPU_RasPi_Temp_num			"CPU-Ras-Pi Temperatur [%.1f °C]"	<temperature>	(Chart_Sys_Temp)

  • Scripts:
    –cpu_temp.sh
#!/bin/bash
INPUT=$(/bin/cat /sys/class/thermal/thermal_zone0/temp)
TEMP=$(echo "scale=1; $INPUT / 1000" | bc)
echo $TEMP

–cpuRasPi_Office_temp.sh

#!/bin/bash

if [ -f /media/fritzbox-usb/CpuTempPi.txt ]
	then 
		INPUT=$(/bin/cat /media/fritzbox-usb/CpuTempPi.txt)
		echo $INPUT
	else
		INPUT="Fritz-Box nicht gemountet"
		echo $INPUT
fi		

Things-File:

Thing exec:command:cpu_temp "OH2-PI Temperatur" @ "Kinderzimmer" 
					[command="/bin/bash /etc/openhab2/scripts/cpu_temp.sh", interval=120, timeout=15, transform="REGEX((.*?))"]
					
Thing exec:command:cpu_raspi_temp "RasPi Temperatur" @ "Kinderzimmer" 
					[command="/bin/bash /etc/openhab2/scripts/cpuRasPi_Office_temp.sh", interval=120, timeout=15, transform="REGEX((.*?))"]

Logger Extract:

==> /var/log/openhab2/openhab.log <==
2018-09-27 00:59:39.028 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: CPU_RasPi_Temp_num (Type=NumberItem, State=NULL, Label=CPU-Ras-Pi Temperatur, Category=temperature, Groups=[Chart_Sys_Temp])
2018-09-27 00:59:39.038 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: CPU_RasPi_Temp (Type=StringItem, State=Fritz-Box nicht gemountet, Label=RasPi_CPU Temp-String, Category=temperature, Groups=[Chart_Sys_Temp])
==> /var/log/openhab2/events.log <==
==> /var/log/openhab2/openhab.log <==
2018-09-27 01:00:01.660 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: CPU_RasPi_Temp_num (Type=NumberItem, State=NULL, Label=CPU-Ras-Pi Temperatur, Category=temperature, Groups=[Chart_Sys_Temp])
2018-09-27 01:00:01.688 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: CPU_RasPi_Temp (Type=StringItem, State=Fritz-Box nicht gemountet, Label=RasPi_CPU Temp-String, Category=temperature, Groups=[Chart_Sys_Temp])
==> /var/log/openhab2/events.log <==
2018-09-27 01:00:09.436 [vent.ItemStateChangedEvent] - Schaltdose_Fritz_01_Power changed from 21.230 W to 24.580 W
==> /var/log/openhab2/openhab.log <==
2018-09-27 01:00:09.930 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: CPU_RasPi_Temp_num (Type=NumberItem, State=NULL, Label=CPU-Ras-Pi Temperatur, Category=temperature, Groups=[Chart_Sys_Temp])
2018-09-27 01:00:09.939 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: CPU_RasPi_Temp (Type=StringItem, State=Fritz-Box nicht gemountet, Label=RasPi_CPU Temp-String, Category=temperature, Groups=[Chart_Sys_Temp])
==> /var/log/openhab2/events.log <==
2018-09-27 01:19:37.884 [vent.ItemStateChangedEvent] - CPU_RasPi_Temp changed from Fritz-Box nicht gemountet to 55.8
2018-09-27 01:19:37.893 [vent.ItemStateChangedEvent] - Dummy changed from Datei nicht gefunden to 55.8
2018-09-27 01:19:37.965 [vent.ItemStateChangedEvent] - CPU_RasPi_Temp_num changed from NULL to 0
==> /var/log/openhab2/openhab.log <==
2018-09-27 01:19:37.968 [INFO ] [pse.smarthome.model.script.cpu-rules] - Fritzbox-Usb gemountet u. Raspi ist offline CPU_RasPi_Temp_num (Type=NumberItem, State=0, Label=CPU-Ras-Pi Temperatur, Category=temperature, Groups=[Chart_Sys_Temp])
==> /var/log/openhab2/events.log <==
2018-09-27 01:47:23.110 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'avm_fritz.items'
2018-09-27 01:47:33.342 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: CPU_RasPi_Temp_num (Type=NumberItem, State=0, Label=CPU-Ras-Pi Temperatur, Category=temperature, Groups=[Chart_Sys_Temp])
2018-09-27 01:47:33.351 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: CPU_RasPi_Temp (Type=StringItem, State=55.8, Label=RasPi_CPU Temp-String, Category=temperature, Groups=[Chart_Sys_Temp])
2018-09-27 01:57:55.012 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'avm_fritz.items'
2018-09-27 01:58:05.400 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: CPU_RasPi_Temp_num (Type=NumberItem, State=0, Label=CPU-Ras-Pi Temperatur, Category=temperature, Groups=[Chart_Sys_Temp])
2018-09-27 01:58:05.408 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: CPU_RasPi_Temp (Type=StringItem, State=55.8, Label=RasPi_CPU Temp-String, Category=temperature, Groups=[Chart_Sys_Temp])

I don’t understand that the Rule triggers three times at start and later when a .items-file is updated it fires too !!??. Does OpenHAB see a .items-change as a start ? The behavior occurs in both OH-Versions

Has anyone an idea or can explain me what happens there ?

Regards
Peter

Well, yes. Changing the .rules or .items file will fire that trigger.
I’m not saying this is intended, but normal it is.
I suggest you open a GitHub issue to have developers either fix it or state it works as designed.

2 Likes

I believe it is by design. When an .items file is reloaded, the Items get set to initial NULL state. System started rules are commonly used to precondition Items as the user wants them, so for that usage triggering System started is desirable.

You can’t please everyone of course, there will be use cases for not doing it that way, but they had to choose one or the other.

1 Like

Thank you both (@mstormi and @rossko57) for your infos.
I had another idea to fix it with a Counter-Variable in the Start-Rule. But no chance. The varibale is initiated too, of course :rofl:.
In some cases, e.g when testing with new items, it’s not meaningful or necessary to restart the system.
But i understand the principle which seems to be quit right , because under normal circumstances, no changes will be done in the running system.

Thank you for this tip, but as i’m a newbie in this community i don’t know how to do this. Maybe i will learn it later :thinking:

Another question: Has one of you a tip for me to find out my Java Runtime Environment Version ?

But the leading question for me is: why is this rule fired three times behind each other on start ??!!

Regards
Peter

[12:17:09] openhabian@openhabianpi:~$ java -version
openjdk version "1.8.0_152"
OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
[12:17:14] openhabian@openhabianpi:~$
1 Like

Thank’s Markus. Wow, this was a fast answer and easy for me to understand. I tried it in the same second and it works fine.

As a thought, Items not in the xx.items file that you edit and reload do not get reinitialized.
It should be possible to create an Item in it’s own zz.items file, and have some System started rule run to set that Item to some state.
Another rule triggered from Item changed will only run at boot time, not trigger from editing any file (other than zz.items). That’s what you want, a system-really-started trigger?

EDIT - I don’t think this will work at all !! Now think all Items get NULLed if ant xx.items file is reloaded (so as to allow Groups to recalculate)

1 Like

Thank’s for your hints. I just have a little problem to understand the “System started”-Trigger. So i made some tests.

  1. Created (changed) a Rule which starts when System starts/refresh. It should only count how often it will be fired.(IMHO only once)
val String filename = "startup-rules"
var Number count = 0

rule "Look for Raspi_Office is online"

when
		System started
		
	then
		
		logInfo (filename, "CPU TEMP " + "Line 1: ")
		logInfo (filename, "CPU TEMP " + "Line 2: " )				// Test-Switch
		count= count + 1
		logInfo (filename, "ZĂ€hler " + "Line 3: " + count)
		
		if (count < 2) {
		logInfo (filename, "ZĂ€hler ist ok " + "Line 4: " + count)
		
		}else {
		logInfo (filename, "ZĂ€hler ist viel zu hoch" + "Line 4: " + count)
		}

  1. Stopped OH2
  2. Shutdown and Power off
  3. Power on, so System restarts.
  4. Looked into the Log and saw that my Startup-Rule (startup-rules) fired four times and after a refresh only once(see below):
2018-10-03 22:31:14.876 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astra_sun.items'
2018-10-03 22:31:15.239 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astra_moon.items'
2018-10-03 22:31:15.423 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'yahoo.items'
2018-10-03 22:31:15.675 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff.items'
2018-10-03 22:31:15.996 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'owm.items'
2018-10-03 22:31:16.204 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2018-10-03 22:31:16.390 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonos.items'
2018-10-03 22:31:16.787 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'system.items'
2018-10-03 22:31:16.977 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'castle.items'
2018-10-03 22:31:21.414 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'avm_fritz.items'
2018-10-03 22:31:22.191 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.items'
2018-10-03 22:31:23.070 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2018-10-03 22:31:26.143 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-10-03 22:31:31.914 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'cpu.rules'
2018-10-03 22:31:35.059 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'castle.rules'
2018-10-03 22:31:37.154 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.rules'
2018-10-03 22:31:38.068 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'startup.rules'
2018-10-03 22:31:39.899 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'castle.sitemap'
2018-10-03 22:31:40.472 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'avm_fritz.things'
2018-10-03 22:31:40.874 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sample_ntp.things'
2018-10-03 22:31:40.902 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'cpu_tempPI.things'
2018-10-03 22:31:40.977 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.things'
2018-10-03 22:31:41.067 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonos.things'
2018-10-03 22:31:41.096 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
_2018-10-03 22:31:45.506 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: _
_2018-10-03 22:31:45.513 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2:_ 
2018-10-03 22:31:45.704 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2018-10-03 22:31:45.766 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:sun:local every 300 seconds
_2018-10-03 22:31:46.169 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 1_
2018-10-03 22:31:46.219 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2018-10-03 22:31:46.243 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:moon:local every 300 seconds
2018-10-03 22:31:46.536 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing
2018-10-03 22:31:51.663 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'ntp:ntp:local' to inbox.
_2018-10-03 22:31:52.642 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist okLine 4: 1_
_2018-10-03 22:31:52.648 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: _
_2018-10-03 22:31:52.661 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2:_ 
2018-10-03 22:31:52.692 [INFO ] [marthome.model.script.astro-rules_30] - Tagesphase Day_Phase (Type=StringItem, State=NIGHT, Label=Tagesphase, Category=sunmoon, Groups=[gAstro])
_2018-10-03 22:31:52.669 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 2_
_2018-10-03 22:31:52.729 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist viel zu hochLine 4: 2_
2018-10-03 22:31:56.285 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2018-10-03 22:31:56.953 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2018-10-03 22:31:57.064 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-10-03 22:31:57.164 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'samsungtv:tv:0d1cef01_00dc_1000_960f_90f1aac88a51' to inbox.
2018-10-03 22:32:00.449 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2018-10-03 22:32:00.457 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'peter'
_2018-10-03 22:32:08.592 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: _
_2018-10-03 22:32:08.624 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: _
_2018-10-03 22:32:08.631 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 3_
_2018-10-03 22:32:08.648 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist viel zu hochLine 4: 3_
_2018-10-03 22:32:17.236 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: _
_2018-10-03 22:32:17.240 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: _
_2018-10-03 22:32:17.248 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 4_
_2018-10-03 22:32:17.253 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist viel zu hochLine 4: 4_
2018-10-03 22:35:45.207 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'cpu.rules'
_2018-10-03 22:50:32.309 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'startup.rules'_
_2018-10-03 22:50:38.666 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: _
_2018-10-03 22:50:38.673 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: _
_2018-10-03 22:50:38.681 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 1_
_2018-10-03 22:50:38.689 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist ok Line 4: 1_
  1. Then i stopped a part of my cpu-rules
val String filename = "cpu-rules"
/*
rule "OpenhabPi Temperature String to Number"
	when
		Item CPU_Temp changed
	then
		CPU_Temp_num.postUpdate(Float::parseFloat(String::format("%s",CPU_Temp.state).replace(' ','')))
end
//===================================================================================
rule "RaspberryPi Temperature String to Number"
	when
		//Item Dummy2 changed to ON		// Test-Switch
		Item CPU_RasPi_Temp changed
	then
	
	if (CPU_RasPi_Temp.state != "Fritz-Box nicht gemountet" && RasPi_online.state == ON ) 
		{
				logInfo (filename, "Fritzbox-Usb gemountet " + RasPi_online.state)	// this line for test only
				CPU_RasPi_Temp_num.postUpdate(Float::parseFloat(String::format("%s",CPU_RasPi_Temp.state).replace(' ','')))
				
		}
		else if (CPU_RasPi_Temp.state != "Fritz-Box nicht gemountet" && RasPi_online.state == OFF ) 
		{
				CPU_RasPi_Temp_num.postUpdate (0)
				logInfo (filename, "Fritzbox-Usb gemountet u. Raspi ist offline" + " " + CPU_RasPi_Temp_num)
				
		} 
		
		else 
		{
				CPU_RasPi_Temp_num.postUpdate (0)
				logInfo (filename, "Fritzbox-Usb nicht gemountet " + " " + CPU_RasPi_Temp_num)
				
		} 
end
//===============================================================================
// RasPi_online
//===============================================================================
*/

rule "RaspberryPi switch off after shutdown"
	when
		//Item Dummy2 changed to ON   //Testschalter
		Item RasPi_online changed from ON to OFF
	then
		logInfo(filename, "Raspberry Office ist Offline und wird in 3 Minuten ausgeschaltet")
			createTimer(now.plusMinutes(3), [|
				Sonoff_socket_03.sendCommand (OFF)
				logInfo(filename, "Raspberry Office {} wurde ausgeschaltet ",Sonoff_socket_03)
			])
end

The Log shows that the startup-rules was fired twice:

2018-10-03 23:00:20.829 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: 
2018-10-03 23:00:20.834 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: 
2018-10-03 23:00:20.842 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 1
2018-10-03 23:00:21.227 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist ok Line 4: 1
2018-10-03 23:00:23.857 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2018-10-03 23:00:24.599 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2018-10-03 23:00:24.771 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-10-03 23:00:24.890 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'samsungtv:tv:0d1cef01_00dc_1000_960f_90f1aac88a51' to inbox.
2018-10-03 23:00:27.057 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2018-10-03 23:00:27.062 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'peter'
2018-10-03 23:00:47.205 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: 
2018-10-03 23:00:47.210 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: 
2018-10-03 23:00:47.216 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 2
2018-10-03 23:00:47.225 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist viel zu hochLine 4: 2
  1. I stopped the complete cpu-rules , stopped OH2, shutdown and restarted again, and the result was that these three commands of my startup-rules were not executed:
logInfo (filename, "ZĂ€hler " + "Line 3: " + count)
		
		if (count < 2) {
		logInfo (filename, "ZĂ€hler ist ok " + "Line 4: " + count)

The Log looks then

2018-10-03 23:56:25.425 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: 
2018-10-03 23:56:25.947 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: 
2018-10-03 23:56:47.725 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: 
2018-10-03 23:56:47.757 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: 
2018-10-03 23:56:47.766 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 2
2018-10-03 23:56:47.785 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist viel zu hoch Line 4: 2
2018-10-03 23:56:55.219 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 1: 
2018-10-03 23:56:55.227 [INFO ] [smarthome.model.script.startup-rules] - CPU TEMP Line 2: 
2018-10-03 23:56:55.241 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler Line 3: 3
2018-10-03 23:56:55.248 [INFO ] [smarthome.model.script.startup-rules] - ZĂ€hler ist viel zu hoch Line 4: 3

The result is always different. I think there is a relation between the two rules(and maybe others), but i don’t know which.
But the most curious case is that the startup-rules seems to have something like a loop, even if i can’t see it.
https://www.openhab.org/docs/configuration/rules-dsl.html#system-based-triggers

I setup a similar test in my OH 2.3.0 system (with seven xxx.rules files), a ‘System started’ triggered rule that just logged a count and increments it.

From an OH boot up, the rule runs once only.
If I edit/save the .rules file containing the test rule, the rule runs once only.
If I edit/save any other xxx.rules file, the rule does not run.
That all seems to be how it is supposed to work.

So what’s going on with your setup?

I believe errors in rules files can cause multiple load/parsing attempts. But if that were going on with you, I’d expect to see it in your logs.

Thanks for your help and your hints.

That’s what i’m asking me too !!! I would expect to see error messages in the log too. But i can’t see any :thinking:
So what. May be i find the trigger for the trigger one day :smile:

Have a good time
Peter

Your OH startup log shows it actually loaded rules before it did load items files.
That’ll result in two executions of the ‘System started’ rule.
The order is somewhat coincidential due to the way Karaf works. See this thread for a workaround to enforce the proper load order.

Hi Markus,
first of all, thank’s a lot for your interest to still help me.
I have to say that i have changed openhab.event logging to: log:set WARN smarthome.event
I did this, because i thought that everything’s ok, so i don’t need to see every change of an item and if an error occurs it nevertheless will be shown. (that’s my simple thinking :upside_down_face:)
May be i’m wrong, but when i have a look on the log above

it looks like items are loaded before rules. But i will learn and try to understand what you “cracks” have developed. Do you have any variant in use ? (which).
At the moment i’m on a point to say: Why do i do this? (brood about such problems, i’m retired :stuck_out_tongue_winking_eye:), but whoever rests rustes (wer rastet, der rostet in german), although the next hit came this morning, when i looked in my openhab.log, but only hieroglyphics were shown:

	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [15:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.Server.handle(Server.java:534) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.eclipse.jetty.io.EofException
	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:199) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:420) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:313) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:147) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:731) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) ~[87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:519) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:745) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:801) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:235) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:219) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:496) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at java.io.OutputStream.write(OutputStream.java:75) ~[?:?]
	at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:320) ~[?:?]
	at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:218) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:294) ~[?:?]
	at org.eclipse.smarthome.io.rest.core.internal.GsonProvider.writeTo(GsonProvider.java:71) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:265) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:250) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:106) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:86) ~[?:?]
	... 46 more
Caused by: java.io.IOException: Die Verbindung wurde vom Kommunikationspartner zurĂŒckgesetzt
	at sun.nio.ch.FileDispatcherImpl.writev0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51) ~[?:?]
	at sun.nio.ch.IOUtil.write(IOUtil.java:148) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:179) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:420) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:313) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:147) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:731) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) ~[87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:519) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:745) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:801) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:235) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:219) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:496) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at java.io.OutputStream.write(OutputStream.java:75) ~[?:?]
	at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:320) ~[?:?]
	at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:218) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:294) ~[?:?]
	at org.eclipse.smarthome.io.rest.core.internal.GsonProvider.writeTo(GsonProvider.java:71) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:265) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:250) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:106) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:86) ~[?:?]
	... 46 more
2018-10-04 09:52:24.977 [ERROR] [ersey.server.ServerRuntime$Responder] - An I/O error has occurred while writing a response message entity to the container output stream.
org.glassfish.jersey.server.internal.process.MappableException: org.eclipse.jetty.io.EofException
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:92) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.message.internal.MessageBodyFactory.writeTo(MessageBodyFactory.java:1130) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:711) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:444) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:434) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:329) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [15:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.Server.handle(Server.java:534) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.eclipse.jetty.io.EofException
	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:199) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:420) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:313) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:147) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:731) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) ~[87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:519) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:745) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:801) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:235) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:219) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:496) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at java.io.OutputStream.write(OutputStream.java:75) ~[?:?]
	at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:320) ~[?:?]
	at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:218) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:294) ~[?:?]
	at org.eclipse.smarthome.io.rest.core.internal.GsonProvider.writeTo(GsonProvider.java:71) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:265) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:250) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:106) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:86) ~[?:?]
	... 46 more
Caused by: java.io.IOException: DatenĂŒbergabe unterbrochen (broken pipe)
	at sun.nio.ch.FileDispatcherImpl.writev0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51) ~[?:?]
	at sun.nio.ch.IOUtil.write(IOUtil.java:148) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:179) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:420) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:313) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:147) ~[76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:731) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) ~[87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:519) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:745) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:801) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:235) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:219) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:496) ~[84:org.eclipse.jetty.server:9.3.21.v20170918]
	at java.io.OutputStream.write(OutputStream.java:75) ~[?:?]
	at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:320) ~[?:?]
	at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:218) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:294) ~[?:?]
	at org.eclipse.smarthome.io.rest.core.internal.GsonProvider.writeTo(GsonProvider.java:71) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:265) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:250) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:106) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:86) ~[?:?]
	... 46 more


but Basic UI runs!
So what, i will carry on, as long as i get help from the community.

jersey.servlet kind of thing is often caused by including an Item in a sitemap that does not exist (typo in an Item name?)

I’ll try to find. But this seems to be the same as if to find a pin in a haysack.
I found some posts https://github.com/openhab/openhab-distro/issues/587 there. So the problem seems not to be rare.

Looking at the first or last lines of the ‘heiroglyphic block’ often gives a hint. I don’t think those are in the log sample you posted.

Bear with it, we’ll get there :slight_smile:

1 Like

You’re right, my mistake. So it’s something else. But as @rossko57 said, we’ll get there.
Could be a parse error or execution error. Enable log:set debug org.eclipse.smarthome.rules and watch it spit messages if you change a rules file to have errors.

You might want to change to a more current OH (“release” does not necessarily mean “bug-free” :wink: ) such as the latest testing milestone 2.4.0M4, just to see if that makes a difference. There have been a couple of fixes that might or might not affect this behavior.
(warning though, there’s breaking changes on upgrades at least with the ZWave binding).

[16:25:41] root@openhabianpi:/etc/openhab2/services# cat /etc/systemd/system/openhab2.service.d/override.conf
[Service]
ExecStartPre=-/bin/bash -c '/usr/bin/find ${OPENHAB_CONF} -name "*.rules" -exec /usr/bin/rename.ul .rules .x {} \\;'
ExecStartPost=-/bin/sleep 240
ExecStartPost=-/bin/bash -c '/usr/bin/find ${OPENHAB_CONF} -name "*.x" -exec /usr/bin/rename.ul .x .rules {} \\;'
TimeoutStartSec=300
1 Like

Thank you Markus and thank you @rossko57. You’re both great guys. And Markus i’m wrong and you’re abolutely right with your diagnosis that the loading-procedure is not always in the sequence, one wish to have.

What I saw was only the message of OH-Logging, which shows me that nice sequential working. But when I changed back the event-logging to “log:set INFO smarthome.event”, I saw the truth .After that “Loading model ..” the several Items were initialized and suddenly within this sequence my “startup-rules” was fired. Now I will test your “log:set command”.
I aready have a 2.4.0M4-Set from an image of the 2.3 stable-version, which I created with the “openhabian-config tool” to test some new item features of my Fritz-sockets (Power and Battery-Percentage) as @cweitkamp gave the hint. And that was the point were I saw the first time that my startup-rule didn’t work correct and I also found out that my weather-binding causes problems with the OpenWeatherap-Api-Key (401-Error). But this error occurs even in the 2.3.version, but I didn’t see, because my log:set for the binding was OFF, although the most items(channels) seems to work. (But now back to the roots).

I will try to analyze the problem with the log-command you gave me (and, by the way, thinking about complete new start :thinking: or not :wink:) and may be I find something in the openhab.log as @rossko57 told.

Have a nice day (and of course - weekend)

:+1: Thanks. See post below/above with Markus.

Hi Guys (@mstormi / @rossko57)
after a weekend with testing, stripping of my setup to nearly virginity :sweat_smile:, and try to understand the logging errors, when i found the words lambda and createTimer after setting the log:

I, then stopped all my rules and worked on workaround for them. I understand that my rules are fired multiple times within a second, so that the timer comes to an error. But as rossko said

was a stimulation to me and i have stay tuned.

While doing my tests 
, i found this post https://community.openhab.org/t/rule-received-command-or-received-update/35030/3 from @ThomDietrich which points me in the right direction. It was my mania to secure all and everything, i looked into my mapdb and there i found the reasons.

With a good level of OH 2.3, i changed now to OH 2.4-M. Although there are still some warnings

2018-10-12 13:09:55.610 [WARN ] [org.eclipse.jetty.server.HttpChannel] - /rest/sitemaps/events/subscribe

2018-10-12 13:40:54.446 [WARN ] [al.handler.AVMFritzBaseBridgeHandler] - Channel 'voltage' in thing 'avmfritz:FRITZ_DECT_210:Fritz-Box-7490:116570136076' does not exist, recreating thing.

2018-10-12 13:40:54.500 [WARN ] [al.handler.AVMFritzBaseBridgeHandler] - Channel 'voltage' in thing 'avmfritz:FRITZ_DECT_200:Fritz-Box-7490:087610467933' does not exist, recreating thing.

2018-10-12 13:40:54.561 [WARN ] [al.handler.AVMFritzBaseBridgeHandler] - Channel 'voltage' in thing 'avmfritz:FRITZ_DECT_210:Fritz-Box-7490:116570075282' does not exist, recreating thing.

2018-10-12 13:40:54.619 [WARN ] [al.handler.AVMFritzBaseBridgeHandler] - Channel 'voltage' in thing 'avmfritz:FRITZ_DECT_200:Fritz-Box-7490:087610494097' does not exist, recreating thing.

2018-10-12 13:40:54.686 [WARN ] [al.handler.AVMFritzBaseBridgeHandler] - Channel 'battery_level' in thing 'avmfritz:Comet_DECT:Fritz-Box-7490:119601003400' does not exist, recreating thing.

2018-10-12 13:40:54.781 [WARN ] [al.handler.AVMFritzBaseBridgeHandler] - Channel 'battery_level' in thing 'avmfritz:Comet_DECT:Fritz-Box-7490:119600949320' does not exist, recreating thing.

2018-10-12 13:40:54.869 [WARN ] [al.handler.AVMFritzBaseBridgeHandler] - Channel 'battery_level' in thing 'avmfritz:FRITZ_DECT_301:Fritz-Box-7490:099950077350' does not exist, recreating thing.

2018-10-12 13:40:54.919 [WARN ] [al.handler.AVMFritzBaseBridgeHandler] - Channel 'battery_level' in thing 'avmfritz:FRITZ_DECT_301:Fritz-Box-7490:099950074210' does not exist, recreating thing.

2018-10-12 13:40:55.337 [WARN ] [e.jetty.util.thread.ThreadPoolBudget] - Low configured threads: (max=8 - required=1)=7 < warnAt=8 for QueuedThreadPool[ServletModel-11]@12563c{STARTING,8<=0<=8,i=0,q=0}[ReservedThreadExecutor@1712906{s=0/1,p=0}]

I think that @cweitkamp looks for a solution, and of cours you, Markus (https://community.openhab.org/t/low-configured-threads-warning/52084).

Also there seems to be a problem with the ios-app and OH.

2018-10-07 01:26:27.418 [WARN ] [eclipse.jetty.servlet.ServletHandler] - /proxy
java.lang.NullPointerException: null
	at java.net.URI$Parser.parse(URI.java:3042) [?:?]
	at java.net.URI.<init>(URI.java:588) [?:?]
	at java.net.URI.create(URI.java:850) [?:?]
	at org.eclipse.smarthome.ui.internal.proxy.ProxyServletService.uriFromRequest(ProxyServletService.java:282) [147:org.eclipse.smarthome.ui:0.10.0.oh230]
	at org.eclipse.smarthome.ui.internal.proxy.AsyncProxyServlet.rewriteTarget(AsyncProxyServlet.java:66) [147:org.eclipse.smarthome.ui:0.10.0.oh230]
	at org.eclipse.jetty.proxy.ProxyServlet.service(ProxyServlet.java:63) [80:org.eclipse.jetty.proxy:9.3.21.v20170918]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [31:javax.servlet-api:3.1.0]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.Server.handle(Server.java:534) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2018-10-07 01:26:27.459 [WARN ] [eclipse.jetty.servlet.ServletHandler] - /proxy
java.lang.NullPointerException: null

One more time, thanks a lot for your help.

Yes, the logging level for the avmfritz binding has been reduced (see https://github.com/openhab/openhab2-addons/pull/4051). The fix is not part of of OH2.4.0-M4