[openhabcloud] improved logging for troubleshooting purposes (#12430)
* [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>
This commit is contained in:
Sami Salonen
GitHub
parent
89c73a0d81
commit
67843ffbfd
|
|
@ -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()));
|
||||
}
|
||||
});
|
||||
}
|
||||
}).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<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.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 = "<unexpected packet 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 = "<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("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());
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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 {
|
||||
|
|
|
|||
Loading…
Reference in New Issue