adapter keeps reconnecting every 2 minutes

rockthenet commented 6 years ago

Hello. First of all - Thanks for good work. Adapter works fine. Except of one issue. The adapter is reconnecting every 2 minutes.

I am using a Denon AVR-X 2500 H (latest FW)

I already tired to downgrade the adapter to 3.x. Cause i had the issue also on the latest 4.1

Any idea how to get a stable connection?

denon.0 | 2018-09-28 21:49:09.368 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
-- | -- | -- | --
denon.0 | 2018-09-28 21:49:09.364 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:49:09.201 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:49:09.197 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:48:39.363 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-28 21:48:39.195 | warn | Denon AVR has cancelled the connection
denon.0 | 2018-09-28 21:46:22.832 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:46:22.829 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:46:21.538 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:46:21.535 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:45:52.828 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-28 21:45:51.526 | warn | Denon AVR has cancelled the connection
denon.0 | 2018-09-28 21:44:09.346 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:44:09.339 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:44:04.189 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:44:04.181 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:43:39.327 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-28 21:43:34.180 | warn | Denon AVR has cancelled the connection
denon.0 | 2018-09-28 21:41:41.546 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:41:41.541 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:41:36.204 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:41:36.200 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:41:11.538 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-28 21:41:06.196 | warn | Denon AVR has cancelled the connection
denon.0 | 2018-09-28 21:39:19.926 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:39:19.922 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:39:15.630 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:39:15.627 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:38:49.921 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-28 21:38:45.625 | warn | Denon AVR has cancelled the connection
denon.0 | 2018-09-28 21:37:04.173 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:37:04.171 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:37:01.103 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:37:01.098 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:36:34.170 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-28 21:36:31.095 | warn | Denon AVR has cancelled the connection
denon.0 | 2018-09-28 21:35:43.257 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:35:43.243 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:35:43.233 | info | [START] Starting DENON AVR adapter
denon.0 | 2018-09-28 21:35:43.222 | info | starting. Version 0.3.9 in /opt/iobroker/node_modules/iobroker.denon, node: v8.11.3
denon.0 | 2018-09-28 21:35:39.387 | info | terminating
denon.0 | 2018-09-28 21:35:39.370 | info | [END] Stopping Denon AVR adapter...
denon.0 | 2018-09-28 21:34:46.493 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:34:46.490 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:34:39.838 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:34:39.833 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:34:16.486 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-28 21:34:09.812 | warn | Denon AVR has cancelled the connection
denon.0 | 2018-09-28 21:32:20.436 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:32:20.422 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:32:20.411 | info | [START] Starting DENON AVR adapter
denon.0 | 2018-09-28 21:32:20.399 | info | starting. Version 0.3.9 in /opt/iobroker/node_modules/iobroker.denon, node: v8.11.3
denon.0 | 2018-09-28 21:32:16.464 | info | terminating
denon.0 | 2018-09-28 21:32:16.453 | info | [END] Stopping Denon AVR adapter...
denon.0 | 2018-09-28 21:31:57.200 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-28 21:31:53.136 | warn | Denon AVR has cancelled the connection

foxriver76 commented 6 years ago

Hi,

Some questions to get a clue of your problem:

Does it happen when the AVR is turned on or off? Do you have network control configured to always on?

Does another device also use a telnet connection to your AVR?

Have you managed to get a stable connection in the past (with a previous version of the adapter)? Because since a while I haven't changed a thing w.r.t. connection handling.

Is the AVR still online when it closes the socket? Otherwise there could be connection problems? E. g. you could try to ping the AVR and see if it is responding

rockthenet commented 6 years ago

Hi. Thanks for the quick response.

It appears also when the AVR is "turned off"
control was already switched to always on
I also thought that another device maybe keeps connecting. So I closed http connections and killed the remote app. So i iobroker should be the only device. especially in terms of telnet connections.
So far i never had a stable connection with the adapter version 0.3.9 or 0.4.1
Tried to ping the AVR during the "connection closed" phase and got a fast and normal response. No delays.

foxriver76 commented 6 years ago

That sounds good.

