core: denon integration broken

I found the issue, 2016 models have the DeviceInfo xml also avialable in port 80 but after few days the file is gone and available only in the port of 2016 models which is 8080,.

the fix is to try to connect first on 2016 models and if there’s 404 error move to the older port, in addition, error should be thrown only when all models (2) checked and not on the first

I checked my fix with 2 receivers AVR-X2700 (2016) and AVR-X5200 which is bit older, works perfect.

Need to submit PR and hopefully we will have it soon.

About 16 hours in running @JPHutchins’s concurrency test script with 50 workers at 5% packet loss and 100 ms RTT latency:

550922 200
 14534 Exception: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))
 12452 Exception: ("Connection broken: ConnectionResetError(54, 'Connection reset by peer')", ConnectionResetError(54, 'Connection reset by peer'))
    72 Exception: 
    23 Exception: ('Connection aborted.', UnknownProtocol('HTTP/0.0'))

A total of ~27k exceptions – a 4.7% failure rate. It’s pretty clear the AVR doesn’t handle packet loss well.

To find out how relevant this may be, how many of you are running wired vs wireless network connections on your AVR? (click or tap the option that applies to your AVR to vote)

Sorry for the slow process! 2020.12.2 includes denonavr 0.9.8 which we had hoped would resolve these issues. It does resolve the issue for people getting the “audyssey problem”.
denonavr is now on 0.9.9 https://github.com/scarface-4711/denonavr/releases/tag/0.9.9 which reverts to serial instead of parallel API calls - it is our hope that this gets us back to the stability we enjoyed prior to November.

It would be nice to be able to test - I am not sure how to manually bump the denonavr requirement to 0.9.9 but you can see the changes that we make to bump version here: https://github.com/home-assistant/core/pull/44194/files

After 2 weeks, I finally experienced another failure of the integration while restarting Home Assistant and had been capturing packets at the time. Initial analysis points at the integration as the trigger for the AVR failing, for two reasons: 1) since all requests made by the integration except the final round prior to until restarting HA were successful, and 2) the final round of requests was terminated by the integration (TCP FIN) before receiving a response, which seems to have put the web server on port 8080 in a bad state (wireshark was failing to correctly reassemble packets, for a yet unknown reason, that made it appear as though there was no response to some of the final connections until reassembly was disabled).

Prior to restarting, the integration was making a burst of 6 requests every 10 seconds, all resulting in 200 OKs. Comparing the final round of requests that failed against the penultimate round that succeeded didn’t yield any obvious difference.

After HA restarted, the integration was unable to successfully complete requests against port 8080, and began POSTing on port 80 instead. Presumably, this is due to a failure of the model detection logic in denonavr that depends on successfully retrieving “/goform/Deviceinfo.xml” on port 8080, which it couldn’t.

At this point, restarting the AVR alone was insufficient – the integration continued to use port 80 in error. I also had to restart HA to force the integration to reattempt model detection (reloading the integration likely would have had the same outcome).

The update will be included in HA 2021.5 which should be available soon. Waiting for it would be the easy way of testing.

@imregmelig keep us posted, please; both about Denon’s replies and if your AVR manifests the issue again, even on the factory firmware.

When the issue manifests for me again, I’ll be sure and run the debug procedure in your post and open an incident with Denon.

My HA integration has been running smoothly and with 0 errors in the log, since I restored to stock Denon firmware 😃

I have made the jump and restored the firmware on my Denon AVR-X1600H DAB per Denon’s post and @masterfink’s steps in the HA community. Only had to reprogram my DAB radio tuner presets, but uploading USB backup went smoothly.

I can confirm this is a suitable workaround for now, for my type of receiver, with no apparent shortcomings of missing out on a newer firmware. Connectivity is as it was before and no error flood.

The official Denon AVR 2016 app makes multiple requests for updated state every 1 second based on my packet sniffing. I am not aware that the telnet protocol pushes state Connected via telnet now and see state push - the denon (rather than denonavr) integration uses telnet. This would be huge since we have documentation that can be parsed to generate every possible telnet command. Since it’s telnet I would like to add some QoS. I will be modeling the schema of this library: https://github.com/andrewsayre/pyheos

To their credit, Denon does do a good job of maintaining backwards compatibility.

