Hi,
I’m running the Centos distro version of OpenHAB, occured both on 2.2 and on 2.3 (stable)
CentOS Linux release 7.5.1804
Oracle Java:
java version “1.8.0_151”
Java™ SE Runtime Environment (build 1.8.0_151-b12)
Java HotSpot™ 64-Bit Server VM (build 25.151-b12, mixed mode)
/etc/default/openhab2:
EXTRA_JAVA_OPTS="-Xbootclasspath/a:/usr/local/jython2.7.1/jython.jar
-Dpython.home=/usr/local/jython2.7.1
-Dpython.path=/etc/openhab2/lib/python"
Since two days, my Openhab stopped working. It keeps restarting.
When the log is set to normal, it does not display any warning of error.
When I set the log level to debug the (relevant) log displays the DEBUG message below.
If I remove the python file, OpenHAB behaves normally.
Funny thing is that this seems to have started after a power failure, after working correctly for months.
Any ideas?
Thanks
Co
018-09-11 10:58:26.255 [DEBUG] [client.mqttv3.internal.CommsCallback] - paho1074679409746: wait for workAvailable
2018-09-11 10:58:28.356 [INFO ] [org.quartz.core.QuartzScheduler ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
2018-09-11 10:58:28.356 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2018-09-11 10:58:29.269 [INFO ] [netty.handler.logging.LoggingHandler] - [id: 0x5998e9fa, /0:0:0:0:0:0:0:0:9124] ACTIVE
2018-09-11 10:58:33.502 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'omnikOpenHAB.py'
2018-09-11 10:58:35.771 [DEBUG] [ternal.logging.InternalLoggerFactory] - Using java.util.logging as the default logging framework
2018-09-11 10:58:35.788 [DEBUG] [tty.util.internal.PlatformDependent0] - -Dio.netty.noUnsafe: false
2018-09-11 10:58:35.789 [DEBUG] [tty.util.internal.PlatformDependent0] - sun.misc.Unsafe.theUnsafe: available
2018-09-11 10:58:35.790 [DEBUG] [tty.util.internal.PlatformDependent0] - sun.misc.Unsafe.copyMemory: available
2018-09-11 10:58:35.791 [DEBUG] [tty.util.internal.PlatformDependent0] - java.nio.Buffer.address: available
2018-09-11 10:58:35.791 [DEBUG] [tty.util.internal.PlatformDependent0] - direct buffer constructor: available
2018-09-11 10:58:35.793 [DEBUG] [tty.util.internal.PlatformDependent0] - java.nio.Bits.unaligned: available, true
2018-09-11 10:58:35.793 [DEBUG] [tty.util.internal.PlatformDependent0] - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable
java.lang.NullPointerException: null
at org.python.netty.util.internal.PlatformDependent0$6.run(PlatformDependent0.java:295) ~[?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at org.python.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:288) ~[?:?]
at org.python.netty.util.internal.PlatformDependent.getSystemClassLoader(PlatformDependent.java:895) ~[?:?]
at org.python.netty.util.internal.PlatformDependent.isAndroid0(PlatformDependent.java:919) ~[?:?]
at org.python.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:70) ~[?:?]
at org.python.netty.buffer.PooledByteBufAllocator.<clinit>(PooledByteBufAllocator.java:97) ~[?:?]
at java.lang.Class.forName0(Native Method) ~[?:?]
at java.lang.Class.forName(Unknown Source) ~[?:?]
at org.python.core.Py.loadAndInitClass(Py.java:1107) ~[?:?]
at org.python.core.Py.findClassInternal(Py.java:1042) ~[?:?]
at org.python.core.Py.findClassEx(Py.java:1093) ~[?:?]
at org.python.core.packagecache.SysPackageManager.findClass(SysPackageManager.java:142) ~[?:?]
at org.python.core.packagecache.PackageManager.findClass(PackageManager.java:33) ~[?:?]
at org.python.core.packagecache.SysPackageManager.findClass(SysPackageManager.java:130) ~[?:?]
at org.python.core.PyJavaPackage.__findattr_ex__(PyJavaPackage.java:134) ~[?:?]
at org.python.core.PyObject.__findattr__(PyObject.java:965) ~[?:?]
at org.python.core.PyObject.__findattr__(PyObject.java:950) ~[?:?]
at org.python.core.imp.ensureFromList(imp.java:1016) ~[?:?]
at org.python.core.imp.ensureFromList(imp.java:990) ~[?:?]
at org.python.core.imp.import_module_level(imp.java:977) ~[?:?]
at org.python.core.imp.importName(imp.java:1057) ~[?:?]
at org.python.core.ImportFunction.__call__(__builtin__.java:1280) ~[?:?]
at org.python.core.PyObject.__call__(PyObject.java:450) ~[?:?]
at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
at org.python.core.imp.importFromAs(imp.java:1149) ~[?:?]
at org.python.core.imp.importFrom(imp.java:1124) ~[?:?]
at _socket$py.f$0(/usr/local/jython2.7.1/Lib/_socket.py:1965) ~[?:?]
at _socket$py.call_function(/usr/local/jython2.7.1/Lib/_socket.py) ~[?:?]
at org.python.core.PyTableCode.call(PyTableCode.java:171) ~[?:?]
at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
at org.python.core.imp.createFromCode(imp.java:436) ~[?:?]
at org.python.core.imp.createFromPyClass(imp.java:237) ~[?:?]
at org.python.core.imp.createFromPyClass(imp.java:205) ~[?:?]
at org.python.core.imp.loadFromSource(imp.java:657) ~[?:?]
at org.python.core.imp.find_module(imp.java:551) ~[?:?]
at org.python.core.imp.import_next(imp.java:838) ~[?:?]
at org.python.core.imp.import_module_level(imp.java:957) ~[?:?]
at org.python.core.imp.importName(imp.java:1057) ~[?:?]
at org.python.core.ImportFunction.__call__(__builtin__.java:1280) ~[?:?]
at org.python.core.PyObject.__call__(PyObject.java:450) ~[?:?]
at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
at org.python.core.imp.importFromAs(imp.java:1149) ~[?:?]
at org.python.core.imp.importFrom(imp.java:1124) ~[?:?]
at socket$py.f$0(/usr/local/jython2.7.1/Lib/socket.py:132) ~[?:?]
at socket$py.call_function(/usr/local/jython2.7.1/Lib/socket.py) ~[?:?]
at org.python.core.PyTableCode.call(PyTableCode.java:171) ~[?:?]
at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
at org.python.core.imp.createFromCode(imp.java:436) ~[?:?]
at org.python.core.imp.createFromPyClass(imp.java:237) ~[?:?]
at org.python.core.imp.createFromPyClass(imp.java:205) ~[?:?]
at org.python.core.imp.loadFromSource(imp.java:657) ~[?:?]
at org.python.core.imp.find_module(imp.java:551) ~[?:?]
at org.python.core.imp.import_next(imp.java:838) ~[?:?]
at org.python.core.imp.import_module_level(imp.java:957) ~[?:?]
at org.python.core.imp.importName(imp.java:1057) ~[?:?]
at org.python.core.ImportFunction.__call__(__builtin__.java:1280) ~[?:?]
at org.python.core.PyObject.__call__(PyObject.java:450) ~[?:?]
at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
at org.python.core.imp.importOne(imp.java:1076) ~[?:?]
at org.python.pycode._pyx0.f$0(<script>:322) ~[?:?]
at org.python.pycode._pyx0.call_function(<script>) ~[?:?]
at org.python.core.PyTableCode.call(PyTableCode.java:171) ~[?:?]
at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
at org.python.core.Py.runCode(Py.java:1614) ~[?:?]
at org.python.core.__builtin__.eval(__builtin__.java:497) ~[?:?]
at org.python.core.__builtin__.eval(__builtin__.java:501) ~[?:?]
at org.python.util.PythonInterpreter.eval(PythonInterpreter.java:259) ~[?:?]
at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:57) ~[?:?]
at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:64) ~[?:?]
at javax.script.AbstractScriptEngine.eval(Unknown Source) ~[?:?]
at org.eclipse.smarthome.automation.module.script.internal.ScriptEngineManagerImpl.loadScript(ScriptEngineManagerImpl.java:110) ~[?:?]
at org.eclipse.smarthome.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.importFile(ScriptFileWatcher.java:168) ~[?:?]
at org.eclipse.smarthome.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.checkFiles(ScriptFileWatcher.java:267) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
at java.util.concurrent.FutureTask.runAndReset(Unknown Source) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
at java.lang.Thread.run(Unknown Source) [?:?]
2018-09-11 10:58:35.821 [DEBUG] [tty.util.internal.PlatformDependent0] - java.nio.DirectByteBuffer.<init>(long, int): available
2018-09-11 10:58:35.821 [DEBUG] [etty.util.internal.PlatformDependent] - Java version: 8
2018-09-11 10:58:35.822 [DEBUG] [etty.util.internal.PlatformDependent] - sun.misc.Unsafe: available
2018-09-11 10:58:35.822 [DEBUG] [etty.util.internal.PlatformDependent] - -Dio.netty.tmpdir: /var/lib/openhab2/tmp (java.io.tmpdir)
2018-09-11 10:58:35.825 [DEBUG] [etty.util.internal.PlatformDependent] - -Dio.netty.bitMode: 64 (sun.arch.data.model)
2018-09-11 10:58:35.826 [DEBUG] [etty.util.internal.PlatformDependent] - -Dio.netty.noPreferDirect: false
2018-09-11 10:58:35.826 [DEBUG] [etty.util.internal.PlatformDependent] - -Dio.netty.maxDirectMemory: 482344960 bytes
2018-09-11 10:58:35.827 [DEBUG] [etty.util.internal.PlatformDependent] - -Dio.netty.uninitializedArrayAllocationThreshold: -1
2018-09-11 10:58:35.827 [DEBUG] [hon.netty.util.internal.CleanerJava6] - java.nio.ByteBuffer.cleaner(): available
2018-09-11 10:58:35.828 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.numHeapArenas: 4
2018-09-11 10:58:35.828 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.numDirectArenas: 4
2018-09-11 10:58:35.829 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.pageSize: 8192
2018-09-11 10:58:35.829 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.maxOrder: 11
2018-09-11 10:58:35.829 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.chunkSize: 16777216
2018-09-11 10:58:35.830 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.tinyCacheSize: 512
2018-09-11 10:58:35.830 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.smallCacheSize: 256
2018-09-11 10:58:35.830 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.normalCacheSize: 64
2018-09-11 10:58:35.831 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2018-09-11 10:58:35.831 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.cacheTrimInterval: 8192
2018-09-11 10:58:35.831 [DEBUG] [.netty.buffer.PooledByteBufAllocator] - -Dio.netty.allocator.useCacheForAllThreads: true
2018-09-11 10:58:35.905 [DEBUG] [ty.channel.MultithreadEventLoopGroup] - -Dio.netty.eventLoopThreads: 8
2018-09-11 10:58:35.952 [DEBUG] [ython.netty.channel.nio.NioEventLoop] - -Dio.netty.noKeySetOptimization: false
2018-09-11 10:58:35.952 [DEBUG] [ython.netty.channel.nio.NioEventLoop] - -Dio.netty.selectorAutoRebuildThreshold: 512
2018-09-11 10:58:35.953 [DEBUG] [etty.util.internal.PlatformDependent] - org.jctools-core.MpscChunkedArrayQueue: available
2018-09-11 10:58:36.286 [DEBUG] [o.client.mqttv3.internal.ClientState] - paho1074679409746: received bytes count=1
The script triggering the issue:
"""OmnikOpenHAB program.
Get data from an Omnik inverter with 602xxxxx - 606xxxx ans save the data in
OpenHAB items.
"""
scriptExtension.importPreset("RuleSupport")
scriptExtension.importPreset("RuleSimple")
from org.slf4j import LoggerFactory
import socket # Needed for talking to inverter
import sys
import ConfigParser
import os
import struct # Converting bytes to numbers
class OmnikOpenhab(object):
"""
Get data from Omniksol inverter and store the data in OpenHAB items.
"""
global logger
logger = LoggerFactory.getLogger("org.eclipse.smarthome.model.script.rules")
def __init__(self, config_file):
logger.info("omnikOPENHAB - Starting")
# Load the settings
path = "/etc/openhab2/automation/jsr223/"
config_files = path+config_file
self.config = ConfigParser.RawConfigParser()
self.config.read(config_files)
def getInverters(self):
#Get number of inverters
inverterCount = len(self.config.sections())-2
logger.info("omnikOPENHAB - Invertercount: {0}".format(inverterCount))
#Reset totals to zero
OmnikOpenhab.total_e_today = 0
OmnikOpenhab.total_e_total = 0
OmnikOpenhab.total_p_ac = 0
#For each inverter, get data and add to total
for i in range(1,inverterCount+1):
#logger.info("omnikOPENHAB - In the inverterloop, value of index: {0}".format(i))
msg = self.run(i)
self.add(msg)
if msg:
etotal = self.config.get('openhab_items', 'etotal')
logger.info("omnikOPENHAB - Item for total energy: {0} updated with {1}".format(etotal,OmnikOpenhab.total_e_total))
events.postUpdate(str(etotal), str(OmnikOpenhab.total_e_total))
etoday = self.config.get('openhab_items', 'etoday')
logger.info("omnikOPENHAB - Item for today's energy: {0} updated with {1}".format(etoday,OmnikOpenhab.total_e_today))
events.postUpdate(str(etoday), str(OmnikOpenhab.total_e_today))
epower = self.config.get('openhab_items', 'epower')
logger.info("omnikOPENHAB - Item for actual power: {0} updated with {1}".format(epower,OmnikOpenhab.total_p_ac))
events.postUpdate(str(epower), str(OmnikOpenhab.total_p_ac))
logger.info("omnikOPENHAB - End")
else:
logger.info("Could not get inverter data, after sunset?")
def add(self,msg):
#logger.info("omnikOPENHAB - Adding data")
OmnikOpenhab.total_e_today += msg.e_today
OmnikOpenhab.total_e_total += msg.e_total
OmnikOpenhab.total_p_ac += msg.p_ac(1) + msg.p_ac(2) + msg.p_ac(3)
def run(self,inverternr):
"""Get information from inverter and store is configured outputs."""
# Connect to inverter
ip = self.config.get('inverter' + str(inverternr), 'ip')
port = self.config.get('inverter' + str(inverternr), 'port')
for res in socket.getaddrinfo(ip, port, socket.AF_INET, socket.SOCK_STREAM):
family, socktype, proto, canonname, sockadress = res
try:
logger.info("omnikOPENHAB - connecting to {0} port {1}".format(ip, port))
inverter_socket = socket.socket(family, socktype, proto)
inverter_socket.settimeout(10)
inverter_socket.connect(sockadress)
except socket.error as msg:
logger.info("omnikOPENHAB - Could not connect to inverter. Exiting...")
sys.exit(0)
wifi_serial = self.config.getint('inverter' + str(inverternr), 'wifi_sn')
inverter_socket.sendall(OmnikOpenhab.generate_string(wifi_serial))
data = inverter_socket.recv(1024)
inverter_socket.close()
msg = InverterMsg(data)
#logger.info("omnikOPENHAB - ID: {0}".format(msg.id))
return(msg)
def override_config(self, section, option, value):
"""Override config settings"""
self.config.set(section, option, value)
@staticmethod
def generate_string(serial_no):
"""Create request string for inverter.
The request string is build from several parts. The first part is a
fixed 4 char string; the second part is the reversed hex notation of
the s/n twice; then again a fixed string of two chars; a checksum of
the double s/n with an offset; and finally a fixed ending char.
Args:
serial_no (int): Serial number of the inverter
Returns:
str: Information request string for inverter
"""
response = '\x68\x02\x40\x30'
double_hex = hex(serial_no)[2:] * 2
hex_list = [double_hex[i:i + 2].decode('hex') for i in
reversed(range(0, len(double_hex), 2))]
cs_count = 115 + sum([ord(c) for c in hex_list])
checksum = hex(cs_count)[-2:].decode('hex')
response += ''.join(hex_list) + '\x01\x00' + checksum + '\x16'
return response
class InverterMsg(object):
"""Decode the response message from an omniksol inverter."""
raw_msg = ""
def __init__(self, msg, offset=0):
self.raw_msg = msg
self.offset = offset
def __get_string(self, begin, end):
"""Extract string from message.
Args:
begin (int): starting byte index of string
end (int): end byte index of string
Returns:
str: String in the message from start to end
"""
return self.raw_msg[begin:end]
def __get_short(self, begin, divider=10):
"""Extract short from message.
The shorts in the message could actually be a decimal number. This is
done by storing the number multiplied in the message. So by dividing
the short the original decimal number can be retrieved.
Args:
begin (int): index of short in message
divider (int): divider to change short to float. (Default: 10)
Returns:
int or float: Value stored at location `begin`
"""
num = struct.unpack('!H', self.raw_msg[begin:begin + 2])[0]
if num == 65535:
return -1
else:
return float(num) / divider
def __get_long(self, begin, divider=10):
"""Extract long from message.
The longs in the message could actually be a decimal number. By
dividing the long, the original decimal number can be extracted.
Args:
begin (int): index of long in message
divider (int): divider to change long to float. (Default : 10)
Returns:
int or float: Value stored at location `begin`
"""
return float(
struct.unpack('!I', self.raw_msg[begin:begin + 4])[0]) / divider
@property
def id(self):
"""ID of the inverter."""
return self.__get_string(15, 31)
@property
def temperature(self):
"""Temperature recorded by the inverter."""
return self.__get_short(31)
@property
def power(self):
"""Power output"""
print self.__get_short(59)
@property
def e_total(self):
"""Total energy generated by inverter in kWh"""
return self.__get_long(71)
def v_pv(self, i=1):
"""Voltage of PV input channel.
Available channels are 1, 2 or 3; if not in this range the function will
default to channel 1.
Args:
i (int): input channel (valid values: 1, 2, 3)
Returns:
float: PV voltage of channel i
"""
if i not in range(1, 4):
i = 1
num = 33 + (i - 1) * 2
return self.__get_short(num)
def i_pv(self, i=1):
"""Current of PV input channel.
Available channels are 1, 2 or 3; if not in this range the function will
default to channel 1.
Args:
i (int): input channel (valid values: 1, 2, 3)
Returns:
float: PV current of channel i
"""
if i not in range(1, 4):
i = 1
num = 39 + (i - 1) * 2
return self.__get_short(num)
def i_ac(self, i=1):
"""Current of the Inverter output channel
Available channels are 1, 2 or 3; if not in this range the function will
default to channel 1.
Args:
i (int): output channel (valid values: 1, 2, 3)
Returns:
float: AC current of channel i
"""
if i not in range(1, 4):
i = 1
num = 45 + (i - 1) * 2
return self.__get_short(num)
def v_ac(self, i=1):
"""Voltage of the Inverter output channel
Available channels are 1, 2 or 3; if not in this range the function will
default to channel 1.
Args:
i (int): output channel (valid values: 1, 2, 3)
Returns:
float: AC voltage of channel i
"""
if i not in range(1, 4):
i = 1
num = 51 + (i - 1) * 2
return self.__get_short(num)
def f_ac(self, i=1):
"""Frequency of the output channel
Available channels are 1, 2 or 3; if not in this range the function will
default to channel 1.
Args:
i (int): output channel (valid values: 1, 2, 3)
Returns:
float: AC frequency of channel i
"""
if i not in range(1, 4):
i = 1
num = 57 + (i - 1) * 4
return self.__get_short(num, 100)
def p_ac(self, i=1):
"""Power output of the output channel
Available channels are 1, 2 or 3; if no tin this range the function will
default to channel 1.
Args:
i (int): output channel (valid values: 1, 2, 3)
Returns:
float: Power output of channel i
"""
if i not in range(1, 4):
i = 1
num = 59 + (i - 1) * 4
return int(self.__get_short(num, 1)) # Don't divide
@property
def e_today(self):
"""Energy generated by inverter today in kWh"""
return self.__get_short(69, 100) # Divide by 100
@property
def h_total(self):
"""Hours the inverter generated electricity"""
return int(self.__get_long(75, 1)) # Don't divide
class myRule(SimpleRule):
def execute(self, module, inputs):
omnik_openhab = OmnikOpenhab('omnikOpenHAB.cfg')
omnik_openhab.getInverters()
#Housekeeping below
omnik = myRule()
omnik.setTriggers([Trigger("aTimerTrigger", "timer.GenericCronTrigger", Configuration({"cronExpression": "0 * * * * ?"}))])
automationManager.addRule(omnik)