Unable to control STR-DN1030 - "Failed to call service" error when trying to power on/off

[itm1960]

As per the discussion on Reddit. I have installed the custom component and see two entities (media_player and remote), but I get these error messages when I try to turn either of them on or off from the HA GUI:

Failed to call service media_player/turn_off. 'CommandService' object has no attribute 'command_writer'
Failed to call service remote/turn_on. 'CommandService' object has no attribute 'command_writer'

I've turned on debugging and attach the log from the relevant period. sonyavr.log

[itm1960]

I've just noticed that these unknown data packet errors continued to appear continuously in the log for the next couple of hours, 10-20 times per second, despite no manual interaction with the integration from me. The CPU on my HA machine also hit and stayed at 100% - I'm not sure if this was coincidental - so I've deleted the integration for now and restarted HA.

[peteS-UK]

Yes, that's clearly all wrong. It's managed to connect to the socket now and buried in there you can see "Command : 0x2, 0x4, 0xa0, 0x60, 0x0, 0x0, 0x0" which is the integration trying to turn the AVR on and off.

It looks like the AVR is sending out a null byte continuously on that port, which is odd. And, it's doing that as soon as the connection is made - before we try and send anything to it. The only thing I can see in there is the dlna - is the dlna service connecting to the AVR perhaps? I've got no idea why the AVR is sending that out all the time. I wonder if it's related to why it dropped off the network. Maybe worth turning the AVR off at the wall and giving it a couple of mins perhaps - that doesn't seem normal and likely isn't doing your network any favours...

[itm1960]

Ah OK I didn't realise that the data was coming from the AVR - I assumed that it was originating from the integration. I don't know what dlna_dmr.media_player is. I run a Logitech Media Server, which does connect to the AVR as a renderer, but I have no idea if that is causing any unnecessary network traffic. I haven't noticed it causing any problems in the past. I did power off the AVR for a few seconds earlier, to resolve the network problem, so I'll keep an eye on it.

[peteS-UK]

Those debug messages are showing what the integration is receiving back from the AVR.

dlna_dmr.media_player is in the HA logs - there's a DLNA integration as standard in HA so I guess that's enabled and discovering the AVR. You might check if that's enabled in HA integrations and disable it if you're not using it.

Not sure the LMS situation is likely to cause anything as that's going to be sending traffic to a different IP address (i.e. the LMS server). I've also run that at times on my 1040 with LMS and didn't have any problems. If it's anything, it feels more likely to be the DLNA integration on HA if you have that enabled, but it shouldn't be having any impact IMHO.

It may be of course that, although 8080 is open, it's not the port to use for commands etc.. You might want to try running that script with wider range of ports to see if anything else is open if you can't get anywhere with 8080

[itm1960]

OK that makes sense. TBH I can't remember if I actively use the DLNA integration. It does seem to be able to mute the AVR, but there's no apparent option to power it on or off. I've just noticed that the AVR is also listed as a device by the Netgear integration (my main router is a Netgear R7800, running DD-WRT). It has a "failed setup" message in the config page, so I'll disable it as I doubt that it's doing anything useful.

I ran the script for a range of 8000-50000, and the only two ports that responded were 8080 and 10100. So I reinstalled the integration on port 10100 (and restarted HA). Still no luck - I get the same error message when I try powering the AVR on/off

[peteS-UK]

When you say "the same error message" on 10100, do you mean you got the storm of debug "unknown data packet"? I just had a look at the doc for the read function, and it will return a null byte immediately if it gets an EOF message from the host, so I wonder if that's happening. In the doc on the roomieremote site, it said

DN1030 does not provide feedback.

Maybe that's what we're seeing - it just sends an EOF when you try and read, which would create the storm you're seeing.

If so, perhaps we could try it with just sending the commands without listening for any feedback. I'm not sure if a media player component would actually work like that - i.e. completely stateless and just accepting commands. Would that actually be any use to you? Really then, we might be better off just creating a separate integration which is just a service to send the commands, although things like sound field lists, source list etc. are messy then.

[peteS-UK]

I just had a look - I think I can add a toggle to the config for "process feedback" and then just have a stateless device. Is that actually useful - we still don't know if the commands work of course, but I can send you something to test with the state stuff still in, ignoring feedback (so it's not listening and getting all the nulls) so you could then try and just send the commands to see if they work.

[peteS-UK]

OK - you could give this a test

sony.zip

