Custom Driver Abnormal Behavior

Thanks for the help from @holand.ivar now I have a Custom Driver for
my Tuya Vertical Blinds and integration is 100% local.

Driver works but has some abnormal behavior. Of course, I was talking
to the author of this driver but he is confused why driver exhibits some
abnormal behavior. I really would like if not fix the driver but at least to
understand what is going on. So, I decided to ask driver gurus on a forum
for a help.

Here is a driver code:

/**
 * Copyright 2022 Ivar Holand
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *     http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
metadata {
	definition(name: "Tuya Generic Window Blind", namespace: "iholand", author: "iholand") {
		capability "Actuator"
		capability "Sensor"
		capability "WindowBlind"
//		capability "WindowShade"

		command "status"

		attribute "availableEndpoints", "String"
	}
}

preferences {
	section("URIs") {
		input "ipaddress", "text", title: "Device IP:", required: false
		input "devId", "text", title: "Device ID:", required: false
		input "localKey", "text", title: "Device local key:", required: false
		input name: "logEnable", type: "bool", title: "Enable debug logging", defaultValue: true
		input "tuyaProtVersion", "enum", title: "Select tuya protocol version: ", required: true, options: [31: "3.1", 33 : "3.3"]
	}
}

def logsOff() {
	log.warn "debug logging disabled..."
	device.updateSetting("logEnable", [value: "false", type: "bool"])
}

def updated() {
	log.info "updated..."
	log.warn "debug logging is: ${logEnable == true}"
	if (logEnable) runIn(1800, logsOff)

	sendEvent(name: "switch", value: "off")
}

def parse(String description) {
	if (logEnable) log.debug "Receiving message from device"
	if (logEnable) log.debug(description)

	byte[] msg_byte = hubitat.helper.HexUtils.hexStringToByteArray(description)

	String status = new String(msg_byte, "UTF-8")

	String protocol_version = ""

	status = status[20..-1]

	if (logEnable) log.debug "Raw incoming data: " + status

	if (!status.startsWith("{")) {
		// Encrypted message incoming, decrypt first

		if (logEnable) log.debug "Encrypted message detected"
		if (logEnable) log.debug "Bytes incoming: " + msg_byte.size()

		def message_start = 0

		// Find message type to determine start of message
		def message_type = msg_byte[11].toInteger()

		if (message_type == 7) {
			// Incoming control message
			// Find protocol version
			byte[] ver_bytes = [msg_byte[48], msg_byte[49], msg_byte[50]]
			protocol_version = new String(ver_bytes)

			if (protocol_version == "3.1") {
				message_start = 67
			} else if (protocol_version == "3.3") {
				message_start = 63
			}

		} else if (message_type == 10) {
			// Incoming status message
			message_start = 20

			// Status messages do not contain version information, however v 3.3
			// protocol encrypts status messages, v 3.1 does not
			protocol_version = "3.3"
		}

		// Find end of message by looking for 0xAA55
		def end_of_message = 0
		for (u = message_start; u < msg_byte.size()-1; u++) {
			if (msg_byte[u] == (byte)0xAA && msg_byte[u+1] == (byte)0x55) {
				//msg end found
				if (logEnable) log.debug "End of message: ${u-message_start-6}"
				end_of_message = u-message_start-6
				break
			}
		}

		// Re-assemble the bytes for decoding
		ByteArrayOutputStream output = new ByteArrayOutputStream()
		for (i = message_start; i < end_of_message+message_start; i++) {
			output.write(msg_byte[i])
		}

		byte[] payload = output.toByteArray()

		if (logEnable) log.debug "Assembled payload for decrypt: "+ hubitat.helper.HexUtils.byteArrayToHexString(payload)

		def dec_status = ""

		if (protocol_version == "3.1") {
			dec_status = decrypt_bytes(payload, settings.localKey, true)
		} else if (protocol_version == "3.3") {
			dec_status = decrypt_bytes(payload, settings.localKey, false)
		}

		if (logEnable) log.debug "Decryted message: ${dec_status}"

		status = dec_status
	}

	parse_tuya_payload(status)

	try {
		interfaces.rawSocket.close()
	} catch (e) {
		log.error "Could not close socket: $e"
	}
}

def parse_tuya_payload(status) {
	def jsonSlurper = new groovy.json.JsonSlurper()
	def status_object = jsonSlurper.parseText(status)

	sendEvent(name: "availableEndpoints", value: status_object.dps)

	if (status_object.dps["1"] == "open") {
		sendEvent(name: "windowBlind", value : "open")
	} else if (status_object.dps["1"] == "close") {
		sendEvent(name: "windowBlind", value : "closed")
	}

	if (status_object.dps["2"]) {
		sendEvent(name: "tilt", value : status_object.dps["2"])
	}

	if (status_object.dps["3"]) {
		sendEvent(name: "position", value : status_object.dps["3"])
	}
}

def status() {
	send(generate_payload("status"))
}

def open() {
	send(generate_payload("set", ["1":"open"]))

	// Testing
	/*parse_tuya_payload("{\"devId\":\"2502206124a160295f27\",\"dps\":{\"1\":\"open\",\"2\":100,\"3\":98}}")
	parse_tuya_payload("{\"devId\":\"2502206124a160295f27\",\"dps\":{\"3\":40}}")
	parse_tuya_payload("{\"devId\":\"2502206124a160295f27\",\"dps\":{\"1\":\"close\"}")*/
}

