This page last changed on Oct 15, 2013 by juha.

Hey everyone,
I'm having a handful of problems all minor but all annoying .
And I'm trying to find out if they are linked together or not.
Anyway I have noticed the knx-debug.log is spitting out a lot of Polling device status logs and I'm trying to understand what it all means.

DEBUG 2013-10-11 11:22:05,027 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/20 Data: 0x00
DEBUG 2013-10-11 11:22:05,028 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 0/0/2 Data: 0x00
DEBUG 2013-10-11 11:22:05,028 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 6/0/6 Data: 0x00
DEBUG 2013-10-11 11:22:05,032 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 9/1/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,032 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 3/0/1 Data: 0x00
DEBUG 2013-10-11 11:22:05,033 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 4/1/0 Data: 0x00
DEBUG 2013-10-11 11:22:05,033 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/5/6 Data: 0x00
DEBUG 2013-10-11 11:22:05,034 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/31 Data: 0x00
DEBUG 2013-10-11 11:22:05,036 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/2/14 Data: 0x00
DEBUG 2013-10-11 11:22:05,037 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 2/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,037 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/2/16 Data: 0x00
DEBUG 2013-10-11 11:22:05,123 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/21 Data: 0x00
DEBUG 2013-10-11 11:22:05,123 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 9/1/5 Data: 0x00
DEBUG 2013-10-11 11:22:05,125 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/43 Data: 0x00
DEBUG 2013-10-11 11:22:05,127 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/5/5 Data: 0x00
DEBUG 2013-10-11 11:22:05,127 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/5/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,127 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/2/13 Data: 0x00
DEBUG 2013-10-11 11:22:05,128 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 7/0/6 Data: 0x00
DEBUG 2013-10-11 11:22:05,128 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 6/0/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,128 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/16 Data: 0x00
DEBUG 2013-10-11 11:22:05,134 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 2/0/7 Data: 0x00
DEBUG 2013-10-11 11:22:05,134 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/36 Data: 0x00
DEBUG 2013-10-11 11:22:05,135 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 5/0/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,136 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/6/0 Data: 0x00
DEBUG 2013-10-11 11:22:05,143 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 2/0/5 Data: 0x00
DEBUG 2013-10-11 11:22:05,253 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/45 Data: 0x00
DEBUG 2013-10-11 11:22:05,253 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 4/0/1 Data: 0x00
DEBUG 2013-10-11 11:22:05,375 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/2/15 Data: 0x00
DEBUG 2013-10-11 11:22:05,376 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/8 Data: 0x00
DEBUG 2013-10-11 11:22:05,376 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 7/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,378 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 9/1/0 Data: 0x00
DEBUG 2013-10-11 11:22:05,379 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 4/0/5 Data: 0x00
DEBUG 2013-10-11 11:22:05,474 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/15 Data: 0x00
DEBUG 2013-10-11 11:22:05,475 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/11 Data: 0x00
DEBUG 2013-10-11 11:22:05,476 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,476 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 4/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,477 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/47 Data: 0x00
DEBUG 2013-10-11 11:22:05,477 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/35 Data: 0x00
DEBUG 2013-10-11 11:22:05,478 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 5/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,478 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/9 Data: 0x00
DEBUG 2013-10-11 11:22:05,479 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/30 Data: 0x00
DEBUG 2013-10-11 11:22:05,479 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 2/0/1 Data: 0x00
DEBUG 2013-10-11 11:22:05,480 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 7/0/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,481 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,480 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 6/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,528 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/20 Data: 0x00
DEBUG 2013-10-11 11:22:05,528 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 0/0/2 Data: 0x00
DEBUG 2013-10-11 11:22:05,529 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 6/0/6 Data: 0x00
DEBUG 2013-10-11 11:22:05,532 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 9/1/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,533 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 3/0/1 Data: 0x00
DEBUG 2013-10-11 11:22:05,534 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 4/1/0 Data: 0x00
DEBUG 2013-10-11 11:22:05,534 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/5/6 Data: 0x00
DEBUG 2013-10-11 11:22:05,535 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/31 Data: 0x00
DEBUG 2013-10-11 11:22:05,537 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/2/14 Data: 0x00
DEBUG 2013-10-11 11:22:05,538 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 2/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,538 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/2/16 Data: 0x00
DEBUG 2013-10-11 11:22:05,618 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 5/0/7 Data: 0x00
DEBUG 2013-10-11 11:22:05,624 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/21 Data: 0x00
DEBUG 2013-10-11 11:22:05,624 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 9/1/5 Data: 0x00
DEBUG 2013-10-11 11:22:05,626 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/43 Data: 0x00
DEBUG 2013-10-11 11:22:05,627 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/5/5 Data: 0x00
DEBUG 2013-10-11 11:22:05,629 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 6/0/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,629 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/2/13 Data: 0x00
DEBUG 2013-10-11 11:22:05,629 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/5/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,630 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/16 Data: 0x00
DEBUG 2013-10-11 11:22:05,631 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 7/0/6 Data: 0x00
DEBUG 2013-10-11 11:22:05,635 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 2/0/7 Data: 0x00
DEBUG 2013-10-11 11:22:05,635 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/36 Data: 0x00
DEBUG 2013-10-11 11:22:05,636 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 5/0/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,636 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/6/0 Data: 0x00
DEBUG 2013-10-11 11:22:05,644 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 2/0/5 Data: 0x00
DEBUG 2013-10-11 11:22:05,730 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/40 Data: 0x00
DEBUG 2013-10-11 11:22:05,753 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/45 Data: 0x00
DEBUG 2013-10-11 11:22:05,754 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 4/0/1 Data: 0x00
DEBUG 2013-10-11 11:22:05,863 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/25 Data: 0x00
DEBUG 2013-10-11 11:22:05,876 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/2/15 Data: 0x00
DEBUG 2013-10-11 11:22:05,878 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/8 Data: 0x00
DEBUG 2013-10-11 11:22:05,879 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 9/1/0 Data: 0x00
DEBUG 2013-10-11 11:22:05,879 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 7/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,881 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 4/0/5 Data: 0x00
DEBUG 2013-10-11 11:22:05,974 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/15 Data: 0x00
DEBUG 2013-10-11 11:22:05,976 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/11 Data: 0x00
DEBUG 2013-10-11 11:22:05,977 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,977 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 4/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,977 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/47 Data: 0x00
DEBUG 2013-10-11 11:22:05,978 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/35 Data: 0x00
DEBUG 2013-10-11 11:22:05,978 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 5/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,979 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/9 Data: 0x00
DEBUG 2013-10-11 11:22:05,980 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/30 Data: 0x00
DEBUG 2013-10-11 11:22:05,980 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 2/0/1 Data: 0x00
DEBUG 2013-10-11 11:22:05,980 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 7/0/4 Data: 0x00
DEBUG 2013-10-11 11:22:05,981 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/0/3 Data: 0x00
DEBUG 2013-10-11 11:22:05,983 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 6/0/3 Data: 0x00

