"Failed to acquire lock"; no invoicing and database abnormal growth

[Leonardo Scattola]

Hi everybody!
We're experiencing a strange issue on our KB installation: when we create a subscription, the invoice isn't being issue because of a lock exception.
We tried to raise the number of attempts to 200 but the behaviour hasn't changed.

You may find a striped-out log fragment at https://hub-share.thron.com/content/?id=580b8ec1-86f3-4893-9016-0d681210a890&pkey=yX0zx1; however, this is what we do.

1. The account has the "null" payment method as default; this has been assigned upon the account's creation.

2. (requests 29, 30) we stop the auto invoicing system by getting the correct tag id for AUTO_INVOICING_OFF (request 29) and applying it to the account (request 30).

3. (request 34) we create a new subscription for the product we need; for a test (request 35) we check that the subscription has indeed been created.

4. (request 36) for a test we check that the account has the correct payment method

5. (requests 37 and 38) we remove the AUTO_INVOICING_OFF tag (check step 2. above)

After restarting the auto invoicing process we receive a "failed to acquire lock" exception:

2016-10-26 08:03:57,815 [bus_events-th] WARN o.k.commons.locker.GlobalLockerBase - Failed to acquire lock f6863f30-b181-49f4-a4bf-b7dbf9a87f38 for service ACCNT_INV_PAY after 200 retries
2016-10-26 08:03:57,815 [bus_events-th] ERROR o.k.b.invoice.InvoiceDispatcher - Failed to process invoice for account f6863f30-b181-49f4-a4bf-b7dbf9a87f38, targetDate 2016-10-26T08:03:36.000Z
org.killbill.commons.locker.LockFailedException: null
at org.killbill.commons.locker.GlobalLockerBase.lockWithNumberOfTries(GlobalLockerBase.java:69)
at org.killbill.billing.invoice.InvoiceDispatcher.processAccount(InvoiceDispatcher.java:211)
at org.killbill.billing.invoice.InvoiceDispatcher.processSubscriptionInternal(InvoiceDispatcher.java:199)
at org.killbill.billing.invoice.InvoiceDispatcher.processSubscriptionForInvoiceGeneration(InvoiceDispatcher.java:174)
at org.killbill.billing.invoice.InvoiceDispatcher.processSubscriptionForInvoiceGeneration(InvoiceDispatcher.java:170)
at org.killbill.billing.invoice.InvoiceListener.handleSubscriptionTransition(InvoiceListener.java:89)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
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:262)
at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:40)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

We also noticed that the database tables, in particular the `invoice_items` one, keep growing at a steady pace and with couples of related "RECURRING" / "REPAIR_ADJ" rows.

In the log file you will see other curious exceptions (NPEs and others) that I can't explain.

What should we check first? Is there a way to rebuild the subscriptions and invoices list?

Thank you in advance,

Leonardo

[Leonardo Scattola]

Hi everyone!
I've quickly scanned the code and I can't find where the lock is released. I suppose this is a MySQL lock, so it would last as long as the JDBC connection is up; am I wrong?

Thank you,

Leonardo

[stephane brossier]

Leonardo,

Which KB version are you using?

Which database are you using? Which version?

Also looking at your log, it seems you have lots of subscriptions created, but your steps seems to indicate you only created one?

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/b9ff1dac-fbf6-4bef-b0ec-f414b875e3a5%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[stephane brossier]

Leonardo,

FYI: The code to release the lock can be found here (finally clause). If you want to look at the lock implementation itself, you can find it here

Note that releasing the lock can happen in two ways:

1. The code explicitly calls release (previous link)

2. The database connection breaks (e.g database goes down, switch to new master, networking issue?). In that case, MYSQL will ensure that from its point of view the lock is not help (which means subsequent user should be able to acquire the lock).

It would be very interesting to dig deeper and understand why acquiring the lock fails. If you could reproduce and provide any pointer that would be great.

I am suspecting the large amount of invoice/ items created has to do with that lock failure, but reading the code, this is not obvious. Probably we should debug more on the locking issue first, and then understand what the side effect of that issue is.

Stéphane

Leonardo

--
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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/aace2ef0-632f-4515-aa17-8a86dae7c996%40googlegroups.com.

[Leonardo Scattola]

Stéphane,

thank you for your prompt response.

We're using version 0.16.9, with a database migrated from 0.14 following the instructions on https://github.com/killbill/killbill/wiki/Kill-Bill-Migration-0.14.x-to-0.16.x.

You're right: there are many subscriptions (it's our development platform); in this test case I am showing what happens with one subscription only. However, we experience the very same behaviour (exceptions on locks) on our other platforms (quality and production).

I was checking the code related to the lock release process and I was placing some breakpoints around it; my feeling is that the lock.release() invocation somehow fails to release the lock on MySQL. I'll report on this later.

Thank you again,

Leonardo

[Leonardo Scattola]

Stéphane, all,

as I said yesterday, my "invoice_items" table has become huge (more than 860k rows) and many of them are REPAIR_ADJ (225k). This makes me think (sorry, but I don't know the innards of KB very well, so I'm just supposing): perhaps, while trying to create an invoice, a process grabs hold of the lock and "never" (or only after a LONG time) releases it; some other process tries to create an invoice and starts adding new rows on the invoice_items table, but since the invoice cannot be created (because of the impossibility to get the lock) the system issues an equal number of REPAIR_ADJ rows and retries the cycle.

I'm connected on a debug session to my Tomcat and I'm looking at the current AccountItemTree.getLInkedInvoiceItem execution; the size of allItems is more than 375k rows (!), and I suppose that much of the waiting time I'm experiencing is because of this amount of rows.

Is it possible to remove all the duplicate invoice rows somehow? (for example, finding all of the REPAIR_ADJ rows which have a corresponding FIXED or RECURRING and deleting the couple)

Thank you,

Leonardo

[Leonardo Scattola]

Stéphane, all,

a quick update on this issue.
I created a backup on my DB and removed all the "duplicate rows" in the invoice_items table (check my last post on the argument). Some of the invoices have now been created, so I suppose that it's indeed a matter of workload.

I feel now that if the machine hasn't enough firepower (either on the DB side or the Tomcat side) the situation will get worse and worse, since (correct me if I'm wrong) the invoice items will be churned and re-created at the next invoice issue cycle.

Could it be just a matter of insufficient performance? If so, even if we're talking about the development server, I'd be very much worried... since we're experiencing the very same problems on the production site, which is surely bigger (at least on the Tomcat side).

Regards,

Leonardo

[stephane brossier]

Leonardo,

This is for sure not a matter of power. I think the main issue is that you are hitting an NPE in the generation of the billing events, and our code is not hardened enough to handle that case gracefully so then later such billing events are incomplete and invoicing does not correctly generate the items. As a side effect, code keeps regenerating/repairing same items, and then as a side effect, generation takes a long time creating then other issues.

I already committed a fix (not released yet). that i think would fix the invoicing issue.

What i don't know is why you get an NPE (i would need to have access to your data on disk). Most probably there was an issue at some point that creating some data that the code does not know how to handle gracefully.

Your could export such data and send it to me using the export endpoint:

curl -v \

-u admin:password \

-H "X-Killbill-ApiKey: XXXXX" \

-H "X-Killbill-ApiSecret: XXXXX" \

-H "X-Killbill-CreatedBy: something" \

-H "Content-Type: text/plain" \

"http://127.0.0.1:8080/1.0/kb/export/<account_id>"

Stéphane

--

2016-10-26 08:24:47,628 [notifications-th] WARN  o.k.b.j.p.b.DefaultInternalBillingApi - Failed while getting BillingEvent

java.lang.NullPointerException: null

at org.killbill.billing.junction.plumbing.billing.BillCycleDayCalculator.calculateBcd(BillCycleDayCalculator.java:73)

at org.killbill.billing.junction.plumbing.billing.DefaultInternalBillingApi.addBillingEventsForSubscription(DefaultInternalBillingApi.java:200)

at org.killbill.billing.junction.plumbing.billing.DefaultInternalBillingApi.addBillingEventsForBundles(DefaultInternalBillingApi.java:161)

at org.killbill.billing.junction.plumbing.billing.DefaultInternalBillingApi.getBillingEventsForAccountAndUpdateAccountBCD(DefaultInternalBillingApi.java:107)

at org.killbill.billing.invoice.InvoiceDispatcher.processAccountWithLock(InvoiceDispatcher.java:235)

at org.killbill.billing.invoice.InvoiceDispatcher.processAccount(InvoiceDispatcher.java:213)

at org.killbill.billing.invoice.InvoiceDispatcher.processSubscriptionInternal(InvoiceDispatcher.java:199)

at org.killbill.billing.invoice.InvoiceDispatcher.processSubscriptionForInvoiceGeneration(InvoiceDispatcher.java:174)

at org.killbill.billing.invoice.InvoiceListener.handleNextBillingDateEvent(InvoiceListener.java:130)

at org.killbill.billing.invoice.notification.DefaultNextBillingDateNotifier.processEventForInvoiceGeneration(DefaultNextBillingDateNotifier.java:123)

at org.killbill.billing.invoice.notification.DefaultNextBillingDateNotifier.access$400(DefaultNextBillingDateNotifier.java:40)

at org.killbill.billing.invoice.notification.DefaultNextBillingDateNotifier$1.handleReadyNotification(DefaultNextBillingDateNotifier.java:93)

at org.killbill.notificationq.NotificationQueueDispatcher.handleNotificationWithMetrics(NotificationQueueDispatcher.java:203)

at org.killbill.notificationq.dispatching.NotificationCallableCallback.dispatch(NotificationCallableCallback.java:51)

at org.killbill.notificationq.dispatching.NotificationCallableCallback.dispatch(NotificationCallableCallback.java:32)

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

at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:40)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

at java.lang.Thread.run(Thread.java:745)

2016-10-26 08:24:47,629 [notifications-th] WARN  o.k.

--

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/7b07dcf6-298e-4950-a1b1-009d1f78ea64%40googlegroups.com.

[Leonardo Scattola]

Stéphane,

thank you again for your precious hints.

I've performed the call to the export endpoint; you can find this report at https://hub-share.thron.com/content/?id=03c2f2b7-e874-4fd1-8c00-e12a2d47b258&pkey=5G98z2

Meanwhile, I'll perform these actions:

• apply your fix on the code on the development platform
• create a new, clean KB instance (a new DB, another KB instance on a different server)
• re-create the accounts and subscriptions basing on what is currently on the development server
• monitor the situation

