search

openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.7k forks source link

[denon] Telnet connection issue for AVR 3808(older model) #5175

Closed Osmii closed 6 years ago

Osmii commented 7 years ago

Good day to all! I know that older Denon recivers are not suported in this bindig. Mine is Denon AVR 3808. But i would like to ask developer to add suport for older ones AVR 2808, 3808, 4808, and similar. I know that http control doesn´t work on mine becuse is different from newer models. On the other side, telnet connection is working with Avr3808. Well, almost. Telnet is working in one direction only. It´s only updating status of items in Openhab. It would be nice, to make telnet working for older models. Here is my config for binding:

#<instance>.<property>=value

#IP adress of the Denon receiver instance
avr3808.host=192.168.1.60

# Optional, set connection method for receiving updates. Can be http or telnet. 
# Denon receivers only support one concurrent telnet connection, so use http if 
# you have any other app using the telnet connection. Default = telnet
avr3808.update=telnet

# Optional, this sets the refresh interval (in milliseconds) for all instances 
# if you're using the http connection method. Default = 5000 
#refresh=5000

I enabled trace logging for denon binding in karaf console. Log massages:

23:31:49.918 [TRACE] [inding.denon.internal.DenonConnector] - Refresh took 55 ms
23:31:49.920 [DEBUG] [binding.denon.internal.DenonListener] - Denon telnet client connected to null
23:31:51.499 [TRACE] [binding.denon.internal.DenonListener] - Received from null: Nas login:
23:31:51.500 [DEBUG] [inding.denon.internal.DenonConnector] - Invalid command: Nas login:
23:31:51.658 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
23:32:28.054 [INFO ] [marthome.event.ItemStateChangedEvent] - Temp3 changed from 14.750 to 14.687
23:32:30.688 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
23:32:30.691 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:32:51.260 [TRACE] [binding.denon.internal.DenonListener] - Received from null: login: timed out after 60 seconds
23:32:51.260 [DEBUG] [inding.denon.internal.DenonConnector] - Invalid command: login: timed out after 60 seconds
23:32:51.268 [DEBUG] [binding.denon.internal.DenonListener] - Error in telnet connection
java.io.IOException: Telnet connection disconnected
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:76)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:32:51.273 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to null
23:32:51.276 [DEBUG] [inding.denon.internal.DenonConnector] - Refreshing URL: http://null:80/goform/Deviceinfo.xml
23:32:51.283 [DEBUG] [inding.denon.internal.DenonConnector] - HTTP communication error
java.net.UnknownHostException: null
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:184)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:175)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)[:1.8.0_121]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:308)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:326)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1202)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1138)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1546)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1474)[:1.8.0_121]
        at org.openhab.binding.denon.internal.DenonConnector.doHttpRequest(DenonConnector.java:626)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getDocument(DenonConnector.java:564)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.setConfigProperties(DenonConnector.java:496)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getInitialState(DenonConnector.java:204)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector$1.listenerConnected(DenonConnector.java:152)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:106)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:32:51.289 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://null:80/goform/Deviceinfo.xml':
null
23:32:51.291 [DEBUG] [inding.denon.internal.DenonConnector] - Denon <instance> zones: 2
23:32:51.293 [TRACE] [inding.denon.internal.DenonConnector] - Refresh Denon HTTP state
23:32:51.294 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing Denon status
23:32:51.296 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://null:80/goform/formMainZone_MainZoneXml.xml
23:32:51.298 [DEBUG] [inding.denon.internal.DenonConnector] - HTTP communication error
java.net.UnknownHostException: null
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:184)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:175)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)[:1.8.0_121]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:308)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:326)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1202)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1138)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1546)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1474)[:1.8.0_121]
        at org.openhab.binding.denon.internal.DenonConnector.doHttpRequest(DenonConnector.java:626)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getDocument(DenonConnector.java:564)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateMain(DenonConnector.java:433)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.refreshHttpProperties(DenonConnector.java:515)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateState(DenonConnector.java:214)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getInitialState(DenonConnector.java:205)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector$1.listenerConnected(DenonConnector.java:152)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:106)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:32:51.313 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://null:80/goform/formMainZone_MainZoneXml.xml':
null
23:32:51.314 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://null:80/goform/formMainZone_MainZoneXmlStatus.xml
23:32:51.315 [DEBUG] [inding.denon.internal.DenonConnector] - HTTP communication error
java.net.UnknownHostException: null
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:184)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:175)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)[:1.8.0_121]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:308)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:326)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1202)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1138)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1546)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1474)[:1.8.0_121]
        at org.openhab.binding.denon.internal.DenonConnector.doHttpRequest(DenonConnector.java:626)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getDocument(DenonConnector.java:564)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateMainZone(DenonConnector.java:444)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.refreshHttpProperties(DenonConnector.java:516)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateState(DenonConnector.java:214)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getInitialState(DenonConnector.java:205)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector$1.listenerConnected(DenonConnector.java:152)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:106)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:32:51.320 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://null:80/goform/formMainZone_MainZoneXmlStatus.xml':
null
23:32:51.324 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://null:80/goform/formZone2_Zone2XmlStatusLite.xml
23:32:51.326 [DEBUG] [inding.denon.internal.DenonConnector] - HTTP communication error
java.net.UnknownHostException: null
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:184)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:175)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)[:1.8.0_121]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:308)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:326)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1202)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1138)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1546)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1474)[:1.8.0_121]
        at org.openhab.binding.denon.internal.DenonConnector.doHttpRequest(DenonConnector.java:626)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getDocument(DenonConnector.java:564)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateSecondaryZones(DenonConnector.java:466)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.refreshHttpProperties(DenonConnector.java:517)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateState(DenonConnector.java:214)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getInitialState(DenonConnector.java:205)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector$1.listenerConnected(DenonConnector.java:152)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:106)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:32:51.333 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://null:80/goform/formZone2_Zone2XmlStatusLite.xml':
