CUL2MQTT/cul2mqtt.py

#!/usr/bin/python3 -u
#

# pip3 install pyyaml paho-mqtt pyserial

import yaml
from yaml.constructor import ConstructorError

import serial
import sys
import time
from time import sleep
from time import localtime, strftime
import datetime
import paho.mqtt.client as mqtt
import json
import os
import re
import configparser

version = 0.3

# Change working dir to the same dir as this script
os.chdir(sys.path[0])

config = configparser.ConfigParser()
config.read('cul2mqtt.ini')

# global variables
verbose = False
debug = False
quiet = True

serialCULAvailable = False
devdata = {}
RXcodesToDevFunction_IT = {}
RXcodesToDevFunction_RAW = {}
InTopicsToDevIds = {}


# config vars
deviceConfigFile = config['main'].get('devices_config_yml')

log_enable = config['main'].getboolean('log_enable')
log_path = config['main'].get('log_path')
if not os.path.exists(log_path):
    os.makedirs(log_path)

mqtt_server = config['mqtt'].get('server')
mqtt_port = config['mqtt'].getint('port')
mqtt_user = config['mqtt'].get('user')
mqtt_password = config['mqtt'].get('password')

TX_interface_prefer = config['cul'].get('TX_interface_prefer') # UART or MQTT
if TX_interface_prefer is None: # compatibility with old ini file structure
    TX_interface_prefer = config['main'].get('TX_interface_prefer') # UART or MQTT

repeat_received_commands = False # not yet implemented

if len(sys.argv) >= 2:
    if sys.argv[1] == "-q":
        verbose = False
        debug = False
        quiet = True
    elif sys.argv[1] == "-v":
        verbose = True
        debug = False
        quiet = False
    elif sys.argv[1] == "-d":
        verbose = True
        debug = True
        quiet = False

# serial (USB) CUL device
receive_from_serial_cul = config['cul'].getboolean('receive_from_serial_cul')
send_on_serial_cul = config['cul'].getboolean('send_on_serial_cul')
serialPort = config['cul'].get('serialPort')
serialBaudrate = config['cul'].getint('serialBaudrate')
serialTimeout = config['cul'].getint('serialTimeout')


# CUL init command for normal operation, i.E. X21, X05 
culInitCmd = config['cul'].get('culInitCmd') + '\r\n'
culSendsRSSI = config['cul'].getboolean('culSendsRSSI') # set depending on culInitCmd chosen

serialCulInitTimeout = config['cul'].getint('serialCulInitTimeout')
forceSerialCULConnected = config['cul'].getboolean('forceSerialCULConnected')

# MQTT CUL
receive_from_mqtt_cul = config['cul'].getboolean('receive_from_mqtt_cul')
send_on_mqtt_cul = config['cul'].getboolean('send_on_mqtt_cul')
mqtt_cul_topic_received = config['cul'].get('mqtt_cul_topic_received')
mqtt_cul_topic_send = config['cul'].get('mqtt_cul_topic_send')

filterSelfSentIncomingTimeout = config['main'].get('filterSelfSentIncomingTimeout')


try:
    from yaml import CLoader as Loader
except ImportError:
    from yaml import Loader
    
def no_duplicates_constructor(loader, node, deep=False):
    """Check for duplicate keys."""
    mapping = {}
    for key_node, value_node in node.value:
        key = loader.construct_object(key_node, deep=deep)
        value = loader.construct_object(value_node, deep=deep)
        if key in mapping:
            raise ConstructorError("while constructing a mapping", node.start_mark, "found duplicate key (%s)" % key, key_node.start_mark)
        mapping[key] = value
    return loader.construct_mapping(node, deep)

yaml.add_constructor(yaml.resolver.BaseResolver.DEFAULT_MAPPING_TAG, no_duplicates_constructor)


log_last_date = None
logfilehandle = False


def log_start():
    global logfilehandle, log_last_date
    if log_enable:
        if not os.path.exists(log_path):
            os.makedirs(log_path)
            
        try:
            _log_current_date = strftime("%Y%m%d")
            _logfilename = _log_current_date + ".log"
            logfilehandle = open(log_path + '/' + _logfilename, 'a')
            log_last_date = _log_current_date
        except:
            pass


def log_rotate():
    global logfilehandle, log_last_date
    if log_enable:
        _log_current_date = strftime("%Y%m%d")
        
        if log_last_date != _log_current_date:
            try:
                logfilehandle.close()
                _logfilename = _log_current_date + ".log"
                logfilehandle = open(log_path + '/' + _logfilename, 'a')
                log_last_date = _log_current_date
            except:
                pass
            
            
