Parent/Child device telnet problem

I’m working on a multi-zone Onkyo AVR parent/child driver project. The parent exposes the Initialize and Telnet capabilities along with settings for IP address, port, and enabled zones. And each zone is a child device that manages generating the commands sent to the AVR and processing the responses from the same (the parent receives the response and routes it to the appropriate child/zone).

Before starting this parent/child driver project I wrote a single zone driver to workout the logic and all was working as expected.

Anyway, the child calls a method on the parent to send an EISCP command to the AVR via telnet. My original implementation of this method looked like this:

def sendTelnetMsg(String msg) 
{
	return new hubitat.device.HubAction(msg, hubitat.device.Protocol.TELNET)
} 

I was expecting to see the telnet response from the receiver in the parse callback on the parent.

void parse(String description) 
{
    log.debug "parse ${description}"
}

Unfortunately, I'm seeing no such response. However, if I change the implementation of the parent's method called by the child to this, I see the expected response from the AVR in the log output.

def sendTelnetMsg(String msg) 
{
    log.debug "Child called sendTelnetMsg with ${msg}"
    def hubAction = new hubitat.device.HubAction(msg, hubitat.device.Protocol.TELNET)
    log.debug "result: ${hubAction}"
    return hubAction;
}

This seems odd to me and is contrary to what I see with single zone driver where calling return new hubitat.device.HubAction(msg, hubitat.device.Protocol.TELNET) results in a parse callback.

It's certainly not the end of the world and I can handle the HubAction response but I'm wondering if this is normal.

[EDIT]
In thinking about this some more, the fact that the AVR response is being returned on HubAction call suggests this is happening synchronously. This probably isn't optimal if the command to the AVR fails and times out because of a comms issue.

Children should not make hubAction calls directly.
Have the child call a method in the parent that makes the hubAction call.
This is the pattern used for zigbee and zwave multi endpoint implementations.
The standard protocol agnostic pattern we use for this is shown in a few driver examples in our public repo.

Actually, that's what I'm doing. The parent has the telnet capability. The child is calling:

parent.sendTelnetMsg(command);

Just to follow up on this and clarify what I'm doing.

Method in the Child Device:

def sendCommand(String command)
{
	String cmd = parent.getEiscpMessage(command);
	log.debug "parent.getEiscpMessage returned ${cmd}"

	parent.sendTelnetMsg(command);
}

Method in the Parent Device

def sendTelnetMsg(String msg) 
{
	log.debug "Child called sendTelnetMsg with ${msg}"
	def hubAction = new hubitat.device.HubAction(msg, hubitat.device.Protocol.TELNET)
	log.debug "result: ${hubAction}"
	return hubAction;
}

Am I missing something?

@mike.maxwell I put together a stripped-down version of the parent and child devices to demonstrate the issue. The parent creates 2 zones (main and zone 2). And for the sake of simplicity, the child only implements the mute attribute and mute/unmute only affect the main zone

In short:

  • If I send the EISCP message directly from the parent using hubitat.device.HubAction everything works as expected and the parent receives the response via the parse callback

  • If I send the EISCP message from the child by calling a method in the parent (which in turn uses hubitat.device.HubAction), the parent's parse callback never occurs.

Parent Device

metadata 
{
	definition (name: "Test Onkyo Multi-Zone Receiver", namespace: "SteveV", author: "Steve Vibert")
	{
		capability "Initialize"
		capability "Telnet"
	}

    preferences 
	{   
		input name: "onkyoIP", type: "text", title: "Onkyo IP", required: true, displayDuringSetup: true
		input name: "eISCPPort", type: "number", title: "EISCP Port", defaultValue: 60128, required: true, displayDuringSetup: true
        input name: "debugOutput", type: "bool", title: "Enable debug logging", defaultValue: true
    }
}

def sendTelnetMsg(String msg) 
{
    log.debug "parent::sendTelnetMsg ${msg}"
	return new hubitat.device.HubAction(msg, hubitat.device.Protocol.TELNET)
}

