search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.59k forks source link

[denonmarantz] "surroundProgram" show nothing #3724

Closed grzegorz914 closed 6 years ago

grzegorz914 commented 6 years ago

Hi,

I use this binding with AVR-X6300H, all working OK except "surroundProgram", this tag show nothing, change connection between HTTP or Telnet make no differences. Look on the screenshot.

zrzut ekranu 2018-07-11 o 18 21 21

Your Environment

OH2.4 on RPI 3B

jwveldhuis commented 6 years ago

Ok, this is strange. This is a Heos model right? What do these urls give as output? http://AVR:8080/goform/formMainZone_MainZoneXml.xml http://AVR:8080/goform/formMainZone_MainZoneXmlStatus.xml

jwveldhuis commented 6 years ago

You could enable DEBUG or TRACE log level for org.openhab.binding.denonmarantz to see what is being retrieved from the device.

grzegorz914 commented 6 years ago

Hi,

Yes it is Heos,

on both command .xml I get:

Error 403: Forbidden Access Forbidden

log telnet connection:

2018-07-12 07:12:37.606 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Configuring zone channels
2018-07-12 07:12:37.610 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - No zone channels have been added
2018-07-12 07:12:37.613 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - No zone channels have been removed
2018-07-12 07:12:37.620 [hingStatusInfoChangedEvent] - 'denonmarantz:avr:0005cd6f9f92' changed from ONLINE to UNKNOWN
2018-07-12 07:12:37.620 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Denon listener created
2018-07-12 07:12:37.625 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Connecting to 192.168.1.6
2018-07-12 07:12:37.629 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Denon telnet client connected to 192.168.1.6
2018-07-12 07:12:37.629 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'PW?'
2018-07-12 07:12:37.631 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command PW?
2018-07-12 07:12:37.662 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PWON
2018-07-12 07:12:37.664 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PW, value: ON
2018-07-12 07:12:37.666 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID general#power
2018-07-12 07:12:37.670 [hingStatusInfoChangedEvent] - 'denonmarantz:avr:0005cd6f9f92' changed from UNKNOWN to ONLINE
2018-07-12 07:12:37.684 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2ON
2018-07-12 07:12:37.688 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: ON
2018-07-12 07:12:37.692 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID zone2#power
2018-07-12 07:12:37.708 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z3ON
2018-07-12 07:12:37.710 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: ON
2018-07-12 07:12:37.712 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID zone3#power
2018-07-12 07:12:37.933 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'MS?'
2018-07-12 07:12:37.935 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command MS?
2018-07-12 07:12:37.987 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MSMCH STEREO
2018-07-12 07:12:37.991 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MS, value: MCH STEREO
2018-07-12 07:12:37.995 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state MCH STEREO for channelID mainZone#surroundProgram
2018-07-12 07:12:38.001 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSDRC OFF
2018-07-12 07:12:38.003 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: DRC OFF
2018-07-12 07:12:38.019 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSLFE 00
2018-07-12 07:12:38.021 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: LFE 00
2018-07-12 07:12:38.033 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSBAS 50
2018-07-12 07:12:38.035 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: BAS 50
2018-07-12 07:12:38.051 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSTRE 50
2018-07-12 07:12:38.053 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: TRE 50
2018-07-12 07:12:38.066 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSTONE CTRL OFF
2018-07-12 07:12:38.069 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: TONE CTRL OFF
2018-07-12 07:12:38.236 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'MV?'
2018-07-12 07:12:38.238 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command MV?
2018-07-12 07:12:38.300 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MV36
2018-07-12 07:12:38.302 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MV, value: 36
2018-07-12 07:12:38.303 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state 36 for channelID mainZone#volume
2018-07-12 07:12:38.308 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state -44 for channelID mainZone#volumeDB
2018-07-12 07:12:38.318 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MVMAX 60
2018-07-12 07:12:38.320 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MV, value: MAX 60
2018-07-12 07:12:38.539 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'ZM?'
2018-07-12 07:12:38.541 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command ZM?
2018-07-12 07:12:38.612 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: ZMON
2018-07-12 07:12:38.614 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: ZM, value: ON
2018-07-12 07:12:38.616 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID mainZone#power
2018-07-12 07:12:38.843 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'MU?'
2018-07-12 07:12:38.845 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command MU?
2018-07-12 07:12:38.892 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MUOFF
2018-07-12 07:12:38.895 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MU, value: OFF
2018-07-12 07:12:38.897 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state OFF for channelID mainZone#mute
2018-07-12 07:12:39.148 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'SI?'
2018-07-12 07:12:39.150 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command SI?
2018-07-12 07:12:39.201 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SITV
2018-07-12 07:12:39.203 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SI, value: TV
2018-07-12 07:12:39.204 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state TV for channelID mainZone#input
2018-07-12 07:12:39.261 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SVOFF
2018-07-12 07:12:39.262 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SV, value: OFF
2018-07-12 07:12:39.451 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'Z2?'
2018-07-12 07:12:39.453 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command Z2?
2018-07-12 07:12:39.527 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2ON
2018-07-12 07:12:39.528 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: ON
2018-07-12 07:12:39.538 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2NET
2018-07-12 07:12:39.540 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: NET
2018-07-12 07:12:39.541 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state NET for channelID zone2#input
2018-07-12 07:12:39.547 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z208
2018-07-12 07:12:39.548 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: 08
2018-07-12 07:12:39.549 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state 8 for channelID zone2#volume
2018-07-12 07:12:39.551 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state -72 for channelID zone2#volumeDB
2018-07-12 07:12:39.620 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SVOFF
2018-07-12 07:12:39.621 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SV, value: OFF
2018-07-12 07:12:39.754 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'Z2MU?'
2018-07-12 07:12:39.756 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command Z2MU?
2018-07-12 07:12:39.813 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2MUOFF
2018-07-12 07:12:39.815 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: MUOFF
2018-07-12 07:12:39.817 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state OFF for channelID zone2#mute
2018-07-12 07:12:40.058 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'Z3?'
2018-07-12 07:12:40.060 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command Z3?
2018-07-12 07:12:40.099 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z3ON
2018-07-12 07:12:40.101 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: ON
2018-07-12 07:12:40.111 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z3NET
2018-07-12 07:12:40.113 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: NET
2018-07-12 07:12:40.114 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state NET for channelID zone2#input
2018-07-12 07:12:40.120 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z310
2018-07-12 07:12:40.122 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: 10
2018-07-12 07:12:40.123 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state 10 for channelID zone3#volume
2018-07-12 07:12:40.126 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state -70 for channe