def log_write(_msg):
    global logfilehandle
    if not quiet: print(_msg)
    log_rotate()
    if log_enable:
        try:
            logfilehandle.write("[" + str(datetime.datetime.now()) + "] " + _msg + "\n")
            logfilehandle.flush()
        except:
            # guat dann hoit ned...
            pass

log_start()

log_write("CUL2MQTT v" + str(version))
log_write("=====================================")

try:
    with open(deviceConfigFile) as devfile:
        devdata = yaml.load(devfile, Loader=yaml.FullLoader)
        if debug:
            log_write("")
            log_write("")
            log_write("==== parsing config file ====")
            log_write("")
            log_write(devdata)
            log_write("")
        
        for deviceid in devdata:
            if debug:
                log_write("")
                log_write("")
                log_write("Device: " + deviceid)
                log_write(devdata[deviceid])
            
            if "RX" in devdata[deviceid].keys():
                if devdata[deviceid]["RX"] != "":
                    if debug:
                        log_write("RX codes:")
                    for key, value in devdata[deviceid]["RX"].items():
                        if debug:
                            log_write(str(key) + "->" + str(value))
                        if value.startswith("i"):
                            # is Intertechno RX code
                            if value in RXcodesToDevFunction_IT.keys():
                                log_write("")
                                log_write("")
                                log_write("ERROR: RX-string '" + str(value) + "' is already defined for another device! Must be unique.")
                                raise
                            else:
                                RXcodesToDevFunction_IT[value] = deviceid, key
                        else:
                            # is other RX code - lets call it RAW
                            if value in RXcodesToDevFunction_RAW.keys():
                                log_write("")
                                log_write("")
                                log_write("ERROR: RX-string '" + str(value) + "' is already defined for another device! Must be unique.")
                                raise
                            else:
                                RXcodesToDevFunction_RAW[value] = deviceid, key
            
            if "cmdTopic" in devdata[deviceid].keys():
                if devdata[deviceid]["cmdTopic"] != "":
                    cmdTopic = devdata[deviceid]["cmdTopic"]
                    if debug:
                        log_write("cmdTopic: " + cmdTopic)
                    if cmdTopic in InTopicsToDevIds.keys():
                        log_write("")
                        log_write("")
                        log_write("ERROR: cmdTopic '" + str(cmdTopic) + "' is already defined for another device! Must be unique.")
                        raise
                    else:
                        InTopicsToDevIds[cmdTopic] = deviceid
            
        if debug:
            log_write("")
            log_write("")
            log_write("")
            log_write("RXcodesToDevFunction_IT:")
            log_write(RXcodesToDevFunction_IT)
            log_write("")
            log_write("")
            log_write("RXcodesToDevFunction_RAW:")
            log_write(RXcodesToDevFunction_RAW)
            log_write("")
            log_write("")
            log_write("InTopicsToDevIds:")
            log_write(InTopicsToDevIds)
            log_write("")
            log_write("")
            log_write("InTopicsToDevIds.keys():")
            log_write(InTopicsToDevIds.keys())
            log_write("")
            log_write("")
            log_write("devdata.keys():")
            log_write(devdata.keys())
            log_write("")
            log_write("")
            log_write("==== parsing config file complete ====")
            log_write("")
            log_write("")
            log_write("")
            log_write("")

except ConstructorError as err:
    log_write("ERROR on parsing configfile:")
    log_write(err)
    exit(1)
except:
    log_write("ERROR opening configfile")
    log_write("Unexpected error: " + str(sys.exc_info()[0]))
    exit(1)


lastReceivedMaxAge = config['main'].getint('lastReceivedMaxAge') # ignore repeated messages when they are younger than x ms

lastReceivedTime = dict()

lastSentTime = {}
lastSentMinInterval = config['main'].getint('lastSentMinInterval') # ignore repeated messages when they are younger than x ms, should be > 1500 

lastSentCmd = ""
lastSentCmdTime = 0
lastSentDev = ""
lastSentDevCmd = ""

def touch(fname, times=None):
    with open(fname, 'a'):
        os.utime(fname, times)

def on_connect(client, userdata, flags, rc):
    if verbose:
        log_write("MQTT connected with result code " + str(rc))
    if receive_from_mqtt_cul:
        if mqtt_cul_topic_received != "":
            client.subscribe(mqtt_cul_topic_received)
            
            if mqtt_cul_topic_send != "":
                #client.publish
                mqttc.publish(mqtt_cul_topic_send, culInitCmd, qos=0, retain=False)
            
    for in_topic in InTopicsToDevIds.keys():
        if in_topic != "":
            client.subscribe(in_topic)
            if verbose:
                log_write("MQTT subscribed: " + in_topic)