Regards,

Leonardo

[Pierre-Alexandre Meyer]

Leonardo,

Could you share your catalog as well? This would help the debugging.

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/26a35e1d-a3ef-460b-8fe1-5c11a95a490c%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Pierre

[stephane brossier]

Leonardo,

Any update on the issue?

Stéphane

On Fri, Oct 28, 2016 at 8:26 AM, Pierre-Alexandre Meyer <pie...@kill-bill.org> wrote:

Leonardo,

Could you share your catalog as well? This would help the debugging.

Thanks!

To view this discussion on the web visit https://groups.google.com/d/msgid/killbilling-users/CAKXgekr%2BnWL_xE1hWOueGxSa2Y1q4JBpJGs%3DvMv%3DX21UD%2Bp%2B_A%40mail.gmail.com.

[Leonardo Scattola]

Stéphane, Pierre,

sorry for the delay.

You may find the whole list of catalogs at this link: https://hub-share.thron.com/content/?id=9237d1c3-0878-41ad-a2fd-69e10954de8a&pkey=vzyj6f

All of these catalogs are currently present; each of them starts on a different timestamp.

From THRONCatalog20160928 onwards we extended the products range and added a series of different currencies, since we need to set a "contract duration" on our customers,

In the meanwhile, we are setting up a script which will help us to try and migrate the customers and their subscriptions on a different DB.

Thank you again,

Il giorno mercoledì 2 novembre 2016 02:59:15 UTC+1, stephane brossier ha scritto:

Leonardo,

Any update on the issue?

Stéphane

On Fri, Oct 28, 2016 at 8:26 AM, Pierre-Alexandre Meyer <pie...@kill-bill.org> wrote:

Leonardo,

Could you share your catalog as well? This would help the debugging.

Thanks!

On Fri, Oct 28, 2016 at 12:02 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

Stéphane,

thank you again for your precious hints.

I've performed the call to the export endpoint; you can find this report at https://hub-share.thron.com/content/?id=03c2f2b7-e874-4fd1-8c00-e12a2d47b258&pkey=5G98z2

Meanwhile, I'll perform these actions:

• apply your fix on the code on the development platform
• create a new, clean KB instance (a new DB, another KB instance on a different server)
• re-create the accounts and subscriptions basing on what is currently on the development server
• monitor the situation

Regards,

Leonardo

--
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/26a35e1d-a3ef-460b-8fe1-5c11a95a490c%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Pierre

--
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.

[Pierre-Alexandre Meyer]

On Wed, Nov 2, 2016 at 12:29 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

You may find the whole list of catalogs at this link: https://hub-share.thron.com/content/?id=9237d1c3-0878-41ad-a2fd-69e10954de8a&pkey=vzyj6f

All of these catalogs are currently present; each of them starts on a different timestamp.

Thank you, this does help.

I see that omniChannelDam-smallBusiness-monthly was introduced on 2016-09-28. Yet, subscription id 672978cd-c0ba-48ac-914e-54b33550df90 effective on 2016-07-07 is subscribed to this plan.

Could you confirm what I'm seeing? Am I missing a catalog version?

--

Pierre

[Leonardo Scattola]

Pierre,

Il giorno mercoledì 2 novembre 2016 09:25:57 UTC+1, Pierre-Alexandre Meyer ha scritto:

Could you confirm what I'm seeing? Am I missing a catalog version?

my bad! You were indeed missing a catalog in the archive; I've updated the ZIP file at the same link by adding the missing catalog (THRONCatalog20160702.xml)

Thank you again,

Leonardo 

[Pierre-Alexandre Meyer]

On Wed, Nov 2, 2016 at 2:27 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

my bad! You were indeed missing a catalog in the archive; I've updated the ZIP file at the same link by adding the missing catalog (THRONCatalog20160702.xml)

Great, I was able to load that subscription but I'm having a similar problem with c270d5c6-18d6-4eb8-896a-fc09c53c5c14 (effective 2016-07-07 12:37:27). additionalStorage-1TB-annual was introduced on 2016-09-28.

--

Pierre

[Pierre-Alexandre Meyer]

On Thu, Oct 27, 2016 at 9:19 PM, stephane brossier <step...@kill-bill.org> wrote:

What i don't know is why you get an NPE (i would need to have access to your data on disk). Most probably there was an issue at some point that creating some data that the code does not know how to handle gracefully.

It looks like the NPE is caused by https://github.com/killbill/killbill/issues/619. Subscription with id e79b5260-e8c9-47e0-aafc-e91071f9e5c7 for example has 3 CANCEL events.

@Stephane: I don't think the fix was back-ported into 0.16.x - we might have to consider it for 0.16.10.

@Leonardo: In the meantime, the GitHub issue has a query to fix the data (make sure to test it in a QA environment first).

--

Pierre

[Leonardo Scattola]

Pierre, thank you! I updated again the catalogs ZIP archive; on 2016-07-02 we had *two* catalogs updates. You can find them both in the archive.

Thank you again,

Leonardo

[Leonardo Scattola]

Pierre, 

Il giorno mercoledì 2 novembre 2016 10:50:10 UTC+1, Pierre-Alexandre Meyer ha scritto:

@Leonardo: In the meantime, the GitHub issue has a query to fix the data (make sure to test it in a QA environment first).

I can confirm that the query used to detect the multiple cancel events on our development site returned eight elements; however, on our other sites (quality and production) no rows were returned.

We're going on with the migration script in the meanwhile.

[Pierre-Alexandre Meyer]

On Wed, Nov 2, 2016 at 4:30 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

I can confirm that the query used to detect the multiple cancel events on our development site returned eight elements; however, on our other sites (quality and production) no rows were returned.

Quick follow-ups:

• Is the subscription e79b5260-e8c9-47e0-aafc-e91071f9e5c7 from production or development? It should be returned by the query
  
• Do you still see the NPE that Stéphane mentioned above in your production logs?

--

Pierre

[Leonardo Scattola]

Pierre,

Il giorno mercoledì 2 novembre 2016 12:34:56 UTC+1, Pierre-Alexandre Meyer ha scritto:

• Is the subscription e79b5260-e8c9-47e0-aafc-e91071f9e5c7 from production or development? It should be returned by the query
  

These subscriptions come all from our development platform.

• Do you still see the NPE that Stéphane mentioned above in your production logs?

We haven't updated the production WAR yet; I'll finish the tests on the quality site in the afternoon and will report afterwards.

Thank you,

Leonardo

[Leonardo Scattola]

Hello everyone,

I have created a script which performs the following steps:

1. get the accounts list on the source KB
2. for each account
1. create a new account on the destination KB, attaching the default "null payment" plugin
2. stop the invoicing on the destination account (attaching the correct tag)
3. get the bundles and subscriptions on the source KB for this account
4. for each bundle
1. create a new series of subscriptions on the destination and join them into a new bundle; the request date for the new subscriptions will be the one stated in the source bundle
2. if one or more of these subscriptions has been cancelled, cancel it on the destination too; the cancellation date for the new subscriptions will be the one stated in the source bundle
5. restart the invoicing (removing the correct tag)

The destination KB is a new, clean instance on a separate, clean DB.

The script appears to be working and the number of accounts and subscriptions seems to match. However, the destination KB is starting to evaluate the billing for the new subscriptions and in the logs I've seen many such rows:

2016-11-03T11:32:18,494+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,526+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,550+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,578+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,602+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,630+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,661+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,690+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,715+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,738+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,770+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,793+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,818+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

2016-11-03T11:32:18,846+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='e2d8f4a7-c56b-4cbf-bd63-2e6562b27a25', subscriptionStartDate='2116-01-13T10:14:31.000Z', accountTimeZone='UTC', bcd='13'

Why are the subscription start dates in the next century? ... I'm puzzled.

[Leonardo Scattola]

Hello everyone,

regarding the BCD calculation in the future I am getting the same behaviour on the production server:

2016-11-03T06:33:27,449+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='14', tRId='1', Calculated BCD: subscriptionId='f599a5d6-6ecf-4bae-b5d0-1925efdf52d1', subscriptionStartDate='2116-02-10T14:56:05.000Z', accountTimeZone='UTC', bcd='10'

2016-11-03T06:33:27,449+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='14', tRId='1', Calculated BCD: subscriptionId='f599a5d6-6ecf-4bae-b5d0-1925efdf52d1', subscriptionStartDate='2116-02-10T14:56:05.000Z', accountTimeZone='UTC', bcd='10'

2016-11-03T06:33:28,012+0000 lvl='INFO', log='DefaultInternalBillingApi', th='notifications-th', xff='', rId='', aRId='14', tRId='1', Computed billing events for accountId='8f226f40-a709-4924-9965-d5f9f3ab0737'

I am not sure if these rows are being originated after the deploy of the version 0.16.10 (which I have performed this morning), but the case is strange: in the previous tests we were operating on a brand new, clean installation, but we have performed no tests or other activities on the production server (apart from the deploying of this new version).

Thank you,

Leonardo

[stephane brossier]

Leonardo,

Are you seeing that on all subscriptions or just some isolated cases?

Are those for the same (catalog) Plan? 

Is that a new behavior in 0.16.10?

Also, could you provide the following detail for this use case:

> select * from subscription_events where subscription_id = 'f599a5d6-6ecf-4bae-b5d0-1925efdf52d1';

A detail of the Plan entry in your catalog matching that subscription.

Thanks,

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/3727387d-9388-46f8-a187-dd9645b33aed%40googlegroups.com.

[Leonardo Scattola]

Stéphane,

thank you for your prompt response.

Are you seeing that on all subscriptions or just some isolated cases?

It seems like these rows are being originated for some cases only; a quick, non-exhausting search on our current log file shows that there are at least 15 different subscriptions:

• f599a5d6-6ecf-4bae-b5d0-1925efdf52d1
• a365ef70-1577-4fef-a160-dd4b0060dd5f
• 8e8f7f1e-716d-48f7-94e1-bccfa23c9845
• ff6d4c35-707a-4e93-950d-8e4e2d8922b2
• 71f965b3-0ad9-4094-92c2-854f0026dfe3
• b5524e83-9bd9-40ac-8eca-eaa50b71b2e9
• bf5ecf56-00bd-46f7-872a-4243d36a2fec
• c86c5f3e-b302-45c2-941f-892b36c75e8a
• 932ae5fc-4abf-4f10-b450-7b8ae92cb72e
• 4ce35042-9293-4c3f-bda8-3951ba329133
• 4b4ccbe4-1519-4be1-9820-8c94dc4e280c
• 902fdc93-a593-4cdf-a1b7-4ab11de0f765
• 4aa5f42d-8978-46ae-8170-0b354b04e6f4
• e07e7bb9-9b62-48fc-99dd-3bf25844d62c
• 3ac55c3c-6acd-4114-afa8-5f8c437b125b

 

