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

TheKorn · June 17, 2016, 2:07am

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?

steve1 · June 17, 2016, 10:14am

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.

TheKorn · June 17, 2016, 12:12pm

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?

(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!)

steve1 · June 17, 2016, 12:24pm

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.

TheKorn · June 17, 2016, 12:36pm

I’m wondering out loud if there isn’t a combination of config lines that’s causing your config to work and mine not to. Obviously that shouldn’t be, but clearly we’re missing something.

It’s either that or by process of elimination your binding is different than mine.

cameronaps · June 17, 2016, 9:59pm

Hi,

I also had huge issues getting TCP binding to work initially. Here is my config that works well.
################################# TCP - UDP Binding ###################################

all parameters can be applied to both the TCP and UDP binding #unless

specified otherwise

Port to listen for incoming connections

udp:port=25002

Cron-like string to reconnect remote ends, e.g for unstable #connection or remote ends

#udp:reconnectron=‘0 0 0 * * ?’

Interval between reconnection attempts when recovering from a communication error,

in seconds

#udp:retryinterval=3

Queue data whilst recovering from a connection problem (TCP #only)

udp:queue=true

Maximum buffer size whilst reading incoming data

udp:buffersize=20

Share connections within the Item binding configurations

udp:itemsharedconnections=true

Share connections between Item binding configurations

udp:bindingsharedconnections=false

Share connections between inbound and outbound connections

udp:directionssharedconnections=true

Allow masks in ip:port addressing, e.g. 192.168.0.1:* etc

udp:addressmask=true

Pre-amble that will be put in front of data being sent

#udp:preamble=’’

Post-amble that will be appended to data being sent

#//udp: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

udp:blocking=false

timeout, in milliseconds, to wait for a reply when initiating a blocking write/read

operation

udp:timeout=1000

Update the status of Items using the response received from the remote end (if the

remote end sends replies to commands)

udp:updatewithresponse=false

Timeout - or ‘refresh interval’, in milliseconds, of the worker thread

udp:refreshinterval=1500

Timeout, in milliseconds, to wait when “Selecting” IO channels ready for communication

udp:selecttimeout=1000

Used character set

#tcp:charset=ASCII

And here is a switch example that works.

Switch Study_Lights “Study Lights” (Study, Lights_Interior) {udp=">[ON:10.0.2.90:8888:‘MAP(Study_Light.map)’],>[OFF:10.0.2.90:8888:‘MAP(Study_Light.map)’]"}

PS sorry for the formatting of the post. I can never work out how to do it properly!!!

TheKorn · June 17, 2016, 10:23pm

Thanks… For giggles I copied all your info into my openhab.cfg, and then made a slightly different item since I don’t have your map file:

String  MYTHTV "[%s]" {udp=">[172.18.0.108:6948:REGEX((.*))]"}
String  MYTHTV2 {udp=">[localhost:8888:REGEX((.*))]" }
Switch  MYTHTV3 {udp=">[ON:10.0.2.90:8888:REGEX((.*))],>[OFF:10.0.2.90:8888:REGEX((.*))]"}

And updated my rule…

rule "shut off test switch 1 always"
when
    // only process on a switch on state
    Item TEST_SWITCH_1 changed to ON
then
    {
        logInfo("openhab","Test switch 1 pressed.")
        var String mymessage
        mymessage = "testing"
        logInfo("openhab", "test message sent:" + mymessage)
        sendCommand(MYTHTV,mymessage)
        sendCommand(MYTHTV2,mymessage)
        sendCommand(MYTHTV3,ON)
        sendCommand(MYTHTV3,OFF)
    }    
end

…unfortunately…

2016-06-17 17:20:01.645 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV, command=testing]
2016-06-17 17:20:01.914 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV2, command=testing]
2016-06-17 17:20:02.193 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV3, command=ON]
2016-06-17 17:20:02.444 [ERROR] [AbstractDatagramChannelBinding:943 ]- there is no channel that services [itemName=MYTHTV3, command=OFF]

Udo_Hartmann · June 18, 2016, 6:01pm