Not sure if it is related but my Denon keeps on filling the logfile with 403 errors. The solution in the other two mentioned issues, power cycle and reinstall integration, works only temporary for me.

I met with the same issue. It worked well without any problem until about one week ago. I have tried to delete and re-install the integration, re-power the amplifier, etc… It just stops working after a period of time.

There is also the same issue with my Epson projector and Vacuum. It seems that all devices added via IP address won’t work correctly now.

@imregmelig keep us posted, please; both about Denon’s replies and if your AVR manifests the issue again, even on the factory firmware.

When the issue manifests for me again, I’ll be sure and run the debug procedure in your post and open an incident with Denon.

@DevSecNinja As a matter of fact I have, just this morning.

Here’s their response, which state they need logfiles through the Heos app, when the problem occurs.

The incident was reported to our engineers, however, we do need log files to find out what is going on.

When the problem occurs, immediately note the time on the smartphone / tablet. Immediately after this, open the HEOS app and go to: settings> help> report a problem. In the description you must enter a clear and concise problem description. Also state here the noted time and this reference number: 201224-000505

The speaker LEDs will flash purple while the log files are being uploaded. As soon as we have received the files on our server, we will notify you and forward the log files to our development department in Japan where the files will be read. It may take a few weeks until we have received an advice.

I am happy with the firmware rollback for now and I don’t plan on updating again at this moment. Feel free to use my incident number 201224-000505 if you can.

Ah sorry, I missed that in your message.

Happy New Year, everyone.

I thought I’d share something in the HA community forum pointed out: for those that don’t need to turn the AVR on from HA, setting the AVR to turn Network Control off when in Standby should make the web control API engine restart every time the AVR turns on. Might be a nice workaround to deal with the issue we’ve been debating.

We’re still trying to manually trigger the errors BTW - if anyone wants to futz around here is a script where we are attempting to prove that parallel requests were the problem in the first place (no success proving this so far). Note that on my receiver GET and POST work and GET causes more problems

import requests
from concurrent.futures import ThreadPoolExecutor
from datetime import datetime

HOST = "192.168.0.119"

print("Running")

def make_xml_request(commands: list) -> bytes:
        """Prepare XML body for Denon API."""
        xml_parts = ['<?xml version="1.0" encoding="utf-8"?>\n', "<tx>"]
        cmd_l = '<cmd id="1">'
        cmd_r = "</cmd>"
        for i, command in enumerate(commands):
            if i != 0 and i % 5 == 0:
                # API allows multiple XML roots, limit 5 commands each
                xml_parts.append("</tx><tx>")
            xml_parts.append(f"{cmd_l}{command}{cmd_r}")
        xml_parts.append("</tx>")
        return "".join(xml_parts).encode()

xml = make_xml_request(["GetRenameSource", "GetDeletedSource"])

def r1():
    return requests.get(f"http://{HOST}:8080/goform/Deviceinfo.xml").status_code

def r1a():
    return requests.get(f"http://{HOST}:80/description.xml")

def r1b():
    return requests.get(f"http://{HOST}:60006/upnp/desc/aios_device/aios_device.xml").status_code

def r2(xml):
    # print(datetime.utcnow())
    return requests.get(f"http://{HOST}:8080/goform/AppCommand.xml", data=xml, headers = {'Content-Type': 'application/xml'})

e = ThreadPoolExecutor(max_workers=50)
out = []
for _ in range(100):
    out.append(e.submit(r1))
    out.append(e.submit(r1b))
    e.submit(r2, xml)
    # out.append(e.submit(r2, xml))
    # out.append(e.submit(r2, xml))

for resp in out:
    print((resp.result(timeout=5)))

I was not able to trigger it sending out sequences of 2,000 updates (which includes all 6 requests) with 50 in parallel. And this was repeated 50 times over a few hours never getting the receiver into the “locked” state. I was able to observe the endpoints taking longer to reply (up to 3 seconds).

@doug-hoffman and @JPHutchins

While you’re going down this rabbit hole, something I’ve found and that might make recovering from the problem slightly more user-friendly: instead of power-cycling the AVR, just put it to standby and then press and hold the standby button until “Restart” shows up on the display. There might even be an alternative to reloading the integration after that, but I still have to make sure it’s actually a thing.

