Onkyo Binding Timeouts

KidSquid · December 19, 2017, 5:22pm

Hoping someone may have an idea on why the log is flooded with this ERROR message every minute?

I can ping the unit fine, in fact I have kept the ping going for 5 minutes and while the ping never drops, the connection still shows an error message every minute.

My receiver model is: TX-NR545

I am using the “unsupported” version of the thing as my model is not directly listed. Controls for volume, power, and state work as intended. This seems like a simple network issue but traces and pings never fail.

Any ideas welcome.

2017-12-07 00:36:09.735 [ERROR] [nding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out 
2017-12-07 00:37:09.735 [ERROR] [nding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out

pgruetter · December 20, 2017, 9:56pm

I remember having similar messages that didn’t make a lot of sense to me. This particular one only happened when the Onkyo was actually shut off though.
Anyway, I disabled logging for the Onkyo binding since it was generating too much noise. I’m also using an unsupported model and everything works fine.

Had these lines in /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg

# Onkyo 
log4j.logger.org.openhab.binding.onkyo = OFF
log4j.logger.b.binding.onkyo.internal = OFF

Now I just upgraded to OH2.2 and changed the lines to:

# Onkyo
log4j2.logger.org_openhab_binding_onkyo.name = org.openhab.binding.onkyo
log4j2.logger.org_openhab_binding_onkyo.level = OFF

(see this post for examples)

KidSquid · December 22, 2017, 1:06am

Thanks for this…

I really prefer not to disable a logger all together as when issues do arise you need to remember you have disabled logging to get at the root of the issue.

Hopefully the binding developer will take note of the issue I posted on Git and look into it further.

I do appreciate you taking the time and letting me know how you addressed the situation.

Squid

pauli_anttila · December 26, 2017, 8:10am

@KidSquid, thats weird indeed. Could you enable trace level logging for binding to get more information? When traces are enabled, send also some commands to receiver (e.g volume).

KidSquid · December 26, 2017, 4:55pm

@pauli_anttila

Thanks for looking into this…

Here’s a small snippet of the TRACE log with a couple of volume changes…let me know what else I can provide or test.

26-Dec-2017 10:45:17.445 [ERROR] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out
26-Dec-2017 10:45:55.889 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - handleCommand for channel zone1#volume: 34
26-Dec-2017 10:45:55.891 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Sending command 'MVL' with value '22' to Onkyo Receiver @10.5.1.11:60128
26-Dec-2017 10:45:55.891 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=MVL, value=22] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:45:55.893 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 4953435000000010000000080100000021314D564C32320D -> ISCP[00][00][00][10][00][00][00][08][01][00][00][00]!1MVL22[CR]
26-Dec-2017 10:45:55.894 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 24 bytes: 4953435000000010000000080100000021314D564C32320D
26-Dec-2017 10:45:55.961 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:45:55.962 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:45:55.962 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C32321A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL22[EOF][CR][LF]
26-Dec-2017 10:45:55.962 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=MVL, value=22]
26-Dec-2017 10:45:55.962 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C32321A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL22[EOF][CR][LF]
26-Dec-2017 10:45:55.962 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command VOLUME
26-Dec-2017 10:45:55.962 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '22' to openHAB state '34' (class org.eclipse.smarthome.core.library.types.PercentType)
26-Dec-2017 10:46:12.444 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.123:60128
26-Dec-2017 10:46:12.444 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.123:60128 (Socket[unconnected])
26-Dec-2017 10:46:17.444 [ERROR] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out
26-Dec-2017 10:46:40.220 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:46:40.220 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=63997])
26-Dec-2017 10:46:40.220 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:46:40.220 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:46:40.325 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:46:40.325 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:46:40.325 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:46:40.325 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:46:40.325 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:46:40.325 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:46:40.326 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:46:42.707 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:46:42.707 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:46:42.707 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:46:42.707 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:46:42.779 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:46:42.779 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:46:42.779 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:46:42.779 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:46:42.779 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:46:42.779 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:46:42.779 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:47:12.444 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.123:60128
26-Dec-2017 10:47:12.444 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.123:60128 (Socket[unconnected])
26-Dec-2017 10:47:17.445 [ERROR] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out
26-Dec-2017 10:47:24.269 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - handleCommand for channel zone1#volume: 38
26-Dec-2017 10:47:24.269 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Sending command 'MVL' with value '26' to Onkyo Receiver @10.5.1.11:60128
26-Dec-2017 10:47:24.269 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=MVL, value=26] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:47:24.269 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 4953435000000010000000080100000021314D564C32360D -> ISCP[00][00][00][10][00][00][00][08][01][00][00][00]!1MVL26[CR]
26-Dec-2017 10:47:24.269 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 24 bytes: 4953435000000010000000080100000021314D564C32360D
26-Dec-2017 10:47:24.341 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:47:24.341 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C32361A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL26[EOF][CR][LF]
26-Dec-2017 10:47:24.341 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:47:24.341 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=MVL, value=26]
26-Dec-2017 10:47:24.341 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command VOLUME
26-Dec-2017 10:47:24.341 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C32361A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL26[EOF][CR][LF]
26-Dec-2017 10:47:24.341 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '26' to openHAB state '38' (class org.eclipse.smarthome.core.library.types.PercentType)
26-Dec-2017 10:47:40.221 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:47:40.221 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=63997])
26-Dec-2017 10:47:40.221 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:47:40.221 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:47:40.290 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:47:40.291 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:47:40.291 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:47:40.291 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:47:40.291 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:47:40.291 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:47:40.291 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:47:42.707 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:47:42.707 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:47:42.707 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:47:42.707 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:47:42.770 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:47:42.770 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:47:42.770 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:47:42.770 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:47:42.770 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:47:42.770 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:47:42.771 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:48:12.444 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.123:60128
26-Dec-2017 10:48:12.444 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.123:60128 (Socket[unconnected])
26-Dec-2017 10:48:17.445 [ERROR] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out
26-Dec-2017 10:48:40.222 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:48:40.222 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=63997])
26-Dec-2017 10:48:40.222 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:48:40.222 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:48:40.279 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:48:40.279 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:48:40.279 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:48:40.279 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:48:40.279 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:48:40.279 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:48:40.279 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:48:42.708 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:48:42.708 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:48:42.708 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:48:42.708 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:48:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:48:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:48:42.777 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:48:42.777 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:48:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:48:42.777 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:48:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:49:12.444 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.123:60128
26-Dec-2017 10:49:12.444 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.123:60128 (Socket[unconnected])
26-Dec-2017 10:49:17.444 [ERROR] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out
26-Dec-2017 10:49:40.222 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:49:40.222 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=63997])
26-Dec-2017 10:49:40.222 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:49:40.222 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:49:40.291 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:49:40.291 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:49:40.291 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:49:40.291 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:49:40.291 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:49:40.291 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:49:40.291 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:49:42.709 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:49:42.709 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:49:42.709 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:49:42.709 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:49:42.772 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:49:42.772 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:49:42.772 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:49:42.772 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:49:42.772 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:49:42.772 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:49:42.773 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:50:12.445 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.123:60128
26-Dec-2017 10:50:12.445 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.123:60128 (Socket[unconnected])
26-Dec-2017 10:50:17.445 [ERROR] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out
26-Dec-2017 10:50:40.223 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:50:40.223 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=63997])
26-Dec-2017 10:50:40.223 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:50:40.223 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:50:40.292 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:50:40.293 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:50:40.293 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:50:40.293 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:50:40.293 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:50:40.293 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:50:40.293 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:50:42.709 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:50:42.709 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:50:42.709 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:50:42.709 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:50:42.776 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:50:42.776 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:50:42.776 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:50:42.776 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:50:42.776 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:50:42.776 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:50:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:51:12.445 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.123:60128
26-Dec-2017 10:51:12.445 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.123:60128 (Socket[unconnected])
26-Dec-2017 10:51:17.446 [ERROR] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Can't connect: connect timed out
26-Dec-2017 10:51:40.224 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:51:40.224 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=63997])
26-Dec-2017 10:51:40.224 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:51:40.224 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:51:40.298 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:51:40.298 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:51:40.298 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:51:40.298 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:51:40.298 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:51:40.298 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:51:40.298 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:51:42.710 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:51:42.710 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:51:42.710 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:51:42.710 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
26-Dec-2017 10:51:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:51:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:51:42.777 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:51:42.777 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:51:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:51:42.777 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:51:42.778 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]