def on_disconnect(client, userdata, rc):
    if rc != 0:
        log_write("Unexpected MQTT disconnection. Will auto-reconnect")
        
def on_message(client, userdata, msg):
    #print(msg.topic + ": " + str(msg.payload))
    payload = msg.payload.decode("utf-8")
    
    if verbose:
        log_write("")
        log_write("MQTT received: " + msg.topic + " -> " + str(payload))
    
    # MQTT message is output from CUL
    if receive_from_mqtt_cul and msg.topic == mqtt_cul_topic_received:
        payload = payload.rstrip()
            
        # support output from Tasmota SerialBridge on tele/[DEVICE]/RESULT topic
        # example: {"SerialReceived":"p10  144   80  480   48   32 1360  28  1  3 4   160  6336     0 735C1470"}
        if payload.startswith('{"SerialReceived":'):
            payload_json = json.loads(payload)
            payload = payload_json.get('SerialReceived')
            if payload != None:
                cul_received(payload, "MQTT") # to lower case as MQTT CUL via Tasmota SerialBridge with Rule changes output to all uppercase
                if verbose:
                    log_write("MQTT-CUL RX: '" + payload + "'")
        elif not payload.startswith('{'):
            # ignore everything different starting with { 
            cul_received(payload.lower(), "MQTT") # to lower case as MQTT CUL via Tasmota SerialBridge with Rule changes output to all uppercase
            if verbose:
                log_write("MQTT-CUL RX: '" + payload.lower() + "'")
        
    else:
        for in_topic, dev in InTopicsToDevIds.items():
            if msg.topic == in_topic:
                if verbose: log_write("MQTT received - '" + msg.topic + "' = '" + payload + "' => DEV: " + dev)
                
                if 'name' in devdata[dev].keys():
                    log_write('devName: ' + devdata[dev]['name'])
                
                global lastSentDev, lastSentDevCmd, lastSentCmdTime
                now = int(round(time.time() * 1000))
                if debug:
                    log_write("dev="+dev+", lastSentDevCmd="+lastSentDevCmd)
                if dev == lastSentDev and payload == lastSentDevCmd and (now - lastSentCmdTime) < 1000:
                    if verbose:
                        log_write("MQTT: ignored command as we just sent this.")
                else:
                    cul_send(dev, payload)
                    
                if 'statTopic' in devdata[dev].keys():
                    if verbose: log_write('statTopic: ' + devdata[dev]['statTopic'])
                    mqttc.publish(devdata[dev]['statTopic'], payload, qos=0, retain=False)
                    
                if 'add_statTopics_on' in devdata[dev].keys():
                    if verbose: log_write("add_statTopics_on:")
                    for res in devdata[dev]['add_statTopics_on']:
                        if 'on_payload' in res and 'topic' in res and 'payload' in res:
                            if payload == res['on_payload'] and payload != "" and res['topic'] != "" and res['payload'] != "":
                                if verbose: log_write("  on '" + payload + "': '" + res['payload'] + "' => '" + res['topic'] + "'")
                                mqttc.publish(res['topic'], res['payload'], qos=0, retain=False)

                    
def publish_device_statusupdate(device, cmd, value):
    if device in devdata.keys():
        if 'statTopic' in devdata[device].keys():
            statTopic = devdata[device].get('statTopic')
            
            if value is not None and cmd == "%VALUE%": 
                if verbose: log_write("    MQTT publish: '" + value + "' -> '" + statTopic + "'")
                mqttc.publish(statTopic, value, qos=0, retain=False)
            else: 
                if verbose: log_write("    MQTT publish: '" + cmd + "' -> '" + statTopic + "'")
                mqttc.publish(statTopic, cmd, qos=0, retain=False)
        
        if 'add_statTopics_on' in devdata[device].keys():
            if verbose: log_write("    MQTT publish add_statTopics_on:")
            for res in devdata[device].get('add_statTopics_on'):
                if 'on_payload' in res and 'topic' in res and 'payload' in res:
                    if cmd == res['on_payload']:
                        if verbose: log_write("        on '" + res['on_payload'] + "' -> publish '" + res['payload'] + "' on topic '" + res['topic'] + "'")
                        mqttc.publish(res['topic'], res['payload'], qos=0, retain=False)
                        
        if 'add_statTopics' in devdata[device].keys():
            if verbose: log_write("    MQTT publish on add_statTopics:")
            for res in devdata[device]['add_statTopics']:
                if verbose: log_write("        '" + cmd + "' -> '" + res + "'")
                mqttc.publish(res, cmd, qos=0, retain=False)
        