void parse( description) 
{
    log.debug "parent::parse ${description}"
}

def initialize()
{
	String ip = settings?.onkyoIP as String;
	Integer port = settings?.eISCPPort as Integer;

	log.debug "Opening telnet connection with ${ip}:${port}"
	telnetConnect(ip, port, null, null);

    // If the parent sends a telnet message all works as expected and the response comes in 
    // via the parent's parse callback
    String cmd = getEiscpMessage("AMTQSTN");
    sendTelnetMsg(cmd);
}

def installed()
{
    log.warn "parent::installed..."
	initialize()
}

def reset()
{
    log.warn "parent::reset..."
}

def updated()
{
	log.info "parent::updated..."
    log.debug "calling createChildDevices..."
    createChildDevices()
    initialize()
}

def createChildDevices()
{
    log.debug "parent::createChildDevices..."
    // def zoneList = ["Main", "Zone 2", "Zone 3"]
    def zoneList = ["Main", "Zone 2"]

    try 
    {
        zoneList.each { it ->
        
            log.debug "Checking for existance of child ${childName}"
            String childName = it;
            def child = getChildDevice(childName);

            if(child == null) 
            {
                log.debug "Child ${childName} does not exist.  Creating..."
                createChildDevice(childName, "Test Onkyo AVR Zone")
                child = getChildDevice(childName)
            }

            else
                log.debug "Child ${childName} already exists. Skipping..."

        }
    }

    catch(ex) 
    {
        log.error "createChildDevices caused the following exception: ${ex}";
    }    
}

private def getChildDevice(String zoneName)
{
    def child = null
    
    try 
    {
        childDevices.each { it ->
            if(it.deviceNetworkId == "${device.deviceNetworkId}-${zoneName}")
                child = it;
        }
        
        return child;
    } 

    catch(ex) 
    {
        log.error "getChildDevice caused the following exception: ${ex}";
        return null;
    }
}

private void createChildDevice(String zoneName, String type) 
{
    try 
    {
        def child = addChildDevice("${type}", "${device.deviceNetworkId}-${zoneName}",
            [label: "${zoneName}",  isComponent: false, name: "${zoneName}"])
        
        log.trace "Child device with network id: ${device.deviceNetworkId}-${zoneName} successfully created."
    } 

    catch(ex) 
    {
        log.error "createChildDevice caused the following exception: ${ex}"
    }
}

// The following was borrowed from Mike Maxwell's SmartThings Onkyo driver code - thanks Mike!
/* This is where I construct the entire message character by character. Each char is represented by a 2 disgit hex value */
def getEiscpMessage(command)
{
	def sb = StringBuilder.newInstance()
	def eiscpDataSize = command.length() + 3  // this is the eISCP data size
	def eiscpMsgSize = eiscpDataSize + 1 + 16  // this is the size of the entire eISCP msg
    
	sb.append("ISCP")
	// the following are all in HEX representing one char

	// 4 char Big Endian Header
	sb.append((char)Integer.parseInt("00", 16))
	sb.append((char)Integer.parseInt("00", 16))
	sb.append((char)Integer.parseInt("00", 16))
	sb.append((char)Integer.parseInt("10", 16))

	// 4 char  Big Endian data size
	sb.append((char)Integer.parseInt("00", 16))
	sb.append((char)Integer.parseInt("00", 16))
	sb.append((char)Integer.parseInt("00", 16))
	// the official ISCP docs say this is supposed to be just the data size  (eiscpDataSize)
	// ** BUT **
	// It only works if you send the size of the entire Message size (eiscpMsgSize)
	// Changing eiscpMsgSize to eiscpDataSize for testing
	sb.append((char)Integer.parseInt(Integer.toHexString(eiscpDataSize), 16))
	//sb.append((char)Integer.parseInt(Integer.toHexString(eiscpMsgSize), 16))

	// eiscp_version = "01";
	sb.append((char)Integer.parseInt("01", 16))

	// 3 chars reserved = "00"+"00"+"00";
	sb.append((char)Integer.parseInt("00", 16))
	sb.append((char)Integer.parseInt("00", 16))
	sb.append((char)Integer.parseInt("00", 16))

	//  eISCP data
	// Start Character
	sb.append("!")

	// eISCP data - unittype char '1' is receiver
	sb.append("1")

	// eISCP data - 3 char command and param    ie PWR01
	sb.append(command)

	// msg end - this can be a few different cahrs depending on your receiver
	// my NR5008 works when I use  'EOF'
	//OD is CR
	//0A is LF
	/*
	[CR]			Carriage Return					ASCII Code 0x0D			
	[LF]			Line Feed						ASCII Code 0x0A			
	[EOF]			End of File						ASCII Code 0x1A			
	*/
	//works with cr or crlf
	sb.append((char)Integer.parseInt("0D", 16)) //cr

	return sb.toString()
}

