From 8be6e1e86b354dc5dcabeb03c1995497e8d969e4 Mon Sep 17 00:00:00 2001 From: Luis Barrios Date: Wed, 11 Jan 2017 15:56:24 +0100 Subject: [PATCH] Improve logging --- .../DefaultMoquetteSslContextCreator.java | 26 ++++++---- .../main/java/io/moquette/server/Server.java | 50 +++++++++++++++---- 2 files changed, 57 insertions(+), 19 deletions(-) diff --git a/broker/src/main/java/io/moquette/server/DefaultMoquetteSslContextCreator.java b/broker/src/main/java/io/moquette/server/DefaultMoquetteSslContextCreator.java index 37c5d8a1..5c14cace 100644 --- a/broker/src/main/java/io/moquette/server/DefaultMoquetteSslContextCreator.java +++ b/broker/src/main/java/io/moquette/server/DefaultMoquetteSslContextCreator.java @@ -49,11 +49,12 @@ class DefaultMoquetteSslContextCreator implements ISslContextCreator { @Override public SSLContext initSSLContext() { + LOG.info("Checking SSL configuration properties..."); final String jksPath = props.getProperty(BrokerConstants.JKS_PATH_PROPERTY_NAME); - LOG.info("Starting SSL using keystore at {}", jksPath); + LOG.info("Initializing SSL context. KeystorePath = {}.", jksPath); if (jksPath == null || jksPath.isEmpty()) { //key_store_password or key_manager_password are empty - LOG.warn("You have configured the SSL port but not the jks_path, SSL not started"); + LOG.warn("The keystore path is null or empty. The SSL context won't be initialized."); return null; } @@ -63,12 +64,12 @@ class DefaultMoquetteSslContextCreator implements ISslContextCreator { final String keyManagerPassword = props.getProperty(BrokerConstants.KEY_MANAGER_PASSWORD_PROPERTY_NAME); if (keyStorePassword == null || keyStorePassword.isEmpty()) { //key_store_password or key_manager_password are empty - LOG.warn("You have configured the SSL port but not the key_store_password, SSL not started"); + LOG.warn("The keystore password is null or empty. The SSL context won't be initialized."); return null; } if (keyManagerPassword == null || keyManagerPassword.isEmpty()) { //key_manager_password or key_manager_password are empty - LOG.warn("You have configured the SSL port but not the key_manager_password, SSL not started"); + LOG.warn("The key manager password is null or empty. The SSL context won't be initialized."); return null; } @@ -78,26 +79,33 @@ class DefaultMoquetteSslContextCreator implements ISslContextCreator { boolean needsClientAuth = Boolean.valueOf(sNeedsClientAuth); try { + LOG.info("Loading keystore. KeystorePath = {}.", jksPath); InputStream jksInputStream = jksDatastore(jksPath); SSLContext serverContext = SSLContext.getInstance("TLS"); final KeyStore ks = KeyStore.getInstance("JKS"); ks.load(jksInputStream, keyStorePassword.toCharArray()); + LOG.info("Initializing key manager..."); final KeyManagerFactory kmf = KeyManagerFactory.getInstance(KeyManagerFactory.getDefaultAlgorithm()); kmf.init(ks, keyManagerPassword.toCharArray()); TrustManager[] trustManagers = null; if (needsClientAuth) { + LOG.warn( + "Client authentication is enabled. The keystore will be used as a truststore. KeystorePath = {}.", + jksPath); // use keystore as truststore, as server needs to trust certificates signed by the server certificates TrustManagerFactory tmf = TrustManagerFactory.getInstance(TrustManagerFactory.getDefaultAlgorithm()); tmf.init(ks); trustManagers = tmf.getTrustManagers(); } // init sslContext + LOG.info("Initializing SSL context..."); serverContext.init(kmf.getKeyManagers(), trustManagers, null); - + LOG.info("The SSL context has been initialized successfully."); + return serverContext; } catch (NoSuchAlgorithmException | UnrecoverableKeyException | CertificateException | KeyStoreException | KeyManagementException | IOException ex) { - LOG.error("Can't start SSL layer!", ex); + LOG.error("Unable to initialize SSL context. Cause = {}, errorMessage = {}.", ex.getCause(), ex.getMessage()); return null; } } @@ -108,13 +116,13 @@ class DefaultMoquetteSslContextCreator implements ISslContextCreator { LOG.info("Starting with jks at {}, jks normal {}", jksUrl.toExternalForm(), jksUrl); return getClass().getClassLoader().getResourceAsStream(jksPath); } - LOG.info("jks not found in bundled resources, try on the filesystem"); + LOG.warn("No keystore has been found in the bundled resources. Scanning filesystem..."); File jksFile = new File(jksPath); if (jksFile.exists()) { - LOG.info("Using {} ", jksFile.getAbsolutePath()); + LOG.info("Loading external keystore. Url = {}.", jksFile.getAbsolutePath()); return new FileInputStream(jksFile); } - LOG.warn("File {} doesn't exists", jksFile.getAbsolutePath()); + LOG.warn("The keystore file does not exist. Url = {}.", jksFile.getAbsolutePath()); return null; } } diff --git a/broker/src/main/java/io/moquette/server/Server.java b/broker/src/main/java/io/moquette/server/Server.java index 51e195ba..dfcb2194 100644 --- a/broker/src/main/java/io/moquette/server/Server.java +++ b/broker/src/main/java/io/moquette/server/Server.java @@ -45,6 +45,8 @@ import java.util.Collections; import java.util.List; import java.util.Properties; +import static io.moquette.logging.LoggingUtils.getInterceptorIds; + /** * Launch a configured version of the server. * @author andrea @@ -68,7 +70,7 @@ public class Server { public static void main(String[] args) throws IOException { final Server server = new Server(); server.startServer(); - System.out.println("Server started, version 0.9-SNAPSHOT"); + LOG.info("Server started, version 0.9-SNAPSHOT"); //Bind a shutdown hook Runtime.getRuntime().addShutdownHook(new Thread() { @Override @@ -84,7 +86,9 @@ public class Server { * @throws IOException in case of any IO error. */ public void startServer() throws IOException { - IResourceLoader filesystemLoader = new FileResourceLoader(defaultConfigFile()); + File defaultConfigurationFile = defaultConfigFile(); + LOG.info("Starting Moquette server. Configuration file path = {}.", defaultConfigurationFile.getAbsolutePath()); + IResourceLoader filesystemLoader = new FileResourceLoader(defaultConfigurationFile); final IConfig config = new ResourceLoaderConfig(filesystemLoader); startServer(config); } @@ -100,7 +104,7 @@ public class Server { * @throws IOException in case of any IO Error. */ public void startServer(File configFile) throws IOException { - LOG.info("Using m_config file: " + configFile.getAbsolutePath()); + LOG.info("Starting Moquette server. Configuration file path = {}.", configFile.getAbsolutePath()); IResourceLoader filesystemLoader = new FileResourceLoader(configFile); final IConfig config = new ResourceLoaderConfig(filesystemLoader); startServer(config); @@ -119,6 +123,7 @@ public class Server { * @throws IOException in case of any IO Error. */ public void startServer(Properties configProps) throws IOException { + LOG.info("Starting Moquette server using properties object..."); final IConfig config = new MemoryConfig(configProps); startServer(config); } @@ -129,6 +134,7 @@ public class Server { * @throws IOException in case of any IO Error. */ public void startServer(IConfig config) throws IOException { + LOG.info("Starting Moquette server using IConfig instance..."); startServer(config, null); } @@ -140,6 +146,7 @@ public class Server { * @throws IOException in case of any IO Error. * */ public void startServer(IConfig config, List handlers) throws IOException { + LOG.info("Starting moquette server using IConfig instance and intercept handlers..."); startServer(config, handlers, null, null, null); } @@ -149,29 +156,37 @@ public class Server { if (handlers == null) { handlers = Collections.emptyList(); } + LOG.info("Starting Moquette Server. MQTT message interceptors = {}.", getInterceptorIds(handlers)); final String handlerProp = System.getProperty(BrokerConstants.INTERCEPT_HANDLER_PROPERTY_NAME); if (handlerProp != null) { config.setProperty(BrokerConstants.INTERCEPT_HANDLER_PROPERTY_NAME, handlerProp); } configureCluster(config); - LOG.info("Persistent store file: {}", config.getProperty(BrokerConstants.PERSISTENT_STORE_PROPERTY_NAME)); + LOG.info("Configuring Using persistent store file. Path = {}.", config.getProperty(BrokerConstants.PERSISTENT_STORE_PROPERTY_NAME)); m_processorBootstrapper = new ProtocolProcessorBootstrapper(); + LOG.info("Initializing MQTT protocol processor..."); final ProtocolProcessor processor = m_processorBootstrapper.init(config, handlers, authenticator, authorizator, this); if (sslCtxCreator == null) { + LOG.warn("Using default SSL context creator..."); sslCtxCreator = new DefaultMoquetteSslContextCreator(config); } + LOG.info("Binding server to the configured ports..."); m_acceptor = new NettyAcceptor(); m_acceptor.initialize(processor, config, sslCtxCreator); m_processor = processor; + + LOG.info("The Moquette server has been initialized successfully."); m_initialized = true; } private void configureCluster(IConfig config) throws FileNotFoundException { + LOG.info("Configuring embedded Hazelcast instance..."); String interceptHandlerClassname = config.getProperty(BrokerConstants.INTERCEPT_HANDLER_PROPERTY_NAME); if (interceptHandlerClassname == null || !HZ_INTERCEPT_HANDLER.equals(interceptHandlerClassname)) { + LOG.info("There are no Hazelcast intercept handlers. The server won't start a Hazelcast instance."); return; } String hzConfigPath = config.getProperty(BrokerConstants.HAZELCAST_CONFIGURATION); @@ -180,16 +195,17 @@ public class Server { Config hzconfig = isHzConfigOnClasspath ? new ClasspathXmlConfig(hzConfigPath) : new FileSystemXmlConfig(hzConfigPath); - LOG.info(String.format("starting server with hazelcast configuration file : %s",hzconfig)); + LOG.info("Starting Hazelcast instance. ConfigurationFile = {}.",hzconfig); hazelcastInstance = Hazelcast.newHazelcastInstance(hzconfig); } else { - LOG.info("starting server with hazelcast default file"); + LOG.info("Starting Hazelcast instance with default configuration."); hazelcastInstance = Hazelcast.newHazelcastInstance(); } listenOnHazelCastMsg(); } private void listenOnHazelCastMsg() { + LOG.info("Subscribing to Hazelcast topic. TopicName = {}.", "moquette"); HazelcastInstance hz = getHazelcastInstance(); ITopic topic = hz.getTopic("moquette"); topic.addMessageListener(new HazelcastListener(this)); @@ -208,24 +224,31 @@ public class Server { * */ public void internalPublish(PublishMessage msg) { if (!m_initialized) { - throw new IllegalStateException("Can't publish on a server is not yet started"); + LOG.error("The server is not started. The message cannot be published. MqttClientId = {}, messageId = {}.", + msg.getClientId(), msg.getMessageID()); + throw new IllegalStateException("Can't publish on a server is not yet started"); + } + if (LOG.isDebugEnabled()) { + LOG.debug("Publishing message. MqttClientId = {}, messageId = {}.", msg.getClientId(), msg.getMessageID()); } m_processor.internalPublish(msg); } public void stopServer() { - LOG.info("Server stopping..."); + LOG.info("Unbinding server from the configured ports..."); m_acceptor.close(); + LOG.info("Stopping MQTT protocol processor..."); m_processorBootstrapper.shutdown(); m_initialized = false; if (hazelcastInstance != null) { + LOG.info("Stopping embedded Hazelcast instance..."); try { hazelcastInstance.shutdown(); } catch (HazelcastInstanceNotActiveException e) { - LOG.info("hazelcast already shutdown"); + LOG.warn("The embedded Hazelcast instance is already shut down."); } } - LOG.info("Server stopped"); + LOG.info("The Moquette server has been stopped."); } /** @@ -248,8 +271,12 @@ public class Server { * */ public void addInterceptHandler(InterceptHandler interceptHandler) { if (!m_initialized) { + LOG.error("The server is not started. The MQTT message interceptor cannot be added. InterceptorId = {}.", + interceptHandler.getID()); throw new IllegalStateException("Can't register interceptors on a server that is not yet started"); + } + LOG.info("Adding MQTT message interceptor. InterceptorId = {}.", interceptHandler.getID()); m_processor.addInterceptHandler(interceptHandler); } @@ -260,8 +287,11 @@ public class Server { * */ public void removeInterceptHandler(InterceptHandler interceptHandler) { if (!m_initialized) { + LOG.error("The server is not started. The MQTT message interceptor cannot be removed. InterceptorId = {}.", + interceptHandler.getID()); throw new IllegalStateException("Can't deregister interceptors from a server that is not yet started"); } + LOG.info("Removing MQTT message interceptor. InterceptorId = {}.", interceptHandler.getID()); m_processor.removeInterceptHandler(interceptHandler); }