[denonmarantz] Auto-configuration is blocking initialize

[jlaur]

The binding provides auto-configuration that will try to detect protocol, port and number of zones.

The way this is implemented is by calling a method from initialize:

openhab-addons/bundles/org.openhab.binding.denonmarantz/src/main/java/org/openhab/binding/denonmarantz/internal/handler/DenonMarantzHandler.java

Lines 306 to 317 in bae5b0c

	@Override
	public void initialize() {
	config = getConfigAs(DenonMarantzConfiguration.class);
	// Configure Connection type (Telnet/HTTP) and number of zones
	// Note: this only happens for discovered Things
	try {
	autoConfigure();
	} catch (InterruptedException e) {
	Thread.currentThread().interrupt();
	return;
	}

This method will then perform up to three blocking calls with a timeout of three seconds each:

openhab-addons/bundles/org.openhab.binding.denonmarantz/src/main/java/org/openhab/binding/denonmarantz/internal/handler/DenonMarantzHandler.java

Lines 205 to 304 in bae5b0c

	/**
	* Try to auto configure the connection type (Telnet or HTTP) for unmanaged Things.
	*/
	private void autoConfigure() throws InterruptedException {
	/*
	* The isTelnet parameter has no default.
	* When not set we will try to auto-detect the correct values
	* for isTelnet and zoneCount and update the Thing accordingly.
	*/
	if (config.isTelnet() == null) {
	logger.debug("Trying to auto-detect the connection.");
	ContentResponse response;
	boolean telnetEnable = true;
	int httpPort = 80;
	boolean httpApiUsable = false;
	// try to reach the HTTP API at port 80 (most models, except Denon ...H should respond.
	String host = config.getHost();
	try {
	response = httpClient.newRequest("http://" + host + "/goform/Deviceinfo.xml")
	.timeout(3, TimeUnit.SECONDS).send();
	if (response.getStatus() == HttpURLConnection.HTTP_OK) {
	logger.debug("We can access the HTTP API, disabling the Telnet mode by default.");
	telnetEnable = false;
	httpApiUsable = true;
	}
	} catch (TimeoutException | ExecutionException e) {
	logger.debug("Error when trying to access AVR using HTTP on port 80.", e);
	}
	if (telnetEnable) {
	// the above attempt failed. Let's try on port 8080, as for some models a subset of the HTTP API is
	// available
	try {
	response = httpClient.newRequest("http://" + host + ":8080/goform/Deviceinfo.xml")
	.timeout(3, TimeUnit.SECONDS).send();
	if (response.getStatus() == HttpURLConnection.HTTP_OK) {
	logger.debug("This model responds to HTTP port 8080, disabling the Telnet mode by default.");
	telnetEnable = false;
	httpPort = 8080;
	httpApiUsable = true;
	}
	} catch (TimeoutException | ExecutionException e) {
	logger.debug(
	"Additionally tried to connect to port 8080, this also failed. Reverting to Telnet mode.",
	e);
	}
	}
	// default zone count
	int zoneCount = 2;
	// try to determine the zone count by checking the Deviceinfo.xml file
	if (httpApiUsable) {
	int status = 0;
	response = null;
	try {
	response = httpClient.newRequest("http://" + host + ":" + httpPort + "/goform/Deviceinfo.xml")
	.timeout(3, TimeUnit.SECONDS).send();
	status = response.getStatus();
	} catch (TimeoutException | ExecutionException e) {
	logger.debug("Failed in fetching the Deviceinfo.xml to determine zone count", e);
	}
	if (status == HttpURLConnection.HTTP_OK && response != null) {
	DocumentBuilderFactory domFactory = DocumentBuilderFactory.newInstance();
	try {
	// see
	// https://cheatsheetseries.owasp.org/cheatsheets/XML_External_Entity_Prevention_Cheat_Sheet.html
	domFactory.setFeature("http://xml.org/sax/features/external-general-entities", false);
	domFactory.setFeature("http://xml.org/sax/features/external-parameter-entities", false);
	domFactory.setFeature("http://apache.org/xml/features/nonvalidating/load-external-dtd", false);
	domFactory.setXIncludeAware(false);
	domFactory.setExpandEntityReferences(false);
	DocumentBuilder builder;
	builder = domFactory.newDocumentBuilder();
	Document dDoc = builder.parse(new InputSource(new StringReader(response.getContentAsString())));
	XPath xPath = XPathFactory.newInstance().newXPath();
	Node node = (Node) xPath.evaluate("/Device_Info/DeviceZones/text()", dDoc, XPathConstants.NODE);
	if (node != null) {
	String nodeValue = node.getNodeValue();
	logger.trace("/Device_Info/DeviceZones/text() = {}", nodeValue);
	zoneCount = Integer.parseInt(nodeValue);
	logger.debug("Discovered number of zones: {}", zoneCount);
	}
	} catch (ParserConfigurationException | SAXException | IOException | XPathExpressionException
	| NumberFormatException e) {
	logger.debug("Something went wrong with looking up the zone count in Deviceinfo.xml: {}",
	e.getMessage());
	}
	}
	}
	config.setTelnet(telnetEnable);
	config.setZoneCount(zoneCount);
	Configuration configuration = editConfiguration();
	configuration.put(PARAMETER_TELNET_ENABLED, telnetEnable);
	configuration.put(PARAMETER_ZONE_COUNT, zoneCount);
	updateConfiguration(configuration);
	}
	}

This can potentially block initialize for up to nine seconds on first initialization, and at least six seconds for unresponding hosts.

Expected Behavior

The framework expects initialize() to be non-blocking and to return quickly. See https://www.openhab.org/docs/developer/bindings/#startup

Current Behavior

When creating a Thing with an IP address that doesn't exist on the network (similar to a powered off receiver):

2024-05-26 21:22:17.112 [DEBUG] [internal.handler.DenonMarantzHandler] - Trying to auto-detect the connection.
2024-05-26 21:22:20.116 [DEBUG] [internal.handler.DenonMarantzHandler] - Error when trying to access AVR using HTTP on port 80.
java.util.concurrent.TimeoutException: Total timeout 3000 ms elapsed
	at org.eclipse.jetty.client.HttpDestination$RequestTimeouts.onExpired(HttpDestination.java:631) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.client.HttpDestination$RequestTimeouts.onExpired(HttpDestination.java:614) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.io.CyclicTimeouts.onTimeoutExpired(CyclicTimeouts.java:110) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.io.CyclicTimeouts.access$100(CyclicTimeouts.java:50) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.io.CyclicTimeouts$Timeouts.onTimeoutExpired(CyclicTimeouts.java:196) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:298) ~[bundleFile:9.4.54.v20240208]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:833) [?:?]