All these logs are generated in the same second. This worries me a bit as I assume that polling a status generates traffic on the bus. Taking into account the limited speed available on the bus this would not be good. Why is Openremote doing all this polling? Can anyone clarify?

Seeing this output I start to wonder if the following is related:
First of all the quite high CPU usage, I have a 1.2 Ghz dual core atom processor on my ubuntu machine and Openremote is running 5 java threads at about 50% which seems high for software like Openremote.
Could the two be linked?

Then I have a much bigger and much more worrying issue. I have ABB touchsensors, lately I have noticed they have been getting unresponsive.
When I push a button the switch doesn't react. However if I push the button a second time it'll react and if I push it again for another 10 times it will work fine. It's like the switch has gone in sleep mode and pushing it once wakes it up again and from there it works fine again.

Any thoughts?
Thanks guys, as always any support much appreciated.
Stijn

Ok small update from my side.
I have found the issue with high memory consumption. I wanted to see if my touchsensors still have the same issue as described above without OR running. So I decided to take OR down.
After logging in on Ubuntu today I noticed it wasn't displaying the upgrades etc because of a high load.
I checked the running processes and all the java processes I mentioned above were still there but my OR was turned off yesterday.
After killing these old java processes and starting OR again I noticed only 1 java process.
I tried to stop the process by issuing ./openremote.sh stop and ./openremote.sh stop -force but both didn't stop the java process. I had to kill it manually.
The normal stop command didn't spit out an error however when running the stop command with the -force addition I got:

root@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ ./openremote.sh stop -force
Kill failed: $CATALINA_PID not set
Root@Server:~/OpenRemote-Controller-Pro1.0.10/bin$

It seems the "old" OR processes which were still running were also trying to connect to the KNX bus because when I started OR when all other old processes were killed it immediately connected to the bus where previous days it could take 10 to 15 minutes before it could connect. I tried it now twice in a row without any "old" processes and it connected instantly.

So I checked on the high amount of debug output and that's still the same so it seems the high cpu usage described in my first post is not related to this, hence can be scratched of the list.
Cheers
Stijn

Posted by garfield.arbuckle at Oct 13, 2013 00:53

The debug statement is a bit misleading (it may have been removed since, I don't recall exactly though). Anyhow, it's not a request sent on the bus, it's just moving the KNX device state from the protocol implementation to the controller's status cache. So no bus traffic is generated.

Posted by juha at Oct 15, 2013 13:10

Ok great,
Thanks Juha, any way I can disable this clutter?
It makes it difficult to debug.
Is it normal it constantly is generating these messages?
Thanks
Stijn

Posted by garfield.arbuckle at Oct 15, 2013 13:15

The knx.log is the normal log at info level or above, without the debug statements.

Posted by juha at Oct 15, 2013 13:21

Ok thanks.
Any idea on the java processes not stopping?
Anything I can do to prevent that besides killing them manually?
Stijn

Posted by garfield.arbuckle at Oct 15, 2013 13:24

IIRC, you need to set the CATALINA_PID env variable to point to a file handle that is used to store the process ID. The shutdown command will look for the PID from the location pointed by the CATALINA_PID variable.

Posted by juha at Oct 15, 2013 13:37

Ok have absolutely no clue what that means .
I will try and google it later
Stijn

Posted by garfield.arbuckle at Oct 15, 2013 13:45

Sorry didn't mean to make it sound complicated.

If running linux or mac osx, you can do:

> export CATALINA_PID=/path/to/pid.file
> sh openremote.sh start
> sh openremote.sh stop -force

If you check the pid.file content, you'll see it will store the process id number there which is what the 'stop' picks up when it looks for which process to kill (note you will need to use to force for now for immediate shutdown, the plain stop won't stop immediately due to running threads, which we are not managing, and the container will not stop them for some very long time period – maybe 5 minutes – or maybe wait for them indefinitely to stop working – which they wont, so only -force will work).

Posted by juha at Oct 22, 2013 00:18

Hey Juha,
No problem, I had my Linux savvy colleague have a look at it and in the mean time I've been able to figure it out.
For the non linux experts here's how I did it, might not be the cleanest way of doing it so any tips from people with more Linux experience is always welcome:

Step 1: Understanding the problem
------

Start openremote by going to the bin folder in your OR folder:

user@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ ./openremote.sh start

You have started openremote, now lets stop it

user@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ ./openremote.sh stop -force

We are using the -force option for the reason Juha mentioned in the post above and we're getting the following error

Kill failed: $CATALINA_PID not set

Ok so what does this mean. The force option uses a kill command to stop the java process which is associated to OR however you need to set this environment variable in your system.
Otherwise OR won't be able to find the java process and kill it.

Now issue the top command

user@Server:~/top

