Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Unexpected number of invoices 0 for payment 9b91d324-7118-4cbd-9ea3-5ddacdab11da #4

Closed
husam-otri opened this issue Feb 28, 2016 · 7 comments
Closed

Unexpected number of invoices 0 for payment 9b91d324-7118-4cbd-9ea3-5ddacdab11da #4

husam-otri opened this issue Feb 28, 2016 · 7 comments
Assignees
@pierre
Labels
bug

Comments

@husam-otri
Copy link

Hi,

I upgraded killbill from (0.14.0 to 0.16.1) so i upgraded the plugin from 0.1.0 to 0.2.x but i have got this issue, seems the plugins can't read the new record in invoice_payments table although the record there !.

MariaDB [killbill]> select * from invoice_payments \G;
*************************** 1. row ***************************
                record_id: 1
                       id: 381f6299-0f05-4f5e-86c7-0e08752e1f6a
                     type: ATTEMPT
               invoice_id: 606dbcb2-0918-44f9-8746-2c3327fb6087
               payment_id: 9b91d324-7118-4cbd-9ea3-5ddacdab11da
             payment_date: 2016-02-28 13:53:39
                   amount: 3500.000000000
                 currency: USD
       processed_currency: USD
        payment_cookie_id: NULL
linked_invoice_payment_id: NULL
                  success: 1
               created_by: PaymentRequestProcessor
             created_date: 2016-02-28 13:53:39
        account_record_id: 1
         tenant_record_id: 1

MariaDB [killbill]> select * from payments \G;
*************************** 1. row ***************************
              record_id: 1
                     id: 9b91d324-7118-4cbd-9ea3-5ddacdab11da
             account_id: 5010b1a7-2089-48b8-9cdd-9bbadab41be8
      payment_method_id: e7f658aa-9bce-4d09-a2b8-5fd214752f26
           external_key: 2728f548-099d-4ded-8426-e7bbafd2ac05
             state_name: PURCHASE_SUCCESS
last_success_state_name: PURCHASE_SUCCESS
             created_by: PaymentRequestProcessor
           created_date: 2016-02-28 13:53:39
             updated_by: PaymentRequestProcessor
           updated_date: 2016-02-28 13:53:39
      account_record_id: 1
       tenant_record_id: 1
1 row in set (0.00 sec)

And also i can see there is new record in notification table:

MariaDB [killbill]> select * from notifications \G;
*************************** 1. row ***************************
                record_id: 1
               class_name: org.killbill.billing.invoice.notification.NextBillingDateNotificationKey
               event_json: {"uuidKey":"e16f9018-b8fa-4dd4-a2a8-5f6c2218a2f8","targetDate":"2016-03-28T13:53:39.000Z","isDryRunForInvoiceNotification":false}
               user_token: a5c22771-21e1-440a-af26-611bdb7cd92f
             created_date: 2016-02-28 13:53:39
           creating_owner: localhost.localdomain
         processing_owner: NULL
processing_available_date: NULL
         processing_state: AVAILABLE
              error_count: 0
              search_key1: 1
              search_key2: 1
               queue_name: invoice-service:next-billing-date-queue
           effective_date: 2016-03-28 13:53:39
        future_user_token: 3550c592-2175-4e65-91b1-440450179b59
1 row in set (0.01 sec)

could you please take a look, and let me know if i missed something,

Thanks in advance.