def close() {
	send(generate_payload("set", ["1":"close"]))
}

def setPosition(position) {
	send(generate_payload("set", ["3":position]))
}

def setTiltLevel(tilt) {
	send(generate_payload("set", ["2":tilt]))
}

def startPositionChange(direction) {
	if (direction == "open") {
		open()
	} else if (direction == "close") {
		close()
	}
}

def stopPositionChange() {
	send(generate_payload("set", ["1":"stop"]))
}

import hubitat.device.HubAction
import hubitat.device.Protocol

def send(byte[] message) {
	String msg = hubitat.helper.HexUtils.byteArrayToHexString(message)

	if (logEnable) log.debug "Sending message to " + settings.ipaddress + ":" + 6668 + " msg: " + msg

	try {
		//port 6668
		interfaces.rawSocket.connect(settings.ipaddress, 6668, byteInterface: true, readDelay: 500)
		interfaces.rawSocket.sendMessage(msg)
	} catch (e) {
		log.error "Error $e"
	}
}

def generate_payload(command, data=null) {

	def json = new groovy.json.JsonBuilder()

	json_data = payload()["device"][command]["command"]

	if (json_data.containsKey("gwId")) {
		json_data["gwId"] = settings.devId
	}
	if (json_data.containsKey("devId")) {
		json_data["devId"] = settings.devId
	}
	if (json_data.containsKey("uid")) {
		json_data["uid"] = settings.devId
	}
	if (json_data.containsKey("t")) {
		Date now = new Date()
		json_data["t"] = (now.getTime()/1000).toInteger().toString()
		//json_data["t"] = "1602184793" // for testing
	}

	if (data != null) {
		json_data["dps"] = data
	}

	json json_data

	if (logEnable) log.debug tuyaProtVersion

	json_payload = groovy.json.JsonOutput.toJson(json.toString())
	json_payload = json_payload.replaceAll("\\\\", "")
	json_payload = json_payload.replaceFirst("\"", "")
	json_payload = json_payload[0..-2]

	if (logEnable) log.debug "payload before=" + json_payload

	ByteArrayOutputStream output = new ByteArrayOutputStream()

	if (command == "set" && tuyaProtVersion == "31") {
		encrypted_payload = encrypt(json_payload, settings.localKey)

		if (logEnable) log.debug "Encrypted payload: " + hubitat.helper.HexUtils.byteArrayToHexString(encrypted_payload.getBytes())

		preMd5String = "data=" + encrypted_payload + "||lpv=" + "3.1" + "||" + settings.localKey

		if (logEnable) log.debug "preMd5String" + preMd5String

		hexdigest = generateMD5(preMd5String)

		hexdig = new String(hexdigest[8..-9].getBytes("UTF-8"), "ISO-8859-1")

		json_payload = "3.1" + hexdig + encrypted_payload

	} else if (tuyaProtVersion == "33") {
		encrypted_payload = encrypt(json_payload, settings.localKey, false)

		if (logEnable) log.debug encrypted_payload

		if (command != "status" && command != "12") {
			output.write("3.3".getBytes())
			output.write("\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000".getBytes())
			output.write(hubitat.helper.HexUtils.hexStringToByteArray(encrypted_payload))
		} else {
			output.write(hubitat.helper.HexUtils.hexStringToByteArray(encrypted_payload))
		}
	}

	if (tuyaProtVersion == "31") {
		output.write(json_payload.getBytes())
	}

	if (logEnable) log.debug "payload after=" + json_payload

	output.write(hubitat.helper.HexUtils.hexStringToByteArray(payload()["device"]["suffix"]))

	byte[] bff = output.toByteArray()

	if (logEnable) log.debug hubitat.helper.HexUtils.byteArrayToHexString(bff)

	postfix_payload = bff

	postfix_payload_hex_len = postfix_payload.size()

	if (logEnable) log.debug postfix_payload_hex_len

	if (logEnable) log.debug "Prefix: " + hubitat.helper.HexUtils.byteArrayToHexString(hubitat.helper.HexUtils.hexStringToByteArray(payload()["device"]["prefix"]))

	output = new ByteArrayOutputStream();

	output.write(hubitat.helper.HexUtils.hexStringToByteArray(payload()["device"]["prefix"]))
	output.write(hubitat.helper.HexUtils.hexStringToByteArray(payload()["device"][command]["hexByte"]))
	output.write(hubitat.helper.HexUtils.hexStringToByteArray("000000"))
	output.write(postfix_payload_hex_len)
	output.write(postfix_payload)

	byte[] buf = output.toByteArray()

	crc32 = CRC32b(buf, buf.size()-8) & 0xffffffff
	if (logEnable) log.debug buf.size()

	hex_crc = Long.toHexString(crc32)

	if (logEnable) log.debug "HEX crc: $hex_crc : " + hex_crc.size()/2

	// Pad the CRC in case highest byte is 0
	if (hex_crc.size() < 7) {
		hex_crc = "00" + hex_crc
	}

	crc_bytes = hubitat.helper.HexUtils.hexStringToByteArray(hex_crc)

	buf[buf.size()-8] = crc_bytes[0]
	buf[buf.size()-7] = crc_bytes[1]
	buf[buf.size()-6] = crc_bytes[2]
	buf[buf.size()-5] = crc_bytes[3]

	return buf
}

