Feature/improve logging

docs/_docs/logging.md

@@ -22,8 +22,12 @@ publish and subscribe command
 ```
 $ mqtt pub -i c1 -t test -m "Hello World" -d -h broker.hivemq.com
 
-Client '[email protected]' sending CONNECT MqttConnect{keepAlive=60, cleanStart=true, sessionExpiryInterval=0}
-Client '[email protected]' received CONNACK MqttConnAck{reasonCode=SUCCESS, sessionPresent=false, restrictions=MqttConnAckRestrictions{receiveMaximum=10, maximumPacketSize=268435460, topicAliasMaximum=5, maximumQos=EXACTLY_ONCE, retainAvailable=true, wildcardSubscriptionAvailable=true, sharedSubscriptionAvailable=true, subscriptionIdentifiersAvailable=true}} 
-Client '[email protected]' sending PUBLISH ('Hello World') MqttPublish{topic=test, payload=11byte, qos=AT_MOST_ONCE, retain=false}
-Client '[email protected]' received PUBLISH acknowledgement MqttPublishResult{publish=MqttPublish{topic=test, payload=11byte, qos=AT_MOST_ONCE, retain=false}}
+Client '[email protected]' sending CONNECT
+    MqttConnect{keepAlive=60, cleanStart=true, sessionExpiryInterval=0}
+Client '[email protected]' received CONNACK
+    MqttConnAck{reasonCode=SUCCESS, sessionPresent=false, restrictions=MqttConnAckRestrictions{receiveMaximum=10, maximumPacketSize=268435460, topicAliasMaximum=5, maximumQos=EXACTLY_ONCE, retainAvailable=true, wildcardSubscriptionAvailable=true, sharedSubscriptionAvailable=true, subscriptionIdentifiersAvailable=true}} 
+Client '[email protected]' sending PUBLISH ('Hello World')
+    MqttPublish{topic=test, payload=11byte, qos=AT_MOST_ONCE, retain=false}
+Client '[email protected]' finish PUBLISH
+    MqttPublishResult{publish=MqttPublish{topic=test, payload=11byte, qos=AT_MOST_ONCE, retain=false}}
 ```

gradle.properties

@@ -12,7 +12,7 @@ find-bugs.version=3.0.2
 gson.version=2.10.1
 gson-fire.version=1.8.5
 guava.version=32.0.1-jre
-hivemq-client.version=1.3.1
+hivemq-client.version=1.3.2
 javax.version=1.3.2
 jetbrains-annotations.version=23.1.0
 jline.version=3.21.0

src/main/java/com/hivemq/cli/commands/cli/PublishCommand.java

@@ -73,7 +73,7 @@ public PublishCommand(final @NotNull MqttClientExecutor mqttClientExecutor) {
         }
         LoggerUtils.setupConsoleLogging(logToLogfile, logLevel);
 
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         connectOptions.setDefaultOptions();
         connectOptions.logUnusedOptions();

src/main/java/com/hivemq/cli/commands/cli/SubscribeCommand.java

@@ -24,7 +24,6 @@
 import com.hivemq.cli.mqtt.MqttClientExecutor;
 import com.hivemq.cli.utils.LoggerUtils;
 import com.hivemq.client.mqtt.MqttClient;
-import com.hivemq.client.mqtt.exceptions.ConnectionFailedException;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
 import org.tinylog.Logger;
@@ -88,7 +87,7 @@ public SubscribeCommand(final @NotNull MqttClientExecutor mqttClientExecutor) {
         }
         LoggerUtils.setupConsoleLogging(logToLogfile, logLevel);
 
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         connectOptions.setDefaultOptions();
         connectOptions.logUnusedOptions();
