KillBill 0.16.4 -> 0.16.5 Problem with Failed Payment for Invoice

[Nadya Kuzmina]

Hello,

When we upgaded from KillBill 0.16.4 to KillBill 0.16.5 (no problems in KillBill 0.16.4), we have noticed that on certain types of Payment Gateway failures for an invoice payment, Kaui produces the following error when trying to access the invoice to which the failed payment belongs:

Error while communicating with the Kill Bill server: Error 400

We are using Authorize.Net as our Payment Gateway. We have implemented an Authorize.Net Payment Gateway Plugin in Java which interacts with Authorize.Net.

Here is our erroneous scenario:

- Create a new account in Killbill with Auto Pay ON

- Add a payment method which results in an Error from Authorize.Net (Authorize.Net Code 2 -- This transaction has been declined.). This is the default payment method on the account.

- Create a new subscription

The new subscription triggers automatic invoice generation followed by a charge to the default payment method. The charge fails as expected.

When the invoice is clicked in Kaui, we see: Error while communicating with the Kill Bill server: Error 400

On a failed payment, the PaymentTransactionInfoPlugin object returned to KillBill contains:

pluginStatus = PaymentPluginStatus.ERROR
gatewayError = "Code 2 -- This transaction has been declined."
gatewayErrorCode = 2

In the database the record in the invoice_payments table contains NULL in the payment_id column.

Note that we did not experience this problem with Killbill 0.16.4.

We would appreciate your thoughts on how to address this scenario. Do we need to return a different pluginStatus or gatewayErrorCode in this situation? Also, which changes between Killbill versions would be likely to cause the above problem?

Thank you,

Nadya.

[Pierre-Alexandre Meyer]

Hello Nadya,

Could you share the stacktrace on the Kill Bill side? This would help narrow down the issue. On top of my head, I don't recall any bug fixed in 0.16.5 that would trigger this issue.

GatewayError and GatewayErrorCode are ignored by the system, so they shouldn't have any impact. A plugin status of ERROR is correct in your case (declined transaction).

On a related note, is the Authorize.Net plugin generic enough that you could open-source it? It would make it easier for us to review the code in case it's an implementation issue.

Thanks,

--
You received this message because you are subscribed to the Google Groups "Kill Bill users mailing-list" group.
To unsubscribe from this group and stop receiving emails from it, send an email to killbilling-us...@googlegroups.com.
To post to this group, send email to killbill...@googlegroups.com.
Visit this group at https://groups.google.com/group/killbilling-users.
To view this discussion on the web visit https://groups.google.com/d/msgid/killbilling-users/8f956250-8582-4469-ad08-0c9c72fdac50%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Pierre

[gpre...@womply.com]

> On a related note, is the Authorize.Net plugin generic enough that you could open-source it? It would make it easier for us to review the code in case it's an implementation issue.

