[hdpowerview] Timing dependency during initialization of shades

[jlaur]

#11707 fixed an issue with shades going ONLINE initially, then into OFFLINE with communication error for a minute. This fix was correct, but not enough.

#12002 changed this behavior to initialize to UNKNOWN instead of ONLINE - c8647e8. This makes sense since we don't know if it's online until we have received data. It could even be unknown to the hub if configured wrongly.

However, this last change revealed a problem that was luring since the beginning. Some shades will go ONLINE before switching state to UNKNOWN, then only back to ONLINE after a minute.

After analyzing this again I found the real issue. Look at this example (id 36321 is blind11):

2022-01-18 16:59:45.298 [DEBUG] [ternal.handler.HDPowerViewHubHandler] - Initializing hub
2022-01-18 16:59:45.311 [DEBUG] [ternal.handler.HDPowerViewHubHandler] - Scheduling poll for 5000 ms out, then every 60000 ms
2022-01-18 16:59:50.313 [DEBUG] [ternal.handler.HDPowerViewHubHandler] - Polling for state
2022-01-18 16:59:50.445 [DEBUG] [ternal.handler.HDPowerViewHubHandler] - Received data for 11 shades
2022-01-18 16:59:50.448 [DEBUG] [ternal.handler.HDPowerViewHubHandler] - Shade '24927' handler not initialized
[...]
2022-01-18 16:59:50.465 [DEBUG] [ternal.handler.HDPowerViewHubHandler] - Updating shade '36321'
2022-01-18 16:59:50.555 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hdpowerview:shade:hub:blind11' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to ONLINE
2022-01-18 16:59:50.562 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hdpowerview:shade:hub:blind11' changed from ONLINE to INITIALIZING
2022-01-18 16:59:50.565 [DEBUG] [rnal.handler.HDPowerViewShadeHandler] - Initializing shade handler
2022-01-18 16:59:54.368 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hdpowerview:shade:hub:blind11' changed from INITIALIZING to UNKNOWN
2022-01-18 17:01:25.971 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hdpowerview:shade:hub:blind11' changed from UNKNOWN to ONLINE

Timeline of events:

• Hub is initialized and poll job is scheduled after 5 seconds.
• Shade data is fetched by hub handler, but shade handlers are not yet initialized.
• Some shade handlers may exist even if they are not initialized.
• Those that exists will receive data and marked as ONLINE.
• During initialization they will then be reset to UNKNOWN.

It's possible that the 5 second delay in starting the job was some kind of work-around for this issue. However, with a slow system (Raspberry Pi 3) and many shades (I have 11) this assumption about when handlers would be initialized is false.

Problem is here, in HDPowerViewHubHandler:

    private void updateShadeThing(String shadeId, Thing thing, @Nullable ShadeData shadeData) {
        HDPowerViewShadeHandler thingHandler = ((HDPowerViewShadeHandler) thing.getHandler());
        if (thingHandler == null) {
            logger.debug("Shade '{}' handler not initialized", shadeId);
            return;
        }
        if (shadeData == null) {
            logger.debug("Shade '{}' has no data in hub", shadeId);
        } else {
            logger.debug("Updating shade '{}'", shadeId);
        }
        thingHandler.onReceiveUpdate(shadeData);
    }

This does not consider the status of the shade things, only if it's possible to get the handler.

Solution requirements:

• Do not introduce a delay in initializing shades, i.e. wait up to one minute for polling.
• Get rid of the 5 second initial delay.

Proposal:

• HDPowerViewHubHandler should fetch data immediately and update shade handlers which are fully initialized.
• For shades not yet ready, keep the data.
• Implement childHandlerInitialized to initialize shade handlers when they are ready. See https://www.openhab.org/docs/developer/bindings/#handler-initialization-notification.
• Get rid of data in hub handler as shades are updated.