Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Can not connect to yamaha receiver at XXX.XXX.XXX.XXX socket hang up #478

Open
thebilberry opened this issue Sep 28, 2024 · 10 comments
Open

Can not connect to yamaha receiver at XXX.XXX.XXX.XXX socket hang up #478

thebilberry opened this issue Sep 28, 2024 · 10 comments
Labels
bug Something isn't working

Comments

@thebilberry
Copy link

To Reproduce
Steps to reproduce the behavior:

  1. Receiver is switched on and network is connected
  2. start adapter (or is already running)
  3. error-message every 30s in log (see screenshot)
    But: Despite errors, adapter runs as expected. Control from ioBroker is possible and data from receiver is written to ioBroker datapoints.

Expected behavior
No error in log, if everything works.

Screenshots & Logfiles
yamaha_log
(IP address between 'at' and 'socket' hidden)

Versions:

  • Adapter version: 0.5.4
  • JS-Controller version: 6.0.11
  • Node version: 20.17.0
  • Operating system: Ubuntu 22.04.5
@mcm1957 mcm1957 added the bug Something isn't working label Sep 28, 2024
@Apollon77
Copy link
Member

Plese enable debug loglevel and post debug log

@thebilberry
Copy link
Author

I'm afraid that it won't help much. No significant log entries are written between errors:
(I have shortened the repetitions and marked them with [...])

2024-10-11 18:05:57.771 - info: host.iobserver instance system.adapter.yamaha.0 in version "0.5.4" started with pid 42393
2024-10-11 18:06:01.879 - debug: yamaha.0 (42393) Redis Objects: Use Redis connection: 0.0.0.0:9001
2024-10-11 18:06:01.936 - debug: yamaha.0 (42393) Objects client ready ... initialize now
2024-10-11 18:06:01.941 - debug: yamaha.0 (42393) Objects create System PubSub Client
2024-10-11 18:06:01.943 - debug: yamaha.0 (42393) Objects create User PubSub Client
2024-10-11 18:06:02.057 - debug: yamaha.0 (42393) Objects client initialize lua scripts
2024-10-11 18:06:02.091 - debug: yamaha.0 (42393) Objects connected to redis: 0.0.0.0:9001
2024-10-11 18:06:02.193 - debug: yamaha.0 (42393) Redis States: Use Redis connection: 0.0.0.0:9000
2024-10-11 18:06:02.215 - debug: yamaha.0 (42393) States create System PubSub Client
2024-10-11 18:06:02.217 - debug: yamaha.0 (42393) States create User PubSub Client
2024-10-11 18:06:02.291 - debug: yamaha.0 (42393) States connected to redis: 0.0.0.0:9000
2024-10-11 18:06:02.374 - debug: yamaha.0 (42393) Plugin sentry Initialize Plugin (enabled=true)
2024-10-11 18:06:05.093 - info:  yamaha.0 (42393) starting. Version 0.5.4 in /opt/iobroker/node_modules/iobroker.yamaha, node: v20.18.0, js-controller: 6.0.11
2024-10-11 18:06:05.568 - debug: yamaha.0 (42393) Y5: on connect
2024-10-11 18:06:05.577 - debug: yamaha.0 (42393) Y5: connected!
2024-10-11 18:06:05.581 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:06:05.582 - debug: yamaha.0 (42393) Y5: @ZONE2:PWR=? written
2024-10-11 18:06:05.648 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby@RESTRICTED
2024-10-11 18:06:05.650 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby@RESTRICTED
2024-10-11 18:06:06.581 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:06:06.588 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby
2024-10-11 18:06:06.589 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby
2024-10-11 18:06:07.581 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:06:07.584 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby
2024-10-11 18:06:07.586 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby
2024-10-11 18:06:08.580 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:06:08.584 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby
2024-10-11 18:06:08.585 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby
2024-10-11 18:06:09.581 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:06:09.585 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby
2024-10-11 18:06:09.585 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby
[...]
2024-10-11 18:09:22.877 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:22.885 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby
2024-10-11 18:09:22.885 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby
2024-10-11 18:09:23.879 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:23.899 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby
2024-10-11 18:09:23.900 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby
2024-10-11 18:09:24.879 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:24.885 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby
2024-10-11 18:09:24.886 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby
2024-10-11 18:09:25.549 - debug: yamaha.0 (42393) execCommand: id=yamaha.0.power val=true
2024-10-11 18:09:25.879 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:25.887 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=Standby
2024-10-11 18:09:25.888 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=Standby
2024-10-11 18:09:25.943 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:25.944 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:25.946 - debug: yamaha.0 (42393) Y5: on data: @MAIN:AVAIL=Ready@MAIN:DIRMODE=Off@MAIN:INP=AV4@MAIN:MUTE=Off@MAIN:SOUNDPRG=Surround Decoder@MAIN:STRAIGHT=Off@MAIN:VOL=-49.0@SYS:DMCCONTROL=Enable
2024-10-11 18:09:25.953 - debug: yamaha.0 (42393) Rawdata: MAIN:AVAIL=Ready@MAIN:DIRMODE=Off@MAIN:INP=AV4@MAIN:MUTE=Off@MAIN:SOUNDPRG=Surround Decoder@MAIN:STRAIGHT=Off@MAIN:VOL=-49.0@SYS:DMCCONTROL=Enable
2024-10-11 18:09:25.989 - debug: yamaha.0 (42393) Y5: on data: @MAIN:VOL=-55.0
2024-10-11 18:09:25.990 - debug: yamaha.0 (42393) Rawdata: MAIN:VOL=-55.0
2024-10-11 18:09:26.133 - info: yamaha.0 (42393) State value to set for "yamaha.0.Realtime.MAIN.VOL" has to be type "number" but received type "string"
2024-10-11 18:09:26.880 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:26.903 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:26.904 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:27.880 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:27.903 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:27.904 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:28.881 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:28.915 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:28.916 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:29.885 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:29.916 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:29.916 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:30.884 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:30.916 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:30.917 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:31.884 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:31.921 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:31.922 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:31.929 - error: yamaha.0 (42393) Can not connect to yamaha receiver at xxx.xxx.xxx.xxx socket hang up
2024-10-11 18:09:32.884 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:32.920 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:32.921 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:33.885 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:33.924 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:33.927 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:09:34.886 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:09:34.920 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:09:34.921 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
[...]
2024-10-11 18:12:31.146 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:12:31.154 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:12:31.155 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:12:32.147 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:12:32.151 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:12:32.151 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:12:33.148 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:12:33.151 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:12:33.152 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:12:34.149 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:12:34.172 - error: yamaha.0 (42393) Can not connect to yamaha receiver at xxx.xxx.xxx.xxx socket hang up
2024-10-11 18:12:34.188 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:12:34.188 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:12:35.150 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:12:35.215 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:12:35.216 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
2024-10-11 18:12:36.153 - debug: yamaha.0 (42393) Y5: @MAIN:PWR=? written
2024-10-11 18:12:36.188 - debug: yamaha.0 (42393) Y5: on data: @MAIN:PWR=On
2024-10-11 18:12:36.188 - debug: yamaha.0 (42393) Rawdata: MAIN:PWR=On
[...]

