Minor on logging, removed ugly if(isDebugEnabled()) for debug logging, kept only when the toString generation could potentially take long, and trasformed in tracing logs. Moved Error to Warn log level

This commit is contained in:
andsel
2017-01-18 23:28:11 +01:00
parent e295fcf9f2
commit 716c9ac0a0
17 changed files with 72 additions and 144 deletions
@@ -100,10 +100,8 @@ final class BrokerInterceptor implements Interceptor {
@Override
public void notifyClientConnected(final ConnectMessage msg) {
for (final InterceptHandler handler : this.handlers.get(InterceptConnectMessage.class)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Sending MQTT CONNECT message to interceptor. MqttClientId = {}, interceptorId = {}.",
msg.getClientID(), handler.getID());
}
LOG.debug("Sending MQTT CONNECT message to interceptor. MqttClientId = {}, interceptorId = {}.",
msg.getClientID(), handler.getID());
executor.execute(new Runnable() {
@Override
public void run() {
@@ -116,10 +114,8 @@ final class BrokerInterceptor implements Interceptor {
@Override
public void notifyClientDisconnected(final String clientID, final String username ) {
for (final InterceptHandler handler : this.handlers.get(InterceptDisconnectMessage.class)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Notifying MQTT client disconnection to interceptor. MqttClientId = {}, username = {}, interceptorId = {}.",
clientID, username, handler.getID());
}
LOG.debug("Notifying MQTT client disconnection to interceptor. MqttClientId = {}, username = {}, " +
"interceptorId = {}.", clientID, username, handler.getID());
executor.execute(new Runnable() {
@Override
public void run() {
@@ -132,10 +128,8 @@ final class BrokerInterceptor implements Interceptor {
@Override
public void notifyClientConnectionLost(final String clientID, final String username) {
for (final InterceptHandler handler : this.handlers.get(InterceptConnectionLostMessage.class)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Notifying unexpected MQTT client disconnection to interceptor. MqttClientId = {}, username = {}, interceptorId = {}.",
clientID, username, handler.getID());
}
LOG.debug("Notifying unexpected MQTT client disconnection to interceptor. MqttClientId = {}, " +
"username = {}, interceptorId = {}.", clientID, username, handler.getID());
executor.execute(new Runnable() {
@Override
public void run() {
@@ -148,10 +142,8 @@ final class BrokerInterceptor implements Interceptor {
@Override
public void notifyTopicPublished(final PublishMessage msg, final String clientID, final String username) {
for (final InterceptHandler handler : this.handlers.get(InterceptPublishMessage.class)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Notifying MQTT PUBLISH message to interceptor. MqttClientId = {}, messageId = {}, topic = {}, interceptorId = {}.",
clientID, msg.getMessageID(), msg.getTopicName(), handler.getID());
}
LOG.debug("Notifying MQTT PUBLISH message to interceptor. MqttClientId = {}, messageId = {}, topic = {}, " +
"interceptorId = {}.", clientID, msg.getMessageID(), msg.getTopicName(), handler.getID());
executor.execute(new Runnable() {
@Override
public void run() {
@@ -164,10 +156,8 @@ final class BrokerInterceptor implements Interceptor {
@Override
public void notifyTopicSubscribed(final Subscription sub, final String username) {
for (final InterceptHandler handler : this.handlers.get(InterceptSubscribeMessage.class)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Notifying MQTT SUBSCRIBE message to interceptor. MqttClientId = {}, topicFilter = {}, interceptorId = {}.",
sub.getClientId(), sub.getTopicFilter(), handler.getID());
}
LOG.debug("Notifying MQTT SUBSCRIBE message to interceptor. MqttClientId = {}, topicFilter = {}, " +
"interceptorId = {}.", sub.getClientId(), sub.getTopicFilter(), handler.getID());
executor.execute(new Runnable() {
@Override
public void run() {
@@ -180,10 +170,8 @@ final class BrokerInterceptor implements Interceptor {
@Override
public void notifyTopicUnsubscribed(final String topic, final String clientID, final String username) {
for (final InterceptHandler handler : this.handlers.get(InterceptUnsubscribeMessage.class)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Notifying MQTT UNSUBSCRIBE message to interceptor. MqttClientId = {}, topic = {}, interceptorId = {}.",
clientID, topic, handler.getID());
}
LOG.debug("Notifying MQTT UNSUBSCRIBE message to interceptor. MqttClientId = {}, topic = {}, " +
"interceptorId = {}.", clientID, topic, handler.getID());
executor.execute(new Runnable() {
@Override
public void run() {
@@ -196,10 +184,9 @@ final class BrokerInterceptor implements Interceptor {
@Override
public void notifyMessageAcknowledged( final InterceptAcknowledgedMessage msg ) {
for (final InterceptHandler handler : this.handlers.get(InterceptAcknowledgedMessage.class)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Notifying MQTT ACK message to interceptor. MqttClientId = {}, messageId = {}, topic = {}, interceptorId = {}.",
msg.getMsg().getClientID(), msg.getMsg().getMessageID(), msg.getTopic(), handler.getID());
}
LOG.debug("Notifying MQTT ACK message to interceptor. MqttClientId = {}, messageId = {}, topic = {}, " +
"interceptorId = {}.",
msg.getMsg().getClientID(), msg.getMsg().getMessageID(), msg.getTopic(), handler.getID());
executor.execute(new Runnable() {
@Override
public void run() {
@@ -29,10 +29,8 @@ class InternalRepublisher {
//fire as retained the message
Integer packetID = storedMsg.getQos() == AbstractMessage.QOSType.MOST_ONE ? null : targetSession.nextPacketId();
if (packetID != null) {
if (LOG.isDebugEnabled()) {
LOG.debug("Adding message to inflight zone. MqttClientId = {}, packetId = {}, messageId = {}, topic = {}.",
targetSession.clientID, packetID, storedMsg.getMessageID(), storedMsg.getTopic());
}
LOG.debug("Adding message to inflight zone. MqttClientId = {}, packetId = {}, messageId = {}, topic = {}.",
targetSession.clientID, packetID, storedMsg.getMessageID(), storedMsg.getTopic());
targetSession.inFlightAckWaiting(storedMsg.getGuid(), packetID);
}
PublishMessage publishMsg = retainedPublish(storedMsg);
@@ -50,10 +48,8 @@ class InternalRepublisher {
for (IMessagesStore.StoredMessage pubEvt : storedPublishes) {
//put in flight zone
if (LOG.isDebugEnabled()) {
LOG.debug("Adding message ot inflight zone. MqttClientId = {}, guid = {}, messageId = {}, topic = {}.",
clientSession.clientID, pubEvt.getGuid(), pubEvt.getMessageID(), pubEvt.getTopic());
}
LOG.debug("Adding message ot inflight zone. MqttClientId = {}, guid = {}, messageId = {}, topic = {}.",
clientSession.clientID, pubEvt.getGuid(), pubEvt.getMessageID(), pubEvt.getTopic());
clientSession.inFlightAckWaiting(pubEvt.getGuid(), pubEvt.getMessageID());
PublishMessage publishMsg = notRetainedPublish(pubEvt);
//set the PacketIdentifier only for QoS > 0
@@ -61,11 +61,8 @@ class MessagesPublisher {
ByteBuffer message = origMessage.duplicate();
if (targetIsActive) {
if (LOG.isDebugEnabled()) {
LOG.debug(
"Sending PUBLISH message to subscriber. MessageId = {}, mqttClientId = {}, topicFilter = {}, qos = {}, active = {}.",
pubMsg.getMessageID(), sub.getClientId(), sub.getTopicFilter(), qos, targetIsActive);
}
LOG.debug("Sending PUBLISH message to active subscriber. MessageId = {}, mqttClientId = {}, topicFilter = {}, " +
"qos = {}.", pubMsg.getMessageID(), sub.getClientId(), sub.getTopicFilter(), qos);
PublishMessage publishMsg = notRetainedPublish(topic, qos, message);
if (qos != AbstractMessage.QOSType.MOST_ONE) {
//QoS 1 or 2
@@ -77,11 +74,9 @@ class MessagesPublisher {
this.messageSender.sendPublish(targetSession, publishMsg);
} else {
if (!targetSession.isCleanSession()) {
if (LOG.isDebugEnabled()) {
LOG.debug(
"Storing pending PUBLISH message. MessageId = {}, mqttClientId = {}, topicFilter = {}, qos = {}, active = {}.",
pubMsg.getMessageID(), sub.getClientId(), sub.getTopicFilter(), qos, targetIsActive);
}
LOG.debug("Storing pending PUBLISH inactive message. MessageId = {}, mqttClientId = {}, " +
"topicFilter = {}, qos = {}.",
pubMsg.getMessageID(), sub.getClientId(), sub.getTopicFilter(), qos);
//store the message in targetSession queue to deliver
targetSession.enqueue(pubMsg);
}
@@ -577,9 +577,7 @@ public class ProtocolProcessor {
int messageID = msg.getMessageID();
targetSession.moveInFlightToSecondPhaseAckWaiting(messageID);
//once received a PUBREC reply with a PUBREL(messageID)
if (LOG.isDebugEnabled()) {
LOG.debug("Processing PUBREC message. MqttClientId = {}, messageId = {}.", clientID, messageID);
}
LOG.debug("Processing PUBREC message. MqttClientId = {}, messageId = {}.", clientID, messageID);
PubRelMessage pubRelMessage = new PubRelMessage();
pubRelMessage.setMessageID(messageID);
pubRelMessage.setQos(AbstractMessage.QOSType.LEAST_ONE);
@@ -590,9 +588,7 @@ public class ProtocolProcessor {
public void processPubComp(Channel channel, PubCompMessage msg) {
String clientID = NettyUtils.clientID(channel);
int messageID = msg.getMessageID();
if (LOG.isDebugEnabled()) {
LOG.debug("Processing PUBCOMP message. MqttClientId = {}, messageId = {}.", clientID, messageID);
}
LOG.debug("Processing PUBCOMP message. MqttClientId = {}, messageId = {}.", clientID, messageID);
//once received the PUBCOMP then remove the message from the temp memory
ClientSession targetSession = m_sessionsStore.sessionForClient(clientID);
StoredMessage inflightMsg = targetSession.secondPhaseAcknowledged(messageID);
@@ -733,9 +729,7 @@ public class ProtocolProcessor {
return;
}
if (LOG.isDebugEnabled()) {
LOG.debug("Removing subscription. MqttClientId = {}, topic = {}.", clientID, topic);
}
LOG.debug("Removing subscription. MqttClientId = {}, topic = {}.", clientID, topic);
subscriptions.removeSubscription(topic, clientID);
clientSession.unsubscribeFrom(topic);
String username = NettyUtils.userName(channel);
@@ -45,8 +45,8 @@ class Qos0PublishHandler extends QosPublishHandler {
String clientID = NettyUtils.clientID(channel);
toStoreMsg.setClientID(clientID);
if (LOG.isDebugEnabled()) {
LOG.debug("Sending publish message to subscribers. MqttClientId = {}, topic = {}, messageId = {}, payload = {}, subscriptionTree = {}.",
if (LOG.isTraceEnabled()) {
LOG.trace("Sending publish message to subscribers. MqttClientId = {}, topic = {}, messageId = {}, payload = {}, subscriptionTree = {}.",
clientID, topic, msg.getMessageID(), DebugUtils.payload2Str(toStoreMsg.getMessage()),
subscriptions.dumpTree());
} else {
@@ -50,8 +50,8 @@ class Qos1PublishHandler extends QosPublishHandler {
String clientID = NettyUtils.clientID(channel);
toStoreMsg.setClientID(clientID);
if (LOG.isDebugEnabled()) {
LOG.debug("Sending publish message to subscribers. MqttClientId = {}, topic = {}, messageId = {}, payload = {}, subscriptionTree = {}.",
if (LOG.isTraceEnabled()) {
LOG.trace("Sending publish message to subscribers. MqttClientId = {}, topic = {}, messageId = {}, payload = {}, subscriptionTree = {}.",
clientID, topic, msg.getMessageID(), DebugUtils.payload2Str(toStoreMsg.getMessage()),
subscriptions.dumpTree());
} else {
@@ -55,8 +55,8 @@ class Qos2PublishHandler extends QosPublishHandler {
String clientID = NettyUtils.clientID(channel);
toStoreMsg.setClientID(clientID);
if (LOG.isDebugEnabled()) {
LOG.debug("Sending publish message to subscribers. MqttClientId = {}, topic = {}, messageId = {}, payload = {}, subscriptionTree = {}.",
if (LOG.isTraceEnabled()) {
LOG.trace("Sending publish message to subscribers. MqttClientId = {}, topic = {}, messageId = {}, payload = {}, subscriptionTree = {}.",
clientID, topic, msg.getMessageID(), DebugUtils.payload2Str(toStoreMsg.getMessage()),
subscriptions.dumpTree());
} else {
@@ -119,18 +119,14 @@ class Qos2PublishHandler extends QosPublishHandler {
private void sendPubRec(String clientID, int messageID) {
if (LOG.isDebugEnabled()) {
LOG.debug("Sending PUBREC message. MqttClientId = {}, messageId = {}.", clientID, messageID);
}
LOG.debug("Sending PUBREC message. MqttClientId = {}, messageId = {}.", clientID, messageID);
PubRecMessage pubRecMessage = new PubRecMessage();
pubRecMessage.setMessageID(messageID);
connectionDescriptors.sendMessage(pubRecMessage,messageID, clientID);
}
private void sendPubComp(String clientID, int messageID) {
if (LOG.isDebugEnabled()) {
LOG.debug("Sending PUBCOMP message. MqttClientId = {}, messageId = {}.", clientID, messageID);
}
LOG.debug("Sending PUBCOMP message. MqttClientId = {}, messageId = {}.", clientID, messageID);
PubCompMessage pubCompMessage = new PubCompMessage();
pubCompMessage.setMessageID(messageID);
connectionDescriptors.sendMessage(pubCompMessage, messageID, clientID);
@@ -108,16 +108,16 @@ public class SubscriptionsStore {
m_sessionsStore = sessionsStore;
List<ClientTopicCouple> subscriptions = sessionsStore.listAllSubscriptions();
//reload any subscriptions persisted
if (LOG.isDebugEnabled()) {
LOG.debug("Reloading all stored subscriptions. SubscriptionTree = {}.", dumpTree());
if (LOG.isTraceEnabled()) {
LOG.trace("Reloading all stored subscriptions. SubscriptionTree = {}.", dumpTree());
}
for (ClientTopicCouple clientTopic : subscriptions) {
LOG.info("Re-subscribing client to topic. ClientId = {}, topicFilter = {}.", clientTopic.clientID, clientTopic.topicFilter);
add(clientTopic);
}
if (LOG.isDebugEnabled()) {
LOG.debug("The stored subscriptions have been reloaded. SubscriptionTree = {}.", dumpTree());
if (LOG.isTraceEnabled()) {
LOG.trace("The stored subscriptions have been reloaded. SubscriptionTree = {}.", dumpTree());
}
}
@@ -133,14 +133,12 @@ public class SubscriptionsStore {
couple.createdNode.addSubscription(newSubscription); //createdNode could be null?
//spin lock repeating till we can, swap root, if can't swap just re-do the operation
} while(!subscriptions.compareAndSet(oldRoot, couple.root));
if (LOG.isDebugEnabled()) {
LOG.debug("A subscription has been added. Root = {}, oldRoot = {}.", couple.root, oldRoot);
}
LOG.debug("A subscription has been added. Root = {}, oldRoot = {}.", couple.root, oldRoot);
}
protected NodeCouple recreatePath(String topic, final TreeNode oldRoot) {
List<Token> tokens = new ArrayList<>();
List<Token> tokens;
try {
tokens = parseTopic(topic);
} catch (ParseException ex) {