Merge pull request #177 from vnandwana/sse

Enhanced logging in KPM package and added logger name to SSE endpoint logs.

Author: pierre

osgi-bundles/bundles/kpm/src/main/java/org/killbill/billing/osgi/bundles/kpm/KPMClient.java

@@ -33,9 +33,13 @@
 import org.killbill.billing.plugin.util.http.InvalidRequest;
 import org.killbill.billing.plugin.util.http.ResponseFormat;
 import org.killbill.commons.utils.Strings;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public class KPMClient extends HttpClient {
 
+    private final Logger logger = LoggerFactory.getLogger(KPMClient.class);
+
     public KPMClient(final boolean strictSSL,
                      final int connectTimeoutMs,
                      final int requestTimeoutMs) throws GeneralSecurityException {
@@ -44,8 +48,10 @@ public KPMClient(final boolean strictSSL,
 
     @Override
     protected Builder getBuilderWithHeaderAndQuery(final String verb, final String url, final Map<String, String> headers, final Map<String, String> queryParams) throws URISyntaxException {
+        logger.debug("Building request: verb={}, url={}, headers={}, queryParams={}", verb, url, headers, queryParams);
         final Builder builder = super.getBuilderWithHeaderAndQuery(verb, url, headers, queryParams);
         builder.setHeader("User-Agent", "KillBill/kpm-plugin/1.0");
+
         return builder;
     }
 
@@ -60,8 +66,13 @@ public void download(final String uri, final Path target) throws InvalidRequest,
     }
 
     public void download(final String uri, final Map<String, String> headers, final Path target) throws InvalidRequest, IOException, URISyntaxException, InterruptedException {
+        logger.info("Starting download: uri={}, target={}", uri, target);
         try (final InputStream is = doCall(GET, uri, null, Collections.emptyMap(), headers, InputStream.class, ResponseFormat.RAW)) {
             Files.copy(is, target, StandardCopyOption.REPLACE_EXISTING);
+            logger.info("Download completed: uri={}, target={}", uri, target);
+        } catch (final Exception e) {
+            logger.error("Download failed: uri={}, target={}, error={}", uri, target, e.getMessage(), e);
+            throw e;
         }
     }
 
@@ -96,6 +107,7 @@ public Path downloadToTempOS(final String url, final Map<String, String> headers
         } catch (final Exception e) {
             throw new RuntimeException(String.format("Error when GET request to '%s', because: %s", url, e.getMessage()), e);
         }
+
         return target;
     }
 
@@ -115,7 +127,7 @@ private Path createTarget(final String... names) {
                 }
             }
         } catch (final IOException ex) {
-            throw new RuntimeException("Cannot create temp file for downloaded file because: " + ex.getMessage());
+            throw new RuntimeException("Cannot create temp file for downloaded file because: " + ex.getMessage(), ex);
         }
     }
 }

osgi-bundles/bundles/kpm/src/main/java/org/killbill/billing/osgi/bundles/kpm/impl/DefaultPluginInstaller.java

