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

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]

Udo_Hartmann · June 20, 2016, 10:18am

Did you setup openHAB manually?

Maybe it’s worth to do a

sudo chown openhab: /usr/local/openhab -R

just to be sure, there are no other files and/or folders, of which openHAB needs write permission.

How do you edit your configs?

steve1 · June 20, 2016, 10:30am

Given the file appears to be readable, I think we may be trying to diagnose the wrong cause of the exception. Any IOException thrown from ConfigDispatcher.processConfigFile will be logged as file “cannot be read”. This is not good since there are several potential sources of IOException in that code.

The first stack trace you posted did not have the createFileExclusively method in the call stack. The line where the exception originated is where the config is passed to some binding. I’m starting to think that some binding is throwing an IOException during configuration processing and this terminates the configuration file processing. That would explain why you see some of your configs (processed before the exception) and not others. Based on the createFileExclusively call stack line, I’d guess a binding is trying to create a file and cannot for some reason (permissions, invalid location, etc.).

If my guess is correct, we need to determine which binding is trigging the exception during configuration processing and why. Is there a complete call stack logged for the `createFileExclusively’?

TheKorn · June 20, 2016, 1:27pm

Yeah, followed the getting started steps. Don’t really remember why I selected /usr/local/openhab . I had a good reason at some point.

Can’t hurt, that’s for sure.

I nuked the openhab.log file right before restarting last night, so easy to grab…

2016-06-19 22:32:34.345 [DEBUG] [o.config.core.ConfigDispatcher] - Processing openHAB default configuration file '/usr/local/openhab/configurations/openhab_default.cfg'.
2016-06-19 22:32:34.431 [ERROR] [o.config.core.ConfigDispatcher] - Default openHAB configuration file 'configurations/openhab_default.cfg' cannot be read.
java.io.IOException: Permission denied
        at java.io.UnixFileSystem.createFileExclusively(Native Method) ~[na:1.7.0_101]
        at java.io.File.createTempFile(File.java:2001) ~[na:1.7.0_101]
        at org.eclipse.equinox.internal.cm.reliablefile.ReliableFile.getOutputStream(ReliableFile.java:341) ~[na:na]
        at org.eclipse.equinox.internal.cm.reliablefile.ReliableFileOutputStream.<init>(ReliableFileOutputStream.java:98) ~[na:na]
        at org.eclipse.equinox.internal.cm.reliablefile.ReliableFileOutputStream.<init>(ReliableFileOutputStream.java:49) ~[na:na]
        at org.eclipse.equinox.internal.cm.ConfigurationStore.writeConfigurationFile(ConfigurationStore.java:113) ~[na:na]
        at org.eclipse.equinox.internal.cm.ConfigurationStore$1.run(ConfigurationStore.java:99) ~[na:na]
        at java.security.AccessController.doPrivileged(Native Method) [na:1.7.0_101]
        at org.eclipse.equinox.internal.cm.ConfigurationStore.saveConfiguration(ConfigurationStore.java:97) ~[na:na]
        at org.eclipse.equinox.internal.cm.ConfigurationImpl.update(ConfigurationImpl.java:255) ~[na:na]
        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.initializeDefaultConfiguration(ConfigDispatcher.java:147) [org.openhab.config.core_1.8.1.jar:na]
        at org.openhab.config.core.ConfigDispatcher.initializeBundleConfigurations(ConfigDispatcher.java:138) [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]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_101]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_101]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_101]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_101]
        at org.eclipse.equinox.internal.ds.model.ServiceComponent.activate(ServiceComponent.java:235) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.activate(ServiceComponentProp.java:146) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.build(ServiceComponentProp.java:345) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponent(InstanceProcess.java:620) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.ServiceReg.getService(ServiceReg.java:53) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceUse$1.run(ServiceUse.java:141) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at java.security.AccessController.doPrivileged(Native Method) [na:1.7.0_101]
        at org.eclipse.osgi.internal.serviceregistry.ServiceUse.getService(ServiceUse.java:139) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:468) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:467) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.internal.core.BundleContextImpl.getService(BundleContextImpl.java:594) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.equinox.internal.cm.ManagedServiceTracker.addingService(ManagedServiceTracker.java:65) [org.eclipse.equinox.cm_1.0.400.v20120522-1841.jar:na]
        at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:932) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:1) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:894) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:107) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:130) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:214) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:433) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:260) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.SCRManager.performWork(SCRManager.java:816) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.SCRManager$QueuedJob.dispatch(SCRManager.java:783) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.WorkThread.run(WorkThread.java:89) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor.run(Executor.java:70) [org.eclipse.equinox.util_1.0.400.v20120917-192807.jar:na]
2016-06-19 22:32:34.433 [DEBUG] [o.config.core.ConfigDispatcher] - Processing openHAB main configuration file '/usr/local/openhab/configurations/openhab.cfg'.
2016-06-19 22:32:34.467 [ERROR] [o.config.core.ConfigDispatcher] - Main openHAB configuration file 'configurations/openhab.cfg' cannot be read.
java.io.IOException: Permission denied
        at java.io.UnixFileSystem.createFileExclusively(Native Method) ~[na:1.7.0_101]
        at java.io.File.createTempFile(File.java:2001) ~[na:1.7.0_101]
        at org.eclipse.equinox.internal.cm.reliablefile.ReliableFile.getOutputStream(ReliableFile.java:341) ~[na:na]
        at org.eclipse.equinox.internal.cm.reliablefile.ReliableFileOutputStream.<init>(ReliableFileOutputStream.java:98) ~[na:na]
        at org.eclipse.equinox.internal.cm.reliablefile.ReliableFileOutputStream.<init>(ReliableFileOutputStream.java:49) ~[na:na]
        at org.eclipse.equinox.internal.cm.ConfigurationStore.writeConfigurationFile(ConfigurationStore.java:113) ~[na:na]
        at org.eclipse.equinox.internal.cm.ConfigurationStore$1.run(ConfigurationStore.java:99) ~[na:na]
        at java.security.AccessController.doPrivileged(Native Method) [na:1.7.0_101]
        at org.eclipse.equinox.internal.cm.ConfigurationStore.saveConfiguration(ConfigurationStore.java:97) ~[na:na]
        at org.eclipse.equinox.internal.cm.ConfigurationImpl.update(ConfigurationImpl.java:255) ~[na:na]
        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]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_101]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_101]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_101]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_101]
        at org.eclipse.equinox.internal.ds.model.ServiceComponent.activate(ServiceComponent.java:235) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.activate(ServiceComponentProp.java:146) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.build(ServiceComponentProp.java:345) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponent(InstanceProcess.java:620) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.ServiceReg.getService(ServiceReg.java:53) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceUse$1.run(ServiceUse.java:141) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at java.security.AccessController.doPrivileged(Native Method) [na:1.7.0_101]
        at org.eclipse.osgi.internal.serviceregistry.ServiceUse.getService(ServiceUse.java:139) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:468) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:467) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.internal.core.BundleContextImpl.getService(BundleContextImpl.java:594) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.equinox.internal.cm.ManagedServiceTracker.addingService(ManagedServiceTracker.java:65) [org.eclipse.equinox.cm_1.0.400.v20120522-1841.jar:na]
        at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:932) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:1) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:894) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:107) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:130) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:214) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:433) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
        at org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:260) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.SCRManager.performWork(SCRManager.java:816) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.SCRManager$QueuedJob.dispatch(SCRManager.java:783) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.ds.WorkThread.run(WorkThread.java:89) [org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
        at org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor.run(Executor.java:70) [org.eclipse.equinox.util_1.0.400.v20120917-192807.jar:na]
2016-06-19 22:32:34.486 [INFO ] [.o.core.internal.CoreActivator] - openHAB runtime has been started (v1.8.1).
2016-06-19 22:32:38.346 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl] - mDNS service has been started
2016-06-19 22:32:38.463 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl] - Service Discovery initialization completed.
2016-06-19 22:32:47.393 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'thermostat.sitemap'
2016-06-19 22:32:47.534 [INFO ] [penhab.io.rest.RESTApplication] - Started REST API at /rest
2016-06-19 22:32:47.896 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2016-06-19 22:32:47.981 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'vera.sitemap'
2016-06-19 22:32:48.151 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'db4o.persist'
2016-06-19 22:32:48.212 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'mysql.persist'
2016-06-19 22:32:48.245 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2016-06-19 22:32:48.259 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'logging.persist'
2016-06-19 22:32:48.279 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'exec.persist'
2016-06-19 22:32:48.398 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'other.items'
2016-06-19 22:32:48.494 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'locks.items'
2016-06-19 22:32:48.550 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'thermostat.items'
(seems reasonable to stop copying info at this point)

…but that kind of brings up another question. When I was trying to enable debug logging for core, I added this to my logback.xml:

<logger name="org.openhab.config.core" level="TRACE" additivity="false">
       <appender-ref ref="FILE" />
</logger>

…is that the correct method of getting core messages into openhab.log ?

SON OF A… well something certainly liked that chown -R! Just restarted after the chown, and now in my tcp binding log…

2016-06-20 08:17:09.657 [DEBUG] [AbstractDatagramChannelBinding:1337]- Setting up the outbound channel Channel [item=MYTHTV, command=0, direction=OUT, remote=/172.18.0.108:6948, bu
ffer=, isBlocking=false, isReconnecting=false, channel=, host=172.18.0.108, port=6948]
2016-06-20 08:17:09.658 [INFO ] [AbstractDatagramChannelBinding:1341]- 'Connecting' the channel Channel [item=MYTHTV, command=0, direction=OUT, remote=/172.18.0.108:6948, buffer=,
isBlocking=false, isReconnecting=false, channel=, host=172.18.0.108, port=6948]
2016-06-20 08:17:09.661 [DEBUG] [AbstractDatagramChannelBinding:1337]- Setting up the outbound channel Channel [item=MYTHTV3, command=OFF, direction=OUT, remote=/10.0.2.90:8888, bu
ffer=, isBlocking=false, isReconnecting=false, channel=, host=10.0.2.90, port=8888]
2016-06-20 08:17:09.664 [INFO ] [AbstractDatagramChannelBinding:1341]- 'Connecting' the channel Channel [item=MYTHTV3, command=OFF, direction=OUT, remote=/10.0.2.90:8888, buffer=,
isBlocking=false, isReconnecting=false, channel=, host=10.0.2.90, port=8888]
2016-06-20 08:17:09.665 [DEBUG] [AbstractDatagramChannelBinding:1305]- Setting up the outbound assigned channel Channel [item=MYTHTV3, command=ON, direction=OUT, remote=/10.0.2.90:
8888, buffer=, isBlocking=false, isReconnecting=false, channel=/172.18.0.55:41331::/10.0.2.90:8888, host=10.0.2.90, port=8888]
2016-06-20 08:17:09.666 [INFO ] [AbstractDatagramChannelBinding:1348]- There is already an active channel sun.nio.ch.DatagramChannelImpl@3596f070 for the remote end /10.0.2.90:8888
2016-06-20 08:17:09.668 [DEBUG] [AbstractDatagramChannelBinding:1337]- Setting up the outbound channel Channel [item=MYTHTV2, command=1, direction=OUT, remote=localhost/127.0.0.1:8
888, buffer=, isBlocking=false, isReconnecting=false, channel=, host=localhost, port=8888]
2016-06-20 08:17:09.669 [INFO ] [AbstractDatagramChannelBinding:1341]- 'Connecting' the channel Channel [item=MYTHTV2, command=1, direction=OUT, remote=localhost/127.0.0.1:8888, bu
ffer=, isBlocking=false, isReconnecting=false, channel=, host=localhost, port=8888]

Best of all, tcpdump verifies that udp packets are being blasted out on the correct port! Yay! (Now to go back a few days and not make it spew garbage… but that’s my deal. )

Wow, what a wild goose chase! Thanks so much @steve1 and @Udo_Hartmann an for hanging tough with this one!

Udo_Hartmann · June 20, 2016, 4:17pm

Catchouw