null
23:32:51.335 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://null:80/goform/AppCommand.xml
23:32:51.348 [DEBUG] [inding.denon.internal.DenonConnector] - HTTP communication error
java.net.UnknownHostException: null
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:184)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:175)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)[:1.8.0_121]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)[:1.8.0_121]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:308)[:1.8.0_121]
        at sun.net.www.http.HttpClient.New(HttpClient.java:326)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1202)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1138)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1316)[:1.8.0_121]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1291)[:1.8.0_121]
        at org.openhab.binding.denon.internal.DenonConnector.doHttpRequest(DenonConnector.java:623)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.postDocument(DenonConnector.java:596)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateDisplayInfo(DenonConnector.java:482)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.refreshHttpProperties(DenonConnector.java:518)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateState(DenonConnector.java:214)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getInitialState(DenonConnector.java:205)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector$1.listenerConnected(DenonConnector.java:152)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:106)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:32:51.354 [TRACE] [inding.denon.internal.DenonConnector] - Refresh took 61 ms
23:32:51.356 [DEBUG] [binding.denon.internal.DenonListener] - Denon telnet client connected to null
23:32:51.710 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
23:32:52.710 [TRACE] [binding.denon.internal.DenonListener] - Received from null: Nas login:
23:32:52.710 [DEBUG] [inding.denon.internal.DenonConnector] - Invalid command: Nas login:
23:33:30.701 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
23:33:30.704 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)

Here is a link for Denon Avr 3808 serial protocol.

My setup is Openhab2 2.1.0.004-SNAPSHOT, binding-denon1 - 1.10.0.SNAPSHOT on Synology DS216Play, DSM 6.1-15047 Update 2. I`m prepared to test binding in any kind of way. Sorry for my bad english :)

idserda commented 7 years ago

Hi, could you check these two things?

Osmii commented 7 years ago

Hi, idserda!

Are you sure you have configured only 1 instance in your denon.cfg? It looks like there are two, where one is connecting to localhost (?) and thus getting some Synology telnet login prompt (DenonConnector] - Invalid command: Nas login:).

Yes, I`m sure. I belive that Nas login prompt was due enabled telnet access on my Synology. I disable it and now is gone.

In the beginig of the logs, you can see that i changed volume on the reciver and that status was updating.

23:09:03.614 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 29.5 to 29
23:09:03.615 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
23:09:04.264 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV285
23:09:04.264 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 285
23:09:04.273 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
23:09:04.274 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 29 to 28.5
23:09:04.279 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
23:09:44.499 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
23:09:44.502 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:09:46.492 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to null
23:09:46.495 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to null
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:10:04.323 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
23:10:44.504 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
23:10:44.506 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]

How often do you see Denon receiver configured at in your log?

I belive that I never saw this. How to make sure?

Are you sure no other application is connecting to the receiver using telnet? Could try to set up a telnet connection to the receiver at 192.168.1.60 manually?

I tried to establish "manual connection" with this Command3808 telnet client. Debug logs from client were:

No valid IP address.
2017-05-01 11:27:57.232 - Attempting to open connection with 192.168.1.60
2017-05-01 11:27:58.241 - EXCEPTION

An exception occured at 2017-05-01 11:27:58.243: 
--------------------------------------------------

System.Exception: An exception occured in the Denon process routine. ---> System.Net.Sockets.SocketException: No connection could be made because the target machine actively refused it 192.168.1.60:23
   at System.Net.Sockets.Socket.EndConnect(IAsyncResult asyncResult)
   at System.Net.Sockets.TcpClient.EndConnect(IAsyncResult asyncResult)
   at Command3808.Network_MT.Connect() in C:\Users\bsaville\Documents\Visual Studio 2008\Projects\Command3808\Command3808\Network_MT.vb:line 259
   at Command3808.Network_MT.Process() in C:\Users\bsaville\Documents\Visual Studio 2008\Projects\Command3808\Command3808\Network_MT.vb:line 71
   --- End of inner exception stack trace ---

--------------------------------------------------

Then I tried to disable Denon binding...

23:57:41.939 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STOPPING - org.openhab.binding.denon
23:57:41.948 [DEBUG] [org.openhab.binding.denon           ] - ServiceEvent UNREGISTERING - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.denon, component.name=org.openhab.binding.denon.binding, component.id=21, service.id=270, service.bundleid=228, service.scope=bundle} - org.openhab.binding.denon
23:57:41.988 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonPower changed from ON to OFF
23:57:41.977 [DEBUG] [binding.denon.internal.DenonListener] - Error in telnet connection
java.net.SocketException: Socket closed
        at java.net.SocketInputStream.read(SocketInputStream.java:204)[:1.8.0_121]
        at java.net.SocketInputStream.read(SocketInputStream.java:141)[:1.8.0_121]
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)[:1.8.0_121]
        at java.io.BufferedInputStream.read(BufferedInputStream.java:345)[:1.8.0_121]
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)[:1.8.0_121]
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265)[:1.8.0_121]
        at org.apache.commons.net.telnet.TelnetInputStream.__read(TelnetInputStream.java:141)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.telnet.TelnetInputStream.run(TelnetInputStream.java:611)[176:org.apache.commons.net:3.2.0]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