On which device and OS is ioBroker running? You could try to play with the advanced settings, especially interval between commands.

Another thing would be setting the adapter to debug, requests could be to frequently because the adapter didn't get the correct data from the configuration page. I think I have no hardcoded fallback.

rockthenet commented 6 years ago

Running iobroker on a Pi3 with various other adapters.
Tried to change the figures. (i guess higher is a good idea in this case) Nothing changed so far.

Debug mode seems to be the next step...

foxriver76 commented 6 years ago

Than try to set adapter on debug and post a part of the log here.

rockthenet commented 6 years ago

Alright. Unfortunately i have almost no experience with the iobroker debug feature - so i just gave a try. Please find attached log

iobroker.2018-09-29.log.html.zip

foxriver76 commented 6 years ago

Thanks, it also looks good.

Nothing special until the AVR closes the socket. How high did you set the request interval when you tested it?

rockthenet commented 6 years ago

Okay. Thank u very much.

Abrufintervall (ms): 7000 to 14000 to 140000

Intervall zwischen den Befehlen (ms): 100 to 200 to 2000

Btw: isn't it unusual that the reconnect part is always listed twice?

...
denon.0 | 2018-09-28 21:37:04.173 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:37:04.171 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-28 21:37:01.103 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-28 21:37:01.098 | info | [CONNECT] Trying to connect to 192.168.178.74:23
...

foxriver76 commented 6 years ago

Yes it is. Thanks. I did not see it until now. If it's possible try to restart the raspberry. Should be the safest way to make sure, that the adapter isn't running twice.

rockthenet commented 6 years ago

Alright. So maybe its just something with (my) denon adapter. So i manually deleted the denon adapter and reinstalled it. Now i had several errors in the log (and again the double connection):


denon.0 | 2018-09-29 18:40:12.428 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
-- | -- | -- | --
denon.0 | 2018-09-29 18:40:12.423 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-29 18:40:11.684 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-29 18:40:11.679 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-29 18:39:42.421 | warn | Connection closed: Error: This socket has been ended by the other party
denon.0 | 2018-09-29 18:39:41.675 | warn | Denon AVR has cancelled the connection
denon.0 | 2018-09-29 18:37:38.996 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-29 18:37:38.984 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-29 18:37:38.981 | info | [START] Starting DENON AVR adapter
denon.0 | 2018-09-29 18:37:38.970 | info | starting. Version 0.4.2 in /opt/iobroker/node_modules/iobroker.denon, node: v8.11.3
denon.0 | 2018-09-29 18:37:07.509 | info | terminating
denon.0 | 2018-09-29 18:37:07.485 | info | [END] Stopping Denon AVR adapter...
denon.0 | 2018-09-29 18:37:07.482 | error | at Manager.ondata (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/socket.io-client/lib/manager.js:335:16)
denon.0 | 2018-09-29 18:37:07.482 | error | at Decoder.add (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/socket.io-parser/index.js:251:12)
denon.0 | 2018-09-29 18:37:07.482 | error | at Decoder.Emitter.emit (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/component-emitter/index.js:133:20)
denon.0 | 2018-09-29 18:37:07.482 | error | at Decoder.<anonymous> (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/component-bind/index.js:21:15)
denon.0 | 2018-09-29 18:37:07.482 | error | at Manager.ondecoded (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/socket.io-client/lib/manager.js:345:8)
denon.0 | 2018-09-29 18:37:07.482 | error | at Manager.Emitter.emit (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/component-emitter/index.js:133:20)
denon.0 | 2018-09-29 18:37:07.482 | error | at Manager.<anonymous> (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/component-bind/index.js:21:15)
denon.0 | 2018-09-29 18:37:07.482 | error | at Socket.onpacket (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/socket.io-client/lib/socket.js:244:12)
denon.0 | 2018-09-29 18:37:07.482 | error | at Socket.onack (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/socket.io-client/lib/socket.js:319:9)
denon.0 | 2018-09-29 18:37:07.482 | error | at Socket.adapter.getObject (/opt/iobroker/node_modules/iobroker.denon/main.js:762:66)
denon.0 | 2018-09-29 18:37:07.482 | error | TypeError: Cannot read property 'common' of null
denon.0 | 2018-09-29 18:37:07.480 | error | uncaught exception: Cannot read property 'common' of null
denon.0 | 2018-09-29 18:37:03.400 | info | [CONNECT] Adapter connected to DENON-AVR: 192.168.178.74:23
denon.0 | 2018-09-29 18:37:03.387 | info | [CONNECT] Trying to connect to 192.168.178.74:23
denon.0 | 2018-09-29 18:37:03.384 | info | [START] Starting DENON AVR adapter
denon.0 | 2018-09-29 18:37:03.374 | info | starting. Version 0.4.2 in /opt/iobroker/node_modules/iobroker.denon, node: v8.11.3
denon.0 | 2018-09-29 18:36:59.474 | info | terminating
denon.0 | 2018-09-29 18:36:59.446 | info | [END] Stopping Denon AVR adapter...
denon.0 | 2018-09-29 18:36:49.797 | info | start browse
denon.0 | 2018-09-29 18:35:04.258 | warn | No IP-address set
denon.0 | 2018-09-29 18:35:04.247 | info | starting. Version 0.4.2 in /opt/iobroker/node_modules/iobroker.denon, node: v8.11.3