For reference these are my items:

Switch OnkyoPower "Onkyo Power" {channel="onkyo:onkyoUnsupported:46b0ff21-xxxx-xxxx-5cf6-21098bb9823b:zone1#power"}
Dimmer OnkyoVolume "Onkyo Volume [%d]" {channel="onkyo:onkyoUnsupported:46b0ff21-xxxx-xxxx-5cf6-21098bb9823b:zone1#volume"}
Number OnkyoInput "AVR Input  [%s]" {channel="onkyo:onkyoUnsupported:46b0ff21-xxxx-xxxx-5cf6-21098bb9823b:zone1#input"}

pauli_anttila · December 26, 2017, 5:34pm

It seems that you have two simultaneous connections to Onkyo receiver. From local port 63997 and 64356.

First client test connection:

26-Dec-2017 10:50:40.223 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:50:40.223 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=63997])
26-Dec-2017 10:50:40.223 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:50:40.223 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D

Both clients receive response:

26-Dec-2017 10:50:40.292 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:50:40.293 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:50:40.293 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:50:40.293 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:50:40.293 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:50:40.293 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:50:40.293 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)

Another client test connection after 2 seconds:

26-Dec-2017 10:50:42.709 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Test connection to 10.5.1.11:60128
26-Dec-2017 10:50:42.709 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])
26-Dec-2017 10:50:42.709 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
26-Dec-2017 10:50:42.709 [TRACE] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D