def parseRXCode(rx_code, source_cul):
    receivedForDevice = None
    receivedCmnd = None
    receivedValue = None
    
    if rx_code.startswith("i"):
        # parse Intertechno RX code
        if debug: log_write("    PROTOCOL: Intertechno")
        sucessfullyParsedITCode = False
        
        # look if this code is in the device_config
        if rx_code in RXcodesToDevFunction_IT:
            if debug: log_write("    code found in device config")
            receivedForDevice = RXcodesToDevFunction_IT[rx_code][0]
            receivedCmnd = RXcodesToDevFunction_IT[rx_code][1]
            sucessfullyParsedITCode = True
            if debug: log_write("    DEV: " + receivedForDevice + ", CMD: " + receivedCmnd + ", RX: " + rx_code)
            if verbose: 
                #log_write("")
                log_write("    CUL '" + source_cul + "' received '" + rx_code + "' => DEV: " + receivedForDevice + ", CMD: " + receivedCmnd)
        
        # if this had no result -> try again with last 16 bit stripped, as in many cases this is only RSSI and not part of the code
        # in this case treat this last 16bit as sensor value
        rx_code_stripped = rx_code[0:-2]
        if not sucessfullyParsedITCode and rx_code_stripped in RXcodesToDevFunction_IT:
            if debug: log_write("    code found in device config with last 16 bit stripped")
            receivedForDevice = RXcodesToDevFunction_IT[rx_code_stripped][0]
            receivedCmnd = RXcodesToDevFunction_IT[rx_code_stripped][1]
            
            receivedValue = rx_code[-2:]
            
            # convert value to decimal if enabled for this device
            if "convertValueToDecimal" in devdata[receivedForDevice]:
                if devdata[receivedForDevice]["convertValueToDecimal"] == True:
                    if debug: log_write("    converting value to decimal")
                    receivedValue = str(int(receivedValue, base=16))
            
            sucessfullyParsedITCode = True
            if debug: log_write("    DEV: " + receivedForDevice + ", CMD: " + receivedCmnd + ", VALUE: " + receivedValue + ", RX: " + rx_code_stripped)
            if verbose: 
                #log_write("")
                log_write("    CUL '" + source_cul + "' received '" + rx_code_stripped + "' => DEV: " + receivedForDevice + ", CMD: " + receivedCmnd + ", VALUE: " + receivedValue)
        
        # if this also did not work, try to parse it as "default/cheap" Intertechno code... 
        if not sucessfullyParsedITCode:
            if debug: log_write("    treat code as 'default/cheap' Intertechno code...")
            try:
                receivedForDevice, receivedCmnd = decodeInterTechnoRX(rx_code_stripped)
            except:
                log_write("    Error parsing code as 'default/cheap' Intertechno code.")
            if debug: 
                log_write(str(receivedForDevice) + ", " + str(receivedCmnd))
            
    else:
        # parse other/RAW RX code
        if debug: log_write("    PROTOCOL: OTHER/RAW")
        if rx_code in RXcodesToDevFunction_RAW:
            receivedForDevice = RXcodesToDevFunction_RAW[rx_code][0]
            receivedCmnd = RXcodesToDevFunction_RAW[rx_code][1]
            if debug: log_write("    DEV: " + receivedForDevice + ", CMD: " + receivedCmnd + ", RX: " + rx_code)
            if verbose: 
                #log_write("")
                log_write("    CUL '" + source_cul + "' received '" + rx_code + "' => DEV: " + receivedForDevice + ", CMD: " + receivedCmnd)
    
    #if debug: 
    #    log_write("    DEV: " + str(receivedForDevice) + ", CMD: " + str(receivedCmnd) + ", RX: " + rx_code)
    
    if receivedForDevice != None and receivedCmnd != None and receivedForDevice != False and receivedCmnd != False:
        publish_device_statusupdate(receivedForDevice, receivedCmnd, receivedValue)