// Helper functions
def payload()
{
	def payload_dict = [
		"device": [
			"status": [
				"hexByte": "0a",
				"command": ["devId": "", "gwId": "", "uid":"", "t": ""]
			],
			"set": [
				"hexByte": "07",
				"command": ["devId":"", "uid": "", "t": ""]
			],
			"prefix": "000055aa00000000000000",
			"suffix": "000000000000aa55"
		]
	]

	return payload_dict
}

// Huge thank you to MrYutz for posting Groovy AES ecryption drivers for groovy
//https://community.hubitat.com/t/groovy-aes-encryption-driver/31556

import javax.crypto.spec.SecretKeySpec;
import javax.crypto.spec.IvParameterSpec;
import javax.crypto.Cipher

// Encrypt plain text v. 3.1 uses base64 encoding, while 3.3 does not
def encrypt (def plainText, def secret, encodeB64=true) {

	// Encryption is AES in ECB mode, pad using PKCS5Padding as needed
	def cipher = Cipher.getInstance("AES/ECB/PKCS5Padding ")
	SecretKeySpec key = new SecretKeySpec(secret.getBytes("UTF-8"), "AES")

	// Give the encryption engine the encryption key
	cipher.init(Cipher.ENCRYPT_MODE, key)

	def result = ""

	if (encodeB64) {
		result = cipher.doFinal(plainText.getBytes("UTF-8")).encodeBase64().toString()
	} else {
		result = cipher.doFinal(plainText.getBytes("UTF-8")).encodeHex().toString()
	}

	return result
}