2016-02-28 15:53:42,663 [Thread-6] INFO  o.k.b.k.0.20.0 - [stripe-plugin] read 1622 bytes
2016-02-28 15:53:42,663 [Thread-6] INFO  o.k.b.k.0.20.0 - [stripe-plugin] Conn close
2016-02-28 15:53:42,663 [Thread-6] INFO  o.k.b.k.0.20.0 - [stripe-plugin] [ActiveMerchant::Billing::StripeGateway] --> 200 OK (1622 2.1810s)
2016-02-28 15:53:42,663 [Thread-6] INFO  o.k.b.k.0.20.0 - [stripe-plugin] [ActiveMerchant::Billing::StripeGateway] connection_attempt=1 connection_request_time=2.1830s connection_msg="success"
2016-02-28 15:53:42,667 [Thread-6] INFO  o.k.b.k.0.20.0 - [stripe-plugin] [ActiveMerchant::Billing::StripeGateway] connection_request_total_time=2.1830s
2016-02-28 15:53:42,901 [Thread-6] WARN  o.k.b.p.j.k.0.2.0 - Unexpected number of invoices 0 for payment 9b91d324-7118-4cbd-9ea3-5ddacdab11da
java.lang.IllegalArgumentException: Unexpected number of invoices 0 for payment 9b91d324-7118-4cbd-9ea3-5ddacdab11da
    at com.google.common.base.Preconditions.checkArgument(Preconditions.java:122)
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.sendEmailForPayment(EmailNotificationListener.java:222)
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.handleKillbillEvent(EmailNotificationListener.java:129)
    at org.killbill.killbill.osgi.libs.killbill.OSGIKillbillEventDispatcher$1.update(OSGIKillbillEventDispatcher.java:72)
    at org.killbill.billing.osgi.KillbillEventObservable.notifyObservers(KillbillEventObservable.java:70)
    at org.killbill.billing.osgi.KillbillEventObservable.setChangedAndNotifyObservers(KillbillEventObservable.java:83)
    at org.killbill.billing.osgi.KillbillEventObservable.handleKillbillEvent(KillbillEventObservable.java:78)
    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.EventSubscriber.handleEvent(EventSubscriber.java:74)
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchWithException(EventBusThatThrowsException.java:106)
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchQueuedEventsWithException(EventBusThatThrowsException.java:94)
    at com.google.common.eventbus.EventBusThatThrowsException.postWithException(EventBusThatThrowsException.java:82)
    at org.killbill.bus.DefaultPersistentBus.dispatchBusEventWithMetrics(DefaultPersistentBus.java:299)
    at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:40)
    at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:29)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:102)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:85)
    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:40)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
@husam-otri
Copy link
Author

I moved the issue to here: https://groups.google.com/forum/#!topic/killbilling-users/jGKr8Zcgjcw

please feel free to close this one

@pierre pierre self-assigned this Mar 1, 2016
@pierre pierre added the bug label Mar 1, 2016
@pierre
Copy link
Member

pierre commented Mar 2, 2016

Thanks for the report.

I traced the issue back to a race condition, where the plugin gets notified of the payment, before the invoice payment gets processed. The proper fix is to have the plugin listen to INVOICE_PAYMENT events, instead of PAYMENT events, but these have been introduced in 0.17.x (see killbill/killbill-plugin-api@15378c6#diff-32bc7a5d6f7332ed89ac18db23f1df62).

I'll try to come up with a work-around for 0.16.x.

pierre added a commit that referenced this issue Mar 2, 2016
@pierre
listener: retry in case of race condition bug
7e12c3e 
This is a workaround for #4:
when a race condition is detected, have the bus retry the dispatch.

Note that this only works when the persistent bus is used, i.e.
org.killbill.persistent.bus.external.inMemory=false.

Signed-off-by: Pierre-Alexandre Meyer <pierre@mouraf.org>
pierre added a commit that referenced this issue Mar 2, 2016
@pierre
listener: listen to INVOICE_PAYMENT events, not PAYMENT events
17f03b1 
This fixes #4.

Signed-off-by: Pierre-Alexandre Meyer <pierre@mouraf.org>
@pierre
Copy link
Member

pierre commented Mar 3, 2016

A work-around has been released with 0.2.1.

Note that upgrading to the new version requires a property change for Kill Bill versions 0.16.2 and below (details in #3 (comment)).

@pierre pierre closed this as completed Mar 3, 2016
@husam-otri
Copy link
Author

Ok, i've created new file /conf/killbill.properties and add the content (org.killbill.osgi.system.bundle.export.packages.api= .... ) as you you mentioned it in ticket #3
(and i assumed that killbill will automatically recognize this configuration without add anything in /conf/catalina.properties , is that right? if No, please let me know how i can make killbill recognize this config ), unfortunately the execution can't be pass after this condition for all attempts!, bellow i just pasted the last lines for the error, please let me know if you should scroll up and pasted more lines:

com.google.common.eventbus.EventBusException: java.lang.reflect.InvocationTargetException
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchWithException(EventBusThatThrowsException.java:108)
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchQueuedEventsWithException(EventBusThatThrowsException.java:94)
    at com.google.common.eventbus.EventBusThatThrowsException.postWithException(EventBusThatThrowsException.java:82)
    at org.killbill.bus.DefaultPersistentBus.dispatchBusEventWithMetrics(DefaultPersistentBus.java:299)
    at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:40)
    at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:29)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:102)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:85)
    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:40)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.reflect.InvocationTargetException: null
    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.EventSubscriber.handleEvent(EventSubscriber.java:74)
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchWithException(EventBusThatThrowsException.java:106)
    ... 13 common frames omitted