23:57:41.990 [ERROR] [org.openhab.binding.denon           ] - [org.openhab.binding.denon.binding(21)] The deactivate method has thrown an exception
java.lang.NullPointerException
        at org.apache.commons.net.telnet.TelnetClient._closeOutputStream(TelnetClient.java:86)
        at org.apache.commons.net.telnet.TelnetOutputStream.close(TelnetOutputStream.java:155)
        at org.apache.commons.net.telnet.TelnetClient.disconnect(TelnetClient.java:127)
        at org.openhab.binding.denon.internal.DenonListener.disconnect(DenonListener.java:122)
        at org.openhab.binding.denon.internal.DenonListener.shutdown(DenonListener.java:94)
        at org.openhab.binding.denon.internal.DenonConnector.disconnect(DenonConnector.java:172)
        at org.openhab.binding.denon.internal.DenonBinding.deactivate(DenonBinding.java:64)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_121]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_121]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_121]
        at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_121]
        at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:302)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:343)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:152)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:813)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:452)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:306)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[32:org.apache.felix.scr:2.0.6]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
        at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[32:org.apache.felix.scr:2.0.6]
        at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[32:org.apache.felix.scr:2.0.6]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:419)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
        at org.apache.karaf.bundle.command.Stop.executeOnBundle(Stop.java:38)[38:org.apache.karaf.bundle.core:4.0.8]
        at org.apache.karaf.bundle.command.BundlesCommand.doExecute(BundlesCommand.java:64)[38:org.apache.karaf.bundle.core:4.0.8]
        at org.apache.karaf.bundle.command.BundlesCommand.execute(BundlesCommand.java:54)[38:org.apache.karaf.bundle.core:4.0.8]
        at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:83)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:67)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:87)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:480)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:406)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:182)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:119)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:94)[55:org.apache.karaf.shell.core:4.0.8]
        at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:274)[55:org.apache.karaf.shell.core:4.0.8]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
23:57:42.091 [DEBUG] [org.openhab.binding.denon           ] - ServiceEvent UNREGISTERING - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.denon.DenonBindingProvider}={component.name=org.openhab.binding.denon.genericbindingprovider, component.id=22, service.id=123, service.bundleid=228, service.scope=bundle} - org.openhab.binding.denon
23:57:42.113 [DEBUG] [inding.denon.internal.DenonActivator] - Denon binding has been stopped.
23:57:42.115 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STOPPED - org.openhab.binding.denon
23:57:44.997 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
23:57:45.000 [DEBUG] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/Deviceinfo.xml
23:57:45.142 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/Deviceinfo.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form Deviceinfo.xml is not defined</p></body></html>

23:57:45.199 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
23:57:45.202 [DEBUG] [inding.denon.internal.DenonConnector] - Denon avr2000 zones: 2
23:57:45.203 [TRACE] [inding.denon.internal.DenonConnector] - Refresh Denon HTTP state
23:57:45.206 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing Denon status
23:57:45.207 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formMainZone_MainZoneXml.xml
23:57:45.344 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formMainZone_MainZoneXml.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formMainZone_MainZoneXml.xml is not defined</p></body></html>

23:57:45.357 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
23:57:45.358 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formMainZone_MainZoneXmlStatus.xml
23:57:45.496 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formMainZone_MainZoneXmlStatus.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formMainZone_MainZoneXmlStatus.xml is not defined</p></body></html>

23:57:45.519 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
23:57:45.521 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formZone2_Zone2XmlStatusLite.xml
23:57:45.662 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formZone2_Zone2XmlStatusLite.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formZone2_Zone2XmlStatusLite.xml is not defined</p></body></html>

23:57:45.680 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
23:57:45.681 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/AppCommand.xml
23:57:46.062 [DEBUG] [inding.denon.internal.DenonConnector] - Encoding error in post
javax.xml.bind.UnmarshalException: unexpected element (uri:"", local:"html"). Expected elements are <{}cmd>,<{}rx>,<{}text>
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.handleEvent(UnmarshallingContext.java:726)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportError(Loader.java:247)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportError(Loader.java:242)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportUnexpectedChildElement(Loader.java:109)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext$DefaultRootLoader.childElement(UnmarshallingContext.java:1131)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext._startElement(UnmarshallingContext.java:556)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.startElement(UnmarshallingContext.java:538)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.SAXConnector.startElement(SAXConnector.java:153)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.startElement(AbstractSAXParser.java:509)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanStartElement(XMLNSDocumentScannerImpl.java:374)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl$NSContentDriver.scanRootElementHook(XMLNSDocumentScannerImpl.java:613)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:3132)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(XMLDocumentScannerImpl.java:852)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:602)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:112)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:505)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:841)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:770)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:643)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(UnmarshallerImpl.java:243)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal(UnmarshallerImpl.java:214)[:1.8.0_121]
        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:157)[:1.8.0_121]
        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:204)[:1.8.0_121]
        at org.openhab.binding.denon.internal.DenonConnector.postDocument(DenonConnector.java:602)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateDisplayInfo(DenonConnector.java:482)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.refreshHttpProperties(DenonConnector.java:518)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.updateState(DenonConnector.java:214)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector.getInitialState(DenonConnector.java:205)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonConnector$1.listenerConnected(DenonConnector.java:152)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:106)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:57:46.077 [TRACE] [inding.denon.internal.DenonConnector] - Refresh took 874 ms