Child Device

metadata 
{
	definition (name: "Test Onkyo AVR Zone", namespace: "SteveV", author: "Steve Vibert")
	{
		capability "Initialize"
		attribute "mute", "string"
		command "sendRawDataCommand", ["e.g. PWR01 (Main Zone Power On - See Onkyo EISCP Spec)"]
	}

	preferences 
	{   
        input name: "debugOutput", type: "bool", title: "Enable debug logging", defaultValue: true
    }
}

void parse(String description) 
{
    log.debug "child::parse ${description}"

    if(description == "AMT01")
    {
		log.info "${device.getName()} is unmuted";
        sendEvent(name: "mute", value: "muted");
    }

    else if(description == "AMT00")
    {
		log.info "${device.getName()} is unmuted";
		sendEvent(name: "mute", value: "unmuted");
    }
}

def initialize()
{
    log.warn "child::initialize..."
    sendCommand( "AMTQSTN" );
}

def installed()
{
    log.warn "child::installed..."
	initialize()
}

def updated()
{
	log.info "child::updated..."
		
	if (debugOutput) 
		runIn(1800,logsOff)

    initialize()
}

def logsOff() 
{
    log.warn "child::debug logging disabled..."
}

def mute()
{
    // For testing purposes this sends command to main zone regardless of the actual child zone.
    sendCommand("AMT01");
}

def unmute()
{
    // For testing purposes this sends command to main zone regardless of the actual child zone.
    sendCommand("AMT00");
}

def sendRawDataCommand(String cmd)
{
    sendCommand(cmd)
}

def sendCommand(String command)
{
    log.debug "child::sendCommand - calling parent.getEiscpMessage for command: ${command}..."
	String cmd = parent.getEiscpMessage(command);
    log.debug "child::sendCommand - calling parent.sendTelnetMsg with EISCP: ${cmd} "

    // We can't hubitat.device.HubAction from a child device so we'll call parent's sendTelnetMsg method.
    // Unfortunately, this doesn't work and the telnet message doesn't appear to be sent to the AVR
    parent.sendTelnetMsg(cmd);
}```

Ok, I see, ill take a look.

Looking at the HubAction documentation, the example for sending a Z-wave message includes calling sendHubCommand with the HubAction object:

//Create and send a Z-Wave message
def hubAction = new hubitat.device.HubAction(new hubitat.zwave.commands.basicv1.BasicGet().format(), hubitat.device.Protocol.ZWAVE)
sendHubCommand(hubAction)

None of the other HubAction examples include sendHubCommand but I tried it on a whim and it seems to fix my issue. What's weird is that this isn't needed with standalone (non-parent/child) devices; the device can simply create a new HubAction object using the TELNET protocol and it works.

Anyway, here's the modified method in the parent that's called by the child:

def sendTelnetMsg(String msg) 
{
    log.debug "Child called sendTelnetMsg with ${msg}"
    sendHubCommand(new hubitat.device.HubAction(msg, hubitat.device.Protocol.TELNET))
}