Finally { lock.unlock() not working as expected

I have the following:

logInfo("Testing", "Done")
}
finally {
        lock.unlock()
}
logInfo("Testing", "Battery - Unlocked")

I see the “Done” in the log file, but never see the “Battery - Unlocked”.

import java.lang.*
import org.openhab.core.library.types.*
import java.util.concurrent.locks.Lock
import java.util.concurrent.locks.ReentrantLock

var Lock lock = new ReentrantLock()

rule "Outback JSON parsing"
when
        Item Outback_Dev_status changed
then	
	logInfo("Testing", "JSON - Locking")
	lock.lock()
	try {
		var String json = Outback_Dev_status.state.toString
      		var Number battery_soc = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==10)][0].SOC", json))
		var Number battery_voltage = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==10)][0].Batt_V", json))
		var String battery_temp_string = new String(transform("JSONPATH", "$.devstatus.ports[?(@.Port==10)][0].Batt_temp", json))
		var Number battery_temp = new Integer(battery_temp_string.split(" ").get(0))
		var Number shunt_a_amps = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==10)][0].Shunt_A_I", json))
		var Number shunt_b_amps = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==10)][0].Shunt_B_I", json))
		var Number shunt_total_amps = shunt_a_amps + shunt_b_amps
		var Number today_out_kwh = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==10)][0].Out_kWh_today", json))
		var Number charge_a_amps = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==5)][0].Out_I", json))
		var Number charge_b_amps = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==6)][0].Out_I", json))
		var Number charge_c_amps = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==7)][0].Out_I", json))
		var Number charge_d_amps = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==8)][0].Out_I", json))
		var Number charge_a_kwh = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==5)][0].Out_kWh", json))
		var Number charge_b_kwh = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==6)][0].Out_kWh", json))
		var Number charge_c_kwh = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==7)][0].Out_kWh", json))
		var Number charge_d_kwh = new Double(transform("JSONPATH", "$.devstatus.ports[?(@.Port==8)][0].Out_kWh", json))
		var Number charge_a_watts = charge_a_amps * battery_voltage
		var Number charge_b_watts = charge_b_amps * battery_voltage
		var Number charge_c_watts = charge_c_amps * battery_voltage
		var Number charge_d_watts = charge_d_amps * battery_voltage
		var Number total_watts = charge_a_watts + charge_b_watts + charge_c_watts + charge_d_watts
		var Number today_solar_kwh = charge_a_kwh + charge_b_kwh + charge_c_kwh + charge_d_kwh
	
        	postUpdate(Battery_Charge, battery_soc)
		postUpdate(Battery_Voltage, battery_voltage)
		postUpdate(Battery_Temp, battery_temp * 1.8 + 32)
		postUpdate(Solar_Charge_A_Watts, charge_a_watts)
		postUpdate(Solar_Charge_B_Watts, charge_b_watts)
		postUpdate(Solar_Charge_C_Watts, charge_c_watts)
		postUpdate(Solar_Charge_D_Watts, charge_d_watts)
		postUpdate(Solar_Total_Watts, total_watts)
		postUpdate(Shunt_A_Amps, shunt_a_amps)
		postUpdate(Shunt_B_Amps, shunt_b_amps)
		postUpdate(Shunt_Total_Amps, shunt_total_amps)
		postUpdate(Today_Out_kWh, today_out_kwh)
		postUpdate(Today_Solar_kWh, today_solar_kwh)

		var Number a_l1_voltage = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==1)][0].VAC_out_L1", json))
		var Number a_l1_buy_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==1)][0].Buy_I_L1", json))
		var Number a_l1_inv_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==1)][0].Inv_I_L1", json))
		var Number a_l2_voltage = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==1)][0].VAC_out_L2", json))
		var Number a_l2_buy_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==1)][0].Buy_I_L2", json))
		var Number a_l2_inv_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==1)][0].Inv_I_L2", json))
		var Number a_l1_buy_watts = a_l1_voltage * a_l1_buy_amps
		var Number a_l2_buy_watts = a_l1_voltage * a_l2_buy_amps
		var Number buy_a_watts = a_l1_buy_watts + a_l2_buy_watts
		var Number a_l1_watts = a_l1_voltage * a_l1_inv_amps
		var Number a_l2_watts = a_l2_voltage * a_l2_inv_amps
		var Number inverter_a_watts = a_l1_watts + a_l2_watts

		postUpdate(Buy_A_Watts, buy_a_watts)
		postUpdate(Inverter_A_Watts, inverter_a_watts)

		var Number b_l1_voltage = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==2)][0].VAC_out_L1", json))
		var Number b_l1_buy_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==2)][0].Buy_I_L1", json))
		var Number b_l1_inv_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==2)][0].Inv_I_L1", json))
		var Number b_l2_voltage = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==2)][0].VAC_out_L2", json))
		var Number b_l2_buy_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==2)][0].Buy_I_L2", json))
		var Number b_l2_inv_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==2)][0].Inv_I_L2", json))
		var Number b_l1_buy_watts = b_l1_voltage * b_l1_buy_amps
		var Number b_l2_buy_watts = b_l1_voltage * b_l2_buy_amps
		var Number buy_b_watts = b_l1_buy_watts + b_l2_buy_watts
		var Number b_l1_watts = b_l1_voltage * b_l1_inv_amps
		var Number b_l2_watts = b_l2_voltage * b_l2_inv_amps
		var Number inverter_b_watts = b_l1_watts + b_l2_watts

		postUpdate(Buy_B_Watts, buy_b_watts)
		postUpdate(Inverter_B_Watts, inverter_b_watts)

		var Number c_l1_voltage = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==3)][0].VAC_out_L1", json))
		var Number c_l1_buy_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==3)][0].Buy_I_L1", json))
		var Number c_l1_inv_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==3)][0].Inv_I_L1", json))
		var Number c_l2_voltage = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==3)][0].VAC_out_L2", json))
		var Number c_l2_buy_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==3)][0].Buy_I_L2", json))
	        var Number c_l2_inv_amps = new Integer(transform("JSONPATH", "$.devstatus.ports[?(@.Port==3)][0].Inv_I_L2", json))
		var Number c_l1_buy_watts = c_l1_voltage * c_l1_buy_amps
		var Number c_l2_buy_watts = c_l1_voltage * c_l2_buy_amps
		var Number buy_c_watts = c_l1_buy_watts + c_l2_buy_watts
		var Number c_l1_watts = c_l1_voltage * c_l1_inv_amps
		var Number c_l2_watts = c_l2_voltage * c_l2_inv_amps
		var Number inverter_c_watts = c_l1_watts + c_l2_watts

		postUpdate(Buy_C_Watts, buy_c_watts)
		postUpdate(Inverter_C_Watts, inverter_c_watts)

		postUpdate(Inverter_Total_Watts, inverter_a_watts + inverter_b_watts + inverter_c_watts)
		postUpdate(Buy_Total_Watts, buy_a_watts + buy_b_watts + buy_c_watts)
	}
	finally {
		lock.unlock()
	}
	logInfo("Testing", "JSON - Unlocked")