def decodeInterTechnoRX(rx_code):
    # decode old fixed code from Intertechno remotes
    _housecode = None
    _devaddr = None
    _command = None
    _itname = None
    
    #print(rx_code[0:1])
    #print(rx_code[1:3])
    #print(rx_code[3:5])
    #print(rx_code[5:7])
    
    if rx_code[0:1] == "i": 
        if rx_code[1:3] == "00": _housecode = "A"
        elif rx_code[1:3] == "40": _housecode = "B"
        elif rx_code[1:3] == "10": _housecode = "C"
        elif rx_code[1:3] == "50": _housecode = "D"
        elif rx_code[1:3] == "04": _housecode = "E"
        elif rx_code[1:3] == "44": _housecode = "F"
        elif rx_code[1:3] == "14": _housecode = "G"
        elif rx_code[1:3] == "54": _housecode = "H"
        elif rx_code[1:3] == "01": _housecode = "I"
        elif rx_code[1:3] == "41": _housecode = "J"
        elif rx_code[1:3] == "11": _housecode = "K"
        elif rx_code[1:3] == "51": _housecode = "L"
        elif rx_code[1:3] == "05": _housecode = "M"
        elif rx_code[1:3] == "45": _housecode = "N"
        elif rx_code[1:3] == "15": _housecode = "O"
        elif rx_code[1:3] == "55": _housecode = "P"
        
        if rx_code[3:5] == "00": _devaddr = "1"
        elif rx_code[3:5] == "40": _devaddr = "2"
        elif rx_code[3:5] == "10": _devaddr = "3"
        elif rx_code[3:5] == "50": _devaddr = "4"
        elif rx_code[3:5] == "04": _devaddr = "5"
        elif rx_code[3:5] == "44": _devaddr = "6"
        elif rx_code[3:5] == "14": _devaddr = "7"
        elif rx_code[3:5] == "54": _devaddr = "8"
        elif rx_code[3:5] == "01": _devaddr = "9"
        elif rx_code[3:5] == "41": _devaddr = "10"
        elif rx_code[3:5] == "11": _devaddr = "11"
        elif rx_code[3:5] == "51": _devaddr = "12"
        elif rx_code[3:5] == "05": _devaddr = "13"
        elif rx_code[3:5] == "45": _devaddr = "14"
        elif rx_code[3:5] == "15": _devaddr = "15"
        elif rx_code[3:5] == "55": _devaddr = "16"
        
        if rx_code[5:7] == "15": _command = "ON"
        elif rx_code[5:7] == "14": _command = "OFF"
        
        if _housecode != None and _devaddr != None and _command != None:
            _itname = "IT_" + _housecode + _devaddr
            if debug: log_write("valid IT code: '" + _itname + "' => '" + _command + "'")
            return _itname, _command
            
        else:
            if debug: log_write("unknown or invalid IT code '" + rx_code + "'")
            return False, False

    else:
        if debug: log_write("unknown or invalid IT code '" + rx_code + "'")

def encodeInterTechnoRX(itname, cmd):
    # decode old fixed code from InterTechno remotes
    _housecode = None
    _devaddr = None
    _command = None
    
    #print(itname[0:3])
    #print(itname[3:4])
    #print(itname[4:])
    
    if itname[0:3] == "IT_": 
        if itname[3:4] == "A": _housecode = "00"
        elif itname[3:4] == "B": _housecode = "40"
        elif itname[3:4] == "C": _housecode = "10"
        elif itname[3:4] == "D": _housecode = "50"
        elif itname[3:4] == "E": _housecode = "04"
        elif itname[3:4] == "F": _housecode = "44"
        elif itname[3:4] == "G": _housecode = "14"
        elif itname[3:4] == "H": _housecode = "54"
        elif itname[3:4] == "I": _housecode = "01"
        elif itname[3:4] == "J": _housecode = "41"
        elif itname[3:4] == "K": _housecode = "11"
        elif itname[3:4] == "L": _housecode = "51"
        elif itname[3:4] == "M": _housecode = "05"
        elif itname[3:4] == "N": _housecode = "45"
        elif itname[3:4] == "O": _housecode = "15"
        elif itname[3:4] == "P": _housecode = "55"
        
        if itname[4:] == "1": _devaddr = "00"
        elif itname[4:] == "2": _devaddr = "40"
        elif itname[4:] == "3": _devaddr = "10"
        elif itname[4:] == "4": _devaddr = "50"
        elif itname[4:] == "5": _devaddr = "04"
        elif itname[4:] == "6": _devaddr = "44"
        elif itname[4:] == "7": _devaddr = "14"
        elif itname[4:] == "8": _devaddr = "54"
        elif itname[4:] == "9": _devaddr = "01"
        elif itname[4:] == "10": _devaddr = "41"
        elif itname[4:] == "11": _devaddr = "11"
        elif itname[4:] == "12": _devaddr = "51"
        elif itname[4:] == "13": _devaddr = "05"
        elif itname[4:] == "14": _devaddr = "45"
        elif itname[4:] == "15": _devaddr = "15"
        elif itname[4:] == "16": _devaddr = "55"
        
        if cmd == "ON": _command = "15"
        elif cmd == "OFF": _command = "14"
        
        if debug: print("IT housecode=", _housecode, "- devaddr=", _devaddr, "- command=", _command)
                
        if _housecode != None and _devaddr != None and _command != None:
            _rxcode = "i" + _housecode + _devaddr + _command
            #print("encoded IT RX code: '" + itname + "' => '" + cmd + "' = '" + _rxcode)
            return _rxcode
            
        else:
            if debug: log_write("    unknown or invalid IT code '" + rx_code + "'")
            return False
        
    else:
        if debug: log_write("    unknown or invalid IT code '" + rx_code + "'")