@JPHutchins I only ever saw 6 requests within a second over the several days I captured, and even in the final round before the restart. Actually, the final round was sent in two chunks – 3 requests, followed by a 10 second gap, followed by 3 requests. None of the final 6 requests got a response from the AVR.

requests is executed every 10 seconds

Wow that sounds like a pretty aggressive polling. Denon receivers also have telnet protocol that pushes all events in real time. Maybe addon could be migrated to this? I will have some more free time after a week or so, I can help with the migration then if you want.

Just chiming in: same issues here, but probably due to mid-November Denon firmware update.

It has broken not only the HA integration, but Denon’s own AVR Remote app. When this bug kicks in, the app also becomes unable to connect to the AVR.

Same issue with Denon X3500H. Firmware Version | 2600-8113-8161-3085

I’d be happy to help test things or submitting bugs at Denon, as it seems to me that their update caused these issues. Unfortunately I don’t know what exactly to tell them other than “I think you guys broke the Home Assistant integration!”. 😃

(If their official app development reflects the firmware we might need a lot of patience though)

Same here on my new Denon X3700H. Also hard to say if it happened after a Home Assistant update or firmware upgrade of Denon, but like @DanielNL tested: it’s probably a change on Denon’s side…

2020-12-07 17:45:49 WARNING (MainThread) [homeassistant.components.media_player] Updating denonavr media_player took longer than the scheduled update interval 0:00:10
2020-12-07 17:45:49 ERROR (ThreadPoolExecutor-236143_0) [DenonAVR] No connection to /goform/AppCommand.xml end point on host 192.168.0.20
2020-12-07 17:45:49 ERROR (SyncWorker_21) [DenonAVR] Update failed.
2020-12-07 17:45:49 ERROR (ThreadPoolExecutor-236143_1) [DenonAVR] No connection to /goform/AppCommand.xml end point on host 192.168.0.20
2020-12-07 17:45:49 ERROR (ThreadPoolExecutor-236143_1) [DenonAVR] Getting tone control failed.

In more information is needed, I’m happy to provide.

Same issues here, started after updating from 0.116.4 to 0.118.5. Checked the firmware on my Denon AVR-S950H and it has been auto updated to a version from mid november.

First visible error in my log:

During DenonAVR device identification, when trying to request http://192.168.1.20:8080/description.xml the following error occurred: HTTPConnectionPool(host='192.168.1.20', port=8080): Read timed out. (read timeout=2)

After which i get the same errors as already stated.

Edit:

I just downgraded HA to 0.116.4 through a snapshot i had and the problem persisted. I guess the cause lies with the firmware upgrade on the receiver.

Did a reset last Sunday and it worked without a problem the whole week until I just now restarted HA after updating to 0.118.5 It’s 403 all over again on several xml files. Web interface of the receiver is functioning in a browser though.

Yes same here again. Has been working for 5 days straight, but this morning started throwing errors again:

2020-12-05 11:44:07 ERROR (ThreadPoolExecutor-130115_1) [DenonAVR] No connection to /goform/AppCommand.xml end point on host 192.168.1.XX
2020-12-05 11:44:07 ERROR (ThreadPoolExecutor-130115_1) [DenonAVR] Getting tone control failed.

Removed power of receiver and put back after 1 minute or so, working again. Didn’t need to remove integration or restart Home Assistant.

Guess I’ll just put one of my energy plugs behind it and switch it off every night for a minute, until it’s fixed.

I have a Denon avr-x2700h and can confirm that the power-cycle method solves the issue only temporarily. On very random moments, it loses connection and the log is flooded with errors. A notable error is:

No connection to /goform/AppCommand.xml end point on host 192.168.1.11

The receiver is reachable using the regular web-interface.

I have also mentioned this, including a couple of others in the community forum: link.

I am on the latest Home-Assistant (0.118.4) in Docker on a NUC.

I found a github issue that mentions Appcommand.xml but I am not yet sure if that merge is included in the latest release: issue

+1

Yeah, receiver reboot is only a temporary fix. Issue comes back after couple of days.

Are there any known workarounds that do not involve physical access to the receiver? So I could set up an automation to reset the integration or something every couple of days.

Note to developers of the integration: other Denon protocol that emulates RS-232 over ethernet seems to still work fine, so maybe addon could be transitioned to that?