Could you please resubmit your openhab.cfg in question of udp and tcp, but please set three backticks ` ahead and behind the quote to avoid changes through the forum’s software? Maybe you have a typo near

//udp:postamble='\r\n'

// is commenting out in .items .rules, but not in openhab.cfg…

TheKorn · June 19, 2016, 2:55am

To whom are you talking? @cameronaps or myself?

Udo_Hartmann · June 19, 2016, 10:44am

Sorry, I meant @cameronaps

steve1 · June 19, 2016, 10:47am

Just to follow up… I commented all tcp/udp configs in openhab.cfg except for udp:charset=ASCII and the binding worked correctly, as described earlier. @TheKorn, for some reason your system is not picking up the UDP configurations (based on the missing log files). I don’t have any theory for why that is happening (I’m assuming you are modifying the correct openhab.cfg). You could run a remote debugger to see what’s happening in the server but that may be more work than you want to invest.

TheKorn · June 19, 2016, 10:52am

@steve1 Can you give me a thumbnail of what would be required?

And yeah, really sure I’m writing to the correct openhab.cfg. It picks up all the other changes I make!

(Just realized that JRE might be the variable here…)

steve1 · June 19, 2016, 11:22am

Just a thought… are there any warnings or errors being logged by the ConfigDispatcher?

For remote debugging, the basic idea is to set up an openHAB 1.8 Eclipse-based development environment, add a few arguments to the openHAB server startup to enable remote debugging over a socket and then create an Eclipse remote debugging configuration. After setting breakpoints, you would start Eclipse and connect to the running openHAB server over a TCP socket. When the breakpoints are hit, you can step through the execution from Eclipse.

TheKorn · June 19, 2016, 11:26am

You’re going to have to help me out here… ELI5 what the ConfigDispatcher is, and where it logs stuff.

I might just have to go the remote debugging route. (I really want to get this working!)

steve1 · June 19, 2016, 11:28am

It would be in the regular openhab log file. The logging category will end with ConfigDispatcher. For that matter, I’d look for any warnings or errors in the log file in any category.

TheKorn · June 19, 2016, 11:39am

Huh…

2016-06-19 06:03:40.508 [ERROR] [o.config.core.ConfigDispatcher] - Main openHAB configuration file 'configurations/openhab.cfg' cannot be read.
        at org.openhab.config.core.ConfigDispatcher.processConfigFile(ConfigDispatcher.java:212) [org.openhab.config.core_1.8.1.jar:na]
        at org.openhab.config.core.ConfigDispatcher.initializeMainConfiguration(ConfigDispatcher.java:169) [org.openhab.config.core_1.8.1.jar:na]
        at org.openhab.config.core.ConfigDispatcher.initializeBundleConfigurations(ConfigDispatcher.java:139) [org.openhab.config.core_1.8.1.jar:na]
        at org.openhab.config.core.ConfigDispatcher.activate(ConfigDispatcher.java:99) [org.openhab.config.core_1.8.1.jar:na]

…but I believe this may be a case of one error that actually signals another. Reason being is that openhab is still able to pick up my zwave, mail, imperihab, and network health configs that are in the same file. I’d expect if OH actually couldn’t read the file that all of those should fall out of the system entirely!

WTF++. Well at least I have an idea of where to look, though not really sure what to look for. World has read and execute attributes to that directory, that directory’s parent, and the openhab.cfg file, so I literally can’t figure out why it wouldn’t be able to read it. I think I’ll make a dummy account not in the group and brute test test the file permissions.

steve1 · June 19, 2016, 3:30pm

I recommend configuring the logging for org.openhab.config.core so it logs at TRACE level. The code will log more details about which files it’s loading (including the absolute path, which would very useful in this case).

TheKorn · June 19, 2016, 5:23pm

Thanks!

2016-06-19 12:04:10.982 [DEBUG] [o.config.core.ConfigDispatcher] - Processing openHAB main configuration file '/usr/local/openhab/configurations/openhab.cfg'.
2016-06-19 12:04:11.013 [ERROR] [o.config.core.ConfigDispatcher] - Main openHAB configuration file 'configurations/openhab.cfg' cannot be read.
java.io.IOException: Permission denied

vince@openhab:/usr/local$ sudo -u openhab less /usr/local/openhab/configurations/openhab.cfg
# This is the default configuration file, which comes with every openHAB distribution.
#  NOT ANYMORE, B****ES!!  VG 3/1/2016  :D

#######################################################################################
#####                        General configurations                               #####
#######################################################################################

(etc.etc.etc.)

(bang heads against brick)

So openhab says it can’t read it, but when I do a sudo -u openhab (the user that openhab runs under) and ask to read the file, it can read it just fine!??!? What user is openhab trying to read the file as, nobody? Heck even that should work, since world has read privileges!

Actually let’s test that! Add user nobody2, give 'em a password, don’t add them to OH group or anything…

vince@openhab:/usr/local$ sudo useradd nobody2
vince@openhab:/usr/local$ sudo passwd nobody2
Enter new UNIX password:
Retype new UNIX password:
passwd: password updated successfully
vince@openhab:/usr/local$ exit
logout
Connection to 172.18.0.55 closed.

C:\Users\vince>ssh nobody2@172.18.0.55
nobody2@172.18.0.55's password:
Welcome to Ubuntu 14.04.4 LTS (GNU/Linux 3.13.0-79-generic x86_64)

 * Documentation:  https://help.ubuntu.com/


The programs included with the Ubuntu system are free software;
the exact distribution terms for each program are described in the
individual files in /usr/share/doc/*/copyright.

Ubuntu comes with ABSOLUTELY NO WARRANTY, to the extent permitted by
applicable law.


The programs included with the Ubuntu system are free software;
the exact distribution terms for each program are described in the
individual files in /usr/share/doc/*/copyright.

Ubuntu comes with ABSOLUTELY NO WARRANTY, to the extent permitted by
applicable law.

Could not chdir to home directory /home/nobody2: No such file or directory
$ head -10 /usr/local/openhab/configurations/openhab.cfg
# This is the default configuration file, which comes with every openHAB distribution.
#  NOT ANYMORE, B****ES!!  VG 3/1/2016  :D

#######################################################################################
#####                        General configurations                               #####
#######################################################################################

So… literally any user on the box (even a ten second old user) has rights to read that file, and somehow OH cannot. Ugh. Makes no sense to me how that could be possible.

Udo_Hartmann · June 19, 2016, 5:48pm

So what’s the output of

ls -l /usr/local/openhab/configurations/

?
Is your system a raspberryPi? Maybe your file system is corrupt (this happens from time to time, especially when using [micro]SD cards)

I’m pretty sure, openHAB has read permissions, and there is another failure within your openhab.cfg.
You could rename your openhab.cfg to openhab_old.cfg and then copy it to openhab.cfg, so that it will be a new file. Then search the new file for hidden errors, maybe a // instead of a #, or a space at the beginning of a configuration, a . instead of a : and so on.
Because zwave seems to be ok, the error might occur after zwave config?

TheKorn · June 20, 2016, 3:35am

vince@openhab:~$ ls -l /usr/local/openhab/configurations/
total 968
drwxrwsr-x 2 openhab openhab   4096 Mar 28 13:26 documentation_vince
drwxrwsr-x 3 openhab openhab   4096 Jun 16 15:25 items
-rw-rw-r-- 1 openhab openhab   3733 Mar  4 04:43 logback_debug.xml
-rw-rw-r-- 1 openhab openhab   5027 Jun 19 12:03 logback.xml
-rw-r--r-- 1 root    openhab   4907 Jun 19 12:01 logback.xml.bak
drwxrwsr-x 2 openhab openhab   4096 Mar  2 01:00 maintenance_scripts
-rwxrw-r-- 1 openhab openhab  89109 Jun 17 17:24 openhab.cfg
-rwxr--r-- 1 root    openhab  89109 Jun 19 12:01 openhab.cfg.bak
-rw-rw-r-- 1 openhab openhab  88830 Mar 16 16:08 openhab.cfg.bak2
-rw-rw-r-- 1 openhab openhab  83943 Jan 12 13:11 openhab_default.cfg
-rw-rw-r-- 1 openhab openhab 576402 Feb 17 01:15 openhab.sql.backup
drwxrwsr-x 4 openhab openhab   4096 Feb 20 09:42 persistence
drwxrwsr-x 2 openhab openhab   4096 May 25 21:43 rules
drwxrwsr-x 2 openhab openhab   4096 Feb 20 09:42 scripts
drwxrwsr-x 2 openhab openhab   4096 May  2 16:25 sitemaps
drwxrwsr-x 2 openhab openhab   4096 Apr 29 07:06 transform
-rw-rw-r-- 1 openhab openhab     24 Jan 12 13:11 users.cfg

Nope, intel Atom running off of a 240GB corsair SSD that only has 64GB partitioned on it (i.e. so write leveling has loooooooots of room to work with) with 2GB of ram. Nothing interesting in syslog, nothing interesting in dmesg (keeps saying ethernet card is going into/out of promiscuous mode, but that’s because I keep running tcpdump… )

vince@openhab:/var/log$ df -h
Filesystem             Size  Used Avail Use% Mounted on
udev                   1.5G  4.0K  1.5G   1% /dev
tmpfs                  301M  1.5M  300M   1% /run
/dev/sda1               58G  5.3G   50G  10% /
none                   4.0K     0  4.0K   0% /sys/fs/cgroup
none                   5.0M  4.0K  5.0M   1% /run/lock
none                   1.5G  440K  1.5G   1% /run/shm
none                   100M   32K  100M   1% /run/user

vince@openhab:/var/log$ free -h
             total       used       free     shared    buffers     cached
Mem:          2.9G       2.2G       723M       8.6M       224M       1.0G
-/+ buffers/cache:       1.0G       2.0G
Swap:         1.0G         0B       1.0G

Yeah that’s what I’m feeling as well. I even went so far as to backup my openhab.cfg, copy openhab_default.cfg to openhab.cfg, and go through and transfer options section by section (there were only three or four that I really needed to configure). No change!

Filesystem is fine, auto fsck’s on boot, plus it’s ext4 with journaling anyway so it’s tough to knock over. (I don’t think the system has ever had a hard crash, actually!)

Actually looking at this message, could this be some sort of locking issue?

java.io.IOException: Permission denied
        at java.io.UnixFileSystem.createFileExclusively(Native Method) ~[na:1.7.0_101]