JVC Integration locks up Projector (jvc_projector)

AnalogThinker commented 3 weeks ago

The problem

I was recommended to open a new ticket for this issue.

Problem:

After a few commands sent to the projector through the jvc_projector integration (over LAN), Integration will become unavailable and greyed out
Once unavailable, integration or HA restart does NOT solve the issue, only a Projector power cycle would make it reconnect
Once unavailable, Projector MAY still respond to IR commands, but can also become locked and not even respond to PHYSICAL BUTTONS on the device (and require a forced power disconnect, which skips the cool-down and can reduce lifespan)

Projector details : Make : JVC Model : DLA-RS45U

Potential issue: From scrolling through the previous HACS community-driven project, there were reports of issues from command sequence/ACK and internal command delays were implemented to avoid some similar behaviours. May be related or not.

What version of Home Assistant Core has the issue?

core-2024.8.2

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

jvc_projector

Link to integration documentation on our website

https://www.home-assistant.io/integrations/jvc_projector/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logs give me a warning:

Logger: jvcprojector.command
Source: components/jvc_projector/coordinator.py:46
response '' not int for cmd 'SC'

followed by :

Logger: homeassistant.components.jvc_projector.coordinator
Source: helpers/update_coordinator.py:386
integration: JVC Projector (documentation, issues)
First occurred: 12:07:45 AM (2 occurrences)
Last logged: 2:52:19 AM

Error fetching JVC Projector data: Unable to connect to 192.168.2.5

Also found this:

Logger: homeassistant.components.jvc_projector.coordinator
Source: helpers/update_coordinator.py:354
integration: JVC Projector (documentation, issues)
First occurred: August 21, 2024 at 9:24:41 PM (1 occurrences)
Last logged: August 21, 2024 at 9:24:41 PM

Unexpected error fetching JVC Projector data
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 354, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/jvc_projector/coordinator.py", line 46, in _async_update_data
    state = await self.device.get_state()
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/jvcprojector/projector.py", line 126, in get_state
    res = await self._send([pwr, inp, src])
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/jvcprojector/projector.py", line 180, in _send
    await self._device.send(cmds)
  File "/usr/local/lib/python3.12/site-packages/jvcprojector/device.py", line 78, in send
    await self._send(cmd)
  File "/usr/local/lib/python3.12/site-packages/jvcprojector/device.py", line 172, in _send
    data = await self._conn.readline()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/jvcprojector/connection.py", line 52, in readline
    return await asyncio.wait_for(self._reader.readline(), timeout=self._timeout)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/tasks.py", line 520, in wait_for
    return await fut
           ^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 568, in readline
    line = await self.readuntil(sep)
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 660, in readuntil
    await self._wait_for_data('readuntil')
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 545, in _wait_for_data
    await self._waiter
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1003, in _read_ready__data_received
    data = self._sock.recv(self.max_size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ConnectionResetError: [Errno 104] Connection reset by peer



### Additional information

_No response_

home-assistant[bot] commented 3 weeks ago

Hey there @steveeasley, @msavazzi, mind taking a look at this issue as it has been labeled with an integration (jvc_projector) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `jvc_projector` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign jvc_projector` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

jvc_projector documentation jvc_projector source _{^{(message by IssueLinks)}}

SteveEasley commented 2 weeks ago

From scrolling through the previous HACS community-driven project, there were reports of issues from command sequence/ACK and internal command delays were implemented to avoid some similar behaviours.

Yeah I worked on a similar issue before in https://github.com/home-assistant/core/issues/116233. This is the first I have heard it happening since the fix for it. Would you mind enabling debugging and attaching some logs?

Turn on logging by going to Settings | Devices and Services, click the JVC integration, then click Enable debug logging.

Now see if you can get it to fail.

View the logs by going to Settings | System | Logs, and click Load Full Logs (you may need refresh the logs a few times to get it all.

AnalogThinker commented 1 week ago

home-assistant_jvc_projector_2024-09-03T01-28-54.504Z.log

Hey @SteveEasley It happened another few times since my post, and was able to have the Log enabled on my last Movie/Gaming session. Please see attached.

For pointers, if this helps: HA reports JVC became Unknown at 06:07:50PM HA reports JVC became Unavailable at 06:07:57 PM

Since that time, all options are greyed out, and my projector is unresponsive, regardless of the input method (It doesn't ping anymore, no Remote/Physical unit buttons do anything). That will be another power cord pull.

The unit lock-up is so odd... I don't feel like I'm ready to take the unit down for JTAG logging tho, hope you can see something from the log haha!

AnalogThinker commented 1 week ago

Edit : It doesn't ping anymore, just checked. Cisco switch says Physical link is Up to the JVC, and RJ45 on the Projector indeed shows Link from lit green LED, with Orange activity blinking as expected.

msavazzi commented 1 week ago

@AnalogThinker I would suggest a ticket is opened with JVC as is really a bad behavior, in any case the projector should not lock completely to force a power disconnection.

This is where something weird happens: “ 2024-09-02 18:07:13.619 DEBUG (MainThread) [homeassistant.components.jvc_projector.coordinator] Finished fetching JVC Projector data in 1.831 seconds (success: True) 2024-09-02 18:07:18.782 DEBUG (MainThread) [jvcprojector.device] Connecting to 192.168.2.5 2024-09-02 18:07:18.785 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJ_OK' 2024-09-02 18:07:18.786 DEBUG (MainThread) [jvcprojector.device] Handshake sending 'PJREQ' 2024-09-02 18:07:18.788 DEBUG (MainThread) [jvcprojector.device] Handshake received b'PJACK' 2024-09-02 18:07:18.788 DEBUG (MainThread) [jvcprojector.device] Sending ref 'PW (b'?\x89\x01PW\n')' 2024-09-02 18:07:18.863 DEBUG (MainThread) [jvcprojector.device] Received ack b'\x06\x89\x01PW\n' 2024-09-02 18:07:18.864 DEBUG (MainThread) [jvcprojector.device] Received ref b'1' (b'@\x89\x01PW1\n') 2024-09-02 18:07:19.366 DEBUG (MainThread) [jvcprojector.device] Sending ref 'IP (b'?\x89\x01IP\n')' 2024-09-02 18:07:34.368 WARNING (MainThread) [jvcprojector.device] Response timeout for 'IP' 2024-09-02 18:07:34.919 DEBUG (MainThread) [jvcprojector.device] Sending ref 'SC (b'?\x89\x01SC\n')' 2024-09-02 18:07:49.921 WARNING (MainThread) [jvcprojector.device] Response timeout for 'SC' 2024-09-02 18:07:50.424 DEBUG (MainThread) [jvcprojector.device] Disconnected 2024-09-02 18:07:50.425 DEBUG (MainThread) [homeassistant.components.jvc_projector.coordinator] Finished fetching JVC Projector data in 31.643 seconds (success: True) “ As there are 2 time outs on a normal IP command and then there is the time out on the SC command (each 15 sec). Overall the data check returns true even if an error occurred. From then on the projector becomes unresponsive.

All the previous interactions are the 5sec pool on the status, I do not see any special command in the sequence

Also the time is not too much: 2024-09-02 16:27:17.911 ERROR (MainThread) [homeassistant.components.jvc_projector.coordinator] Unexpected error fetching JVC Projector data ConnectionResetError: [Errno 104] Connection reset by peer

Last good one: 2024-09-02 18:07:13.617 DEBUG (MainThread) [jvcprojector.device] Disconnected

home-assistant / core