Possibly at some point, but we're not there yet. We are implementing it to use Authorize.Net's CIM functionality (http://www.authorize.net/solutions/merchantsolutions/merchantservices/cim/) so we never store the actual credit card number locally, but rather a token that AuthNet generates.

-Greg

[Pierre-Alexandre Meyer]

On Mon, Jun 13, 2016 at 10:08 AM, <gpre...@womply.com> wrote:

Possibly at some point, but we're not there yet.  We are implementing it to use Authorize.Net's CIM functionality (http://www.authorize.net/solutions/merchantsolutions/merchantservices/cim/) so we never store the actual credit card number locally, but rather a token that AuthNet generates.

FYI, most open-source plugins implement both mechanisms (i.e. gateway tokenization and local PAN storage). The vast majority of Kill Bill users don't store the card numbers.

--

Pierre

[Nadya Kuzmina]

Hi Pierre,

Unfortunately, there is no Exception thrown in this case on KillBill's side. But the invoice_payments table row contains NULL in the payment_id column.

[Nadya Kuzmina]

Hi Pierre,

It turns out that the problem with failed payments in invoices seems to have been introduced in KillBill 0.16.4 (and works in KillBill 0.16.3).

KillBill 0.16.4 appears to have started saving invoice_payments in two stages:
Stage 1 (Before going out to the Payment Gateway plugin): save the invoice_payments record with payment_id as NULL
Stage 2 (After getting a response from Payment Gateway plugin): update the invoice_payments record with a (not-null) payment_id

The corresponding code is in DefaultPaymentDao.notifyOfPaymentCompletionInternal() method:

                    if (existingAttempt == null) {
                        transactional.create(invoicePayment, context); <-- Stage 1
                    } else if (!existingAttempt.getSuccess() && invoicePayment.getSuccess()) { <-- Stage 2
                        transactional.updateAttempt(existingAttempt.getRecordId(),
                                                    invoicePayment.getPaymentId().toString(),
                                                    invoicePayment.getPaymentDate().toDate(),
                                                    invoicePayment.getAmount(),
                                                    invoicePayment.getCurrency(),
                                                    invoicePayment.getProcessedCurrency(),
                                                    invoicePayment.getPaymentCookieId(),
                                                    null,
                                                    context);


The condition (!existingAttempt.getSuccess() && invoicePayment.getSuccess()) does the job for successful payments. However,
invoicePayment.getSuccess() is false for failed payments, so the corresponding invoice_payment record is never updated with a payment_id.

Is this a KillBill problem or are we missing something on our end?

Thank you,

Nadya.

[stephane brossier]

Nadya,

I think your assessment is correct. I created issue #560 to track it and assigned it in our next release. I'll take a closer look in the next few days and hopefully we can release something soon. 

Thanks for reporting the issue.

Stéphane

--
You received this message because you are subscribed to the Google Groups "Kill Bill users mailing-list" group.
To unsubscribe from this group and stop receiving emails from it, send an email to killbilling-us...@googlegroups.com.
To post to this group, send email to killbill...@googlegroups.com.
Visit this group at https://groups.google.com/group/killbilling-users.

To view this discussion on the web visit https://groups.google.com/d/msgid/killbilling-users/CAJ7PEMgzdt%3Dor91HOrEDw8xdc6jsY%2ByUMsaLeoy8Ccad2d%2BR9Q%40mail.gmail.com.

[stephane brossier]

Nadya,

Let me provide a bit of background into what is happening and then i would need a bit of help from your part to confirm the issue i am seeing is the same one you experience.

As you correctly figured out, we changed the protocol between the payment module and the invoice module (see #560) to rely on a 2-phase commit protocol (i can provide more details if this is of any interest) where the entry in invoice_payments is first recorded with a 'NULL' payment_id (because it is not known yet) and then, the row is updated after payment went through:

* In the 0.16.x train, this will only be updated if successful (which means in the case of failure to row will stay with a NULL value and should be ignored by the system. This is consistent with previous behavior in 0.16.3. However, it seems our code does not handle well the NULL case and this is the cause of your issue.

* In the 0.17.x train (not released yet), we introduced a success row and so both successful or failed transactions will appear in this table.

Could you confirm you are seeing the exception beloe when you click on your invoice in KAUI?

Stéphane

---

2016-06-14T16:15:36,868+0000 lvl='WARN', log='LoggingResponse', th='qtp2058424956-29', xff='', rId='a9077591-1c5e-4b81-aa09-494e5205d376', aRId='130', tRId='1', Bad request

java.lang.NullPointerException: null

at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:210)

at com.google.common.collect.SingletonImmutableSet.<init>(SingletonImmutableSet.java:47)

at com.google.common.collect.ImmutableSet.of(ImmutableSet.java:94)

at com.google.common.collect.ImmutableSet.copyOf(ImmutableSet.java:319)

at com.google.common.collect.ImmutableSet.copyOf(ImmutableSet.java:300)

at org.killbill.billing.jaxrs.resources.InvoiceResource.getPayments(InvoiceResource.java:559)

at org.killbill.commons.skeleton.metrics.TimedResourceInterceptor.invoke(TimedResourceInterceptor.java:67)

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:483)

at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)

at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205)

at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)

at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)

at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)

at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)

at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)

at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)

at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1542)

at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1473)

at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419)

at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409)

at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409)

at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:540)

at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:715)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

[Nadya Kuzmina]

Stéphane,

Yes, I am seeing the same Exception stack trace as you provided when I click on an invoice with a failed payment in KAUI in Killbill 0.16.5.

Thank you for the background on the issue. I will follow up with some questions shortly.

[Nadya Kuzmina]

Stéphane,

 