Caused by: java.lang.RuntimeException: org.killbill.billing.plugin.notification.setup.EmailNotificationListener$RaceConditionException
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.handleKillbillEvent(EmailNotificationListener.java:165)
    at org.killbill.killbill.osgi.libs.killbill.OSGIKillbillEventDispatcher$1.update(OSGIKillbillEventDispatcher.java:72)
    at org.killbill.billing.osgi.KillbillEventObservable.notifyObservers(KillbillEventObservable.java:70)
    at org.killbill.billing.osgi.KillbillEventObservable.setChangedAndNotifyObservers(KillbillEventObservable.java:83)
    at org.killbill.billing.osgi.KillbillEventObservable.handleKillbillEvent(KillbillEventObservable.java:78)
    ... 19 common frames omitted
Caused by: org.killbill.billing.plugin.notification.setup.EmailNotificationListener$RaceConditionException: null
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.sendEmailForPayment(EmailNotificationListener.java:231)
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.handleKillbillEvent(EmailNotificationListener.java:131)
    ... 23 common frames omitted
2016-03-05 18:03:48,999 [Thread-6] WARN  o.k.b.p.j.k.0.2.2 - Race condition detected for event DefaultBusExternalEvent{objectId=a7547b82-33ef-4fdf-9478-b7e6ea08c57b, accountId=ad5d0e75-4a51-4380-ad30-b1cdd1f16e4f, tenantId=9a72322b-7692-4c12-8bbb-5e9c36d679ef, objectType=PAYMENT, eventType=PAYMENT_SUCCESS}
org.apache.felix.log.LogException: org.killbill.billing.plugin.notification.setup.EmailNotificationListener$RaceConditionException: null
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.sendEmailForPayment(EmailNotificationListener.java:231)
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.handleKillbillEvent(EmailNotificationListener.java:131)
    at org.killbill.killbill.osgi.libs.killbill.OSGIKillbillEventDispatcher$1.update(OSGIKillbillEventDispatcher.java:72)
    at org.killbill.billing.osgi.KillbillEventObservable.notifyObservers(KillbillEventObservable.java:70)
    at org.killbill.billing.osgi.KillbillEventObservable.setChangedAndNotifyObservers(KillbillEventObservable.java:83)
    at org.killbill.billing.osgi.KillbillEventObservable.handleKillbillEvent(KillbillEventObservable.java:78)
    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.EventSubscriber.handleEvent(EventSubscriber.java:74)
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchWithException(EventBusThatThrowsException.java:106)
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchQueuedEventsWithException(EventBusThatThrowsException.java:94)
    at com.google.common.eventbus.EventBusThatThrowsException.postWithException(EventBusThatThrowsException.java:82)
    at org.killbill.bus.DefaultPersistentBus.dispatchBusEventWithMetrics(DefaultPersistentBus.java:299)
    at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:40)
    at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:29)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:102)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:85)
    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:40)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