Are those for the same (catalog) Plan? 

No, they're related to different products; all of them are "free products" (ie their recurring price is 0 and they have no upfront price), but they might have non-free addons (for example, the "professionalServices" product.

Is that a new behavior in 0.16.10?

Honestly I don't know; it's a behaviour I've noticed only yesterday, after the upgrade.

Also, could you provide the following detail for this use case:

> select * from subscription_events where subscription_id = 'f599a5d6-6ecf-4bae-b5d0-1925efdf52d1';

A detail of the Plan entry in your catalog matching that subscription.

I've extended the query a bit to match the subscription IDs I've found on the log file. The query is:

select * from subscription_events where subscription_id in ('f599a5d6-6ecf-4bae-b5d0-1925efdf52d1', 'a365ef70-1577-4fef-a160-dd4b0060dd5f', '8e8f7f1e-716d-48f7-94e1-bccfa23c9845', 'ff6d4c35-707a-4e93-950d-8e4e2d8922b2', '71f965b3-0ad9-4094-92c2-854f0026dfe3', 'b5524e83-9bd9-40ac-8eca-eaa50b71b2e9', 'bf5ecf56-00bd-46f7-872a-4243d36a2fec', 'c86c5f3e-b302-45c2-941f-892b36c75e8a', '932ae5fc-4abf-4f10-b450-7b8ae92cb72e', '4ce35042-9293-4c3f-bda8-3951ba329133', '4b4ccbe4-1519-4be1-9820-8c94dc4e280c', '902fdc93-a593-4cdf-a1b7-4ab11de0f765', '4aa5f42d-8978-46ae-8170-0b354b04e6f4', 'e07e7bb9-9b62-48fc-99dd-3bf25844d62c', '3ac55c3c-6acd-4114-afa8-5f8c437b125b');

 

You will find its results on the "futures.csv" attached file.

The corresponding catalogs extracts are int he file "catalogs extracts.txt"

Thank you again,

Leonardo

[stephane brossier]

Leonardo,

Mystery solved... The short story is that while the trace is confusing the computation of BCD is correct.

If you care about details, i filed https://github.com/killbill/killbill/issues/644

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/3049589d-9c65-4185-8001-ec9e3bdd7ca0%40googlegroups.com.

[Leonardo Scattola]

Hi everybody,

sorry to bother you again... Our machines have been at 100% CPU usage for a long time now,, so I had a look at the logs that have been written this morning.

I see a large number of such rows (check the file "catalina.out" in the attachments):

2016-11-08T06:55:11,303+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='8', tRId='1', Calculated BCD: subscriptionId='5e8489f5-497c-4517-8a91-c7cb0cdcbac0', subscriptionStartDate='2016-07-08T06:55:10.000Z', accountTimeZone='UTC', bcd='8'

2016-11-08T06:55:11,334+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='8', tRId='1', Calculated BCD: subscriptionId='5285b9c3-910a-4e59-aa0c-1b956010aaa8', subscriptionStartDate='2016-07-08T07:42:25.000Z', accountTimeZone='UTC', bcd='8'

2016-11-08T06:55:11,363+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='8', tRId='1', Calculated BCD: subscriptionId='4b9531f8-9880-4814-8ab1-e2c0bef76be6', subscriptionStartDate='2116-07-08T07:43:22.000Z', accountTimeZone='UTC', bcd='8'

What makes me wonder is that some of these subscriptionIds are always repeated, sometimes a large number of times:

2016-11-08T07:55:39,470+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:39,810+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:39,870+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:39,931+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,021+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,116+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,212+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,311+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,416+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,552+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,642+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,759+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,904+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:40,997+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,073+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,134+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,195+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,299+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,362+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,428+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,490+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,552+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,881+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:41,997+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,096+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,215+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,311+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,422+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,536+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,641+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,742+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,828+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:42,936+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:43,049+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:43,151+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:43,276+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:43,382+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:43,498+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:43,576+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:43,636+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,007+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,065+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,122+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,180+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,246+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,305+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,368+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,425+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T07:55:44,486+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

and so on.

I have then extracted these rows (the ones with "Calculated BCD:") and created an Excel file ("BCD Calculations.xlsx" in attachments) with two sheets:

• the first has four columns: the timestamp of the log row, the subscription ID, the subscription start date and the BCD
• the second one is a pivot on the first, showing the number of rows in the log fragment for each subscription

The first five most frequent subscriptions account for 732 log rows on 1224 (nearly 60%!) and, seeing the high CPU usage of the machine, the feeling is that this huge amount of BCD calculations are generating much of the unresponsiveness of the application...

These logs have been extracted from our beta/quality platform, which is aligned to the 0.16.10 version.

One idea could be setting up another KB machine to perform these calculation and having the other one respond to the external webservices invocation, but I don't think it's an optimal case.

Thank you for your suggestions,

Leonardo

 

[Pierre-Alexandre Meyer]

On Tue, Nov 8, 2016 at 12:21 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

check the file "catalina.out" in the attachments:

I see a lot of HTTP queries for /1.0/kb/invoices/searchbyDate in the logs. Is that a custom endpoint?

One idea could be setting up another KB machine to perform these calculation and having the other one respond to the external webservices invocation, but I don't think it's an optimal case.

Indeed - there is something wrong as Kill Bill should never use that much CPU.

--

Pierre

[Leonardo Scattola]

Pierre,

Il giorno martedì 8 novembre 2016 16:04:39 UTC+1, Pierre-Alexandre Meyer ha scritto:

I see a lot of HTTP queries for /1.0/kb/invoices/searchbyDate in the logs. Is that a custom endpoint?

Yup! This is a custom method that we implemented to get the list of invoices for an account filtering them on a date range. You can find the source code on the "snippet.txt" file in the attachments.

Thank you,

Leonardo 

[Pierre-Alexandre Meyer]

On Tue, Nov 8, 2016 at 7:16 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

I see a lot of HTTP queries for /1.0/kb/invoices/searchbyDate in the logs. Is that a custom endpoint?

Yup! This is a custom method that we implemented to get the list of invoices for an account filtering them on a date range. You can find the source code on the "snippet.txt" file in the attachments.

Can you reproduce the 100% CPU issue on a stock 0.16.11 deployment?

--

Pierre

[Leonardo Scattola]

Pierre,

Il giorno martedì 8 novembre 2016 16:25:19 UTC+1, Pierre-Alexandre Meyer ha scritto:

Can you reproduce the 100% CPU issue on a stock 0.16.11 deployment?

Would it be sufficient to put the stock 0.6.11 war with the current database? I don't think that the load is caused by this function; it's called only once or twice per week...

 

[Leonardo Scattola]

Pierre,

the behaviour is the very same with the stock version of KB 0.16.11: the machine was idle when I checked (no BCD were being calculated).

I stopped the Tomcat, switched the war with the stock one and restarted the Tomcat; the machine was still idle.

I then created a new subscription and the BCD calculation started; the behaviour I noticed this morning is still there, as you can see in the following log snippet.

2016-11-08T15:53:07,237+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T15:53:07,269+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T15:53:07,300+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T15:53:07,335+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T15:53:07,386+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T15:53:07,419+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T15:53:07,452+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

2016-11-08T15:53:07,484+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', Calculated BCD: subscriptionId='552f69be-3436-4eca-8944-2bb61e4c66c9', subscriptionStartDate='2116-03-11T16:24:17.000Z', accountTimeZone='UTC', bcd='11'

Thank you again,

Leonardo

[Pierre-Alexandre Meyer]

Can you share the full logs (including the startup sequence and HTTP queries you sent)?

--

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/4c5b696a-e9a0-48d8-a5c3-e2ce98986b98%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Pierre

[Leonardo Scattola]

Pierre,

Il giorno martedì 8 novembre 2016 16:57:28 UTC+1, Pierre-Alexandre Meyer ha scritto:

Can you share the full logs (including the startup sequence and HTTP queries you sent)?

sure! Check the catalina.out file in the attached archive. Let me comment the list of actions that I performed:

Lines 1 to 457: Tomcat startup phase

********** Start of the subscription creation phase

Lines 460 to 480: get the same account's details via externalKey

Lines 482 to 502: get the tag definitions list

Lines 504 to 526: stop the automatic invoicing for the account (POSTing the tag AUTO_INVOICING_OFF)

Lines 528 to 555: creation of a new subscription

Lines 557 to 578: check to confirm that the account has an associated payment method (the "null payment" plugin)

Lines 581 to 600: get the tag definitions list again

Lines 602 to 623: restart the invoicing process for the account (DELETE-ing the tag AUTO_INVOICING_OFF)

** From line 625 onwards: the BCD calculations start **

********** Start of the subscription deletion phase (we want to delete the newly create subscription)

Lines 902 to 922: get the account's details via account ID

Lines 1131 to 1145, 1156 to 1158 (in the meanwhile the BCD calculations are still in progress): get the subscription's details

Lines 1412 to 1427, 1444 to 1447: get the subscription's details

Lines 1456 to 1471, 1499 to 1502: perform the subscription deletion

*** All of the subsequent calls are related to the invoices list process started on line 534; no further action has been performed.

Line 47473 onwards: Tomcat is being shut down

Thank you,

Leonardo

[stephane brossier]

Leonardo,

The use case of setting AUTO_INVOICING_OFF, creating the subscriptions and removing AUTO_INVOICING_OFF is a fairly well supported use case.

However, it seems like there are a lot of subscriptions that were created for this account... i am counting more than 1000+ subscriptions. Note that this is definitely a use case we want to support, but in all honesty this is also something we have never tried.  I am unclear if this issue has anything to do with large amount of subscriptions at this point.

Could you send me a data export for this account (so i could try to load it) and reproduce your issue:

# Replace user/passwrd and tenant keys with your values

> curl  -u admin:password -H "X-Killbill-ApiKey: bob" -H "X-Killbill-ApiSecret: lazar" -H "X-Killbill-CreatedBy: demo" -H "Content-Type: text/plain" "http://127.0.0.1:8080/1.0/kb/export/27df570b-8a43-4922-a182-1009f2c3b00e" > /tmp/27df570b-8a43-4922-a182-1009f2c3b00e.data

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/57d5c590-6deb-4e14-8d03-7e094365877c%40googlegroups.com.