* In the 0.16.x train, this will only be updated if successful (which means in the case of failure to row will stay with a NULL value and should be ignored by the system. This is consistent with previous behavior in 0.16.3. However, it seems our code does not handle well the NULL case and this is the cause of your issue.

Interesting! So in 0.16.x an invoice is not associated with failed payments? In version 0.16.3 we are able to view a failed payment on the Invoice page in KAUI. I am attaching a snapshot of this case (invoice_with_failed_payments.png).

There are a couple of other places that have Exceptions in the case of a NULL payment_id in invoice_payments (in 0.16.5):

- In KAUI: given an invoice with a failed payment and an account with a balance > 0, when one clicks on 'Pay All Invoices' in Billing Info on the main Account page (http://<host>:8080/kaui/accounts/b0539ff2-a8aa-4dba-a23b-5cc2d46a9250/pay_all_invoices), I am seeing the Exception stack trace below (see Stacktrace1).


- Email Notification plugin: We have email notification plugin configured to send emails for invoice payments. When an invoice payment fails, the email notification plugin fails with the Exception stack trace below (see Stacktrace2).

 

* In the 0.17.x train (not released yet), we introduced a success row and so both successful or failed transactions will appear in this table.

In this case, will Kaui display a failed payment for an invoice, similar to the snapshot that I've attached?

Thank you,

Nadya.


Stacktrace1:

Kill Bill registers:

POST http://<host>:8080/1.0/kb/accounts/b0539ff2-a8aa-4dba-a23b-5cc2d46a9250/invoicePayments?externalPayment=false&paymentAmount=

And then logs:

org.killbill.billing.payment.api.PaymentApiException: Internal payment error : java.lang.NullPointerException
    at org.killbill.billing.payment.dispatcher.PaymentPluginDispatcher.dispatchWithExceptionHandling(PaymentPluginDispatcher.java:68)
    at org.killbill.billing.payment.core.sm.OperationCallbackBase.dispatchWithAccountLockAndTimeout(OperationCallbackBase.java:70)
    at org.killbill.billing.payment.core.sm.control.OperationControlCallback.doOperationCallback(OperationControlCallback.java:84)
    at org.killbill.automaton.DefaultOperation.run(DefaultOperation.java:51)
    at org.killbill.automaton.DefaultState.runOperation(DefaultState.java:80)
    at org.killbill.billing.payment.core.sm.PluginControlPaymentAutomatonRunner.run(PluginControlPaymentAutomatonRunner.java:123)
    at org.killbill.billing.payment.core.sm.PluginControlPaymentAutomatonRunner.run(PluginControlPaymentAutomatonRunner.java:104)
    at org.killbill.billing.payment.core.PluginControlPaymentProcessor.createPurchase(PluginControlPaymentProcessor.java:122)
    at org.killbill.billing.payment.api.DefaultPaymentApi.createPurchaseWithPaymentControl(DefaultPaymentApi.java:301)
    at org.killbill.billing.util.glue.KillbillApiAopModule$ProfilingMethodInterceptor$1.execute(KillbillApiAopModule.java:52)
    at org.killbill.commons.profiling.Profiling.executeWithProfiling(Profiling.java:33)
    at org.killbill.billing.util.glue.KillbillApiAopModule$ProfilingMethodInterceptor.invoke(KillbillApiAopModule.java:49)
    at org.killbill.billing.util.security.AopAllianceMethodInvocationAdapter.proceed(AopAllianceMethodInvocationAdapter.java:45)
    at org.apache.shiro.authz.aop.AuthorizingAnnotationMethodInterceptor.invoke(AuthorizingAnnotationMethodInterceptor.java:68)
    at org.killbill.billing.util.security.AopAllianceMethodInterceptorAdapter.invoke(AopAllianceMethodInterceptorAdapter.java:32)
    at org.killbill.billing.jaxrs.resources.JaxRsResourceBase.createPurchaseForInvoice(JaxRsResourceBase.java:461)
    at org.killbill.billing.jaxrs.resources.AccountResource.payAllInvoices(AccountResource.java:682)

    at org.killbill.commons.skeleton.metrics.TimedResourceInterceptor.invoke(TimedResourceInterceptor.java:67)
    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:497)

    at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
    at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205)
    at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
    at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
    at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
    at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
    at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
    at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
    at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1542)
    at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1473)
    at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419)
    at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409)
    at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409)
    at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:540)
    at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:715)

    at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)




Stacktrace2:

2016-06-14T18:22:34,283+0000 lvl='WARN', log='KillbillLogWriter', th='Thread-12', xff='', rId='', aRId='', tRId='', [org.killbill.killbill.osgi.libs.killbill.OSGIKillbillServiceReference@b00765c]Race condition detected for event DefaultBusExternalEvent{objectId=27fc97be-7e97-4f8e-9dde-0cee1ac1e7c1, accountId=b0539ff2-a8aa-4dba-a23b-5cc2d46a9250, tenantId=12e6a24a-2aab-4b34-abc7-5f1ab9e4af03, objectType=PAYMENT, eventType=PAYMENT_FAILED}
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:497)
    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:103)
    at org.killbill.queue.dispatching.Dispatcher$CallableQueue.call(Dispatcher.java:86)
    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)

 