23:57:46.079 [DEBUG] [binding.denon.internal.DenonListener] - Denon telnet client connected to 192.168.1.60
23:57:46.877 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to null
23:57:46.878 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to null
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:58:17.048 [INFO ] [marthome.event.ItemStateChangedEvent] - Temp3 changed from 14.375 to 14.437
23:58:32.223 [INFO ] [marthome.event.ItemStateChangedEvent] - Temp5 changed from 36.856 to 37.394
23:58:35.250 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV26
23:58:35.250 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 26
23:58:46.884 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to null
23:58:46.886 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to null
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]
23:59:18.707 [INFO ] [marthome.event.ItemStateChangedEvent] - Temp3 changed from 14.437 to 14.500
23:59:46.894 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to null
23:59:46.913 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to null
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]

Binding status was: 228 | Resolved | 80 | 1.10.0.201702140757 | openHAB Denon Binding But telnet connection was still "present":

00:07:47.071 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to null
00:07:47.093 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to null
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[228:org.openhab.binding.denon:1.10.0.201702140757]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[228:org.openhab.binding.denon:1.10.0.201702140757]

So, then i stoped Openhab server and tried to establish telnet conection with Command3808 again. Conection was established. I tried to mute the reciver. Everything worked. Logs from client:

2017-05-02 12:01:24.433 - Attempting to open connection with 192.168.1.60
2017-05-02 12:01:24.435 - Connection established with 192.168.1.60
2017-05-02 12:02:11.756 - SEND: MUON
2017-05-02 12:02:11.830 - RECV: MUON
2017-05-02 12:02:14.858 - SEND: MUOFF
2017-05-02 12:02:14.896 - RECV: MUOFF
idserda commented 7 years ago

Thanks for the logs. It looks like the binding somehow tries to connect to an instance that has no hostname defined, judging from this line:

23:09:46.492 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to null

I've added an extra check so that instances without a hostname configured are ignored. There is a new jar here: https://www.dropbox.com/s/nj9w6a5m16qo7wm/org.openhab.binding.denon_1.10.0.201705021012.jar?dl=0 . Could you test this?

The logging should look like this:

10:14:22.206 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STARTING - org.openhab.binding.denon
10:14:22.206 [DEBUG] [inding.denon.internal.DenonActivator] - Denon binding has been started.
10:14:22.207 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding updated
10:14:22.207 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon receiver configured at 192.168.1.70
10:14:22.207 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STARTED - org.openhab.binding.denon
10:14:22.208 [DEBUG] [binding.denon.internal.DenonListener] - Denon listener created
10:14:22.208 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.70
10:14:22.209 [DEBUG] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.70:80/goform/Deviceinfo.xml
10:14:22.830 [DEBUG] [inding.denon.internal.DenonConnector] - Denon avr2000 zones: 2
10:14:22.912 [DEBUG] [binding.denon.internal.DenonListener] - Denon telnet client connected to 192.168.1.70
Osmii commented 7 years ago

No problem! I uninstalled binding from Paper UI, then copied new jar file to addons folder and added conf to openhab.cfg in services folder.