2016-03-05 18:03:49,001 [bus_ext_events-th] ERROR o.k.q.d.CallableCallbackBase - Fatal NotificationQ dispatch error, data corruption...
com.google.common.eventbus.EventBusException: java.lang.reflect.InvocationTargetException
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchWithException(EventBusThatThrowsException.java:108)
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchQueuedEventsWithException(EventBusThatThrowsException.java:94)
    at com.google.common.eventbus.EventBusThatThrowsException.postWithException(EventBusThatThrowsException.java:82)
    at org.killbill.bus.DefaultPersistentBus.dispatchBusEventWithMetrics(DefaultPersistentBus.java:299)
    at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:40)
    at org.killbill.bus.dispatching.BusCallableCallback.dispatch(BusCallableCallback.java:29)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:102)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:85)
    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:40)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.reflect.InvocationTargetException: null
    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.EventSubscriber.handleEvent(EventSubscriber.java:74)
    at com.google.common.eventbus.EventBusThatThrowsException.dispatchWithException(EventBusThatThrowsException.java:106)
    ... 13 common frames omitted
Caused by: java.lang.RuntimeException: org.killbill.billing.plugin.notification.setup.EmailNotificationListener$RaceConditionException
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.handleKillbillEvent(EmailNotificationListener.java:165)
    at org.killbill.killbill.osgi.libs.killbill.OSGIKillbillEventDispatcher$1.update(OSGIKillbillEventDispatcher.java:72)
    at org.killbill.billing.osgi.KillbillEventObservable.notifyObservers(KillbillEventObservable.java:70)
    at org.killbill.billing.osgi.KillbillEventObservable.setChangedAndNotifyObservers(KillbillEventObservable.java:83)
    at org.killbill.billing.osgi.KillbillEventObservable.handleKillbillEvent(KillbillEventObservable.java:78)
    ... 19 common frames omitted
Caused by: org.killbill.billing.plugin.notification.setup.EmailNotificationListener$RaceConditionException: null
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.sendEmailForPayment(EmailNotificationListener.java:231)
    at org.killbill.billing.plugin.notification.setup.EmailNotificationListener.handleKillbillEvent(EmailNotificationListener.java:131)
    ... 23 common frames omitted
2016-03-05 18:03:49,071 [Thread-6] INFO  o.k.b.p.j.k.0.2.2 - Received event INVOICE_CREATION for object type = INVOICE, id = be9fc658-5098-45dd-89a4-4a03aa5cbf44

@pierre
Copy link
Member

pierre commented Mar 5, 2016

Ok, i've created new file /conf/killbill.properties and add the content (org.killbill.osgi.system.bundle.export.packages.api= .... ) as you you mentioned it in ticket #3
(and i assumed that killbill will automatically recognize this configuration without add anything in /conf/catalina.properties , is that right? if No, please let me know how i can make killbill recognize this config )

The property org.killbill.osgi.system.bundle.export.packages.api should be set similarly to how you configure your database connections for example. Typically, adding the line in conf/catalina.properties should be enough.

If you haven't setup Kill Bill with a killbill.properties file already (via the system property org.killbill.server.properties or by using KPM and/or Docker images), it won't be picked up automatically.

unfortunately the execution can't be pass after this condition for all attempts!

Yes, this is expected: the newly introduced exception will make Kill Bill retry sending the email. By the time it is retried, the race condition shouldn't exist anymore. You will see this stacktrace in 0.16.x, which will disappear when 0.17.x is released.

Could you confirm the email is eventually sent, despite the stacktrace?

@husam-otri
Copy link
Author

I installed killbill using KPM, so i've added org.killbill.osgi.system.bundle.export.packages.api=org.killbill.billing.account.api,org.killbill.billing.analytics.api.sanity,...,org.killbill.billing.invoice.api,org.killbill.billing.invoice.api.formatters,...;version=1.2.0 to /conf/catalina.properties then restarted tomcat again, but i'm getting the same problem, the execution can't be pass the condition for all attempts so the email won't be sent!.

@pierre
Copy link
Member

pierre commented Mar 5, 2016

The property change is related to #3. Without it, the plugin may throw NoClassDefFoundError (or similar errors) on InvoiceFormatter due to i18n changes. If you don't see errors related to InvoiceFormatter, the property has been taken into account.

As for this issue, the exception RaceConditionException is expected and is not an error. It is a work-around for this issue on 0.16.x. As described in #4 (comment), the plugin stops the execution, but Kill Bill detects the error and will retry the dispatch of the event. A subsequent time (most likely on the second try), the invoicePayments variable will contain one element.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@pierre pierre

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@pierre @husam-otri