Receiver stops communicating with homebridge

[chetstone]

Every week or so, homebridge will say it cannot communicate with the receiver and I have to go unplug the receiver and plug it back in to reset it. I mentioned this in #114 and in that issue I theorized that the problem had to do with either

1) Too frequent polling of the receiver by homebridge. or 2) A problem with HDMI-CEC causing the receiver to become unresponsive to the network.

As you pointed out, polling should not be an issue. I realize now that that is the only way that homebridge can keep the state updated.

I now know that HDMI-CEC is also not the issue. I have turned off all HDMI-CEC functionality in the receiver for several months now and in fact during the month of January all my HDMI-CEC devices were powered off and never used, yet this problem keeps happening.

Here is the relevant lines of the log in debug mode:

[2/3/2022, 8:55:53 PM] [DenonTv] Device: 192.168.1.208 Marantz Main Zone, deviceInfo error: Error: timeout of 5000ms exceeded
    at createError (/opt/homebrew/lib/node_modules/homebridge-denon-tv/node_modules/axios/lib/core/createError.js:16:15)
    at RedirectableRequest.handleRequestTimeout (/opt/homebrew/lib/node_modules/homebridge-denon-tv/node_modules/axios/lib/adapters/http.js:328:16)
    at RedirectableRequest.emit (node:events:390:28)
    at Timeout.<anonymous> (/opt/homebrew/lib/node_modules/homebridge-denon-tv/node_modules/follow-redirects/index.js:164:12)
    at listOnTimeout (node:internal/timers:557:17)
    at processTimers (node:internal/timers:500:7) {
  config: [Object],
  code: 'ECONNABORTED',
  request: [Writable],
  response: undefined,
  isAxiosError: true,
  toJSON: [Function: toJSON]
}, device offline, trying to reconnect
[2/3/2022, 8:55:53 PM] [DenonTv] Device: 192.168.1.208 Marantz Zone 2 Zone 2, deviceInfo error: Error: timeout of 5000ms exceeded
    at createError (/opt/homebrew/lib/node_modules/homebridge-denon-tv/node_modules/axios/lib/core/createError.js:16:15)
    at RedirectableRequest.handleRequestTimeout (/opt/homebrew/lib/node_modules/homebridge-denon-tv/node_modules/axios/lib/adapters/http.js:328:16)
    at RedirectableRequest.emit (node:events:390:28)
    at Timeout.<anonymous> (/opt/homebrew/lib/node_modules/homebridge-denon-tv/node_modules/follow-redirects/index.js:164:12)
    at listOnTimeout (node:internal/timers:557:17)
    at processTimers (node:internal/timers:500:7) {
  config: [Object],
  code: 'ECONNABORTED',
  request: [Writable],
  response: undefined,
  isAxiosError: true,
  toJSON: [Function: toJSON]
}, device offline, trying to reconnect

And my configuration:

{
            "devices": [
                {
                    "name": "Marantz",
                    "host": "192.168.1.208",
                    "port": 8080,
                    "refreshInterval": 5,
                    "zoneControl": 0,
                    "volumeControl": 1,
                    "masterPower": true,
                    "masterVolume": false,
                    "masterMute": true,
                    "switchInfoMenu": false,
                    "disableLogInfo": false,
                    "inputs": [
                        {
                            "name": "Gesar",
                            "reference": "AUX1",
                            "mode": "SI"
                        },
                        {
                            "name": "Computer",
                            "reference": "CD",
                            "mode": "SI"
                        },
                        {
                            "name": "KCSM",
                            "reference": "SMART1",
                            "mode": "MS"
                        },
                        {
                            "name": "Venice Classic",
                            "reference": "SMART2",
                            "mode": "MS"
                        },
                        {
                            "name": "Gesar Stereo",
                            "reference": "SMART3",
                            "mode": "MS"
                        },
                        {
                            "name": "Gesar Neu:X",
                            "reference": "SMART4",
                            "mode": "MS"
                        },
                        {
                            "name": "NET",
                            "reference": "NET",
                            "mode": "SI"
                        },
                        {
                            "name": "BluRay",
                            "reference": "BD",
                            "mode": "SI"
                        },
                        {
                            "name": "Apple TV",
                            "reference": "MPLAY",
                            "mode": "SI"
                        },
                        {
                            "name": "Phono",
                            "reference": "PHONO",
                            "mode": "SI"
                        },
                        {
                            "name": "Bluetooth",
                            "reference": "BT",
                            "mode": "SI"
                        },
                        {
                            "name": "Tuner",
                            "reference": "TUNER",
                            "mode": "SI"
                        }
                    ],
                    "buttonsMainZone": [
                        {
                            "name": "Gesar Stereo",
                            "reference": "MSSMART3"
                        },
                        {
                            "name": "Apple TV",
                            "reference": "SIMPLAY"
                        }
                    ],
                    "manufacturer": "Marantz",
                    "modelName": "NR1711"
                },
                {
                    "name": "Marantz Zone 2",
                    "host": "192.168.1.208",
                    "port": 8080,
                    "refreshInterval": 5,
                    "zoneControl": 1,
                    "volumeControl": 1,
                    "masterPower": false,
                    "masterVolume": false,
                    "masterMute": false,
                    "switchInfoMenu": false,
                    "disableLogInfo": false,
                    "buttonsZone2": [
                        {
                            "name": "SOURCE",
                            "reference": "Z2SOURCE",
                            "mode": "SI"
                        }
                    ],
                    "manufacturer": "Marantz",
                    "modelName": "NR1711"
                }
            ],
            "platform": "DenonTv"
        }

I wonder if this has something to do with my masterPower: true setting?

I use Homebridge mainly to automating turning the receiver on in the morning and turning it off at bedtime. I rarely use my IR remote to control the receiver except for volume-- I try to use homebridge to change inputs and any other functions. I don't use other Denon apps. Just homebridge.

I don't think the network itself is the problem--- the server and receiver are both connected by GB ethernet to the same switch, and power-cycling the receiver reliably fixes the problem (until the next week)

If I could see the moment in the log when the receiver stops responding, that could be a clue, but the log in Debug mode is just too verbose. It fills up the 2MB homebridge log file in less than an hour. Is there any way to turn down the verbosity?

BTW I'm using homebridge-denon-tv v3.12.17 with Homebridge v1.3.4 on on Apple MacMini (M1 chip) running MacOS 11.6.2. The receiver is a Marantz NR1711. I just updated the firmware last week to 3400-0195-8061-3085, hoping that update would fix the problem, but no.

[grzegorz914]

Thanks for report this, first of all please update the plugin to the latest one it’s fixed some network problems and stability. Next please look in readme or config the plugin using GUI because some properties like ‘refreshInterval’, ‘branding’ are not used anymore. Also the min. node.js >=14.0. After this Please test and report back. On my side all working fine without any problem since 1 month.

[chetstone]

Thanks I'll try that. Is there any way to change the logging verbosity? With Homebridge Debug mode off, there is not enough information to tell when there is a problem. But with Debug mode on, there is way too much info. By the time I realize there is a problem, when I go to look at the log, the first instance of the problem has disappeared from the log.

[grzegorz914]

Please use plugin built in debug mode, go to plugin settings Advanced Section >> Enable Debug Mode

[elministerr]

it seems i had the same problem today.. homebridge don't reconize any avr changes until i put the avr off and on via the remote control. I turned now the debug mode on in advanced settings and hope some info appears next time the behavior appears.

[grzegorz914]

I have observed same behavior. Looks like the AVR server stop responding or the network card freezes because in same time also the original app from denon not working. After power cycle ON/OFF all start working fine.

[elministerr]

i think my problem is a other issue. Maybe i open a another issue if i can reproduce the behavior. Today i put on airplay and homebridge don't recgonize my avr activity. the device is grey (off) in homebridge -> devices. But activity are registered in the log:

^[[37m[10/02/2022, 08:48:20] ^[[39m^[[36m[DenonTv]^[[39m Device: Denon-AVR-X1600H.fritz.box Denon AVR, debug: Parse state data: { "item": { "Power": [ { "value": [ "OFF" ] } ], "InputFuncSelect": [ { "value": [ "NET" ] } ], "VolumeDisplay": [ { "value": [ "Relative" ] } ], "MasterVolume": [ { "value": [ "-40.5" ] } ], "Mute": [ { "value": [ "off" ] } ] } } ^[[37m[10/02/2022, 08:48:20] ^[[39m^[[36m[DenonTv]^[[39m Device: Denon-AVR-X1600H.fritz.box Denon AVR, debug: Parse sound mode data: { "rx": { "cmd": [ { "surround": [ "Stereo " ] } ] } }

If try to put the avr on in homebridge -> devices it always send the "POWER value off" signal until i put the AVR via remote control on. After that everthing working fine.

[darkjlz]

I have the exact same problem, my receiver ( Marantz NR 1607 ) is seen disconnected every minute by home bridge (Device state error: Error: timeout of 2000ms exceeded)

[grzegorz914]

Please try latest beta and let me know

[darkjlz]

Doesn't work with homebridge-denon-tv v3.16.11-beta.9 either Now logs are: Device state error: Error: timeout of 2500ms exceeded and Check state error: Error: timeout of 2500ms exceeded. every 2min

[grzegorz914]

Your device do not respond at all, are you set correct IP address and Port?

[darkjlz]

My device icon is on within Home app, disconnects for few seconds and is back again

[2/12/2022, 4:54:25 PM] [homebridge-denon-tv] Device: 192.168.0.170 Ampli, Device state error: Error: timeout of 2500ms exceeded [2/12/2022, 4:54:25 PM] [homebridge-denon-tv] Device: 192.168.0.170 Ampli, Check state error: Error: timeout of 2500ms exceeded. [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] Device: 192.168.0.170 Ampli, Connected. [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] -------- Ampli -------- [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] Manufacturer: Marantz [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] Model: NR1607 [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] Zones: 2 [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] Control: Main Zone [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] Firmware: 00 [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] Api version: 0300 [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] Serialnr: masked [2/12/2022, 4:54:32 PM] [homebridge-denon-tv] ---------------------------------- [2/12/2022, 4:56:54 PM] [homebridge-denon-tv] Device: 192.168.0.170 Ampli, Device state error: Error: timeout of 2500ms exceeded [2/12/2022, 4:56:54 PM] [homebridge-denon-tv] Device: 192.168.0.170 Ampli, Check state error: Error: timeout of 2500ms exceeded. [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] Device: 192.168.0.170 Ampli, Connected. [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] -------- Ampli -------- [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] Manufacturer: Marantz [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] Model: NR1607 [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] Zones: 2 [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] Control: Main Zone [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] Firmware: 00 [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] Api version: 0300 [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] Serialnr: masked [2/12/2022, 4:57:02 PM] [homebridge-denon-tv] ----------------------------------

[darkjlz]

Plugin is working , just disconnecting a few seconds every 2 min

[grzegorz914]

Check your Network connection, try use lan if use wlan?

[darkjlz]

I'll try with ethernet instead of wifi and let you know, thanks !

[grzegorz914]

try latest beta too, I have increased timeout

[darkjlz]

I plugged ethernet instead of wifi: homebridge-denon-tv v3.16.11-beta.13 :works Reverted back to homebridge-denon-tv v3.16.10: works

Looks like this issue is Wlan related since I installed an Unifi AP, sorry for the drill!

[grzegorz914]

OK, thanks for test, try with beta.14 and wifi and let me know,

[darkjlz]

Installed homebridge-denon-tv v3.16.11-beta.14 and wifi After 10min, so far so good, well done !!!

[darkjlz]

Spoke too soon [2/12/2022, 6:28:03 PM] [homebridge-denon-tv] Device: 192.168.0.170 Ampli, Check state error: Error: timeout of 2750ms exceeded. [2/12/2022, 6:28:11 PM] [homebridge-denon-tv] Device: 192.168.0.170 Ampli, Connected.

[grzegorz914]

So, definitely you need check your WiFi.

[darkjlz]

Thank you very much !

[darkjlz]

if this can help others, I think I fixed my problems by disabling " Multicast enhancement" in unifi wireless settings

[grzegorz914]

I close this with 3.16.11

[chetstone]

This is still not fixed. I finally found time to upgrade from 3.15 a few days ago. With 3.16.10 I was seeing the same thing as @darkjlz, except wi-fi is not involved. In my setup everything is connected by ethernet. Upgrading to 3.16.11 helped--- it is no longer disconnecting every two minutes, but it's still happening frequently, seemingly at random, maybe a couple of times per hour on average. When it disconnects, the Marantz tile in the home app changes to say the receiver is off, then after a few seconds it changes to on.

I also experienced a complete loss of connection last night. Although the Home app tile indicated the receiver was on and allowed me to use the controls, they had no effect on the receiver. I had to turn power off and back on with the remote control to reestablish connection (this is an improvement on 3.15 -- I used to have to remove AC power from the receiver for 20 seconds to reset it).

Here is the log info for one of the brief dropouts:

[2/16/2022, 4:05:55 PM] [DenonTv] Device: 192.168.1.208 Marantz, debug: Device state error: Error: timeout of 2750ms exceeded
[2/16/2022, 4:05:55 PM] [Marantz Off] Send notification to Prowl: Marantz Off
[2/16/2022, 4:06:03 PM] [DenonTv] Device: 192.168.1.208 Zone 2, Connected.
[2/16/2022, 4:06:03 PM] [DenonTv] -------- Zone 2 --------
[2/16/2022, 4:06:03 PM] [DenonTv] Manufacturer: Marantz
[2/16/2022, 4:06:03 PM] [DenonTv] Model: NR1711
[2/16/2022, 4:06:03 PM] [DenonTv] Control: Zone 2
[2/16/2022, 4:06:03 PM] [DenonTv] ----------------------------------
[2/16/2022, 4:06:03 PM] [DenonTv] Device: 192.168.1.208 Marantz, debug: Get device info:

[[ 7000 (!!) lines of device info omitted ]]

[2/16/2022, 4:06:03 PM] [DenonTv] Device: 192.168.1.208 Marantz, Connected.
[2/16/2022, 4:06:03 PM] [DenonTv] -------- Marantz --------
[2/16/2022, 4:06:03 PM] [DenonTv] Manufacturer: Marantz
[2/16/2022, 4:06:03 PM] [DenonTv] Model: NR1711
[2/16/2022, 4:06:03 PM] [DenonTv] Zones: 2
[2/16/2022, 4:06:03 PM] [DenonTv] Control: Main Zone
[2/16/2022, 4:06:03 PM] [DenonTv] Firmware: 00
[2/16/2022, 4:06:03 PM] [DenonTv] Api version: 0301
[2/16/2022, 4:06:03 PM] [DenonTv] Serialnr: 00067866BE0C
[2/16/2022, 4:06:03 PM] [DenonTv] ----------------------------------
[2/16/2022, 4:06:06 PM] [DenonTv] Device: 192.168.1.208 Marantz, debug: Parse state data: {
  "item": {
    "Power": [
      {
        "value": [
          "ON"
        ]
      }
    ],
    "InputFuncSelect": [
      {
        "value": [
          "AUX1"
        ]
      }
    ],
    "VolumeDisplay": [
      {
        "value": [
          "Relative"
        ]
      }
    ],
    "MasterVolume": [
      {
        "value": [
          "-24.0"
        ]
      }
    ],
    "Mute": [
      {
        "value": [
          "off"
        ]
      }
    ]
  }
}
[2/16/2022, 4:06:06 PM] [DenonTv] Device: 192.168.1.208 Marantz, debug: Parse sound mode data: {
  "rx": {
    "cmd": [
      {
        "surround": [
          "Stereo                                                         "
        ]
      }
    ]
  }
}
[2/16/2022, 4:06:06 PM] [Marantz On] Send notification to Prowl: Marantz On

The lines [Marantz On] and [Marantz Off] are coming from the homebridge-pushed-notification plugin. I set this up some time ago to try to help with debugging this problem. It sends me a notification on my phone whenever the Marantz turns on or off. As I mentioned, when I get the Marantz Off notification, the Home app tile also indicates the receiver is off.

[grzegorz914]

@chetstone thanks for report this again, this never happened on my side so its difficult to find what is wrong. I think its just Denon/Marantz server side problem. I have pushed 3.16.12-beta.0 for test, please look at this and let mi know.

[badgertastic]

Been noticing the same. Symptoms: Device not responding in Home app. Marantz app and website not responsive or slow.

Tried 3.17 but same.

When I disconnect receiver from network, homebridge-denon-tv no longer reports 'disconnected' and then when network is reconnected it repeatedly logs saying its Connected, looping until eventually homebridge crashes due to too many open files.

I've rolled back to 3.16.5 for now.

[grzegorz914]

@badgertastic fixed in 3.17.1

[chetstone]

@grzegorz914 Thanks so much for your patience and continued support on this issue.

So 3.16.12-beta.0 fixed the problem of frequent brief disconnects, I haven't seen anything for 24 hours.

Not sure if the original problem, where the connection drops completely, is fixed. I'll need to test with this beta for a couple of weeks (or should I upgrade to 3.17.1?)

[grzegorz914]

Please try 3.17.1, here is also integrated MQTT Client which publish all available data from AVR to the MQTT Broker if needed.

[chetstone]

With 3.17.1 the frequent disconnect/reconnect is happening again.

I'm reverting to 3.16.12-beta.0

[grzegorz914]

OK, then try please 3.17.3-beta.0

[chetstone]

Unfortunately 3.17.3-beta.0 still has the problem. I wanted to look at the code to see what you're changing to try to fix this issue, but on Github there are no tags or branches for the beta versions. I guess you're changing the timeout, but probably other things as well.

I wonder if you could expose the timeout as an advanced configuration parameter?

At any rate, since 3.16.12-beta.0 seems to work better and I don't need MQTT, I'm going to switch back to that. I'll let you know if the connection drops completely over the next couple of weeks.

Thanks for your help.

[chetstone]

Looking at the code of the two beta versions as pulled from npm, I see the main differences:

3.16.12-beta.0 has no axios timeout and it has a longer checkState interval: 3000ms

3.17.3-beta.0 has a 5000ms axios timeout and a checkState interval of 1500ms

I guess the checkState interval is the polling refresh interval. Having the axios timeout longer than the refresh interval could result in requests stacking up and the receiver unable to process them fast enough. I would prefer a longer polling interval. Could you add that back into the advanced configuration options?

Also, it looks like b2268b44eabcf7a41fbc78458ca50d95dfc92698 could be the fix for the "connection dropping completely" issue I was having. So if we stop the frequent timing out that should take care of it.

[grzegorz914]

Check state is TimeOut timer, only called if data from AVR is received, can not generate stacking process. If data is not received in 5sec then error is generated and start reconnect Timer. I do not have this problem like You, my Denon AVR 6300 X always response without any error. I think this is local Network environment problem. In 3.16.12-beta.0 was removed the timeout from Axios, but this is not so good solution because after disconnect the AVR from network will no error generated. Please check Your network please, are you use WiFi or Lab connection?

[grzegorz914]

@chetstone please try 3.17.3-beta.9 probably I'm found the bug

[chetstone]

TLDR; After extensive testing with 3.17.3-beta.9 I have concluded that this component is not causing my networking issues. That said, I recommend increasing the axios timeout to 10 seconds and the checkState interval to 3 seconds.

The issues:

1. Frequent brief disconnections and reconnections which started after the axios timeout was added.
2. Occasional (once or twice a month) permanent disconnections which required removing power from the receiver to reset.

Since I am not using wifi, but rather the receiver and server are connected to the same Trendnet TEG-S80g gigabit ethernet switch in my entertainment center, I assumed my network was not the problem. I was wrong. It turns out the Trendnet was causing issue 1.

I had a theory that excess network traffic was causing issues, so I set up Charles proxy on my server to watch the packets. I could see frequent delays of more than one second, and when they were more than 5 seconds, issue 1 would happen. But with Charles I could only see the traffic between the server and receiver, and I wanted to see all the traffic on the receiver interface, so I set up Wireshark on another computer. In order to do that, I had to bypass the Trendnet and connect the receiver directly to my main switch near my router. When I did that, issue 1 completely went away. The longest delays became 100ms, and those were very rare. I'm not a networking expert, but it seems that the receiver and server were losing routing information when connected to the Trendnet. Wireshark was showing ARP and DHCP requests when the delays were happening.

I also saw Issue 2 occur once while connected to Wireshark. Again, I'm not a networking expert, but as far as I could tell, there was no unusual network activity just before the disconnect, so I have to assume that this is an internal issue with the receiver. I'm surprised more people haven't experienced this. I guess I'll just have to live with it– I don't think it's worth reporting to Denon/Marantz, since they probably don't support their API on anything other than their own apps.

Regarding my recommendations, the longest delay I saw was 7 seconds. A 10 second axios timeout would have masked issue 1 completely.

And a couple of times I saw homebridge grab an incorrect value from the Denon because of querying too soon after a change. When using the Home app to turn on the receiver, it takes a couple of seconds to turn on and when checkState queries during this period, the value returned is "OFF" which provides homebridge with the wrong state. Increasing the checkstate interval may be an easy way to remedy this.

Increasing these timeouts would help eliminate some errors and problems and would not in my opinion cause any decrease in the usability of the component.

Thanks again @grzegorz914 for your patience and help with this issue.

[grzegorz914]

Thanks for the long test and investigation, of course I can set the timeout to 10sec. Regarding report wrong state after power ON it can not be happen because the value are only pushed to characteristic if changed and correct data received from AVR. This is other issue which will be fixed in 3.17.5

3.17.4 released with 10sec timeout, please report back after some time.

[grzegorz914]

3.17.5-beta.0 also available for test

[theworldinfocus]

Hello, I have the same issue, when adding the AV to Homebridge: [DenonTv] Device: Receiver, debug: Device info error: Error: timeout of 10000ms exceeded

I have already tried some other versions without success.

[grzegorz914]

What a receiver?

[theworldinfocus]

Thanks for your quick reply! It's a Denon AVC-X6700H, It was working before but as I had more difficulties than the disconnects, I have removed it and also re-setup my homebridge, now the receiver doesn't get up anymore in Homebridge

[grzegorz914]

Check your config, and network settings, adress IP, port. Ping to AVR.

[theworldinfocus]

that's all working, if I try Port 80 instead of 8080 I get a 403 (what is OK, as 8080 is correct). The Web interface is loading as expected

[grzegorz914]

May by Try power cycle the AVR

[theworldinfocus]

I completely took it off the power for a few minutes, now it's working, thats weird. Thank you for your help!

[grzegorz914]

The server on AVR side some time freezes, it’s a firmware bug.

[badgertastic]

Has been a while, with several updates thanks @grzegorz914, so thought I'd try latest 3.17.3. Unfortunately within a day, my Marantz SR-8012 became unresponsive in Home app. Downgraded again to 3.16.5. Seems perfectly stable on this release.