I have Denon 3600h and it’s not working too… When I unplug and plug back the AVR it goes back to work but after couple of days it gets off.

Any suggestions?

For me it has been working on and off for the last week, I still have yet to find why this is happening, at first I thought it was due to using the HEOS integration, and too many connections being open at the same time (2 android devices and an iOS device using the HEOS app and then Home Assistant as well), but so far I can’t seem to replicate it…

I’m not sure what the correct sequence is, but I definitely removed the integration, power off for 5 minutes, power on, restart home assistant and added integration again.

It’s now working fine for over 2 days, let’s hope it stays this way.

I’m seeing this on a X8500H with firmware 7000-6144-5161-3085 and HA 0.118.2:

2020-11-30 14:57:39 ERROR (SyncWorker_0) [DenonAVR] Host 192.168.123.45 returned HTTP status code 403 to POST command at end point /goform/AppCommand.xml
2020-11-30 14:57:39 ERROR (SyncWorker_0) [DenonAVR] Getting renamed and deleted sources failed.
2020-11-30 14:57:39 ERROR (SyncWorker_0) [DenonAVR] Host 192.168.123.45 returned HTTP status code 403 to GET request at end point /goform/formMainZone_MainZoneXml.xml
2020-11-30 14:57:39 ERROR (ThreadPoolExecutor-1_1) [DenonAVR] Host 192.168.123.45 returned HTTP status code 403 to GET request at end point /goform/formMainZone_MainZoneXml.xml
2020-11-30 14:57:39 ERROR (ThreadPoolExecutor-2_0) [DenonAVR] Host 192.168.123.45 returned HTTP status code 403 to GET request at end point /goform/formMainZone_MainZoneXmlStatus.xml
2020-11-30 14:57:39 ERROR (ThreadPoolExecutor-2_1) [DenonAVR] Host 192.168.123.45 returned HTTP status code 403 to GET request at end point /goform/formMainZone_MainZoneXml.xml
2020-11-30 14:57:41 ERROR (ThreadPoolExecutor-1_0) [DenonSSDP] During DenonAVR device identification, when trying to request http://192.168.123.45:8080/description.xml the following error occurred: HTTPConnectionPool(host='192.168.123.45', port=8080): Read timed out. (read timeout=2)
2020-11-30 14:57:41 ERROR (ThreadPoolExecutor-1_0) [DenonAVR] Unable to get device information of host 192.168.123.45, can not use the serial number as identification
2020-11-30 14:57:41 ERROR (ThreadPoolExecutor-3_0) [DenonAVR] Host 192.168.123.45 returned HTTP status code 403 to GET request at end point /goform/formMainZone_MainZoneXmlStatus.xml
2020-11-30 14:57:41 ERROR (ThreadPoolExecutor-3_0) [DenonAVR] Host 192.168.123.45 returned HTTP status code 403 to GET request at end point /goform/formMainZone_MainZoneXml.xml
2020-11-30 14:57:41 ERROR (SyncWorker_0) [DenonAVR] Missing status information from XML of Main for: Power, InputFuncSelect, Mute, MasterVolume

Have power cycled probably 5-10 times over the past few weeks, but the problem always comes back. I’ll try to remove the integration, power cycle, then re-configure it, to see if that is any more permanent.

I don’t know why but today I tried to recycle the power and re-install the integration and it worked well this time. I will see how long it could last this time.

Did the unplug twice last week after which control returned but for me it’s only a temporary fix. After some time the 403’s are back again but haven’t found out yet what triggers it. Will try another unplug this weekend, last one was with 0.118.3 and haven’t tried with 0.118.4 yet.

I can confirm this works, after unplug the power and replug this, the control of the receiver returns.

Thanks

Not sure if it is related but my Denon keeps on filling the logfile with 403 errors. The solution in the other two mentioned issues, power cycle and reinstall integration, works only temporary for me.

Yes that’s what I had as well, continues 403, I was already wondering why my automations regarding the receiver weren’t working. Removed power for a few minutes and re-adding to HASS worked for me

Are you sure it’s not like the other issues already posted? Apparently there was a firmware update last week and you need to power cycle your amplifier and remove and re-add the amp to Home Assistant. This worked for me and my X2500. #43049 #43229