[epsonprojector] Connection lost and not recovering when projector is switched off

[ghys]

I have a projector (EH-TW3200) connected via TCP (using ser2net on another machine, not locally connected to a serial port).
Every time I switch it off, with the 3.0 release binding:

• the subsequent commands timeout after 10 seconds (which is fine, it behaved like this before too)
• it fails to reconnect (not fine)
• the projector thing goes OFFLINE and remains so, and the projector can't be controlled anymore. The solution is to disable it and enable it again.

Expected Behavior

The projector should remain ONLINE and continue to work after being switched off.

Current Behavior

The projector is working while on:

08:29:23.845 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Query: 'PWR?'
08:29:23.949 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Response: 'PWR=01'
08:29:23.951 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Query: 'SOURCE?'
08:29:24.053 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Response: 'SOURCE=30'
08:29:24.055 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Query: 'CMODE?'
08:29:24.157 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Response: 'CMODE=15'
08:29:24.159 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Query: 'LUMINANCE?'
08:29:24.261 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Response: 'LUMINANCE=01'
08:29:24.266 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Query: 'ERR?'
08:29:24.414 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Response: 'ERR=00'
08:29:24.416 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Query: 'ERR?'
08:29:24.517 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Response: 'ERR=00'

Switching it off with a command:

08:29:33.381 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'EpsonProjector_Power' received command OFF
08:29:33.472 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Query: 'PWR OFF'

Leads in:

08:29:56.537 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Response: ':'
08:29:56.539 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Refusing further commands for 10 seconds to power OFF completion
08:29:56.540 [DEBUG] [ojector.internal.EpsonProjectorDevice] - Query: 'PWR?'

Then a few seconds later:

08:30:01.549 [DEBUG] [nternal.handler.EpsonProjectorHandler] - Couldn't execute command 'Power', No response received
08:30:01.550 [DEBUG] [nternal.handler.EpsonProjectorHandler] - Closing connection to device 'epsonprojector:projector-tcp:salon'
08:30:01.551 [DEBUG] [.connector.EpsonProjectorTcpConnector] - Close tcp out stream
08:30:01.552 [DEBUG] [.connector.EpsonProjectorTcpConnector] - Close tcp in stream
08:30:01.553 [DEBUG] [.connector.EpsonProjectorTcpConnector] - Closing socket
08:30:01.554 [DEBUG] [.connector.EpsonProjectorTcpConnector] - Closed
08:30:01.556 [DEBUG] [.connector.EpsonProjectorTcpConnector] - Open connection to address'192.168.1.xxx:2001'
08:30:01.556 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'epsonprojector:projector-tcp:salon' changed from ONLINE to OFFLINE
08:30:01.559 [DEBUG] [nternal.handler.EpsonProjectorHandler] - Refusing command LampTime while not ready
...
08:37:01.652 [DEBUG] [nternal.handler.EpsonProjectorHandler] - Refusing command Power while not ready
08:37:01.653 [DEBUG] [nternal.handler.EpsonProjectorHandler] - Refusing command LampTime while not ready
...
08:37:51.663 [DEBUG] [nternal.handler.EpsonProjectorHandler] - Refusing command Power while not ready
08:37:51.664 [DEBUG] [nternal.handler.EpsonProjectorHandler] - Refusing command LampTime while not ready
...

The thing is stuck until I reenable it as described above.

Possible Solution

Perhaps the connection isn't cleaned properly before opening the new one, or the connection works but the commands are not executed since the thing is still reported as OFFLINE?

Steps to Reproduce (for Bugs)

For reference this is my ser2net configuration:

2001:raw:600:/dev/ttyS1:9600 8DATABITS NONE 1STOPBIT

1. Add a TCP projector connecting to the ser2net above
2. Switch it on
3. Switch it off

Context

I'm positive this is fairly recent, as I've sideloaded this binding for most of 2020 and am only experiencing this issue since I used the distribution binding.

Your Environment

openHAB 3.0 Release

[ghys]

@mlobstein what I think happens here:

1. the 10-second timeout delay after the response to PWR OFF begins
   

   openhab-addons/bundles/org.openhab.binding.epsonprojector/src/main/java/org/openhab/binding/epsonprojector/internal/EpsonProjectorDevice.java

   Line 131 in d223696

   timeoutJob = scheduler.schedule(() -> {

2. a PWR? command is still sent - can't explain why now, probably a race condition with the polling thread... (In my case, I receive the ":" response about 20 seconds after the PWR ON command, so maybe a 30-second delay after sending PWR OFF would be more appropriate?)
3. The response to PWR? isn't received in time, so disconnect() is called, unfortunately this has the effect of cancelling the timeout job:
   

   openhab-addons/bundles/org.openhab.binding.epsonprojector/src/main/java/org/openhab/binding/epsonprojector/internal/EpsonProjectorDevice.java

   Line 211 in d223696

   timeoutJob.cancel(true);

4. Therefore the ready is never set back to true, and so no subsequent commands will be sent:
   

   openhab-addons/bundles/org.openhab.binding.epsonprojector/src/main/java/org/openhab/binding/epsonprojector/internal/handler/EpsonProjectorHandler.java

   Line 300 in d223696

   logger.debug("Refusing command '{}' while not ready", commandType.toString());

[paulianttila]

Related to point 2.

openhab-addons/bundles/org.openhab.binding.epsonprojector/src/main/java/org/openhab/binding/epsonprojector/internal/EpsonProjectorDevice.java

Line 91 in d223696

private boolean ready = true;

I think that variable should be volatile

[mlobstein]

Can this be closed? The issue was addressed by PR #9770 & PR #10079