]> git.basschouten.com Git - openhab-addons.git/commitdiff
[openhabcloud] improved logging for troubleshooting purposes (#12430)
authorSami Salonen <ssalonen@gmail.com>
Mon, 19 Sep 2022 13:41:16 +0000 (16:41 +0300)
committerGitHub <noreply@github.com>
Mon, 19 Sep 2022 13:41:16 +0000 (15:41 +0200)
* [openhabcloud] Sensor UUID and secret in logging

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhab] More logging. Lambda callbacks

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] Sensor short UUID/secret completely

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] pong milliseconds

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] Log websecket factory HTTP calls and PACKETs (on connect)

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] Sensor more secrets

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] abort connect on exceptional errors

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] remove dead code

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] Socket.IO http logging only with TRACE level enabled

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] logging level tuning

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] fix typo sensored->censored

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
* [openhabcloud] warn level logging (not info) when disconnected

Signed-off-by: Sami Salonen <ssalonen@gmail.com>
Signed-off-by: Sami Salonen <ssalonen@gmail.com>
bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudClient.java
bundles/org.openhab.io.openhabcloud/src/main/java/org/openhab/io/openhabcloud/internal/CloudService.java

index 31c81daa66c2c3b9aba3064e84f7c0d82c1800fb..e7013f55f0960fd8a76d589968cfa3a476dc3db9 100644 (file)
@@ -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<String, List<String>> headers = (Map<String, List<String>>) 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()));
+        //
+        // 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<String, List<String>> headers = (Map<String, List<String>>) 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.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.");
                     }
-                });
-            }
-        }).on(Manager.EVENT_CONNECT_ERROR, new Emitter.Listener() {
-
-            @Override
-            public void call(Object... args) {
-                if (args.length > 0) {
+                })//
+                .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 = "<unexpected packet type>";
+                    if (args.length == 1 && args[0] instanceof Packet<?>) {
+                        packetTypeIndex = ((Packet<?>) args[0]).type;
+
+                        if (packetTypeIndex < Parser.types.length) {
+                            type = Parser.types[packetTypeIndex];
+                        } else {
+                            type = "<unknown 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(
-                                "Error connecting to the openHAB Cloud instance: {} {}. Should reconnect automatically.",
-                                e.getClass().getSimpleName(), e.getMessage());
+                        logger.debug("Socket.IO re-connect attempt error: {} {}", e.getClass().getSimpleName(),
+                                e.getMessage());
                     } else {
-                        logger.debug(
-                                "Error connecting to the openHAB Cloud instance: {}. Should reconnect automatically.",
-                                args[0]);
+                        logger.debug("Socket.IO re-connect attempt error: {}", 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]);
+                })//
+                .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.error("Error during communication");
+                        logger.warn("Socket.IO disconnected");
                     }
-                } 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) {
-                        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);
+                    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.error(
-                                    "Error connecting to the openHAB Cloud instance: {}. Reconnecting after {} ms.",
-                                    args[0], delay);
+                            logger.warn("Error during communication");
                         }
                     } else {
-                        logger.error("Error connecting to the openHAB Cloud instance. Reconnecting.");
+                        // 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();
                     }
-                    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() {
-
-            @Override
-            public void call(Object... args) {
-                onEvent("command", (JSONObject) args[0]);
-            }
-        });
+                })//
+
+                .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());
+    }
 }
index fce8d8ce93bd43ff5cd895cf64045d1768aa1794..64d93bfad4a570bfed37c60589f8c8657108697a 100644 (file)
@@ -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 {