def cul_received(payload, source_cul):
    global lastReceivedTime, lastReceivedMaxAge
    
    if payload[:2] == 'is': # msg is reply from CUL to raw send command
        pass
        
    elif payload[:1] == 'i': # is a IT compatible code - so look it up in the code table
        
        if culSendsRSSI:
            inCmd = payload[:-2] # strip last 2 chars, depending on used CUL receive mode - if enabled this is only RSSI
        else:
            inCmd = payload
            
        if verbose:
            log_write("    inCmd: " + inCmd + ", receiving CUL: " + source_cul)
        
        # filter fast repeated codes (strip first char on Intertechno codes as the repetation will come in as RAW without "i" prefix)
        ignoreCommand = False
        if inCmd in lastReceivedTime.keys():
            lastTime = int(lastReceivedTime[inCmd])
            now = int(round(time.time() * 1000))
            tdelta = (now - lastTime)
            if debug: log_write("    TDELTA = " + str(tdelta))
            if debug: log_write("    lastTime = " + str(lastTime))
            
            if tdelta < lastReceivedMaxAge:
                if verbose: log_write("    ignoring code from CUL '" + source_cul + "', CMD: '" + inCmd + "' - already received " + str(tdelta) + " ms ago")
                ignoreCommand = True
        
        if not ignoreCommand:
            lastReceivedTime[inCmd] = int(round(time.time() * 1000))
            parseRXCode(inCmd, source_cul)
            
    elif payload[:1] == 'p': # is RAW data
        # example: "p11  288  864  800  320  288  832  33  1  4 1   288 10224     0 A4CEF09580"
        # split string and extract last row as we dont need the rest
        splitPayload = payload.split(' ')
        actualPayload = splitPayload[len(splitPayload)-1]
        if debug: log_write("    actualPayload: '" + actualPayload)
                
        ignoreCommand = False
                
        # handle/filter repetations of Intertechno codes
        isITrepetation = False
        if ('i'+actualPayload) in lastReceivedTime.keys():
            isITrepetation = True
            if debug: log_write("    skipping repeated Intertechno code")
            lastTime = int(lastReceivedTime['i'+actualPayload])
            now = int(round(time.time() * 1000))
            tdelta = (now - lastTime)
            if debug: log_write("    TDELTA = " + str(tdelta))
            if tdelta < lastReceivedMaxAge:
                if verbose: log_write("    ignoring code from CUL '" + source_cul + "', CMD: '" + 'i'+actualPayload + "' - already received " + str(tdelta) + " ms ago")
                ignoreCommand = True
                
        # filter fast repeated codes
        if not isITrepetation:
            if actualPayload in lastReceivedTime.keys():
                lastTime = int(lastReceivedTime[actualPayload])
                now = int(round(time.time() * 1000))
                tdelta = (now - lastTime)
                if debug: log_write("    TDELTA = " + str(tdelta))
                if tdelta < lastReceivedMaxAge:
                    if verbose: log_write("    ignoring code from CUL '" + source_cul + "', CMD: '" + actualPayload + "' - already received " + str(tdelta) + " ms ago")
                    ignoreCommand = True
        
        if not ignoreCommand:
            if isITrepetation:
                # treat as Intertechno code
                lastReceivedTime['i'+actualPayload] = int(round(time.time() * 1000))
                parseRXCode('i'+actualPayload, source_cul)
            else:
                lastReceivedTime[actualPayload] = int(round(time.time() * 1000))
                parseRXCode(actualPayload, source_cul)
                            
            #if repeat_received_commands:
            #    lastSentLength = len(lastSent)
            #    i = 0
            #    dontRepeat = False
            #    while i < lastSentLength:
            #        #print(str(i) + ": " + lastReceived[i])
            #        if lastSent[i] == decCmd:
            #            lastTime = int(lastSentTime[i])
            #            now = int(round(time.time() * 1000))
            #            tdelta = (now - lastTime)
            #            #print("TDELTA = " + str(tdelta))
            #            if tdelta < lastSentMaxAge:
            #                print("ignoring command as it originated from ourselfs " + inCmd + " " + str(tdelta) + " ms ago")
            #                dontRepeat = True
            #                #break
            #        i += 1
            #    #cmdToSend = culSendCmds[decCmd]
            #    if not dontRepeat:
            #        if device != "" and cmd != "":
            #            print("REPEATING COMMAND: " + cmd + " TO DEVICE " + device)
            #            cul_send(device, cmd)
            