[Leonardo Scattola]

Stéphane,

keep in mind that this is a quality/beta account, so the number of subscriptions is much larger than the production typical case (unfortunately :D ). Still, we're experiencing high levels of CPU in the production site too...

Check the attachments for the export.

Thank you,

Leonardo

[Leonardo Scattola]

Stéphane,

let me add further details to my last.

In my message of 3rd November, 12:38:56 I wrote:

I have created a script which performs the following steps:

1. get the accounts list on the source KB
2. for each account
1. create a new account on the destination KB, attaching the default "null payment" plugin
2. stop the invoicing on the destination account (attaching the correct tag)
3. get the bundles and subscriptions on the source KB for this account
4. for each bundle
1. create a new series of subscriptions on the destination and join them into a new bundle; the request date for the new subscriptions will be the one stated in the source bundle
2. if one or more of these subscriptions has been cancelled, cancel it on the destination too; the cancellation date for the new subscriptions will be the one stated in the source bundle
5. restart the invoicing (removing the correct tag)

You can find the script source code in the cloudlink-killbillmigration.zip archive; it's a Scala project that interacts with KB with its client library; check the pom.xml file for the dependencies list.

I have executed this test setting our production server as the source and a new KB instance (with an empty DB) as the destination.

The script completed in about 40 minutes; check the "kbmigration.zip" archive for its full log.

The problem is the same we encountered in our quality/beta platform (check my previous messages): the machine has been at 100% CPU from the beginning of the script execution (more precisely from when it has started to perform the BCD calculations); moreover, the invoicing events calculation (and especially the "Calculated BCD" rows) is still in progress.

Many of the "Calculated BCD" rows are repeated a large number of times:

2016-11-09T11:27:20,931+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='5', tRId='1', Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:20,938+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='3', tRId='1', Calculated BCD: subscriptionId='0b288af2-f350-46ac-8e08-eacf9722b8a5', subscriptionStartDate='2016-09-28T11:22:33.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:20,950+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='5', tRId='1', Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:20,964+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='3', tRId='1', Calculated BCD: subscriptionId='7a1a9367-2989-4bef-a0ec-90cd4fcad71a', subscriptionStartDate='2016-09-28T11:22:34.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:20,970+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='5', tRId='1', Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:20,989+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='5', tRId='1', Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:20,991+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='3', tRId='1', Calculated BCD: subscriptionId='583b4b5b-c5a2-4040-98da-f084bd5e9b8e', subscriptionStartDate='2016-09-28T11:22:35.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:21,008+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='5', tRId='1', Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:21,018+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='3', tRId='1', Calculated BCD: subscriptionId='45dbd8a5-9a0f-437c-b0f2-d9129ea1803e', subscriptionStartDate='2116-10-25T11:22:35.000Z', accountTimeZone='UTC', bcd='25'

2016-11-09T11:27:21,028+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='5', tRId='1', Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:21,046+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='3', tRId='1', Calculated BCD: subscriptionId='902b4fe1-9262-41b2-a9da-5fd48c5fef8d', subscriptionStartDate='2016-10-25T11:22:36.000Z', accountTimeZone='UTC', bcd='25'

2016-11-09T11:27:21,046+0000 lvl='INFO', log='BillCycleDayCalculator', th='notifications-th', xff='', rId='', aRId='3', tRId='1', Calculated BCD: subscriptionId='902b4fe1-9262-41b2-a9da-5fd48c5fef8d', subscriptionStartDate='2016-10-25T11:22:36.000Z', accountTimeZone='UTC', bcd='25'

2016-11-09T11:27:21,047+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='5', tRId='1', Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

2016-11-09T11:27:21,066+0000 lvl='INFO', log='BillCycleDayCalculator', th='bus_events-th', xff='', rId='', aRId='5', tRId='1', Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