2024-05-26 21:22:22.114 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'denonmarantz:avr:53596abe49' takes more than 5000ms.
2024-05-26 21:22:23.119 [DEBUG] [internal.handler.DenonMarantzHandler] - Additionally tried to connect to port 8080, this also failed. Reverting to Telnet mode.
java.util.concurrent.TimeoutException: Total timeout 3000 ms elapsed
	at org.eclipse.jetty.client.HttpDestination$RequestTimeouts.onExpired(HttpDestination.java:631) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.client.HttpDestination$RequestTimeouts.onExpired(HttpDestination.java:614) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.io.CyclicTimeouts.onTimeoutExpired(CyclicTimeouts.java:110) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.io.CyclicTimeouts.access$100(CyclicTimeouts.java:50) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.io.CyclicTimeouts$Timeouts.onTimeoutExpired(CyclicTimeouts.java:196) ~[bundleFile:9.4.54.v20240208]
	at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:298) ~[bundleFile:9.4.54.v20240208]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:833) [?:?]
2024-05-26 21:22:23.124 [DEBUG] [internal.handler.DenonMarantzHandler] - Configuring zone channels
2024-05-26 21:22:23.124 [DEBUG] [internal.handler.DenonMarantzHandler] - No zone channels have been added
2024-05-26 21:22:23.124 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone3#volume
2024-05-26 21:22:23.124 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone4#volume
2024-05-26 21:22:23.124 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone4#input
2024-05-26 21:22:23.124 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone4#volumeDB
2024-05-26 21:22:23.125 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone4#mute
2024-05-26 21:22:23.125 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone3#mute
2024-05-26 21:22:23.125 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone3#input
2024-05-26 21:22:23.125 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone3#volumeDB
2024-05-26 21:22:23.125 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone4#power
2024-05-26 21:22:23.126 [TRACE] [internal.handler.DenonMarantzHandler] - Removed channel zone3#power
2024-05-26 21:22:23.140 [DEBUG] [elnet.DenonMarantzTelnetClientThread] - Denon listener created

Possible Solution

The auto-configuration phase could be scheduled to be executed in a separate thread.

Steps to Reproduce

See above.

Context

Your Environment

• Version used: 4.2 snapshot 4096