def IT_RXtoTXCode(itReceiveCode):
    if debug: 
        statusstr = "IT_RXtoTXCode    "
        statusstr += "RX: "
        statusstr += itReceiveCode
        #print("IT_RXtoTXCode ReceiveCode:  " + itReceiveCode)
    
    itReceiveCode = itReceiveCode[1:] # remove first character "i"
    itReceiveCodeLengthBytes = int(len(itReceiveCode)/2)
    
    itReceiveCodeBytes = []
    itTransmitTristate = "is"
    
    for x in range(itReceiveCodeLengthBytes):
        itReceiveCodeBytes.append(bin(int(itReceiveCode[x*2:(x*2+2)],16))[2:].zfill(8))
        
    for x in range(len(itReceiveCodeBytes)):
        #print("IT REC byte " + str(x) + " = " + str(itReceiveCodeBytes[x]))
        for y in range(4):
            quarterbyte = str(itReceiveCodeBytes[x][y*2:y*2+2])
            if quarterbyte == "00":
                tmpTristate = "0";
            elif quarterbyte == "01":
                tmpTristate = "F";
            elif quarterbyte == "10":
                tmpTristate = "D";
            elif quarterbyte == "11":
                tmpTristate = "1";
            #print(quarterbyte +  " -> " + tmpTristate)
            itTransmitTristate = itTransmitTristate + tmpTristate
    
    if debug: 
        statusstr += " -> TX: "
        statusstr += itTransmitTristate
        #print("IT_RXtoTXCode TransmitCode: " + itTransmitTristate)
        log_write(statusstr)
    
    return(itTransmitTristate)
        
def cul_send(device, cmd):
    global lastSentTime
    culCmd = ""
    culSendCmdsKeyName = device + ' ' + cmd
    if debug: log_write("CUL send '" + cmd + "' to device '" + device + "'")
            
    tx_code = False
    
    if 'TX' in devdata[device]:
        if debug: print("TX data available, cmd="+cmd)
        if debug: print(devdata[device]['TX'])
        if cmd in devdata[device]['TX'].keys():
            tx_code = devdata[device]['TX'][cmd]
            if verbose: log_write("    TX code for '" + cmd + "': " + tx_code)
    
    if not tx_code:
        if verbose: log_write("    deviceID: " + device)
        if 'RX' in devdata[device].keys():
            if verbose: 
                log_write("    RX code configured, cmd=" + cmd)
                log_write(devdata[device]['RX'])
            if cmd in devdata[device]['RX'].keys():
                rx_code = devdata[device]['RX'][cmd]
                if debug: log_write("    RX code for '" + cmd + "': " + rx_code)
                tx_code = IT_RXtoTXCode(rx_code)
                if verbose: log_write("    TX code for '" + cmd + "': " + tx_code)
            else: 
                log_write("    RX code for '" + cmd + "' NOT FOUND")
                
        elif device.startswith("IT_"):
            # InterTechno device with fixed code - encode RX code for IT device name and convert to TX code
            rx_code = encodeInterTechnoRX(device, cmd)
            if rx_code:
                if debug: log_write("    RX code for '" + cmd + "': " + rx_code)
                tx_code = IT_RXtoTXCode(rx_code)
                if verbose: log_write("    TX code for '" + cmd + "': " + tx_code)
            
    if not tx_code:
        if verbose: log_write("    no valid TX code for this device/command")
    else:
        now = int(round(time.time() * 1000))
        
        # look if this command has been sent in the past, and when
        if culSendCmdsKeyName in lastSentTime.keys():
            lastTime = lastSentTime[culSendCmdsKeyName]
        else:
            lastTime = 0
            
        lastTimeAge = now - lastTime
        if verbose: log_write('    lastTime: ' + str(lastTimeAge) + 'ms ago')
        
        if lastTimeAge > lastSentMinInterval: # only send if last time + min interval is exceeded
            lastSentTime[culSendCmdsKeyName] = now # save what we send, so that we dont repeat our own sent messages if repeating is enabled
            
            TX_interface = TX_interface_prefer
            if 'TX_interface' in devdata[device].keys():
                if verbose: log_write("    TX_interface: " + devdata[device]['TX_interface'])
                
            if TX_interface == "UART" and not serialCULAvailable:
                TX_interface = "MQTT"
            
            global lastSentCmd, lastSentCmdTime, lastSentDev, lastSentDevCmd
            lastSentCmd = tx_code
            lastSentCmdTime = now
            lastSentDev = device
            lastSentDevCmd = cmd
            
            if send_on_mqtt_cul and (TX_interface == "MQTT" or TX_interface == "both"):
                log_write("    TX via MQTT: " + tx_code)
                mqttc.publish(mqtt_cul_topic_send, tx_code, qos=0, retain=False)
                
            if serialCULAvailable and send_on_serial_cul and (TX_interface == "UART" or TX_interface == "both"):
                log_write("    TX via UART: " + tx_code)
                culCmd = tx_code + '\r\n'
                ser.write(culCmd.encode('ascii'))
                
        else:
            log_write("WARNING: CUL send command repeated too quickly.")
            
    publish_device_statusupdate(device, cmd, None)


