Can't figure out TCP binding for the life of me. Help!

,

So I’m trying to do something that should be dirt simple – send a UDP packet to an IP with the message “testing” to a port.

String  MYTHTV "[%s]" {udp=">[:172.18.0.128:6948:'REGEX((.*))']"}
rule "send UDP packet"
when
    Item TEST_SWITCH_1 changed to ON
then
    {
        var String mymessage
        mymessage = "testing"
        logInfo("openhab", "test message sent:" + mymessage)
        sendCommand(MYTHTV,mymessage)
    }    
end

But I’m using tcpdump to spy on openhab, and when I hit my test switch it shows in the log that the rule is firing but absolutely nothing is being sent out to that machine.

What am I doing wrong here!?? This seems like baby town frolicks level simple, yet am getting nothing! (No errors and no packets.)

Is the leading “:” needed for a String item command binding? The wiki implies it isn’t. I’d try removing that. If that doesn’t help, have you tried turning on trace level logging for the tcp binding to see if there are any hints?

Well, not sure if I’m making headway or not.

With the leading : deleted, and with tcp binding in debug mode, I get this when I hit the switch:

2016-06-14 22:07:17.218 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]

With the leading : in there, I no longer get the error message. I get nothing in the tcp log at all! (And both versions still don’t send anything out at all.)

So I flipped on trace level debugging… and not much better. With the :, nothing at all in tcp log file. Without the :, same message as above.

I am getting messages in my tcp log file, in case you’re wondering. But they’re mostly just housekeeping garbage:

2016-06-14 22:17:56.103 [DEBUG] [.o.b.tcp.internal.TCPActivator:35  ]- TCP/UDP binding has been started.
2016-06-14 22:17:57.515 [INFO ] [t.AbstractSocketChannelBinding:768 ]- The maximum buffer will be set to the default value of 1024
2016-06-14 22:17:57.521 [INFO ] [t.AbstractSocketChannelBinding:775 ]- The interval to retry connection setups will be set to the default value of 5
2016-06-14 22:17:57.522 [INFO ] [t.AbstractSocketChannelBinding:782 ]- The cron job to reset connections will be set to the default value of 0 0 0 * * ?
2016-06-14 22:17:57.523 [INFO ] [t.AbstractSocketChannelBinding:789 ]- The setting to queue write operation until a channel gets connected will be set to the default value of true
2016-06-14 22:17:57.524 [INFO ] [t.AbstractSocketChannelBinding:796 ]- The port to listen for incoming connections will be set to the default value of 0
2016-06-14 22:17:57.526 [INFO ] [t.AbstractSocketChannelBinding:803 ]- The setting to share channels within an Item will be set to the default value of true
2016-06-14 22:17:57.555 [INFO ] [t.AbstractSocketChannelBinding:810 ]- The setting to share channels between the items with the same direction will be set to the default value of true
2016-06-14 22:17:57.562 [INFO ] [t.AbstractSocketChannelBinding:817 ]- The setting to share channels between directions will be set to the default value of true
2016-06-14 22:17:57.563 [INFO ] [t.AbstractSocketChannelBinding:824 ]- The setting to use address masks for incoming connections will be set to the default value of true
2016-06-14 22:17:57.578 [INFO ] [t.protocol.internal.TCPBinding:173 ]- The maximum time out for blocking write operations will be set to the default vaulue of 3000
2016-06-14 22:17:57.582 [INFO ] [t.protocol.internal.TCPBinding:180 ]- The blocking nature of read/write operations will be set to the default vaulue of false
2016-06-14 22:17:57.585 [INFO ] [t.protocol.internal.TCPBinding:187 ]- The preamble for all write operations will be set to the default vaulue of ""
2016-06-14 22:17:57.587 [INFO ] [t.protocol.internal.TCPBinding:194 ]- The postamble for all write operations will be set to the default vaulue of ""
2016-06-14 22:17:57.589 [INFO ] [t.protocol.internal.TCPBinding:201 ]- Updating states with returned values will be set to the default vaulue of true
2016-06-14 22:17:57.590 [INFO ] [t.protocol.internal.TCPBinding:208 ]- The characterset will be set to the default vaulue of ASCII

Any other ideas?

Well, interesting…