@Apollon77
Copy link
Member

"Socket hang up" means that the TCP socket which is opened to the receiver was disconnected ... it is then restored ... if there are no real issues we could downgrade to log as info or such

@mcm1957
Copy link
Member

mcm1957 commented Oct 14, 2024

Don't think that info would be any solution.
Not sure why a connection attempt will fail every 30s (or at some other short interval).

If the disconnect is no problem at all and is to be expected than a debug log should be max level as info would fill logs too

@Apollon77
Copy link
Member

If info log is too much the loglevel can be increased to warn to not log it. In my eyes such a disconnection which shoud not be standard is interesting to see for the user, thats why I would not go below info

@mcm1957 mcm1957 closed this as completed Oct 14, 2024
@Apollon77 Apollon77 reopened this Oct 14, 2024
@makuris
Copy link

makuris commented Oct 15, 2024

I am running this yamaha adapter for years now (and totally love it) and suddenly since 1-2 weeks I also have the socket hang up errors in my logs. Not so frequent as described above but only 2-3 times a day. However, one of my scripts which changes the light in my living room based on the status of the yamaha reacts as if it is powered off each time this error occurs. I tried now to catch the error in my script. Since this never happened before, is there any idea what could cause this?

@Apollon77
Copy link
Member

Was there any update of the Firmware? Pr is there anything you did? The adapter did not received any updates in last time so it is unlikely that it is the adapter :-(

@mcm1957
Copy link
Member

mcm1957 commented Oct 16, 2024

Is there any change in your network environment? Did you reboot / updgrade switches or router?
Is there any WLAN connection involved which might have become a loittle bit unstable doe to external changes?

@makuris
Copy link

makuris commented Oct 16, 2024

The yamaha is rather old, so there was no Firmware update for years. Everything is connected via cable without a change of the infrastrucutre. The only thing I did recently is an update of ioBroker itself, the timing could fit with the first occurence of this error. I guess I will reboot my router/network, maybe this already fixes the issue :-) Thank you for your quick support. If there was no update of the adapter I will search for other causes.

@thebilberry
Copy link
Author

thebilberry commented Oct 16, 2024 •
edited
Loading

Just like mine:

  • no update of the adapter (as known)
  • no firmware update from YAMAHA
  • no change to the network configuration
  • wired connection used

Only update of the js-controller (incl. node).

Unfortunately, I can't narrow it down any further. Maybe I can try to reproduce the start of the error in a container with an older version of ioBroker.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@Apollon77 @mcm1957 @makuris @thebilberry