[stephane brossier]

Nadya,

On Tue, Jun 14, 2016 at 11:37 AM, Nadya Kuzmina <nkuz...@womply.com> wrote:

Stéphane,

 

* In the 0.16.x train, this will only be updated if successful (which means in the case of failure to row will stay with a NULL value and should be ignored by the system. This is consistent with previous behavior in 0.16.3. However, it seems our code does not handle well the NULL case and this is the cause of your issue.

Interesting! So in 0.16.x an invoice is not associated with failed payments? In version 0.16.3 we are able to view a failed payment on the Invoice page in KAUI. I am attaching a snapshot of this case (invoice_with_failed_payments.png).

Ok, my bad... i am getting confused :-(  In  0.16.x (bug asides), an invoice **will still be** associated with failed payments. And hopefully i am taking care of the bug, so that should work in our next release. As a matter of fact, i just pushed a fix into master (if you are interested to build from source, you could verify whether or not i fixed the issue before i cut a release). Instructions:

> git clone https://github.com/killbill/killbill.git

> cd killbill

# war gets built under profiles/killbill/target/

> mvn -Dgpg.skip=true -DskipTests=true clean install

 

There are a couple of other places that have Exceptions in the case of a NULL payment_id in invoice_payments (in 0.16.5):

- In KAUI: given an invoice with a failed payment and an account with a balance > 0, when one clicks on 'Pay All Invoices' in Billing Info on the main Account page (http://<host>:8080/kaui/accounts/b0539ff2-a8aa-4dba-a23b-5cc2d46a9250/pay_all_invoices), I am seeing the Exception stack trace below (see Stacktrace1).

From the exception i see below, it seems to indicate your payment plugin is throwing the exception, but i don't see the exception. Could it be possible your plugin calls KB and hits the same NPE we already identified?

 

- Email Notification plugin: We have email notification plugin configured to send emails for invoice payments. When an invoice payment fails, the email notification plugin fails with the Exception stack trace below (see Stacktrace2).

 

The stack trace is expected for 0.16.x. There is a race condition for which we created a workaround in 0.16.x, hence the stack trace, but email should still be sent. Is the email sent?   Also, the issue will be fixed cleanly in 0.17.x.

I would suggest to deploy the code fix i just pushed (either building from source as indicated, or waiting for next release when it is out).

Stéphane

[Nadya Kuzmina]

Stéphane,

Thank you for the quick fix! We have compiled KillBill from source per your instructions and verified that it fixes our issue with failed payments in invoices.

We'd like to release the fixed version of KillBill into our production environment. When do you plan to make the next release?

Thank you!

[stephane brossier]

Nadya and Roberto,

I just released 0.16.6 which has the fix for #560 (and also updated the github issue to provide more context).

Let me know if you have any questions.

Stéphane

[Nadya Kuzmina]

Stéphane,

That's great! Thanks for the release! We will deploy it into our production.

A question about dependency management for KillBill eco-system:

Aside from killbill, we also depend on the following KillBill components:

        <killbill-base-plugin.version>0.3.1</killbill-base-plugin.version>
        <killbill-platform.version>0.21</killbill-platform.version>
        <killbill-plugin-api.version>0.18</killbill-plugin-api.version>

What is a proper way to manage these dependencies? Now that you made a new release of KillBill, should we also update these dependency versions to those of your latest killbill-oss-parent pom?

Thanks for all your help!

Nadya.

[stephane brossier]

The pom from the main killbill repo defines a killbill-oss-parent parent pom, which then specifies all the dependencies. In the case of 0.16.6 release, the parent pom is 0.94.1 (this will show you all the dependencies used for that version):

        <killbill-api.version>0.33</killbill-api.version>

        <killbill-base-plugin.version>0.3.3</killbill-base-plugin.version>

        <killbill-client.version>0.23.1</killbill-client.version>

        <killbill-commons.version>0.15</killbill-commons.version>

        <killbill-platform.version>0.26</killbill-platform.version>

        <killbill-plugin-api.version>0.18</killbill-plugin-api.version>

In most case you don't really need to know the details, the final war would come up with all the right deps; if you are writing plugins this is good to know, if for 0.16.x plugin-api should be stable.

Also, don't forget to check the #560 ticket in case you need to apply a data fix.

S.

[Nadya Kuzmina]

Thank you for the explanation, Stéphane.

We have custom KillBill plugins, so I will update the KillBill dependencies to be consistent with those of 0.16.6 release.