[onkyo] changing volume does not work after some time

Tags: #<Tag:0x00007f1867aee378>

The last few days I had problems that openhab was not able to change the volume of my onky avr (Main and Zone2).

I found out that restarting the avr solves the problem temporary.

To produce some meaningfull logs I did the following:

  • openhab> smarthome:send avr1Z1_Volume 30
  • openhab> smarthome:send avr1Z1_Volume 20
  • increase Volume via remote
  • increase Volume via remote once more

This is the og when it dod not work:

[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - handleCommand for channel zone1#volume: 30
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Sending command 'MVL' with value '1E' to Onkyo Receiver @192.168.1.31:60128
[DEBUG] [nding.onkyo.internal.OnkyoConnection] - Send command: [command=MVL, value=1E] to 192.168.1.31:60128 (Socket[addr=/192.168.1.31,port=60128,localport=35320])
[ItemCommandEvent          ] - Item 'avr1Z1_Volume' received command 30
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 4953435000000010000000080100000021314D564C31450D -> ISCP[00][00][00][10][00][00][00][08][01][00][00][00]!1MVL1E[CR]
[TRACE] [nding.onkyo.internal.OnkyoConnection] - Sending 24 bytes: 4953435000000010000000080100000021314D564C31450D
[ItemStateChangedEvent     ] - avr1Z1_Volume changed from 36 to 30
[DEBUG] [nding.onkyo.internal.OnkyoConnection] - Test connection to 192.168.1.31:60128
[DEBUG] [nding.onkyo.internal.OnkyoConnection] - Send command: [command=PWR, value=QSTN] to 192.168.1.31:60128 (Socket[addr=/192.168.1.31,port=60128,localport=35320])
[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]
[TRACE] [nding.onkyo.internal.OnkyoConnection] - Sending 26 bytes: 49534350000000100000000A0100000021315057525153544E0D
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - handleCommand for channel zone1#volume: 20
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Sending command 'MVL' with value '14' to Onkyo Receiver @192.168.1.31:60128
[DEBUG] [nding.onkyo.internal.OnkyoConnection] - Send command: [command=MVL, value=14] to 192.168.1.31:60128 (Socket[addr=/192.168.1.31,port=60128,localport=35320])
[ItemCommandEvent          ] - Item 'avr1Z1_Volume' received command 20
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 4953435000000010000000080100000021314D564C31340D -> ISCP[00][00][00][10][00][00][00][08][01][00][00][00]!1MVL14[CR]
[TRACE] [nding.onkyo.internal.OnkyoConnection] - Sending 24 bytes: 4953435000000010000000080100000021314D564C31340D
[ItemStateChangedEvent     ] - avr1Z1_Volume changed from 30 to 20
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C32351A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL25[EOF][CR][LF]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.1.31:60128: data=[command=MVL, value=25]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command VOLUME
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '25' to openHAB state '37' (class org.eclipse.smarthome.core.library.types.PercentType)
[ItemStateChangedEvent     ] - avr1Z1_Volume changed from 20 to 37
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
[TRACE] [g.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]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.1.31:60128: data=[command=MVL, value=26]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command VOLUME
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '26' to openHAB state '38' (class org.eclipse.smarthome.core.library.types.PercentType)
[ItemStateChangedEvent     ] - avr1Z1_Volume changed from 37 to 38

This is the log after restarting the device - it worked:

[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - handleCommand for channel zone1#volume: 30
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Sending command 'MVL' with value '1E' to Onkyo Receiver @192.168.1.31:60128
[DEBUG] [nding.onkyo.internal.OnkyoConnection] - Send command: [command=MVL, value=1E] to 192.168.1.31:60128 (Socket[addr=/192.168.1.31,port=60128,localport=43982])
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 4953435000000010000000080100000021314D564C31450D -> ISCP[00][00][00][10][00][00][00][08][01][00][00][00]!1MVL1E[CR]
[TRACE] [nding.onkyo.internal.OnkyoConnection] - Sending 24 bytes: 4953435000000010000000080100000021314D564C31450D
[ItemCommandEvent          ] - Item 'avr1Z1_Volume' received command 30
[ItemStateChangedEvent     ] - avr1Z1_Volume changed from 38 to 30
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C31451A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL1E[EOF][CR][LF]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.1.31:60128: data=[command=MVL, value=1E]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command VOLUME
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '1E' to openHAB state '30' (class org.eclipse.smarthome.core.library.types.PercentType)
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - handleCommand for channel zone1#volume: 20
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Sending command 'MVL' with value '14' to Onkyo Receiver @192.168.1.31:60128
[DEBUG] [nding.onkyo.internal.OnkyoConnection] - Send command: [command=MVL, value=14] to 192.168.1.31:60128 (Socket[addr=/192.168.1.31,port=60128,localport=43982])
[ItemCommandEvent          ] - Item 'avr1Z1_Volume' received command 20
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Created eISCP message: 4953435000000010000000080100000021314D564C31340D -> ISCP[00][00][00][10][00][00][00][08][01][00][00][00]!1MVL14[CR]
[TRACE] [nding.onkyo.internal.OnkyoConnection] - Sending 24 bytes: 4953435000000010000000080100000021314D564C31340D
[ItemStateChangedEvent     ] - avr1Z1_Volume changed from 30 to 20
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C31341A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL14[EOF][CR][LF]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.1.31:60128: data=[command=MVL, value=14]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command VOLUME
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '14' to openHAB state '20' (class org.eclipse.smarthome.core.library.types.PercentType)
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C31351A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL15[EOF][CR][LF]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.1.31:60128: data=[command=MVL, value=15]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command VOLUME
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '15' to openHAB state '21' (class org.eclipse.smarthome.core.library.types.PercentType)
[ItemStateChangedEvent     ] - avr1Z1_Volume changed from 20 to 21
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Data size: 10
[TRACE] [g.onkyo.internal.eiscp.EiscpProtocol] - Received eISCP message, 49534350000000100000000A0100000021314D564C31361A0D0A -> ISCP[00][00][00][10][00][00][00][LF][01][00][00][00]!1MVL16[EOF][CR][LF]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received status update from Onkyo Receiver @192.168.1.31:60128: data=[command=MVL, value=16]
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Received command VOLUME
[DEBUG] [b.binding.onkyo.handler.OnkyoHandler] - Converted data '16' to openHAB state '22' (class org.eclipse.smarthome.core.library.types.PercentType)

I don’t know if the problem is with the device or with the binding.
But the device was not updated.
Openhab (and therefore the binding) was updated in the past weeks to version 2.1.
I am using the slightly updated version of the binding from @pauli_anttila
(see: [onkyo] issues with volumes states since OH2.1)

Any idea what is causing this or how I can investigate it further?

1 Like

Did you ever find a solution for this problem? I’m having similar problems with my TX-NR818. After a restart of the AVR I can connect the Openhab addon and also with the official Android app. After some time I cannot connect using the official app any more, but Openhab is still connected and can also control the receiver.

In this state I tried to connect using a telnet terminal to the port of the receiver and that still worked. I also got the updates from the volume etc. But when I tried to send commands (e.g. with the Python onkyo-eiscp addon ) I got a timeout error. After a restart of the AVR it worked without problems. It’s almost as after some time only read only connections can be made.

Then I also have the problem that sometimes even Openhab with it’s constant connection looses the connection to the AVR completely and doesn’t receive updates from the receiver anymore.

1 Like

I “solved” it by updateing openHAB and/or migration to a new system.
At least I have no problems since a few month.

see: https://github.com/openhab/openhab2-addons/issues/2482#issuecomment-439511823

Ok, I guess I have a different problem then. I just tested this with a tcp console. I was able to connect to the port and I was also able send the command, but there was simply no response from the AVR. I also stopped the Openhab onkyo addon and tried it again with the console application and still no answer from the AVR. I started the addon again and it was able to change the volume. Only after I disconnected the AVR completely from power and connected it again I was able to send the command with the console application received the answer from the AVR.

Maybe this is a problem with my TX-NR818 receiver. Which Onkyo model do you have? And can you now connect the official Android app every time even when Openhab is running for a few days? And do you also use the HDMI passthrough function where the receiver passes through the HDMI signal even when it is in standby mode?

I have a TX-NR626.

The Android App works fine, when I use it.

I think I am using passthrough.
But I am not sure and I cannot check this at the moment.

It seams that both our receivers are from the same year and they both got the last firmware update in 2015 on the same day. Did you also update your receiver to the latest firmware? (In your case version 1091-5110-0000-0302)

I also did some more tests in the meantime. I wrote a litte test script that tries to connect to the receiver every 5 minutes and tries to get the power setting. The script did run for 48 hours without any problems, then just after the 48 hours the timeout started to appear in the log.

I’ve restarted the receiver again and now I’am running this test a second time to see if the problem occurs again after 48 hours. After that I will add a rule to Openhab that will disable the Onkyo Thing once per day for 5 minutes. Maybe the recevier has a problem when a connection is open for more than 48 hours. And it is simply the only thing I can think of that I could try to solve this problem. (Besides making a rule to power off the receiver automatically every day)

1 Like

Sometimes the issue occured multiple times per day for me.

see: https://github.com/openhab/openhab2-addons/issues/2482#issuecomment-396035724

I have one also; I’m running the last firmware update for the unit also.

I’m running OH 2.3 and I even tried the Onkyo bindings v2.4 and v2.5 and its still not working consistently.

All I care about is the power state functions of it so I can turn off Sonos in the room.

Best, Jay

I have the same problem with my Onkyo TX NR818 with the latest firmware
1141-4104-0201-0000 (24-09-2015). After a day or two the receiver isn’t controllable anymore via OpenHAB, the official Onkyo Remote App or via IR remote control - only unplugging makes everything work again. Perhaps some sort of timing problem or too many commands in a specific period overload the network interface of the receiver. But that is just guessing. I am running OpenHAB on a Rasperry 4 with official Docker image 2.5m4. Had the problem since i switched to the new binding 2. Some have fixed the problem by using a more powerful hardware. But i upgraded from a Raspberry 3 to 4 and still have the problem.
Has anybody a solution?

I never found a solution for this problem besides unplugging the power from the receiver. I also upgraded to Rasperry Pi 4 and still got the problem. I tried to find out if the problem occurs on specific actions or after a certain runtime, but it seems to be completely random. I guess this is an issue of the Onkyo firmware and sadly there are no more updates and without any source code of the firmware I also see no other option than to replace the whole receiver with a newer one and hope that this one doesn’t have this problem.