// Decrypt ByteArray
def decrypt_bytes (byte[] cypherBytes, def secret, decodeB64=false) {
	if (logEnable) log.debug "*********** Decrypting **************"

	def cipher = Cipher.getInstance("AES/ECB/PKCS5Padding ")
	SecretKeySpec key = new SecretKeySpec(secret.getBytes(), "AES")

	cipher.init(Cipher.DECRYPT_MODE, key)

	if (decodeB64) {
		cypherBytes = cypherBytes.decodeBase64()
	}

	def result = cipher.doFinal(cypherBytes)

	return new String(result, "UTF-8")
}

import java.security.MessageDigest

def generateMD5(String s){
	MessageDigest.getInstance("MD5").digest(s.bytes).encodeHex().toString()
}

def CRC32b(bytes, length) {
	crc = 0xFFFFFFFF

	for (i = 0; i < length; i++) {
		b = Byte.toUnsignedInt(bytes[i])

		crc = crc ^ b
		for (j = 7; j >= 0; j--) {
			mask = -(crc & 1)
			crc = (crc >> 1) ^(0xEDB88320 & mask)
		}
	}

	return ~crc
}

Just in case, here is extracted Device Commands/Status structure:

Response

{
  "result": {
    "category": "cl",
    "functions": [
      {
        "code": "control",
        "lang_config": {
          "close": "Close",
          "open": "Open",
          "stop": "Stop"
        },
        "name": "Control",
        "type": "Enum",
        "values": "{\"range\":[\"open\",\"stop\",\"close\"]}"
      },
      {
        "code": "percent_control",
        "lang_config": {
          "unit": "%"
        },
        "name": "Curtain position setting",
        "type": "Integer",
        "values": "{\"unit\":\"%\",\"min\":0,\"max\":100,\"scale\":0,\"step\":1}"
      },
      {
        "code": "mode",
        "lang_config": {
          "morning": "Morning Mode",
          "night": "Night Mode"
        },
        "name": "Mode",
        "type": "Enum",
        "values": "{\"range\":[\"morning\",\"night\"]}"
      }
    ],
    "status": [
      {
        "code": "control",
        "lang_config": {
          "close": "Close",
          "open": "Open",
          "stop": "Stop"
        },
        "name": "Control",
        "type": "Enum",
        "values": "{\"range\":[\"open\",\"stop\",\"close\"]}"
      },
      {
        "code": "percent_control",
        "lang_config": {
          "unit": "%"
        },
        "name": "Curtain position setting",
        "type": "Integer",
        "values": "{\"unit\":\"%\",\"min\":0,\"max\":100,\"scale\":0,\"step\":1}"
      },
      {
        "code": "percent_state",
        "lang_config": {
          "unit": "%"
        },
        "name": "Current curtain position",
        "type": "Integer",
        "values": "{\"unit\":\"%\",\"min\":0,\"max\":100,\"scale\":0,\"step\":1}"
      },
      {
        "code": "mode",
        "lang_config": {
          "morning": "Morning Mode",
          "night": "Night Mode"
        },
        "name": "Mode",
        "type": "Enum",
        "values": "{\"range\":[\"morning\",\"night\"]}"
      },
      {
        "code": "work_state",
        "lang_config": {
          "closing": "Closing",
          "opening": "Opening"
        },
        "name": "Work State",
        "type": "Enum",
        "values": "{\"range\":[\"opening\",\"closing\"]}"
      },
      {
        "code": "time_total",
        "lang_config": {
          "unit": "ms"
        },
        "name": "Total Time",
        "type": "Integer",
        "values": "{\"unit\":\"ms\",\"min\":0,\"max\":120000,\"scale\":0,\"step\":1}"
      },
      {
        "code": "situation_set",
        "lang_config": {
          "fully_close": "Fully close",
          "fully_open": "Fully open"
        },
        "name": "Situation_set",
        "type": "Enum",
        "values": "{\"range\":[\"fully_open\",\"fully_close\"]}"
      }
    ]
  },
  "success": true,
  "t": 1667927367503,
  "tid": "19f68e325f8811ed8475060dd053b58c"
}