I have attached the full log file in the catalina.zip archive (** warning: it's HUGE! **); however, I filtered those rows in a much smaller file.

I then performed a quick extraction from these rows, to understand how many of these calculation have been performed on a single subscriptionId; you can find these results in an Excel pivot table; for example, the following row:

Calculated BCD: subscriptionId='bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090', subscriptionStartDate='2016-09-28T11:26:15.000Z', accountTimeZone='UTC', bcd='28'

has been repeated 79917 times and counting.

As you can see in the pivot table, there are 442 subscription IDs in the catalina.log file; I am certain that the total amount of migrated subscription is not so bigger (surely less than 500).

If you need I can provide you with a full snapshot of the killbill database; however, I have exported the current status for the account 0bd484b5-4b9a-4ea6-bd69-57c3835c61db, owner of the subscription bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090; you may find the export at this link.

Regards,

Leonardo

[Leonardo Scattola]

Stéphane,

a quick update: the catalina.out file has grown to a whopping 885MB and KB is still processing the BCD calculations.

There are now 418809 rows of "Calculated BCD" and the "top ten" is as follows:

bfb9d3dd-3fcf-4019-b45b-8d8ae23e5090	79917
2fd85592-f88d-4a8b-95bc-4958965f6bde	58270
39142922-6f35-48fb-bb53-a642f6dd2b07	55955
37446f6e-ea1a-44a9-98a7-2f67b15d2274	5648
8f5e6304-52b1-4bfc-96f3-999958519cc7	5648
85cf4ebe-5255-44e0-ab71-62c2807315b5	5628
012a6262-5574-419e-9b9e-d6d6565f4d3f	4224
902b4fe1-9262-41b2-a9da-5fd48c5fef8d	4224
670da212-5047-40ab-a577-34ff9940b5a1	4224
77fe269f-a3ca-49d2-9457-4cd7b202a0d0	4224

The calculations are still ongoing...

Regards,

Leonardo

[Leonardo Scattola]

Stéphane,

another quick update on the argument: the BCD calculation process on the test server is *still* ongoing. This is the very same issue that we are still experiencing on our production server, and I'm worried because of the impacts in our platform's responsivity. Any ideas?

Regards,

Leonardo

[stephane brossier]

Leonardo,

I want to investigate your issue, but i have many more tasks on my plate right now. Also your setup is quite complex (large catalog with lots of versions, lots of subscriptions, ....), so just reproducing takes a long time. One idea is for you to debug by setting breakpoints and digging into why this is happening (happy to provide guidance or any support to facilitate that task). I think the more knowledge you gather about the system the better anyways. A few things to look at:

1. Is that an infinite loop (does not look like it)?

2. If not why do we see so many traces for subscriptions?

Note that i still want to investigate on my end, but if time is a concern, anything you can do on your end will help.

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/7fad0a80-233d-4cee-89a6-a4a2429005f4%40googlegroups.com.

[stephane brossier]

Leonardo,

Took another look: What i am seeing is that there is a very large number of subscriptions and bundles and so the code loops though all bundles * subscriptions * billing events which in your case is quite a lot. We could definitely improve that (would be quite easy actually), but i am not seeing bugs (as far as i can tell). The reason why you see so many traces like the one below is because some of your subscriptions are BUNDLE aligned and when you have lots of AOs in a bundle we recompute same BCD over and over. As i said space for optimization...

Stéphane

On Thu, Nov 10, 2016 at 8:21 AM, stephane brossier <step...@kill-bill.org> wrote:

Leonardo,

I want to investigate your issue, but i have many more tasks on my plate right now. Also your setup is quite complex (large catalog with lots of versions, lots of subscriptions, ....), so just reproducing takes a long time. One idea is for you to debug by setting breakpoints and digging into why this is happening (happy to provide guidance or any support to facilitate that task). I think the more knowledge you gather about the system the better anyways. A few things to look at:

1. Is that an infinite loop (does not look like it)?

2. If not why do we see so many traces for subscriptions?

Note that i still want to investigate on my end, but if time is a concern, anything you can do on your end will help.

Stéphane

[Leonardo Scattola]

Stéphane,

thank you for your first investigation. I have checked the data and I can confirm that there are

• 63 accounts
  
• 460 bundles
• 1272 subscriptions

What do you mean by "billing events"? I suppose that they are the subscription creation, the invoices creation (one per month if the payment is monthly, starting from the subscription creation date), the payment and so on. Let's pretend that there are 10 of such events for each subscription; the total of loops should be then 460*1272*10= roughly 6 millions of BCD calculations, right?

Is that in your opinion really a very large number of subscriptions and bundles?

When these BCD calculations will be completed, will the system consider them as "already performed" or will it for some reason recompute all the BCDs if the bundle will be altered? (for example, should I switch payment from MONTHLY to ANNUAL, will it recompute all the BCDs for the bundle?)

What should I do in the short term to improve the performance? Should I add another KB instance on the same DB, will it take part into the calculation somehow? It wouldn't be a problem for us to attach other servers in a cluster.

You mentioned the fact that some of our subscriptions are BUNDLE aligned. Will switching the subscriptions' alignment to ACCOUNT (or SUBSCRIPTION) affect the performance? If I understood correctly, setting the alignment to ACCOUNT will align the BCD for the subscription to the one of the account; this could not be a problem for us, but I fear I'm missing something.

As for the issue 659 (optimization), do we have a way to check if a BCD has already been computed? What kind of caching do you have in mind?

In the DB I can see a charged_through_date in the subscriptions table; could that be a starting point?

Thank you,

Leonardo

Il giorno venerdì 11 novembre 2016 03:26:24 UTC+1, stephane brossier ha scritto:

Leonardo,

Took another look: What i am seeing is that there is a very large number of subscriptions and bundles and so the code loops though all bundles * subscriptions * billing events which in your case is quite a lot. We could definitely improve that (would be quite easy actually), but i am not seeing bugs (as far as i can tell). The reason why you see so many traces like the one below is because some of your subscriptions are BUNDLE aligned and when you have lots of AOs in a bundle we recompute same BCD over and over. As i said space for optimization...

Stéphane

On Thu, Nov 10, 2016 at 8:21 AM, stephane brossier <step...@kill-bill.org> wrote:

Leonardo,

I want to investigate your issue, but i have many more tasks on my plate right now. Also your setup is quite complex (large catalog with lots of versions, lots of subscriptions, ....), so just reproducing takes a long time. One idea is for you to debug by setting breakpoints and digging into why this is happening (happy to provide guidance or any support to facilitate that task). I think the more knowledge you gather about the system the better anyways. A few things to look at:

1. Is that an infinite loop (does not look like it)?

2. If not why do we see so many traces for subscriptions?

Note that i still want to investigate on my end, but if time is a concern, anything you can do on your end will help.

Stéphane

On Wed, Nov 9, 2016 at 11:28 PM, Leonardo Scattola <leonardo...@newvision.it> wrote:

Stéphane,

another quick update on the argument: the BCD calculation process on the test server is *still* ongoing. This is the very same issue that we are still experiencing on our production server, and I'm worried because of the impacts in our platform's responsivity. Any ideas?

Regards,

Leonardo

--
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.

[stephane brossier]

Leonardo,

I just released 0.16.12. Could you try it and let me know if this helps with your use case?

Stéphane

To unsubscribe from this group and stop receiving emails from it, send an email to killbilling-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/16dbf5c0-95b7-45f3-bf33-78741131643a%40googlegroups.com.

[Leonardo Scattola]

Stéphane,

I have reviewed your code; I think it will surely help, but if we create a new bcdCache object for each invocation of the function addBillingEventsForSubscription I feel that the performance boost is only marginal... What if we create a static object for bcdCache? (something like

public class DefaultInternalBillingApi implements BillingInternalApi {

    private static final Logger log = LoggerFactory.getLogger(DefaultInternalBillingApi.class);

    private static Map<UUID, Integer> bcdCache =new HashMap<UUID, Integer>();

and then pass it on in the addBillingEventsForSubscription function: 

for (final EffectiveSubscriptionInternalEvent transition : billingTransitions) {
    final int bcdLocal = bcdCalculator.calculateBcd(account, currentAccountBCD, bundleId, subscription, transition, DefaultInternalBillingApi.bcdCache, context);

We should have a much bigger performance boost, because each BCD calculation would be performed only once; on the other hand, the memory usage could rise a lot (depending on the number of subscriptions...)

What do you think?

Regards,

Leonardo

[Leonardo Scattola]

Stéphane,

I deployed the new WAR on the test Tomcat (the one which has been populated by the migration script) and I am again reviewing the logs.

I've noticed that  KB attempts to issue an invoice with the very same elements on different invoices again and again (check the attached log file):

(starting at line 91):

2016-11-14T10:20:10,463+0000 lvl='INFO', log='FixedAndRecurringInvoiceItemGenerator', th='notifications-th', xff='', rId='', aRId='2', tRId='1', Proposed Invoice items for invoiceId='26fe4024-e3b0-4577-ba29-53729ecf36cd', accountId='4c8849da-19ba-4361-8002-6b5c21d2e4ab'

DefaultBillingEvent{type=CREATE, effectiveDate=2015-07-30T11:22:07.000Z, planPhaseName=contentList-monthly-evergreen, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, totalOrdering=342}

RECURRING{startDate=2015-07-30, endDate=2015-08-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2015-08-30, endDate=2015-09-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2015-09-30, endDate=2015-10-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2015-10-30, endDate=2015-11-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2015-11-30, endDate=2015-12-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2015-12-30, endDate=2016-01-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-01-30, endDate=2016-02-29, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-02-29, endDate=2016-03-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-03-30, endDate=2016-04-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-04-30, endDate=2016-05-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-05-30, endDate=2016-06-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-06-30, endDate=2016-07-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-07-30, endDate=2016-08-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-08-30, endDate=2016-09-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-09-30, endDate=2016-10-30, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

RECURRING{startDate=2016-10-30, endDate=2016-11-09, amount=0.00, rate=0.0, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, linkedItemId=null}

DefaultBillingEvent{type=CANCEL, effectiveDate=2016-11-09T11:22:08.000Z, planPhaseName=contentList-monthly-evergreen, subscriptionId=8f5e6304-52b1-4bfc-96f3-999958519cc7, totalOrdering=343}

DefaultBillingEvent{type=CREATE, effectiveDate=2016-09-28T11:22:11.000Z, planPhaseName=thronForSales-1kcontacts-annual-evergreen, subscriptionId=edeae58a-fcac-437a-92dd-1d702d8e697b, totalOrdering=347}

RECURRING{startDate=2016-09-28, endDate=2017-09-28, amount=204.00, rate=204.0, subscriptionId=edeae58a-fcac-437a-92dd-1d702d8e697b, linkedItemId=null}

DefaultBillingEvent{type=CREATE, effectiveDate=2015-10-02T11:22:08.000Z, planPhaseName=downloadConnector-monthly-evergreen, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, totalOrdering=344}

RECURRING{startDate=2015-10-02, endDate=2015-11-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2015-11-02, endDate=2015-12-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2015-12-02, endDate=2016-01-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-01-02, endDate=2016-02-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-02-02, endDate=2016-03-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-03-02, endDate=2016-04-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-04-02, endDate=2016-05-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-05-02, endDate=2016-06-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-06-02, endDate=2016-07-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-07-02, endDate=2016-08-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-08-02, endDate=2016-09-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-09-02, endDate=2016-10-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-10-02, endDate=2016-11-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

RECURRING{startDate=2016-11-02, endDate=2016-12-02, amount=0.00, rate=0.0, subscriptionId=f89003e5-903f-42c5-a190-9ae084f925df, linkedItemId=null}

DefaultBillingEvent{type=CREATE, effectiveDate=2016-09-28T11:22:10.000Z, planPhaseName=thronForMarketing-1kdevices-annual-evergreen, subscriptionId=25442614-31b8-4fc5-b1d5-afedec3dc681, totalOrdering=346}

RECURRING{startDate=2016-09-28, endDate=2017-09-28, amount=332.00, rate=332.0, subscriptionId=25442614-31b8-4fc5-b1d5-afedec3dc681, linkedItemId=null}

DefaultBillingEvent{type=CREATE, effectiveDate=2015-07-30T11:22:05.000Z, planPhaseName=mediaCenter-monthly-evergreen, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, totalOrdering=340}

RECURRING{startDate=2015-07-30, endDate=2015-08-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2015-08-30, endDate=2015-09-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2015-09-30, endDate=2015-10-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2015-10-30, endDate=2015-11-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2015-11-30, endDate=2015-12-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2015-12-30, endDate=2016-01-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-01-30, endDate=2016-02-29, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-02-29, endDate=2016-03-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-03-30, endDate=2016-04-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-04-30, endDate=2016-05-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-05-30, endDate=2016-06-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-06-30, endDate=2016-07-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-07-30, endDate=2016-08-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-08-30, endDate=2016-09-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-09-30, endDate=2016-10-30, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

RECURRING{startDate=2016-10-30, endDate=2016-11-09, amount=0.00, rate=0.0, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, linkedItemId=null}

DefaultBillingEvent{type=CANCEL, effectiveDate=2016-11-09T11:22:06.000Z, planPhaseName=mediaCenter-monthly-evergreen, subscriptionId=37446f6e-ea1a-44a9-98a7-2f67b15d2274, totalOrdering=341}

DefaultBillingEvent{type=CREATE, effectiveDate=2016-09-28T11:22:09.000Z, planPhaseName=omniChannelDam-smallBusiness-annual-evergreen, subscriptionId=75702be4-2d64-4c4a-a321-d84c3c0723c0, totalOrdering=345}

RECURRING{startDate=2016-09-28, endDate=2017-09-28, amount=20400.00, rate=20400.0, subscriptionId=75702be4-2d64-4c4a-a321-d84c3c0723c0, linkedItemId=null}

and again at lines 174, 257, 340, 423 and so on: the invoice items seem to keep recurring again and again, witht the very same dates and amounts and for the very same subscriptions.

What should I check in order to ensure that the issues are indeed different?

Thank you,

Leonardo

[Leonardo Scattola]

Stéphane,

for what regards my latest message I found out that there are 159 occurrences of the string

Generated null invoice for accountId='4c8849da-19ba-4361-8002-6b5c21d2e4ab', targetDate='2016-11-09', targetDateTime='2016-11-09T11:22:05.000Z'

in the log snippet I sent you...

I'll keep on looking at the code.

Thank you,

Leonardo

[stephane brossier]

On Mon, Nov 14, 2016 at 12:30 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

Stéphane,

I have reviewed your code; I think it will surely help, but if we create a new bcdCache object for each invocation of the function addBillingEventsForSubscription I feel that the performance boost is only marginal...

Well, did you try it?

In a case where you have 300+ subscriptions / bundle (which was your case), we would compute the BCD one time instead of 300? Is that really a marginal improvement?

 

What if we create a static object for bcdCache? (something like

public class DefaultInternalBillingApi implements BillingInternalApi {

    private static final Logger log = LoggerFactory.getLogger(DefaultInternalBillingApi.class);

    private static Map<UUID, Integer> bcdCache =new HashMap<UUID, Integer>();

and then pass it on in the addBillingEventsForSubscription function: 

for (final EffectiveSubscriptionInternalEvent transition : billingTransitions) {
    final int bcdLocal = bcdCalculator.calculateBcd(account, currentAccountBCD, bundleId, subscription, transition, DefaultInternalBillingApi.bcdCache, context);

We should have a much bigger performance boost, because each BCD calculation would be performed only once; on the other hand, the memory usage could rise a lot (depending on the number of subscriptions...)

What do you think?

You are correct that having a global cache that would be populated only the first time we have a new subscription could help (assuming such cache is large enough to keep BCD for all subscriptions). That being said, before we even go there, i would like to make sure this is really the issue you are hitting (i am not convinced yet). 

I would suggest the following:

1. Try the new release, and report back

2. If does not work, implement yourself a cache as you described (although if we were to implement such cache we would take a different route, but we can talk about that when/if  the time comes) so we can check whether this is really the cause of your trouble.

Stéphane

 

To unsubscribe from this group and stop receiving emails from it, send an email to killbilling-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/77a52cf0-9cf6-4cde-bc8b-838ddb803422%40googlegroups.com.

[Leonardo Scattola]

Stéphane,

let me answer in-line.

I have reviewed your code; I think it will surely help, but if we create a new bcdCache object for each invocation of the function addBillingEventsForSubscription I feel that the performance boost is only marginal...

Well, did you try it?

yes: the "beta/quality" machine has been running running with the new version since 10:00 UTC.

In a case where you have 300+ subscriptions / bundle (which was your case), we would compute the BCD one time instead of 300? Is that really a marginal improvement?

Sorry for not expressing myself correctly: i was worried because I thought that he bcdCache is created anew each time you invoke  addBillingEventsForSubscription, and if this is the case it could be furtherly sped up. However, the cache layer you provided is surely speeding up things a lot! Thank you.

I would suggest the following:

1. Try the new release, and report back

Reporting :D

but the problem now is that it looks like that the same invoice is being generated over and over (check my message of this morning, 10:43 UTC).

Thank you again,

Leonardo

[stephane brossier]

Leonardo,

We have found the issue, this only seems to happen because your catalog has $0 recurring price.

Questions:

1. What's the use case to invoice $0 items (note that current invoicing code will not generate anything)?

2. We want to fix that bug, but it seems like an edge case and because we have released 0.18 yesterday, 0.16.x is now in maintenance mode and we will only fix critical bugs. Can you migrate to 0.18 (actually, we highly suggest you do that if you don't have yet production traffic). We could fix it in 0.18.1.

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/a9d5dad8-2b2a-4168-8329-dd6880218097%40googlegroups.com.

[leonardo...@gmail.com]

Stéphane,
thank you for your quick response. Let me answer in-line:

> We have found the issue, this only seems to happen because your catalog has $0 recurring price.
>

> Questions:
> 1. What's the use case to invoice $0 items (note that current invoicing code will not generate anything)?

Many of our products have a "null cost" (they're free of charge); we need to take note of the subscription and when we started the project it seemed natural to set a monthly fee of 0 euros. We could as well have set the pricing model to an upfront fee of 0 euros, but we thought it was as good.

> 2. We want to fix that bug, but it seems like an edge case and because we have released 0.18 yesterday, 0.16.x is now in maintenance mode and we will only fix critical bugs. Can you migrate to 0.18 (actually, we highly suggest you do that if you don't have yet production traffic). We could fix it in 0.18.1.

We surely want to migrate to 0.18, but we have been in production with the 0.16 branches for some time now...
Are there any changes on the DB? Is there a DDL we can apply so we can just upgrade the development and the beta/quality sites?

Thank you again,

Leonardo

[leonardo...@gmail.com]

Oh, now I've noticed that

> > We have found the issue

and I appreciate the issue ID :D

Thank you again,

Leonardo

[leonardo...@gmail.com]

Il giorno lunedì 14 novembre 2016 22:03:13 UTC+1, leonardo...@gmail.com ha scritto:
> Are there any changes on the DB? Is there a DDL we can apply so we can just upgrade the development and the beta/quality sites?

Oh, never mind. I found out myself: https://github.com/killbill/killbill/releases/tag/killbill-0.18.0

[Leonardo Scattola]

Stéphane, all,

I compiled KB version 0.18.0 and performed a scan of my catalog files using the following command:

java -jar killbill-catalog-0.18.0-load-tool.jar SpyCarAdvanced.xml

The result is an exception:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".

SLF4J: Defaulting to no-operation (NOP) logger implementation

SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

Exception in thread "main" javax.xml.bind.UnmarshalException: Unable to create an instance of org.killbill.billing.catalog.StandaloneCatalog

 - with linked exception:

[java.lang.reflect.InvocationTargetException]

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.handleEvent(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.Loader.reportError(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.createInstance(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.StructureLoader.startElement(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext._startElement(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallingContext.startElement(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.ValidatingUnmarshaller.startElement(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.SAXConnector.startElement(Unknown Source)

        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.startElement(Unknown Source)

        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanStartElement(Unknown Source)

        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl$NSContentDriver.scanRootElementHook(Unknown Source)

        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(Unknown Source)

        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(Unknown Source)

        at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(Unknown Source)

        at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(Unknown Source)

        at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown Source)

        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(Unknown Source)

        at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(Unknown Source)

        at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(Unknown Source)

        at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(Unknown Source)

        at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal(Unknown Source)

        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(Unknown Source)

        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(Unknown Source)

        at org.killbill.xmlloader.XMLLoader.getObjectFromStream(XMLLoader.java:66)

        at org.killbill.xmlloader.XMLLoader.getObjectFromUri(XMLLoader.java:58)

        at org.killbill.billing.catalog.LoadCatalog.main(LoadCatalog.java:33)

Caused by: java.lang.reflect.InvocationTargetException

        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

        at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)

        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)

        at java.lang.reflect.Constructor.newInstance(Unknown Source)

        at com.sun.xml.internal.bind.v2.ClassFactory.create0(Unknown Source)

        at com.sun.xml.internal.bind.v2.runtime.ClassBeanInfoImpl.createInstance(Unknown Source)

        ... 26 more

Caused by: java.lang.NoClassDefFoundError: com/google/common/collect/Ordering

        at org.killbill.billing.catalog.CatalogEntityCollection.<init>(CatalogEntityCollection.java:34)

        at org.killbill.billing.catalog.StandaloneCatalog.<init>(StandaloneCatalog.java:96)

        ... 32 more

Caused by: java.lang.ClassNotFoundException: com.google.common.collect.Ordering

        at java.net.URLClassLoader.findClass(Unknown Source)

        at java.lang.ClassLoader.loadClass(Unknown Source)

        at sun.misc.Launcher$AppClassLoader.loadClass(Unknown Source)

        at java.lang.ClassLoader.loadClass(Unknown Source)

        ... 34 more

That java.lang.ClassNotFoundException: com.google.common.collect.Ordering is strange...

My target is Java 1.7; does it matter?

Thank you,

Leonardo

[Leonardo Scattola]

Stéphane, all,

I have checked the jar file and indeed there is no such class in its contents; if I add it manually the loader will work.

After fixing the jar file, I've checked the latest catalogs (which were loaded just fine in all the 0.16.x versions) with the following command:

java -jar killbill-catalog-0.18.0-load-tool.jar THRONCatalog20161109.xml

This command fails with the following error:

Exception in thread "main" java.lang.IllegalStateException: Cannot extract pricelist for plan videoMood-commercials-sup-annual

        at org.killbill.billing.catalog.DefaultPlan.findPriceListForPlan(DefaultPlan.java:323)

        at org.killbill.billing.catalog.DefaultPlan.initialize(DefaultPlan.java:188)

        at org.killbill.billing.catalog.StandaloneCatalog.initialize(StandaloneCatalog.java:309)

        at org.killbill.billing.catalog.StandaloneCatalog.initialize(StandaloneCatalog.java:58)

        at org.killbill.xmlloader.XMLLoader.validate(XMLLoader.java:95)

        at org.killbill.xmlloader.XMLLoader.getObjectFromStream(XMLLoader.java:71)

        at org.killbill.xmlloader.XMLLoader.getObjectFromUri(XMLLoader.java:58)

        at org.killbill.billing.catalog.LoadCatalog.main(LoadCatalog.java:33)

What should I check?

Thank you,

Leonardo

[Leonardo Scattola]

Stéphane, all,

I reviewed the catalog file which failed the check and I found the problem.

I can however confirm the problem with the missing com/google/common/collect/Ordering class.

Thank you again,

Leonardo

[Leonardo Scattola]

Stéphane, all,

Il giorno martedì 15 novembre 2016 14:40:59 UTC+1, Leonardo Scattola ha scritto:

I can however confirm the problem with the missing com/google/common/collect/Ordering class.

There are other problems which I believe are somehow linked to this one.

I have deployed the WAR on our development server and Tomcat threw this error:

Nov 15, 2016 4:32:28 PM org.apache.catalina.core.StandardContext listenerStart

SEVERE: Exception sending context initialized event to listener instance of class org.killbill.billing.server.listeners.KillbillGuiceListener

java.lang.NoClassDefFoundError: org/killbill/commons/embeddeddb/mysql/MySQLStandaloneDB

        at org.killbill.billing.server.modules.EmbeddedDBProvider.get(EmbeddedDBProvider.java:55)

        at org.killbill.billing.server.modules.EmbeddedDBProvider.get(EmbeddedDBProvider.java:42)

        at com.google.inject.internal.BoundProviderFactory.get(BoundProviderFactory.java:55)

        at com.google.inject.internal.ProviderToInternalFactoryAdapter$1.call(ProviderToInternalFactoryAdapter.java:46)

        at com.google.inject.internal.InjectorImpl.callInContext(InjectorImpl.java:1031)

        at com.google.inject.internal.ProviderToInternalFactoryAdapter.get(ProviderToInternalFactoryAdapter.java:40)

        at com.google.inject.Scopes$1$1.get(Scopes.java:65)

        at com.google.inject.internal.InternalFactoryToProviderAdapter.get(InternalFactoryToProviderAdapter.java:40)

        at com.google.inject.internal.InternalInjectorCreator$1.call(InternalInjectorCreator.java:204)

        at com.google.inject.internal.InternalInjectorCreator$1.call(InternalInjectorCreator.java:198)

        at com.google.inject.internal.InjectorImpl.callInContext(InjectorImpl.java:1024)

        at com.google.inject.internal.InternalInjectorCreator.loadEagerSingletons(InternalInjectorCreator.java:198)

        at com.google.inject.internal.InternalInjectorCreator.injectDynamically(InternalInjectorCreator.java:179)

        at com.google.inject.internal.InternalInjectorCreator.build(InternalInjectorCreator.java:109)

        at com.google.inject.Guice.createInjector(Guice.java:95)

        at org.killbill.commons.skeleton.listeners.GuiceServletContextListener.getInjector(GuiceServletContextListener.java:92)

        at com.google.inject.servlet.GuiceServletContextListener.contextInitialized(GuiceServletContextListener.java:45)

        at org.killbill.commons.skeleton.listeners.GuiceServletContextListener.contextInitialized(GuiceServletContextListener.java:54)

        at org.killbill.billing.server.listeners.KillbillPlatformGuiceListener.initializeGuice(KillbillPlatformGuiceListener.java:159)

        at org.killbill.billing.server.listeners.KillbillPlatformGuiceListener.contextInitialized(KillbillPlatformGuiceListener.java:106)

        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4973)

        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5467)

        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)

        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)

        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)

        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:632)

        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:670)

        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1839)

        at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

        at java.util.concurrent.FutureTask.run(Unknown Source)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

        at java.lang.Thread.run(Unknown Source)

Caused by: java.lang.ClassNotFoundException: org.killbill.commons.embeddeddb.mysql.MySQLStandaloneDB

        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1718)

        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1569)

        ... 33 more

The WAR has been compiled with this command (as executed by IntelliJ Idea)::

"C:\Program Files\Java\jdk1.7.0_79\bin\java" -Xmx1000m "-Dmaven.home=C:\Program Files (x86)\JetBrains\IntelliJ IDEA Community Edition 2016.2.3\plugins\maven\lib\maven3" "-Dclassworlds.conf=C:\Program Files (x86)\JetBrains\IntelliJ IDEA Community Edition 2016.2.3\plugins\maven\lib\maven3\bin\m2.conf" -Didea.launcher.port=7534 "-Didea.launcher.bin.path=C:\Program Files (x86)\JetBrains\IntelliJ IDEA Community Edition 2016.2.3\bin" -Dfile.encoding=UTF-8 -classpath "C:\Program Files (x86)\JetBrains\IntelliJ IDEA Community Edition 2016.2.3\plugins\maven\lib\maven3\boot\plexus-classworlds-2.4.jar;C:\Program Files (x86)\JetBrains\IntelliJ IDEA Community Edition 2016.2.3\lib\idea_rt.jar" com.intellij.rt.execution.application.AppMain org.codehaus.classworlds.Launcher -Didea.version=2016.2.5 -DskipTests=true install -P mysql,jdk17,!jdk16

 

The profiles selected are the ones in the attached image.

Thank you,

Leonardo

[Pierre-Alexandre Meyer]

Thank you for the report, Leonardo. This has been fixed by https://github.com/killbill/killbill/commit/fb0e21535ec31f472ce9e49d48cdd94ccb8603ab.

--

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/ab987542-0e31-4095-8267-7cceb2ac9f44%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Pierre

[Pierre-Alexandre Meyer]

Is that happening with the official 0.18.0 build or with your wrapper?

If the latter, you may need to change your build following https://github.com/killbill/killbill/commit/317d258bb7379ca173ba7c051f2891772757a76d.

--

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/672af337-78d3-4e74-a605-95cf84783eb6%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Pierre

[Leonardo Scattola]

Il giorno martedì 15 novembre 2016 17:46:48 UTC+1, Pierre-Alexandre Meyer ha scritto:

Is that happening with the official 0.18.0 build or with your wrapper?

with the official 0.18.0 build, unfortunately.

 

If the latter, you may need to change your build following https://github.com/killbill/killbill/commit/317d258bb7379ca173ba7c051f2891772757a76d.

Let me check again, just in case.

Thank you,

Leonardo

[stephane brossier]

Leonardo,

I committed a fix for the invoice loop around $0 recurring items. If you had a chance to take latest code from master and could verify if things work that would be great (then we could make a release end of the week/early next week) for you.

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/3219f529-7aa2-4f09-8b50-8915dc9bb4c4%40googlegroups.com.

[Leonardo Scattola]

Stéphane,

I uploaded the new WAR (killbill-profiles-killbill-0.18.0.war) on our Tomcat but it throws the same exception on startup:

Nov 16, 2016 7:32:22 AM org.apache.catalina.core.StandardContext listenerStart

Thank you,

Leonardo

[Leonardo Scattola]

Stéphane,

I have manually patched the WAR file and added the missing classes, then I deployed this WAR on my development Tomcat. It seems that the corrections are valid and the invoice calculation are not looping anymore (and that's wonderful!) I have performed a small number of preliminary tests (creating and cancelling subscriptions, changing their billing period and so on) and so far I haven't find any further problems (and that's even more wonderful :D).

The only remaining problem is the exception on startup that you may find on my previous message.

Thank you again,

Leonardo 

[stephane brossier]

Leonardo,

I am glad the fixes worked out. Regarding your exception, i am bit puzzled because i have started Kb many times with the new images and have not encountered such exception. 

Have you try to start it using our start start command (from build directory):

# Properties (e.g. DB url, credentials..) are defined in profiles/killbill/src/main/resources/killbill-server.properties

> ./bin/start-server -s 

Do you see such error when starting that way?

Could you provide some details on how you deploy/start to trigger this 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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/80529453-c5ca-493c-902f-b14bece29b91%40googlegroups.com.

[Leonardo Scattola]

Stéphane,

I started KB from command line without encountering that exception: Jetty started just fine, KB loaded the catalogs and connected to the DB without problems.

As what regards our Tomcat installations:

• there is only one webapp, defined in tomcat7/Catalina/localhost/ROOT.xml, with the following context:

<Context path="/" docBase="/opt/killbill/app/killbill-default.war" />

• /opt/killbill/app/killbill-default.war is a symlink to killbill-profiles-killbill-0.18.1-SNAPSHOT.war (in another directory)
• Please find attached the catalina.properties file
• You will find the Tomcat's log in the catalina.out attachment; the exception appears in the localhost.<date> log file (check my previous messages).

Thank you again,

Leonardo

[stephane brossier]

Leonardo,

I just tried deploying our latest war into a tomcat container, and it works like a charm for me.

I followed the steps from our doc, but the main difference (maybe) is that i deployed our war under: $CATALINA_HOME/webapps/ROOT.war 

and called the war `ROOT.war`.

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-users+unsubscribe@googlegroups.com.
To post to this group, send email to killbilling-users@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/f5d19300-fe1f-487a-a00a-6d8da02db882%40googlegroups.com.

[stephane brossier]

Leonardo,

Follow up: I also tried the same way you did by placing my war in a different place and *not* naming it ROOT.war, and it also works well:

<Context path="/" docBase="/tmp/killbill/killbill.war" />

Stéphane

[Leonardo Scattola]

Stéphane, all,

we finally went live with the 0.18.1 snapshot version. As predicted, the CPU usage dropped instantly and there are no invoice calculations looping.

However, we encountered another issue on the invoicing calculation: we created a new subscription for one of our customers and restarted the invoicing process (removing the AUTO_INVOICING_OFF tag); our Tomcat reported this exception.

DefaultBillingEvent{type=CREATE, effectiveDate=2016-01-18T22:01:46.000Z, planPhaseName=professionalServices-solutionanalyst-tenpack-addonplan-evergreen, subscriptionId=c4b03069-63e9-4935-9da8-8a7ed92649e7, totalOrdering=126}

        FIXED{startDate=2016-01-18, endDate=null, amount=8000.00, rate=null, subscriptionId=c4b03069-63e9-4935-9da8-8a7ed92649e7, linkedItemId=null}

org.killbill.billing.invoice.api.InvoiceApiException: SAFETY BOUND TRIGGERED subscriptionId='c4b03069-63e9-4935-9da8-8a7ed92649e7', resultingItem=FIXED{startDate=2016-01-18, endDate=null, amount=8000.00, rate=null, subscriptionId=c4b03069-63e9-4935-9da8-8a7ed92649e7, linkedItemId=null}

        at org.killbill.billing.invoice.generator.FixedAndRecurringInvoiceItemGenerator.safetyBound(FixedAndRecurringInvoiceItemGenerator.java:424)

        at org.killbill.billing.invoice.generator.FixedAndRecurringInvoiceItemGenerator.generateItems(FixedAndRecurringInvoiceItemGenerator.java:110)

        at org.killbill.billing.invoice.generator.DefaultInvoiceGenerator.generateInvoice(DefaultInvoiceGenerator.java:84)

        at org.killbill.billing.invoice.InvoiceDispatcher.processAccountWithLockAndInputTargetDate(InvoiceDispatcher.java:331)

        at org.killbill.billing.invoice.InvoiceDispatcher.processAccountWithLock(InvoiceDispatcher.java:258)

        at org.killbill.billing.invoice.InvoiceDispatcher.processAccount(InvoiceDispatcher.java:224)

        at org.killbill.billing.invoice.InvoiceTagHandler.processUnpaid_AUTO_INVOICING_OFF_invoices(InvoiceTagHandler.java:64)

        at org.killbill.billing.invoice.InvoiceTagHandler.process_AUTO_INVOICING_OFF_removal(InvoiceTagHandler.java:58)

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

        at java.lang.reflect.Method.invoke(Unknown Source)

        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(Unknown Source)

        at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:40)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

        at java.lang.Thread.run(Unknown Source)

The subscriptions for this customer are showing but there are no invoices for these subscriptions.

What should I check first?

Thank you,

Leonardo

[Leonardo Scattola]

Stéphane, all,

in addition we still have had a "Failed to acquire lock" on another customer:

2016-11-22T08:18:21,323+0000 lvl='WARN', log='GlobalLockerBase', th='bus_events-th', xff='', rId='', aRId='6', tRId='1', Failed to acquire lock 7a6dd639-77f4-48ed-b38c-5cd507322308 for service ACCNT_INV_PAY after 50 retries

2016-11-22T08:18:21,324+0000 lvl='WARN', log='InvoiceDispatcher', th='bus_events-th', xff='', rId='', aRId='6', tRId='1', Failed to process invoice for accountId='7a6dd639-77f4-48ed-b38c-5cd507322308', targetDate='2016-11-22'

org.killbill.commons.locker.LockFailedException: null

        at org.killbill.commons.locker.GlobalLockerBase.lockWithNumberOfTries(GlobalLockerBase.java:66)

        at org.killbill.billing.invoice.InvoiceDispatcher.processAccount(InvoiceDispatcher.java:222)

        at org.killbill.billing.invoice.InvoiceDispatcher.processSubscriptionInternal(InvoiceDispatcher.java:210)

        at org.killbill.billing.invoice.InvoiceDispatcher.processSubscriptionForInvoiceGeneration(InvoiceDispatcher.java:185)

        at org.killbill.billing.invoice.InvoiceDispatcher.processSubscriptionForInvoiceGeneration(InvoiceDispatcher.java:181)

        at org.killbill.billing.invoice.InvoiceListener.handleSubscriptionTransition(InvoiceListener.java:80)

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

        at java.lang.reflect.Method.invoke(Unknown Source)

        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(Unknown Source)

        at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:40)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

        at java.lang.Thread.run(Unknown Source)

The Tomcat has been restarted a few seconds ago, there are no other clients attached and this is an account without a particular activity (except for the huge number of invoice items due to the previous KB behaviour).

You can find the export file at https://hub-share.thron.com/content/?id=b22d094e-982a-4d78-9b60-dcfc91a53851&pkey=rUxBqB.

Is there a way to reduce the size of the DB by removing the unneeded rows?

Thank you,

Leonardo

[Leonardo Scattola]

Stéphane, all,

... and another exception has arisen on another customer:

2016-11-22T08:35:03,072+0000 lvl='ERROR', log='CallableCallbackBase', th='bus_events-th', xff='', rId='', aRId='4', tRId='1', 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: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(Unknown Source)

        at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:40)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

        at java.lang.Thread.run(Unknown Source)

Caused by: java.lang.reflect.InvocationTargetException: null

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

        at java.lang.reflect.Method.invoke(Unknown Source)

        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.IllegalStateException: Double billing detected: [Item{id=c53b3964-c51f-4df6-8887-26fe97392599, accountId=a2e6d3ea-10ef-4b1f-865a-1a52654f2e7f, bundleId=2b1a35b2-6fe8-42a1-9dce-440621ced78c, subscriptionId=baf1b087-b546-4f3b-a8c1-1c0b8f68f057, targetInvoiceId=c83a5b31-7f72-4605-88f8-336817a5a518, invoiceId=94e61977-eeb4-4ed2-bec0-fc18d06827a6, planName='professionalServices-solutionanalyst-daily-addonpl', phaseName='professionalServices-solutionanalyst-daily-addonpl', startDate=2016-02-02, endDate=2016-03-02, amount=0.00, rate=0E-9, currency=EUR, createdDate=2016-02-02T08:44:24.000Z, linkedId=null, currentRepairedAmount=0, adjustedAmount=0, action=ADD}, Item{id=75f1ea79-dbdb-4399-a746-ffc010e4af65, accountId=a2e6d3ea-10ef-4b1f-865a-1a52654f2e7f, bundleId=2b1a35b2-6fe8-42a1-9dce-440621ced78c, subscriptionId=baf1b087-b546-4f3b-a8c1-1c0b8f68f057, targetInvoiceId=c83a5b31-7f72-4605-88f8-336817a5a518, invoiceId=0ec04a97-0cf5-4287-b216-4084589540d3, planName='professionalServices-solutionanalyst-daily-addonpl', phaseName='professionalServices-solutionanalyst-daily-addonpl', startDate=2016-02-02, endDate=2016-03-02, amount=0.00, rate=0E-9, currency=EUR, createdDate=2016-02-02T08:44:24.000Z, linkedId=null, currentRepairedAmount=0, adjustedAmount=0, action=ADD}, Item{id=fefa35fd-63bd-40b8-a0d2-36e036840e98, accountId=a2e6d3ea-10ef-4b1f-865a-1a52654f2e7f, bundleId=2b1a35b2-6fe8-42a1-9dce-440621ced78c, subscriptionId=baf1b087-b546-4f3b-a8c1-1c0b8f68f057, targetInvoiceId=c83a5b31-7f72-4605-88f8-336817a5a518, invoiceId=3a8c5fea-f16a-4e14-8e24-743e8ca044ad, planName='professionalServices-solutionanalyst-daily-addonpl', phaseName='professionalServices-solutionanalyst-daily-addonpl', startDate=2016-02-02, endDate=2016-03-02, amount=0.00, rate=0E-9, currency=EUR, createdDate=2016-02-02T08:44:27.000Z, linkedId=null, currentRepairedAmount=0, adjustedAmount=0, action=ADD}]

        at com.google.common.base.Preconditions.checkState(Preconditions.java:197)

        at org.killbill.billing.invoice.tree.ItemsInterval.getResulting_ADD_Item(ItemsInterval.java:158)

        at org.killbill.billing.invoice.tree.ItemsInterval.getResultingItem(ItemsInterval.java:134)

        at org.killbill.billing.invoice.tree.ItemsInterval.buildFromItems(ItemsInterval.java:89)

        at org.killbill.billing.invoice.tree.ItemsNodeInterval$1.onLastNode(ItemsNodeInterval.java:102)

        at org.killbill.billing.invoice.tree.NodeInterval.build(NodeInterval.java:59)

        at org.killbill.billing.invoice.tree.NodeInterval.build(NodeInterval.java:69)

        at org.killbill.billing.invoice.tree.ItemsNodeInterval.buildForExistingItems(ItemsNodeInterval.java:92)

        at org.killbill.billing.invoice.tree.SubscriptionItemTree.build(SubscriptionItemTree.java:102)

        at org.killbill.billing.invoice.tree.AccountItemTree.build(AccountItemTree.java:82)

        at org.killbill.billing.invoice.tree.AccountItemTree.mergeWithProposedItems(AccountItemTree.java:156)

        at org.killbill.billing.invoice.generator.FixedAndRecurringInvoiceItemGenerator.generateItems(FixedAndRecurringInvoiceItemGenerator.java:107)

        at org.killbill.billing.invoice.generator.DefaultInvoiceGenerator.generateInvoice(DefaultInvoiceGenerator.java:84)

        at org.killbill.billing.invoice.InvoiceDispatcher.processAccountWithLockAndInputTargetDate(InvoiceDispatcher.java:331)

        at org.killbill.billing.invoice.InvoiceDispatcher.processAccountWithLock(InvoiceDispatcher.java:258)

        at org.killbill.billing.invoice.InvoiceDispatcher.processAccount(InvoiceDispatcher.java:224)

        at org.killbill.billing.invoice.InvoiceTagHandler.processUnpaid_AUTO_INVOICING_OFF_invoices(InvoiceTagHandler.java:64)

        at org.killbill.billing.invoice.InvoiceTagHandler.process_AUTO_INVOICING_OFF_removal(InvoiceTagHandler.java:58)

        ... 19 common frames omitted

I'm a little scared about these new exceptions... are they indeed new or didn't they appear because of the invoicing loops?

Thank you,

Leonardo

[Pierre-Alexandre Meyer]

Hi Leonardo,

On Tue, Nov 22, 2016 at 12:14 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

we finally went live with the 0.18.1 snapshot version

FWIW, 0.18.1 has been released.

 

As predicted, the CPU usage dropped instantly and there are no invoice calculations looping.

Great!

 

However, we encountered another issue on the invoicing calculation: we created a new subscription for one of our customers and restarted the invoicing process (removing the AUTO_INVOICING_OFF tag); our Tomcat reported this exception.

DefaultBillingEvent{type=CREATE, effectiveDate=2016-01-18T22:01:46.000Z, planPhaseName=professionalServices-solutionanalyst-tenpack-addonplan-evergreen, subscriptionId=c4b03069-63e9-4935-9da8-8a7ed92649e7, totalOrdering=126}

        FIXED{startDate=2016-01-18, endDate=null, amount=8000.00, rate=null, subscriptionId=c4b03069-63e9-4935-9da8-8a7ed92649e7, linkedItemId=null}

org.killbill.billing.invoice.api.InvoiceApiException: SAFETY BOUND TRIGGERED subscriptionId='c4b03069-63e9-4935-9da8-8a7ed92649e7', resultingItem=FIXED{startDate=2016-01-18, endDate=null, amount=8000.00, rate=null, subscriptionId=c4b03069-63e9-4935-9da8-8a7ed92649e7, linkedItemId=null}

In 0.18.0, we introduced this safety check (see SAFETY BOUND TRIGGERED message). To make sure we don't end up invoicing over and over a customer in case of a bug or data integrity issue, we disable invoicing for that account after generating too many items for a given subscription on a given day.

This could be an issue while catching-up (in your scenario, removing AUTO_INVOICING_OFF forces a catch-up). The behavior is configurable though through the property org.killbill.invoice.maxDailyNumberOfItemsSafetyBound. It's 15 by default. Set it to -1 to disable it.

More details in https://github.com/killbill/killbill/issues/26 and https://github.com/killbill/killbill/releases/tag/killbill-0.18.0. 

--

Pierre

[Pierre-Alexandre Meyer]

On Tue, Nov 22, 2016 at 12:29 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

The Tomcat has been restarted a few seconds ago, there are no other clients attached and this is an account without a particular activity (except for the huge number of invoice items due to the previous KB behaviour).

You can find the export file at https://hub-share.thron.com/content/?id=b22d094e-982a-4d78-9b60-dcfc91a53851&pkey=rUxBqB.

I'll take a look at the export but it's indeed possible the invoice generation takes too long because of the bad data.

Note that the exception is only for the invoice generation process for the account 7a6dd639-77f4-48ed-b38c-5cd507322308. Other accounts should be unaffected (and Kill Bill should still be able to accept and process requests).

Is there a way to reduce the size of the DB by removing the unneeded rows?

Assuming there are no payments attached to an invoice, it should be safe to delete the corresponding rows in invoices and invoice_items. I'll take a look at your data to see if I can reproduce it first.

--

Pierre

[Pierre-Alexandre Meyer]

On Tue, Nov 22, 2016 at 12:36 AM, Leonardo Scattola <leonardo...@newvision.it> wrote:

... and another exception has arisen on another customer:

[...] 

Caused by: java.lang.IllegalStateException: Double billing detected

 

This is another safety check by the system. If for a given subscription and service period, we detect that the invoicing code is about to double bill the customer, we prevent the invoice from being posted. We don't want to customer to pay twice because of a bug in the system or in the data.

Judging by the logs, it looks like it's related to the $0 items issue. You would need indeed to clean-up these superfluous double-entries.

 

I'm a little scared about these new exceptions... are they indeed new or didn't they appear because of the invoicing loops?

While the safety bound check is new, the double billing check isn't. I'm not quite sure why you didn't see it before.

Taking a step back, we like to log full exceptions in the logs to get the attention from the administrator when unexpected states happen. It doesn't necessarily mean Kill Bill isn't functioning (in these cases, only specific accounts have issues).

Note that the exception message should always tell you more about it (and if the message is different, it would be easier to create different threads here, as it's getting hard to follow the various issues).

--

Pierre

[Pierre-Alexandre Meyer]

On Tue, Nov 22, 2016 at 8:25 AM, Pierre-Alexandre Meyer <pie...@kill-bill.org> wrote:

I'll take a look at the export but it's indeed possible the invoice generation takes too long because of the bad data.

I managed to load all of your data. The large dataset for that account (26,683 invoices and 159,971 invoice items) is indeed the culprit.

It takes 25 minutes for a single invoice run: it's slow, but eventually completes with no exception. However, if there is anything else in the system trying to generate another run in the meantime (which is common, due to the event-based nature of the system), that process will time-out quite quickly trying to get the invoice lock for that account (the timeout is configured by default at 5s).

Looking at the invoicing code and some traces, the bulk of the time is spent building the existing in-memory AccountItemTree. While there are some obvious quick wins we could make, the easiest and fastest path moving forward would be for you to clean up the data. Unfortunately, it's not that obvious which invoice items to delete. Could you instead simply re-create that specific account along with its subscriptions?

On a related note, I've verified that, with a clean invoices and invoice_items state, invoice generation is pretty fast for this specific account (I went all the way to the end of 2018). 

--

Pierre

[Leonardo Scattola]

Pierre, all,

we migrated (at last!) the production database on a new KB instance, pruning all the unneeded invoice elements and invoices. The DB size dropped from nearly 2GB to 20MB and now KB seems to be responding in a nice and quick fashion.

Thank you all for your support!

Leonardo