log http connection:


` 2018-07-12 07:06:51.927 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing Denon status
2018-07-12 07:06:51.931 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formMainZone_MainZoneXml.xml
2018-07-12 07:06:51.947 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formMainZone_MainZoneXml.xml':
Error 403: Forbidden
Access Forbidden
2018-07-12 07:06:52.042 [DEBUG] [ector.http.DenonMarantzHttpConnector] - Failed to unmarshal xml document: null
2018-07-12 07:06:52.044 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formMainZone_MainZoneXmlStatus.xml
2018-07-12 07:06:52.055 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formMainZone_MainZoneXmlStatus.xml':
Error 403: Forbidden
Access Forbidden
2018-07-12 07:06:52.132 [DEBUG] [ector.http.DenonMarantzHttpConnector] - Failed to unmarshal xml document: null
2018-07-12 07:06:52.133 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formZone2_Zone2XmlStatusLite.xml
2018-07-12 07:06:52.144 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formZone2_Zone2XmlStatusLite.xml':
<?xml version="1.0" encoding="utf-8" ?>
<item>
<Power><value>ON</value></Power>
<InputFuncSelect><value>NET</value></InputFuncSelect>
<VolumeDisplay><value>Relative</value></VolumeDisplay>
<MasterVolume><value>-72</value></MasterVolume>
<Mute><value>off</value></Mute>
</item>
2018-07-12 07:06:52.177 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formZone3_Zone3XmlStatusLite.xml
2018-07-12 07:06:52.184 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formZone3_Zone3XmlStatusLite.xml':
<?xml version="1.0" encoding="utf-8" ?>
<item>
<Power><value>ON</value></Power>
<InputFuncSelect><value>NET</value></InputFuncSelect>
<VolumeDisplay><value>Relative</value></VolumeDisplay>
<MasterVolume><value>-70</value></MasterVolume>
<Mute><value>off</value></Mute>
</item>
2018-07-12 07:06:52.205 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/AppCommand.xml

it is nothing about surroundProgram

jwveldhuis commented 6 years ago

Ok, so for HEOS the http method won’t work. Telnet should, and I see it is getting the MCH STEREO surround mode:

2018-07-12 07:12:37.987 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MSMCH STEREO
2018-07-12 07:12:37.991 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MS, value: MCH STEREO
2018-07-12 07:12:37.995 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state MCH STEREO for channelID mainZone#surroundProgram

So the only question now is why it is showing - in the UI. What is de definition of the Item? Does it have the corresponding Thing and ChannelID?

grzegorz914 commented 6 years ago

HI,

Yes, with telnet connection in log the surroundMode is showing but not in the UI

my .item

Group      Wzmacniacz "Wzmacniacz"
Switch     Wzmacniacz_Zasilanie  "Zasilanie"    <switch>     (KinoDomowe, Wzmacniacz)
Dimmer     Wzmacniacz_Glosnosc  "Głośność"    <soundvolume>  (KinoDomowe, Wzmacniacz)
Switch     Wzmacniacz_Wycisz    "Wycisz"      <soundvolume_mute>  (KinoDomowe, Wzmacniacz)
String     Wzmacniacz_TrybDzwieku   "Tryb dźwięku [%s]"   <text>        (KinoDomowe, Wzmacniacz)
String     Wzmacniacz_Zrodlo   "Źródło [MAP(zrodlaav.map):%s]"       <settings>        (KinoDomowe, Wzmacniacz)
String     Wzmacniacz_Wiadomosc   "Powiadomienie [%s]"   <text>        (KinoDomowe, Wzmacniacz)
zrzut ekranu 2018-07-12 o 07 43 41
jwveldhuis commented 6 years ago

And Thing definition?

grzegorz914 commented 6 years ago

Previous post edited, screenshot.

jwveldhuis commented 6 years ago

Could you add another item like this: String marantz_surround "Surround: [%s]" {channel="denonmarantz:avr:0006781d58b1:general#surroundProgram"} Replace the ID with yours.

grzegorz914 commented 6 years ago

Same effect

zrzut ekranu 2018-07-12 o 07 55 37
jwveldhuis commented 6 years ago

Hmm.. ok, so we have ruled out a lot already:

Can you try to switch the surround mode using the AVR remote while openhab is running?

Also please enable OpenHAB debug an post the logs related to updating the surroundMode channel. Note that you are running 2.4, which is not a stable version.

grzegorz914 commented 6 years ago

Nothing change in UI

Telnet:

2018-07-12 08:12:13.317 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SSSMG GAM
2018-07-12 08:12:13.323 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SS, value: SMG GAM
2018-07-12 08:12:53.805 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SSSMG MOV
2018-07-12 08:12:53.810 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SS, value: SMG MOV
2018-07-12 08:13:05.524 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SSSMG MUS
2018-07-12 08:13:05.529 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SS, value: SMG MUS
2018-07-12 08:13:14.925 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SSSMG PUR
2018-07-12 08:13:14.928 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SS, value: SMG PUR
2018-07-12 08:13:14.965 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MSDIRECT
2018-07-12 08:13:14.967 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MS, value: DIRECT
2018-07-12 08:13:14.970 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state DIRECT for channelID mainZone#surroundProgram
2018-07-12 08:13:14.982 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSDRC OFF
2018-07-12 08:13:14.984 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: DRC OFF
2018-07-12 08:13:14.998 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSLFE 00
2018-07-12 08:13:15.000 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: LFE 00
2018-07-12 08:13:15.011 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSBAS 50
2018-07-12 08:13:15.013 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: BAS 50
2018-07-12 08:13:15.025 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSTRE 50
2018-07-12 08:13:15.028 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: TRE 50
2018-07-12 08:13:15.042 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSTONE CTRL OFF
2018-07-12 08:13:15.044 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: TONE CTRL OFF

Http:

2018-07-12 08:14:10.067 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing Denon status
2018-07-12 08:14:10.072 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formMainZone_MainZoneXml.xml
2018-07-12 08:14:10.082 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formMainZone_MainZoneXml.xml':
2018-07-12 08:14:10.178 [DEBUG] [ector.http.DenonMarantzHttpConnector] - Failed to unmarshal xml document: null
2018-07-12 08:14:10.182 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formMainZone_MainZoneXmlStatus.xml
2018-07-12 08:14:10.197 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formMainZone_MainZoneXmlStatus.xml':
2018-07-12 08:14:10.251 [DEBUG] [ector.http.DenonMarantzHttpConnector] - Failed to unmarshal xml document: null
2018-07-12 08:14:10.254 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formZone2_Zone2XmlStatusLite.xml
2018-07-12 08:14:10.261 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formZone2_Zone2XmlStatusLite.xml':
2018-07-12 08:14:10.320 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID zone2#power
2018-07-12 08:14:10.336 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state 8 for channelID zone2#volume
2018-07-12 08:14:10.342 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state -72 for channelID zone2#volumeDB
2018-07-12 08:14:10.349 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state OFF for channelID zone2#mute
2018-07-12 08:14:10.353 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state NET for channelID zone2#input
2018-07-12 08:14:10.358 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formZone3_Zone3XmlStatusLite.xml
2018-07-12 08:14:10.368 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formZone3_Zone3XmlStatusLite.xml':
2018-07-12 08:14:10.408 [hingStatusInfoChangedEvent] - 'denonmarantz:avr:0005cd6f9f92' changed from UNKNOWN to ONLINE
2018-07-12 08:14:10.430 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID zone3#power
2018-07-12 08:14:10.434 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state 10 for channelID zone3#volume
2018-07-12 08:14:10.437 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state -70 for channelID zone3#volumeDB
2018-07-12 08:14:10.441 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state OFF for channelID zone3#mute
2018-07-12 08:14:10.444 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state NET for channelID zone2#input
2018-07-12 08:14:10.448 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/AppCommand.xml
2018-07-12 08:14:10.508 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state  for channelID general#artist
2018-07-12 08:14:10.511 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state  for channelID general#album
2018-07-12 08:14:10.514 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state  for channelID general#track
2018-07-12 08:14:10.517 [DEBUG] [ector.http.DenonMarantzHttpConnector] - HTTP polling started.
2018-07-12 08:14:15.520 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing Denon status
2018-07-12 08:14:15.524 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formMainZone_MainZoneXml.xml
2018-07-12 08:14:15.534 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formMainZone_MainZoneXml.xml':
2018-07-12 08:14:15.579 [DEBUG] [ector.http.DenonMarantzHttpConnector] - Failed to unmarshal xml document: null
2018-07-12 08:14:15.582 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formMainZone_MainZoneXmlStatus.xml
2018-07-12 08:14:15.593 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formMainZone_MainZoneXmlStatus.xml':
2018-07-12 08:14:15.639 [DEBUG] [ector.http.DenonMarantzHttpConnector] - Failed to unmarshal xml document: null
2018-07-12 08:14:15.642 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formZone2_Zone2XmlStatusLite.xml
2018-07-12 08:14:15.650 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formZone2_Zone2XmlStatusLite.xml':
2018-07-12 08:14:15.675 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formZone3_Zone3XmlStatusLite.xml
2018-07-12 08:14:15.683 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formZone3_Zone3XmlStatusLite.xml':
2018-07-12 08:14:15.717 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/AppCommand.xml
2018-07-12 08:14:20.783 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing Denon status
2018-07-12 08:14:20.786 [TRACE] [ector.http.DenonMarantzHttpConnector] - Refreshing URL: http://192.168.1.6:8080/goform/formMainZone_MainZoneXml.xml
2018-07-12 08:14:20.793 [TRACE] [ector.http.DenonMarantzHttpConnector] - result of getDocument for uri 'http://192.168.1.6:8080/goform/formMainZone_MainZoneXml.xml':
2018-07-12 08:14:20.810 [DEBUG] [ector.http.DenonMarantzHttpConnector] - Failed to unmarshal xml document: null
jwveldhuis commented 6 years ago

Ok, no need for http logs anymore.

Can you enable the general debug? To see how openhab internally handles the updates.

grzegorz914 commented 6 years ago

What a general debug?

jwveldhuis commented 6 years ago

SmartHome debug, should be in the logging properties file. Don’t know out of my head and can’t quickly find a doc on it. There should be a way to enable debug for the whole setup.

jwveldhuis commented 6 years ago

org.eclipse.smarthome set it to DEBUG

grzegorz914 commented 6 years ago 
2018-07-12 08:36:54.848 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CLOSE --> CLOSED
2018-07-12 08:36:54.849 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - queue EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:54.850 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@2fa84d[SelectChannelEndPoint@12de327{/192.168.0.100:50567<->8080,CLOSED,ISHUT,OSHUT,-,-,101/30000,HttpConnection@2fa84d}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@c952b4{s=START},c=HttpChannelOverHttp@1666fa4{r=3,c=false,a=IDLE,uri=null}] parsed false HttpParser{s=CLOSED,0 of -1}
2018-07-12 08:36:54.852 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c run org.eclipse.jetty.io.ManagedSelector$2@1088184
2018-07-12 08:36:54.852 [DEBUG] [.eclipse.jetty.server.HttpConnection] - releaseRequestBuffer HttpConnection@2fa84d[SelectChannelEndPoint@12de327{/192.168.0.100:50567<->8080,CLOSED,ISHUT,OSHUT,-,-,102/30000,HttpConnection@2fa84d}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@c952b4{s=START},c=HttpChannelOverHttp@1666fa4{r=3,c=false,a=IDLE,uri=null}]
2018-07-12 08:36:54.854 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Destroyed SelectChannelEndPoint@12de327{/192.168.0.100:50567<->8080,CLOSED,ISHUT,OSHUT,-,-,105/30000,HttpConnection@2fa84d}{io=0/0,kio=-1,kro=-1}
2018-07-12 08:36:54.854 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@2fa84d[SelectChannelEndPoint@12de327{/192.168.0.100:50567<->8080,CLOSED,ISHUT,OSHUT,-,-,104/30000,HttpConnection@2fa84d}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@c952b4{s=START},c=HttpChannelOverHttp@1666fa4{r=3,c=false,a=IDLE,uri=null}] onFillable exit HttpChannelState@199d8fc{s=IDLE a=NOT_ASYNC i=true r=NONE/false w=false} null
2018-07-12 08:36:54.855 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - run EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:54.856 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c run
2018-07-12 08:36:54.857 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produce enter
2018-07-12 08:36:54.857 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - onClose HttpConnection@2fa84d[SelectChannelEndPoint@12de327{/192.168.0.100:50567<->8080,CLOSED,ISHUT,OSHUT,-,-,107/30000,HttpConnection@2fa84d}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@c952b4{s=START},c=HttpChannelOverHttp@1666fa4{r=3,c=false,a=IDLE,uri=null}]
2018-07-12 08:36:54.858 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c producing
2018-07-12 08:36:54.860 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c ran SelectChannelEndPoint@12de327{/192.168.0.100:50567<->8080,CLOSED,ISHUT,OSHUT,-,-,110/30000,HttpConnection@2fa84d}{io=0/0,kio=-1,kro=-1}:runFillable
2018-07-12 08:36:54.860 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c ran org.eclipse.jetty.io.ManagedSelector$2@1088184
2018-07-12 08:36:54.861 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produce exit
2018-07-12 08:36:54.861 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector loop waiting on select
2018-07-12 08:36:54.862 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produce exit
2018-07-12 08:36:54.862 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - ran EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:54.864 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - ran EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:54.905 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,out,FI,-,30004/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4} idle timeout check, elapsed: 30003 ms, remaining: -3 ms
2018-07-12 08:36:54.906 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,out,FI,-,30005/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4} idle timeout expired
2018-07-12 08:36:54.908 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - close HttpParser{s=START,0 of -1}
2018-07-12 08:36:54.909 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> CLOSE
2018-07-12 08:36:54.910 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,out,-,-,30009/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}] onFillInterestedFailed {}
2018-07-12 08:36:54.912 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - oshut SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,out,-,-,30011/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}
2018-07-12 08:36:54.914 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,-,-,30012/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}]
2018-07-12 08:36:54.916 [DEBUG] [org.eclipse.jetty.io.FillInterest   ] - FillInterest@727f5f{true,AC.ReadCB@1d28f5a{HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,0/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}]}} register AC.ReadCB@1d28f5a{HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,1/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}]}
2018-07-12 08:36:54.918 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - changeInterests p=false 1->1 for SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,3/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}
2018-07-12 08:36:54.920 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Queued change SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,4/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}:runUpdateKey on org.eclipse.jetty.io.ManagedSelector@1958523 id=0 keys=1 selected=0
2018-07-12 08:36:54.921 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,6/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}
2018-07-12 08:36:54.921 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector loop woken up from select, 0/1 selected
2018-07-12 08:36:54.922 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Running change SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,0/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}:runUpdateKey
2018-07-12 08:36:54.924 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 1 on SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,1/30000,HttpConnection@1d28f5a}{io=1/1,kio=1,kro=4}
2018-07-12 08:36:54.925 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector loop waiting on select
2018-07-12 08:36:54.988 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector loop woken up from select, 1/1 selected
2018-07-12 08:36:54.990 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - onSelected 1->0 r=true w=false for SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,67/30000,HttpConnection@1d28f5a}{io=1/0,kio=1,kro=1}
2018-07-12 08:36:54.991 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - task SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,69/30000,HttpConnection@1d28f5a}{io=1/0,kio=1,kro=1}:runFillable
2018-07-12 08:36:54.993 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produced SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,70/30000,HttpConnection@1d28f5a}{io=1/0,kio=1,kro=1}:runFillable
2018-07-12 08:36:54.994 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c dispatch
2018-07-12 08:36:54.995 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - queue EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:54.996 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - run EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:54.996 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c run SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,74/30000,HttpConnection@1d28f5a}{io=1/0,kio=1,kro=1}:runFillable
2018-07-12 08:36:54.997 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c run
2018-07-12 08:36:54.998 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produce enter
2018-07-12 08:36:54.999 [DEBUG] [org.eclipse.jetty.io.FillInterest   ] - FillInterest@727f5f{true,AC.ReadCB@1d28f5a{HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,75/30000,HttpConnection@1d28f5a}{io=1/0,kio=1,kro=1}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}]}} fillable AC.ReadCB@1d28f5a{HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,FI,-,76/30000,HttpConnection@1d28f5a}{io=1/0,kio=1,kro=1}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}]}
2018-07-12 08:36:55.000 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c producing
2018-07-12 08:36:55.000 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,-,-,78/30000,HttpConnection@1d28f5a}{io=1/0,kio=1,kro=1}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}] onFillable enter HttpChannelState@167d52e{s=IDLE a=NOT_ASYNC i=true r=NONE/false w=false} null
2018-07-12 08:36:55.001 [DEBUG] [lipse.jetty.io.SelectChannelEndPoint] - Key interests updated 1 -> 0 on SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,-,-,79/30000,HttpConnection@1d28f5a}{io=0/0,kio=0,kro=1}
2018-07-12 08:36:55.002 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector loop waiting on select
2018-07-12 08:36:55.002 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled -1 SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,-,-,80/30000,HttpConnection@1d28f5a}{io=0/0,kio=0,kro=1}
2018-07-12 08:36:55.004 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - ishut SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,Open,in,OSHUT,-,-,82/30000,HttpConnection@1d28f5a}{io=0/0,kio=0,kro=1}
2018-07-12 08:36:55.006 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - close SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,83/30000,HttpConnection@1d28f5a}{io=0/0,kio=0,kro=1}
2018-07-12 08:36:55.007 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Queued change org.eclipse.jetty.io.ManagedSelector$2@1e54322 on org.eclipse.jetty.io.ManagedSelector@1958523 id=0 keys=1 selected=0
2018-07-12 08:36:55.008 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector loop woken up from select, 0/0 selected
2018-07-12 08:36:55.008 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - atEOF HttpParser{s=CLOSE,0 of -1}
2018-07-12 08:36:55.010 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produced org.eclipse.jetty.io.ManagedSelector$2@1e54322
2018-07-12 08:36:55.010 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,88/30000,HttpConnection@1d28f5a}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}] filled -1 HeapByteBuffer@1439fd9[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2018-07-12 08:36:55.011 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c dispatch
2018-07-12 08:36:55.012 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - queue EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:55.012 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,90/30000,HttpConnection@1d28f5a}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}] parse HeapByteBuffer@1439fd9[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
2018-07-12 08:36:55.013 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - run EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:55.014 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c run
2018-07-12 08:36:55.014 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=CLOSE HeapByteBuffer@1439fd9[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2018-07-12 08:36:55.015 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produce enter
2018-07-12 08:36:55.015 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CLOSE --> CLOSED
2018-07-12 08:36:55.016 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c producing
2018-07-12 08:36:55.017 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,94/30000,HttpConnection@1d28f5a}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}] parsed false HttpParser{s=CLOSED,0 of -1}
2018-07-12 08:36:55.017 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector loop waiting on select
2018-07-12 08:36:55.018 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c run org.eclipse.jetty.io.ManagedSelector$2@1e54322
2018-07-12 08:36:55.019 [DEBUG] [.eclipse.jetty.server.HttpConnection] - releaseRequestBuffer HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,96/30000,HttpConnection@1d28f5a}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}]
2018-07-12 08:36:55.019 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Destroyed SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,97/30000,HttpConnection@1d28f5a}{io=0/0,kio=-1,kro=-1}
2018-07-12 08:36:55.021 [DEBUG] [.eclipse.jetty.server.HttpConnection] - HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,98/30000,HttpConnection@1d28f5a}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}] onFillable exit HttpChannelState@167d52e{s=IDLE a=NOT_ASYNC i=true r=NONE/false w=false} null
2018-07-12 08:36:55.021 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - onClose HttpConnection@1d28f5a[SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,99/30000,HttpConnection@1d28f5a}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@5384b3{s=START},c=HttpChannelOverHttp@162aa6c{r=3,c=false,a=IDLE,uri=null}]
2018-07-12 08:36:55.022 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c ran SelectChannelEndPoint@1dc9893{/192.168.0.100:50565<->8080,CLOSED,ISHUT,OSHUT,-,-,100/30000,HttpConnection@1d28f5a}{io=0/0,kio=-1,kro=-1}:runFillable
2018-07-12 08:36:55.023 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c ran org.eclipse.jetty.io.ManagedSelector$2@1e54322
2018-07-12 08:36:55.024 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produce exit
2018-07-12 08:36:55.024 [DEBUG] [hread.strategy.ExecuteProduceConsume] - EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c produce exit
2018-07-12 08:36:55.025 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - ran EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
2018-07-12 08:36:55.025 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - ran EPC Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@ec6c0c
jwveldhuis commented 6 years ago

Includes jetty, not needed. Try with the logging scope above. Please try to find the log lines for surroundProgram

grzegorz914 commented 6 years ago

I have found only this:

2018-07-12 08:49:41.229 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating command 'ON' for item 'Wzmacniacz_Zasilanie' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#power'
2018-07-12 08:49:41.231 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleCommand()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@658872'.
2018-07-12 08:49:41.238 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'PWON'
2018-07-12 08:49:41.240 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command PWON
2018-07-12 08:49:41.247 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating update 'ON' for item 'Wzmacniacz_Zasilanie' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#power'
2018-07-12 08:49:41.249 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleUpdate()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@658872'.
2018-07-12 08:49:41.325 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: ZMON
2018-07-12 08:49:41.326 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: ZM, value: ON
2018-07-12 08:49:41.327 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID mainZone#power
2018-07-12 08:49:41.733 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PWON
2018-07-12 08:49:41.734 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PW, value: ON
2018-07-12 08:49:41.735 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID general#power
2018-07-12 08:49:41.751 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2ON
2018-07-12 08:49:41.753 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: ON
2018-07-12 08:49:41.754 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID zone2#power
2018-07-12 08:49:41.769 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z3ON
2018-07-12 08:49:41.771 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: ON
2018-07-12 08:49:41.773 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID zone3#power
2018-07-12 08:49:52.368 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PWON
2018-07-12 08:49:52.371 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PW, value: ON
2018-07-12 08:49:52.392 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2ON
2018-07-12 08:49:52.395 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: ON
2018-07-12 08:49:52.417 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z3ON
2018-07-12 08:49:52.419 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: ON
2018-07-12 08:50:52.483 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Socket timeout
2018-07-12 08:50:52.959 [DEBUG] [.thing.internal.CommunicationManager] - Received  event 'STEREO' for non-existing channel 'denonmarantz:avr:0005cd6f9f92:surroundProgram', not forwarding it to the handler
2018-07-12 08:50:52.962 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating command 'STEREO' for item 'Wzmacniacz_TrybDzwieku' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#surroundProgram'
2018-07-12 08:50:52.965 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleCommand()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@658872'.
2018-07-12 08:50:52.966 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Unsupported command STEREO for channel general#surroundProgram
2018-07-12 08:50:52.980 [DEBUG] [.thing.internal.CommunicationManager] - Received  event 'STEREO' for non-existing channel 'denonmarantz:avr:0005cd6f9f92:surroundProgram', not forwarding it to the handler
2018-07-12 08:50:52.996 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating update 'STEREO' for item 'Wzmacniacz_TrybDzwieku' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#surroundProgram'
2018-07-12 08:50:52.998 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleUpdate()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@658872'.
jwveldhuis commented 6 years ago

Seems there is something wrong with the channel definition.

"non-existing channel 'denonmarantz:avr:0005cd6f9f92:surroundProgram' Should have been 'denonmarantz:avr:0005cd6f9f92: general# surroundProgram'.

Can you delete the Thing and re-add it?

jwveldhuis commented 6 years ago

Wait, I think I found it. In part of the code it is using mainZone#. Need some time to check and correct this.

grzegorz914 commented 6 years ago

OK,

I waiting, I thing this probably also corresponding with this issue: #3727

jwveldhuis commented 6 years ago

Yes will check both issues at the same time, will let you know once I have a fix.

jwveldhuis commented 6 years ago

hi @grzegorz914 I just created a PR to fix this. Can you try the updated binding to see if it fixes the issue for you? https://openhab.jfrog.io/openhab/libs-pullrequest-local/org/openhab/binding/org.openhab.binding.denonmarantz/2.4.0-SNAPSHOT/org.openhab.binding.denonmarantz-2.4.0-SNAPSHOT.jar

Uninstall the current denonmarantz binding, and place the jar into /usr/share/openhab2/addons

grzegorz914 commented 6 years ago

hi,

looks like problem exist, in log all OK but nothing in web or app UI.

2018-07-18 07:02:49.254 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MV, value: MAX 60
2018-07-18 07:02:49.282 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MSDOLBY SURROUND
2018-07-18 07:02:49.284 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MS, value: DOLBY SURROUND
2018-07-18 07:02:49.286 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state DOLBY SURROUND for channelID mainZone#surroundProgram
2018-07-18 07:02:49.324 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SDHDMI
2018-07-18 07:02:49.326 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SD, value: HDMI
2018-07-18 07:02:49.338 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSDRC OFF

2018-07-18 07:06:47.745 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MSDOLBY SURROUND
2018-07-18 07:06:47.746 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MS, value: DOLBY SURROUND
2018-07-18 07:06:47.747 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state DOLBY SURROUND for channelID mainZone#surroundProgram
2018-07-18 07:06:47.761 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SDHDMI
zrzut ekranu 2018-07-18 o 07 08 38

img_0247

jwveldhuis commented 6 years ago

Did you update the item to use general#surroundProgram? I see mainZone#surroundProgram in the log. Does the binding show general#surroundProgram for the Channel in the Thing configuration? If not, the old binding is still active.

grzegorz914 commented 6 years ago

Yes,

zrzut ekranu 2018-07-18 o 07 49 03
jwveldhuis commented 6 years ago

Did you restart openHAB? I don’t understand the log.

grzegorz914 commented 6 years ago

YES,

other items working OK, only source switch and surroundProgram not working.

2018-07-18 07:58:40.181 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating command 'OFF' for item 'Wzmacniacz_Zasilanie' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#power'
2018-07-18 07:58:40.183 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleCommand()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@526fe9'.
2018-07-18 07:58:40.185 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'PWSTANDBY'
2018-07-18 07:58:40.186 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command PWSTANDBY
2018-07-18 07:58:40.200 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating update 'OFF' for item 'Wzmacniacz_Zasilanie' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#power'
2018-07-18 07:58:40.201 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleUpdate()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@526fe9'.
2018-07-18 07:58:40.277 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PWSTANDBY
2018-07-18 07:58:40.279 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PW, value: STANDBY
2018-07-18 07:58:40.280 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state OFF for channelID general#power
2018-07-18 07:58:40.305 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2OFF
2018-07-18 07:58:40.307 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: OFF
2018-07-18 07:58:40.308 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state OFF for channelID zone2#power
2018-07-18 07:58:40.321 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z3OFF
2018-07-18 07:58:40.323 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: OFF
2018-07-18 07:58:40.325 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state OFF for channelID zone3#power
2018-07-18 07:58:40.366 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: ZMOFF
2018-07-18 07:58:40.370 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: ZM, value: OFF
2018-07-18 07:58:40.374 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state OFF for channelID mainZone#power
2018-07-18 07:58:53.198 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating command 'ON' for item 'Wzmacniacz_Zasilanie' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#power'
2018-07-18 07:58:53.201 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleCommand()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@526fe9'.
2018-07-18 07:58:53.203 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'PWON'
2018-07-18 07:58:53.205 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command PWON
2018-07-18 07:58:53.208 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating update 'ON' for item 'Wzmacniacz_Zasilanie' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#power'
2018-07-18 07:58:53.210 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleUpdate()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@526fe9'.
2018-07-18 07:58:53.285 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PWON
2018-07-18 07:58:53.287 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PW, value: ON
2018-07-18 07:58:53.288 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID general#power
2018-07-18 07:58:53.657 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2ON
2018-07-18 07:58:53.659 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: ON
2018-07-18 07:58:53.661 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID zone2#power
2018-07-18 07:58:53.675 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z3ON
2018-07-18 07:58:53.677 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: ON
2018-07-18 07:58:53.679 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID zone3#power
2018-07-18 07:58:53.730 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: ZMON
2018-07-18 07:58:53.732 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: ZM, value: ON
2018-07-18 07:58:53.734 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state ON for channelID mainZone#power
2018-07-18 07:59:04.289 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PWON
2018-07-18 07:59:04.292 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PW, value: ON
2018-07-18 07:59:04.314 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z2ON
2018-07-18 07:59:04.316 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z2, value: ON
2018-07-18 07:59:04.338 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: Z3ON
2018-07-18 07:59:04.340 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: Z3, value: ON
2018-07-18 07:59:16.908 [DEBUG] [.thing.internal.CommunicationManager] - Received  event 'GAME' for non-existing channel 'denonmarantz:avr:0005cd6f9f92:input', not forwarding it to the handler
2018-07-18 07:59:16.912 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating command 'GAME' for item 'Wzmacniacz_Zrodlo' to handler for channel 'denonmarantz:avr:0005cd6f9f92:mainZone#input'
2018-07-18 07:59:16.915 [DEBUG] [.thing.internal.CommunicationManager] - Received  event 'GAME' for non-existing channel 'denonmarantz:avr:0005cd6f9f92:input', not forwarding it to the handler
2018-07-18 07:59:16.917 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleCommand()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@526fe9'.
2018-07-18 07:59:16.919 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'SIGAME'
2018-07-18 07:59:16.921 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command SIGAME
2018-07-18 07:59:16.924 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating update 'GAME' for item 'Wzmacniacz_Zrodlo' to handler for channel 'denonmarantz:avr:0005cd6f9f92:mainZone#input'
2018-07-18 07:59:16.926 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleUpdate()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@526fe9'.
2018-07-18 07:59:17.985 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SSSMG MUS
2018-07-18 07:59:17.990 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SS, value: SMG MUS
2018-07-18 07:59:18.010 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SIGAME
2018-07-18 07:59:18.015 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SI, value: GAME
2018-07-18 07:59:18.023 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state GAME for channelID mainZone#input
2018-07-18 07:59:18.039 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: CVFL 50
2018-07-18 07:59:18.041 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: CV, value: FL 50
2018-07-18 07:59:18.044 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: CVFR 50
2018-07-18 07:59:18.046 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: CV, value: FR 50
2018-07-18 07:59:18.070 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: CVC 50
2018-07-18 07:59:18.072 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: CV, value: C 50
2018-07-18 07:59:18.074 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: CVSL 50
2018-07-18 07:59:18.079 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: CV, value: SL 50
2018-07-18 07:59:18.081 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: CVSR 50
2018-07-18 07:59:18.083 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: CV, value: SR 50
2018-07-18 07:59:18.084 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: CVSBL 50
2018-07-18 07:59:18.086 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: CV, value: SBL 50
2018-07-18 07:59:18.099 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: CVSBR 50
2018-07-18 07:59:18.100 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: CV, value: SBR 50
2018-07-18 07:59:18.102 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: CVEND
2018-07-18 07:59:18.120 [DEBUG] [.thing.internal.CommunicationManager] - Received  event 'GAME' for non-existing channel 'denonmarantz:avr:0005cd6f9f92:input', not forwarding it to the handler
2018-07-18 07:59:18.109 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: CV, value: END
2018-07-18 07:59:18.311 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MVMAX 60
2018-07-18 07:59:18.313 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MV, value: MAX 60
2018-07-18 07:59:18.326 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: MSDOLBY SURROUND
2018-07-18 07:59:18.328 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: MS, value: DOLBY SURROUND
2018-07-18 07:59:18.330 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Received state DOLBY SURROUND for channelID mainZone#surroundProgram
2018-07-18 07:59:18.370 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SDHDMI
2018-07-18 07:59:18.372 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SD, value: HDMI
2018-07-18 07:59:18.386 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSDRC OFF
2018-07-18 07:59:18.388 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: DRC OFF
2018-07-18 07:59:18.406 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: DCAUTO
2018-07-18 07:59:18.408 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: DC, value: AUTO
2018-07-18 07:59:18.424 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSMULTEQ:AUDYSSEY
2018-07-18 07:59:18.426 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: MULTEQ:AUDYSSEY
2018-07-18 07:59:18.438 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSDYNEQ ON
2018-07-18 07:59:18.439 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: DYNEQ ON
2018-07-18 07:59:18.455 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSDYNVOL OFF
2018-07-18 07:59:18.457 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: DYNVOL OFF
2018-07-18 07:59:18.470 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSLFE 00
2018-07-18 07:59:18.471 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: LFE 00
2018-07-18 07:59:18.483 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSBAS 50
2018-07-18 07:59:18.484 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: BAS 50
2018-07-18 07:59:18.499 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSTRE 50
2018-07-18 07:59:18.501 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: TRE 50
2018-07-18 07:59:18.518 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: PSTONE CTRL OFF
2018-07-18 07:59:18.519 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: PS, value: TONE CTRL OFF
2018-07-18 07:59:18.536 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SVOFF
2018-07-18 07:59:18.537 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SV, value: OFF
2018-07-18 08:00:18.599 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Socket timeout
jwveldhuis commented 6 years ago

denonmarantz:avr:0005cd6f9f92:input Is also wrong, should be denonmarantz:avr:0005cd6f9f92: mainZone# input.

Let me check again if there are any traces of these wrong channel IDs in the code. Otherwise you might need to try first in a fresh openhab install.

jwveldhuis commented 6 years ago

@grzegorz914 please verify in a fresh OpenHAB instance with the .jar file I posted. Pretty sure it's resolved and you might be looking at some old configuration that still is active in your instance somehow.

grzegorz914 commented 6 years ago

Install openHAB from scratch not help:

Linked item after add thing is correct but Input source and surroundProgram do not work correct from app or web UI, 

2018-07-18 11:40:50.007 [DEBUG] [nmarantz.handler.DenonMarantzHandler] - Unsupported command REFRESH for channel general#surroundProgram
2018-07-18 11:40:50.011 [.ItemChannelLinkAddedEvent] - Link 'Wzmacniacz_TrybDzwieku-denonmarantz:avr:0005cd6f9f92:general#surroundProgram' has been added.
2018-07-18 11:40:50.010 [DEBUG] [mon.registry.AbstractManagedProvider] - Added new element Wzmacniacz_TrybDzwieku -> denonmarantz:avr:0005cd6f9f92:general#surroundProgram to ManagedItemChannelLinkProvider.
2018-07-18 11:41:36.491 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Socket timeout
2018-07-18 11:42:03.953 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'SI?'
2018-07-18 11:42:03.955 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command SI?
2018-07-18 11:42:03.955 [DEBUG] [mon.registry.AbstractManagedProvider] - Added new element Wzmacniacz_Zrodlo -> denonmarantz:avr:0005cd6f9f92:mainZone#input to ManagedItemChannelLinkProvider.
2018-07-18 11:42:03.960 [.ItemChannelLinkAddedEvent] - Link 'Wzmacniacz_Zrodlo-denonmarantz:avr:0005cd6f9f92:mainZone#input' has been added.
2018-07-18 11:42:03.968 [DEBUG] [.thing.internal.CommunicationManager] - Received  event 'GAME' for non-existing channel 'denonmarantz:avr:0005cd6f9f92:input', not forwarding it to the handler
2018-07-18 11:42:04.008 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SIGAME
2018-07-18 11:42:04.010 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SI, value: GAME
2018-07-18 11:42:04.068 [TRACE] [ctor.telnet.DenonMarantzTelnetClient] - Received from 192.168.1.6: SVOFF
2018-07-18 11:42:04.070 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Received Command: SV, value: OFF
2018-07-18 11:42:16.498 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating command 'ON' for item 'Wzmacniacz_Zasilanie' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#power'
2018-07-18 11:42:16.502 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleCommand()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@14c658'.
2018-07-18 11:42:16.504 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'PWON'
2018-07-18 11:42:16.506 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command PWON
2018-07-18 11:42:16.509 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating update 'ON' for item 'Wzmacniacz_Zasilanie' to handler for channel 'denonmarantz:avr:0005cd6f9f92:general#power'
2018-07-18 11:42:16.511 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleUpdate()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@14c658'.
2018-07-18 11:42:23.587 [DEBUG] [.thing.internal.CommunicationManager] - Received  event 'GAME' for non-existing channel 'denonmarantz:avr:0005cd6f9f92:input', not forwarding it to the handler
2018-07-18 11:42:23.595 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating command 'GAME' for item 'Wzmacniacz_Zrodlo' to handler for channel 'denonmarantz:avr:0005cd6f9f92:mainZone#input'
2018-07-18 11:42:23.597 [DEBUG] [.thing.internal.CommunicationManager] - Received  event 'GAME' for non-existing channel 'denonmarantz:avr:0005cd6f9f92:input', not forwarding it to the handler
2018-07-18 11:42:23.600 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleCommand()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@14c658'.
2018-07-18 11:42:23.604 [DEBUG] [r.telnet.DenonMarantzTelnetConnector] - Sending command 'SIGAME'
2018-07-18 11:42:23.608 [DEBUG] [ctor.telnet.DenonMarantzTelnetClient] - Sending command SIGAME
2018-07-18 11:42:23.613 [DEBUG] [nternal.profiles.ProfileCallbackImpl] - Delegating update 'GAME' for item 'Wzmacniacz_Zrodlo' to handler for channel 'denonmarantz:avr:0005cd6f9f92:mainZone#input'
2018-07-18 11:42:23.616 [DEBUG] [nternal.common.InvocationHandlerSync] - Already in a safe-call context, executing 'ThingHandler.handleUpdate()' directly on 'org.openhab.binding.denonmarantz.handler.DenonMarantzHandler@14c658'.