diff --git a/bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudClient.java b/bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudClient.java index 31c81daa6..e7013f55f 100644 --- a/bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudClient.java +++ b/bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudClient.java @@ -43,11 +43,17 @@ import org.slf4j.LoggerFactory; import io.socket.backo.Backoff; import io.socket.client.IO; +import io.socket.client.IO.Options; import io.socket.client.Manager; import io.socket.client.Socket; import io.socket.emitter.Emitter; import io.socket.engineio.client.Transport; +import io.socket.parser.Packet; +import io.socket.parser.Parser; import io.socket.thread.EventThread; +import okhttp3.OkHttpClient.Builder; +import okhttp3.logging.HttpLoggingInterceptor; +import okhttp3.logging.HttpLoggingInterceptor.Level; /** * This class provides communication between openHAB and the openHAB Cloud service. @@ -157,159 +163,170 @@ public class CloudClient { public void connect() { try { - socket = IO.socket(baseURL); + Options options = new Options(); + if (logger.isTraceEnabled()) { + // When trace level logging is enabled, we activate further logging of HTTP calls + // of the Socket.IO library + Builder okHttpBuilder = new Builder(); + HttpLoggingInterceptor loggingInterceptor = new HttpLoggingInterceptor(); + loggingInterceptor.setLevel(Level.BASIC); + okHttpBuilder.addInterceptor(loggingInterceptor); + okHttpBuilder.addNetworkInterceptor(loggingInterceptor); + options.callFactory = okHttpBuilder.build(); + options.webSocketFactory = okHttpBuilder.build(); + } + socket = IO.socket(baseURL, options); URL parsed = new URL(baseURL); protocol = parsed.getProtocol(); } catch (URISyntaxException e) { logger.error("Error creating Socket.IO: {}", e.getMessage()); + return; } catch (MalformedURLException e) { logger.error("Error parsing baseURL to get protocol, assuming https. Error: {}", e.getMessage()); + return; } - socket.io().on(Manager.EVENT_TRANSPORT, new Emitter.Listener() { - @Override - public void call(Object... args) { - logger.trace("Manager.EVENT_TRANSPORT"); - Transport transport = (Transport) args[0]; - transport.on(Transport.EVENT_REQUEST_HEADERS, new Emitter.Listener() { - @Override - public void call(Object... args) { - logger.trace("Transport.EVENT_REQUEST_HEADERS"); - @SuppressWarnings("unchecked") - Map> headers = (Map>) args[0]; - headers.put("uuid", List.of(uuid)); - headers.put("secret", List.of(secret)); - headers.put("openhabversion", List.of(OpenHAB.getVersion())); - headers.put("clientversion", List.of(CloudService.clientVersion)); - headers.put("remoteaccess", List.of(((Boolean) remoteAccessEnabled).toString())); - } - }); - } - }).on(Manager.EVENT_CONNECT_ERROR, new Emitter.Listener() { - - @Override - public void call(Object... args) { - if (args.length > 0) { - if (args[0] instanceof Exception) { - Exception e = (Exception) args[0]; - logger.debug( - "Error connecting to the openHAB Cloud instance: {} {}. Should reconnect automatically.", - e.getClass().getSimpleName(), e.getMessage()); - } else { - logger.debug( - "Error connecting to the openHAB Cloud instance: {}. Should reconnect automatically.", - args[0]); - } - } else { - logger.debug("Error connecting to the openHAB Cloud instance. Should reconnect automatically."); - } - } - }); - socket.on(Socket.EVENT_CONNECT, new Emitter.Listener() { - @Override - public void call(Object... args) { - logger.debug("Socket.IO connected"); - isConnected = true; - onConnect(); - } - }).on(Socket.EVENT_CONNECTING, new Emitter.Listener() { - @Override - public void call(Object... args) { - logger.debug("Socket.IO connecting"); - } - }).on(Socket.EVENT_RECONNECTING, new Emitter.Listener() { - @Override - public void call(Object... args) { - logger.debug("Socket.IO re-connecting (attempt {})", args[0]); - } - }).on(Socket.EVENT_RECONNECT, new Emitter.Listener() { - @Override - public void call(Object... args) { - logger.debug("Socket.IO re-connected successfully (attempt {})", args[0]); - } - }).on(Socket.EVENT_RECONNECT_ERROR, new Emitter.Listener() { - @Override - public void call(Object... args) { - if (args[0] instanceof Exception) { - Exception e = (Exception) args[0]; - logger.debug("Socket.IO re-connect attempt error: {} {}", e.getClass().getSimpleName(), - e.getMessage()); - } else { - logger.debug("Socket.IO re-connect attempt error: {}", args[0]); - } - } - }).on(Socket.EVENT_RECONNECT_FAILED, new Emitter.Listener() { - @Override - public void call(Object... args) { - logger.debug("Socket.IO re-connect attempts failed. Stopping reconnection."); - } - }).on(Socket.EVENT_DISCONNECT, new Emitter.Listener() { - @Override - public void call(Object... args) { - if (args.length > 0) { - logger.debug("Socket.IO disconnected: {}", args[0]); - } else { - logger.debug("Socket.IO disconnected"); - } - isConnected = false; - onDisconnect(); - } - }).on(Socket.EVENT_ERROR, new Emitter.Listener() { - @Override - public void call(Object... args) { - if (CloudClient.this.socket.connected()) { - if (logger.isDebugEnabled() && args.length > 0) { - logger.error("Error during communication: {}", args[0]); - } else { - logger.error("Error during communication"); - } - } else { - // We are not connected currently, manual reconnection is needed to keep trying to (re-)establish - // connection. - // - // Socket.IO 1.x java client: 'error' event is emitted from Socket on connection errors that are not - // retried, but also with error that are automatically retried. If we - // - // Note how this is different in Socket.IO 2.x java client, Socket emits 'connect_error' event. - // OBS: Don't get confused with Socket IO 2.x docs online, in 1.x connect_error is emitted also on - // errors that are retried by the library automatically! - long delay = reconnectBackoff.duration(); - // Try reconnecting on connection errors - if (logger.isDebugEnabled() && args.length > 0) { + // + // socket manager events + // + socket.io()// + .on(Manager.EVENT_TRANSPORT, args -> { + logger.trace("Manager.EVENT_TRANSPORT"); + Transport transport = (Transport) args[0]; + transport.on(Transport.EVENT_REQUEST_HEADERS, new Emitter.Listener() { + @Override + public void call(Object... args) { + logger.trace("Transport.EVENT_REQUEST_HEADERS"); + @SuppressWarnings("unchecked") + Map> headers = (Map>) args[0]; + headers.put("uuid", List.of(uuid)); + headers.put("secret", List.of(secret)); + headers.put("openhabversion", List.of(OpenHAB.getVersion())); + headers.put("clientversion", List.of(CloudService.clientVersion)); + headers.put("remoteaccess", List.of(((Boolean) remoteAccessEnabled).toString())); + } + }); + })// + .on(Manager.EVENT_CONNECT_ERROR, args -> { + if (args.length > 0) { if (args[0] instanceof Exception) { Exception e = (Exception) args[0]; - logger.error( - "Error connecting to the openHAB Cloud instance: {} {}. Reconnecting after {} ms.", - e.getClass().getSimpleName(), e.getMessage(), delay); + logger.debug( + "Error connecting to the openHAB Cloud instance: {} {}. Should reconnect automatically.", + e.getClass().getSimpleName(), e.getMessage()); } else { - logger.error( - "Error connecting to the openHAB Cloud instance: {}. Reconnecting after {} ms.", - args[0], delay); + logger.debug( + "Error connecting to the openHAB Cloud instance: {}. Should reconnect automatically.", + args[0]); } } else { - logger.error("Error connecting to the openHAB Cloud instance. Reconnecting."); + logger.debug("Error connecting to the openHAB Cloud instance. Should reconnect automatically."); } - socket.close(); - sleepSocketIO(delay); - socket.connect(); - } - } - }).on("request", new Emitter.Listener() { - @Override - public void call(Object... args) { - onEvent("request", (JSONObject) args[0]); - } - }).on("cancel", new Emitter.Listener() { - @Override - public void call(Object... args) { - onEvent("cancel", (JSONObject) args[0]); - } - }).on("command", new Emitter.Listener() { + })// + .on(Manager.EVENT_OPEN, args -> logger.debug("Socket.IO OPEN"))// + .on(Manager.EVENT_CLOSE, args -> logger.debug("Socket.IO CLOSE: {}", args[0]))// + .on(Manager.EVENT_PACKET, args -> { + int packetTypeIndex = -1; + String type = ""; + if (args.length == 1 && args[0] instanceof Packet) { + packetTypeIndex = ((Packet) args[0]).type; - @Override - public void call(Object... args) { - onEvent("command", (JSONObject) args[0]); - } - }); + if (packetTypeIndex < Parser.types.length) { + type = Parser.types[packetTypeIndex]; + } else { + type = ""; + } + } + logger.trace("Socket.IO Packet: {} ({})", type, packetTypeIndex); + })// + ; + + // + // socket events + // + socket.on(Socket.EVENT_CONNECT, args -> { + logger.debug("Socket.IO connected"); + isConnected = true; + onConnect(); + })// + .on(Socket.EVENT_CONNECTING, args -> logger.debug("Socket.IO connecting"))// + .on(Socket.EVENT_RECONNECTING, args -> logger.debug("Socket.IO re-connecting (attempt {})", args[0]))// + .on(Socket.EVENT_RECONNECT, + args -> logger.debug("Socket.IO re-connected successfully (attempt {})", args[0]))// + .on(Socket.EVENT_RECONNECT_ERROR, args -> { + if (args[0] instanceof Exception) { + Exception e = (Exception) args[0]; + logger.debug("Socket.IO re-connect attempt error: {} {}", e.getClass().getSimpleName(), + e.getMessage()); + } else { + logger.debug("Socket.IO re-connect attempt error: {}", args[0]); + } + })// + .on(Socket.EVENT_RECONNECT_FAILED, + args -> logger.debug("Socket.IO re-connect attempts failed. Stopping reconnection."))// + .on(Socket.EVENT_DISCONNECT, args -> { + if (args.length > 0) { + logger.warn("Socket.IO disconnected: {}", args[0]); + } else { + logger.warn("Socket.IO disconnected"); + } + isConnected = false; + onDisconnect(); + })// + .on(Socket.EVENT_ERROR, args -> { + if (CloudClient.this.socket.connected()) { + if (args.length > 0) { + if (args[0] instanceof Exception) { + Exception e = (Exception) args[0]; + logger.warn("Error during communication: {} {}", e.getClass().getSimpleName(), + e.getMessage()); + } else { + logger.warn("Error during communication: {}", args[0]); + } + } else { + logger.warn("Error during communication"); + } + } else { + // We are not connected currently, manual reconnection is needed to keep trying to + // (re-)establish + // connection. + // + // Socket.IO 1.x java client: 'error' event is emitted from Socket on connection errors that + // are not + // retried, but also with error that are automatically retried. If we + // + // Note how this is different in Socket.IO 2.x java client, Socket emits 'connect_error' + // event. + // OBS: Don't get confused with Socket IO 2.x docs online, in 1.x connect_error is emitted + // also on + // errors that are retried by the library automatically! + long delay = reconnectBackoff.duration(); + // Try reconnecting on connection errors + if (args.length > 0) { + if (args[0] instanceof Exception) { + Exception e = (Exception) args[0]; + logger.warn( + "Error connecting to the openHAB Cloud instance: {} {}. Reconnecting after {} ms.", + e.getClass().getSimpleName(), e.getMessage(), delay); + } else { + logger.warn( + "Error connecting to the openHAB Cloud instance: {}. Reconnecting after {} ms.", + args[0], delay); + } + } else { + logger.warn("Error connecting to the openHAB Cloud instance. Reconnecting."); + } + socket.close(); + sleepSocketIO(delay); + socket.connect(); + } + })// + + .on(Socket.EVENT_PING, args -> logger.debug("Socket.IO ping"))// + .on(Socket.EVENT_PONG, args -> logger.debug("Socket.IO pong: {} ms", args[0]))// + .on("request", args -> onEvent("request", (JSONObject) args[0]))// + .on("cancel", args -> onEvent("cancel", (JSONObject) args[0]))// + .on("command", args -> onEvent("command", (JSONObject) args[0]))// + ; socket.connect(); } @@ -318,7 +335,8 @@ public class CloudClient { */ public void onConnect() { - logger.info("Connected to the openHAB Cloud service (UUID = {}, base URL = {})", this.uuid, this.localBaseUrl); + logger.info("Connected to the openHAB Cloud service (UUID = {}, base URL = {})", censored(this.uuid), + this.localBaseUrl); reconnectBackoff.reset(); isConnected = true; } @@ -328,21 +346,13 @@ public class CloudClient { */ public void onDisconnect() { - logger.info("Disconnected from the openHAB Cloud service (UUID = {}, base URL = {})", this.uuid, + logger.info("Disconnected from the openHAB Cloud service (UUID = {}, base URL = {})", censored(this.uuid), this.localBaseUrl); isConnected = false; // And clean up the list of running requests runningRequests.clear(); } - /** - * Callback method for socket.io client which is called when an error occurs - */ - - public void onError(IOException error) { - logger.debug("{}", error.getMessage()); - } - /** * Callback method for socket.io client which is called when a message is received */ @@ -684,4 +694,11 @@ public class CloudClient { } }); } + + private static String censored(String secret) { + if (secret.length() < 4) { + return "*******"; + } + return secret.substring(0, 2) + "..." + secret.substring(secret.length() - 2, secret.length()); + } } diff --git a/bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudService.java b/bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudService.java index fce8d8ce9..64d93bfad 100644 --- a/bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudService.java +++ b/bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudService.java @@ -228,7 +228,7 @@ public class CloudService implements ActionService, CloudClientListener, EventSu } } - logger.debug("UUID = {}, secret = {}", InstanceUUID.get(), getSecret()); + logger.debug("UUID = {}, secret = {}", censored(InstanceUUID.get()), censored(getSecret())); if (cloudClient != null) { cloudClient.shutdown(); @@ -284,7 +284,7 @@ public class CloudService implements ActionService, CloudClientListener, EventSu file.getParentFile().mkdirs(); try { Files.writeString(file.toPath(), content, StandardCharsets.UTF_8); - logger.debug("Created file '{}' with content '{}'", file.getAbsolutePath(), content); + logger.debug("Created file '{}' with content '{}'", file.getAbsolutePath(), censored(content)); } catch (FileNotFoundException e) { logger.error("Couldn't create file '{}'.", file.getPath(), e); } catch (IOException e) { @@ -311,16 +311,23 @@ public class CloudService implements ActionService, CloudClientListener, EventSu if (!file.exists()) { newSecretString = randomString(20); - logger.debug("New secret = {}", newSecretString); + logger.debug("New secret = {}", censored(newSecretString)); writeFile(file, newSecretString); } else { newSecretString = readFirstLine(file); - logger.debug("Using secret at '{}' with content '{}'", file.getAbsolutePath(), newSecretString); + logger.debug("Using secret at '{}' with content '{}'", file.getAbsolutePath(), censored(newSecretString)); } return newSecretString; } + private static String censored(String secret) { + if (secret.length() < 4) { + return "*******"; + } + return secret.substring(0, 2) + "..." + secret.substring(secret.length() - 2, secret.length()); + } + @Override public void sendCommand(String itemName, String commandString) { try {