# main
if receive_from_serial_cul or send_on_serial_cul:
    if not os.path.exists(serialPort):
        log_write("ERROR opening connection to serial CUL... device '" + serialPort + "' does not exist.")
        if log_enable: log_write("CUL2MQTT v"+str(version)+" starting")
        
        if receive_from_mqtt_cul:
            if forceSerialCULConnected:
                exit(2)
            else:
                log_write("resuming in MQTT-CUL only mode...")
                TX_interface_prefer = "MQTT"
                receive_from_serial_cul = False
                send_on_serial_cul = False
                serialCULAvailable = False
                log_write("")
                log_write("")
    else:
        log_write("opening connection to UART-CUL...")
        serLine = ""
        ser = serial.Serial(port=serialPort,baudrate=serialBaudrate,parity=serial.PARITY_NONE,stopbits=serial.STOPBITS_ONE,bytesize=serial.EIGHTBITS,timeout=serialTimeout)
        sleep(serialCulInitTimeout)
        ser.write('V\r\n'.encode('ascii'))  # get CUL version info
        serLine = ser.readline()
        serLine = serLine.decode('ascii').rstrip('\r\n')
        if serLine.startswith("V ") and serLine.find("culfw") != -1:
            log_write("connected. CUL version: " + serLine)
            serialCULAvailable = True
            sleep(0.1)
            log_write('Initializing CUL with command: ' + culInitCmd.rstrip('\r\n'))
            ser.write(culInitCmd.encode('ascii'))  # initialize CUL in normal receive mode
            sleep(0.5)
        else:
            log_write("WARNING: could not connect UART-CUL")
            receive_from_serial_cul = False
            send_on_serial_cul = False
            serialCULAvailable = False
            TX_interface_prefer = "MQTT"
            if forceSerialCULConnected:
                exit(2)

mqttc = mqtt.Client()
mqttc.on_connect = on_connect
mqttc.on_disconnect = on_disconnect
mqttc.on_message = on_message

if mqtt_user is not None and mqtt_password is not None:
    if len(mqtt_user) > 0 and len(mqtt_password) > 0:
        mqttc.username_pw_set(mqtt_user, mqtt_password)
    
mqttc.connect(mqtt_server, mqtt_port, 60)
mqttc.loop_start()

while True:
    if receive_from_serial_cul:
        serLine = ser.readline()
        if len(serLine) > 0:
            now = int(round(time.time() * 1000))
            recvCmd = serLine.decode('ascii')
            recvCmd = recvCmd.rstrip('\r\n')
            
            #if debug:
            #    print("lastSentCmd: " + lastSentCmd + ", lastSentCmdTime=" + str(lastSentCmdTime))
            
            if recvCmd == lastSentCmd and (now - lastSentCmdTime) < filterSelfSentIncomingTimeout:
                pass
            else:
                if verbose:
                    log_write("")
                    log_write("UART-CUL RX: '" + recvCmd + "'")
                cul_received(recvCmd, "UART")
        
    sleep(0.05)
    
##         #print "test"
##         #touch("/tmp/culagent_running")

#except KeyboardInterrupt:
#    print("\n")