Any idea?

foxriver76 commented 6 years ago

The error is my fault. But it should only happen at the first start, because I’m calling the callback to early when it’s not sure that the state exists.

Have you done a restart of your host system? How did you install the adapter? Why it logs no ip address set at the end? Did you remove it?

rockthenet commented 6 years ago

Made the following:

2 times: Manually delete & reinstall via console and via Web interface
reboot after delete & reinstall

Didn't delete any ip in the log. Just copy paste. Is there any way to check if the adapter is 2 times active /running?

foxriver76 commented 6 years ago

I don’t think it is running twice. Just seems to be that the reconnection is twice their somehow. But when starting the adapter it only connects once and you nevertheless lose the connection.

I will fix the two issues tomorrow, with double connection when avr closes the conn and the cannot read common of null...

But that won‘t solve your issue. I‘m running out of ideas. Is there anything special in your network setup?

foxriver76 commented 6 years ago

I fixed the double reconnection issue as well as the error which occurs once (cannot read property common of null). W.r.t your issue we should focus on your network not on the adapter itself.

rockthenet commented 6 years ago

Wow - great work. Thanks again for this massive support. :+1: I'll check the new version soon. Further I'll check it with a clean iobroker installation and also in a separate LAN connection. So I'll keep this ticket updated...

rockthenet commented 6 years ago

Update: Now i have a stable connection! For about >15 Min... and still running. :smiley:

Tested several things:

clean iobroker = nothing changed
seperat network connection = nothing changed
switched the AVR connection from Ethernet to Wireless. = nothing changed
checked the FM Version. (Which I successfully updated before of this hassle and before I ever tried to connect with iobroker) And suddenly there was an additional update available. So it seems that the AVR did not update to the latest FW version in the beginning AND there was something wrong with the Telnet / Remote Feature in the FW had installed. :unamused:

Official changelog:

last updated:- 08/08/2018

Firmware Vers:1400-0394-7091-6064

**************************************************************

08/08/2018

Firmware Vers: 1400-0394-7091-6064(DZ19-023, , AVR-X2500HBKE2, AVR-X2500HBKE2GB

1) DTS Virtual:X ready.
2) ALLM ( Auto Latency Mode ) is ready
3) Video improvements under certain conditions
4) Apple AirPlay 2
5) Grouping improvements 
**6) Other minor bug fixes.**

Filename:-DPMS_AVR-X2500HE2_LEGO_0006.zip
heos_40.prod_1.466.190.zip
**************************************************************

So finally i am happy to have a working Adapter. Sorry for the trouble. Lets say - even the paid developers at Denon produce bugs from time to time... And it's not always the fault of third party developers.

foxriver76 commented 6 years ago

I'm glad that it now works with your AVR. Thanks for providing the detailed information.

And if you have any issues, please let me know.

foxriver76 / ioBroker.denon

adapter keeps reconnecting every 2 minutes #24