@@ -109,7 +108,7 @@ public SubscribeCommand(final @NotNull MqttClientExecutor mqttClientExecutor) {
 
         try {
             mqttClientExecutor.subscribe(subscribeClient, subscribeOptions);
-        } catch (final ConnectionFailedException exception) {
+        } catch (final Exception exception) {
             LoggerUtils.logCommandError("Unable to subscribe", exception, debugOptions);
             return 1;
         }

src/main/java/com/hivemq/cli/commands/hivemq/export/clients/ExportClientsCommand.java

@@ -164,7 +164,7 @@ public ExportClientsCommand() {
         final BlockingQueue<String> clientIdsQueue = new LinkedBlockingQueue<>(CLIENT_IDS_QUEUE_LIMIT);
         final BlockingQueue<ClientDetails> clientDetailsQueue = new LinkedBlockingQueue<>(CLIENT_DETAILS_QUEUE_LIMIT);
 
-        Logger.info("Starting export of client details for HiveMQ at {} ", url);
+        Logger.info("Starting export of client details for HiveMQ at {}", url);
 
         // Start retrieving client ids
         final ClientIdsRetrieverTask clientIdsRetrieverTask =

src/main/java/com/hivemq/cli/commands/options/DebugOptions.java

@@ -25,18 +25,18 @@ public class DebugOptions {
     @CommandLine.Option(names = {"-d", "--debug"}, defaultValue = "false", description = "Enable debug mode")
     private void activateDebugMode(final boolean debug) {
         if (debug && !isVerbose) {
-            this.isDebug = true;
+            isDebug = true;
         }
     }
 
     @SuppressWarnings("unused")
     @CommandLine.Option(names = {"-v", "--verbose"}, defaultValue = "false", description = "Enable verbose mode")
     private void activateVerboseMode(final boolean verbose) {
         if (verbose) {
-            this.isVerbose = true;
+            isVerbose = true;
             isDebug = true;
         } else {
-            this.isVerbose = false;
+            isVerbose = false;
         }
     }
 

src/main/java/com/hivemq/cli/commands/shell/ContextDisconnectCommand.java

@@ -44,7 +44,7 @@ public ContextDisconnectCommand(final @NotNull MqttClientExecutor executor) {
 
     @Override
     public @NotNull Integer call() {
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         if (contextClient != null) {
             disconnectOptions.logUnusedDisconnectOptions(contextClient.getConfig().getMqttVersion());

src/main/java/com/hivemq/cli/commands/shell/ContextPublishCommand.java

@@ -42,7 +42,7 @@ public ContextPublishCommand(final @NotNull MqttClientExecutor executor) {
 
     @Override
     public @NotNull Integer call() {
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         if (contextClient != null) {
             publishOptions.logUnusedOptions(contextClient.getConfig().getMqttVersion());

src/main/java/com/hivemq/cli/commands/shell/ContextSubscribeCommand.java

@@ -64,7 +64,7 @@ public ContextSubscribeCommand(final @NotNull MqttClientExecutor mqttClientExecu
 
     @Override
     public @NotNull Integer call() {
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         if (contextClient == null) {
             Logger.error("The client to subscribe with does not exist");

src/main/java/com/hivemq/cli/commands/shell/ContextSwitchCommand.java

@@ -56,7 +56,7 @@ public ContextSwitchCommand(final @NotNull MqttClientExecutor mqttClientExecutor
 
     @Override
     public @NotNull Integer call() {
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         if (contextName == null && identifier == null) {
             ShellCommand.usage(this);

src/main/java/com/hivemq/cli/commands/shell/ContextUnsubscribeCommand.java

@@ -42,7 +42,7 @@ public ContextUnsubscribeCommand(final @NotNull MqttClientExecutor mqttClientExe
 
     @Override
     public @NotNull Integer call() {
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         if (contextClient == null) {
             Logger.error("The client to unsubscribe with does not exist");

src/main/java/com/hivemq/cli/commands/shell/ShellConnectCommand.java

@@ -48,7 +48,7 @@ public ShellConnectCommand(final @NotNull MqttClientExecutor mqttClientExecutor)
     }
 
     public @NotNull Integer call() {
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         connectOptions.setDefaultOptions();
         connectOptions.logUnusedOptions();

src/main/java/com/hivemq/cli/commands/shell/ShellDisconnectCommand.java

@@ -54,7 +54,7 @@ public class ShellDisconnectCommand implements Callable<Integer> {
         if (disconnectOptions.getHost() == null) {
             disconnectOptions.setHost(defaultCLIProperties.getHost());
         }
-        Logger.trace("Command {} ", this);
+        Logger.trace("Command {}", this);
 
         try {
             if (disconnectOptions.isDisconnectAll()) {

src/main/java/com/hivemq/cli/mqtt/AbstractMqttClientExecutor.java

@@ -128,23 +128,24 @@ abstract void mqtt3Disconnect(
                 return connectMqtt5Client(connectOptions, subscribeOptions);
             case MQTT_3_1_1:
                 return connectMqtt3Client(connectOptions, subscribeOptions);
+            default:
+                throw new IllegalStateException("The MQTT Version specified is not supported. Version was " +
+                        connectOptions.getVersion());
         }
-
-        throw new IllegalStateException("The MQTT Version specified is not supported. Version was " +
-                connectOptions.getVersion());
     }
 
     public void subscribe(final @NotNull MqttClient client, final @NotNull SubscribeOptions subscribeOptions) {
         for (int i = 0; i < subscribeOptions.getTopics().length; i++) {
             final String topic = subscribeOptions.getTopics()[i];
 
             // This check only works as subscribes are implemented blocking.
-            // Otherwise, we would need to check the topics before they are iterated as they are added to the client data after a successful subscribe.
+            // Otherwise, we would need to check the topics before they are iterated
+            // as they are added to the client data after a successful subscribe.
             final List<MqttTopicFilter> intersectingFilters =
                     checkForSharedTopicDuplicate(clientKeyToClientData.get(ClientKey.of(client)).getSubscribedTopics(),
                             topic);
-            // Client{clientIdentifier='hmq_RcrDi_18591249_30a12e2c4bbd17e322a300a4257d76bd', hostname='broker.hivemq.com'} -> {ClientData@3806}
-            // Client{clientIdentifier='hmq_RcrDi_18591249_30a12e2c4bbd17e322a300a4257d76bd', hostname='broker.hivemq.com'}
+            // Client{clientIdentifier='hmq_RcrDi_18591249', hostname='broker.hivemq.com'} -> {ClientData@3806}
+            // Client{clientIdentifier='hmq_RcrDi_18591249', hostname='broker.hivemq.com'}
             if (!intersectingFilters.isEmpty()) {
                 Logger.warn("WARN: New subscription to '{}' intersects with already existing subscription(s) {}",
                         topic,
@@ -266,10 +267,19 @@ public boolean isConnected(final @NotNull ClientKey key) {
     }
 
     private @NotNull Mqtt5Client connectMqtt5Client(
-            final @NotNull ConnectOptions connectOptions, final @Nullable SubscribeOptions subscribeOptions)
-            throws Exception {
+            final @NotNull ConnectOptions connectOptions,
+            final @Nullable SubscribeOptions subscribeOptions) throws Exception {
         final MqttClientBuilder clientBuilder = createBuilder(connectOptions);
-        final Mqtt5Client client = clientBuilder.useMqttVersion5().build();
+        final Mqtt5Client client = clientBuilder.useMqttVersion5()
+                .advancedConfig()
+                .interceptors()
+                .incomingQos1Interceptor(new Mqtt5DebugIncomingQos1Interceptor())
+                .outgoingQos1Interceptor(new Mqtt5DebugOutgoingQos1Interceptor())
+                .incomingQos2Interceptor(new Mqtt5DebugIncomingQos2Interceptor())
+                .outgoingQos2Interceptor(new Mqtt5DebugOutgoingQos2Interceptor())
+                .applyInterceptors()
+                .applyAdvancedConfig()
+                .build();
         final Mqtt5Publish willPublish = createMqtt5WillPublish(connectOptions.getWillOptions());
         final Mqtt5ConnectRestrictions connectRestrictions =
                 createMqtt5ConnectRestrictions(connectOptions.getConnectRestrictionOptions());
@@ -308,6 +318,8 @@ public boolean isConnected(final @NotNull ClientKey key) {
                         buildRemainingMqtt5PublishesCallback(subscribeOptions, client));
 
 
+        System.setProperty("javax.net.debug", "ssl:handshake");
+
         mqtt5Connect(client, connectBuilder.build());
 
         final ClientData clientData = new ClientData(client);
@@ -383,7 +395,7 @@ public boolean isConnected(final @NotNull ClientKey key) {
             }
             return builder.build().asWill();
         } else if (willOptions.getWillMessage() != null) {
-            Logger.warn("option -wt is missing if a will message is configured - will options were: {} ",
+            Logger.warn("option -wt is missing if a will message is configured - will options were: {}",
                     willOptions.toString());
         }
         return null;
@@ -403,7 +415,7 @@ public boolean isConnected(final @NotNull ClientKey key) {
             }
             return builder.build();
         } else if (willOptions.getWillMessage() != null) {
-            Logger.warn("option -wt is missing if a will message is configured - will options were: {} ",
+            Logger.warn("option -wt is missing if a will message is configured - will options were: {}",
                     willOptions.toString());
         }
         return null;

src/main/java/com/hivemq/cli/mqtt/Mqtt5DebugIncomingQos1Interceptor.java

@@ -0,0 +1,38 @@
+/*
+ * Copyright 2019-present HiveMQ and the HiveMQ Community
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.hivemq.cli.mqtt;
+
+import com.hivemq.cli.utils.LoggerUtils;
+import com.hivemq.client.internal.mqtt.message.publish.puback.MqttPubAckBuilder;
+import com.hivemq.client.mqtt.mqtt5.Mqtt5ClientConfig;
+import com.hivemq.client.mqtt.mqtt5.advanced.interceptor.qos1.Mqtt5IncomingQos1Interceptor;
+import com.hivemq.client.mqtt.mqtt5.message.publish.Mqtt5Publish;
+import com.hivemq.client.mqtt.mqtt5.message.publish.puback.Mqtt5PubAckBuilder;
+import org.jetbrains.annotations.NotNull;
+import org.tinylog.Logger;
+
+public class Mqtt5DebugIncomingQos1Interceptor implements Mqtt5IncomingQos1Interceptor {
+
+    @Override
+    public void onPublish(
+            final @NotNull Mqtt5ClientConfig clientConfig,
+            final @NotNull Mqtt5Publish publish,
+            final @NotNull Mqtt5PubAckBuilder pubAckBuilder) {
+        final String clientPrefix = LoggerUtils.getClientPrefix(clientConfig);
+        Logger.debug("{} sending PUBACK\n    {}", clientPrefix, ((MqttPubAckBuilder) pubAckBuilder).build());
+    }
+}

src/main/java/com/hivemq/cli/mqtt/Mqtt5DebugIncomingQos2Interceptor.java

@@ -0,0 +1,51 @@
+/*
+ * Copyright 2019-present HiveMQ and the HiveMQ Community
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.hivemq.cli.mqtt;
+
+import com.hivemq.cli.utils.LoggerUtils;
+import com.hivemq.client.internal.mqtt.message.publish.pubcomp.MqttPubCompBuilder;
+import com.hivemq.client.internal.mqtt.message.publish.pubrec.MqttPubRecBuilder;
+import com.hivemq.client.mqtt.mqtt5.Mqtt5ClientConfig;
+import com.hivemq.client.mqtt.mqtt5.advanced.interceptor.qos2.Mqtt5IncomingQos2Interceptor;
+import com.hivemq.client.mqtt.mqtt5.message.publish.Mqtt5Publish;
+import com.hivemq.client.mqtt.mqtt5.message.publish.pubcomp.Mqtt5PubCompBuilder;
+import com.hivemq.client.mqtt.mqtt5.message.publish.pubrec.Mqtt5PubRecBuilder;
+import com.hivemq.client.mqtt.mqtt5.message.publish.pubrel.Mqtt5PubRel;
+import org.jetbrains.annotations.NotNull;
+import org.tinylog.Logger;
+
+public class Mqtt5DebugIncomingQos2Interceptor implements Mqtt5IncomingQos2Interceptor {
+
+    @Override
+    public void onPublish(
+            @NotNull final Mqtt5ClientConfig clientConfig,
+            @NotNull final Mqtt5Publish publish,
+            @NotNull final Mqtt5PubRecBuilder pubRecBuilder) {
+        final String clientPrefix = LoggerUtils.getClientPrefix(clientConfig);
+        Logger.debug("{} sending PUBREC\n    {}", clientPrefix, ((MqttPubRecBuilder) pubRecBuilder).build());
+    }
+
+    @Override
+    public void onPubRel(
+            @NotNull final Mqtt5ClientConfig clientConfig,
+            @NotNull final Mqtt5PubRel pubRel,
+            @NotNull final Mqtt5PubCompBuilder pubCompBuilder) {
+        final String clientPrefix = LoggerUtils.getClientPrefix(clientConfig);
+        Logger.debug("{} received PUBREL\n    {}", clientPrefix, pubRel);
+        Logger.debug("{} sending PUBCOMP\n    {}", clientPrefix, ((MqttPubCompBuilder) pubCompBuilder).build());
+    }
+}

src/main/java/com/hivemq/cli/mqtt/Mqtt5DebugOutgoingQos1Interceptor.java

@@ -0,0 +1,37 @@
+/*
+ * Copyright 2019-present HiveMQ and the HiveMQ Community
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.hivemq.cli.mqtt;
+
+import com.hivemq.cli.utils.LoggerUtils;
+import com.hivemq.client.mqtt.mqtt5.Mqtt5ClientConfig;
+import com.hivemq.client.mqtt.mqtt5.advanced.interceptor.qos1.Mqtt5OutgoingQos1Interceptor;
+import com.hivemq.client.mqtt.mqtt5.message.publish.Mqtt5Publish;
+import com.hivemq.client.mqtt.mqtt5.message.publish.puback.Mqtt5PubAck;
+import org.jetbrains.annotations.NotNull;
+import org.tinylog.Logger;
+
+public class Mqtt5DebugOutgoingQos1Interceptor implements Mqtt5OutgoingQos1Interceptor {
+
+    @Override
+    public void onPubAck(
+            final @NotNull Mqtt5ClientConfig clientConfig,
+            final @NotNull Mqtt5Publish publish,
+            final @NotNull Mqtt5PubAck pubAck) {
+        final String clientPrefix = LoggerUtils.getClientPrefix(clientConfig);
+        Logger.debug("{} received PUBACK\n    {}", clientPrefix, pubAck);
+    }
+}