@@ -47,6 +47,8 @@ public DefaultPluginInstaller(final PluginFileService pluginFileService) {
      */
     @Override
     public Path install(final Path downloadedFile, final String pluginKey, final String pluginVersion) throws KPMPluginException {
+        logger.info("Starting installation of plugin: {} version: {}", pluginKey, pluginVersion);
+
         try {
             // Make directory
             final Path pluginDirectory = pluginFileService.createPluginDirectory(pluginKey, pluginVersion);
@@ -56,17 +58,25 @@ public Path install(final Path downloadedFile, final String pluginKey, final Str
                                            pluginDirectory.resolve(PluginNamingResolver.of(pluginKey, pluginVersion).getPluginJarFileName()),
                                            StandardCopyOption.REPLACE_EXISTING);
 
+            logger.info("Copied plugin file to: {}", result);
+
             // Make symlink
             pluginFileService.createSymlink(pluginDirectory);
 
+            logger.info("Created symlink for plugin: {} version: {}", pluginKey, pluginVersion);
+
             return result;
         } catch (final IOException e) {
+            logger.error("Failed to install plugin: {} version: {} due to error: {}", pluginKey, pluginVersion, e.getMessage(), e);
+
             throw new KPMPluginException(String.format("Unable to install plugin with key: %s", pluginKey), e);
         }
     }
 
     @Override
     public Path uninstall(final String pluginKey, final String pluginVersion) throws KPMPluginException {
+        logger.info("Starting uninstallation of plugin: {} version: {}", pluginKey, pluginVersion);
+
         try {
             final PluginNamingResolver namingResolver = PluginNamingResolver.of(pluginKey, pluginVersion);
             // Example value: <bundlesPath>/plugins/java/some-plugins/1.2.3/
@@ -75,10 +85,11 @@ public Path uninstall(final String pluginKey, final String pluginVersion) throws
             final Path pluginFile = pluginDirectory.resolve(namingResolver.getPluginJarFileName());
             // Example value: <bundlesPath>/plugins/java/some-plugins/
             final Path parentOfPluginDir = pluginDirectory.getParent();
-            logger.debug("#uninstall() key{}-{}. Is Exists? dir:{}, file:{}", pluginKey, pluginVersion, Files.exists(pluginDirectory), Files.exists(pluginFile));
+
+            logger.debug("Uninstalling plugin: {} version: {}. Exists? dir: {}, file: {}", pluginKey, pluginVersion, Files.exists(pluginDirectory), Files.exists(pluginFile));
 
             FilesUtils.deleteRecursively(pluginDirectory);
-            logger.debug("#uninstall() Is still exists after deleteRecursively()? dir: {}, file: {}", Files.exists(pluginDirectory), Files.exists(pluginFile));
+            logger.info("Deleted plugin directory: {}", pluginDirectory);
 
             final String symlinkName = DefaultPluginFileService.DEFAULT_SYMLINK_NAME;
             try (final Stream<Path> stream = Files.list(parentOfPluginDir)) {
@@ -93,19 +104,23 @@ public Path uninstall(final String pluginKey, final String pluginVersion) throws
                         .filter(path -> !path.getFileName().toString().equals(symlinkName))
                         .max(Comparator.naturalOrder())
                         .orElse(null);
-                logger.debug("nextLatestPluginForKey: {}", nextLatestPluginForKey);
+
                 if (nextLatestPluginForKey != null) {
                     pluginFileService.createSymlink(nextLatestPluginForKey);
+                    logger.info("Updated symlink to point to: {}", nextLatestPluginForKey);
                     return nextLatestPluginForKey;
                 } else {
                     // Removed plugin is the last plugin by key. Delete the pluginKey directory
                     FilesUtils.deleteIfExists(parentOfPluginDir);
+                    logger.info("Deleted empty plugin directory: {}", parentOfPluginDir);
                 }
             }
         } catch (final IOException e) {
-            final String msg = String.format("Cannot uninstall: %s version: %s, because %s", pluginKey, pluginVersion, e.getMessage());
-            throw new KPMPluginException(msg, e);
+            logger.error("Failed to uninstall plugin: {} version: {} due to error: {}", pluginKey, pluginVersion, e.getMessage(), e);
+
+            throw new KPMPluginException(String.format("Cannot uninstall: %s version: %s", pluginKey, pluginVersion), e);
         }
+
         return null;
     }
 }

osgi-bundles/bundles/kpm/src/main/java/org/killbill/billing/osgi/bundles/kpm/impl/DefaultPluginManager.java