Same as before - just unzip this over the existing files. It will break the media player component at the moment - it will show the state as unknown and not do anything. Delete the old config. When you add a new one, down at the bottom, there's a tick box for "process feedback". Make sure you untick this. That will stop it trying to listen for anything. Once you've installed it (on 8080), go to Developer Tools/Services and use the Sony AVR service to send commands - on off etc.. This will tell us if the commands actually work. If they do, I can tidy up the media player component to work a bit, but there's no point if the commands don't work.

[itm1960]

When I said I got exactly the same error message I meant this one, which pops up for a few seconds when I try to power on/off the media_player or remote entities: Failed to call service media_player/turn_off. 'CommandService' object has no attribute 'command_writer'

I just reinstalled the integration (port 8080) and copied the files from your zip over the originals. In the meantime the AVR dropped off the network - just like it did before. Once again, when I went into the Network Settings it just hung with a flashing "Please Wait" message (it is connected via ethernet). I powered it off for a few minutes then back on again - this restored it to the LAN. I then tried powering it off from the integration again. I got the same message as above popping up, plus similar messages to those before in the log:

2024-07-04 18:25:11.126 INFO (MainThread) [homeassistant.setup] Setting up sonyavr
2024-07-04 18:25:11.127 INFO (MainThread) [homeassistant.setup] Setup of domain sonyavr took 0.00 seconds
...
2024-07-04 18:25:28.737 INFO (MainThread) [homeassistant.components.media_player] Setting up sonyavr.media_player
2024-07-04 18:25:28.738 INFO (MainThread) [homeassistant.components.remote] Setting up sonyavr.remote
...
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 241, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2741, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2784, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 977, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1049, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/config/custom_components/sonyavr/remote.py", line 123, in async_turn_off
    await self._device.async_turn_off()
  File "/config/custom_components/sonyavr/sonyavr.py", line 1227, in async_turn_off
    await self.command_service.async_power_off()
  File "/config/custom_components/sonyavr/sonyavr.py", line 634, in async_power_off
    await self.async_send_command(CMD_POWER_OFF)
  File "/config/custom_components/sonyavr/sonyavr.py", line 593, in async_send_command
    if not self.block_sending and self.command_writer is not None:
                                  ^^^^^^^^^^^^^^^^^^^
AttributeError: 'CommandService' object has no attribute 'command_writer'

[peteS-UK]

Did you reboot ha after copying the files? I wouldn't expect you to have the option to power off from the integration, or to you mean via the service under developer tools?

If you're getting that when you call the service, it likely means it's lost the connection to the avr again - i.e. it's dropped off the network again, although I'd expect to see a Cannot connect to command socket message if it hadn't been able to make the connection in the first place.

[itm1960]

Yes I rebooted after copying them. If I call the remote.turn_off service for the sonyavr remote (from the Services page in the HA UI) I don't get an error message but it doesn't turn off the AVR. I can ping the AVR from the HA server, so it hasn't fallen off the network. Log entries are below:

2024-07-05 11:55:11.981 DEBUG (MainThread) [custom_components.sonyavr] Adding 192.168.1.82 from config
2024-07-05 11:55:11.988 DEBUG (MainThread) [custom_components.sonyavr.sonyavr] Network: 192.168.1 IP: 192.168.1.36
2024-07-05 11:55:11.988 DEBUG (MainThread) [custom_components.sonyavr.sonyavr] Set Max Volume: 45 and Volume Range: 45
...
2024-07-05 11:55:22.473 INFO (MainThread) [homeassistant.components.media_player] Setting up sonyavr.media_player
2024-07-05 11:55:22.475 INFO (MainThread) [homeassistant.components.remote] Setting up sonyavr.remote
...
2024-07-05 12:05:24.741 DEBUG (MainThread) [custom_components.sonyavr.sonyavr] Command : 0x2, 0x4, 0xa0, 0x60, 0x0, 0x0, 0x0

[peteS-UK]

Seems like we may be approaching the end of the road sadly. The Command: line is it sending the power off command. I guess final check would be to try that on any other open port you can find, but if that doesn't work then it seems that the 1030 just doesn't work the same as the other AVRs - which would explain the comment on roomie about it not giving feedback if it's just different to the others, but will be a shame.

[itm1960]

Yes I think you may be right. I tried one last time on port 10100 (the only other open port that I've found so far), but had no luck. Thanks for your help, anyway - much appreciated

[peteS-UK]

Shame indeed - once we found the open port, I was hopeful, but the comment on roomie was concerning about no feedback. I'll add a comment to the readme that it doesn't work with 1030 sadly. If you find anything else, let me know and I'm happy to have another look at things.

[peteS-UK]

Given that 1030 doesn't behave like other AVRs, I'll close down this thread - feel free to open a new one if we discover anything else.