Trouble with Telnet

Hello,

Does anyone have any simple easy to understand examples of basic telnet usage in Hubitat? There doesn't seem to be any sort of official docs on how it works so I'm trying to glean from the various examples I can find in the forums.

Since Hubitat doesn't natively support Wifi based presence detection based on MAC address. (IE: the sort that OpenHAB uses) I'm trying to build a device driver that mimics the OpenHAB capability by telneting into my router, running some ARP and PING commands and then parsing the response to determine if a given device (by MAC address) is currently on my Wifi network.

I've done a considerable amount of testing the router commands via telnet and so far it seems to do a very good job of detecting the presence of our Android phones. The only hitch is getting Hubitat to send the commands to the router. Here is my device driver code:

metadata 
{
	definition (name: "Telnet Sensor", namespace: "jeremy.akers", author: "Jeremy Akers") 
	{
		capability "Presence Sensor"
		capability "Sensor"
		capability "Polling"
		capability "Telnet"
		capability "Initialize"
		command "poll"
		command "forcePoll"
	}

	preferences 
	{
		section("Device Settings:") 
		{
			input "username", "string", title:"Router Username", description: "Username", required: true, displayDuringSetup: true
			input "password", "password", title:"Router Password", description: "Password", required: true, displayDuringSetup: true
			input "MAC", "string", title:"MAC of Device", description: "MAC Address", required: true, displayDuringSetup: true

		}
	}
}

def installed() 
{
	log.info('Telnet Presence: installed()')
	initialize()
	state.presence = false
	state.ip =  null
	state.waiting = false
}

def updated() 
{
	log.info('Telnet Presence: updated()')
	initialize()
	state.presence = false
	state.ip = null
	state.waiting = false

	unschedule()
	runEvery1Minute(pollSchedule)
}
def pollSchedule()
{
    forcePoll()
}
def initialize() 
{
	log.info('Telnet Presence: initialize()')
	telnetClose() 
	telnetConnect([terminalType: 'VT100'], '192.168.0.1', 23, settings.username, settings.password)
}

def forcePoll()
{
	log.debug "Polling for host ${settings.MAC}..."
	//sendMsg("arp -an | grep ${settings.MAC} || echo No Match")
	sendMsg("sleep 10000")
	log.debug("Message sent. Awaiting response.")
	state.waiting = true
	state.lastPoll = now() 
}

def poll()
{
    if(now() - state.lastPoll > (60000))
        forcePoll()
    else
        log.debug "poll called before interval threshold was reached"
}


def sendMsg(String msg) 
{
	log.info("Sending telnet msg: " + msg)
	return new hubitat.device.HubAction(msg, hubitat.device.Protocol.TELNET)
}


private parse(String msg) 
{
	log.debug("Parse: " + msg)
	if(msg.startsWith("? "))
	{
		Scanner scanner = new Scanner(msg);
		scanner.next()
		iptext = scanner.next()
		ip = iptext.substring(1, iptext.length()-1)
		scanner.next()
		mac = scanner.next()
		log.debug("IP: " + ip + ", MAC: " + mac)
		state.ip = ip
		state.presence = true
		state.waiting = false
	}
	else if(msg.equals("No Match"))
	{
		state.ip = null
		state.presence = false
		state.waiting = false
	}		
}

def telnetStatus(String status){
	log.warn "telnetStatus: error: " + status
	if (status != "receive error: Stream is closed")
	{
		log.error "Connection was dropped."
		initialize()
	} 
}

Now here's the really confusing part: This code was working for a few minutes today, and then stopped again. I was making changes and fine tuning the parsing of the ARP command output when it just stopped sending the telnet commands to the router. I hadn't touched any of the actual telnet handling code, only the part that parses the response. As you can see from the code I log the entire response before parsing it so if it were failing somewhere in the parse block I should be able to see that in the logs.

However what I am seeing is this behavior:

[dev:577](http://192.168.0.55/logs#dev577)2018-12-04 07:59:39.163 pm [debug](http://192.168.0.55/device/edit/577)Message sent. Awaiting response.

[dev:577](http://192.168.0.55/logs#dev577)2018-12-04 07:59:39.161 pm [info](http://192.168.0.55/device/edit/577)Sending telnet msg: sleep 10000

[dev:577](http://192.168.0.55/logs#dev577)2018-12-04 07:59:39.160 pm [debug](http://192.168.0.55/device/edit/577)Polling for host <mac address>...

[dev:577](http://192.168.0.55/logs#dev577)2018-12-04 07:59:32.258 pm [debug](http://192.168.0.55/device/edit/577)Parse:

[dev:577](http://192.168.0.55/logs#dev577)2018-12-04 07:59:32.093 pm [info](http://192.168.0.55/device/edit/577)Telnet Presence: initialize()

The telnet connection is made within "initialize". This step works because I can see the telnet connection when I run a netstat command on the router itself:

admin@RT-AC3200:/tmp/home/root# netstat -en | grep :23
tcp        0      0 192.168.0.1:23          192.168.0.233:41642     ESTABLISHED 
tcp        0      0 192.168.0.1:23          192.168.0.55:48424      ESTABLISHED

192.168.0.1 is the ASUS router, 192.168.0.55 is my Hubitat device and 192.168.0.233 is my PC. You can see the Hubitat shows an established connection via telnet.

Further evidence that the telnetConnect succeeds: if I enter the wrong password I get a message back (via my parse method) saying "Login Incorrect"

However what isn't showing up is any evidence of successfully running any commands, so I suspect something is failing with the HubAction. It's not throwing any exceptions or putting any errors in the logs so it's making it very difficult to understand what the problem is.

If I let this sit idle long enough, I do finally get a message back via parse:

[dev:577](http://192.168.0.55/logs#dev577)2018-12-04 08:19:32.497 pm [warn](http://192.168.0.55/device/edit/577)telnetStatus: error: receive error: Stream is closed

[dev:577](http://192.168.0.55/logs#dev577)2018-12-04 08:19:32.483 pm [debug](http://192.168.0.55/device/edit/577)Parse: admin@RT-AC3200:/tmp/home/root# atimed out waiting for input: auto-logout

Any tips on how to investigate this further? What's really puzzling me is that this was working, and then just mysteriously stopped as I was working on the "parse" method code.

-Jeremy

While not much help with Telnet, I do have a very simple option for you... If you can run a script periodically on your ROUTER to detect presence, why not just then have that application use the Hubitat "Maker API" App to update the status of a Virtual Presence Device? I am doing this directly from my iPhone using an old app called Locative. Others have used Tasker on their Android phones to do the same.

Just an idea for you to ponder...

Because I can't permanently modify anything on the router (Unless I replace the Asus firmware which I'd like to avoid). IE: No installing scripts or crontab or anything like that is possible. It runs 100% on tmpfs and every reboot causes the entire file system to be reset again. So while I could theoretically do it... I would have to replace it on every router reboot.

Plus I have a bunch of other use cases for telnet so I'd really like to just learn how to make telnet work.

I've tested Tasker, IFTTT, Trigger, etc but the apps just aren't reliable enough. Android is really stingy with background apps so they often don't trigger for 5+ minutes after the phone has connected to Wifi. Watching the ARP table on the router shows the phone as present often before my car turns down my driveway. This is the single feature that I really liked on OpenHAB: It would just listen on port 67 for DHCP requests and it would know instantly when any registered devices connected to Wifi. Since it's listening to the DHCP requests and responses it would also know the assigned IP and then it would occasionally ping that IP to see if it's still there. Miss enough pings and the device is set to "Not present". It was the one part of OpenHAB that worked wonderfully out of the box.

I've also pondered setting this up as a crontab on another server I have in the house but that would mean: 1) I need to do a broadcast ping every time to make sure that machine has an updated ARP cache table (Adds a lot of noise to my network, each broadcast can take 20+ seconds to complete) and 2) Adds an additional failure point to my setup. Plus again I'd like to learn how the telnet functionality in Hubitat works.

Really hoping one of the Hubitat staff members can point me in the right direction...

-Jeremy

You may want to open a ticket with support. I was having some hub issues that I tracked down to the "telnetStatus: error: receive error: Stream is closed" which was happening consistently at about 1:00 in the morning and it was causing my hub to crash...even though there should have been nothing going on at that time. They looked into it and I never got a status back, but the error went away after a few days, not sure if it was rebooting my IP2IR device or installing new firmware or what. Like you, I wanted to know what was happening at 1:00 to cause a receive error to occur, but that was impossible to figure out with no insight into what the hub is doing.

1 Like

One issue that jumps out at me is that you are not actually sending the HubAction from sendMsg(), you are returning it. That is fine if you are actually returning it to the system to process, but for instance you are calling sendMsg() in the middle of forcePoll(), it should be the last line of force poll and if you want to be explicit it should be "return sendMsg(...)" plus any methods that call forcePoll() should do the same. Otherwise, change the line in sendMsg to use the sendHubCommand() method instead of returning the HubAction.

http://groovy-lang.org/style-guide.html#_return_keyword_optional

This fixed it. Just removed the return and replaced it with "sendHubCommand(new " and it works like a charm. Like I said: Without docs I was just going off of examples I could find in the forums and I guess I saw that being done that in one of the other telnet examples.

That being said, and maybe I should move this to a separate topic, but I think I found a race condition by accident: As I was playing with this just now I clicked "Save" on the telnet presence device driver code and very quickly switched browser tabs to the actual virtual device instance and hit "Save Preferences" to update it, and it returned a "404 Error" and printed this in the logs: (Notice that the "mac.settings" field that I had populated now shows as NULL in the logs):

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:59.420 pm [debug](http://192.168.0.55/device/edit/577)MAC not found: null

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:59.419 pm [debug](http://192.168.0.55/device/edit/577)Parse: NoMatch

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:59.398 pm [error](http://192.168.0.55/device/edit/577)org.h2.jdbc.JdbcSQLException: General error: "java.lang.IllegalStateException: This map is closed [1.4.197/4]" [50000-197] (parse)

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:59.273 pm [debug](http://192.168.0.55/device/edit/577)Parse: admin@RT-AC3200:/tmp/home/root# arp -an | grep null || echo NoMatch

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:59.225 pm [error](http://192.168.0.55/device/edit/577)org.h2.jdbc.JdbcSQLException: The database has been closed [90098-197] (pollSchedule)

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:59.176 pm [debug](http://192.168.0.55/device/edit/577)Message sent. Awaiting response.

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:59.161 pm [info](http://192.168.0.55/device/edit/577)Sending telnet msg: arp -an | grep null || echo NoMatch

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:59.160 pm [debug](http://192.168.0.55/device/edit/577)Polling for host null...

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:57.142 pm [error](http://192.168.0.55/device/edit/577)org.h2.jdbc.JdbcSQLException: The database has been closed [90098-197] on line 39 (updated)

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:55.928 pm [error](http://192.168.0.55/device/edit/577)org.h2.jdbc.JdbcSQLException: IO Exception: "nio:/home/hub/hubitatdb.mv.db"; SQL statement: UPDATE DEVICE D SET D.STATE = ? WHERE D.ID = ? [90028-197] (telnetStatus)

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:55.791 pm [warn](http://192.168.0.55/device/edit/577)telnetStatus: error: receive error: Stream is closed

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:55.772 pm [info](http://192.168.0.55/device/edit/577)Telnet Presence: initialize()

[dev:577](http://192.168.0.55/logs#dev577)2018-12-09 03:51:55.767 pm [info](http://192.168.0.55/device/edit/577)Telnet Presence: updated()

I just wanted to bump this thread. I'm still seeing this race condition crash my hub. The docs on the telnet interface are still quite lacking so it's very difficult to figure out from the docs if I'm doing something wrong or if there's a bug in the hub.

See the screenshot below:

Basically after some time the telnet connection stops working. What's puzzling is I get no errors. The device continues to "poll" on schedule, but nothing ever comes back to "parse" so events just stop firing.

If I try to "re-initialize", which does a "telnetClose" followed by a new "telnetConnect" it sometimes puts the hub into the above race condition state where every page returns a "Status 500" error. I have to pull the power cord from the hub and re-power it to reset it.

Any thoughts or guidance on how to troubleshoot this? Are there some hidden docs out there that I haven't found yet?

Thanks,
-Jeremy

My driver code, for reference:

metadata 
{
	definition (name: "OpenScale Weight and Temperature Sensor", namespace: "jeremy.akers", author: "Jeremy Akers") 
	{
        capability "Temperature Measurement"
        
        command "poll"
        command "forcePoll"
        command "initialize"
        
        attribute "weight", "number"
	}

	preferences 
	{
		section("Device Settings:") 
		{
			input "polltime", "number", title:"How often to poll in minutes", description:"Polling time (minutes)", required: true, displayDuringSetup: true
			input "ipaddr", "string", title:"IP of Device", description: "IP Address", required: true, displayDuringSetup: true
			input "port", "number", title:"Port number of device", description:"Port number", required: true, displayDuringSetup: true
		}
	}
}

def installed() 
{
	log.info('OpenScale Weight and Temperature Sensor: installed()')
}

def updated() 
{
	log.info('OpenScale Weight and Temperature Sensor: updated()')
	unschedule()
	initialize()
	log.debug("Scheduling for: 0 */${settings.polltime} * * * ?")
	schedule("0 */${settings.polltime} * * * ?", pollSchedule)

}
def pollSchedule()
{
    forcePoll()
}
def initialize() 
{
	log.info('OpenScale Weight and Temperature Sensor: initialize()')
	telnetClose() 
	try
	{	
		telnetConnect([terminalType: 'VT100'], settings.ipaddr, (int) settings.port, null, null)
	}
	catch(Exception e)
	{
		log.error("Failed to connect. Will retry in 60 seconds. Error: " + e)
		runIn(60, initialize) // Try again in 60 seconds
	}
}

def forcePoll()
{
	//log.debug "Polling for weight..."
	sendMsg("0")
	state.lastPoll = now() 
}

def poll()
{
    if(now() - state.lastPoll > (settings.polltime * 6000))
        forcePoll()
    else
        log.debug "poll called before interval threshold was reached"
}


def sendMsg(String msg) 
{
	//log.info("Sending telnet msg: " + msg)
	sendHubCommand(new hubitat.device.HubAction(msg, hubitat.device.Protocol.TELNET))
}


private parse(String msg) 
{
	log.debug("Parse: " + msg)
	def splitText = msg.split(',')
	weight = splitText[1]
	tempC = Float.parseFloat(splitText[3])
	tempF = tempC * 1.8 + 32.0
	//log.debug("Parsed: " + weight + "lbs, " + tempF + "F")
	sendEvent(name: "temperature", value: tempF.round(2), unit: "F")
	sendEvent(name: "weight", value: weight, unit: "lbs")
	log.info("Weight: ${weight}, Temp: ${tempF}")
}

def telnetStatus(String status){
	log.warn "OpenScale Weight and Temperature Sensor; telnetStatus: error: " + status
	//if (status != "receive error: Stream is closed")
	//{
		log.error "Connection was dropped. Retrying in 30 seconds."
		runIn(30, initialize)
	//} 
}

I know that this doesn't answer your questions about Telnet, but have you considered the following approach?
It checks to see if a certain ip address has been utilized. (Contrary to the name, it does work with Android phones.) It doesn't work on mac addresses (which I suppose is better), but on ip addresses (which would have been reserved in advance.)

I'm not just using telnet for presence. If you look at the code I posted two days ago you'll see this particular driver has nothing to do with presence detection. I built a scale using SparkFun OpenScale to monitor how much dog food I have in my automatic dog food feeder. The OpenScale is connected to a Raspberry Pi via serial port connection and I'm using ser2net to enable remote connections to the serial port via telnet.

Obviously for presence detection I can now just use the Hubitat app for that, but there are lots of other uses for telnet and I'd like to understand how to make it work.

Do you have telnet installed on your RPi? It is not installed by default. The default communication method with your pi will be SSH which is not the same as telnet.

For what it's worth, the Telnet command in another driver using the same method is slightly different.

return new hubitat.device.HubAction("$MESSAGE\n", hubitat.device.Protocol.TELNET)

It doesn't use sendHubCommand. Don't know if that is part of the issue or not. Also, your authentication is "null" and "null"? Is that allowed? I thought it had to have a UN and Password?

If you read the thread you'll see that I said it works at first and then after some time (days, weeks) it stops working. Obviously if I didn't have a telnet service on the Pi it would never work at all. I'm using ser2net as the telnet service that takes incoming telnet connections and connects them directly to the serial port. This works for a while, and then eventually the connection drops for whatever reason but Hubitat never returns any errors. Since there's never any errors, the driver continues right along sending data to a closed connection and obviously nothing ever comes back. And this will run for days with no errors ever being returned to the driver. And then we have the race condition which crashes the hub when I try to manually re-initialize the connection.

Not all telnet servers require username/password. ser2net just connects the telnet port directly to the serial port, so any characters that come in via telnet are sent to the serial device, and then any responses are returned to the telnet client.

Sorry, then nope....no clue.

Have you considered simply having the pi periodically broadcast the reading via the maker API? Rather than screw with Telnet (which is an "always on" connection) and whatnot, it would seam easier to have the Pi come up with the reading and then send that via a Get message to HE via the maker API. Just a thought. Good luck!

I think that I would probably try to wait after the unschedule. From what I understand this is a fairly expensive task. It may be happening too slowly and perhaps a scheduled poll is hitting the telnet connection before it is fully ready. Likewise, I would probably set the cron string to not poll immediately in case of a similar situation.

I have the following driver working for some time now without any incidence and the biggest difference perhaps I see is the scheduled polling.

https://github.com/codahq/hubitat_codahq/blob/master/devicestypes/optoma-uhd51a.groovy

Maybe looking at creating some separation in the connection events and the polling is a place to start.