end


rule "Battery State Events"
when
        Item Battery_Charge changed
then	
	logInfo("Testing", "Generator_Auto = " + Generator_Auto.state)
	logInfo("Testing", "Battery - Locking")
	lock.lock()
	try {
		logInfo("Testing", "Battery_Charge = " + Battery_Charge.state)
		if (Battery_Charge.state <= 70) {
			sendCommand(Battery_Low, ON)
			if (Generator_Auto.state == OFF && Generator_Failed.state == OFF) {
				sendMail("8323303810@mms.att.net", "Battery", "Battery SOC at " + Battery_Charge.state + "%" "Load at " +  Inverter_Total_Watts.state + " watts")
					sendCommand(Generator_Auto, ON)
			}
		}
		logInfo("Testing", "Battery_Charge = " + Battery_Charge.state)
		if (Battery_Charge.state >= 90 && Generator_Auto.state == ON) {
			sendCommand(Battery_Low, OFF)
			sendCommand(Generator_Auto, OFF)
		}
	logInfo("Testing", "Done")
	}
	finally {
		lock.unlock()
	}
	logInfo("Testing", "Battery - Unlocked")
end

Log

    2016-01-04 19:46:37.588 [INFO ] [g.openhab.model.script.Testing] - JSON - Locking
    2016-01-04 19:46:37.598 [INFO ] [runtime.busevents             ] - Battery_Charge state updated to 84
    2016-01-04 19:46:37.599 [INFO ] [runtime.busevents             ] - Battery_Voltage state updated to 47.4
    2016-01-04 19:46:37.599 [INFO ] [runtime.busevents             ] - Battery_Temp state updated to 77.0
    2016-01-04 19:46:37.600 [INFO ] [runtime.busevents             ] - Solar_Charge_A_Watts state updated to 0.00
    2016-01-04 19:46:37.610 [INFO ] [runtime.busevents             ] - Solar_Charge_B_Watts state updated to 0.00
    2016-01-04 19:46:37.610 [INFO ] [runtime.busevents             ] - Solar_Charge_C_Watts state updated to 0.00
    2016-01-04 19:46:37.611 [INFO ] [runtime.busevents             ] - Solar_Charge_D_Watts state updated to 0.00
    2016-01-04 19:46:37.611 [INFO ] [runtime.busevents             ] - Solar_Total_Watts state updated to 0.00
    2016-01-04 19:46:37.613 [INFO ] [runtime.busevents             ] - Shunt_A_Amps state updated to -202.4
    2016-01-04 19:46:37.615 [INFO ] [runtime.busevents             ] - Shunt_B_Amps state updated to 0.4
    2016-01-04 19:46:37.615 [INFO ] [g.openhab.model.script.Testing] - JSON - Unlocked
    2016-01-04 19:46:37.616 [INFO ] [runtime.busevents             ] - Shunt_Total_Amps state updated to -202.0
    2016-01-04 19:46:37.617 [INFO ] [runtime.busevents             ] - Today_Out_kWh state updated to 48.67
    2016-01-04 19:46:37.617 [INFO ] [runtime.busevents             ] - Today_Solar_kWh state updated to 21.5
    2016-01-04 19:46:37.617 [INFO ] [runtime.busevents             ] - Buy_A_Watts state updated to 0
    2016-01-04 19:46:37.618 [INFO ] [runtime.busevents             ] - Inverter_A_Watts state updated to 2724
    2016-01-04 19:46:37.618 [INFO ] [runtime.busevents             ] - Buy_B_Watts state updated to 0
    2016-01-04 19:46:37.619 [INFO ] [runtime.busevents             ] - Inverter_B_Watts state updated to 2611
    2016-01-04 19:46:37.619 [INFO ] [runtime.busevents             ] - Buy_C_Watts state updated to 0
    2016-01-04 19:46:37.620 [INFO ] [runtime.busevents             ] - Inverter_C_Watts state updated to 1989
    2016-01-04 19:46:37.621 [INFO ] [runtime.busevents             ] - Inverter_Total_Watts state updated to 7324
    2016-01-04 19:46:37.621 [INFO ] [runtime.busevents             ] - Buy_Total_Watts state updated to 0
    2016-01-04 19:46:37.635 [INFO ] [g.openhab.model.script.Testing] - Generator_Auto = OFF
    2016-01-04 19:46:37.648 [INFO ] [g.openhab.model.script.Testing] - Battery - Locking
    2016-01-04 19:46:37.688 [INFO ] [g.openhab.model.script.Testing] - Battery_Charge = 84
    2016-01-04 19:46:37.744 [INFO ] [g.openhab.model.script.Testing] - Battery_Charge = 84
    2016-01-04 19:46:37.800 [INFO ] [g.openhab.model.script.Testing] - Done
    2016-01-04 19:46:38.703 [INFO ] [runtime.busevents             ] - Water_Pressure state updated to 74
    2016-01-04 19:46:38.817 [INFO ] [runtime.busevents             ] - Basement_HVAC_Supply state updated to 117.26599999999999
    2016-01-04 19:46:38.963 [INFO ] [runtime.busevents             ] - Water_Meter state updated to 44934
    2016-01-04 19:46:38.965 [INFO ] [runtime.busevents             ] - Today_Water_Used state updated to 777

Continues, but nothing after the “Done”. So the next time the rule run it sits as “JSON - Locking”.

Add a catch(Throwable t) { logError("Testing", "Exception thrown: " + t.toString) } and see if there is a problem. I’m not 100% positive that the finally is guaranteed to be run in the rules language. I’ve found at least one case where it doesn’t. Its possible adding the catch may help it keep the exception from killing the function before the finally can run.

I agree with @rlkoshak that it seems that the finally statement seems to have a different behaviour in rules than it has in java (actually I didn’t find out what behaviour it has here). If the idea with the catch statement works it will solve your problem (but then still no need for the finally…)

Regards
Dieter

If you put the last log message inside the FINALLY block, does the message appear ? It actually seems like that’s where it belongs – next to the lock.unlock() statement which it is “shadowing”.

( If that works, it would support theory that parser actually terminates a rule’s THEN clause after the finally { } block… FINALLY may literally mean FINALLY…:slight_smile: ).