18:51:38.094 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent INSTALLED - org.openhab.binding.denon
18:51:40.675 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent RESOLVED - org.openhab.binding.denon
18:51:40.935 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STARTING - org.openhab.binding.denon
18:51:40.940 [DEBUG] [inding.denon.internal.DenonActivator] - Denon binding has been started.
18:51:40.945 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STARTED - org.openhab.binding.denon
18:51:40.965 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonPower bound to property PW
18:51:40.968 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonVolume bound to property MV
18:51:40.972 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonInput bound to property INPUT
18:51:40.975 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonMute bound to property MU
18:51:40.977 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item Denonpoweronoffmz bound to property ZM
18:51:40.980 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item Denonnetusb bound to property SINET
18:51:40.982 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonCurrentTrack bound to property TRACK
18:51:40.986 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonPowerZ3 bound to property Z3
18:51:40.989 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonVolumeZ3 bound to property Z3ZV
18:51:40.992 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonInputZ3 bound to property Z3SOURCE
18:51:40.994 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonMuteZ3 bound to property Z3MU
18:51:41.000 [DEBUG] [org.openhab.binding.denon           ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.denon.DenonBindingProvider}={component.name=org.openhab.binding.denon.genericbindingprovider, component.id=225, service.id=371, service.bundleid=231, service.scope=bundle} - org.openhab.binding.denon
18:51:41.023 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon all bindings changed
18:51:41.028 [DEBUG] [org.openhab.binding.denon           ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.denon, component.name=org.openhab.binding.denon.binding, component.id=224, service.id=373, service.bundleid=231, service.scope=bundle} - org.openhab.binding.denon
18:51:41.036 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent [unknown:512] - org.openhab.binding.denon
18:51:41.040 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding updated
18:51:41.059 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon receiver configured at 192.168.1.60
18:51:41.408 [DEBUG] [binding.denon.internal.DenonListener] - Denon listener created
18:51:41.411 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon receiver configured at 192.168.1.60
18:51:41.411 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
18:51:41.416 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[231:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[231:org.openhab.binding.denon:1.10.0.201705021012]
18:51:41.438 [DEBUG] [binding.denon.internal.DenonListener] - Denon listener created
18:51:41.445 [DEBUG] [.binding.denon.internal.DenonBinding] - No host configured for receiver <instance>
18:51:41.448 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
18:51:41.459 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[231:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[231:org.openhab.binding.denon:1.10.0.201705021012]

Then I restarted Openhab an try to change volume from reciver. Status was updating. Nothing hapend when I changed volume from Openhab! 

19:01:46.202 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'DenonVolume' received command 13
19:01:46.200 [TRACE] [inding.denon.internal.DenonConnector] - Calling url http://192.168.1.60:80/goform/formiPhoneAppDirect.xml?MV13
19:01:46.226 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 26 to 13
19:01:46.400 [TRACE] [inding.denon.internal.DenonConnector] - Calling url http://192.168.1.60:80/goform/formiPhoneAppDirect.xml?MV13
19:01:46.407 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'DenonVolume' received command 13
19:01:51.242 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV375
19:01:51.243 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 375
19:01:51.251 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 13 to 37.5
19:01:51.255 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
19:01:51.258 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
19:01:56.596 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV38
19:01:56.597 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 38
19:01:56.602 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
19:01:56.602 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
19:01:56.609 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 37.5 to 38
19:01:59.931 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV375
19:01:59.932 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 375
19:01:59.940 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
19:01:59.941 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
19:01:59.944 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 38 to 37.5
19:02:01.664 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV37
19:02:01.664 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 37
19:02:01.681 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 37.5 to 37
19:02:01.682 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
19:02:01.685 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
19:02:05.044 [INFO ] [marthome.event.ItemStateChangedEvent] - Temp7 changed from NULL to 10.75
19:02:06.047 [INFO ] [marthome.event.ItemStateChangedEvent] - Nap1 changed from NULL to 4.09
19:02:08.587 [TRACE] [inding.denon.internal.DenonConnector] - Calling url http://192.168.1.60:80/goform/formiPhoneAppDirect.xml?MV18
19:02:08.598 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'DenonVolume' received command 18
19:02:08.619 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 37 to 18
19:02:08.785 [TRACE] [inding.denon.internal.DenonConnector] - Calling url http://192.168.1.60:80/goform/formiPhoneAppDirect.xml?MV18
19:02:08.796 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'DenonVolume' received command 18
19:02:12.046 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
19:02:12.050 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[231:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[231:org.openhab.binding.denon:1.10.0.201705021012]
19:03:01.740 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
19:03:12.057 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
19:03:12.059 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[231:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[231:org.openhab.binding.denon:1.10.0.201705021012]

I noticed that when the item is changed from Openhab, binding is calling url.. Is that ok? Because url for my reciver is diferent..

idserda commented 7 years ago

Thanks! You are using openHAB 2 right? Then the configuration needs to be in denon.cfg in the conf/services/ directory, not in openhab.cfg. The line Denon receiver configured at 192.168.1.60 shows up twice, have you configured it twice somehow? Or multiple versions of the binding installed?

In the second log it's using http to communicate with the receiver instead of telnet, which is wrong indeed.

Osmii commented 7 years ago

Yes! I`m using Openhab2. Installation is one month old. I did installed and uninstalled Denon binding a few times. I put configuration in denon.cfg file in conf/services as you told me. After that the line Denon receiver configured at 192.168.1.60 was still showing up twice, so i removed denon.cfg from services, just to see if there is some difference. Well, it starts with same configuration as it is in removed denon.cfg. So there must be duplicate, but i cannot find it. Any idea where to look? If I remove binding, there is nothing showing up in karaf console after restart.

14:27:12.928 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STARTING - org.openhab.binding.denon
14:27:13.053 [DEBUG] [org.openhab.binding.denon           ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.denon.DenonBindingProvider}={component.name=org.openhab.binding.denon.genericbindingprovider, component.id=223, service.id=367, service.bundleid=232, service.scope=bundle} - org.openhab.binding.denon
14:27:13.109 [DEBUG] [org.openhab.binding.denon           ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.denon, component.name=org.openhab.binding.denon.binding, component.id=222, service.id=368, service.bundleid=232, service.scope=bundle} - org.openhab.binding.denon
14:27:13.132 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon all bindings changed
14:27:13.144 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding updated
14:27:13.155 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon receiver configured at 192.168.1.60
14:27:13.159 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonPower bound to property PW
14:27:13.174 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonPower
14:27:13.174 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonPower
14:27:13.175 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonVolume bound to property MV
14:27:13.176 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonVolume
14:27:13.176 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonVolume
14:27:13.197 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonInput bound to property INPUT
14:27:13.202 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonInput
14:27:13.205 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonInput
14:27:13.214 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonMute bound to property MU
14:27:13.217 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonMute
14:27:13.226 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonMute
14:27:13.228 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item Denonpoweronoffmz bound to property ZM
14:27:13.243 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item Denonpoweronoffmz
14:27:13.247 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item Denonpoweronoffmz
14:27:13.252 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item Denonnetusb bound to property SINET
14:27:13.255 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item Denonnetusb
14:27:13.258 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item Denonnetusb
14:27:13.261 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonCurrentTrack bound to property TRACK
14:27:13.265 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonCurrentTrack
14:27:13.330 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonCurrentTrack
14:27:13.331 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonPowerZ3 bound to property Z3
14:27:13.332 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonPowerZ3
14:27:13.332 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonPowerZ3
14:27:13.333 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonVolumeZ3 bound to property Z3ZV
14:27:13.334 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonVolumeZ3
14:27:13.334 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonVolumeZ3
14:27:13.335 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonInputZ3 bound to property Z3SOURCE
14:27:13.336 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonInputZ3
14:27:13.336 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonInputZ3
14:27:13.337 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonMuteZ3 bound to property Z3MU
14:27:13.337 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding changed for item DenonMuteZ3
14:27:13.338 [DEBUG] [.binding.denon.internal.DenonBinding] - No connector found for item DenonMuteZ3
14:27:13.363 [DEBUG] [inding.denon.internal.DenonActivator] - Denon binding has been started.
14:27:13.373 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STARTED - org.openhab.binding.denon
14:27:14.085 [DEBUG] [binding.denon.internal.DenonListener] - Denon listener created
14:27:14.150 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon receiver configured at 192.168.1.60
14:27:14.151 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
14:27:14.170 [DEBUG] [binding.denon.internal.DenonListener] - Denon listener created
14:27:14.176 [DEBUG] [.binding.denon.internal.DenonBinding] - No host configured for receiver <instance>
14:27:14.179 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
14:27:14.184 [DEBUG] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/Deviceinfo.xml
14:27:14.234 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[232:org.openhab.binding.denon:1.10.0.201705021012]
14:27:14.324 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/Deviceinfo.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form Deviceinfo.xml is not defined</p></body></html>

14:27:14.489 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
14:27:14.491 [DEBUG] [inding.denon.internal.DenonConnector] - Denon avr3808 zones: 2
14:27:14.493 [TRACE] [inding.denon.internal.DenonConnector] - Refresh Denon HTTP state
14:27:14.494 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing Denon status
14:27:14.496 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formMainZone_MainZoneXml.xml
14:27:14.633 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formMainZone_MainZoneXml.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formMainZone_MainZoneXml.xml is not defined</p></body></html>

14:27:14.713 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
14:27:14.715 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formMainZone_MainZoneXmlStatus.xml
14:27:14.852 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formMainZone_MainZoneXmlStatus.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formMainZone_MainZoneXmlStatus.xml is not defined</p></body></html>

14:27:14.881 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
14:27:14.885 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formZone2_Zone2XmlStatusLite.xml
14:27:15.022 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formZone2_Zone2XmlStatusLite.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formZone2_Zone2XmlStatusLite.xml is not defined</p></body></html>

14:27:15.043 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
14:27:15.044 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/AppCommand.xml
14:27:15.302 [DEBUG] [inding.denon.internal.DenonConnector] - Encoding error in post
javax.xml.bind.UnmarshalException: unexpected element (uri:"", local:"html"). Expected elements are <{}cmd>,<{}rx>,<{}text>
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.handleEvent(UnmarshallingContext.java:726)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportError(Loader.java:247)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportError(Loader.java:242)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportUnexpectedChildElement(Loader.java:109)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext$DefaultRootLoader.childElement(UnmarshallingContext.java:1131)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext._startElement(UnmarshallingContext.java:556)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.startElement(UnmarshallingContext.java:538)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.SAXConnector.startElement(SAXConnector.java:153)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.startElement(AbstractSAXParser.java:509)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanStartElement(XMLNSDocumentScannerImpl.java:374)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl$NSContentDriver.scanRootElementHook(XMLNSDocumentScannerImpl.java:613)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:3132)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(XMLDocumentScannerImpl.java:852)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:602)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:112)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:505)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:841)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:770)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:643)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(UnmarshallerImpl.java:243)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal(UnmarshallerImpl.java:214)[:1.8.0_121]
        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:157)[:1.8.0_121]
        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:204)[:1.8.0_121]
        at org.openhab.binding.denon.internal.DenonConnector.postDocument(DenonConnector.java:603)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector.updateDisplayInfo(DenonConnector.java:483)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector.refreshHttpProperties(DenonConnector.java:519)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector.updateState(DenonConnector.java:215)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector.getInitialState(DenonConnector.java:206)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector$1.listenerConnected(DenonConnector.java:152)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:106)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[232:org.openhab.binding.denon:1.10.0.201705021012]
14:27:15.311 [TRACE] [inding.denon.internal.DenonConnector] - Refresh took 818 ms
14:27:15.313 [DEBUG] [binding.denon.internal.DenonListener] - Denon telnet client connected to 192.168.1.60
14:27:32.592 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV35
14:27:32.593 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 35
14:27:32.627 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
14:27:32.627 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
14:27:32.634 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from NULL to 35
14:27:32.686 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV36
14:27:32.687 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 36
14:27:32.697 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
14:27:32.697 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
14:27:32.700 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 35 to 36
14:27:32.764 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV365
14:27:32.765 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 365
14:27:32.771 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
14:27:32.772 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
14:27:32.775 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 36 to 36.5
14:28:14.243 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
14:28:14.246 [DEBUG] [binding.denon.internal.DenonListener] - Cannot connect to 192.168.1.60
java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)[:1.8.0_121]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)[:1.8.0_121]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)[:1.8.0_121]
        at java.net.Socket.connect(Socket.java:589)[:1.8.0_121]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:175)[176:org.apache.commons.net:3.2.0]
        at org.apache.commons.net.SocketClient.connect(SocketClient.java:196)[176:org.apache.commons.net:3.2.0]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:105)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[232:org.openhab.binding.denon:1.10.0.201705021012]
14:28:32.956 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
idserda commented 7 years ago

There's also some configuration under userdata/config/org/openhab, could you check there?

Osmii commented 7 years ago

Yes :) What to do with it? Delete denon.config file?

<instance>.<property>="value"
avr2000.host="192.168.1.60"
avr2000.update="telnet"
avr3808.host="192.168.1.60"
avr3808.update="telnet"
service.pid="org.openhab.denon"
idserda commented 7 years ago

Yes, stop openhab, delete that file, keep the denon.cfg in conf/services and try again 😃

Osmii commented 7 years ago

I belive that this problem is solved. Now, how to make items to send telnet commands...

15:18:37.603 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonPower bound to property PW
15:18:37.606 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonVolume bound to property MV
15:18:37.610 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonInput bound to property INPUT
15:18:37.616 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonMute bound to property MU
15:18:37.618 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item Denonpoweronoffmz bound to property ZM
15:18:37.627 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item Denonnetusb bound to property SINET
15:18:37.630 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonCurrentTrack bound to property TRACK
15:18:37.633 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonPowerZ3 bound to property Z3
15:18:37.636 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonVolumeZ3 bound to property Z3ZV
15:18:37.639 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonInputZ3 bound to property Z3SOURCE
15:18:37.643 [DEBUG] [internal.DenonGenericBindingProvider] - denon:avr3808 item DenonMuteZ3 bound to property Z3MU
15:18:37.787 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon all bindings changed
15:18:37.794 [DEBUG] [org.openhab.binding.denon           ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.denon, component.name=org.openhab.binding.denon.binding, component.id=220, service.id=367, service.bundleid=232, service.scope=bundle} - org.openhab.binding.denon
15:18:37.804 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon binding updated
15:18:37.807 [DEBUG] [.binding.denon.internal.DenonBinding] - Denon receiver configured at 192.168.1.60
15:18:37.813 [DEBUG] [org.openhab.binding.denon           ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.denon.DenonBindingProvider}={component.name=org.openhab.binding.denon.genericbindingprovider, component.id=221, service.id=365, service.bundleid=232, service.scope=bundle} - org.openhab.binding.denon
15:18:37.816 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STARTING - org.openhab.binding.denon
15:18:37.829 [DEBUG] [inding.denon.internal.DenonActivator] - Denon binding has been started.
15:18:37.839 [DEBUG] [org.openhab.binding.denon           ] - BundleEvent STARTED - org.openhab.binding.denon

15:18:38.565 [DEBUG] [binding.denon.internal.DenonListener] - Denon listener created
15:18:38.622 [DEBUG] [binding.denon.internal.DenonListener] - Connecting to 192.168.1.60
15:18:38.631 [DEBUG] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/Deviceinfo.xml
15:18:38.769 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/Deviceinfo.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form Deviceinfo.xml is not defined</p></body></html>

15:18:38.871 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
15:18:38.872 [DEBUG] [inding.denon.internal.DenonConnector] - Denon avr3808 zones: 2
15:18:38.874 [TRACE] [inding.denon.internal.DenonConnector] - Refresh Denon HTTP state
15:18:38.875 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing Denon status
15:18:38.876 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formMainZone_MainZoneXml.xml
15:18:39.013 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formMainZone_MainZoneXml.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formMainZone_MainZoneXml.xml is not defined</p></body></html>

15:18:39.049 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
15:18:39.050 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formMainZone_MainZoneXmlStatus.xml
15:18:39.187 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formMainZone_MainZoneXmlStatus.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formMainZone_MainZoneXmlStatus.xml is not defined</p></body></html>

15:18:39.215 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
15:18:39.217 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/formZone2_Zone2XmlStatusLite.xml
15:18:39.355 [TRACE] [inding.denon.internal.DenonConnector] - result of getDocument for uri 'http://192.168.1.60:80/goform/formZone2_Zone2XmlStatusLite.xml':
<html><head><title>Document Error: Data follows</title></head>
                <body><h2>Access Error: Data follows</h2>
                <p>Form formZone2_Zone2XmlStatusLite.xml is not defined</p></body></html>

15:18:39.380 [DEBUG] [inding.denon.internal.DenonConnector] - Failed to unmarshal xml document: null
15:18:39.383 [TRACE] [inding.denon.internal.DenonConnector] - Refreshing URL: http://192.168.1.60:80/goform/AppCommand.xml
15:18:39.734 [DEBUG] [inding.denon.internal.DenonConnector] - Encoding error in post
javax.xml.bind.UnmarshalException: unexpected element (uri:"", local:"html"). Expected elements are <{}cmd>,<{}rx>,<{}text>
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.handleEvent(UnmarshallingContext.java:726)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportError(Loader.java:247)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportError(Loader.java:242)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportUnexpectedChildElement(Loader.java:109)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext$DefaultRootLoader.childElement(UnmarshallingContext.java:1131)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext._startElement(UnmarshallingContext.java:556)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.startElement(UnmarshallingContext.java:538)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.SAXConnector.startElement(SAXConnector.java:153)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.startElement(AbstractSAXParser.java:509)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanStartElement(XMLNSDocumentScannerImpl.java:374)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl$NSContentDriver.scanRootElementHook(XMLNSDocumentScannerImpl.java:613)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:3132)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(XMLDocumentScannerImpl.java:852)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:602)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:112)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:505)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:841)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:770)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213)[:1.8.0_121]
        at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:643)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(UnmarshallerImpl.java:243)[:1.8.0_121]
        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal(UnmarshallerImpl.java:214)[:1.8.0_121]
        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:157)[:1.8.0_121]
        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:204)[:1.8.0_121]
        at org.openhab.binding.denon.internal.DenonConnector.postDocument(DenonConnector.java:603)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector.updateDisplayInfo(DenonConnector.java:483)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector.refreshHttpProperties(DenonConnector.java:519)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector.updateState(DenonConnector.java:215)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector.getInitialState(DenonConnector.java:206)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonConnector$1.listenerConnected(DenonConnector.java:152)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.connectTelnetClient(DenonListener.java:106)[232:org.openhab.binding.denon:1.10.0.201705021012]
        at org.openhab.binding.denon.internal.DenonListener.run(DenonListener.java:57)[232:org.openhab.binding.denon:1.10.0.201705021012]
15:18:39.742 [TRACE] [inding.denon.internal.DenonConnector] - Refresh took 868 ms
15:18:39.743 [DEBUG] [binding.denon.internal.DenonListener] - Denon telnet client connected to 192.168.1.60

15:19:10.447 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from NULL to 11
15:19:10.459 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'DenonVolume' received command 11
15:19:10.452 [TRACE] [inding.denon.internal.DenonConnector] - Calling url http://192.168.1.60:80/goform/formiPhoneAppDirect.xml?MV11
15:19:10.612 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'DenonVolume' received command 11
15:19:10.904 [TRACE] [inding.denon.internal.DenonConnector] - Calling url http://192.168.1.60:80/goform/formiPhoneAppDirect.xml?MV11
15:19:12.990 [TRACE] [inding.denon.internal.DenonConnector] - Calling url http://192.168.1.60:80/goform/formiPhoneAppDirect.xml?MV21
15:19:12.994 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'DenonVolume' received command 21
15:19:13.003 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 11 to 21
15:19:13.185 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'DenonVolume' received command 21
15:19:13.189 [TRACE] [inding.denon.internal.DenonConnector] - Calling url http://192.168.1.60:80/goform/formiPhoneAppDirect.xml?MV21

15:19:38.683 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout

15:20:38.767 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout

15:21:04.089 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV36
15:21:04.096 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 36
15:21:04.126 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 21 to 36
15:21:04.122 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
15:21:04.139 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
15:21:04.520 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV355
15:21:04.522 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 355
15:21:04.527 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
15:21:04.528 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83
15:21:04.530 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 36 to 35.5
15:21:04.643 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MV35
15:21:04.644 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: 35
15:21:04.651 [INFO ] [marthome.event.ItemStateChangedEvent] - DenonVolume changed from 35.5 to 35
15:21:04.655 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 83
15:21:04.657 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 83

15:22:04.707 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
15:23:04.779 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
15:24:04.840 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
Osmii commented 7 years ago

Just for info. My first installation was Openhab1 on Win2012 server, second was Openhab2 on Win2012 server, third was Openhab2 on Osmc based raspberry Pi3, and now,fourth on Synology DS216play. Denon bindin was behaving the same on all installations, that is only receiving updates from receiver.

15:49:33.313 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
15:49:38.963 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MSSTEREO
15:49:38.964 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MS, value: STEREO
15:49:38.975 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVFL 485
15:49:38.979 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: FL 485
15:49:39.010 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVFR 50
15:49:39.014 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: FR 50
15:49:39.050 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVC 49
15:49:39.051 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: C 49
15:49:39.090 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVSW 50
15:49:39.091 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: SW 50
15:49:39.130 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVSL 445
15:49:39.133 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: SL 445
15:49:39.170 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVSR 525
15:49:39.172 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: SR 525
15:49:39.210 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVSBL 50
15:49:39.212 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: SBL 50
15:49:39.250 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVSBR 50
15:49:39.251 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: SBR 50
15:49:39.290 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: CVSB 50
15:49:39.298 [DEBUG] [inding.denon.internal.DenonConnector] - Command: CV, value: SB 50
15:49:39.299 [TRACE] [binding.denon.internal.DenonListener] - Received from 192.168.1.60: MVMAX 845
15:49:39.301 [DEBUG] [inding.denon.internal.DenonConnector] - Command: MV, value: MAX 845
15:50:39.351 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
15:51:39.425 [TRACE] [binding.denon.internal.DenonListener] - Socket timeout
idserda commented 7 years ago

Great that we got one problem fixed.

I had to look it up in the code, but the current binding only supports sending commands over http. With the telnet connection it's only possible to send 1 command at a time. After sending this command you have to disconnect and reconnect the telnet connection before you can send another command. This is not very convenient. I could try to implement it, but I don't think it'll be very reliable.

Osmii commented 7 years ago

There is this app for android, that i'm using it for years now, and it's pretty reliable from my experience. I belive that it uses telnet connection (I cannot connect to receiver unless I shut down Openhab). If you could try to implement it, it would be great for owners of older Denon receivers. We could use the binding for full control and avtomation of the recivier! Thank you idserda!

idserda commented 7 years ago

Thanks for that suggestion! Took a look at the app, found out (using Wireshark) that it's sending all the commands over telnet in one session. So, no need to reconnect telnet after every command. Rewrote some stuff in the binding and commands can now also be send over telnet 😃

Here's a new jar if you want to test: https://www.dropbox.com/s/46e9tbos2e8fnmq/org.openhab.binding.denon_1.10.0.201705041212.jar?dl=0

You don't need to change any settings for it to work (as long as update method is set to telnet). First version of this, might still need some tweaks.

Osmii commented 7 years ago

Here's a new jar if you want to test:

If I? Let me some time ... : D

Osmii commented 7 years ago

Hi, idserda! After few days of testing, binding seems to be very stable :D All the items from my config are working well! (Main zone and Z3) I wanna say BIG THANK YOU for resolving this issue! If you make this official, some users will be very happy, like me! Thank you again! p.s. If you need me and my receiver for testing purposes , just tell me!

idserda commented 7 years ago

That's good to hear! I'll submit a pull request so these changes will be incorporated in the binding.

EleRas commented 6 years ago

Hi,

Is there any update on this? I couldn't find a pull request for this and newer Denon - receivers only have a telnet - connection, no webinterface possible any longer. Seems as if Denon is discontinuing the webinterface and now only relies on telnet.

idserda commented 6 years ago

No, no pull request yet, but you could try the jar mentioned in the comment from May 3rd.

idserda commented 6 years ago

There is a PR now for the change mentioned above: https://github.com/openhab/openhab1-addons/pull/5342

pravussum commented 6 years ago

Built it and confirm it's working with a Denon AVR-X4400H (Main + Zone 2).

9037568 commented 6 years ago

Closed via merged PR.