when I change from udp to tcp, things work. (Well they don’t work, but at least I see what I’d expect to see – start a four way handshake then a reset coming back.) When I switch to udp, that’s when I get “no channel defined”:

2016-06-14 22:31:49.741 [INFO ] [t.AbstractSocketChannelBinding:1128]- Attempting to reconnect the channel for /172.18.0.128:6948
2016-06-14 22:31:50.245 [INFO ] [t.AbstractSocketChannelBinding:1128]- Attempting to reconnect the channel for /172.18.0.108:6948
2016-06-14 22:31:50.251 [WARN ] [t.AbstractSocketChannelBinding:1478]- The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: Connection refused
2016-06-14 22:31:52.757 [WARN ] [t.AbstractSocketChannelBinding:1478]- The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: No route to host
2016-06-14 22:31:55.254 [INFO ] [t.AbstractSocketChannelBinding:1128]- Attempting to reconnect the channel for /172.18.0.108:6948
2016-06-14 22:31:55.263 [WARN ] [t.AbstractSocketChannelBinding:1478]- The channel java.nio.channels.SocketChannel[closed] has encountered an unknown IO Exception: Connection refused
2016-06-14 22:31:57.760 [INFO ] [t.AbstractSocketChannelBinding:1128]- Attempting to reconnect the channel for /172.18.0.128:6948
2016-06-14 22:32:00.265 [INFO ] [t.AbstractSocketChannelBinding:1128]- Attempting to reconnect the channel for /172.18.0.108:6948
// ((...then switching back to udp...))
2016-06-14 22:32:04.814 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-14 22:32:07.981 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-14 22:32:08.874 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-14 22:32:09.373 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-14 22:32:10.572 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-14 22:32:11.537 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-14 22:32:12.623 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-14 22:32:13.564 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]

It’s almost like the tcp code and the udp code got intermixed? How can it possibly be looking for a channel on a connectionless protocol?

(And turns out my virtual [destination] machine was being assigned one IP when booting, and a different IP when running. Oh joy, figure that one out later. 108 is the “running” destination IP, in case anyone is eagle-eyed enough to catch that.)

through searching I found https://groups.google.com/d/msg/openhab/As_A3cobQ0o/uEEU9ZKKEkgJ:

I should have seen this early on, but I will not blaim you as the
wiki for the binding contains an error. For String items, the
should not be part of the item definition. Thanks for “pointing” this out, as I need to add an additional
check in the code to prevent this situation

String remote1 “IrTrans remote1” { tcp=“>[blablaix:21000:‘MAP(iremote.map)’]”}

should be better

So for outgoing String Items you don’t have to setup a command, but then you even have to omit the colon.

String  MYTHTV "[%s]" {udp=">[172.18.0.128:6948:'REGEX((.*))']"}

should work. What did you setup in the openhab.cfg for udp?

I’m traveling right now and I don’t have access to my development system. In my opinion, this binding is far too difficult to use and it’s not documented well.

I’ve looked at the “no channel defined” error in the source code on the github site and it appears that the code is expecting a “" for the command in the binding configuration. This doesn’t match the documentation, but it might be worth trying to put a":” before the address. You could also experiment with putting the actual command string “testing” instead of “*” to see if that makes a difference.

Doesn’t hurt anything to try! :smiley: Both

 String  MYTHTV "[%s]" {udp=">[\"\":172.18.0.108:6948:'REGEX((.*))']"}

and

String  MYTHTV "[%s]" {udp=">['':172.18.0.108:6948:'REGEX((.*))']"}

show absolutely nothing in the tcp trace logs. (If anything, that’s probably the biggest failure of this binding – it aborts with absolutely no messages whatsoever, even on trace! Easy to cast stones, though…)

With this…

String  MYTHTV "[%s]" {udp=">[172.18.0.108:6948:'REGEX((.testing))']"}

I get the ‘no channel’ message again.

Just to cover the base I also grabbed the latest version off of cloudbees (couple of days old) & restarted OH, no change.

I left them at defaults (everything commented out); there didn’t seem to be anything really relevant to udp that was worth changing.

Grrrrr… I think the forum software corrupted my message. The wildcard command is the asterisk character. It should followed by a colon (no double quotes).

So it should look like

String  MYTHTV "[%s]" {udp=">[*:172.18.0.108:6948:'REGEX((.*))']"}

?

Well good thought, buuuuuuut no change…