this will show you the processes which are using most of the CPU power. On my server the java thread for OR is right at the top of top (yes pun intended)

top - 11:14:44 up 22 days, 17:39, 1 user, load average: 0.20, 0.24, 0.20
Tasks: 101 total, 1 running, 100 sleeping, 0 stopped, 0 zombie
Cpu(s): 1.3%us, 0.7%sy, 0.0%ni, 98.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 2050912k total, 1958740k used, 92172k free, 316352k buffers
Swap: 376828k total, 72548k used, 304280k free, 854096k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
28849 user 20 0 3054m 338m 11m S 5 16.9 2:32.89 java

The PID for the java thread here is 28849, now press 'k' and you'll be able to kill it by issuing the PID number

top - 11:16:30 up 22 days, 17:40, 1 user, load average: 0.03, 0.17, 0.18
Tasks: 101 total, 1 running, 100 sleeping, 0 stopped, 0 zombie
Cpu(s): 1.5%us, 0.6%sy, 0.0%ni, 97.8%id, 0.0%wa, 0.0%hi, 0.1%si, 0.0%st
Mem: 2050912k total, 1956640k used, 94272k free, 316428k buffers
Swap: 376828k total, 72548k used, 304280k free, 854116k cached
PID to kill: 28849
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
28849 user 20 0 3054m 335m 11m S 5 16.8 2:38.60 java

Ok so the java process has been killed, lets do the config to link the PID so it can be killed by OR.

Step 2: Create the file to store the PID.
-------

What I have done is just create an empty file in the OR bin folder where the openremote.sh file resides.

user@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ nano CATALINA.PID
Save and Exit

user@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ ls
CATALINA.PID openremote.bat openremote.sh tomcat

As you can see we now have a file where we can store the PID in.
Now we just need the full path for later when we adjust our .bashrc file.

user@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ pwd
/home/user/OpenRemote-Controller-Pro1.0.10/bin

Step3:Adjust your .bashrc file to export the PID
------

< insert Linux expert comment why this is the best way to do this and what the .bashrc actually is>

Go to your home directory

user@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ cd ~

user@Server:~$ nano .bashrc

Now completely scroll down and add the following

export CATALINA_PID="/home/user/OpenRemote-Controller-Pro1.0.10/bin/CATALINA.PID

Note that this is the full path to the file you have created above.

save and close

Step 4: Test
------
First log out of your ssh session, assuming you have used SSH, alternatively close your terminal.
Now log back in again, this should activate your new .bashrc commands.
Now start openremote

user@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ ./openremote.sh start
Using CATALINA_BASE: /home/user/OpenRemote-Controller-Pro1.0.10
Using CATALINA_HOME: /home/user/OpenRemote-Controller-Pro1.0.10
Using CATALINA_TMPDIR: /home/user/OpenRemote-Controller-Pro1.0.10/temp
Using JRE_HOME:

And now try to stop it with the -force option

user@Server:~/OpenRemote-Controller-Pro1.0.10/bin$ ./openremote.sh stop -force
Killing: 28849

As you can see OR is now able to kill the java thread. You can double-check by using the top command as in step1

I hope this is a clear explanation.

Disclaimer: above tutorial by a non Linux expert, if anyone has any comments or remarks please let me know and I'll adjust.

Posted by garfield.arbuckle at Oct 22, 2013 10:53

Thanks for posting the detailed instructions.

The step 2 should be unnecessary. As long as the CATALINA_PID is defined, the file should be created by the OpenRemote process. It shouldn't be necessary to create an empty file. The only exception I can think of is if there's some permissions issues for the OR process to create the file (but then I suspect that writing to the file would fail as well).

Posted by juha at Oct 22, 2013 22:18

Hey Juha,
I tried it first without creating the blank file and it didn't work for me.
However I tested it again and you are right it does work without creating the blank file, I must have done something wrong the first time around.
Stijn

Posted by garfield.arbuckle at Oct 22, 2013 23:35
Document generated by Confluence on Jun 05, 2016 09:41