search

killbill / killbill

Open-Source Subscription Billing & Payments Platform
https://killbill.io
Apache License 2.0
4.59k stars 768 forks source link

Improve plugin lifecyle logging #1269

Open sbrossie opened 4 years ago

sbrossie commented 4 years ago

KAUI currently receives all the logs from KB (SSE) during install, start, stop, but unfortunately they are not very clear:

  1. Lots of those logs are low level OSGI logs that are not meaningful (bundle install -> printed when starting the plugin)
  2. There are not easy logs to understand that a given action was completed
  3. Errors: We should optimize for some easy errors, such as plugin no found
pierre commented 4 years ago

Closely related, if a plugin fails to start properly, it's not obvious to the user.

For instance, consider the following during the startup sequence:

2020-02-06T18:58:38,366+0000 lvl='INFO', log='FileInstall', th='localhost-startStop-1', xff='', rId='', tok='', aRId='', tRId='', Starting bundle file:/var/lib/killbill/bundles/plugins/java/stripe-plugin/7.0.3/stripe-plugin-7.0.3.jar
2020-02-06T18:58:38,367+0000 lvl='INFO', log='KillbillLogWriter', th='FelixDispatchQueue', xff='', rId='', tok='', aRId='', tRId='', [org.kill-bill.billing.killbill-platform-osgi-bundles-logger] BundleEvent STARTED
2020-02-06T18:58:38,382+0000 lvl='INFO', log='KillbillLogWriter', th='FelixDispatchQueue', xff='', rId='', tok='', aRId='', tRId='', [org.kill-bill.billing.plugin.java.stripe-plugin] BundleEvent RESOLVED
2020-02-06T18:58:39,401+0000 lvl='INFO', log='KillbillLogWriter', th='FelixDispatchQueue', xff='', rId='', tok='', aRId='', tRId='', [org.kill-bill.billing.plugin.java.stripe-plugin] BundleEvent STOPPED
2020-02-06T18:58:39,405+0000 lvl='WARN', log='FileInstall', th='localhost-startStop-1', xff='', rId='', tok='', aRId='', tRId='', Unable to start bundle
org.osgi.framework.BundleException: Activator start error in bundle org.kill-bill.billing.plugin.java.stripe-plugin [3].
        at org.apache.felix.framework.Felix.activateBundle(Felix.java:2204)
        at org.apache.felix.framework.Felix.startBundle(Felix.java:2072)
        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:976)
        at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:963)
        at org.killbill.billing.osgi.FileInstall.startBundle(FileInstall.java:258)
        at org.killbill.billing.osgi.BundleRegistry.startBundles(BundleRegistry.java:103)
        at org.killbill.billing.osgi.DefaultOSGIService.start(DefaultOSGIService.java:104)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.killbill.billing.lifecycle.DefaultLifecycle.doFireStage(DefaultLifecycle.java:156)
        at org.killbill.billing.lifecycle.DefaultLifecycle.fireSequence(DefaultLifecycle.java:143)
        at org.killbill.billing.lifecycle.DefaultLifecycle.fireStartupSequencePriorEventRegistration(DefaultLifecycle.java:84)
        at org.killbill.billing.server.listeners.KillbillPlatformGuiceListener.startLifecycle(KillbillPlatformGuiceListener.java:307)
        at org.killbill.billing.server.listeners.KillbillPlatformGuiceListener.contextInitialized(KillbillPlatformGuiceListener.java:129)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4745)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5207)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:752)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:728)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:988)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1860)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.AbstractMethodError: net.sf.log4jdbc.sql.jdbcapi.ConnectionSpy.getSchema()Ljava/lang/String;
        at org.killbill.billing.plugin.dao.PluginDao.<init>(PluginDao.java:76)
        at org.killbill.billing.plugin.dao.PluginDao.<init>(PluginDao.java:63)
        at org.killbill.billing.plugin.dao.payment.PluginPaymentDao.<init>(PluginPaymentDao.java:136)
        at org.killbill.billing.plugin.dao.payment.PluginPaymentDao.<init>(PluginPaymentDao.java:90)
        at org.killbill.billing.plugin.stripe.dao.StripeDao.<init>(StripeDao.java:56)
        at org.killbill.billing.plugin.stripe.StripeActivator.start(StripeActivator.java:47)
        at org.apache.felix.framework.util.SecureAction.startActivator(SecureAction.java:645)
        at org.apache.felix.framework.Felix.activateBundle(Felix.java:2154)
        ... 28 common frames omitted
2020-02-06T18:58:39,408+0000 lvl='INFO', log='DefaultLifecycle', th='localhost-startStop-1', xff='', rId='', tok='', aRId='', tRId='', Killbill lifecycle firing stage START_SERVICE

At this point, the user will see it stopped on Kaui. If the user attempts to start it, the error is cryptic:

2020-02-06T18:59:59,518+0000 lvl='INFO', log='BeatrixListener', th='bus_events-th', xff='', rId='', tok='', aRId='', tRId='0', Sending extBusEvent='DefaultBusExternalEvent{objectId=null, accountId=null, t
enantId=null, objectType=SERVICE_BROADCAST, eventType=BROADCAST_SERVICE}' from busEvent='DefaultBroadcastInternalEvent{serviceName='*****************', type='START_PLUGIN', jsonEvent='{"pluginKey":"stripe
","pluginName":***************,"pluginVersion":"7.0.3","properties":[{"key":"pluginType","value":null},{"key":"pluginUri","value":null},{"key":"forceDownload","value":false},{"key":"kbVersion","value":"0.
22.2"}]}'}'
2020-02-06T18:59:59,672+0000 lvl='ERROR', log='Killbill EventBus', th='bus_ext_events-th', xff='', rId='', tok='', aRId='', tRId='', Exception thrown by subscriber method handleKillbillEvent(org.killbill.
billing.notification.plugin.api.ExtBusEvent) on subscriber org.killbill.billing.osgi.OSGIListener@bfbe2ab when dispatching event: DefaultBusExternalEvent{objectId=null, accountId=null, tenantId=null, obje
ctType=SERVICE_BROADCAST, eventType=BROADCAST_SERVICE}
java.lang.IllegalStateException: Plugin stripe-plugin version 7.0.3 cannot be started because the version 7.0.3 already exists in the registry (state = 4)
        at org.killbill.billing.osgi.BundleRegistry.installAndStartNewBundle(BundleRegistry.java:73)
        at org.killbill.billing.osgi.OSGIListener.handleKillbillEvent(OSGIListener.java:109)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.google.common.eventbus.Subscriber.invokeSubscriberMethod(Subscriber.java:87)
        at com.google.common.eventbus.Subscriber$1.run(Subscriber.java:72)
        at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:398)
        at com.google.common.eventbus.Subscriber.dispatchEvent(Subscriber.java:67)
        at com.google.common.eventbus.Dispatcher$ImmediateDispatcher.dispatch(Dispatcher.java:186)
        at com.google.common.eventbus.EventBusThatThrowsException.postWithException(EventBusThatThrowsException.java:65)
        at org.killbill.bus.DefaultPersistentBus.dispatchBusEventWithMetrics(DefaultPersistentBus.java:376)
        at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:41)
        at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:30)
        at org.killbill.queue.dispatching.Dispatcher$CallableQueueHandler.call(Dispatcher.java:137)
        at org.killbill.queue.dispatching.Dispatcher$CallableQueueHandler.call(Dispatcher.java:105)
        at org.killbill.commons.concurrent.WrappedCallable.call(WrappedCallable.java:42)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:48)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)