Both client receive response:

26-Dec-2017 10:50:42.776 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:50:42.776 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]
26-Dec-2017 10:50:42.776 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received status update from Onkyo Receiver @10.5.1.11:60128: data=[command=PWR, value=01]
26-Dec-2017 10:50:42.776 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Received command POWER
26-Dec-2017 10:50:42.776 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
26-Dec-2017 10:50:42.776 [DEBUG] [org.openhab.binding.onkyo.handler.OnkyoHandler    ] - Converted data '01' to openHAB state 'ON' (class org.eclipse.smarthome.core.library.types.OnOffType)
26-Dec-2017 10:50:42.777 [TRACE] [openhab.binding.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230311A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR01[EOF][CR][LF]

I have no clue why there are two simultaneous connections, but it seems that cause the problem as some times another client is not able to connect to the receiver and log error message.

This is how the log should look like (my logs):

2017-12-26 19:16:21.053 [DEBUG] [nding.onkyo.internal.OnkyoConnection] - Test connection to 192.168.30.21:60128
2017-12-26 19:16:21.059 [DEBUG] [nding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 192.168.30.21:60128 (Socket[addr=/192.168.30.21,port=60128,localport=46674])
2017-12-26 19:16:21.060 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
2017-12-26 19:16:21.060 [TRACE] [nding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
2017-12-26 19:16:21.124 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
2017-12-26 19:16:21.125 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230301A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR00[EOF][CR][LF]
2017-12-26 19:16:21.125 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.30.21:60128: data=[command=PWR, value=00]
2017-12-26 19:16:21.126 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command POWER
2017-12-26 19:16:21.126 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '00' to openHAB state 'OFF' (class org.eclipse.smarthome.core.library.types.OnOffType)

2017-12-26 19:17:21.053 [DEBUG] [nding.onkyo.internal.OnkyoConnection] - Test connection to 192.168.30.21:60128
2017-12-26 19:17:21.053 [DEBUG] [nding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 192.168.30.21:60128 (Socket[addr=/192.168.30.21,port=60128,localport=46674])
2017-12-26 19:17:21.054 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
2017-12-26 19:17:21.054 [TRACE] [nding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
2017-12-26 19:17:21.111 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
2017-12-26 19:17:21.111 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230301A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR00[EOF][CR][LF]
2017-12-26 19:17:21.112 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.30.21:60128: data=[command=PWR, value=00]
2017-12-26 19:17:21.113 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command POWER
2017-12-26 19:17:21.114 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '00' to openHAB state 'OFF' (class org.eclipse.smarthome.core.library.types.OnOffType)

2017-12-26 19:18:21.053 [DEBUG] [nding.onkyo.internal.OnkyoConnection] - Test connection to 192.168.30.21:60128
2017-12-26 19:18:21.053 [DEBUG] [nding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 192.168.30.21:60128 (Socket[addr=/192.168.30.21,port=60128,localport=46674])
2017-12-26 19:18:21.054 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 49534350000000100000000A0100000021315057525153544E0D -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWRQSTN[CR]
2017-12-26 19:18:21.054 [TRACE] [nding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
2017-12-26 19:18:21.120 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
2017-12-26 19:18:21.121 [TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A01000000213150575230301A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1PWR00[EOF][CR][LF]
2017-12-26 19:18:21.122 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.30.21:60128: data=[command=PWR, value=00]
2017-12-26 19:18:21.122 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command POWER
2017-12-26 19:18:21.123 [DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '00' to openHAB state 'OFF' (class org.eclipse.smarthome.core.library.types.OnOffType)

KidSquid · December 26, 2017, 5:59pm

@pauli_anttila

Are you sure that is what you’re seeing??

If I look through the logging I see the other port you mention but only as a local port, I see other ports mentioned as well. All outbound traffic seems to happen on the same port. 60128

26-Dec-2017 11:53:40.268 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=63997])

26-Dec-2017 11:53:42.754 [DEBUG] [org.openhab.binding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 10.5.1.11:60128 (Socket[addr=/10.5.1.11,port=60128,localport=64356])

pauli_anttila · December 26, 2017, 6:06pm

Are you sure that is what you’re seeing??

Yes, port 60128 is remote port (Onkyo receiver) and local port is client’s port (Onkyo binding).

KidSquid · December 26, 2017, 6:11pm

@pauli_anttila

Weird…

I have doubled checked and their is only one instance of the ONKYO binding, and I have only one thing. I wonder where the other connection could be coming from?

pauli_anttila · December 27, 2017, 4:45pm

@KidSquid, have you restarted the Onkyo binding (or OH) to see if there is only one connection?

KidSquid · December 27, 2017, 10:06pm

I restarted the binding and can still see the timeouts…

What’s strange is that I’m seeing lots of ports now where you stated I should only see one…

jwiseman · September 7, 2018, 11:02pm

Help please . . .

I’ve been running the Onyko binding for 4 months and I really want to resolve this continuous error in my logs.

I have 2 Onkyo’s and I only use them to detect if power is on or not; very basic.

[nding.onkyo.internal.OnkyoConnection] - Error occurred when sending command: Broken pipe (Write failed)
2018-09-07 17:40:31.101 [WARN ] [nding.onkyo.internal.OnkyoConnection] - Error occurred when sending command: Broken pipe (Write failed)
2018-09-07 17:42:31.112 [WARN ] [nding.onkyo.internal.OnkyoConnection] - Error occurred when sending command: Broken pipe (Write failed)
2018-09-07 17:45:31.134 [WARN ] [nding.onkyo.internal.OnkyoConnection] - Error occurred when sending command: Broken pipe (Write failed)
2018-09-07 17:47:31.142 [WARN ] [nding.onkyo.internal.OnkyoConnection] - Error occurred when sending command: Broken pipe (Write failed)
2018-09-07 17:49:01.152 [WARN ] [nding.onkyo.internal.OnkyoConnection] - Error occurred when sending command: Broken pipe (Write failed)
2018-09-07 17:50:31.163 [WARN ] [nding.onkyo.internal.OnkyoConnection] - Error occurred when sending command: Broken pipe (Write failed)
2018-09-07 17:52:31.172 [WARN ]

Does anybody have a new build of the binding that I can get the JAR from you?

I’m running the version 2.3 on a Synology.

Best, Jay

KidSquid · September 8, 2018, 1:11am

I ended up suppressing the error messages as they were filling my logs like yours. This was my last option and unfortunately no others were presented.

I never was able to find any suggestions after posting here and on Git.

Please let me know if you discover a solution.

Squid