@@ -100,7 +100,7 @@ private void notifyFileSystemChange(final PluginStateChange newState,
                                         final String pluginKey,
                                         final String pluginVersion) {
         try {
-            logger.info("Notifying Kill Bill: state='{}', pluginKey='{}', pluginVersion={}", newState, pluginKey, pluginVersion);
+            logger.info("Notifying Kill Bill of plugin state change: state='{}', pluginKey='{}', pluginVersion={}", newState, pluginKey, pluginVersion);
 
             killbillApi.getSecurityApi().login(adminUsername, adminPassword);
 
@@ -110,6 +110,8 @@ private void notifyFileSystemChange(final PluginStateChange newState,
                                                                  pluginNamingResolver.getPluginName(),
                                                                  pluginVersion,
                                                                  null /* Unused */);
+
+            logger.info("Successfully notified Kill Bill of plugin state change: pluginKey={}, pluginVersion={}", pluginKey, pluginVersion);
         } finally {
             killbillApi.getSecurityApi().logout();
         }
@@ -118,6 +120,7 @@ private void notifyFileSystemChange(final PluginStateChange newState,
     @Override
     public GetAvailablePluginsModel getAvailablePlugins(@Nonnull final String kbVersion,
                                                         final boolean forceDownload) throws KPMPluginException {
+        logger.info("Fetching available plugins for Kill Bill version: {}, forceDownload: {}", kbVersion, forceDownload);
         final GetAvailablePluginsModel result = new GetAvailablePluginsModel();
 
         final VersionsProvider versionsProvider = availablePluginsComponentsFactory.createVersionsProvider(kbVersion, forceDownload);
@@ -133,14 +136,16 @@ public GetAvailablePluginsModel getAvailablePlugins(@Nonnull final String kbVers
                 .getPlugins();
         plugins.forEach(entry -> result.addPlugins(entry.getPluginKey(), entry.getPluginVersion()));
 
+        logger.info("Successfully fetched {} available plugins for Kill Bill version: {}", plugins.size(), kbVersion);
+
         return result;
     }
 
     @Override
     public void install(@Nonnull final String uri,
                         @Nonnull final String pluginKey,
                         @Nonnull final String pluginVersion) throws KPMPluginException {
-        logger.debug("Installing plugin via URL for key: {}, pluginVersion: {}, uri: {}", pluginKey, pluginVersion, uri);
+        logger.info("Starting installation of plugin: pluginKey={}, pluginVersion={}, uri={}", pluginKey, pluginVersion, uri);
 
         Path downloadedFile = null;
         final PluginNamingResolver namingResolver = PluginNamingResolver.of(pluginKey, pluginVersion, uri);
@@ -161,6 +166,7 @@ public void install(@Nonnull final String uri,
 
             notifyFileSystemChange(PluginStateChange.NEW_VERSION, pluginKey, fixedVersion);
 
+            logger.info("Plugin installed successfully: pluginKey={}, pluginVersion={}", pluginKey, pluginVersion);
         } catch (final InvalidRequest e) {
             String responseInfo = "";
             if (e.getResponse() != null) {
@@ -207,8 +213,8 @@ public void install(@Nonnull final String pluginKey,
                         String artifactId,
                         String pluginVersion,
                         final boolean forceDownload) throws KPMPluginException {
-        logger.info("Install plugin via coordinate. key:{}, kbVersion:{}, version:{}, groupId:{}, artifactId:{}",
-                    pluginKey, kbVersion, pluginVersion, groupId, artifactId);
+        logger.info("Starting coordinate-based plugin installation: " +
+                    "pluginKey={}, kbVersion={}, version={}, groupId={}, artifactId={}", pluginKey, kbVersion, pluginVersion, groupId, artifactId);
 
         DownloadResult downloadResult = null;
         Path installedPath = null;
@@ -230,9 +236,12 @@ public void install(@Nonnull final String pluginKey,
             pluginIdentifiersDAO.add(pluginKey, groupId, artifactId, pluginVersion);
 
             notifyFileSystemChange(PluginStateChange.NEW_VERSION, pluginKey, pluginVersion);
-            logger.info("Plugin key: {} installed successfully via coordinate.", pluginKey);
+
+            logger.info("Successfully installed plugin via coordinate: pluginKey={}, version={}", pluginKey, pluginVersion);
         } catch (final Exception e) {
-            logger.error("Error when install pluginKey: '{}' with coordinate. Exception: {}", pluginKey, e.getMessage());
+            logger.error("Error installing plugin via coordinate: pluginKey={}, version={}, error={}",
+                         pluginKey, pluginVersion, e.getMessage(), e);
+
             // If exception happened, installed file should be deleted.
             FilesUtils.deleteIfExists(installedPath);
             throw new KPMPluginException(e);
@@ -245,21 +254,30 @@ public void install(@Nonnull final String pluginKey,
 
     @Override
     public void uninstall(final String pluginKey, final String version) throws KPMPluginException {
-        // Uninstall from bundlesPath
-        final Path nextPluginByKey = pluginInstaller.uninstall(pluginKey, version);
-        // Update plugin_identifiers.json
-        final String nextPluginVersion = (nextPluginByKey == null || nextPluginByKey.getFileName() == null) ?
-                                         null :
-                                         PluginNamingResolver.getVersionFromString(nextPluginByKey.getFileName().toString());
-        if (Strings.isNullOrEmpty(nextPluginVersion)) {
-            // Last plugin by pluginKey. Just remove it.
-            pluginIdentifiersDAO.remove(pluginKey);
-        } else {
-            // Replace the version value
-            pluginIdentifiersDAO.add(pluginKey, nextPluginVersion);
-        }
+        logger.info("Starting uninstallation of plugin: pluginKey={}, version={}", pluginKey, version);
 
-        // What if notifyFileSystemChange() implementation fails? Like, wrong username/password?
-        notifyFileSystemChange(PluginStateChange.DISABLED, pluginKey, version);
+        try {
+            // Uninstall from bundlesPath
+            final Path nextPluginByKey = pluginInstaller.uninstall(pluginKey, version);
+            // Update plugin_identifiers.json
+            final String nextPluginVersion = (nextPluginByKey == null || nextPluginByKey.getFileName() == null) ?
+                                             null :
+                                             PluginNamingResolver.getVersionFromString(nextPluginByKey.getFileName().toString());
+            if (Strings.isNullOrEmpty(nextPluginVersion)) {
+                // Last plugin by pluginKey. Just remove it.
+                pluginIdentifiersDAO.remove(pluginKey);
+            } else {
+                // Replace the version value
+                pluginIdentifiersDAO.add(pluginKey, nextPluginVersion);
+            }
+
+            // What if notifyFileSystemChange() implementation fails? Like, wrong username/password?
+            notifyFileSystemChange(PluginStateChange.DISABLED, pluginKey, version);
+
+            logger.info("Successfully uninstalled plugin: pluginKey={}, version={}", pluginKey, version);
+        } catch (final Exception e) {
+            logger.error("Error uninstalling plugin: pluginKey={}, version={}, error={}", pluginKey, version, e.getMessage(), e);
+            throw new KPMPluginException("Uninstallation failed for plugin " + pluginKey, e);
+        }
     }
 }

osgi-bundles/bundles/logger/src/main/java/org/killbill/billing/osgi/bundles/logger/KillbillLogWriter.java

@@ -52,8 +52,10 @@ public KillbillLogWriter(final LogEntriesManager logEntriesManager, final Killbi
     public void log(final ServiceReference serviceReference, final int level, final String message, final Throwable exception) {
         final Bundle bundle = serviceReference == null ? null : serviceReference.getBundle();
 
+        final String loggerName = message.split("; ")[0];
+
         // Forward the log to HTTP consumers
-        logEntriesManager.recordEvent(new LogEntryJson(bundle, level, message, exception));
+        logEntriesManager.recordEvent(new LogEntryJson(bundle, level, loggerName, message, exception));
 
         if (serviceReference != null && "true".equals(serviceReference.getProperty("KILL_BILL_ROOT_LOGGING"))) {
             // LogEntry comes from Logback already (see OSGIAppender), ignore

osgi-bundles/bundles/logger/src/main/java/org/killbill/billing/osgi/bundles/logger/LogEntryJson.java

@@ -34,10 +34,11 @@ public class LogEntryJson {
     private final UUID id;
     private final String level;
     private final String name;
+    private final String logger;
     private final String message;
     private final Long time;
 
-    public LogEntryJson(final Bundle bundle, final int intLevel, final String message, final Throwable exception) {
+    public LogEntryJson(final Bundle bundle, final int intLevel, final String loggerName, final String message, final Throwable exception) {
         id = UUID.randomUUID();
 
         if (intLevel == LogService.LOG_ERROR) {
@@ -64,10 +65,15 @@ public LogEntryJson(final Bundle bundle, final int intLevel, final String messag
             name = bundle.getSymbolicName();
         }
 
+        this.logger = loggerName;
         this.message = message;
         this.time = System.currentTimeMillis();
     }
 
+    public String getLogger() {
+        return logger;
+    }
+
     public UUID getId() {
         return id;
     }
@@ -98,6 +104,7 @@ public String toString() {
             sb.append("\"id\":\"").append(id).append("\"");
             sb.append(", \"level\":\"").append(level).append("\"");
             sb.append(", \"name\":\"").append(name).append("\"");
+            sb.append(", \"logger\":\"").append(logger).append("\"");
             sb.append(", \"message\":\"").append(message).append("\"");
             sb.append(", \"time\":\"").append(time).append("\"");
             sb.append('}');

osgi/src/main/java/org/killbill/billing/osgi/OSGIAppender.java

@@ -81,7 +81,11 @@ protected void append(final ILoggingEvent eventObject) {
             }
         }
 
-        logService.log(SR, level, eventObject.getFormattedMessage(), t);
+        final String loggerName = eventObject.getLoggerName();
+
+        final String msg = loggerName + "; " + eventObject.getFormattedMessage();
+
+        logService.log(SR, level, msg, t);
     }
 
     private static final class RootBundleLogbackServiceReference implements ServiceReference {