String  MYTHTV "[%s]" {udp=">[*:172.18.0.108:6948:'REGEX((.*))']"}

begat

2016-06-15 12:10:06.624 [ERROR] [AbstractDatagramChannelBinding:961 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-15 12:10:07.539 [ERROR] [AbstractDatagramChannelBinding:961 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-15 12:10:08.190 [ERROR] [AbstractDatagramChannelBinding:961 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-15 12:10:09.044 [ERROR] [AbstractDatagramChannelBinding:961 ]- there is no channel that services [itemName=MYTHTV, command=testing]

(and tcpdump verifies that no packets at all in/out to 172.18.0.108)

So here’s a thought… looking at that log and guessing a bit, it seems as though it’s interpreting the command to be testing, when what I’m really after is a send command, followed by an argument of what to put in the packet. Just kind of throwing that out there in case it helps jog any ideas.

Think I finally understood what you were going for here…

String  MYTHTV "[%s]" {udp=">[testing:172.18.0.108:6948:'REGEX((.*))']"}

Unfortunately, no change with that… (“no channel” blah blah blah)

Anybody else have any ideas why this isn’t working? Given that it’s trying to work with tcp (and refuses to work with udp) looking more and more like a binding bug to me. (…but fully willing to entertain the idea that I’m wrong! :slight_smile:)

I found the problem. It’s a bug in the UDP-specific code. If you don’t specify any UDP configurations in openhab.cfg, no channels are created. In my case, I added…

udp:charset=ASCII

as a workaround for the issue (although that’s the default value). Also, the *: command wildcard does not work for UDP, but you can leave out the command name on a StringItem and the binding will process any command string.

Here’s my test item…

String UdpTest { udp=">[localhost:8888:REGEX((.*))]" }

The openHAB command is “testing”, but that command can be transformed to any “protocol string” (text only, not binary) using one of the openhab transformations.

What is an example of a string you are trying to actually send to the device?

1 Like

Thanks! I’ll try that and report back!

Trying to send a MythNotification to my MythTV frontends. So basically, XML over UDP is the intended message down the road.

(I already did a raw udp socket test, and MythNotification doesn’t enforce well-formed XML so you can send something like

<mythnotification version="1"><text>%message_text%</text></mythnotification>

with no whitespace whatsoever and it’s happy… thankfully!)


Well, no joy in mudville. I added

tcp:charset=ASCII
udp:charset=ASCII

to my openhab.cfg, then stopped and restarted openhab. Item is…

String  MYTHTV "[%s]" {udp=">[172.18.0.108:6948:'REGEX((.*))']"}

And no change; still says no channel that services testing.

You didn’t happen to change anything else, did you? Also might try not sending to localhost as it’s often a special case. Should be able to send an unsolicited udp packet at just about anything and that endpoint should drop it unaffected.

Just for completeness sake, also tried…

String  MYTHTV "[%s]" {udp=">[172.18.0.108:6948:REGEX((.*))]"}

As usual, no change… no channel. (sigh!)

Well, IWOMM. :slight_smile: Seriously, there’s apparently something different between our environments. I didn’t change anything else.

I did send a message to another host and that worked fine. When it works, you should see a log message similar to the following…

2016-06-16 20:14:10.462 [INFO ] [AbstractDatagramChannelBinding] - 'Connecting' the channel Channel [item=UdpTest, command=1, direction=OUT, remote=/10.0.0.22:8888, buffer=, isBlocking=false, isReconnecting=false, channel=, host=10.0.0.22, port=8888] 

I’m testing this with a openHAB 1.8 development environment. I assume you aren’t using openHAB 2. Is that correct?

oh yeah… using OpenHAB 1.8.1, tcp binding updated to 1.9.whatever from cloudbees a couple of days ago.


Just to cover the base, reverted the tcp binding back to 1.8.1 stock. No change (no channel).

Also, for giggles I copied and pasted your item definition exactly, changing only the name to MYTHTV2…

String  MYTHTV "[%s]" {udp=">[172.18.0.108:6948:REGEX((.*))]"}
String  MYTHTV2 {udp=">[localhost:8888:REGEX((.*))]" }

and

        var String mymessage
        mymessage = "testing"
        logInfo("openhab", "test message sent:" + mymessage)
        sendCommand(MYTHTV,mymessage)
        sendCommand(MYTHTV2,mymessage)

Doesn’t produce anything useful:

2016-06-16 22:43:48.873 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-16 22:43:49.154 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV2, command=testing]

The only thing I see different is that you’re sending a command of “1”, somehow. How?

It just means the configuration is not associated with a specific openHAB command. From the
source code documentation…

// for those configuration strings that are not really linked to a openHAB command we
// create a dummy Command to be able to store the configuration information
// I have choosen to do that with NumberItems

It definitely either works or not for me depending on whether I have a udp configuration in my openhab.cfg. Do you see lines like the following in your log file (notice it is AbstractDatagramChannelBinding and not the TCPBinding)?

2016-06-17 06:06:40.128 [INFO ] [AbstractDatagramChannelBinding] - The maximum buffer will be set to the default value of 1024
2016-06-17 06:06:40.128 [INFO ] [AbstractDatagramChannelBinding] - The interval to retry connection setups will be set to the default value of 5
2016-06-17 06:06:40.128 [INFO ] [AbstractDatagramChannelBinding] - The cron job to reset connections will be set to the default value of 0 0 0 * * ?
2016-06-17 06:06:40.129 [INFO ] [AbstractDatagramChannelBinding] - The port to listen for incoming connections will be set to the default value of 0
2016-06-17 06:06:40.129 [INFO ] [AbstractDatagramChannelBinding] - The setting to share channels within an Item will be set to the default value of true
2016-06-17 06:06:40.129 [INFO ] [AbstractDatagramChannelBinding] - The setting to share channels between the items with the same direction will be set to the default vaulue of true
2016-06-17 06:06:40.129 [INFO ] [AbstractDatagramChannelBinding] - The setting to share channels between directions will be set to the default vaulue of true
2016-06-17 06:06:40.129 [INFO ] [AbstractDatagramChannelBinding] - The setting to use address masks for incoming connections will be set to the default value of true
2016-06-17 06:06:40.129 [INFO ] [AbstractDatagramChannelBinding] - The refresh interval of the worker thread will be set to the default value of 250
2016-06-17 06:06:40.129 [INFO ] [t.protocol.internal.UDPBinding] - The maximum time out for blocking write operations will be set to the default vaulue of 3000
2016-06-17 06:06:40.129 [INFO ] [t.protocol.internal.UDPBinding] - The blocking nature of read/write operations will be set to the default vaulue of false
2016-06-17 06:06:40.129 [INFO ] [.service.AbstractActiveService] - UDP Refresh Service has been started

If not, it means the configuration is not being pushed to the UDP binding, which will happen if openHAB doesn’t see any udp configurations in openhab.cfg. If the messages are there, I’m out of theories about why it’s not working for you.

For testing, I have a Python utility that send commands to the item using the ReST API. However, I don’t think that would cause different binding behavior. Since you are seeing the “no channel” message it means the item command is being processed by the binding.

I’m getting similar yet subtly different startup messages:

2016-06-16 22:40:49.301 [DEBUG] [.o.b.tcp.internal.TCPActivator:35  ]- TCP/UDP binding has been started.
2016-06-16 22:40:50.201 [INFO ] [t.AbstractSocketChannelBinding:768 ]- The maximum buffer will be set to the default value of 1024
2016-06-16 22:40:50.205 [INFO ] [t.AbstractSocketChannelBinding:775 ]- The interval to retry connection setups will be set to the default value of 5
2016-06-16 22:40:50.206 [INFO ] [t.AbstractSocketChannelBinding:782 ]- The cron job to reset connections will be set to the default value of 0 0 0 * * ?
2016-06-16 22:40:50.207 [INFO ] [t.AbstractSocketChannelBinding:789 ]- The setting to queue write operation until a channel gets connected will be set to the default value of true
2016-06-16 22:40:50.209 [INFO ] [t.AbstractSocketChannelBinding:796 ]- The port to listen for incoming connections will be set to the default value of 0
2016-06-16 22:40:50.210 [INFO ] [t.AbstractSocketChannelBinding:803 ]- The setting to share channels within an Item will be set to the default value of true
2016-06-16 22:40:50.211 [INFO ] [t.AbstractSocketChannelBinding:810 ]- The setting to share channels between the items with the same direction will be set to the default value of t
rue
2016-06-16 22:40:50.212 [INFO ] [t.AbstractSocketChannelBinding:817 ]- The setting to share channels between directions will be set to the default value of true
2016-06-16 22:40:50.214 [INFO ] [t.AbstractSocketChannelBinding:824 ]- The setting to use address masks for incoming connections will be set to the default value of true
2016-06-16 22:40:50.230 [INFO ] [t.protocol.internal.TCPBinding:173 ]- The maximum time out for blocking write operations will be set to the default vaulue of 3000
2016-06-16 22:40:50.232 [INFO ] [t.protocol.internal.TCPBinding:180 ]- The blocking nature of read/write operations will be set to the default vaulue of false
2016-06-16 22:40:50.233 [INFO ] [t.protocol.internal.TCPBinding:187 ]- The preamble for all write operations will be set to the default vaulue of ""
2016-06-16 22:40:50.234 [INFO ] [t.protocol.internal.TCPBinding:194 ]- The postamble for all write operations will be set to the default vaulue of ""
2016-06-16 22:40:50.236 [INFO ] [t.protocol.internal.TCPBinding:201 ]- Updating states with returned values will be set to the default vaulue of true
2016-06-16 22:41:35.751 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]

Hrmmm… the reported object names are different between our bindings! (“AbstractDatagramChannelBinding” vs “t.AbstractSocketChannelBinding:768”!)

Here’s the entire option list for tcp-udp from my openhab.cfg:

################################# TCP - UDP Binding ###################################
#
# all parameters can be applied to both the TCP and UDP binding unless
# specified otherwise

# Port to listen for incoming connections
#tcp:port=25001

# Cron-like string to reconnect remote ends, e.g for unstable connection or remote ends
#tcp:reconnectcron=0 0 0 * * ?

# Interval between reconnection attempts when recovering from a communication error,
# in seconds
#tcp:retryinterval=5

# Queue data whilst recovering from a connection problem (TCP only)
#tcp:queue=true

# Maximum buffer size whilst reading incoming data
#tcp:buffersize=1024

# Share connections within the Item binding configurations
#tcp:itemsharedconnections=true

# Share connections between Item binding configurations
#tcp:bindingsharedconnections=true

# Share connections between inbound and outbound connections
#tcp:directionssharedconnections=false

# Allow masks in ip:port addressing, e.g. 192.168.0.1:* etc
#tcp:addressmask=true

# Pre-amble that will be put in front of data being sent
#tcp:preamble=

# Post-amble that will be appended to data being sent
#tcp:postamble=\r\n

# Perform all write/read (send/receive) operations in a blocking mode, e.g. the binding
# will wait for a reply from the remote end after data has been sent
#tcp:blocking=false

# timeout, in milliseconds, to wait for a reply when initiating a blocking write/read
#  operation
#tcp:timeout=3000

# Update the status of Items using the response received from the remote end (if the
# remote end sends replies to commands)
#tcp:updatewithresponse=true

# Timeout - or 'refresh interval', in milliseconds, of the worker thread
tcp:refreshinterval=250

# Timeout, in milliseconds, to wait when "Selecting" IO channels ready for communication
#tcp:selecttimeout=1000

# Used character set
tcp:charset=ASCII
udp:charset=ASCII

I have one (apparently default) options in the log that have no mention in your list:

The setting to queue write operation until a channel gets connected will be set to the default value of true

And you have one (looks like a critical one!) that is not mentioned in my list:

UDP Refresh Service has been started

This seems to leave two possibilities… either something in your config is really different than mine, or somehow you have a really different (grumble!workinggrumble!) version of the tcp binding than what shipped with 1.8.1 and also 1.9.x that’s available on cloudbees.

…so what’s the entirety of your tcp/udp config look like in openhab.cfg? :smiley:

(Don’t misread my frustration as frustration at you – very happy you’re doing a deep dive trying to help! Just generally frustrated. Thanks in advance!)

I don’t have access to my config right now ( and probably won’t be able to check that until tomorrow). However, AbstractSocketChannelBinding is for the TCP-related code. The log messages for that are in my log too. I just didn’t include them because they weren’t relevant. The AbstractDatagramChannelBinding is the log category for the UDP-related code. Also, the log messages for the TCP and UDP initialization will not be the same.

I’ve verified several times that adding and removing the udp config line will enable or disable the channel initialization of the UDP part of the binding.