And here is a Device Driver page:

All buttons on the Device Diver page are 100% functional except for the
"Set Position" button. This function is not supported (I think) by the device.
Device does not report Status by itself but always updates Status in a
response for the "Status Report" command.

Here is my Test Rule:

Here is a first abnormality.
I think, it should not be difference how command is generated from RM
But this I mean command could be created as a "Command" and/or "Custom Command"
(please check first 2 lines in my test rule above).
If I am using "Close" command from RM (first line , now commented out) nothing is
happening with physical device and log always produces an error:

But if I am using close() custom attribute command everything is working just fine.
Also "Close" button from the Device Driver page also is working without any problems.
What is wrong with this picture?

Second abnormality is:
I was not able to use open/closed status in RM rule.
My "While Loop" periodically sends a "Status" command. On the Device Driver page
status is updated accordingly but RM never can detect an updated open/closed status.
If I am using "Position" value as n open/closed detection the RM rule can see it
just fine and everything is working as it should.
Again, what is wrong with this picture?

I hope, driver experts can spot something in the driver code.

Thank you in advance.

And just in case, here is my final rule which works just fine:

open/close status check done a bit different from it was in my test rule.

PS.
All testing and debugging was done on my spare C-5 with latest 2.3.3.140 SW
but actual working version is on my work horse C-7 also with latest 2.3.3.140 SW
I think, this should not matter.

Driver experts where are you?
I really would like to hear a comment(s) prom professionals
on why is Custom Driver doing something unusual.

The error is on this line within prase (error says line 79 but it is 80 in the code you posted):
byte[] ver_bytes = [msg_byte[48], msg_byte[49], msg_byte[50]]

There is a debug log right before it saying 28 bytes incoming and that line is trying to extract bytes 48-50 so you are getting an out of bounds error.

The parse function is parsing commands coming back from the device.

There should be no difference from using the Close option in RM vs a custom command of close vs pressing close on the device page vs Close on a dashboard. They all call the same function in the driver.

That is exactly what I am/was thinking
But to my BIG surprise there is a difference.
"Close" button from the Device Driver page and "close()" custom command
from RM never produces an error and Device responded 100% times I test this.
However "Close" command from the RM always generated that error and
Device never responded. This makes no sense at all.
I am not a SW developer (experienced EE) but I don't like any mysteries and
really would like to know what is going on and why.
(There is one more mystery with Status reporting.)
And that is why i am asking for the expert's opinion.

Add a debug log line to the close() function so you can see it if gets called for sure.
Make A new rule with ONE action, which is the Close: .... device

Run the Close button from the device page, screen shot the log (most important is the Sending Message)
Then Run Actions manually in the new rule, screen shot the logs again.

Compare the two, should be sending the exact same message to the device in both cases.

OK, I will try. My problem is - I am not a SW person (code was created by
@holand.ivar) but I should be able to do this little debugging.

How about my second question : "Status" change not registered by RM
for open/closed condition but "Position" has no problem?

Hi Vitaly,

In the latest driver I have done an attempt to force a state change from the driver, i.e. isStateChange : true together with the sendEvent. I have seen that for some reason RM does not always see the state change from the driver, but adding the isStateChange : truehas helped. Try that and see if that helps.

I also think the latest version of the driver could help with the error on ArrayIndexOutOfBounds exception you see as I see that the driver you posted is a few iterations old.

As a reminder, here is the latest driver: hubitatappndevice/tuyaGenericWindowBlind.groovy at master · ivarho/hubitatappndevice · GitHub

Ops!
For whatever reason I did not have this latest driver version.
I will definitely test it as soon as I will find a good timeframe
not to be too annoying for my wife.
I will post latest test results as soon as testing will be done.

Meanwhile I am very happy with the driver version I am using now.
All control is 100% local. This is VERY BIG deal for me.

Many Thank you, Ivar!
And Happy Holidays!

Download the Hubitat app